blockchain-core icon indicating copy to clipboard operation
blockchain-core copied to clipboard

Published 20 hours ago • verified publisher icon helium

Hotspot is receiving RF packets but Miner always rejects offers

Open jem-Solytica opened this issue 3 years ago • 5 comments

Based on the packet forwarder and miner logs on a SyncroB.it v2 hotspot, I'm concerned that the miner is losing all the inbound sensor data packets. I'm trying to determine if this is normal or aberrant behavior.

  1. Is this normal/expected behavior?
  2. (Especially if this is normal), there should be a more detail in the logs as to why the chain rejected an offer (e.g., because it's a LoRaWAN packet, but not a Helium-enabled device; another miner already submitted; etc.)?

Hotspot seems to be running okay otherwise (it's synced, not relayed, beaconing, witnessing, challenging, etc.). SyncroB.it support indicates that this is a helium/blockchain problem, not a hardware/firmware problem.

It appears that the hotspot is receiving data packets, based on the packet forwarder logs that look like this:

JSON up: {"stat":{"time":"2022-02-04 01:17:19 GMT","rxnb":3,"rxok":3,"rxfw":3,"ackr":100.0,"dwnb":0,"txnb":0,"temp":30.0}}

##### END #####
### Concentrator temperature: 30 C ###
# GPS sync is disabled
### [GPS] ###
src/jitqueue.c:442:jit_print_queue(): INFO: [jit] queue is empty
#--------
src/jitqueue.c:442:jit_print_queue(): INFO: [jit] queue is empty
### [JIT] ###
# BEACON rejected: 0
# BEACON sent so far: 0
# BEACON queued: 0
# SX1302 counter (PPS):  0
# SX1302 counter (INST): 917477438
### SX1302 Status ###
# TX rejected (too early): 0.00% (req:8, rej:0)
# TX rejected (too late): 0.00% (req:8, rej:0)
# TX rejected (collision beacon): 0.00% (req:8, rej:0)
# TX rejected (collision packet): 0.00% (req:8, rej:0)
# TX errors: 0
# RF packets sent to concentrator: 0 (0 bytes)
# PULL_RESP(onse) datagrams received: 0 (0 bytes)
# PULL_DATA sent: 3 (100.00% acknowledged)
### [DOWNSTREAM] ###
# PUSH_DATA acknowledged: 100.00%
# PUSH_DATA datagrams sent: 4 (932 bytes)
# RF packets forwarded: 3 (108 bytes)
# CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets received by concentrator: 3
### [UPSTREAM] ###
##### 2022-02-04 01:17:19 GMT #####

INFO: [down] PULL_ACK received in 0 ms
INFO: [down] PULL_ACK received in 0 ms
INFO: [up] PUSH_ACK received in 0 ms
JSON up: {"rxpk":[{"jver":1,"tmst":905076622,"chan":6,"rfch":1,"freq":905.100000,"mid": 8,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssis":-121,"lsnr":-6.5,"foff":7839,"rssi":-114,"size":64,"data":"QD0k/gAAGgAIHHoYwa2lRix95To/0T0+kKU0kuz1whS/kgakl9ykBaR5jW1rWiyAK/0eI9QCcHlMXeNYqyWY3g=="}]}

INFO: Received pkt from mote: 00FE243D (fcnt=26)

INFO: [down] PULL_ACK received in 0 ms
INFO: [up] PUSH_ACK received in 0 ms
JSON up: {"rxpk":[{"jver":1,"tmst":893945944,"chan":2,"rfch":0,"freq":904.300000,"mid": 8,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssis":-127,"lsnr":-11.2,"foff":5985,"rssi":-117,"size":22,"data":"gNsWCgEAfQAIKNVBB8pIUsI2HGtprg=="}]}

INFO: Received pkt from mote: 010A16DB (fcnt=125)

INFO: [up] PUSH_ACK received in 0 ms
JSON up: {"rxpk":[{"jver":1,"tmst":887933805,"chan":4,"rfch":1,"freq":904.700000,"mid": 8,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssis":-124,"lsnr":-7.2,"foff":6214,"rssi":-117,"size":22,"data":"gNsWCgEAfQAIKNVBB8pIUsI2HGtprg=="}]}

INFO: Received pkt from mote: 010A16DB (fcnt=125)

INFO: [up] PUSH_ACK received in 1 ms
JSON up: {"stat":{"time":"2022-02-04 01:16:49 GMT","rxnb":6,"rxok":5,"rxfw":5,"ackr":100.0,"dwnb":0,"txnb":0,"temp":30.0}}

These packets look like they're being passed to the miner, which appears to be submitting offers to the blockchain, but those offers are always rejected, with a sequence of log events similar to this:

2022-02-04 01:16:50.668 16569 [warning] <0.1594.0>@blockchain_state_channels_client:handle_cast:170 Got rejection: {blockchain_state_channel_rejection_v1_pb,0,<<193,77,255,107,160,98,36,134,173,88,96,196,77,109,192,135,98,232,66,117,232,220,193,63,149,142,102,31,248,124,139,200>>} for: <0.7522.3>, dropping packet
2022-02-04 01:16:50.561 16569 [warning] <0.1594.0>@blockchain_state_channels_client:handle_cast:170 Got rejection: {blockchain_state_channel_rejection_v1_pb,0,<<193,77,255,107,160,98,36,134,173,88,96,196,77,109,192,135,98,232,66,117,232,220,193,63,149,142,102,31,248,124,139,200>>} for: <0.7520.3>, dropping packet
2022-02-04 01:16:50.561 16569 [info] <0.1594.0>@blockchain_state_channel_common:send_offer:145 sending offer: {blockchain_state_channel_offer_v1_pb,{routing_information_pb,{devaddr,17438427}},<<193,77,255,107,160,98,36,134,173,88,96,196,77,109,192,135,98,232,66,117,232,220,193,63,149,142,102,31,248,124,139,200>>,22,0,<<0,60,164,177,78,86,126,237,10,149,122,132,226,34,41,149,82,119,13,207,75,248,209,9,41,186,26,15,228,74,128,249,77>>,<<48,69,2,32,94,191,29,205,176,139,198,49,155,108,232,120,240,17,193,190,190,141,190,88,101,112,127,47,125,208,16,116,92,153,237,244,2,33,0,236,39,44,44,80,201,66,110,174,146,95,136,95,61,228,174,250,95,74,61,166,90,79,148,128,172,167,189,186,32,79,172>>,'US915',false}, pid: <0.7522.3>
2022-02-04 01:16:50.445 16569 [info] <0.1594.0>@blockchain_state_channel_common:send_offer:145 sending offer: {blockchain_state_channel_offer_v1_pb,{routing_information_pb,{devaddr,17438427}},<<193,77,255,107,160,98,36,134,173,88,96,196,77,109,192,135,98,232,66,117,232,220,193,63,149,142,102,31,248,124,139,200>>,22,0,<<0,60,164,177,78,86,126,237,10,149,122,132,226,34,41,149,82,119,13,207,75,248,209,9,41,186,26,15,228,74,128,249,77>>,<<48,70,2,33,0,235,0,102,1,251,57,20,110,157,14,122,111,180,93,175,250,132,111,64,242,146,167,113,168,37,148,117,182,190,8,147,68,2,33,0,228,216,168,251,43,15,220,171,203,108,162,40,191,173,26,197,76,170,101,247,118,31,247,203,187,180,147,17,118,140,104,148>>,'US915',false}, pid: <0.7520.3>
2022-02-04 01:16:50.332 16569 [info] <0.1594.0>@blockchain_state_channels_client:handle_packet:381 handle_packet #packet_pb{oui=0,type=lorawan,payload=<<128,219,22,10,1,0,125,0,8,40,213,65,7,202,72,82,194,54,28,107,105,174>>,timestamp=887933805,signal_strength=-124,frequency=904.7,datarate=<<"SF8BW125">>,snr=-7.2,routing=#routing_information_pb{data={devaddr,17438427}},rx2_window=undefined} to ["/p2p/11w77YQLhgUt8HUJrMtntGGr97RyXmot1ofs5Ct2ELTmbFoYsQa","/p2p/11afuQSrmk52mgxLu91AdtDXbJ9wmqWBUxC3hvjejoXkxEZfPvY"] with handler blockchain_state_channel_handler
2022-02-04 01:16:50.331 16569 [notice] <0.1594.0>@blockchain_state_channels_client:handle_cast:160 failed to find router for join packet with routing information {devaddr,17438427}:{unknown_devaddr_prefix,1}, trying default routers
2022-02-04 01:16:50.331 16569 [notice] <0.1625.0>@miner_lora:handle_packets:623 Routing {devaddr,17438427}

jem-Solytica avatar Feb 04 '22 01:02 jem-Solytica

I don't think the lora radio differentiates an inbound frame based on whether it is destined for the helium network or not. I propose the rejection is because the packet is simply not destined for a server on helium. Your miner is trying to find a route/path for the data but cannot.

wifihax avatar Feb 26 '22 03:02 wifihax

That's what I suspect as well, but there's just not a lot of info to that effect in the logs. Might be worth evaluating if it's possible for the hotspot to determine if this a packet is destined for the Helium network without having to send the offer and get the rejection (which I assume includes sending the packet across the wire, needlessly, as it turns out)?

jem-Solytica avatar Feb 27 '22 05:02 jem-Solytica

Are you seeing this message at all? Looks in my case that it defaults to a "default" path... just in case. @blockchain_state_channels_client:handle_cast:{160,17} failed to find router for join packet with routing information {devaddr,138456789}:{unknown_devaddr_prefix,38}, trying default routers

wifihax avatar Feb 27 '22 12:02 wifihax

Did you get anywhere with this? Im getting the same on my panther, about 6-7 entries in the log per second all day long

onstat avatar May 06 '22 22:05 onstat

No. Situation remains unchanged. For my setup, ranges from 1,500-5,000 packets a day, currently. At least I can tell the concentrator is working!

From: onstat @.> Sent: Friday, May 6, 2022 5:08:46 PM To: helium/blockchain-core @.> Cc: Jason E. McCollough @.>; Author @.> Subject: Re: [helium/blockchain-core] Hotspot is receiving RF packets but Miner always rejects offers (Issue #1233)

Did you get anywhere with this? Im getting the same on my panther, about 6-7 entries in the log per second all day long

— Reply to this email directly, view it on GitHubhttps://github.com/helium/blockchain-core/issues/1233#issuecomment-1120044879, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ADXYY5B4OLBTMWA2YKBROL3VIWJ65ANCNFSM5NQQWXAA. You are receiving this because you authored the thread.Message ID: @.***>

jem-Solytica avatar May 06 '22 23:05 jem-Solytica