Use python stdlib logging

[alikins]

Proposal: Use python stdlib logging

Author: Adrian Likins alikins@redhat.com

Date: 2016-10-10

• Status: New
• Proposal type: core design
• Targeted Release: 2.3
• Associated PR: <link to GH PR in ansible/proposals if PR was submitted>
• Estimated time to implement: working prototype exists, a few weeks of iterations to square it up

  Motivation

Python stdlib logging is a well known and common approach to logging, with a flexible and extensible configuration, wide 3rd party vendor support, and offers integration with common python modules.

Problems

What problems exist that this proposal will solve?

• Current logging support is very limited
• Current logging approach is unusual
• Current logging approach makes it difficult to take advantage of 3rd party tools that support stdlib logging
• Current approach ('display') has grown organically and has an unusual API
• Current logging approach makes it very difficult to support structured logging
• Current logging approach does not offer find grained configuration (for ex, enabling debug level output for only 'ansible.parsing.vault')
• Current logging approach only offers a limited amount of context associated with records and some fields/info are wrong or misleading:
  • the 'pid' used in the logger name is only the pid of the main process, and does not reflect what process made the original call.
  • the logger name is non-standard
  • the ''pathname', 'filename', 'module', funcName' and 'lineno' log attributes are wrong and only point to display.py, not the originating call

    Solution proposal

• Use 'logging' module throughout the code base, replacing use of 'display.debug', 'display.warn' etc
  • eliminates the need to format messages in calling code
  • defers 'str/repr' of objects until log record is formatted. For example, a log.debug('template=%s', template) would never need to str/repr(template) if the handlers log level is 'INFO'
• Use standard logging.getLogger(name) logger setup
  • where useful, also setup per class loggers
  • This allows fine grained control of logging, on a per module or per class level
• Make use of 'log.exception()' for logging exception info from except clauses (including tracebacks)
  • eliminates 'hidden' exceptions that are caught and ignored
• Use a config file based logging setup (either yaml->dictConfig or 'fileConfig')
• provide log handlers for files, syslog, journald, console
  • optional: log handlers for windows logging
• provide a log handler for supporting concurrent logging from subprocess
• set up and use a log handler attached to 'ansible.*' logger namespace
  • allow attaching other specific loggers to our handlers (for ex, 'urllib3', 'requests')
  • allow attaching the root logger to our handler and enabling propagation to see all loggers process wide
• provide log formatters for current display output style, a basic line oriented format for log files, a detailed 'debug' formatter for troubleshooting and debugging.
  • optional: formatters for JSON output for use with ELK or other log indexing tools
• provide log filters and adapters for adding contextual info to logging events (Very useful for debugging and troubleshooting by devs, users and support).
  • some examples of info that could be added to records:
  • sys.argv
  • curent user
  • local hostname
  • remote_addr/hostname (for logging task/connection info)
  • remote_user
  • playbook/play/block/task context
• provide log filters for handling 'unsafe' text (censoring passwds etc)
• optional: provide a callback plugin that uses stdlib logging (either modifying existing 'default' or providing a new one_/
• prototype branch: https://github.com/alikins/ansible/tree/display_logging_notes
• 'logging' callback prototype branch: https://github.com/alikins/ansible/tree/stdlog_callback

Example logging use

import logging

log = logging.getLogger(__name__)
<...>
        log.warning("provided hosts list is empty, only localhost is available")

Output with added context info:

2016-10-10 13:21:08,278 user=adrian cmd_name=ansible-playbook <@> [ansible.cli.playbook WARNING] (pid=31566) tid=139879600539392:MainThread run:146 - provided hosts list is empty, only localhost is available

log.exception() example on a playbook yaml parsing error

2016-10-10 13:28:26,343 user=adrian cmd_name=ansible-playbook <@> [ansible CRITICAL] (pid=32217) tid=139760017659648:MainThread <module>:130 - Syntax Error while loading YAML.

The error appears to have been in '/home/adrian/src/ansible/ping.yml': line 12, column 1, but may
be elsewhere in the file depending on the exact syntax problem.

The offending line appears to be:

#- hosts: me,localhost,swoop
^ here
Traceback (most recent call last):
  File "/home/adrian/src/ansible/bin/ansible-playbook", line 121, in <module>
    exit_code = cli.run()
  File "/home/adrian/src/ansible/lib/ansible/cli/playbook.py", line 161, in run
    results = pbex.run()
  File "/home/adrian/src/ansible/lib/ansible/executor/playbook_executor.py", line 85, in run
    pb = Playbook.load(playbook_path, variable_manager=self._variable_manager, loader=self._loader)
  File "/home/adrian/src/ansible/lib/ansible/playbook/__init__.py", line 53, in load
    pb._load_playbook_data(file_name=file_name, variable_manager=variable_manager)
  File "/home/adrian/src/ansible/lib/ansible/playbook/__init__.py", line 76, in _load_playbook_data
    ds = self._loader.load_from_file(os.path.basename(file_name))
  File "/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py", line 124, in load_from_file
    parsed_data = self.load(data=file_data, file_name=file_name, show_content=show_content)
  File "/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py", line 104, in load
    self._handle_error(yaml_exc, file_name, show_content)
  File "/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py", line 205, in _handle_error
    raise AnsibleParserError(YAML_SYNTAX_ERROR, obj=err_obj, show_content=show_content)
AnsibleParserError: Syntax Error while loading YAML.

The error appears to have been in '/home/adrian/src/ansible/ping.yml': line 12, column 1, but may
be elsewhere in the file depending on the exact syntax problem.

The offending line appears to be:

#- hosts: me,localhost,swoop
^ here

Same example using a 3rd party json logging formatter (logomatic.JsonFormatter in this case)

{"asctime": "2016-10-10T13:32:27Z+0000", "name": "ansible", "processName": "MainProcess", "filename": "ansible-playbook", "funcName": "<module>", "levelname": "CRITICAL", "lineno": 130, "module": "ansible-playbook", "threadName": "MainThread", "message": "Syntax Error while loading YAML.\n\n\nThe error appears to have been in '/home/adrian/src/ansible/ping.yml': line 12, column 1, but may\nbe elsewhere in the file depending on the exact syntax problem.\n\nThe offending line appears to be:\n\n\n#- hosts: me,localhost,swoop\n^ here\n", "exc_info": "Traceback (most recent call last):\n  File \"/home/adrian/src/ansible/bin/ansible-playbook\", line 121, in <module>\n    exit_code = cli.run()\n  File \"/home/adrian/src/ansible/lib/ansible/cli/playbook.py\", line 161, in run\n    results = pbex.run()\n  File \"/home/adrian/src/ansible/lib/ansible/executor/playbook_executor.py\", line 85, in run\n    pb = Playbook.load(playbook_path, variable_manager=self._variable_manager, loader=self._loader)\n  File \"/home/adrian/src/ansible/lib/ansible/playbook/__init__.py\", line 53, in load\n    pb._load_playbook_data(file_name=file_name, variable_manager=variable_manager)\n  File \"/home/adrian/src/ansible/lib/ansible/playbook/__init__.py\", line 76, in _load_playbook_data\n    ds = self._loader.load_from_file(os.path.basename(file_name))\n  File \"/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py\", line 124, in load_from_file\n    parsed_data = self.load(data=file_data, file_name=file_name, show_content=show_content)\n  File \"/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py\", line 104, in load\n    self._handle_error(yaml_exc, file_name, show_content)\n  File \"/home/adrian/src/ansible/lib/ansible/parsing/dataloader.py\", line 205, in _handle_error\n    raise AnsibleParserError(YAML_SYNTAX_ERROR, obj=err_obj, show_content=show_content)\nAnsibleParserError: Syntax Error while loading YAML.\n\n\nThe error appears to have been in '/home/adrian/src/ansible/ping.yml': line 12, column 1, but may\nbe elsewhere in the file depending on the exact syntax problem.\n\nThe offending line appears to be:\n\n\n#- hosts: me,localhost,swoop\n^ here\n", "cmd_name": "ansible-playbook", "remote_user": "", "remote_addr": "", "cmd_line": "/home/adrian/src/ansible/bin/ansible-playbook -i hosts ping.yml", "user": "adrian", "timestamp": "2016-10-10T13:32:27Z+0000"}

An example of a debug log with contextual info about remote hosts being targetted:

2016-10-10 13:44:11,142 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: ansible.cfg set ssh_args: (-C)(-o)(ControlMaster=auto)(-o)(ControlPersist=60s)
2016-10-10 13:44:11,142 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: ansible_password/ansible_ssh_pass not set: (-o)(KbdInteractiveAuthentication=no)(-o)(PreferredAuthentications=gssapi-with-mic,gssapi-keyex,hostbased,publickey)(-o)(PasswordAuthentication=no)
2016-10-10 13:44:11,143 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: ANSIBLE_REMOTE_USER/remote_user/ansible_user/user/-u set: (-o)(User=vagrant)
2016-10-10 13:44:11,143 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: ANSIBLE_TIMEOUT/timeout set: (-o)(ConnectTimeout=10)
2016-10-10 13:44:11,143 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: PlayContext set ssh_common_args: ()
2016-10-10 13:44:11,143 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: PlayContext set ssh_extra_args: ()
2016-10-10 13:44:11,143 user=adrian cmd_name=ansible-playbook remote=<vagrant@192.168.121.231> [ansible.plugins.connection DEBUG] (pid=1505) _add_args:128 - SSH: found only ControlPersist; added ControlPath: (-o)(ControlPath=/home/adrian/.ansible/cp/ansible-ssh-%h-%p-%r)

Dependencies (optional)

For basic use, there are no external dependencies. The 'logging' module exists in all python versions supported. For concurrent logging to a single file, the 'multiprocess' module is required.

Additional log handlers, formatters, and filters may have additional deps. For example, log handlers for logging to 3rd party cloud based logging services may need 'requests' or a app specific dep.

If a yaml based logging config supports is needed on py2.6, a backport of 2.7's 'logging.dictConfig' may be needed.

Testing (optional)

Logging focused testing is recommended.

Additionally it will be useful to include tests that compare old style display based logging output to 'logging' output.

Testing of an assortment of logging configurations is recommended (custom formats, custom handlers, logging to syslog/journal/etc). Testing of log file handling and rotation. Testing of multiprocess concurrency correctness and stability.

Documentation (optional)

This will need user and developer focused documentation.

Users will have significant logging options available. Examples configurations of some common cases (file logging, syslog, journald, remote logging, ELK stack, etc).

Developers will need documentation on proper use of 'logging' module (although the module is well documented elsewhere). This will include any ansible specific changes (our handlers, formatters, filters, and adapters will need documentation on their use).

Anything else?

Related:

• Example of adding stdlib file based logging to module_common: https://github.com/alikins/ansible/commits/module_common_logging (note this only logs info to a file on the remote node. It does not currently foward logs back to the manager).
• Example of adding file based stdlib based logging to module_utils/basic.py: https://github.com/alikins/ansible/commits/module_logging (note this only logs info to a file on the remote node. It does not currently foward logs back to the manager).

[jnpr-bowen]

What is this status of this proposal? I have third party Python modules using the logger class that I am trying to wrap Ansible around and have no idea how to set up or configure so that Ansible will get those logger messages written somewhere. The proposal opening says there is a "working prototype", is there something I can use to help validate third party code using logger class can be configured and work inside and Ansible playbook?

[ssbarnea]

I am wondering how many years do we need until Ansible logging would be done right. As of today, even the latest 2.13.1 does enforce wrapping of warnings, which hinders console display and makes impossible to process the output. Effectively making it worse for both humans and machines.

@cidrblock Maybe we can push a little bit more to sort this out? That bug alone hinders usability our most development tools

[bcoca]

@ssbarnea 'done right' has many different opinions, this proposal has been discussed many times always ending in an impasse.

While the core team now has more consensus on the approach going forward, it still needs to be backwards compatible with the current 'display', otherwise all 3rd party plugins using it would cease to function.

In any case, if you want to bring it up for further discussion, we have monthly IRC meetings exactly for this purpose. https://github.com/ansible/community/issues?q=is%3Aissue+is%3Aopen+label%3Acore+label%3Ameeting_agenda

FYI, this is not a bug, it is a proposal