[v4,3/9] dts: add basic logging facility

  The logging module provides loggers distinguished by two attributes,
a custom format and a verbosity switch. The loggers log to both console
and more verbosely to files.

Signed-off-by: Owen Hilyard <ohilyard@iol.unh.edu>
Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
---
 dts/framework/__init__.py |   3 +
 dts/framework/logger.py   | 124 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 127 insertions(+)
 create mode 100644 dts/framework/__init__.py
 create mode 100644 dts/framework/logger.py
  

> -----Original Message-----
> From: Juraj Linkeš <juraj.linkes@pantheon.tech>
> Sent: Friday, July 29, 2022 6:56 PM
> To: thomas@monjalon.net; david.marchand@redhat.com; Randles, Ronan
> <ronan.randles@intel.com>; Honnappa.Nagarahalli@arm.com;
> ohilyard@iol.unh.edu; Tu, Lijuan <lijuan.tu@intel.com>
> Cc: dev@dpdk.org; Juraj Linkeš <juraj.linkes@pantheon.tech>
> Subject: [PATCH v4 3/9] dts: add basic logging facility
> 
> The logging module provides loggers distinguished by two attributes, a custom
> format and a verbosity switch. The loggers log to both console and more
> verbosely to files.
> 
> Signed-off-by: Owen Hilyard <ohilyard@iol.unh.edu>
> Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
> ---
>  dts/framework/__init__.py |   3 +
>  dts/framework/logger.py   | 124 ++++++++++++++++++++++++++++++++++++++
>  2 files changed, 127 insertions(+)
>  create mode 100644 dts/framework/__init__.py  create mode 100644
> dts/framework/logger.py
>

Reviewed-by: Lijuan Tu <lijuan.tu@intel.com>

Thanks,
Lijuan
  

On Fri, Jul 29, 2022 at 10:55:44AM +0000, Juraj Linkeš wrote:
> The logging module provides loggers distinguished by two attributes,
> a custom format and a verbosity switch. The loggers log to both console
> and more verbosely to files.
> 
> Signed-off-by: Owen Hilyard <ohilyard@iol.unh.edu>
> Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>

Few small comments inline below.

Thanks,
/Bruce

> ---
>  dts/framework/__init__.py |   3 +
>  dts/framework/logger.py   | 124 ++++++++++++++++++++++++++++++++++++++
>  2 files changed, 127 insertions(+)
>  create mode 100644 dts/framework/__init__.py
>  create mode 100644 dts/framework/logger.py
> 
> diff --git a/dts/framework/__init__.py b/dts/framework/__init__.py
> new file mode 100644
> index 0000000000..3c30bccf43
> --- /dev/null
> +++ b/dts/framework/__init__.py
> @@ -0,0 +1,3 @@
> +# SPDX-License-Identifier: BSD-3-Clause
> +# Copyright(c) 2022 PANTHEON.tech s.r.o.
> +#
> diff --git a/dts/framework/logger.py b/dts/framework/logger.py
> new file mode 100644
> index 0000000000..920ce0fb15
> --- /dev/null
> +++ b/dts/framework/logger.py
> @@ -0,0 +1,124 @@
> +# SPDX-License-Identifier: BSD-3-Clause
> +# Copyright(c) 2010-2014 Intel Corporation
> +# Copyright(c) 2022 PANTHEON.tech s.r.o.
> +# Copyright(c) 2022 University of New Hampshire
> +#
> +
> +import logging
> +import os.path
> +from typing import TypedDict
> +
> +"""
> +DTS logger module with several log level. DTS framework and TestSuite log
> +will saved into different log files.
> +"""
> +verbose = False
> +date_fmt = "%d/%m/%Y %H:%M:%S"

Please use Year-month-day ordering for dates, since it's unambiguous - as
well as being an ISO standard date format. (ISO 8601)

> +stream_fmt = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
> +
> +
> +class LoggerDictType(TypedDict):
> +    logger: "DTSLOG"
> +    name: str
> +    node: str
> +
> +
> +# List for saving all using loggers
> +global Loggers
> +Loggers: list[LoggerDictType] = []
> +
> +
> +def set_verbose() -> None:
> +    global verbose
> +    verbose = True
> +

Is there a need for a clear_verbose() or "set_not_verbose()" API?

> +
> +class DTSLOG(logging.LoggerAdapter):
> +    """
> +    DTS log class for framework and testsuite.
> +    """
> +
> +    node: str
> +    logger: logging.Logger
> +    sh: logging.StreamHandler
> +    fh: logging.FileHandler
> +    verbose_handler: logging.FileHandler
> +
> +    def __init__(self, logger: logging.Logger, node: str = "suite"):
> +        global log_dir
> +
> +        self.logger = logger
> +        self.logger.setLevel(1)  # 1 means log everything
> +
> +        self.node = node
> +
> +        # add handler to emit to stdout
> +        sh = logging.StreamHandler()
> +        sh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> +
> +        sh.setLevel(logging.DEBUG)  # file handler default level
> +        global verbose
> +        if verbose is True:
> +            sh.setLevel(logging.DEBUG)
> +        else:
> +            sh.setLevel(logging.INFO)  # console handler defaultlevel

The global should be defined at the top of the function.
Looks like some of the setlevel calls are unnecessary; two should be enough
rather than three. For example:

	sh.setLevel(logging.INFO)
	if verbose:
		sh.setLevel(logging.DEGUG)

> +
> +        self.logger.addHandler(sh)
> +        self.sh = sh
> +
> +        if not os.path.exists("output"):
> +            os.mkdir("output")
> +
> +        fh = logging.FileHandler(f"output/{node}.log")
> +        fh.setFormatter(
> +            logging.Formatter(
> +                fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
> +                datefmt=date_fmt,
> +            )
> +        )
> +
> +        fh.setLevel(1)  # We want all the logs we can get in the file
> +        self.logger.addHandler(fh)
> +        self.fh = fh
> +
> +        # This outputs EVERYTHING, intended for post-mortem debugging
> +        # Also optimized for processing via AWK (awk -F '|' ...)
> +        verbose_handler = logging.FileHandler(f"output/{node}.verbose.log")
> +        verbose_handler.setFormatter(
> +            logging.Formatter(
> +                fmt="%(asctime)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|%(funcName)s|"
> +                "%(process)d|%(thread)d|%(threadName)s|%(message)s",
> +                datefmt=date_fmt,
> +            )
> +        )
> +
> +        verbose_handler.setLevel(1)  # We want all the logs we can get in the file
> +        self.logger.addHandler(verbose_handler)
> +        self.verbose_handler = verbose_handler
> +
> +        super(DTSLOG, self).__init__(self.logger, dict(node=self.node))
> +
> +    def logger_exit(self) -> None:
> +        """
> +        Remove stream handler and logfile handler.
> +        """
> +        for handler in (self.sh, self.fh, self.verbose_handler):
> +            handler.flush()
> +            self.logger.removeHandler(handler)
> +
> +
> +def getLogger(name: str, node: str = "suite") -> DTSLOG:
> +    """
> +    Get logger handler and if there's no handler for specified Node will create one.
> +    """
> +    global Loggers
> +    # return saved logger
> +    logger: LoggerDictType
> +    for logger in Loggers:
> +        if logger["name"] == name and logger["node"] == node:
> +            return logger["logger"]
> +
> +    # return new logger
> +    dts_logger: DTSLOG = DTSLOG(logging.getLogger(name), node)
> +    Loggers.append({"logger": dts_logger, "name": name, "node": node})
> +    return dts_logger

Looking through this patch alone, I see the "verbose" global only seems to
be used to set the log-level in the logger init function. If this is the
only use of it across all the patches in the set, it may be more readable
to change the variable from a "verbose" flag, to instead being a log-level
one. That way your global define is:

	log_level = logging.INFO

and set_verbose() becomes:

	global log_level
	log_level = logging.DEBUG

thereby removing the branch from you logging init fn.

NOTE: I have not yet had the chance to review the rest of the series, so if
verbose is used elsewhere, please ignore this comment.

> -- 
> 2.30.2
>
  

> -----Original Message-----
> From: Bruce Richardson <bruce.richardson@intel.com>
> Sent: Thursday, September 8, 2022 10:31 AM
> To: Juraj Linkeš <juraj.linkes@pantheon.tech>
> Cc: thomas@monjalon.net; david.marchand@redhat.com;
> ronan.randles@intel.com; Honnappa.Nagarahalli@arm.com;
> ohilyard@iol.unh.edu; lijuan.tu@intel.com; dev@dpdk.org
> Subject: Re: [PATCH v4 3/9] dts: add basic logging facility
> 
> On Fri, Jul 29, 2022 at 10:55:44AM +0000, Juraj Linkeš wrote:
> > The logging module provides loggers distinguished by two attributes, a
> > custom format and a verbosity switch. The loggers log to both console
> > and more verbosely to files.
> >
> > Signed-off-by: Owen Hilyard <ohilyard@iol.unh.edu>
> > Signed-off-by: Juraj Linkeš <juraj.linkes@pantheon.tech>
> 
> Few small comments inline below.
> 
> Thanks,
> /Bruce
> 
> > ---
> >  dts/framework/__init__.py |   3 +
> >  dts/framework/logger.py   | 124
> ++++++++++++++++++++++++++++++++++++++
> >  2 files changed, 127 insertions(+)
> >  create mode 100644 dts/framework/__init__.py  create mode 100644
> > dts/framework/logger.py
> >
> > diff --git a/dts/framework/__init__.py b/dts/framework/__init__.py new
> > file mode 100644 index 0000000000..3c30bccf43
> > --- /dev/null
> > +++ b/dts/framework/__init__.py
> > @@ -0,0 +1,3 @@
> > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2022
> > +PANTHEON.tech s.r.o.
> > +#
> > diff --git a/dts/framework/logger.py b/dts/framework/logger.py new
> > file mode 100644 index 0000000000..920ce0fb15
> > --- /dev/null
> > +++ b/dts/framework/logger.py
> > @@ -0,0 +1,124 @@
> > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2010-2014
> > +Intel Corporation # Copyright(c) 2022 PANTHEON.tech s.r.o.
> > +# Copyright(c) 2022 University of New Hampshire #
> > +
> > +import logging
> > +import os.path
> > +from typing import TypedDict
> > +
> > +"""
> > +DTS logger module with several log level. DTS framework and TestSuite
> > +log will saved into different log files.
> > +"""
> > +verbose = False
> > +date_fmt = "%d/%m/%Y %H:%M:%S"
> 
> Please use Year-month-day ordering for dates, since it's unambiguous - as well
> as being an ISO standard date format. (ISO 8601)
> 

Ack.

> > +stream_fmt = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
> > +
> > +
> > +class LoggerDictType(TypedDict):
> > +    logger: "DTSLOG"
> > +    name: str
> > +    node: str
> > +
> > +
> > +# List for saving all using loggers
> > +global Loggers
> > +Loggers: list[LoggerDictType] = []
> > +
> > +
> > +def set_verbose() -> None:
> > +    global verbose
> > +    verbose = True
> > +
> 
> Is there a need for a clear_verbose() or "set_not_verbose()" API?
> 

No, this is used with a comman-line option or env variable which just sets it once and that's it.

> > +
> > +class DTSLOG(logging.LoggerAdapter):
> > +    """
> > +    DTS log class for framework and testsuite.
> > +    """
> > +
> > +    node: str
> > +    logger: logging.Logger
> > +    sh: logging.StreamHandler
> > +    fh: logging.FileHandler
> > +    verbose_handler: logging.FileHandler
> > +
> > +    def __init__(self, logger: logging.Logger, node: str = "suite"):
> > +        global log_dir
> > +
> > +        self.logger = logger
> > +        self.logger.setLevel(1)  # 1 means log everything
> > +
> > +        self.node = node
> > +
> > +        # add handler to emit to stdout
> > +        sh = logging.StreamHandler()
> > +        sh.setFormatter(logging.Formatter(stream_fmt, date_fmt))
> > +
> > +        sh.setLevel(logging.DEBUG)  # file handler default level
> > +        global verbose
> > +        if verbose is True:
> > +            sh.setLevel(logging.DEBUG)
> > +        else:
> > +            sh.setLevel(logging.INFO)  # console handler defaultlevel
> 
> The global should be defined at the top of the function.
> Looks like some of the setlevel calls are unnecessary; two should be enough
> rather than three. For example:
> 
> 	sh.setLevel(logging.INFO)
> 	if verbose:
> 		sh.setLevel(logging.DEGUG)
> 

Ack.

> > +
> > +        self.logger.addHandler(sh)
> > +        self.sh = sh
> > +
> > +        if not os.path.exists("output"):
> > +            os.mkdir("output")
> > +
> > +        fh = logging.FileHandler(f"output/{node}.log")
> > +        fh.setFormatter(
> > +            logging.Formatter(
> > +                fmt="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
> > +                datefmt=date_fmt,
> > +            )
> > +        )
> > +
> > +        fh.setLevel(1)  # We want all the logs we can get in the file
> > +        self.logger.addHandler(fh)
> > +        self.fh = fh
> > +
> > +        # This outputs EVERYTHING, intended for post-mortem debugging
> > +        # Also optimized for processing via AWK (awk -F '|' ...)
> > +        verbose_handler = logging.FileHandler(f"output/{node}.verbose.log")
> > +        verbose_handler.setFormatter(
> > +            logging.Formatter(
> > +
> fmt="%(asctime)s|%(name)s|%(levelname)s|%(pathname)s|%(lineno)d|%(funcN
> ame)s|"
> > +                "%(process)d|%(thread)d|%(threadName)s|%(message)s",
> > +                datefmt=date_fmt,
> > +            )
> > +        )
> > +
> > +        verbose_handler.setLevel(1)  # We want all the logs we can get in the file
> > +        self.logger.addHandler(verbose_handler)
> > +        self.verbose_handler = verbose_handler
> > +
> > +        super(DTSLOG, self).__init__(self.logger,
> > + dict(node=self.node))
> > +
> > +    def logger_exit(self) -> None:
> > +        """
> > +        Remove stream handler and logfile handler.
> > +        """
> > +        for handler in (self.sh, self.fh, self.verbose_handler):
> > +            handler.flush()
> > +            self.logger.removeHandler(handler)
> > +
> > +
> > +def getLogger(name: str, node: str = "suite") -> DTSLOG:
> > +    """
> > +    Get logger handler and if there's no handler for specified Node will create
> one.
> > +    """
> > +    global Loggers
> > +    # return saved logger
> > +    logger: LoggerDictType
> > +    for logger in Loggers:
> > +        if logger["name"] == name and logger["node"] == node:
> > +            return logger["logger"]
> > +
> > +    # return new logger
> > +    dts_logger: DTSLOG = DTSLOG(logging.getLogger(name), node)
> > +    Loggers.append({"logger": dts_logger, "name": name, "node": node})
> > +    return dts_logger
> 
> Looking through this patch alone, I see the "verbose" global only seems to be
> used to set the log-level in the logger init function. If this is the only use of it
> across all the patches in the set, it may be more readable to change the variable
> from a "verbose" flag, to instead being a log-level one. That way your global
> define is:
> 
> 	log_level = logging.INFO
> 
> and set_verbose() becomes:
> 
> 	global log_level
> 	log_level = logging.DEBUG
> 
> thereby removing the branch from you logging init fn.
> 
> NOTE: I have not yet had the chance to review the rest of the series, so if
> verbose is used elsewhere, please ignore this comment.
> 

It isn't. It's used solely to enable more logging, so I'll move the code around to achieve what you outlined.

> > --
> > 2.30.2
> >
  

<snip>
> >
> > > ---
> > >  dts/framework/__init__.py |   3 +
> > >  dts/framework/logger.py   | 124
> > ++++++++++++++++++++++++++++++++++++++
> > >  2 files changed, 127 insertions(+)
> > >  create mode 100644 dts/framework/__init__.py  create mode 100644
> > > dts/framework/logger.py
> > >
> > > diff --git a/dts/framework/__init__.py b/dts/framework/__init__.py
> > > new file mode 100644 index 0000000000..3c30bccf43
> > > --- /dev/null
> > > +++ b/dts/framework/__init__.py
> > > @@ -0,0 +1,3 @@
> > > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2022
> > > +PANTHEON.tech s.r.o.
> > > +#
> > > diff --git a/dts/framework/logger.py b/dts/framework/logger.py new
> > > file mode 100644 index 0000000000..920ce0fb15
> > > --- /dev/null
> > > +++ b/dts/framework/logger.py
> > > @@ -0,0 +1,124 @@
> > > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2010-2014
> > > +Intel Corporation # Copyright(c) 2022 PANTHEON.tech s.r.o.
> > > +# Copyright(c) 2022 University of New Hampshire #
> > > +
> > > +import logging
> > > +import os.path
> > > +from typing import TypedDict
> > > +
> > > +"""
> > > +DTS logger module with several log level. DTS framework and
> > > +TestSuite log will saved into different log files.
Nit "DTS logger module with several log levels. DTS framework and TestSuite logs are saved in different log files."

<snip>
  

> -----Original Message-----
> From: Honnappa Nagarahalli <Honnappa.Nagarahalli@arm.com>
> Sent: Wednesday, September 14, 2022 1:31 AM
> To: Juraj Linkeš <juraj.linkes@pantheon.tech>; Bruce Richardson
> <bruce.richardson@intel.com>
> Cc: thomas@monjalon.net; david.marchand@redhat.com;
> ronan.randles@intel.com; ohilyard@iol.unh.edu; lijuan.tu@intel.com;
> dev@dpdk.org; nd <nd@arm.com>; nd <nd@arm.com>
> Subject: RE: [PATCH v4 3/9] dts: add basic logging facility
> 
> <snip>
> > >
> > > > ---
> > > >  dts/framework/__init__.py |   3 +
> > > >  dts/framework/logger.py   | 124
> > > ++++++++++++++++++++++++++++++++++++++
> > > >  2 files changed, 127 insertions(+)  create mode 100644
> > > > dts/framework/__init__.py  create mode 100644
> > > > dts/framework/logger.py
> > > >
> > > > diff --git a/dts/framework/__init__.py b/dts/framework/__init__.py
> > > > new file mode 100644 index 0000000000..3c30bccf43
> > > > --- /dev/null
> > > > +++ b/dts/framework/__init__.py
> > > > @@ -0,0 +1,3 @@
> > > > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2022
> > > > +PANTHEON.tech s.r.o.
> > > > +#
> > > > diff --git a/dts/framework/logger.py b/dts/framework/logger.py new
> > > > file mode 100644 index 0000000000..920ce0fb15
> > > > --- /dev/null
> > > > +++ b/dts/framework/logger.py
> > > > @@ -0,0 +1,124 @@
> > > > +# SPDX-License-Identifier: BSD-3-Clause # Copyright(c) 2010-2014
> > > > +Intel Corporation # Copyright(c) 2022 PANTHEON.tech s.r.o.
> > > > +# Copyright(c) 2022 University of New Hampshire #
> > > > +
> > > > +import logging
> > > > +import os.path
> > > > +from typing import TypedDict
> > > > +
> > > > +"""
> > > > +DTS logger module with several log level. DTS framework and
> > > > +TestSuite log will saved into different log files.
> Nit "DTS logger module with several log levels. DTS framework and TestSuite
> logs are saved in different log files."
> 

Thanks, these nitpicks are important - there are a lot comments from the original authors that need ironing out. Although I this one particular example was written be either me or Owen. :-)

> <snip>