OTAA ok, 12h later I get denied, reboot gateway --> OK again ...!?

arjanvanb · January 23, 2017, 10:09pm

And also, I still wonder if “regular” downlinks work at the time where (you expect) OTAA does not work.

By the way, if the following are indeed the Join Request and Accept, I find 5.5 seconds quite a long time to respond. Especially as I assume the backend servers are not really busy yet, and even more so as it’s just half a second before JOIN_ACCEPT_DELAY2:

(For a regular downlink, for EU863 the default RECEIVE_DELAY1 is 1 second, and RECEIVE_DELAY2 2 seconds. Maybe TTN configures different values?)

kersing · January 23, 2017, 11:04pm

The response for RX2 will be sent to the gateway between 5 and 6 seconds after the join request. However in my experience the response arrives just after the 5 second mark, not half a second into the window. Any additional delay is probably due to network lag. This is assuming the response is for RX2 and not a delayed RX1 packet…
(All downlink packets, join response and data, will be offered to the gateway within 1 second of it being due to be transmitted)

salvatore_forte · January 24, 2017, 10:54am

Hi @kersing,

maybe I was not that clear in the last post, the two pictures above are referred to an unsuccessful join attempt! Since I found out that I can’t get any downlink packet from web server, even when I use the ABP activation, I start to believe that the problem is the timestamp at which the RF packet delivery is scheduled. Who is defining it? Could be that there is a mismatch and that’s the reason why packets get lost?

arjanvanb · January 24, 2017, 11:03am

…or that it arrives quite late at your gateway? (I have not checked all your logs to see at what time the downlinks arrive; see kersing’s last post.)

salvatore_forte · January 24, 2017, 11:25am

Hi @arjanvanb,

only thing I know I am starting to get really confused! I can’t understand straight how things are going on!
I want to cool off a bit and review stuff since the beginning in order to get more understanding of the problem, even because seems like @matthijs was able to have “ttn-abp.ino” and “ttn-otaa.ino” both working on TTN, and I haven’t made any change of those sketch files.

kersing · January 24, 2017, 6:07pm

Ok, looked at the screenshots again, the issue you are having is timing related. The packet at 11:49:26.3… should have been sent by the gateway exactly 5 seconds after the packet of 11:49:20.8 arrived. The time between the sending the first and receiving the second packet exceeds 5 seconds so the gateway receives the data after it should have been transmitted. As a result the node will never receive the data at the time it expects it and the join fails.

Looking at the ‘PULL_ACK’ lines in the second screen shot I notice the turn around times vary wildly and are rather large. For my gateways the results are 20-40ms, your results are 240-882ms. The lower value might work, the high value is too large.

salvatore_forte · January 26, 2017, 11:38am

Hi @kersing,

sorry if it took me some time to answer. I agree with you, looks like the server is taking too long to send packets after receiving an uplink message. In fact, if you look at the picture, you can see that the gateway receive and forward downlink packets back to the end node on Lora side, but probably both its receive windows are already closed and the packet gets lost.

"tcpdump -i ppp0 port 1700 -X" and "./poly_pkt_fwd"

I have a few questions I would like to ask:

I am connecting to web server over GSM, and the gateway is placed indoor, could it be the reason why it’s taking so long to get ack/packets from server?
Could you give me an indication about end node timing? How long it takes to open both receive windows? How many seconds each window remain opened?
I am sending packets using the 3 standard Lora channels (868.1 MHz / 868.3 MHz / 868.5 MHz) that are configured into radio 1 gateway’s transceiver. I had a look into the “global_conf.json” file and looks like “tx_enable” is set to FALSE. Considering that the downlink packets are sent over the same 3 prior mentioned channels, is that configuration still ok or should I put it to TRUE? Could you have a look of it to see if I have set everything right?

Just to run a test, I would like to make the receive windows on Arduino side larger and see if the downlink problem still remain. @matthijs, could you advise me how to do that in the LMIC’s configuration files?

Many thanks for your kind support!

Best regards,

Salvatore

arjanvanb · January 26, 2017, 11:49am

…but you already tried that? Of course, you could make the windows even larger; @matthijs already explained earlier, as quoted above.

salvatore_forte · January 26, 2017, 11:53am

Hi @arjanvanb,

since the problem was the missing downlink packet reception, I got back to ABP sketch and I didn’t make that fix, also because it was not working anyway during OTAA. Any advise to give about that?

arjanvanb · January 26, 2017, 11:55am

I’d assume you could increase it by 10%, 20%, whatever you want. For 20%, I’d try:

LMIC_setClockError(MAX_CLOCK_ERROR * 20 / 100);

arjanvanb · January 26, 2017, 12:18pm

…but taking a step back:

If the downlink packets are received (or: pulled?) too late for the downlink window (which seems to be the problem), then why would restarting the gateway solve this for some time? Maybe it somehow decreases the 3G network lag, due to some more network activity when the gateway is started?

salvatore_forte · January 26, 2017, 2:17pm

…not hundred percent sure that the problem is due to late pull from server, but considering the results of the test I have made, I don’t see any other explanation by now.

[/quote][quote=“arjanvanb, post:36, topic:2025”]
LMIC_setClockError(MAX_CLOCK_ERROR * 20 / 100);
[/quote]

Anyway, this fix in the code doesn’t solve the problem. With regard to LMIC library I have seen that receiving downlink packets in RX1 window has been not tested yet. Only RX2 should work. Have you ever tried to get packets back using LMIC library?

arjanvanb · January 26, 2017, 3:31pm

True for TTN, for reasons described in Why is RX_SLOT 1 not used?

Not for data, but LMiC OTAA works fine for me.

How far did you stretch the receive window? Maybe even 100% of the maximum error is allowed:

LMIC_setClockError(MAX_CLOCK_ERROR);

salvatore_forte · January 26, 2017, 4:02pm

Hi @arjanvanb,

Have you tried to just remove power from your arduino (or even push the reset button) and then try to activate it once again? In my case, as soon as I restart my Arduino, I can’t activate the device any longer (I didn’t make any change at all!).
I post the console view: in the event of a restart, you can see a new JOIN_REQUEST, the device can’t get JOIN_ACCEPT so it will keep sending request at scheduled TX interval.

Please, let me know if you run that test.

arjanvanb · January 26, 2017, 4:42pm

I have no specific problems with resetting and all. I don’t always get a successful OTAA right away, but I’m using Jaap’s single channel gateway, and that uses some smart timing to scan for all spreading factors, that might miss out on packets. I never need to reset anything to eventually get activated.

But that’s not new information, right? That’s why you came to this topic in the first place, or has something changed now?

arjanvanb · January 26, 2017, 6:47pm

A bit of logging from my single channel gateway, for a successful OTAA:

A 18:23:18.659167	pull	01946a025ccf7ff42f1970ec
B 18:23:22.555010	rxpk	01bf72005ccf7ff42f1970ec	message	{"rxpk":[{"rssi":-46,"stat":1,"modu":"LORA","rfch":0,"tmst":349218460,"datr":"SF7BW125","lsnr":9,"time":"2017-01-26T18:23:22.510034Z","codr":"4/5","data":"ANwAANB+1bNwHm/t9XzurwDIhgMK8sk=","freq":868.100,"chan":0,"size":23}]}	length	237
C 18:23:23.658268	pull	01af68025ccf7ff42f1970ec
D 18:23:27.372908	txpk	{"txpk":{"imme":false,"tmst":354218460,"freq":868.1,"rfch":0,"powe":14,"modu":"LORA","datr":"SF7BW125","codr":"4/5","ipol":true,"size":33,"data":"IIE/R/UI/6JnC24j4B+EueJdnEEV8C7qCz3T4gs+ypLa"}}
E 18:23:27.389906	txpk_ack	{"txpk_ack":{"error":"NONE"}}
F 18:23:27.508022	transmitPkt	9886	6300	-1	868100000	112	112	2	64	14	33

Above, line B is the Join Request (with the gateway’s timestamp being 349218460). TTN Console shows that at 19:23:22; it seems to know my local time zone.

Line D is the Join Accept which seems to arrive at the gateway after 4.818 seconds. The timestamp in the Accept, indicating when to forward it to the node, is set to be 354218460, hence 5,000,000 microseconds or 5 seconds after the timestamp from the Join Request. (All relative to the gateway’s timestamp, like Kersing explained above.) So, TTN wants the gateway to send it in RX1, following JOIN_ACCEPT_DELAY1. Indeed, in line F it’s transmitted.

Before truly transmitting it in line F, in line E an acknowledgement is already sent back to TTN. Jaap’s single channel gateway will report TOO_LATE if the downlink came too late (following Semtech’s Gateway to Server Interface Definition):

local msg='{"txpk_ack":{"error":"NONE"}}'
if trig <= 0 then
  msg='{"txpk_ack":{"error":"TOO_LATE"}}'
end

So, the size of the acknowledgement might give you an indication if the gateway thinks all is fine? When sent without whitespace, the NONE is 29 bytes, the TOO_LATE is 33 bytes.

As LMiC starts OTAA whenever the first packet is to be sent, a successful Join is followed by the first data:

G 18:23:27.684300	rxpk	01ee4d005ccf7ff42f1970ec	message	{"rxpk":[{"rssi":-48,"stat":1,"modu":"LORA","rfch":0,"tmst":354347381,"datr":"SF7BW125","lsnr":9,"time":"2017-01-26T18:23:27.639420Z","codr":"4/5","data":"QCkuASaAAAAByFaF53Iu+vzmwQ==","freq":868.100,"chan":0,"size":19}]}	length	233

(As an aside: this way, the first data received after a Join, will always be a bit late, unless one explicitly first forces a Join when starting the device.)

After the OTAA, the gateway goes into pulling commands from TTN, and sending statistics:

H 18:23:28.657846	pull	017601025ccf7ff42f1970ec
I 18:23:33.657938	pull	015754025ccf7ff42f1970ec
J 18:23:38.631359	stat	01e961005ccf7ff42f1970ec	message	{"stat":{"rxfw":2,"alti":3,"lati":52.123456,"rxok":2,"long":4.987654,"time":"2017-01-26 18:23:38 GMT","txnb":1,"dwnb":2,"rxnb":2,"ackr":100.0}}	length	155
K 18:23:38.659612	pull	01b3d0025ccf7ff42f1970ec

Every now and then my node will ask for a link check in an uplink. (Even though TTN does not support ADR yet, my test node has link check enabled.)

L 19:02:53.661983	pull	015e66025ccf7ff42f1970ec
M 19:02:54.474860	rxpk	01450f005ccf7ff42f1970ec	message	{"rxpk":[{"rssi":-54,"stat":1,"modu":"LORA","rfch":0,"tmst":573653463,"datr":"SF10BW125","lsnr":12,"time":"2017-01-26T19:02:54.429481Z","codr":"4/5","data":"QCkuASbAMwABMngK0sWEN3AgBQ==","freq":868.100,"chan":0,"size":19}]}	length	235
N 19:02:56.191305	txpk	{"txpk":{"imme":false,"tmst":575653463,"freq":869.525,"rfch":0,"powe":27,"modu":"LORA","datr":"SF9BW125","codr":"4/5","ipol":true,"size":12,"data":"YCkuASYgAwDQNni9"}}
O 19:02:56.206041	txpk_ack	{"txpk_ack":{"error":"NONE"}}
P 19:02:56.426678	transmitPkt	10332	7063	0	869525000	144	112	2	64	27	12
Q 19:02:58.661714	pull	013877025ccf7ff42f1970ec

In line M the timestamp in the uplink is 573653463. In the downlink in line N, which is received after 1.716 seconds, it’s 575653463, hence 2 seconds difference. Again, the downlink is received just in time to forward it to the node. For this, TTN Console seems to have the seconds wrong in 20:02:50, and they are not in line with the uplink that preceded the downlink:

If your gateway does not print timestamps, then the following (or alternatives) might help to add a timestamp when monitoring a file called logfile:

tail -f logfile 2>&1 | while read l; do d=`date +%H:%M:%S.%N`; echo $d $l; done

matthijskooijman · January 26, 2017, 9:08pm

I’m not entirely sure that will work - at some point the RX windows will end up overlapping (which each other and possibly even the TX time), and I’m not sure what will happen then (I remember leaving that for later, but I never got around to handling that gracefully).

salvatore_forte · January 27, 2017, 10:37am

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!

kersing · January 27, 2017, 1:44pm

That could well be the case. I do not know the typical response times for IP traffic for your GSM provider.

For join the windows are at 5 and 6 seconds ± 20 microseconds after the node transmitted the packet, windows length depends on the implementation but is probably about about 0.3 seconds at SF12.

No, it is false for ONE of the radios. The other radio takes care of all transmissions.

You should be using the configuartion from TTN Github That one is set correctly.

That seems to be the case.

Looking at multiple traces you provided I am sure your gateway receives data late. Looking at the latest trace:
11:04:50.435723 is join request.
11:04:55.914887 is join accept response
Time difference is 5.479164 seconds. That should have been at most 4.9 seconds to allow the gateway software some processing time. (The relative timestamp tmst in the join request is 998979548 microseconds, in the accept it’s 1003979548. So TTN wants the gateway to send the join accept 5000000 microseconds after receiving the join request.)

10:52:06.493745 uplink packet from node
10:52:07.880705 downlink response.
Time difference is 1.38696 which again is well beyond the limits. (Timestamps being 235026052 and 236026052, hence 1000000 microseconds difference.)

The thing to look at now is why the data is getting to your gateway late. That is something network related between your gateway and TTN router because TTN sends data in a timely manner for other gateways.

arjanvanb · January 28, 2017, 6:43pm

Just noticed that the 3rd logs were sent from a different gateway IP address? Is that to be expected, or is it a different gateway?