ovirt-img: fix logging config

[aesteve-rh]

In ovit-img log_file defaults to /dev/stderr fd,
and is passed to logging configurator through
filename argument.

However, this is not correct, filename only is
used for files. File descriptions shall go
as stream parameters.

Otherwise the tool breaks with
'OSError: [Errno 29] Illegal seek'
in an internal logging module.
Reproduced with Python 3.6 in CentOS Stream 8.

To solve it, default log_file to None instead, so
that logging configuration does not use a filename
and falls back to the stream argument, which defaults
to stderr.

This PR implements part of #72.

Fixes: #113
Fixes: a2bbe12
Signed-off-by: Albert Esteve aesteve@redhat.com

[nirs]

Nice catch 👍

[aesteve-rh]

This should theoretically fix the issue now but the logs get lost somewhere. They do not get printed through stdout, nor stderr. If I specify a file I can see the logs correctly in the file though. But I'm not sure where the logs are sent with default parameters.

I'll continue investigating tomorrow.

[rokkbert]

This should theoretically fix the issue now but the logs get lost somewhere. They do not get printed through stdout, nor stderr. If I specify a file I can see the logs correctly in the file though. But I'm not sure where the logs are sent with default parameters.

Seems to work ok for me:

rob@host-vdsm ovirt-imageio]$ ./ovirt-img download-disk  --log-level debug -c engine1 f931f3b6-669a-46d2-8309-f23d0575cdaf diskimage  > stdout-file
2022-07-27 19:42:04,608 DEBUG   (MainThread) [ovirt] Found host hardware id: c6222167-c316-4be6-aa63-98b0063fda3f
2022-07-27 19:42:04,616 DEBUG   (MainThread) [ovirt] Found data center: Default
2022-07-27 19:42:04,630 DEBUG   (MainThread) [ovirt] Using host id 4802bfd0-77fe-41f5-a957-ff61322f1662
2022-07-27 19:42:04,630 INFO    (MainThread) [ovirt] Creating transfer image=Disk(id='f931f3b6-669a-46d2-8309-f23d0575cdaf') direction=download host=Host(name='host-vdsm') backup=None shallow=None timeout_policy=cancel
...

Without debug log level it's hard to say, because nothing normally gets logged at warning level.

[nirs]

This should theoretically fix the issue now but the logs get lost somewhere. They do not get printed through stdout, nor stderr. If I specify a file I can see the logs correctly in the file though. But I'm not sure where the logs are sent with default parameters.

Seems to work ok for me:
...
2022-07-27 19:42:04,630 INFO (MainThread) [ovirt] Creating transfer image=Disk(id='f931f3b6-669a-46d2-8309-f23d0575cdaf') direction=download host=Host(name='host-vdsm') backup=None shallow=None timeout_policy=cancel

Without debug log level it's hard to say, because nothing normally gets logged at warning level.

--log-level=info works, your output shows INFO logs.

[nirs]

This patch works on Fedora and CentOS Stream 8:

diff --git a/ovirt_imageio/client/_options.py b/ovirt_imageio/client/_options.py
index 42a073c..048a486 100644
--- a/ovirt_imageio/client/_options.py
+++ b/ovirt_imageio/client/_options.py
@@ -117,8 +117,7 @@ class Parser:
             name="log_file",
             args=["--log-file"],
             config=True,
-            default="/dev/stderr",
-            help="Log file name (default: /dev/stderr).",
+            help="Log to file instead of stderr.",
         ),
         Option(
             name="log_level",

Example run:

$ ./ovirt-img download-disk -c engine adb9b2c7-32a9-4e87-894c-710de7165086 /data/fc/tmp/dl.qcow2 --log-level info
2022-07-27 22:05:55,782 INFO    (MainThread) [ovirt] Creating transfer image=Disk(id='adb9b2c7-32a9-4e87-894c-710de7165086') direction=download host=None backup=None shallow=None timeout_policy=cancel
2022-07-27 22:05:56,386 INFO    (MainThread) [ovirt] Transfer 'd5018efd-fa92-4014-af71-6dfe80c82ae5' ready on host 'host4' in 0.6 seconds
2022-07-27 22:05:58,205 INFO    (MainThread) [ovirt] Finalizing transfer 'd5018efd-fa92-4014-af71-6dfe80c82ae5'
2022-07-27 22:06:00,238 INFO    (MainThread) [ovirt] Transfer 'd5018efd-fa92-4014-af71-6dfe80c82ae5' finalized in 2.0 seconds
[ 100% ] 6.00 GiB, 4.60 s, 1.30 GiB/s | download completed                     

[aesteve-rh]

If I run download-disk with a wrong disk UUID I do not see the DEBUG logs in the stderr output:
./ovirt-img download-disk --config engine <wrong_uuid> image.qcow2 --log-level debug

However, if redirected to a file, I can see many logs:

$ ./ovirt-img download-disk --config engine <wrong_uuid> image.qcow2 --log-level debug --log-file err.log
...
$ cat err.log
2022-07-27 18:02:02,430 DEBUG   (MainThread) [ovirt] * Trying 127.0.0.1...
2022-07-27 18:02:02,430 DEBUG   (MainThread) [ovirt] * TCP_NODELAY set
2022-07-27 18:02:02,430 DEBUG   (MainThread) [ovirt] * Connected to test-ovirt.local (127.0.0.1) port 443 (#0)
2022-07-27 18:02:02,431 DEBUG   (MainThread) [ovirt] * ALPN, offering http/1.1
2022-07-27 18:02:02,431 DEBUG   (MainThread) [ovirt] * successfully set certificate verify locations:
2022-07-27 18:02:02,431 DEBUG   (MainThread) [ovirt] * CAfile: /home/aesteve/cert.pem
2022-07-27 18:02:02,431 DEBUG   (MainThread) [ovirt] *   CApath: none
...

But is true that with a normal run, I get all logs printed to stderr as expected. I'll do a couple more tests and move on with this approach if I don't find any better option.

[nirs]

I reproduced the issue, this is not python 3.6 issue. Looks like debug logs from the sdk are missing when using --log-level debug and default log_level (None).

It is my fault, this patch fixes the issue:

diff --git a/ovirt_imageio/client/_options.py b/ovirt_imageio/client/_options.py
index 42a073c..048a486 100644
--- a/ovirt_imageio/client/_options.py
+++ b/ovirt_imageio/client/_options.py
@@ -117,8 +117,7 @@ class Parser:
             name="log_file",
             args=["--log-file"],
             config=True,
-            default="/dev/stderr",
-            help="Log file name (default: /dev/stderr).",
+            help="Log to file instead of stderr.",
         ),
         Option(
             name="log_level",
diff --git a/ovirt_imageio/client/_ovirt.py b/ovirt_imageio/client/_ovirt.py
index f2ce99b..7b49f69 100644
--- a/ovirt_imageio/client/_ovirt.py
+++ b/ovirt_imageio/client/_ovirt.py
@@ -46,7 +46,7 @@ def connect(args):
         username=args.username,
         password=args.password,
         ca_file=args.cafile,
-        log=log if args.log_file else None,
+        log=log,
         debug=args.log_level == "debug")

But we also need to fix the tests assuming /dev/stderr.

[rokkbert]

--log-level=info works, your output shows INFO logs.

Yes, sorry, I meant without specifying a log level at all. The default is warning, I thought, and there usually are no warnings, so I can't see if they would appear on the console.

[rokkbert]

If I run download-disk with a wrong disk UUID I do not see the DEBUG logs in the stderr output:
./ovirt-img download-disk --config engine <wrong_uuid> image.qcow2 --log-level debug

Interesting. I do, with the current version:

rob@host-vdsm ovirt-imageio]$ ./ovirt-img download-disk -c engine1 foo image.qcow2 --log-level debug
2022-07-28 12:30:02,913 DEBUG   (MainThread) [ovirt] * Trying 192.168.122.244...
2022-07-28 12:30:02,914 DEBUG   (MainThread) [ovirt] * TCP_NODELAY set
2022-07-28 12:30:02,914 DEBUG   (MainThread) [ovirt] * Connected to rob-ovirt-engine.local (192.168.122.244) port 443 (#0)
...
  File "/usr/lib64/python3.6/site-packages/ovirtsdk4/service.py", line 118, in _raise_error
    raise error
ovirtsdk4.NotFoundError: HTTP response code is 404.

[nirs]

Interesting. I do, with the current version:

Current version is fixed.