Add configurable filters to qemu_img_log(), and re-write img_info_log()
to call into qemu_img_log() with a custom filter instead.

After this patch, every last call to qemu_img() is now guaranteed to
either have its return code checked for zero, OR have its output
actually visibly logged somewhere.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 tests/qemu-iotests/iotests.py | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)

diff --git a/tests/qemu-iotests/iotests.py b/tests/qemu-iotests/iotests.py
index 6af503058f..0c69327c00 100644
--- a/tests/qemu-iotests/iotests.py
+++ b/tests/qemu-iotests/iotests.py
@@ -317,10 +317,14 @@ def qemu_img_info(*args: str) -> Any:
 def qemu_img_map(*args: str) -> Any:
     return qemu_img_json('map', "--output", "json", *args)
 
-def qemu_img_log(*args: str) -> subprocess.CompletedProcess[str]:
+def qemu_img_log(
+        *args: str,
+        filters: Iterable[Callable[[str], str]] = (),
+) -> subprocess.CompletedProcess[str]:
     """
     Logged, unchecked variant of qemu_img() that allows non-zero exit codes.
 
+    By default, output will be filtered through filter_testfiles().
     If logging is perceived to be disabled, this function will fall back
     to prohibiting non-zero return codes.
 
@@ -331,7 +335,7 @@ def qemu_img_log(*args: str) -> subprocess.CompletedProcess[str]:
     :return: a CompletedProcess instance with returncode and console output.
     """
     result = qemu_img(*args, check=not logging_enabled())
-    log(result.stdout, filters=[filter_testfiles])
+    log(result.stdout, filters=filters or [filter_testfiles])
     return result
 
 def img_info_log(filename: str, filter_path: Optional[str] = None,
@@ -345,10 +349,11 @@ def img_info_log(filename: str, filter_path: Optional[str] = None,
     args += extra_args
     args.append(filename)
 
-    output = qemu_img(*args, check=False).stdout
     if not filter_path:
         filter_path = filename
-    log(filter_img_info(output, filter_path))
+    qemu_img_log(
+        *args,
+        filters=[lambda output: filter_img_info(output, filter_path)])
 
 def qemu_io_wrap_args(args: Sequence[str]) -> List[str]:
     if '-f' in args or '--image-opts' in args:
-- 
2.34.1

On 09.03.22 04:54, John Snow wrote:
> Add configurable filters to qemu_img_log(), and re-write img_info_log()
> to call into qemu_img_log() with a custom filter instead.
>
> After this patch, every last call to qemu_img() is now guaranteed to
> either have its return code checked for zero, OR have its output
> actually visibly logged somewhere.
>
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   tests/qemu-iotests/iotests.py | 13 +++++++++----
>   1 file changed, 9 insertions(+), 4 deletions(-)

 From my POV, this is a regression because before this patch (not this 
series, though, admittedly), `img_info_log()` would throw an exception 
on error, and with patch 12 being as it is, it will revert to its 
pre-series behavior of not throwing an exception.  I prefer exceptions 
to failed reference output diffs, because an exception tells me which 
call failed.

Hanna

On Thu, Mar 17, 2022 at 11:39 AM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 09.03.22 04:54, John Snow wrote:
> > Add configurable filters to qemu_img_log(), and re-write img_info_log()
> > to call into qemu_img_log() with a custom filter instead.
> >
> > After this patch, every last call to qemu_img() is now guaranteed to
> > either have its return code checked for zero, OR have its output
> > actually visibly logged somewhere.
> >
> > Signed-off-by: John Snow <jsnow@redhat.com>
> > ---
> >   tests/qemu-iotests/iotests.py | 13 +++++++++----
> >   1 file changed, 9 insertions(+), 4 deletions(-)
>
>  From my POV, this is a regression because before this patch (not this
> series, though, admittedly), `img_info_log()` would throw an exception
> on error, and with patch 12 being as it is, it will revert to its
> pre-series behavior of not throwing an exception.  I prefer exceptions
> to failed reference output diffs, because an exception tells me which
> call failed.

Hm, yeah. I just need to figure out if *all* of the qemu_img_log()
calls are safe to enforce the return code of zero on... or how many
need work if I change the default behavior. Let me see what I can do.

I suppose it's maybe a bit late to try and squeak any of this in for
freeze, so I can roll everything back up into one big series again and
send a new revision.

On Thu, Mar 17, 2022 at 1:00 PM John Snow <jsnow@redhat.com> wrote:
>
> On Thu, Mar 17, 2022 at 11:39 AM Hanna Reitz <hreitz@redhat.com> wrote:
> >
> > On 09.03.22 04:54, John Snow wrote:
> > > Add configurable filters to qemu_img_log(), and re-write img_info_log()
> > > to call into qemu_img_log() with a custom filter instead.
> > >
> > > After this patch, every last call to qemu_img() is now guaranteed to
> > > either have its return code checked for zero, OR have its output
> > > actually visibly logged somewhere.
> > >
> > > Signed-off-by: John Snow <jsnow@redhat.com>
> > > ---
> > >   tests/qemu-iotests/iotests.py | 13 +++++++++----
> > >   1 file changed, 9 insertions(+), 4 deletions(-)
> >
> >  From my POV, this is a regression because before this patch (not this
> > series, though, admittedly), `img_info_log()` would throw an exception
> > on error, and with patch 12 being as it is, it will revert to its
> > pre-series behavior of not throwing an exception.  I prefer exceptions

Oh, actually... patch #12 does this:

-    output = qemu_img_pipe(*args)
+    output = qemu_img(*args, check=False).stdout

so I never actually toggled error checking on for this function at
all. This isn't a regression.

At a glance, img_info_log() calls fail as a matter of course in 242
and 266 and ... hm, I can't quite test 207, it doesn't work for me,
even before this series.

I didn't test *all* qemu_img calls yet either, but ... I'm going to
gently suggest that "converting logged calls to qemu_img() to be
checked calls" is "for another series" material.

--js

> > to failed reference output diffs, because an exception tells me which
> > call failed.
>
> Hm, yeah. I just need to figure out if *all* of the qemu_img_log()
> calls are safe to enforce the return code of zero on... or how many
> need work if I change the default behavior. Let me see what I can do.
>
> I suppose it's maybe a bit late to try and squeak any of this in for
> freeze, so I can roll everything back up into one big series again and
> send a new revision.

On 17.03.22 18:45, John Snow wrote:
> On Thu, Mar 17, 2022 at 1:00 PM John Snow <jsnow@redhat.com> wrote:
>> On Thu, Mar 17, 2022 at 11:39 AM Hanna Reitz <hreitz@redhat.com> wrote:
>>> On 09.03.22 04:54, John Snow wrote:
>>>> Add configurable filters to qemu_img_log(), and re-write img_info_log()
>>>> to call into qemu_img_log() with a custom filter instead.
>>>>
>>>> After this patch, every last call to qemu_img() is now guaranteed to
>>>> either have its return code checked for zero, OR have its output
>>>> actually visibly logged somewhere.
>>>>
>>>> Signed-off-by: John Snow <jsnow@redhat.com>
>>>> ---
>>>>    tests/qemu-iotests/iotests.py | 13 +++++++++----
>>>>    1 file changed, 9 insertions(+), 4 deletions(-)
>>>   From my POV, this is a regression because before this patch (not this
>>> series, though, admittedly), `img_info_log()` would throw an exception
>>> on error, and with patch 12 being as it is, it will revert to its
>>> pre-series behavior of not throwing an exception.  I prefer exceptions
> Oh, actually... patch #12 does this:
>
> -    output = qemu_img_pipe(*args)
> +    output = qemu_img(*args, check=False).stdout

:(

You’re right, I missed that.

> so I never actually toggled error checking on for this function at
> all. This isn't a regression.
>
> At a glance, img_info_log() calls fail as a matter of course in 242
> and 266 and ... hm, I can't quite test 207, it doesn't work for me,
> even before this series.

Ugh, broken in e3296cc796aeaf319f3ed4e064ec309baf5e4da4.

(putting that on my TOFIX list)

> I didn't test *all* qemu_img calls yet either, but ... I'm going to
> gently suggest that "converting logged calls to qemu_img() to be
> checked calls" is "for another series" material.

:C

I mean, adding a `check` parameter to `img_info_log()` and 
`qemu_img_log()` would be something like a 9+/5- diff (including 242 and 
266 changes, but disregarding the necessary comment changes in 
`qemu_img_log()`).  I think that’d be fine, and a bit thin for its own 
“series”. O:)

Hanna

On Thu, Mar 17, 2022 at 2:27 PM Hanna Reitz <hreitz@redhat.com> wrote:
>
> On 17.03.22 18:45, John Snow wrote:
> > On Thu, Mar 17, 2022 at 1:00 PM John Snow <jsnow@redhat.com> wrote:
> >> On Thu, Mar 17, 2022 at 11:39 AM Hanna Reitz <hreitz@redhat.com> wrote:
> >>> On 09.03.22 04:54, John Snow wrote:
> >>>> Add configurable filters to qemu_img_log(), and re-write img_info_log()
> >>>> to call into qemu_img_log() with a custom filter instead.
> >>>>
> >>>> After this patch, every last call to qemu_img() is now guaranteed to
> >>>> either have its return code checked for zero, OR have its output
> >>>> actually visibly logged somewhere.
> >>>>
> >>>> Signed-off-by: John Snow <jsnow@redhat.com>
> >>>> ---
> >>>>    tests/qemu-iotests/iotests.py | 13 +++++++++----
> >>>>    1 file changed, 9 insertions(+), 4 deletions(-)
> >>>   From my POV, this is a regression because before this patch (not this
> >>> series, though, admittedly), `img_info_log()` would throw an exception
> >>> on error, and with patch 12 being as it is, it will revert to its
> >>> pre-series behavior of not throwing an exception.  I prefer exceptions
> > Oh, actually... patch #12 does this:
> >
> > -    output = qemu_img_pipe(*args)
> > +    output = qemu_img(*args, check=False).stdout
>
> :(
>
> You’re right, I missed that.
>
> > so I never actually toggled error checking on for this function at
> > all. This isn't a regression.
> >
> > At a glance, img_info_log() calls fail as a matter of course in 242
> > and 266 and ... hm, I can't quite test 207, it doesn't work for me,
> > even before this series.
>
> Ugh, broken in e3296cc796aeaf319f3ed4e064ec309baf5e4da4.
>
> (putting that on my TOFIX list)
>
> > I didn't test *all* qemu_img calls yet either, but ... I'm going to
> > gently suggest that "converting logged calls to qemu_img() to be
> > checked calls" is "for another series" material.
>
> :C
>
> I mean, adding a `check` parameter to `img_info_log()` and
> `qemu_img_log()` would be something like a 9+/5- diff (including 242 and
> 266 changes, but disregarding the necessary comment changes in
> `qemu_img_log()`).  I think that’d be fine, and a bit thin for its own
> “series”. O:)

You're right. I uh. actually started doing this after I told you I
wasn't going to, because I was surprised by how few calls there were.
so I changed my mind about not wanting to audit them.

Merry Christmas!

--js