search

datalad / datalad

Keep code, data, containers under control with git and git-annex
http://datalad.org
Other
543 stars 111 forks source link

logging is freaking out and starts to breed ValueError: I/O operation on closed file. #5351

Closed yarikoptic closed 3 years ago

yarikoptic commented 3 years ago

While doing a full python -m nose -s -v datalad/ 2>&1 | tee /tmp/all-tests-asyncio.log for #5350 at some point screen starts to get flooded with complaints from logger ... First encounter:

datalad.interface.tests.test_add_archive_content.test_add_archive_use_archive_dir ... ok
datalad.interface.tests.test_annotate_paths.test_annotate_paths ... --- Logging error ---
Traceback (most recent call last):
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/logging/__init__.py", line 1028, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
Call stack:
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/__main__.py", line 8, in <module>
    run_exit()
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/core.py", line 121, in __init__
    **extra_args)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/unittest/main.py", line 101, in __init__
    self.runTests()
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/core.py", line 207, in runTests
    result = self.testRunner.run(self.test)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/core.py", line 62, in run
    test(result)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 178, in __call__
    return self.run(*arg, **kw)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 225, in run
    test(orig)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 178, in __call__
    return self.run(*arg, **kw)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 225, in run
    test(orig)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 178, in __call__
    return self.run(*arg, **kw)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 225, in run
    test(orig)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 178, in __call__
    return self.run(*arg, **kw)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 225, in run
    test(orig)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 178, in __call__
    return self.run(*arg, **kw)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/suite.py", line 225, in run
    test(orig)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/case.py", line 46, in __call__
    return self.run(*arg, **kwarg)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/case.py", line 134, in run
    self.runTest(result)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/case.py", line 152, in runTest
    test(result)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/unittest/case.py", line 676, in __call__
    return self.run(*args, **kwds)
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/unittest/case.py", line 628, in run
    testMethod()
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/site-packages/nose/case.py", line 198, in runTest
    self.test(*self.arg)
  File "/home/yoh/proj/datalad/datalad-master/datalad/tests/utils.py", line 578, in _wrap_with_tree
    return t(*(arg + (d,)), **kw)
  File "/home/yoh/proj/datalad/datalad-master/datalad/tests/utils.py", line 757, in _wrap_with_tempfile
    return t(*(arg + (filename,)), **kw)
  File "/home/yoh/proj/datalad/datalad-master/datalad/interface/tests/test_annotate_paths.py", line 122, in test_annotate_paths
    annotate_paths(path=['a', 'b'])
  File "/home/yoh/proj/datalad/datalad-master/datalad/interface/utils.py", line 330, in eval_func
    wrapped_class = get_wrapped_class(wrapped)
  File "/home/yoh/proj/datalad/datalad-master/datalad/utils.py", line 2533, in get_wrapped_class
    lgr.debug("Determined class of decorated function: %s", _func_class)
Message: 'Determined class of decorated function: %s'
Arguments: (<class 'datalad.interface.annotate_paths.AnnotatePaths'>,)
--- Logging error ---
Traceback (most recent call last):
  File "/home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/lib/python3.7/logging/__init__.py", line 1028, in emit
    stream.write(msg + self.terminator)
ValueError: I/O operation on closed file.
DataLad 0.13.7.dev714 WTF (datalad, dependencies) # WTF - datalad: version=0.13.7.dev714 full_version=0.13.7.dev714-g33d3-dirty - dependencies: cmd:git=2.24.0 cmd:annex=8.20201127+git54-ga1b227171-1~ndall+1 cmd:bundled-git=2.24.0 cmd:system-git=2.29.2 cmd:system-ssh=8.4p1 cmd:7z=16.02 annexremote=1.4.3 appdirs=1.4.4 boto=2.49.0 exifread=2.3.1 humanize=3.0.1 iso8601=0.1.13 keyring=21.4.0 keyrings.alt=4.0.0 msgpack=1.0.0 mutagen=1.45.1 requests=2.24.0 wrapt=1.12.1
DataLad 0.13.7.dev714 WTF (configuration, credentials, datalad, dataset, dependencies, environment, extensions, git-annex, location, metadata_extractors, metadata_indexers, python, system) # WTF ## configuration ## credentials - keyring: - active_backends: - SecretService Keyring - PlaintextKeyring with no encyption v.1.0 at /home/yoh/.local/share/python_keyring/keyring_pass.cfg - config_file: /home/yoh/.config/python_keyring/keyringrc.cfg - data_root: /home/yoh/.local/share/python_keyring ## datalad - full_version: 0.13.7.dev714-g33d3-dirty - version: 0.13.7.dev714 ## dataset - id: None - metadata: - path: /home/yoh/proj/datalad/datalad-master - repo: GitRepo ## dependencies - annexremote: 1.4.3 - appdirs: 1.4.4 - boto: 2.49.0 - cmd:7z: 16.02 - cmd:annex: 8.20201127+git54-ga1b227171-1~ndall+1 - cmd:bundled-git: 2.24.0 - cmd:git: 2.24.0 - cmd:system-git: 2.29.2 - cmd:system-ssh: 8.4p1 - exifread: 2.3.1 - humanize: 3.0.1 - iso8601: 0.1.13 - keyring: 21.4.0 - keyrings.alt: 4.0.0 - msgpack: 1.0.0 - mutagen: 1.45.1 - requests: 2.24.0 - wrapt: 1.12.1 ## environment - GIT_PAGER: less --no-init --quit-if-one-screen - LANG: en_US.UTF-8 - PATH: /home/yoh/anaconda-5.2.0-2.7/envs/datalad-py3.7.9/bin:/home/yoh/anaconda-5.2.0-2.7/condabin:/home/yoh/gocode/bin:/home/yoh/gocode/bin:/home/yoh/bin:/home/yoh/.local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/sbin:/usr/sbin:/usr/local/sbin ## extensions ## git-annex - build flags: - Assistant - Webapp - Pairing - Inotify - DBus - DesktopNotify - TorrentParser - MagicMime - Feeds - Testsuite - S3 - WebDAV - dependency versions: - aws-0.20 - bloomfilter-2.0.1.0 - cryptonite-0.25 - DAV-1.3.3 - feed-1.0.0.0 - ghc-8.4.4 - http-client-0.5.13.1 - persistent-sqlite-2.8.2 - torrent-10000.1.1 - uuid-1.3.13 - yesod-1.6.0 - key/value backends: - SHA256E - SHA256 - SHA512E - SHA512 - SHA224E - SHA224 - SHA384E - SHA384 - SHA3_256E - SHA3_256 - SHA3_512E - SHA3_512 - SHA3_224E - SHA3_224 - SHA3_384E - SHA3_384 - SKEIN256E - SKEIN256 - SKEIN512E - SKEIN512 - BLAKE2B256E - BLAKE2B256 - BLAKE2B512E - BLAKE2B512 - BLAKE2B160E - BLAKE2B160 - BLAKE2B224E - BLAKE2B224 - BLAKE2B384E - BLAKE2B384 - BLAKE2BP512E - BLAKE2BP512 - BLAKE2S256E - BLAKE2S256 - BLAKE2S160E - BLAKE2S160 - BLAKE2S224E - BLAKE2S224 - BLAKE2SP256E - BLAKE2SP256 - BLAKE2SP224E - BLAKE2SP224 - SHA1E - SHA1 - MD5E - MD5 - WORM - URL - X* - operating system: linux x86_64 - remote types: - git - gcrypt - p2p - S3 - bup - directory - rsync - web - bittorrent - webdav - adb - tahoe - glacier - ddar - git-lfs - httpalso - hook - external - supported repository versions: - 8 - upgrade supported from repository versions: - 0 - 1 - 2 - 3 - 4 - 5 - 6 - 7 - version: 8.20201127+git54-ga1b227171-1~ndall+1 ## location - path: /home/yoh/proj/datalad/datalad-master - type: dataset ## metadata_extractors - annex (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.annex - version: None - audio (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.audio - version: None - datacite (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.datacite - version: None - datalad_core (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.datalad_core - version: None - datalad_rfc822 (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.datalad_rfc822 - version: None - exif (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.exif - version: None - frictionless_datapackage (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.frictionless_datapackage - version: None - image (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.image - version: None - xmp (datalad 0.13.7): - distribution: datalad 0.13.7 - load_error: None - module: datalad.metadata.extractors.xmp - version: None ## metadata_indexers ## python - implementation: CPython - version: 3.7.9 ## system - distribution: debian/bullseye/sid - encoding: - default: utf-8 - filesystem: utf-8 - locale.prefered: UTF-8 - max_path_length: 293 - name: Linux - release: 5.9.0-4-amd64 - type: posix - version: #1 SMP Debian 5.9.11-1 (2020-11-27)
adswa commented 3 years ago

I wonder if this still happens with the non-asyncio-based runner

yarikoptic commented 3 years ago

failing to reproduce now on my laptop on that commit 7b549bd271d92c679e15324cda624d336627e2a5 but newer the rest (python etc)... fwiw I ran into "operation on closed file" in the case of foreach as well (#5517) but not from logging I believe, but there it was due to threading. not sure if relates etc. anyways -- let's just let it RiP and reopen if resurfaces