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

[Xykon]

Hello everyone,

A new stable firmware v1.18.1.r4 is now available for the LTE modules (GPy, G01, FiPy). This update fixes an issue where the modem becomes unresponsive during LTE.init(), improves the reliability of LTE.pppsuspend() and improves LTE.isattached() detection. A development version with the same LTE improvements is also now available (1.19.0.b5).

A new NB-IoT firmware 40343 is also now available for download at http://software.pycom.io/downloads/sequans2.html

This new firmware most importantly fixes the DNS issue that was introduced in recent versions. It should also have full support for PSM and eDRX though I haven't tested these features yet.

Unfortunately I am not able to provide differential upgrade packages from every previous NB-IoT firmware as the older firmwares don't always upgrade correctly. You can either upgrade from the factory firmware 33080 or the previous NB-IoT firmware 38729, otherwise please use the full firmware package for now.

If you haven't already, please make sure to also read the previous update before updating your modem.

With this new NB-IoT firmware you can use the same commands as used for a CAT-M1 firmware. The following code has been successfully tested with Vodafone NL:

from network import LTE
lte = LTE()
lte.attach(band=20, apn="nb.inetd.gdsp")
while not lte.isattached():
    time.sleep(0.25)
lte.connect()       # start a data session and obtain an IP address
while not lte.isconnected():
    time.sleep(0.25)

If you require any additional AT commands to make a successful NB-IoT connection please post them here so I can add them to the API.

[danielm]

@wghirakawa
The issue is that socket.connect() and SSL handshake will not timeout also in case the socket timeout is set and hang the application forever.
https://forum.pycom.io/topic/3985/new-lte-firmware-releases-v1-18-1-r4-stable-1-19-0-b5-development-nb-iot-firmware-40343/45

[wghirakawa]

@danielm what socket issues are you referring too?

[danielm]

@iwahdan
Are there any news regarding solution for known socket issues?

[iwahdan]

@tlanier No problem!, thanks for letting us know

[tlanier]

@tlanier
The bug I was experiencing was caused by my inexperience using Python. I was allocating a new WLAN object every time I ran the code without destroying the old object.

Here is a listing of my new wifi.py module that fixes my problem. I'm sorry if I've caused anyone to lose confidence in the GPy or spend time looking for bugs that did not exist.

from network import WLAN
from util import log
import utime

wlan = None

def connect():
    global wlan

    if (wlan != None):
        if wlan.isconnected():
            print('Already connected')
            return

    wlan = WLAN(mode=WLAN.STA)
    
    while True:
        # scan for WIFI access points
        nets = wlan.scan()
        print(nets)
        
        for net in nets:
            if (net.ssid == 'NURSEX'):
                print('NURSEX WIFI found')
                # wlan.connect(net.ssid, auth=(net.sec, 'password'), timeout=5000)
                wlan.connect(net.ssid, auth=(net.sec, 'password'))
                while not wlan.isconnected():
                    utime.sleep_ms(1000)
                print('WLAN connection succeeded!')
                return
        
        utime.sleep_ms(1000)

def disconnect():
    global wlan

    if (wlan != None):
        wlan.disconnect()
        wlan = None```

[danielm]

@iwahdan
Great, please let me know if you need help with testing.

[iwahdan]

Hi @danielm, I am investigating the handshake problem, and for a the socket.connect timeout I think it is possible to have a workaround in the Micropython, but it would need proper design to ensure a robust implementation .

I've already created an internal ticket for it.

[danielm]

@iwahdan
Is it possible to fix the ssl handshake not timing out?
What about socket.connect() timeout workaround implementation?

Due to nature of network communication any socket operation may fail but it should never hang if timeout is set. Otherwise it will not be possible to develop reliable applications.

[iwahdan]

@danielm Thanks, No the problem I mentioned in that post is because the ssl handshake does not timeout, which I think is not what happens in your case.

[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

[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, 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, 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.

[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:

[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

[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]

@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?

[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 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?