Ghost downlink messages in consle

j4zzcat commented 6 years ago

Hi,

I'm seeing ghost messages in the console. I don't have any application registered, I'm merely testing with the things node.

Clicking on the things node button will result in two messages in the console. One is for real, the other seems to be a downlink ghost. After power-cycling the things node, the ghost messages disappear.

Screenshot, notice the ghost messages with count > 28800.

Those ghost messages always seems to have the following in their log:

cmd:link-adr
error:too many failed ADR requests

As in:

start 4/2/2018 22:00:50.372992
0ms bridge br-eu1 receive

    backend:mqtt

116.08ms bridge br-eu1 forward

    backend:ttn

116.95ms router ttn-router-eu receive

    gateway:j4zzcat-ttngw-1

117.32ms router ttn-router-eu build downlink

    options:2

117.39ms router ttn-router-eu forward

    brokers:1

118.02ms broker ttn-broker-eu receive

318.33ms broker ttn-broker-eu deduplicate

    duplicates:1

337.66ms broker ttn-broker-eu got devices from networkserver

    devices:5

337.72ms broker ttn-broker-eu check mic

    mic checks:5

340.03ms networkserver ttn-networkserver-eu update state

341.32ms networkserver ttn-networkserver-eu schedule mac command

    cmd:link-adr
    reason:optimize

341.34ms networkserver ttn-networkserver-eu set ack

    reason:adr-ack-req

343.6ms broker ttn-broker-eu forward

    handler:ttn-handler-eu

344.66ms handler ttn-handler-eu receive

345.37ms handler ttn-handler-eu process uplink

345.38ms handler ttn-handler-eu check mic

447.57ms handler ttn-handler-eu prepare downlink

448.35ms handler ttn-handler-eu process downlink

448.88ms handler ttn-handler-eu set empty payload

448.93ms handler ttn-handler-eu forward

    broker:ttn-broker-eu

451.28ms broker ttn-broker-eu receive

452.69ms networkserver ttn-networkserver-eu update state

452.73ms networkserver ttn-networkserver-eu mac error

    cmd:link-adr
    error:too many failed ADR requests

454.28ms broker ttn-broker-eu forward
    router:ttn-router-eu
455.4ms router ttn-router-eu receive
456.15ms router ttn-router-eu send

And the payload looks like this:

{
  "gw_id": "j4zzcat-ttngw-1",
  "payload": "YCwdASYg1nCGCCkK",
  "f_cnt": 28886,
  "lora": {
    "spreading_factor": 9,
    "bandwidth": 125,
    "air_time": 144384000
  },
  "coding_rate": "4/5",
  "timestamp": "2018-03-25T12:32:53.598Z",
  "dev_addr": "26011D2C",
  "frequency": 869525000
}

KrishnaIyer commented 6 years ago

@j4zzcat : Could you please comment on why you closed this issue? it's useful if we look back into this issue.

j4zzcat commented 6 years ago

@krishnalyer I’m not sure this was really a problem. I want to further explore the issue before reporting.

htdvisser commented 6 years ago

I see the original message was edited with more information.

From what I can see, the situation is as follows:

The device is using ADR
The device previously rejected multiple ADR commands
The network server is attempting to optimize the data rate (on the uplink flow)
The network server is rejecting its own data rate optimization (on the downlink flow) because of too many failed requests

Files to look at:

htdvisser commented 5 years ago

This should be better now (in develop, deployed on next release). We no longer count packet loss as a failed ADR command.

TheThingsArchive / ttn

Ghost downlink messages in consle #703