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

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.

0_1543243812915_4b8b91ac-08d9-46f7-8d2a-24250e47fd01-image.png

Part of urequests.py where crash occurs:

0_1543243413146_5eec8529-151c-4402-9d5d-d6411b14fa98-image.png

Simple test program:

0_1543243895758_452859ac-ed45-45f4-a7e6-38569ca0c915-image.png

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

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

@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

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
Great, please let me know if you need help with testing.

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```

iwahdan

@tlanier No problem!, thanks for letting us know

danielm

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

wghirakawa

@danielm what socket issues are you referring too?

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

Explore Pybytes | Official Documentation | Report a Firmware Bug/Issue | GitHub

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

Pycom on Twitter