[PATCH 1/3] main: always put BUP_FORCE_TTY into the environment

[Johannes Berg]

Nix reports that progress output from midx/bloom while save
is running is no longer printed.

The reason turns out to be somewhat complicated:
* midx/bloom progress output is printed directly from the C
code, if stderr is known to be a tty from isatty(2) or the
environment variable BUP_FORCE_TTY
* save is a built-in command now, and so are midx/bloom (but
the latter is less relevant)
* a process inherits the environment that the parent has,
unless otherwise specified

So with the _old_ setup (with save not a module but process),
when save is started, main would set both BUP_FORCE_TTY (and
BUP_TTY_WIDTH) in the environment for the subprocess, causing
save to obtain it, and further midx/bloom to inherit it from
save. One of the downsides of this setup is that the size of
the window is now fixed, so resizing doesn't update.

With the _new_ setup, where save is a module, we don't set
BUP_FORCE_TTY or BUP_TTY_WIDTH in the environment since the
redirection and fixing etc. all happens in the main, and the
code is directly accessing stdout/stderr via the filtering.

The problem now is the following:
1) We create the filter thread, so that stdout/stderr are
no longer pointing to the real tty fd, so that isatty()
returns false. This is fine for save, or when we start
bloom/midx directly, as the _helpers.c istty2 has been
evaluated already before we redirect the fds.
2) As described, we don't set the environment variables
when we run the save code, since it's a module.

However, as a result, when save starts midx/bloom as a new
subprocess, they inherit the redirected fds, so that they're
not writing to the tty themselves, but also don't get the
environment variable BUP_FORCE_TTY since they're started by
save and that was a module.

The solution then is fairly simple: set BUP_FORCE_TTY in the
environment unconditionally, and BUP_TTY_WIDTH only for the
external submodules ("tty_env").

This didn't just affect save -> midx/bloom, but also the ssh
sub command which passes BUP_FORCE_TTY/BUP_TTY_WIDTH to the
remote process, so potentially the server's debug output was
also affected. Nix reported that the client debug output was
not shown ("Receiving index from server: %d/%d\r"), but I
don't have an explanation for that related to this commit,
as that code is actually running in the process of the save,
thus should be shown depending on helpers.istty2, which was
always correct in the main process.

I'll note, in passing, that this setup now actually windows
can be resized and we actually respond to that (though only
because we query the TTY width for every message...) for all
module subcommands, unlike binary subcommands that receive
BUP_TTY_WIDTH in the environment and it can never change.

Reported-by: Nix <n...@esperi.org.uk>
Fixes: 5dd0172dddb9 ("bup: filter stdout/stderr via thread/pipe for internal subcommands")
Signed-off-by: Johannes Berg <joha...@sipsolutions.net>
---
lib/bup/main.py | 7 +++----
1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index 0c21c88f5703..bf772a68583d 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -198,11 +198,10 @@ fix_stdout = not already_fixed and os.isatty(1)
fix_stderr = not already_fixed and os.isatty(2)

if fix_stdout or fix_stderr:
+ _ttymask = (fix_stdout and 1 or 0) + (fix_stderr and 2 or 0)
+ environ[b'BUP_FORCE_TTY'] = b'%d' % _ttymask
tty_env = merge_dict(environ,
- {b'BUP_FORCE_TTY': (b'%d'
- % ((fix_stdout and 1 or 0)
- + (fix_stderr and 2 or 0))),
- b'BUP_TTY_WIDTH': b'%d' % _tty_width(), })
+ {b'BUP_TTY_WIDTH': b'%d' % _tty_width()})
else:
tty_env = environ

--
2.33.1

[Johannes Berg]

We treat BUP_FORCE_TTY from the environment as a bitmap
all the time, so do the same in main. This requires an
update to one of the tests using it, but otherwise it's
supposed to be internal API, i.e. not documented in the
man page or such.

Signed-off-by: Johannes Berg <joha...@sipsolutions.net>
---

lib/bup/main.py | 8 +++++---
test/ext/test-ls | 2 +-
2 files changed, 6 insertions(+), 4 deletions(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index bf772a68583d..ed711853736e 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -193,9 +193,11 @@ if not cmd_module:

already_fixed = int(environ.get(b'BUP_FORCE_TTY', 0))
if subcmd_name in [b'mux', b'ftp', b'help']:
- already_fixed = True
-fix_stdout = not already_fixed and os.isatty(1)
-fix_stderr = not already_fixed and os.isatty(2)
+ fix_stdout = False
+ fix_stderr = False
+else:
+ fix_stdout = not (already_fixed & 1) and os.isatty(1)
+ fix_stderr = not (already_fixed & 2) and os.isatty(2)

if fix_stdout or fix_stderr:

_ttymask = (fix_stdout and 1 or 0) + (fix_stderr and 2 or 0)

diff --git a/test/ext/test-ls b/test/ext/test-ls
index 8a93c399e5a8..86d8c58c6766 100755
--- a/test/ext/test-ls
+++ b/test/ext/test-ls
@@ -61,7 +61,7 @@ src_tree_hash=$(git log --format=%T -n1 src)

WVSTART "$ls_cmd_desc (short)"

-(export BUP_FORCE_TTY=1; WVPASSEQ "$(WVPASS bup-ls | tr -d ' ')" src)
+(export BUP_FORCE_TTY=3; WVPASSEQ "$(WVPASS bup-ls | tr -d ' ')" src)

WVPASSEQ "$(WVPASS bup-ls /)" "src"

--
2.33.1

[Johannes Berg]

I put this in my tree, but added the following paragraph to the commit
message:


Also, as another note, we now always put BUP_FORCE_TTY into
the environment, which we avoided previously for some calls.
However, prior to the change to have most things be modules,
we were also doing that, since everything we called (git and
other tools like par2) would be started by a subprocess, so
this doesn't really seem to pose any danger.


johannes

[Johannes Berg]

On Tue, 2021-11-30 at 21:53 +0100, Johannes Berg wrote:
>

> The solution then is fairly simple: set BUP_FORCE_TTY in the
> environment unconditionally, and BUP_TTY_WIDTH only for the
> external submodules ("tty_env").

[...]

> I'll note, in passing, that this setup now actually windows
> can be resized and we actually respond to that (though only
> because we query the TTY width for every message...) for all
> module subcommands, unlike binary subcommands that receive
> BUP_TTY_WIDTH in the environment and it can never change.
>

Actually, this is wrong, and then:

> if fix_stdout or fix_stderr:
> + _ttymask = (fix_stdout and 1 or 0) + (fix_stderr and 2 or 0)
> + environ[b'BUP_FORCE_TTY'] = b'%d' % _ttymask
> tty_env = merge_dict(environ,
> - {b'BUP_FORCE_TTY': (b'%d'
> - % ((fix_stdout and 1 or 0)
> - + (fix_stderr and 2 or 0))),
> - b'BUP_TTY_WIDTH': b'%d' % _tty_width(), })
> + {b'BUP_TTY_WIDTH': b'%d' % _tty_width()})

Can just get rid of tty_env entirely and always put BUP_TTY_WIDTH into
the environment, because otherwise options.tty_width() doesn't work at
all, since it also sees a redirected stdout/stderr.

And that then pretty much removes the need for my "main/options: fix
output string confusion" patch since tty_width() will work correctly due
to BUP_TTY_WIDTH, except of course for the [:] bug.

That then together will get us back to where we were before - it'd be
nice to react to changing window sizes, but we clearly never did that in
the past either.

johannes

[Johannes Berg]

The solution then is fairly simple: set both BUP_FORCE_TTY
and BUP_TTY_WIDTH in the environment unconditionally. The
latter is necessary so that options._tty_width() works in
the module-based commands as well.

This didn't just affect save -> midx/bloom, but also the ssh

calls that pass BUP_FORCE_TTY/BUP_TTY_WIDTH to the remote

process, so potentially the server's debug output was also
affected. Nix reported that the client debug output was not
shown ("Receiving index from server: %d/%d\r"), but I don't
have an explanation for that related to this commit, as that
code is actually running in the process of the save, thus
should be shown depending on helpers.istty2, which was
always correct in the main process.

Also, I'll note that we now always put BUP_FORCE_TTY into

the environment, which we avoided previously for some calls.
However, prior to the change to have most things be modules,
we were also doing that, since everything we called (git and
other tools like par2) would be started by a subprocess, so
this doesn't really seem to pose any danger.

Reported-by: Nix <n...@esperi.org.uk>
Fixes: 5dd0172dddb9 ("bup: filter stdout/stderr via thread/pipe for internal subcommands")

Signed-off-by: Johannes Berg <joha...@sipsolutions.net>
---

lib/bup/main.py | 12 ++++--------
1 file changed, 4 insertions(+), 8 deletions(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index 0c21c88f5703..c55274a46c7d 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -198,13 +198,9 @@ fix_stdout = not already_fixed and os.isatty(1)

fix_stderr = not already_fixed and os.isatty(2)

if fix_stdout or fix_stderr:
- tty_env = merge_dict(environ,

- {b'BUP_FORCE_TTY': (b'%d'
- % ((fix_stdout and 1 or 0)
- + (fix_stderr and 2 or 0))),
- b'BUP_TTY_WIDTH': b'%d' % _tty_width(), })

-else:
- tty_env = environ

+ _ttymask = (fix_stdout and 1 or 0) + (fix_stderr and 2 or 0)
+ environ[b'BUP_FORCE_TTY'] = b'%d' % _ttymask

+ environ[b'BUP_TTY_WIDTH'] = b'%d' % _tty_width()


sep_rx = re.compile(br'([\r\n])')
@@ -382,7 +378,7 @@ def run_subproc_cmd(args):
p = subprocess.Popen(c,
stdout=PIPE if fix_stdout else out,
stderr=PIPE if fix_stderr else err,
- env=tty_env, bufsize=4096, close_fds=True)
+ bufsize=4096, close_fds=True)
# Assume p will receive these signals and quit, which will
# then cause us to quit.
for sig in (signal.SIGINT, signal.SIGTERM, signal.SIGQUIT):
--
2.33.1

[Johannes Berg]

There's a bug here that causes output to be cut off if it's
if the line was too long, in that case 'width' chars would
be removed at the beginning, rather than actually showing
'width' chars. Fix that.

Reported-by: Nix <n...@esperi.org.uk>
Fixes: 00fb1f1b2a53 ("Clean subprocess output without newliner")

Signed-off-by: Johannes Berg <joha...@sipsolutions.net>
---

lib/bup/main.py | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index c55274a46c7d..c6010381cd60 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -220,7 +220,7 @@ def print_clean_line(dest, content, width, sep=None):
assert not sep_rx.match(x)
content = b''.join(content)
if sep == b'\r' and len(content) > width:
- content = content[width:]
+ content = content[:width]
os.write(dest, content)
if len(content) < width:
os.write(dest, b' ' * (width - len(content)))
--
2.33.1

[Johannes Berg]

and maybe the subject should now say "truncation" instead of "confusion"
... but I guess Rob can decide and it doesn't matter much anyway.

johannes

[Rob Browning]

Johannes Berg <joha...@sipsolutions.net> writes:

> Nix reports that progress output from midx/bloom while save
> is running is no longer printed.
>
> The reason turns out to be somewhat complicated:
> * midx/bloom progress output is printed directly from the C
> code, if stderr is known to be a tty from isatty(2) or the
> environment variable BUP_FORCE_TTY
> * save is a built-in command now, and so are midx/bloom (but
> the latter is less relevant)
> * a process inherits the environment that the parent has,
> unless otherwise specified

Pushed a more recent version.

--
Rob Browning
rlb @defaultvalue.org and @debian.org
GPG as of 2011-07-10 E6A9 DA3C C9FD 1FF8 C676 D2C4 C0F0 39E9 ED1B 597A
GPG as of 2002-11-03 14DD 432F AE39 534D B592 F9A0 25C8 D377 8C7E 73A4

[Rob Browning]

Johannes Berg <joha...@sipsolutions.net> writes:

> We treat BUP_FORCE_TTY from the environment as a bitmap
> all the time, so do the same in main. This requires an
> update to one of the tests using it, but otherwise it's
> supposed to be internal API, i.e. not documented in the
> man page or such.

Pushed.

[Rob Browning]

From: Johannes Berg <joha...@sipsolutions.net>

Nix reports that progress output from midx/bloom while save
is running is no longer printed.

The reason turns out to be somewhat complicated:
* midx/bloom progress output is printed directly from the C
code, if stderr is known to be a tty from isatty(2) or the
environment variable BUP_FORCE_TTY
* save is a built-in command now, and so are midx/bloom (but
the latter is less relevant)
* a process inherits the environment that the parent has,
unless otherwise specified

Reviewed-by: Rob Browning <r...@defaultvalue.org>
[r...@defaultvalue.org: remove now unused merge_dict from imports]
Signed-off-by: Rob Browning <r...@defaultvalue.org>
Tested-by: Rob Browning <r...@defaultvalue.org>
---

Pushed.

lib/bup/main.py | 13 ++++---------
1 file changed, 4 insertions(+), 9 deletions(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index 0c21c88f..746fce45 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -31,7 +31,6 @@ from bup.helpers import (
columnate,
handle_ctrl_c,
log,
- merge_dict,
tty_width
)
from bup.git import close_catpipes
@@ -198,13 +197,9 @@ fix_stdout = not already_fixed and os.isatty(1)

fix_stderr = not already_fixed and os.isatty(2)

if fix_stdout or fix_stderr:
- tty_env = merge_dict(environ,
- {b'BUP_FORCE_TTY': (b'%d'
- % ((fix_stdout and 1 or 0)
- + (fix_stderr and 2 or 0))),
- b'BUP_TTY_WIDTH': b'%d' % _tty_width(), })
-else:
- tty_env = environ
+ _ttymask = (fix_stdout and 1 or 0) + (fix_stderr and 2 or 0)
+ environ[b'BUP_FORCE_TTY'] = b'%d' % _ttymask
+ environ[b'BUP_TTY_WIDTH'] = b'%d' % _tty_width()


sep_rx = re.compile(br'([\r\n])')

@@ -382,7 +377,7 @@ def run_subproc_cmd(args):

p = subprocess.Popen(c,
stdout=PIPE if fix_stdout else out,
stderr=PIPE if fix_stderr else err,
- env=tty_env, bufsize=4096, close_fds=True)
+ bufsize=4096, close_fds=True)
# Assume p will receive these signals and quit, which will
# then cause us to quit.
for sig in (signal.SIGINT, signal.SIGTERM, signal.SIGQUIT):
--

2.30.2

[Rob Browning]

From: Johannes Berg <joha...@sipsolutions.net>

There's a bug here that causes output to be cut off if it's
if the line was too long, in that case 'width' chars would
be removed at the beginning, rather than actually showing
'width' chars. Fix that.

Reported-by: Nix <n...@esperi.org.uk>
Fixes: 00fb1f1b2a53 ("Clean subprocess output without newliner")
Signed-off-by: Johannes Berg <joha...@sipsolutions.net>

Reviewed-by: Rob Browning <r...@defaultvalue.org>
---

Pushed.

lib/bup/main.py | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/bup/main.py b/lib/bup/main.py
index 746fce45..dcab41b5 100755
--- a/lib/bup/main.py
+++ b/lib/bup/main.py
@@ -219,7 +219,7 @@ def print_clean_line(dest, content, width, sep=None):

assert not sep_rx.match(x)
content = b''.join(content)
if sep == b'\r' and len(content) > width:
- content = content[width:]
+ content = content[:width]
os.write(dest, content)
if len(content) < width:
os.write(dest, b' ' * (width - len(content)))
--

2.30.2

[Nix]

On 5 Dec 2021, Rob Browning said:

> Johannes Berg <joha...@sipsolutions.net> writes:
>
>> Nix reports that progress output from midx/bloom while save
>> is running is no longer printed.
>>
>> The reason turns out to be somewhat complicated:
>> * midx/bloom progress output is printed directly from the C
>> code, if stderr is known to be a tty from isatty(2) or the
>> environment variable BUP_FORCE_TTY
>> * save is a built-in command now, and so are midx/bloom (but
>> the latter is less relevant)
>> * a process inherits the environment that the parent has,
>> unless otherwise specified
>
> Pushed a more recent version.

I can confirm that the bug I reported is fixed now. Thank you!

(and now I will proceed to not notice for ever, because bup is the only
backup program I have ever used that is reliable enough to be forgotten
about in cron and actually work for years at a time, so I don't see its
messages anyway. :) )

[Nix]

On 6 Dec 2021, n...@esperi.org.uk verbalised:

> On 5 Dec 2021, Rob Browning said:
>
>> Johannes Berg <joha...@sipsolutions.net> writes:
>>
>>> Nix reports that progress output from midx/bloom while save
>>> is running is no longer printed.
>>>
>>> The reason turns out to be somewhat complicated:
>>> * midx/bloom progress output is printed directly from the C
>>> code, if stderr is known to be a tty from isatty(2) or the
>>> environment variable BUP_FORCE_TTY
>>> * save is a built-in command now, and so are midx/bloom (but
>>> the latter is less relevant)
>>> * a process inherits the environment that the parent has,
>>> unless otherwise specified
>>
>> Pushed a more recent version.
>
> I can confirm that the bug I reported is fixed now. Thank you!

However, at the end of the backup we have a bit of fallout from the
__del__-to-context manager change:

Receiving index from server: 594924/594924, done.
Exception ignored in: <function BaseConn.__del__ at 0x7f1d216bc1f0>
Traceback (most recent call last):
File "/pkg/bup/0.32-256/usr/lib/bup/bup/helpers.py", line 465, in __del__
assert self._base_closed
AssertionError:
WARNING: 17 errors encountered while saving.
Exception ignored in: <function PackWriter_Remote.__del__ at 0x7f24ceda71f0>
Traceback (most recent call last):
File "/pkg/bup/0.32-256/usr/lib/bup/bup/client.py", line 544, in __del__
TypeError: super() argument 1 must be type, not None

The latter error is particularly mystifying. It *is* a type:
super(PackWriter_Remote, self).__del__()

(The backup appears to have finished regardless: not too surprisingly
given that this happens when the remote PackWriter is finally closed.
Not sure what state the last index in the local index cache is, but if
that's needed in the next backup it'll get pulled down anyway...)

[Johannes Berg]

On Mon, 2021-12-06 at 02:14 +0000, Nix wrote:
>
> However, at the end of the backup we have a bit of fallout from the
> __del__-to-context manager change:
>
> Receiving index from server: 594924/594924, done.
> Exception ignored in: <function BaseConn.__del__ at 0x7f1d216bc1f0>
> Traceback (most recent call last):
> File "/pkg/bup/0.32-256/usr/lib/bup/bup/helpers.py", line 465, in __del__
> assert self._base_closed

This one is kind of normal for now, but also harmless. The changes
exposed a number of "forgot to close the instance" type things, which
were always there. They don't appear visibly in the tests, so it was
hidden. I fixed a bunch and threw in a commit to detect them in the ext
tests, and a new version of pytest started warning on them in the int
tests, so I hope over time we'll catch them, but I also know that there
are quite a few "__init__() raises an exception" type issues with this,
not all of which occur during the tests.

> AssertionError:
> WARNING: 17 errors encountered while saving.
> Exception ignored in: <function PackWriter_Remote.__del__ at 0x7f24ceda71f0>
> Traceback (most recent call last):
> File "/pkg/bup/0.32-256/usr/lib/bup/bup/client.py", line 544, in __del__
> TypeError: super() argument 1 must be type, not None
>
> The latter error is particularly mystifying. It *is* a type:
> super(PackWriter_Remote, self).__del__()
>

Which version of python is this with?

> (The backup appears to have finished regardless: not too surprisingly
> given that this happens when the remote PackWriter is finally closed.
> Not sure what state the last index in the local index cache is, but if
> that's needed in the next backup it'll get pulled down anyway...)
>

It should all be OK, even wrt. the index.

johannes

[Nix]

On 6 Dec 2021, Johannes Berg outgrape:

> On Mon, 2021-12-06 at 02:14 +0000, Nix wrote:
>> AssertionError:
>> WARNING: 17 errors encountered while saving.
>> Exception ignored in: <function PackWriter_Remote.__del__ at 0x7f24ceda71f0>
>> Traceback (most recent call last):
>> File "/pkg/bup/0.32-256/usr/lib/bup/bup/client.py", line 544, in __del__
>> TypeError: super() argument 1 must be type, not None
>>
>> The latter error is particularly mystifying. It *is* a type:
>> super(PackWriter_Remote, self).__del__()
>>
> Which version of python is this with?

Nov 30 tip of 3.9 branch, commit 99a9b343316172f049a52b39a406f0c0c42c106f.

Nothing obvious has landed since then that might fix it.

--
NULL && (void)

[Johannes Berg]

OK. I was just wondering if you were using 2.7 or 3.x :)
I have 3.9 and 3.10 here myself.

johannes