Hi,
When I try to have my device join Chirpstack, I get an error:
error:"join-server returned error: unmarshal response error: invalid character 'u' looking for beginning of value"
I first suspected that it was a version mismatch between the components, but I’ve tried the latest ones and the ones I had success with earlier to to prevail.
That would be: chirpstack-network-server:3.10, chirpstack-application-server:3.12.2, chirpstack-gateway-bridge:3.9.
I’ve attached the parts of the logs, and screenshots showing the error in the UI.
Let me know if more information is required to debug this issue.
In “Live lorawan frames” under my gateway, it’s decoded fine: https://i.imgur.com/ABTacIW.png
When I look at “Device Data” for the device, the error is shown: https://i.imgur.com/UFyY7w8.png
Logs, Gateway bridge:
2020-11-09T11:48:37.971361252Z time="2020-11-09T11:48:37Z" level=debug msg="backend/semtechudp: received udp packet from gateway" addr="10.240.1.250:7669" protocol_version=2 type=PushData 2020-11-09T11:48:37.971492353Z time="2020-11-09T11:48:37Z" level=info msg="integration/mqtt: publishing event" event=up qos=0 topic=gateway/60c5a8fffe761594/event/up uplink_id=f2b36bcb-828b-4818-82cb-4a72a0aa2a21 2020-11-09T11:48:37.971499953Z time="2020-11-09T11:48:37Z" level=debug msg="[client] enter Publish" module=mqtt 2020-11-09T11:48:37.971532653Z time="2020-11-09T11:48:37Z" level=debug msg="[client] sending publish message, topic: gateway/60c5a8fffe761594/event/up" module=mqtt 2020-11-09T11:48:37.971535953Z time="2020-11-09T11:48:37Z" level=debug msg="[net] obound wrote msg, id: 0" module=mqtt 2020-11-09T11:48:37.971538853Z time="2020-11-09T11:48:37Z" level=debug msg="[net] outgoing waiting for an outbound message" module=mqtt 2020-11-09T11:48:37.972772762Z time="2020-11-09T11:48:37Z" level=debug msg="backend/semtechudp: sending udp packet to gateway" addr="10.240.1.250:7669" protocol_version=2 type=PushACK
Logs, Application server:
time="2020-11-09T08:33:13Z" level=debug msg="sql query executed" args="[]" duration=2.719612ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[1]" duration=2.973013ms query="\n\t\tselect *\n\t\tfrom integration\n\t\twhere application_id = $1\n\t\torder by kind" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[1]" duration=5.050522ms query="select * from application where id = $1" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[3 2020-11-09 08:33:14.072527565 +0000 UTC m=+257546.004447683 SETUP 100]" duration=3.219714ms query="\n\t\tselect\n\t\t\tsess.*\n\t\tfrom\n\t\t\tremote_multicast_class_c_session sess\n\t\tinner join\n\t\t\tremote_multicast_setup ms\n\t\t\ton\n\t\t\t\tsess.dev_eui = ms.dev_eui\n\t\t\t\tand sess.multicast_group_id = ms.multicast_group_id\n\t\t\t\tand sess.mc_group_id = ms.mc_group_id\n\t\twhere\n\t\t\tms.state_provisioned = true\n\t\t\tand ms.state = $3\n\t\t\tand sess.state_provisioned = false\n\t\t\tand sess.retry_count < $1\n\t\t\tand sess.retry_after < $2\n\t\tlimit $4\n\t\tfor update\n\t\tskip locked" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[3 2020-11-09 08:33:14.227324938 +0000 UTC m=+257546.159244956 100]" duration=3.375315ms query="\n\t\tselect\n\t\t\t*\n\t\tfrom\n\t\t\tremote_multicast_setup\n\t\twhere\n\t\t\tstate_provisioned = false\n\t\t\tand retry_count < $1\n\t\t\tand retry_after < $2\n\t\tlimit $3\n\t\tfor update\n\t\tskip locked" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[3 2020-11-09 08:33:14.741496973 +0000 UTC m=+257546.673416991 100]" duration=3.915217ms query="\n\t\tselect\n\t\t\tfs.dev_eui,\n\t\t\tfs.frag_index,\n\t\t\tfs.created_at,\n\t\t\tfs.updated_at,\n\t\t\tfs.mc_group_ids,\n\t\t\tfs.nb_frag,\n\t\t\tfs.frag_size,\n\t\t\tfs.fragmentation_matrix,\n\t\t\tfs.block_ack_delay,\n\t\t\tfs.padding,\n\t\t\tfs.descriptor,\n\t\t\tfs.state,\n\t\t\tfs.state_provisioned,\n\t\t\tfs.retry_after,\n\t\t\tfs.retry_count,\n\t\t\tfs.retry_interval\n\t\tfrom\n\t\t\tremote_fragmentation_session fs\n\t\twhere\n\t\t\tfs.state_provisioned = false\n\t\t\tand fs.retry_count < $1\n\t\t\tand fs.retry_after < $2\n\t\t\tand (\n\t\t\t\t-- in case of unicast\n\t\t\t\tarray_length(fs.mc_group_ids, 1) is null\n\n\t\t\t\t-- in case of multicast\n\t\t\t\tor exists (\n\t\t\t\t\tselect\n\t\t\t\t\t\t1\n\t\t\t\t\tfrom\n\t\t\t\t\t\tremote_multicast_setup ms\n\t\t\t\t\twhere\n\t\t\t\t\t\tms.dev_eui = fs.dev_eui\n\t\t\t\t\t\tand ms.state_provisioned = true\n\t\t\t\t\t\tand ms.mc_group_id = any(fs.mc_group_ids)\n\t\t\t\t)\n\t\t\t)\n\t\tlimit $3\n\t\tfor update of fs\n\t\tskip locked" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[DONE 2020-11-09 08:33:14.215420086 +0000 UTC m=+257546.147340104 1]" duration=3.006113ms query="\n\t\tselect\n\t\t\tid,\n\t\t\tcreated_at,\n\t\t\tupdated_at,\n\t\t\tname,\n\t\t\tmulticast_group_id,\n\t\t\tfragmentation_matrix,\n\t\t\tdescriptor,\n\t\t\tpayload,\n\t\t\tstate,\n\t\t\tnext_step_after,\n\t\t\tunicast_timeout,\n\t\t\tfrag_size,\n\t\t\tredundancy,\n\t\t\tblock_ack_delay,\n\t\t\tmulticast_timeout,\n\t\t\tgroup_type,\n\t\t\tdr,\n\t\t\tfrequency,\n\t\t\tping_slot_period\n\t\tfrom\n\t\t\tfuota_deployment\n\t\twhere\n\t\t\tstate != $1\n\t\t\tand next_step_after <= $2\n\t\tlimit $3\n\t\tfor update\n\t\tskip locked" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[[168 23 88 255 254 4 46 130]]" duration=3.237714ms query="select * from device where dev_eui = $1" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[]" duration=1.490307ms query="\n\t\tselect\n\t\t\tg.*\n\t\tfrom gateway g\n\t\tinner join network_server ns\n\t\t\ton ns.id = g.network_server_id\n\t\twhere\n\t\t\tns.gateway_discovery_enabled = true\n\t\t\tand g.ping = true\n\t\t\tand (g.last_ping_sent_at is null or g.last_ping_sent_at <= (now() - (interval '24 hours' / ns.gateway_discovery_interval)))\n\t\torder by last_ping_sent_at\n\t\tlimit 1\n\t\tfor update" time="2020-11-09T08:33:14Z" level=error msg="api/js: unmarshal base payload error" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="api/js: unmarshal base payload error" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="api/js: unmarshal base payload error" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="backend/joinserver: error handling request" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="backend/joinserver: error handling request" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="backend/joinserver: error handling request" error="unexpected end of JSON input" time="2020-11-09T08:33:14Z" level=error msg="join-server returned error: unmarshal response error: invalid character 'u' looking for beginning of value" dev_eui=a81758fffe042e82 type=OTAA time="2020-11-09T08:33:14Z" level=info msg="finished unary call with code OK" ctx_id=0f88a4d2-3790-4b04-b2da-603e817c59eb grpc.code=OK grpc.method=HandleError grpc.service=as.ApplicationServerService grpc.start_time="2020-11-09T08:33:14Z" grpc.time_ms=11.812 peer.address="127.0.0.1:50956" span.kind=server system=grpc time="2020-11-09T08:33:14Z" level=info msg="integration/logger: logging event" ctx_id=0f88a4d2-3790-4b04-b2da-603e817c59eb dev_eui=a81758fffe042e82 type=error time="2020-11-09T08:33:14Z" level=info msg="integration/mqtt: publishing event" ctx_id=0f88a4d2-3790-4b04-b2da-603e817c59eb dev_eui=a81758fffe042e82 qos=0 retain=false topic=application/1/device/a81758fffe042e82/event/error
Logs, network server:
time="2020-11-09T08:33:14Z" level=debug msg="running class-b / class-c scheduler batch" ctx_id=109cf1f0-0ae4-440a-b4fa-6bc34a867dd8 time="2020-11-09T08:33:14Z" level=debug msg="running multicast scheduler batch" ctx_id=71a6752b-94ef-458e-9bc4-844c7eda905c time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[100 2020-11-09 08:33:14.193659338 +0000 UTC m=+257255.349894477]" duration=2.745614ms 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" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[100 358040h33m34.834679196s 2020-11-09 08:33:14.834681496 +0000 UTC m=+257255.990916635]" duration=1.439008ms query="\n select\n d.*\n from\n device d\n where\n\t\t\td.mode in ('B', 'C')\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\t\t\t\t\t\td.mode = 'C'\n \tor (\n\t\t\t\t\t\t\td.mode = 'B'\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 > $3 \n )\n order by\n d.dev_eui\n limit $1\n for update of d skip locked" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[6d5db27e-4ce2-4b2b-b5d7-91f069397978]" duration=2.603814ms query="select * from routing_profile where routing_profile_id = $1" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[[168 23 88 255 254 4 46 130]]" duration=1.322907ms query="select * from device where dev_eui = $1" time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[a81758fffe042e82 0000000000000000 45632 JoinRequestType]" duration="824.804µs" 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="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[afa0a20c-59e8-4f24-8bce-5c154e21f315]" duration=1.294907ms 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 " time="2020-11-09T08:33:14Z" level=debug msg="sql query executed" args="[b36a2e0a-efa4-453b-bab6-8b69c0be0228]" duration="870.404µs" query="select * from service_profile where service_profile_id = $1" time="2020-11-09T08:33:14Z" level=error msg="uplink: processing uplink frame error" ctx_id=afdb9062-d24b-45e6-b2f1-841534e0aa90 error="join-request to join-server error: unmarshal response error: invalid character 'u' looking for beginning of value" time="2020-11-09T08:33:14Z" level=info msg="finished client unary call" ctx_id=afdb9062-d24b-45e6-b2f1-841534e0aa90 grpc.code=OK grpc.ctx_id=0f88a4d2-3790-4b04-b2da-603e817c59eb grpc.duration=16.862688ms grpc.method=HandleError grpc.service=as.ApplicationServerService span.kind=client system=grpc time="2020-11-09T08:33:14Z" level=info msg="gateway/mqtt: uplink frame received" gateway_id=60c5a8fffe761594 uplink_id=f40d85d9-9d4e-4ec6-94ee-d42b491942de time="2020-11-09T08:33:14Z" level=info msg="uplink: frame(s) collected" ctx_id=afdb9062-d24b-45e6-b2f1-841534e0aa90 mtype=JoinRequest uplink_ids="[f40d85d9-9d4e-4ec6-94ee-d42b491942de]"