Bug 146686

Summary: Service acpid seems to die unexpectedly
Product: [openSUSE] SUSE LINUX 10.0 Reporter: Jarom Hatch <jhatch>
Component: BasesystemAssignee: Thomas Renninger <trenn>
Status: RESOLVED WONTFIX QA Contact: E-mail List <qa-bugs>
Severity: Major    
Priority: P5 - None    
Version: Final   
Target Milestone: ---   
Hardware: i686   
OS: SuSE Linux 10.0   
Whiteboard:
Found By: Other Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---

Description Jarom Hatch 2006-01-30 17:12:21 UTC
Since my upgrade from SuSE 9.3 to SuSE 10 I have seen several times when I close the lid of my laptop (IBM Thinkpad T43) that the system does not suspend until I restart the acpid service. I have collected logs that show that the service is not responding.  Here is the log output:

From dmesg:

    ACPI-0304: *** Error: Looking up [SERN] in namespace, AE_ALREADY_EXISTS
    ACPI-0622: *** Warning: During name lookup/catalog, AE_ALREADY_EXISTS
    ACPI-1174: *** Error: Method execution failed [\_SB_.PCI0.LPC_.EC__.GBIF] (Node cfec72c0), AE_ALREADY_EXISTS
    ACPI-1048: *** Warning: Failed to acquire semaphore[cfeb9d00|1|0], AE_TIME
    ACPI-0661: *** Error: Looking up [SERN] in namespace, AE_NOT_FOUND
    ACPI-0622: *** Warning: During name lookup/catalog, AE_NOT_FOUND
    ACPI-1174: *** Error: Method execution failed [\_SB_.PCI0.LPC_.EC__.GBIF] (Node cfec72c0), AE_NOT_FOUND
    ACPI-1174: *** Error: Method execution failed [\_SB_.PCI0.LPC_.EC__.BAT0._BIF] (Node cfec7f40), AE_NOT_FOUND
    ACPI-0147: *** Warning: Error evaluating _BIF

from /var/log/acpid: (note the multiple presses of the lid button that resulted in no action)

[Sun Jan 29 23:48:56 2006] received event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:48:56 2006] notifying client 5839[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5854[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5855[0:0]
[Sun Jan 29 23:48:56 2006] completed event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:48:56 2006] received event "button/lid LID 00000080 00000004"
[Sun Jan 29 23:48:56 2006] notifying client 5839[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5854[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5855[0:0]
[Sun Jan 29 23:48:56 2006] completed event "button/lid LID 00000080 00000004"
[Sun Jan 29 23:48:56 2006] received event "ibm/hotkey HKEY 00000080 00005002"
[Sun Jan 29 23:48:56 2006] notifying client 5839[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5854[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5855[0:0]
[Sun Jan 29 23:48:56 2006] completed event "ibm/hotkey HKEY 00000080 00005002"
[Sun Jan 29 23:48:56 2006] received event "button/lid LID 00000080 00000005"
[Sun Jan 29 23:48:56 2006] notifying client 5839[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5854[0:0]
[Sun Jan 29 23:48:56 2006] notifying client 5855[0:0]
[Sun Jan 29 23:48:56 2006] completed event "button/lid LID 00000080 00000005"
[Sun Jan 29 23:49:31 2006] received event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:49:31 2006] received event "button/lid LID 00000080 00000006"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "button/lid LID 00000080 00000006"
[Sun Jan 29 23:49:31 2006] received event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:49:31 2006] received event "button/lid LID 00000080 00000007"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "button/lid LID 00000080 00000007"
[Sun Jan 29 23:49:31 2006] received event "ibm/hotkey HKEY 00000080 00005002"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "ibm/hotkey HKEY 00000080 00005002"
[Sun Jan 29 23:49:31 2006] received event "button/lid LID 00000080 00000008"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "button/lid LID 00000080 00000008"
[Sun Jan 29 23:49:31 2006] received event "ibm/hotkey HKEY 00000080 00000000"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "ibm/hotkey HKEY 00000080 00000000"
[Sun Jan 29 23:49:31 2006] received event "button/lid LID 00000080 00000009"
[Sun Jan 29 23:49:31 2006] notifying client 5839[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5854[0:0]
[Sun Jan 29 23:49:31 2006] notifying client 5855[0:0]
[Sun Jan 29 23:49:31 2006] completed event "button/lid LID 00000080 00000009"

From /var/log/acpid after restarting acpid service:

[Sun Jan 29 23:51:03 2006] exiting
[Sun Jan 29 23:51:03 2006] starting up
[Sun Jan 29 23:51:03 2006] 0 rules loaded
[Sun Jan 29 23:51:04 2006] client connected from 5839[0:0]
[Sun Jan 29 23:51:04 2006] 1 client rule loaded
[Sun Jan 29 23:51:05 2006] client connected from 5854[0:0]
[Sun Jan 29 23:51:05 2006] 1 client rule loaded
[Sun Jan 29 23:51:06 2006] client connected from 5855[0:0]
[Sun Jan 29 23:51:06 2006] 1 client rule loaded
[Sun Jan 29 23:51:17 2006] received event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:51:17 2006] notifying client 5839[0:0]
[Sun Jan 29 23:51:17 2006] notifying client 5854[0:0]
[Sun Jan 29 23:51:17 2006] notifying client 5855[0:0]
[Sun Jan 29 23:51:17 2006] completed event "ibm/hotkey HKEY 00000080 00005001"
[Sun Jan 29 23:51:17 2006] received event "button/lid LID 00000080 0000000a"
[Sun Jan 29 23:51:17 2006] notifying client 5839[0:0]
[Sun Jan 29 23:51:17 2006] notifying client 5854[0:0]
[Sun Jan 29 23:51:17 2006] notifying client 5855[0:0]
[Sun Jan 29 23:51:17 2006] completed event "button/lid LID 00000080 0000000a"
[Sun Jan 29 23:51:38 2006] received event "processor CPU 00000081 00000000"
[Sun Jan 29 23:51:38 2006] notifying client 5839[0:0]
[Sun Jan 29 23:51:38 2006] notifying client 5854[0:0]
[Sun Jan 29 23:51:38 2006] notifying client 5855[0:0]
[Sun Jan 29 23:51:38 2006] completed event "processor CPU 00000081 00000000"

From /var/log/messages: (during restart of acpid service)

Jan 29 23:51:03 Mithril [powersave]: ERROR (start:449) acpid socket died
Comment 1 Thomas Renninger 2006-01-31 09:54:32 UTC
The first messages are kernel ACPI interpreter messages.
There will come some ACPI patches soon, maybe they fix it.
I will tell you as soon as the patches are in the kernel.

The acpid socket died should not be sever, but normal when restarting the acpid service. Maybe we could suppress the message for update reasons, but this is really minor. Holger, what do you think ...
Comment 2 Holger Macht 2006-01-31 10:16:21 UTC
In newer versions, the message should be more informative, namely that we are trying to reconnect to the acpid socket. Also a message is thrown when the reconnect was successful. I would not supress the message in the update case. This only adds unneeded complexity to the reconnect implementation for something that happens really seldom.
Comment 3 Thomas Renninger 2006-02-03 12:58:27 UTC
Ahh, Ok this is about 10.0, so there won't be fixes for the AE_ALREADY_EXISTS and ACPI semaphore stuff...
You may want to try the latest 10.1 Beta, if you stil see these messages or have any ACPI problems, please reopen.
BTW, there have been acpid YOU updates, are you sure you are running the latest version?