Bug 1820221

Created attachment 1675780 [details]
virt-v2v.6.log : the file name is on the same line as "virt-v2v:" and the migration succeeded from a wrapper perspective.

Created attachment 1675781 [details]
virt-v2v.7.log: the file name is on a new line after "virt-v2v:" and the migration failed from a wrapper perspective.

Wrapping code here:
https://github.com/libguestfs/libguestfs-common/blob/be42b0b8a1a436483a04feb889f9f2b58bd4342e/mlstdutils/std_utils.ml#L549
called from:
https://github.com/libguestfs/libguestfs-common/blob/be42b0b8a1a436483a04feb889f9f2b58bd4342e/mltools/tools_utils.ml#L155

The thought is that, as with ANSI (colour) codes, we might suppress
wrapping if the output is being consumed by a program rather than
being sent to the console.  It's a pretty simple change to make.

I should also note that if you look a few lines earlier:
https://github.com/libguestfs/libguestfs-common/blob/be42b0b8a1a436483a04feb889f9f2b58bd4342e/mltools/tools_utils.ml#L152
you can see that we do log the "raw" message as JSON output,
if you use the --machine-readable option.

For more information:

http://libguestfs.org/guestfs.3.html#advanced-machine-readable-output

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

This bug was closed in error by a process we do not control.  My apologies,
reopening.

(In reply to Richard W.M. Jones from comment #3)
> Wrapping code here:
> https://github.com/libguestfs/libguestfs-common/blob/
> be42b0b8a1a436483a04feb889f9f2b58bd4342e/mlstdutils/std_utils.ml#L549
> called from:
> https://github.com/libguestfs/libguestfs-common/blob/
> be42b0b8a1a436483a04feb889f9f2b58bd4342e/mltools/tools_utils.ml#L155
> 
> The thought is that, as with ANSI (colour) codes, we might suppress
> wrapping if the output is being consumed by a program rather than
> being sent to the console.  It's a pretty simple change to make.

I guess we'd move "istty" from "mltools/tools_utils.ml" to "mlstdutils/std_utils.ml" (and export it too). Tools_utils depends on Std_utils, the latter defines "wrap", so "wrap" would use "istty" internally, after moving "istty".

Alternatively, don't touch Std_utils at all, leave "wrap" as-is, only modify "error", "warning", and "info" in "mltools/tools_utils.ml", to avoid calling "wrap" in case "istty" (which would remain internal to Std_utils) returned "true" for stderr / stdout.

Apart from "error", "warning", and "info" in "mltools/tools_utils.ml" in libguestfs-common, the only "wrap" caller seems to be "resize/resize.ml" in guestfs-tools. I don't understand why this utility (i.e., virt-resize) doesn't just call "info". In its current state, it blocks me from adding the tty check only to "mltools/tools_utils.ml".

One of the "wrap" calls in "virt-resize" even goes back to commit afec56ea3d26 ("Rewrite virt-resize in OCaml.", 2011-04-09), which commit even introduced a local "wrap" function, in "resize/utils.ml".

That local "wrap" function seems to have disappeared into libguestfs-common (I think? "mllib"?), via the following series of commits:

9960ac1a0fdf ("sparsify: Re-use progress bar wrapper code from virt-resize.", 2012-10-11)
7213910cf1e3 ("OCaml tools: Use Common_gettext and Common_utils modules.", 2013-03-28)
4566e33ff7c5 ("tools: Move shared OCaml code to mllib/ directory.", 2013-09-24)

So as of now (82fa31dc30a8), there is no "wrap" function defined in guestfs-tools, but "resize/resize.ml" still uses "wrap" directly. Rich, can we change that to "info"? Thanks.

> Apart from "error", "warning", and "info" in "mltools/tools_utils.ml" in libguestfs-common,
> the only "wrap" caller seems to be "resize/resize.ml" in guestfs-tools.

(https://github.com/rwmjones/guestfs-tools/blob/7d5d5e921d3d483a997f40566c1ccabf8a689a8a/resize/resize.ml#L941 and further on in this file)

I'm sure this is just a historical oversight and these should be replaced by calls
to info as you say.

[guestfs-tools PATCH] virt-resize: replace "wrap" calls with calls to "info"
Message-Id: <20220209131738.12004-1-lersek>
https://listman.redhat.com/archives/libguestfs/2022-February/msg00131.html

(In reply to Laszlo Ersek from comment #14)
> [guestfs-tools PATCH] virt-resize: replace "wrap" calls with calls to "info"
> Message-Id: <20220209131738.12004-1-lersek>
> https://listman.redhat.com/archives/libguestfs/2022-February/msg00131.html

Commit 626f0441d251.

(In reply to Laszlo Ersek from comment #11)

> Alternatively, don't touch Std_utils at all, leave "wrap" as-is, only
> modify "error", "warning", and "info" in "mltools/tools_utils.ml", to
> avoid calling "wrap" in case "istty" (which would remain internal to
> Std_utils) returned "true" for stderr / stdout.

Rich points out on the mailing list that with the patch in comment 15
upstream, we can demote "wrap" to helper function for "error",
"warning", and "info"; IOW we can move "wrap" to
"mltools/tools_utils.ml", and remove its public interface from
"mlstdutils/std_utils.mli".

[libguestfs-common PATCH 0/3] don't wrap log messages written to non-TTYs
Message-Id: <20220211153225.17424-1-lersek>
https://listman.redhat.com/archives/libguestfs/2022-February/msg00171.html

(In reply to Laszlo Ersek from comment #17)
> [libguestfs-common PATCH 0/3] don't wrap log messages written to non-TTYs
> Message-Id: <20220211153225.17424-1-lersek>
> https://listman.redhat.com/archives/libguestfs/2022-February/msg00171.html

Merged into upstream libguestfs-common as commit range 5b5fac3e0b10..41126802097f.

Related: libguestfs commit 19cc3dbcc4c4 ("Update common submodule", 2022-02-15).

I've learned from painful experience that backporting submodule
patches is difficult, so I suggest that we leave this bug to RHEL 9.1
and get the fix through a rebase.

Works for me, even more so because we'd have to clone this BZ for libguestfs and guestfs-tools as well.

Related: guestfs-tools commit 59eeed778ca2 ("Update common submodule, document "--wrap" in the manuals", 2022-02-15).

Related: virt-v2v commit f77770eed0e3 ("Update common submodule, document "--wrap" in the manual", 2022-02-15).

Surprise!  We can get this through the rebasing necessary
for other bugs in RHEL 9.0, in particular bug 2039255.

Test the bug with virt-v2v-1.45.99-1.el9.x86_64

Steps:
1.Check if "Std_utils.wrap" is moved from mlstdutils/std_utils.ml to mltools/tools_utils.ml
1.1 # rpmbuild -rp virt-v2v-1.45.99-1.el9.src.rpm

1.2 # cat /root/rpmbuild/BUILD/virt-v2v-1.45.99/common/mltools/tools_utils.ml |grep Std_utils.wrap
  if Std_utils.wrap () || istty chan then

1.3 # cat /root/rpmbuild/BUILD/virt-v2v-1.45.99/common/mlstdutils/std_utils.ml |grep Std_utils.wrap
nothing


2.Check new option '--wrap'

2.1 # man virt-v2v |grep wrap -A 1
       --wrap
           Wrap error, warning, and informative messages.  This is the default when the output is a tty.  If the
           output of the program is redirected to a file, wrapping is disabled unless you use this option.


2.2 # virt-v2v --help |grep wrap
  --wrap                              Wrap log messages even if not tty
    

2.3 Compare the v2v debug logs when convert guest 'without --wrap' or 'with --wrap'

2.3.1 # virt-v2v -ic vpx://root.198.169/data/10.73.199.217/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io  vddk-thumbprint=B5:52:1F:B4:21:09:45:24:51:32:56:F6:63:6A:93:5D:54:08:2D:78  -ip /home/passwd  -o rhv-upload -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx7.0-rhel9.0-x86_64 -v -x |& tee > virt-v2v-no-wrap-option.log

2.3.2 # virt-v2v -ic vpx://root.198.169/data/10.73.199.217/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io  vddk-thumbprint=B5:52:1F:B4:21:09:45:24:51:32:56:F6:63:6A:93:5D:54:08:2D:78  -ip /home/passwd  -o rhv-upload -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx7.0-rhel9.0-x86_64 --wrap -v -x |& tee > virt-v2v-with-wrap-option.log

2.3.3 Found some difference info in logs, for example:
# diff virt-v2v-no-wrap-option.log virt-v2v-with-wrap-option.log
.....
.....
< nbdkit: debug: bound to unix socket /tmp/v2v.vFdQns/in0
< nbdkit: debug: written pidfile /tmp/v2vnbdkit.YFxABl/nbdkit1.pid
---
> nbdkit: debug: bound to unix socket /tmp/v2v.Ec60J8/in0
> nbdkit: debug: written pidfile /tmp/v2vnbdkit.fSQY8I/nbdkit1.pid
246a247
> nbdkit: debug: 2022-02-16T12:21:24.845-05:00 trivia -[25066] [Originator@6876 sub=ThreadPool] Thread enlisted
249a251,252
> nbdkit: debug: 2022-02-16T12:21:24.845-05:00 trivia -[25067] [Originator@6876 sub=ThreadPool] Thread enlisted
> nbdkit: debug: 2022-02-16T12:21:24.845-05:00 info -[25066] [Originator@6876 sub=ThreadPool] Entering IO thread loop
252a256
> nbdkit: debug: 2022-02-16T12:21:24.845-05:00 info -[25067] [Originator@6876 sub=ThreadPool] Entering fair thread loop
.....
.....
< supermin: creati[    0.732940] EXT4-fs (sdb): mounting ext2 file system using the ext4 subsystem
< ng /dev/root as block special 8:16
---
> supermin: creating /dev/root as [    0.741572] EXT4-fs (sdb): mounting ext2 file system using the ext4 subsystem
> block special 8:16
.....
.....
< fs: /dev/rhel_bootp-73-199-156/root (xfs) role:libguestfs: trace: v2v: inspect_os = ["/dev/rhel_bootp-73-199-156/root"]
< libguestfs: trace: v2v: inspect_get_format "/dev/rhel_bootp-73-199-156/root"
<  root
---
> fs: /dev/rhel_bootp-73-199-156/root (xfs) role: root
<     package_format: rpm
---
>     package_formatlibguestfs: trace: v2v: inspect_os = ["/dev/rhel_bootp-73-199-156/root"]
> libguestfs: trace: v2v: inspect_get_format "/dev/rhel_bootp-73-199-156/root"
> : rpm
.....
.....
< guestfsd: => aug_get (0x13) took 0.00 secs
< libguestfs: trace: v2v: aug_get = "/usr/share/augeas/lenses/dist/shellvars.aug:251.12-.60:"
---
> guestfsd: => aug_get (0x13) took libguestfs: trace: v2v: aug_get = "/usr/share/augeas/lenses/dist/shellvars.aug:251.12-.60:"
> 0.00 secs
.....
.....
> guestfsd: => aug_get (0x13) took 0.00 secs
3098c3102,3103
< guestfsd: => aug_get libguestfs: trace: v2v: aug_get = "4"
---
> guestfsd: => aug_get (0x13) took 0.00 secs
> libguestfs: trace: v2v: aug_get = "4"
3100,3102d3104
< (0x13) took 0.00 secs
.....
.....

2.3.4 
# cat virt-v2v-no-wrap-option.log |wc -l
16259
# cat virt-v2v-with-wrap-option.log |wc -l
16265

2.3.5
#ls -la
2944 -rw-r--r--. 1 root root 3012803 Feb 16 12:19 virt-v2v-no-wrap-option.log
2944 -rw-r--r--. 1 root root 3013391 Feb 16 12:25 virt-v2v-with-wrap-option.log



Hi Laszlo,
  Could you please help to confirm if the result of step2 is expected and above steps are enough to verify the bug?

It'll only affect log lines printed by virt-v2v itself.  Most of the
output of virt-v2v -v -x is produced by other programs so isn't
affected (it wasn't wrapped before).

Here's a test ...

virt-v2v 1.45.97:

# output is to tty, and is wrapped

$ virt-v2v -i disk /nothere -o null
virt-v2v: error: access: No such file or directory: /nothere

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

# output is to pipe, and is wrapped

$ virt-v2v -i disk /nothere -o null |& cat
virt-v2v: error: access: No such file or directory: /nothere

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]


virt-v2v 1.45.99:

# output is to tty, and is wrapped

$ virt-v2v -i disk /nothere -o null
[   0.0] Setting up the source: -i disk /nothere
virt-v2v: error: access: No such file or directory: /nothere

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

# output is to a pipe, and is NOT wrapped

$ virt-v2v -i disk /nothere -o null |& cat
[   0.0] Setting up the source: -i disk /nothere
virt-v2v: error: access: No such file or directory: /nothere

If reporting bugs, run virt-v2v with debugging enabled and include the complete output:

  virt-v2v -v -x [...]

# old behaviour to a pipe restored using --wrap option

$ virt-v2v -i disk /nothere -o null --wrap |& cat
[   0.0] Setting up the source: -i disk /nothere
virt-v2v: error: access: No such file or directory: /nothere

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

Right, wrapping affects only "info", "warning" and "error" calls made from OCaml code in libguestfs, virt-v2v, and guestfs-tools. In particular, "debug" calls are not wrapped (they have never been wrapped -- code that logs debug messages is free to format those messages as it likes, and "wrapping" has never been relevant there). Thanks!

Thanks Richard and Laszlo, verify the bug with virt-v2v-1.45.99-1.el9.x86_64 according to comment27

Steps:
1.Convert a running guest from VMware by v2v, the v2v error is wrapped

# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io vddk-thumbprint=1F:97:34:5F:B6:C2:BA:66:46:CB:1A:71:76:7D:6B:50:1E:03:00:EA  -ip /home/passwd   -o rhv-upload  -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx6.7-ubuntu18.04LTS-x86_64-bug1683888  
[   0.0] Setting up the source: -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk esx6.7-ubuntu18.04LTS-x86_64-bug1683888
virt-v2v: error: libvirt domain 
‘esx6.7-ubuntu18.04LTS-x86_64-bug1683888’ is running or paused.  It 
must be shut down in order to perform virt-v2v conversion

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

2.Convert a running guest from VMware by v2v and make output a pipe, the v2v error is not wrapped

# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io vddk-thumbprint=1F:97:34:5F:B6:C2:BA:66:46:CB:1A:71:76:7D:6B:50:1E:03:00:EA  -ip /home/passwd   -o rhv-upload  -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx6.7-ubuntu18.04LTS-x86_64-bug1683888  |& cat
[   0.0] Setting up the source: -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk esx6.7-ubuntu18.04LTS-x86_64-bug1683888
virt-v2v: error: libvirt domain ‘esx6.7-ubuntu18.04LTS-x86_64-bug1683888’ is running or paused.  It must be shut down in order to perform virt-v2v conversion

If reporting bugs, run virt-v2v with debugging enabled and include the complete output:

  virt-v2v -v -x [...]


3.Convert a running guest from VMware by v2v and make output a pipe and add '--wrap' to command line,  the v2v error is wrapped

# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io vddk-thumbprint=1F:97:34:5F:B6:C2:BA:66:46:CB:1A:71:76:7D:6B:50:1E:03:00:EA  -ip /home/passwd   -o rhv-upload  -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx6.7-ubuntu18.04LTS-x86_64-bug1683888 --wrap |& cat
[   0.0] Setting up the source: -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk esx6.7-ubuntu18.04LTS-x86_64-bug1683888
virt-v2v: error: libvirt domain 
‘esx6.7-ubuntu18.04LTS-x86_64-bug1683888’ is running or paused.  It 
must be shut down in order to perform virt-v2v conversion

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]

4.Convert a running guest from VMware by v2v and make output a pipe and add '-w' option to command line,  the v2v error is wrapped as well

# virt-v2v -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk -io vddk-libdir=/home/vddk7.0.2 -io vddk-thumbprint=1F:97:34:5F:B6:C2:BA:66:46:CB:1A:71:76:7D:6B:50:1E:03:00:EA  -ip /home/passwd   -o rhv-upload  -oc https://dell-per740-22.lab.eng.pek2.redhat.com/ovirt-engine/api  -op /home/rhvpasswd  -os nfs_data -b ovirtmgmt esx6.7-ubuntu18.04LTS-x86_64-bug1683888  -w |& cat
[   0.0] Setting up the source: -i libvirt -ic vpx://root.73.141/data/10.73.75.219/?no_verify=1 -it vddk esx6.7-ubuntu18.04LTS-x86_64-bug1683888
virt-v2v: error: libvirt domain 
‘esx6.7-ubuntu18.04LTS-x86_64-bug1683888’ is running or paused.  It 
must be shut down in order to perform virt-v2v conversion

If reporting bugs, run virt-v2v with debugging enabled and include the 
complete output:

  virt-v2v -v -x [...]



Hi Laszlo,

   Please help to step4, short option "-w" works as '--wrap' in v2v, is it expected?

(In reply to mxie from comment #31)

> Hi Laszlo,
> 
>    Please help to step4, short option "-w" works as '--wrap' in v2v, is it
> expected?

I was pretty surprised about this myself, after I had removed the short "-w" option, at Rich's request, and in my testing, "-w" continued to work.

The solution to this riddle is that (a) "--wrap" is also accepted with a single dash "-wrap", and (b) well-defined (= unique) prefixes of any long option work just as fine as the complete long option itself.

In other words, you can replace "--wrap" with (for example) "--wra" and "-wra" both. And a special case of this is "-w".

You can double-check with (e.g.) "-wr" wrapping as well, but "-wR" being refused.

Getopt in OCaml seems to come from <https://opam.ocaml.org/packages/getopt/>, and it refers to GNU getopt and getopt_long. The latter are documented at <http://www.gnu.org/software/libc/manual/html_node/Getopt-Long-Options.html>, and are consistent with the above.

Once we introduce an actual short "-w" option, we'll have to see if it works automatically as intended (i.e., "-w" would be parsed as "-w", and not as a shorthand of "--wrap"); at that time, if the result is unexpected, we might have to reconfigure how the Getopt module parses the command line options. But at the moment, this behavior is sort of expected.

Thanks!

... For another example, the following command:

  virt-resize --expand /dev/sda1 test1.img test1.resized.img
              ^^^^^^^^

works OK in the following form as well:

  virt-resize -exp /dev/sda1 test1.img test1.resized.img
              ^^^^

(Note the single hyphen, and the truncated, but still unique, option name.)

Thanks Laszlo, move the bug from ON_QA to VERIFIED according to comment26 ~ comment32

A bit surprising, especially the single dash multi-character
forms are permitted.  But I guess it's fine, hopefully :)

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: virt-v2v), 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/RHEA-2022:2566