Fwd: Re: OpenVPN doesn't restart after sleep
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 <tony@vanderhoff.org>
To: Bob Proulx <bob@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:tony@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=tony@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=tony@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
Reply to: