search

chirpstack / chirpstack-gateway-bridge

ChirpStack Gateway Bridge abstracts Packet Forwarder protocols into Protobuf or JSON over MQTT.
https://www.chirpstack.io
MIT License
423 stars 272 forks source link

Gateway bridge on Kerlink iStation only forwards a few messages after bootin, then stops publishing to MQTT #214

Closed ldorigo closed 1 year ago

ldorigo commented 1 year ago

What happened?

I already posted about this on the community forum (https://forum.chirpstack.io/t/kerlink-istation-heartbeat-messages-are-sent-to-the-gateway-but-most-uplink-messages-are-lost/14922/6), but I'm now relatively confident it's a bug in the Gateway Bridge so I'm opening an issue here. Already explained the issue in detail there so refer there for more detail.

The forwarder appears to timeout on most messages it forwards to the gateway-bridge. Some messages go through, however - notably, just after the gateway is rebooted. Relevant logs where one packet goes through and one does not:

2022-10-05T11:26:53.969143+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:53.968844464+02:00" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushData                   
2022-10-05T11:26:53.975921+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:53.975689768+02:00" level=debug msg="backend/semtechudp: sending udp packet to gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushACK                       
2022-10-05T11:26:55.817461+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:55.817273733+02:00" level=debug msg="[pinger]   ping check 4.246189219" module=mqtt                                                                                  
2022-10-05T11:26:56.989257+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.988963004+02:00" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushData                   
2022-10-05T11:26:56.991936+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.991619789+02:00" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=eu868/gateway/7076ff0056070a51/event/up uplink_id=14509                 
2022-10-05T11:26:56.992987+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.992670502+02:00" level=debug msg="[client]   enter Publish" module=mqtt                                                                                           
2022-10-05T11:26:56.994727+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.993680547+02:00" level=debug msg="[client]   sending publish message, topic: eu868/gateway/7076ff0056070a51/event/up" module=mqtt                                 
2022-10-05T11:26:56.997848+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.997521717+02:00" level=debug msg="[net]      obound msg to write 0" module=mqtt                                                                                   
2022-10-05T11:26:56.998758+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:56.995323286+02:00" level=debug msg="backend/semtechudp: sending udp packet to gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushACK                       
2022-10-05T11:26:57.004184+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:57.004024005+02:00" level=debug msg="[net]      obound wrote msg, id: 0" module=mqtt                                                                                 
2022-10-05T11:26:57.004455+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:26:57.004333019+02:00" level=debug msg="[net]      outgoing waiting for an outbound message" module=mqtt                                                                
2022-10-05T11:27:00.004971+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.00453268+02:00" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushData                    
2022-10-05T11:27:00.005747+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.005544391+02:00" level=debug msg="backend/semtechudp: sending udp packet to gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushACK                       
2022-10-05T11:27:00.817333+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.817109034+02:00" level=debug msg="[pinger]   ping check 3.812699679" module=mqtt                                                                                  
2022-10-05T11:27:00.817607+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.817484051+02:00" level=debug msg="[pinger]   keepalive sending ping" module=mqtt                                                                                  
2022-10-05T11:27:00.849633+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.849382798+02:00" level=debug msg="[net]      startIncoming Received Message" module=mqtt                                                                          
2022-10-05T11:27:00.849965+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.849830151+02:00" level=debug msg="[net]      startIncomingComms: got msg on ibound" module=mqtt                                                                   
2022-10-05T11:27:00.850251+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.850125831+02:00" level=debug msg="[net]      startIncomingComms: received pingresp" module=mqtt                                                                   
2022-10-05T11:27:00.853485+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:00.853103963+02:00" level=debug msg="[net]      logic waiting for msg on ibound" module=mqtt                                                                         
2022-10-05T11:27:01.557169+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:01.55685516+02:00" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="127.0.0.1:35872" protocol_version=2 type=PullData                    
2022-10-05T11:27:01.557680+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:01.557488188+02:00" level=debug msg="backend/semtechudp: sending udp packet to gateway" addr="127.0.0.1:35872" protocol_version=2 type=PullACK                       
2022-10-05T11:27:01.559447+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:01.559149262+02:00" level=debug msg="integration/mqtt: set gateway subscription" gateway_id=7076ff0056070a51 subscribe=true                                          
2022-10-05T11:27:01.559752+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:01.559608616+02:00" level=debug msg="integration/mqtt: gateway subscription set" gateway_id=7076ff0056070a51 subscribe=true                                          
2022-10-05T11:27:03.017350+02:00 klk-wiis-070A51 chirpstack-gateway-bridge[1184]: time="2022-10-05T11:27:03.01703189+02:00" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="127.0.0.1:37642" protocol_version=2 type=PushData

Packet Forwarder:

:26:53.964734+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  02 AD 37 00 70 76 FF 00 56 07 0A 51 7B 22 72 78 70 6B 22 3A 5B 7B 22 61 65 73 6B 22 3A 30 2C 22  |..7.pv..V..Q{"rxpk":[{"aesk":0,"|                                                                                                                      
:26:53.965841+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  62 72 64 22 3A 33 2C 22 63 6F 64 72 22 3A 22 34 2F 35 22 2C 22 64 61 74 61 22 3A 22 22 2C 22 64  |brd":3,"codr":"4/5","data":"","d|                                                                                                                      
:26:53.966435+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  61 74 72 22 3A 22 53 46 37 42 57 31 32 35 22 2C 22 64 65 6C 61 79 65 64 22 3A 74 72 75 65 2C 22  |atr":"SF7BW125","delayed":true,"|                                                                                                                      
:26:53.966902+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  66 72 65 71 22 3A 38 36 37 2E 37 2C 22 6A 76 65 72 22 3A 32 2C 22 6D 6F 64 75 22 3A 22 4C 4F 52  |freq":867.7,"jver":2,"modu":"LOR|                                                                                                                      
:26:53.967252+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  41 22 2C 22 72 73 69 67 22 3A 5B 7B 22 61 6E 74 22 3A 30 2C 22 63 68 61 6E 22 3A 33 2C 22 6C 73  |A","rsig":[{"ant":0,"chan":3,"ls|                                                                                                                      
:26:53.967578+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  6E 72 22 3A 2D 31 31 2E 38 2C 22 72 73 73 69 63 22 3A 2D 31 31 32 7D 5D 2C 22 73 69 7A 65 22 3A  |nr":-11.8,"rssic":-112}],"size":|                                                                                                                      
:26:53.967890+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  30 2C 22 73 74 61 74 22 3A 2D 31 2C 22 74 69 6D 65 22 3A 22 32 30 32 32 2D 31 30 2D 30 35 54 30  |0,"stat":-1,"time":"2022-10-05T0|                                                                                                                      
:26:53.968202+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  39 3A 32 36 3A 32 39 2E 33 37 39 37 39 5A 22 2C 22 74 6D 73 74 22 3A 33 37 34 33 39 30 33 35 7D  |9:26:29.37979Z","tmst":37439035}|                                                                                                                      
:26:53.968381+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  5D 7D                                                                                            |]}|                                                                                                                                                    
:26:53.977465+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.recv:  02 AD 37 01                                                                                      |..7.|                                                                                                                                                  
:26:53.979182+02:00 klk-wiis-070A51 lorafwd[1216]: <6> Uplink message (AD37) sent                                                                                                                                                                                                                                            
:26:56.243383+02:00 klk-wiis-070A51 lorad[1169]: <7>   api.send:  0a 7f 08 82 80 80 87 03 12 47 0a 37 40 c9 a8 04 e0 80 05 00 02 97 c7 df 25 56 23 54 03 ff bb 14  |.........G.7@...........%V#T....|                                                                                                                        
:26:56.243879+02:00 klk-wiis-070A51 lorad[1169]: <7>   api.send:  4e 8d c6 58 77 17 78 2b 6d cb 73 ff 79 81 ba cf 3b d2 ea 1c e7 51 10 c5 b5 9e 5b 56 44 62 db b7  |N..Xw.x+m.s.y...;....Q....[VDb..|                                                                                                                        
:26:56.244264+02:00 klk-wiis-070A51 lorad[1169]: <7>   api.send:  5c ae af 10 a0 cf f8 9d 03 18 00 20 00 28 04 30 00 1a 2e 08 85 02 12 29 08 b4 d2 d3 1e 12 0c 08  |\.......... .(.0.......)........|                                                                                                                        
:26:56.244614+02:00 klk-wiis-070A51 lorad[1169]: <7>   api.send:  00 10 e0 9b f5 99 06 18 d8 e3 0d 1d 00 00 8f c2 22 0f 0d 00 00 28 41 15 00 00 8a 41 1d 00 00 80  |................"....(A....A....|                                                                                                                        
:26:56.244936+02:00 klk-wiis-070A51 lorad[1169]: <7>   api.send:  40                                                                                               |@|                                                                                                                                                       
:26:56.245917+02:00 klk-wiis-070A51 lorafwd[1216]: <7>   api.recv:  0A 7F 08 82 80 80 87 03 12 47 0A 37 40 C9 A8 04 E0 80 05 00 02 97 C7 DF 25 56 23 54 03 FF BB 14  |.........G.7@...........%V#T....|                                                                                                                      
:26:56.246163+02:00 klk-wiis-070A51 lorafwd[1216]: <7>   api.recv:  4E 8D C6 58 77 17 78 2B 6D CB 73 FF 79 81 BA CF 3B D2 EA 1C E7 51 10 C5 B5 9E 5B 56 44 62 DB B7  |N..Xw.x+m.s.y...;....Q....[VDb..|                                                                                                                      
:26:56.246382+02:00 klk-wiis-070A51 lorafwd[1216]: <7>   api.recv:  5C AE AF 10 A0 CF F8 9D 03 18 00 20 00 28 04 30 00 1A 2E 08 85 02 12 29 08 B4 D2 D3 1E 12 0C 08  |\.......... .(.0.......)........|                                                                                                                      
:26:56.246591+02:00 klk-wiis-070A51 lorafwd[1216]: <7>   api.recv:  00 10 E0 9B F5 99 06 18 D8 E3 0D 1D 00 00 8F C2 22 0F 0D 00 00 28 41 15 00 00 8A 41 1D 00 00 80  |................"....(A....A....|                                                                                                                      
:26:56.246660+02:00 klk-wiis-070A51 lorafwd[1216]: <7>   api.recv:  40                                                                                               |@|                                                                                                                                                     
:26:56.246810+02:00 klk-wiis-070A51 lorafwd[1216]: <6> Received uplink message:                                                                                                                                                                                                                                              
:26:56.246920+02:00 klk-wiis-070A51 lorafwd[1216]: <6> | lora uplink (30E00002), payload 55 B, channel 868.1 MHz, crc ok, bw 125 kHz, sf 11, cr 4/5                                                                                                                                                                          
:26:56.246990+02:00 klk-wiis-070A51 lorafwd[1216]: <6> | Unconfirmed Data Up, DevAddr E004A8C9, FCtrl [ADR], FCnt 5, FPort 2                                                                                                                                                                                                 
:26:56.247047+02:00 klk-wiis-070A51 lorafwd[1216]: <6> |  - radio (00000105)                                                                                                                                                                                                                                                 
:26:56.247155+02:00 klk-wiis-070A51 lorafwd[1216]: <6> |   - demodulator counter 64284980, UTC time 2022-10-05T09:26:56.225752Z, rssi -71.5 dB, snr 4< 10.5 <17.25 dB                                                                                                                                                        
:26:56.251939+02:00 klk-wiis-070A51 lorad[1169]: <6> Sent 1 uplink message                                                                                                                                                                                                                                                   
:26:56.981899+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  02 AD 38 00 70 76 FF 00 56 07 0A 51 7B 22 72 78 70 6B 22 3A 5B 7B 22 61 65 73 6B 22 3A 30 2C 22  |..8.pv..V..Q{"rxpk":[{"aesk":0,"|                                                                                                                      
:26:56.982588+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  62 72 64 22 3A 32 36 31 2C 22 63 6F 64 72 22 3A 22 34 2F 35 22 2C 22 64 61 74 61 22 3A 22 51 4D  |brd":261,"codr":"4/5","data":"QM|                                                                                                                      
:26:56.983334+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  6D 6F 42 4F 43 41 42 51 41 43 6C 38 66 66 4A 56 59 6A 56 41 50 2F 75 78 52 4F 6A 63 5A 59 64 78  |moBOCABQACl8ffJVYjVAP/uxROjcZYdx|                                                                                                                      
:26:56.983922+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  64 34 4B 32 33 4C 63 2F 39 35 67 62 72 50 4F 39 4C 71 48 4F 64 52 45 4D 57 31 6E 6C 74 57 52 47  |d4K23Lc/95gbrPO9LqHOdREMW1nltWRG|                                                                                                                      
:26:56.984564+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  4C 62 74 31 79 75 72 77 3D 3D 22 2C 22 64 61 74 72 22 3A 22 53 46 31 31 42 57 31 32 35 22 2C 22  |Lbt1yurw==","datr":"SF11BW125","|                                                                                                                      
:26:56.985109+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  66 72 65 71 22 3A 38 36 38 2E 31 2C 22 6A 76 65 72 22 3A 32 2C 22 6D 6F 64 75 22 3A 22 4C 4F 52  |freq":868.1,"jver":2,"modu":"LOR|                                                                                                                      
:26:56.985639+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  41 22 2C 22 72 73 69 67 22 3A 5B 7B 22 61 6E 74 22 3A 30 2C 22 63 68 61 6E 22 3A 35 2C 22 6C 73  |A","rsig":[{"ant":0,"chan":5,"ls|                                                                                                                      
:26:56.986799+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  6E 72 22 3A 31 30 2E 35 2C 22 72 73 73 69 63 22 3A 2D 37 31 7D 5D 2C 22 73 69 7A 65 22 3A 35 35  |nr":10.5,"rssic":-71}],"size":55|                                                                                                                      
:26:56.987395+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  2C 22 73 74 61 74 22 3A 31 2C 22 74 69 6D 65 22 3A 22 32 30 32 32 2D 31 30 2D 30 35 54 30 39 3A  |,"stat":1,"time":"2022-10-05T09:|                                                                                                                      
:26:56.987937+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  32 36 3A 35 36 2E 32 32 35 37 35 32 5A 22 2C 22 74 6D 73 74 22 3A 36 34 32 38 34 39 38 30 7D 5D  |26:56.225752Z","tmst":64284980}]|                                                                                                                      
:26:56.988317+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.send:  7D                                                                                               |}|                                                                                                                                                     
:26:56.994165+02:00 klk-wiis-070A51 lorafwd[1216]: <6> Uplink message (AD38) sent                                                                                                                                                                                                                                            
:26:56.996005+02:00 klk-wiis-070A51 lorafwd[1216]: <4> Uplink message (AD37) timed out                                                                                                                                                                                                                                       
:26:57.000089+02:00 klk-wiis-070A51 lorafwd[1216]: <7>  gwmp.recv:  02 AD 38 01                                                                                      |..8.|                                                                                                                                                  
:26:57.028256+02:00 klk-wiis-070A51 lorafwd[1216]: <6> Uplink message (AD38) acknowledged in 6.30061 ms

Longer logs:

Configuration files:

gist:556ad5718765129eeb7a811b362cb5b8 · GitHub

gist:0ee5e5edaaeb26fdf15b6372928605be · GitHub

Component Version
Application Server v4 (docker)
Gateway Bridge v4.1 (published 4th of october, bug was also present in previous version)
Forwarder Semtech UDP built-in to kerlink gateway
brocaar commented 1 year ago

Which firmware version are you using on your gateway? If it is not the latest version, could you try upgrading the firmware and try to reproduce the issue?

ldorigo commented 1 year ago

Hi, sorry for the slow response and thanks for the suggestion - we were finally able to upgrade the firmware version, and it seems to work now.