helium / gwmp-mux

Multiplexer for Semtech's GWMP over UDP
Apache License 2.0
5 stars 8 forks source link

Wrong SNR #6

Open krispstack opened 5 months ago

krispstack commented 5 months ago

Hi

SNR Value is wrong when published for gwmp-mux to gateway-rs or any other semtech packet fwd listner

received packet with snr: 6.8, but after gwmp-mux snr changes to snr: 0.0000002, this will affect ADR and geolocation.

Mon Apr 8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: INFO: Received pkt from mote: 0037CFD6 (fcnt=1) Mon Apr 8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"rxpk":[{"jver":1,"tmst":682631918,"chan":0,"rfch":0,"freq":865.062500,"mid": 0,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","rssis":-95,"lsnr":6.8,"foff":-1300,"rssi":-94,"size":20,"data":"QNbPNwABAQANyqD8ngiq26Hk4gs="}]} Mon Apr 8 06:25:05 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:05.336 INFO From 00:16:C0:01:FF:14:AF:78 received uplink: @682631918 us, 865.06 MHz, DataRate(SF12, BW125), rssis: -95, snr: 6.8, len: 20 Mon Apr 8 06:25:05 2024 daemon.info helium_gateway[4487]: 2024-04-08T06:25:05.340018Z INFO run: gateway_rs::gateway: ignored uplink downlink_mac=00:16:C0:01:FF:14:AF:78 uplink=@682631918 us, 865062500 MHz, Sf12bw125, snr: 0.0000002, rssi: -95, len: 20 region=UNKNOWN Mon Apr 8 06:25:05 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:05.343 WARN Reconnected to GWMP client 00:16:C0:01:FF:14:AF:78 Mon Apr 8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: INFO: [up] PUSH_ACK received in 0 ms Mon Apr 8 06:25:10 2024 daemon.info lora_pkt_fwd[3441]: INFO: [down] PULL_ACK received in 0 ms Mon Apr 8 06:25:15 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:15 2024 daemon.info lora_pkt_fwd[3441]: INFO: Received pkt from mote: 0037CFD6 (fcnt=2) Mon Apr 8 06:25:15 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:15 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"rxpk":[{"jver":1,"tmst":692638807,"chan":1,"rfch":0,"freq":865.402500,"mid": 0,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","rssis":-92,"lsnr":7.5,"foff":-1299,"rssi":-92,"size":20,"data":"QNbPNwABAgANyqOY3gypThUO0NM="}]} Mon Apr 8 06:25:15 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:15.342 INFO From 00:16:C0:01:FF:14:AF:78 received uplink: @692638807 us, 865.40 MHz, DataRate(SF12, BW125), rssis: -92, snr: 7.5, len: 20 Mon Apr 8 06:25:15 2024 daemon.info helium_gateway[4487]: 2024-04-08T06:25:15.345983Z INFO run: gateway_rs::gateway: ignored uplink downlink_mac=00:16:C0:01:FF:14:AF:78 uplink=@692638807 us, 865402500 MHz, Sf12bw125, snr: 0, rssi: -92, len: 20 region=UNKNOWN Mon Apr 8 06:25:15 2024 daemon.info lora_pkt_fwd[3441]: INFO: [up] PUSH_ACK received in 0 ms Mon Apr 8 06:25:15 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:15.351 WARN Reconnected to GWMP client 00:16:C0:01:FF:14:AF:78 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ##### 2024-04-08 06:25:16 UTC ##### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### [UPSTREAM] ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # RF packets received by concentrator: 2 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00% Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # RF packets forwarded: 2 (40 bytes) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # PUSH_DATA datagrams sent: 3 (615 bytes) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # PUSH_DATA acknowledged: 100.00% Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### [DOWNSTREAM] ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # PULL_DATA sent: 3 (100.00% acknowledged) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # PULL_RESP(onse) datagrams received: 0 (0 bytes) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # RF packets sent to concentrator: 0 (0 bytes) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # TX errors: 0 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### SX1302 Status ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # SX1302 counter (INST): 693398519 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # SX1302 counter (PPS): 0 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # BEACON queued: 0 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # BEACON sent so far: 0 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # BEACON rejected: 0 Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### [JIT] ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: src/jitqueue.c:440:jit_print_queue(): INFO: [jit] queue is empty Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: #-------- Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: src/jitqueue.c:440:jit_print_queue(): INFO: [jit] queue is empty Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### [GPS] ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # Invalid time reference (age: 1712557516 sec) Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: # no valid GPS coordinates available yet Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ### Concentrator temperature: 35 C ### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: ##### END ##### Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"stat":{"time":"2024-04-08 06:25:16 UTC","rxnb":2,"rxok":2,"rxfw":2,"ackr":100.0,"dwnb":0,"txnb":0,"temp":34.7}} Mon Apr 8 06:25:16 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:16.162 INFO From 00:16:C0:01:FF:14:AF:78 received stat: Stat { time: "2024-04-08 06:25:16 UTC", lati: None, long: None, alti: None, rxnb: 2, rxok: 2, rxfw: 2, ackr: Some(100.0), dwnb: 0, txnb: 0, temp: Some(34.7) } Mon Apr 8 06:25:16 2024 daemon.info lora_pkt_fwd[3441]: INFO: [up] PUSH_ACK received in 0 ms Mon Apr 8 06:25:20 2024 daemon.info lora_pkt_fwd[3441]: INFO: [down] PULL_ACK received in 0 ms Mon Apr 8 06:25:25 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:25.183 WARN Reconnected to GWMP client 00:16:C0:01:FF:14:AF:78 Mon Apr 8 06:25:25 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:25 2024 daemon.info lora_pkt_fwd[3441]: INFO: Received pkt from mote: 0037CFD6 (fcnt=3) Mon Apr 8 06:25:25 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:25 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"rxpk":[{"jver":1,"tmst":702645394,"chan":1,"rfch":0,"freq":865.402500,"mid": 0,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","rssis":-100,"lsnr":6.2,"foff":-1300,"rssi":-100,"size":20,"data":"QNbPNwABAwANyhmUNDoRU7Hq8eo="}]} Mon Apr 8 06:25:25 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:25.348 INFO From 00:16:C0:01:FF:14:AF:78 received uplink: @702645394 us, 865.40 MHz, DataRate(SF12, BW125), rssis: -100, snr: 6.2, len: 20 Mon Apr 8 06:25:25 2024 daemon.info helium_gateway[4487]: 2024-04-08T06:25:25.352438Z INFO run: gateway_rs::gateway: ignored uplink downlink_mac=00:16:C0:01:FF:14:AF:78 uplink=@702645394 us, 865402500 MHz, Sf12bw125, snr: 0.0000014, rssi: -100, len: 20 region=UNKNOWN Mon Apr 8 06:25:25 2024 daemon.info lora_pkt_fwd[3441]: INFO: [up] PUSH_ACK received in 0 ms Mon Apr 8 06:25:25 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:25.357 WARN Lost connection to GWMP client 00:16:C0:01:FF:14:AF:78. Dropping frames. Mon Apr 8 06:25:30 2024 daemon.info lora_pkt_fwd[3441]: INFO: [down] PULL_ACK received in 0 ms Mon Apr 8 06:25:35 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:35.184 WARN Reconnected to GWMP client 00:16:C0:01:FF:14:AF:78 Mon Apr 8 06:25:40 2024 daemon.info lora_pkt_fwd[3441]: INFO: [down] PULL_ACK received in 0 ms Mon Apr 8 06:25:41 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:41 2024 daemon.info lora_pkt_fwd[3441]: INFO: Received pkt from mote: 0037CFD6 (fcnt=4) Mon Apr 8 06:25:41 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr 8 06:25:41 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"rxpk":[{"jver":1,"tmst":719048092,"chan":0,"rfch":0,"freq":865.062500,"mid": 0,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","rssis":-99,"lsnr":5.8,"foff":-1298,"rssi":-99,"size":63,"data":"gNbPNwCABAABQ0/WFMUVjcpcSE6fWdm+ekg7faHzld8wA7gVaVU0GrCiGbwGtoQVhtmo216c8RgPY/PWeI9Q"}]} Mon Apr 8 06:25:41 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:41.757 INFO From 00:16:C0:01:FF:14:AF:78 received uplink: @719048092 us, 865.06 MHz, DataRate(SF12, BW125), rssis: -99, snr: 5.8, len: 63 Mon Apr 8 06:25:41 2024 daemon.info helium_gateway[4487]: 2024-04-08T06:25:41.761113Z INFO run: gateway_rs::gateway: ignored uplink downlink_mac=00:16:C0:01:FF:14:AF:78 uplink=@719048092 us, 865062500 MHz, Sf12bw125, snr: 0.0000002, rssi: -99, len: 63 region=UNKNOWN

thanks

lthiery commented 5 months ago

@krispstack thanks for the report. i'm pressed for time this week but i will investigate this as soon as i have a moment!

krispstack commented 5 months ago

@krispstack thanks for the report. i'm pressed for time this week but i will investigate this as soon as i have a moment!

@lthiery thanks

lthiery commented 5 months ago

@krispstack gwmp-mux uses my other repo, semtech-udp for deserialization and serialization (or in this case, reserialization) of the frames. so does gateway-rs...

i started by writing a roundtrip snr test with this particular frame, but i didn't catch anything wrong with the SNR :thinking:

i double-checked and gateway-rs is also using the most recent version of semtech-udp so i'm a bit confused. i will have to spend sometime injecting the frame into gateway-rs to try to reproduce this, but i'm a bit at a loss at the moment. i just wanted to share the initial effort and next steps.

lthiery commented 5 months ago

Following my test above and looking more closely at the logs, I think this may be an issue with the conversion from the semtech-udp RxPk type to the gateway-rs PacketRouterPacketUpV1 type...

For example, we see:

Mon Apr  8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: INFO: Received pkt from mote: 0037CFD6 (fcnt=1) Mon Apr  8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: Mon Apr  8 06:25:05 2024 daemon.info lora_pkt_fwd[3441]: JSON up: {"rxpk":[{"jver":1,"tmst":682631918,"chan":0,"rfch":0,"freq":865.062500,"mid": 0,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","rssis":-95,"lsnr":6.8,"foff":-1300,"rssi":-94,"size":20,"data":"QNbPNwABAQANyqD8ngiq26Hk4gs="}]}
Mon Apr  8 06:25:05 2024 daemon.info gwmp-mux[4422]: Apr 08 06:25:05.336 INFO From 00:16:C0:01:FF:14:AF:78 received uplink: @682631918 us, 865.06 MHz, DataRate(SF12, BW125), rssis: -95, snr: 6.8, len: 20
Mon Apr  8 06:25:05 2024 daemon.info helium_gateway[4487]: 2024-04-08T06:25:05.340018Z  INFO run: gateway_rs::gateway: ignored uplink downlink_mac=00:16:C0:01:FF:14:AF:78 uplink=@682631918 us, 865062500 MHz, Sf12bw125, snr: 0.0000002, rssi: -95, len: 20 region=UNKNOWN 

As you can see, the report from gwmp-mux is consistent but its the log from helium_gateway that has the corrupt snr. I don't have any ideas quite yet what the issue might actually be though because this conversion looks pretty foolproof.

Leaving this note here but tagging @madninja for extra eyes.

lthiery commented 5 months ago

@krispstack i have setup a test that sends this exact frame into gwmp-mux and then it goes through the way to gateway-rs with no problem:

2024-04-19T21:09:33.229537Z  INFO run: gateway_rs::gateway: ignored uplink downlink_mac=08:07:06:05:04:03:02:01 uplink=@682631918 us, 865.0625 MHz, Sf12bw125, snr: 6.8, rssi: -95, len: 20 region=UNKNOWN

Can you share what version of gwmp-mux and what version of gateway-rs you are running?

krispstack commented 5 months ago

@lthiery gwmp-mux version 0.11.0 gateway-rs version 1.3.0

ARCH : mipsel-unknown-linux-musl

I have even tried with to with chirpstack, I get a wrong SNR Value

sx1302_pkt_fwd <--> gwmp-mux <--> chirpstack

lthiery commented 5 months ago

@krispstack thanks that helps. anyway you know how to capture the UDP frames using pcap or wireshark?

krispstack commented 5 months ago

@lthiery no idea about pcap or wireshark

lthiery commented 5 months ago

@krispstack is it a linux system you can provide me with remote access to?

lthiery commented 5 months ago

@krispstack are you compiling these applications yourself? I found some issues related to rust and mips and the assumption that hardware floating point is available. I wonder if it may be what's happening and causing the corruption of the float.

Can you rebuild the apps if possible with 'RUSTFLAGS="-feature=+soft-float,-fp64”'?

krispstack commented 5 months ago

@lthiery

tried, But Im geting a warning while building

~/helium/gwmp-mux$ RUSTFLAGS="-C target-feature=+soft-float,-fp64" cross build --release --target mipsel-unknown-linux-musl

warning: unknown feature specified for -Ctarget-feature: soft-float

lthiery commented 4 months ago

Hi @krispstack - I finally had a minute to fiddle around and try to replicate the build over here. I believe RUSTFLAG needs to be passed via Cross.toml when using cargo-cross.

I was able to get a build going with no warnings:

[build]
build-std = true
xargo = true
rustflags = [
    "-C", "target-feature=+soft-float,-fp64"
]

And the cross command

cross build +nightly --release --target mipsel-unknown-linux-musl

Can you tell me if this binary behaves differently?