Why does journalctl prefix duplicate output with "ANSWER"? #681

New Issue

iainelder · 2023-04-18T10:18:32Z

iainelder commented

2023-04-18 10:18:32 +00:00

Why does journalctl duplicate Borgmatic's output lines prefixed with "ANSWER"?

$ journalctl --user --since 11:55 --unit borgmatic.service --follow
-- Logs begin at Fri 2023-03-10 17:06:24 CET. --
Apr 18 11:58:48 isme-t480s systemd[1999]: Started Borgmatic backup.
Apr 18 11:58:49 isme-t480s borgmatic[35314]: ssh://...@....repo.borgbase.com/./repo: Creating archive
Apr 18 11:58:51 isme-t480s borgmatic[35314]: Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T11:58:50.019937"
Apr 18 11:58:51 isme-t480s borgmatic[35314]: ANSWER Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T11:58:50.019937"
Apr 18 11:59:00 isme-t480s borgmatic[35314]: Remote: Storage quota: 30.49 GB out of 1.00 TB used.
Apr 18 11:59:00 isme-t480s borgmatic[35314]: ANSWER Remote: Storage quota: 30.49 GB out of 1.00 TB used.
Apr 18 12:01:45 isme-t480s borgmatic[35314]: Remote: Storage quota: 30.61 GB out of 1.00 TB used.
Apr 18 12:01:45 isme-t480s borgmatic[35314]: ANSWER Remote: Storage quota: 30.61 GB out of 1.00 TB used.

The ANSWER lines in my terminal are a yellow-green color. The rest of the lines are the normal color.

Searching with journalctl --grep ANSWER shows only Borgmatic output.

My Borgmatic config looks like this:

location:
  source_directories:
    - /home/isme
  repositories:
    - path: ssh://...@....repo.borgbase.com/./repo
      label: BorgBase
  patterns:
    - '- /home/isme/.cache'
storage:
  encryption_passphrase: "..."
retention:
  keep_within: 24H
  keep_daily: 7
  keep_monthly: 6
  keep_yearly: 1

Here is my service file at ~/.config/systemd/user/borgmatic.service:

[Unit]
Description=Borgmatic backup

[Install]
WantedBy=default.target

[Service]
Type=simple
ExecStart=/home/isme/.local/bin/borgmatic --verbosity=1 --stats

And here is my timer file at ~/.config/systemd/user/borgmatic.timer:

[Unit]
Description=Run borgmatic backup after boot and then every hour

[Timer]
OnBootSec=1m
OnUnitActiveSec=1h

[Install]
WantedBy=timers.target

I searched Google for both borgmatic ANSWER and journalctl ANSWER, but didn't see anything useful.

Environment

borgmatic version: 1.7.10

borgmatic installation method: pipx

Borg version: 1.2.4

Python version: 3.8.10

operating system and version: Ubuntu 20.04.5 LTS

Why does journalctl duplicate Borgmatic's output lines prefixed with "ANSWER"? ```console $ journalctl --user --since 11:55 --unit borgmatic.service --follow -- Logs begin at Fri 2023-03-10 17:06:24 CET. -- Apr 18 11:58:48 isme-t480s systemd[1999]: Started Borgmatic backup. Apr 18 11:58:49 isme-t480s borgmatic[35314]: ssh://...@....repo.borgbase.com/./repo: Creating archive Apr 18 11:58:51 isme-t480s borgmatic[35314]: Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T11:58:50.019937" Apr 18 11:58:51 isme-t480s borgmatic[35314]: ANSWER Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T11:58:50.019937" Apr 18 11:59:00 isme-t480s borgmatic[35314]: Remote: Storage quota: 30.49 GB out of 1.00 TB used. Apr 18 11:59:00 isme-t480s borgmatic[35314]: ANSWER Remote: Storage quota: 30.49 GB out of 1.00 TB used. Apr 18 12:01:45 isme-t480s borgmatic[35314]: Remote: Storage quota: 30.61 GB out of 1.00 TB used. Apr 18 12:01:45 isme-t480s borgmatic[35314]: ANSWER Remote: Storage quota: 30.61 GB out of 1.00 TB used. ``` The ANSWER lines in my terminal are a yellow-green color. The rest of the lines are the normal color. Searching with `journalctl --grep ANSWER` shows only Borgmatic output. My Borgmatic config looks like this: ```yaml location: source_directories: - /home/isme repositories: - path: ssh://...@....repo.borgbase.com/./repo label: BorgBase patterns: - '- /home/isme/.cache' storage: encryption_passphrase: "..." retention: keep_within: 24H keep_daily: 7 keep_monthly: 6 keep_yearly: 1 ``` Here is my service file at `~/.config/systemd/user/borgmatic.service`: ```cfg [Unit] Description=Borgmatic backup [Install] WantedBy=default.target [Service] Type=simple ExecStart=/home/isme/.local/bin/borgmatic --verbosity=1 --stats ``` And here is my timer file at `~/.config/systemd/user/borgmatic.timer`: ```cfg [Unit] Description=Run borgmatic backup after boot and then every hour [Timer] OnBootSec=1m OnUnitActiveSec=1h [Install] WantedBy=timers.target ``` I searched Google for both `borgmatic ANSWER` and `journalctl ANSWER`, but didn't see anything useful. #### Environment **borgmatic version:** 1.7.10 **borgmatic installation method:** pipx **Borg version:** 1.2.4 **Python version:** 3.8.10 **operating system and version:** Ubuntu 20.04.5 LTS

witten commented

2023-04-18 17:03:12 +00:00

The reason you're getting double logs is because borgmatic is logging once to stdout and once directly to syslog/journald. The ANSWER lines are those logs that go direct to syslog, and ANSWER is the log level for a particular log (e.g., WARN, INFO, DEBUG, etc.).

My recommendation is to tweak the borgmatic flags in your systemd serivce to be more similar to the sample systemd service file. Specifically, reduce the stdout logging and increase the syslog verbosity:

Example:

/home/isme/.local/bin/borgmatic --verbosity -1 --syslog-verbosity 1 --stats

This means that stdout will log errors only and syslog/journald will log up to INFO level (so, everything except DEBUG logs).

Note that there's an open pull request that would allow disabling stdout logging entirely.

Let me know if you have any other questions on this!

EDIT: The pull request has been merged and released as part of #484 and borgmatic 1.7.14, so if you're using that version or higher, do this to even disable errors to stdout:

/home/isme/.local/bin/borgmatic --verbosity -2 --syslog-verbosity 1 --stats

The reason you're getting double logs is because borgmatic is logging once to stdout and once directly to syslog/journald. The `ANSWER` lines are those logs that go direct to syslog, and `ANSWER` is the log level for a particular log (e.g., `WARN`, `INFO`, `DEBUG`, etc.). My recommendation is to tweak the borgmatic flags in your systemd serivce to be more similar to the [sample systemd service file](https://projects.torsion.org/borgmatic-collective/borgmatic/src/branch/master/sample/systemd/borgmatic.service#L64). Specifically, reduce the stdout logging and increase the syslog verbosity: Example: ``` /home/isme/.local/bin/borgmatic --verbosity -1 --syslog-verbosity 1 --stats ``` This means that stdout will log errors only and syslog/journald will log up to `INFO` level (so, everything except `DEBUG` logs). Note that there's an [open pull request](https://projects.torsion.org/borgmatic-collective/borgmatic/pulls/675) that would allow disabling stdout logging entirely. Let me know if you have any other questions on this! EDIT: The pull request has been merged and released as part of #484 and borgmatic 1.7.14, so if you're using that version or higher, do this to even disable errors to stdout: ``` /home/isme/.local/bin/borgmatic --verbosity -2 --syslog-verbosity 1 --stats ```

witten added the

question / support

label 2023-04-18 17:03:20 +00:00

iainelder commented

2023-04-18 19:52:53 +00:00

I took your advice on the flags. Now there are no more duplicate messages in the journal.

$ journalctl --user --since=-2m --unit borgmatic.service
-- Logs begin at Fri 2023-03-10 17:06:24 CET, end at Tue 2023-04-18 21:04:39 CEST. --
Apr 18 21:04:28 isme-t480s systemd[3040]: Started Borgmatic backup.
Apr 18 21:04:29 isme-t480s borgmatic[14281]: INFO ssh://...@....repo.borgbase.com/./repo: Creating archive
Apr 18 21:04:32 isme-t480s borgmatic[14281]: ANSWER Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T21:04:30.375910"
Apr 18 21:04:39 isme-t480s borgmatic[14281]: ANSWER Remote: Storage quota: 30.25 GB out of 1.00 TB used.

That solves the main problem. Thanks for your clear explanation.

Is ANSWER a real log level? I don't see it mentioned in the syslog documentation.

The word ANSWER and everything following in the line still appears in green. It makes me think it's something else with special handling in systemd or syslog.

I took your advice on the flags. Now there are no more duplicate messages in the journal. ```console $ journalctl --user --since=-2m --unit borgmatic.service -- Logs begin at Fri 2023-03-10 17:06:24 CET, end at Tue 2023-04-18 21:04:39 CEST. -- Apr 18 21:04:28 isme-t480s systemd[3040]: Started Borgmatic backup. Apr 18 21:04:29 isme-t480s borgmatic[14281]: INFO ssh://...@....repo.borgbase.com/./repo: Creating archive Apr 18 21:04:32 isme-t480s borgmatic[14281]: ANSWER Creating archive at "ssh://...@....repo.borgbase.com/./repo::isme-t480s-2023-04-18T21:04:30.375910" Apr 18 21:04:39 isme-t480s borgmatic[14281]: ANSWER Remote: Storage quota: 30.25 GB out of 1.00 TB used. ``` That solves the main problem. Thanks for your clear explanation. Is `ANSWER` a real log level? I don't see it mentioned in the [syslog](https://manpages.ubuntu.com/manpages/bionic/man3/syslog.3.html) documentation. The word `ANSWER` and everything following in the line still appears in green. It makes me think it's something else with special handling in systemd or syslog.

witten commented

2023-04-18 21:15:10 +00:00

Is ANSWER a real log level? I don't see it mentioned in the syslog documentation.

It's a custom log level used only by borgmatic. Its purpose is to allow borgmatic to respond to user requests like list or info even when the --verbosity level is low (0).

The word ANSWER and everything following in the line still appears in green. It makes me think it's something else with special handling in systemd or syslog.

I believe borgmatic only colors output sent to stdout, so my guess is that journalctl is choosing to color output based on the log level. From the journalctl documentation: "When outputting to a tty, lines are colored according to priority: lines of level ERROR and higher are colored red; lines of level NOTICE and higher are highlighted; lines of level DEBUG are colored lighter grey; other lines are displayed normally."

> Is ANSWER a real log level? I don't see it mentioned in the syslog documentation. It's a custom log level used only by borgmatic. Its purpose is to allow borgmatic to respond to user requests like `list` or `info` even when the `--verbosity` level is low (0). > The word ANSWER and everything following in the line still appears in green. It makes me think it's something else with special handling in systemd or syslog. I believe borgmatic only colors output sent to stdout, so my guess is that journalctl is choosing to color output based on the log level. From the [journalctl documentation](https://www.man7.org/linux/man-pages/man1/journalctl.1.html): "When outputting to a tty, lines are colored according to priority: lines of level ERROR and higher are colored red; lines of level NOTICE and higher are highlighted; lines of level DEBUG are colored lighter grey; other lines are displayed normally."

iainelder commented

2023-04-19 08:30:10 +00:00

Yes, journalctl seems to color the output according to its log level.

My guess is that Borgmatic's ANSWER log level is equivalent to a warning.

Here's a screenshot of how I see the different log levels.

The ANSWER lines all look like that green/yellow line.

I've annotated the text version with how each message is painted.

Apr 19 10:11:58 isme-t480s LogTest[27199]: Hello, emerg!   # bold red
Apr 19 10:11:58 isme-t480s LogTest[27200]: Hello, alert!   # bold red
Apr 19 10:11:58 isme-t480s LogTest[27201]: Hello, crit!    # bold red
Apr 19 10:11:58 isme-t480s LogTest[27205]: Hello, err!     # bold red
Apr 19 10:11:58 isme-t480s LogTest[27207]: Hello, warning! # bold green/yellow
Apr 19 10:11:58 isme-t480s LogTest[27208]: Hello, notice!  # bold white
Apr 19 10:11:58 isme-t480s LogTest[27209]: Hello, info!    # white
Apr 19 10:11:58 isme-t480s LogTest[27210]: Hello, debug!   # gray

To generate that I used systemd-cat to write some test messages to the journal.

This script sets p to each of the documented log levels. systemd-cat uses the level to write a message identifying itself as LogTest.

for p in emerg alert crit err warning notice info debug; do
  systemd-cat --identifier=LogTest --priority="$p" <<< "Hello, $p!"
done

In another terminal I watch for messages from LogTest.

journalctl --boot --identifier=LogTest --no-tail --follow

Yes, journalctl seems to color the output according to its log level. My guess is that Borgmatic's ANSWER log level is equivalent to a warning. Here's a screenshot of how I see the different log levels. ![image](/attachments/ed2fffbd-6332-4b08-983f-cfc83dc75750) The ANSWER lines all look like that green/yellow line. I've annotated the text version with how each message is painted. ```text Apr 19 10:11:58 isme-t480s LogTest[27199]: Hello, emerg! # bold red Apr 19 10:11:58 isme-t480s LogTest[27200]: Hello, alert! # bold red Apr 19 10:11:58 isme-t480s LogTest[27201]: Hello, crit! # bold red Apr 19 10:11:58 isme-t480s LogTest[27205]: Hello, err! # bold red Apr 19 10:11:58 isme-t480s LogTest[27207]: Hello, warning! # bold green/yellow Apr 19 10:11:58 isme-t480s LogTest[27208]: Hello, notice! # bold white Apr 19 10:11:58 isme-t480s LogTest[27209]: Hello, info! # white Apr 19 10:11:58 isme-t480s LogTest[27210]: Hello, debug! # gray ``` To generate that I used [systemd-cat](https://serverfault.com/questions/573946/how-can-i-send-a-message-to-the-systemd-journal-from-the-command-line) to write some test messages to the journal. This script sets `p` to each of the documented log levels. systemd-cat uses the level to write a message identifying itself as LogTest. ```bash for p in emerg alert crit err warning notice info debug; do systemd-cat --identifier=LogTest --priority="$p" <<< "Hello, $p!" done ``` In another terminal I watch for messages from LogTest. ```bash journalctl --boot --identifier=LogTest --no-tail --follow ```

iainelder commented

2023-04-19 08:35:41 +00:00

This now answers all my initial questions and satisfies my curiosity, so I'll close the issue. Thanks for your support!

iainelder closed this issue

2023-04-19 08:35:46 +00:00

witten commented

2023-04-20 04:29:36 +00:00

Sure thing!

Sign in to join this conversation.