Git Product home page Git Product logo

Comments (18)

tommas0serafin avatar tommas0serafin commented on September 21, 2024 1

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.

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024 1

Hey Rob,

  • 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.

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

  • 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.

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

Thanks again for your time,

Take care

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024

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.

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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?

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024

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

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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?

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024

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

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

  • An application thread calls uMqttClientConnect(), which results in the MQTT connection request AT+UMQTTC=1, at 00:13:15.220; at this point execution of that thread is in uCellMqttClientConnect() -> connect() and the U_CELL_MQTT_CLIENT_ENTRY_FUNCTION macro at the start of uCellMqttClientConnect() will have called entryFunction(), which will have locked the cellular API mutex gUCellPrivateMutex; the thread is sitting there looping, with that mutex locked, waiting for the response.
  • While uMqttClientConnect() is running, another application thread calls uNetworkInterfaceUp() to bring up the internal GNSS chip within the SARA-R422M8S; doing this brings up the CMUX (see AT+CMUX=0,0,,128 at 00:13:15.820). The effect of this is to swap-out the underlying AT client (by calling uCellMuxEnable(), which calls the internal function uCellMuxPrivateEnable()); the original AT client will remain locked and it will be replaced with a new AT client that pushes commands down the CMUX channel instead, beside the GNSS commands running on another CMUX channel. The moment this happens in the code is just here: you can see that it replaces the atHandle variable inside the cellular pInstance pointer with the new one. This is all fine, the ubxlib code is designed for thread-safety, that's what the mutexes are for. But hang on a second...
  • Here's the bit I don't understand: uCellMuxEnable() won't run unless it can get a lock on gUCellPrivateMutex, which it should not be able to do because the other thread still has a lock on it. So if mutexes are working, I don't see how the sequence above can ever happen.
  • Anyway, at 00:13:17.251 the +UUMQTTC: 1,1 URC comes back; do you have any diagnostic prints in your application that we should see if uMqttClientConnect() returns at this point? It would be interesting to know if it does or if, for reasons to do with the CMUX thing above, the URC is being ignored. My guess is that it probably does return because...
  • At 00:13:20.111 there is an AT+UMQTTC=4,1, which would result from an application call to uMqttClientSubscribe() -> uCellMqttSubscribe() -> subscribe(); since uCellMqttSubscribe() is also gated by U_CELL_MQTT_CLIENT_ENTRY_FUNCTION it could not be done unless gUCellPrivateMutex were lockable.
  • Here's the next bit I don't understand: at 00:13:20.570 there is an AT+UMQTTC=9,1,0, which is a call to uMqttClientPublish() -> uCellMqttPublish() -> publish() and the same thing applies: the thread should not be able to get here as uMqttClientSubscribe() won't have returned yet because the URC indicating the success of the subscribe has not come back from the module; you can see the module object to this with the +CME ERROR: Operation not allowed: it is still busy doing the subscribe.
  • There seem to be occurrences of AT+UMQTTER about every 150 ms: I guess the application is polling uMqttClientGetLastErrorCode() in the background or some such? While it can do that, it doesn't mean a great deal until one of the uMqtt API calls has returned an error. Note that the ubxlib code will, internally, do an AT+UMQTTER when an error has occurred anyway, purely to get that information into the AT debug log.
  • The final bit I've just realised I don't understand: you won't be surprised to hear me say that uMqttClientGetLastErrorCode() -> uCellMqttGetLastErrorCode() -> getLastMqttErrorCode() is also guarded by a lock on gUCellPrivateMutex, so any thread calling it should be blocked, it should not be possible for all of the AT+UMQTTER's to appear in the log like that.

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

Unh?

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024

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.

  • Anyway, at 00:13:17.251 the +UUMQTTC: 1,1 URC comes back; do you have any diagnostic prints in your application that we should see if uMqttClientConnect() returns at this point? It would be interesting to know if it does or if, for reasons to do with the CMUX thing above, the URC is being ignored. My guess is that it probably does return because...

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

  • Here's the next bit I don't understand: at 00:13:20.570 there is an AT+UMQTTC=9,1,0, which is a call to uMqttClientPublish() -> uCellMqttPublish() -> publish() and the same thing applies: the thread should not be able to get here as uMqttClientSubscribe() won't have returned yet because the URC indicating the success of the subscribe has not come back from the module; you can see the module object to this with the +CME ERROR: Operation not allowed: it is still busy doing the subscribe.

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

  • There seem to be occurrences of AT+UMQTTER about every 150 ms: I guess the application is polling uMqttClientGetLastErrorCode() in the background or some such? While it can do that, it doesn't mean a great deal until one of the uMqtt API calls has returned an error. Note that the ubxlib code will, internally, do an AT+UMQTTER when an error has occurred anyway, purely to get that information into the AT debug log.
    The final bit I've just realised I don't understand: you won't be surprised to hear me say that uMqttClientGetLastErrorCode() -> uCellMqttGetLastErrorCode() -> getLastMqttErrorCode() is also guarded by a lock on gUCellPrivateMutex, so any thread calling it should be blocked, it should not be possible for all of the AT+UMQTTER's to appear in the log like that.

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).

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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?

from ubxlib.

tommas0serafin avatar tommas0serafin commented on September 21, 2024

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

  • 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.

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).

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

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

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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.

from ubxlib.

RobMeades avatar RobMeades commented on September 21, 2024

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

from ubxlib.

Related Issues (20)

Recommend Projects

  • React photo React

    A declarative, efficient, and flexible JavaScript library for building user interfaces.

  • Vue.js photo Vue.js

    🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.

  • Typescript photo Typescript

    TypeScript is a superset of JavaScript that compiles to clean JavaScript output.

  • TensorFlow photo TensorFlow

    An Open Source Machine Learning Framework for Everyone

  • Django photo Django

    The Web framework for perfectionists with deadlines.

  • D3 photo D3

    Bring data to life with SVG, Canvas and HTML. 📊📈🎉

Recommend Topics

  • javascript

    JavaScript (JS) is a lightweight interpreted programming language with first-class functions.

  • web

    Some thing interesting about web. New door for the world.

  • server

    A server is a program made to process requests and deliver data to clients.

  • Machine learning

    Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.

  • Game

    Some thing interesting about game, make everyone happy.

Recommend Org

  • Facebook photo Facebook

    We are working to build community through open source technology. NB: members must have two-factor auth.

  • Microsoft photo Microsoft

    Open source projects and samples from Microsoft.

  • Google photo Google

    Google ❤️ Open Source for everyone.

  • D3 photo D3

    Data-Driven Documents codes.