Re: [Qemu-devel] [PATCH] qemu.py: Call logging.basicConfig() automatically

[Eduardo Habkost <ehabkost@redhat.com>]

On Fri, Sep 22, 2017 at 10:37:44AM +0200, Lukáš Doktor wrote:
> Dne 21.9.2017 v 18:22 Eduardo Habkost napsal(a):
> > Not all scripts using qemu.py configure the Python logging
> > module, and end up generating a "No handlers could be found for
> > logger" message instead of actual log messages.
> > 
> > To avoid requiring every script using qemu.py to configure
> > logging manually, call basicConfig() when creating a QEMUMachine
> > object.  This won't affect scripts that already set up logging,
> > but will ensure that scripts that don't configure logging keep
> > working.
> > 
> > Reported-by: Kevin Wolf <kwolf@redhat.com>
> > Fixes: 4738b0a85a0c2031fddc71b51cccebce0c4ba6b1
> > Signed-off-by: Eduardo Habkost <ehabkost@redhat.com>
> > ---
> >  scripts/qemu.py | 3 +++
> >  1 file changed, 3 insertions(+)
> > 
> > diff --git a/scripts/qemu.py b/scripts/qemu.py
> > index 5e02dd8e78..73d6031e02 100644
> > --- a/scripts/qemu.py
> > +++ b/scripts/qemu.py
> > @@ -89,6 +89,9 @@ class QEMUMachine(object):
> >          self._qmp = None
> >          self._qemu_full_args = None
> >  
> > +        # just in case logging wasn't configured by the main script:
> > +        logging.basicConfig(level=(logging.DEBUG if debug else logging.WARN))
> > +
> >      def __enter__(self):
> >          return self
> >  
> > 
> 
> Hello Eduardo,
> 
> what troubles me about this approach is it enables debug based
> on first instance arguments, while other instances might use a
> different value. Ideally we should create `"%s.%s" % (__name__,
> id(self))` logger per each instance and only set this log level
> there. The same would have to happen for QMP and other modules,
> which should either use the configured instance's logger, or
> create own logger as a child of that logger and optionally
> tweaked the levels there (if necessary), so the result would
> be:
> 
> QEMUMachine(debug=True)
> QEMUMachine(debug=False)
> 
> qemu.139855463298312: DEBUG: Starting instance 139855463298312
> qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463298312: INFO: Started qemu cmd...
> qemu.139855463216512: INFO: Started qemu cmd...
> 
> while with your patch you get:
> 
> qemu.139855463298312: DEBUG: Starting instance 139855463298312
> qemu.139855463298312.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463298312: INFO: Started qemu cmd...
> qemu.139855463216512: DEBUG: Starting instance 139855463298312
> qemu.139855463216512.qmp: DEBUG: Initializing connection to qmp
> qemu.139855463216512: INFO: Started qemu cmd...
> 
> 

IMO, the solution for that is to obsolete the 'debug' parameter
and use the Python logging configuration to control QEMUMachine
logging.  Most (or all?) scripts have a global verbosity setting,
anyway.

> But mine approach would break other scripts that call
> logging.baseConfig (eg. qemu/device-crash-test), because they
> rely on root logger's log-level (because `import qemu` would
> have issued logging.baseConfig). I can't come-up with a better
> alternative and this indeed fixes the issues with scripts using
> qemu without initializing loggers so considering this as a
> **hotfix**:
> 
> Acked-by: Lukáš Doktor <ldoktor@redhat.com>

Thanks!

> 
> But we should focus on fixing all the entry points (either
> initialize from all of them, or force-create the root logger
> based on the entry-point requirements). Kevin, could you please
> share the exact reproducer? I used a custom file importing
> QEMUMachine() with a some added LOG calls.
> 
> Lukáš
> 

-- 
Eduardo