INFO messages should go to stdout

[opoplawski]

Current info messages appear to go to stderr:

$ /usr/local/cvdupdate/bin/cvd update >/dev/null
2022-05-24 11:27:00 cvdupdate-1.1.0 INFO Using system configured nameservers
2022-05-24 11:27:00 cvdupdate-1.1.0 INFO main.cvd is up-to-date. Version: 62
2022-05-24 11:27:00 cvdupdate-1.1.0 INFO daily.cvd is up-to-date. Version: 26551
2022-05-24 11:27:00 cvdupdate-1.1.0 INFO bytecode.cvd is up-to-date. Version: 333

This makes it hard to capture errors from cron jobs.

[micahsnyder]

I am unsure how to change it so only INFO-level messages go to stdout and the rest go to stderr. I could replace all of the self.logger.info() with calls to print, but then they won't appear in the log file.

If anyone knows of a way to redirect log messages to stderr by log-level, I would appreciate the help.

[backbord]

Perhaps you could have the basic setup log to stdout and add a separate StreamHandler for the messages that should go to stderr. Maybe like so? (It is no beauty.)

    def _init_logging(self) -> None:
        """
        Initializes the logging parameters.
        """
        today = datetime.datetime.now()
        log_file = self.log_dir / f"{today:%Y-%m-%d}.log"

        if not self.log_dir.exists():
            # Make a new log directory
            os.makedirs(log_file.parent)
        else:
            # Log dir already exists, lets check if we need to prune old logs
            logs = self.log_dir.glob('*.log')
            for log in logs:
                log_date_str = str(log.stem)
                log_date = datetime.datetime.strptime(log_date_str, "%Y-%m-%d")
                if log_date + datetime.timedelta(days=self.config["# logs to keep"]) < today:
                    # Log is too old, delete!
                    os.remove(str(log))

        stderr_level = logging.WARNING

        stderr_handler = logging.StreamHandler(sys.stderr)
        stderr_handler.setLevel(stderr_level)

        class FilterNotStdErr(logging.Filter):
            def filter(self, record: logging.LogRecord) -> bool:
                return record.levelno < stderr_level

        stdout_handler = logging.StreamHandler(sys.stdout)
        stdout_handler.addFilter(FilterNotStdErr())

        logging.basicConfig(
            level=logging.DEBUG if self.verbose else logging.INFO,
            format="%(asctime)s - %(levelname)s:  %(message)s",
            datefmt="%Y-%m-%d %I:%M:%S %p",
            force=True,  # an import might already have the root logger configured
            handlers=[
                stderr_handler,
                stdout_handler,
                logging.FileHandler(log_file),
            ],
        )

        self.logger = logging.getLogger(f"cvdupdate-{self.version}")

        # Also set the log level for urllib3, because it's "DEBUG" by default,
        # and we may not like that.
        urllib3_logger = logging.getLogger("urllib3.connectionpool")
        urllib3_logger.setLevel(self.logger.level)

[claviola]

@micahsnyder any chance this could be merged? I'd like to not have to send stderr to /dev/null in case something goes awry with an update. But as it is, running it as a cron would be very noisy.

[micahsnyder]

Hi @claviola thank you for the reminder. I'll try to review this suggestion next week.

If you want to submit a PR for the suggested change, that does make things easier.