u-blox / ubxlib

Portable C libraries which provide APIs to build applications with u-blox products and services. Delivered as add-on to existing microcontroller and RTOS SDKs.
Apache License 2.0
287 stars 82 forks source link

Continuous UMQTTER 13,0 Error Loop and Improper Shutdown Behavior (SARA-R422M8S) #202

Closed tommas0serafin closed 4 months ago

tommas0serafin commented 4 months ago

Hi Rob, Upon losing internet connection on my device, regardless of whether it's due to antenna disconnection or forced disconnection, the device starts throwing UMQTTER error code 13,0, which then transitions to 13,50 or 13,34, indicating a normal behavior. However, upon re-establishing the connection, the system enters an error loop where it fails to connect, consistently throwing UMQTTER error code 13,0. Occasionally I noticed a discrepancy between the actual connection status and the one identified by the internal callbacks (network is up but it is detected as down). This behavior is reproducible consistently.

Furthermore, I've observed that the module fails to shut down properly. After every shutdown attempt (with AT commands), the UART pins on the ESP32 side remain active, causing a current leak into the u-blox module. As a consequence the ublox module outputs 0.7v-1.1v not allowing a proper shutdown procedure. I patched this issue by resetting the gpios on the microcontroller's side but I need to understand if there's an hardware issue causing it or if it's a library bug.

Serial output upon reconnection:

U_CELL_PWR: powering on.
AT
AT
AT
AT
AT
AT

OK
ATE0
AT

OK
AT+CMEE=2
ATE0

OK

OK

OK

OK
AT+UDCONF=1,0

OK
ATI9

00.12,A00.00

OK
AT&C1

OK
AT&D0

OK
AT+UCGED=2

OK
AT&K3

OK
AT+UPSV=4

OK
AT+UPSMR=1

OK
AT+CPSMS?

+CPSMS:0,,,"01100000","00000000"

OK
AT+CEDRXS?

+CEDRXS:

OK
AT+UMNOPROF?

+UMNOPROF: 100

OK
AT+UGPRF?

+UGPRF: 2,0,""

OK
AT+CFUN=4

OK
U_CELL_NET: preparing to register/connect...
AT+CREG=2

OK
AT+CGREG=2

OK
AT+CEREG=4

OK
AT+CIMI

295050903238865

OK
U_CELL_NET: user-specified APN is "em".
AT+CGDCONT=1,"IP","em"

OK
U_CELL_NET: setting automatic network selection mode...
AT+COPS?

SARA-R422M8S-00B-00

ERROR

+COPS: 0

OK
AT+CFUN=1

OK
AT+CREG?

+CREG: 2,0

OK
0: NReg
AT+CGREG?

+CGREG: 2,4

OK
0: OoC
AT+CEREG?

+CEREG: 4,0

OK
0: NReg
AT+CREG?

+CREG: 2,0

OK
0: NReg
AT+CGREG?

+CGREG: 2,4

OK
0: OoC
AT+CEREG?

+CEREG: 4,0

OK
0: NReg
AT+CREG?

+CREG: 2,0

OK

+CREG: 2

+CEREG: 2,,,,,,,,
0: NReg
-1: Search
-1: Search

+CREG: 5,"4E62","00006BE6",3

3: RegR
AT+CGREG?

+CGREG: 2,2

OK
0: Search
AT+CEREG?

+CEREG: 4,4

OK
0: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR

+CGREG: 5,"4E62","00006BE6",3,"46"
3: RegR
AT+COPS=3,0

OK
AT+COPS?

+COPS: 0,0,"vodafone IT",3

OK
AT+CGATT?

+CGATT: 1

OK
AT+CGACT?

ERROR
AT+CGACT=1,1

+CGACT: 1,0

OK
AT+CGACT?

OK
AT+CGACT=1,1

OK
AT+CGACT?

+CGACT: 1,1

OK
AT+UPSD=0,0,0

OK
AT+UPSD=0,100,1

OK
U_CELL_NET: connected after 15 second(s).
AT+UMQTT=2,"cssiot01.eurac.edu",1883

OK
AT+CGSN

355438111885391

OK
AT+UMQTT=0,"355438111885391"

OK
AT+UMQTT=10,120

OK
U_CELL_MQTT: trying to connect...
AT+UMQTTC=1

OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
RobMeades commented 4 months ago

Hi there, and sorry to hear you're having so many problems. Splitting them out:

upon re-establishing the connection, the system enters an error loop where it fails to connect, consistently throwing UMQTTER error code 13,0.

From the trace you have pasted in above this looks as though it would be a module problem: at least, I can't see how the ubxlib code would cause this, unless you can see something? If it is a module problem we can try to help but it is kind of a "best effort" thing from a ubxlib standpoint and you might be better off raising it through the proper module support routes.

Occasionally I noticed a discrepancy between the actual connection status and the one identified by the internal callbacks (network is up but it is detected as down). This behavior is reproducible consistently.

This may, of course, be a ubxlib issue - it would imply that we have missed a registration URC, which would be interesting. if you are able to a log of the ubxlib debug output at the time that would be very interesting.

Furthermore, I've observed that the module fails to shut down properly. After every shutdown attempt (with AT commands), the UART pins on the ESP32 side remain active, causing a current leak into the u-blox module. As a consequence the ublox module outputs 0.7v-1.1v not allowing a proper shutdown procedure. I patched this issue by resetting the gpios.

When we close a UART we expect the platform code to put any pins into an "off" state but it might well be that not all platforms do this. We could "grab" any pins that were once UART pins, making them GPIOs and then put them into some form of "off" state (let them float high?). This would be quite difficult to test of course, not something our automated system is built to do. Or we could add a note somewhere that this is something to look out for at application level? I'm always a little wary making a behavioural change to code that has been out there for several years.

tommas0serafin commented 4 months ago

Hi Rob, Thanks for your quick reply. For what concerns the connection status discrepancy the situation would be similar to the debug output I'm sharing. In this case the module is sending the mqtt messages but is not able to receive them. The defined callback in the struct uMqttClientConnection_t which checks uDeviceHandle_t detects the network as down and I receive these UMQTTER 13,0 while the connection seems to be up.

U_CELL: initialising with enable power pin not connected, PWR_ON pin 15 (0x0f) (and is toggled from 1 to 0) and VInt pin 7 (0x07) (and is 1 when module is on).
I (320600) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (320610) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
U_CELL_PWR: powering on.
AT
AT
AT
AT
AT
AT

OK
ATE0
ATE0

OK
AT+CMEE=2

OK
AT+UDCONF=1,0

OK
ATI9

00.12,A00.00

OK
AT&C1

OK
AT&D0

OK
AT+UCGED=2

OK
AT&K3

OK
AT+UPSV=4

OK
AT+UPSMR=1

OK
AT+CPSMS?

+CPSMS:0,,,"01100000","00000000"

OK
AT+CEDRXS?

+CEDRXS:

OK
AT+UMNOPROF?

+UMNOPROF: 100

OK
AT+UGPRF?

+UGPRF: 2,0,""

OK
AT+CFUN=4

OK
U_CELL_NET: preparing to register/connect...
AT+CREG=2

OK
AT+CGREG=2

OK
AT+CEREG=4

OK
AT+CIMI

295050903238865

OK
U_CELL_NET: user-specified APN is "em".
AT+CGDCONT=1,"IP","em"

OK
U_CELL_NET: setting automatic network selection mode...
AT+COPS?

+COPS: 0

OK
AT+CFUN=1

OK
AT+CREG?

+CREG: 2,0

OK
0: NReg
AT+CGREG?

+CGREG: 2,4

OK
0: OoC
AT+CEREG?

+CEREG: 4,0

OK
0: NReg
AT+CREG?

+CREG: 2,0

OK
0: NReg
AT+CGREG?

+CGREG: 2,4

OK
0: OoC
AT+CEREG?

+CEREG: 4,0

OK
0: NReg
AT+CREG?

+CREG: 2,0

OK
0: NReg

+CREG: 2

+CEREG: 2,,,,,,,,
-1: Search
-1: Search

+CREG: 5,"4E62","00006BE6",3

3: RegR
AT+CGREG?

+CGREG: 2,2

OK
0: Search
AT+CEREG?

+CEREG: 4,4

OK
0: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC
AT+CREG?

+CREG: 2,5,"4E62","00006BE6",3

OK
3: RegR
AT+CGREG?

+CGREG: 2,2

OK
3: Search
AT+CEREG?

+CEREG: 4,4

OK
3: OoC

+CGREG: 5,"4E62","00006BE6",3,"46"
3: RegR
AT+COPS=3,0

OK
AT+COPS?

+COPS: 0,0,"vodafone IT",3

OK
AT+CGATT?

+CGATT: 1

OK
AT+CGACT?

+CGACT: 1,0

OK
AT+CGACT=1,1

OK
AT+CGACT?

+CGACT: 1,1

OK
AT+UPSD=0,0,0

OK
AT+UPSD=0,100,1

OK
U_CELL_NET: connected after 12 second(s).
AT+UMQTT=2,"xxxxxxxxx",1883

OK
AT+CGSN

355438111885391

OK
AT+UMQTT=0,"355438111885391"

OK
AT+UMQTT=10,120

OK
U_CELL_MQTT: trying to connect...
AT+UMQTTC=1

OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
I (340590) GNSS: Bringing up GNSS
AT+CMUX=0,0,,128

OK
ATE0

OK
AT+CMEE=2

OK
AT+UPSV?

+UPSV: 4 

OK
AT+UPSV=0

OK
U_GNSS: initialising with ENABLE_POWER pin not connected, transport type Virtual Serial.
ATI

SARA-R422M8S-00B-00

OK
AT+UGIND=0

OK
AT+UGPS?

+UGPS: 0

OK

+UUMQTTC: 1,1
AT+UGPS=1,15,127

OK
I (343970) GNSS: Starting continuous location.

AT+UGPS?

+UGPS: 1,0

OK
AT+UGPS?

+UGPS: 1,0

OK
AT+UGPS=1,1

OK
E (344420) GNSS: Local Aid is off!
U_GNSS: sent command b5 62 06 08 00 00 0e 30.
U_GNSS: decoded UBX response 0x06 0x08: e8 03 01 00 01 00 [body 6 byte(s)].
U_GNSS: sent command b5 62 06 01 02 00 01 07 11 3a.
U_GNSS: decoded UBX response 0x06 0x01: 01 07 00 00 00 00 00 00 [body 8 byte(s)].
U_GNSS: sent command b5 62 06 01 08 00 01 07 01 00 00 00 00 00 18 e2.
U_GNSS: decoded UBX response 0x05 0x01: 06 3e [body 2 byte(s)].
I (345000) GNSS: Continuous location started!
AT+UMQTTC=4,1,"xxxxxxxxx"

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTC=9,1,0,"xxxxxxxxx",1

+UUMQTTC: 4,1,1,"xxxxxxxxx"

>[00]

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.

+UUMQTTC: 6,1

AT+UMQTTC=5,"xxxxxxxxx"

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTC=4,1,"xxxxxxxxx"

+CME ERROR: Operation not allowed

AT+UMQTTER

+UUMQTTC: 5,1

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTC=9,1,0,"xxxxxxxxx",1

>[00]

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.

+UUMQTTC: 9,1
AT+UMQTTC=5,"xxxxxxxxx"

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.

AT+UMQTTC=4,1,"xxxxxxxxx"

+CME ERROR: Operation not allowed

AT+UMQTTER

+UUMQTTC: 5,1

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.
AT+UMQTTC=9,1,0,"xxxxxxxxx",1

>[00]

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
AT+UMQTTER

+UMQTTER: 13,0

OK
U_CELL_MQTT: error codes 13, 0.

On the other hand, for what concerns the hardware access/control (GPIOs), I think the behavior differs according to the module used (at least that's what I understood from the datasheet). I do not exclude the chance of having some hardware issues on the board I'm currently working on, I was more interested in understanding if you were aware of this behavior.

As I said there might be some hardware (wiring/powering) problems leading to these errors, my biggest concern is the connection status one.

RobMeades commented 4 months ago

the situation would be similar to the debug output I'm sharing

Understood: I think it depends on what is meant by "up". From this part of the AT trace:

AT+COPS?
+COPS: 0,0,"vodafone IT",3
OK
AT+CGATT?
+CGATT: 1
OK
AT+CGACT?
+CGACT: 1,0
OK
AT+CGACT=1,1
OK
AT+CGACT?
+CGACT: 1,1
OK
AT+UPSD=0,0,0
OK
AT+UPSD=0,100,1
OK

...the module is registered with the network, has a PDP context activated and the internal "profile" within the module has been connected to that context; hence all of the internal clients within the module (IP, MQTT, HTTP) should be able to connect. For some reason the MQTT client within the module is stuck in a state where it does not. Let me see if I can find out internally if this is a known issue and if there is some form of workaround that ubxlib could apply.

for what concerns the hardware access/control (GPIOs) ... I was more interested in understanding if you were aware of this behavior.

This is not something we (where "we" means ubxlib) would notice, I think, power consumption in various states is not something that our test system addresses, for better or worse we leave that to the module. As to what we should do in this particular case, I'm open to advice.

RobMeades commented 4 months ago

A couple of questions for clarification:

I didn't read the detail of the second AT log above (the one concerning the "registration/connectedness discrepancy"); you say:

The defined callback in the struct uMqttClientConnection_t which checks uDeviceHandle_t detects the network as down and I receive these UMQTTER 13,0 while the connection seems to be up.

By this I guess you mean that, when you call uMqttClientConnect you set a pKeepGoingCallback in the uMqttClientConnection_t structure you pass to that function, and from that callback you call another ubxlib API to determine the network state - which one is that? Obviously in this particular AT log an MQTT connection has successfully been made (+UUMQTTC: 1,1) , so the module is in the clear.

On the "MQTT client in the module does not connect" case, you say:

Upon losing internet connection on my device, regardless of whether it's due to antenna disconnection or forced disconnection, the device starts throwing UMQTTER error code 13,0, which then transitions to 13,50 or 13,34, indicating a normal behavior. However, upon re-establishing the connection, the system enters an error loop where it fails to connect, consistently throwing UMQTTER error code 13,0

I had assumed that the first AT log you pasted in above was an instance of this case, since there is no +UUMQTTC: of any kind in it, yet in that AT log the module appears to be coming up from off-state: can you confirm that you believe the module has not connected in that AT log because when it was previously powered-up, there was a coverage loss and, despite the module being powered off and on again, that loss of coverage resulted in the subsequent "lack of a +UUMQTTC URC" behaviour of the MQTT client?

RobMeades commented 4 months ago

One more thing: it might be a good idea to define U_AT_CLIENT_PRINT_WITH_TIMESTAMP for your build of ubxlib: this will add a timestamp before each AT item logged, this way we can see how long things are taking.

tommas0serafin commented 4 months ago

Hey Rob, This is the signature of the callback I'm using, it falls under uNetworkStatusCallback_t:

static void network_status_callback(uDeviceHandle_t devHandle,
                                    uNetworkType_t netType,
                                    bool isUp,
                                    uNetworkStatus_t *pStatus,
                                    void *pParameter)

Here I'm basically checking on the boolean value isUp.

For what concerns the second point, you're right this a module restart after a forced disconnection (I unplugged the antenna). This is for me the easiest way to force the connection issue. Basically after experiencing the loss of connection I close, power off and restart the module to start over. Since this problem is way less common if I restart the whole device (ublox + micro), I also though this might be a sync problem of the UART between the ublox module and the microcontroller.

Hope it helps, Thanks in advance

RobMeades commented 4 months ago

This is the signature of the callback I'm using, it falls under uNetworkStatusCallback_t:

Understood: you have called uNetworkSetStatusCallback() and given it your network_status_callback() function to call and, sometime during the second AT log above, it is being called with false for isUp. The network status callback is called for every registration URC and the last one in that log is:

+CGREG: 5,"4E62","00006BE6",3,"46"

...which indicates registered, roaming, on E-GPRS (RAT 3). The callback code internal to ubxlib which handles this within the uNetwork API is statusCallback() and all that does to set isUp is call the U_CELL_NET_STATUS_MEANS_REGISTERED macro on the network status. In this particular case the network status should be 5 (U_CELL_NET_STATUS_REGISTERED_ROAMING), which should result in true. Since the callback is called for each URC, would you be able to print out the value from the callback, so that we can see it in the log after each URC lands, along with maybe the pair of values from the uNetworkStatusCell_t member of the uNetworkStatus_t union, and paste that AT log here?

For what concerns the second point...

Just to be clear, can you indicate approximately where in the sequence of the first AT log you pasted in above the antenna is reconnected to the module?

tommas0serafin commented 4 months ago

Unfortunately the hardware failed me, I'll come back tomorrow with more detailed logs (I'll add what you suggested).

To clarify the last point, the antenna is reconnected while the module is powered off (but the micro isn't) so the whole log you read includes only the section with the antenna on.

RobMeades commented 4 months ago

Darn. More tomorrow then.

To clarify the last point,

Understood. Makes it all the more difficult to understand though: if the antenna is reconnected before the module is powered back up that should not affect the MQTT client in the module, given that the module registers with the network. If it is possible to take a log with U_AT_CLIENT_PRINT_WITH_TIMESTAMP defined for the ubxlib build then that might be interesting, having a view of time as well.

tommas0serafin commented 4 months ago

Hi Rob, I followed your advice and here's the log. I also noticed that most of the time the reason of the shutdown is related to uMqttClientIsConnected(pContext) and not the network callback. However I hope we can get something out of this log and sort things out. Hopefully for you it might be a hardware related issue.

U_CELL: initialising with enable power pin not connected, PWR_ON pin 15 (0x0f) (and is toggled from 1 to 0) and VInt pin 7 (0x07) (and is 1 when module is on).
I (783070) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (783080) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
U_CELL_PWR: powering on.
0000/01/01 00:13:01.521: AT
0000/01/01 00:13:01.730: AT
0000/01/01 00:13:02.080: AT
0000/01/01 00:13:02.430: AT
0000/01/01 00:13:02.780: AT
0000/01/01 00:13:04.260: AT

0000/01/01 00:13:04.261: OK
0000/01/01 00:13:04.370: ATE0
0000/01/01 00:13:04.410: ATE0

0000/01/01 00:13:04.411: OK
0000/01/01 00:13:04.520: AT+CMEE=2
0000/01/01 00:13:04.560: 
0000/01/01 00:13:04.561: OK
0000/01/01 00:13:04.670: AT+UDCONF=1,0
0000/01/01 00:13:04.710: 
0000/01/01 00:13:04.711: OK
0000/01/01 00:13:04.820: ATI9
0000/01/01 00:13:04.860: 
0000/01/01 00:13:04.861: 00.12,A00.00
0000/01/01 00:13:04.861: 
0000/01/01 00:13:04.861: OK
0000/01/01 00:13:04.970: AT&C1
0000/01/01 00:13:05.010: 
0000/01/01 00:13:05.011: OK
0000/01/01 00:13:05.120: AT&D0
0000/01/01 00:13:05.160: 
0000/01/01 00:13:05.161: OK
0000/01/01 00:13:05.270: AT+UCGED=2
0000/01/01 00:13:05.310: 
0000/01/01 00:13:05.311: OK
0000/01/01 00:13:05.420: AT&K3
0000/01/01 00:13:05.470: 
0000/01/01 00:13:05.471: OK
0000/01/01 00:13:05.580: AT+UPSV=4
0000/01/01 00:13:05.620: 
0000/01/01 00:13:05.621: OK
0000/01/01 00:13:05.730: AT+UPSMR=1
0000/01/01 00:13:05.770: 
0000/01/01 00:13:05.771: OK
0000/01/01 00:13:05.880: AT+CPSMS?
0000/01/01 00:13:05.920: 
0000/01/01 00:13:05.921: +CPSMS:0,,,"01100000","00000000"
0000/01/01 00:13:05.921: 
0000/01/01 00:13:05.921: OK
0000/01/01 00:13:06.030: AT+CEDRXS?
0000/01/01 00:13:06.070: 
0000/01/01 00:13:06.071: +CEDRXS:
0000/01/01 00:13:06.071: 
0000/01/01 00:13:06.071: OK
0000/01/01 00:13:06.180: AT+UMNOPROF?
0000/01/01 00:13:06.220: 
0000/01/01 00:13:06.221: +UMNOPROF: 100
0000/01/01 00:13:06.221: 
0000/01/01 00:13:06.221: OK
0000/01/01 00:13:06.330: AT+UGPRF?
0000/01/01 00:13:06.370: 
0000/01/01 00:13:06.371: +UGPRF: 2,0,""
0000/01/01 00:13:06.371: 
0000/01/01 00:13:06.371: 
0000/01/01 00:13:06.371: 
0000/01/01 00:13:06.372: OK
0000/01/01 00:13:06.480: AT+CFUN=4
0000/01/01 00:13:06.520: 
0000/01/01 00:13:06.521: OK
U_CELL_NET: preparing to register/connect...
0000/01/01 00:13:06.630: AT+CREG=2
0000/01/01 00:13:06.670: 
0000/01/01 00:13:06.671: OK
0000/01/01 00:13:06.780: AT+CGREG=2
0000/01/01 00:13:06.820: 
0000/01/01 00:13:06.821: OK
0000/01/01 00:13:06.930: AT+CEREG=4
0000/01/01 00:13:06.970: 
0000/01/01 00:13:06.971: OK
0000/01/01 00:13:07.080: AT+CIMI
0000/01/01 00:13:07.120: 
0000/01/01 00:13:07.121: 295050903238861
0000/01/01 00:13:07.121: 
0000/01/01 00:13:07.121: OK
U_CELL_NET: user-specified APN is "em".
0000/01/01 00:13:07.230: AT+CGDCONT=1,"IP","em"
0000/01/01 00:13:07.270: 
0000/01/01 00:13:07.271: OK
U_CELL_NET: setting automatic network selection mode...
0000/01/01 00:13:07.380: AT+COPS?
0000/01/01 00:13:07.420: 
0000/01/01 00:13:07.421: +COPS: 0
0000/01/01 00:13:07.421: 
0000/01/01 00:13:07.421: OK
0000/01/01 00:13:08.420: AT+CFUN=1
0000/01/01 00:13:08.460: 
0000/01/01 00:13:08.461: OK
0000/01/01 00:13:08.570: AT+CREG?
0000/01/01 00:13:08.610: 
0000/01/01 00:13:08.611: +CREG: 2,0
0000/01/01 00:13:08.611: 
0000/01/01 00:13:08.611: OK
0: NReg
0000/01/01 00:13:08.910: AT+CGREG?
0000/01/01 00:13:08.950: 
0000/01/01 00:13:08.951: +CGREG: 2,4
0000/01/01 00:13:08.951: 
0000/01/01 00:13:08.951: OK
0: OoC
0000/01/01 00:13:09.250: AT+CEREG?
0000/01/01 00:13:09.290: 
0000/01/01 00:13:09.291: +CEREG: 4,0
0000/01/01 00:13:09.291: 
0000/01/01 00:13:09.291: OK
0: NReg
0000/01/01 00:13:09.590: AT+CREG?
0000/01/01 00:13:09.630: 
0000/01/01 00:13:09.631: +CREG: 2,0
0000/01/01 00:13:09.631: 
0000/01/01 00:13:09.631: OK
0: NReg
0000/01/01 00:13:09.930: AT+CGREG?
0000/01/01 00:13:09.970: 
0000/01/01 00:13:09.971: +CGREG: 2,4
0000/01/01 00:13:09.971: 
0000/01/01 00:13:09.971: OK
0: OoC
0000/01/01 00:13:10.270: AT+CEREG?
0000/01/01 00:13:10.310: 
0000/01/01 00:13:10.311: +CEREG: 4,0
0000/01/01 00:13:10.311: 
0000/01/01 00:13:10.311: OK
0: NReg
0000/01/01 00:13:10.610: AT+CREG?
0000/01/01 00:13:10.650: 
0000/01/01 00:13:10.651: +CREG: 2,0
0000/01/01 00:13:10.651: 
0000/01/01 00:13:10.651: OK
0: NReg
0000/01/01 00:13:10.950: AT+CGREG?
0000/01/01 00:13:10.990: 
0000/01/01 00:13:10.991: +CGREG: 2,4
0000/01/01 00:13:10.991: 
0000/01/01 00:13:10.991: OK
0: OoC
0000/01/01 00:13:11.060: 
0000/01/01 00:13:11.061: +CREG: 2
-1: Search
0000/01/01 00:13:11.080: 
0000/01/01 00:13:11.080: +CEREG: 2,,,,,,,,
-1: Search
0000/01/01 00:13:11.290: AT+CEREG?
0000/01/01 00:13:11.330: 
0000/01/01 00:13:11.331: +CEREG: 4,2
0000/01/01 00:13:11.331: 
0000/01/01 00:13:11.331: OK
0: Search
0000/01/01 00:13:11.630: AT+CREG?
0000/01/01 00:13:11.670: 
0000/01/01 00:13:11.671: +CREG: 2,2
0000/01/01 00:13:11.671: 
0000/01/01 00:13:11.671: OK
0: Search
0000/01/01 00:13:11.970: AT+CGREG?
0000/01/01 00:13:12.010: 
0000/01/01 00:13:12.011: +CGREG: 2,4
0000/01/01 00:13:12.011: 
0000/01/01 00:13:12.011: OK
0: OoC
0000/01/01 00:13:12.310: AT+CEREG?
0000/01/01 00:13:12.350: 
0000/01/01 00:13:12.351: +CEREG: 4,2
0000/01/01 00:13:12.351: 
0000/01/01 00:13:12.351: OK
0: Search
0000/01/01 00:13:12.650: AT+CREG?
0000/01/01 00:13:12.690: 
0000/01/01 00:13:12.691: +CREG: 2,2
0000/01/01 00:13:12.691: 
0000/01/01 00:13:12.691: OK
0: Search
0000/01/01 00:13:12.990: AT+CGREG?
0000/01/01 00:13:13.030: 
0000/01/01 00:13:13.031: +CGREG: 2,4
0000/01/01 00:13:13.031: 
0000/01/01 00:13:13.031: OK
0: OoC
0000/01/01 00:13:13.150: 
0000/01/01 00:13:13.151: +CREG: 5,"90EF","0AAF90A3",9
9: RegR
0000/01/01 00:13:13.170: 
0000/01/01 00:13:13.171: +CEREG: 5,"90EF","AAF90A3",9,,,,
9: RegR
0000/01/01 00:13:13.330: AT+COPS=3,0
0000/01/01 00:13:13.370: 
0000/01/01 00:13:13.371: OK
0000/01/01 00:13:13.480: AT+COPS?
0000/01/01 00:13:13.520: 
0000/01/01 00:13:13.521: +COPS: 0,0,"I TIM",9
0000/01/01 00:13:13.521: 
0000/01/01 00:13:13.521: OK
0000/01/01 00:13:13.630: AT+CGATT?
0000/01/01 00:13:13.670: 
0000/01/01 00:13:13.671: +CGATT: 1
0000/01/01 00:13:13.671: 
0000/01/01 00:13:13.671: OK
0000/01/01 00:13:13.780: AT+CGACT?
0000/01/01 00:13:13.820: 
0000/01/01 00:13:13.821: +CGACT: 1,1
0000/01/01 00:13:13.821: 
0000/01/01 00:13:13.821: OK
0000/01/01 00:13:13.930: AT+UPSD=0,0,0
0000/01/01 00:13:13.970: 
0000/01/01 00:13:13.971: OK
0000/01/01 00:13:14.080: AT+UPSD=0,100,1
0000/01/01 00:13:14.120: 
0000/01/01 00:13:14.121: OK
U_CELL_NET: connected after 7 second(s).
0000/01/01 00:13:14.230: AT+UMQTT=2,"xxxxxxxxxx",1883
0000/01/01 00:13:14.270: 
0000/01/01 00:13:14.271: 
0000/01/01 00:13:14.271: 
0000/01/01 00:13:14.271: OK
0000/01/01 00:13:14.380: AT+CGSN
0000/01/01 00:13:14.420: 
0000/01/01 00:13:14.421: 355438111885391
0000/01/01 00:13:14.421: 
0000/01/01 00:13:14.421: OK
0000/01/01 00:13:14.530: AT+UMQTT=0,"355438111885391"
0000/01/01 00:13:14.570: 
0000/01/01 00:13:14.571: 
0000/01/01 00:13:14.571: 
0000/01/01 00:13:14.571: OK
0000/01/01 00:13:14.680: AT+UMQTT=10,120
0000/01/01 00:13:14.720: 
0000/01/01 00:13:14.721: 
0000/01/01 00:13:14.721: 
0000/01/01 00:13:14.721: OK
U_CELL_MQTT: trying to connect...
0000/01/01 00:13:15.220: AT+UMQTTC=1
0000/01/01 00:13:15.260: 
0000/01/01 00:13:15.261: 
0000/01/01 00:13:15.261: 
0000/01/01 00:13:15.261: OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
0000/01/01 00:13:15.370: AT+UMQTTER
0000/01/01 00:13:15.410: 
0000/01/01 00:13:15.411: +UMQTTER: 13,0
0000/01/01 00:13:15.411: 
0000/01/01 00:13:15.411: 
0000/01/01 00:13:15.411: 
0000/01/01 00:13:15.412: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:15.520: AT+UMQTTER
0000/01/01 00:13:15.560: 
0000/01/01 00:13:15.561: +UMQTTER: 13,0
0000/01/01 00:13:15.561: 
0000/01/01 00:13:15.561: 
0000/01/01 00:13:15.561: 
0000/01/01 00:13:15.562: OK
0000/01/01 00:13:15.670: AT+UMQTTER
0000/01/01 00:13:15.710: 
0000/01/01 00:13:15.711: +UMQTTER: 13,0
0000/01/01 00:13:15.711: 
0000/01/01 00:13:15.711: 
0000/01/01 00:13:15.711: 
0000/01/01 00:13:15.712: OK
U_CELL_MQTT: error codes 13, 0.
I (797680) GNSS: Bringing up GNSS
0000/01/01 00:13:15.820: AT+CMUX=0,0,,128
0000/01/01 00:13:15.860: 
0000/01/01 00:13:15.861: OK
0000/01/01 00:13:16.491: ATE0
0000/01/01 00:13:16.530: 
0000/01/01 00:13:16.531: OK
0000/01/01 00:13:16.640: AT+CMEE=2
0000/01/01 00:13:16.680: 
0000/01/01 00:13:16.681: OK
0000/01/01 00:13:16.790: AT+UPSV?
0000/01/01 00:13:16.830: 
0000/01/01 00:13:16.831: +UPSV: 4 
0000/01/01 00:13:16.831: 
0000/01/01 00:13:16.831: OK
0000/01/01 00:13:16.940: AT+UPSV=0
0000/01/01 00:13:16.980: 
0000/01/01 00:13:16.981: OK
U_GNSS: initialising with ENABLE_POWER pin not connected, transport type Virtual Serial.
0000/01/01 00:13:17.090: ATI
0000/01/01 00:13:17.130: 
0000/01/01 00:13:17.131: SARA-R422M8S-00B-00
0000/01/01 00:13:17.131: 
0000/01/01 00:13:17.131: OK
0000/01/01 00:13:17.240: AT+UGIND=0
0000/01/01 00:13:17.251: 
0000/01/01 00:13:17.251: +UUMQTTC: 1,1
0000/01/01 00:13:17.270: 
0000/01/01 00:13:17.270: 
0000/01/01 00:13:17.271: 
0000/01/01 00:13:17.271: OK
0000/01/01 00:13:17.380: AT+UGPS?
0000/01/01 00:13:17.420: 
0000/01/01 00:13:17.421: +UGPS: 0
0000/01/01 00:13:17.421: 
0000/01/01 00:13:17.421: 
0000/01/01 00:13:17.421: 
0000/01/01 00:13:17.422: OK
0000/01/01 00:13:17.921: AT+UGPS=1,15,127
0000/01/01 00:13:19.090: 
0000/01/01 00:13:19.091: 
0000/01/01 00:13:19.091: 
0000/01/01 00:13:19.091: OK
I (801060) GNSS: Starting continuous location.

0000/01/01 00:13:19.200: AT+UGPS?
0000/01/01 00:13:19.240: 
0000/01/01 00:13:19.241: +UGPS: 1,0
0000/01/01 00:13:19.241: 
0000/01/01 00:13:19.241: 
0000/01/01 00:13:19.241: 
0000/01/01 00:13:19.242: OK
0000/01/01 00:13:19.350: AT+UGPS?
0000/01/01 00:13:19.390: 
0000/01/01 00:13:19.391: +UGPS: 1,0
0000/01/01 00:13:19.391: 
0000/01/01 00:13:19.391: 
0000/01/01 00:13:19.391: 
0000/01/01 00:13:19.392: OK
0000/01/01 00:13:19.500: AT+UGPS=1,1
0000/01/01 00:13:19.540: 
0000/01/01 00:13:19.541: 
0000/01/01 00:13:19.541: 
0000/01/01 00:13:19.541: OK
E (801510) GNSS: Local Aid is off!
U_GNSS: sent command b5 62 06 08 00 00 0e 30.
U_GNSS: decoded UBX response 0x06 0x08: e8 03 01 00 01 00 [body 6 byte(s)].
U_GNSS: sent command b5 62 06 01 02 00 01 07 11 3a.
U_GNSS: decoded UBX response 0x06 0x01: 01 07 00 00 00 00 00 00 [body 8 byte(s)].
U_GNSS: sent command b5 62 06 01 08 00 01 07 01 00 00 00 00 00 18 e2.
U_GNSS: decoded UBX response 0x05 0x01: 06 3e [body 2 byte(s)].
I (802080) GNSS: Continuous location started!
0000/01/01 00:13:20.111: AT+UMQTTC=4,1,"xxxxxxxxxxxxx"
0000/01/01 00:13:20.160: 
0000/01/01 00:13:20.161: 
0000/01/01 00:13:20.161: 
0000/01/01 00:13:20.161: OK
0000/01/01 00:13:20.270: AT+UMQTTER
0000/01/01 00:13:20.310: 
0000/01/01 00:13:20.311: +UMQTTER: 13,0
0000/01/01 00:13:20.311: 
0000/01/01 00:13:20.311: 
0000/01/01 00:13:20.311: 
0000/01/01 00:13:20.312: OK
0000/01/01 00:13:20.420: AT+UMQTTER
0000/01/01 00:13:20.460: 
0000/01/01 00:13:20.461: +UMQTTER: 13,0
0000/01/01 00:13:20.461: 
0000/01/01 00:13:20.461: 
0000/01/01 00:13:20.461: 
0000/01/01 00:13:20.463: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:20.570: AT+UMQTTC=9,1,0,"xxxxxxxxxxxxxxx",1
0000/01/01 00:13:20.620: 
0000/01/01 00:13:20.621: +CME ERROR: Operation not allowed
0000/01/01 00:13:20.621: 
0000/01/01 00:13:20.741: AT+UMQTTER
0000/01/01 00:13:20.780: 
0000/01/01 00:13:20.781: +UMQTTER: 13,0
0000/01/01 00:13:20.781: 
0000/01/01 00:13:20.781: 
0000/01/01 00:13:20.781: 
0000/01/01 00:13:20.782: OK
0000/01/01 00:13:20.891: AT+UMQTTER
0000/01/01 00:13:20.930: 
0000/01/01 00:13:20.931: +UMQTTER: 13,0
0000/01/01 00:13:20.931: 
0000/01/01 00:13:20.931: 
0000/01/01 00:13:20.931: 
0000/01/01 00:13:20.933: OK
U_CELL_MQTT: error codes 13, 0.

0000/01/01 00:13:56.523: AT+UMQTTC=5,"xxxxxxxxxxxxx"
0000/01/01 00:13:56.570: 
0000/01/01 00:13:56.571: 
0000/01/01 00:13:56.571: 
0000/01/01 00:13:56.571: OK
0000/01/01 00:13:56.680: AT+UMQTTER
0000/01/01 00:13:56.720: 
0000/01/01 00:13:56.721: +UMQTTER: 13,0
0000/01/01 00:13:56.721: 
0000/01/01 00:13:56.721: 
0000/01/01 00:13:56.721: 
0000/01/01 00:13:56.722: OK
0000/01/01 00:13:56.830: AT+UMQTTER
0000/01/01 00:13:56.870: 
0000/01/01 00:13:56.871: +UMQTTER: 13,0
0000/01/01 00:13:56.871: 
0000/01/01 00:13:56.871: 
0000/01/01 00:13:56.871: 
0000/01/01 00:13:56.872: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:56.980: AT+UMQTTC=4,1,"xxxxxxxxxxxxx"
0000/01/01 00:13:57.030: 
0000/01/01 00:13:57.031: +CME ERROR: Operation not allowed
0000/01/01 00:13:57.031: 
0000/01/01 00:13:57.151: AT+UMQTTER
0000/01/01 00:13:57.190: 
0000/01/01 00:13:57.191: +UMQTTER: 13,0
0000/01/01 00:13:57.191: 
0000/01/01 00:13:57.191: 
0000/01/01 00:13:57.192: 
0000/01/01 00:13:57.193: OK
0000/01/01 00:13:57.300: AT+UMQTTER
0000/01/01 00:13:57.340: 
0000/01/01 00:13:57.341: +UMQTTER: 13,0
0000/01/01 00:13:57.341: 
0000/01/01 00:13:57.341: 
0000/01/01 00:13:57.341: 
0000/01/01 00:13:57.343: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:57.450: AT+UMQTTC=9,1,0,"xxxxxxxxxxxxx",1
0000/01/01 00:13:57.500: 
0000/01/01 00:13:57.501: +CME ERROR: Operation not allowed
0000/01/01 00:13:57.501: 
0000/01/01 00:13:57.621: AT+UMQTTER
0000/01/01 00:13:57.660: 
0000/01/01 00:13:57.661: +UMQTTER: 13,0
0000/01/01 00:13:57.661: 
0000/01/01 00:13:57.661: 
0000/01/01 00:13:57.661: 
0000/01/01 00:13:57.662: OK
0000/01/01 00:13:57.770: AT+UMQTTER
0000/01/01 00:13:57.780: 
0000/01/01 00:13:57.780: +UUMQTTC: 5,1
0000/01/01 00:13:57.810: 
0000/01/01 00:13:57.811: +UMQTTER: 13,0
0000/01/01 00:13:57.811: 
0000/01/01 00:13:57.811: 
0000/01/01 00:13:57.811: 
0000/01/01 00:13:57.813: OK
U_CELL_MQTT: error codes 13, 0.

0000/01/01 00:14:01.261: AT+UMQTTC=5,"xxxxxxxxxxxx"
0000/01/01 00:14:01.300: 
0000/01/01 00:14:01.301: 
0000/01/01 00:14:01.301: 
0000/01/01 00:14:01.301: OK
0000/01/01 00:14:01.410: AT+UMQTTER
0000/01/01 00:14:01.450: 
0000/01/01 00:14:01.451: +UMQTTER: 13,0
0000/01/01 00:14:01.451: 
0000/01/01 00:14:01.451: 
0000/01/01 00:14:01.451: 
0000/01/01 00:14:01.452: OK
0000/01/01 00:14:01.560: AT+UMQTTER
0000/01/01 00:14:01.600: 
0000/01/01 00:14:01.601: +UMQTTER: 13,0
0000/01/01 00:14:01.601: 
0000/01/01 00:14:01.601: 
0000/01/01 00:14:01.601: 
0000/01/01 00:14:01.602: OK
U_CELL_MQTT: error codes 13, 0.
GPIO 11: 0

0000/01/01 00:14:02.650: 
0000/01/01 00:14:02.651: +UUMQTTC: 5,1
U_GNSS: sent command b5 62 06 01 08 00 01 07 00 00 00 00 00 00 17 dc.
U_GNSS: decoded UBX response 0x05 0x01: 06 01 [body 2 byte(s)].
0000/01/01 00:14:32.891: AT+UGPS=0
0000/01/01 00:14:36.010: 
0000/01/01 00:14:36.011: 
0000/01/01 00:14:36.011: 
0000/01/01 00:14:36.011: OK
0000/01/01 00:14:36.120: AT+UPSV=4
0000/01/01 00:14:36.170: 
0000/01/01 00:14:36.171: OK
I (878270) GNSS: Continuous location stopped!
0000/01/01 00:14:37.401: AT
0000/01/01 00:14:37.440: 
0000/01/01 00:14:37.441: OK
0000/01/01 00:14:37.441: AT+UPSV=0
0000/01/01 00:14:37.490: 
0000/01/01 00:14:37.491: OK
U_CELL_PWR: powering off using the PWR_ON pin.
0000/01/01 00:14:39.530: 
0000/01/01 00:14:39.531: +UUMQTTC: 0,100
0000/01/01 00:14:40.720: 
0000/01/01 00:14:40.721: +CREG: 0
0000/01/01 00:14:40.721: 
0000/01/01 00:14:40.721: +CEREG: 0,,,,,,,,
-1: NReg
-1: NReg
Device powered off

Thanks for your time and patience

RobMeades commented 4 months ago

Ah, great, that makes things a lot easier to follow. I will explain in detail what I'm seeing, then you can follow through the code yourself to see what I am getting at; also, I am inferring the behavour of your application and you may have ideas as to what's going on yourself.

Basically, the log says that ESP-IDF (which version, out of interest?) mutexes are just not working in your case, which, if true, is quite bizarre. Putting it another way, the sequence above cannot happen if the ESP-IDF/FreeRTOS xSemaphoreCreateMutex()/xSemaphoreTake()/xSemaphoreGive() functions are working as they should.

Basically, all of the thread safety built into the ubxlib code is being ignored.

Unh?

tommas0serafin commented 4 months ago

Hey Rob, I added some extra prints in my log to clarify the situation. Some assumptions you made were correct but some others unfortunately weren't.

[uMqttClientConnect()] is the clause of a conditional, hence I won't execute the other MQTT operations unless it succeeds

[uMqttClientPublish()] basically never fails in terms of sending something, even when the connections seems to be absent. Additionaly it's not mandatory to be subscribed to a topic to use the function so I'm missing your point here.

Here's the big news, I'm never explicitly calling [uMqttClientGetLastErrorCode()] in my whole firmware. I tried in the past but, since it never resets, I couldn't really find an application for it. The errors you see come 100% from some internal calls.

BTW, here I'm sharing two logs of the most common behaviors I experience after the network disconnection:

U_CELL: initialising with enable power pin not connected, PWR_ON pin 15 (0x0f) (and is toggled from 1 to 0) and VInt pin 7 (0x07) (and is 1 when module is on).
I (734644) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (734654) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
U_CELL_PWR: powering on.
0000/01/01 00:12:11.740: [00]0000/01/01 00:12:11.850: AT
0000/01/01 00:12:12.060: AT
0000/01/01 00:12:12.410: AT
0000/01/01 00:12:12.760: AT
0000/01/01 00:12:13.110: AT
0000/01/01 00:12:14.280: AT

0000/01/01 00:12:14.280: OK
0000/01/01 00:12:14.380: ATE0
0000/01/01 00:12:14.420: ATE0

0000/01/01 00:12:14.420: OK
0000/01/01 00:12:14.520: AT+CMEE=2
0000/01/01 00:12:14.560: 
0000/01/01 00:12:14.560: OK
0000/01/01 00:12:14.660: AT+UDCONF=1,0
0000/01/01 00:12:14.700: 
0000/01/01 00:12:14.700: OK
0000/01/01 00:12:14.800: ATI9
0000/01/01 00:12:14.840: 
0000/01/01 00:12:14.840: 00.12,A00.00
0000/01/01 00:12:14.840: 
0000/01/01 00:12:14.841: OK
0000/01/01 00:12:14.950: AT&C1
0000/01/01 00:12:14.990: 
0000/01/01 00:12:14.990: OK
0000/01/01 00:12:15.090: AT&D0
0000/01/01 00:12:15.130: 
0000/01/01 00:12:15.130: OK
0000/01/01 00:12:15.230: AT+UCGED=2
0000/01/01 00:12:15.270: 
0000/01/01 00:12:15.270: OK
0000/01/01 00:12:15.370: AT&K3
0000/01/01 00:12:15.410: 
0000/01/01 00:12:15.410: OK
0000/01/01 00:12:15.510: AT+UPSV=4
0000/01/01 00:12:15.550: 
0000/01/01 00:12:15.550: OK
0000/01/01 00:12:15.650: AT+UPSMR=1
0000/01/01 00:12:15.690: 
0000/01/01 00:12:15.690: OK
0000/01/01 00:12:15.790: AT+CPSMS?
0000/01/01 00:12:15.830: 
0000/01/01 00:12:15.830: +CPSMS:0,,,"01100000","00000000"
0000/01/01 00:12:15.831: 
0000/01/01 00:12:15.831: OK
0000/01/01 00:12:15.940: AT+CEDRXS?
0000/01/01 00:12:15.980: 
0000/01/01 00:12:15.980: +CEDRXS:
0000/01/01 00:12:15.980: 
0000/01/01 00:12:15.980: OK
0000/01/01 00:12:16.090: AT+UMNOPROF?
0000/01/01 00:12:16.130: 
0000/01/01 00:12:16.130: +UMNOPROF: 100
0000/01/01 00:12:16.130: 
0000/01/01 00:12:16.131: OK
0000/01/01 00:12:16.240: AT+UGPRF?
0000/01/01 00:12:16.280: 
0000/01/01 00:12:16.280: +UGPRF: 2,0,""
0000/01/01 00:12:16.280: 
0000/01/01 00:12:16.281: 
0000/01/01 00:12:16.281: 
0000/01/01 00:12:16.282: OK
0000/01/01 00:12:16.390: AT+CFUN=4
0000/01/01 00:12:16.610: 
0000/01/01 00:12:16.610: OK
Bringing up the network...
U_CELL_NET: preparing to register/connect...
0000/01/01 00:12:16.710: AT+CREG=2
0000/01/01 00:12:16.750: 
0000/01/01 00:12:16.750: OK
0000/01/01 00:12:16.850: AT+CGREG=2
0000/01/01 00:12:16.890: 
0000/01/01 00:12:16.890: OK
0000/01/01 00:12:16.990: AT+CEREG=4
0000/01/01 00:12:17.030: 
0000/01/01 00:12:17.030: OK
0000/01/01 00:12:17.130: AT+CIMI
0000/01/01 00:12:17.170: 
0000/01/01 00:12:17.170: 295050903238861
0000/01/01 00:12:17.170: 
0000/01/01 00:12:17.171: OK
U_CELL_NET: user-specified APN is "em".
0000/01/01 00:12:17.280: AT+CGDCONT=1,"IP","em"
0000/01/01 00:12:17.320: 
0000/01/01 00:12:17.320: OK
U_CELL_NET: setting automatic network selection mode...
0000/01/01 00:12:17.420: AT+COPS?
0000/01/01 00:12:17.460: 
0000/01/01 00:12:17.460: +COPS: 0
0000/01/01 00:12:17.460: 
0000/01/01 00:12:17.460: OK
0000/01/01 00:12:18.460: AT+CFUN=1
0000/01/01 00:12:18.500: 
0000/01/01 00:12:18.500: OK
0000/01/01 00:12:18.600: AT+CREG?
0000/01/01 00:12:18.640: 
0000/01/01 00:12:18.640: +CREG: 2,0
0000/01/01 00:12:18.640: 
0000/01/01 00:12:18.640: OK
0: NReg
0000/01/01 00:12:18.940: AT+CGREG?
0000/01/01 00:12:18.980: 
0000/01/01 00:12:18.980: +CGREG: 2,4
0000/01/01 00:12:18.980: 
0000/01/01 00:12:18.980: OK
0: OoC
0000/01/01 00:12:19.280: AT+CEREG?
0000/01/01 00:12:19.320: 
0000/01/01 00:12:19.320: +CEREG: 4,0
0000/01/01 00:12:19.320: 
0000/01/01 00:12:19.320: OK
0: NReg
0000/01/01 00:12:19.620: AT+CREG?
0000/01/01 00:12:19.660: 
0000/01/01 00:12:19.660: +CREG: 2,0
0000/01/01 00:12:19.660: 
0000/01/01 00:12:19.660: OK
0: NReg
0000/01/01 00:12:19.960: AT+CGREG?
0000/01/01 00:12:20.000: 
0000/01/01 00:12:20.000: +CGREG: 2,4
0000/01/01 00:12:20.000: 
0000/01/01 00:12:20.000: OK
0: OoC
0000/01/01 00:12:20.300: AT+CEREG?
0000/01/01 00:12:20.340: 
0000/01/01 00:12:20.340: +CEREG: 4,0
0000/01/01 00:12:20.340: 
0000/01/01 00:12:20.340: OK
0000/01/01 00:12:20.341: 
0000/01/01 00:12:20.342: +CREG: 2
0: NReg
-1: Search
0000/01/01 00:12:20.380: 
0000/01/01 00:12:20.380: +CEREG: 2,,,,,,,,
-1: Search
0000/01/01 00:12:20.660: AT+CREG?
0000/01/01 00:12:20.700: 
0000/01/01 00:12:20.700: +CREG: 2,2
0000/01/01 00:12:20.700: 
0000/01/01 00:12:20.700: OK
0: Search
0000/01/01 00:12:21.000: AT+CGREG?
0000/01/01 00:12:21.040: 
0000/01/01 00:12:21.040: +CGREG: 2,4
0000/01/01 00:12:21.040: 
0000/01/01 00:12:21.040: OK
0: OoC
0000/01/01 00:12:21.340: AT+CEREG?
0000/01/01 00:12:21.380: 
0000/01/01 00:12:21.380: +CEREG: 4,2
0000/01/01 00:12:21.380: 
0000/01/01 00:12:21.380: OK
0: Search
0000/01/01 00:12:21.680: AT+CREG?
0000/01/01 00:12:21.720: 
0000/01/01 00:12:21.720: +CREG: 2,2
0000/01/01 00:12:21.720: 
0000/01/01 00:12:21.720: OK
0: Search
0000/01/01 00:12:21.890: 
0000/01/01 00:12:21.890: +CREG: 5,"90EF","0AAF9DA2",9
0000/01/01 00:12:21.891: 
0000/01/01 00:12:21.891: +CEREG: 5,"90EF","AAF9DA2",9,,,,
9: RegR
9: RegR
0000/01/01 00:12:22.020: AT+COPS=3,0
0000/01/01 00:12:22.060: 
0000/01/01 00:12:22.060: OK
0000/01/01 00:12:22.160: AT+COPS?
0000/01/01 00:12:22.200: 
0000/01/01 00:12:22.200: +COPS: 0,0,"I TIM",9
0000/01/01 00:12:22.200: 
0000/01/01 00:12:22.201: OK
0000/01/01 00:12:22.310: AT+CGATT?
0000/01/01 00:12:22.350: 
0000/01/01 00:12:22.350: +CGATT: 1
0000/01/01 00:12:22.350: 
0000/01/01 00:12:22.350: OK
0000/01/01 00:12:22.460: AT+CGACT?
0000/01/01 00:12:22.500: 
0000/01/01 00:12:22.500: +CGACT: 1,1
0000/01/01 00:12:22.500: 
0000/01/01 00:12:22.500: OK
0000/01/01 00:12:22.610: AT+UPSD=0,0,0
0000/01/01 00:12:22.650: 
0000/01/01 00:12:22.650: OK
0000/01/01 00:12:22.750: AT+UPSD=0,100,1
0000/01/01 00:12:22.790: 
0000/01/01 00:12:22.790: OK
U_CELL_NET: connected after 5 second(s).
before pUMqttClientOpen()
after pUMqttClientOpen()
E (746014) Receptic: Connection down..
before uMqttClientConnect()
0000/01/01 00:12:22.890: AT+UMQTT=2,"cssiot01.eurac.edu",1883
0000/01/01 00:12:22.930: 
0000/01/01 00:12:22.930: 
0000/01/01 00:12:22.930: 
0000/01/01 00:12:22.930: OK
0000/01/01 00:12:23.030: AT+CGSN
0000/01/01 00:12:23.070: 
0000/01/01 00:12:23.070: 355438111885391
0000/01/01 00:12:23.070: 
0000/01/01 00:12:23.071: OK
0000/01/01 00:12:23.180: AT+UMQTT=0,"355438111885391"
0000/01/01 00:12:23.220: 
0000/01/01 00:12:23.220: 
0000/01/01 00:12:23.220: 
0000/01/01 00:12:23.220: OK
0000/01/01 00:12:23.320: AT+UMQTT=10,120
0000/01/01 00:12:23.360: 
0000/01/01 00:12:23.360: 
0000/01/01 00:12:23.360: 
0000/01/01 00:12:23.360: OK
U_CELL_MQTT: trying to connect...
0000/01/01 00:12:23.860: AT+UMQTTC=1
0000/01/01 00:12:23.900: 
0000/01/01 00:12:23.900: 
0000/01/01 00:12:23.900: 
0000/01/01 00:12:23.900: OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
0000/01/01 00:12:24.010: AT+UMQTTER
0000/01/01 00:12:24.050: 
0000/01/01 00:12:24.050: +UMQTTER: 13,0
0000/01/01 00:12:24.050: 
0000/01/01 00:12:24.051: 
0000/01/01 00:12:24.051: 
0000/01/01 00:12:24.052: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:12:24.160: AT+UMQTTER
0000/01/01 00:12:24.200: 
0000/01/01 00:12:24.200: +UMQTTER: 13,0
0000/01/01 00:12:24.200: 
0000/01/01 00:12:24.201: 
0000/01/01 00:12:24.201: 
0000/01/01 00:12:24.202: OK
0000/01/01 00:12:24.310: AT+UMQTTER
0000/01/01 00:12:24.350: 
0000/01/01 00:12:24.350: +UMQTTER: 13,0
0000/01/01 00:12:24.350: 
0000/01/01 00:12:24.351: 
0000/01/01 00:12:24.351: 
0000/01/01 00:12:24.352: OK
U_CELL_MQTT: error codes 13, 0.
I (748074) GNSS: Continuous location stopped!
0000/01/01 00:12:25.850: AT+COPS?
0000/01/01 00:12:25.890: 
0000/01/01 00:12:25.890: +COPS: 0,0,"I TIM",9
0000/01/01 00:12:25.891: 
0000/01/01 00:12:25.891: OK
0000/01/01 00:12:26.000: AT+CFUN=4
0000/01/01 00:12:26.330: 
0000/01/01 00:12:26.330: OK
0000/01/01 00:12:26.330: 
0000/01/01 00:12:26.330: +UUMQTTC: 1,0
0000/01/01 00:12:26.331: 
0000/01/01 00:12:26.332: +CREG: 0
0000/01/01 00:12:26.335: 
0000/01/01 00:12:26.337: +CEREG: 0,,,,,,,,
-1: NReg
-1: NReg
E (749584) Receptic: Network is down
0000/01/01 00:12:26.460: AT+CREG?
0000/01/01 00:12:26.500: 
0000/01/01 00:12:26.500: +CREG: 2,0
0000/01/01 00:12:26.500: 
0000/01/01 00:12:26.500: OK
-1: NReg
0000/01/01 00:12:26.800: AT+CGREG?
0000/01/01 00:12:26.840: 
0000/01/01 00:12:26.840: +CGREG: 2,4
0000/01/01 00:12:26.840: 
0000/01/01 00:12:26.840: OK
-1: OoC
0000/01/01 00:12:27.140: AT+CEREG?
0000/01/01 00:12:27.180: 
0000/01/01 00:12:27.180: +CEREG: 4,0
0000/01/01 00:12:27.180: 
0000/01/01 00:12:27.180: OK
-1: NReg
0000/01/01 00:12:27.480: AT+CGATT?
0000/01/01 00:12:27.520: 
0000/01/01 00:12:27.520: +CGATT: 0
0000/01/01 00:12:27.520: 
0000/01/01 00:12:27.520: OK
-1: NReg
U_CELL_NET: disconnected.
0000/01/01 00:12:27.630: AT+UPSV=0
0000/01/01 00:12:27.680: 
0000/01/01 00:12:27.680: OK
U_CELL_PWR: powering off using the PWR_ON pin.
Device powered off
U_CELL: initialising with enable power pin not connected, PWR_ON pin 15 (0x0f) (and is toggled from 1 to 0) and VInt pin 7 (0x07) (and is 1 when module is on).
I (804954) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (804964) gpio: GPIO[7]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
U_CELL_PWR: powering on.
0000/01/01 00:13:22.050: [00]0000/01/01 00:13:22.160: AT
0000/01/01 00:13:22.370: AT
0000/01/01 00:13:22.720: AT
0000/01/01 00:13:23.070: AT
0000/01/01 00:13:23.420: AT
0000/01/01 00:13:24.480: AT

0000/01/01 00:13:24.480: OK
0000/01/01 00:13:24.580: ATE0
0000/01/01 00:13:24.620: ATE0

0000/01/01 00:13:24.620: OK
0000/01/01 00:13:24.720: AT+CMEE=2
0000/01/01 00:13:24.760: 
0000/01/01 00:13:24.760: OK
0000/01/01 00:13:24.860: AT+UDCONF=1,0
0000/01/01 00:13:24.900: 
0000/01/01 00:13:24.900: OK
0000/01/01 00:13:25.000: ATI9
0000/01/01 00:13:25.040: 
0000/01/01 00:13:25.040: 00.12,A00.00
0000/01/01 00:13:25.040: 
0000/01/01 00:13:25.041: OK
0000/01/01 00:13:25.150: AT&C1
0000/01/01 00:13:25.190: 
0000/01/01 00:13:25.190: OK
0000/01/01 00:13:25.290: AT&D0
0000/01/01 00:13:25.330: 
0000/01/01 00:13:25.330: OK
0000/01/01 00:13:25.430: AT+UCGED=2
0000/01/01 00:13:25.470: 
0000/01/01 00:13:25.470: OK
0000/01/01 00:13:25.570: AT&K3
0000/01/01 00:13:25.610: 
0000/01/01 00:13:25.610: OK
0000/01/01 00:13:25.710: AT+UPSV=4
0000/01/01 00:13:25.750: 
0000/01/01 00:13:25.750: OK
0000/01/01 00:13:25.850: AT+UPSMR=1
0000/01/01 00:13:25.890: 
0000/01/01 00:13:25.890: OK
0000/01/01 00:13:25.990: AT+CPSMS?
0000/01/01 00:13:26.030: 
0000/01/01 00:13:26.030: +CPSMS:0,,,"01100000","00000000"
0000/01/01 00:13:26.031: 
0000/01/01 00:13:26.031: OK
0000/01/01 00:13:26.140: AT+CEDRXS?
0000/01/01 00:13:26.180: 
0000/01/01 00:13:26.180: +CEDRXS:
0000/01/01 00:13:26.180: 
0000/01/01 00:13:26.180: OK
0000/01/01 00:13:26.290: AT+UMNOPROF?
0000/01/01 00:13:26.330: 
0000/01/01 00:13:26.330: +UMNOPROF: 100
0000/01/01 00:13:26.330: 
0000/01/01 00:13:26.331: OK
0000/01/01 00:13:26.440: AT+UGPRF?
0000/01/01 00:13:26.480: 
0000/01/01 00:13:26.480: +UGPRF: 2,0,""
0000/01/01 00:13:26.480: 
0000/01/01 00:13:26.481: 
0000/01/01 00:13:26.481: 
0000/01/01 00:13:26.482: OK
0000/01/01 00:13:26.590: AT+CFUN=4
0000/01/01 00:13:26.630: 
0000/01/01 00:13:26.630: OK
U_CELL_NET: preparing to register/connect...
0000/01/01 00:13:26.730: AT+CREG=2
0000/01/01 00:13:26.770: 
0000/01/01 00:13:26.770: OK
0000/01/01 00:13:26.870: AT+CGREG=2
0000/01/01 00:13:26.910: 
0000/01/01 00:13:26.910: OK
0000/01/01 00:13:27.010: AT+CEREG=4
0000/01/01 00:13:27.050: 
0000/01/01 00:13:27.050: OK
0000/01/01 00:13:27.150: AT+CIMI
0000/01/01 00:13:27.190: 
0000/01/01 00:13:27.190: 295050903238861
0000/01/01 00:13:27.190: 
0000/01/01 00:13:27.191: OK
U_CELL_NET: user-specified APN is "em".
0000/01/01 00:13:27.300: AT+CGDCONT=1,"IP","em"
0000/01/01 00:13:27.340: 
0000/01/01 00:13:27.340: OK
U_CELL_NET: setting automatic network selection mode...
0000/01/01 00:13:27.440: AT+COPS?
0000/01/01 00:13:27.480: 
0000/01/01 00:13:27.480: +COPS: 0
0000/01/01 00:13:27.480: 
0000/01/01 00:13:27.480: OK
0000/01/01 00:13:28.480: AT+CFUN=1
0000/01/01 00:13:28.520: 
0000/01/01 00:13:28.520: OK
0000/01/01 00:13:28.620: AT+CREG?
0000/01/01 00:13:28.660: 
0000/01/01 00:13:28.660: +CREG: 2,0
0000/01/01 00:13:28.660: 
0000/01/01 00:13:28.660: OK
0: NReg
0000/01/01 00:13:28.960: AT+CGREG?
0000/01/01 00:13:29.000: 
0000/01/01 00:13:29.000: +CGREG: 2,4
0000/01/01 00:13:29.000: 
0000/01/01 00:13:29.000: OK
0: OoC
0000/01/01 00:13:29.300: AT+CEREG?
0000/01/01 00:13:29.340: 
0000/01/01 00:13:29.340: +CEREG: 4,0
0000/01/01 00:13:29.340: 
0000/01/01 00:13:29.340: OK
0: NReg
0000/01/01 00:13:29.640: AT+CREG?
0000/01/01 00:13:29.680: 
0000/01/01 00:13:29.680: +CREG: 2,0
0000/01/01 00:13:29.680: 
0000/01/01 00:13:29.680: OK
0: NReg
0000/01/01 00:13:29.980: AT+CGREG?
0000/01/01 00:13:30.020: 
0000/01/01 00:13:30.020: +CGREG: 2,4
0000/01/01 00:13:30.020: 
0000/01/01 00:13:30.020: OK
0: OoC
0000/01/01 00:13:30.320: AT+CEREG?
0000/01/01 00:13:30.360: 
0000/01/01 00:13:30.360: +CEREG: 4,0
0000/01/01 00:13:30.360: 
0000/01/01 00:13:30.360: OK
0: NReg
0000/01/01 00:13:30.660: AT+CREG?
0000/01/01 00:13:30.700: 
0000/01/01 00:13:30.700: +CREG: 2,0
0000/01/01 00:13:30.700: 
0000/01/01 00:13:30.700: OK
0: NReg
0000/01/01 00:13:31.000: AT+CGREG?
0000/01/01 00:13:31.040: 
0000/01/01 00:13:31.040: +CGREG: 2,4
0000/01/01 00:13:31.040: 
0000/01/01 00:13:31.040: OK
0: OoC
0000/01/01 00:13:31.340: AT+CEREG?
0000/01/01 00:13:31.380: 
0000/01/01 00:13:31.380: +CEREG: 4,0
0000/01/01 00:13:31.380: 
0000/01/01 00:13:31.380: OK
0: NReg
0000/01/01 00:13:31.680: AT+CREG?
0000/01/01 00:13:31.720: 
0000/01/01 00:13:31.720: +CREG: 2,0
0000/01/01 00:13:31.720: 
0000/01/01 00:13:31.720: OK
0: NReg
0000/01/01 00:13:31.860: 
0000/01/01 00:13:31.860: +CREG: 2
0000/01/01 00:13:31.860: 
0000/01/01 00:13:31.860: +CEREG: 2,,,,,,,,
-1: Search
-1: Search
0000/01/01 00:13:32.020: AT+CGREG?
0000/01/01 00:13:32.060: 
0000/01/01 00:13:32.060: +CGREG: 2,4
0000/01/01 00:13:32.060: 
0000/01/01 00:13:32.060: OK
0: OoC
0000/01/01 00:13:32.360: AT+CEREG?
0000/01/01 00:13:32.400: 
0000/01/01 00:13:32.400: +CEREG: 4,2
0000/01/01 00:13:32.400: 
0000/01/01 00:13:32.400: OK
0: Search
0000/01/01 00:13:32.700: AT+CREG?
0000/01/01 00:13:32.740: 
0000/01/01 00:13:32.740: +CREG: 2,2
0000/01/01 00:13:32.740: 
0000/01/01 00:13:32.740: OK
0: Search
0000/01/01 00:13:33.040: AT+CGREG?
0000/01/01 00:13:33.080: 
0000/01/01 00:13:33.080: +CGREG: 2,4
0000/01/01 00:13:33.080: 
0000/01/01 00:13:33.080: OK
0: OoC
0000/01/01 00:13:33.380: AT+CEREG?
0000/01/01 00:13:33.420: 
0000/01/01 00:13:33.420: +CEREG: 4,2
0000/01/01 00:13:33.420: 
0000/01/01 00:13:33.420: OK
0: Search
0000/01/01 00:13:33.720: AT+CREG?
0000/01/01 00:13:33.760: 
0000/01/01 00:13:33.760: +CREG: 2,2
0000/01/01 00:13:33.760: 
0000/01/01 00:13:33.760: OK
0: Search
0000/01/01 00:13:34.060: AT+CGREG?
0000/01/01 00:13:34.100: 
0000/01/01 00:13:34.100: +CGREG: 2,4
0000/01/01 00:13:34.100: 
0000/01/01 00:13:34.100: OK
0: OoC
0000/01/01 00:13:34.400: AT+CEREG?
0000/01/01 00:13:34.440: 
0000/01/01 00:13:34.440: +CEREG: 4,2
0000/01/01 00:13:34.440: 
0000/01/01 00:13:34.440: OK
0: Search
0000/01/01 00:13:34.740: AT+CREG?
0000/01/01 00:13:34.780: 
0000/01/01 00:13:34.780: +CREG: 2,2
0000/01/01 00:13:34.780: 
0000/01/01 00:13:34.780: OK
0: Search
0000/01/01 00:13:35.080: AT+CGREG?
0000/01/01 00:13:35.120: 
0000/01/01 00:13:35.120: +CGREG: 2,4
0000/01/01 00:13:35.120: 
0000/01/01 00:13:35.120: OK
0: OoC
0000/01/01 00:13:35.420: AT+CEREG?
0000/01/01 00:13:35.460: 
0000/01/01 00:13:35.460: +CEREG: 4,2
0000/01/01 00:13:35.460: 
0000/01/01 00:13:35.460: OK
0: Search
0000/01/01 00:13:35.760: AT+CREG?
0000/01/01 00:13:35.800: 
0000/01/01 00:13:35.800: +CREG: 2,2
0000/01/01 00:13:35.800: 
0000/01/01 00:13:35.800: OK
0: Search
0000/01/01 00:13:36.100: AT+CGREG?
0000/01/01 00:13:36.140: 
0000/01/01 00:13:36.140: +CGREG: 2,4
0000/01/01 00:13:36.140: 
0000/01/01 00:13:36.140: OK
0: OoC
0000/01/01 00:13:36.440: AT+CEREG?
0000/01/01 00:13:36.480: 
0000/01/01 00:13:36.480: +CEREG: 4,2
0000/01/01 00:13:36.480: 
0000/01/01 00:13:36.480: OK
0: Search
0000/01/01 00:13:36.780: AT+CREG?
0000/01/01 00:13:36.820: 
0000/01/01 00:13:36.820: +CREG: 2,2
0000/01/01 00:13:36.820: 
0000/01/01 00:13:36.820: OK
0: Search
0000/01/01 00:13:37.120: AT+CGREG?
0000/01/01 00:13:37.160: 
0000/01/01 00:13:37.160: +CGREG: 2,4
0000/01/01 00:13:37.160: 
0000/01/01 00:13:37.160: OK
0: OoC
0000/01/01 00:13:37.460: AT+CEREG?
0000/01/01 00:13:37.500: 
0000/01/01 00:13:37.500: +CEREG: 4,2
0000/01/01 00:13:37.500: 
0000/01/01 00:13:37.500: OK
0: Search
0000/01/01 00:13:37.800: AT+CREG?
0000/01/01 00:13:37.840: 
0000/01/01 00:13:37.840: +CREG: 2,2
0000/01/01 00:13:37.840: 
0000/01/01 00:13:37.840: OK
0: Search
0000/01/01 00:13:38.140: AT+CGREG?
0000/01/01 00:13:38.180: 
0000/01/01 00:13:38.180: +CGREG: 2,4
0000/01/01 00:13:38.180: 
0000/01/01 00:13:38.180: OK
0: OoC
0000/01/01 00:13:38.480: AT+CEREG?
0000/01/01 00:13:38.520: 
0000/01/01 00:13:38.520: +CEREG: 4,2
0000/01/01 00:13:38.520: 
0000/01/01 00:13:38.520: OK
0: Search
0000/01/01 00:13:38.820: AT+CREG?
0000/01/01 00:13:38.860: 
0000/01/01 00:13:38.860: +CREG: 2,2
0000/01/01 00:13:38.860: 
0000/01/01 00:13:38.860: OK
0: Search
0000/01/01 00:13:39.160: AT+CGREG?
0000/01/01 00:13:39.200: 
0000/01/01 00:13:39.200: +CGREG: 2,4
0000/01/01 00:13:39.200: 
0000/01/01 00:13:39.200: OK
0: OoC
0000/01/01 00:13:39.500: AT+CEREG?
0000/01/01 00:13:39.540: 
0000/01/01 00:13:39.540: +CEREG: 4,2
0000/01/01 00:13:39.540: 
0000/01/01 00:13:39.540: OK
0: Search
0000/01/01 00:13:39.840: AT+CREG?
0000/01/01 00:13:39.880: 
0000/01/01 00:13:39.880: +CREG: 2,2
0000/01/01 00:13:39.880: 
0000/01/01 00:13:39.880: OK
0: Search
0000/01/01 00:13:40.180: AT+CGREG?
0000/01/01 00:13:40.220: 
0000/01/01 00:13:40.220: +CGREG: 2,4
0000/01/01 00:13:40.220: 
0000/01/01 00:13:40.220: OK
0: OoC
0000/01/01 00:13:40.520: AT+CEREG?
0000/01/01 00:13:40.560: 
0000/01/01 00:13:40.560: +CEREG: 4,2
0000/01/01 00:13:40.560: 
0000/01/01 00:13:40.560: OK
0: Search
0000/01/01 00:13:40.860: AT+CREG?
0000/01/01 00:13:40.900: 
0000/01/01 00:13:40.900: +CREG: 2,2
0000/01/01 00:13:40.900: 
0000/01/01 00:13:40.901: OK
0: Search
0000/01/01 00:13:41.200: AT+CGREG?
0000/01/01 00:13:41.240: 
0000/01/01 00:13:41.240: +CGREG: 2,4
0000/01/01 00:13:41.240: 
0000/01/01 00:13:41.241: OK
0: OoC
0000/01/01 00:13:41.410: 
0000/01/01 00:13:41.410: +CREG: 5,"90EF","0AAF9DA2",9
9: RegR
0000/01/01 00:13:41.430: 
0000/01/01 00:13:41.430: +CEREG: 5,"90EF","AAF9DA2",9,,,,
9: RegR
0000/01/01 00:13:41.550: AT+COPS=3,0
0000/01/01 00:13:41.590: 
0000/01/01 00:13:41.590: OK
0000/01/01 00:13:41.690: AT+COPS?
0000/01/01 00:13:41.730: 
0000/01/01 00:13:41.730: +COPS: 0,0,"I TIM",9
0000/01/01 00:13:41.730: 
0000/01/01 00:13:41.731: OK
0000/01/01 00:13:41.840: AT+CGATT?
0000/01/01 00:13:41.880: 
0000/01/01 00:13:41.880: +CGATT: 1
0000/01/01 00:13:41.880: 
0000/01/01 00:13:41.880: OK
0000/01/01 00:13:41.990: AT+CGACT?
0000/01/01 00:13:42.030: 
0000/01/01 00:13:42.030: +CGACT: 1,1
0000/01/01 00:13:42.030: 
0000/01/01 00:13:42.030: OK
0000/01/01 00:13:42.140: AT+UPSD=0,0,0
0000/01/01 00:13:42.180: 
0000/01/01 00:13:42.180: OK
0000/01/01 00:13:42.280: AT+UPSD=0,100,1
0000/01/01 00:13:42.320: 
0000/01/01 00:13:42.320: OK
U_CELL_NET: connected after 15 second(s).
0000/01/01 00:13:42.420: AT+UMQTT=2,"xxxxxxxxxxxxxx",1883
0000/01/01 00:13:42.460: 
0000/01/01 00:13:42.460: 
0000/01/01 00:13:42.460: 
0000/01/01 00:13:42.460: OK
0000/01/01 00:13:42.570: AT+CGSN
0000/01/01 00:13:42.610: 
0000/01/01 00:13:42.610: 355438111885391
0000/01/01 00:13:42.610: 
0000/01/01 00:13:42.611: OK
0000/01/01 00:13:42.720: AT+UMQTT=0,"355438111885391"
0000/01/01 00:13:42.760: 
0000/01/01 00:13:42.760: 
0000/01/01 00:13:42.760: 
0000/01/01 00:13:42.760: OK
0000/01/01 00:13:42.870: AT+UMQTT=10,120
0000/01/01 00:13:42.910: 
0000/01/01 00:13:42.910: 
0000/01/01 00:13:42.910: 
0000/01/01 00:13:42.910: OK
U_CELL_MQTT: trying to connect...
0000/01/01 00:13:43.410: AT+UMQTTC=1
0000/01/01 00:13:43.450: 
0000/01/01 00:13:43.450: 
0000/01/01 00:13:43.450: 
0000/01/01 00:13:43.450: OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
0000/01/01 00:13:43.560: AT+UMQTTER
0000/01/01 00:13:43.600: 
0000/01/01 00:13:43.600: +UMQTTER: 13,0
0000/01/01 00:13:43.600: 
0000/01/01 00:13:43.601: 
0000/01/01 00:13:43.601: 
0000/01/01 00:13:43.602: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:43.710: AT+UMQTTER
0000/01/01 00:13:43.750: 
0000/01/01 00:13:43.750: +UMQTTER: 13,0
0000/01/01 00:13:43.750: 
0000/01/01 00:13:43.751: 
0000/01/01 00:13:43.751: 
0000/01/01 00:13:43.752: OK
0000/01/01 00:13:43.860: AT+UMQTTER
0000/01/01 00:13:43.900: 
0000/01/01 00:13:43.900: +UMQTTER: 13,0
0000/01/01 00:13:43.900: 
0000/01/01 00:13:43.901: 
0000/01/01 00:13:43.901: 
0000/01/01 00:13:43.902: OK
U_CELL_MQTT: error codes 13, 0.
after uMqttClientConnect()
I (827124) GNSS: Bringing up GNSS
0000/01/01 00:13:44.010: AT+CMUX=0,0,,128
0000/01/01 00:13:44.050: 
0000/01/01 00:13:44.050: OK
0000/01/01 00:13:44.680: ATE0
0000/01/01 00:13:44.720: 
0000/01/01 00:13:44.720: OK
0000/01/01 00:13:44.820: AT+CMEE=2
0000/01/01 00:13:44.860: 
0000/01/01 00:13:44.860: OK
0000/01/01 00:13:44.960: AT+UPSV?
0000/01/01 00:13:45.000: 
0000/01/01 00:13:45.000: +UPSV: 4 
0000/01/01 00:13:45.000: 
0000/01/01 00:13:45.001: OK
0000/01/01 00:13:45.110: AT+UPSV=0
0000/01/01 00:13:45.150: 
0000/01/01 00:13:45.150: OK
U_GNSS: initialising with ENABLE_POWER pin not connected, transport type Virtual Serial.
0000/01/01 00:13:45.250: ATI
0000/01/01 00:13:45.290: 
0000/01/01 00:13:45.290: SARA-R422M8S-00B-00
0000/01/01 00:13:45.291: 
0000/01/01 00:13:45.291: OK
0000/01/01 00:13:45.400: AT+UGIND=0
0000/01/01 00:13:45.440: 
0000/01/01 00:13:45.440: 
0000/01/01 00:13:45.440: 
0000/01/01 00:13:45.440: OK
0000/01/01 00:13:45.550: AT+UGPS?
0000/01/01 00:13:45.590: 
0000/01/01 00:13:45.590: +UGPS: 0
0000/01/01 00:13:45.590: 
0000/01/01 00:13:45.591: 
0000/01/01 00:13:45.591: 
0000/01/01 00:13:45.591: OK
0000/01/01 00:13:46.090: AT+UGPS=1,15,127
0000/01/01 00:13:47.250: 
0000/01/01 00:13:47.250: 
0000/01/01 00:13:47.250: 
0000/01/01 00:13:47.250: OK
I (830474) GNSS: Starting continuous location.

0000/01/01 00:13:47.360: AT+UGPS?
0000/01/01 00:13:47.400: 
0000/01/01 00:13:47.400: +UGPS: 1,0
0000/01/01 00:13:47.400: 
0000/01/01 00:13:47.401: 
0000/01/01 00:13:47.401: 
0000/01/01 00:13:47.401: OK
0000/01/01 00:13:47.510: AT+UGPS?
0000/01/01 00:13:47.550: 
0000/01/01 00:13:47.550: +UGPS: 1,0
0000/01/01 00:13:47.550: 
0000/01/01 00:13:47.551: 
0000/01/01 00:13:47.551: 
0000/01/01 00:13:47.551: OK
0000/01/01 00:13:47.660: AT+UGPS=1,1
0000/01/01 00:13:47.700: 
0000/01/01 00:13:47.700: 
0000/01/01 00:13:47.700: 
0000/01/01 00:13:47.700: OK
E (830924) GNSS: Local Aid is off!
U_GNSS: sent command b5 62 06 08 00 00 0e 30.
U_GNSS: decoded UBX response 0x06 0x08: e8 03 01 00 01 00 [body 6 byte(s)].
U_GNSS: sent command b5 62 06 01 02 00 01 07 11 3a.
U_GNSS: decoded UBX response 0x06 0x01: 01 07 00 00 00 00 00 00 [body 8 byte(s)].
U_GNSS: sent command b5 62 06 01 08 00 01 07 01 00 00 00 00 00 18 e2.
U_GNSS: decoded UBX response 0x05 0x01: 06 3e [body 2 byte(s)].
I (831514) GNSS: Continuous location started!
before uMqttClientSubscribe()
0000/01/01 00:13:48.290: AT+UMQTTC=4,1,"xxxxxxxxxxxxxxx"
0000/01/01 00:13:48.340: 
0000/01/01 00:13:48.340: +CME ERROR: Operation not allowed
0000/01/01 00:13:48.341: 
0000/01/01 00:13:48.460: AT+UMQTTER
0000/01/01 00:13:48.500: 
0000/01/01 00:13:48.500: +UMQTTER: 13,0
0000/01/01 00:13:48.500: 
0000/01/01 00:13:48.501: 
0000/01/01 00:13:48.501: 
0000/01/01 00:13:48.502: OK
0000/01/01 00:13:48.610: AT+UMQTTER
0000/01/01 00:13:48.650: 
0000/01/01 00:13:48.650: +UMQTTER: 13,0
0000/01/01 00:13:48.650: 
0000/01/01 00:13:48.651: 
0000/01/01 00:13:48.651: 
0000/01/01 00:13:48.652: OK
U_CELL_MQTT: error codes 13, 0.
after uMqttClientSubscribe()
before uMqttClientPublish()
0000/01/01 00:13:48.760: AT+UMQTTC=9,1,0,"xxxxxxxxxxxx",1
0000/01/01 00:13:48.810: 
0000/01/01 00:13:48.810: +CME ERROR: Operation not allowed
0000/01/01 00:13:48.811: 
0000/01/01 00:13:48.930: AT+UMQTTER
0000/01/01 00:13:48.970: 
0000/01/01 00:13:48.970: +UMQTTER: 13,0
0000/01/01 00:13:48.971: 
0000/01/01 00:13:48.971: 
0000/01/01 00:13:48.971: 
0000/01/01 00:13:48.972: OK
0000/01/01 00:13:49.080: AT+UMQTTER
0000/01/01 00:13:49.120: 
0000/01/01 00:13:49.120: +UMQTTER: 13,0
0000/01/01 00:13:49.121: 
0000/01/01 00:13:49.121: 
0000/01/01 00:13:49.121: 
0000/01/01 00:13:49.122: OK
U_CELL_MQTT: error codes 13, 0.

0000/01/01 00:13:53.910: 
0000/01/01 00:13:53.910: +UUMQTTC: 1,1

0000/01/01 00:14:48.290: AT+UMQTTC=5,"xxxxxxxxxxxx"
0000/01/01 00:14:48.340: 5,"xxxxxxxxxxxxxxx"0000/01/01 00:14:58.410: AT+UMQTTER
0000/01/01 00:15:08.520: AT+UMQTTER

U_CELL_MQTT: error codes -1, -1.

before uMqttClientSubscribe()
0000/01/01 00:15:18.530: AT+UMQTTC=4,1,"xxxxxxxxxxxxxxxxxxxxxx"
0000/01/01 00:15:18.580: 4,1,"xxxxxxxxxxxxxxxxxxxxx"0000/01/01 00:15:28.560: AT+UMQTTER
0000/01/01 00:15:38.670: AT+UMQTTER
U_CELL_MQTT: error codes -1, -1.
after uMqttClientSubscribe()
before uMqttClientPublish()
0000/01/01 00:15:48.680: AT+UMQTTC=9,1,0,"xxxxxxxxxxxx",1
0000/01/01 00:15:48.730: 9,1,0,"xxxxxxxxxxxxxxxx",10000/01/01 00:17:58.690: AT+UMQTTER
0000/01/01 00:18:08.700: AT+UMQTTER
U_CELL_MQTT: error codes -1, -1.

As I already mentioned these issues might be related to some hardware problem (first of all the AT-based power-off fail that forces me to use the PWR_ON pin).

RobMeades commented 4 months ago

Hmmm, maybe my inference about the way your application is written is wrong, maybe something entirely different is going on here. A fundamental question: is your application multi-threaded, i.e. are ubxlib API calls being made from more than one task, or only from a single task?

I had assumed it must be multi-threaded because what I see in that first log with timestamps, the one I commented on above, is this [removing superfluous line endings]:

U_CELL_MQTT: trying to connect...
0000/01/01 00:13:15.220: AT+UMQTTC=1
0000/01/01 00:13:15.261: OK
U_CELL_MQTT: waiting for response for up to 120 second(s)...
0000/01/01 00:13:15.370: AT+UMQTTER
0000/01/01 00:13:15.411: +UMQTTER: 13,0
0000/01/01 00:13:15.412: OK
U_CELL_MQTT: error codes 13, 0.
0000/01/01 00:13:15.520: AT+UMQTTER
0000/01/01 00:13:15.561: +UMQTTER: 13,0
0000/01/01 00:13:15.562: OK
0000/01/01 00:13:15.670: AT+UMQTTER
0000/01/01 00:13:15.711: +UMQTTER: 13,0
0000/01/01 00:13:15.712: OK
U_CELL_MQTT: error codes 13, 0.
I (797680) GNSS: Bringing up GNSS
0000/01/01 00:13:15.820: AT+CMUX=0,0,,128

a) On the face of it there has been an attempt to connect (AT+UMQTTC=1, which will be uMqttClientConnect() -> uCellMqttClientConnect() meaning gUCellPrivateMutex is locked) and, while waiting for the connection to succeed or fail (i.e. to get the +UUMQTTC: 1,x URC), 600 millisecond later, GNSS is being brought up (uNetworkInterfaceUp() -> uCellMuxEnable() [AT+CMUX=0,0,,128] and that has to have locked gUCellPrivateMutex). It seemed to me that mutexes cannot be working if that sequence is to have happened.

(b) Same for the MQTT subscribe operation that follows: this is not about MQTT-protocol publish/subscribe rules, the AT+UMQTTC=4,1 at 00:13:20.111 (uMqttClientSubscribe() -> uCellMqttSubscribe() so gUCellPrivateMutex is now locked) is still running when there is an AT+UMQTTC=9,1,0, just 459 milliseconds later at 00:13:20.570 (uMqttClientPublish() -> uCellMqttPublish(), which has to have locked gUCellPrivateMutex). You can see that the module says +CME ERROR: Operation not allowed because it is still processing the publish request, that transaction has not yet completed, so it is not as though we have lost the URC or something, the module has not sent it.

HOWEVER

If you are not calling uMqttClientGetLastErrorCode(), the only reason the ubxlib code would be calling getLastMqttErrorCode() internally is if it thought the MQTT operation had failed, and pretty much immediately at that. A reason it might think this is if the UART had thought it had received something, effectively a phantom URC. Thing is, the URC processing looks for the prefix string, so +UUMQTTC:; the phantom URC would have to be quite specific. And it should print it in the log.

You've been hinting at a possible HW problem.

first of all the AT-based power-off fail that forces me to use the PWR_ON pin

Can you explain more about this please? I'm guessing that AT+CPWROFF is failing? That's not something I've ever heard of before, maybe if we focus on that it will turn up a clue.

RobMeades commented 4 months ago

One other thing to confirm, in case of a misunderstanding: in the uMqttClientConnection_t structure you pass to uMqttClientConnect(), I believe you are setting a pKeepGoingCallback function; can you confirm that function is returning true?

tommas0serafin commented 4 months ago

Hey Rob, So the application has two threads, one for the MQTT tasks and one that handles the GNSS.

The power-off with the AT commands (i.e. AT+CPWROFF) always fails. With that I mean the modules immediately powers down but, I guess because of the UART-related current leak, it stays in this in-between state where it can still be poked by the library checks. However when the power-off API tries with the hard power-off via PWR_ON pin instead of shutting down, the modules turns on again (V_INT comes back to 1.8v).

The callback function I wrote actually checks the status of the network from the devHandle and might return true or false accordingly. Is this a bad idea?

Thanks again for your support

RobMeades commented 4 months ago

So the application has two threads, one for the MQTT tasks and one that handles the GNSS.

That should be fine, we have a heavily multi-threaded example which does a similar thing.

The power-off with the AT commands (i.e. AT+CPWROFF) always fails. With that I mean the modules immediately powers down but, I guess because of the UART-related current leak, it stays in this in-between state where it can still be poked by the library checks. However when the power-off API tries with the hard power-off via PWR_ON pin instead of shutting down, the modules turns on again (V_INT comes back to 1.8v).

That is very strange indeed, seems as though the module is actively able to draw power from the UART IO lines. The pulse on the PWR_ON HW pin is a toggle (i.e. if the module is off it switches it on, if the module is on it switches it off), which is why the ubxlib code always checks if the module is up first by bouncing AT off it; if responsiveness to an AT check isn't reliable proof that the module is powered on or off, things are going to get very confused indeed. Not sure I can advise you how to proceed on how HW issues though, not really my area I'm afraid.

The callback function I wrote actually checks the status of the network from the devHandle and might return true or false accordingly. Is this a bad idea?

It is certainly not necessary: the module operation will fail anyway if the network status is such that the operation cannot succeed and calling into a ubxlib API function from a callback out of the ubxlib API can lead to problems: some API functions involve AT commands that have URC-style responses that get put into a callback queue, a queue which your callback may already be in, leading to the API locking up. Better just to use the callback as your application's timeout/watchdog/abandon-that-operation-please control based on information local to it.

tommas0serafin commented 4 months ago

Hey Rob,

The +UMQTTER: 13,0 was related to the callback, Now that I set it to false I'm not experiencing the issue anymore.

About this point, I think neither of us is actually supposed to solve it.

Thanks again for your time,

Take care

RobMeades commented 4 months ago

That's excellent news, I leave you in the capable hands of your HW people :-).