← Back to team overview

ac100 team mailing list archive

unsuccessful resume with binary driver

 


So, I use the nvidia binary driver, as I do gles2 coding in my past time.. and I use standby heavily, but this combo doesn't always resume.

Unsuccessful resume with the binary driver usually exhibits as backlight turning on, some flickering so that it feels it is at least trying, but then a blank screen with nothing working, not even vt switch.

This seems to be more consistent with the new beta driver.
(I don't remember any successful resumes)
With the earlier alpha the success rate was I think around 50%

But I now noticed that it isn't totally frozen, I can ssh in when it's in that state. So I guess it really is just the driver/kernel/gpu not going in to some known good state.

Also, I noticed that in the syslog there are some ec commands logged, I figured it might be helpful for someone who is more familiar with them, so I attached the syslog (trimmed to start from the resume)

And now that I'm going on about suspend, at some point the close lid didn't even suspend reliably, so I sometimes suspended from the menu, but as I was doing that in train just when my stop comes, I'm in a hurry and close the lid anyway, and next time it resumes (succesfully), it goes to suspend immediatelly again, so there is some double standby action going on there.
(and I think I once saw a double modulated standby-led-blink)




For completeness:

The binary xorg/gles2 driver is the new beta one.

scoopr@ac100:~$ lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 11.10
Release:	11.10
Codename:	oneiric

scoopr@ac100:~$ uname -a
Linux ac100 2.6.38-1001-ac100 #1-Ubuntu SMP PREEMPT Thu Oct 20 07:09:13 UTC 2011 armv7l armv7l armv7l GNU/Linux




--
Mikko Lehtonen · scoopr

Dec 19 17:32:44 ac100 bluetoothd[788]: HCI dev 0 down
Dec 19 17:32:44 ac100 bluetoothd[788]: Adapter /org/bluez/788/hci0 has been disabled
Dec 19 17:32:44 ac100 bluetoothd[788]: HCI dev 0 unregistered
Dec 19 17:32:44 ac100 bluetoothd[788]: Stopping hci0 event socket
Dec 19 17:32:44 ac100 bluetoothd[788]: Unregister path: /org/bluez/788/hci0
Dec 19 17:32:44 ac100 kernel: [  948.894034] Tegra cpufreq suspend: setting frequency to 216000 kHz
Dec 19 17:32:44 ac100 kernel: [  948.894156] Freezing user space processes ... (elapsed 0.02 seconds) done.
Dec 19 17:32:44 ac100 kernel: [  948.920639] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Dec 19 17:32:44 ac100 kernel: [  948.940499] PM: Entering mem sleep
Dec 19 17:32:44 ac100 kernel: [  948.940556] Suspending console(s) (use no_console_suspend to debug)
Dec 19 17:32:44 ac100 kernel: [  949.190416] tegradc tegradc.1: suspend
Dec 19 17:32:44 ac100 kernel: [  949.190496] tegradc tegradc.0: suspend
Dec 19 17:32:44 ac100 kernel: [  949.190655] tegra_grhost tegra_grhost: suspending
Dec 19 17:32:44 ac100 kernel: [  949.190852] tegra_grhost tegra_grhost: suspended
Dec 19 17:32:44 ac100 kernel: [  949.204220] tegra_avp_suspend()+
Dec 19 17:32:44 ac100 kernel: [  949.205265] spk event: 4
Dec 19 17:32:44 ac100 kernel: [  949.228491] PM: suspend of devices complete after 286.090 msecs
Dec 19 17:32:44 ac100 kernel: [  949.229801] PM: late suspend of devices complete after 1.261 msecs
Dec 19 17:32:44 ac100 kernel: [  949.247406] Disabling non-boot CPUs ...
Dec 19 17:32:44 ac100 kernel: [  949.390479] IRQ46 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390520] IRQ63 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390553] IRQ70 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390585] IRQ73 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390617] IRQ85 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390657] IRQ129 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.390692] IRQ153 no longer affine to CPU1
Dec 19 17:32:44 ac100 kernel: [  949.391155] CPU1: shutdown
Dec 19 17:32:44 ac100 kernel: [  949.393222] Entering suspend state LP0
Dec 19 17:32:44 ac100 kernel: [  949.393565] Resume caused by WAKE15, Power
Dec 19 17:32:44 ac100 kernel: [  949.393604] Suspended for 2614.020 seconds
Dec 19 17:32:44 ac100 kernel: [  949.394061] Enabling non-boot CPUs ...
Dec 19 17:32:44 ac100 kernel: [  949.411144] CPU1: Booted secondary processor
Dec 19 17:32:44 ac100 kernel: [  949.411247] Calibrating delay loop (skipped) already calibrated this CPU previously.. 
Dec 19 17:32:44 ac100 kernel: [  949.420825] Switched to NOHz mode on CPU #1
Dec 19 17:32:44 ac100 kernel: [  949.553673] CPU1 is up
Dec 19 17:32:44 ac100 kernel: [  949.581961] PM: early resume of devices complete after 0.760 msecs
Dec 19 17:32:44 ac100 kernel: [  949.645099] tegra_avp_resume()+
Dec 19 17:32:44 ac100 kernel: [  949.645343] tegra_grhost tegra_grhost: resuming
Dec 19 17:32:44 ac100 kernel: [  949.645703] tegra_grhost tegra_grhost: resumed
Dec 19 17:32:44 ac100 kernel: [  949.645927] tegradc tegradc.0: resume
Dec 19 17:32:44 ac100 kernel: [  949.646135] tegra_dvfs: rate 216000000 too high for dvfs on disp1
Dec 19 17:32:44 ac100 kernel: [  949.661970] tegradc tegradc.1: resume
Dec 19 17:32:44 ac100 kernel: [  949.911675] usb 1-1: reset high speed USB device using tegra-ehci and address 2
Dec 19 17:32:44 ac100 kernel: [  950.181669] usb 2-1: reset high speed USB device using tegra-ehci and address 2
Dec 19 17:32:44 ac100 kernel: [  950.183784] spk event: 2
Dec 19 17:32:44 ac100 kernel: [  950.410971] usb 1-1.1: reset high speed USB device using tegra-ehci and address 3
Dec 19 17:32:44 ac100 kernel: [  950.601226] usb 1-1.2: reset full speed USB device using tegra-ehci and address 4
Dec 19 17:32:44 ac100 kernel: [  950.772771] btusb 1-1.2:1.0: no reset_resume for driver btusb?
Dec 19 17:32:44 ac100 kernel: [  950.772814] btusb 1-1.2:1.1: no reset_resume for driver btusb?
Dec 19 17:32:44 ac100 kernel: [  950.810976] usb 2-1.2: reset high speed USB device using tegra-ehci and address 3
Dec 19 17:32:44 ac100 kernel: [  951.026448] PM: resume of devices complete after 1444.066 msecs
Dec 19 17:32:44 ac100 kernel: [  951.029659] PM: Finishing wakeup.
Dec 19 17:32:44 ac100 kernel: [  951.029691] Restarting tasks ... done.
Dec 19 17:32:44 ac100 kernel: [  951.143921] Tegra cpufreq resume: restoring frequency to 1000000 kHz
Dec 19 17:32:44 ac100 bluetoothd[788]: HCI dev 0 registered
Dec 19 17:32:44 ac100 bluetoothd[788]: Listening for HCI events on hci0
Dec 19 17:32:44 ac100 bluetoothd[788]: HCI dev 0 up
Dec 19 17:32:44 ac100 bluetoothd[788]: Could not get the contents of DMI chassis type
Dec 19 17:32:44 ac100 bluetoothd[788]: Adapter /org/bluez/788/hci0 has been enabled
Dec 19 17:32:44 ac100 pulseaudio[1199]: [pulseaudio] bluetooth-util.c: Error from RegisterEndpoint reply: org.freedesktop.DBus.Error.UnknownMethod
Dec 19 17:32:45  pulseaudio[1199]: last message repeated 2 times
Dec 19 17:32:45 ac100 bluetoothd[788]: Adapter /org/bluez/788/hci0 has been enabled
Dec 19 17:32:45 ac100 anacron[2228]: Anacron 2.3 started on 2011-12-19
Dec 19 17:32:45 ac100 anacron[2228]: Will run job `cron.monthly' in 15 min.
Dec 19 17:32:45 ac100 anacron[2228]: Jobs will be executed sequentially
Dec 19 17:32:46 ac100 kernel: [  952.731788] init: anacron main process (2228) killed by TERM signal
Dec 19 17:32:46 ac100 kernel: [  952.873228] EXT4-fs (mmcblk0p12): re-mounted. Opts: commit=600
Dec 19 17:32:46 ac100 kernel: [  952.940712] EXT4-fs (mmcblk0p7): re-mounted. Opts: commit=0,commit=600
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> wake requested (sleeping: yes  enabled: yes)
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> waking up and re-enabling...
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> WWAN now enabled by management service
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> (wlan0): now managed
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Dec 19 17:32:46 ac100 NetworkManager[637]: <info> (wlan0): bringing up device.
Dec 19 17:32:47 ac100 NetworkManager[637]: <info> (wlan0): preparing device.
Dec 19 17:32:47 ac100 NetworkManager[637]: <info> (wlan0): deactivating device (reason 'managed') [2]
Dec 19 17:32:47 ac100 kernel: [  953.744613] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Dec 19 17:32:47 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: starting -> ready
Dec 19 17:32:47 ac100 NetworkManager[637]: <info> (wlan0): device state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Dec 19 17:32:47 ac100 kernel: [  953.825054] ieee80211 phy0: device no longer idle - scanning
Dec 19 17:32:47 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: ready -> inactive
Dec 19 17:32:49 ac100 kernel: [  955.910952] ieee80211 phy0: device now idle
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Auto-activating connection 'foobar'.
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) starting connection 'foobar'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> (wlan0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> (wlan0): device state change: prepare -> config (reason 'none') [40 50 0]
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0/wireless): connection 'foobar' has security, and secrets exist.  No new secrets needed.
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: added 'ssid' value 'foobar'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: added 'scan_ssid' value '1'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: added 'key_mgmt' value 'WPA-PSK'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: added 'auth_alg' value 'OPEN'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: added 'psk' value '<omitted>'
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Dec 19 17:32:49 ac100 NetworkManager[637]: <info> Config: set interface ap_scan to 1
Dec 19 17:32:50 ac100 kernel: [  956.510375] ieee80211 phy0: device no longer idle - scanning
Dec 19 17:32:50 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: inactive -> scanning
Dec 19 17:32:51 ac100 wpa_supplicant[768]: Trying to authenticate with 00:24:36:ad:a9:7f (SSID='foobar' freq=2462 MHz)
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: scanning -> authenticating
Dec 19 17:32:51 ac100 kernel: [  958.050845] ieee80211 phy0: device now idle
Dec 19 17:32:51 ac100 kernel: [  958.055353] ieee80211 phy0: device no longer idle - working
Dec 19 17:32:51 ac100 kernel: [  958.110653] wlan0: authenticate with 00:24:36:ad:a9:7f (try 1)
Dec 19 17:32:51 ac100 wpa_supplicant[768]: Trying to associate with 00:24:36:ad:a9:7f (SSID='foobar' freq=2462 MHz)
Dec 19 17:32:51 ac100 kernel: [  958.112707] wlan0: authenticated
Dec 19 17:32:51 ac100 kernel: [  958.112804] ieee80211 phy0: device now idle
Dec 19 17:32:51 ac100 kernel: [  958.170534] ieee80211 phy0: device no longer idle - working
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: authenticating -> associating
Dec 19 17:32:51 ac100 kernel: [  958.210939] wlan0: associate with 00:24:36:ad:a9:7f (try 1)
Dec 19 17:32:51 ac100 kernel: [  958.214246] wlan0: RX AssocResp from 00:24:36:ad:a9:7f (capab=0x431 status=0 aid=3)
Dec 19 17:32:51 ac100 kernel: [  958.214297] wlan0: associated
Dec 19 17:32:51 ac100 kernel: [  958.214373] ieee80211 phy0: Allocated STA 00:24:36:ad:a9:7f
Dec 19 17:32:51 ac100 kernel: [  958.215052] ieee80211 phy0: Inserted STA 00:24:36:ad:a9:7f
Dec 19 17:32:51 ac100 kernel: [  958.215121] ieee80211 phy0: WMM queue=2 aci=0 acm=0 aifs=3 cWmin=15 cWmax=1023 txop=0 uapsd=0
Dec 19 17:32:51 ac100 kernel: [  958.217650] ieee80211 phy0: WMM queue=3 aci=1 acm=0 aifs=7 cWmin=15 cWmax=1023 txop=0 uapsd=0
Dec 19 17:32:51 ac100 kernel: [  958.220276] ieee80211 phy0: WMM queue=1 aci=2 acm=0 aifs=2 cWmin=7 cWmax=15 txop=94 uapsd=0
Dec 19 17:32:51 ac100 kernel: [  958.224657] ieee80211 phy0: WMM queue=0 aci=3 acm=0 aifs=2 cWmin=3 cWmax=7 txop=47 uapsd=0
Dec 19 17:32:51 ac100 wpa_supplicant[768]: Associated with 00:24:36:ad:a9:7f
Dec 19 17:32:51 ac100 kernel: [  958.277182] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Dec 19 17:32:51 ac100 kernel: [  958.278149] cfg80211: Calling CRDA for country: FI
Dec 19 17:32:51 ac100 kernel: [  958.291104] wlan0: dropped frame to 00:24:36:ad:a9:7f (unauthorized port)
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: associating -> 4-way handshake
Dec 19 17:32:51 ac100 wpa_supplicant[768]: WPA: Key negotiation completed with 00:24:36:ad:a9:7f [PTK=CCMP GTK=CCMP]
Dec 19 17:32:51 ac100 wpa_supplicant[768]: CTRL-EVENT-CONNECTED - Connection to 00:24:36:ad:a9:7f completed (auth) [id=0 id_str=]
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> (wlan0): supplicant interface state: 4-way handshake -> completed
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'foobar'.
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> (wlan0): device state change: config -> ip-config (reason 'none') [50 70 0]
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> dhclient started with pid 2393
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0) Beginning IP6 addrconf.
Dec 19 17:32:51 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Dec 19 17:32:52 ac100 dhclient: Internet Systems Consortium DHCP Client 4.1.1-P1
Dec 19 17:32:52 ac100 dhclient: Copyright 2004-2010 Internet Systems Consortium.
Dec 19 17:32:52 ac100 dhclient: All rights reserved.
Dec 19 17:32:52 ac100 dhclient: For info, please visit https://www.isc.org/software/dhcp/
Dec 19 17:32:52 ac100 dhclient: 
Dec 19 17:32:52 ac100 kernel: [  958.446665] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.446728] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.446778] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.446832] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.446877] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.446929] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.446973] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447024] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.447067] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447544] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.447601] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447670] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.447732] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447789] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.447835] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447887] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.447931] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.447990] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448047] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.448110] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448170] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.448236] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448285] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.448338] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448391] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
Dec 19 17:32:52 ac100 kernel: [  958.448447] cfg80211: 2402000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448501] cfg80211: Disabling freq 2484 MHz
Dec 19 17:32:52 ac100 kernel: [  958.448551] cfg80211: Regulatory domain changed to country: FI
Dec 19 17:32:52 ac100 kernel: [  958.448591] cfg80211:     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Dec 19 17:32:52 ac100 kernel: [  958.448649] cfg80211:     (2402000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448695] cfg80211:     (5170000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448758] cfg80211:     (5250000 KHz - 5330000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Dec 19 17:32:52 ac100 kernel: [  958.448810] cfg80211:     (5490000 KHz - 5710000 KHz @ 40000 KHz), (N/A, 2700 mBm)
Dec 19 17:32:52 ac100 NetworkManager[637]: <info> (wlan0): DHCPv4 state changed nbi -> preinit
Dec 19 17:32:52 ac100 dhclient: Listening on LPF/wlan0/6c:62:6d:17:c1:ab
Dec 19 17:32:52 ac100 dhclient: Sending on   LPF/wlan0/6c:62:6d:17:c1:ab
Dec 19 17:32:52 ac100 dhclient: Sending on   Socket/fallback
Dec 19 17:32:52 ac100 dhclient: DHCPREQUEST of 192.168.1.23 on wlan0 to 255.255.255.255 port 67
Dec 19 17:32:52 ac100 dhclient: DHCPACK of 192.168.1.23 from 192.168.1.1
Dec 19 17:32:52 ac100 dhclient: bound to 192.168.1.23 -- renewal in 33288 seconds.
Dec 19 17:32:52 ac100 NetworkManager[637]: <info> (wlan0): DHCPv4 state changed preinit -> reboot
Dec 19 17:32:52 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) scheduled...
Dec 19 17:32:52 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) started...
Dec 19 17:32:52 ac100 NetworkManager[637]: <info>   address 192.168.1.23
Dec 19 17:32:52 ac100 NetworkManager[637]: <info>   prefix 24 (255.255.255.0)
Dec 19 17:32:52 ac100 NetworkManager[637]: <info>   gateway 192.168.1.1
Dec 19 17:32:52 ac100 NetworkManager[637]: <info>   nameserver '192.168.1.1'
Dec 19 17:32:52 ac100 NetworkManager[637]: <info>   domain name 'pp.htv.fi'
Dec 19 17:32:52 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Dec 19 17:32:52 ac100 avahi-daemon[635]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.23.
Dec 19 17:32:52 ac100 avahi-daemon[635]: New relevant interface wlan0.IPv4 for mDNS.
Dec 19 17:32:52 ac100 avahi-daemon[635]: Registering new address record for 192.168.1.23 on wlan0.IPv4.
Dec 19 17:32:53 ac100 avahi-daemon[635]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::6e62:6dff:fe17:c1ab.
Dec 19 17:32:53 ac100 avahi-daemon[635]: New relevant interface wlan0.IPv6 for mDNS.
Dec 19 17:32:53 ac100 avahi-daemon[635]: Registering new address record for fe80::6e62:6dff:fe17:c1ab on wlan0.*.
Dec 19 17:32:53 ac100 NetworkManager[637]: <info> (wlan0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Dec 19 17:32:53 ac100 NetworkManager[637]: <info> Policy set 'foobar' (wlan0) as default for IPv4 routing and DNS.
Dec 19 17:32:53 ac100 NetworkManager[637]: <info> Activation (wlan0) successful, device activated.
Dec 19 17:32:53 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Dec 19 17:32:53 ac100 dbus[615]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Dec 19 17:32:53 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 4 of 5 (IP4 Configure Get) complete.
Dec 19 17:32:53 ac100 dbus[615]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 19 17:32:54 ac100 kernel: [  960.683021] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:32:54 ac100 kernel: [  961.200710] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:32:58 ac100 kernel: [  964.779859] keyboard: can't emulate rawmode for keycode 217
Dec 19 17:32:58 ac100 kernel: [  964.961343] keyboard: can't emulate rawmode for keycode 217
Dec 19 17:32:58 ac100 kernel: [  965.218685] keyboard: can't emulate rawmode for keycode 139
Dec 19 17:32:58 ac100 kernel: [  965.287194] keyboard: can't emulate rawmode for keycode 139
Dec 19 17:32:58 ac100 kernel: [  965.288313] keyboard: can't emulate rawmode for keycode 217
Dec 19 17:32:58 ac100 avahi-daemon[635]: Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::6e62:6dff:fe17:c1ab.
Dec 19 17:32:58 ac100 avahi-daemon[635]: Joining mDNS multicast group on interface wlan0.IPv6 with address 2002:3e4e:8d91:0:6e62:6dff:fe17:c1ab.
Dec 19 17:32:58 ac100 avahi-daemon[635]: Registering new address record for 2002:3e4e:8d91:0:6e62:6dff:fe17:c1ab on wlan0.*.
Dec 19 17:32:58 ac100 avahi-daemon[635]: Withdrawing address record for fe80::6e62:6dff:fe17:c1ab on wlan0.
Dec 19 17:32:58 ac100 NetworkManager[637]: <info> Activation (wlan0) Stage 3 of 5 (IP Configure Start) starting DHCPv6 as requested by IPv6 router...
Dec 19 17:32:58 ac100 NetworkManager[637]: <warn> Failed to add route Object not found
Dec 19 17:32:58 ac100 NetworkManager[637]: <error> [1324308778.939417] [nm-device.c:1784] dhcp6_start(): (wlan0): failed to add IPv6 multicast route: Object not found
Dec 19 17:32:58 ac100 NetworkManager[637]: <info> Activation (wlan0) Beginning DHCPv6 transaction (timeout in 45 seconds)
Dec 19 17:32:58 ac100 NetworkManager[637]: <info> dhclient started with pid 2426
Dec 19 17:32:58 ac100 dhclient: Internet Systems Consortium DHCP Client 4.1.1-P1
Dec 19 17:32:58 ac100 dhclient: Copyright 2004-2010 Internet Systems Consortium.
Dec 19 17:32:58 ac100 dhclient: All rights reserved.
Dec 19 17:32:58 ac100 dhclient: For info, please visit https://www.isc.org/software/dhcp/
Dec 19 17:32:58 ac100 dhclient: 
Dec 19 17:32:59 ac100 dhclient: Bound to *:546
Dec 19 17:32:59 ac100 dhclient: Listening on Socket/wlan0
Dec 19 17:32:59 ac100 dhclient: Sending on   Socket/wlan0
Dec 19 17:32:59 ac100 kernel: [  965.466567] keyboard: can't emulate rawmode for keycode 217
Dec 19 17:32:59 ac100 dhclient: XMT: Info-Request on wlan0, interval 930ms.
Dec 19 17:32:59 ac100 dhclient: RCV: Reply message on wlan0 from fe80::224:36ff:fe9f:9a06.
Dec 19 17:32:59 ac100 NetworkManager[637]: <info> (wlan0): DHCPv6 client pid 2426 exited with status 0
Dec 19 17:32:59 ac100 NetworkManager[637]: <info> (wlan0): DHCPv6 state changed end -> renew6
Dec 19 17:32:59 ac100 NetworkManager[637]: <info>   nameserver '2002:3e4e:8d91:0:224:36ff:fe9f:9a06'
Dec 19 17:32:59 ac100 NetworkManager[637]: <info>   domain search 'pp.htv.fi.'
Dec 19 17:32:59 ac100 NetworkManager[637]: nm_ip6_config_add_nameserver: assertion `IN6_ARE_ADDR_EQUAL (nameserver, &nameservers[i]) == FALSE' failed
Dec 19 17:33:00 ac100 NetworkManager[637]: <info> Policy set 'foobar' (wlan0) as default for IPv4 routing and DNS.
Dec 19 17:33:00 ac100 NetworkManager[637]: <warn> Failed to add route Object exists
Dec 19 17:33:00 ac100 NetworkManager[637]: <info> Policy set 'foobar' (wlan0) as default for IPv6 routing and DNS.
Dec 19 17:33:08 ac100 kernel: [  974.598966] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:33:08 ac100 kernel: [  974.921562] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:33:08 ac100 kernel: [  975.146549] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:33:08 ac100 kernel: [  975.351866] ec system event c5 04 00 00 80 00                                ......
Dec 19 17:32:57 ac100 ntpdate[2437]: step time server 91.189.94.4 offset -15.658233 sec

Follow ups