`process_udp dropped REGISTER_SUPER due to time stamp error` when I try to connect a supernode to another

randomize00 commented 3 years ago

Hello,everyone. I try to build a federation community with two nodes. There are two machines - A(47.104.20.99) and B(106.55.4.71) . I use latest dev branch code with the macro N2N_HAVE_DAEMON commented.

On machine A, the following bash command is typed: supernode -vvvv and In B, supernode -l 47.104.20.99:7654 -vvvv

Here are the output. In machine A.

28/Jan/2021 16:16:16 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
28/Jan/2021 16:16:16 [sn_utils.c:530] Assign IP 58.218.10.48/0 to tap adapter of edge.
28/Jan/2021 16:16:16 [sn_utils.c:1334] Rx REGISTER_SUPER for CE:66:24:82:2B:D8 [106.55.4.71:7654]
28/Jan/2021 16:16:16 [sn_utils.c:383] update_edge for CE:66:24:82:2B:D8 [106.55.4.71:7654]
28/Jan/2021 16:16:16 [sn_utils.c:441] update_edge unchanged CE:66:24:82:2B:D8 ==> 106.55.4.71:7654
28/Jan/2021 16:16:16 [sn_utils.c:176] try_broadcast
28/Jan/2021 16:16:16 [sn_utils.c:1406] Tx REGISTER_SUPER_ACK for CE:66:24:82:2B:D8 [106.55.4.71:7654]
28/Jan/2021 16:16:26 [sn_utils.c:1818] timeout
28/Jan/2021 16:16:26 [sn_utils.c:732] Purging old communities and edges
28/Jan/2021 16:16:26 [sn_utils.c:748] Remove 0 edges
28/Jan/2021 16:16:26 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
28/Jan/2021 16:16:26 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
28/Jan/2021 16:16:26 [sn_utils.c:1226] process_udp dropped REGISTER_SUPER due to time stamp error.
28/Jan/2021 16:16:36 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
28/Jan/2021 16:16:36 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
28/Jan/2021 16:16:36 [sn_utils.c:1226] process_udp dropped REGISTER_SUPER due to time stamp error.

and machine B,

28/Jan/2021 16:16:16 [sn_utils.c:1818] timeout
28/Jan/2021 16:16:16 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
28/Jan/2021 16:16:16 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
28/Jan/2021 16:16:16 [sn_utils.c:732] Purging old communities and edges
28/Jan/2021 16:16:16 [sn_utils.c:748] Remove 0 edges
28/Jan/2021 16:16:16 [sn_utils.c:918] Processing incoming UDP packet [len: 50][sender: 47.104.20.99:7654]
28/Jan/2021 16:16:16 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
28/Jan/2021 16:16:16 [sn_utils.c:1499] process_udp dropped REGISTER_SUPER_ACK due to time stamp error.
28/Jan/2021 16:16:26 [sn_utils.c:1818] timeout
28/Jan/2021 16:16:26 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
28/Jan/2021 16:16:26 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
28/Jan/2021 16:16:36 [sn_utils.c:1818] timeout
28/Jan/2021 16:16:36 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
28/Jan/2021 16:16:36 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]

It looks like, all REGISTER_SUPER packet but firstly received by machine A are dropped due to time stamp out of allowed frame.

On the other hand, the REGISTER_SUPER_ACK received by B is also dropped due to the same reason.

Do I miss some parameters or set some parameters incorrectly ?

Thanks.

Logan007 commented 3 years ago

Please try to sync the two supernode's clocks. The shall not be more than 16 seconds apart – I can't see from the logs if the REGISTER_SUPER belongs to that very same REGISTER_SUPER_ACK.

Supernodes communicate through a channel protected by header encryption. It includes time stamps for replay protection. For details, please refer to the corresponding section of our crypto doc.

Logan007 commented 3 years ago

macro N2N_HAVE_DAEMON commented

By the way, you could use the -f command-line option.

Are A and B desktop PCs or any special hardware? Asking this because of the hardware clock.

randomize00 commented 3 years ago

machine A is a server ( physical machine ) but machine B is a virtual machine supplied by Tencent Cloud.

Logan007 commented 3 years ago

Are their clocks in sync? (date on linux)

They do not have to be in the same time zone because the time stamps use UTC.

randomize00 commented 3 years ago

Mostly probably not since I haven't set them. Maybe I should use ntpd service to syncronize their clock, thank you.

Logan007 commented 3 years ago

Let me know if it helps.

randomize00 commented 3 years ago

I've checked the ntpd serivce on both machines. Both have already started the ntpd service before I did that test.

on machine A:

[root@tgmserver ~]# ntpstat 
synchronised to NTP server (100.100.61.88) at stratum 2
   time correct to within 11 ms
   polling server every 1024 s

and machine B:

ntpstat
synchronised to NTP server (169.254.0.81) at stratum 3 
   time correct to within 66 ms
   polling server every 1024 s

and they are only a second apart.

Logan007 commented 3 years ago

Could you please help me debugging? Could you add one line to the code in src/n2n.c around line 718 as follows (the printf-line):

    if(diff >= TIME_STAMP_FRAME) {
        traceEvent(TRACE_DEBUG, "time_stamp_verify_and_update found a timestamp out of allowed frame.");
// !!!
        printf("!!! stamp: 0x%016llx curr: 0x%016llx diff: 0x%016llx allowed: 0x%016llx\n", stamp, time_stamp(), diff, TIME_STAMP_FRAME);
        return 0; // failure
    }

and then run make clean and make and then your scenario again? I would be very interested in the output.

randomize00 commented 3 years ago

Sorry for late.

This is the ouput when I re-run the scenario.

Machine A (47.104.20.99)

29/Jan/2021 09:16:12 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:17 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 09:16:17 [sn_utils.c:530] Assign IP 58.218.10.48/0 to tap adapter of edge.
29/Jan/2021 09:16:17 [sn_utils.c:1334] Rx REGISTER_SUPER for 16:85:72:36:1F:DA [106.55.4.71:7654]
29/Jan/2021 09:16:17 [sn_utils.c:383] update_edge for 16:85:72:36:1F:DA [106.55.4.71:7654]
29/Jan/2021 09:16:17 [sn_utils.c:441] update_edge unchanged 16:85:72:36:1F:DA ==> 106.55.4.71:7654
29/Jan/2021 09:16:17 [sn_utils.c:176] try_broadcast
29/Jan/2021 09:16:17 [sn_utils.c:1406] Tx REGISTER_SUPER_ACK for 16:85:72:36:1F:DA [106.55.4.71:7654]

29/Jan/2021 09:16:27 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:27 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 09:16:27 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x601361eb00001de6 curr: 0x7afb67fbbb90f33b diff: 0x1ae80610bb90d555 allowed: 0x0000001000000000
29/Jan/2021 09:16:27 [sn_utils.c:1226] process_udp dropped REGISTER_SUPER due to time stamp error.

29/Jan/2021 09:16:37 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:37 [sn_utils.c:732] Purging old communities and edges
29/Jan/2021 09:16:37 [sn_utils.c:748] Remove 0 edges
29/Jan/2021 09:16:37 [sn_utils.c:918] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 09:16:37 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x601361f500001de6 curr: 0x7afb67f5a1b8f33b diff: 0x1ae80600a1b8d555 allowed: 0x0000001000000000
29/Jan/2021 09:16:37 [sn_utils.c:1226] process_udp dropped REGISTER_SUPER due to time stamp error.

Machine B (106.55.4.71)

29/Jan/2021 09:16:17 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:17 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 09:16:17 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
29/Jan/2021 09:16:17 [sn_utils.c:732] Purging old communities and edges
29/Jan/2021 09:16:17 [sn_utils.c:748] Remove 0 edges
29/Jan/2021 09:16:17 [sn_utils.c:918] Processing incoming UDP packet [len: 50][sender: 47.104.20.99:7654]
29/Jan/2021 09:16:17 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x60137ffd3f5fbbc0 curr: 0x601361e1004168f6 diff: 0x00001e1c3f1e52ca allowed: 0x0000001000000000
29/Jan/2021 09:16:17 [sn_utils.c:1499] process_udp dropped REGISTER_SUPER_ACK due to time stamp error.

29/Jan/2021 09:16:27 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:27 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 09:16:27 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]

29/Jan/2021 09:16:37 [sn_utils.c:1818] timeout
29/Jan/2021 09:16:37 [sn_utils.c:701] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 09:16:37 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]

Logan007 commented 3 years ago

Taking a look at the debug output time stamps, I see the following:

Machine B's current time stamp 0x601361e1 (first half of the output value = Unix time in seconds) is perfectly in sync with the indicated time from the regular log messages.
The second half of that value looks odd, especially the lower nibbles. They should be ...000 or xx1.
The stamp that is being checked (0x60137ffd....) is two hours and 12 minutes more in the future than the local one.
Machine A's current timestamp 0x7afb67f5 is way too far in the future: May 20, 2035, 5:55 PM.
Also, the lower bits look suspicously wrong.

So, there might be several reasons:

error in time stamp generation code (always an option)
error in reading local clock on machine A (very strange, note that B sees a difference of two hours only while at machine A, it seems to be off by years)
maybe endianess issue?

So, what CPU endianess do your systems work with? (lscpu | grep Endian)

Also, as the lower bits of the stamps look somewhat unexpected, can you please confirm that you used the latest source code? I am sorry I have to ask this, but we have had some very recent changes in time stamp generation a few days ago which should result in the time stamp pattern mentioned, and the debug output shows more the older pattern (random in lower bits). All edges and supernodes have to be the exact same version then.

On machine A, the following bash command is typed: supernode -vvvv

Did you install after compilation or did you run in local directory? If in local directory, did you use ./supernode?

And then, concerning the strange time/clock issue:

I am not sure it this applies to your systems, but could you just try to set the correct timezones and make use of hwclock if available?

For example, as root – using your data, of course:

ln -s /usr/share/zoneinfo/Asia/Kathmandu /etc/localtime
hwclock --utc

But I still am wondering how debug output gets it correct while time stamp does not...

randomize00 commented 3 years ago

I've checked the CPU endianess. both are with little endian..

And I re-downloaded the latest source code on dev branch, added the debug code on src/n2n.c: 718, rebuilded, and re-runned.

The problem remains.

log on Machine A:

[root@tgmserver n2n-dev]# lscpu | grep Endian
Byte Order:          Little Endian
[root@tgmserver n2n-dev]# 
[root@tgmserver n2n-dev]# supernode -vvvv -f
29/Jan/2021 18:08:32 [sn.c:697] traceLevel is 6
29/Jan/2021 18:08:32 [sn.c:704] supernode is listening on UDP 7654 (main)
29/Jan/2021 18:08:32 [sn.c:712] supernode is listening on UDP 5645 (management)
29/Jan/2021 18:08:32 [sn.c:721] Dropping privileges to uid=65534, gid=65534
29/Jan/2021 18:08:32 [sn.c:737] supernode started

29/Jan/2021 18:08:42 [sn_utils.c:1819] timeout
29/Jan/2021 18:08:42 [sn_utils.c:733] Purging old communities and edges
29/Jan/2021 18:08:42 [sn_utils.c:749] Remove 0 edges
29/Jan/2021 18:08:43 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 18:08:43 [sn_utils.c:531] Assign IP 58.218.10.48/0 to tap adapter of edge.
29/Jan/2021 18:08:43 [sn_utils.c:1335] Rx REGISTER_SUPER for 1A:BB:42:58:31:51 [106.55.4.71:7654]
29/Jan/2021 18:08:43 [sn_utils.c:384] update_edge for 1A:BB:42:58:31:51 [106.55.4.71:7654]
29/Jan/2021 18:08:43 [sn_utils.c:442] update_edge unchanged 1A:BB:42:58:31:51 ==> 106.55.4.71:7654
29/Jan/2021 18:08:43 [sn_utils.c:176] try_broadcast
29/Jan/2021 18:08:43 [sn_utils.c:1407] Tx REGISTER_SUPER_ACK for 1A:BB:42:58:31:51 [106.55.4.71:7654]

29/Jan/2021 18:08:53 [sn_utils.c:1819] timeout
29/Jan/2021 18:08:53 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 18:08:53 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013deb500001de7 curr: 0x7afbdff5a1baf33b diff: 0x1ae80140a1b8d554 allowed: 0x0000001000000000
29/Jan/2021 18:08:53 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

29/Jan/2021 18:09:03 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 18:09:03 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013debf00001de7 curr: 0x7afbdfffa3b0f33b diff: 0x1ae80140a3b2d554 allowed: 0x0000001000000000
29/Jan/2021 18:09:03 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

29/Jan/2021 18:09:13 [sn_utils.c:1819] timeout
29/Jan/2021 18:09:13 [sn_utils.c:702] send REGISTER_SUPER to 106.55.4.71:7654
29/Jan/2021 18:09:13 [sn_utils.c:146] sendto_sock 91 to [106.55.4.71:7654]
29/Jan/2021 18:09:13 [sn_utils.c:733] Purging old communities and edges
29/Jan/2021 18:09:13 [sn_utils.c:749] Remove 0 edges
29/Jan/2021 18:09:13 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 18:09:13 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013dec900001de7 curr: 0x7afbdff9a9b2f33b diff: 0x1ae80130a9f2dd94 allowed: 0x0000001000000000
29/Jan/2021 18:09:13 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

29/Jan/2021 18:09:23 [sn_utils.c:1819] timeout
29/Jan/2021 18:09:23 [sn_utils.c:702] send REGISTER_SUPER to 106.55.4.71:7654
29/Jan/2021 18:09:23 [sn_utils.c:146] sendto_sock 91 to [106.55.4.71:7654]
29/Jan/2021 18:09:23 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
29/Jan/2021 18:09:23 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013ded300001de7 curr: 0x7afbdff3b3daf33b diff: 0x1ae80120b3dadd94 allowed: 0x0000001000000000
29/Jan/2021 18:09:23 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

^C29/Jan/2021 18:09:28 [sn.c:638] Shutting down...
29/Jan/2021 18:09:28 [sn_utils.c:1819] timeout
[root@tgmserver n2n-dev]#

Log on Machine B

root@VM-0-2-ubuntu:~/n2n-dev# lscpu | grep Endian
Byte Order:            Little Endian
root@VM-0-2-ubuntu:~/n2n-dev# supernode -l 47.104.20.99:7654 -vvvv -f 
29/Jan/2021 18:08:33 [sn.c:697] traceLevel is 6
29/Jan/2021 18:08:33 [sn.c:704] supernode is listening on UDP 7654 (main)
29/Jan/2021 18:08:33 [sn.c:712] supernode is listening on UDP 5645 (management)
29/Jan/2021 18:08:33 [sn.c:721] Dropping privileges to uid=65534, gid=65534
29/Jan/2021 18:08:33 [sn.c:737] supernode started

29/Jan/2021 18:08:43 [sn_utils.c:1819] timeout
29/Jan/2021 18:08:43 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 18:08:43 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
29/Jan/2021 18:08:43 [sn_utils.c:733] Purging old communities and edges
29/Jan/2021 18:08:43 [sn_utils.c:749] Remove 0 edges
29/Jan/2021 18:08:43 [sn_utils.c:919] Processing incoming UDP packet [len: 50][sender: 47.104.20.99:7654]
29/Jan/2021 18:08:43 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013ffff676c6bd0 curr: 0x6013deab00416bff diff: 0x00002154672b0011 allowed: 0x0000001000000000
29/Jan/2021 18:08:43 [sn_utils.c:1500] process_udp dropped REGISTER_SUPER_ACK due to time stamp error.

29/Jan/2021 18:08:53 [sn_utils.c:1819] timeout
29/Jan/2021 18:08:53 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 18:08:53 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]

29/Jan/2021 18:09:03 [sn_utils.c:1819] timeout
29/Jan/2021 18:09:03 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 18:09:03 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]

29/Jan/2021 18:09:13 [sn_utils.c:1819] timeout
29/Jan/2021 18:09:13 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 18:09:13 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
29/Jan/2021 18:09:13 [sn_utils.c:733] Purging old communities and edges
29/Jan/2021 18:09:13 [sn_utils.c:749] Remove 0 edges
29/Jan/2021 18:09:13 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 47.104.20.99:7654]
29/Jan/2021 18:09:13 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013dec90040993b curr: 0xf613dfdd778a4f23 diff: 0x69fffeeb88b67948 allowed: 0x0000001000000000
29/Jan/2021 18:09:13 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

29/Jan/2021 18:09:23 [sn_utils.c:1819] timeout
29/Jan/2021 18:09:23 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
29/Jan/2021 18:09:23 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
29/Jan/2021 18:09:23 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 47.104.20.99:7654]
29/Jan/2021 18:09:23 [n2n.c:716] time_stamp_verify_and_update found a timestamp out of allowed frame.
!!! stamp: 0x6013ded30040993b curr: 0xf613dfd7778b0f23 diff: 0x69fffefb88b53948 allowed: 0x0000001000000000
29/Jan/2021 18:09:23 [sn_utils.c:1227] process_udp dropped REGISTER_SUPER due to time stamp error.

^C29/Jan/2021 18:09:30 [sn.c:638] Shutting down...
29/Jan/2021 18:09:30 [sn_utils.c:1819] timeout

Logan007 commented 3 years ago

Very unexpected. I am a bit puzzled, so I will come up with some more debug printfs I have to ask you to put into the code... please stay tuned.

Logan007 commented 3 years ago

Please replace the time_stamp() function in n2n.c completely by the following code, only printfs added (would you prefer a patch-file?):

uint64_t time_stamp (void) {

    struct timeval tod;
    uint64_t micro_seconds;
    uint64_t co, mask_lo, mask_hi, hi_unchanged, counter, new_co;

    gettimeofday(&tod, NULL);
printf("!!! tv_sec 0x%08x   tc_usec 0x%08x\n", tod.tv_sec, tod.tv_usec);

    // (roughly) calculate the microseconds since 1970, leftbound
    micro_seconds = ((uint64_t)(tod.tv_sec) << 32) + ((uint64_t)tod.tv_usec << 12);
    // more exact but more costly due to the multiplication:
    // micro_seconds = ((uint64_t)(tod.tv_sec) * 1000000ULL + tod.tv_usec) << 12;
printf("!!! micro_seconds 0x%016llx\n", micro_seconds);
printf("!!! previously_issued 0x%016llx\n", previously_issued_time_stamp);

    // extract "counter only" flag (lowest bit)
    co = (previously_issued_time_stamp << 63) >> 63;
    // set mask accordingly
    mask_lo   = -co;
    mask_lo >>= 32;
    // either 0x00000000FFFFFFFF (if co flag set) or 0x0000000000000000 (if co flag not set)

    mask_lo  |= (~mask_lo) >> 52;
    // either 0x00000000FFFFFFFF (unchanged)      or 0x0000000000000FFF (lowest 12 bit set)
printf("!!! co 0x%016llx   mask_lo 0x%016llx\n", co, mask_lo);

    mask_hi   = ~mask_lo;

    hi_unchanged = ((previously_issued_time_stamp & mask_hi) == (micro_seconds & mask_hi));
    // 0 if upper bits unchanged (compared to previous stamp), 1 otherwise

    // read counter and shift right for flags
    counter   = (previously_issued_time_stamp & mask_lo) >> 4;
printf("!!! counter 0x%016llx   ", counter);

    counter  += hi_unchanged;
    counter  &= -hi_unchanged;
    // either counter++ if upper part of timestamp unchanged, 0 otherwise

    // back to time stamp format
    counter <<= 4;
printf("counter 0x%016llx   ", counter);

    // set new co flag if counter overflows while upper bits unchanged or if it was set before
    new_co  |= (((counter & mask_lo) == 0) & hi_unchanged) | co;

    // in case co flag changed, masks need to be recalculated
    mask_lo   = -new_co;
    mask_lo >>= 32;
    mask_lo  |= (~mask_lo) >> 52;
    mask_hi   = ~mask_lo;
printf("!!! mask_lo 0x%016llx   new_counter 0x%016llx\n", mask_lo, new_co);

    // assemble new timestamp
    micro_seconds &= mask_hi;
    micro_seconds |= counter;
    micro_seconds |= new_co;
printf("!!! micro_seconds 0x%016llx\n", micro_seconds);

    previously_issued_time_stamp = micro_seconds;

    return micro_seconds;
}

// returns an initial time stamp for use with replay protection
uint64_t initial_time_stamp (void) {

    return time_stamp() - TIME_STAMP_FRAME;
}

Let me know what you get... Thank you for cooperation in debugging and your patience!

Logan007 commented 3 years ago

Sorry, all the 64-bit output xs need a ll preffix, I will edit it in the post above.

Logan007 commented 3 years ago

I think I found the/one issue:

The line

    new_co  |= (((counter & mask_lo) == 0) & hi_unchanged) | co;

needs to change to

    new_co   = (((counter & mask_lo) == 0) & hi_unchanged) | co;

(remove the pipe next to the assigning =). new_co 's content might have been random, explaining some very strange time stamps we have seen on your machines. Do you want to test that?

Logan007 commented 3 years ago

I think it helps. I have already prepared a corresponding pull request.

randomize00 commented 3 years ago

Sorry for too late. I've just applied the change and found out that it really works. Thanks for the help.

Here's the new outputs.

Machine A

[root@tgmserver n2n-dev]# supernode -vvvv -f
30/Jan/2021 15:37:03 [sn.c:697] traceLevel is 6
30/Jan/2021 15:37:03 [sn.c:704] supernode is listening on UDP 7654 (main)
30/Jan/2021 15:37:03 [sn.c:712] supernode is listening on UDP 5645 (management)
30/Jan/2021 15:37:03 [sn.c:721] Dropping privileges to uid=65534, gid=65534
30/Jan/2021 15:37:03 [sn.c:737] supernode started

30/Jan/2021 15:37:13 [sn_utils.c:1819] timeout
30/Jan/2021 15:37:13 [sn_utils.c:733] Purging old communities and edges
30/Jan/2021 15:37:13 [sn_utils.c:749] Remove 0 edges
30/Jan/2021 15:37:14 [sn_utils.c:919] Processing incoming UDP packet [len: 91][sender: 106.55.4.71:7654]
30/Jan/2021 15:37:14 [sn_utils.c:531] Assign IP 58.218.10.48/0 to tap adapter of edge.
30/Jan/2021 15:37:14 [sn_utils.c:1335] Rx REGISTER_SUPER for 96:9F:21:BC:94:2E [106.55.4.71:7654]
30/Jan/2021 15:37:14 [sn_utils.c:384] update_edge for 96:9F:21:BC:94:2E [106.55.4.71:7654]
30/Jan/2021 15:37:14 [sn_utils.c:442] update_edge unchanged 96:9F:21:BC:94:2E ==> 106.55.4.71:7654
30/Jan/2021 15:37:14 [sn_utils.c:176] try_broadcast
30/Jan/2021 15:37:14 [sn_utils.c:1407] Tx REGISTER_SUPER_ACK for 96:9F:21:BC:94:2E [106.55.4.71:7654]

30/Jan/2021 15:37:24 [sn_utils.c:1819] timeout
30/Jan/2021 15:37:34 [sn_utils.c:1819] timeout

Machine B

root@VM-0-2-ubuntu:~/n2n-dev# supernode -l 47.104.20.99:7654 -vvvv -f 
30/Jan/2021 15:37:04 [sn.c:697] traceLevel is 6
30/Jan/2021 15:37:04 [sn.c:704] supernode is listening on UDP 7654 (main)
30/Jan/2021 15:37:04 [sn.c:712] supernode is listening on UDP 5645 (management)
30/Jan/2021 15:37:04 [sn.c:721] Dropping privileges to uid=65534, gid=65534
30/Jan/2021 15:37:04 [sn.c:737] supernode started

30/Jan/2021 15:37:14 [sn_utils.c:1819] timeout
30/Jan/2021 15:37:14 [sn_utils.c:702] send REGISTER_SUPER to 47.104.20.99:7654
30/Jan/2021 15:37:14 [sn_utils.c:146] sendto_sock 91 to [47.104.20.99:7654]
30/Jan/2021 15:37:14 [sn_utils.c:733] Purging old communities and edges
30/Jan/2021 15:37:14 [sn_utils.c:749] Remove 0 edges
30/Jan/2021 15:37:14 [sn_utils.c:919] Processing incoming UDP packet [len: 50][sender: 47.104.20.99:7654]
30/Jan/2021 15:37:14 [sn_utils.c:1506] Rx REGISTER_SUPER_ACK myMAC=9A:59:FA:54:F3:C3 [47.104.20.99:7654] (external 106.55.4.71:7654)

30/Jan/2021 15:37:24 [sn_utils.c:1819] timeout
30/Jan/2021 15:37:34 [sn_utils.c:1819] timeout

Logan007 commented 3 years ago

I am just glad that we found this somewhat hard-to-find bug, thank you for your support!

p5n commented 7 months ago

I see very similar issue when enable header encryption with -H:

Apr 13 00:45:58 p5n supernode[6824]: 13/Apr/2024 00:45:58 [n2n.c:926] time_stamp_verify_and_update found a timestamp out of allowed frame.
Apr 13 00:45:58 p5n supernode[6824]: 13/Apr/2024 00:45:58 [sn_utils.c:1869] dropped REGISTER_SUPER due to time stamp error

it can be reproduced even when edge and supernode runs on the same host.

hamishcoleman commented 7 months ago

@p5n This project only has a very small amount of activity these days, but if you would like to try out the new fork n3n, we would be happy to try and fix this issue in a ticket over there.

ntop / n2n

`process_udp dropped REGISTER_SUPER due to time stamp error` when I try to connect a supernode to another #608