NFS4 over tinc hangs

[Nikolaus Rath]

Guus Sliepen <guus-NnCthlHDAqpg9hUCZPvPmw at public.gmane.org> writes:
>> I am using tinc 1.0.16 on 3.0.0, 64bit Ubuntu 10.04 LTS on both server
>> and client.
>> 
>> The problem is that as soon as more than three tinc clients are
>> accessing the NFS shares, any operations on the NFS mountpoints by the
>> clients hang. On the clients, tinc then takes 100% CPU time. On the
>> server, the tinc stance runs with about 20% load. When activating tinc
>> debugging, tinc seems to be busy forwarding packets. I also ran a packet
>> sniffer which showed me that 90% of the packets were NFS related, but I
>> am not familiar enough with NFS to be able to tell anything from the
>> packets themselves.
>
> Can you show me a few lines of the debug messages when it is busy
> forwarding?

This is from the server:

[...]
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 146 bytes to oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 254 bytes from chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 254 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 130 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 130 bytes to athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 122 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 122 bytes to chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 350 bytes from oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 350 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 190 bytes from athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 190 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 570 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 570 bytes to oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 234 bytes from chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 234 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 146 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 146 bytes to athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 114 bytes from inspiron (128.59.145.39 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 114 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 130 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 130 bytes to chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 254 bytes from oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 254 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 114 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 114 bytes to inspiron (128.59.145.39 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 122 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 122 bytes to oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 314 bytes from athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 314 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 190 bytes from chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 190 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 562 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 562 bytes to athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 146 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 146 bytes to chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 66 bytes from inspiron (128.59.145.39 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 66 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 234 bytes from oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 234 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 130 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 130 bytes to oberon (128.59.46.189 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 226 bytes from athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 226 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Read packet of 122 bytes from Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Sending packet of 122 bytes to athena (128.59.151.185 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Received packet of 354 bytes from chronos (128.59.46.138 port 655)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Writing packet of 354 bytes to Linux tun/tap device (tun mode)
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Got INT signal
Mar 12 10:15:28 spitzer tinc.hbt[2230]: Reverting to old debug level (0)

I also put a screenshot of the corresponding wireshork dump online at 
http://www.rath.org/res/wireshark.png


> Also, without full debugging enabled, when this happens, run "tincd -n
> <netname> -kUSR2" on one of the clients using 100% CPU and on the server, and
> send me the node, edge and subnet list that tinc logged. This allows me to see
> if there could be a routing loop within tinc or if there is another cause for
> this problem.

On the client:

Mar 12 10:14:08 chronos tinc.hbt[1662]: Statistics for Linux tun/tap device (tun mode) /dev/net/tun:
Mar 12 10:14:08 chronos tinc.hbt[1662]:  total bytes in:   111523435
Mar 12 10:14:08 chronos tinc.hbt[1662]:  total bytes out:   83944329
Mar 12 10:14:08 chronos tinc.hbt[1662]: Nodes:
Mar 12 10:14:08 chronos tinc.hbt[1662]:  athena at 128.59.151.185 port 655 cipher 0 digest 0 maclength 0 compression 0 options c status 0018 nexthop spitzer via athena pmtu 1518 (min 0 max 1518)
Mar 12 10:14:08 chronos tinc.hbt[1662]:  chronos at MYSELF cipher 0 digest 0 maclength 0 compression 0 options c status 0018 nexthop chronos via chronos pmtu 1518 (min 0 max 1518)
Mar 12 10:14:08 chronos tinc.hbt[1662]:  inspiron at 128.59.145.39 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop spitzer via inspiron pmtu 1408 (min 1408 max 1408)
Mar 12 10:14:08 chronos tinc.hbt[1662]:  oberon at 128.59.46.189 port 655 cipher 0 digest 0 maclength 0 compression 0 options c status 0018 nexthop spitzer via oberon pmtu 1518 (min 0 max 1518)
Mar 12 10:14:08 chronos tinc.hbt[1662]:  spitzer at 128.59.144.255 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop spitzer via spitzer pmtu 1408 (min 1408 max 1408)
Mar 12 10:14:08 chronos tinc.hbt[1662]:  vostro at (null) cipher 0 digest 0 maclength 0 compression 0 options 0 status 0020 nexthop - via - pmtu 1518 (min 0 max 1518)
Mar 12 10:14:08 chronos tinc.hbt[1662]: End of nodes.
Mar 12 10:14:08 chronos tinc.hbt[1662]: Edges:
Mar 12 10:14:08 chronos tinc.hbt[1662]:  athena to spitzer at 128.59.144.255 port 655 options c weight 69
Mar 12 10:14:08 chronos tinc.hbt[1662]:  chronos to spitzer at 128.59.144.255 port 655 options c weight 42
Mar 12 10:14:08 chronos tinc.hbt[1662]:  inspiron to spitzer at 128.59.144.255 port 655 options c weight 19
Mar 12 10:14:08 chronos tinc.hbt[1662]:  oberon to spitzer at 128.59.144.255 port 655 options c weight 44
Mar 12 10:14:08 chronos tinc.hbt[1662]:  spitzer to athena at 128.59.151.185 port 655 options c weight 69
Mar 12 10:14:08 chronos tinc.hbt[1662]:  spitzer to chronos at 128.59.46.138 port 655 options c weight 42
Mar 12 10:14:08 chronos tinc.hbt[1662]:  spitzer to inspiron at 128.59.145.39 port 655 options c weight 19
Mar 12 10:14:08 chronos tinc.hbt[1662]:  spitzer to oberon at 128.59.46.189 port 655 options c weight 44
Mar 12 10:14:08 chronos tinc.hbt[1662]: End of edges.
Mar 12 10:14:08 chronos tinc.hbt[1662]: Subnet list:
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.2/32#10 owner spitzer
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.7/32#10 owner inspiron
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.8/32#10 owner vostro
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.19/32#10 owner chronos
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.20/32#10 owner athena
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.21/32#10 owner oberon
Mar 12 10:14:08 chronos tinc.hbt[1662]:  192.168.1.0/24#15 owner spitzer
Mar 12 10:14:08 chronos tinc.hbt[1662]: End of subnet list.


On the server:

Mar 12 10:10:20 spitzer tinc.hbt[2230]: Statistics for Linux tun/tap device (tun mode) /dev/net/tun:
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  total bytes in:  4791288583
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  total bytes out: 1859950768
Mar 12 10:10:20 spitzer tinc.hbt[2230]: Nodes:
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  athena at 128.59.151.185 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop athena via athena pmtu 1408 (min 1408 max 1408)
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  chronos at 128.59.46.138 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop chronos via chronos pmtu 1407 (min 1407 max 1407)
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  inspiron at 128.59.145.39 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop inspiron via inspiron pmtu 1407 (min 1407 max 1407)
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  oberon at 128.59.46.189 port 655 cipher 419 digest 64 maclength 4 compression 11 options c status 001a nexthop oberon via oberon pmtu 1407 (min 1407 max 1407)
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  spitzer at MYSELF cipher 0 digest 0 maclength 0 compression 0 options c status 0018 nexthop spitzer via spitzer pmtu 1518 (min 0 max 1518)
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  vostro at (null) cipher 419 digest 64 maclength 4 compression 11 options c status 0020 nexthop vostro via vostro pmtu 1408 (min 0 max 1518)
Mar 12 10:10:20 spitzer tinc.hbt[2230]: End of nodes.
Mar 12 10:10:20 spitzer tinc.hbt[2230]: Edges:
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  athena to spitzer at 128.59.144.255 port 655 options c weight 69
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  chronos to spitzer at 128.59.144.255 port 655 options c weight 42
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  inspiron to spitzer at 128.59.144.255 port 655 options c weight 19
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  oberon to spitzer at 128.59.144.255 port 655 options c weight 44
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  spitzer to athena at 128.59.151.185 port 655 options c weight 69
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  spitzer to chronos at 128.59.46.138 port 655 options c weight 42
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  spitzer to inspiron at 128.59.145.39 port 655 options c weight 19
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  spitzer to oberon at 128.59.46.189 port 655 options c weight 44
Mar 12 10:10:20 spitzer tinc.hbt[2230]: End of edges.
Mar 12 10:10:20 spitzer tinc.hbt[2230]: Subnet list:
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.2/32#10 owner spitzer
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.7/32#10 owner inspiron
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.8/32#10 owner vostro
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.19/32#10 owner chronos
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.20/32#10 owner athena
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.21/32#10 owner oberon
Mar 12 10:10:20 spitzer tinc.hbt[2230]:  192.168.1.0/24#15 owner spitzer
Mar 12 10:10:20 spitzer tinc.hbt[2230]: End of subnet list.


Any idea?

Best,

   -Nikolaus

-- 
 »Time flies like an arrow, fruit flies like a Banana.«

  PGP fingerprint: 5B93 61F8 4EA2 E279 ABF6  02CF A9AD B7F8 AE4E 425C