Bug 1312188

Summary: virtlogd failed to open guest log file while doing migration
Product: Red Hat Enterprise Linux 7 Reporter: yafu <yafu>
Component: libvirtAssignee: Peter Krempa <pkrempa>
Status: CLOSED ERRATA QA Contact: Virtualization Bugs <virt-bugs>
Severity: low Docs Contact:
Priority: low    
Version: 7.3CC: dyuan, fjin, jscotka, mzhan, pkrempa, rbalakri, 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:38:31 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 yafu 2016-02-26 03:13:36 UTC
Description of problem:
Do migraion, when the libvirtd tried to call virtlogd to write the guest state in guest log file, virtlogd failed with error on source host:  Cannot open log file: '/usr/local/var/log/libvirt/qemu/rhel7.1.log': Device or resource busy

Version-Release number of selected component (if applicable):
libvirt-1.3.1-1.el7.x86_64
qemu-kvm-rhev-2.3.0-31.el7_2.8.x86_64

How reproducible:
100%

Steps to Reproduce:
1.Edit virtlogd.conf and restart virtlogd on source host:
  log_outputs="3:syslog:virtlogd 3:file:/var/log/libvirt/virtlogd.log"
  
  #service virtlogd restart

2.Edit libvirtd.conf and restart libvirtd on source host:
  log_outputs="3:syslog:libvirtd 3:file:/var/log/libvirt/libvirtd.log"

  #service libvirtd restart

3.Do migration:
  #virsh migrate rhel7.1 qemu+ssh://10.73.195.123/system --live --verbose

4.After migration completed, check the virtlogd's log on source host:
  #tailf /var/log/libvirt/virtlogd.log | grep -i error
2016-02-26 02:57:21.127+0000: 2033: error : virLogHandlerDomainOpenLogFile:379 : Cannot open log file: '/var/log/libvirt/qemu/rhel7.1.log': Device or resource busy
2016-02-26 02:57:21.128+0000: 2011: error : virNetSocketReadWire:1613 : End of file while reading data: Input/output error
  
5.After migration completed, check the libvirtd's log on source host:
 #tailf /var/log/libvirt/libvirtd.log | grep -i error
2016-02-26 02:57:21.127+0000: 1790: error :virNetClientProgramDispatchError:177 : Cannot open log file: '/var/log/libvirt/qemu/rhel7.1.log': Device or resource busy

6.Check the guest log on source host and there is no "shutting down" log in guest log file.

Actual results:


Expected results:
virtlogd should open guest log file and write the log correctly.

Additional info:

Comment 5 Peter Krempa 2016-06-07 16:19:57 UTC
commit cf3ea0769c54a328733bcb0cd27f546e70090c89
Author: Peter Krempa <pkrempa>
Date:   Tue Jun 7 16:31:15 2016 +0200

    qemu: process: Append the "shutting down" message using the new APIs
    
    Use qemuDomainLogAppendMessage rather than attempting to open a new
    logging context with file descriptors. The new approach allows to log
    the message even if qemu is still running at that point which appens
    during migration finish phase where qemuProcessStop is killing qemu.
    
    Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1312188

commit 91a6eacc8f214882c5c67ad84d767bdc0d46b944
Author: Peter Krempa <pkrempa>
Date:   Tue Jun 7 16:19:03 2016 +0200

    qemu: domain: Implement helper for one-shot log entries to the VM log file
    
    Along with the virtlogd addition of the log file appending API implement
    a helper for logging one-shot entries to the log file including the
    fallback approach of using direct file access.
    
    This will be used for noting the shutdown of the qemu proces and
    possibly other actions such as VM migration and other critical VM
    lifecycle events.

commit 78b9b85c069d1dea60139cff7ee6f6d5ac2f3359
Author: Peter Krempa <pkrempa>
Date:   Tue Jun 7 16:15:22 2016 +0200

    log: daemon: Add remote protocol handling for the log appending API
    
    Implement the RPC dispatcher and caller for the new API.

commit 5e6143fbccf2e6afb73c3f872ccdafd02fed5d95
Author: Peter Krempa <pkrempa>
Date:   Tue Jun 7 16:09:09 2016 +0200

    log: handler: Add new API to append to logging files
    
    For logging one-shot entries to the VM log file it's quite a waste to
    hold open the file descriptor for logging that is provided by the
    current API.
    
    This new API will be ideal for logging one-shot entries to the file
    e.g. at the point when we shut the VM down rather than having to add the
    whole file-descriptor infrastructure.
    
    Additionally this will allow to add the messages even after restart of
    libvirtd since virtlogd doesn't allow to obtain a regular context with
    filedescriptors while the VM is still active.

Comment 7 Fangge Jin 2016-07-05 10:54:57 UTC
Reproduce on build libvirt-1.3.5-1.el7.x86_64

Verify pass build libvirt-2.0.0-1.el7.x86_64
1. Prepare two hosts for migration

2. On the two hosts, set log level and log outputs in libvirtd.conf and restart libvirtd.service:
# grep "^log" /etc/libvirt/libvirtd.conf
log_level = 1
log_outputs="1:file:/var/log/libvirt/libvirtd.log"

# systemctl restart libvirtd

3. Keep the default stdio_handler setting(or set it to logd) in qemu.conf:
# grep 'stdio_handler' /etc/libvirt/qemu.conf
#stdio_handler = "logd"

4. Start a guest on one host:
# virsh start rhel7.2

5. Migrate the guest to the other host:
# virsh migrate rhel7.2 qemu+ssh://hp-dl385g7-06.lab.eng.pek2.redhat.com/system --live --verbose
Migration: [100 %]

6. Check libvirtd.log, NO such error:
2016-02-26 02:57:21.127+0000: 2033: error : virLogHandlerDomainOpenLogFile:379 : Cannot open log file: '/var/log/libvirt/qemu/rhel7.1.log': Device or resource busy
2016-02-26 02:57:21.128+0000: 2011: error : virNetSocketReadWire:1613 : End of file while reading data: Input/output error

7. Check qemu log, the guest shutdown log is written correctly:
# cat /var/log/libvirt/qemu/rhel7.2.log
...
2016-07-05 10:40:04.873+0000: shutting down
2016-07-05T10:40:04.876707Z qemu-kvm: terminating on signal 15 from pid 8653

Comment 9 errata-xmlrpc 2016-11-03 18:38:31 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