Bug 1755460

Logs:
https://drive.google.com/drive/u/0/folders/1gX4wwdi79pBz356Q6xbr3pQMP6Lu4dC5

(In reply to Ilanit Stein from comment #0)
Comment 0 does not include enough info, let me add the missing info, taken from
v2v-devel thread.


v2v-import log error:

nbdkit: python[1]: debug: pwrite count=2097152 offset=712746467328 fua=0
nbdkit: debug: python: unload
nbdkit: debug: vddk: unload
nbdkit: debug: VDDK call: VixDiskLib_Exit ()
nbdkit: debug: VixDiskLib: VixDiskLib_Exit: Unmatched Init calls so far: 1.
qemu-img: error while writing sector 1392087040: Input/output error
nbdkit: debug: VixDiskLibVim: VixDiskLibVim_Exit: Clean up.

This log fragment does not show any useful info.


ovirt-imageio-daemon.log:

These are the last messages from daemon.log:
(all previous messages seem to be normal read/write messages).

2019-09-25 02:04:50,473 INFO    (Thread-5) [images] [local] WRITE size=2097152 offset=712742273024 flush=False ticket=68ea2ffa-8370-4727-97f1-2d138992de64
2019-09-25 02:04:50,512 INFO    (Thread-5) [images] [local] WRITE size=2097152 offset=712744370176 flush=False ticket=68ea2ffa-8370-4727-97f1-2d138992de64
2019-09-25 02:04:50,548 INFO    (Thread-5) [images] [local] WRITE size=2097152 offset=712746467328 flush=False ticket=68ea2ffa-8370-4727-97f1-2d138992de64
2019-09-25 02:04:50,588 INFO    (Thread-5) [http] CLOSE client=local [connection=11727.200110/1, dispatch=4191.419305/727430, operation=3758.203536/727430, read=534.690564/515292, write=1949.710381/515292, zero=
80.659942/212138]
2019-09-25 02:05:09,053 INFO    (Thread-1364) [http] OPEN client=local
2019-09-25 02:05:09,054 INFO    (Thread-1364) [tickets] [local] REMOVE ticket=68ea2ffa-8370-4727-97f1-2d138992de64
2019-09-25 02:05:09,055 INFO    (Thread-1364) [http] CLOSE client=local [connection=0.001648/1, dispatch=0.000488/1]

This log show normal upload ending at abnormally (client closed the connection without flushing).
The client had some issue or crashed.

There are no logs attached to the bug, so we don't know anything else.


This does not look like ovirt-imageio-daemon issue or RHV issue. Please move
the bug to virt-v2v and attach complete logs.

Ilanit, can you please check if this failure is from the same run when CFME killed conversions? If yes please close this and track an IMS fix instead (to fix the polling frequency inside CFME IMS code)

Ilanit, could you collect the journal from the machine running virt-v2v?
This does look quite similar to the cezdata bug from here, but I can't
prove that without the journal.

# journalctl -S "2019-09-25" -U "2019-09-26" > journal.log

Created attachment 1621888 [details]
journal.log from Sep 25, 2019

Thanks Ilanit for getting back so quickly.

This is the same as the cezdata bug, because in the journal we can
see that CFME is logging in and sending a kill signal to virt-v2v (or
perhaps to a related process):

Sep 25 02:04:49 leopard03.qa.lab.tlv.redhat.com sshd[36961]: Accepted publickey 
for root from 10.35.161.44 port 44844 ssh2: RSA SHA256:g5Bu+bCcBH/JcIKTqU/bwBNOk
ydRI04Stgrxk2CygOY
Sep 25 02:04:50 leopard03.qa.lab.tlv.redhat.com systemd-logind[3281]: New sessio
n 1977 of user root.
Sep 25 02:04:50 leopard03.qa.lab.tlv.redhat.com systemd[1]: Started Session 1977
 of user root.
Sep 25 02:04:50 leopard03.qa.lab.tlv.redhat.com sshd[36961]: pam_unix(sshd:session): session opened for user root by (uid=0)
Sep 25 02:04:50 leopard03.qa.lab.tlv.redhat.com sudo[36981]:     root : TTY=unknown ; PWD=/root ; USER=root ; COMMAND=/bin/kill -s TERM 14115

and we can see from the wrapper log that virt-v2v is reported dead about a second later:

2019-09-25 02:04:51,424:INFO: virt-v2v terminated with return code 15 (virt-v2v-wrapper:1914)

*** This bug has been marked as a duplicate of bug 1755632 ***