Bug 2039652

Summary: No error info report when failed to start daemon for setting log_outputs to non-exist dir
Product: Red Hat Enterprise Linux 9 Reporter: yafu <yafu>
Component: libvirtAssignee: Martin Kletzander <mkletzan>
libvirt sub component: General QA Contact: yafu <yafu>
Status: CLOSED ERRATA Docs Contact:
Severity: unspecified    
Priority: unspecified CC: dzheng, jdenemar, lcheng, mprivozn, virt-maint, xuzhang, yanqzhan, yicui
Version: 9.0Keywords: AutomationBackLog, Triaged, Upstream
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: libvirt-8.0.0-1.el9 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-05-17 12:46:17 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: 8.0.0
Embargoed:

Description yafu 2022-01-12 07:28:17 UTC 
Description of problem:
No error info report when failed to start daemon for setting log_outputs to non-exist dir

Version-Release number of selected component (if applicable):
libvirt-8.0.0-0rc1.1.el9.x86_64

How reproducible:
100%

Steps to Reproduce:
1.Change log setting in virtqemud.conf and set log_outputs to non-existing dir:
#vim /etc/libvirt/virtqemud.conf
log_level = 1
log_outputs = "1:syslog:virtqemud 1:file:/test/virteqmud.log"

2.Check the log path:
#ls /test
ls: cannot access '/test': No such file or directory

3.Restart the daemon:
#systemctl restart virtqemud
Job for virtqemud.service failed because the control process exited with error code.
See "systemctl status virtqemud.service" and "journalctl -xeu virtqemud.service" for details.

4.Check the syslog:
#cat /var/log/messages
Jan 12 02:20:36 * systemd[1]: Starting Virtualization qemu daemon...
Jan 12 02:20:36 * virtqemud[30897]: 2022-01-12 07:20:36.624+0000: 30897: info : libvirt version: 8.0.0, package: 0rc1.1.el9 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2022-01-10-08:11:57, )
Jan 12 02:20:36 * virtqemud[30897]: 2022-01-12 07:20:36.624+0000: 30897: info : hostname: *
Jan 12 02:20:36 * virtqemud[30897]: 2022-01-12 07:20:36.624+0000: 30897: debug : virLogParseOutputs:1635 : outputs=1:syslog:virtqemud 1:file:/test/virteqmud.log
Jan 12 02:20:36 * virtqemud[30897]: 2022-01-12 07:20:36.624+0000: 30897: debug : virLogParseOutput:1482 : output=1:syslog:virtqemud
Jan 12 02:20:36 * virtqemud[30897]: 2022-01-12 07:20:36.624+0000: 30897: debug : virLogParseOutput:1482 : output=1:file:/test/virteqmud.log
Jan 12 02:20:36 dell-per440-14 systemd[1]: virtqemud.service: Main process exited, code=exited, status=1/FAILURE
Jan 12 02:20:36 dell-per440-14 systemd[1]: virtqemud.service: Failed with result 'exit-code'.

5.Try to start the daemon at foreground:
# virtqemud 
2022-01-12 07:23:25.769+0000: 30937: info : libvirt version: 8.0.0, package: 0rc1.1.el9 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2022-01-10-08:11:57, )
2022-01-12 07:23:25.769+0000: 30937: info : hostname: *
2022-01-12 07:23:25.769+0000: 30937: debug : virLogParseOutputs:1635 : outputs=1:syslog:virtqemud 1:file:/test/virteqmud.log
2022-01-12 07:23:25.770+0000: 30937: debug : virLogParseOutput:1482 : output=1:syslog:virtqemud
2022-01-12 07:23:25.770+0000: 30937: debug : virLogParseOutput:1482 : output=1:file:/test/virteqmud.log


Actual results:
Daemon failed to start, but no error info about the failed reason when setting log_output to non-exist dir

Expected results:
Should report related error when failed to start daemon

Additional info:
1.Can start daemon successfully when setting log_output to non-existing dir with libvirt-daemon-7.10.0-1.module+el8.6.0+13502+4f24a11d.x86_64.
Comment 1 Michal Privoznik 2022-01-12 10:06:54 UTC 
Fixed upstream by:

2a9264b8b2 util: fix prototype of virDaemonSetupLogging
cfb67c8cf4 Do not print error in remote_daemon.c:main
9b652d5841 Dispatch error in virInitialize
9f6749dea0 util: Check for errors in virLogSetFromEnv
a873924e36 Exit on errors from virDaemonSetupLogging
b863085493 util: Initialize virLogMutex statically
ed5a93e4ed util: Report error in virLogSetDefaultOutputToFile
47fb83f8b7 util: Do not hide errors in virLogSetDefaultOutput
3e54152d9f util: Report error in virLogParseDefaultPriority

v8.0.0-rc1~44
Comment 2 yafu 2022-01-13 09:12:52 UTC 
(In reply to Michal Privoznik from comment #1)
> Fixed upstream by:
> 
> 2a9264b8b2 util: fix prototype of virDaemonSetupLogging
> cfb67c8cf4 Do not print error in remote_daemon.c:main
> 9b652d5841 Dispatch error in virInitialize
> 9f6749dea0 util: Check for errors in virLogSetFromEnv
> a873924e36 Exit on errors from virDaemonSetupLogging
> b863085493 util: Initialize virLogMutex statically
> ed5a93e4ed util: Report error in virLogSetDefaultOutputToFile
> 47fb83f8b7 util: Do not hide errors in virLogSetDefaultOutput
> 3e54152d9f util: Report error in virLogParseDefaultPriority
> 
> v8.0.0-rc1~44

Hi Michal,

I still can reproduce the issue with v8.0.0-rc2-5-g59e0d130fe. 
Would you help to check it please?Thanks.
Comment 3 Martin Kletzander 2022-01-13 13:47:51 UTC 
Fix posted upstream:

https://listman.redhat.com/archives/libvir-list/2022-January/msg00590.html
Comment 4 Martin Kletzander 2022-01-13 14:45:23 UTC 
Fixed upstream with v8.0.0-rc2-10-g537b51daeb8a:
commit 537b51daeb8a9a89e58df16bdc5f83dd3f31b978
Author: Martin Kletzander <mkletzan>
Date:   Thu Jan 13 14:41:03 2022 +0100

    Print errors on daemon startup if logging setup fails
Comment 8 yafu 2022-01-19 02:49:35 UTC 
Verified with libvirt-8.0.0-1.el9.x86_64.

Test steps:
1.Change log setting in virtqemud.conf and set log_outputs to non-existing dir:
#vim /etc/libvirt/virtqemud.conf
log_level = 1
log_outputs = "1:syslog:virtqemud 1:file:/test/virteqmud.log"

2.Check the log path:
#ls /test
ls: cannot access '/test': No such file or directory

3.Restart the daemon:
#systemctl restart virtqemud
Job for virtqemud.service failed because the control process exited with error code.
See "systemctl status virtqemud.service" and "journalctl -xeu virtqemud.service" for details.

4.Check the syslog, can see error info about the non-existing dir:
#cat /var/log/messages
...
Jan 18 21:45:52 dell-per440-14 virtqemud[29429]: 2022-01-19 02:45:52.596+0000: 29429: debug : virLogParseOutputs:1635 : outputs=3:syslog:virtqemud 1:file:/test/libvirtd.log
Jan 18 21:45:52 dell-per440-14 virtqemud[29429]: 2022-01-19 02:45:52.596+0000: 29429: debug : virLogParseOutput:1482 : output=3:syslog:virtqemud
Jan 18 21:45:52 dell-per440-14 virtqemud[29429]: 2022-01-19 02:45:52.596+0000: 29429: debug : virLogParseOutput:1482 : output=1:file:/test/libvirtd.log
Jan 18 21:45:52 dell-per440-14 virtqemud[29429]: libvirt:  error : failed to open /test/libvirtd.log: No such file or directory
Jan 18 21:45:52 dell-per440-14 systemd[1]: virtqemud.service: Main process exited, code=exited, status=1/FAILURE
Jan 18 21:45:52 dell-per440-14 systemd[1]: virtqemud.service: Failed with result 'exit-code'.
Jan 18 21:45:52 dell-per440-14 systemd[1]: Failed to start Virtualization qemu daemon.

...
Comment 10 errata-xmlrpc 2022-05-17 12:46:17 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 (new packages: libvirt), 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://access.redhat.com/errata/RHBA-2022:2390