Output piped to grep not filtering #271

New Issue

breakingspell · 2019-12-11T06:24:15Z

breakingspell commented

2019-12-11 06:24:15 +00:00

Hello! Have an odd issue with parsing Borgmatic output that cropped up many months ago following an update (>1.3.5). Noticed the issue persists after some system maintenance and backup scrutiny today.

Output from borgmatic list doesn't filter when it's piped into grep or awk, it just outputs the entire list. I use a large repository for many Windows and Debian systems, so it's handy to filter out data for just one host with a quick grep.

When piped, it also loses color output if enabled, disabling color in the .yaml does not affect the piped output, nor does using the old flag "--list" rather than borgmatic list.
I wondered if it was an issue with grep or Python, but realized it was likely Borgmatic as the behavior is resolved by rolling back to 1.3.5 and appears on 1.3.6 and beyond.

Borg itself has no variables set, and the behavior is displayed on multiple hosts on latest Borgmatic, both bash and zsh. The other repositories I use are single-host so I don't run into it very often, but it seems odd enough to open an issue for it.

Personally I don't use the pipe much aside from grep and awk (same behavior in awk), but let me know if there's more information I can provide about my use-case or enviro.
Thanks for the time, Borgmatic does it's job superb otherwise🙌

Steps to reproduce (if a bug)

v1.3.5
sudo borgmatic --list | grep Blackbox
Blackbox-2019-10-22T14:20:54.717235
Blackbox-2019-11-11T03:36:44.345371
Blackbox-2019-11-25T14:40:14.133734
Blackbox-2019-12-04T11:25:55.210536

v1.3.6+ (current 1.4.18)
sudo borgmatic list | grep Blackbox
SlimfastX1-2019-03-18T15:29:22.427160
BackboneX3-2019-04-08T01:36:40.637633
SlimfastA1-2019-04-15T11:17:25.736069
BackboneW10L-2019-05-28T16:30:08.936829
Slimfast-2019-06-04T23:48:54.919927
Slimfast-2019-06-05T00:41:51.754492
BackboneX3-2019-06-05T23:14:36.511028
Slimfast-2019-06-16T17:09:39.447034
BackboneW10L-2019-07-02T01:51:32.304652
BackboneX3-2019-07-04T15:44:39.532669
SlimfastA1-2019-07-05T12:50:50.167760
...

borg list /media/usb/backup/borg | grep Blackbox
Enter passphrase for key /media/usb/backup/borg:
Blackbox-2019-10-22T14:20:54.717235
Blackbox-2019-11-11T03:36:44.345371
Blackbox-2019-11-25T14:40:14.133734
Blackbox-2019-12-04T11:25:55.210536

Config generated from latest version only has location and encryption_passphrase non-standard;

location:
	repositories:
		- user@localhost:/media/usb/backup/borg

Environment

borgmatic version:

1.3.6 - 1.4.18

borgmatic installation method:

Debian Buster repo and pip

Borg version:

1.1.9

Python version:

Python 3.7.3

Hello! Have an odd issue with parsing Borgmatic output that cropped up many months ago following an update (>1.3.5). Noticed the issue persists after some system maintenance and backup scrutiny today. Output from `borgmatic list` doesn't filter when it's piped into grep or awk, it just outputs the entire list. I use a large repository for many Windows and Debian systems, so it's handy to filter out data for just one host with a quick grep. When piped, it also loses color output if enabled, disabling color in the .yaml does not affect the piped output, nor does using the old flag "--list" rather than `borgmatic list`. I wondered if it was an issue with grep or Python, but realized it was likely Borgmatic as the behavior is resolved by rolling back to 1.3.5 and appears on 1.3.6 and beyond. Borg itself has no variables set, and the behavior is displayed on multiple hosts on latest Borgmatic, both bash and zsh. The other repositories I use are single-host so I don't run into it very often, but it seems odd enough to open an issue for it. Personally I don't use the pipe much aside from grep and awk (same behavior in awk), but let me know if there's more information I can provide about my use-case or enviro. Thanks for the time, Borgmatic does it's job superb otherwise🙌 #### Steps to reproduce (if a bug) v1.3.5 sudo borgmatic --list | grep Blackbox Blackbox-2019-10-22T14:20:54.717235 Blackbox-2019-11-11T03:36:44.345371 Blackbox-2019-11-25T14:40:14.133734 Blackbox-2019-12-04T11:25:55.210536 v1.3.6+ (current 1.4.18) sudo borgmatic list | grep Blackbox SlimfastX1-2019-03-18T15:29:22.427160 BackboneX3-2019-04-08T01:36:40.637633 SlimfastA1-2019-04-15T11:17:25.736069 BackboneW10L-2019-05-28T16:30:08.936829 Slimfast-2019-06-04T23:48:54.919927 Slimfast-2019-06-05T00:41:51.754492 BackboneX3-2019-06-05T23:14:36.511028 Slimfast-2019-06-16T17:09:39.447034 BackboneW10L-2019-07-02T01:51:32.304652 BackboneX3-2019-07-04T15:44:39.532669 SlimfastA1-2019-07-05T12:50:50.167760 ... borg list /media/usb/backup/borg | grep Blackbox Enter passphrase for key /media/usb/backup/borg: Blackbox-2019-10-22T14:20:54.717235 Blackbox-2019-11-11T03:36:44.345371 Blackbox-2019-11-25T14:40:14.133734 Blackbox-2019-12-04T11:25:55.210536 Config generated from latest version only has location and encryption_passphrase non-standard; location: repositories: - user@localhost:/media/usb/backup/borg #### Environment **borgmatic version:** 1.3.6 - 1.4.18 **borgmatic installation method:** Debian Buster repo and pip **Borg version:** 1.1.9 **Python version:** Python 3.7.3

witten commented

2019-12-11 06:46:17 +00:00

I appreciate you taking the time to report this. I think what's going on here is that in borgmatic 1.3.5, Borg's output as produced by borgmatic list goes to stdout, so normal grep works. However, in borgmatic 1.3.6+, Borg's output from borgmatic list goes to Python's logging system and then on to stderr. So this modification would be required to perform a grep (redirecting stderr to stdout) and get the desired behavior:

sudo borgmatic list 2>&1 | grep Blackbox

The reason this occurs is that Python's logging stream handler defaults to logging to stderr instead of stdout. So once borgmatic switched to using it in 1.3.6, most logged output switched to stderr.

Now, the question is what to do about it.. The challenge is that some logs, like the borgmatic list output you're after, would naturally belong on stdout to support filtering easily with grep. However, other logs.. like error logs, naturally belong on stderr. Maybe borgmatic needs two separate stream handlers, one for each use case..

When piped, it also loses color output if enabled

I believe this may be mostly intentional, or at least accurately reflecting the current code. Color gets auto-disabled on a "non-interactive" terminal.. So for instance build logs don't get spammed with a bunch of color codes. I believe that filtering the output with grep makes the terminal detect as non-interactive as well, which is why it loses color output. Maybe the auto-detection should be a little more sophisticated?

I appreciate you taking the time to report this. I *think* what's going on here is that in borgmatic 1.3.5, Borg's output as produced by `borgmatic list` goes to stdout, so normal grep works. However, in borgmatic 1.3.6+, Borg's output from `borgmatic list` goes to Python's logging system and then on to stderr. So this modification would be required to perform a grep (redirecting stderr to stdout) and get the desired behavior: ```bash sudo borgmatic list 2>&1 | grep Blackbox ``` The reason this occurs is that Python's logging [stream handler](https://docs.python.org/3/library/logging.handlers.html#streamhandler) defaults to logging to stderr instead of stdout. So once borgmatic switched to using it in 1.3.6, most logged output switched to stderr. Now, the question is what to do about it.. The challenge is that some logs, like the `borgmatic list` output you're after, would naturally belong on stdout to support filtering easily with grep. However, other logs.. like error logs, naturally belong on stderr. Maybe borgmatic needs two separate stream handlers, one for each use case.. > When piped, it also loses color output if enabled I believe this may be mostly intentional, or at least accurately reflecting the current code. Color gets auto-disabled on a "non-interactive" terminal.. So for instance build logs don't get spammed with a bunch of color codes. I believe that filtering the output with grep makes the terminal detect as non-interactive as well, which is why it loses color output. Maybe the auto-detection should be a little more sophisticated?

witten added the

bug

label 2019-12-11 06:46:28 +00:00

breakingspell commented

2019-12-11 07:30:32 +00:00

Had an inkling feeling that logging was at fault due to that system being the major change between those versions, but due to it appearing directly in the terminal, assumed I was still only dealing with stdout and moved on. Redirecting stderr to stdout with 2>&1 does exactly as intended!

Perhaps the redirect could be aliased only within Borgmatic's list flag or as a config option. As you noted though, could encounter a situation where it might display unwanted logs onscreen even with list. Most other Borgmatic functions don't have situations where you'd utilize a grep filter like these, as they're monitored in other ways, so list is really the only "broken" function due to this behavior in Python.

I've aliased the redirect on the system i'm testing with, haven't seen any spew with borgmatic list by itself, no filtering. Once backups run tonight i'll check the output once more and see if anything changes, doubt it'll be any trouble.

When piped, it also loses color output if enabled

Maybe the auto-detection should be a little more sophisticated?

By design I agree, it's not unusual to lose color output between tasks like these in other applications. The color output changing was actually what cued me in on the python output being at fault, but once again, I made assumptions and had moved on 😉

Thanks again for the solution! I'll report back if I encounter any oddity from using an aliased borgmatic list 2>&1

Had an inkling feeling that logging was at fault due to that system being the major change between those versions, but due to it appearing directly in the terminal, assumed I was still only dealing with stdout and moved on. Redirecting stderr to stdout with `2>&1` does exactly as intended! Perhaps the redirect could be aliased only within Borgmatic's `list` flag or as a config option. As you noted though, could encounter a situation where it might display unwanted logs onscreen even with `list`. Most other Borgmatic functions don't have situations where you'd utilize a grep filter like these, as they're monitored in other ways, so `list` is really the only "broken" function due to this behavior in Python. I've aliased the redirect on the system i'm testing with, haven't seen any spew with `borgmatic list` by itself, no filtering. Once backups run tonight i'll check the output once more and see if anything changes, doubt it'll be any trouble. >When piped, it also loses color output if enabled >>Maybe the auto-detection should be a little more sophisticated? By design I agree, it's not unusual to lose color output between tasks like these in other applications. The color output changing was actually what cued me in on the python output being at fault, but once again, I made assumptions and had moved on 😉 Thanks again for the solution! I'll report back if I encounter any oddity from using an aliased `borgmatic list 2>&1`

witten commented

2019-12-11 18:23:47 +00:00

I do plan to fix the stderr/stdout output properly as part of this ticket.. I was suggesting the redirect as a temporary work-around so you wouldn't be blocked!

breakingspell commented

2019-12-11 19:52:28 +00:00

Much appreciated, as the redirect did illustrate exactly what's going on.

I thought at first that two stream handlers may be overly-complicating the process for only one flag affected, but having defined stdout and stderr handlers in Borgmatic might come in handy in the future if other functions run into similar behaviors due to Python's logging system.

Much appreciated, as the redirect did illustrate exactly what's going on. I thought at first that two stream handlers may be overly-complicating the process for only one flag affected, but having defined stdout and stderr handlers in Borgmatic might come in handy in the future if other functions run into similar behaviors due to Python's logging system.

witten referenced this issue from a commit

2019-12-11 20:15:06 +00:00

Support piping "borgmatic list" output to grep. Retain colored output when piping/redirecting (#271).

witten commented

2019-12-12 05:44:51 +00:00

Okay, this fix is released in borgmatic 1.4.19. Certain log levels now go to stdout; others go to stderr. I believe this should solve your use case. I've also made a fix to retain the color setting when piping output.

Give it a shot and let me know how it goes! Thanks.

Okay, this fix is released in borgmatic 1.4.19. Certain log levels now go to stdout; others go to stderr. I believe this should solve your use case. I've also made a fix to retain the color setting when piping output. Give it a shot and let me know how it goes! Thanks.

witten closed this issue

2019-12-12 05:44:51 +00:00

breakingspell commented

2019-12-12 09:31:49 +00:00

Updated and all set! Behaves as intended now across the board, grep returns a colored, clean list following the pipe. Great fix, thanks again for the response and support.

Syslogs report as they should, no change there. I'll keep an eye out!

Updated and all set! Behaves as intended now across the board, grep returns a colored, clean list following the pipe. Great fix, thanks again for the response and support. Syslogs report as they should, no change there. I'll keep an eye out!

witten commented

2019-12-12 17:22:18 +00:00

I'm glad it's working out for you!

Sign in to join this conversation.