search

helium / gateway-rs

The Helium Gateway
Apache License 2.0
280 stars 110 forks source link

Release v1.0.0-alpha.21 not connecting any helium devices #153

Closed djieno closed 2 years ago

djieno commented 2 years ago

I haven't been able to connect my device on the helium network using my own mikrotik/gateway-rs. I've placed the device really close to the mikrotik router so from the rssi I could confirm if it's my device connecting to it (beside some logs showing it's deveui).

I can see my device trying to request a join to the helium network but is has NEVER been granted or connected to my gateway-rs. Neighboring hotspots are supplying the connecting the device as shown in the console.helium.com. My hotspot/gatway-rs is even 'offline' (on console.helium.com) while I see from the logging it's relaying messages (prolly lora and not helium messages/devices). In 8 days being online no 'data' has been successfully confirmed console.helium.com.

image

mikrotik (wAP LR8 kit) using internal antenna Nov 20 13:47:33.049 INFO uplink @2989534108 us, 868.50 MHz, Ok(DataRate(SF7, BW125)), snr: 7.5, rssi: -3, len: 23 from MacAddress(37:30:39:20:5A:00:48:00), module: gateway Nov 20 13:47:35.211 INFO rx1 downlink @2994534108 us, 868.50 MHz, DataRate(SF7, BW125), len: 33 via MacAddress(37:30:39:20:5A:00:48:00), module: gateway Nov 20 13:47:38.209 INFO uplink @2994699100 us, 868.10 MHz, Ok(DataRate(SF7, BW125)), snr: 9.75, rssi: -3, len: 24 from MacAddress(37:30:39:20:5A:00:48:00), module: gateway

tcpdump sudo tcpdump -i enp2s0 udp port 1680 -AXvvv 13:47:33.049098 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 275) ipfire.lan.39554 > amd1.lan.1680: [udp sum ok] UDP, length 247 0x0000: 4500 0113 0000 4000 3f11 247c 0a01 0101 E.....@.?.$|.... 0x0010: 0a01 015c 9a82 0690 00ff c02d 0201 2500 ..........-..%. 0x0020: 3730 3920 5a00 4800 7b22 7278 706b 223a 709.Z.H.{"rxpk": 0x0030: 5b7b 2263 6861 6e22 3a32 2c22 636f 6472 [{"chan":2,"codr 0x0040: 223a 2234 2f35 222c 2264 6174 6122 3a22 ":"4/5","data":" 0x0050: 4144 4969 3073 7a75 3339 304e 5048 5145 ADIi0szu390NPHQE 0x0060: 3048 3756 7333 412b 6f62 5a47 7a6c 733d 0H7Vs3A+obZGzls= 0x0070: 222c 2264 6174 7222 3a22 5346 3742 5731 ","datr":"SF7BW1 0x0080: 3235 222c 2266 7265 7122 3a38 3638 2e35 25","freq":868.5 0x0090: 3030 3030 302c 226c 736e 7222 3a37 2e35 00000,"lsnr":7.5 0x00a0: 3030 3030 302c 226d 6f64 7522 3a22 4c4f 00000,"modu":"LO 0x00b0: 5241 222c 2272 6663 6822 3a31 2c22 7273 RA","rfch":1,"rs 0x00c0: 7369 223a 2d33 2c22 7369 7a65 223a 3233 si":-3,"size":23 0x00d0: 2c22 7374 6174 223a 312c 2274 696d 6522 ,"stat":1,"time" 0x00e0: 3a22 3230 3231 2d31 312d 3230 5431 333a :"2021-11-20T13: 0x00f0: 3437 3a33 322e 3935 3337 3436 5a22 2c22 47:32.953746Z"," 0x0100: 746d 7374 223a 3239 3839 3533 3431 3038 tmst":2989534108 0x0110: 7d5d 7d }]} 13:47:33.049278 IP (tos 0x0, ttl 63, id 40355, offset 0, flags [DF], proto UDP (17), length 32) amd1.lan.1680 > ipfire.lan.39554: [udp sum ok] UDP, length 4 0x0000: 4500 0020 9da3 4000 3f11 87cb 0a01 015c E.....@.?......\ 0x0010: 0a01 0101 0690 9a82 000c 2163 0201 2501 ..........!c..%. 13:47:35.211732 IP (tos 0x0, ttl 63, id 40853, offset 0, flags [DF], proto UDP (17), length 238) amd1.lan.1680 > ipfire.lan.42721: [bad udp cksum 0x174a -> 0xb50a!] UDP, length 210 0x0000: 4500 00ee 9f95 4000 3f11 850b 0a01 015c E.....@.?......\ 0x0010: 0a01 0101 0690 a6e1 00da 174a 0210 e603 ...........J.... 0x0020: 7b22 7478 706b 223a 7b22 696d 6d65 223a {"txpk":{"imme": 0x0030: 6661 6c73 652c 2274 6d73 7422 3a32 3939 false,"tmst":299 0x0040: 3435 3334 3130 382c 2266 7265 7122 3a38 4534108,"freq":8 0x0050: 3638 2e35 2c22 7266 6368 223a 302c 2270 68.5,"rfch":0,"p 0x0060: 6f77 6522 3a32 372c 226d 6f64 7522 3a22 owe":27,"modu":" 0x0070: 4c4f 5241 222c 2264 6174 7222 3a22 5346 LORA","datr":"SF 0x0080: 3742 5731 3235 222c 2263 6f64 7222 3a22 7BW125","codr":" 0x0090: 342f 3522 2c22 6970 6f6c 223a 7472 7565 4/5","ipol":true 0x00a0: 2c22 7072 6561 223a 6e75 6c6c 2c22 7369 ,"prea":null,"si 0x00b0: 7a65 223a 3333 2c22 6461 7461 223a 2249 ze":33,"data":"I 0x00c0: 4378 7270 4567 5677 6a2b 6458 444f 5039 CxrpEgVwj+dXDOP9 0x00d0: 6e37 6559 4f5a 4850 316d 7265 5934 3979 n7eYOZHP1mreY49y 0x00e0: 4b7a 614a 4770 6c48 684c 5022 7d7d KzaJGplHhLP"}} 13:47:35.215643 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 40) ipfire.lan.42721 > amd1.lan.1680: [udp sum ok] UDP, length 12 0x0000: 4500 0028 0000 4000 3f11 2567 0a01 0101 E..(..@.?.%g.... 0x0010: 0a01 015c a6e1 0690 0014 418f 0210 e605 .........A..... 0x0020: 3730 3920 5a00 4800 0000 0000 0000 709.Z.H....... 13:47:37.219313 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 146) ipfire.lan.39554 > amd1.lan.1680: [udp sum ok] UDP, length 118 0x0000: 4500 0092 0000 4000 3f11 24fd 0a01 0101 E.....@.?.$..... 0x0010: 0a01 015c 9a82 0690 007e a50e 0200 2300 ........~....#. 0x0020: 3730 3920 5a00 4800 7b22 7374 6174 223a 709.Z.H.{"stat": 0x0030: 7b22 6163 6b72 223a 3130 302e 3030 3030 {"ackr":100.0000 0x0040: 3030 2c22 6477 6e62 223a 312c 2272 7866 00,"dwnb":1,"rxf 0x0050: 7722 3a31 2c22 7278 6e62 223a 322c 2272 w":1,"rxnb":2,"r 0x0060: 786f 6b22 3a31 2c22 7469 6d65 223a 2232 xok":1,"time":"2 0x0070: 3032 312d 3131 2d32 3020 3133 3a34 373a 021-11-20.13:47: 0x0080: 3337 2047 4d54 222c 2274 786e 6222 3a30 37.GMT","txnb":0 0x0090: 7d7d }} 13:47:37.219855 IP (tos 0x0, ttl 63, id 41078, offset 0, flags [DF], proto UDP (17), length 32) amd1.lan.1680 > ipfire.lan.39554: [udp sum ok] UDP, length 4 0x0000: 4500 0020 a076 4000 3f11 84f8 0a01 015c E....v@.?......\ 0x0010: 0a01 0101 0690 9a82 000c 2364 0200 2301 ..........#d..#. 13:47:38.208265 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 275) ipfire.lan.39554 > amd1.lan.1680: [udp sum ok] UDP, length 247 0x0000: 4500 0113 0000 4000 3f11 247c 0a01 0101 E.....@.?.$|.... 0x0010: 0a01 015c 9a82 0690 00ff 2a1f 0201 7a00 .........*...z. 0x0020: 3730 3920 5a00 4800 7b22 7278 706b 223a 709.Z.H.{"rxpk": 0x0030: 5b7b 2263 6861 6e22 3a30 2c22 636f 6472 [{"chan":0,"codr 0x0040: 223a 2234 2f35 222c 2264 6174 6122 3a22 ":"4/5","data":" 0x0050: 5141 4142 4145 6941 4141 4142 4d36 3739 QAABAEiAAAABM679 0x0060: 4b54 5166 5136 7577 5675 747a 7866 5167 KTQfQ6uwVutzxfQg 0x0070: 222c 2264 6174 7222 3a22 5346 3742 5731 ","datr":"SF7BW1 0x0080: 3235 222c 2266 7265 7122 3a38 3638 2e31 25","freq":868.1 0x0090: 3030 3030 302c 226c 736e 7222 3a39 2e37 00000,"lsnr":9.7 0x00a0: 3530 3030 302c 226d 6f64 7522 3a22 4c4f 50000,"modu":"LO 0x00b0: 5241 222c 2272 6663 6822 3a31 2c22 7273 RA","rfch":1,"rs 0x00c0: 7369 223a 2d33 2c22 7369 7a65 223a 3234 si":-3,"size":24 0x00d0: 2c22 7374 6174 223a 312c 2274 696d 6522 ,"stat":1,"time" 0x00e0: 3a22 3230 3231 2d31 312d 3230 5431 333a :"2021-11-20T13: 0x00f0: 3437 3a33 382e 3131 3830 3830 5a22 2c22 47:38.118080Z"," 0x0100: 746d 7374 223a 3239 3934 3639 3931 3030 tmst":2994699100 0x0110: 7d5d 7d }]} 13:47:38.208855 IP (tos 0x0, ttl 63, id 41244, offset 0, flags [DF], proto UDP (17), length 32) amd1.lan.1680 > ipfire.lan.39554: [udp sum ok] UDP, length 4 0x0000: 4500 0020 a11c 4000 3f11 8452 0a01 015c E.....@.?..R...\ 0x0010: 0a01 0101 0690 9a82 000c cc62 0201 7a01 ...........b..z. 13:47:38.442585 IP (tos 0x0, ttl 63, id 0, offset 0, flags [DF], proto UDP (17), length 40) ipfire.lan.42721 > amd1.lan.1680: [udp sum ok] UDP, length 12 0x0000: 4500 0028 0000 4000 3f11 2567 0a01 0101 E..(..@.?.%g.... 0x0010: 0a01 015c a6e1 0690 0014 bdfd 02a5 6902 .............i. 0x0020: 3730 3920 5a00 4800 0000 0000 0000 709.Z.H.......

image

madninja commented 2 years ago

Could you supply more of the gateway-rs logs please? I see a downlink in there but I'm missing the state channel and router log entries, so can't tell what router this is connected to (assuming oui 1 but want to make sure again)

djieno commented 2 years ago

@madninja I've also gone a little eenthusiastic with the logs in pastebin https://pastebin.com/p3whPg4w (1000 last logs). I could perform the whole 'my device getting asking to join' with a fresh restart of gateway-rs if that would help.

docker logs -f gateway-rs |grep -i oui

Nov 20 01:54:47.580 WARN gateway service error, shutting down: Service(Rpc(Status { code: Unknown, message: "error reading a body from connection: connection error received: unspecific protocol error detected", source: Some(hyper::Error(Body, Error { kind: GoAway(b"", PROTOCOL_ERROR, Remote) })) })), oui: 12, uri: http://54.219.236.122:8080/, pubkey: 112ewJNEUfSg3Jvo276tMjzFC2JzmmZcJJ32CWz2fzYqbyCMMTe1, module: router Nov 20 01:54:47.580 WARN gateway service error, shutting down: Service(Rpc(Status { code: Unknown, message: "error reading a body from connection: connection error received: unspecific protocol error detected", source: Some(hyper::Error(Body, Error { kind: GoAway(b"", PROTOCOL_ERROR, Remote) })) })), oui: 15, uri: http://66.23.231.34:8080/, pubkey: 117FMcZy77Ehz6gbTtSdSEs38vF784NLkxmWXUPcA2Ze3QxwJhG, module: router Nov 20 10:47:39.383 INFO starting, oui: 16, uri: http://13.37.13.24:8080/, pubkey: 11afuQSrmk52mgxLu91AdtDXbJ9wmqWBUxC3hvjejoXkxEZfPvY, module: router Nov 20 10:47:39.415 INFO starting, oui: 15, uri: http://66.23.231.34:8080/, pubkey: 117FMcZy77Ehz6gbTtSdSEs38vF784NLkxmWXUPcA2Ze3QxwJhG, module: router Nov 20 10:47:39.446 INFO starting, oui: 13, uri: http://46.246.38.248:8080/, pubkey: 115ZS5of9wsV3M5sH3mePp9NVnKayUXG7qT2W7Sn4KJLMzd3eMr, module: router Nov 20 10:47:39.486 INFO starting, oui: 12, uri: http://54.219.236.122:8080/, pubkey: 112ewJNEUfSg3Jvo276tMjzFC2JzmmZcJJ32CWz2fzYqbyCMMTe1, module: router Nov 20 10:47:39.517 INFO starting, oui: 10, uri: http://54.228.141.195:8080/, pubkey: 11YmZtwTPEuMSFGxze1x9TfDfGezN7vXevLu71iJe9FBbvNRAgk, module: router

Nov 20 10:47:39.549 INFO starting, oui: 9, uri: http://44.238.156.97:8080/, pubkey: 11w77YQLhgUt8HUJrMtntGGr97RyXmot1ofs5Ct2ELTmbFoYsQa, module: router Nov 20 10:47:39.582 INFO starting, oui: 4, uri: http://54.193.165.228:8080/, pubkey: 11263KvqW3GZPAvag5sQYtBJSjb25azSTSwoi5Tza9kboaLRxcsv, module: router Nov 20 10:47:39.620 INFO starting, oui: 2, uri: http://54.176.88.149:8080/, pubkey: 1124CJ9yJaHq4D6ugyPCDnSBzQik61C1BqD9VMh1vsUmjwt16HNB, module: router Nov 20 10:47:39.652 INFO starting, oui: 1, uri: http://52.8.80.146:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router Nov 20 10:47:41.671 INFO connected state channel, oui: 1, uri: http://52.8.80.146:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router Nov 20 10:47:41.826 INFO received banner (ignored), sc_id: Hmr8FArvYD9teoNYq6s9rmhbiP5YYZNZnfRPzq4BJk8, oui: 1, uri: http://52.8.80.146:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router Nov 20 10:47:53.693 INFO accepting new state channel, sc_id: yb4ProTVYpSDr-002A1H3mu7OwnYNFQ12tcmr_DYGr0, oui: 1, uri: http://52.8.80.146:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router Nov 20 10:56:28.044 INFO connected state channel, oui: 2, uri: http://54.176.88.149:8080/, pubkey: 1124CJ9yJaHq4D6ugyPCDnSBzQik61C1BqD9VMh1vsUmjwt16HNB, module: router

anhvu-sg commented 2 years ago

Same problem with my LPS8 Data only hotspot image

ZEROF commented 2 years ago

@anhvu-sg

You have issue with your gateway key. You should be able to resolve this by using backup of gateway_key.bin. And error will stop if you get right output from helium_gateway key info command and after restarting helium_gateway.

When I got this "error", I was in obligation to reinstall everything from scratch, because it was much faster than waiting and debugging.

marrik96 commented 2 years ago

I'm also having issues and error logs. helium-gateway commands all fail with error.

helium_gateway key info returns error below:

Error: Service(Rpc(Status { code: Unimplemented, metadata: MetadataMap { headers: {"date": "Fri, 03 Dec 2021 19:17:05 GMT", "content-type": "application/grpc"} }, source: None }))

Some output from logs:

Fri Dec 3 19:14:23 2021 daemon.info helium_gateway[23827]: INFO using gateway, uri: http://52.49.199.40:8080/, pubkey: 11tk4zzbyfMPYYHYda255ACoqfYFVdrUSoCWrCYfn8BoyuYrERK, module: dispatcher Fri Dec 3 19:14:24 2021 daemon.info helium_gateway[23827]: WARN gateway stream error: CryptoError(Signature(signature::Error { source: None })), module: dispatcher Fri Dec 3 19:14:29 2021 daemon.info helium_gateway[23827]: INFO using gateway, uri: http://54.251.77.229:8080/, pubkey: 11Gx2yPEmBGUrbHUiUWQs9vV7JDHQLZSddQs6e3WB2uvqSMUDBW, module: dispatcher Fri Dec 3 19:14:31 2021 daemon.info helium_gateway[23827]: WARN gateway stream error: CryptoError(Signature(signature::Error { source: None })), module: dispatcher Fri Dec 3 19:14:36 2021 daemon.info helium_gateway[23827]: INFO using gateway, uri: http://54.251.77.229:8080/, pubkey: 11Gx2yPEmBGUrbHUiUWQs9vV7JDHQLZSddQs6e3WB2uvqSMUDBW, module: dispatcher Fri Dec 3 19:14:38 2021 daemon.info helium_gateway[23827]: WARN gateway stream error: CryptoError(Signature(signature::Error { source: None })), module: dispatcher Fri Dec 3 19:14:43 2021 daemon.info helium_gateway[23827]: INFO using gateway, uri: http://3.38.70.101:8080/, pubkey: 11yJXQPG9deHqvw2ac6VWtNP7gZj8X3t3Qb3Gqm9j729p4AsdaA, module: dispatcher

marrik96 commented 2 years ago

Well, a reboot fixed it! I did a gateway reset but a full reboot seems to have fixed things.

madninja commented 2 years ago

Well, a reboot fixed it! I did a gateway reset but a full reboot seems to have fixed things.

Interesting, what hardware is this on?

marrik96 commented 2 years ago

Well, a reboot fixed it! I did a gateway reset but a full reboot seems to have fixed things.

Interesting, what hardware is this on?

Dragino LPS8 running lgw-5.4.1633695703 and v1.0.0-alpha.21

madninja commented 2 years ago

I see this thread has gone a bit off-track with other issues. @djieno are you still having this issue?

lthiery commented 2 years ago

@djieno One thing to consider is if you are too close to the gateway, you actually saturate the receiver. Try removing antennas and/or creating some distance between the end-device and the gateway.

IoTThinks commented 2 years ago

I use Dragino LPS8 (Firmware lgw-5.4.1636008262) and have similar problem. My Data-only is listed in helium.com already.

The node can Join but later no uplink to Helium. I can upload data from this node to this gateway to ChirpStack before.

image

Helium in Dragino image

This is node's log. I think the node is unable to get the response after the Join request from Helium to continue. Hence the UplinkCounter is always 0. The UplinkCounter should increase. image

My log is below. Downlinks look OK because there is "REPORT~ # PULL_DATA sent: 1 (100.00% acknowledged)"

root@dragino-20e2e8:~# logread -f
Wed Dec 22 13:12:25 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:12:25 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]:
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ################## Report at: 2021-12-22 06:12:35 UTC ##################
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [UPSTREAM] ###
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets received by concentrator: 1
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets forwarded: 1 (23 bytes)
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA datagrams sent: 1 (242 bytes)
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA acknowledged: 100.00%
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [DOWNSTREAM] ###
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_DATA sent: 1 (100.00% acknowledged)
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets sent to concentrator: 0 (0 bytes)
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # TX errors: 0
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON queued: 0
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON sent so far: 0
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON rejected: 0
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [PPS] ###
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # SX1301 time (PPS): 3692870
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO: [jit] queue is empty
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ### [GPS] ###
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ # GPS *FAKE* coordinates: latitude 10.761254, longitude 106.659548, altitude 8 m
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ##### END #####
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"stat":{"time":"2021-12-22 06:12:35 UTC","lati":10.761254,"long":106.659548,"alti":8,"rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:12:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [down] PULL_ACK received in 0 ms
Wed Dec 22 13:12:40 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:12:40 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:12:44 2021 daemon.info lora_pkt_fwd[2550]: PKT_FWD~ JOIN_REQ+ {"AppEUI":,"01010000000000A0", "DevEUI":,"122B8361C14140A8", "DevNonce": "41348"}
Wed Dec 22 13:12:44 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"rxpk":[{"tmst":42186220,"time":"2021-12-22T06:12:44.314152Z","chan":1,"rfch":0,"freq":921.400000,"stat":1,"modu":"LORA","datr":"SF10BW125","codr":"4/5","lsnr":9.2,"rssi":-30,"size":23,"data":"AAEBAAAAAACgEiuDYcFBQKiEoZqWkM4="}]}
Wed Dec 22 13:12:44 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:12:44 2021 daemon.info helium_gateway[2022]:  INFO uplink @42186220 us, 921.40 MHz, Ok(DataRate(SF10, BW125)), snr: 9.2, rssi: -30, len: 23 from MacAddress(A8:40:41:20:E2:E8:50), module: gateway
Wed Dec 22 13:12:56 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:12:56 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]:
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ################## Report at: 2021-12-22 06:13:05 UTC ##################
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [UPSTREAM] ###
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets received by concentrator: 1
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets forwarded: 1 (23 bytes)
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA datagrams sent: 1 (242 bytes)
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA acknowledged: 100.00%
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [DOWNSTREAM] ###
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_DATA sent: 1 (100.00% acknowledged)
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets sent to concentrator: 0 (0 bytes)
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # TX errors: 0
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON queued: 0
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON sent so far: 0
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON rejected: 0
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [PPS] ###
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # SX1301 time (PPS): 63688083
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO: [jit] queue is empty
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ### [GPS] ###
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ # GPS *FAKE* coordinates: latitude 10.761254, longitude 106.659548, altitude 8 m
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ##### END #####
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"stat":{"time":"2021-12-22 06:13:05 UTC","lati":10.761254,"long":106.659548,"alti":8,"rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:13:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [down] PULL_ACK received in 0 ms
Wed Dec 22 13:13:11 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:13:11 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:13:21 2021 daemon.info lora_pkt_fwd[2550]: PKT_FWD~ JOIN_REQ+ {"AppEUI":,"01030000000200A0", "DevEUI":,"122B8361C14140A8", "DevNonce": "29835"}
Wed Dec 22 13:13:21 2021 daemon.info lora_pkt_fwd[2550]: PKT_FWD~ JOIN_REQ+ {"AppEUI":,"01010000000000A0", "DevEUI":,"122B8361C14140A8", "DevNonce": "29835"}
Wed Dec 22 13:13:21 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"rxpk":[{"tmst":79329852,"time":"2021-12-22T06:13:21.459739Z","chan":2,"rfch":0,"freq":921.600000,"stat":1,"modu":"LORA","datr":"SF10BW125","codr":"4/5","lsnr":6.8,"rssi":-30,"size":23,"data":"AAEBAAAAAACgEiuDYcFBQKiLdAKzKio="}]}
Wed Dec 22 13:13:21 2021 daemon.info helium_gateway[2022]:  INFO uplink @79329852 us, 921.60 MHz, Ok(DataRate(SF10, BW125)), snr: 6.8, rssi: -30, len: 23 from MacAddress(A8:40:41:20:E2:E8:50), module: gateway
Wed Dec 22 13:13:21 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:13:26 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:13:26 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]:
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ################## Report at: 2021-12-22 06:13:35 UTC ##################
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [UPSTREAM] ###
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets received by concentrator: 3
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # CRC_OK: 33.33%, CRC_FAIL: 66.67%, NO_CRC: 0.00%
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets forwarded: 1 (23 bytes)
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA datagrams sent: 1 (242 bytes)
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA acknowledged: 100.00%
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [DOWNSTREAM] ###
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_DATA sent: 1 (100.00% acknowledged)
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets sent to concentrator: 0 (0 bytes)
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # TX errors: 0
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON queued: 0
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON sent so far: 0
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON rejected: 0
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [PPS] ###
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # SX1301 time (PPS): 63688083
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO: [jit] queue is empty
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ### [GPS] ###
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ # GPS *FAKE* coordinates: latitude 10.761254, longitude 106.659548, altitude 8 m
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ##### END #####
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"stat":{"time":"2021-12-22 06:13:35 UTC","lati":10.761254,"long":106.659548,"alti":8,"rxnb":3,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:13:35 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [down] PULL_ACK received in 0 ms
Wed Dec 22 13:13:41 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:13:41 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:13:57 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:13:57 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:13:58 2021 daemon.info lora_pkt_fwd[2550]: PKT_FWD~ JOIN_REQ+ {"AppEUI":,"01010000000000A0", "DevEUI":,"122B8361C14140A8", "DevNonce": "24573"}
Wed Dec 22 13:13:58 2021 daemon.info lora_pkt_fwd[2550]: PKT_FWD~ JOIN_REQ+ {"AppEUI":,"01010000000000A0", "DevEUI":,"122B8361C14140A8", "DevNonce": "24567"}
Wed Dec 22 13:13:58 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"rxpk":[{"tmst":116473500,"time":"2021-12-22T06:13:58.598056Z","chan":2,"rfch":0,"freq":921.600000,"stat":1,"modu":"LORA","datr":"SF10BW125","codr":"4/5","lsnr":7.0,"rssi":-31,"size":23,"data":"AAEBAAAAAACgEiuDYcFBQKj3XxxnPjw="}]}
Wed Dec 22 13:13:58 2021 daemon.info helium_gateway[2022]:  INFO uplink @116473500 us, 921.60 MHz, Ok(DataRate(SF10, BW125)), snr: 7, rssi: -31, len: 23 from MacAddress(A8:40:41:20:E2:E8:50), module: gateway
Wed Dec 22 13:13:58 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]:
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ################## Report at: 2021-12-22 06:14:05 UTC ##################
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [UPSTREAM] ###
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets received by concentrator: 2
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # CRC_OK: 50.00%, CRC_FAIL: 50.00%, NO_CRC: 0.00%
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets forwarded: 1 (23 bytes)
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA datagrams sent: 1 (243 bytes)
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PUSH_DATA acknowledged: 100.00%
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [DOWNSTREAM] ###
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_DATA sent: 1 (100.00% acknowledged)
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # RF packets sent to concentrator: 0 (0 bytes)
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # TX errors: 0
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON queued: 0
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON sent so far: 0
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # BEACON rejected: 0
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ ### [PPS] ###
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: REPORT~ # SX1301 time (PPS): 123690238
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO: [jit] queue is empty
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ### [GPS] ###
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ # GPS *FAKE* coordinates: latitude 10.761254, longitude 106.659548, altitude 8 m
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ ##### END #####
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: RXTX~ {"stat":{"time":"2021-12-22 06:14:05 UTC","lati":10.761254,"long":106.659548,"alti":8,"rxnb":2,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [up] PUSH_ACK received in 0 ms
Wed Dec 22 13:14:05 2021 daemon.info lora_pkt_fwd[2550]: INFO~ [down] PULL_ACK received in 0 ms
Wed Dec 22 13:14:12 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:14:12 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
Wed Dec 22 13:14:27 2021 user.notice iot_keep_alive: Internet Access OK: via wlan0-2
Wed Dec 22 13:14:27 2021 user.notice iot_keep_alive: use WAN or WiFi for internet access now
madninja commented 2 years ago

I don't see any helium_gateway in the logs you shared.

IoTThinks commented 2 years ago

@madninja I filter the helium log as below. Yesterday, I can receive Join-request/Join-accept in Console.helium.com but not uplink data. Now, even no Join-request/Join-Accept.

Uplink from node can reach the hotspot. However, it seems the data from the Hotspot can not reach Helium.

Some issue with state channel? Or something is wrong with my key? Thanks a lot for your help and effort.

root@dragino-20e2e8:~# logread | grep helium
Fri Dec 24 08:36:49 2021 daemon.info helium_gateway[24384]:  DEBG reconnect::poll_ready: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" }))
Fri Dec 24 08:36:49 2021 daemon.info helium_gateway[24384]:  DEBG service.ready=true processing request
Fri Dec 24 08:36:49 2021 daemon.info helium_gateway[24384]:  DEBG error: error trying to connect: tcp connect error: Operation timed out (os error 145)
Fri Dec 24 08:36:49 2021 daemon.info helium_gateway[24384]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Operation timed out (os error 145)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Fri Dec 24 08:36:49 2021 daemon.info helium_gateway[24384]:  DEBG connecting to 178.82.0.172:8080
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384 }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG Connection; peer=Server
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=Settings { flags: (0x1: ACK) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=Settings { flags: (0x1: ACK) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received settings ACK; applying Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384 }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG received frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:38:14 2021 daemon.info helium_gateway[24384]:  DEBG send frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
Fri Dec 24 08:38:24 2021 daemon.info helium_gateway[24384]:  INFO no update found, module: updater
Fri Dec 24 08:39:02 2021 daemon.info helium_gateway[24384]:  DEBG reconnect::poll_ready: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" }))
Fri Dec 24 08:39:02 2021 daemon.info helium_gateway[24384]:  DEBG service.ready=true processing request
Fri Dec 24 08:39:02 2021 daemon.info helium_gateway[24384]:  DEBG error: error trying to connect: tcp connect error: Operation timed out (os error 145)
Fri Dec 24 08:39:02 2021 daemon.info helium_gateway[24384]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Operation timed out (os error 145)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Fri Dec 24 08:39:02 2021 daemon.info helium_gateway[24384]:  DEBG connecting to 178.82.0.172:8080
Fri Dec 24 08:41:16 2021 daemon.info helium_gateway[24384]:  DEBG reconnect::poll_ready: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" }))
Fri Dec 24 08:41:16 2021 daemon.info helium_gateway[24384]:  DEBG service.ready=true processing request
Fri Dec 24 08:41:16 2021 daemon.info helium_gateway[24384]:  DEBG error: error trying to connect: tcp connect error: Operation timed out (os error 145)
Fri Dec 24 08:41:16 2021 daemon.info helium_gateway[24384]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Operation timed out (os error 145)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Fri Dec 24 08:41:16 2021 daemon.info helium_gateway[24384]:  DEBG connecting to 178.82.0.172:8080
Fri Dec 24 08:43:29 2021 daemon.info helium_gateway[24384]:  DEBG reconnect::poll_ready: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" }))
Fri Dec 24 08:43:29 2021 daemon.info helium_gateway[24384]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:29 2021 daemon.info helium_gateway[24384]:  DEBG error: error trying to connect: tcp connect error: Operation timed out (os error 145)
Fri Dec 24 08:43:29 2021 daemon.info helium_gateway[24384]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Operation timed out (os error 145)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Fri Dec 24 08:43:29 2021 daemon.info helium_gateway[24384]:  DEBG connecting to 178.82.0.172:8080
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO starting server, key: 13vS6HMc5nMMwqbXLjKMDunwJ8EY3UsUxWVsFzbjyhQpAmYDimC, version: 1.0.0-alpha.21
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO starting, module: gateway
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO starting, module: dispatcher
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO default router, uri: http://54.176.88.149:8080/, pubkey: 1124CJ9yJaHq4D6ugyPCDnSBzQik61C1BqD9VMh1vsUmjwt16HNB, module: dispatcher
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO using gateway, uri: http://52.49.199.40:8080/, pubkey: 11tk4zzbyfMPYYHYda255ACoqfYFVdrUSoCWrCYfn8BoyuYrERK, module: dispatcher
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO starting, module: updater
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  INFO starting, listen: 127.0.0.1:4467, module: api
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG connecting to 52.49.199.40:8080
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG connected to 52.49.199.40:8080
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG binding client connection
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG client connection bound
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG Connection; peer=Client
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Settings { flags: (0x0) }
Fri Dec 24 08:43:31 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Settings { flags: (0x1: ACK) }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Settings { flags: (0x1: ACK) }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received frame=WindowUpdate { stream_id: StreamId(1), size_increment: 5 }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5 }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:32 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:33 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:34 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:36 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:37 2021 daemon.info helium_gateway[6925]:  INFO new packet forwarder client: MacAddress(A8:40:41:20:E2:E8:50), 127.0.0.1:46953, module: gateway
Fri Dec 24 08:43:37 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:38 2021 daemon.info helium_gateway[6925]:  INFO no update found, module: updater
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Data { stream_id: StreamId(1) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 16, uri: http://2.50.80.172:8080/, pubkey: 11afuQSrmk52mgxLu91AdtDXbJ9wmqWBUxC3hvjejoXkxEZfPvY, module: router
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 15, uri: http://66.23.231.34:8080/, pubkey: 117FMcZy77Ehz6gbTtSdSEs38vF784NLkxmWXUPcA2Ze3QxwJhG, module: router
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:39 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(7), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(7), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 12, uri: http://54.219.236.122:8080/, pubkey: 112ewJNEUfSg3Jvo276tMjzFC2JzmmZcJJ32CWz2fzYqbyCMMTe1, module: router
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(9), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 10, uri: http://54.228.141.195:8080/, pubkey: 11YmZtwTPEuMSFGxze1x9TfDfGezN7vXevLu71iJe9FBbvNRAgk, module: router
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(11), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(11), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 9, uri: http://44.238.156.97:8080/, pubkey: 11w77YQLhgUt8HUJrMtntGGr97RyXmot1ofs5Ct2ELTmbFoYsQa, module: router
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:40 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(13), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(13), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 4, uri: http://54.193.165.228:8080/, pubkey: 11263KvqW3GZPAvag5sQYtBJSjb25azSTSwoi5Tza9kboaLRxcsv, module: router
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(15), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(15), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 2, uri: http://54.176.88.149:8080/, pubkey: 1124CJ9yJaHq4D6ugyPCDnSBzQik61C1BqD9VMh1vsUmjwt16HNB, module: router
Fri Dec 24 08:43:41 2021 daemon.info helium_gateway[6925]:  DEBG service.ready=true processing request
Fri Dec 24 08:43:42 2021 daemon.info helium_gateway[6925]:  DEBG send frame=Headers { stream_id: StreamId(17), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:42 2021 daemon.info helium_gateway[6925]:  DEBG received frame=Headers { stream_id: StreamId(17), flags: (0x4: END_HEADERS) }
Fri Dec 24 08:43:42 2021 daemon.info helium_gateway[6925]:  INFO updated routing to height 1151309, module: dispatcher
Fri Dec 24 08:43:42 2021 daemon.info helium_gateway[6925]:  INFO starting, oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
IoTThinks commented 2 years ago

Suddenly it works in ... staging https://staging-console.helium.wtf/ Last time, it sent Join-request and Join-accept in https://console.helium.com/

How to configure the gateway to send to the https://console.helium.com? I want it to go to production Helium. Thanks a lot in advance.

image

It seems puting region = "AS923_2" in default.toml works. Putting region = ""AS923_2" in settings.toml doesn't override region = "US915" in default.toml.

The below error is still there but seems no impact. I have no idea where the http://178.82.0.172:8080 comes from as it is not in default.toml or setting.toml. => 90% confirmed.

Fri Dec 24 11:45:04 2021 daemon.info helium_gateway[26027]:  DEBG reconnect::poll_ready: hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" }))
Fri Dec 24 11:45:04 2021 daemon.info helium_gateway[26027]:  DEBG service.ready=true processing request
Fri Dec 24 11:45:04 2021 daemon.info helium_gateway[26027]:  DEBG error: error trying to connect: tcp connect error: Operation timed out (os error 145)
Fri Dec 24 11:45:04 2021 daemon.info helium_gateway[26027]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Operation timed out (os error 145)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 145, kind: TimedOut, message: "Operation timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Fri Dec 24 11:45:04 2021 daemon.info helium_gateway[26027]:  DEBG connecting to 178.82.0.172:8080
IoTThinks commented 2 years ago

The first Join-request / Join-accept may take 3-4 hours (not 20 minutes as mentioned in the website) for my case. I stop/start the gateway-rs a few times. Then later Join request / Join accept will be much faster.

ahmadsayed commented 2 years ago

The below error is still there but seems no impact. I have no idea where the http://178.82.0.172:8080 comes from as it is not in default.toml or setting.toml. => 90% confirmed.

I am also continuously getting 

Dec 25 01:55:24 rak-gateway helium_gateway[1775]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Connection timed out (os error 110)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 110, kind: TimedOut, message: "Connection timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router

In my the console no longer report any traffic coming to my data-only hotspot, and I keep receiving this timeout for IP 178.82.0.172, i am not sure where this IP configured

Dec 25 01:56:46 rak-gateway ttn-gateway[551]: # SX1301 time (PPS): 3842598895
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: ### [GPS] ###
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: # Valid time reference (age: 0 sec)
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: # no valid GPS coordinates available yet
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: ##### END #####
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: JSON up: {"stat":{"time":"2021-12-24 17:56:35 GMT","rxnb":2,"rxok":2,"rxfw":2,"ackr":100.0,"dwnb":0,"txnb":0}}
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: INFO: [up] PUSH_ACK received in 0 ms
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: INFO: [down] PULL_ACK received in 0 ms
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: INFO: Received pkt from mote: 48000037 (fcnt=11)
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: JSON up: {"rxpk":[{"tmst":3878413612,"time":"2021-12-24T17:57:15.814717Z","tmms":1324403854814,"chan":0,"rfch":0,"freq":923.200000,"stat":1,"modu":"LORA","datr":"SF10BW125","codr":"4/5","lsnr":11.2,"rssi":-34,"size":24,"data":"gDcAAEgACwACu8cWGtKxNECE+kr6dEVY"}]}
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: INFO: [up] PUSH_ACK received in 0 ms
Dec 25 01:56:46 rak-gateway ttn-gateway[551]: INFO: Received pkt from mote: 48000037 (fcnt=11)
Dec 25 01:56:46 rak-gateway helium_gateway[1775]:  INFO uplink @3883426084 us, 923.60 MHz, Ok(DataRate(SF10, BW125)), snr: 8.5, rssi: -33, len: 24 from MacAddress(B8:27:EB:FF:FE:F2:E7), module: gateway
Dec 25 01:57:11 rak-gateway helium_gateway[1775]:  INFO uplink @3908525532 us, 923.60 MHz, Ok(DataRate(SF10, BW125)), snr: 8.2, rssi: -34, len: 24 from MacAddress(B8:27:EB:FF:FE:F2:E7), module: gateway
Dec 25 01:57:35 rak-gateway helium_gateway[1775]:  WARN failed to connect state channel: Service(Rpc(Status { code: Unavailable, message: "error trying to connect: tcp connect error: Connection timed out (os error 110)", source: Some(tonic::transport::Error(Transport, hyper::Error(Connect, ConnectError("tcp connect error", Os { code: 110, kind: TimedOut, message: "Connection timed out" })))) })), oui: 1, uri: http://178.82.0.172:8080/, pubkey: 112qB3YaH5bZkCnKA5uRH7tBtGNv2Y5B4smv1jsmvGUzgKT71QpE, module: router
Dec 25 01:57:41 rak-gateway helium_gateway[1775]:  INFO uplink @3938639404 us, 923.20 MHz, Ok(DataRate(SF10, BW125)), snr: 13, rssi: -36, len: 24 from MacAddress(B8:27:EB:FF:FE:F2:E7), module: gateway
Dec 25 01:58:05 rak-gateway ttn-gateway[551]: JSON up: {"rxpk":[{"tmst":3883426084,"time":"2021-12-24T17:57:25.827188Z","tmms":1324403864826,"chan":2,"rfch":0,"freq":923.600000,"stat":1,"modu":"LORA","datr":"SF10BW125","codr":"4/5","lsnr":8.5,"rssi":-33,"size":24,"data":"gDcAAEgACwACu8cWGtKxNECE+kr6dEVY"}]}
Dec 25 01:58:05 rak-gateway ttn-gateway[551]: INFO: [up] PUSH_ACK received in 4 ms
Dec 25 01:58:05 rak-gateway ttn-gateway[551]: INFO: [down] PULL_ACK received in 0 ms
Dec 25 01:58:05 rak-gateway ttn-gateway[551]: INFO: [down] PULL_ACK received in 0 ms
Dec 25 01:58:05 rak-gateway ttn-gateway[551]: INFO: Disabling GPS mode for concentrator's counter...
IoTThinks commented 2 years ago

@ahmadsayed Check in staging Helium URL instead?

First Join in staging takes a few hours.

I am curious if I can push data in console.helium.com again.

ahmadsayed commented 2 years ago

@IoTThinks tried the staging , still no luck I am receiving the traffic successfully at the staging, but still coming from hotspot far from me that are full miner, still my data gateway reports the same warning, and reciving packet on LORA, but looks it fail to forward it to the OUI, for some reason it is trying to connect to http://178.82.0.172:8080 , without being able to reach it.

IoTThinks commented 2 years ago

Ignore the failed IPs, no impact. I think they hardcode this IP in the alpha code.

You need to set the region in default.toml. Setting region on settings.toml doesnt work.

Then wait for 3-4 hours for the first Join-request or Join-accept in staging. Hope your node will reach your hotspot which is nearer.

ahmadsayed commented 2 years ago

@IoTThinks it works now thanks a lot

hallard commented 2 years ago

Fixed like #166

madninja commented 2 years ago

Closing this issue