Am 02.05.2019 um 11:43 schrieb Martin Kletzander:

On Thu, May 02, 2019 at 11:22:39AM +0200, Lothar Schilling wrote:

...

Hi everybody,

I've set up an new CentOS 7.6.1810 server. Then, via yum I installed qemu-kvm libvirt libvirt-python libguestfs-tools virt-install. There were no problems. But when I try to

systemctl start libvirtd

I get the following message:

"libvirtd: process 472: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2754."

Firstly I would make sure that all the packages are up to date.  I'm not sure what the relevant versions are on CentOS 7.6.1810, so saying what versio you have installed might help later.

All installed packages are up to date.

This message actually doesn't look like it comes from libvirt.  Are there few more lines in a log somewhere?

...

Starting libvirtd manually just by issuing the command "libvirtd" without any further arguments is working, though.

As root?  This would also make sense if the communication that fails with the above error is happening between libvirtd and systemd (when the daemon is started by systemd).

...

I do not have the slightest idea what is going on, especially as I didn't change anything about the config files.

I'm not really sure what the daemon is supposed to tell systemd apart sd_notify() when it is starting.  Maybe it is some value from the environment that we're sending and the error originates there, actually.  Like the hostname or something similar.  Again, having more logs would help as I too don't really know what is going on in there.

...

Any help would be appreciated, thank you

Lothar Schilling

_______________________________________________ libvirt-users mailing list libvirt-users@redhat.com https://www.redhat.com/mailman/listinfo/libvirt-users

I turned logging up to maximum. That's all I get: May  2 11:02:06 hl308-3 systemd: Starting Virtualization daemon... May  2 11:02:06 hl308-3 libvirtd: 472: info : libvirt version: 4.5.0, package: 10.el7_6.7 (CentOS BuildSystem <http://bugs.centos.org>, 2019-04-24-14:04:12, x86-01.bsys.centos.org) May  2 11:02:06 hl308-3 libvirtd: 472: info : hostname: my.server.net May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=6 events=1 cb=0x7eff3bbde300 opaque=(nil) ff=(nil) May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=8 events=1 cb=0x7eff3bd06760 opaque=0x558f9db485a0 ff=(nil) May  2 11:02:06 hl308-3 systemd: Started Virtualization daemon. May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=3 fd=11 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69520 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=4 fd=12 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69700 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: process 472: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2754. May  2 11:02:06 hl308-3 libvirtd: This is normally a bug in some application using the D-Bus library. May  2 11:02:06 hl308-3 libvirtd: D-Bus not built with -rdynamic so unable to print a backtrace May  2 11:02:06 hl308-3 systemd: libvirtd.service: main process exited, code=killed, status=6/ABRT

On Thu, May 02, 2019 at 01:07:32PM +0200, Michal Privoznik wrote:

On 5/2/19 12:08 PM, Lothar Schilling wrote:

...

I turned logging up to maximum. That's all I get:

May  2 11:02:06 hl308-3 systemd: Starting Virtualization daemon... May  2 11:02:06 hl308-3 libvirtd: 472: info : libvirt version: 4.5.0, package: 10.el7_6.7 (CentOS BuildSystem <http://bugs.centos.org>, 2019-04-24-14:04:12, x86-01.bsys.centos.org) May  2 11:02:06 hl308-3 libvirtd: 472: info : hostname: my.server.net May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=6 events=1 cb=0x7eff3bbde300 opaque=(nil) ff=(nil) May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=8 events=1 cb=0x7eff3bd06760 opaque=0x558f9db485a0 ff=(nil) May  2 11:02:06 hl308-3 systemd: Started Virtualization daemon. May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=3 fd=11 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69520 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=4 fd=12 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69700 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: process 472: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2754. May  2 11:02:06 hl308-3 libvirtd: This is normally a bug in some application using the D-Bus library. May  2 11:02:06 hl308-3 libvirtd: D-Bus not built with -rdynamic so unable to print a backtrace May  2 11:02:06 hl308-3 systemd: libvirtd.service: main process exited, code=killed, status=6/ABRT

This is not the maximum loggin. We'll need to see debug logs:

https://wiki.libvirt.org/page/DebugLogs

and perhaps running libvirtd under gdb and getting a stack trace (with all strings expanded) might help too.

Actually gdb might be the only help here. The reason is that that dbus call just reports the error and then calls abort(), so libvirtd will not even get an error message (which would help us track down what might've been the case). If you can do something like: $ dnf --enablerepo='*debug*' install libvirt-debuginfo dbus-debuginfo $ cat >/var/lib/libvirt/gdbabortscript <<EOF start break abort commands t a a bt full end continue EOF $ cat >/etc/systemd/system/libvirtd.service.d/override.conf <<EOF [Service] ExecStart= ExecStart=gdb --batch -x /var/lib/libvirt/gdbabortscript /usr/sbin/libvirtd $LIBVIRTD_ARGS EOF $ systemctl daemon-reload $ restorecon -F /var/lib/libvirt/gdbabortscript /etc/systemd/system/libvirtd.service.d/override.conf $ systemctl restart libvirtd.service You should get the full stacktrace of the issue in the output of: journalctl -u libvirtd.service and you can post it here so we can find out what's happening. HTH, Martin

Am 03.05.2019 um 16:43 schrieb Martin Kletzander:

On Thu, May 02, 2019 at 02:25:28PM +0200, Martin Kletzander wrote:

...

On Thu, May 02, 2019 at 01:07:32PM +0200, Michal Privoznik wrote:

...

On 5/2/19 12:08 PM, Lothar Schilling wrote:

...

I turned logging up to maximum. That's all I get:

May  2 11:02:06 hl308-3 systemd: Starting Virtualization daemon... May  2 11:02:06 hl308-3 libvirtd: 472: info : libvirt version: 4.5.0, package: 10.el7_6.7 (CentOS BuildSystem <http://bugs.centos.org>, 2019-04-24-14:04:12, x86-01.bsys.centos.org) May  2 11:02:06 hl308-3 libvirtd: 472: info : hostname: my.server.net May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=6 events=1 cb=0x7eff3bbde300 opaque=(nil) ff=(nil) May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=8 events=1 cb=0x7eff3bd06760 opaque=0x558f9db485a0 ff=(nil) May  2 11:02:06 hl308-3 systemd: Started Virtualization daemon. May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=3 fd=11 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69520 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=4 fd=12 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69700 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: process 472: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2754. May  2 11:02:06 hl308-3 libvirtd: This is normally a bug in some application using the D-Bus library. May  2 11:02:06 hl308-3 libvirtd: D-Bus not built with -rdynamic so unable to print a backtrace May  2 11:02:06 hl308-3 systemd: libvirtd.service: main process exited, code=killed, status=6/ABRT

This is not the maximum loggin. We'll need to see debug logs:

https://wiki.libvirt.org/page/DebugLogs

and perhaps running libvirtd under gdb and getting a stack trace (with all strings expanded) might help too.

Actually gdb might be the only help here.  The reason is that that dbus call just reports the error and then calls abort(), so libvirtd will not even get an error message (which would help us track down what might've been the case).

If you can do something like:

Even better, there are some ways to get the core dump information which I completely forgot about:

- coredumpctl -- IIRC you are running CentOS 7, so this will not be available                  for you yet.  If it was, coredumpctl show just shows all we                  need (by default it picks the last core dump and stacktrace is                  part of the output).

- abrt-cli -- Similar to the above, it should be available for you, but you               need to have abrt installed and setup.  Which is not always the               default.  If you do, or you set it up yourself, however, you               should be able to get to the core dump as well, but it is not as               easy as with coredumpctl (i.e. I did not get to it in first 10               seconds).

- Setup your own -- either set the ulimit for the service and look for the file                     that gets created or set kernel.core_pattern using sysctl                     to a command that gets ran with each core dump (this one                     does not need any ulimit setting, but you need to know what                     to specify there.

Please let us know if you got anywhere, I'd like to see what the issue is and how we can fix it.

...

 $ dnf --enablerepo='*debug*' install libvirt-debuginfo dbus-debuginfo

 $ cat >/var/lib/libvirt/gdbabortscript <<EOF  start  break abort  commands  t a a bt full  end  continue  EOF

 $ cat >/etc/systemd/system/libvirtd.service.d/override.conf <<EOF  [Service]  ExecStart=  ExecStart=gdb --batch -x /var/lib/libvirt/gdbabortscript /usr/sbin/libvirtd $LIBVIRTD_ARGS  EOF

 $ systemctl daemon-reload  $ restorecon -F /var/lib/libvirt/gdbabortscript /etc/systemd/system/libvirtd.service.d/override.conf  $ systemctl restart libvirtd.service

You should get the full stacktrace of the issue in the output of:

 journalctl -u libvirtd.service

and you can post it here so we can find out what's happening.

HTH, Martin

Thank you, but I decided to reformat the machine and start from scratch.

Am 22.05.2019 um 11:04 schrieb Lothar Schilling:

Am 03.05.2019 um 16:43 schrieb Martin Kletzander:

...

On Thu, May 02, 2019 at 02:25:28PM +0200, Martin Kletzander wrote:

...

On Thu, May 02, 2019 at 01:07:32PM +0200, Michal Privoznik wrote:

...

On 5/2/19 12:08 PM, Lothar Schilling wrote:

...

I turned logging up to maximum. That's all I get:

May  2 11:02:06 hl308-3 systemd: Starting Virtualization daemon... May  2 11:02:06 hl308-3 libvirtd: 472: info : libvirt version: 4.5.0, package: 10.el7_6.7 (CentOS BuildSystem <http://bugs.centos.org>, 2019-04-24-14:04:12, x86-01.bsys.centos.org) May  2 11:02:06 hl308-3 libvirtd: 472: info : hostname: my.server.net May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=6 events=1 cb=0x7eff3bbde300 opaque=(nil) ff=(nil) May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=8 events=1 cb=0x7eff3bd06760 opaque=0x558f9db485a0 ff=(nil) May  2 11:02:06 hl308-3 systemd: Started Virtualization daemon. May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=3 fd=11 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69520 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: 472: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=4 fd=12 events=0 cb=0x7eff3bcfb420 opaque=0x558f9db69700 ff=0x7eff3bcfb3d0 May  2 11:02:06 hl308-3 libvirtd: process 472: arguments to dbus_message_iter_append_basic() were incorrect, assertion "_dbus_check_is_valid_utf8 (*string_p)" failed in file ../../dbus/dbus-message.c line 2754. May  2 11:02:06 hl308-3 libvirtd: This is normally a bug in some application using the D-Bus library. May  2 11:02:06 hl308-3 libvirtd: D-Bus not built with -rdynamic so unable to print a backtrace May  2 11:02:06 hl308-3 systemd: libvirtd.service: main process exited, code=killed, status=6/ABRT This is not the maximum loggin. We'll need to see debug logs:

https://wiki.libvirt.org/page/DebugLogs

and perhaps running libvirtd under gdb and getting a stack trace (with all strings expanded) might help too.

Actually gdb might be the only help here.  The reason is that that dbus call just reports the error and then calls abort(), so libvirtd will not even get an error message (which would help us track down what might've been the case).

If you can do something like:

Even better, there are some ways to get the core dump information which I completely forgot about:

- coredumpctl -- IIRC you are running CentOS 7, so this will not be available                  for you yet.  If it was, coredumpctl show just shows all we                  need (by default it picks the last core dump and stacktrace is                  part of the output).

- abrt-cli -- Similar to the above, it should be available for you, but you               need to have abrt installed and setup.  Which is not always the               default.  If you do, or you set it up yourself, however, you               should be able to get to the core dump as well, but it is not as               easy as with coredumpctl (i.e. I did not get to it in first 10               seconds).

- Setup your own -- either set the ulimit for the service and look for the file                     that gets created or set kernel.core_pattern using sysctl                     to a command that gets ran with each core dump (this one                     does not need any ulimit setting, but you need to know what                     to specify there.

Please let us know if you got anywhere, I'd like to see what the issue is and how we can fix it.

...

 $ dnf --enablerepo='*debug*' install libvirt-debuginfo dbus-debuginfo

 $ cat >/var/lib/libvirt/gdbabortscript <<EOF  start  break abort  commands  t a a bt full  end  continue  EOF

 $ cat >/etc/systemd/system/libvirtd.service.d/override.conf <<EOF  [Service]  ExecStart=  ExecStart=gdb --batch -x /var/lib/libvirt/gdbabortscript /usr/sbin/libvirtd $LIBVIRTD_ARGS  EOF

 $ systemctl daemon-reload  $ restorecon -F /var/lib/libvirt/gdbabortscript /etc/systemd/system/libvirtd.service.d/override.conf  $ systemctl restart libvirtd.service

You should get the full stacktrace of the issue in the output of:

 journalctl -u libvirtd.service

and you can post it here so we can find out what's happening.

HTH, Martin Hi Martin,

I set up the machine from scratch and now I#m back to where I started from... Following your instructions I ran journalctl -u libvirtd.service. The output is attached.

Thank you Lothar By the way, though I turned on logging in libvirtd.conf there is no output of any kind in /var/log/libvirtd/*...