1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

OpenVPN refuses client traffic after short time (Toastman 1.28.7497)

Discussion in 'Tomato Firmware' started by vpn_brad, Jun 12, 2012.

  1. vpn_brad

    vpn_brad Serious Server Member

    Hi, I posted this on the openvpn forum last week but didn't get any answer. I'm not sure what the right time to wait is - apologies if this is considered double posting.

    I am trying to connect my home and office networks with openvpn. The connection initially works fine and I can access machines on the remote network from either side, but after any inactivity, traffic stops and eventually the client restarts the connection on ping timeout. The setup is:

    Office: ASUS-RT-N16, "1.28.7497 MIPSR2-Toastman-RT K26 USB VPN", client
    Home: Linksys E300, "1.28.7497 MIPSR2-Toastman-RT K26 USB VPN", server

    The office net is 192.168.2.0/24 and home is 192.168.1.0/24. The connection between the routers is stable with no detectable packet loss (same provider, ~6-9ms pings).

    The ping/keepalive is set to ping 10s, restart after 180s. This is what happens:
    1) client connects successfully
    2) client sends ping every 10 seconds and gets response from server. At this point, the connection works fine.
    3) after about 60-90s, the client stops getting a response to the ping (checked with verb 7) and the server log shows "read UDPv4 [ECONNREFUSED]: Connection refused (code=146)" for each client ping sent
    4) after ~180s, the client reconnects
    5) during reconnection, the server still sees the existing connection, so drops it before accepting the new connection

    After step 1, if I set a continuous ping from a pc on the office side to a pc on the home side, then everything keeps working (i.e. the client keepalive pings keep getting responses, no connection refused messages in the server log, and the connection works). As soon as I stop the ping though, the keepalive pings start getting refused again after a few secs and I'm back at step 3. I confirmed the routing table doesn't change between step 2 and 3.

    See config below. Note: X.X.. and Y.Y.. substituted for public IPs.


    Client Config
    Code:
    daemon
    client
    dev tun11
    proto udp
    remote private.dyndns.org 1194
    resolv-retry 30
    nobind
    persist-key
    persist-tun
    comp-lzo yes
    cipher AES-128-CBC
    verb 3
    ca ca.crt
    cert client.crt
    key client.key
    status-version 2
    status status
    verb 5
    Server Config
    Code:
    daemon
    server 10.8.0.0 255.255.255.0
    proto udp
    port 1194
    dev tun21
    cipher AES-128-CBC
    comp-lzo yes
    keepalive 15 60
    verb 3
    push "route 192.168.1.0 255.255.255.0"
    client-config-dir ccd
    ccd-exclusive
    route 192.168.2.0 255.255.255.0
    ca ca.crt
    dh dh.pem
    cert server.crt
    key server.key
    status-version 2
    status status
    keepalive 10 180
    verb 5
    Client Log (note: date, unknown.da.. etc. removed)


    Code:
    17:58:50 tun: Universal TUN/TAP device driver, 1.6
    17:58:50 openvpn[6255]: OpenVPN 2.1.1 mipsel-unknown-linux-gnu [SSL] [LZO2] [EPOLL] built on Mar 23 2012
    17:58:50 openvpn[6255]: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
    17:58:50 openvpn[6255]: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
    17:58:50 tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
    17:58:50 openvpn[6255]: LZO compression initialized
    17:58:50 openvpn[6255]: Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
    17:58:50 openvpn[6255]: Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
    17:58:50 openvpn[6262]: Socket Buffers: R=[114688->131072] S=[114688->131072]
    17:58:50 openvpn[6262]: UDPv4 link local: [undef]
    17:58:50 openvpn[6262]: UDPv4 link remote: X.X.X.X:1194
    17:58:50 openvpn[6262]: TLS: Initial packet from X.X.X.X:1194, sid=f4c4ef11 35338174
    17:58:50 openvpn[6262]: VERIFY OK: depth=1, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=ThreePegs/name=changeme/emailAddress=info@threepegs.com
    17:58:50 openvpn[6262]: VERIFY OK: depth=0, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=home_router_server/name=changeme/emailAddress=info@threepegs.com
    17:58:51 openvpn[6262]: Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    17:58:51 openvpn[6262]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    17:58:51 openvpn[6262]: Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    17:58:51 openvpn[6262]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    17:58:51 openvpn[6262]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
    17:58:51 openvpn[6262]: [home_router_server] Peer Connection Initiated with X.X.X.X:1194
    17:58:53 openvpn[6262]: SENT CONTROL [home_router_server]: 'PUSH_REQUEST' (status=1)
    17:58:53 openvpn[6262]: PUSH: Received control message: 'PUSH_REPLY,route 192.168.1.0 255.255.255.0,route 10.8.0.1,topology net30,ping 10,ping-restart 180,ifconfig 10.8.0.6 10.8.0.5'
    17:58:53 openvpn[6262]: OPTIONS IMPORT: timers and/or timeouts modified
    17:58:53 openvpn[6262]: OPTIONS IMPORT: --ifconfig/up options modified
    17:58:53 openvpn[6262]: OPTIONS IMPORT: route options modified
    17:58:53 openvpn[6262]: TUN/TAP device tun11 opened
    17:58:53 openvpn[6262]: TUN/TAP TX queue length set to 100
    17:58:53 openvpn[6262]: /sbin/ifconfig tun11 10.8.0.6 pointopoint 10.8.0.5 mtu 1500
    17:58:53 openvpn[6262]: /sbin/route add -net 192.168.1.0 netmask 255.255.255.0 gw 10.8.0.5
    17:58:53 openvpn[6262]: /sbin/route add -net 10.8.0.1 netmask 255.255.255.255 gw 10.8.0.5
    17:58:53 openvpn[6262]: Initialization Sequence Completed
    18:00:01 root: -- MARK --
    18:01:54 openvpn[6262]: [home_router_server] Inactivity timeout (--ping-restart), restarting
    18:01:54 openvpn[6262]: TCP/UDP: Closing socket
    18:01:54 openvpn[6262]: SIGUSR1[soft,ping-restart] received, process restarting
    18:01:54 openvpn[6262]: Restart pause, 2 second(s)
    18:01:56 openvpn[6262]: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
    18:01:56 openvpn[6262]: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
    18:01:56 openvpn[6262]: Re-using SSL/TLS context
    18:01:56 openvpn[6262]: LZO compression initialized
    18:01:56 openvpn[6262]: Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
    18:01:56 openvpn[6262]: Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
    18:01:56 openvpn[6262]: Socket Buffers: R=[114688->131072] S=[114688->131072]
    18:01:56 openvpn[6262]: UDPv4 link local: [undef]
    18:01:56 openvpn[6262]: UDPv4 link remote: X.X.X.X:1194
    18:01:56 openvpn[6262]: TLS: Initial packet from X.X.X.X:1194, sid=d964dfb0 b94f4c14
    18:01:56 openvpn[6262]: VERIFY OK: depth=1, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=ThreePegs/name=changeme/emailAddress=info@threepegs.com
    18:01:56 openvpn[6262]: VERIFY OK: depth=0, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=home_router_server/name=changeme/emailAddress=info@threepegs.com
    18:01:56 openvpn[6262]: Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    18:01:56 openvpn[6262]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    18:01:56 openvpn[6262]: Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    18:01:56 openvpn[6262]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    18:01:56 openvpn[6262]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
    18:01:56 openvpn[6262]: [home_router_server] Peer Connection Initiated with X.X.X.X:1194
    18:01:59 openvpn[6262]: SENT CONTROL [home_router_server]: 'PUSH_REQUEST' (status=1)
    18:01:59 openvpn[6262]: PUSH: Received control message: 'PUSH_REPLY,route 192.168.1.0 255.255.255.0,route 10.8.0.1,topology net30,ping 10,ping-restart 180,ifconfig 10.8.0.6 10.8.0.5'
    18:01:59 openvpn[6262]: OPTIONS IMPORT: timers and/or timeouts modified
    18:01:59 openvpn[6262]: OPTIONS IMPORT: --ifconfig/up options modified
    18:01:59 openvpn[6262]: OPTIONS IMPORT: route options modified
    18:01:59 openvpn[6262]: Preserving previous TUN/TAP instance: tun11
    18:01:59 openvpn[6262]: Initialization Sequence Completed


    Server Log



    Code:
    17:58:50 openvpn[2486]: MULTI: multi_create_instance called
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 Re-using SSL/TLS context
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 LZO compression initialized
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 TLS: Initial packet from Y.Y.Y.Y:5701, sid=8781b554 95305a86
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 VERIFY OK: depth=1, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=ThreePegs/name=changeme/emailAddress=info@threepegs.com
    17:58:50 openvpn[2486]: Y.Y.Y.Y:5701 VERIFY OK: depth=0, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=office_router/name=changeme/emailAddress=info@threepegs.com
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
    17:58:51 openvpn[2486]: Y.Y.Y.Y:5701 [office_router] Peer Connection Initiated with Y.Y.Y.Y:5701
    17:58:51 openvpn[2486]: MULTI: new connection by client 'office_router' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
    17:58:51 openvpn[2486]: OPTIONS IMPORT: reading client specific options from: ccd/office_router
    17:58:51 openvpn[2486]: MULTI: Learn: 10.8.0.6 -> office_router/Y.Y.Y.Y:5701
    17:58:51 openvpn[2486]: MULTI: primary virtual IP for office_router/Y.Y.Y.Y:5701: 10.8.0.6
    17:58:51 openvpn[2486]: MULTI: internal route 192.168.2.0/24 -> office_router/Y.Y.Y.Y:5701
    17:58:51 openvpn[2486]: MULTI: Learn: 192.168.2.0/24 -> office_router/Y.Y.Y.Y:5701
    17:58:53 openvpn[2486]: office_router/Y.Y.Y.Y:5701 PUSH: Received control message: 'PUSH_REQUEST'
    17:58:53 openvpn[2486]: office_router/Y.Y.Y.Y:5701 SENT CONTROL [office_router]: 'PUSH_REPLY,route 192.168.1.0 255.255.255.0,route 10.8.0.1,topology net30,ping 10,ping-restart 180,ifconfig 10.8.0.6 10.8.0.5' (status=1)
    17:59:03 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    17:59:13 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    17:59:23 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    17:59:33 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    17:59:43 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    17:59:53 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:01 root: -- MARK --
    18:00:03 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:13 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:23 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:33 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:43 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:00:53 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:03 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:13 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:23 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:34 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:44 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:54 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
    18:01:55 openvpn[2486]: MULTI: multi_create_instance called
    18:01:55 openvpn[2486]: Y.Y.Y.Y:63466 Re-using SSL/TLS context
    18:01:55 openvpn[2486]: Y.Y.Y.Y:63466 LZO compression initialized
    18:01:55 openvpn[2486]: Y.Y.Y.Y:63466 Control Channel MTU parms [ L:1558 D:138 EF:38 EB:0 ET:0 EL:0 ]
    18:01:55 openvpn[2486]: Y.Y.Y.Y:63466 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:135 ET:0 EL:0 AF:3/1 ]
    18:01:55 openvpn[2486]: Y.Y.Y.Y:63466 TLS: Initial packet from Y.Y.Y.Y:63466, sid=87ed5f1d 2928c2ef
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 VERIFY OK: depth=1, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=ThreePegs/name=changeme/emailAddress=info@threepegs.com
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 VERIFY OK: depth=0, /C=HK/ST=HongKong/L=Central/O=ThreePegs/OU=ThreePegs/CN=office_router/name=changeme/emailAddress=info@threepegs.com
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
    18:01:56 openvpn[2486]: Y.Y.Y.Y:63466 [office_router] Peer Connection Initiated with Y.Y.Y.Y:63466
    18:01:56 openvpn[2486]: MULTI: new connection by client 'office_router' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
    18:01:56 openvpn[2486]: OPTIONS IMPORT: reading client specific options from: ccd/office_router
    18:01:56 openvpn[2486]: MULTI: Learn: 10.8.0.6 -> office_router/Y.Y.Y.Y:63466
    18:01:56 openvpn[2486]: MULTI: primary virtual IP for office_router/Y.Y.Y.Y:63466: 10.8.0.6
    18:01:56 openvpn[2486]: MULTI: internal route 192.168.2.0/24 -> office_router/Y.Y.Y.Y:63466
    18:01:56 openvpn[2486]: MULTI: Learn: 192.168.2.0/24 -> office_router/Y.Y.Y.Y:63466
    18:01:58 openvpn[2486]: office_router/Y.Y.Y.Y:63466 PUSH: Received control message: 'PUSH_REQUEST'
    18:01:58 openvpn[2486]: office_router/Y.Y.Y.Y:63466 SENT CONTROL [office_router]: 'PUSH_REPLY,route 192.168.1.0 255.255.255.0,route 10.8.0.1,topology net30,ping 10,ping-restart 180,ifconfig 10.8.0.6 10.8.0.5' (status=1)
    18:02:29 openvpn[2486]: read UDPv4 [ECONNREFUSED]: Connection refused (code=146)
     
  2. alfred

    alfred Networkin' Nut Member

    I am running 7497 also. Site-to-site-OpenVPN works fine.

    I had seen a similar case, but not exactly the same, set UDP Timeout to a higher value may help.

    Check Advance / Countrack/Netfilter page, UDP Timeout settings, increase Unreplied/Assured both ten or twenty seconds more, and see if the problem solved.
     
  3. vpn_brad

    vpn_brad Serious Server Member

    Thanks for the suggestion Alfred, but no change unfortunately. I doubled both timeouts from 30/180 seconds to 60/360 seconds, but the problem remains.

    I ran another test to check the behavior further. I logged onto the client router and ran a continuous ping to the server router (i.e. 192.168.2.1 -> 192.168.1.1). With this ping running, the connection remains up and stable for an indefinite period. Once stopped, the same thing happens though, server will start refusing the client keepalive pings and thus client will reconnect.

    So I guess the question is what is the difference between the keepalive pings being sent by openvpn ("keepalive 15 60") and those that are sent when i type "ping 192.186.1.1" from a console session on the router? Because the latter succeed in keeping the connection alive whereas the former do not.
     
  4. vpn_brad

    vpn_brad Serious Server Member

    Okay, I think I've fixed things. I changed the ping interval from 10s to 1s. So I'm now using "keepalive 1 180". This seems to have fixed the problem. The connection has been up for nearly 24 hours now. I still see hourly "expiring key" messages, but I understand this is normal.

    Cheers
     
  5. alfred

    alfred Networkin' Nut Member

    I have my server config with keepalive 15 60 and UDP Unreplied/Assured timeout with 30/30 that works fine over years.

    Don't understand why you have 2 lines of keepalive 15 60 and keepalive 10 180 in your server config.
     
  6. vpn_brad

    vpn_brad Serious Server Member

    This is the result of the firmware building the config.ovpn at boot time, using it's own inbuilt complied settings plus anything added to the "Custom Configuration" box on the VPN Tunnelling->OpenVPN Server->Server1->Advanced tab. If I have nothing in the custom config, then config.ovpn will only have the "keepalive 15 60" keepalive entry. But when this is the case, I experience the disconnection problem. I presume the second entry supersedes the first if two are present, and I guess this is why the firmware doesn't bother to parse and remove the default entry. You can see the full working serve config below.

    Code:
    # Automatically generated configuration
    daemon
    server 10.8.0.0 255.255.255.0
    proto udp
    port 1194
    dev tun21
    cipher AES-128-CBC
    comp-lzo yes
    keepalive 15 60
    verb 3
    push "route 192.168.1.0 255.255.255.0"
    client-config-dir ccd
    ccd-exclusive
    route 192.168.2.0 255.255.255.0
    ca ca.crt
    dh dh.pem
    cert server.crt
    key server.key
    status-version 2
    status status
     
    # Custom Configuration
    keepalive 1 180
    verb 5
     

Share This Page