[krillin] On airplane mode battery discharge more rapidly than with airplane mode off

[Alberto Pagliarini]

After The last r21 on BQ phone when I enable airplane mode it seems that the phone discharge more rapidly.

As you can see in the image attached I enabled airplane mode at 00:00 (12 midnight) and the battery charge is decreased more than the previously hours with airplane mode switched off.

Easy way to check for the bug:
$ tail -f /var/log/syslog | grep powerd

Then look for acquire/release SysState. It shouldn't happen when flight mode is enabled. When either cellular data or wifi is enable, you should see that at every 5 minutes, as it's the default delta for push-client.

[Pat McGowan (pat-mcgowan)]

I confirmed that the rate jumps up over 3% per hr with flight mode on, the suspends seem reasonable although sepnt a bit less time in suspend - will add the reports

[Ricardo Salveti (rsalveti)]

I'll try to reproduce with my device, but would be nice if any of you guys could upload your /var/log/syslog, as that should easily tell what blocked the suspend.

[Ricardo Salveti (rsalveti)]

It seems there is a bug in the push-client logic here:

Apr 21 15:57:11 ubuntu-phablet kernel: [ 7980.901790]PM: suspend exit 2015-04-21 15:57:11.756043448 UTC
Apr 21 15:57:11 ubuntu-phablet kernel: [ 7980.901836]active wakeup source: EINT wakelock
Apr 21 15:57:12 ubuntu-phablet powerd[930]: worker thread finished waiting for hw alarm
Apr 21 15:57:12 ubuntu-phablet powerd[930]: Emitting wakeup signal
Apr 21 15:57:12 ubuntu-phablet powerd[930]: worker thread is finished working; calling join()
Apr 21 15:57:12 ubuntu-phablet powerd[930]: worker thread is destroyed.
Apr 21 15:57:12 ubuntu-phablet kernel: [ 7981.152869][Ker_PM][request_suspend_state]wakeup (3->0) at 7981069295709 (2015-04-21 15:57:12.007101603 UTC)
Apr 21 15:57:12 ubuntu-phablet powerd[930]: handle_requestSysState from :1.132 - ACTIVE (1)
Apr 21 15:57:12 ubuntu-phablet powerd[930]: name_watch_add: looking for :1.132
Apr 21 15:57:12 ubuntu-phablet powerd[930]: watching :1.132 to see when it disappears on dbus
Apr 21 15:57:12 ubuntu-phablet powerd[930]: libsuspend: acquire_wake_lock: powerd_power_request
Apr 21 15:57:12 ubuntu-phablet powerd[930]: handle_requestSysState - SUCCESS
Apr 21 15:57:12 ubuntu-phablet powerd[930]: Enqueue state change to ACTIVE
Apr 21 15:57:12 ubuntu-phablet powerd[930]: exiting suspend
Apr 21 15:57:12 ubuntu-phablet powerd[930]: libsuspend: exit_suspend.
Apr 21 15:57:12 ubuntu-phablet powerd[930]: Emitting signal for transition to state ACTIVE (1)
Apr 21 15:57:12 ubuntu-phablet powerd[930]: Transition to ACTIVE complete
Apr 21 15:57:12 ubuntu-phablet powerd[930]: libsuspend: release_wake_lock: powerd_power_request
Apr 21 15:58:12 ubuntu-phablet powerd[930]: handle_requestWakeup from :1.132 - ubuntu push client, 1429632192
Apr 21 15:58:12 ubuntu-phablet powerd[930]: void {anonymous}::reset_alarm_clock() found 1 remaining wakeup requests
Apr 21 15:58:12 ubuntu-phablet powerd[930]: setting hardware wakeup time to 2015-04-21 16:03:12 for ubuntu push client
Apr 21 15:58:12 ubuntu-phablet powerd[930]: starting hardware alarm worker thread
Apr 21 15:58:12 ubuntu-phablet powerd[930]: handle_clearSysState from :1.132, cookie: 3e00b5b1-f2e9-490e-aacf-e3c2eaa9d70f
Apr 21 15:58:12 ubuntu-phablet powerd[930]: name_watch_remove: looking for :1.132
Apr 21 15:58:12 ubuntu-phablet powerd[930]: name_watch: ref_count for :1.132 is now 0
Apr 21 15:58:12 ubuntu-phablet powerd[930]: no longer watching :1.132, there are no more requests
Apr 21 15:58:12 ubuntu-phablet powerd[930]: libsuspend: acquire_wake_lock: powerd_power_request
Apr 21 15:58:12 ubuntu-phablet powerd[930]: Enqueue state change to SUSPEND
Apr 21 15:58:12 ubuntu-phablet powerd[930]: libsuspend: prepare_suspend.
Apr 21 15:58:12 ubuntu-phablet powerd[930]: Emitting signal for transition to state SUSPEND (0)
Apr 21 15:58:12 ubuntu-phablet powerd[930]: entering suspend
Apr 21 15:58:12 ubuntu-phablet powerd[930]: libsuspend: enter_suspend.

After flight mode was enabled push-client started to wake the device up at every 5 minutes, causing the battery drain.

[Ricardo Salveti (rsalveti)]

When flight mode was enabled at pat's syslog:
Apr 21 12:00:14 ubuntu-phablet URfkill[1056]: set_soft: Setting WWAN to blocked
Apr 21 12:00:14 ubuntu-phablet NetworkManager[1404]: <info> (/ril_1) modem is now Offline

[Pat McGowan (pat-mcgowan)]

Disabling Wifi and BT directly and the drain stays at normal levels

The flight mode optimization in push client to not enable wakeup does not seem to be working per comments above

[Ricardo Salveti (rsalveti)]

So the issue is that push-client is tracking NM's WirelessEnabled state, and that doesn't get properly updated on krillin/arale when you enable flight mode directly (as when that happens urfkill will use libhybris to disable the interface, making it to disappear completely). The same issue doesn't happen on mako.

To test, just run $ dbus-monitor --system "path='/org/freedesktop/NetworkManager'" and watch the WirelessEnabled changes.

As a workaround, if you first disable wifi and then enable flight mode, it will make push-client happy and nothing will wake up your device.

Reproduced that behavior with image 19 and 21.

[Tony Espy (awe)]

Note, on IRC there was some discussion about the push-client using urfkill for both monitoring FlightMode and the state of the WiFi device, this is possible, but will requires more than a simple DBus signal listener change.

When a urfkill device changes, urfkill sends a "DeviceChanged" signal with the path of the DBus object ( eg. /org/freedesktop/URfkill/0 ). The properties of this device can then be queried using the standard DBus.Properties.GetAll() method.

Of interest in this case would 'type=1' ( WiFi ) and 'soft' property, which indicates whether or not the device is blocked. If FM is enabled, all devices are blocked initially. If the WiFi device was enabled while in FM, another "DeviceChanged" signal would be emitted...

This isn't ideal, but it would work. I will add an enhancement request/bug to urfkill that suggests the addition of BlockIdx and Block signals. This would allow a client to just listen for a 'Block' signal and examine it's 'type' and 'soft' values which is closer to the current signal logic which listens for NM 'WirelessEnabled' PropertyChanged signals.

[Samuele Pedroni (pedronis)]

does the last suggestion work also on mako, or do we need to do yet a different thing there?

from discussion with Pat also it seems maybe we should actually wait for the better urfkill interface

[Tony Espy (awe)]

@Samuele

This approach should work for *all* devices. We're having a sprint next week, and *might* be able to turn around the better urfkill interface ( ie. the Block & BlockIdx signals ), so we might want to wait till next Mon ( the start of our next sprint ) for a decision on this...

[Ricardo Salveti (rsalveti)]

So we're consuming more power when flight mode is enabled because push-client is holding the suspend blocker for more time than when you have a working connection (flight mode disabled) in place.

From logs, with radio on:
 7869 Apr 21 09:15:12 ubuntu-phablet powerd[930]: handle_requestSysState from :1.132 - ACTIVE (1)
 7896 Apr 21 09:15:18 ubuntu-phablet powerd[930]: handle_clearSysState from :1.132, cookie: 2cca2d22-cef5-4f53-bd45-49f04d3dded5

With radio off:
  515 Apr 21 12:15:12 ubuntu-phablet powerd[930]: handle_requestSysState from :1.132 - ACTIVE (1)
  558 Apr 21 12:16:12 ubuntu-phablet powerd[930]: handle_clearSysState from :1.132, cookie: 4a98dd84-ce27-42e6-b7ff-c17089ad301f

So push wakes up the device at every 5 minutes and keeps it awake for an entire 1 minute (probably the timeout for not finding a connection).

[Alberto Pagliarini (batopa)]

Last night I tested again filght mode disabling first wifi and I can confirm that the issue goes away doing that.

Last night battery was at 63%
Turn off wifi
Turn on flight mode
This morning battery charge was 63% yet!

[Tony Espy (awe)]

Note, Samuele asked whether or not the push-client also needs to monitor URKill's DeviceAdded and DeviceRemoved. Note, these might be generated for a WiFi device that's being controlled via hybris.

Also, one other thing that might be useful is creating a urkill script similar to monitor-ofono, which could be used to monitor signals generated by URfkill.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Examining output of "dbus-monitor --system" shows that URfkill is actually emitting signals that can be used by push-client to track the status of the radio devices, for instance:

signal sender=:1.3 -> dest=(null destination) serial=85 path=/org/freedesktop/URfkill/WLAN; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.URfkill.Killswitch"
   array [
      dict entry(
         string "state"
         variant int32 1
      )
   ]
   array [
   ]

These signals are emitted per device category (aka "Killswitch"): WWAN, WLAN, and BLUETOOTH.

The possible values of "state" are:

KILLSWITCH_STATE_UNBLOCKED = 0
KILLSWITCH_STATE_SOFT_BLOCKED = 1
KILLSWITCH_STATE_HARD_BLOCKED = 2

Radio is ON if the state is unblocked, OFF otherwise.

[Samuele Pedroni (pedronis)]

we have a MP up now using the approach proposed in #17

[Launchpad Janitor (janitor)]

This bug was fixed in the package ubuntu-push - 0.64.1+15.04.20150430~rtm-0ubuntu1

---------------
ubuntu-push (0.64.1+15.04.20150430~rtm-0ubuntu1) 14.09; urgency=medium

  [ Samuele Pedroni (Canonical Services Ltd.) ]
  * switch poller to use killswitch state for WLAN instead of misleading
    NM property (fixes lp:1446584) (LP: #1446584)

 -- CI Train Bot <email address hidden> Thu, 30 Apr 2015 14:01:07 +0000

[Samuele Pedroni (pedronis)]

fixed in vivid overlay

147. By CI Train Bot Account on 2015-04-30

    Releasing 0.68+15.04.20150430.1-0ubuntu1

146. By Ricardo Salveti on 2015-04-30

    [ Samuele Pedroni ]
    * switch poller to use killswitch state for WLAN instead of misleading NM property (LP: #1446584)

[Launchpad Janitor (janitor)]

This bug was fixed in the package ubuntu-push - 0.68+15.04.20150430.1-0ubuntu1

---------------
ubuntu-push (0.68+15.04.20150430.1-0ubuntu1) vivid; urgency=medium

  [ Samuele Pedroni ]
  * switch poller to use killswitch state for WLAN instead of
    misleading NM property (LP: #1446584)
  * don't have goroutines from a previous test overlap with the next,
    races gets detected otherwise
  * have the TestDialWorksDirect* tests quickly timeout, go1.3 wants a
    ServerName set in the tls config for them to work
  * fix flaky test
  * support sha384/512 certs, some exercizing of that
  * let send a build number with acceptanceclient
  * add helper to get int out of ConnectMsg Info

  [ CI Train Bot ]
  * New rebuild forced.

ubuntu-push (0.68+15.04.20150403-0ubuntu1) vivid; urgency=medium

  [ Samuele Pedroni ]
  [Roberto Alsina]
  * click-hook: report failure if hooks_path doesn't exist. [client]

  [Bret Barker]
  * add a hacky busy sleep loop to workaround go's sleep not
    accounting for suspended time, more logging (lp:1435109). [client]

  [John R. Lenton]
  * Refactor code maintaining session (better fix for lp:1390663) [client]

  [Samuele Pedroni]
  * just delegate whether there's a update-worthy image to the
    system-settings helper and system-image. [client]
  * stop waking up for polling if in flight-mode and wireless not
    enabled (lp:1437135). [client]
  * don't hold a lock for a long time on handleErrConn, trigger
    autoRedial on Error more actively (lp:1435109). [client]
  * disallow RC4 and SSLv3. [server]

ubuntu-push (0.68+15.04.20150306.2-0ubuntu1) vivid; urgency=medium

  [ John R. Lenton ]
  * Use settings from org.freedesktop.Accounts for silent mode, when to
    vibrate, and default sound. [client] (LP: #1426418, LP: #1427702)

  [ Samuele "Yak Shaver of the Year" Pedroni ]
  * Closing webchecker (avoids leaving goroutines around in testing). [client]
  * WatchSignal cancelling, and connectivity exposed cancelling, make
    connectivity start not leave watches behind (more goroutine
    cleanup). [client]
  * TestTakeTheBusWorks doesn't block anymore, fixed leaking of
    webcheckers. [client]

ubuntu-push (0.67+15.04.20150209-0ubuntu1) vivid; urgency=medium

  [ John R. Lenton ]
  * Updated precommit script. [dev]
  * Include code examples in docs (instead of repeating). [docs]
  * Cleanup and improve logging, and make log messages more
    consistent. [client]
  * Partially work around bug lp:1390663 in a minimally intrusive way
    (real fix will have to wait). [client]
  * Add an explicit check and log message for nil error on webcheck's
    CopyN. [client]

  [ Samuele Pedroni ]
  * Make tests more robust in the face of go 1.3 [client, server]
  * Introduce StartClientAuthFlex for acceptance tests: Start a client
    with auth, take a devId regexp, don't check any client event; support
    connbroken in acceptanceclient. [server]
  * Clean up goroutines in tests. [client]
  * Workaround gc issue with 1.3 and 32 bits. Fixes FTBFS. [client]

  [ Bret Barker ]
  * Add SIGQUIT handler to spit out stack dumps; more logging
    tweaks. [client, server]
  * Log line nums, enabled when logLevel = debug. [client se...