New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Namespace the ansible.utils.display logging configuration #41859

Open
wants to merge 1 commit into
base: devel
from

Conversation

Projects
None yet
4 participants
@dmsimard
Contributor

dmsimard commented Jun 22, 2018

SUMMARY

The logging configuration provided by ansible.utils.display was not
namespaced which could cause conflicts with other python software
running with Ansible such as plugins, modules, etc.

This patch is effectively no-op in the sense that it keeps the exact
same formatting and configuration but will prevent conflicts from
happening.
It also makes it easier to customize the logging configuration in
the future if we need to or would like to expose a way for users
to provide their own configuration.

Fixes: #41838
Fixes: #25757
Fixes: #25759

ISSUE TYPE
  • Bugfix Pull Request
COMPONENT NAME

display

ANSIBLE VERSION
ansible 2.5.5
  config file = None
  configured module search path = [u'/root/.ansible/plugins/modules', u'/usr/share/ansible/plugins/modules']
  ansible python module location = /tmp/venv/lib/python2.7/site-packages/ansible
  executable location = /tmp/venv/bin/ansible
  python version = 2.7.5 (default, Aug  4 2017, 00:39:18) [GCC 4.8.5 20150623 (Red Hat 4.8.5-16)]
ADDITIONAL INFORMATION

Log output before the change:

2018-06-22 18:38:48,084 p=3993 u=root |   [WARNING]: Unable to parse /etc/ansible/hosts as an inventory source

2018-06-22 18:38:48,084 p=3993 u=root |   [WARNING]: No inventory was parsed, only implicit localhost is available

2018-06-22 18:38:48,087 p=3993 u=root |   [WARNING]: provided hosts list is empty, only localhost is available. Note that the implicit localhost does not match 'all'

2018-06-22 18:38:48,425 p=3993 u=root |  PLAY [localhost] ****************************************************************************************************************************************************************************************************
2018-06-22 18:38:48,436 p=3993 u=root |  TASK [Test] *********************************************************************************************************************************************************************************************************
2018-06-22 18:38:48,463 p=3993 u=root |  ok: [localhost] => {
    "msg": "test"
}
2018-06-22 18:38:48,465 p=3993 u=root |  PLAY RECAP **********************************************************************************************************************************************************************************************************
2018-06-22 18:38:48,465 p=3993 u=root |  localhost                  : ok=1    changed=0    unreachable=0    failed=0 

Log output after the change:

2018-06-22 19:35:06,457 p=4273 u=root |   [WARNING]: Unable to parse /etc/ansible/hosts as an inventory source

2018-06-22 19:35:06,458 p=4273 u=root |   [WARNING]: No inventory was parsed, only implicit localhost is available

2018-06-22 19:35:06,461 p=4273 u=root |   [WARNING]: provided hosts list is empty, only localhost is available. Note that the implicit localhost does not match 'all'

2018-06-22 19:35:07,278 p=4273 u=root |  PLAY [localhost] ****************************************************************************************************************************************************************************************************
2018-06-22 19:35:07,301 p=4273 u=root |  TASK [Test] *********************************************************************************************************************************************************************************************************
2018-06-22 19:35:07,346 p=4273 u=root |  ok: [localhost] => {
    "msg": "test"
}
2018-06-22 19:35:07,378 p=4273 u=root |  PLAY RECAP **********************************************************************************************************************************************************************************************************
2018-06-22 19:35:07,378 p=4273 u=root |  localhost                  : ok=1    changed=0    unreachable=0    failed=0   
@dmsimard

This comment has been minimized.

Contributor

dmsimard commented Jun 22, 2018

To better illustrate this change, here's output from logging_tree:

Before

<--""
   Level DEBUG
   Handler File u'/tmp/venv/ansible.log'
     Filter <ansible.utils.display.FilterBlackList object at 0x274e390>
     Formatter fmt='%(asctime)s %(name)s %(message)s' datefmt=None
   |
   o<--"p=4367 u=root | "
     Level NOTSET so inherits level DEBUG

After

<--""
   Level WARNING
   |
   o<--[ansible]
       |
       o<--[ansible.utils]
           |
           o   "ansible.utils.display"
               Level DEBUG
               Propagate OFF
               Handler File u'/tmp/venv/ansible.log'
                 Formatter fmt='%(asctime)s p=%(process)d u=%(user)s | %(message)s' datefmt=None

Merged with ARA (for sake of comparison)

<--""
   Level WARNING
   |
   o   "alembic"
   |   Level WARNING
   |   Propagate OFF
   |   Handler Stream <open file '<stdout>', mode 'w' at 0x7f766f33f150>
   |     Level INFO
   |     Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None
   |   Handler TimedRotatingFile '/root/.ara/ara.log' when='MIDNIGHT' interval=86400 backupCount=30
   |     Level INFO
   |     Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None
   |   |
   |   o<--[alembic.autogenerate]
   |   |   |
   |   |   o<--"alembic.autogenerate.compare"
   |   |       Level NOTSET so inherits level WARNING
   |   |
   |   o<--[alembic.ddl]
   |   |   |
   |   |   o<--"alembic.ddl.postgresql"
   |   |       Level NOTSET so inherits level WARNING
   |   |
   |   o<--[alembic.runtime]
   |   |   |
   |   |   o<--"alembic.runtime.migration"
   |   |       Level NOTSET so inherits level WARNING
   |   |
   |   o<--[alembic.util]
   |       |
   |       o<--"alembic.util.messaging"
   |           Level NOTSET so inherits level WARNING
   |
   o<--[ansible]
   |   |
   |   o<--[ansible.utils]
   |       |
   |       o   "ansible.utils.display"
   |           Level DEBUG
   |           Propagate OFF
   |           Handler File u'/tmp/venv/ansible.log'
   |             Formatter fmt='%(asctime)s p=%(process)d u=%(user)s |  %(message)s' datefmt=None
   |
   o   "ara"
   |   Level INFO
   |   Propagate OFF
   |   Handler TimedRotatingFile '/root/.ara/ara.log' when='MIDNIGHT' interval=86400 backupCount=30
   |     Level INFO
   |     Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None
   |   |
   |   o<--"ara.callback"
   |   |   Level NOTSET so inherits level INFO
   |   |
   |   o<--[ara.config]
   |   |   |
   |   |   o<--"ara.config.logging"
   |   |       Level NOTSET so inherits level INFO
   |   |
   |   o<--"ara.models"
   |       Level NOTSET so inherits level INFO
   |
   o<--"flask_migrate"
   |   Level NOTSET so inherits level WARNING
   |
   o<--"sqlalchemy"
   |   Level WARNING
   |   |
   |   o<--[sqlalchemy.dialects]
   |   |   |
   |   |   o<--"sqlalchemy.dialects.postgresql"
   |   |       Level NOTSET so inherits level WARNING
   |   |
   |   o   "sqlalchemy.engine"
   |   |   Level WARNING
   |   |   Propagate OFF
   |   |   Handler TimedRotatingFile '/root/.ara/ara.log' when='MIDNIGHT' interval=86400 backupCount=30
   |   |     Level INFO
   |   |     Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None
   |   |
   |   o<--[sqlalchemy.ext]
   |   |   |
   |   |   o<--"sqlalchemy.ext.baked"
   |   |       Level NOTSET so inherits level WARNING
   |   |
   |   o<--[sqlalchemy.orm]
   |       |
   |       o<--[sqlalchemy.orm.dynamic]
   |       |   |
   |       |   o<--"sqlalchemy.orm.dynamic.DynaLoader"
   |       |       Level NOTSET so inherits level WARNING
   |       |
   |       o<--[sqlalchemy.orm.mapper]
   |       |   |
   |       |   o<--"sqlalchemy.orm.mapper.Mapper"
   |       |       Level NOTSET so inherits level WARNING
   |       |
   |       o<--"sqlalchemy.orm.path_registry"
   |       |   Level NOTSET so inherits level WARNING
   |       |
   |       o<--[sqlalchemy.orm.properties]
   |       |   |
   |       |   o<--"sqlalchemy.orm.properties.ColumnProperty"
   |       |       Level NOTSET so inherits level WARNING
   |       |
   |       o<--[sqlalchemy.orm.query]
   |       |   |
   |       |   o<--"sqlalchemy.orm.query.Query"
   |       |       Level NOTSET so inherits level WARNING
   |       |
   |       o<--[sqlalchemy.orm.relationships]
   |       |   |
   |       |   o<--"sqlalchemy.orm.relationships.RelationshipProperty"
   |       |       Level NOTSET so inherits level WARNING
   |       |
   |       o<--[sqlalchemy.orm.strategies]
   |           |
   |           o<--"sqlalchemy.orm.strategies.ColumnLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.DeferredColumnLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.DoNothingLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.ExpressionColumnLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.JoinedLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.LazyLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.NoLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.SelectInLoader"
   |           |   Level NOTSET so inherits level WARNING
   |           |
   |           o<--"sqlalchemy.orm.strategies.SubqueryLoader"
   |               Level NOTSET so inherits level WARNING
   |
   o   "werkzeug"
       Level INFO
       Propagate OFF
       Handler Stream <open file '<stdout>', mode 'w' at 0x7f766f33f150>
         Level INFO
         Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None
       Handler TimedRotatingFile '/root/.ara/ara.log' when='MIDNIGHT' interval=86400 backupCount=30
         Level INFO
         Formatter fmt='%(asctime)s %(levelname)s %(name)s: %(message)s' datefmt=None

@ansibot

This comment has been minimized.

Contributor

ansibot commented Jun 22, 2018

The test ansible-test sanity --test ansible-doc --python 2.6 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
AttributeError: 'module' object has no attribute 'dictConfig'

The test ansible-test sanity --test ansible-doc --python 2.7 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
  File "/usr/lib/python2.7/logging/config.py", line 794, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python2.7/logging/config.py", line 576, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler 'ansible_handler': 'NoneType' object has no attribute 'startswith'

The test ansible-test sanity --test ansible-doc --python 3.5 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/usr/lib/python3.5/logging/config.py", line 558, in configure
    handler = self.configure_handler(handlers[name])
  File "/usr/lib/python3.5/logging/config.py", line 731, in configure_handler
    result = factory(**kwargs)
  File "/usr/lib/python3.5/logging/__init__.py", line 998, in __init__
    self.baseFilename = os.path.abspath(filename)
  File "/usr/lib/python3.5/posixpath.py", line 357, in abspath
    if not isabs(path):
  File "/usr/lib/python3.5/posixpath.py", line 64, in isabs
    return s.startswith(sep)
AttributeError: 'NoneType' object has no attribute 'startswith'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
  File "/usr/lib/python3.5/logging/config.py", line 795, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.5/logging/config.py", line 566, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler 'ansible_handler': 'NoneType' object has no attribute 'startswith'

The test ansible-test sanity --test ansible-doc --python 3.6 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/config.py", line 558, in configure
    handler = self.configure_handler(handlers[name])
  File "/usr/lib/python3.6/logging/config.py", line 731, in configure_handler
    result = factory(**kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1017, in __init__
    filename = os.fspath(filename)
TypeError: expected str, bytes or os.PathLike object, not NoneType

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
  File "/usr/lib/python3.6/logging/config.py", line 795, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.6/logging/config.py", line 566, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler 'ansible_handler': expected str, bytes or os.PathLike object, not NoneType

The test ansible-test sanity --test ansible-doc --python 3.7 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/usr/local/opt/pyenv/versions/python3.7.0a2/lib/python3.7/logging/config.py", line 555, in configure
    handler = self.configure_handler(handlers[name])
  File "/usr/local/opt/pyenv/versions/python3.7.0a2/lib/python3.7/logging/config.py", line 728, in configure_handler
    result = factory(**kwargs)
  File "/usr/local/opt/pyenv/versions/python3.7.0a2/lib/python3.7/logging/__init__.py", line 1027, in __init__
    filename = os.fspath(filename)
TypeError: expected str, bytes or os.PathLike object, not NoneType

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
  File "/usr/local/opt/pyenv/versions/python3.7.0a2/lib/python3.7/logging/config.py", line 792, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/local/opt/pyenv/versions/python3.7.0a2/lib/python3.7/logging/config.py", line 563, in configure
    '%r' % name) from e
ValueError: Unable to configure handler 'ansible_handler'

The test ansible-test sanity --test docs-build [explain] failed with the error:

Command "/usr/bin/python test/sanity/code-smell/docs-build.py" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "test/sanity/code-smell/docs-build.py", line 101, in <module>
    main()
  File "test/sanity/code-smell/docs-build.py", line 17, in main
    raise subprocess.CalledProcessError(sphinx.returncode, cmd, output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['make', 'singlehtmldocs']' returned non-zero exit status 2.

The test ansible-test sanity --test no-tests-as-filters [explain] failed with the error:

Command "/usr/bin/python test/sanity/code-smell/no-tests-as-filters.py" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/root/ansible/lib/ansible/plugins/__init__.py", line 30, in <module>
    from __main__ import display
ImportError: cannot import name 'display'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.6/logging/config.py", line 558, in configure
    handler = self.configure_handler(handlers[name])
  File "/usr/lib/python3.6/logging/config.py", line 731, in configure_handler
    result = factory(**kwargs)
  File "/usr/lib/python3.6/logging/__init__.py", line 1017, in __init__
    filename = os.fspath(filename)
TypeError: expected str, bytes or os.PathLike object, not NoneType

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "test/sanity/code-smell/no-tests-as-filters.py", line 25, in <module>
    from ansible.plugins.test import core, files, mathstuff
  File "/root/ansible/lib/ansible/plugins/__init__.py", line 32, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
  File "/usr/lib/python3.6/logging/config.py", line 795, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python3.6/logging/config.py", line 566, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler 'ansible_handler': expected str, bytes or os.PathLike object, not NoneType

click here for bot help

Namespace the ansible.utils.display logging configuration
The logging configuration provided by ansible.utils.display was not
namespaced which could cause conflicts with other python software
running with Ansible such as plugins, modules, etc.

This patch is effectively no-op in the sense that it keeps the exact
same formatting and configuration but will prevent conflicts from
happening.
It also makes it easier to customize the logging configuration in
the future if we need to or would like to expose a way for users
to provide their own configuration.

@dmsimard dmsimard force-pushed the dmsimard:logging branch to b408832 Jun 22, 2018

@ansibot

This comment has been minimized.

Contributor

ansibot commented Jun 22, 2018

The test ansible-test sanity --test ansible-doc --python 2.6 [explain] failed with the error:

Command "ansible-doc -t cache jsonfile memcached memory mongodb pickle redis yaml" returned exit status 1.
>>> Standard Error
Traceback (most recent call last):
  File "/root/ansible/bin/ansible-doc", line 68, in <module>
    from ansible.utils.display import Display
  File "/root/ansible/lib/ansible/utils/display.py", line 75, in <module>
    logging.config.dictConfig(LOGGING_CONFIG)
AttributeError: 'module' object has no attribute 'dictConfig'

click here for bot help

@ansibot ansibot added the stale_ci label Jul 5, 2018

@Akasurde Akasurde referenced this pull request Dec 10, 2018

Open

Better Logging #49657

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment