Retransmission issue about californium HOT 4 CLOSED

@calvingao,

is this still an issue for you? I have just created a test case for the situation you describe, i.e. server's ACK containing the piggy-backed response is lost and client re-transmits its request. The test runs without problems so I would be interested to know where you stand with this.

BTW Which version of Californium are you using?

from californium.

Hi,

I think we observe a similar behaviour in conjunction with Leshan with the following message flow:

• LWM2M client sends register request
• LWM2M server receives register request
• LWM2M server sends piggy-backed response
• LWM2M client does not receive response because of networking issues
• LWM2M client retries request
• LWM2M server receives request
• LWM2M server identifies message as a duplicate and logs that response gets sent again
• LWM2M server does NOT send response (Does not appear in MessageTracer)

Here are some Logs that we create with the help of a MessageTracer:

09:17:21.187    x.y.z.LogMessageTracer                                            /23.23.23.23:4242 =RX=> req CON-POST   MID=47866, Token=, OptionSet={"Uri-Path":"rd", "Uri-Query":["ep=XYZ","b=UQ"]}, "</1/0>,</3/0>,</5/0>,</1".. 42 bytes
09:12:57.497    org.eclipse.californium.core.network.stack.ReliabilityLayer       Respond with the current response to the duplicate request
09:12:57.497    org.eclipse.californium.core.network.Matcher                      Duplicate request: CON-POST   MID=47866, Token=, OptionSet={"Uri-Path":"rd", "Uri-Query":["ep=XYZ","b=UQ"]}, "</1/0>,</3/0>,</5/0>,</1".. 42 bytes
09:12:57.497    x.y.z.LogMessageTracer                                            /23.23.23.23:4242 =RX=> req CON-POST   MID=47866, Token=, OptionSet={"Uri-Path":"rd", "Uri-Query":["ep=XYZ","b=UQ"]}, "</1/0>,</3/0>,</5/0>,</1".. 42 bytes
09:10:46.905    x.y.z.LogMessageTracer                                            /23.23.23.23:4242 <=TX= res ACK-2.01   MID=47866, Token=, OptionSet={"Location-Path":["rd","XYZ"]}, no payload
09:10:46.898    x.y.z.LogMessageTracer                                            /23.23.23.23:4242 =RX=> req CON-POST   MID=47866, Token=, OptionSet={"Uri-Path":"rd", "Uri-Query":["ep=XYZ","b=UQ"]}, "</1/0>,</3/0>,</5/0>,</1".. 42 bytes

We are using version 2.0.0-M2. We only get this issue sporadically with a live system, but can not reproduce it.

Are there any news on this issue or does anyone has an idea? We will keep trying to reproduce this.

Thanks
Daniel

from californium.

Using the 2.0.x branch, ExtendedTestServer with -Xmx2g and lower EXCHANGE_LIFETIME to 24.7s (instead of 247s) in CaliforniumReceivetest.properties, and running the BenchmarkClient using

coap://localhost:5783/benchmark 500 20000

(500 clients each using 20000 request), I get:

Create 500 benchmark clients, expect to send 10000000 request overall to coap://localhost:5783/benchmark
Benchmark clients created.
Benchmark started.
310433 requests (31043 reqs/s, 0 retransmissions (0,00%), 500 clients)
641089 requests (33065 reqs/s, 46 retransmissions (0,01%), 500 clients)
909439 requests (26835 reqs/s, 500 retransmissions (0,19%), 500 clients)
1170006 requests (26056 reqs/s, 500 retransmissions (0,19%), 500 clients)
1461561 requests (29155 reqs/s, 495 retransmissions (0,17%), 500 clients)
1859099 requests (39753 reqs/s, 0 retransmissions (0,00%), 500 clients)
2162651 requests (30355 reqs/s, 270 retransmissions (0,09%), 500 clients)
2454989 requests (29233 reqs/s, 500 retransmissions (0,17%), 500 clients)
2849501 requests (39451 reqs/s, 0 retransmissions (0,00%), 500 clients)
3170885 requests (32138 reqs/s, 419 retransmissions (0,13%), 500 clients)
3476836 requests (30595 reqs/s, 399 retransmissions (0,13%), 500 clients)
3778554 requests (30171 reqs/s, 492 retransmissions (0,16%), 500 clients)
4087479 requests (30892 reqs/s, 361 retransmissions (0,12%), 500 clients)
4372886 requests (28540 reqs/s, 500 retransmissions (0,18%), 500 clients)
4687451 requests (31456 reqs/s, 367 retransmissions (0,12%), 500 clients)
4986412 requests (29896 reqs/s, 500 retransmissions (0,17%), 500 clients)
5315761 requests (32934 reqs/s, 149 retransmissions (0,05%), 500 clients)
5665418 requests (34965 reqs/s, 299 retransmissions (0,09%), 500 clients)
5930897 requests (26547 reqs/s, 500 retransmissions (0,19%), 500 clients)
6196460 requests (26556 reqs/s, 567 retransmissions (0,21%), 500 clients)
6545574 requests (34911 reqs/s, 121 retransmissions (0,03%), 500 clients)
6899673 requests (35409 reqs/s, 411 retransmissions (0,12%), 500 clients)
7209030 requests (30935 reqs/s, 450 retransmissions (0,15%), 500 clients)
7502861 requests (29383 reqs/s, 500 retransmissions (0,17%), 500 clients)
7781423 requests (27856 reqs/s, 405 retransmissions (0,15%), 500 clients)
8127662 requests (34623 reqs/s, 312 retransmissions (0,09%), 500 clients)
8426491 requests (29882 reqs/s, 416 retransmissions (0,14%), 500 clients)
8729812 requests (30332 reqs/s, 466 retransmissions (0,15%), 500 clients)
9002429 requests (27261 reqs/s, 500 retransmissions (0,18%), 500 clients)
9305059 requests (30263 reqs/s, 435 retransmissions (0,14%), 500 clients)
9624564 requests (31950 reqs/s, 293 retransmissions (0,09%), 500 clients)
9926921 requests (30235 reqs/s, 410 retransmissions (0,14%), 500 clients)
Benchmark clients finished.
10000000 requests sent, 10000000 expected
10000000 requests in 322339ms, 31023 reqs/s
11583 retransmissions (0,12%)
239 clients with 19640 to 19796 requests.
12 clients with 19801 to 19870 requests.
45 clients with 20091 to 20199 requests.
200 clients with 20200 to 20394 requests.
4 clients with 20400 to 20454 requests.

The server logs (with an unpublished extension):

16:15:01.288 WARN [ReliabilityLayer]: 11583 resend responses

So the retransmission rate is 0,12%. Currently I'm not able to drop messages intentionally
(cf-nat is right now not extended), but for me this indicates, that all retransmissions working properly.

@calvingao
If possible, could you retest with the current 2.0.x branch?
Otherwise I would close this issue.

from californium.

Using PR #523 and #524 the issue could be retested.

Start NAT emulator with:

:6783 localhost:5783 20

(forward 6783 to 5783, drop 20% of the messages)
and the BenchmarkClient with:

coap://localhost:6783/benchmark 500 200 nonestop

results in:

100000 requests sent, 100000 expected
100000 requests in 507177ms, 197 reqs/s
54564 retransmissions (54,56%)
501 transmission errors (0,50%)

So about 99,5% of the request are successful.

Using asymmetric message dropping (more test-weight on response resending)

:6783 localhost:5783 -f5 -b20

(forward (request) 5% drops, backwards (responses) 20% drops)

results in:

100000 requests sent, 100000 expected
100000 requests in 217846ms, 459 reqs/s
30796 retransmissions (30,80%)
42 transmission errors (0,04%)

That shows, that the issue is fixed.

from californium.