Conan: force conan to not use tqdm for decompression progress bar

[moltob]

Conan version 1.9.0, started happening as soon as Conan started to use tqdm internally.

Window 7, user logged in as Admin, cmd as shell.

In the above scenario some of our users get this error:

Decompressing conan_package.tgz:   0%|          | 0.00/1.56M [00:00<?, ?B/s]Traceback (most recent call last):
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\conans\client\remote_manager.py", line 433, in uncompress_file
    tar_extract(file_handler, dest_folder)
  File "C:\Users\q444547\AppData\Local\Programs\Python\Python37\lib\contextlib.py", line 119, in __exit__
    next(self.gen)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\conans\util\progress_bar.py", line 73, in open_binary
    file_wrapped.pb_close()
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\conans\util\progress_bar.py", line 49, in pb_close
    self._pb.close()
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\tqdm\_tqdm.py", line 1158, in close
    self.sp(self.__repr__())
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\tqdm\_tqdm.py", line 231, in print_status
    fp_write('\r' + s + (' ' * max(last_len[0] - len_s, 0)))
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\tqdm\_tqdm.py", line 224, in fp_write
    fp.write(_unicode(s))
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\conans\client\output.py", line 68, in write
    self._stream.write(data)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 40, in write
    self.__convertor.write(text)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 141, in write
    self.write_and_convert(text)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 169, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 174, in write_plain_text
    self.wrapped.write(text[start:end])
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 40, in write
    self.__convertor.write(text)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 141, in write
    self.write_and_convert(text)
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 169, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "c:\_repos\gen5\conti3\bin\toolenv\venv\lib\site-packages\colorama\ansitowin32.py", line 174, in write_plain_text
    self.wrapped.write(text[start:end])
PermissionError:

(Yes, it stops there.) Debugging this is difficult, as tool developers are not really able to reproduce the issue. It seems that something with stream handling in Windows cmd is weird. Using a different shell like cmder prevents the issue from surfacing...

Because of this it will be extremely difficult to fix this...

So... do we have a way of keeping conan from trying to use tqdm during package decompression? Can we fake a non-terminal session?

[danimtb]

Hi @moltob,

Could you please indicate the conan installation you have? Is conan installed just via pip? if so, do you experience that behavior in both python 2 and python 3? What is the version of tqdm you have installed?

Thanks

[moltob]

Hey @danimtb, thanks for the feedback. Here is the information you asked for:

Yes, conan is installed via PIP in Python 3.6 and 3.7 in a virtual environment. The installed package versions are:

asn1crypto==0.24.0
astroid==2.0.4
attrs==18.2.0
bottle==0.12.13
cattrs==0.9.0
certifi==2018.10.15
cffi==1.11.5
chardet==3.0.4
cloudpickle==0.6.1
colorama==0.3.9
conan==1.9.0
cryptography==2.3.1
daiquiri==1.5.0
deprecation==2.0.6
distro==1.1.0
doit==0.31.1
entrypoints==0.2.3
fasteners==0.14.1
future==0.16.0
gcovr==4.1
github3.py==1.2.0
icci.doit==3.7.0
idna==2.7
isort==4.3.4
Jinja2==2.10
jwcrypto==0.6.0
keyring==16.1.0
lazy-object-proxy==1.3.1
lxml==4.2.5
MarkupSafe==1.1.0
mccabe==0.6.1
monotonic==1.5
node-semver==0.2.0
packaging==18.0
patch==1.16
pluginbase==0.7
protobuf==3.6.1
pycparser==2.19
Pygments==2.2.0
PyJWT==1.6.4
pylint==2.1.1
pyparsing==2.3.0
python-dateutil==2.7.5
pywin32-ctypes==0.2.0
PyYAML==3.13
requests==2.20.0
six==1.11.0
tqdm==4.28.1
typed-ast==1.1.0
uritemplate==3.0.0
urllib3==1.24.1
wrapt==1.10.11

[moltob]

Our environment is not compatible with Python 2, so I cannot let the user test it there.

[danimtb]

Thanks for the information. I think it is enough for us to try to reproduce it

[danimtb]

Hi @moltob

I tried to reproduce your issue in a Windows 10 machine as I don't have Win7 available.

Did my test with Python 3.7 running in a virtualenv, installed conan pip install conan and I also installed the requirements above.

Installing OpenSSL from a cmd shell and worked fine:

(conan_issue) C:\Users\danimtb>conan install OpenSSL/1.0.2m@conan/stable
...
OpenSSL/1.0.2m@conan/stable: Not found in local cache, looking in remotes...
OpenSSL/1.0.2m@conan/stable: Trying with 'conan-center'...
Downloading conanmanifest.txt
[==================================================] 58B/58B
Downloading conanfile.py
[==================================================] 18.2KB/18.2KB
OpenSSL/1.0.2m@conan/stable: Installing package
Requirements
    OpenSSL/1.0.2m@conan/stable from 'conan-center' - Downloaded
    zlib/1.2.11@conan/stable from 'conan-community' - Cache
Packages
    OpenSSL/1.0.2m@conan/stable:606fdb601e335c2001bdf31d478826b644747077 - Download
    zlib/1.2.11@conan/stable:6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7 - Cache

zlib/1.2.11@conan/stable: Already installed!
OpenSSL/1.0.2m@conan/stable: Retrieving package 606fdb601e335c2001bdf31d478826b644747077 from remote 'conan-center'
Downloading conanmanifest.txt
[==================================================] 4.6KB/4.6KB
Downloading conaninfo.txt
[==================================================] 1.2KB/1.2KB
Downloading conan_package.tgz
[==================================================] 5.6MB/5.6MB
Decompressing conan_package.tgz: 100%|██████████| 5.32M/5.32M [00:00<00:00, 5.59MB/s]
OpenSSL/1.0.2m@conan/stable: Package installed 606fdb601e335c2001bdf31d478826b644747077

You can see the output of the tqdm progress bar there. I am no able to reproduce the issue.

Do you know if it is failing in any particular case? Could be related to an encoding conversion or the terminal not supporting colors (maybe you could try setting CONAN_COLOR_DISPLAY environment variable to 0). But I have no clue.

[SSE4]

the following regularly happens for me if I use the scrollbar during the conan execution:

bTraceback (most recent call last):
  File "C:\Python27\lib\site-packages\conans\client\command.py", line 1427, in run
    method(args[0][1:])
  File "C:\Python27\lib\site-packages\conans\client\command.py", line 393, in install
    install_folder=args.install_folder)
  File "C:\Python27\lib\site-packages\conans\client\conan_api.py", line 87, in wrapper
    return f(*args, **kwargs)
  File "C:\Python27\lib\site-packages\conans\client\conan_api.py", line 484, in install_reference
    generators=generators)
  File "C:\Python27\lib\site-packages\conans\client\manager.py", line 86, in install
    output.highlight("Installing package")
  File "C:\Python27\lib\site-packages\conans\client\output.py", line 79, in highlight
    self.writeln(data, Color.BRIGHT_MAGENTA)
  File "C:\Python27\lib\site-packages\conans\client\output.py", line 53, in writeln
    self.write(data, front, back, True)
  File "C:\Python27\lib\site-packages\conans\client\output.py", line 115, in write
    super(ScopedOutput, self).write("%s: " % self.scope, front, back, False)
  File "C:\Python27\lib\site-packages\conans\client\output.py", line 69, in write
    self._stream.write(data)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 41, in write
    self.__convertor.write(text)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 162, in write
    self.write_and_convert(text)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 187, in write_and_convert
    self.write_plain_text(text, cursor, start)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 195, in write_plain_text
    self.wrapped.write(text[start:end])
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 41, in write
    self.__convertor.write(text)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 162, in write
    self.write_and_convert(text)
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 190, in write_and_convert
    self.write_plain_text(text, cursor, len(text))
  File "C:\Python27\lib\site-packages\colorama\ansitowin32.py", line 195, in write_plain_text
    self.wrapped.write(text[start:end])
IOError: [Errno 0] Error

ERROR: [Errno 0] Error

[memsharded]

Interestingly, it is in the same point self.wrapped.write(text[start:end]) than the above error.

Maybe yes, it makes sense to implement an opt-out of tqdm (or an opt-in to tqdm, not sure).

[moltob]

Thanks @danimtb for trying. As noted above, we have seen this error only on Windows 7. Also you have to be an administrator. But even then, I am not able to reproduce on my own machine (only saw it on other user's machines).

@memsharded There are other progress bars as well in conan (e.g while downloading etc.), right? I am wondering why decompression visualization was switched to tqdm... IMHO it looks a bit inconsistent. tqdm gives the additional ETA, however decompression is usually much faster than downloading.

[memsharded]

@moltob

We introduced first just this tqdm progress bar to this unzipping of the conan_xxx.tgz files (the unzip progress bar didn't exist a couple of releases ago), with the plan to migrate to tqdm all the other progress bar later to tqdm. It will be done in next releases, to have a consistent UI, but for sure we need to stabilize theses issues first. Your feedback will help :)

[danimtb]

I'd say that first we need to know if this issue really comes from tqdm before implementing an otp-out.

But with the information provided and our resources I am not sure if we will be able to come with a fix. I will keep this open but please @SSE4 and @moltob report if you find some sort of reproducible example for us to investigate.

Thanks!

[memsharded]

For reference, this seems something that fails inside colorama, not tqdm:

• https://github.com/pypa/pip/issues/3581
• https://github.com/tartley/colorama/issues/119
• https://github.com/pytest-dev/py/issues/103

I think the most relevant issue is in colorama itself:

• https://github.com/tartley/colorama/issues/101

It could be related to Windows encodings.

If that is the reason, the test that can be done is simple: try deactivating the colorama processing. There is an env-var for it: put CONAN_COLOR_DISPLAY=0

Please try to set it, and see if the error is gone, and we will think what to do. Many thanks!

[SSE4]

I'll try with disabled CONAN_COLOR_DISPLAY and let you know

[SSE4]

with CONAN_COLOR_DISPLAY=0 it just outputs [Errno 0] Error. with no stacktrace and still fails.
this is pretty weird that error 0 is treated as error at all.

[moltob]

I'll report in tomorrow after one of my affected users has retried with the mentioned setting.

Thanks a lot for helping!

[moltob]

Triggered affected user to try it out. Stand by.

[moltob]

User reproduced issue. Even after setting CONAN_COLOR_DISPLAY=0 the error still occurred. Since the code in conan is guarding tqdm usage by checking for a TTY, the user does _not_ have the issue, if he pipes the output to file.

[danimtb]

Thanks a lot for testing @moltob. So the environment to reproduce it is the one you described above and the action done would be anything triggering an output to console of a tqdm progress bar, right?

[memsharded]

But the final error trace still fails in colorama, like in the above trace? Because the surprising thing is that the code that actually uses colorama is like this:

@staticmethod
    def factory(interactive=None):
        """Factory"""
        # Respect color env setting or check tty if unset
        color_set = "CONAN_COLOR_DISPLAY" in os.environ
        if ((color_set and get_env("CONAN_COLOR_DISPLAY", 1))
                or (not color_set
                    and hasattr(sys.stdout, "isatty")
                    and sys.stdout.isatty())):
            import colorama
            if get_env("PYCHARM_HOSTED"):  # in PyCharm disable convert/strip
                colorama.init(convert=False, strip=False)
            else:
                colorama.init()
            color = True
        else:
            color = False
        out = ConanOutput(sys.stdout, color)
        user_io = UserIO(out=out)

As you can see, if that variable is set to 0, colorama should absolutely never be used, not called. I will try to debug it a little bit more, but please tell if the failing traces are still in colorama. Thanks!

[moltob]

Unfortunately, in that case it failed without trace... It starts decompressing with 0% and stops there, silently. I have seen that on other users' desktops as well. The funny thing: It is working when piping output to a file, so maybe this the switch that safes it in progress_bar.py:

# If there is no terminal, just print a beat every TIMEOUT_BEAT seconds.
if not output.is_terminal:
    output = _NoTerminalOutput(output)

So I have in general seen this fail in three ways:

• With the full blown stack trace from the ticket description.
• With a oneliner like "Error [0]", I believe.
• Silently, just aborting.

Note that this must be something really fishy, as it is _only_ happening if you are running CMD, not another console, and _only_ if the user account has admin privileges. And even then it still seems to work for some users...

Maybe this is something affecting tqdm _and_ colorama in some way, so we are looking at two different problems. Possibly the colorama effect shadows the tqdm/conan problem.

But all I can say right now is: It surfaced after conan introduced tqdm and we never had this before (AFAIK!). And conan used colored output from day one I started to use it.

Thanks for your support!!!

[jgsogo]

Hi!

I'm having a look at this issue and it won't be enough using CONAN_COLOR_DISPLAY=0 because tqdm itself is initialazing it for Windows in this code block:

try:  # pragma: no cover
    if IS_WIN:
        import colorama
        colorama.init()
    else:
        colorama = None
except ImportError:  # pragma: no cover
    colorama = None
except:  # pragma: no cover
    raise  # try updating colorama?

There is no workaround for this initialization (just ask them to include some kind of opt-out). Nevertheless we should investigate two workarounds in order to check if this is the root of the problem:

1. We can remove those lines from the tqdm package modifying the .py file in our workspace. This is a patch just to check if this is related to colorama.

2. We can try a workaround in Conan: changing the implementation of the open_binary function to something like:

   @contextmanager
   def colorama_shutdown():
       # Maybe opt-out/in too according to env variable CONAN_COLOR_DISPLAY
       try:
           import colorama
           colorama.deinit()
           yield
           colorama.init()
       except ImportError:
           yield
   
   @contextmanager
   def open_binary(path, output, **kwargs):
       with open(path, mode='rb') as f:
           file_wrapped = _FileReaderWithProgressBar(f, output=output, **kwargs)
           with colorama_shutdown():
               yield file_wrapped
               file_wrapped.pb_close()
   
            if not output.is_terminal:
               output.write("\n")
   

   I haven't tested this code, so it can contain some errors, also I cannot reproduce the issue to test if this aliviates the pain until we take a final decission about it.

Note.- This issue in colorama might be relevant if we keep using tqdm (https://github.com/tartley/colorama/issues/145), we need it to be fixed (maybe we should open the PR).

[moltob]

@jgsogo Thanks a bunch for the analysis! Since I'm calling conan from Python via API I can probably monkey patch colorama and have affected users retry with that. Need to prepare this and report back next week.

Unfortunately I cannot just have them change tqdm code, as they are no Python devs. Also I'm worried that other code still calls colorama as well. I'll patch all those calls if needed and we'll see.

[moltob]

To figure out where to patch I intrumented calls to colorama's init, deinitand reinit functions. Turns out only init is called:

>>> Initializing colorama from c:\...\bin\toolenv\venv\lib\site-packages\icci\doit\reporting.py:20 (configure_logging)
>>> Initializing colorama from c:\...\bin\toolenv\venv\lib\site-packages\tqdm\_utils.py:33 (<module>)
>>> Initializing colorama from c:\...\bin\toolenv\venv\lib\site-packages\conans\client\conan_api.py:185 (factory)

When I set CONAN_COLOR_DISPLAY=0, the conan call is missing, the other two are still there, as expected. The icci-doit package is an internally developed package that is in turn calling conan via API as mentioned above.

Temporarily added an immediate return to colorama.init(). This showed something interesting: I still got colored logger output! Turns out the console emulator cmder I am using on Windows has native support for these ANSI color sequences. And this emulator never breaks decompression (unfortunately CMD does neither for me...).

Repeating the test with CMD shows uncolored output and some ugly characters, as I am using daiquiri for logger initialization, which in turn just uses color codes in the corresponding formatter, without colorama initialization on its own. So this is expected.

The differences in the shell emulators with and without ANSI color support further hints at colorama.

Will look into preventing the init for my test user...

[moltob]

Dammit... Just got feedback from user:

• He disabled any colorama init calls.
• I could verify this, since the aforementioned daiquiri component created the ugly control sequences in his output screenshot.
• Decompression _still_ fails at 0%.

[moltob]

I you tell me a smart way to disable tqdm in a single location while _not_ piping to file, I'll let him retry that...

[jgsogo]

To disable tqdm you have to remove the import tqdm (at that moment the colorama library is imported and initialized) and also the places where it is used. All the code related to it is inside the file conans/util/progress_bar.py.

This is a patch you can apply on release/1.9.2 (in your first post you said this is the version you were using) or you can make the changes your own, those are easy ones.

diff --git a/conans/util/progress_bar.py b/conans/util/progress_bar.py
index b6f4df56..a76ed66e 100644
--- a/conans/util/progress_bar.py
+++ b/conans/util/progress_bar.py
@@ -1,6 +1,6 @@

 import os
-from tqdm import tqdm
+#from tqdm import tqdm
 from contextlib import contextmanager

 TIMEOUT_BEAT_SECONDS = 30
@@ -27,7 +27,7 @@ class _FileReaderWithProgressBar(object):
         self._output = output
         self._fileobj = fileobj
         self.seek(0, os.SEEK_END)
-        self._pb = tqdm(total=self.tell(), desc=desc, file=output, **pb_kwargs)
+        # self._pb = tqdm(total=self.tell(), desc=desc, file=output, **pb_kwargs)
         self.seek(0)

     def seekable(self):
@@ -42,15 +42,17 @@ class _FileReaderWithProgressBar(object):
     def read(self, size):
         prev = self.tell()
         ret = self._fileobj.read(size)
-        self._pb.update(self.tell() - prev)
+        # self._pb.update(self.tell() - prev)
         return ret

     def pb_close(self):
-        self._pb.close()
+        # self._pb.close()
+        pass

     def pb_write(self, message):
         """ Allow to write messages to output without interfering with the progress bar """
-        tqdm.write(message, file=self._ori_output)
+        # tqdm.write(message, file=self._ori_output)
+        pass


 class _NoTerminalOutput(object):

Thanks for your feedback

[moltob]

Thanks for the info. Created a patched version of progress_bar.py and sent to user for testing. Let's see.

[memsharded]

I have tracked down this issue to an OS problem, when Windows, in some occassions is holding the sys.stdout resource blocked, and then attempts to output to it might fail. Not only in tqdm, but also in @SSE4 case, there are other places where the system fails, for example if scrolling the CMD window. Doing that scroll can interrupt transfers (downloads of packages), that are not using tqdm at all, and even also after completely disabled colorama.

I have proposed in https://github.com/conan-io/conan/pull/4375 a more robust way to output to stdout, as a workaround to this issue. I think it might solve this in a more global way.

[moltob]

Feedback from user: User decompression issue fixed by disabling tqdm altogether. (He did not scroll, though... :smile: )

@memsharded That is really excellent! :rocket: Thanks a lot for taking this issue serious!

[moltob]

@memsharded Were you able to reproduce the error?

[memsharded]

Hi @moltob

I was able to reproduce some errors with @SSE4 help.
I have proposed to try to fix the underlying error, in: https://github.com/conan-io/conan/pull/4375. The problem is that in some systems (Windows), with some terminals (CMD), and under unknown circumstances (the Windows OS build could affect), sometimes the OS will temporarily lock the stdout. When conan tries to write in it, it fails with IOError. The above fix tries to alleviate it by first retrying, then skipping the output.

It is already merged to develop and released in Test PyPI: https://test.pypi.org/project/conan/#history, if you want to give it a try now before the release: $ pip install --index-url https://test.pypi.org/simple/ conan. Many thanks for your continuous feedback!

[moltob]

I'll be kind of hard to use the prerelease in our setup on that user's machine. I'll verify this with public 1.12 once it's available. Thanks a lot!