代码改变世界

OpenStack 实现技术分解 (6) 通用库 — oslo_log

2017-03-26 23:34  云物互联  阅读(343)  评论(0)  编辑  收藏  举报

目录

前文列表

OpenStack 实现技术分解 (1) 开发环境 — Devstack 部署案例详解
OpenStack 实现技术分解 (2) 虚拟机初始化工具 — Cloud-Init & metadata & userdata
OpenStack 实现技术分解 (3) 开发工具 — VIM & dotfiles
OpenStack 实现技术分解 (4) 通用技术 — TaskFlow
OpenStack 实现技术分解 (5) 应用开发 — 使用 OpenStackClients 进行二次开发

扩展阅读

Usage — oslo.log 3.21.1.dev1 documentation
oslo.log – Oslo Logging Library

日志级别

在记录日志时, 需要将日志消息关联一个级别, 系统默认提供了 6 个级别，它们分别是：

critical > error > warning > info > debug > notset

级别越高打印的日志越少，反之亦然:

  • DEBUG: 打印全级别日志( notset 等同于 debug)
  • INFO: 打印 info/warning/error/critical 级别日志
  • WARNING: 打印 warning/error/critical 级别日志
  • ERROR: 打印 error/critical 级别日志
  • CRITICAL: 打印 critical 级别

一般而言, 在程序的开发阶段会打印大量的日志, 此时的日志级别应为 DEBUG. 直到程序稳定后, 为了提高程序的执行效率, 需要打印日志应该相对减少. 根据实际情况, 可能会删减 DEBUG 级别的日志代码. 此时, 程序员更关心的是跟踪用户的动作, 例如: 用户对于核心数据的修改动作就非常有必要记录在案, 所以可以选择 INFO 及以上级别的日志, 其中最重要的信息就应该选择 CRITICAL 级别了. 需要注意的是, 异常捕获代码块(try-except)中都应该使用 ERROR/EXCEPTION(由 oslo_log 提供的异常栈级别) 级别的日志, 以便定位具体的错误原因.

oslo.log

(摘自官方文档)The oslo.log (logging) configuration library provides standardized configuration for all openstack projects. It also provides custom formatters, handlers and support for context specific logging (like resource id’s etc).

oslo.log(logging) 库为所有的 OpenStack 项目提供了标准的日志处理方式, 它还提供能自定义日志格式以及各种 handlers, 同时也支持指定上下文对象的日志, 例如: resource_id 的日志等等.

实际上 oslo_log 是基于 Python’s standard logging library 标准库的封装, 在整体使用的简易性上得到了提升.

初始化设置 DEMO

from oslo_config import cfg
from oslo_log import log as logging

LOG = logging.getLogger(__name__)
CONF = cfg.CONF
DOMAIN = "demo"

logging.register_options(CONF)
logging.setup(CONF, DOMAIN)

# Oslo Logging uses INFO as default
LOG.info("Oslo Logging")
LOG.warning("Oslo Logging")
LOG.error("Oslo Logging")

显然的, 为了充分利用 oslo_conf 的跨文件作用域特性, oslo_log 一般会与 oslo_conf 结合使用, 由 oslo_conf 为 oslo_log 提供项目的日志配置项参数值. 对于 oslo_log 而言, 配置项引入是一个非常重要且具有实践价值的设计理念.

oslo.log 的相关配置项

各个配置项的含义在注释中也作了清晰的介绍:

################
# From oslo.log
################

# If set to true, the logging level will be set to DEBUG instead of the default
# INFO level. (boolean value)
# Note: This option can be changed without restarting.
debug = true

# DEPRECATED: If set to false, the logging level will be set to WARNING instead
# of the default INFO level. (boolean value)
# This option is deprecated for removal.
# Its value may be silently ignored in the future.
#verbose = true

# The name of a logging configuration file. This file is appended to any
# existing logging configuration files. For details about logging configuration
# files, see the Python logging module documentation. Note that when logging
# configuration files are used then all logging configuration is set in the
# configuration file and other logging configuration options are ignored (for
# example, logging_context_format_string). (string value)
# Note: This option can be changed without restarting.
# Deprecated group/name - [DEFAULT]/log_config
#log_config_append = <None>

# Defines the format string for %%(asctime)s in log records. Default:
# %(default)s . This option is ignored if log_config_append is set. (string
# value)
#log_date_format = %Y-%m-%d %H:%M:%S

# (Optional) Name of log file to send logging output to. If no default is set,
# logging will go to stderr as defined by use_stderr. This option is ignored if
# log_config_append is set. (string value)
# Deprecated group/name - [DEFAULT]/logfile
#log_file = <None>

# (Optional) The base directory used for relative log_file  paths. This option
# is ignored if log_config_append is set. (string value)
# Deprecated group/name - [DEFAULT]/logdir
#log_dir = <None>

# Uses logging handler designed to watch file system. When log file is moved or
# removed this handler will open a new log file with specified path
# instantaneously. It makes sense only if log_file option is specified and
# Linux platform is used. This option is ignored if log_config_append is set.
# (boolean value)
#watch_log_file = false

# Use syslog for logging. Existing syslog format is DEPRECATED and will be
# changed later to honor RFC5424. This option is ignored if log_config_append
# is set. (boolean value)
#use_syslog = false

# Syslog facility to receive log lines. This option is ignored if
# log_config_append is set. (string value)
#syslog_log_facility = LOG_USER

# Log output to standard error. This option is ignored if log_config_append is
# set. (boolean value)
#use_stderr = true

# Format string to use for log messages with context. (string value)
#logging_context_format_string = %(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s

# Format string to use for log messages when context is undefined. (string
# value)
#logging_default_format_string = %(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [-] %(instance)s%(message)s

# Additional data to append to log message when logging level for the message
# is DEBUG. (string value)
#logging_debug_format_suffix = %(funcName)s %(pathname)s:%(lineno)d

# Prefix each line of exception output with this format. (string value)
#logging_exception_prefix = %(asctime)s.%(msecs)03d %(process)d ERROR %(name)s %(instance)s

# Defines the format string for %(user_identity)s that is used in
# logging_context_format_string. (string value)
#logging_user_identity_format = %(user)s %(tenant)s %(domain)s %(user_domain)s %(project_domain)s

# List of package logging levels in logger=LEVEL pairs. This option is ignored
# if log_config_append is set. (list value)
#default_log_levels = amqp=WARN,amqplib=WARN,boto=WARN,qpid=WARN,sqlalchemy=WARN,suds=INFO,oslo.messaging=INFO,iso8601=WARN,requests.packages.urllib3.connectionpool=WARN,urllib3.connectionpool=WARN,websocket=WARN,requests.packages.urllib3.util.retry=WARN,urllib3.util.retry=WARN,keystonemiddleware=WARN,routes.middleware=WARN,stevedore=WARN,taskflow=WARN,keystoneauth=WARN,oslo.cache=INFO,dogpile.core.dogpile=INFO

# Enables or disables publication of error events. (boolean value)
#publish_errors = false

# The format for an instance that is passed with the log message. (string
# value)
#instance_format = "[instance: %(uuid)s] "

# The format for an instance UUID that is passed with the log message. (string
# value)
#instance_uuid_format = "[instance: %(uuid)s] "

# Enables or disables fatal status of deprecations. (boolean value)
#fatal_deprecations = false

对于有 Python logging 标准库使用经验的程序员而言, 应该很容易的就能体会到 oslo_log 对 logging 进行封装后带来的好处. 以往使用 logging 时需要在代码中显式定义的状态信息(e.g. 日志级别/打印格式/handler 等), 现在都能够通过 oslo_log 配置文件的配置项参数值来简化定义. 有效的避免了在程序中写出许多无谓的代码, 而且通过阅读配置文件能够更清晰的理解当前程序的日志状态.

一般来说我们需要关心的 oslo_log 配置项有以下几个:

  • debug = true: 是否将日志级别设定为 DEBUG
  • verbose = true: 将日志级别设定为 INFO(true) 还是 WARNING(false)
  • log_date_format = %Y-%m-%d %H:%M:%S: 日志的日期格式
  • log_file = <None>: 日志文件名称
  • log_dir = <None>: 日志文件路径
  • use_stderr = true: 是否让日志以 system standard error 管道输出
  • logging_context_format_string: 日志内容格式
  • default_log_levels: 相关程序的默认日志级别
  • instance_format: instance 的日志打印格式, 所谓的上下文对象日志

oslo_log 支持通过调用 logging 的 register_options() method 来实现配置项的注册:

CONF = cfg.CONF

def prepare():

    # Required step to register common, logging and generic configuration
    # variables
    logging.register_options(CONF)

register_options method 会帮助我们将上述配置文件中的配置项以默认值注册到 CONF 对象中:

logging.register_options(CONF)
>>> CONF.items()
[('default_log_levels', ['amqp=WARN', 'amqplib=WARN', 'boto=WARN', 'qpid=WARN', 'sqlalchemy=WARN', 'suds=INFO', 'oslo.messaging=INFO', 'iso8601=WARN', 'requests.packages.urllib3.connectionpool=WARN', 'urllib3.connectionpool=WARN', 'websocket=WARN', 'requests.packages.urllib3.util.retry=WARN', 'urllib3.util.retry=WARN', 'keystonemiddleware=WARN', 'routes.middleware=WARN', 'stevedore=WARN', 'taskflow=WARN', 'keystoneauth=WARN', 'oslo.cache=INFO', 'dogpile.core.dogpile=INFO']), ('verbose', True), ('watch_log_file', False), ('logging_default_format_string', '%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [-] %(instance)s%(message)s'), ('use_stderr', False), ('log_date_format', '%Y-%m-%d %H:%M:%S'), ('rate_limit_burst', 0), ('logging_context_format_string', '%(asctime)s.%(msecs)03d %(process)d %(levelname)s %(name)s [%(request_id)s %(user_identity)s] %(instance)s%(message)s'), ('instance_format', '[instance: %(uuid)s] '), ('use_syslog', False), ('log_dir', None), ('publish_errors', False), ('logging_debug_format_suffix', '%(funcName)s %(pathname)s:%(lineno)d'), ('logging_exception_prefix', '%(asctime)s.%(msecs)03d %(process)d ERROR %(name)s %(instance)s'), ('syslog_log_facility', 'LOG_USER'), ('instance_uuid_format', '[instance: %(uuid)s] '), ('log_config_append', None), ('rate_limit_except_level', 'CRITICAL'), ('rate_limit_interval', 0), ('debug', False), ('log_file', None), ('logging_user_identity_format', '%(user)s %(tenant)s %(domain)s %(user_domain)s %(project_domain)s')]

所以我们在使用 oslo_log 时无需在程序代码中重复定义这些 options. 能够非常方便的通过修改配置文件中配置项的值, 来实现对 oslo_log 的管理.
NOTE: 如果在执行了 logging.register_options(CONF) 之后, 又在程序中重复定义了这些重名配置项的话, 会触发异常:

slo_config.cfg.DuplicateOptError: duplicate option: debug

在注册了配置项之后, 还可以通过调用 logging 的 setup() method 来指定该 logger 的作用域, 支持在一个程序中存在多个不同 domain 的 logger:

DOMAIN = 'demo'

def prepare():

    # Required setup based on configuration and domain
    logging.setup(CONF, DOMAIN)

同时, oslo_log 也支持使用 logging 的 set_defaults method 来动态修改日志级别:

    # Optional step to set new defaults if necessary for
    # * logging_context_format_string
    # * default_log_levels

    extra_log_level_defaults = [
        'dogpile=INFO',
        'routes=INFO'
        ]

    logging.set_defaults(
        default_log_levels=logging.get_default_log_levels() +
        extra_log_level_defaults)

上述的 3 个 method 让程序中日志的使用变得更加灵活.

oslo.log 的日志级别

oslo.log 常用的 5 个日志级及其对应的 function:

from oslo_log import log as logging

LOG = logging.getLogger(__name__)

LOG.debug("Some key is %s", "key")

LOG.info("Create something %s start", "test")

LOG.exception("Failed to create something %(something)s as error %(err)s", {"something": "something", "err": "err"})

LOG.error("Failed to create something")

LOG.cretical("Fatal error as %s", "fatal")

oslo.log 的使用技巧

一般而言, 我会建议程序中的日志宜多不宜少, 但在上文也有提到, 大量的日志会对程序运行效率造成影响, 所以理解如何精准的在程序中的不同场景使用不同级别的日志就显得很有必要了.

推荐使用 LOG.debug 的地方

LOG.debug 一般用于对实参数据体精确度较为敏感的 function/method 语句块的首行, 让开发者能够快速的判断是否得到了预期实参. 所以这里需要打印出 module_name & function_name/method_name & 实参值.
EXAMPLE 1: REST API controller method 中接收到的 request info:

def index(self, req):
    LOG.debug("Get server list with parameter %s,", req.GET())
    ...

EXAMPLE 2: 一些通过逻辑比较复杂的流程而得到的参数 

...
# 执行一次复杂的排序操作
sort_result = _complex_sort(arr)
LOG.debug("Front list %(fro)s change to %(now)s after complex_sort.", {'fro': arr, 'now': sort_result})
...

推荐使用 LOG.info 的地方

LOG.info 一般用于标记业务逻辑步骤, 让运维/开发人员都能够快速判断程序流到了哪一个步, 所以这里需要打印 module_name & step_description & 业务对象的唯一标示

EXAMPLE: 当执行一个所需步骤大于等于二的程序流程时, 需要打印程序流开始到结束的过程

...
LOG.info("Create server %s start.", server.id)
...
LOG.info("Prepare image for server %s.", server.id)
...
LOG.info("Prepare network for server %s", server.id)
...
LOG.info("Create server %s successful", server.id)
...

推荐使用 LOG.exception 的地方

LOG.exception/LOG.error 一般用于 try-except 异常捕获语句块, 如果捕获到的是某一个准确的异常可以使用 LOG.error, 如果捕获的是某一类异常或全部异常时可以使用 LOG.exception 来打印出异常栈.

EXAMPLE: 在暴露的 RPC API 或者 HTTP API 方法中加入 exception 级别日志

def index(self, req):
    ...
    try:
        self.server_api.get_all_servers()
    except Exception as err:
        LOG.exception("Failed to get servers as error %s", six.text_type(err))
        raise exc.HTTPInnevalError()
    ...

推荐使用 LOG.error 的地方

EXAMPLE: 同上, 但如果程序流没有再上一层的调用时, 也可以使用LOG.error, 因为已经不需要打印异常栈了.

try:
    # do something
    ...
except Exception as err:
    LOG.error("Failed to do something as error %s", six.text_type(err))
    raise

推荐使用 LOG.cretical 的地方

LOG.cretical 一般用于当错误可能会导致程序进程崩溃等极其严重的逻辑块中

try:
    # 执行一些危险操作
    ...
except Exception as err:
    LOG.cretical("Failed to do something as error %s", six.text_type(err))
    raise