search

brocaar / chirpstack-network-server

ChirpStack Network Server is an open-source LoRaWAN network-server.
https://www.chirpstack.io
MIT License
1.49k stars 546 forks source link

New DownlinkTxPower Config does not override default regional downlink power #352

Closed alkindirizky closed 6 years ago

alkindirizky commented 6 years ago

Is this a bug or a feature request?

(probably) bug

What did you expect?

My Lora Gateway supports TX power up to 24 dBm. Setting TX power via adding this line to LoraServer config:

downlink_TX_power=24

is supposed to override the default TX power of my region, which is AS_923 (14 dBm)

What happened?

Upon seeing the CONFIRMED downlink packet via LoraAppServer, under 'power' field inside 'txinfo' field, the power does not change to 24 dBm. It stays the same at default regional TX power, which 14 dBm.

However, the UNCONFIRMED MAC command downlink, RXParamSetupReq, shows correct TX power, 24 dBm. This issue also occurs at other TX power values that are supported by my gateway.

What version are your using?

How can your issue be reproduced?

  1. Change the downlink_tx_power config in loraserver.toml to any value supported by gateway, except -1
  2. Start the LoraServer
  3. Send a downlink packet

Could you share your log output?

Sep 03 11:46:11  test-lora loraserver[2736]: time="2018-09-03T11:46:11Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:11  test-lora loraserver[2736]: time="2018-09-03T11:46:11Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:11.97948712 +0000 UTC m=+53.148443850]" duration="713.256µs" query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:12  test-lora loraserver[2736]: time="2018-09-03T11:46:12Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:12  test-lora loraserver[2736]: time="2018-09-03T11:46:12Z" level=debug msg="sql query executed" args="[100 338891h46m32.122936747s]" duration=3.920491ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:12  test-lora loraserver[2736]: time="2018-09-03T11:46:12Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:12  test-lora loraserver[2736]: time="2018-09-03T11:46:12Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:12  test-lora loraserver[2736]: time="2018-09-03T11:46:12Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:12.981131845 +0000 UTC m=+54.150088594]" duration="668.561µs" query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:13  test-lora loraserver[2736]: time="2018-09-03T11:46:13Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:13  test-lora loraserver[2736]: time="2018-09-03T11:46:13Z" level=debug msg="sql query executed" args="[100 338891h46m33.131319572s]" duration=6.016838ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:13  test-lora loraserver[2736]: time="2018-09-03T11:46:13Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:13  test-lora loraserver[2736]: time="2018-09-03T11:46:13Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:13  test-lora loraserver[2736]: time="2018-09-03T11:46:13Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:13.983144202 +0000 UTC m=+55.152100975]" duration="624.375µs" query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[100 338891h46m34.147930005s]" duration=4.611676ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[3930323560378704]" duration="397.448µs" query="\n select\n     *\n from\n     device_queue\n where\n     dev_eui = $1\n order by\n     f_cnt"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=GetNextDownlinkFCntForDevEUI grpc.service=ns.NetworkServerService grpc.start_time="2018-09-03T11:46:14Z" grpc.time_ms=0.723 peer.address="127.0.0.1:49140" span.kind=server system=grpc
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[[57 48 50 53 96 55 135 4]]" duration="412.017µs" query="select * from device where dev_eui = $1"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[9892786f-6253-4a04-acf7-1704ef33673a]" duration="714.807µs" query="\n select\n     created_at,\n     updated_at,\n\n     device_profile_id,\n     supports_class_b,\n     class_b_timeout,\n     ping_slot_period,\n     ping_slot_dr,\n     ping_slot_freq,\n     supports_class_c,\n     class_c_timeout,\n     mac_version,\n     reg_params_revision,\n     rx_delay_1,\n     rx_dr_offset_1,\n     rx_data_rate_2,\n     rx_freq_2,\n     factory_preset_freqs,\n     max_eirp,\n     max_duty_cycle,\n     supports_join,\n     rf_region,\n     supports_32bit_fcnt\n from device_profile\n where\n     device_profile_id = $1\n "
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[2018-09-03 11:46:14.626226077 +0000 UTC m=+55.795182798 2018-09-03 11:46:14.626226077 +0000 UTC m=+55.795182798 [57 48 50 53 96 55 135 4] [110 39 64 18 150 11] 877 64 true <nil> false <nil>]" duration=1.681592ms query="\n insert into device_queue (\n     created_at,\n     updated_at,\n     dev_eui,\n     frm_payload,\n     f_cnt,\n     f_port,\n     confirmed,\n     emit_at_time_since_gps_epoch,\n     is_pending,\n     timeout_after\n ) values ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)\n returning id"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=info msg="device-queue item created" dev_eui=3930323560378704 f_cnt=877
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=info msg="finished unary call with code OK" grpc.code=OK grpc.method=CreateDeviceQueueItem grpc.service=ns.NetworkServerService grpc.start_time="2018-09-03T11:46:14Z" grpc.time_ms=3.11 peer.address="127.0.0.1:49140" span.kind=server system=grpc
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:14  test-lora loraserver[2736]: time="2018-09-03T11:46:14Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:14.985140379 +0000 UTC m=+56.154097114]" duration="451.609µs" query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="sql query executed" args="[100 338891h46m35.163142281s]" duration=1.277301ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="sql query executed" args="[[57 48 50 53 96 55 135 4]]" duration="737.933µs" query="\n select\n     *\n from\n     device_queue\n where\n     dev_eui = $1\n order by\n     f_cnt\n limit 1"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="sql query executed" args="[3930323560378704]" duration="577.117µs" query="\n select\n     *\n from\n     device_queue\n where\n     dev_eui = $1\n order by\n     f_cnt"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="sql query executed" args="[2011 2018-09-03 11:46:15.168379441 +0000 UTC m=+56.337336124 [57 48 50 53 96 55 135 4] [110 39 64 18 150 11] 877 64 true <nil> true 2018-09-03 11:46:21.168378583 +0000 UTC m=+62.337335289]" duration=2.567207ms query="\n update device_queue\n set\n     updated_at = $2,\n     dev_eui = $3,\n     frm_payload = $4,\n     f_cnt = $5,\n     f_port = $6,\n     confirmed = $7,\n     emit_at_time_since_gps_epoch = $8,\n     is_pending = $9,\n     timeout_after = $10\n where\n     id = $1"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=info msg="device-queue item updated" dev_eui=3930323560378704 emit_at_time_since_gps_epoch="<nil>" f_cnt=877 is_pending=true timeout_after="2018-09-03 11:46:21.168378583 +0000 UTC m=+62.337335289"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=info msg="backend/gateway: publishing downlink frame" qos=0 topic=gateway/b827ebfffef7884f/tx
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=info msg="device-session saved" dev_addr=02b776f1 dev_eui=3930323560378704
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:15  test-lora loraserver[2736]: time="2018-09-03T11:46:15Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:15.988109491 +0000 UTC m=+57.157066237]" duration=1.553405ms query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:16  test-lora loraserver[2736]: time="2018-09-03T11:46:16Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:16  test-lora loraserver[2736]: time="2018-09-03T11:46:16Z" level=debug msg="sql query executed" args="[100 338891h46m36.180694248s]" duration=2.045274ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:16  test-lora loraserver[2736]: time="2018-09-03T11:46:16Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:16  test-lora loraserver[2736]: time="2018-09-03T11:46:16Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:16  test-lora loraserver[2736]: time="2018-09-03T11:46:16Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:16.993679066 +0000 UTC m=+58.162635779]" duration="993.507µs" query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:17  test-lora loraserver[2736]: time="2018-09-03T11:46:17Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:17  test-lora loraserver[2736]: time="2018-09-03T11:46:17Z" level=debug msg="sql query executed" args="[100 338891h46m37.187700619s]" duration=2.086461ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:17  test-lora loraserver[2736]: time="2018-09-03T11:46:17Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
Sep 03 11:46:17  test-lora loraserver[2736]: time="2018-09-03T11:46:17Z" level=debug msg="running multicast scheduler batch"
Sep 03 11:46:17  test-lora loraserver[2736]: time="2018-09-03T11:46:17Z" level=debug msg="sql query executed" args="[100 2018-09-03 11:46:17.996701334 +0000 UTC m=+59.165658101]" duration=1.612155ms query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tmulticast_queue\n\t\twhere\n\t\t\tschedule_at <= $2\n\t\torder by\n\t\t\tid\n\t\tlimit $1\n\t\tfor update skip locked\n\t"
Sep 03 11:46:18  test-lora loraserver[2736]: time="2018-09-03T11:46:18Z" level=debug msg="running class-b / class-c scheduler batch"
Sep 03 11:46:18  test-lora loraserver[2736]: time="2018-09-03T11:46:18Z" level=debug msg="sql query executed" args="[100 338891h46m38.192063393s]" duration=1.499006ms query="\n select\n     d.*\n from\n     device d\n inner join device_profile dp\n     on dp.device_profile_id = d.device_profile_id\n where (\n     \tdp.supports_class_c = true\n     \tor dp.supports_class_b = true\n     )\n     -- we want devices with queue items\n     and exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and (\n      \tdp.supports_class_c = true\n      \tor (\n      \t\tdp.supports_class_b = true\n      \t\tand dq.emit_at_time_since_gps_epoch <= $2\n      \t)\n      )\n     )\n     -- we don't want device with pending queue items that did not yet\n     -- timeout\n     and not exists (\n  select\n      1\n  from\n      device_queue dq\n  where\n      dq.dev_eui = d.dev_eui\n      and is_pending = true\n      and dq.timeout_after > now()\n     )\n order by\n     d.dev_eui\n limit $1\n for update of d skip locked"
Sep 03 11:46:18  test-lora loraserver[2736]: time="2018-09-03T11:46:18Z" level=error msg="schedule next device-queue item error" dev_eui=343437317436840e error="uplink gateway-history is empty"
andrewflash commented 6 years ago

Any update regarding this issue?

brocaar commented 6 years ago

@alkindirizky thanks for reporting 👍

I think I have found the issue. It wasn't correctly overwriting the TX power value for Class B and C.