This entry is to help folks troubleshoot an OTAA Join Request / Accept cycle.
This is what it should look like
I went through a Join Request / Accept cycle on my now running system.
I recorded a log of lora-app-server with debug on, sudo journalctl -f -n 100 -u lora-app-server,
LOG FILE OUTPUT
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time=“2019-07-12T18:49:10-04:00” level=info msg=“finished streaming call with code Canceled” error=“rpc error: code = Canceled desc = context canceled” grpc.code=Canceled grpc.method=StreamFrameLogs grpc.service=api.DeviceService grpc.start_time=“2019-07-12T18:46:54-04:00” grpc.time_ms=136462.11 peer.address=“127.0.0.1:57912” span.kind=server system=grpc
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="js: request received" message_type=JoinReq receiver_id=696f740101010101 sender_id=030201 transaction_id=2352370911
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=debug msg="sql query executed" args="[[52 53 49 49 121 55 119 18]]" duration="799.958µs" query="select * from device_keys where dev_eui = $1"
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=debug msg="sql query executed" args="[[52 53 49 49 121 55 119 )]À 18] 2019-07-12 18:49:10.530369552 -0400 EDT m=+136.857560805 [43 126 21 22 40 174 210 166 171 247 21 136 9 207 79 60] [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] 8 [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]]" duration=4.14284ms query="\n update device_keys\n set\n updated_at = $2,\n\t\t\tnwk_key = $3,\n\t\t\tapp_key = $4,\n\t\t\tjoin_nonce = $5,\n\t\t\tgen_app_key = $6\n where\n dev_eui = $1"
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="device-keys updated" dev_eui=3435313179377712
Jul 12 18:49:10 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:10-04:00" level=info msg="js: sending response" message_type=JoinAns receiver_id=030201 result_code=Success sender_id=696f740101010101 transaction_id=2352370911
Jul 12 18:49:11 wiriots00 lora-app-server[1203]: time="2019-07-12T18:49:11-04:00" level=debug msg="sql query executed" args="[3 2019-07-12 18:49:11.084050786 -0400 EDT m=+137.411241976 100]" duration="896.612µs" 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"
LORWAN FRAMES FROM UI
Content for the JSON entries in the picture
[
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 924500000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “1s”
},
“context”: “t2xTBA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataDown”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 1,
“fOpts”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 9,
“chMask”: [
true,
true,
true,
true,
true,
true,
true,
true,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 0,
“nbRep”: 1
}
}
}
]
},
“fPort”: null,
“frmPayload”: null
},
“mic”: “50267fae”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -42,
“loraSnr”: 7.8,
“channel”: 2,
“rfChain”: 0,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “t2xTBA==”
}
],
“txInfo”: {
“frequency”: 902700000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataUp”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 2,
“fOpts”: null
},
“fPort”: 0,
“frmPayload”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“channelMaskAck”: true,
“dataRateAck”: true,
“powerAck”: true
}
},
{
“cid”: “LinkADRReq”,
“payload”: {
“channelMaskAck”: true,
“dataRateAck”: true,
“powerAck”: true
}
}
]
},
“mic”: “2d0871fd”
}
},
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 923900000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “1s”
},
“context”: “ttRgjA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataDown”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 0,
“fOpts”: [
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 0,
“chMask”: [
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 7,
“nbRep”: 0
}
}
},
{
“cid”: “LinkADRReq”,
“payload”: {
“dataRate”: 0,
“txPower”: 5,
“chMask”: [
true,
true,
true,
true,
true,
true,
true,
true,
false,
false,
false,
false,
false,
false,
false,
false
],
“redundancy”: {
“chMaskCntl”: 0,
“nbRep”: 1
}
}
}
]
},
“fPort”: null,
“frmPayload”: null
},
“mic”: “a0256faa”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -41,
“loraSnr”: 10,
“channel”: 1,
“rfChain”: 0,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “ttRgjA==”
}
],
“txInfo”: {
“frequency”: 902500000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “UnconfirmedDataUp”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“fhdr”: {
“devAddr”: “034b35eb”,
“fCtrl”: {
“adr”: true,
“adrAckReq”: false,
“ack”: false,
“fPending”: false,
“classB”: false
},
“fCnt”: 1,
“fOpts”: null
},
“fPort”: 99,
“frmPayload”: [
{
“bytes”: “cVa80j4c/p4b2Dk=”
}
]
},
“mic”: “b98e89ef”
}
},
{
“downlinkMetaData”: {
“txInfo”: {
“gatewayId”: “0004a30b0022813c”,
“frequency”: 925700000,
“power”: 20,
“modulation”: “LORA”,
“loraModulationInfo”: {
“bandwidth”: 500,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: true
},
“board”: 0,
“antenna”: 0,
“timing”: “DELAY”,
“delayTimingInfo”: {
“delay”: “5s”
},
“context”: “tjuRDA==”
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “JoinAccept”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“bytes”: “rRhFmXoqzPerBoL4bF82n6H4BSpUad2XyF3FwA==”
},
“mic”: “f2d2f108”
}
},
{
“uplinkMetaData”: {
“rxInfo”: [
{
“gatewayId”: “0004a30b0022813c”,
“time”: null,
“timeSinceGpsEpoch”: null,
“rssi”: -41,
“loraSnr”: 11,
“channel”: 4,
“rfChain”: 1,
“board”: 0,
“antenna”: 0,
“location”: {
“latitude”: 45.37303,
“longitude”: -75.6234,
“altitude”: 227,
“source”: “UNKNOWN”,
“accuracy”: 0
},
“fineTimestampType”: “NONE”,
“context”: “tjuRDA==”
}
],
“txInfo”: {
“frequency”: 903100000,
“modulation”: “LORA”,
“loRaModulationInfo”: {
“bandwidth”: 125,
“spreadingFactor”: 10,
“codeRate”: “4/5”,
“polarizationInversion”: false
}
}
},
“phyPayload”: {
“mhdr”: {
“mType”: “JoinRequest”,
“major”: “LoRaWANR1”
},
“macPayload”: {
“joinEUI”: “696f740101010101”,
“devEUI”: “3435313179377712”,
“devNonce”: 21441
},
“mic”: “665251e3”
}
}
]
