New LTE Firmware releases v1.18.1.r4 (stable) & 1.19.0.b5 (development) & NB-IoT firmware 40343

[danielm]

@Xykon @iwahdan
I would appreciate feedback on my previous two posts.
LTE implementation in 1.18.1.r3 to 1.18.1.r5 works worse than in 1.18.1.r2. Testing code is provided, you may check yourself.

[Paul Thornton]

Hi All,

Due to moving office's and limited internet access the development team are unable to investigate the LTE issues at the moment. Thanks for being patient whilst we work on this.

@danielm Ill make sure they see your response and take a look just as soon as they can.

Paul T,

[robert-hh]

@paul-thornton Hello Paul. Welcome to the community.

[Paul Thornton]

@robert-hh

Thanks :D Ill make a proper introduction post soon. I just snuck on to post this and get you all updated. Look forward to getting stuck in the forums some cool projects being worked on in here. :)

[danielm]

@paul-thornton
Hi Paul, thanks for the information regarding moving of the office.

[combaindeft]

@Xykon ... the new firmware doesn't work with Telia NB-IOT in sweden :-( ... cannot attach anymore ...

I tried to just use the "update" dup ... but I'm trying now to use the total reset method and see if that helps ... elsewise I'll be downgrading back to the previous version that worked ...

[wghirakawa]

I was having major problems, with trying to do the update using v1.18.1.r4 and using the FW package 39529. After following multiple recommendations from other FiPy Users, as well as trying to do the method as described in the Docs, it was to no avail. Then I viewed @rskoniec post at https://forum.pycom.io/topic/3995/fipy-firmware-upgrade-failed-cat-m1/26 showed me a potential way of getting my FW at least to 38638. But after attempting downgrading my FiPy Firmware to v1.18.1.r1 and trying to upgrade to 38638 it just was not happening. It kept getting stuck on Attempting AT Auto-Negotiation, then it would eventually fail.

ERROR sending AT command... no response? b''
AT auto-negotiation failed! Exiting.
Unable to load updater from /sd/updater.elf

@rskoniec was kind enough to remotely connect to my computer and we spent roughly 3 hours trying to do the firmware upgrade to the SQNS Modem. @rskoniec knows exactly what he did, and will be replying to this post with how he was able to get my firmware on my modem upgraded. As it stands I have a FiPY + Pytrack and my sqnsupgrade.version() is as bellow.

SYSTEM VERSION
==============
  FIRMWARE VERSION
    Bootloader0  : 5.1.1.0 [33080]
    Bootloader1  : 5.1.1.0 [38638]
    Bootloader2* : 5.1.1.0 [38638]
    NV Info      : 1.1,0,0
    Software     : 5.1.1.0 [38638] by robot-soft at 2018-08-20 09:51:46
    UE           : 5.0.0.0d
  COMPONENTS
    ZSP0         : 1.0.99-13604
    ZSP1         : 1.0.99-12341

I will be attempting to upgrade to the newest SQNS Firmware after updating the FiPy to r4. I will attempt upgrading to 39529 using the method as described in the forum, and will post my results.

I cannot thank @rskoniec enough for the time he dedicated to help another developer! I hope that my post will save others valuable time, especially during this holiday season.

[iwahdan]

@danielm said in New LTE Firmware releases v1.18.1.r4 (stable) & 1.19.0.b5 (development) & NB-IoT firmware 40343:

https://54.167.116.227/post

Hello @danielm , I could reproduce the issue you had with getting disconnected after the first HTTP post request I submitted a fix now for it as pre-release v1.18.1.r6.

Thanks for your feedback

[wghirakawa]

After upgrading the FiPy Firware to v1.18.1.r4 I attempted to follow the instructions on the forum to ugprade to 39529. Using the following method.

1. Use Filezilla to transfer upgdiff_38638-to-39529.dup and updater.elf to flash memory.
2. Executed the following in the REPL

import sqnsupgrade
sqnsupgrade.run('upgdiff_38638-to-39529.dup','updater.elf')

which ultimately resulted in the successful upgrade of my SQNS Modem Firmware to the version info below.

SYSTEM VERSION
==============
  FIRMWARE VERSION
    Bootloader0  : 5.1.1.0 [39529]
    Bootloader1* : 5.1.1.0 [39529]
    Bootloader2  : 5.1.1.0 [39529]
    NV Info      : 1.1,0,0
    Software     : 5.1.1.0 [39529] by robot-soft at 2018-09-28 16:07:40
    UE           : 5.0.0.0d
  COMPONENTS
    ZSP0         : 1.0.99-13616
    ZSP1         : 1.0.99-12355

[danielm]

@iwahdan
Thanks a lot, I will start testing in the evening or tomorrow.

Could you please let my test code running on 1.18.1.r6 over the weekend just to be sure that there will not be any unexpected hang?

[danielm]

@iwahdan
I did some testing and it seems that LTE init/disconnect issues are solved.

When I left the test running for some time socket errors/exceptions started to be raised at some point.

INFO 1140. HTTP POST successful: {"args":{},"data":{"time":"10843"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"10843"},"url":"https://34.202.13.18/post"}
INFO 1141. HTTP POST successful: {"args":{},"data":{"time":"10858"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"10858"},"url":"https://34.202.13.18/post"}
INFO 1142. HTTP POST successful: {"args":{},"data":{"time":"10873"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"10873"},"url":"https://34.202.13.18/post"}
INFO 1143. HTTP POST successful: {"args":{},"data":{"time":"10894"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"10894"},"url":"https://34.202.13.18/post"}
INFO 1144. HTTP POST successful: {"args":{},"data":{"time":"10936"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"10936"},"url":"https://34.202.13.18/post"}
WARNING 1145. HTTP POST failed: -76
WARNING 1146. HTTP POST failed: -1
WARNING 1147. HTTP POST failed: -1
WARNING 1148. HTTP POST failed: -1
WARNING 1149. HTTP POST failed: -1
WARNING 1150. HTTP POST failed: -1
WARNING 1151. HTTP POST failed: -1
WARNING 1152. HTTP POST failed: -1
WARNING 1153. HTTP POST failed: -1
WARNING 1154. HTTP POST failed: -1
WARNING 1155. HTTP POST failed: 23
WARNING 1156. HTTP POST failed: 23
WARNING 1157. HTTP POST failed: 23
WARNING 1158. HTTP POST failed: 23
WARNING 1159. HTTP POST failed: 23
WARNING 1160. HTTP POST failed: 23
WARNING 1161. HTTP POST failed: 23
WARNING 1162. HTTP POST failed: 23

WARNING 7130. HTTP POST failed: 23
WARNING 7131. HTTP POST failed: 23
WARNING 7132. HTTP POST failed: 23
WARNING 7133. HTTP POST failed: 23
WARNING 7134. HTTP POST failed: 23
WARNING 7135. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 7136. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 7137. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 7138. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 7139. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 7140. HTTP POST failed: [Errno 105] ENOBUFS

WARNING 10758. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10759. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10760. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10761. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10762. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10763. HTTP POST failed: [Errno 105] ENOBUFS
WARNING 10764. HTTP POST failed: [Errno 105] ENOBUFS

The code was hanged at 10764. POST attempt. It was not possible to break the loop using Ctrl + C, but it was possible to reset the machine using Ctrl+F.

After soft-reset POST attempts were unsuccessful as well. LTE dettach attempt resulted in OSError, however the modem did dettach. After consequent machine.reset() POST requests worked. It seems that after several hundreds socket creations the modem starts to act weirdly.

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff8028,len:8
load:0x3fff8030,len:1728
load:0x4009fa00,len:0
load:0x4009fa00,len:14584
entry 0x400a059c
INFO Starting initialization of LTE
INFO LTE initialized
LTE is attached after init: True
LTE is connected after init: False
INFO Attached to LTE network
INFO LTE connect command sent
INFO Connected to LTE network
WARNING 1. HTTP POST failed: -1
WARNING 2. HTTP POST failed: -1
WARNING 3. HTTP POST failed: -1
WARNING 4. HTTP POST failed: -1
WARNING 5. HTTP POST failed: -1
WARNING 6. HTTP POST failed: -1
Traceback (most recent call last):
  File "main.py", line 78, in <module>
  File "main.py", line 70, in run
KeyboardInterrupt:
Pycom MicroPython 1.18.1.r6 [v1.8.6-849-a8966d1] on 2018-11-23; FiPy with ESP32
Type "help()" for more information.
>>>
>>>
>>>
>>>
>>>
>>> test.lte
<LTE>
>>> test.lte.dettach()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
OSError: the requested operation failed
>>> test.lte.isattached()
False
>>> import machine
>>> machine.reset()
ets Jun  8 2016 00:22:57

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff8028,len:8
load:0x3fff8030,len:1728
load:0x4009fa00,len:0
load:0x4009fa00,len:14584
entry 0x400a059c
INFO Starting initialization of LTE
INFO LTE initialized
LTE is attached after init: False
LTE is connected after init: False
INFO LTE attach command sent
INFO Attached to LTE network
INFO LTE connect command sent
INFO Connected to LTE network
INFO 1. HTTP POST successful: {"args":{},"data":{"time":"69"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"14","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"69"},"url":"https://34.202.13.18/post"}
INFO 2. HTTP POST successful: {"args":{},"data":{"time":"77"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"14","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"77"},"url":"https://34.202.13.18/post"}
INFO 3. HTTP POST successful: {"args":{},"data":{"time":"87"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"14","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"87"},"url":"https://34.202.13.18/post"}
INFO 4. HTTP POST successful: {"args":{},"data":{"time":"95"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"14","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"95"},"url":"https://34.202.13.18/post"}
INFO 5. HTTP POST successful: {"args":{},"data":{"time":"103"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"15","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"103"},"url":"https://34.202.13.18/post"}
INFO 6. HTTP POST successful: {"args":{},"data":{"time":"111"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"15","accept":"application/json","content-type":"application/json","x-forwarded-port":"443"},"json":{"time":"111"},"url":"https://34.202.13.18/post"}

During tests with 1.18.1.r2 long-term test did behave in a similar way:
https://forum.pycom.io/topic/3985/new-lte-firmware-releases-v1-18-1-r4-stable-1-19-0-b5-development-nb-iot-firmware-40343/22

Exception value of first failed POST request was -76 in both tests. What does it mean?

[iwahdan]

@danielm this error code is :

#define MBEDTLS_ERR_NET_RECV_FAILED -0x004C /**< Reading information from the socket failed. */

So these socket errors you get I think occurs when using ssl, did you have same problem with posting to non-secure site?

Anyway I am also running your code over the weekend via our NB-IoT network emulator , I will see if I get same errors as yours.

[danielm]

@iwahdan
I just started the same test without SSL and will leave it running during the night.
Thank you for conducting tests in your environment.
Where can I find list of socket exceptions?

[danielm]

@iwahdan
The test failed also without SSL:

INFO 6619. HTTP POST successful: {"args":{},"data":{"time":"15432"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"15432"},"url":"https://34.202.13.18/post"}
INFO 6620. HTTP POST successful: {"args":{},"data":{"time":"15435"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"15435"},"url":"https://34.202.13.18/post"}
INFO 6621. HTTP POST successful: {"args":{},"data":{"time":"15437"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"15437"},"url":"https://34.202.13.18/post"}
INFO 6622. HTTP POST successful: {"args":{},"data":{"time":"15439"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"15439"},"url":"https://34.202.13.18/post"}
INFO 6623. HTTP POST successful: {"args":{},"data":{"time":"15441"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"15441"},"url":"https://34.202.13.18/post"}
WARNING 6624. HTTP POST failed: -1
WARNING 6625. HTTP POST failed: -1
WARNING 6626. HTTP POST failed: -1
WARNING 6627. HTTP POST failed: -1
WARNING 6628. HTTP POST failed: -1
WARNING 6629. HTTP POST failed: -1
WARNING 6630. HTTP POST failed: -1
WARNING 6631. HTTP POST failed: -1
WARNING 6632. HTTP POST failed: -1
WARNING 6633. HTTP POST failed: -1
WARNING 6634. HTTP POST failed: 23
WARNING 6635. HTTP POST failed: 23
WARNING 6636. HTTP POST failed: 23
WARNING 6637. HTTP POST failed: 23
WARNING 6638. HTTP POST failed: 23
WARNING 6639. HTTP POST failed: 23

[danielm]

Second test without SSL failed as well, this time with "weird" exception:

INFO 9937. HTTP POST successful: {"args":{},"data":{"time":"22492"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"22492"},"url":"https://34.202.13.18/post"}
INFO 9938. HTTP POST successful: {"args":{},"data":{"time":"22494"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"22494"},"url":"https://34.202.13.18/post"}
INFO 9939. HTTP POST successful: {"args":{},"data":{"time":"22497"},"files":{},"form":{},"headers":{"x-forwarded-proto":"https","host":"34.202.13.18","content-length":"17","accept":"application/json","content-type":"application/json","x-forwarded-port":"80"},"json":{"time":"22497"},"url":"https://34.202.13.18/post"}
WARNING 9940. HTTP POST failed: 'NoneType' object has no attribute 'split'
WARNING 9941. HTTP POST failed: -1
WARNING 9942. HTTP POST failed: -1
WARNING 9943. HTTP POST failed: -1
WARNING 9944. HTTP POST failed: -1
WARNING 9945. HTTP POST failed: -1
WARNING 9946. HTTP POST failed: -1
WARNING 9947. HTTP POST failed: -1
WARNING 9948. HTTP POST failed: -1
WARNING 9949. HTTP POST failed: -1
WARNING 9950. HTTP POST failed: 23
WARNING 9951. HTTP POST failed: 23
WARNING 9952. HTTP POST failed: 23
WARNING 9953. HTTP POST failed: 23
WARNING 9954. HTTP POST failed: 23
WARNING 9955. HTTP POST failed: 23

[tlanier]

I'm now trying just to get reliable network communication working using WIFI with v1.18.1.r4.

Sometimes it works and sometimes it doesn't.

Below is a simple program to try to download a web page using a WIFI connection with the urequests.py module.

The socket connection command fails at least 50% of the time returning a OSError: -1 exception.

Part of urequests.py where crash occurs:

Simple test program:

[iwahdan]

Hi @danielm, when running your code I don't get the errors you have but however I do get another issue where the test is stuck at some point waiting for the POST response message - since blocking sockets is used - (it gets stuck after couple of hundred Posts, so I was not able to reach the point you had in your test (i.e in range of Thousands)), which i am currently investigating and might actually be a problem with our NB-IoT emulator.

Will keep you updated.

[danielm]

Hi @iwahdan, do you have possbility to connect to production NB-IoT network of MNO to find out if this problem disappears?

I think I have encountered this behavior in the past as well. The module was not completely hanged as it was possible to soft reset using Ctrl+F. I am suspecting that some operation with blocking socket will not timeout despite the fact that the timeout has been set.

[iwahdan]

Hi @danielm the error you are getting
HTTP POST failed: 'NoneType' object has no attribute 'split' is because the socket operation socket.recv() has returned error code = EGAIN which could be when the operation timesout if you are are setting a socket timeout > 0 , where this error is considered non blocking by the readline function in MicroPython py/stream.c where in that case a None object is returned. maybe this should be handled in requests.py

on the other hand the problem of failing to create more sockets HTTP POST failed: 23 that happens at some point, is because lwip stack fails to allocate new sockets and this is because every time the exception 'NoneType' object has no attribute 'split' is raised it is not caught by the exception handler in requests.py

    except OSError:
        s.close()
        raise

As it is an AttributeError not an OSError exp, thus the socket is not closed and by turn the lwip stack does not free that socket as it considers conn still active since err code is EGAIN.
I know that in the normal case when the POST is successful you also don't close the socket afterwards but that is not a problem as the lwip will Reuse the oldest socket not closed yet [Note: that the Max active sockets is Configured to 10] .

so the flow goes as follow socket # 54 gets allocated for first message then 55 for second and so on till #64 .. then lwip will allocate socket #54 again for creating new socket then #55 and so on.
However when a socket connection timeout if the socket is not closed the socket # will be reserved forever.

so in your case if a socket operation timeout say every 1000 successful POST the esp32 will fail to allocate new sockets after 10000 POSTs (so it is a socket leak)

so to fix you problem you have to do the following modifications in requests.py:

Update exception handler to include all exceptions so that the socket is closed in any case:

    except :
        s.close()
        raise

maybe it is also a good idea to close the socket after successful POST as follows:

response = urequests.post(url, headers={ "Content-Type": "application/json", "Accept": "application/json"}, data='{"time": "%s"}' % (time.time()))
print("INFO", "%s. HTTP POST successful: %s" % (n, response.text))
response.close()

Thanks for your help.

[danielm]

Hi @iwahdan. Thank you for excelent analysis. I will perform recommended modifications and also long-term tests.
I believe that this issue is not related to issues you are describing in this post?
https://forum.pycom.io/topic/3985/new-lte-firmware-releases-v1-18-1-r4-stable-1-19-0-b5-development-nb-iot-firmware-40343/39