[radvd-devel-l] losing default route

Sat Jul 23 12:05:54 EDT 2005

On Saturday 23 July 2005 15:41, Pekka Savola wrote:
> On Sat, 23 Jul 2005, Tomasz Grobelny wrote:
> > man says there are only 4 levels... But with "-d 5" before last message I
> > get "calling schedule_timer from alarm_handler context".
>
> Ok.
>
> I did quite a bit of debugging on this, and I suspect the problem is
> that for some reason, radvd can't exit the while loop in
> timer.c:alarm_handler().
>
> Could you add the attached code which adds a bit of debugging in this
> code path, and report the results?
>
There was propably 'c' missing in your patch (use vs. usec). Here is the full 
record of radvd session:
$ sudo radvd -d 5 -m stderr
[Jul 23 16:34:29] radvd: version 0.8 started
[Jul 23 16:34:29] radvd: inet_pton returned 1
[Jul 23 16:34:29] radvd: hardware type for eth2 is 1
[Jul 23 16:34:29] radvd: link layer token length for eth2 is 48
[Jul 23 16:34:29] radvd: prefix length for eth2 is 64
[Jul 23 16:34:29] radvd: interface definition for eth2 is ok
[Jul 23 16:34:29] radvd: sending RA on eth2
[Jul 23 16:34:29] radvd: setting timer: 10.00 secs
[Jul 23 16:34:29] radvd: setting timer: 10 secs 0 usecs
[Jul 23 16:34:29] radvd: calling schedule_timer from set_timer context
[Jul 23 16:34:29] radvd: calling alarm: 9 secs, 997804 usecs
[Jul 23 16:34:29] radvd: recvmsg len=56
[Jul 23 16:34:29] radvd: if_index 5
[Jul 23 16:34:29] radvd: found Interface: eth2

[Jul 23 16:34:39] radvd: alarm_handler: expiry: 1122129279.280458, now: 
1122129279.281554; entering the loop.
[Jul 23 16:34:39] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:34:39] radvd: timer_handler called for eth2
[Jul 23 16:34:39] radvd: sending RA on eth2
[Jul 23 16:34:39] radvd: setting timer: 4.91 secs
[Jul 23 16:34:39] radvd: setting timer: 4 secs 907838 usecs
[Jul 23 16:34:39] radvd: calling schedule_timer from set_timer context
[Jul 23 16:34:39] radvd: calling alarm: 4 secs, 907685 usecs
[Jul 23 16:34:39] radvd: alarm_handler: after calling the handler
[Jul 23 16:34:39] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:34:39] radvd: calling alarm: 4 secs, 906210 usecs
[Jul 23 16:34:39] radvd: recvmsg len=56
[Jul 23 16:34:39] radvd: if_index 5
[Jul 23 16:34:39] radvd: found Interface: eth2

[Jul 23 16:34:44] radvd: alarm_handler: expiry: 1122129284.192777, now: 
1122129284.192780; entering the loop.
[Jul 23 16:34:44] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:34:44] radvd: timer_handler called for eth2
[Jul 23 16:34:44] radvd: sending RA on eth2
[Jul 23 16:34:44] radvd: setting timer: 8.17 secs
[Jul 23 16:34:44] radvd: setting timer: 8 secs 166982 usecs
[Jul 23 16:34:44] radvd: calling schedule_timer from set_timer context
[Jul 23 16:34:44] radvd: calling alarm: 8 secs, 166833 usecs
[Jul 23 16:34:44] radvd: alarm_handler: after calling the handler
[Jul 23 16:34:44] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:34:44] radvd: calling alarm: 8 secs, 166351 usecs
[Jul 23 16:34:44] radvd: recvmsg len=56
[Jul 23 16:34:44] radvd: if_index 5
[Jul 23 16:34:44] radvd: found Interface: eth2

[Jul 23 16:34:52] radvd: alarm_handler: expiry: 1122129292.363086, now: 
1122129292.363537; entering the loop.
[Jul 23 16:34:52] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:34:52] radvd: timer_handler called for eth2
[Jul 23 16:34:52] radvd: sending RA on eth2
[Jul 23 16:34:52] radvd: setting timer: 8.88 secs
[Jul 23 16:34:52] radvd: setting timer: 8 secs 881456 usecs
[Jul 23 16:34:52] radvd: calling schedule_timer from set_timer context
[Jul 23 16:34:52] radvd: calling alarm: 8 secs, 881308 usecs
[Jul 23 16:34:52] radvd: alarm_handler: after calling the handler
[Jul 23 16:34:52] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:34:52] radvd: calling alarm: 8 secs, 880857 usecs
[Jul 23 16:34:52] radvd: recvmsg len=56
[Jul 23 16:34:52] radvd: if_index 5
[Jul 23 16:34:52] radvd: found Interface: eth2

[Jul 23 16:35:01] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:35:01] radvd: next timer has already expired, queueing signal
[Jul 23 16:35:01] radvd: alarm_handler: expiry: 1122129301.248311, now: 
1122129301.248740; entering the loop.
[Jul 23 16:35:01] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:35:01] radvd: timer_handler called for eth2
[Jul 23 16:35:01] radvd: sending RA on eth2
[Jul 23 16:35:01] radvd: setting timer: 3.49 secs
[Jul 23 16:35:01] radvd: setting timer: 3 secs 488885 usecs
[Jul 23 16:35:01] radvd: calling schedule_timer from set_timer context
[Jul 23 16:35:01] radvd: calling alarm: 3 secs, 488735 usecs
[Jul 23 16:35:01] radvd: alarm_handler: after calling the handler
[Jul 23 16:35:01] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:35:01] radvd: calling alarm: 3 secs, 488236 usecs
[Jul 23 16:35:01] radvd: recvmsg len=56
[Jul 23 16:35:01] radvd: if_index 5
[Jul 23 16:35:01] radvd: found Interface: eth2

[Jul 23 16:35:04] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:35:04] radvd: next timer has already expired, queueing signal
[Jul 23 16:35:04] radvd: alarm_handler: expiry: 1122129304.741733, now: 
1122129304.742262; entering the loop.
[Jul 23 16:35:04] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:35:04] radvd: timer_handler called for eth2
[Jul 23 16:35:04] radvd: sending RA on eth2
[Jul 23 16:35:04] radvd: setting timer: 3.51 secs
[Jul 23 16:35:04] radvd: setting timer: 3 secs 506997 usecs
[Jul 23 16:35:04] radvd: calling schedule_timer from set_timer context
[Jul 23 16:35:04] radvd: calling alarm: 3 secs, 506808 usecs
[Jul 23 16:35:04] radvd: alarm_handler: after calling the handler
[Jul 23 16:35:04] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:35:04] radvd: calling alarm: 3 secs, 506342 usecs
[Jul 23 16:35:04] radvd: recvmsg len=56
[Jul 23 16:35:04] radvd: if_index 5
[Jul 23 16:35:04] radvd: found Interface: eth2
--- stops for the first time: ---
[Jul 23 16:35:08] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:35:08] radvd: calling alarm: 0 secs, 8 usecs
--- and continues after ifdown/ifup on client side: ---
[Jul 23 16:36:03] radvd: recvmsg len=16
[Jul 23 16:36:03] radvd: if_index 5
[Jul 23 16:36:03] radvd: found Interface: eth2
[Jul 23 16:36:03] radvd: random mdelay for eth2: 356.73
[Jul 23 16:36:03] radvd: calling schedule_timer from clear_timer context
[Jul 23 16:36:03] radvd: sending RA on eth2
[Jul 23 16:36:03] radvd: setting timer: 6.73 secs
[Jul 23 16:36:03] radvd: setting timer: 6 secs 728848 usecs
[Jul 23 16:36:03] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:03] radvd: calling alarm: 6 secs, 728652 usecs
[Jul 23 16:36:03] radvd: recvmsg len=56
[Jul 23 16:36:03] radvd: if_index 5
[Jul 23 16:36:03] radvd: found Interface: eth2

[Jul 23 16:36:10] radvd: alarm_handler: expiry: 1122129370.42420, now: 
1122129370.42742; entering the loop.
[Jul 23 16:36:10] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:10] radvd: timer_handler called for eth2
[Jul 23 16:36:10] radvd: sending RA on eth2
[Jul 23 16:36:10] radvd: setting timer: 4.20 secs
[Jul 23 16:36:10] radvd: setting timer: 4 secs 200776 usecs
[Jul 23 16:36:10] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:10] radvd: calling alarm: 4 secs, 200628 usecs
[Jul 23 16:36:10] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:10] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:10] radvd: calling alarm: 4 secs, 199893 usecs
[Jul 23 16:36:10] radvd: recvmsg len=56
[Jul 23 16:36:10] radvd: if_index 5
[Jul 23 16:36:10] radvd: found Interface: eth2

[Jul 23 16:36:14] radvd: alarm_handler: expiry: 1122129374.246793, now: 
1122129374.247099; entering the loop.
[Jul 23 16:36:14] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:14] radvd: timer_handler called for eth2
[Jul 23 16:36:14] radvd: sending RA on eth2
[Jul 23 16:36:14] radvd: setting timer: 3.64 secs
[Jul 23 16:36:14] radvd: setting timer: 3 secs 642110 usecs
[Jul 23 16:36:14] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:14] radvd: calling alarm: 3 secs, 641961 usecs
[Jul 23 16:36:14] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:14] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:14] radvd: calling alarm: 3 secs, 641512 usecs
[Jul 23 16:36:14] radvd: recvmsg len=56
[Jul 23 16:36:14] radvd: if_index 5
[Jul 23 16:36:14] radvd: found Interface: eth2

[Jul 23 16:36:17] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:17] radvd: calling alarm: 0 secs, 523 usecs
[Jul 23 16:36:17] radvd: alarm_handler: expiry: 1122129377.893351, now: 
1122129377.893858; entering the loop.
[Jul 23 16:36:17] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:17] radvd: timer_handler called for eth2
[Jul 23 16:36:17] radvd: sending RA on eth2
[Jul 23 16:36:17] radvd: setting timer: 6.39 secs
[Jul 23 16:36:17] radvd: setting timer: 6 secs 390697 usecs
[Jul 23 16:36:17] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:17] radvd: calling alarm: 6 secs, 390549 usecs
[Jul 23 16:36:17] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:17] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:17] radvd: calling alarm: 6 secs, 390057 usecs
[Jul 23 16:36:17] radvd: recvmsg len=56
[Jul 23 16:36:17] radvd: if_index 5
[Jul 23 16:36:17] radvd: found Interface: eth2

[Jul 23 16:36:24] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:24] radvd: next timer has already expired, queueing signal
[Jul 23 16:36:24] radvd: alarm_handler: expiry: 1122129384.287780, now: 
1122129384.288046; entering the loop.
[Jul 23 16:36:24] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:24] radvd: timer_handler called for eth2
[Jul 23 16:36:24] radvd: sending RA on eth2
[Jul 23 16:36:24] radvd: setting timer: 4.76 secs
[Jul 23 16:36:24] radvd: setting timer: 4 secs 759843 usecs
[Jul 23 16:36:24] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:24] radvd: calling alarm: 4 secs, 759694 usecs
[Jul 23 16:36:24] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:24] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:24] radvd: calling alarm: 4 secs, 759201 usecs
[Jul 23 16:36:24] radvd: recvmsg len=56
[Jul 23 16:36:24] radvd: if_index 5
[Jul 23 16:36:24] radvd: found Interface: eth2

[Jul 23 16:36:29] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:29] radvd: next timer has already expired, queueing signal
[Jul 23 16:36:29] radvd: alarm_handler: expiry: 1122129389.51908, now: 
1122129389.52329; entering the loop.
[Jul 23 16:36:29] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:29] radvd: timer_handler called for eth2
[Jul 23 16:36:29] radvd: sending RA on eth2
[Jul 23 16:36:29] radvd: setting timer: 5.37 secs
[Jul 23 16:36:29] radvd: setting timer: 5 secs 367369 usecs
[Jul 23 16:36:29] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:29] radvd: calling alarm: 5 secs, 367221 usecs
[Jul 23 16:36:29] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:29] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:29] radvd: calling alarm: 5 secs, 366734 usecs
[Jul 23 16:36:29] radvd: recvmsg len=56
[Jul 23 16:36:29] radvd: if_index 5
[Jul 23 16:36:29] radvd: found Interface: eth2

[Jul 23 16:36:34] radvd: alarm_handler: expiry: 1122129394.422809, now: 
1122129394.423024; entering the loop.
[Jul 23 16:36:34] radvd: alarm_handler: prior to calling the handler
[Jul 23 16:36:34] radvd: timer_handler called for eth2
[Jul 23 16:36:34] radvd: sending RA on eth2
[Jul 23 16:36:34] radvd: setting timer: 4.84 secs
[Jul 23 16:36:34] radvd: setting timer: 4 secs 838655 usecs
[Jul 23 16:36:34] radvd: calling schedule_timer from set_timer context
[Jul 23 16:36:34] radvd: calling alarm: 4 secs, 838505 usecs
[Jul 23 16:36:34] radvd: alarm_handler: after calling the handler
[Jul 23 16:36:34] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:34] radvd: calling alarm: 4 secs, 838053 usecs
[Jul 23 16:36:34] radvd: recvmsg len=56
[Jul 23 16:36:34] radvd: if_index 5
[Jul 23 16:36:34] radvd: found Interface: eth2
--- and stops for the second time: ---
[Jul 23 16:36:39] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:36:39] radvd: calling alarm: 0 secs, 213 usecs
$ 
(I inserted blank lines or comments where there was no output for a few 
seconds.)

> >> Have you tried whether this worked in 0.7.2? (There were some changes
> >> in timestamp usage in 0.7.3)
> >
> > I had 0.7.2 and it worked just fine. Then I upgraded both client and
> > router OS (PLD Linux) and found that it stopped working. Then I thought
> > that maybe the bug is fixed in 0.8 so I tried this version, without
> > success.
>
> Could you please test 0.7.2 again?  I see only very few changes
> between 0.7.2 and 0.8 which should affect this, so I'd like to be
> double sure about this.
>
Ok, checked this once again. It also ends with such two lines:
[Jul 23 16:45:47] radvd: calling schedule_timer from alarm_handler context
[Jul 23 16:45:47] radvd: calling alarm: 0 secs, 14 usecs

What I found is that sending a SIGALRM to radvd process makes it work again 
(until next stop). Consequently it must be setitimer (timer.c:52) that works 
incorrectly (or am I wrong?). It doesn't return any error (the return value 
is always 0) but if I insert "next.it_value.tv_sec++;" just before calling 
setitimer radvd works much more reliable. With my config file before the 
change it worked ca. 2 minutes, now with the same config it works for about 
15 minutes and nothing bad happens. But it is only a workaround. I hope you 
have any idea for real solution.

Tomek