View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0001956 | GNUnet | transport service | public | 2011-11-23 09:40 | 2024-05-03 13:58 |
| Reporter | LRN | Assigned To | LRN | ||
| Priority | normal | Severity | minor | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | Git master | ||||
| Target Version | 0.9.0 | ||||
| Summary | 0001956: udp unreliability constant fails randomly | ||||
| Description | r18262 | ||||
| Steps To Reproduce | run $ end_it=0 ; while test "$end_it" = "0"; do rm -f udp.log && PATH=$PATH:$PATHTOGNUNET GNUNET_PREFIX=$GNUNETPREFIX GNUNET_FORCE_LOG=";;demultiplexer;;DEBUG/;;notify_ready;;DEBUG/;;notify_receive;;DEBUG/;;;;WARNING" GNUNET_FORCE_LOGFILE=udp.log .libs/test_transport_api_unreliability_constant_udp ; end_it=$(cat udp.log | grep "Reliability failed" | wc -l); done until it stops | ||||
| Additional Information | ®п 23 12:28:30-00000000000251895623 transport-api-10624 DEBUG Receiving `RECV' message. ®п 23 12:28:30-00000000000251895623 transport-api-10624 DEBUG Received message of type 12345 from `KJI3'. ®п 23 12:28:30-00000000000251895623 test_transport_api_unreliability_constant_udp-10624 DEBUG Got 532 ®п 23 12:28:30-00000000000251895623 transport-api-10624 DEBUG Receiving `SEND_OK' message, transmission succeeded. ®п 23 12:28:30-00000000000251895623 test_transport_api_unreliability_constant_udp-10624 DEBUG Sending message 533 of size 10000 ®п 23 12:28:30-00000000000251895623 transport-api-10624 DEBUG Transmitting 10080 bytes to transport service ®п 23 12:28:30-00000000000251895625 transport-api-10624 DEBUG Receiving `RECV' message. ®п 23 12:28:30-00000000000251895625 transport-api-10624 DEBUG Received message of type 12345 from `KJI3'. ®п 23 12:28:30-00000000000251895625 test_transport_api_unreliability_constant_udp-10624 DEBUG Got 533 ®п 23 12:28:30-00000000000251895625 transport-api-10624 DEBUG Receiving `SEND_OK' message, transmission succeeded. ®п 23 12:28:30-00000000000251895625 test_transport_api_unreliability_constant_udp-10624 DEBUG Sending message 534 of size 10000 ®п 23 12:28:30-00000000000251895625 transport-api-10624 DEBUG Transmitting 10080 bytes to transport service ®п 23 12:28:30-00000000000251895626 transport-api-10624 DEBUG Receiving `SEND_OK' message, transmission succeeded. ®п 23 12:28:30-00000000000251895626 test_transport_api_unreliability_constant_udp-10624 DEBUG Sending message 535 of size 10000 ®п 23 12:28:30-00000000000251895626 transport-api-10624 DEBUG Transmitting 10080 bytes to transport service ®п 23 12:28:30-00000000000251895627 transport-api-10624 DEBUG Receiving `RECV' message. ®п 23 12:28:30-00000000000251895627 transport-api-10624 DEBUG Received message of type 12345 from `KJI3'. ®п 23 12:28:30-00000000000251895627 test_transport_api_unreliability_constant_udp-10624 DEBUG Got 535 ®п 23 12:28:30-00000000000251895627 test_transport_api_unreliability_constant_udp-10624 ERROR Expected message no 534, got 535 ®п 23 12:28:30-00000000000251895627 test_transport_api_unreliability_constant_udp-10624 ERROR Reliability failed: Last message sent 535, Next message scheduled 536, Last message received 535, Message expected 534 ®п 23 12:28:30-00000000000251895646 transport-4684 ERROR State for neighbour `KJI3' 1F49DE0 changed from `S_CONNECTED' to `S_DISCONNECT' in line 894 ®п 23 12:28:30-00000000000251895674 transport-12644 ERROR State for neighbour `FC74' 1E03480 changed from `S_CONNECTED' to `S_DISCONNECT' in line 894 | ||||
| Tags | No tags attached. | ||||
| Attached Files | udp_log_01.log (5,038 bytes)
transport-api-8952 DEBUG Calling notify_transmit_ready test_transport_api_unreliability_constant_udp-8952 DEBUG Sending message 129 of size 10000 transport-api-8952 DEBUG Transmitting 10080 bytes to transport service transport-udp-11364 DEBUG UDP transmits 10000-byte message to `FC74' using address `127.0.0.1:12040' session 0x3BFEF8 mode 1 transport-udp-11364 DEBUG Session 0x3BFEF8 successfully checked! transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 368-byte message to 127.0.0.1:12040 (368: ok) transport-udp-12808 DEBUG UDP received 368-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 368-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-api-8952 DEBUG Receiving `RECV' message. transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-api-8952 DEBUG Received message of type 12345 from `KJI3'. transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' test_transport_api_unreliability_constant_udp-8952 DEBUG Got 129 transport-udp-12808 DEBUG UDP transmited 88-byte message to 127.0.0.1:12050 (88: ok) transport-udp-11364 DEBUG UDP received 88-byte message from `127.0.0.1:12040' type 57 transport-udp-11364 DEBUG We received a sending delay of 0 transport-udp-11364 DEBUG UDP processes 88-byte acknowledgement from `FC74' at `127.0.0.1:12040' transport-api-8952 DEBUG Receiving `SEND_OK' message, transmission succeeded. udp_log_02.log (5,668 bytes)
transport-api-8952 DEBUG Calling notify_transmit_ready test_transport_api_unreliability_constant_udp-8952 DEBUG Sending message 130 of size 10000 transport-api-8952 DEBUG Transmitting 10080 bytes to transport service transport-udp-11364 DEBUG UDP transmits 10000-byte message to `FC74' using address `127.0.0.1:12040' session 0x3BFEF8 mode 1 transport-udp-11364 DEBUG Session 0x3BFEF8 successfully checked! transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 368-byte message to 127.0.0.1:12040 (368: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-12808 DEBUG UDP received 368-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 368-byte fragment from `127.0.0.1:12050' transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-12808 DEBUG UDP transmited 88-byte message to 127.0.0.1:12050 (88: ok) transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-11364 DEBUG UDP received 88-byte message from `127.0.0.1:12040' type 57 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG We received a sending delay of 0 transport-udp-11364 DEBUG UDP processes 88-byte acknowledgement from `FC74' at `127.0.0.1:12040' transport-udp-12808 DEBUG UDP transmited 88-byte message to 127.0.0.1:12050 (88: ok) transport-udp-11364 DEBUG UDP received 88-byte message from `127.0.0.1:12040' type 57 transport-udp-11364 DEBUG We received a sending delay of 0 transport-udp-11364 DEBUG UDP processes 88-byte acknowledgement from `FC74' at `127.0.0.1:12040' transport-udp-11364 DEBUG Session for ACK not found, dropping ACK! transport-api-8952 DEBUG Receiving `SEND_OK' message, transmission succeeded. udp_log.diff (5,385 bytes)
--- udp_log_01.log 2011-11-23 13:14:19 +0400 +++ udp_log_02.log 2011-11-23 13:14:45 +0400 @@ -1,5 +1,5 @@ transport-api-8952 DEBUG Calling notify_transmit_ready -test_transport_api_unreliability_constant_udp-8952 DEBUG Sending message 129 of size 10000 +test_transport_api_unreliability_constant_udp-8952 DEBUG Sending message 130 of size 10000 transport-api-8952 DEBUG Transmitting 10080 bytes to transport service transport-udp-11364 DEBUG UDP transmits 10000-byte message to `FC74' using address `127.0.0.1:12040' session 0x3BFEF8 mode 1 transport-udp-11364 DEBUG Session 0x3BFEF8 successfully checked! @@ -11,9 +11,7 @@ transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 -transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) -transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 @@ -25,16 +23,23 @@ transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-11364 DEBUG UDP transmited 368-byte message to 127.0.0.1:12040 (368: ok) +transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 +transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) +transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' transport-udp-12808 DEBUG UDP received 368-byte message from `127.0.0.1:12050' type 18 transport-udp-12808 DEBUG UDP processes 368-byte fragment from `127.0.0.1:12050' +transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 +transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' +transport-udp-12808 DEBUG UDP transmited 88-byte message to 127.0.0.1:12050 (88: ok) transport-udp-11364 DEBUG UDP transmited 1400-byte message to 127.0.0.1:12040 (1400: ok) -transport-api-8952 DEBUG Receiving `RECV' message. transport-udp-12808 DEBUG UDP received 1400-byte message from `127.0.0.1:12050' type 18 -transport-api-8952 DEBUG Received message of type 12345 from `KJI3'. +transport-udp-11364 DEBUG UDP received 88-byte message from `127.0.0.1:12040' type 57 transport-udp-12808 DEBUG UDP processes 1400-byte fragment from `127.0.0.1:12050' -test_transport_api_unreliability_constant_udp-8952 DEBUG Got 129 +transport-udp-11364 DEBUG We received a sending delay of 0 +transport-udp-11364 DEBUG UDP processes 88-byte acknowledgement from `FC74' at `127.0.0.1:12040' transport-udp-12808 DEBUG UDP transmited 88-byte message to 127.0.0.1:12050 (88: ok) transport-udp-11364 DEBUG UDP received 88-byte message from `127.0.0.1:12040' type 57 transport-udp-11364 DEBUG We received a sending delay of 0 transport-udp-11364 DEBUG UDP processes 88-byte acknowledgement from `FC74' at `127.0.0.1:12040' +transport-udp-11364 DEBUG Session for ACK not found, dropping ACK! transport-api-8952 DEBUG Receiving `SEND_OK' message, transmission succeeded. \ No newline at end of file 0004-Use-better-random-generator-on-W32.patch (1,399 bytes)
From a0f9f2ff0e3f1f029e5b285971cb7dc4cbec1e3b Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?=D0=A0=D1=83=D1=81=D0=BB=D0=B0=D0=BD=20=D0=98=D0=B6=D0=B1=D1?=
=?UTF-8?q?=83=D0=BB=D0=B0=D1=82=D0=BE=D0=B2?= <lrn1986@gmail.com>
Date: Wed, 23 Nov 2011 21:26:41 +0400
Subject: [PATCH 4/4] Use better random generator on W32
---
src/util/crypto_random.c | 29 +++++++++++++++++++++++++++++
1 files changed, 29 insertions(+), 0 deletions(-)
diff --git a/src/util/crypto_random.c b/src/util/crypto_random.c
index 719acf0..9fc1486 100644
--- a/src/util/crypto_random.c
+++ b/src/util/crypto_random.c
@@ -34,6 +34,35 @@
#define LOG_STRERROR(kind,syscall) GNUNET_log_from_strerror (kind, "util", syscall)
+/* TODO: ndurner, move this to plibc? */
+/* The code is derived from glibc, obviously */
+#if MINGW
+#ifdef RANDOM
+# undef RANDOM
+#endif
+#ifdef SRANDOM
+# undef SRANDOM
+#endif
+#define RANDOM() glibc_weak_rand32()
+#define SRANDOM(s) glibc_weak_srand32(s)
+static int32_t glibc_weak_rand32_state = 1;
+
+void
+glibc_weak_srand32 (int32_t s)
+{
+ glibc_weak_rand32_state = s;
+}
+
+int32_t
+glibc_weak_rand32 ()
+{
+ int32_t val = glibc_weak_rand32_state;
+ val = ((glibc_weak_rand32_state * 1103515245) + 12345) & 0x7fffffff;
+ glibc_weak_rand32_state = val;
+ return val;
+}
+#endif
+
/**
* Create a cryptographically weak pseudo-random number in the interval of 0 to 1.
*
--
1.7.4
| ||||
|
|
Uploaded udp_log_01 and udp_log_02, and their diff. Maybe that'll be useful. |
|
|
(after that message 131 gets sent, received, then it fails with "Expected message no 130, got 131") |
|
|
udp.log_002 - with some fragmentation-level log info |
|
|
Found the source of the problem. As always, it's the famously weak msvcrt rand() implementation, which only returns 15-bit values (chopping off lower 16 bits of the number it generates). (the algorithm for generating weak integers is the same in msvcrt and glibc, the difference is only in RAND_MAX, and the way the random number is fitted into it - msvcrt shifts to the right by 16 bits, glibc takes a mod of dividing it by RAND_MAX). Because of that the same ID gets assigned to a couple different fragments within a short time-frame ( less than 20ms ). As a result, the receiver thinks that the message is the same (based on its ID), and doesn't send it for processing, just acknowledges it to the sender. And when the next message comes, it's one step ahead of what was expected. I've attached a patch that replaces RANDOM and SRANDOM in crypto_random.c with 31-bit-long glibc version. With that patch applied i ran the test in a way described above, and it haven't failed for more than an hour (without the patch it fails within a few minutes). |
|
|
Fixed as suggested in SVN 18286. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2011-11-23 09:40 | LRN | New Issue | |
| 2011-11-23 09:40 | LRN | Status | new => assigned |
| 2011-11-23 09:40 | LRN | Assigned To | => Matthias Wachs |
| 2011-11-23 10:16 | LRN | File Added: udp_log_01.log | |
| 2011-11-23 10:16 | LRN | File Added: udp_log_02.log | |
| 2011-11-23 10:17 | LRN | File Added: udp_log.diff | |
| 2011-11-23 10:17 | LRN | Note Added: 0004964 | |
| 2011-11-23 10:18 | LRN | Note Added: 0004965 | |
| 2011-11-23 11:06 | LRN | File Added: udp.log_002 | |
| 2011-11-23 11:07 | LRN | Note Added: 0004966 | |
| 2011-11-23 15:12 | Christian Grothoff | Target Version | => 0.9.0 |
| 2011-11-23 18:30 | LRN | File Added: 0004-Use-better-random-generator-on-W32.patch | |
| 2011-11-23 18:30 | LRN | Note Added: 0004968 | |
| 2011-11-23 18:49 | NDurner | Assigned To | Matthias Wachs => NDurner |
| 2011-11-23 20:23 | Christian Grothoff | Note Added: 0004969 | |
| 2011-11-23 20:23 | Christian Grothoff | Status | assigned => resolved |
| 2011-11-23 20:23 | Christian Grothoff | Resolution | open => fixed |
| 2011-11-23 20:23 | Christian Grothoff | Assigned To | NDurner => LRN |
| 2011-11-30 18:38 | Christian Grothoff | Status | resolved => closed |
| 2024-05-03 13:58 | Christian Grothoff | Category | UDP transport => transport service |
