pre/post task output is logged twice #4

New Issue

palto42 · 2020-01-05T13:12:45Z

palto42 commented

2020-01-05 13:12:45 +00:00

Example logs at verbosity=0 from pre/post tasks using curl command to trigger an action via a web interface which returns a simple message like "Power on port 4" as a result.

Jan 05 14:02:13 myserver systemd[1]: Started bormatic backup.
Jan 05 14:02:14 myserver borgmatic[8566]: Power on port 4
Jan 05 14:02:14 myserver borgmatic[8566]: WARNING Power on port 4
Jan 05 14:02:53 myserver borgmatic[8566]: Released port 4
Jan 05 14:02:53 myserver borgmatic[8566]: WARNING Released port 4

Example logs at verbosity=0 from pre/post tasks using `curl` command to trigger an action via a web interface which returns a simple message like "Power on port 4" as a result. ``` Jan 05 14:02:13 myserver systemd[1]: Started bormatic backup. Jan 05 14:02:14 myserver borgmatic[8566]: Power on port 4 Jan 05 14:02:14 myserver borgmatic[8566]: WARNING Power on port 4 Jan 05 14:02:53 myserver borgmatic[8566]: Released port 4 Jan 05 14:02:53 myserver borgmatic[8566]: WARNING Released port 4 ```

palto42 added the

bug

label 2020-01-05 13:12:45 +00:00

palto42 commented

2020-01-05 13:53:09 +00:00

This seems to happen because the logger has both console and syslog handlers:

    if syslog_path and not interactive_console():
        syslog_handler = logging.handlers.SysLogHandler(address=syslog_path)
        syslog_handler.setFormatter(logging.Formatter('borgmatic: %(levelname)s %(message)s'))
        syslog_handler.setLevel(syslog_log_level)
        handlers = (console_handler, syslog_handler)
    elif log_file:
        file_handler = logging.handlers.WatchedFileHandler(log_file)
        file_handler.setFormatter(logging.Formatter('[%(asctime)s] %(levelname)s: %(message)s'))
        file_handler.setLevel(log_file_log_level)
        handlers = (console_handler, file_handler)
    else:
        handlers = (console_handler,)

Not fully clear why, but it seems that the console handler is required to get some of the logging into the syslog.

This seems to happen because the logger has both console and syslog handlers: ``` if syslog_path and not interactive_console(): syslog_handler = logging.handlers.SysLogHandler(address=syslog_path) syslog_handler.setFormatter(logging.Formatter('borgmatic: %(levelname)s %(message)s')) syslog_handler.setLevel(syslog_log_level) handlers = (console_handler, syslog_handler) elif log_file: file_handler = logging.handlers.WatchedFileHandler(log_file) file_handler.setFormatter(logging.Formatter('[%(asctime)s] %(levelname)s: %(message)s')) file_handler.setLevel(log_file_log_level) handlers = (console_handler, file_handler) else: handlers = (console_handler,) ``` Not fully clear why, but it seems that the console handler is required to get some of the logging into the syslog.

palto42 commented

2020-01-05 14:03:59 +00:00

the solution is to redirect the 'stdout' in the systemd service configuration to null or redirect it into a file. See systemd config

Example:

[Service]
ExecStart=/opt/borgmatic/bin/borgmatic --syslog-verbosity 1
# suppress stdout
StandardOutput=null

Alternatively the console log level can be lowered to suppress console output into the syslog.

borgmatic -v -1 --syslog-verbosity 1

the solution is to redirect the 'stdout' in the systemd service configuration to `null` or redirect it into a file. See [systemd config](https://www.freedesktop.org/software/systemd/man/systemd.exec.html) Example: ``` [Service] ExecStart=/opt/borgmatic/bin/borgmatic --syslog-verbosity 1 # suppress stdout StandardOutput=null ``` Alternatively the console log level can be lowered to suppress console output into the syslog. ``` borgmatic -v -1 --syslog-verbosity 1 ```

palto42 closed this issue

2020-01-05 14:03:59 +00:00

Sign in to join this conversation.