Hi,
On the latest versions of Lora server (v3.2.0 and v3.2.1), it seems that frequently the network server does not respond to uplink frames where you would normally expect a response. I’ve noticed occurrences where a device sent over 20 join requests before the network server responded with a JoinAccept. Sometimes, after joining and sending confirmed uplinks, the network server also only sends back confirmation frames after many uplink frames are received.
I use an AS 923 setup with no 400ms dwell limits imposed. I also run an AU 915 setup and also experienced the same behaviour.
On the logs, no errors are shown (related to the marked frames). All the uplink frames in question show up with a gateway/mqtt: uplink frame received message and nothing else after. When the network server finally decides to respond, it then gets chatty:
time="2019-10-10T02:12:44Z" level=info msg="gateway/mqtt: uplink frame received"
time="2019-10-10T02:12:44Z" level=info msg="packet(s) collected" dev_eui=70b3d57050001395 gw_count=1 gw_ids=00800000a0003e52 mtype=JoinRequest
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[[112 179 213 112 80 0 19 149]]" duration=3.69053ms query="select * from device where dev_eui = $1"
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[0a708b17-3270-416f-bd9f-d6670c3ab09b]" duration=2.447928ms 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\t\t\tgeoloc_buffer_ttl,\n\t\t\tgeoloc_min_buffer_size\n from device_profile\n where\n device_profile_id = $1\n "
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[3a4644bb-083e-464e-afbb-37773f9de5d1]" duration=1.727534ms query="select * from service_profile where service_profile_id = $1"
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[70b3d57050001395 70b3d57050000004 935 JoinRequestType]" duration=2.773711ms query="\n\t\tselect\n\t\t\tcount(*)\n\t\tfrom\n\t\t\tdevice_activation\n\t\twhere\n\t\t\tdev_eui = $1\n\t\t\tand join_eui = $2\n\t\t\tand dev_nonce = $3\n\t\t\tand join_req_type = $4"
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[[112 179 213 112 80 0 19 149]]" duration=1.809977ms query="delete from device_queue where dev_eui = $1"
time="2019-10-10T02:12:44Z" level=info msg="device-queue flushed" dev_eui=70b3d57050001395
time="2019-10-10T02:12:44Z" level=info msg="device-session saved" dev_addr=005f9218 dev_eui=70b3d57050001395
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[2019-10-10 02:12:44.680458648 +0000 UTC m=+2070.510642185 [112 179 213 112 80 0 19 149] [112 179 213 112 80 0 0 4] [0 95 146 24] [166 238 149 137 253 173 159 108 206 166 19 213 53 46 34 224] [166 238 149 137 253 173 159 108 206 166 19 213 53 46 34 224] [166 238 149 137 253 173 159 108 206 166 19 213 53 46 34 224] 935 JoinRequestType]" duration=3.836299ms query="\n\t\tinsert into device_activation (\n\t\t\tcreated_at,\n\t\t\tdev_eui,\n\t\t\tjoin_eui,\n\t\t\tdev_addr,\n\t\t\ts_nwk_s_int_key,\n\t\t\tf_nwk_s_int_key,\n\t\t\tnwk_s_enc_key,\n\t\t\tdev_nonce,\n\t\t\tjoin_req_type\n\t\t) values ($1, $2, $3, $4, $5, $6, $7, $8, $9)\n\t\treturning id"
time="2019-10-10T02:12:44Z" level=info msg="device-activation created" dev_eui=70b3d57050001395 id=31
time="2019-10-10T02:12:44Z" level=debug msg="sql query executed" args="[[112 179 213 112 80 0 19 149] 2019-10-10 02:12:44.684386431 +0000 UTC m=+2070.514569974 0a708b17-3270-416f-bd9f-d6670c3ab09b 3a4644bb-083e-464e-afbb-37773f9de5d1 6d5db27e-4ce2-4b2b-b5d7-91f069397978 false 0 A]" duration=2.461622ms query="\n\t\tupdate device set\n\t\t\tupdated_at = $2,\n\t\t\tdevice_profile_id = $3,\n\t\t\tservice_profile_id = $4,\n\t\t\trouting_profile_id = $5,\n\t\t\tskip_fcnt_check = $6,\n\t\t\treference_altitude = $7,\n\t\t\tmode = $8\n\t\twhere\n\t\t\tdev_eui = $1"
time="2019-10-10T02:12:44Z" level=info msg="device updated" dev_eui=70b3d57050001395
time="2019-10-10T02:12:44Z" level=info msg="gateway/mqtt: publishing gateway command" command=down gateway_id=00800000a0003e52 qos=0 topic=gateway/00800000a0003e52/command/down
time="2019-10-10T02:12:44Z" level=info msg="downlink-frames saved" dev_eui=70b3d57050001395 token=21411
Is anyone else experiencing the same issues?