29 Jun
2014
29 Jun
'14
12:04 p.m.
I think this was discussed not too long ago, but I can t find the email thread. Sorry,
this is quite a long email.
Here at 5.1023 I keep experiencing certain adjacencies going up and down. At the bottom of
this email is an extract of several hours of my log (all times are UK local time, current
GMT+1).
Last night I investigated one of these, when 8.400 went down at 2014-06-28 22:04:03. I
used a packet sniffer and could see that my Ethernet Router Hello message went out, with
8.400 in it, at the following times:
22:03:18
22:03:23
22:03:33
22:03:38
22:03:48
22:03:53
I did not send any Ethernet Router Hello messages in that period that excluded 8.400.
Conversely, from 8.400 I received Ethernet Router Hello messages, with 5.1023 included
except where noted at the following times:
22:03:28
22:03:29
22:03:30
22:03:45
22:03:46
22:03:47
22:04:03 (5.1023 missing)
22:04:04
22:04:07
22:04:08
22:04:09
22:04:25
22:04:26
So here are some interesting things about the above information.
1. I am supposed to send out the Ethernet Router Hello every 15 seconds. From my router
log, that is exactly what happens (at :18, :33, :48 etc). However the packet sniffer sees
extra packets inserted. I have no idea where these packets are coming from (although my
suspicion is winpcap, see later).
2. 8.400 seems to send its Ethernet Router Hello every 15 seconds, but repeats them
several times at 1-second intervals. In the extract above it is repeated 3 times, then 3
times, then 5 times.
3. For a node to decide to drop an adjacency (ie to exclude it from the Ethernet Router
Hello message), it must fail to see an Ethernet Router Hello for 3xHello Timer (Hello
Timer is 15 seconds by default, so 45 seconds). Clearly my side has sent several Ethernet
Router Hello messages in that time. If this was UDP dropping packets, then I would have
hoped that it would not drop my particular ones 3 times in a row over a period of 45
seconds.
So, somehow, my Ethernet Router Hello messages are being dropped on their way to 8.400.
However, this can t be outbound from 5.1023, because if that was the case then all my
adjacencies would all go down at the same time. At any one time, only adjacency goes down.
This suggests that the packet is somehow getting lost towards the end of its journey to
8.400.
What kind of node is 8.400? 47.556 is another one that appears to have this problem, I see
that one is SIMH.
I am wondering if pcap/winpcap might be implicated here. The reason is that I noticed
winpcap seems to drop incoming packets if you have sent a burst of outbound packets. In my
router I was sending all the DECnet Level 1 Routing messages, all at the same time and
getting some problems similar to this with a node local to my network, because my router
did not see the packets coming from the other node, even though the sniffer could see
them. I changed my router code to send the Level 1 Routing messages with a 1-second delay
between them, and that problem went away. So, I am wondering if the remote nodes I have
this problem with are SIMH nodes?
I do also see, less frequently, timeouts on my side. These are when I fail to see an
Ethernet Router Hello from the other node for 45 seconds. I have not analysed this
scenario.
Any ideas?
Regards
Rob
2014-06-28 15:00:50 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 15:42:04 Adjacency timeout 8.400 (Slot 23)
2014-06-28 15:42:04 Adjacency down 8.400 (Slot 23)
2014-06-28 15:42:06 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 16:37:12 Adjacency timeout 8.400 (Slot 23)
2014-06-28 16:37:12 Adjacency down 8.400 (Slot 23)
2014-06-28 16:37:17 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 18:11:46 Adjacency timeout 8.400 (Slot 23)
2014-06-28 18:11:46 Adjacency down 8.400 (Slot 23)
2014-06-28 18:12:04 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 18:15:11 Adjacency timeout 47.556 (Slot 25)
2014-06-28 18:15:11 Adjacency down 47.556 (Slot 25)
2014-06-28 18:15:14 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 18:33:15 Adjacency timeout 47.556 (Slot 25)
2014-06-28 18:33:15 Adjacency down 47.556 (Slot 25)
2014-06-28 18:33:18 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 18:33:19 Adjacency down 47.556 (Slot 25)
2014-06-28 18:33:42 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 18:54:37 Adjacency timeout 47.556 (Slot 25)
2014-06-28 18:54:37 Adjacency down 47.556 (Slot 25)
2014-06-28 18:54:43 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 19:36:02 Adjacency timeout 47.556 (Slot 25)
2014-06-28 19:36:02 Adjacency down 47.556 (Slot 25)
2014-06-28 19:36:20 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 19:44:36 Adjacency timeout 28.41 (Slot 24)
2014-06-28 19:44:36 Adjacency down 28.41 (Slot 24)
2014-06-28 19:53:04 Adjacency up 28.41 (Slot 24) on psilo.update.uu.se
2014-06-28 19:55:08 Adjacency timeout 28.41 (Slot 24)
2014-06-28 19:55:08 Adjacency down 28.41 (Slot 24)
2014-06-28 19:57:20 Adjacency up 28.41 (Slot 24) on psilo.update.uu.se
2014-06-28 20:00:03 Adjacency down 8.400 (Slot 23)
2014-06-28 20:00:03 Adjacency down 47.556 (Slot 25)
2014-06-28 20:00:04 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 20:00:05 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 20:18:08 Adjacency timeout 8.400 (Slot 23)
2014-06-28 20:18:08 Adjacency down 8.400 (Slot 23)
2014-06-28 20:18:12 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 20:47:46 Adjacency down 8.400 (Slot 23)
2014-06-28 20:47:46 Adjacency down 47.556 (Slot 25)
2014-06-28 20:47:49 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 20:47:49 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 22:04:03 Adjacency down 8.400 (Slot 23)
2014-06-28 22:04:04 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 23:10:26 Adjacency timeout 5.99 (Slot 30)
2014-06-28 23:10:26 Adjacency down 5.99 (Slot 30)
2014-06-28 23:18:28 Adjacency down 8.400 (Slot 23)
2014-06-28 23:18:28 Adjacency down 47.556 (Slot 25)
2014-06-28 23:18:34 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-28 23:18:35 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-28 23:25:50 Adjacency timeout 47.556 (Slot 25)
2014-06-28 23:25:50 Adjacency down 47.556 (Slot 25)
2014-06-28 23:25:54 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 00:06:52 Adjacency timeout 8.400 (Slot 23)
2014-06-29 00:06:52 Adjacency down 8.400 (Slot 23)
2014-06-29 00:06:58 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 00:10:47 Adjacency timeout 47.556 (Slot 25)
2014-06-29 00:10:47 Adjacency down 47.556 (Slot 25)
2014-06-29 00:10:47 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 00:28:21 Adjacency timeout 8.400 (Slot 23)
2014-06-29 00:28:21 Adjacency down 8.400 (Slot 23)
2014-06-29 00:28:26 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 00:30:54 Adjacency down 8.400 (Slot 23)
2014-06-29 00:31:18 Adjacency timeout 47.556 (Slot 25)
2014-06-29 00:31:18 Adjacency down 47.556 (Slot 25)
2014-06-29 00:31:21 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 00:31:21 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 00:45:41 Adjacency timeout 8.400 (Slot 23)
2014-06-29 00:45:41 Adjacency down 8.400 (Slot 23)
2014-06-29 00:46:04 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 00:53:57 Adjacency down 11.2 (Slot 21)
2014-06-29 00:54:05 Adjacency up 11.2 (Slot 21) on psilo.update.uu.se
2014-06-29 04:45:36 Adjacency timeout 47.556 (Slot 25)
2014-06-29 04:45:36 Adjacency down 47.556 (Slot 25)
2014-06-29 04:45:38 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 04:49:49 Adjacency timeout 47.556 (Slot 25)
2014-06-29 04:49:49 Adjacency down 47.556 (Slot 25)
2014-06-29 04:53:19 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 06:46:04 Adjacency up 62.637 (Slot 29) on psilo.update.uu.se
2014-06-29 08:01:32 Adjacency timeout 47.556 (Slot 25)
2014-06-29 08:01:32 Adjacency down 47.556 (Slot 25)
2014-06-29 08:01:33 Adjacency timeout 8.400 (Slot 23)
2014-06-29 08:01:33 Adjacency down 8.400 (Slot 23)
2014-06-29 08:03:04 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 08:03:51 Adjacency timeout 8.400 (Slot 23)
2014-06-29 08:03:51 Adjacency down 8.400 (Slot 23)
2014-06-29 08:04:39 Adjacency timeout 47.556 (Slot 23)
2014-06-29 08:04:49 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se
2014-06-29 08:04:50 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 08:05:52 Adjacency timeout 47.556 (Slot 25)
2014-06-29 08:05:52 Adjacency down 47.556 (Slot 25)
2014-06-29 08:08:06 Adjacency up 47.556 (Slot 25) on psilo.update.uu.se
2014-06-29 08:10:02 Adjacency timeout 8.400 (Slot 23)
2014-06-29 08:10:02 Adjacency down 8.400 (Slot 23)
2014-06-29 08:10:18 Adjacency up 8.400 (Slot 23) on psilo.update.uu.se