RAK3172 and RAK7289V2 Communication Error Log Analysis Related Questions

LPWAN Industrial Gateways / Concentrators
1

[Equipment and servers in use]

  1. RAK3172
  2. RAK7289V2
  3. Chirpstack V4

Hello~

I’m asking you a question to analyze the log because there is an error during communication test with RAK7289V2 with RAK3172.

When transferring data from RAK3172, “+EVT:SEND_CONFIRMED_FAILED (4)” error occurs, and the gateway log was checked to analyze it

On RAK7289V2, I don’t think I can see logs output that match the transmission time zone.

However, during the gateway log, a log like “user.notice data-broker: data-broker timeout, restart it” was output, and I wonder if this is dust.

[RAK3172 Log]
[2024-06-04 02:00:49.829] modemTx->AT
[2024-06-04 02:00:50.180] OK
[2024-06-04 02:00:50.180] modemTx->AT+NJS=?
[2024-06-04 02:00:50.547] AT+NJS=1
[2024-06-04 02:00:50.547] OK
[2024-06-04 02:00:55.591] modemTx->AT+SEND=9:360C03EE0000000501000064AAA6
[2024-06-04 02:00:55.959] OK
[2024-06-04 02:01:02.285] +EVT:SEND_CONFIRMED_FAILED(4)
[2024-06-04 02:01:04.362] modemTx->AT+SEND=9:360C03EE0000000E010000640F67
[2024-06-04 02:01:04.743] OK
[2024-06-04 02:01:08.704] +EVT:SEND_CONFIRMED_OK
[2024-06-04 02:01:08.704] +EVT:RX_1:-76:6:UNICAST:9:400301b124

[RAK7289V2 Log]
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ##### 2024-06-04 02:00:51 UTC #####
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### [UPSTREAM] ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # RF packets received by concentrator: 2
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # RF packets forwarded: 2 (133 bytes)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # PUSH_DATA datagrams sent: 3 (945 bytes)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # PUSH_DATA acknowledged: 100.00%
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### [DOWNSTREAM] ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # PULL_DATA sent: 6 (100.00% acknowledged)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # RF packets sent to concentrator: 0 (0 bytes)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # TX errors: 0
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # TX rejected (collision packet): 15.28% (req:72, rej:11)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # TX rejected (collision beacon): 0.00% (req:72, rej:0)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # TX rejected (too late): 0.00% (req:72, rej:0)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # TX rejected (too early): 41.67% (req:72, rej:30)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### SX1302 Status ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # SX130X counter (INST): 1082671339
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # SX130X time (PPS): 1082251806, offset us 0
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # BEACON queued: 0
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # BEACON sent so far: 0
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # BEACON rejected: 0
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### [JIT] ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: #--------
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### [GPS] ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # Valid time reference (age: 0 sec)
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: # GPS coordinates: latitude 33.45046, longitude 126.57281, altitude 392 m
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ### Concentrator[0] temperature: 33 C ###
Tue Jun 4 02:00:51 2024 user.notice lora_pkt_fwd[4677]: ##### END #####
Tue Jun 4 02:00:52 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:00:52] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:00:54 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:00:54] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:00:56 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:00:56] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:00:58 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:00:58] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:01 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:01] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:03 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:03] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:04 2024 user.notice data-broker: data-broker timeout, restart it
Tue Jun 4 02:01:05 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:05] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:07 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:07] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:09 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:09] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:11 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:11] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:13 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:13] “GET /diag/syslog HTTP/1.0” 200 -
Tue Jun 4 02:01:15 2024 user.info restify: 127.0.0.1 - - [04/Jun/2024 02:01:15] “GET /diag/syslog HTTP/1.0” 200 -

2

Hi @song ,

It is unlikely that this log causes the downlink failure user.notice data-broker: data-broker timeout, restart it.

On your setup,

  1. How far is the gateway to the device?
  2. What spreading factor (DR) are you using?
  3. What RSSI and SNR values do you usually get?
  4. Is the downlink error always happen? Or there is specific instance only like for example just on the first tranmission, after certain interval, etc.?