Forward to list, having replied directly to Bob in error.
-------- Original Message -------- Subject: Re: OpenVPN doesn't restart after sleep Date: Thu, 16 Apr 2015 15:10:29 +0200 From: Tony van der Hoff <t...@vanderhoff.org> To: Bob Proulx <b...@proulx.com> Thanks for your reply, Bob. I have now risen from my sick-bed, and can once again make some sensible judgements! Thanks for your patience. On 03/04/15 00:11, Bob Proulx wrote: > Tony van der Hoff wrote: >> I have OpenVPN on my KDE Wheezy laptop configured to connect to my >> wheezy VPS. When booting from scratch this works fine. > > Works for me too. Note that I am not using KDE however. Doesn't seem > like that should matter. Unless you are using some KDE specific > network something. > Hmm, I am using KDE network Manager (V0.9.0.3) but am unaware of any problems with it. >> However, if I close the lid, thus putting the lappie into sleep mode, >> then re-open it, OpenVPN appears to start, but I'm unable to access any >> address outside of my local network, until I run <sudo service openvpn >> restart>. > > You say "address" which sounds promising that you are actually talking > about addresses explicitly. But most people confuse names and > addresses and mix them up in conversation. > I meant 'addresses' <ping 8.8.8.8> gives 100% packet loss. <ping router> or <ping 192.168.1.1> succeed as expected, so networking is up. > Do you have a caching nameserver installed? bind9 or other? Does > restarting just bind9 also solve the problem? > No name server on this laptop. > When using a vpn you are also very likely using private resources > behind that vpn. No, my setup is extremely simple. My only reason for using VPN is to defeat geolocation filters. I use no resources on the remote host. It does run a nameserver, but only for a subdomain, which I'm not trying to access. > If a ping to the address succeeds and the DNS lookup fails then you > know the networking is okay. I suspect this to be the problem. > I'm not sure that I fully understand your logic, but no matter, it is the entire network beyond my router that appears unresponsive. I think DNS is a red herring. > Another useful debugging hint is to run this in a text window and > watch the display change. > > watch ip route show > > Or the shortest save the keystrokes typing abbreviation. > > watch ip r > > When the vpn is offline there won't be any routes for the tunnel > devices. After the vpn is established it will register routes > corresponding to the tunnels. Seeing them be dropped and established > is useful for me to see when the tunnels become usable. > The routing table is identical for the failing case and the non-failing one: every 2.0s: ip route show 0.0.0.0/1 via 10.8.0.13 dev tun0 default via 192.168.1.1 dev wlan0 proto static 10.8.0.1 via 10.8.0.13 dev tun0 10.8.0.13 dev tun0 proto kernel scope link src 10.8.0.14 128.0.0.0/1 via 10.8.0.13 dev tun0 169.254.0.0/16 dev wlan0 scope link metric 1000 192.168.1.0/24 dev wlan0 proto kernel scope link src 192.168.1.223 It does not change with time. > Another useful debugging hint is to run this in a window and watch the > log file. > > tail -F /var/log/syslog > > That will display the actions of openvpn daemon as they are logged to > the system log file. Watching that will display what is happening as > it happens. This seems to be the most fruitful approach, but my networking knowledge is severely challenged by the results: Attachment 1: syslog -- After the wake-up from suspend. Attachment 2: syslog2 -- after issuing openvpn restart. Hope they make it through bendel. -- Tony van der Hoff | mailto:t...@vanderhoff.org Ariège, France |
Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> sleep requested (sleeping: no enabled: yes) Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> sleeping or disabling... Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): now unmanaged Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: activated -> unmanaged (reason 'sleeping') [100 10 37] Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): deactivating device (reason 'sleeping') [37] Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 2007 Apr 16 14:51:04 tony-lt kernel: [327812.194614] wlan0: deauthenticating from 00:19:70:3a:d5:9d by local choice (reason=3) Apr 16 14:51:04 tony-lt kernel: [327812.234650] cfg80211: Calling CRDA to update world regulatory domain Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): cleaning up... Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (wlan0): taking down device. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Withdrawing address record for 192.168.1.223 on wlan0. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.223. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Interface wlan0.IPv4 no longer relevant for mDNS. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Interface wlan0.IPv6 no longer relevant for mDNS. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::e60:76ff:fe6c:e66f. Apr 16 14:51:04 tony-lt avahi-daemon[2492]: Withdrawing address record for fe80::e60:76ff:fe6c:e66f on wlan0. Apr 16 14:51:04 tony-lt kernel: [327812.274502] cfg80211: World regulatory domain updated: Apr 16 14:51:04 tony-lt kernel: [327812.274507] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Apr 16 14:51:04 tony-lt kernel: [327812.274510] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274513] cfg80211: (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274516] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274518] cfg80211: (5170000 KHz - 5250000 KHz @ 160000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274521] cfg80211: (5250000 KHz - 5330000 KHz @ 160000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274523] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274525] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm) Apr 16 14:51:04 tony-lt kernel: [327812.274528] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm) Apr 16 14:51:04 tony-lt dbus[2367]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (eth0): now unmanaged Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (eth0): device state change: unavailable -> unmanaged (reason 'sleeping') [20 10 37] Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (eth0): cleaning up... Apr 16 14:51:04 tony-lt NetworkManager[2536]: <info> (eth0): taking down device. Apr 16 14:51:04 tony-lt dbus[2367]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Apr 16 14:51:05 tony-lt anacron[5006]: Anacron 2.3 started on 2015-04-16 Apr 16 14:51:05 tony-lt anacron[5006]: Normal exit (0 jobs run) Apr 16 14:51:05 tony-lt ntpd[26036]: Deleting interface #39 wlan0, fe80::e60:76ff:fe6c:e66f#123, interface stats: received=0, sent=0, dropped=0, active_time=2916 secs Apr 16 14:51:05 tony-lt ntpd[26036]: Deleting interface #38 wlan0, 192.168.1.223#123, interface stats: received=3, sent=7, dropped=0, active_time=2916 secs Apr 16 14:51:05 tony-lt ntpd[26036]: peers refreshed Apr 16 14:51:06 tony-lt kernel: [327814.093878] PM: Syncing filesystems ... done. Apr 16 14:51:06 tony-lt kernel: [327814.112280] PM: Preparing system for mem sleep Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: The canary thread is apparently starving. Taking action. Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: Demoting known real-time threads. Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: Successfully demoted thread 4778 of process 4762 (/usr/bin/pulseaudio). Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: Successfully demoted thread 4777 of process 4762 (/usr/bin/pulseaudio). Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: Successfully demoted thread 4762 of process 4762 (/usr/bin/pulseaudio). Apr 16 14:51:24 tony-lt rtkit-daemon[4765]: Demoted 3 threads. Apr 16 14:51:24 tony-lt kernel: [327814.188613] Freezing user space processes ... (elapsed 0.01 seconds) done. Apr 16 14:51:24 tony-lt kernel: [327814.204173] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done. Apr 16 14:51:24 tony-lt kernel: [327814.220175] PM: Entering mem sleep Apr 16 14:51:24 tony-lt kernel: [327814.220341] Suspending console(s) (use no_console_suspend to debug) Apr 16 14:51:24 tony-lt kernel: [327814.220889] sd 0:0:0:0: [sda] Synchronizing SCSI cache Apr 16 14:51:24 tony-lt kernel: [327814.221125] sd 0:0:0:0: [sda] Stopping disk Apr 16 14:51:24 tony-lt kernel: [327814.320223] i8042 aux 00:08: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327814.320245] i8042 kbd 00:07: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327814.320380] ACPI handle has no context! Apr 16 14:51:24 tony-lt kernel: [327814.424441] ACPI handle has no context! Apr 16 14:51:24 tony-lt kernel: [327815.276159] radeon 0000:01:05.0: power state changed by ACPI to D3 Apr 16 14:51:24 tony-lt kernel: [327815.276232] PM: suspend of devices complete after 1055.742 msecs Apr 16 14:51:24 tony-lt kernel: [327815.296124] pcieport 0000:00:06.0: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.352181] ohci_hcd 0000:00:13.0: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.360180] ehci_hcd 0000:00:12.2: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.384181] ohci_hcd 0000:00:12.1: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.392181] ohci_hcd 0000:00:12.0: wake-up capability enabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.392277] PM: late suspend of devices complete after 116.040 msecs Apr 16 14:51:24 tony-lt kernel: [327815.392327] ACPI: Preparing to enter system sleep state S3 Apr 16 14:51:24 tony-lt kernel: [327815.434091] PM: Saving platform NVS memory Apr 16 14:51:24 tony-lt kernel: [327815.441462] Disabling non-boot CPUs ... Apr 16 14:51:24 tony-lt kernel: [327815.544176] CPU 1 is now offline Apr 16 14:51:24 tony-lt kernel: [327815.544879] ACPI: Low-level resume complete Apr 16 14:51:24 tony-lt kernel: [327815.544879] PM: Restoring platform NVS memory Apr 16 14:51:24 tony-lt kernel: [327815.544879] Enabling non-boot CPUs ... Apr 16 14:51:24 tony-lt kernel: [327815.544879] Booting Node 0 Processor 1 APIC 0x1 Apr 16 14:51:24 tony-lt kernel: [327815.544879] smpboot cpu 1: start_ip = 9a000 Apr 16 14:51:24 tony-lt kernel: [327815.442904] Calibrating delay loop (skipped) already calibrated this CPU Apr 16 14:51:24 tony-lt kernel: [327815.442904] [Firmware Bug]: cpu 1, try to use APIC500 (LVT offset 0) for vector 0x400, but the register is already in use for vector 0xf9 on another cpu Apr 16 14:51:24 tony-lt kernel: [327815.442904] perf: IBS APIC setup failed on cpu #1 Apr 16 14:51:24 tony-lt kernel: [327815.442904] Switch to broadcast mode on CPU1 Apr 16 14:51:24 tony-lt kernel: [327815.576825] NMI watchdog enabled, takes one hw-pmu counter. Apr 16 14:51:24 tony-lt kernel: [327815.577157] CPU1 is up Apr 16 14:51:24 tony-lt kernel: [327815.578367] ACPI: Waking up from system sleep state S3 Apr 16 14:51:24 tony-lt kernel: [327815.632169] ohci_hcd 0000:00:12.0: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.640169] ohci_hcd 0000:00:12.1: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.664169] ehci_hcd 0000:00:12.2: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.672168] ohci_hcd 0000:00:13.0: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.688577] PM: early resume of devices complete after 62.497 msecs Apr 16 14:51:24 tony-lt kernel: [327815.689051] radeon 0000:01:05.0: power state changed by ACPI to D0 Apr 16 14:51:24 tony-lt kernel: [327815.689058] radeon 0000:01:05.0: power state changed by ACPI to D0 Apr 16 14:51:24 tony-lt kernel: [327815.689062] snd_hda_intel 0000:01:05.1: setting latency timer to 64 Apr 16 14:51:24 tony-lt kernel: [327815.689066] radeon 0000:01:05.0: power state changed by ACPI to D0 Apr 16 14:51:24 tony-lt kernel: [327815.689069] radeon 0000:01:05.0: power state changed by ACPI to D0 Apr 16 14:51:24 tony-lt kernel: [327815.689080] radeon 0000:01:05.0: setting latency timer to 64 Apr 16 14:51:24 tony-lt kernel: [327815.702355] sd 0:0:0:0: [sda] Starting disk Apr 16 14:51:24 tony-lt kernel: [327815.705947] pcieport 0000:00:06.0: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327815.722329] [drm] PCIE GART of 512M enabled (table at 0x00000000C0040000). Apr 16 14:51:24 tony-lt kernel: [327815.722579] radeon 0000:01:05.0: WB enabled Apr 16 14:51:24 tony-lt kernel: [327815.722582] [drm] fence driver on ring 0 use gpu addr 0xa0000c00 and cpu addr 0xffff8800a8310c00 Apr 16 14:51:24 tony-lt kernel: [327815.754508] [drm] ring test on 0 succeeded in 1 usecs Apr 16 14:51:24 tony-lt kernel: [327815.754548] [drm] ib test on ring 0 succeeded in 0 usecs Apr 16 14:51:24 tony-lt kernel: [327815.768506] i8042 kbd 00:07: wake-up capability disabled by ACPI Apr 16 14:51:24 tony-lt kernel: [327816.012204] ata3: SATA link down (SStatus 0 SControl 300) Apr 16 14:51:24 tony-lt kernel: [327816.184109] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Apr 16 14:51:24 tony-lt kernel: [327816.256277] ata2.00: configured for UDMA/100 Apr 16 14:51:24 tony-lt kernel: [327818.088113] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Apr 16 14:51:24 tony-lt kernel: [327818.096399] ata1.00: configured for UDMA/100 Apr 16 14:51:24 tony-lt kernel: [327820.928075] usb 1-3: reset high-speed USB device number 7 using ehci_hcd Apr 16 14:51:24 tony-lt kernel: [327824.789190] PM: resume of devices complete after 9100.526 msecs Apr 16 14:51:24 tony-lt kernel: [327824.789539] PM: Finishing wakeup. Apr 16 14:51:24 tony-lt acpid: client 2818[0:0] has disconnected Apr 16 14:51:24 tony-lt kernel: [327824.789541] Restarting tasks ... done. Apr 16 14:51:24 tony-lt kernel: [327824.810067] video LNXVIDEO:00: Restoring backlight state Apr 16 14:51:25 tony-lt anacron[5460]: Anacron 2.3 started on 2015-04-16 Apr 16 14:51:25 tony-lt anacron[5460]: Normal exit (0 jobs run) Apr 16 14:51:26 tony-lt anacron[5594]: Anacron 2.3 started on 2015-04-16 Apr 16 14:51:26 tony-lt anacron[5594]: Normal exit (0 jobs run) Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> wake requested (sleeping: yes enabled: yes) Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> waking up and re-enabling... Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): now managed Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): bringing up device. Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): preparing device. Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): deactivating device (reason 'managed') [2] Apr 16 14:51:26 tony-lt kernel: [327826.444473] ADDRCONF(NETDEV_UP): wlan0: link is not ready Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (eth0): now managed Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (eth0): bringing up device. Apr 16 14:51:26 tony-lt kernel: [327826.455804] r8169 0000:09:00.0: eth0: link down Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (eth0): preparing device. Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (eth0): deactivating device (reason 'managed') [2] Apr 16 14:51:26 tony-lt kernel: [327826.457038] ADDRCONF(NETDEV_UP): eth0: link is not ready Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: starting -> ready Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42] Apr 16 14:51:26 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: ready -> inactive Apr 16 14:51:26 tony-lt NetworkManager[2536]: <warn> Trying to remove a non-existant call id. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Auto-activating connection 'Livebox-2e43'. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) starting connection 'Livebox-2e43' Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0/wireless): access point 'Livebox-2e43' has security, but secrets are required. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: config -> need-auth (reason 'none') [50 60 0] Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: need-auth -> prepare (reason 'none') [60 40 0] Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting... Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0] Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0/wireless): connection 'Livebox-2e43' has security, and secrets exist. No new secrets needed. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Config: added 'ssid' value 'Livebox-2e43' Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Config: added 'scan_ssid' value '1' Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Config: added 'key_mgmt' value 'WPA-PSK' Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Config: added 'psk' value '<omitted>' Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete. Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> Config: set interface ap_scan to 1 Apr 16 14:51:27 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: inactive -> scanning Apr 16 14:51:28 tony-lt wpa_supplicant[2663]: wlan0: SME: Trying to authenticate with 00:19:70:3a:d5:9d (SSID='Livebox-2e43' freq=2412 MHz) Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: scanning -> authenticating Apr 16 14:51:28 tony-lt kernel: [327828.388014] wlan0: authenticate with 00:19:70:3a:d5:9d (try 1) Apr 16 14:51:28 tony-lt wpa_supplicant[2663]: wlan0: Trying to associate with 00:19:70:3a:d5:9d (SSID='Livebox-2e43' freq=2412 MHz) Apr 16 14:51:28 tony-lt kernel: [327828.390755] wlan0: authenticated Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: authenticating -> associating Apr 16 14:51:28 tony-lt kernel: [327828.415666] wlan0: associate with 00:19:70:3a:d5:9d (try 1) Apr 16 14:51:28 tony-lt kernel: [327828.420624] wlan0: RX AssocResp from 00:19:70:3a:d5:9d (capab=0x431 status=0 aid=3) Apr 16 14:51:28 tony-lt kernel: [327828.420628] wlan0: associated Apr 16 14:51:28 tony-lt wpa_supplicant[2663]: wlan0: Associated with 00:19:70:3a:d5:9d Apr 16 14:51:28 tony-lt kernel: [327828.448913] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready Apr 16 14:51:28 tony-lt kernel: [327828.450344] cfg80211: Calling CRDA for country: FR Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake Apr 16 14:51:28 tony-lt wpa_supplicant[2663]: wlan0: WPA: Key negotiation completed with 00:19:70:3a:d5:9d [PTK=CCMP GTK=TKIP] Apr 16 14:51:28 tony-lt wpa_supplicant[2663]: wlan0: CTRL-EVENT-CONNECTED - Connection to 00:19:70:3a:d5:9d completed (auth) [id=0 id_str=] Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'Livebox-2e43'. Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled. Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started... Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0] Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds) Apr 16 14:51:28 tony-lt kernel: [327828.466330] cfg80211: Regulatory domain changed to country: FR Apr 16 14:51:28 tony-lt kernel: [327828.466334] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) Apr 16 14:51:28 tony-lt kernel: [327828.466338] cfg80211: (2402000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm) Apr 16 14:51:28 tony-lt kernel: [327828.466341] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz), (N/A, 2000 mBm) Apr 16 14:51:28 tony-lt kernel: [327828.466343] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz), (N/A, 2000 mBm) Apr 16 14:51:28 tony-lt kernel: [327828.466345] cfg80211: (5490000 KHz - 5710000 KHz @ 80000 KHz), (N/A, 2700 mBm) Apr 16 14:51:28 tony-lt kernel: [327828.466348] cfg80211: (57240000 KHz - 65880000 KHz @ 2160000 KHz), (N/A, 4000 mBm) Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> dhclient started with pid 6188 Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete. Apr 16 14:51:28 tony-lt dhclient: Internet Systems Consortium DHCP Client 4.2.2 Apr 16 14:51:28 tony-lt dhclient: Copyright 2004-2011 Internet Systems Consortium. Apr 16 14:51:28 tony-lt dhclient: All rights reserved. Apr 16 14:51:28 tony-lt dhclient: For info, please visit https://www.isc.org/software/dhcp/ Apr 16 14:51:28 tony-lt dhclient: Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): DHCPv4 state changed nbi -> preinit Apr 16 14:51:28 tony-lt dhclient: Listening on LPF/wlan0/0c:60:76:6c:e6:6f Apr 16 14:51:28 tony-lt dhclient: Sending on LPF/wlan0/0c:60:76:6c:e6:6f Apr 16 14:51:28 tony-lt dhclient: Sending on Socket/fallback Apr 16 14:51:28 tony-lt dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67 Apr 16 14:51:28 tony-lt dhclient: DHCPACK from 192.168.1.1 Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> (wlan0): DHCPv4 state changed preinit -> reboot Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> address 192.168.1.223 Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> prefix 24 (255.255.255.0) Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> gateway 192.168.1.1 Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> nameserver '192.168.1.1' Apr 16 14:51:28 tony-lt NetworkManager[2536]: nm_ip4_config_add_nameserver: assertion `nameserver != s' failed Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> nameserver '192.168.1.1' Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> domain name 'home' Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Configure Commit) scheduled... Apr 16 14:51:28 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) started... Apr 16 14:51:28 tony-lt avahi-daemon[2492]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.223. Apr 16 14:51:28 tony-lt avahi-daemon[2492]: New relevant interface wlan0.IPv4 for mDNS. Apr 16 14:51:28 tony-lt avahi-daemon[2492]: Registering new address record for 192.168.1.223 on wlan0.IPv4. Apr 16 14:51:28 tony-lt dhclient: bound to 192.168.1.223 -- renewal in 34605 seconds. Apr 16 14:51:29 tony-lt acpid: client connected from 2818[0:0] Apr 16 14:51:29 tony-lt acpid: 1 client rule loaded Apr 16 14:51:29 tony-lt NetworkManager[2536]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0] Apr 16 14:51:29 tony-lt NetworkManager[2536]: <info> Policy set 'Livebox-2e43' (wlan0) as default for IPv4 routing and DNS. Apr 16 14:51:29 tony-lt NetworkManager[2536]: <info> Activation (wlan0) successful, device activated. Apr 16 14:51:29 tony-lt dbus[2367]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) Apr 16 14:51:29 tony-lt NetworkManager[2536]: <info> Activation (wlan0) Stage 5 of 5 (IPv4 Commit) complete. Apr 16 14:51:29 tony-lt dbus[2367]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Apr 16 14:51:30 tony-lt ntpdate[6444]: the NTP socket is in use, exiting Apr 16 14:51:30 tony-lt avahi-daemon[2492]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::e60:76ff:fe6c:e66f. Apr 16 14:51:30 tony-lt avahi-daemon[2492]: New relevant interface wlan0.IPv6 for mDNS. Apr 16 14:51:30 tony-lt avahi-daemon[2492]: Registering new address record for fe80::e60:76ff:fe6c:e66f on wlan0.*. Apr 16 14:51:31 tony-lt ntpd[26036]: Listen normally on 41 wlan0 192.168.1.223 UDP 123 Apr 16 14:51:31 tony-lt ntpd[26036]: Listen normally on 42 wlan0 fe80::e60:76ff:fe6c:e66f UDP 123 Apr 16 14:51:31 tony-lt ntpd[26036]: peers refreshed Apr 16 14:51:39 tony-lt kernel: [327839.216125] wlan0: no IPv6 routers present
Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: TCP/UDP: Closing socket Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /sbin/route del -net 10.8.0.1 netmask 255.255.255.255 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: ERROR: Linux route delete command failed: external program exited with error status: 7 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /sbin/route del -net 188.246.204.210 netmask 255.255.255.255 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: ERROR: Linux route delete command failed: external program exited with error status: 7 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /sbin/route del -net 0.0.0.0 netmask 128.0.0.0 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: ERROR: Linux route delete command failed: external program exited with error status: 7 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /sbin/route del -net 128.0.0.0 netmask 128.0.0.0 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: ERROR: Linux route delete command failed: external program exited with error status: 7 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: Closing TUN/TAP interface Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /sbin/ifconfig tun0 0.0.0.0 Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: Linux ip addr del failed: external program exited with error status: 255 Apr 16 14:54:54 tony-lt avahi-daemon[2492]: Withdrawing workstation service for tun0. Apr 16 14:54:54 tony-lt NetworkManager[2536]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/tun0, iface: tun0) Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: /etc/openvpn/update-resolv-conf tun0 1500 1542 10.8.0.14 10.8.0.13 init Apr 16 14:54:54 tony-lt ovpn-tony-lt[3651]: SIGTERM[hard,] received, process exiting Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: OpenVPN 2.2.1 x86_64-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [eurephia] [MH] [PF_INET6] [IPv6 payload 20110424-2 (2.2RC2)] built on Dec 1 2014 Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: LZO compression initialized Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ] Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: Socket Buffers: R=[229376->131072] S=[229376->131072] Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ] Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: Local Options hash (VER=V4): '41690919' Apr 16 14:54:55 tony-lt ovpn-tony-lt[6856]: Expected Remote Options hash (VER=V4): '530fdded' Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: UDPv4 link local: [undef] Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: UDPv4 link remote: [AF_INET]188.246.204.210:1194 Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: TLS: Initial packet from [AF_INET]188.246.204.210:1194, sid=7e040c59 37c423cd Apr 16 14:54:55 tony-lt ntpd[26036]: Deleting interface #40 tun0, 10.8.0.14#123, interface stats: received=31, sent=35, dropped=0, active_time=638 secs Apr 16 14:54:55 tony-lt ntpd[26036]: 178.32.186.153 interface 10.8.0.14 -> (none) Apr 16 14:54:55 tony-lt ntpd[26036]: 178.33.227.201 interface 10.8.0.14 -> (none) Apr 16 14:54:55 tony-lt ntpd[26036]: 195.154.211.37 interface 10.8.0.14 -> (none) Apr 16 14:54:55 tony-lt ntpd[26036]: 37.59.60.67 interface 10.8.0.14 -> (none) Apr 16 14:54:55 tony-lt ntpd[26036]: peers refreshed Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: VERIFY OK: depth=1, /C=UK/ST=BUCKS/L=BUCKINGHAM/O=VANDERHOFF/CN=VANDERHOFF_CA/name=tony/emailAddress=t...@vanderhoff.org Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: VERIFY OK: nsCertType=SERVER Apr 16 14:54:55 tony-lt ovpn-tony-lt[6857]: VERIFY OK: depth=0, /C=UK/ST=BUCKS/L=BUCKINGHAM/O=VANDERHOFF/CN=VANDERHOFF_CA/name=tony/emailAddress=t...@vanderhoff.org Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA Apr 16 14:54:56 tony-lt ovpn-tony-lt[6857]: [VANDERHOFF_CA] Peer Connection Initiated with [AF_INET]188.246.204.210:1194 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: SENT CONTROL [VANDERHOFF_CA]: 'PUSH_REQUEST' (status=1) Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 208.67.222.222,dhcp-option DNS 208.67.220.220,dhcp-option DNS 192.168.1.1,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.14 10.8.0.13' Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: OPTIONS IMPORT: timers and/or timeouts modified Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: OPTIONS IMPORT: --ifconfig/up options modified Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: OPTIONS IMPORT: route options modified Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: ROUTE default_gateway=192.168.1.1 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: TUN/TAP device tun0 opened Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: TUN/TAP TX queue length set to 100 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /sbin/ifconfig tun0 10.8.0.14 pointopoint 10.8.0.13 mtu 1500 Apr 16 14:54:58 tony-lt NetworkManager[2536]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/tun0, iface: tun0) Apr 16 14:54:58 tony-lt NetworkManager[2536]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/tun0, iface: tun0): no ifupdown configuration found. Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /etc/openvpn/update-resolv-conf tun0 1500 1542 10.8.0.14 10.8.0.13 init Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /sbin/route add -net 188.246.204.210 netmask 255.255.255.255 gw 192.168.1.1 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /sbin/route add -net 0.0.0.0 netmask 128.0.0.0 gw 10.8.0.13 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /sbin/route add -net 128.0.0.0 netmask 128.0.0.0 gw 10.8.0.13 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: /sbin/route add -net 10.8.0.1 netmask 255.255.255.255 gw 10.8.0.13 Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: GID set to nogroup Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: UID set to nobody Apr 16 14:54:58 tony-lt ovpn-tony-lt[6857]: Initialization Sequence Completed Apr 16 14:54:59 tony-lt ntpd[26036]: Listen normally on 43 tun0 10.8.0.14 UDP 123 Apr 16 14:54:59 tony-lt ntpd[26036]: 37.59.60.67 interface 192.168.1.223 -> 10.8.0.14 Apr 16 14:54:59 tony-lt ntpd[26036]: 195.154.211.37 interface 192.168.1.223 -> 10.8.0.14 Apr 16 14:54:59 tony-lt ntpd[26036]: 178.33.227.201 interface 192.168.1.223 -> 10.8.0.14 Apr 16 14:54:59 tony-lt ntpd[26036]: 178.32.186.153 interface 192.168.1.223 -> 10.8.0.14 Apr 16 14:54:59 tony-lt ntpd[26036]: peers refreshed