Issue #1: flushing UART RX, extended logging

[avbentem]

This adds flushing the LoRa UART RX buffer each time a command is about to be sent, and will also log the flushed bytes if debugging is enabled.

In the original code, flushing of the RX buffer is only done for the first command in configLora. That would still make a subsequent step in the configuration fail when encountering, e.g., just a single newline rather than a proper reply (that starts with LORA_FRAME_START, 0x23, followed by a byte that confirms the command that was just sent).

For me, this fix solves issue #1, the endless reboot loop when activating the gateway.

Notes

• For me, RX flushing is mostly only effective once: when invoking configureRXChain(0, ...) I consistently still see a single \r or 0x0D CR in the receive buffer. However, when enabling logging, one can see another CR was already printed (and hence consumed) for the recv_rpl reply of the previous command, being getVersion(). So where does this excessive CR originate from?

  • Does LORA_COMMAND_VERSION output two CRs for some revisions of the LoRa module?
  • Could it be some keep-alive mechanism, and should empty lines be ignored by design?
  • ...?

• I sometimes also see RX flushing being effective before the very first command, then showing a few (random?) bytes; maybe the buffer is not clean after a reboot? I did not investigate.

• The code uses status *= configure... which forces status = false if one of the steps fails, but still executes all steps even if one has already failed. That makes debugging hard, so I added some additional logging. (I feel one should consider something like status &= configure... or status = status && configure... instead.)

• I've not encountered the new logging for LORA: UART TIMEOUT.

• Tested with EU-868, and a LoRa module that shows at its bottom side:

  LG8501601782 LG-X271 REV: C

• Some logging is included below to show where LORA: flushing is printed for me.

Logging

The following log shows the one occurrence of LORA: flushing: 0d.

For me (and I've seen it in other people's logs as well) a lot of serial debug output gets lost at 115,200 baud. Even at 921,600 baud the output can be very confusing, as lines (partially) go missing or are merged into something that might look feasible but is rubbish. It seems the firmware would benefit greatly from logging functions that await for their output buffer to clear before continuing.

This log has been created by:

• In system_init.c, using SYS_ERROR_DEBUG:

  
  SYS_DEBUG_INIT debugInit =
  {
      .moduleInit = {0},
      .errorLevel = SYS_ERROR_DEBUG
  };

• In system_config.h, using:

  #define DRV_USART_BAUD_RATE_IDX0 921600

• Enabling some more logging that is commented out in the code.

• Replacing SYS_CONSOLE_PRINT with SYS_PRINT as otherwise I would not see the output.

• Using "%02x" rather than "%#x" to print hexadecimal values with leading zeroes.

CNFG: Load online user config state change to 7
CNFG: Configuring LoRa module
LORA: Changing state from 2 to 4
LORA: Starting reconfiguration

LORA: send_cmd: 23 31 01 00 00 55 0d 
LORA: recv_rpl: 23 31 01 00 00 55 0d
LORA: sendCommand OK

LORA: send_cmd: 23 3a 01 00 00 5e 0d 
LORA: recv_rpl: 23 3a 10 00 01 01 4c 47 38 35 30 31 36 30 31 37 38 32 04 01 0d
LORA: sendCommand OK
LORA: version: 01

RF: 0,1,867500000
LORA: flushing: 0d 
LORA: send_cmd: 23 34 06 00 00 01 e0 ff b4 33 24 0d 
LORA: recv_rpl: 23 34 01 00 00 58 0d
LORA: sendCommand OK

RF: 1,1,868500000
LORA: send_cmd: 23 34 06 00 01 01 20 42 c4 33 b8 0d 
LORA: recv_rpl: 23 34 01 00 00 58 0d
LORA: sendCommand OK

IF: 0,1,1,-400000
LORA: send_cmd: 23 35 07 00 00 01 01 80 e5 f9 ff be 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 1,1,1,-200000
LORA: send_cmd: 23 35 07 00 01 01 01 c0 f2 fc ff 0f 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 2,1,1,0
LORA: send_cmd: 23 35 07 00 02 01 01 00 00 00 00 63 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 3,1,0,-400000
LORA: send_cmd: 23 35 07 00 03 01 00 80 e5 f9 ff c0 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 4,1,0,-200000
LORA: send_cmd: 23 35 07 00 04 01 00 c0 f2 fc ff 11 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 5,1,0,0
LORA: send_cmd: 23 35 07 00 05 01 00 00 00 00 00 65 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 6,1,0,200000
LORA: send_cmd: 23 35 07 00 06 01 00 40 0d 03 00 b6 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF: 7,1,0,400000
LORA: send_cmd: 23 35 07 00 07 01 00 80 1a 06 00 07 0d 
LORA: recv_rpl: 23 35 01 00 00 59 0d
LORA: sendCommand OK

IF8: 1,1,-200000,250000,7
LORA: send_cmd: 23 36 08 00 01 01 c0 f2 fc ff 02 02 14 0d 
LORA: recv_rpl: 23 36 01 00 00 5a 0d
LORA: sendCommand OK

IF9: 1,1,300000,125000,50000
LORA: send_cmd: 23 37 0b 00 01 01 e0 93 04 00 03 50 c3 00 00 f4 0d 
LORA: recv_rpl: 23 37 01 00 00 5b 0d
LORA: sendCommand OK

LORA: send_cmd: 23 40 01 00 34 98 0d 
LORA: recv_rpl: 23 40 01 00 00 64 0d
LORA: sendCommand OK

LORA: send_cmd: 23 31 01 00 00 55 0d 
LORA: recv_rpl: 23 31 01 00 00 55 0d
LORA: sendCommand OK

LORA: send_cmd: 23 30 01 00 00 54 0d 
MON: SYS Stack size: 2831
MON: heap usage: 152KB (233KB), free: 187KB
LORA: recv_rpl: 23 30 01 00 00 54 0d
LORA: sendCommand OK
LORA: configLora OK
LORA: Configuration succeeded
LORA: Starting operation
LORA: Changing state from 4 to 6

[johanstokking]

Thanks very much @avbentem !

There's an update coming up, I'll check whether we can incorporate this as well.

[martinichka]

Hi @avbentem,

Thank for your PR. Great that you managed to stop the reboots. We are working on the issue to solve the root cause of the communication failures (more on it later today on the forum). Your PR is clean and does not harm. We will merge it and generate a beta firmware, while solving the root cause.

Thanks again