0

Final Update at bottom

I have a working KVM domain which I've configured and want to use as a 'template' for other guests. So, my process is roughly this:

  1. Shut down the 'source' domain (07xQBuild)
  2. Run virt-clone --original 07xQBuild --name 07x2 --file ./07x2.qcow2
  3. Mount the newly created 07x2.qcow2 image using guestmount, and edit things like the networking configuration (/etc/netplan/01-config.yaml, /etc/hostname, etc.)
  4. Unmount the image and start with virsh start 07x2

But this always ends with:

error: Failed to start domain 07x2
error: Cannot open log file: '/usr/local/var/log/libvirt/qemu/07x2-fs0-virtiofsd.log': Device or resource busy

There is no 07x2-fs0-virtiofsd.log file, and the 07x2.log file just contains:

2020-07-28 13:42:29.400+0000: shutting down, reason=failed

I tried running LIBVIRT_DEBUG=1 virsh start 07x2 but among the 400+ lines of output, all I could see by way of error was this:

2020-07-28 13:15:00.954+0000: 40737: info : virObjectNew:250 : OBJECT_NEW: obj=0x56440bb29480 classname=virDomain
2020-07-28 13:15:00.954+0000: 40737: info : virObjectRef:385 : OBJECT_REF: obj=0x56440bb25be0
2020-07-28 13:15:00.954+0000: 40737: debug : virDomainGetID:1721 : dom=0x56440bb29480, (VM: name=07x2, uuid=761c9104-b8de-474a-a5d6-31be46b50562)
2020-07-28 13:15:00.955+0000: 40737: debug : virDomainCreate:6544 : dom=0x56440bb29480, (VM: name=07x2, uuid=761c9104-b8de-474a-a5d6-31be46b50562)
2020-07-28 13:15:00.955+0000: 40737: debug : virNetMessageNew:45 : msg=0x56440bb27df0 tracked=0
2020-07-28 13:15:00.955+0000: 40737: debug : virNetMessageEncodePayload:388 : Encode length as 60
2020-07-28 13:15:00.955+0000: 40737: info : virNetClientSendInternal:2108 : RPC_CLIENT_MSG_TX_QUEUE: client=0x56440bb26f60 len=60 prog=536903814 vers=1 proc=9 type=0 status=0 serial=7
2020-07-28 13:15:00.955+0000: 40737: debug : virNetClientCallNew:2061 : New call 0x56440bb39290: msg=0x56440bb27df0, expectReply=1, nonBlock=0
2020-07-28 13:15:00.955+0000: 40737: debug : virNetClientIO:1879 : Outgoing message prog=536903814 version=1 serial=7 proc=9 type=0 length=60 dispatch=(nil)
2020-07-28 13:15:00.955+0000: 40737: debug : virNetClientIO:1931 : We have the buck head=0x56440bb39290 call=0x56440bb39290
2020-07-28 13:15:00.955+0000: 40737: info : virEventGLibHandleUpdate:196 : EVENT_GLIB_UPDATE_HANDLE: watch=1 events=0
2020-07-28 13:15:00.955+0000: 40737: debug : virEventGLibHandleUpdate:206 : Update handle data=0x56440bb27420 watch=1 fd=4 events=0
2020-07-28 13:15:00.955+0000: 40737: debug : virEventGLibHandleUpdate:227 : Removed old handle watch=15
2020-07-28 13:15:00.955+0000: 40738: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-07-28 13:15:00.955+0000: 40737: info : virEventGLibTimeoutUpdate:381 : EVENT_GLIB_UPDATE_TIMEOUT: timer=2 interval=5000
2020-07-28 13:15:00.955+0000: 40737: debug : virEventGLibTimeoutUpdate:390 : Update timeout data=0x56440bb27dc0 timer=2 interval=5000 ms
2020-07-28 13:15:00.955+0000: 40738: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-07-28 13:15:02.363+0000: 40737: info : virEventGLibTimeoutUpdate:381 : EVENT_GLIB_UPDATE_TIMEOUT: timer=2 interval=3000
2020-07-28 13:15:02.363+0000: 40737: debug : virEventGLibTimeoutUpdate:390 : Update timeout data=0x56440bb27dc0 timer=2 interval=3000 ms
2020-07-28 13:15:02.363+0000: 40737: debug : virNetMessageDecodeLength:160 : Got length, now need 304 total (300 more)
2020-07-28 13:15:02.363+0000: 40737: info : virNetClientCallDispatch:1263 : RPC_CLIENT_MSG_RX: client=0x56440bb26f60 len=304 prog=536903814 vers=1 proc=9 type=1 status=1 serial=7
2020-07-28 13:15:02.363+0000: 40737: debug : virKeepAliveCheckMessage:369 : ka=0x56440bb28bb0, client=0x56440bb26f60, msg=0x56440bb26fc8
2020-07-28 13:15:02.363+0000: 40737: info : virEventGLibTimeoutUpdate:381 : EVENT_GLIB_UPDATE_TIMEOUT: timer=2 interval=5000
2020-07-28 13:15:02.363+0000: 40737: debug : virEventGLibTimeoutUpdate:390 : Update timeout data=0x56440bb27dc0 timer=2 interval=5000 ms
2020-07-28 13:15:02.363+0000: 40737: debug : virNetMessageClear:73 : msg=0x56440bb26fc8 nfds=0
2020-07-28 13:15:02.363+0000: 40738: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-07-28 13:15:02.363+0000: 40737: debug : virNetClientIOEventLoopPassTheBuck:1559 : Giving up the buck 0x56440bb39290
2020-07-28 13:15:02.363+0000: 40737: debug : virNetClientIOEventLoopPassTheBuck:1573 : No thread to pass the buck to
2020-07-28 13:15:02.363+0000: 40737: info : virEventGLibHandleUpdate:196 : EVENT_GLIB_UPDATE_HANDLE: watch=1 events=1
2020-07-28 13:15:02.363+0000: 40737: debug : virEventGLibHandleUpdate:206 : Update handle data=0x56440bb27420 watch=1 fd=4 events=1
2020-07-28 13:15:02.363+0000: 40737: debug : virEventGLibHandleUpdate:222 : Added new handle watch=19
2020-07-28 13:15:02.363+0000: 40737: debug : virNetClientIO:1956 : All done with our call head=(nil) call=0x56440bb39290 rv=0
2020-07-28 13:15:02.363+0000: 40737: debug : virNetMessageFree:86 : msg=0x56440bb27df0 nfds=0 cb=(nil)
2020-07-28 13:15:02.363+0000: 40738: debug : virEventRunDefaultImpl:340 : running default event implementation
2020-07-28 13:15:02.363+0000: 40737: debug : virDomainGetName:1642 : domain=0x56440bb29480
error: Failed to start domain 07x2
2020-07-28 13:15:02.363+0000: 40737: debug : virDomainFree:562 : dom=0x56440bb29480, (VM: name=07x2, uuid=761c9104-b8de-474a-a5d6-31be46b50562)
2020-07-28 13:15:02.364+0000: 40737: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x56440bb29480
2020-07-28 13:15:02.364+0000: 40737: info : virObjectUnref:349 : OBJECT_DISPOSE: obj=0x56440bb29480
2020-07-28 13:15:02.364+0000: 40737: debug : virDomainDispose:323 : release domain 0x56440bb29480 07x2 761c9104-b8de-474a-a5d6-31be46b50562
2020-07-28 13:15:02.364+0000: 40737: info : virObjectUnref:347 : OBJECT_UNREF: obj=0x56440bb25be0
error: Cannot open log file: '/usr/local/var/log/libvirt/qemu/07x2-fs0-virtiofsd.log': Device or resource busy

I tried dumping the XML of the source domain (which works) and the cloned one (which doesn't), and the only 4 differences are name, uuid, source file, and mac address:

# diff 07xQBuild.xml 07x2.xml
2,3c2,3
<   <name>07xQBuild</name>
<   <uuid>24ed7962-518e-4151-8635-84cb72a8a9b4</uuid>
---
>   <name>07x2</name>
>   <uuid>761c9104-b8de-474a-a5d6-31be46b50562</uuid>
45c45
<       <source file='/fast_data/kvm/images/07xQBuild.qcow2'/>
---
>       <source file='/fast_data/kvm/images/07x2.qcow2'/>
83c83
<       <mac address='52:54:00:01:7c:fc'/>
---
>       <mac address='52:54:00:c6:4a:e4'/>

Is there something else that's needed after cloning a domain with virt-clone?

2020-07-28 17:10 BST Update

OK, this seems like it might be something simple—I can create a new guest called 07x3 and that starts fine. Since I've been rebuilding and testing 07x2 a few times, it looks like something got stuck. To remove & recreate a domain, I've been doing this:

# virsh destroy 07x2
# virsh undefine 07x2
# rm 07x2.qcow2

That has worked for all other domains, but 07x2 always results in that error. So I guess the new question is how to find out what else I need to remove / clear / purge before being able to recreate it?

2020-08-14 11:31 BST Update

Based on @gediz-gÜrsu's answer, I tried this:

  1. # cp -a /fast_data/kvm/images/07xTemplate.qcow2 /fast_data/kvm/images/07x2.qcow2
  2. # cp -a /usr/local/etc/libvirt/qemu/07xTemplate.xml /usr/local/etc/libvirt/qemu/07x2.xml
  3. Edited that xml, replacing the name, uuid, disk source and mac address
  4. # virsh define /usr/local/etc/libvirt/qemu/07x2.xml
  5. Used guestmount to update the disk image settings (IP address, etc)
  6. # virsh start 07x2

I got exactly the same error, and no log file called 07x2-fs0-virtiofsd.log. 07x2.log looks exactly as in the original question. So I guess we can rule out virt-clone as the cause of the problem.

However, running lsof | grep virtiofsd.log yielded this:

virtlogd   3255                   root   15w      REG              253,1           0    5773534 /usr/local/var/log/libvirt/qemu/07x1-fs0-virtiofsd.log
virtlogd   3255                   root   17w      REG              253,1           0    5773535 /usr/local/var/log/libvirt/qemu/07x1-fs1-virtiofsd.log
virtlogd   3255                   root   19w      REG              253,1           0    5773536 /usr/local/var/log/libvirt/qemu/07x1-fs2-virtiofsd.log
virtlogd   3255                   root   21w      REG              253,1           0    5773537 /usr/local/var/log/libvirt/qemu/07x1-fs3-virtiofsd.log
virtlogd   3255                   root   23w      REG              253,1           0    5773538 /usr/local/var/log/libvirt/qemu/07x1-fs4-virtiofsd.log
virtlogd   3255                   root   27w      REG              253,1           0    5767384 /usr/local/var/log/libvirt/qemu/07x2-fs0-virtiofsd.log (deleted)
virtlogd   3255                   root   29w      REG              253,1           0    5767385 /usr/local/var/log/libvirt/qemu/07x2-fs1-virtiofsd.log (deleted)
virtlogd   3255                   root   31w      REG              253,1           0    5773542 /usr/local/var/log/libvirt/qemu/07x3-fs0-virtiofsd.log
virtlogd   3255                   root   33w      REG              253,1           0    5773543 /usr/local/var/log/libvirt/qemu/07x3-fs1-virtiofsd.log
virtlogd   3255                   root   35w      REG              253,1           0    5773807 /usr/local/var/log/libvirt/qemu/07x3-fs2-virtiofsd.log
virtlogd   3255                   root   37w      REG              253,1           0    5773808 /usr/local/var/log/libvirt/qemu/07x3-fs3-virtiofsd.log
virtlogd   3255                   root   39w      REG              253,1           0    5774205 /usr/local/var/log/libvirt/qemu/07x3-fs4-virtiofsd.log

Sorry, it's wide—scroll across to see the 2 (deleted) entries for what I guess is the cause of the problem. So, the solution appeared to be simply service virtlogd restart. I'm now able to start that domain successfully!

dsl101
  • 433
  • 1
  • 8
  • 14
  • Have you tried actually looking at `/usr/local/var/log/libvirt/qemu/07x2-fs0-virtiofsd.log` to see what is there? – Michael Hampton Jul 28 '20 at 16:29
  • Yes, as I mentioned, there is no such file... – dsl101 Jul 28 '20 at 16:43
  • Ah, I found where you mentioned it. But did you check the directory and its parent directories? That path is rather odd. – Michael Hampton Jul 28 '20 at 16:48
  • Yes, there's no such log file anywhere. I suspect the path issue is because this is a locally compiled version of libvirtd. I also verified that the 07x2.qcow2 file isn't the issue by changing the new domain name in the virt-clone command to 07x2New—that would boot up just fine. It seems _something_ is objecting to the domain name 07x2. Of course I could just skip that one and go straight to 07x3, but I really don't like not knowing what caused this, in case it happens again... – dsl101 Jul 28 '20 at 17:34

1 Answers1

0

If it is not automated and if it happens again, next time instead of using virt-clone try to use virsh edit with cp -ar.

Change the uuid name mac and new names of copied drives.

You can also use virt-manager to add and remove drives and change name it is very practical when used with ssh -X or -Y.

The "resource busy cant open file" may be a permission issue if lsof does not give anything about this file ...

lsof |grep virtiofsd.log
Gediz GÜRSU
  • 536
  • 4
  • 12
  • Been away for 10 days, but thanks for the pointers—I updated the question with full details of your first suggestion (not the cause), but your second suggestion led to the solution (an open file handle to a deleted log file). Perhaps you could add what actually solved it (service virtlogd restart), in case people don't make it all the way through my long explanation :). – dsl101 Aug 14 '20 at 11:51