Bug 1325072

Summary: "virtlogd --verbose" doesn't output verbose messages
Product: Red Hat Enterprise Linux 7 Reporter: Fangge Jin <fjin>
Component: libvirtAssignee: Jaroslav Suchanek <jsuchane>
Status: CLOSED ERRATA QA Contact: Virtualization Bugs <virt-bugs>
Severity: low Docs Contact:
Priority: low    
Version: 7.3CC: dyuan, jsuchane, mzhan, rbalakri, yafu, yanqzhan, zpeng
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: libvirt-2.0.0-1.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-03 18:41:28 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 Fangge Jin 2016-04-08 07:00:40 UTC 
Description of problem:
"virtlogd --verbose" doesn't output verbose messages

Version-Release number of selected component (if applicable):
libvirt-1.3.3-1.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
0.Don't change log setting in /etc/libvirt/virtlog.conf:
# grep '^log' /etc/libvirt/virtlogd.conf
(nothing output)

1.stop virtlogd.service
# systemctl stop virtlogd

2.
# virtlogd --verbose
^C

3.Change log_level to 3 or 4, the result is same with step 2.

4.Change log_level to 2:
# grep '^log' /etc/libvirt/virtlogd.conf
log_level = 2

5.
# virtlogd --verbose
2016-04-08 06:59:36.710+0000: 3512: info : libvirt version: 1.3.3, package: 1.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2016-04-06-04:13:31, x86-034.build.eng.bos.redhat.com)
2016-04-08 06:59:36.710+0000: 3512: info : hostname: fjin-4-113
2016-04-08 06:59:36.710+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f2687637c40 classname=virNetServer
2016-04-08 06:59:36.714+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f2687639f50 classname=virNetDaemon
2016-04-08 06:59:36.714+0000: 3512: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=1 fd=5 events=1 cb=0x7f26859d4720 opaque=(nil) ff=(nil)
2016-04-08 06:59:36.714+0000: 3512: info : virObjectRef:296 : OBJECT_REF: obj=0x7f2687637c40
2016-04-08 06:59:36.714+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f2687639fe0 classname=virLogHandler
2016-04-08 06:59:36.714+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f26876386e0 classname=virNetServerService
2016-04-08 06:59:36.714+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f2687638a20 classname=virNetSocket
2016-04-08 06:59:36.714+0000: 3512: info : virNetSocketNew:277 : RPC_SOCKET_NEW: sock=0x7f2687638a20 fd=7 errfd=-1 pid=0 localAddr=127.0.0.1;0, remoteAddr=<null>
2016-04-08 06:59:36.714+0000: 3512: info : virObjectRef:296 : OBJECT_REF: obj=0x7f26876386e0
2016-04-08 06:59:36.714+0000: 3512: info : virObjectRef:296 : OBJECT_REF: obj=0x7f2687638a20
2016-04-08 06:59:36.714+0000: 3512: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=2 fd=7 events=0 cb=0x7f26859bf230 opaque=0x7f2687638a20 ff=0x7f26859bf1e0
2016-04-08 06:59:36.714+0000: 3512: info : virObjectRef:296 : OBJECT_REF: obj=0x7f26876386e0
2016-04-08 06:59:36.714+0000: 3512: info : virEventPollAddHandle:140 : EVENT_POLL_ADD_HANDLE: watch=3 fd=8 events=1 cb=0x7f26859b9410 opaque=0x7f2687639f50 ff=(nil)
2016-04-08 06:59:36.714+0000: 3512: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f26876396e0 classname=virNetServerProgram
2016-04-08 06:59:36.714+0000: 3512: info : virObjectRef:296 : OBJECT_REF: obj=0x7f26876396e0
2016-04-08 06:59:36.714+0000: 3512: info : virEventPollUpdateHandle:152 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=1
2016-04-08 06:59:36.714+0000: 3512: info : virEventPollRunOnce:641 : EVENT_POLL_RUN: nhandles=3 timeout=-1

As shown above, there are info logs output.

Actual results:
"virtlogd --verbose" doesn't output verbose messages when log_level is not set or set to 3/4.

Expected results:
"virtlogd --verbose" can output verbose messages when log_level is not set, which is equal to setting log_level=2


Additional info:
Comment 2 Jaroslav Suchanek 2016-04-08 15:16:57 UTC 
Seems that cmdline override should be done before outputs definition. This may help:

diff --git a/src/logging/log_daemon.c b/src/logging/log_daemon.c
index 68f0647..ac897b2 100644
--- a/src/logging/log_daemon.c
+++ b/src/logging/log_daemon.c
@@ -405,6 +405,12 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config,
         virLogParseOutputs(config->log_outputs);

     /*
+     * Command line override for --verbose
+     */
+    if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO))
+        virLogSetDefaultPriority(VIR_LOG_INFO);
+
+    /*
      * If no defined outputs, and either running
      * as daemon or not on a tty, then first try
      * to direct it to the systemd journal
@@ -464,12 +470,6 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config,
         VIR_FREE(tmp);
     }

-    /*
-     * Command line override for --verbose
-     */
-    if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO))
-        virLogSetDefaultPriority(VIR_LOG_INFO);
-
     return 0;

  error:
Comment 3 Jaroslav Suchanek 2016-06-28 13:28:17 UTC 
Fixed upstream by:
commit c59b9e1483ca50290f865737877358978d88dfc7
Author:     Jaroslav Suchanek <jsuchane>
AuthorDate: Tue Jun 28 13:05:30 2016 +0200
Commit:     Erik Skultety <eskultet>
CommitDate: Tue Jun 28 13:52:34 2016 +0200

    logging: fixing log level initialization from cmdline

    Reorder code for setting default log level from cmdline prior
    initialization of log outputs. Thus the --verbose option is reflected.

    This resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1325072
Comment 5 Yanqiu Zhang 2016-07-06 06:39:37 UTC 
Reproduce this bug with libvirt-1.3.3-1.el7.x86_64.
Steps to reproduce:

0.Don't change log setting in /etc/libvirt/virtlogd.conf:
1.# systemctl stop virtlogd

2.# virtlogd --verbose
(nothing output)
^C

3.Change log_level to 3 or 4, the result is same with step 2.

4.Change log_level to 2:
# vim /etc/libvirt/virtlogd.conf
log_level = 2

5.
# virtlogd --verbose
2016-07-06 02:15:13.201+0000: 31272: info : libvirt version: 1.3.3, package: 1.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2016-04-06-04:13:31, x86-034.build.eng.bos.redhat.com)
2016-07-06 02:15:13.201+0000: 31272: info : hostname: hostB
2016-07-06 02:15:13.201+0000: 31272: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f52fb1ddd00 classname=virNetServer
2016-07-06 02:15:13.201+0000: 31272: info : virObjectNew:202 : OBJECT_NEW: obj=0x7f52fb1e0090 classname=virNetDaemon
......

Verify this bug with libvirt-2.0.0-1.el7.x86_64
Steps to verify:

0.Don't change log setting in /etc/libvirt/virtlogd.conf:
1.# systemctl stop virtlogd

2.# virtlogd --verbose
2016-07-05 05:42:21.381+0000: 8151: info : libvirt version: 2.0.0, package: 1.el7 (Unknown, 2016-07-01-15:41:46, hostA)
2016-07-05 05:42:21.381+0000: 8151: info : hostname: hostB
2016-07-05 05:42:21.381+0000: 8151: info : virObjectNew:202 : OBJECT_NEW: obj=0x7fc3c3d8ccd0 classname=virNetServer
......
3.Change log_level to 3 or 4, retest step 1-2, the result is same with step 2.

4.Change log_level to 2, the result is same with step 2.
Comment 7 errata-xmlrpc 2016-11-03 18:41:28 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.

https://rhn.redhat.com/errata/RHSA-2016-2577.html