AF_LTE socket and nrfxlib

[miked531]

After many hours of successful LTE connections and using the AF_LTE socket just fine (many creates, many send/receive, many closes), my application now hangs on a call to socket(AF_LTE,0,NPROTO_AT). Hung, as in the call to socket() does not return. I have no idea where to look to resolve this. Is the nrfxlib code available for review? I'll sign an NDA if I can get my eyes on it. I've spent way too much time trying to code around strange behavior in nrfxlib/nrf/zephyr.

This is running on nrf9160 DK, modem fw v1.1.1 and NCS v1.2.0

Mike

[Didrik Rokhaug]

Hi.

I can not give you access to the bsdlib source code. However, I can try to help you find the source of the problem.

Do you use the at_cmd library to send AT commands?

Do you see similar behavior on other types of sockets?

How many other sockets are you using (and are you using the lwm2m_carrier library or other libraries that might use sockets)?

Are you able to capture a modem trace that captures the problem?

Best regards,

Didrik

[miked531]

Hi,

I do not use at_cmd, I rolled my own (prior to when the at_* libs were mature enough for my use)

I have seen various socket issues over the past several months and have several tickets in devzone. They have all(?) been resolved by now.

I should have no more than 3 sockets open at once (AF_LTE for monitoring the modem is always open and normally waiting on recv(); AF_LTE for commanding the modem, only occasionally; AF_INET for send/recv of UDP data once we are connected to the network). My occasional AF_LTE socket for commanding keeps getting fd=1 or 2 when created, so I don't think I am leaking them anyplace. I'm not using any additional libs that should be using sockets (and not using lwm2m_carrier).

This happens very infrequently and I cannot get modem traces as my application also uses the nrf52840 on the DK.

I'm curious what the socket call might be doing that would cause it to hang? I can deal with errors, but hanging threads is much more difficult. If you can't share the bsdlib source, can you give some insight to what may be happening?

[miked531]

Your explanation for tracing is a little over my head as I don't have a great understanding of the board. It was much easier for me to chop out the pieces of my application that demonstrate the problem. I have included the code that illustrates the issue, and it does it consistently in under 5 minutes. The code creates a thread that listens for status notifications from the modem, while the main thread repeatedly turns modem on and off with some sleeps in between. In my application the sleeps are much longer, but I sped them up to demonstrate the problem in a reasonable amount of time.

The output shows the application hanging at the end:

*** Booting Zephyr OS build v2.1.99-ncs1  ***
[00:00:00.188] opened socket, fd 1
[00:00:00.191] send[1]: AT+CMEE=1
[00:00:00.194] read[1]: OK
[00:00:00.197] send[1]: AT+CFUN?
[00:00:00.200] read[1]: +CFUN: 0
[00:00:00.203] read[1]: OK
[00:00:00.206] send[1]: AT%XSYSTEMMODE?
[00:00:00.216] read[1]: %XSYSTEMMODE: 1,0,0,0
[00:00:00.220] read[1]: OK
[00:00:00.222] send[1]: AT+CGMI
[00:00:00.231] read[1]: Nordic Semiconductor ASA
[00:00:00.236] read[1]: OK
[00:00:00.238] send[1]: AT+CGMM
[00:00:00.248] read[1]: nRF9160-SICA
[00:00:00.251] read[1]: OK
[00:00:00.253] send[1]: AT+CGMR
[00:00:00.263] read[1]: mfw_nrf9160_1.1.1
[00:00:00.266] read[1]: OK
[00:00:00.269] send[1]: AT+CGSN
[00:00:00.278] read[1]: 352656100038754
[00:00:00.282] read[1]: OK
[00:00:00.284] send[1]: AT+CIMI
[00:00:00.293] read[1]: +CME ERROR: 0
[00:00:00.297] send[1]: AT+CEREG=5
[00:00:00.306] read[1]: OK
[00:00:00.309] send[1]: AT%CESQ=1
[00:00:00.318] read[1]: OK
[00:00:00.321] send[1]: AT+CGEREP=1
[00:00:00.330] read[1]: OK
[00:00:00.333] send[1]: AT+CNEC=24
[00:00:00.342] read[1]: OK
[00:00:00.345] send[1]: AT+CIND=1,1,1
[00:00:00.355] read[1]: OK
[00:00:00.357] send[1]: AT%XSIM=1
[00:00:00.366] read[1]: OK
[00:00:01.188] poweron modem
[00:00:01.197] opened socket, fd 2
[00:00:01.200] send[2]: AT+CMEE=1
[00:00:01.209] read[2]: OK
[00:00:01.212] send[2]: AT+CEMODE=2
[00:00:01.221] read[2]: OK
[00:00:01.224] send[2]: AT+CFUN=1
[00:00:01.264] read[2]: OK
[00:00:01.267] wait for 15 seconds
[00:00:05.135] read[1]: %XSIM: 1
[00:00:05.855] read[1]: %CESQ: 46,2,0,0
[00:00:05.859] read[1]: +CEREG: 2,"121F","0115760F",7,0,0,"11100000","11100000"
[00:00:08.199] read[1]: +CGEV: ME PDN ACT 0,0
[00:00:08.204] read[1]: +CIND: "service",1
[00:00:08.208] read[1]: +CIND: "roam",1
[00:00:16.270] poweroff modem
[00:00:16.279] opened socket, fd 2
[00:00:16.282] send[2]: AT+CMEE=1
[00:00:16.292] read[2]: OK
[00:00:16.294] send[2]: AT+CFUN=4
[00:00:18.988] read[2]: OK
[00:00:18.997] wait for 15 seconds
[00:00:34.000] poweron modem
[00:00:34.009] opened socket, fd 2
[00:00:34.012] send[2]: AT+CMEE=1
[00:00:34.022] read[2]: OK
[00:00:34.024] send[2]: AT+CEMODE=2
[00:00:34.034] read[2]: OK
[00:00:34.036] send[2]: AT+CFUN=1
[00:00:34.077] read[2]: OK
[00:00:34.079] wait for 15 seconds
[00:00:49.083] poweroff modem
[00:00:49.092] opened socket, fd 2
[00:00:49.095] send[2]: AT+CMEE=1
[00:00:50.104] recv[2] timeout after 1000ms
[00:00:50.108] send[2]: AT+CFUN=4
[00:01:00.117] recv[2] timeout after 10000ms
[00:01:10.042] recv[1] timeout after 30000ms
[00:01:10.046] re-opening the modem, fd 1

broken.zip

[Didrik Rokhaug]

Thanks for the code.

One problem with your code is that you (eventually) try to connect to the network 30 times in 30 minutes. That will trigger a network protection feature that will keep you from being able to connect to the network.

That is not the problem seen in your log though.

However, I am not able to reproduce the error in your log.

What SIM card are you using?

If you are not using the iBasis SIM card that came with the DK, could you try that (assuming you are able to connect to your local network with it)?

[miked531]

Understood about the 30 connects. Normal operation has delays in the range of hours and the shortened times are to illustrate the problem in less time.

I am in US and using a SIM from Deutsche Telekom, but have seen the same issue with the iBasis SIM, though less often (based on a very non-scientific observation). The main difference I have seen between the two SIMs is that DT will always use AT&T while iBasis goes between AT&T and Verizon.

I have updated the program to hopefully create the deadlock more frequently. I have had mixed results, so maybe it will happen quicker or maybe not. It can take up to 30 minutes for it to occur so be patient.

broken2.zip

[Didrik Rokhaug]

I let your updated sample run for close to 7 hours, but I am not able to see any hangs. Though maybe I just don't know what to look for. The log is attached.

I also modified your application to enable modem tracing. Could you try to run it, and see if you are able to capture a trace of the hangup?

socket_maybe_stuck.txtbroken_w_trace.zip

[miked531]

I am now not able to create the hang even with my own code, so I have updated the code and attached it again as 'broken3.zip'. In short, I took out the AT+CFUN=1 and spawn several threads to abuse the modem with AT commands. During the handful of times I have run it, it sometimes lasts for a full minute before hanging. It starts getting timeouts then all the output eventually just stops.

The other problem I see is that it sometimes just does a board reset and starts over with the "booting zephyr..." message, with no accompanying information, panic, etc.

It is not performing a real-world scenario, but is able to consistently produce a hang on the socket(AF_LTE) call.

broken3.zip

[Didrik Rokhaug]

With your new code, I am able to reproduce the error, though it takes a lot longer than 1 minute to see the error. On my latest run, the error came after 17,5 minutes.

In one of my traces, the modem reports that it is out of RAM used to communicate with the application. The trace also shows that you are not waiting for a response from the modem before you send a new command.

In a real application (i.e. not one made to provoke an error), you should both take care not to send new commands before the previous one got a reply, and that you read back any data (this also goes for IP or GNSS sockets) fast enough.

However, as the modem does crash at the end, I have informed the modem team and asked if they can take a look at it.

[miked531]

I'm glad you were finally able to reproduce the error. I'm curious why it took much longer for you though. My tests are running on 9160dk rev 0.8.2.

Is there anything inherently wrong with the design of the code regarding how it accesses the modem? Your answer above suggests that perhaps a mutex would be needed when issuing AT commands.

[Didrik Rokhaug]

The response from the modem team was mostly as I expected:

You should wait for a response to the AT commands you send, and ensure that you read back the data sent from the modem so that you don't run out of memory used to communicate with the modem.

This is also probably what causes the application to hang. As there is no more memory that can be used to communicate with the modem, the application is not able to open new sockets or sending new commands.

 

miked531 said:

Your answer above suggests that perhaps a mutex would be needed when issuing AT commands.

 Yes, using a mutex to restrict the access to the modem to only one thread at a time could solve some of your problems. The main point though is that you should wait for a reply before you send a new AT command.

However, both of the traces show that the modem crashes at the end. Both the crashes are due to the same cause, for which the modem team already has a fix. Future releases of the modem firmware will have this fix, and will hopefully solve the problem you are seeing in your original application.

I suggest that you take another look at your AT command library, and try to limit it to just sending one command at a time.

[miked531]

In my quick test that I just coded up, the mutex around the AT and response has apparently resolved the issue.

Do you have an estimate as to when the modem fix will be released?

[Didrik Rokhaug]

Great to hear that it seems to work now!

I can not comment on future releases. For that, you should contact your Regional Sales Manager.

If you do not know how to contact your RSM, you can send me a private message with your location, and I will provide you with the contact information.