Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

INFO messages should go to stdout #43

Open
opoplawski opened this issue May 24, 2022 · 6 comments · May be fixed by #65
Open

INFO messages should go to stdout #43

opoplawski opened this issue May 24, 2022 · 6 comments · May be fixed by #65
Labels
help wanted Extra attention is needed

Comments

@opoplawski
Copy link

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
Copy link
Contributor

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.

@micahsnyder micahsnyder added the help wanted Extra attention is needed label Jul 28, 2022
@backbord
Copy link
Contributor

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
Copy link

@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
Copy link
Contributor

micahsnyder commented Feb 24, 2023

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.

@Sajfer
Copy link

Sajfer commented Nov 12, 2024

Any chance this could be reviewed and merged?

@micahsnyder
Copy link
Contributor

I just tested the proposed change.

I added this to the end of the init function to test each level, since otherwise WARNING and ERROR won't be easily tested:

        # test logging to each of debug, info, warning, and error
        self.logger.debug("Debug log message")
        self.logger.info("Info log message")
        self.logger.warning("Warning log message")
        self.logger.error("Error log message")

I then ran:

cvd update --verbose 2> error.log 1> output.log

I aborted the update with Ctrl-C after a few seconds since that's enough logs to see what is going on.

What I found is that WARNING and ERROR do go to stderr and INFO goes to stdout, but also DEBUG goes to stdout.

❯ cat error.log
2024-11-12 10:46:44 AM - WARNING:  Warning log message
2024-11-12 10:46:44 AM - ERROR:  Error log message

Aborted!

cvdupdate on  main [!?] via 🐍 v3.9.5 (.venv)
❯ cat output.log
2024-11-12 10:46:44 AM - DEBUG:  Debug log message
2024-11-12 10:46:44 AM - INFO:  Info log message
2024-11-12 10:46:44 AM - DEBUG:  Checking for a newer version of cvdupdate.
2024-11-12 10:46:45 AM - DEBUG:  cvdupdate is up-to-date: 1.1.2.
2024-11-12 10:46:45 AM - DEBUG:  Checking available versions via DNS TXT entry query of current.cvd.clamav.net
2024-11-12 10:46:45 AM - INFO:  Using system configured nameservers
2024-11-12 10:46:45 AM - DEBUG:  Checking main.cvd for update from https://database.clamav.net/main.cvd
2024-11-12 10:46:45 AM - DEBUG:  Checking main.cvd version via DNS TXT advertisement.
2024-11-12 10:46:45 AM - DEBUG:  main.cvd version advertised by DNS: 62
2024-11-12 10:46:45 AM - INFO:  main.cvd is up-to-date. Version: 62
2024-11-12 10:46:45 AM - DEBUG:  Checking daily.cvd for update from https://database.clamav.net/daily.cvd
2024-11-12 10:46:45 AM - DEBUG:  Checking daily.cvd version via DNS TXT advertisement.
2024-11-12 10:46:45 AM - DEBUG:  daily.cvd version advertised by DNS: 27456
2024-11-12 10:46:45 AM - DEBUG:  Downloading CDIFFs first...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27444.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27445.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27446.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27447.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27448.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27449.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27450.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27451.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27452.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27453.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27454.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27455.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  We already have daily-27456.cdiff. Skipping...
2024-11-12 10:46:45 AM - DEBUG:  Starting new HTTPS connection (1): database.clamav.net:443
2024-11-12 10:46:45 AM - DEBUG:  https://database.clamav.net:443 "GET /daily.cvd?version=27456 HTTP/11" 200 64215740

I'm okay with this. I think some folks prefer debug to go to stderr. But realistically most people won't use the debug/verbose option.

micahsnyder added a commit that referenced this issue Nov 12, 2024
Currently all log messages are going to stderr.

Fixes: #43

Patch courtesy of GitHub user backbord.
@micahsnyder micahsnyder linked a pull request Nov 12, 2024 that will close this issue
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted Extra attention is needed
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants