Failure to automatically reconnect to Sugar Ad-hoc network

[greenfeld]

I had an XO-1.5 go into suspend mode on its own due to me not touching it for a while. It was previously connected to the first Sugar Ad-hoc network due to not having any connections defined in connections.cfg.

When the XO resumed later it had forgotten all about the available Wifi networks in the area, and started scanning around, seeing various available networks. But it failed to automatically reconnect to the ad-hoc network for several minutes, even after I kept touchpad input for a few minutes to prevent the system from suspending.

This may be related to powerd/NM interactions like #10366; but then it may not be.

(Logs attached were taken before I manually reconnected.)

[greenfeld]

/var/log/messages file

[greenfeld]

Sugar's shell.log file

[greenfeld]

Actually this could be another case of #10366:

Jun  7 09:02:16 localhost NetworkManager[726]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Jun  7 09:02:16 localhost NetworkManager[726]: <info> (eth0): device state change: 5 -> 7 (reason 0)
Jun  7 09:02:16 localhost NetworkManager[726]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started avahi-autoipd...
Jun  7 09:02:16 localhost NetworkManager[726]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Jun  7 09:02:17 localhost kernel: [   54.599042] PM: Syncing filesystems ... done.
Jun  7 09:06:19 localhost kernel: [   54.607548] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jun  7 09:06:19 localhost avahi-daemon[744]: Registering new address record for fe80::227c:8fff:fe43:8756 on eth0.*.
Jun  7 09:06:19 localhost kernel: [   54.632946] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jun  7 09:06:19 localhost kernel: [   54.653765] dcon_source_switch to DCON
Jun  7 09:06:19 localhost kernel: [   54.696950] olpc-dcon: The DCON has control
Jun  7 09:06:19 localhost kernel: [   54.702070] HDA Intel 0000:00:14.0: PCI INT A disabled
Jun  7 09:06:19 localhost kernel: [   54.707665] ehci_hcd 0000:00:10.4: PCI INT D disabled
Jun  7 09:06:19 localhost kernel: [   54.713094] uhci_hcd 0000:00:10.2: PCI INT C disabled
Jun  7 09:06:19 localhost kernel: [   54.718499] uhci_hcd 0000:00:10.1: PCI INT B disabled
Jun  7 09:06:19 localhost kernel: [   54.723918] uhci_hcd 0000:00:10.0: PCI INT A disabled
Jun  7 09:06:19 localhost kernel: [   54.729344] mmc1:0001:1: suspend: PM flags = 0x3
Jun  7 09:06:19 localhost kernel: [   54.734305] viafb_suspend!
Jun  7 09:06:19 localhost kernel: [   54.737824] viafb 0000:00:01.0: PCI INT A disabled
Jun  7 09:06:19 localhost kernel: [   54.744695] sdhci_reset: slot wakeups enabled
Jun  7 09:06:19 localhost kernel: [   54.760062] sdhci_pci_probe: Enable PME set to 0x103
Jun  7 09:06:19 localhost kernel: [   54.765397] PM: suspend of devices complete after 112.010 msecs
Jun  7 09:06:19 localhost kernel: [   54.850283] PM: late suspend of devices complete after 78.530 msecs
Jun  7 09:06:19 localhost kernel: [   54.857176] ACPI: Preparing to enter system sleep state S3
Jun  7 09:06:19 localhost kernel: [   54.863521] ACPI Error: Found unknown opcode 0x5BFF at AML address b00fc63f offset 0x84, ignoring (20100428/psloop-141)
Jun  7 09:06:19 localhost kernel: [   54.875097] PM: Saving platform NVS memory
Jun  7 09:06:19 localhost kernel: [   54.875097] olpc-pm-1.5: wakeup_source is 'rtc alarm'
Jun  7 09:06:19 localhost kernel: [   54.875097] PM: Restoring platform NVS memory
Jun  7 09:06:19 localhost kernel: [   54.881645] ACPI: Waking up from system sleep state S3
{...}
Jun  7 09:06:19 localhost kernel: [   55.248295] olpc-dcon: The CPU has control
Jun  7 09:06:19 localhost kernel: [   55.430344] PM: resume of devices complete after 378.095 msecs
Jun  7 09:06:19 localhost kernel: [   55.436990] Restarting tasks ... done.
Jun  7 09:06:19 localhost NetworkManager[726]: <info> (eth0): avahi-autoipd timed out.
Jun  7 09:06:19 localhost NetworkManager[726]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) scheduled...
Jun  7 09:06:19 localhost NetworkManager[726]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) started...
Jun  7 09:06:19 localhost NetworkManager[726]: <info> (eth0): device state change: 7 -> 9 (reason 5)
Jun  7 09:06:19 localhost NetworkManager[726]: <warn> Activation (eth0) failed for access point (Ad-hoc Network 1)
Jun  7 09:06:19 localhost NetworkManager[726]: <info> Marking connection 'Ad-hoc Network 1' invalid.
Jun  7 09:06:19 localhost NetworkManager[726]: <warn> Activation (eth0) failed.
Jun  7 09:06:19 localhost NetworkManager[726]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) complete.
Jun  7 09:06:19 localhost NetworkManager[726]: <info> (eth0): device state change: 9 -> 3 (reason 0)
Jun  7 09:06:19 localhost NetworkManager[726]: <info> (eth0): deactivating device (reason: 0).
Jun  7 09:06:21 localhost kernel: [   57.457729] PM: Syncing filesystems ... done.
Jun  7 10:04:55 localhost kernel: [   57.466222] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jun  7 10:04:55 localhost NetworkManager[726]: <info> radio killswitch /sys/devices/virtual/ieee80211/phy0/rfkill1 disappeared
Jun  7 10:04:55 localhost avahi-daemon[744]: Withdrawing address record for fe80::227c:8fff:fe43:8756 on eth0.
Jun  7 10:04:55 localhost avahi-daemon[744]: Withdrawing workstation service for eth0.
Jun  7 10:04:55 localhost kernel: [   57.492946] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
{...}
Jun  7 10:04:55 localhost kernel: [   57.937144] ACPI: Preparing to enter system sleep state S3
Jun  7 10:04:55 localhost kernel: [   57.943479] ACPI Error: Found unknown opcode 0x5BFF at AML address b00fc63f offset 0x84, ignoring (20100428/psloop-141)
Jun  7 10:04:55 localhost kernel: [   57.955042] PM: Saving platform NVS memory
Jun  7 10:04:55 localhost kernel: [   57.955042] olpc-pm-1.5: wakeup_source is 'ec'
Jun  7 10:04:55 localhost kernel: [   57.955042] PM: Restoring platform NVS memory
Jun  7 10:04:55 localhost kernel: [   57.966586] ACPI: Waking up from system sleep state S3
{...}
Jun  7 10:04:55 localhost kernel: [   58.526974] Restarting tasks ... done.
Jun  7 10:04:55 localhost NetworkManager[726]: <info> (eth0): now unmanaged
Jun  7 10:04:55 localhost NetworkManager[726]: <info> (eth0): device state change: 3 -> 1 (reason 36)
Jun  7 10:04:55 localhost NetworkManager[726]: <info> (eth0): cleaning up...
Jun  7 10:04:55 localhost kernel: [   58.899524] mmc1: new SDIO card at address 0001
Jun  7 10:04:57 localhost kernel: [   60.316498] libertas: 20:7c:8f:43:87:56, fw 9.70.7p0, cap 0x000003a3
Jun  7 10:04:57 localhost kernel: [   60.333522] libertas: wlan0: Marvell WLAN 802.11 adapter
Jun  7 10:04:57 localhost NetworkManager[726]: <info> found WiFi radio killswitch rfkill2 (at /sys/devices/virtual/ieee80211/phy1/rfkill2) (driver <unknown>)
Jun  7 10:04:57 localhost kernel: [   60.405139] udev[334]: renamed network interface wlan0 to eth0
Jun  7 10:04:57 localhost NetworkManager[726]: <error> [1307441097.443098] [nm-device-wifi.c:3100] real_update_permanent_hw_address(): (eth0): unable to read permanent MAC address (error 0)
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): driver supports SSID scans (scan_capa 0x01).
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): new 802.11 WiFi device (driver: 'libertas_sdio' ifindex: 3)
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): now managed
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): device state change: 1 -> 2 (reason 2)
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): bringing up device.
Jun  7 10:04:57 localhost kernel: [   60.435106] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): preparing device.
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): deactivating device (reason: 2).
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): supplicant interface state:  starting -> ready
Jun  7 10:04:57 localhost NetworkManager[726]: <info> (eth0): device state change: 2 -> 3 (reason 42)
Jun  7 10:05:38 localhost kernel: [  100.273166] PM: Syncing filesystems ... done.
Jun  7 10:05:38 localhost kernel: [  100.281654] Freezing user space processes ... (elapsed 0.01 seconds) done.
Jun  7 10:05:38 localhost kernel: [  100.302910] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jun  7 10:05:38 localhost kernel: [  100.323812] dcon_source_switch to DCON
Jun  7 10:05:38 localhost kernel: [  100.362071] olpc-dcon: The DCON has control
(No further Network manager messages seen prior to reactivating the Interface manually.)

[greenfeld]

Of note is that Sugar at 1307441157.765927 (Jun 7 10:05:57 2011) logs "DEBUG root: autoconnect Sugar Ad-hoc: already connected", shortly after resuming from suspend at 10:05:38.

But /var/log/messages has us invalidating the Ad-hoc connection at Jun 7 09:06:19 an hour earlier, and iwconfig showed that no network ESSID was defined for eth0. Sugar's frame also showed that no network connection was active with only a gray circle displayed.

Perhaps Sugar is getting confused?

[dsd]

Sugar-0.96 includes a rework here, and is more solid in this respect, so this needs retesting. After a brief test this is working. However, powerd isn't suspending quite right at the moment, so requesting a formal retest now would be a bit early.

[manuq]

Working in os8, the 1.5 is reconnecting to the default ad-hoc network that was previously connected before suspending.

[dsd]

This can be tested in 12.1.0 build 12.

[greenfeld]

I have not seen a XO fail to connect to Ad-hoc lately, although XOs definitely can go into idle suspend prior to establishing a network connection.