[HECnet] Adjacencies Keep Bouncing

Sun Jun 29 10:04:46 PDT 2014

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