search

TheThingsNetwork / lorawan-stack

The Things Stack, an Open Source LoRaWAN Network Server
https://www.thethingsindustries.com/stack/
Apache License 2.0
975 stars 306 forks source link

No Application downlinks scheduled #5363

Closed ezamp closed 2 years ago

ezamp commented 2 years ago

Summary

Application downlinks are not scheduled. The join accept or ADR response downlinks are scheduled correctly. This behavior occurs with all devices, regardless the class or the gateway used.

Steps to Reproduce

I don't think it's easily reproducible on other TTN instances. To replicate the problem on my instance:

  1. Go to end-device page
  2. Open tab "Messaging"
  3. Open "Downlink" and compose a payload
  4. Click on "Schedule downlink"

What do you see now?

Screen Shot 2022-04-01 at 16 16 13 PM

_2022-04-01 15:46:13.877 CEST_: 
DEBUG   Push application downlink to queue  {"device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_count": 1, "grpc.method": "DownlinkQueuePush", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN"}

_2022-04-01 15:46:13.879 CEST_: 
DEBUG   Pushed application downlink to queue    {"active_session_queue_length": 1, "device_uid": "urbana-platform-devices.7898428ac6197297", "grpc.method": "DownlinkQueuePush", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "pending_session_queue_length": 0, "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN"}

_2022-04-01 15:46:13.879 CEST_: 
DEBUG   Push application downlink to queue  {"device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_count": 1, "grpc.method": "DownlinkQueuePush", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN"}

_2022-04-01 15:46:13.879 CEST_: 
DEBUG   Application downlink with no absolute time, choose unconfirmed network-initiated downlink slot  {"active_session_queue_length": 1, "device_uid": "urbana-platform-devices.7898428ac6197297", "earliest_at": 1648820774.0792158, "grpc.method": "DownlinkQueuePush", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "pending_session_queue_length": 0, "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN"}

_2022-04-01 15:46:13.879 CEST_: 
DEBUG   Add downlink task   {"active_session_queue_length": 1, "device_uid": "urbana-platform-devices.7898428ac6197297", "grpc.method": "DownlinkQueuePush", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "pending_session_queue_length": 0, "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN", "start_at": 1648820774.0792158}

_2022-04-01 15:46:13.879 CEST_: 
INFO    Finished unary call {"duration": 0.0029, "grpc.method": "DownlinkQueuePush", "grpc.request.application_id": "urbana-platform-devices", "grpc.request.device_id": "7898428ac6197297", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "grpc", "peer.address": "pipe", "request_id": "01FZJP0RZMKQ6CD4MN9B4EJ6BN"}

_2022-04-01 15:46:13.886 CEST_: 
DEBUG   Replace downlink queue  {"device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_count": 0, "grpc.method": "DownlinkQueueReplace", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "request_id": "01FZJP0RZX5V6J6XXMXSWPB046"}

_2022-04-01 15:46:13.888 CEST_: 
DEBUG   Replaced application downlink queue {"active_session_queue_length": 0, "device_uid": "urbana-platform-devices.7898428ac6197297", "grpc.method": "DownlinkQueueReplace", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "networkserver", "pending_session_queue_length": 0, "request_id": "01FZJP0RZX5V6J6XXMXSWPB046"}

_2022-04-01 15:46:13.888 CEST_: 
INFO    Finished unary call {"duration": 0.0028, "grpc.method": "DownlinkQueueReplace", "grpc.request.application_id": "urbana-platform-devices", "grpc.request.device_id": "7898428ac6197297", "grpc.service": "ttn.lorawan.v3.AsNs", "namespace": "grpc", "peer.address": "pipe", "request_id": "01FZJP0RZX5V6J6XXMXSWPB046"}

_2022-04-01 15:46:14.143 CEST_: 
DEBUG   Process downlink task   {"device_uid": "urbana-platform-devices.7898428ac6197297", "namespace": "networkserver", "start_at": 1648820774.0792158, "started_at": 1648820774.143564}

_2022-04-01 15:46:14.145 CEST_: 
DEBUG   No available downlink to send, skip downlink slot   {"band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_type": "data", "earliest_at": 1648820774.1454673, "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "started_at": 1648820774.143564}

_2022-04-01 16:15:32.647 CEST_: 
DEBUG   Process downlink task   {"device_uid": "urbana-platform-devices.7898428ac6197297", "namespace": "networkserver", "start_at": 1648822532.626431, "started_at": 1648822532.6476429}

_2022-04-01 16:15:32.649 CEST_: 
DEBUG   Device needs LinkADRReq, choose class A downlink slot   {"band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_type": "data", "earliest_at": 1648822532.649716, "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "started_at": 1648822532.6476429}

_2022-04-01 16:15:32.650 CEST_: 
DEBUG   Add MAC command to buffer   {"band_id": "EU_863_870", "cid": "CID_LINK_ADR", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_type": "data", "frequency_plan_id": "EU_863_870_TTN", "mac_version": "MAC_V1_0_2", "max_downlink_length": 230, "namespace": "networkserver", "phy_version": "PHY_V1_0_2_REV_B", "started_at": 1648822532.6476429, "transmit_at": 1648822537.221302}

_2022-04-01 16:15:32.650 CEST_: 
DEBUG   Generated downlink  {"ack": false, "adr": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_type": "data", "f_cnt": 1, "f_pending": false, "f_port": 0, "frequency_plan_id": "EU_863_870_TTN", "full_f_cnt": 1, "m_type": "UNCONFIRMED_DOWN", "mac_count": 1, "mac_length": 5, "mac_version": "MAC_V1_0_2", "max_downlink_length": 230, "namespace": "networkserver", "payload_length": 17, "phy_version": "PHY_V1_0_2_REV_B", "priority": "HIGHEST", "started_at": 1648822532.6476429, "transmit_at": 1648822537.221302}

_2022-04-01 16:15:32.650 CEST_: 
DEBUG   Schedule downlink   {"attempt_rx1": true, "attempt_rx2": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_class": "CLASS_A", "downlink_priority": "HIGHEST", "downlink_type": "data", "frequency_plan": "EU_863_870_TTN", "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "path_count": 1, "rx1_data_rate": "lora:<bandwidth:125000 spreading_factor:7 > ", "rx1_delay": "RX_DELAY_5", "rx1_frequency": 867300000, "rx2_data_rate": "lora:<bandwidth:125000 spreading_factor:9 > ", "rx2_frequency": 869525000, "started_at": 1648822532.6476429}

_2022-04-01 16:15:32.652 CEST_: 
DEBUG   Scheduled downlink  {"absolute_time": null, "attempt_rx1": true, "attempt_rx2": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_class": "CLASS_A", "downlink_priority": "HIGHEST", "downlink_type": "data", "frequency_plan": "EU_863_870_TTN", "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "rx1_data_rate": "lora:<bandwidth:125000 spreading_factor:7 > ", "rx1_delay": "RX_DELAY_5", "rx1_frequency": 867300000, "rx2_data_rate": "lora:<bandwidth:125000 spreading_factor:9 > ", "rx2_frequency": 869525000, "started_at": 1648822532.6476429, "transmission_delay": 4.568867733, "transmit_at": 1648822537.2204938}

_2022-04-01 16:15:32.654 CEST_: 
DEBUG   No available downlink to send, skip downlink slot   {"device_uid": "urbana-platform-devices.7898428ac6197297", "earliest_at": 1648822537.2204938, "namespace": "networkserver", "started_at": 1648822532.6476429}

_2022-04-01 16:15:32.654 CEST_: 
DEBUG   Publish events  {"device_uid": "urbana-platform-devices.7898428ac6197297", "event_count": 3, "namespace": "networkserver", "started_at": 1648822532.6476429}

What do you want to see instead?

TTN network server should schedule "immediately" the downlinks for class C devices.

Environment

TTN cluster, v3.18.2 Redis 6.2.5

Can you do this yourself and submit a Pull Request?

No. This looks like a bug in the TTN network server, I'm not familiar with that code.

KrishnaIyer commented 2 years ago

The issue heading and the expected behaviour don't match. Are no downlinks sent or are Class C downlinks not sent "immediately"?

It's seems like it's not the former because I see a downlink being scheduled in your log

_2022-04-01 16:15:32.650 CEST_: 
DEBUG   Generated downlink  {"ack": false, "adr": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_type": "data", "f_cnt": 1, "f_pending": false, "f_port": 0, "frequency_plan_id": "EU_863_870_TTN", "full_f_cnt": 1, "m_type": "UNCONFIRMED_DOWN", "mac_count": 1, "mac_length": 5, "mac_version": "MAC_V1_0_2", "max_downlink_length": 230, "namespace": "networkserver", "payload_length": 17, "phy_version": "PHY_V1_0_2_REV_B", "priority": "HIGHEST", "started_at": 1648822532.6476429, "transmit_at": 1648822537.221302}

_2022-04-01 16:15:32.650 CEST_: 
DEBUG   Schedule downlink   {"attempt_rx1": true, "attempt_rx2": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_class": "CLASS_A", "downlink_priority": "HIGHEST", "downlink_type": "data", "frequency_plan": "EU_863_870_TTN", "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "path_count": 1, "rx1_data_rate": "lora:<bandwidth:125000 spreading_factor:7 > ", "rx1_delay": "RX_DELAY_5", "rx1_frequency": 867300000, "rx2_data_rate": "lora:<bandwidth:125000 spreading_factor:9 > ", "rx2_frequency": 869525000, "started_at": 1648822532.6476429}

_2022-04-01 16:15:32.652 CEST_: 
DEBUG   Scheduled downlink  {"absolute_time": null, "attempt_rx1": true, "attempt_rx2": true, "band_id": "EU_863_870", "dev_addr": "00EF5A9E", "device_class": "CLASS_C", "device_uid": "urbana-platform-devices.7898428ac6197297", "downlink_class": "CLASS_A", "downlink_priority": "HIGHEST", "downlink_type": "data", "frequency_plan": "EU_863_870_TTN", "frequency_plan_id": "EU_863_870_TTN", "namespace": "networkserver", "rx1_data_rate": "lora:<bandwidth:125000 spreading_factor:7 > ", "rx1_delay": "RX_DELAY_5", "rx1_frequency": 867300000, "rx2_data_rate": "lora:<bandwidth:125000 spreading_factor:9 > ", "rx2_frequency": 869525000, "started_at": 1648822532.6476429, "transmission_delay": 4.568867733, "transmit_at": 1648822537.2204938}

TTN network server should schedule "immediately" the downlinks for class C devices.

What do you mean by immediate? The server should account for transmission delays and scheduling conflicts so no downlink would really be immediate.

It seems like you're not setting the Absolute time for the downlink "absolute_time": null,. Without that, the network will choose to send the downlink on the next available downlink slot. Please check our docs for Class C dowlinks.

ezamp commented 2 years ago

The downlink was pushed at 15:46:13 but the downlink was at 16:15:32, 30 minutes later when the device sent an uplink. If I send a downlink message from the platform how can I set the absolute time?

KrishnaIyer commented 2 years ago

I guess by platform you mean the UI (Console). We don't support that yet. You can use the CLI and that's documented in the link I shared above. I'll add it here as well; https://www.thethingsindustries.com/docs/devices/class-c/

ezamp commented 2 years ago

Actually we have a second instance of TTN (v3.18.2) and If I try to send a payload via UI, the downlink is scheduled after some seconds. Screen Shot 2022-04-01 at 17 50 05 PM

KrishnaIyer commented 2 years ago

Ok but is both using Class C and the same type of device+gateway?

ezamp commented 2 years ago

Yes, they both use class C devices and the same gateway model.

On the instance where the downlinks for class C work as expected, in the event detail "Schedule data downlink for transmission on Gateway Server" (on UI) appears "class": "CLASS_C" inside the "request" key:

"request": {
      "class": "CLASS_C",
      "downlink_paths": [
        {
          "uplink_token": "Ch4KHAoQMjRlMTI0ZmZmZWYwNjE5MBIIJOEk//7wYZAQ3KO66g8aDAiM8KqSBhC3x8uVAyDghqfX195dKgwIjPCqkgYQ4MjFjAM="
        }
      ],
      "rx2_data_rate": {
        "lora": {
          "bandwidth": 125000,
          "spreading_factor": 9
        }
      },
      "rx2_frequency": "869525000",
      "frequency_plan_id": "EU_863_870_TTN"
    },

"class": "CLASS_C" is not present in the event generated by the instance where the downlinks are sent after the next uplink.

KrishnaIyer commented 2 years ago

Ok but what is then the difference between these instances? Are they running the same version of TTS with the same configuration? Are you using the same device in both cases? If yes, how are the MAC settings configured?