JupyterNotebook hangs when using DVC

[zanussbaum]

Bug Report

Description

We have been using dvc and it's been working great for our package. However, if we try to use our package (which uses dvc to pull data for us internally) in a Jupyter Notebook, it hangs forever. We have seen that this is where dvc seems to hang

----> 1 import dvc
      2 import dvc.api
      4 from datasetzoo.utils.filesystem import download_objects
File ~/conda/envs/dsn_test/lib/python3.8/site-packages/dvc/__init__.py:9
      6 import dvc.logger
      7 from dvc.version import __version__  # noqa: F401
----> 9 dvc.logger.setup()
File ~/conda/envs/dsn_test/lib/python3.8/site-packages/dvc/logger.py:230, in setup(level)
    227     logging.getLogger("aiohttp").setLevel(logging.CRITICAL)
    229 addLoggingLevel("TRACE", logging.DEBUG - 5)
--> 230 logging.config.dictConfig(
    231     {
    232         "version": 1,
    233         "filters": {
    234             "exclude_errors": {"()": excludeFilter(logging.WARNING)},
    235             "exclude_info": {"()": excludeFilter(logging.INFO)},
    236             "exclude_debug": {"()": excludeFilter(logging.DEBUG)},
    237         },
    238         "formatters": {"color": {"()": ColorFormatter}},
    239         "handlers": {
    240             "console_info": {
    241                 "class": "dvc.logger.LoggerHandler",
    242                 "level": "INFO",
    243                 "formatter": "color",
    244                 "stream": "ext://sys.stdout",
    245                 "filters": ["exclude_errors"],
    246             },
    247             "console_debug": {
    248                 "class": "dvc.logger.LoggerHandler",
    249                 "level": "DEBUG",
    250                 "formatter": "color",
    251                 "stream": "ext://sys.stdout",
    252                 "filters": ["exclude_info"],
    253             },
    254             "console_trace": {
    255                 "class": "dvc.logger.LoggerHandler",
    256                 "level": "TRACE",
    257                 "formatter": "color",
    258                 "stream": "ext://sys.stdout",
    259                 "filters": ["exclude_debug"],
    260             },
    261             "console_errors": {
    262                 "class": "dvc.logger.LoggerHandler",
    263                 "level": "WARNING",
    264                 "formatter": "color",
    265                 "stream": "ext://sys.stderr",
    266             },
    267         },
    268         "loggers": {
    269             "dvc": {
    270                 "level": level,
    271                 "handlers": [
    272                     "console_info",
    273                     "console_debug",
    274                     "console_trace",
    275                     "console_errors",
    276                 ],
    277             },
    278             "dvc_objects": {
    279                 "level": level,
    280                 "handlers": [
    281                     "console_info",
    282                     "console_debug",
    283                     "console_trace",
    284                     "console_errors",
    285                 ],
    286             },
    287             "dvc_data": {
    288                 "level": level,
    289                 "handlers": [
    290                     "console_info",
    291                     "console_debug",
    292                     "console_trace",
    293                     "console_errors",
    294                 ],
    295             },
    296         },
    297         "disable_existing_loggers": False,
    298     }
    299 )
File ~/conda/envs/dsn_test/lib/python3.8/logging/config.py:808, in dictConfig(config)
    806 def dictConfig(config):
    807     """Configure logging using a dictionary."""
--> 808     dictConfigClass(config).configure()
File ~/conda/envs/dsn_test/lib/python3.8/logging/config.py:536, in DictConfigurator.configure(self)
    533 else:
    534     disable_existing = config.pop('disable_existing_loggers', True)
--> 536     _clearExistingHandlers()
    538     # Do formatters first - they don't refer to anything else
    539     formatters = config.get('formatters', EMPTY_DICT)
File ~/conda/envs/dsn_test/lib/python3.8/logging/config.py:273, in _clearExistingHandlers()
    271 """Clear and close existing handlers"""
    272 logging._handlers.clear()
--> 273 logging.shutdown(logging._handlerList[:])
    274 del logging._handlerList[:]
File ~/conda/envs/dsn_test/lib/python3.8/logging/__init__.py:2127, in shutdown(handlerList)
   2125     h.acquire()
   2126     h.flush()
-> 2127     h.close()
   2128 except (OSError, ValueError):
   2129     # Ignore errors which might be caused
   2130     # because handlers have been closed but
   2131     # references to them are still around at
   2132     # application exit.
   2133     pass
File ~/conda/envs/dsn_test/lib/python3.8/site-packages/absl/logging/__init__.py:934, in PythonHandler.close(self)
    931   user_managed = sys.stderr, sys.stdout, sys.__stderr__, sys.__stdout__
    932   if self.stream not in user_managed and (
    933       not hasattr(self.stream, 'isatty') or not self.stream.isatty()):
--> 934     self.stream.close()
    935 except ValueError:
    936   # A ValueError is thrown if we try to run isatty() on a closed file.
    937   pass
File ~/conda/envs/dsn_test/lib/python3.8/site-packages/ipykernel/iostream.py:438, in OutStream.close(self)
    436 if sys.platform.startswith("linux") or sys.platform.startswith("darwin"):
    437     self._should_watch = False
--> 438     self.watch_fd_thread.join()
    439 if self._exc:
    440     etype, value, tb = self._exc
File ~/conda/envs/dsn_test/lib/python3.8/threading.py:1011, in Thread.join(self, timeout)
   1008     raise RuntimeError("cannot join current thread")
   1010 if timeout is None:
-> 1011     self._wait_for_tstate_lock()
   1012 else:
   1013     # the behavior of a negative timeout isn't documented, but
   1014     # historically .join(timeout=x) for x<0 has acted as if timeout=0
   1015     self._wait_for_tstate_lock(timeout=max(timeout, 0))
File ~/conda/envs/dsn_test/lib/python3.8/threading.py:1027, in Thread._wait_for_tstate_lock(self, block, timeout)
   1025 if lock is None:  # already determined that the C code is done
   1026     assert self._is_stopped
-> 1027 elif lock.acquire(block, timeout):
   1028     lock.release()
   1029     self._stop()
KeyboardInterrupt:

How can we avoid this hanging in Jupyter?

[pmrowla]

The hang is in the built in python logging module, not in DVC.

Are you using multiprocessing? It looks like it could be this issue: https://bugs.python.org/issue42097

[dg-carolyn]

Hi @pmrowla , I'm @zanussbaum 's colleague and I believe our problem has to do with logging handlers added by tensorflow (the absl/logging in the stack trace above).
In a jupyter notebook, import dvc works fine, but import tensorflow; import dvc has the same problem.

Specifically, this can be narrowed down to the handlers added by tensorflow like so:

import logging

# Stash the handlers before tensorflow adds its own.
pre_tensorflow_handlers = list(logging._handlerList)

import tensorflow as tf

# Restore handlers
logging._handlerList = pre_tensorflow_handlers

import dvc # This now works fine in Jupyter

This is with python 3.8.13, tensorflow 2.8.0, dvc 2.27.2.

[pmrowla]

That sounds like this is probably a tensorflow (or absl) issue. DVC just uses the standard python logging methods, and does not modify anything internally that would cause logging.config.dictConfig() to hang.

[dg-carolyn]

@pmrowla it looks like an interaction between colorama, tensorflow/absl, and Jupyter. dvc.logger.setup() calls colorama.init() before logging.config.dictConfig(...), and in Jupyter notebook:

import tensorflow
import logging

logging.config.dictConfig(
    {
        'version': 1,
    }
)

works fine, but

import tensorflow
import logging

import colorama
colorama.init()

logging.config.dictConfig(
    {
        'version': 1,
    }
)

hangs with the same stack trace.

[pmrowla]

@dg-carolyn if you import dvc before importing tensorflow (so colorama+dvc logging is init'ed before absl logging) do you get the same behavior

[dberenbaum]

I can reproduce by opening a jupyter notebook and running:

import tensorflow
import dvc

@pmrowla It does not hang if I reverse the imports.

[dberenbaum]

To fix it without debugging the underlying tensorflow and colorama issues, it seems like the easiest thing to do is to move colorama.init() to the bottom of dvc.logger.setup().