Support capturing interactive progress bar

[elbaro]

I am using tqdm which interactively update the progress bar in the terminal.
A sacred observer captures stdout like this:

[train]    loss =   0.0000    acc =   1.0000:   2%|▏         | 29/1500 [00:01<11:18,  2.17it/s]
[train]    loss =   0.0002    acc =   1.0000:   2%|▏         | 29/1500 [00:01<11:18,  2.17it/s]
[train]    loss =   0.0002    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0041    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0002    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0045    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0003    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:52,  3.08it/s]
[train]    loss =   0.0003    acc =   1.0000:   4%|▍         | 58/1500 [00:01<05:31,  4.35it/s]
[train]    loss =   0.0000    acc =   1.0000:   4%|▍         | 58/1500 [00:01<05:31,  4.35it/s]

Applying ex.captured_out_filter = apply_backspaces_and_linefeeds has no effect.
If I have a nested tqdm (two for-loops),

[train]    loss =   0.0000    acc =   1.0000:   2%|▏         | 30/1500 [00:01<10:54,  2.25it/s]�[A

[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:36,  3.19it/s]�[A

[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:36,  3.19it/s]�[A

[train]    loss =   0.0000    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:36,  3.19it/s]�[A

[train]    loss =   0.0001    acc =   1.0000:   3%|▎         | 45/1500 [00:01<07:36,  3.19it/s]�[A

[elbaro]

Also for colored output,

epoch  95 [train] �[33mloss =   0.0080    acc =   0.9992    �[0m    [valid] �[32mloss =   0.0080    acc =   0.9992    �[0m

[JarnoRFB]

tqdm integration seems useful. thanks for reporting! colored output should at least be ignored and not show up in the current format.

[varun19299]

Any updates on this? Would be super-useful to have.

[gabrieldemarmiesse]

I managed to fix the TQDM issue with multiple lines, but not the color issue. To fix, use:

from sacred import SETTINGS
from sacred.utils import apply_backspaces_and_linefeeds


SETTINGS.CAPTURE_MODE = 'sys'

...
ex.captured_out_filter = apply_backspaces_and_linefeeds

From what I understand: If you don't do this, tqdm will detect that you are using a terminal (SETTINGS.CAPTURE_MODE = 'fd' which is the default in linux) and that it's possible to move the cursor inside this terminal. So tqdm will use \n and move the cursor. By using SETTINGS.CAPTURE_MODE = 'sys', tqdm understands that it has to write inside a text stream and that it can't control the cursor. It then uses \r to come back at the start of the line. This use case is then handled correctly by apply_backspaces_and_linefeeds. Given how the capture works, I believe it's impossible to make it work with nested progress bars in TQDM. Colored output is another problem which is unrelated to this fix.

Feel free to correct me. This comes from my limited knowledge of linux, shells and streams.

[fepegar]

I also have this problem. Using only ex.captured_out_filter = apply_backspaces_and_linefeeds doesn't help, my captured output looks like this:

  0%|          | 0/13 [00:00<?, ?it/s]
 23%|██▎       | 3/13 [00:00<00:00, 28.73it/s]
 46%|████▌     | 6/13 [00:00<00:00, 28.87it/s]
 69%|██████▉   | 9/13 [00:00<00:00, 29.18it/s]
 92%|█████████▏| 12/13 [00:00<00:00, 29.34it/s]
100%|██████████| 13/13 [00:00<00:00, 30.83it/s]
INFO - run_epoch - Validation loss after 975 iterations: 0.588838145423394
INFO - run_epoch - Saving model with validation loss 0.588838145423394
INFO - train - End of epoch   5/80

Adding SETTINGS.CAPTURE_MODE = 'sys' results in a different problem. The output looks like this:

100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 25/25 [00:00<00:00, 48.45it/s]
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 389/389 [00:16<00:00, 23.43it/s]
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 25/25 [00:00<00:00, 49.06it/s]
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 389/389 [00:06<00:00, 62.89it/s]
100%|██████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 25/25 [00:00<00:00, 51.81it/s]
100%|████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████| 389/389 [00:06<00:00, 63.78it/s]

Ideally I'd like to capture only what I log:

INFO - run_epoch - Validation loss after 975 iterations: 0.588838145423394
INFO - run_epoch - Saving model with validation loss 0.588838145423394
INFO - train - End of epoch   5/80

[JarnoRFB]

@fepegar isn't the output after applying SETTINGS.CAPTURE_MODE = 'sys' expected as you get the final state of each progress bar? To only capture what is logged you could pass a custom captured output filter like so:

def filter_logs(captured_out):
    return "\n".join(line for line in captured_out.split("\n") if line.startswith("INFO"))
       
ex = Experiment('name')
ex.captured_out_filter = filter_logs 

[fepegar]

The problem with the sys solution is that I only get the progress bars and no logged output.

Maybe I can just filter out the lines containing something that looks like a progress bar.
A hack like this seems to do the job:

def remove_progress(captured_out):
    lines = (line for line in captured_out.splitlines() if 'it/s]' not in line)
    return '\n'.join(lines)
ex.captured_out_filter = remove_progress

[amtseng]

If you're using Python 3, this issue may be because the captured output has all of its carriage returns (\r) converted to new lines (\n). I've submitted this bug report (above).

This quick fix has worked for me:

Try altering line 119 in stdout_capturing.py to be with NamedTemporaryFile(mode="w+", newline='') as target:. You'll still need to apply ex.captured_out_filter = apply_backspaces_and_linefeeds , but you won't need to change SETTINGS.CAPTURE_MODE.