[Pkg-libvirt-maintainers] Bug#661029: Bug#661029: libvirt-bin - crash on startup

Thu Feb 23 23:07:24 UTC 2012

On 23/02/12 18:48, Guido Günther wrote:
> Thanks for your report. Could you check tiwh 0.9.10 from experimental? 
> Also check #649435 which points to libudev. Could you also check with 
> valgrind? 

Same thing with 0.9.10. It looks similar to #649435, not sure if it's 
absolutely identical.

I've attached valgrind output.

root at bl-vmhost-s03:/var/tmp# gdb libvirtd
GNU gdb (GDB) 7.3-debian
Copyright (C) 2011 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later 
<http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/libvirtd...Reading symbols from 
/usr/lib/debug/usr/sbin/libvirtd...done.
done.
(gdb) run
Starting program: /usr/sbin/libvirtd
[Thread debugging using libthread_db enabled]
[New Thread 0x7fffef9b8700 (LWP 31178)]
[New Thread 0x7fffef1b7700 (LWP 31179)]
[New Thread 0x7fffee9b6700 (LWP 31180)]
[New Thread 0x7fffee1b5700 (LWP 31181)]
[New Thread 0x7fffed9b4700 (LWP 31182)]
[New Thread 0x7fffed1b3700 (LWP 31183)]
[New Thread 0x7fffec9b2700 (LWP 31184)]
[New Thread 0x7fffec1b1700 (LWP 31185)]
[New Thread 0x7fffeb9b0700 (LWP 31186)]
[New Thread 0x7fffeb1af700 (LWP 31187)]
[New Thread 0x7fffe91cd700 (LWP 31188)]
2012-02-23 22:32:55.412+0000: 31188: info : libvirt version: 0.9.9
2012-02-23 22:32:55.412+0000: 31188: error : udev_set_log_fn:336 : 
custom logging function 0x7fffe91ccaf8 registered

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffe91cd700 (LWP 31188)]
0x00007ffff48440f8 in _IO_vfprintf_internal (s=0x7fffe91cbf60,
format=0x7ffff7353d38 "device %p has devpath '%s'\n", ap=0x7fffe91cc0d0)
at vfprintf.c:1620
1620 vfprintf.c: No such file or directory.
in vfprintf.c
(gdb) bt full
#0 0x00007ffff48440f8 in _IO_vfprintf_internal (s=0x7fffe91cbf60,
format=0x7ffff7353d38 "device %p has devpath '%s'\n", ap=0x7fffe91cc0d0)
at vfprintf.c:1620
len = <optimized out>
string_malloced = <optimized out>
step0_jumps = {0, -15179, -14483, -14390, -14293, -14199, -15032,
-14766, -13119, -13894, -13811, -13241, -12583, -2939, -3410,
-3367, -3217, -3202, -10653, -8358, -2123, -12480, -2322, -2771,
-1385, -1830, -2607, -3126, -3022, -14856}
space = 0
is_short = 0
use_outdigits = 0
step1_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, -13894, -13811, -13241,
-12583, -2939, -3410, -3367, -3217, -3202, -10653, -8358, -2123,
-12480, -2322, -2771, -1385, -1830, -2607, -3126, -3022, 0}
group = 0
prec = <optimized out>
step2_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -13811, -13241, -12583,
-2939, -3410, -3367, -3217, -3202, -10653, -8358, -2123, -12480,
-2322, -2771, -1385, -1830, -2607, -3126, -3022, 0}
string = 0xffffffff <Address 0xffffffff out of bounds>
---Type <return> to continue, or q <return> to quit---
left = 0
is_long_double = 0
width = <optimized out>
step3a_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, -13341, 0, 0, 0, -3410,
-3367, -3217, -3202, -10653, 0, 0, 0, 0, -2771, 0, 0, 0, 0, 0, 0}
alt = 0
showsign = 0
is_long = 0
is_char = 0
pad = <optimized out>
step3b_jumps = {0 <repeats 11 times>, -12583, 0, 0, -3410, -3367,
-3217, -3202, -10653, -8358, -2123, -12480, -2322, -2771, -1385,
-1830, -2607, 0, 0, 0}
step4_jumps = {0 <repeats 14 times>, -3410, -3367, -3217, -3202,
-10653, -8358, -2123, -12480, -2322, -2771, -1385, -1830, -2607, 0,
0, 0}
is_negative = <optimized out>
base = 16
the_arg = {pa_wchar = 1024 L'\000', pa_int = 1024,
pa_long_int = 1024, pa_long_long_int = 1024, pa_u_int = 1024,
pa_u_long_int = 1024, pa_u_long_long_int = 1024,
---Type <return> to continue, or q <return> to quit---
pa_double = 5.0592322134143646e-321,
pa_long_double = <invalid float value>,
pa_string = 0x400 <Address 0x400 out of bounds>,
pa_wstring = 0x400 <Address 0x400 out of bounds>,
pa_pointer = 0x400, pa_user = 0x400}
spec = <optimized out>
_buffer = {__routine = 0x7ffff7349000, __arg = 0x7ffff7dea742,
__canceltype = 5, __prev = 0x0}
_avail = 0
thousands_sep = 0x0
grouping = 0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>
done = 35
f = <optimized out>
lead_str_end = 0x7ffff7353d3f "%p has devpath '%s'\n"
work_buffer = 
"\000\000\000\000\000\000\000\000H�\000��\177\000\000к\034��\177\000\000��\034��\177\000\000@\001\000\000\000\000\000\000x\000\000��\177", 
'\000' <repeats 18 times>, 
"\001\000\000\000\000\000\000\000@�\034��\177\000\000\000B\224��\177\000\000X\206\206��\177\000\000`\236\000��\177\000\000��\034��\177\000\000 
\000\000��\177\000\000@�\034��\177\000\000@�\034��\177\000\000\060�\034��\177\000\000\027\000\000\000\000\000\000\000��\034��\177\000\000\230\---Type 
<return> to continue, or q <return> to quit---
070\225��\177\000\000\027?\204��\177\000\000d\000\000\000\000\000\000\000\005\000\000\000\000\000\000\000@\001\000\000\000\000\000\000�8\225��\177", 
'\000' <repeats 18 times>...
workstart = 0x0
workend = 0x7fffe91cbe18 "\003"
ap_save = {{gp_offset = 48, fp_offset = 48,
overflow_arg_area = 0x7fffe91cc220,
reg_save_area = 0x7fffe91cc130}}
nspecs_done = <optimized out>
save_errno = 22
readonly_format = 0
jump_table = 
"\001\000\000\004\000\016\000\006\000\000\a\002\000\003\t\000\005\b\b\b\b\b\b\b\b\b\000\000\000\000\000\000\000\032\000\031\000\023\023\023\000\035\000\000\f\000\000\000\000\000\000\025\000\000\000\000\022\000\r\000\000\000\000\000\000\032\000\024\017\023\023\023\n\017\034\000\v\030\027\021\026\f\000\025\033\020\000\000\022\000\r"
__PRETTY_FUNCTION__ = "_IO_vfprintf_internal"
#1 0x00007ffff48eca5c in *__GI___vasprintf_chk (result_ptr=0x7fffe91cc0e8,
flags=1, format=0x7ffff7353d38 "device %p has devpath '%s'\n",
args=0x7fffe91cc0d0) at vasprintf_chk.c:68
sf = {_sbf = {_f = {_flags = -72515584,
---Type <return> to continue, or q <return> to quit---
_IO_read_ptr = 0x7fffe400a990 "device 0x7fffe91cc238 has devpath '7 
events=1 cb=0x4d3580 opaque=(nil) ff=(nil)",
_IO_read_end = 0x7fffe400a990 "device 0x7fffe91cc238 has devpath '7 
events=1 cb=0x4d3580 opaque=(nil) ff=(nil)",
_IO_read_base = 0x7fffe400a990 "device 0x7fffe91cc238 has devpath '7 
events=1 cb=0x4d3580 opaque=(nil) ff=(nil)",
_IO_write_base = 0x7fffe400a990 "device 0x7fffe91cc238 has devpath '7 
events=1 cb=0x4d3580 opaque=(nil) ff=(nil)",
_IO_write_ptr = 0x7fffe400a9b3 "7 events=1 cb=0x4d3580 opaque=(nil) 
ff=(nil)", _IO_write_end = 0x7fffe400a9f4 "",
_IO_buf_base = 0x7fffe400a990 "device 0x7fffe91cc238 has devpath '7 
events=1 cb=0x4d3580 opaque=(nil) ff=(nil)",
_IO_buf_end = 0x7fffe400a9f4 "", _IO_save_base = 0x0,
_IO_backup_base = 0x0, _IO_save_end = 0x0, _markers = 0x0,
_chain = 0x0, _fileno = -469762016, _flags2 = 4,
_old_offset = 0, _cur_column = 0, _vtable_offset = 0 '\000',
_shortbuf = "", _lock = 0x0, _offset = 140737295432244,
_codecvt = 0x7fffe91cc190, _wide_data = 0x7ffff4803c60,
_freeres_list = 0x0, _freeres_buf = 0x7ffff480faf8,
_freeres_size = 40, _mode = -1,
_unused2 = "\000\000\000\000��\034��\177\000\000H����\177\000"}, ---Type 
<return> to continue, or q <return> to quit---
vtable = 0x7ffff4b80740}, _s = {
_allocate_buffer = 0x7ffff487a860 <*__GI___libc_malloc>,
_free_buffer = 0x7ffff487a780 <*__GI___libc_free>}}
ret = -1
needed = <optimized out>
#2 0x00007ffff77dfa64 in vasprintf (__ap=<optimized out>,
__fmt=<optimized out>, __ptr=0x7fffe91cc0e8)
at /usr/include/x86_64-linux-gnu/bits/stdio2.h:199
No locals.
#3 virVasprintf (strp=<optimized out>, fmt=<optimized out>,
list=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/util.c:1677
ret = 0
#4 0x00007ffff77d250b in virLogMessage (
category=0x7ffff7353d0a "../libudev/libudev-device.c", priority=4,
funcname=0x7ffff7353fa0 "udev_device_new_from_syspath", linenr=718,
flags=0, fmt=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/logging.c:719
logVersionStderr = true
---Type <return> to continue, or q <return> to quit---
str = 0x0
msg = 0x0
timestamp = 
"\210�\034��\177\000\000�\004���\177\000\000r�\234�\000\000\000\000Ri���"
fprio = <optimized out>
i = <optimized out>
ret = <optimized out>
saved_errno = 22
emit = <optimized out>
ap = {{gp_offset = 48, fp_offset = 48,
overflow_arg_area = 0x7fffe91cc230,
reg_save_area = 0x7fffe91cc130}}
__func__ = "virLogMessage"
#5 0x00007ffff734c53f in udev_log (udev=<optimized out>,
priority=<optimized out>, file=<optimized out>, line=<optimized out>,
fn=<optimized out>, format=<optimized out>) at ../libudev/libudev.c:59
args = {{gp_offset = 48, fp_offset = 48,
overflow_arg_area = 0x7fffe91cc310,
reg_save_area = 0x7fffe91cc250}}
#6 0x00007ffff734eaaa in udev_device_new_from_syspath (udev=0x7fffe40160b0,
syspath=0x50c55c "/sys/devices/virtual/dmi/id")
---Type <return> to continue, or q <return> to quit---
at ../libudev/libudev-device.c:718
len = 4
subdir = 0x50c561 "devices/virtual/dmi/id"
path = 
"/sys/devices/virtual/dmi/id\000�\177\000\000��\034��\177\000\000\000�\034��\177\000\000����", 
'\000' <repeats 12 times>, 
"\001\000\000\000\000\000\000\000��\204��\177\000\000\063\000\000\060\000\000\000\000�\000\000\000�\000\000\000\062\001\000\000M\002\000\000M\002\000\000\062\001\000\000�\000\000\000�\000\000\000\v\000\000\000\000\000\000\000�\000\000\000\000\000\000\000@�\034��\177", 
'\000' <repeats 14 times>, 
"�\000\000\000\062\001\000\000M\002\000\000M\002\000\000\062\001", 
'\000' <repeats 18 times>, 
"\f\000\000\000\000\000\000\000\005\237\210��\177\000\000�\000\000\000�\000\000\000"...
pos = <optimized out>
statbuf = {st_dev = 13, st_ino = 2460, st_nlink = 1, st_mode = 33188,
st_uid = 0, st_gid = 0, __pad0 = 0, st_rdev = 0, st_size = 4096,
st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1330019813,
tv_nsec = 510035900}, st_mtim = {tv_sec = 1330019813,
tv_nsec = 510035900}, st_ctim = {tv_sec = 1330019813,
tv_nsec = 510035900}, __unused = {0, 0, 0}}
udev_device = 0x7fffe4015d30
__FUNCTION__ = "udev_device_new_from_syspath"
#7 0x00000000004d3067 in udevGetDMIData (data=0x7fffe4015c48)
---Type <return> to continue, or q <return> to quit---
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/node_device/node_device_udev.c:1497
udev = 0x7fffe40160b0
device = 0x0
tmp = 0x0
#8 udevSetupSystemDev ()
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/node_device/node_device_udev.c:1586
def = 0x7fffe4016130
dev = 0x0
ret = -1
#9 udevDeviceMonitorStartup (privileged=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/node_device/node_device_udev.c:1697
priv = 0x7fffe4005700
udev = 0x7fffe40160b0
ret = 0
pciret = <optimized out>
__func__ = "udevDeviceMonitorStartup"
__FUNCTION__ = "udevDeviceMonitorStartup"
#10 0x00007ffff784222e in virStateInitialize (privileged=1)
---Type <return> to continue, or q <return> to quit---
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/libvirt.c:852
i = <optimized out>
ret = <optimized out>
__func__ = "virStateInitialize"
#11 0x0000000000424231 in daemonRunStateInit (opaque=0x7613c0)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./daemon/libvirtd.c:1177
srv = 0x7613c0
#12 0x00007ffff77dc972 in virThreadHelper (data=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/threads-pthread.c:157
args = 0x740350
#13 0x00007ffff4f94b50 in start_thread (arg=<optimized out>)
at pthread_create.c:304
__res = <optimized out>
pd = 0x7fffe91cd700
unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737104369408,
-7063858571489737935, 140737488347360, 140737104370112,
140737354125376, 3, 7063878661805540145,
7063838826043376433}, mask_was_saved = 0}}, priv = {pad = {
---Type <return> to continue, or q <return> to quit---
0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0,
canceltype = 0}}}
not_first_call = <optimized out>
freesize = <optimized out>
__PRETTY_FUNCTION__ = "start_thread"
#14 0x00007ffff48d890d in clone ()
at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
No locals.
#15 0x0000000000000000 in ?? ()
No symbol table info available.

The interesting thing is frame #6 - everything looks okay at this point:
#6 0x00007ffff734eaaa in udev_device_new_from_syspath (udev=0x7fffe40160b0,
syspath=0x50c55c "/sys/devices/virtual/dmi/id")
at ../libudev/libudev-device.c:718
718 info(udev, "device %p has devpath '%s'\n", udev_device, 
udev_device_get_devpath(udev_device));
(gdb) p udev_device
$1 = (struct udev_device *) 0x7fffe4015d30
(gdb) p udev_device->devpath
$2 = 0x7fffe4016174 "/devices/virtual/dmi/id"

info(udev,arg) -> udev_log_cond(udev, LOG_INFO, ## arg)
-> udev_log(udev, LOG_INFO, __FILE__, __LINE__, __FUNCTION__, ##arg)

this is frame #5 which is:
va_start(args, format);
udev->log_fn(udev, priority, file, line, fn, format, args);
va_end(args);

next level down is frame #4 as libudev seems to be calling a log 
function registered earlier:
b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/logging.c:719

interestingly this file _also_ calls va_start

Most of the values look fine:
(gdb) p category
$5 = 0x7ffff7353d0a "../libudev/libudev-device.c"
(gdb) p priority
$6 = 4
(gdb) p funcname
$7 = 0x7ffff7353fa0 "udev_device_new_from_syspath"
(gdb) p linenr
$8 = 718
(gdb) p flags
$9 = 0
(gdb) p fmt
$10 = <optimized out>

At which point I'm not sure where to go. I tried changing 
../libudev/libudev-device.c:718 to just use udev_device->devpath 
directory to see if that showed anything up. It does seem to print one 
line out and then breaks. Maybe what we have is a bad interaction in the 
callback?

2012-02-23 23:01:03.609+0000: 8600: info : libvirt version: 0.9.9
2012-02-23 23:01:03.609+0000: 8600: error : udev_set_log_fn:336 : custom 
logging function 0x7fffe91ccaf8 registered

2012-02-23 23:01:03.609+0000: 8600: error : 
udev_device_new_from_syspath:719 : device 0x7fffe91cc238 has devpath 
'(null)'

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffe91cd700 (LWP 8600)]
0x00007ffff48440f8 in _IO_vfprintf_internal (s=0x7fffe91cae00,
format=0x7ffff7353d18 "device %p has devpath '%s'\n", ap=0x7fffe91caf70)
at vfprintf.c:1620
1620 vfprintf.c: No such file or directory.
in vfprintf.c
(gdb) bt
#0 0x00007ffff48440f8 in _IO_vfprintf_internal (s=0x7fffe91cae00,
format=0x7ffff7353d18 "device %p has devpath '%s'\n", ap=0x7fffe91caf70)
at vfprintf.c:1620
#1 0x00007ffff48eca5c in *__GI___vasprintf_chk (result_ptr=0x7fffe91caf88,
flags=1, format=0x7ffff7353d18 "device %p has devpath '%s'\n",
args=0x7fffe91caf70) at vasprintf_chk.c:68
#2 0x00007ffff77dfa64 in vasprintf (__ap=<optimized out>,
__fmt=<optimized out>, __ptr=0x7fffe91caf88)
at /usr/include/x86_64-linux-gnu/bits/stdio2.h:199
#3 virVasprintf (strp=<optimized out>, fmt=<optimized out>,
list=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/util.c:1677
#4 0x00007ffff77d250b in virLogMessage (
category=0x7ffff7353cea "../libudev/libudev-device.c", priority=4,
funcname=0x7ffff7353f80 "udev_device_new_from_syspath", linenr=719,
flags=0, fmt=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/logging.c:719
#5 0x00007ffff734c53f in udev_log (udev=<optimized out>,
priority=<optimized out>, file=<optimized out>, line=<optimized out>,
---Type <return> to continue, or q <return> to quit---
fn=<optimized out>, format=<optimized out>) at ../libudev/libudev.c:59
#6 0x00007ffff734eaa6 in udev_device_new_from_syspath (udev=0x77adb0,
syspath=0x7fffe91cbea0 "/sys/bus/platform/devices/reg-dummy")
at ../libudev/libudev-device.c:719
#7 0x00007ffff735158e in scan_dir_and_add_devices (udev_enumerate=0x779410,
basedir=<optimized out>, subdir1=<optimized out>, subdir2=<optimized out>)
at ../libudev/libudev-enumerate.c:656
#8 0x00007ffff73517ae in scan_dir (udev_enumerate=0x779410,
basedir=0x7ffff7353fe1 "bus", subdir=0x7ffff7353fd9 "devices",
subsystem=0x0) at ../libudev/libudev-enumerate.c:727
#9 0x00007ffff7351a2d in scan_devices_all (udev_enumerate=0x779410)
at ../libudev/libudev-enumerate.c:877
#10 0x00000000004d3183 in udevEnumerateDevices (udev=0x77adb0)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/node_device/node_device_udev.c:1377
#11 udevDeviceMonitorStartup (privileged=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/node_device/node_device_udev.c:1704
#12 0x00007ffff784222e in virStateInitialize (privileged=1)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/libvirt.c:852
---Type <return> to continue, or q <return> to quit---
#13 0x0000000000424231 in daemonRunStateInit (opaque=0x7613c0)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./daemon/libvirtd.c:1177
#14 0x00007ffff77dc972 in virThreadHelper (data=<optimized out>)
at 
/build/buildd-libvirt_0.9.9-3+b2-amd64-3j4uU0/libvirt-0.9.9/./src/util/threads-pthread.c:157
#15 0x00007ffff4f94b50 in start_thread (arg=<optimized out>)
at pthread_create.c:304
#16 0x00007ffff48d890d in clone ()
at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#17 0x0000000000000000 in ?? ()
(gdb) frame 6
#6 0x00007ffff734eaa6 in udev_device_new_from_syspath (udev=0x77adb0,
syspath=0x7fffe91cbea0 "/sys/bus/platform/devices/reg-dummy")
at ../libudev/libudev-device.c:719
719 info(udev, "device %p has devpath '%s'\n", udev_device, 
udev_device->devpath);
(gdb) p udev_device
$1 = (struct udev_device *) 0x778510
(gdb) p udev_device->devpath
$2 = 0x78cba4 "/devices/platform/reg-dummy"
(gdb)

-------------- next part --------------
A non-text attachment was scrubbed...
Name: valgrind.log
Type: text/x-log
Size: 14446 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-libvirt-maintainers/attachments/20120223/9d1ba92d/attachment-0001.bin>