log-json seems to do nothing except in debug mode #858

New Issue

lingfish · 2024-04-26T01:24:27Z

lingfish commented

2024-04-26 01:24:27 +00:00

What I'm trying to do and why

Trying to push logs to Graylog via JSON.

Steps to reproduce

borgmatic --log-json info --repo usbdisk

Actual behavior

Outputs "normal" text, instead of JSON.

Expected behavior

Log messages in JSON format.

Other notes / implementation ideas

If you run the same with -v 2, amongst normal text output, you can see borg's JSON output.

borgmatic version

1.8.8

borgmatic installation method

pipx

Borg version

borg 1.2.7

Python version

Python 3.11.2

Database version (if applicable)

No response

Operating system and version

PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/"

### What I'm trying to do and why Trying to push logs to Graylog via JSON. ### Steps to reproduce `borgmatic --log-json info --repo usbdisk` ### Actual behavior Outputs "normal" text, instead of JSON. ### Expected behavior Log messages in JSON format. ### Other notes / implementation ideas If you run the same with `-v 2`, amongst normal text output, you can see `borg`'s JSON output. ### borgmatic version 1.8.8 ### borgmatic installation method pipx ### Borg version borg 1.2.7 ### Python version Python 3.11.2 ### Database version (if applicable) _No response_ ### Operating system and version PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/"

witten commented

2024-04-26 06:20:48 +00:00

Thanks for filing this! However I'm pretty sure the behavior you're seeing is a Borg limitation, even without using borgmatic. For instance, here's the equivalent Borg command to not using borgmatic's --verbosity 2:

borg info --log-json --glob-archives {hostname}-* yourrepo

(The --glob-archives value may vary based on your configuration, and yourrepo will depend on the path to your Borg repository.)

What that command produces is "normal" non-JSON repository information, I guess because Borg doesn't consider its info output as log entries subject to --log-json. And there are no other log entries to display (as JSON) at that verbosity level.

But if you add --debug, that's the equivalent to borgmatic's --verbosity 2:

borg info --debug --log-json --glob-archives {hostname}-* yourrepo

That produces the mixed output you're observing:

borgmatic verbose log entries show as non-JSON, because --log-json currently only applies to Borg logging and not borgmatic's own logs.
Borg logs its entries as JSON, because Borg applies --log-json to them.
Borg info output shows as "normal" text, because again, Borg doesn't consider that as part of its log entries.

However, switching back to borgmatic, what you can do is is add the --json flag to --log-json but don't use --verbosity 2. Here's what that does:

borgmatic (non-JSON) verbose log entries get suppressed since you're omitting --verbosity 2.
Borg logs its entries as JSON, because Borg applies --log-json to them.
Borg info output shows as JSON, because of the --json flag.

Maybe that's more along the lines of what you're looking for?

Thanks for filing this! However I'm pretty sure the behavior you're seeing is a Borg limitation, even without using borgmatic. For instance, here's the equivalent Borg command to not using borgmatic's `--verbosity 2`: ```bash borg info --log-json --glob-archives {hostname}-* yourrepo ``` (The `--glob-archives` value may vary based on your configuration, and `yourrepo` will depend on the path to your Borg repository.) What that command produces is "normal" non-JSON repository information, I guess because Borg doesn't consider its `info` output as log entries subject to `--log-json`. And there are no other log entries to display (as JSON) at that verbosity level. But if you add `--debug`, that's the equivalent to borgmatic's `--verbosity 2`: ```bash borg info --debug --log-json --glob-archives {hostname}-* yourrepo ``` That produces the mixed output you're observing: * borgmatic verbose log entries show as non-JSON, because `--log-json` currently only applies to Borg logging and not borgmatic's own logs. * Borg logs its entries as JSON, because Borg applies `--log-json` to them. * Borg `info` output shows as "normal" text, because again, Borg doesn't consider that as part of its log entries. However, switching back to borgmatic, what you _can_ do is is add the `--json` flag to `--log-json` but don't use `--verbosity 2`. Here's what that does: * borgmatic (non-JSON) verbose log entries get suppressed since you're omitting `--verbosity 2`. * Borg logs its entries as JSON, because Borg applies `--log-json` to them. * Borg `info` output shows as JSON, because of the `--json` flag. Maybe that's more along the lines of what you're looking for?

witten added the

question / support

label 2024-04-26 06:20:57 +00:00

lingfish commented

2024-04-29 01:49:55 +00:00

Thanks for responding @witten. Excellent clarification, thanks heaps. You're right, your final suggestion does the job, but I've now realised it's basically only a summary (without --progress of course), and I was barking up the wrong tree.

I think I'd like to see borgmatic's logs turned into a structure, moreso than borg. borg JSON is essentially for GUI authors, and mostly resolves therefore around progress, not full state.

I'll give you a couple of my use cases/wishes for this:

Having a key/identifier for the current repo/backup name (in JSON), so that...
One can search for that label, to then see things like duration of the backup, and anything else associated with it in, say, Graylog

What I mean by repo/backup name is each item listed in the borgmatic repositories: key (preferably even by borgmatic's label!)

I guess the above suggested run method gives some of that, we then miss out on also doing the "human" logging in the same run. One can then do an info with JSON after, but that feels clunky.

As I type this, perhaps it even belongs in the hooks framework.

Using just --json, I do see some useful stuff:

        "repository": {
            "id": "xxxxxxxx",
            "last_modified": "2024-04-27T12:31:13.000000",
            "location": "ssh://user@host/./some_repo",
            "label": "label-from-borgmatic-config"
        }

... but again, it'd be nice to push that into Graylog, but also see the usual multiline logging (and even push that somewhere, which I'm currently doing to Graylog).

Seeing borgmatic informational stuff, also structured (probably just a "message" field), would also be useful, so that the structured logging is complete.

On top of all of this then would be wrapping it all in GELF.

I dunno, a lot of random spitballing here; I just struggle to keep an eye on backups when viewing the normal logging, and trying to think of better ways.

Thanks for responding @witten. Excellent clarification, thanks heaps. You're right, your final suggestion does the job, but I've now realised it's basically only a summary (without `--progress` of course), and I was barking up the wrong tree. I think I'd like to see borgmatic's logs turned into a structure, moreso than borg. borg JSON is essentially for GUI authors, and mostly resolves therefore around progress, not full state. I'll give you a couple of my use cases/wishes for this: 1. Having a key/identifier for the current repo/backup name (in JSON), so that... 2. One can search for that label, to then see things like duration of the backup, and anything else associated with it in, say, Graylog What I mean by repo/backup name is each item listed in the borgmatic `repositories:` key (preferably even by borgmatic's label!) I guess the above suggested run method gives some of that, we then miss out on also doing the "human" logging in the same run. One can then do an `info` with JSON after, but that feels clunky. As I type this, perhaps it even belongs in the hooks framework. Using just `--json`, I do see some useful stuff: ``` "repository": { "id": "xxxxxxxx", "last_modified": "2024-04-27T12:31:13.000000", "location": "ssh://user@host/./some_repo", "label": "label-from-borgmatic-config" } ``` ... but again, it'd be nice to push that into Graylog, but also see the usual multiline logging (and even push that somewhere, which I'm currently doing to Graylog). Seeing borgmatic informational stuff, also structured (probably just a "message" field), would also be useful, so that the structured logging is complete. On top of all of this then would be wrapping it all in GELF. I dunno, a lot of random spitballing here; I just struggle to keep an eye on backups when viewing the normal logging, and trying to think of better ways.

Sign in to join this conversation.