Bug 521874

Since the udev events on the power_supply subsytem are rare, an obvious fix would be to have devkit-power schedule a 'confirmation' poll of the battery state a few seconds after receiving any udev event.

btw, thanks to Kieran Clancy for pin-pointing the issue in https://bugzilla.redhat.com/show_bug.cgi?id=499948

some more info that might be helpful, I opened 4 terminals and ran each of
these commands

1. devkit-power --monitor-detail
2. sudo udevadm monitor --udev --kernel
3. watch -n1 cat /proc/acpi/battery/BAT1/state
4. watch -n1 cat
/sys/devices/LNXSYSTM\:00/device\:00/ACPI0003\:00/power_supply/ACAD/subsystem/BAT1/status 


Then waited for 100% fully charged battery and removed the ac power

1,2 report events immediately, 1 reports a "fully charged" state, then no further events are reported.

3 continues to report "charging state: charged", until ~10secs later it changes
to "discharging"

4 continues to report "Full", until ~10secs later it changes to "Unknown" and
then "Discharging" ~2 secs after that.

So it seems that devkit-power will have to poll at least 10secs after the udev
event to correctly recognise that the battery is discharging

sorry, 4 should have been:

watch -n1 cat /sys/devices/LNXSYSTM\:00/device\:00/PNP0C0A\:00/power_supply/BAT1/status

(In reply to comment #2)
> 1. devkit-power --monitor-detail
> 2. sudo udevadm monitor --udev --kernel
> 1,2 report events immediately, 1 reports a "fully charged" state, then no
> further events are reported.

DeviceKit-power will only use the events from udev for data, and I'm not keen on adding bodges to work around kernel bugs in DeviceKit-power.  If the BAT1/status value changes, then we should get uevents.

I'll reassign to kernel. Thanks for the excellent debugging.

Cheers, but I just want to emphasize that udev does generate an event when ac is unplugged but it is not registered in BAT1/status ***until ~10 secs later***.

That does seem like a kernel bug, but suppose they fix it so it's <1 sec later, even then DevKit-power may fail to pickup the correct status change, since you have a race-condition after the udev event between DevKit-power reading the status change and the kernel updating it quickly enough.

If the kernel isn't quick enough DevKitpower reads a 'fully charged' status and then ***stops polling***. 

I don't see how the race-condition can be circumvented if DevKitpower stops polling after recieving any 'fully charged' event.

Anyway, maybe I miss some understanding of the chain of events and a kernel patch can fix it, fingers crossed ;)

(In reply to comment #5)
> Cheers, but I just want to emphasize that udev does generate an event when ac
> is unplugged but it is not registered in BAT1/status ***until ~10 secs
> later***.
> 
> That does seem like a kernel bug, but suppose they fix it so it's <1 sec later,
> even then DevKit-power may fail to pickup the correct status change, since you
> have a race-condition after the udev event between DevKit-power reading the
> status change and the kernel updating it quickly enough.

In this case there should be two udev events; one for whatever changes when the AC is first unplugged, and the other for when the status changes some time later.

Also, I could be wrong, but I think the udev messages include the changed parameters so this information can be (and possibly is) used instead of reading sysfs, which avoids any race conditions.

(In reply to comment #6)
> 
> In this case there should be two udev events; one for whatever changes when the
> AC is first unplugged, and the other for when the status changes some time
> later.
> 
> Also, I could be wrong, but I think the udev messages include the changed
> parameters so this information can be (and possibly is) used instead of reading
> sysfs, which avoids any race conditions.  

Yes that would work, if a separate udev event was generated when the status changed. I guess the question is why is a second event necessary, and why is there ~10 seconds lag between the udev event (ac unplugged) and status change (in BAT1/status) to "Discharging" on the Aspire One? On another laptop I tested (Dell Inspiron 1520) the status update is 1-2secs after unplugging, and the problem occurs about 50% of the times I unplug (rather than 100%), so sometimes DevKit gets the correct status.

The udev messages I get immediately after unplugging are not very informative, just four lines (Aspire One):

$ sudo udevadm monitor --udev --kernel
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[1254841530.890138] change   /devices/LNXSYSTM:00/device:00/ACPI0003:00/power_supply/ACAD (power_supply)
UDEV  [1254841530.896647] change   /devices/LNXSYSTM:00/device:00/ACPI0003:00/power_supply/ACAD (power_supply)
KERNEL[1254841531.376662] change   /devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT1 (power_supply)
UDEV  [1254841531.404585] change   /devices/LNXSYSTM:00/device:00/PNP0C0A:00/power_supply/BAT1 (power_supply)


I haven't had a chance to try the 2.6.31 kernel, if I do I'll report if anything has changed. I also hope to be able to try this on a newer Aspire One 531 with 6-cell battery next week.

Although, the second udev event must occur stictly AFTER the status has been updated, otherwise we're just shifting the race condition to the second event!

(So I still feel it would be easier to just ask DeviceKit-power to make at least one further poll 30 secs after any udev event, and then it can stop polling if 'fully charged' is still recorded)

Created attachment 363844 [details]
Annotated udevadm monitor on Compaq CQ61

I am seeing this on a (HP) Compaq CQ61, which I imagine has fairly different hardware to the Aspire One.

I've attached my udevadm monitor log (with full --environment). At first I unplug my AC, then wait a bit in case the system detects the state change (which it didn't). Then I plugged it back in, and waited for it to charge. I unplugged it again after this, but this time Devkit-power continued to poll (perhaps due to 'unknown' state instead of 'full' state) and eventually noticed my battery was discharging (which almost never happens). I plugged AC back in, and waited for it to charge again.

This is all annotated in my attached log file.

For the first sequence (where nothing noticed the battery was discharging), I find it odd that there are two kernel events within a fraction of a second (followed by these being sent by udev), but while both events report ACTION=change, there is no difference in the reported environments.

Comment on attachment 363844 [details]
Annotated udevadm monitor on Compaq CQ61

Oops, can't spell.

I'll take this opportunity to say I agree with you that devkit-power should just do one last 30 second poll as it really wouldn't hurt and would guard against similar issues, but I'm also keen to see this particular bug fixed.

Created attachment 364000 [details]
udev/kernel events after unplugging ac

that --environment flag is useful :)

In my case I can now see that the change event is correctly recorded as POWER_SUPPLY_TYPE=Mains (SEQNUM=1247) changing to POWER_SUPPLY_TYPE=Battery (SEQNUM=1248)

And the POWER_SUPPLY_STATUS=Full for both events, which is logical, since the battery has just been charged why should we expect the fully charged status to change instantly?

I can get the same result on my Dell Inspiron 1520 ~50% of the time, but in 100% of cases the POWER_SUPPLY_TYPE always changes to Battery.

So I think DeviceKit-power should check the POWER_SUPPLY_TYPE before suspending polling. What it currently does is get a (correct) udev event saying power has changed to battery supply, which is fully charged (since I just charged it), and then stops polling, that can't be correct! (It musn't stop polling on battery power)

Kieran Clancy - you have 3 events after unplugging, SEQNUMS 3409,3410 and 3409, and your POWER_SUPPLY_TYPE changes from Battery (3409/3410) to Mains(!) (3411), are you sure you unplugged correctly?

(In reply to comment #11)
> 
> In my case I can now see that the change event is correctly recorded as
> POWER_SUPPLY_TYPE=Mains (SEQNUM=1247) changing to POWER_SUPPLY_TYPE=Battery
> (SEQNUM=1248)

I think you need to differentiate between events on the ACAD power supply and events on the BAT1 supply because they have separate environments. That is, events for the ACAD supply will always have POWER_SUPPLY_TYPE=Mains and events for BAT1 will always have POWER_SUPPLY_TYPE=Battery and this will not change no matter what the state of the power supplies are.

In my interpretation of your log, I see that the AC is unplugged and this is detected reliably for the ACAD supply. However, where your BAT1 supply should change status to discharging, it does not, which is where this bug is.

> And the POWER_SUPPLY_STATUS=Full for both events, which is logical, since the
> battery has just been charged why should we expect the fully charged status to
> change instantly?

It's still fully charged, but we expect the status to change because the battery has begun to discharge a small fraction of a second after the AC is unplugged.

> So I think DeviceKit-power should check the POWER_SUPPLY_TYPE before suspending
> polling. What it currently does is get a (correct) udev event saying power has
> changed to battery supply, which is fully charged (since I just charged it),
> and then stops polling, that can't be correct! (It musn't stop polling on
> battery power)

It is possible that the battery hardware simply does not correctly report its discharging status, and that power management in Windows (which works) relies on the ACAD supply events for reliable information. Indeed, if the battery status only changes (when polling it) ~10 seconds after unplugging, that would mean at least a 10 second delay before anything on the system can respond meaningfully to the change, where Windows reacts instantly to the AC being unplugged.

> Kieran Clancy - you have 3 events after unplugging, SEQNUMS 3409,3410 and 3409,
> and your POWER_SUPPLY_TYPE changes from Battery (3409/3410) to Mains(!) (3411),
> are you sure you unplugged correctly?  

Yes, because 3409/3410 are from a different stream of events to 3411. Neither my ACAD nor my BAT1 supply should change POWER_SUPPLY_TYPE. Mine simply does the same thing yours does but the messages arrive in a different order.

Ah,ok I see now that separate battery (BAT1) and mains (ACAD) events are generated,I think both are generated when there is a change in either one, ie when there is any change on the power_supply subsystem, so the POWER_SUPPLY_TYPE doesn't change.

The important bit is that POWER_SUPPLY_ONLINE for the mains (ACAD) changes correctly from 1 to 0 when the battery is unplugged. That is consistent in my log and yours.

So I'm guessing that any change in the power_supply subsystem generates two events for each supply even if there has been a change in only one power supply type.

In any case, udev correctly tells us that mains POWER_SUPPLY_ONLINE=0 after unplugging, and that should be enough for DeviceKit-power to know not to stop polling.

It looks like you can't rely on the STATUS info for the battery to tell whether it is unplugged or not (not instantly anyway)

(In reply to comment #13)
> Ah,ok I see now that separate battery (BAT1) and mains (ACAD) events are
> generated,I think both are generated when there is a change in either one, ie
> when there is any change on the power_supply subsystem, so the
> POWER_SUPPLY_TYPE doesn't change.

Technically this is a bug. If BAT1 hasn't changed state, the kernel shouldn't be sending events for it. My hunch is that the hardware is sending some kind of message to the kernel, but the kernel is not reacting properly.

> In any case, udev correctly tells us that mains POWER_SUPPLY_ONLINE=0 after
> unplugging, and that should be enough for DeviceKit-power to know not to stop
> polling.
> 
> It looks like you can't rely on the STATUS info for the battery to tell whether
> it is unplugged or not (not instantly anyway)  

Indeed. I personally think devkit-power should be more interested in the AC state than the battery state anyway. However, I think any changes to devkit-power should be in addition to whatever fixes might be needed in the kernel.

Agreed, but as it stands Devkit has the correct info to do the right thing, if it checks POWER_SUPPLY_ONLINE when the udev events are recived.

So I think we have two clear issues (thanks for helping me to understand it)

1. DeviceKit-power relies on STATUS=Full event from the battery to stop polling, which is causing this particular bug.

2. The kernel is generating a change event on the Battery (BAT1 for me) when the only change in the environment is on the mains (ACAD) 

and possibly a further issue is that there are no events when the battery goes from STATUS=Full to STATUS=Discharging, but I'm guessing the kernel/udev guys will say that's not a bug.

And let's not forget that this problem didn't exist prior to the introduction of DeviceKit-power in Fedora 11. (I did mention that in the original bug submitted against gnome-power-manager some months back)

In fact, in Fedora 10 I get exactly the same kernel/udev event log when unplugging ac, but gnome-power-manager responds to the "Discharging" status update after ~10 secs.

This bug appears to have been reported against 'rawhide' during the Fedora 12 development cycle.
Changing version to '12'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

*** Bug 549635 has been marked as a duplicate of this bug. ***

The kernel sends events when they're generated by the hardware - we're not going to try to interpret them and risk losing information that might be useful to userspace, so upower needs to schedule another poll if it sees an event without a corresponding change. The battery and ac drivers are also separate and logically independent, so it's not possible to block the event until the battery state has changed.

From the discussion, it sounds like upower assumes that ac=offline and battery=full is still running on ac? That's also a bug.

This message is a reminder that Fedora 12 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 12.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '12'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 12's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 12 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Fedora 12 changed to end-of-life (EOL) status on 2010-12-02. Fedora 12 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.