replace custom logging with python standard library #262

vbraun · 2014-06-30T02:24:52Z

This patch removes hdist_logging.py with the Python logging module. The logging configuration is in a yaml file, pretty standard.

I left the "hit logpipe" command in there, though I still don't understand what its for. Is part of the unit test fixtures? I can take it out and hashdist works fine. See also https://groups.google.com/d/msg/hashdist/TApv422EmZA/LHCApTw8yC8J
Python best practice is to not pass the logger around but use logging.getLogger() to access the singleton loggers. Replacing this would be the next step, but its not done here.

certik · 2014-06-30T05:34:36Z

I am +1 to the change in general. I didn't have time to investigate why Travis tests fail, but that should be fixed. I'll try to build my stack tomorrow with this PR to see if things work.

ahmadia · 2014-06-30T12:59:52Z

I think we already agreed that this is a desirable change, but this will need review and testing before it is ready to merge.

I've been away from email for a couple of days and am catching up but I will try to help review this today.

vbraun · 2014-06-30T14:38:53Z

Ok, logging configuration from a dict was only added in Python 2.7. I've added a suitable backport for python 2.6 and tox.ini to make testing outside of travis easier.

ahmadia · 2014-07-03T15:01:24Z

Okay, this doesn't look quite right to me...

~/hashstack git:hashdist-add_memory_profiler ❯❯❯ hit build test.ipython.yaml                                                                                                         ⬆ ◼
[profile] Building profile/3loby34tkzsb, follow log with:
[profile]   tail -f /Users/aron/.hashdist/tmp/profile-3loby34tkzsb/build.log
running ['hit', 'create-links', u'/Users/aron/.hashdist/tmp/profile-3loby34tkzsb/job/16_in0.json']
running ['hit', 'build-postprocess', '--write-protect']
Up to date, link at: test.ipython
~/hashstack git:hashdist-add_memory_profiler ❯❯❯ hit build -v test.ipython.yaml                                                                                                      ⬆ ◼
[INFO] Resolved package python to [u'/Users/aron/hashstack/pkgs/python/python.yaml', u'/Users/aron/hashstack/pkgs/python/python-from-host.yaml']
[INFO] Resolved package autotools_package to [u'/Users/aron/hashstack/base/autotools_package.yaml']
[INFO] Resolved package base_package to [u'/Users/aron/hashstack/base/base_package.yaml']
[INFO] Resolved package bzip2 to [u'/Users/aron/hashstack/pkgs/bzip2/bzip2.yaml']
[INFO] Resolved package launcher to [u'/Users/aron/hashstack/pkgs/launcher.yaml']
[INFO] Resolved package ncurses to [u'/Users/aron/hashstack/pkgs/ncurses/ncurses.yaml']
[INFO] Resolved package readline to [u'/Users/aron/hashstack/pkgs/readline.yaml']
[INFO] Resolved package zlib to [u'/Users/aron/hashstack/pkgs/zlib/zlib.yaml']
[INFO] Resolved package ipython to [u'/Users/aron/hashstack/pkgs/ipython.yaml']
[INFO] Resolved package distutils_package to [u'/Users/aron/hashstack/base/distutils_package.yaml']
[INFO] Resolved package jinja2 to [u'/Users/aron/hashstack/pkgs/jinja2.yaml']
[INFO] Resolved package setuptools_package to [u'/Users/aron/hashstack/base/setuptools_package.yaml']
[INFO] Resolved package setuptools to [u'/Users/aron/hashstack/pkgs/setuptools.yaml']
[INFO] Resolved package pygments to [u'/Users/aron/hashstack/pkgs/pygments.yaml']
[INFO] Resolved package pyzmq to [u'/Users/aron/hashstack/pkgs/pyzmq.yaml']
[INFO] Resolved package cython to [u'/Users/aron/hashstack/pkgs/cython.yaml']
[INFO] Resolved package numpy to [u'/Users/aron/hashstack/pkgs/numpy/numpy.yaml']
[INFO] Resolved package host-blas to [u'/Users/aron/hashstack/pkgs/host-blas.yaml']
[INFO] Resolved package zmq to [u'/Users/aron/hashstack/pkgs/zmq.yaml']
[INFO] Resolved package sphinx to [u'/Users/aron/hashstack/pkgs/sphinx.yaml']
[INFO] Resolved package docutils to [u'/Users/aron/hashstack/pkgs/docutils.yaml']
[INFO] Resolved package tornado to [u'/Users/aron/hashstack/pkgs/tornado.yaml']
Up to date, link at: test.ipython

ahmadia · 2014-07-03T15:02:06Z

Why am I seeing different output when I run with -v? The verbose output should definitely be a superset of the "normal" output.

ahmadia · 2014-07-03T15:03:28Z

Also, it doesn't appear that hit build without verbose output is hiding the build output.

[sphinx] Building sphinx/efoif5rdsz27, follow log with:
[sphinx]   tail -f /Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27/build.log
running [u'/bin/bash', '_hashdist/build.sh']
environment:
  {'ARTIFACT': u'/Users/aron/.hashdist/bld/sphinx/efoif5rdsz27',
   'BASH': u'/bin/bash',
   'BUILD': u'/Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27',
   u'DOCUTILS_DIR': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c',
   u'DOCUTILS_ID': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro',
   'HASHDIST_CPU_COUNT': '1',
   'HDIST_CONFIG': '{"gc_roots":"/Users/aron/.hashdist/gcroots","source_caches":[{"dir":"/Users/aron/.hashdist/src"}],"default_profile":{"default_use":{"lapack":"host-osx-framework-acce
   'HDIST_IMPORT': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro jinja2/eia76eddu3htrg32t7viltnizdaz2fdu pygments/jnmrpgouqae4czv4vt35fjdmr3yddyyw python/i6pwnfglail6za5c4gmrr6skuynxreje
   'HDIST_IMPORT_PATHS': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c:/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht:/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4:/Users/aron/.has
   'HDIST_VIRTUALS': '',
   u'JINJA2_DIR': u'/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht',
   u'JINJA2_ID': u'jinja2/eia76eddu3htrg32t7viltnizdaz2fdu',
   'PATH': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin',
   'PWD': u'/Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27',
   u'PYGMENTS_DIR': u'/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4',
   u'PYGMENTS_ID': u'pygments/jnmrpgouqae4czv4vt35fjdmr3yddyyw',
   'PYTHON': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6/bin/python',
   'PYTHONPATH': u'/Users/aron/.hashdist/bld/setuptools/rfjv6fjbdlho/lib/python2.7/site-packages:/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4/lib/python2.7/site-packages:/Users/aron/
   u'PYTHON_DIR': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6',
   u'PYTHON_ID': u'python/i6pwnfglail6za5c4gmrr6skuynxreje',
   u'SETUPTOOLS_DIR': u'/Users/aron/.hashdist/bld/setuptools/rfjv6fjbdlho',
   u'SETUPTOOLS_ID': u'setuptools/rfjv6fjbdlhokrt7bl2xikwhsro6rpdo'}
running install
running build
running build_py
...

~/hashstack git:hashdist-add_memory_profiler ❯❯❯ hit build -v test.ipython.yaml                                                                                                      ⬆ ◼
[INFO] Resolved package python to [u'/Users/aron/hashstack/pkgs/python/python.yaml', u'/Users/aron/hashstack/pkgs/python/python-from-host.yaml']
[INFO] Resolved package autotools_package to [u'/Users/aron/hashstack/base/autotools_package.yaml']
[INFO] Resolved package base_package to [u'/Users/aron/hashstack/base/base_package.yaml']
[INFO] Resolved package bzip2 to [u'/Users/aron/hashstack/pkgs/bzip2/bzip2.yaml']
[INFO] Resolved package launcher to [u'/Users/aron/hashstack/pkgs/launcher.yaml']
[INFO] Resolved package ncurses to [u'/Users/aron/hashstack/pkgs/ncurses/ncurses.yaml']
[INFO] Resolved package readline to [u'/Users/aron/hashstack/pkgs/readline.yaml']
[INFO] Resolved package zlib to [u'/Users/aron/hashstack/pkgs/zlib/zlib.yaml']
[INFO] Resolved package ipython to [u'/Users/aron/hashstack/pkgs/ipython.yaml']
[INFO] Resolved package distutils_package to [u'/Users/aron/hashstack/base/distutils_package.yaml']
[INFO] Resolved package jinja2 to [u'/Users/aron/hashstack/pkgs/jinja2.yaml']
[INFO] Resolved package setuptools_package to [u'/Users/aron/hashstack/base/setuptools_package.yaml']
[INFO] Resolved package setuptools to [u'/Users/aron/hashstack/pkgs/setuptools.yaml']
[INFO] Resolved package pygments to [u'/Users/aron/hashstack/pkgs/pygments.yaml']
[INFO] Resolved package pyzmq to [u'/Users/aron/hashstack/pkgs/pyzmq.yaml']
[INFO] Resolved package cython to [u'/Users/aron/hashstack/pkgs/cython.yaml']
[INFO] Resolved package numpy to [u'/Users/aron/hashstack/pkgs/numpy/numpy.yaml']
[INFO] Resolved package host-blas to [u'/Users/aron/hashstack/pkgs/host-blas.yaml']
[INFO] Resolved package zmq to [u'/Users/aron/hashstack/pkgs/zmq.yaml']
[INFO] Resolved package sphinx to [u'/Users/aron/hashstack/pkgs/sphinx.yaml']
[INFO] Resolved package docutils to [u'/Users/aron/hashstack/pkgs/docutils.yaml']
[INFO] Resolved package tornado to [u'/Users/aron/hashstack/pkgs/tornado.yaml']
[sphinx] Building sphinx/efoif5rdsz27, follow log with:
[sphinx]   tail -f /Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27/build.log
running [u'/bin/bash', '_hashdist/build.sh']
environment:
  {'ARTIFACT': u'/Users/aron/.hashdist/bld/sphinx/efoif5rdsz27',
   'BASH': u'/bin/bash',
   'BUILD': u'/Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27',
   u'DOCUTILS_DIR': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c',
   u'DOCUTILS_ID': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro',
   'HASHDIST_CPU_COUNT': '1',
   'HDIST_CONFIG': '{"gc_roots":"/Users/aron/.hashdist/gcroots","source_caches":[{"dir":"/Users/aron/.hashdist/src"}],"default_profile":{"default_use":{"lapack":"host-osx-framework-accelerate","blas":"host-osx-framework-accelerate"},"package_dirs":["pkgs","base"],"parameters":{"python_site_packages_rel":"lib/python2.7/site-packages","pyver":"2.7","platform":"darwin","PATH":"/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin","PROLOGUE":"export MACOSX_DEPLOYMENT_TARGET=$(sw_vers -productVersion | sed \\"s/\\\\(10.[0-9]\\\\).*/\\\\1/\\")\\n","BASH":"/bin/bash"},"hook_import_dirs":["base"]},"build_stores":[{"dir":"/Users/aron/.hashdist/bld"}],"cache":"/Users/aron/.hashdist/cache","build_temp":"/Users/aron/.hashdist/tmp"}',
   'HDIST_IMPORT': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro jinja2/eia76eddu3htrg32t7viltnizdaz2fdu pygments/jnmrpgouqae4czv4vt35fjdmr3yddyyw python/i6pwnfglail6za5c4gmrr6skuynxreje setuptools/rfjv6fjbdlhokrt7bl2xikwhsro6rpdo',
   'HDIST_IMPORT_PATHS': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c:/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht:/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4:/Users/aron/.hashdist/bld/python/i6pwnfglail6:/Users/aron/.hashdist/bld/setuptools/rfjv6fjbdlho',
   'HDIST_VIRTUALS': '',
   u'JINJA2_DIR': u'/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht',
   u'JINJA2_ID': u'jinja2/eia76eddu3htrg32t7viltnizdaz2fdu',
   'PATH': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin',
   'PWD': u'/Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27',
   u'PYGMENTS_DIR': u'/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4',
   u'PYGMENTS_ID': u'pygments/jnmrpgouqae4czv4vt35fjdmr3yddyyw',
   'PYTHON': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6/bin/python',
   'PYTHONPATH': u'/Users/aron/.hashdist/bld/setuptools/rfjv6fjbdlho/lib/python2.7/site-packages:/Users/aron/.hashdist/bld/pygments/jnmrpgouqae4/lib/python2.7/site-packages:/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht/lib/python2.7/site-packages:/Users/aron/.hashdist/bld/docutils/wscijk2u225c/lib/python2.7/site-packages',
   u'PYTHON_DIR': u'/Users/aron/.hashdist/bld/python/i6pwnfglail6',
   u'PYTHON_ID': u'python/i6pwnfglail6za5c4gmrr6skuynxreje',
   u'SETUPTOOLS_DIR': u'/Users/aron/.hashdist/bld/setuptools/rfjv6fjbdlho',
   u'SETUPTOOLS_ID': u'setuptools/rfjv6fjbdlhokrt7bl2xikwhsro6rpdo'}
running install
running build
running build_py
creating build
creating build/lib
creating build/lib/sphinx
copying sphinx/__init__.py -> build/lib/sphinx
copying sphinx/addnodes.py -> build/lib/sphinx
copying sphinx/apidoc.py -> build/lib/sphinx
copying sphinx/application.py -> build/lib/sphinx
copying sphinx/cmdline.py -> build/lib/sphinx
copying sphinx/config.py -> build/lib/sphinx
...
running ['hit', 'build-postprocess', '--shebang=multiline', '--write-protect']
Profile build successful, link at: test.ipython

ahmadia · 2014-07-03T15:13:44Z

@vbraun - Thanks for the pull request. I like how our build logs are now timestamped:

~/hashstack git:hashdist-add_memory_profiler ❯❯❯ zless ~/.hashdist/bld/sphinx/efoif5rdsz27/build.log.gz                                                                              ⬆ ◼
2014/07/03 11:11:51 - INFO: [build:run_job] running [u'/bin/bash', '_hashdist/build.sh']
2014/07/03 11:11:51 - INFO: [build:run_job] environment:
2014/07/03 11:11:51 - INFO: [build:run_job]   {'ARTIFACT': u'/Users/aron/.hashdist/bld/sphinx/efoif5rdsz27',
2014/07/03 11:11:51 - INFO: [build:run_job]    'BASH': u'/bin/bash',
2014/07/03 11:11:51 - INFO: [build:run_job]    'BUILD': u'/Users/aron/.hashdist/tmp/sphinx-efoif5rdsz27',
2014/07/03 11:11:51 - INFO: [build:run_job]    u'DOCUTILS_DIR': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c',
2014/07/03 11:11:51 - INFO: [build:run_job]    u'DOCUTILS_ID': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro',
2014/07/03 11:11:51 - INFO: [build:run_job]    'HASHDIST_CPU_COUNT': '1',
2014/07/03 11:11:51 - INFO: [build:run_job]    'HDIST_CONFIG': '{"gc_roots":"/Users/aron/.hashdist/gcroots","source_caches":[{"dir":"/Users/aron/.hashdist/src"}],"default_profile":{"def
2014/07/03 11:11:51 - INFO: [build:run_job]    'HDIST_IMPORT': u'docutils/wscijk2u225c5imstkh3tcpbmlytvfro jinja2/eia76eddu3htrg32t7viltnizdaz2fdu pygments/jnmrpgouqae4czv4vt35fjdmr3ydd
2014/07/03 11:11:51 - INFO: [build:run_job]    'HDIST_IMPORT_PATHS': u'/Users/aron/.hashdist/bld/docutils/wscijk2u225c:/Users/aron/.hashdist/bld/jinja2/eia76eddu3ht:/Users/aron/.hashdis
2014/07/03 11:11:51 - INFO: [build:run_job]    'HDIST_VIRTUALS': '',
2
...

Here's what I believe is currently missing:

if verbose output is not specified, the output of the package builds should not be sent to stdout
it would be nice to restore the colorized prefix for verbose builds on stdout
The non-verbose output should also be sent to verbose output

ahmadia · 2014-07-05T02:14:23Z

@vbraun - repinging on this one. Do you need anything from me?

vbraun · 2014-07-05T02:36:38Z

No, I agree. Just need some time.

This simplifies the logging: The root logger is the default, and the package logger contains the package name in square brackets. Also, a custom formatter is added for level-dependent formatting.

vbraun · 2014-07-12T04:58:04Z

Ok, fixed all conflicts and the issues.

I've also added gray = debug color. The verbose mode is what is now --log=INFO.

certik · 2014-07-16T19:36:12Z

I tested this PR, and it fixes most of the annoyances that's been bothering me, like

that in verbose mode, the profile installation completely clogs my terminal with hundreds of pages of output
the time stamps to know how long things took
The "Resolved package mercurial to" lines are now prefixed with [INFO]

Tests pass, so I am merging this. If there are any further issues, we can fix that with subsequent PRs.

Thanks @vbraun for this work, it greatly improves the experience.

replace custom logging with python standard library

ahmadia · 2014-07-16T19:37:29Z

Thanks @certik - you are a rockstar :)

ahmadia · 2014-07-17T01:41:48Z

This looks like it may have broken the PyClaw builds on Travis (unconfirmed suspicion): clawpack/pyclaw#442

I've moved the PyClaw CI off our master branch and to the 0.3 tag.

ahmadia mentioned this pull request Jul 1, 2014

Support for building relocateable packages #226

Merged

vbraun added 3 commits July 11, 2014 21:50

replace custom logging with python standard library

33250ef

Python 2.6 fixes

e8423b7

Only use two loggers, root and package

711d306

This simplifies the logging: The root logger is the default, and the package logger contains the package name in square brackets. Also, a custom formatter is added for level-dependent formatting.

certik added a commit that referenced this pull request Jul 16, 2014

Merge pull request #262 from vbraun/logging

891d375

replace custom logging with python standard library

certik merged commit 891d375 into hashdist:master Jul 16, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

replace custom logging with python standard library #262

replace custom logging with python standard library #262

vbraun commented Jun 30, 2014

certik commented Jun 30, 2014

ahmadia commented Jun 30, 2014

vbraun commented Jun 30, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 5, 2014

vbraun commented Jul 5, 2014

vbraun commented Jul 12, 2014

certik commented Jul 16, 2014

ahmadia commented Jul 16, 2014

ahmadia commented Jul 17, 2014

replace custom logging with python standard library #262

replace custom logging with python standard library #262

Conversation

vbraun commented Jun 30, 2014

certik commented Jun 30, 2014

ahmadia commented Jun 30, 2014

vbraun commented Jun 30, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 3, 2014

ahmadia commented Jul 5, 2014

vbraun commented Jul 5, 2014

vbraun commented Jul 12, 2014

certik commented Jul 16, 2014

ahmadia commented Jul 16, 2014

ahmadia commented Jul 17, 2014