Hello,
I am using Chaos Calmer on a tplink-wdr3600 router which connects to the internet through an ADSL modem using pppoe (bridged mode).
I have also setup the router to be an OpenVPN client in order to redirect all traffic to a private VPN service.
This works OK. The problem is when the Internet provider forces a change of my public IP. In this case connectivity is lost, the router cannot ping public ip addresses and the only way to restore this is to restart the openvpn connection (/etc/init.d/openvpn restart).
This seems to be a routing problem but I cannot figure out how to fix it without restarting the openvpn service.
Here is what happens when I stop and start the WAN (pppoe-wan) interface which results in a public IP change:
Fri Jan 5 07:46:47 2018 daemon.info pppd[22923]: Terminating on signal 15
Fri Jan 5 07:46:47 2018 daemon.info pppd[22923]: Connect time 480.5 minutes.
Fri Jan 5 07:46:47 2018 daemon.info pppd[22923]: Sent 63767325 bytes, received 386872459 bytes.
Fri Jan 5 07:46:47 2018 daemon.notice netifd: Network device 'pppoe-wan' link is down
Fri Jan 5 07:46:48 2018 daemon.notice pppd[22923]: Connection terminated.
Fri Jan 5 07:46:48 2018 daemon.info pppd[22923]: Sent PADT
Fri Jan 5 07:46:48 2018 daemon.info pppd[22923]: Exit.
Fri Jan 5 07:46:48 2018 daemon.notice netifd: Interface 'wan' is now down
Fri Jan 5 07:46:48 2018 daemon.warn dnsmasq[28417]: no servers found in /tmp/resolv.conf.auto, will retry
Fri Jan 5 07:46:48 2018 user.notice ddns-scripts[23033]: myddns_ipv4: PID '23033' terminated by 'SIGTERM' at 2018-01-05 07:46
Fri Jan 5 07:46:48 2018 user.notice ddns-scripts[23034]: dynu: PID '23034' terminated by 'SIGTERM' at 2018-01-05 07:46
Fri Jan 5 07:46:52 2018 daemon.notice netifd: Interface 'wan' is setting up now
Fri Jan 5 07:46:52 2018 daemon.info pppd[31225]: Plugin rp-pppoe.so loaded.
Fri Jan 5 07:46:52 2018 daemon.info pppd[31225]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Fri Jan 5 07:46:52 2018 daemon.notice pppd[31225]: pppd 2.4.7 started by root, uid 0
Fri Jan 5 07:46:52 2018 daemon.info pppd[31225]: PPP session is 570
Fri Jan 5 07:46:52 2018 daemon.warn pppd[31225]: Connected to 00:90:1a:a3:fa:ff via interface eth0.2
Fri Jan 5 07:46:52 2018 daemon.info pppd[31225]: Using interface pppoe-wan
Fri Jan 5 07:46:52 2018 daemon.notice pppd[31225]: Connect: pppoe-wan <--> eth0.2
Fri Jan 5 07:46:52 2018 kern.info kernel: [77929.800000] pppoe-wan: renamed from ppp0
Fri Jan 5 07:46:52 2018 daemon.notice pppd[31225]: PAP authentication succeeded
Fri Jan 5 07:46:52 2018 daemon.notice pppd[31225]: peer from calling number 00:90:1A:A3:FA:FF authorized
Fri Jan 5 07:46:53 2018 daemon.notice pppd[31225]: local IP address 176.58.xx.xx
Fri Jan 5 07:46:53 2018 daemon.notice pppd[31225]: remote IP address 62.169.xx.xx
Fri Jan 5 07:46:53 2018 daemon.notice pppd[31225]: primary DNS address 62.169.xx.xx
Fri Jan 5 07:46:53 2018 daemon.notice pppd[31225]: secondary DNS address 212.152.xx.xx
Fri Jan 5 07:46:53 2018 daemon.notice netifd: Network device 'pppoe-wan' link is up
Fri Jan 5 07:46:53 2018 daemon.notice netifd: Interface 'wan' is now up
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: reading /tmp/resolv.conf.auto
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 208.67.222.222#53
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 45.76.95.185#53
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 172.25.4.22#53 for domain intranet.unify.com
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 172.25.4.22#53 for domain global-intra.net
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 172.25.4.22#53 for domain global-ad.net
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using local addresses only for domain lan
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 62.169.xx.xx#53
Fri Jan 5 07:46:53 2018 daemon.info dnsmasq[28417]: using nameserver 212.152.xx/xx#53
Fri Jan 5 07:46:54 2018 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:46:54 2018 daemon.err openvpn(vpnarea)[23302]: write UDPv4: Operation not permitted (code=1)
Fri Jan 5 07:48:03 2018 daemon.notice openvpn(vpnarea)[23302]: TLS: tls_process: killed expiring key
Fri Jan 5 07:48:11 2018 daemon.notice openvpn(vpnarea)[23302]: TLS: soft reset sec=0 bytes=166725872/0 pkts=121976/0
Fri Jan 5 07:48:47 2018 daemon.notice openvpn(vpnarea)[23302]: [VPNArea] Inactivity timeout (--ping-restart), restarting
Fri Jan 5 07:48:47 2018 daemon.notice openvpn(vpnarea)[23302]: TCP/UDP: Closing socket
Fri Jan 5 07:48:47 2018 daemon.notice openvpn(vpnarea)[23302]: SIGUSR1[soft,ping-restart] received, process restarting
Fri Jan 5 07:48:47 2018 daemon.notice openvpn(vpnarea)[23302]: Restart pause, 2 second(s)
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: Re-using SSL/TLS context
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: LZO compression initialized
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: Control Channel MTU parms [ L:1570 D:138 EF:38 EB:0 ET:0 EL:0 ]
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: Socket Buffers: R=[163840->327680] S=[163840->327680]
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: Data Channel MTU parms [ L:1570 D:1450 EF:70 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: UDPv4 link local: [undef]
Fri Jan 5 07:48:49 2018 daemon.notice openvpn(vpnarea)[23302]: UDPv4 link remote: [AF_INET]159.148.xx.xx:443
You can see that after two minutes, the openvpn service picks up the connectivity loss and tries to reconnect but it seems that the server cannot be reached as the initial packet from server is never received.
Here is what should be happening instead (i.e. on /etc/init.d/openvpn start)
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: OpenVPN 2.3.6 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [MH] [IPv6] built on Jul 25 2015
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: LZO compression initialized
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: Control Channel MTU parms [ L:1570 D:138 EF:38 EB:0 ET:0 EL:0 ]
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: Socket Buffers: R=[163840->131072] S=[163840->131072]
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: Data Channel MTU parms [ L:1570 D:1450 EF:70 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: UDPv4 link local: [undef]
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: UDPv4 link remote: [AF_INET]159.148.xx.xx:443
Fri Jan 5 07:52:00 2018 daemon.notice openvpn(vpnarea)[32051]: TLS: Initial packet from [AF_INET]159.148.xx.xx:443, sid=33d7383b 4a6ee272
Fri Jan 5 07:52:00 2018 daemon.warn openvpn(vpnarea)[32051]: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Fri Jan 5 07:52:01 2018 daemon.notice openvpn(vpnarea)[32051]: VERIFY OK: depth=1, C=CH, ST=CH, L=Zurich, O=Offshore Security LTD, OU= , CN=VPNArea, name= , emailAddress=keys@vpnarea.com
Fri Jan 5 07:52:01 2018 daemon.notice openvpn(vpnarea)[32051]: VERIFY OK: nsCertType=SERVER
Fri Jan 5 07:52:01 2018 daemon.notice openvpn(vpnarea)[32051]: VERIFY OK: depth=0, C=CH, ST=CH, L=Zurich, O=Offshore Security LTD, OU= , CN=VPNArea, name= , emailAddress=keys@vpnarea.com
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: Data Channel Encrypt: Using 256 bit message hash 'SHA256' for HMAC authentication
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: Data Channel Decrypt: Using 256 bit message hash 'SHA256' for HMAC authentication
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 4096 bit RSA
Fri Jan 5 07:52:09 2018 daemon.notice openvpn(vpnarea)[32051]: [VPNArea] Peer Connection Initiated with [AF_INET]159.148.xx.xx:443
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: SENT CONTROL [VPNArea]: 'PUSH_REQUEST' (status=1)
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 208.67.220.220,dhcp-option DNS 208.67.222.222,sndbuf 393216,rcvbuf 393216,route 10.186.35.1,topology net30,ping 10,ping-restart 120,ifconfig 10.186.35.6 10.186.35.5'
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: OPTIONS IMPORT: timers and/or timeouts modified
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: Socket Buffers: R=[131072->327680] S=[131072->327680]
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: OPTIONS IMPORT: --ifconfig/up options modified
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: OPTIONS IMPORT: route options modified
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: TUN/TAP device tun0 opened
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: TUN/TAP TX queue length set to 100
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Fri Jan 5 07:52:11 2018 daemon.notice netifd: Interface 'vpnarea' is enabled
Fri Jan 5 07:52:11 2018 daemon.notice netifd: Network device 'tun0' link is up
Fri Jan 5 07:52:11 2018 daemon.notice netifd: Interface 'vpnarea' has link connectivity
Fri Jan 5 07:52:11 2018 daemon.notice netifd: Interface 'vpnarea' is setting up now
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: /sbin/ifconfig tun0 10.186.35.6 pointopoint 10.186.35.5 mtu 1500
Fri Jan 5 07:52:11 2018 daemon.notice netifd: Interface 'vpnarea' is now up
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: /sbin/route add -net 159.148.xx.xx netmask 255.255.255.255 gw 62.169.xx.xx
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: /sbin/route add -net 0.0.0.0 netmask 128.0.0.0 gw 10.186.35.5
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: /sbin/route add -net 128.0.0.0 netmask 128.0.0.0 gw 10.186.35.5
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: /sbin/route add -net 10.186.35.1 netmask 255.255.255.255 gw 10.186.35.5
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: UID set to nobody
Fri Jan 5 07:52:11 2018 daemon.notice openvpn(vpnarea)[32051]: Initialization Sequence Completed
Fri Jan 5 07:52:12 2018 user.notice firewall: Reloading firewall due to ifup of vpnarea (tun0)
Any ideas would be much appreciated
Thanks
(Last edited by thanosz on 5 Jan 2018, 08:28)