9:34 p.m.
On Sat, Mar 28, 2020 at 5:00 AM Gianluca Cecchi
<gianluca.cecchi(a)gmail.com> wrote:
...
Further information.
What I see around time frame in gluster brick log file gluster_bricks-vmstore-vmstore.log
(timestamp is behind 1 hour in log file)
[2020-03-27 23:30:38.575808] I [MSGID: 101055] [client_t.c:436:gf_client_unref]
0-vmstore-server: Shutting down connection
CTX_ID:6e8f70b8-1946-4505-860f-be90e5807cb3-GRAPH_ID:0-PID:223418-HOST:ovirt.mydomain.local-PC_NAME:vmstore-client-0-RECON_NO:-0
[2020-03-27 23:35:15.281449] E [MSGID: 113072] [posix-inode-fd-ops.c:1886:posix_writev]
0-vmstore-posix: write failed: offset 0, [Invalid argument]
[2020-03-27 23:35:15.281545] E [MSGID: 115067]
[server-rpc-fops_v2.c:1373:server4_writev_cbk] 0-vmstore-server: 34139378: WRITEV 10
(00d9fe81-8a31-498e-8401-7b9d1477378e), client:
CTX_ID:d04437ba-ef98-43df-864f-5e9d3738620a-GRAPH_ID:0-PID:27687-HOST:ovirt.mydomain.local-PC_NAME:vmstore-client-0-RECON_NO:-0,
error-xlator: vmstore-posix [Invalid argument]
[2020-03-27 23:40:15.415794] E [MSGID: 113072] [posix-inode-fd-ops.c:1886:posix_writev]
0-vmstore-posix: write failed: offset 0, [Invalid argument]
Invalid arguments are expected when activating a storage domain, and
every 5 minutes when
storage domain are refreshed. The writes are performed to to a temporary file at
/rhev/data-center/mnt/server:_path/.prob-random-uuid
These logs do not show the path, so we don't know if the writes are
related to block size probing.
But in vdsm log we see:
2020-03-27 00:40:08,979+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
This call happens when vdsm is refreshing storage domain. Right before
this log, vdsm try to detect the underlying
storage block size.
So it looks like the gluster logs are related to block size probing
and are not related to the
I/O error that caused the VM to pause.
Looking at both "abnormal vm stop" and storage refresh events:
$ egrep 'Removing remnants of deleted images|abnormal vm stop' vdsm.log.18
2020-03-27 00:20:08,555+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:24:38,254+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:24:47,799+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:25:08,660+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:29:38,344+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:29:47,901+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:30:08,761+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:34:38,436+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:34:48,004+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:35:08,877+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:35:23,817+0100 INFO (libvirt/events) [virt.vm]
(vmId='1abeafb6-72b2-4893-9cc5-41846b737670') abnormal vm stop device
ua-3b753210-09f5-4c40-90fb-ded93b00d19f error eother (vm:5079)
VM disk is on:
/rhev/data-center/mnt/glusterSD/ovirtst.mydomain.storage:_vmstore/81b97244-4b69-4d49-84c4-c822387adc6a/images/3b753210-09f5-4c40-90fb-ded93b00d19f/5a4aac90-a455-41b4-80dd-cf8c1ed81893
2020-03-27 00:39:38,536+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:39:48,089+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:40:08,979+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:44:38,623+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:44:48,166+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:45:09,107+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:49:38,719+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:49:48,246+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:50:09,234+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:53:07,405+0100 INFO (libvirt/events) [virt.vm]
(vmId='6a779081-abd1-4bb1-9e9c-97f334656131') abnormal vm stop device
ua-0a91c346-23a5-4432-8af7-ae0a28f9c208 error eother (vm:5079)
VM disk is on:
/rhev/data-center/mnt/glusterSD/ovirtst.mydomain.storage:_vmstore/81b97244-4b69-4d49-84c4-c822387adc6a/images/0a91c346-23a5-4432-8af7-ae0a28f9c208/2741af0b-27fe-4f7b-a8bc-8b34b9e31cb6
2020-03-27 00:54:15,546+0100 INFO (libvirt/events) [virt.vm]
(vmId='0df701f4-2ae2-4b39-9445-d011673ddf28') abnormal vm stop device
ua-73776048-27ba-412d-a01c-9a46d267401c error eother (vm:5079)
VM disk is on:
/rhev/data-center/mnt/glusterSD/ovirtst.mydomain.storage:_vmstore/81b97244-4b69-4d49-84c4-c822387adc6a/images/73776048-27ba-412d-a01c-9a46d267401c/b3bc914f-8882-43e1-9dd0-dd7e43d60084
2020-03-27 00:54:38,830+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:54:48,344+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:55:09,361+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:59:38,933+0100 INFO (monitor/0cb6ade)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 00:59:48,431+0100 INFO (monitor/81b9724)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
2020-03-27 01:00:09,474+0100 INFO (monitor/665ff83)
[storage.StorageDomain] Removing remnants of deleted images []
(fileSD:726)
I don't see any relation between refreshes and the abnormal vm stop events.
I think the key to understanding this is to enable more verbose logs
in gluster understand what was
the failure that caused the vm to stop.
It would also help if we had detailed error logs in qemu log in
/var/log/libvirt/qemu/vm-name.log
Did you enable libvirt logs? We may have more information about the error there.
You can enable logs by modifying these lines in /etc/libvirt/libvirtd.conf:
log_filters="1:qemu 1:libvirt 4:object 4:json 4:event 1:util"
log_outputs="1:file:/var/log/libvirt/libvirtd.log"
And restart libvirt.
Note that libvirt log may be huge, so you need to watch it and change
the log level or filter after you collect what you need.
To log only warning and errors use:
log_outputs="3:file:/var/log/libvirt/libvirtd.log"
Someone from gluster should help debugging this.
Nir