Hi @arjanvanb,
very kind of you posting such log, I really appreciate it! Following your lead I did a bit of logging as well, seems like timing is working fine also on my side.
/ * OTAA activation tentative. Device not activated! JOIN_ACCEPT message forwarded to endnode
5 seconds after JOIN_REQUEST */
11:04:50.435723 IP 31.157.192.137.49457 > 52.169.76.203.1700: UDP, length 243
0x0000: 4500 010f c9ec 4000 4011 0e57 1f9d c089 E.....@.@..W....
0x0010: 34a9 4ccb c131 06a4 00fb c605 01d9 6700 4.L..1........g.
0x0020: 0000 024b 0803 0571 7b22 7278 706b 223a ...K...q{"rxpk":
0x0030: 5b7b 2274 6d73 7422 3a39 3938 3937 3935 [{"tmst":9989795
0x0040: 3438 2c22 7469 6d65 223a 2232 3031 372d 48,"time":"2017-
0x0050: 3031 2d32 3754 3130 3a30 343a 3530 2e34 01-27T10:04:50.4
0x0060: 3335 3131 315a 222c 2263 6861 6e22 3a30 35111Z","chan":0
0x0070: 2c22 7266 6368 223a 312c 2266 7265 7122 ,"rfch":1,"freq"
0x0080: 3a38 3638 2e31 3030 3030 302c 2273 7461 :868.100000,"sta
0x0090: 7422 3a31 2c22 6d6f 6475 223a 224c 4f52 t":1,"modu":"LOR
0x00a0: 4122 2c22 6461 7472 223a 2253 4638 4257 A","datr":"SF8BW
0x00b0: 3132 3522 2c22 636f 6472 223a 2234 2f35 125","codr":"4/5
0x00c0: 222c 226c 736e 7222 3a31 312e 382c 2272 ","lsnr":11.8,"r
0x00d0: 7373 6922 3a2d 3335 2c22 7369 7a65 223a ssi":-35,"size":
0x00e0: 3233 2c22 6461 7461 223a 2241 4730 7a41 23,"data":"AG0zA
0x00f0: 5042 2b31 624e 774c 6439 376a 746d 5761 PB+1bNwLd97jtmWa
0x0100: 5144 675a 3552 3932 4e77 3d22 7d5d 7d QDgZ5R92Nw="}]}
11:04:51.254810 IP 52.169.76.203.1700 > 31.157.192.137.49457: UDP, length 4
0x0000: 4500 0020 b229 4000 2c11 3b09 34a9 4ccb E....)@.,.;.4.L.
0x0010: 1f9d c089 06a4 c131 000c 6d8b 01d9 6701 .......1..m...g.
11:04:55.914887 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 198
0x0000: 4500 00e2 b68a 4000 2c11 35e6 34a9 4ccb E.....@.,.5.4.L.
0x0010: 1f9d c089 06a4 aebb 00ce a1a4 0100 0003 ................
0x0020: 7b22 7478 706b 223a 7b22 696d 6d65 223a {"txpk":{"imme":
0x0030: 6661 6c73 652c 2274 6d73 7422 3a31 3030 false,"tmst":100
0x0040: 3339 3739 3534 382c 2266 7265 7122 3a38 3979548,"freq":8
0x0050: 3638 2e31 2c22 7266 6368 223a 302c 2270 68.1,"rfch":0,"p
0x0060: 6f77 6522 3a31 342c 226d 6f64 7522 3a22 owe":14,"modu":"
0x0070: 4c4f 5241 222c 2264 6174 7222 3a22 5346 LORA","datr":"SF
0x0080: 3842 5731 3235 222c 2263 6f64 7222 3a22 8BW125","codr":"
0x0090: 342f 3522 2c22 6970 6f6c 223a 7472 7565 4/5","ipol":true
0x00a0: 2c22 7369 7a65 223a 3333 2c22 6461 7461 ,"size":33,"data
0x00b0: 223a 2249 4779 6469 494b 5073 6b77 3064 ":"IGydiIKPskw0d
0x00c0: 5230 7654 4234 686e 3463 4f48 6462 6b64 R0vTB4hn4cOHdbkd
0x00d0: 5967 622f 4458 6874 2f6c 4872 4f79 4222 Ygb/DXht/lHrOyB"
0x00e0: 7d7d }}
11:04:58.718783 IP 31.157.192.137.44731 > 52.169.76.203.1700: UDP, length 12
0x0000: 4500 0028 c9ed 4000 4011 0f3d 1f9d c089 E..(..@.@..=....
0x0010: 34a9 4ccb aebb 06a4 0014 20d7 0133 b702 4.L..........3..
0x0020: 0000 024b 0803 0571 ...K...q
11:04:58.944786 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 4
0x0000: 4500 0020 b76f 4000 2c11 35c3 34a9 4ccb E....o@.,.5.4.L.
0x0010: 1f9d c089 06a4 aebb 000c 30a4 0133 b704 ..........0..3..
11:05:08.738834 IP 31.157.192.137.44731 > 52.169.76.203.1700: UDP, length 12
0x0000: 4500 0028 c9ee 4000 4011 0f3c 1f9d c089 E..(..@.@..<....
0x0010: 34a9 4ccb aebb 06a4 0014 8771 0199 5002 4.L........q..P.
0x0020: 0000 024b 0803 0571 ...K...q
11:05:08.984790 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 4
0x0000: 4500 0020 b999 4000 2c11 3399 34a9 4ccb E.....@.,.3.4.L.
0x0010: 1f9d c089 06a4 aebb 000c 973e 0199 5004 ...........>..P.
11:05:13.950806 IP 31.157.192.137.49457 > 52.169.76.203.1700: UDP, length 111
0x0000: 4500 008b c9ef 4000 4011 0ed8 1f9d c089 E.....@.@.......
0x0010: 34a9 4ccb c131 06a4 0077 f9dd 01a3 e300 4.L..1...w......
0x0020: 0000 024b 0803 0571 7b22 7374 6174 223a ...K...q{"stat":
0x0030: 7b22 7469 6d65 223a 2232 3031 372d 3031 {"time":"2017-01
0x0040: 2d32 3720 3130 3a30 353a 3133 2047 4d54 -27.10:05:13.GMT
0x0050: 222c 2272 786e 6222 3a31 2c22 7278 6f6b ","rxnb":1,"rxok
0x0060: 223a 312c 2272 7866 7722 3a31 2c22 6163 ":1,"rxfw":1,"ac
0x0070: 6b72 223a 302e 302c 2264 776e 6222 3a31 kr":0.0,"dwnb":1
0x0080: 2c22 7478 6e62 223a 317d 7d ,"txnb":1}}`
As you can see, the JOIN_ACCEPT message is forwarded to the endnode 5 secs after the JOIN_REQUEST, same timing as yours. Then I decided to restart both gateway and arduino since, by now, this is the only way I can get my device activated (in fact it worked and device was being immediately activated). With device activated, I sent few downlink packets to monitor timing and see if it is in accordance with the results you posted.
/* OTAA device activated! Uplink packet sent back to endnode 1 sec after "Hello World!" downlink */
10:52:06.493745 IP 31.157.192.137.49457 > 52.169.76.203.1700: UDP, length 246
0x0000: 4500 0112 c97a 4000 4011 0ec6 1f9d c089 E....z@.@.......
0x0010: 34a9 4ccb c131 06a4 00fe 365e 015c 2a00 4.L..1....6^.\*.
0x0020: 0000 024b 0803 0571 7b22 7278 706b 223a ...K...q{"rxpk":
0x0030: 5b7b 2274 6d73 7422 3a32 3335 3032 3630 [{"tmst":2350260
0x0040: 3532 2c22 7469 6d65 223a 2232 3031 372d 52,"time":"2017-
0x0050: 3031 2d32 3754 3039 3a35 323a 3036 2e34 01-27T09:52:06.4
0x0060: 3933 3135 335a 222c 2263 6861 6e22 3a35 93153Z","chan":5
0x0070: 2c22 7266 6368 223a 302c 2266 7265 7122 ,"rfch":0,"freq"
0x0080: 3a38 3637 2e35 3030 3030 302c 2273 7461 :867.500000,"sta
0x0090: 7422 3a31 2c22 6d6f 6475 223a 224c 4f52 t":1,"modu":"LOR
0x00a0: 4122 2c22 6461 7472 223a 2253 4637 4257 A","datr":"SF7BW
0x00b0: 3132 3522 2c22 636f 6472 223a 2234 2f35 125","codr":"4/5
0x00c0: 222c 226c 736e 7222 3a37 2e38 2c22 7273 ","lsnr":7.8,"rs
0x00d0: 7369 223a 2d33 312c 2273 697a 6522 3a32 si":-31,"size":2
0x00e0: 362c 2264 6174 6122 3a22 5143 5174 4153 6,"data":"QCQtAS
0x00f0: 6141 4267 4142 5647 566e 6e6c 307a 6556 aABgABVGVnnl0zeV
0x0100: 5a72 7144 554e 4c78 4261 6b4b 413d 227d ZrqDUNLxBakKA="}
0x0110: 5d7d ]}
10:52:07.219847 IP 52.169.76.203.1700 > 31.157.192.137.49457: UDP, length 4
0x0000: 4500 0020 30ce 4000 2c11 bc64 34a9 4ccb E...0.@.,..d4.L.
0x0010: 1f9d c089 06a4 c131 000c ab08 015c 2a01 .......1.....\*.
10:52:07.880705 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 173
0x0000: 4500 00c9 30d8 4000 2c11 bbb1 34a9 4ccb E...0.@.,...4.L.
0x0010: 1f9d c089 06a4 aebb 00b5 4d85 0100 0003 ..........M.....
0x0020: 7b22 7478 706b 223a 7b22 696d 6d65 223a {"txpk":{"imme":
0x0030: 6661 6c73 652c 2274 6d73 7422 3a32 3336 false,"tmst":236
0x0040: 3032 3630 3532 2c22 6672 6571 223a 3836 026052,"freq":86
0x0050: 372e 352c 2272 6663 6822 3a30 2c22 706f 7.5,"rfch":0,"po
0x0060: 7765 223a 3134 2c22 6d6f 6475 223a 224c we":14,"modu":"L
0x0070: 4f52 4122 2c22 6461 7472 223a 2253 4637 ORA","datr":"SF7
0x0080: 4257 3132 3522 2c22 636f 6472 223a 2234 BW125","codr":"4
0x0090: 2f35 222c 2269 706f 6c22 3a74 7275 652c /5","ipol":true,
0x00a0: 2273 697a 6522 3a31 342c 2264 6174 6122 "size":14,"data"
0x00b0: 3a22 5943 5174 4153 5941 4151 4142 3742 :"YCQtASYAAQAB7B
0x00c0: 6f46 6230 773d 227d 7d oFb0w="}}
10:52:13.933259 IP 31.157.192.137.49457 > 52.169.76.203.1700: UDP, length 111
0x0000: 4500 008b c97b 4000 4011 0f4c 1f9d c089 E....{@.@..L....
0x0010: 34a9 4ccb c131 06a4 0077 3087 01ec b000 4.L..1...w0.....
0x0020: 0000 024b 0803 0571 7b22 7374 6174 223a ...K...q{"stat":
0x0030: 7b22 7469 6d65 223a 2232 3031 372d 3031 {"time":"2017-01
0x0040: 2d32 3720 3039 3a35 323a 3133 2047 4d54 -27.09:52:13.GMT
0x0050: 222c 2272 786e 6222 3a31 2c22 7278 6f6b ","rxnb":1,"rxok
0x0060: 223a 312c 2272 7866 7722 3a31 2c22 6163 ":1,"rxfw":1,"ac
0x0070: 6b72 223a 302e 302c 2264 776e 6222 3a31 kr":0.0,"dwnb":1
0x0080: 2c22 7478 6e62 223a 317d 7d ,"txnb":1}}
10:52:14.419806 IP 52.169.76.203.1700 > 31.157.192.137.49457: UDP, length 4
0x0000: 4500 0020 3470 4000 2c11 b8c2 34a9 4ccb E...4p@.,...4.L.
0x0010: 1f9d c089 06a4 c131 000c 2478 01ec b001 .......1..$x....
10:52:15.298769 IP 31.157.192.137.44731 > 52.169.76.203.1700: UDP, length 12
0x0000: 4500 0028 c97c 4000 4011 0fae 1f9d c089 E..(.|@.@.......
0x0010: 34a9 4ccb aebb 06a4 0014 dcce 013b fb02 4.L..........;..
0x0020: 0000 024b 0803 0571 ...K...q
10:52:15.540786 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 4
0x0000: 4500 0020 3493 4000 2c11 b89f 34a9 4ccb E...4.@.,...4.L.
0x0010: 1f9d c089 06a4 aebb 000c ec9b 013b fb04 .............;..
10:52:25.348910 IP 31.157.192.137.44731 > 52.169.76.203.1700: UDP, length 12
0x0000: 4500 0028 c97d 4000 4011 0fad 1f9d c089 E..(.}@.@.......
0x0010: 34a9 4ccb aebb 06a4 0014 28d8 0132 af02 4.L.......(..2..
0x0020: 0000 024b 0803 0571 ...K...q
10:52:25.579806 IP 52.169.76.203.1700 > 31.157.192.137.44731: UDP, length 4
0x0000: 4500 0020 37a7 4000 2c11 b58b 34a9 4ccb E...7.@.,...4.L.
0x0010: 1f9d c089 06a4 aebb 000c 38a5 0132 af04 ..........8..2..
In this latter case, the downlink packet sent from TTN console follows the “Hello World!” uplink, and it was forwarded 1 sec after. However, I couldn’t open Arduino Serial Monitor since it would restart the sketch and (for sure considering any previous attempt), it would have failed trying to activate my device once again.
Finally, I uploaded the “ttn-abp.ino” sketch to check timing as well. What I have seen is that also in this case the downlink packet from the server is forwarded 1 sec after the “Hello World!” uplink, so I guess it should be just fine…however I don’t see any packet received on Serial Monitor (LMIC.dataLen = 0 means that no packet is being received).
/* ABP activated device. Downlink packet sent to endnode 1 sec after "Hello World!" uplink.
However, LMIC.dataLen=0 on Arduino side meaning no downlink packet has been received. */
10:19:53.487901 IP 2.43.193.163.33372 > 52.169.76.203.1700: UDP, length 247
0x0000: 4500 0113 067b 4000 4011 ee1c 022b c1a3 E....{@.@....+..
0x0010: 34a9 4ccb 825c 06a4 00ff 832b 0135 c100 4.L..\.....+.5..
0x0020: 0000 024b 0803 0571 7b22 7278 706b 223a ...K...q{"rxpk":
0x0030: 5b7b 2274 6d73 7422 3a31 3433 3539 3937 [{"tmst":1435997
0x0040: 3637 352c 2274 696d 6522 3a22 3230 3137 675,"time":"2017
0x0050: 2d30 312d 3237 5430 393a 3139 3a35 332e -01-27T09:19:53.
0x0060: 3438 3733 3032 5a22 2c22 6368 616e 223a 487302Z","chan":
0x0070: 322c 2272 6663 6822 3a31 2c22 6672 6571 2,"rfch":1,"freq
0x0080: 223a 3836 382e 3530 3030 3030 2c22 7374 ":868.500000,"st
0x0090: 6174 223a 312c 226d 6f64 7522 3a22 4c4f at":1,"modu":"LO
0x00a0: 5241 222c 2264 6174 7222 3a22 5346 3742 RA","datr":"SF7B
0x00b0: 5731 3235 222c 2263 6f64 7222 3a22 342f W125","codr":"4/
0x00c0: 3522 2c22 6c73 6e72 223a 372e 322c 2272 5","lsnr":7.2,"r
0x00d0: 7373 6922 3a2d 3333 2c22 7369 7a65 223a ssi":-33,"size":
0x00e0: 3236 2c22 6461 7461 223a 2251 4830 6141 26,"data":"QH0aA
0x00f0: 5361 4142 5141 424e 7863 3963 5a54 4d79 SaABQABNxc9cZTMy
0x0100: 6a36 4342 4676 5571 6679 5938 5a6b 3d22 j6CBFvUqfyY8Zk="
0x0110: 7d5d 7d }]}
10:19:54.295617 IP 52.169.76.203.1700 > 2.43.193.163.33372: UDP, length 4
0x0000: 4500 0020 2dc5 4000 2c11 dbc5 34a9 4ccb E...-.@.,...4.L.
0x0010: 022b c1a3 06a4 825c 000c 6f5c 0135 c101 .+.....\..o\.5..
10:19:54.936678 IP 52.169.76.203.1700 > 2.43.193.163.44112: UDP, length 174
0x0000: 4500 00ca 2e13 4000 2c11 dacd 34a9 4ccb E.....@.,...4.L.
0x0010: 022b c1a3 06a4 ac50 00b6 ac81 0100 0003 .+.....P........
0x0020: 7b22 7478 706b 223a 7b22 696d 6d65 223a {"txpk":{"imme":
0x0030: 6661 6c73 652c 2274 6d73 7422 3a31 3433 false,"tmst":143
0x0040: 3639 3937 3637 352c 2266 7265 7122 3a38 6997675,"freq":8
0x0050: 3638 2e35 2c22 7266 6368 223a 302c 2270 68.5,"rfch":0,"p
0x0060: 6f77 6522 3a31 342c 226d 6f64 7522 3a22 owe":14,"modu":"
0x0070: 4c4f 5241 222c 2264 6174 7222 3a22 5346 LORA","datr":"SF
0x0080: 3742 5731 3235 222c 2263 6f64 7222 3a22 7BW125","codr":"
0x0090: 342f 3522 2c22 6970 6f6c 223a 7472 7565 4/5","ipol":true
0x00a0: 2c22 7369 7a65 223a 3134 2c22 6461 7461 ,"size":14,"data
0x00b0: 223a 2259 4830 6141 5359 4141 5141 426b ":"YH0aASYAAQABk
0x00c0: 5a74 4a6d 7634 3d22 7d7d ZtJmv4="}}
10:19:57.538524 IP 2.43.193.163.44112 > 52.169.76.203.1700: UDP, length 12
0x0000: 4500 0028 067c 4000 4011 ef06 022b c1a3 E..(.|@.@....+..
0x0010: 34a9 4ccb ac50 06a4 0014 1206 01c7 e402 4.L..P..........
0x0020: 0000 024b 0803 0571 ...K...q
10:19:57.785606 IP 52.169.76.203.1700 > 2.43.193.163.44112: UDP, length 4
0x0000: 4500 0020 3072 4000 2c11 d918 34a9 4ccb E...0r@.,...4.L.
0x0010: 022b c1a3 06a4 ac50 000c 21d3 01c7 e404 .+.....P..!.....
10:19:59.952094 IP 2.43.193.163.33372 > 52.169.76.203.1700: UDP, length 111
0x0000: 4500 008b 067d 4000 4011 eea2 022b c1a3 E....}@.@....+..
0x0010: 34a9 4ccb 825c 06a4 0077 ae79 0124 8300 4.L..\...w.y.$..
0x0020: 0000 024b 0803 0571 7b22 7374 6174 223a ...K...q{"stat":
0x0030: 7b22 7469 6d65 223a 2232 3031 372d 3031 {"time":"2017-01
0x0040: 2d32 3720 3039 3a31 393a 3539 2047 4d54 -27.09:19:59.GMT
0x0050: 222c 2272 786e 6222 3a32 2c22 7278 6f6b ","rxnb":2,"rxok
0x0060: 223a 312c 2272 7866 7722 3a31 2c22 6163 ":1,"rxfw":1,"ac
0x0070: 6b72 223a 302e 302c 2264 776e 6222 3a31 kr":0.0,"dwnb":1
0x0080: 2c22 7478 6e62 223a 317d 7d ,"txnb":1}}
10:20:00.505729 IP 52.169.76.203.1700 > 2.43.193.163.33372: UDP, length 4
0x0000: 4500 0020 32d4 4000 2c11 d6b6 34a9 4ccb E...2.@.,...4.L.
0x0010: 022b c1a3 06a4 825c 000c ad6d 0124 8301 .+.....\...m.$..
Few considerations:
-
I have noticed that I don’t see ACK traffic after a packet is being sent, so I guess that if a packet get lost no way to recognize that event.
-
Downlink packets are sent 1 sec after uplink, so Arduino should get them in the RX1 first slot. Is that supposed to work with LMIC library? @matthijs
-
Downlink packets are sent over the same channel used for uplink. I have seen from your log that it has been forwarded on the 869.525 MHZ with SF9BW125 instead. Is that normal? As far as I recall the uplink transmission should be accomplished with a SF9…but maybe I am wrong.
Once again, many thanks for your support. Looking forward for your feedback!