Bug 17861

Summary: Постоянные сегфолты при обработке эвентов
Product: Sisyphus Reporter: Sir Raorn <raorn>
Component: powersaveAssignee: Damir Shayhutdinov <damir>
Status: CLOSED FIXED QA Contact: qa-sisyphus
Severity: blocker    
Priority: P2 CC: damir
Version: unstable   
Hardware: all   
OS: Linux   
Bug Depends on:    
Bug Blocks: 17727    

Description Sir Raorn 2008-11-12 03:11:47 MSK
Достал scripts/thinkpad_acpi_events из 0.14.0, положил в /usr/lib/powersave/scripts, прописал EVENT_OTHER="thinkpad_acpi_events".  При нажатии на Fn+F5 получаю:

Nov 12 03:01:46 centaurus acpid: received event "ibm/hotkey HKEY 00000080 00001005" 
Nov 12 03:01:46 centaurus acpid: notifying client 9314[0:0] 
Nov 12 03:01:46 centaurus acpid: notifying client 5480[104:114] 
Nov 12 03:01:46 centaurus acpid: completed event "ibm/hotkey HKEY 00000080 00001005" 
Nov 12 03:01:46 centaurus kernel: powersaved[9314]: segfault at a3a57331 ip b7e309ec sp bf84be2c error 4 in libdbus-1.so.3.4.0[b7e09000+35000]
Nov 12 03:01:46 centaurus kernel: usb 3-1: USB disconnect, address 6

restart, Fn+F5:

Nov 12 03:02:14 centaurus acpid: received event "ibm/hotkey HKEY 00000080 00001005" 
Nov 12 03:02:14 centaurus acpid: notifying client 9483[0:0] 
Nov 12 03:02:14 centaurus acpid: notifying client 5480[104:114] 
Nov 12 03:02:14 centaurus acpid: completed event "ibm/hotkey HKEY 00000080 00001005" 
Nov 12 03:02:14 centaurus kernel: powersaved[9483]: segfault at a3a57331 ip b7f329ec sp bff4e52c error 4 in libdbus-1.so.3.4.0[b7f0b000+35000]
Nov 12 03:02:15 centaurus kernel: usb 3-1: new full speed USB device using uhci_hcd and address 7

Из старого:

# bzgrep -B1 'powersaved.*segfault' /var/log/syslog/messages.1.bz2 
Nov  2 17:40:44 centaurus acpid: completed event "battery BAT0 00000080 00000001" 
Nov  2 17:42:11 centaurus kernel: powersaved[5674]: segfault at 7b6e406a ip b7e359ec sp bfa4d05c error 4 in libdbus-1.so.3.4.0[b7e0e000+35000]

Оно явно пытается пихать всякую фигню в libdbus.
Comment 1 Sir Raorn 2008-11-14 02:15:00 MSK
-d 31:

Nov 14 02:11:03 centaurus acpid: completed event "ibm/hotkey HKEY 00000080 00001005" 
Nov 14 02:11:03 centaurus powersaved[13025]: DIAG (handleHWEventRequest:158) ACPI Event: 'ibm/hotkey HKEY 00000080 00001005'
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (handleHWEventRequest:170) type: ibm/hotkey, dev_name: HKEY, port: 00000080, count: 00001005
Nov 14 02:11:03 centaurus powersaved[13025]: DIAG (handleHWEventRequest:241) unknown HW event, using [other]. type 'ibm/hotkey' dev_name 'HKEY' port '00000080' count '00001005'
Nov 14 02:11:03 centaurus powersaved[13025]: Info (registerEvent:48) registering event no.'4'
Nov 14 02:11:03 centaurus powersaved[13029]: Info (execute_program:162) Going to execute external action thinkpad_acpi_events
Nov 14 02:11:03 centaurus powersaved[13029]: Info (execute_program:193) Program /usr/lib/powersave/scripts//thinkpad_acpi_events will be executed for event other. Param 1: other,Param 2: scheme_performance
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (filter_function:89) 
Nov 14 02:11:03 centaurus powersaved[13025]: Info (filter_function:147) Received msg: 'NameOwnerChanged' from interface: org.freedesktop.DBus
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (filter_function:148) Obj.path '/org/freedesktop/DBus' from 'org.freedesktop.DBus'
Nov 14 02:11:03 centaurus powersaved[13025]: Info (filter_function:186) Signal from org.freedesktop.DBus with member NameOwnerChanged received
Nov 14 02:11:03 centaurus powersaved[13025]: Info (filter_function:233) Message handled
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (filter_function:89) 
Nov 14 02:11:03 centaurus powersaved[13025]: Info (filter_function:147) Received msg: 'ScriptReturn' from interface: com.novell.powersave.scripts
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (filter_function:148) Obj.path '/com/novell/powersave/scripts' from ':1.96'
Nov 14 02:11:03 centaurus powersaved[13025]: DIAG (filter_function:163) Method sent to Scripts interface
Nov 14 02:11:03 centaurus powersaved[13025]: DIAG (handleScriptsMessage:602) Handling Scripts request
Nov 14 02:11:03 centaurus powersaved[13025]: Debug (handleScriptsMessage:624) Script returned: event id: 4, request: 0, message: '^DL^H^Hl^H^HhJ^H^HЬm╫©'
Nov 14 02:11:03 centaurus powersaved[13025]: Info (checkScriptReturn:168) SCRIPT returned: Name: 'thinkpad_acpi_events', Return value: 0, Comment: '^DL^H^Hl^H^HhJ^H^HЬm╫©'
Nov 14 02:11:03 centaurus powersaved[13025]: Info (checkScriptReturn:187) SCRIPT Event other finished successfully
Nov 14 02:11:03 centaurus powersaved[13025]: Info (sendReply:344) Send error_id 0, 'success'
Nov 14 02:11:03 centaurus kernel: powersaved[13025]: segfault at 2 ip b7eb99ec sp bfbd6abc error 4 in libdbus-1.so.3.4.0[b7e92000+35000]
Comment 2 Sir Raorn 2008-11-14 02:16:41 MSK
Собранное с --enable debug не сегфолтитцо.  В обычной сборке backtrace не видно:

#0  0xb7f449ec in __cxa_pure_virtual () from /usr/lib/libdbus-1.so.3
#1  0xb7f30f85 in __cxa_pure_virtual () from /usr/lib/libdbus-1.so.3
#2  0x0808085f in ?? ()
#3  0x00000f01 in ?? ()

и так далее.
Comment 3 Sir Raorn 2008-11-14 02:51:40 MSK
Дохнет оно в DBus_Server::sendReply(DBusMessage*, int) на вызове dbus_message_append_args().
Comment 4 Sir Raorn 2008-11-17 14:55:45 MSK
backtrace от libdbus:

(gdb) where
#0  0xb7f5e56b in _dbus_first_type_in_signature (str=0x8084a0c, pos=2) at dbus-marshal-basic.c:1461
#1  0xb7f46512 in _dbus_type_reader_get_current_type (reader=0xbfc7a3e8)
    at dbus-marshal-recursive.c:781
#2  0xb7f459df in byteswap_body_helper (reader=0xbfc7a3e8, walk_reader_to_end=1, 
    old_byte_order=50, new_byte_order=108, p=0x0, new_p=0x0) at dbus-marshal-byteswap.c:43
#3  0xb7f45a82 in _dbus_marshal_byteswap (signature=0x8084a0c, signature_start=2, 
    old_byte_order=50, new_byte_order=108, value_str=0x8084a48, value_pos=0)
    at dbus-marshal-byteswap.c:238
#4  0xb7f49920 in _dbus_message_byteswap (message=0x8084a08) at dbus-message.c:121
#5  0xb7f4ba5a in _dbus_message_iter_init_common (message=0x8084a08, real=0xbfc7a504, iter_type=7)
    at dbus-message.c:1711
#6  0xb7f4c460 in dbus_message_iter_init_append (message=0x8084a08, iter=0xbfc7a504)
    at dbus-message.c:2072
#7  0xb7f4b643 in dbus_message_append_args_valist (message=0x8084a08, first_arg_type=113, 
    var_args=0xbfc7a5b8 "ч╔г©") at dbus-message.c:1525
#8  0xb7f4b5bb in dbus_message_append_args (message=0x8084a08, first_arg_type=113)
    at dbus-message.c:1492
#9  0x08063780 in ?? ()
Comment 5 Sir Raorn 2008-11-17 15:56:51 MSK
Проблема в daemon/pm_interface.cpp в функции PM_Interface::handleScriptsMessage():

DBUS_ERROR PM_Interface::handleScriptsMessage(DBusMessage *msg, const string &msg_member)
{
 	char dummy[] = "";
...
		// get the message
		if (!liblazy_dbus_message_get_basic_arg(msg, DBUS_TYPE_STRING, &dummy, 0) < 0) {
			pDebug(DBG_INFO, "Script returned but we could not to get the message."
			       " Continuing anyway...");
			strcpy(dummy, "");
		}

Падать оно перестало когда я поменял char dummy[] на char dummy[1024] (чиста поржать).  В логе всё равно мусор:

Nov 17 15:42:32 centaurus powersaved[11607]: Debug (handleScriptsMessage:624) Script returned: event id: 6, request: 0, message: '4\200^H^H'

Мусор тут потому, что для message надо брать не 0-й, а 2-й аргумент.
Comment 6 Sir Raorn 2008-11-17 17:48:02 MSK
0.15.20-alt3