Bug 831044

Summary: #libvirtd error messages should be fixed
Product: Red Hat Enterprise Linux 6 Reporter: yanbing du <ydu>
Component: libvirtAssignee: Ján Tomko <jtomko>
Status: CLOSED ERRATA QA Contact: Virtualization Bugs <virt-bugs>
Severity: medium Docs Contact:
Priority: medium    
Version: 6.3CC: acathrow, dallan, dyasny, dyuan, mzhan, rwu, whuang
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: libvirt-0.10.1-1.el6.x86_64 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-21 07:16:56 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description yanbing du 2012-06-12 05:07:03 UTC
Description of problem:
When stop libvirtd service and run it in the foreground, that always output lots of error messages, and this should be fixed.

Version-Release number of selected component (if applicable):
libvirt-0.9.10-21.el6.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Stop libvirtd service 
# service libvirtd stop
Stopping libvirtd daemon:                                  [  OK  ]
2. Run libvirtd
# libvirtd
2012-06-11 06:26:45.563+0000: 23012: info : libvirt version: 0.9.10, package: 21.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2012-05-23-09:15:11, x86-003.build.bos.redhat.com)
2012-06-11 06:26:45.563+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 -p tcp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535) status unexpected: exit status 1
2012-06-11 06:26:45.565+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 -p udp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535) status unexpected: exit status 1
2012-06-11 06:26:45.567+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 ! --destination 192.168.122.0/24 --jump MASQUERADE) status unexpected: exit status 1
2012-06-11 06:26:45.568+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --destination 192.168.122.0/24 --out-interface virbr0 --match state --state ESTABLISHED,RELATED --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.570+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --source 192.168.122.0/24 --in-interface virbr0 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.571+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --in-interface virbr0 --out-interface virbr0 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.572+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --out-interface virbr0 --jump REJECT) status unexpected: exit status 1
2012-06-11 06:26:45.574+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --in-interface virbr0 --jump REJECT) status unexpected: exit status 1
2012-06-11 06:26:45.575+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol udp --destination-port 53 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.576+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol tcp --destination-port 53 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.577+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table mangle --delete POSTROUTING --out-interface virbr0 --protocol udp --destination-port 68 --jump CHECKSUM --checksum-fill) status unexpected: exit status 1
2012-06-11 06:26:45.578+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol udp --destination-port 67 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.580+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.581+0000: 23012: error : virCommandWait:2308 : internal error Child process (/sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT) status unexpected: exit status 1
2012-06-11 06:26:45.581+0000: 23012: error : networkAddGeneralIptablesRules:1279 : failed to add iptables rule to allow DHCP requests from 'virbr0'
2012-06-11 06:26:45.632+0000: 23012: error : virCommandWait:2308 : internal error Child process (/bin/sh -c EBT=/sbin/ebtables
cmd='$EBT -t nat -L'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) status unexpected: exit status 1
2012-06-11 06:26:45.635+0000: 23012: error : virCommandWait:2308 : internal error Child process (/bin/sh -c IPT=/sbin/iptables
cmd='$IPT -n -L FORWARD'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) status unexpected: exit status 1
2012-06-11 06:26:45.639+0000: 23012: error : virCommandWait:2308 : internal error Child process (/bin/sh -c IPT=/sbin/ip6tables
cmd='$IPT -n -L FORWARD'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) status unexpected: exit status 1
2012-06-11 06:26:45.639+0000: 23012: error : ebiptablesDriverInit:4105 : internal error firewall tools were not found or cannot be used
2012-06-11 06:26:45.648+0000: 23012: error : virCommandWait:2308 : internal error Child process (/usr/sbin/dmidecode -q -t 0,1,4,17) status unexpected: exit status 1
2012-06-11 06:26:45.648+0000: 23012: error : virSysinfoRead:493 : internal error Failed to execute command (null)
  
Actual results:
As step2 shows.

Expected results:
Avoid these error messages.

Additional info:

Comment 1 Dave Allan 2012-06-12 15:17:28 UTC
I agree that these messages should be reviewed to limit them to things that are actual problems.  Spurious messages lead to user confusion, people blaming libvirt for unrelated problems and distro support requests.  Having said that, some of these messages may reflect real problems and should remain.

Comment 2 Ján Tomko 2012-09-10 15:35:47 UTC
Hello. I'm unable to reproduce this, could you please try it again with a newer libvirt version?

Comment 3 Huang Wenlong 2012-09-11 05:49:04 UTC
(In reply to comment #2)
> Hello. I'm unable to reproduce this, could you please try it again with a
> newer libvirt version?

Hi, jtomko

I can reproduce this error in libvirt-0.10.1-1.el6.x86_64



[root@intel-q9400-4-2 ~]# /etc/init.d/libvirtd stop
Stopping libvirtd daemon:                                  [  OK  ]
                                                                                    
                                                                                                                           
[root@intel-q9400-4-2 ~]# libvirtd 
2012-09-11 05:47:44.173+0000: 2957: info : libvirt version: 0.10.1, package: 1.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2012-08-31-10:30:29, x86-009.build.bos.redhat.com)
2012-09-11 05:47:44.173+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 -p tcp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.175+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 -p udp ! --destination 192.168.122.0/24 --jump MASQUERADE --to-ports 1024-65535) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.176+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table nat --delete POSTROUTING --source 192.168.122.0/24 ! --destination 192.168.122.0/24 --jump MASQUERADE) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.177+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --destination 192.168.122.0/24 --out-interface virbr0 --match state --state ESTABLISHED,RELATED --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.179+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --source 192.168.122.0/24 --in-interface virbr0 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.180+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --in-interface virbr0 --out-interface virbr0 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.182+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --out-interface virbr0 --jump REJECT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.183+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete FORWARD --in-interface virbr0 --jump REJECT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.185+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol udp --destination-port 53 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.186+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol tcp --destination-port 53 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.188+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table mangle --delete POSTROUTING --out-interface virbr0 --protocol udp --destination-port 68 --jump CHECKSUM --checksum-fill) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.189+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol udp --destination-port 67 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.191+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --delete INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.192+0000: 2957: error : virCommandWait:2332 : internal error Child process (/sbin/iptables --table filter --insert INPUT --in-interface virbr0 --protocol tcp --destination-port 67 --jump ACCEPT) unexpected exit status 1: libvir:  error : cannot execute binary /sbin/iptables: Permission denied

2012-09-11 05:47:44.192+0000: 2957: error : networkAddGeneralIptablesRules:1331 : failed to add iptables rule to allow DHCP requests from 'virbr0'
2012-09-11 05:47:44.245+0000: 2957: error : virCommandWait:2332 : internal error Child process (/bin/sh -c EBT="/sbin/ebtables"
cmd='$EBT -t nat -L'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) unexpected exit status 1
2012-09-11 05:47:44.245+0000: 2957: error : ebiptablesDriverTestCLITools:4245 : Testing of ebtables command failed: Failure to execute command '$EBT -t nat -L' : '/bin/sh: line 2: /sbin/ebtables: Permission denied'.

2012-09-11 05:47:44.249+0000: 2957: error : virCommandWait:2332 : internal error Child process (/bin/sh -c IPT="/sbin/iptables"
cmd='$IPT -n -L FORWARD'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) unexpected exit status 1
2012-09-11 05:47:44.249+0000: 2957: error : ebiptablesDriverTestCLITools:4262 : Testing of iptables command failed: Failure to execute command '$IPT -n -L FORWARD' : '/bin/sh: line 2: /sbin/iptables: Permission denied'.

2012-09-11 05:47:44.253+0000: 2957: error : virCommandWait:2332 : internal error Child process (/bin/sh -c IPT="/sbin/ip6tables"
cmd='$IPT -n -L FORWARD'
eval res=\$\("${cmd} 2>&1"\)
if [ $? -ne 0 ]; then  echo "Failure to execute command '${cmd}' : '${res}'.";  exit 1;fi
) unexpected exit status 1
2012-09-11 05:47:44.253+0000: 2957: error : ebiptablesDriverTestCLITools:4279 : Testing of ip6tables command failed: Failure to execute command '$IPT -n -L FORWARD' : '/bin/sh: line 2: /sbin/ip6tables: Permission denied'.

2012-09-11 05:47:44.254+0000: 2957: error : ebiptablesDriverInit:4322 : firewall tools were not found or cannot be used
2012-09-11 05:47:44.259+0000: 2957: error : virCommandWait:2332 : internal error Child process (/usr/sbin/dmidecode -q -t 0,1,4,17) unexpected exit status 1: libvir:  error : cannot execute binary /usr/sbin/dmidecode: Permission denied

2012-09-11 05:47:44.259+0000: 2957: error : virSysinfoRead:773 : internal error Failed to execute command (null)
^C[root@intel-q9400-4-2 ~]# rpm -q libvirt
libvirt-0.10.1-1.el6.x86_64

Comment 4 Dave Allan 2012-09-17 15:41:35 UTC
Hold on a minute, these logs indicate that libvirtd can't execute either ebtables, or dmidecode.  Does the daemon have a permissions problem?

Comment 5 Ján Tomko 2012-09-25 16:40:06 UTC
The error messages are made much clearer by this patch, as demonstrated by comment 3.

commit b8c298d3019ffed3f93989314c90821ddbe47f83
Author:     Laine Stump <laine>
AuthorDate: Mon Aug 6 17:40:06 2012
Commit:     Laine Stump <laine>
CommitDate: Tue Aug 7 21:25:40 2012
    util: include stderr in log message when an external command fails

Comment 6 yanbing du 2012-09-26 03:34:45 UTC
This bug can be reproduced under Enforcing mode, if setenforce = 0, there's no error output, and this can answered comment 2 and comment 4.

And test this bug both with  libvirt-0.10.1-1.el6.x86_64 and libvirt-0.10.2-1.el6.x86_64, we can see the error messages are much clearer: 'Permission denied'.
So this bug can be VERIFIED.

Comment 8 Min Zhan 2012-09-29 06:39:40 UTC
Move to VERIFIED per Comment 6

Comment 9 errata-xmlrpc 2013-02-21 07:16:56 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2013-0276.html