Strange message sent by Electron

[mermaja]

Hello.

First of all I want to congratulate Particle as I have been deploying for several years unsurveilled systems using the Electron (2G version) and I am more than satisfied with its reliability. Thank you for such a good device!

This very morning I have deployed a system that reads environmental data -temperature, humidity, ambient light…- and sends them to a server using a proprietary UDP based protocol. Everything works fine, the Electron is accurate as a clock, but sometimes the server receives strange messages not related to the protocol. Astonishingly the 4 bytes of the message are, translated to text, AT+U. The program sends 4 byte ACK messages but not with this content. I have detected that these strange messages are more frequent when the cellular network quality is worse. In addition, when testing the protocol with a photon using wifi, these kind of messages never appear.

The protocol is robust and the system is not affected by these spurious messages, but I am intrigued and I would like to know where they come from. I supose they are related with the communication between the UDP firmware and the UBLOX modem, but any additional information will be welcome.

Regards and thank you for your help.
Germán.

[joel]

That is pretty interesting…

You are correct that AT+U is related to the cellular modem. The modem is controlled with an AT command set which are all prefixed by AT+. There isn’t an AT+U command but there is an AT+USOST command which is the UDP transmit command used on the Electron. Likely the modem waiting for the 4-bytes data portion but getting de-synced in some fashion so that a following retry supplies AT+USOST with 4-bytes snipped off and used as data.

Can you confirm what version of Device-OS you are running? How often does this happen? Is there any chance you would be willing to setup some low-level tracing to reproduce the issue and pass that trace along?

[mermaja]

Hello.

The device is running OS 1.4.2

The strange message does not appear often. With the device placed at is definitive location it has only happened once -it is there less than a day!- and curiously after the first communication with the server.

When testing the system in a different location, with more problems connecting to the cellular network, the strange messages appeared more often, lets say 10 - 20% of the interactions with the server.

No problem in performing low level tracing. I am using the electron in several projects so it will be useful for all of us.

Regards,
Germán.

[joel]

Low-level logging is pretty easy on an Electron.

Go to https://github.com/particle-iot/device-os/releases/tag/v1.4.2 and flash the three +debug versions of system part 1/2/3 for your electron. If possible, also consider upgrading to 1.4.3 which fixes a low-level reentrancy issue in newlib which can cause rare firmware panics (but wouldn’t be the issue here).

Then make sure your application firmware has a line somewhat like the following to enable logging out the main serial port.

SerialLogHandler *logHandler = new SerialLogHandler(115200, LOG_LEVEL_ALL);

Then just let it run and use particle serial monitor --follow or another serial terminal to log all output to a file. It will have a lot of very verbose logging around the Cell interface and other Device-OS internals which may help shed some light on sequencing around the issue. If you can note what time the AT+U showed up on your server that would also be very helpful as otherwise it might not be immediately apparent from the log.

[mermaja]

Thank you, Joel.

The electron in which we detected the problem is installed at its definitive location -in the middle of the mountain- so I will unpack a fresh one this weekend and perform the tests you suggest. I will use firmware 1.4.3. Relating the log to the problem we detected should not be difficult as our server logs and timestamps every transaction that it receives.

Regards.

[mermaja]

Hello.

First of all, I wish a happy 2020 to the Particle community!

I am having problems trying to debug the system and relate the logs to the strange AT+U messages I get on my server (I still receive unexpected messages, although not very often). I am using Windows 10.

First of all, not all serial tools seem to work. The Serial Monitor from Arduino Ide or a C Serial Port library I use for my developments recognize and open the port, but they do not receive and show data.

The particle tool you suggest resets my computer sometimes when using --follow.

But the main problem is that the log stops while the electron continues working and sending UDP messages. I have used particle serial monitor and Mobaterm application, and in both cases the log stopped after “CIEV matched: 9,1”. It has happened twice, the first time I thought it was due to Mobaterm, but the second one has shown when using the particle CLI, so I think it is a problem related with the electron. I copy below the full, but short, debug session.

Regards,
Germán.

Opening serial monitor for com port: "COM46"
Serial monitor opened successfully:
[ ElectronSerialPipe::begin ] pipeTx=0 pipeRx=0

[ Modem::powerOn ] = = = = = = = = = = = = = =
    30.403 AT send       4 "AT\r\n"
    30.543 AT read UNK   3 "AT\r"
    30.544 AT read OK    6 "\r\nOK\r\n"
    30.544 AT send       9 "AT+CGMM\r\n"
    30.577 AT read UNK   8 "AV+CGMM\r"
    30.578 AT read UNK  13 "\r\nSARA-G350\r\n"
    30.579 AT read OK    6 "\r\nOK\r\n"
    30.780 AT send       6 "ATE0\r\n"
    30.812 AT read UNK   5 "A\xd4E0\r"
    30.813 AT read OK    6 "\r\nOK\r\n"
    30.813 AT send      11 "AT+CMEE=2\r\n"
    30.845 AT read OK    6 "\r\nOK\r\n"
    30.845 AT send      19 "AT+CMER=1,0,0,2,1\r\n"
    30.879 AT read OK    6 "\r\nOK\r\n"
    30.879 AT send      15 "AT+IPR=115200\r\n"
    30.910 AT read OK    6 "\r\nOK\r\n"
    31.010 AT send      10 "AT+CPIN?\r\n"
    31.044 AT read ERR  37 "\r\n+CME ERROR: operation not allowed\r\n"
    31.724 AT read  +   14 "\r\n+CIEV: 9,0\r\n"
CIEV matched: 9,0
    32.046 AT send      10 "AT+CPIN?\r\n"
    32.078 AT read  +   16 "\r\n+CPIN: READY\r\n"
    32.079 AT read OK    6 "\r\nOK\r\n"

[ Modem::init ] = = = = = = = = = = = = = = =
    32.079 AT send       9 "AT+CGSN\r\n"
    32.115 AT read UNK  19 "\r\n353161070767705\r\n"
    32.123 AT read OK    6 "\r\nOK\r\n"
    32.123 AT send       9 "AT+CGMI\r\n"
    32.155 AT read UNK  10 "\r\nu-blox\r\n"
    32.157 AT read OK    6 "\r\nOK\r\n"
    32.157 AT send       9 "AT+CGMR\r\n"
    32.189 AT read UNK   9 "\r\n08.70\r\n"
    32.191 AT read OK    6 "\r\nOK\r\n"
    32.191 AT send       6 "ATI9\r\n"
    32.225 AT read UNK  16 "\r\n08.70,A00.02\r\n"
    32.227 AT read OK    6 "\r\nOK\r\n"
    32.227 AT send       9 "AT+CCID\r\n"
    32.261 AT read  +   30 "\r\n+CCID: 8934076500002697332\r\n"
    32.263 AT read OK    6 "\r\nOK\r\n"
    32.263 AT send      11 "AT+CMGF=1\r\n"
    32.296 AT read OK    6 "\r\nOK\r\n"
    32.296 AT send      13 "AT+CNMI=2,1\r\n"
    32.330 AT read OK    6 "\r\nOK\r\n"
    32.330 AT send       9 "AT+CIMI\r\n"
    32.362 AT read UNK  19 "\r\n214074300560129\r\n"
    32.364 AT read OK    6 "\r\nOK\r\n"
    32.364 AT send      13 "AT+COPS=3,2\r\n"
    32.399 AT read OK    6 "\r\nOK\r\n"
    32.399 AT send      11 "AT+UPSV=1\r\n"
    32.432 AT read OK    6 "\r\nOK\r\n"
0000032433 [system] INFO: Sim Ready
0000032433 [system] INFO: ARM_WLAN_WD 1

[ Modem::register ] = = = = = = = = = = = = = =
    32.433 AT send      12 "AT+CGREG=2\r\n"
    32.466 AT read OK    6 "\r\nOK\r\n"
    32.466 AT send      11 "AT+CREG=2\r\n"
    32.498 AT read OK    6 "\r\nOK\r\n"
    32.498 AT send      10 "AT+CREG?\r\n"
    32.532 AT read  +   14 "\r\n+CREG: 2,0\r\n"
    32.534 AT read OK    6 "\r\nOK\r\n"
    32.534 AT send      11 "AT+CGREG?\r\n"
    32.568 AT read  +   15 "\r\n+CGREG: 2,2\r\n"
    32.569 AT read OK    6 "\r\nOK\r\n"
    32.569 AT send      10 "AT+URAT?\r\n"
    32.603 AT read ERR  23 "\r\n+CME ERROR: unknown\r\n"
    32.603 AT send      10 "AT+CREG?\r\n"
    32.637 AT read  +   14 "\r\n+CREG: 2,0\r\n"
    32.639 AT read OK    6 "\r\nOK\r\n"
    32.639 AT send      11 "AT+CGREG?\r\n"
    32.671 AT read  +   15 "\r\n+CGREG: 2,2\r\n"
    32.673 AT read OK    6 "\r\nOK\r\n"
    45.333 AT read  +   14 "\r\n+CIEV: 2,3\r\n"
    45.335 AT read  +   14 "\r\n+CIEV: 9,1\r\n"
CIEV matched: 9,1