BDD - Python Behave log 日志

引言

日志在整个测试运行中是非常重要的，帮助我们定位问题。也许你习惯用 Print。。。。，尽管效果差不多，但是显得不那么专业了，也不方便日志管理。今天我们来了解一下 Behave 日志机制。

想了解更多 Behave 相关的文章，欢迎阅读《Python BDD Behave 系列》，持续更新中。

Behave log

Behave 使用 Python 的标准 logging 模块进行日志记录。这意味着 Behave 继承了 Python 的日志机制，可以使用相同的配置和方法。

Behave log 项目准备

举个简单的实例

feature 文件

创建 log.feature 文件，准备一些 log 记录，一个运行会失败的 Scenario, 一个运行会成功的 Scenario

# log.feature

Feature: Log Example

	Scenario: Passing
		Given I create log records with:
			| category | level   | message |
			| root     |  FATAL  | Hello Alice  |
			| foo      |  ERROR  | Hello Bob    |
			| foo.bar  |  WARN   | Hello Charly |
			| bar      |  INFO   | Hello Dora   |
			| baz      |  DEBUG  | Hello Emily  |
		When another step passes

	Scenario: Failing
		Given I create log records with:
			| category | level   | message |
			| root     |  FATAL  | Hello Alice  |
			| foo      |  ERROR  | Hello Bob    |
			| foo.bar  |  WARN   | Hello Charly |
			| bar      |  INFO   | Hello Dora   |
			| baz      |  DEBUG  | Hello Emily  |
		When another step fails

step 文件

# log_steps.py

from behave import *
from behave.configuration import LogLevel
import logging

def make_log_record(category, level, message):
    if category in ("root", "__ROOT__"):
        category = None
    logger = logging.getLogger(category)
    logger.log(level, message)

@Given('I create log records with')
def step_I_create_logrecords_with_table(context):
    assert context.table, "REQUIRE: context.table"
    context.table.require_columns(["category", "level", "message"])
    for row in context.table.rows:
        category = row["category"]
        if category == "__ROOT__":
            category = None
        level = LogLevel.parse_type(row["level"])
        message = row["message"]
        make_log_record(category, level, message)


# -----------------------------------------------------------------------------
# STEPS FOR: passing
# -----------------------------------------------------------------------------
@When('{word:w} step passes')
def step_passes(context, word):
    """
    Step that always passes, mostly needed in examples.
    """
    pass

# -----------------------------------------------------------------------------
# STEPS FOR: failing
# -----------------------------------------------------------------------------
@when(u'{word:w} step fails')
def step_fails(context, word):
    """Step that always fails, mostly needed in examples."""
    assert False, "EXPECT: Failing step"

environment.py 文件

context.config.setup_logging() 简单地全局配置日志记录系统的基本配置，以设置默认的日志处理器、日志级别、格式等参数。

# environment.py

from behave import *

def before_all(context):
    pass
    # print("Before all tests")
    context.before_all = "before all"
    # -- SAME-AS:
    # import logging
    # logging.basicConfig(level=context.config.logging_level)
    context.config.setup_logging()

Behave log 执行

log_capture 模式

• Behave 默认 log_capture 模式是开的
• log_capture 模式可通过命令行方式设置
• log_capture 模式也可在 behave 配置文件 behave.ini 中设置
• log_capture 模式只有在 Scenario 运行失败时才会捕获 log 记录

log_capture 开模式

所以执行命令 behave -f plain --logcapture 和 behave -f plain 效果是一样的，只有在 Scenario 运行失败时才会捕获 log 记录（看到 Captured logging: 部分）

PS C:\Automation\Test\bdd> behave -f plain   
Feature: Log Example

  Scenario: Passing
    Given I create log records with ... passed in 0.000s
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes ... passed in 0.001s

  Scenario: Failing
    Given I create log records with ... passed in 0.001s
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails ... failed in 0.001s
Assertion Failed: EXPECT: Failing step
Captured logging:
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly
INFO:bar:Hello Dora


Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.003s

log_capture 关模式即普通模式

命令行选项 --no-logcapture 普通模式，运行成功的 Scenario 也会输出 log

也可以在配置文件 behave.ini 设置，只需执行命令 behave -f plain
[behave]
log_capture = false

PS C:\Automation\Test\bdd> behave -f plain  --no-logcapture
Feature: Log Example

  Scenario: Passing
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly
INFO:bar:Hello Dora
    Given I create log records with ... passed in 0.000s
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes ... passed in 0.000s

  Scenario: Failing
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly
INFO:bar:Hello Dora
    Given I create log records with ... passed in 0.013s
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails ... failed in 0.000s
Assertion Failed: EXPECT: Failing step


Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.013s

logging-filter

根据 log catalog 来过滤 log 记录，只输出想要的 log 信息，前提条件是 log_capture 模式下
e.g.
过滤出包含 foo catalog 的日志记录： behave --logcapture --logging-filter=foo
过滤出包含子类 foo.bar catalog 的日志记录：behave --logcapture --logging-filter=foo.bar
过滤出包含非 foo catalog 的日志记录：behave --logcapture --logging-filter=-foo
过滤出包含 foo 或 bar catalog 的日志记录：behave --logcapture --logging-filter=foo,bar

过滤出包含 foo.bar 或不包含 bar catalog 的日志记录：behave --logcapture --logging-filter=foo.bar,-bar
所以会包含下面这些 log 记录
root --》 非 bar
foo.bar–》foo.bar

  Captured logging:
  CRITICAL:root:Hello Alice  
  ERROR:foo:Hello Bob
  WARNING:foo.bar:Hello Charly

PS C:\ForKelly\Automation\Test\bdd> behave --logcapture --logging-filter=foo.bar,-bar
Feature: Log Example # Features/log/log.feature:1

  Scenario: Passing                 # Features/log/log.feature:3
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes        # steps/log_steps.py:30

  Scenario: Failing                 # Features/log/log.feature:13
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails         # steps/log_steps.py:40
      Assertion Failed: EXPECT: Failing step
      Captured logging:
      CRITICAL:root:Hello Alice
      ERROR:foo:Hello Bob
      WARNING:foo.bar:Hello Charly



Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.001s

logging-level

日志级别（logging level）用于指定日志消息的严重程度。不同的级别对应不同的常量（debug，info, warning, error），logcapture 模式和 logcapture 模式都可以应用.

logcapture 模式

PS C:\Automation\Test\bdd> behave -f plain -T --logging-level=WARN
Feature: Log Example

  Scenario: Passing
    Given I create log records with ... passed
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes ... passed

  Scenario: Failing
    Given I create log records with ... passed
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails ... failed
Assertion Failed: EXPECT: Failing step
Captured logging:
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly


Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.000s

no-logcapture 模式

PS C:Automation\Test\bdd> behave -f plain -T --logging-level=WARN --no-logcapture
Feature: Log Example

  Scenario: Passing
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly
    Given I create log records with ... passed
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes ... passed

  Scenario: Failing
CRITICAL:root:Hello Alice
ERROR:foo:Hello Bob
WARNING:foo.bar:Hello Charly
    Given I create log records with ... passed
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails ... failed
Assertion Failed: EXPECT: Failing step


Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.003s

logging_format

logging.Formatter 类用于配置日志的输出格式。通过使用格式化字符串，您可以指定日志消息的显示方式，包括日期、日志级别、消息内容等。
behave -f plain -T --logging-format=‘LOG.%(levelname)-8s %(name)-10s: %(message)s’

也可以通过配置文件设置：
[behave]
logging_format = %(asctime)s LOG.%(levelname)-8s %(name)s: %(message)s
logging_datefmt = %Y-%m-%dT%H:%M:%S

log_capture 模式

 [behave]
# config for log
log_capture = true
logging_level = WARN
logging_format = %(asctime)s  LOG.%(levelname)-8s %(name)s: %(message)s
logging_datefmt = %Y-%m-%dT%H:%M:%S

PS C:\Automation\Test\bdd> behave
Feature: Log Example # Features/log/log.feature:1

  Scenario: Passing                 # Features/log/log.feature:3
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step passes        # steps/log_steps.py:30

  Scenario: Failing                 # Features/log/log.feature:13
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
    When another step fails         # steps/log_steps.py:40
      Assertion Failed: EXPECT: Failing step
      Captured logging:
      2024-01-01T20:51:36  LOG.CRITICAL root: Hello Alice
      2024-01-01T20:51:36  LOG.ERROR    foo: Hello Bob
      2024-01-01T20:51:36  LOG.WARNING  foo.bar: Hello Charly



Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.002s

no-logcapture 模式

 [behave]
# config for log
log_capture = false
logging_level = WARN
logging_format = %(asctime)s  LOG.%(levelname)-8s %(name)s: %(message)s
logging_datefmt = %Y-%m-%dT%H:%M:%S

PS C:\Automation\Test\bdd> behave
Feature: Log Example # Features/log/log.feature:1

  Scenario: Passing                 # Features/log/log.feature:3
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
2024-01-01T20:53:25  LOG.CRITICAL root: Hello Alice
2024-01-01T20:53:25  LOG.ERROR    foo: Hello Bob
2024-01-01T20:53:25  LOG.WARNING  foo.bar: Hello Charly
    When another step passes        # steps/log_steps.py:30

  Scenario: Failing                 # Features/log/log.feature:13
    Given I create log records with # steps/log_steps.py:13
      | category | level | message      |
      | root     | FATAL | Hello Alice  |
      | foo      | ERROR | Hello Bob    |
      | foo.bar  | WARN  | Hello Charly |
      | bar      | INFO  | Hello Dora   |
      | baz      | DEBUG | Hello Emily  |
2024-01-01T20:53:25  LOG.CRITICAL root: Hello Alice
2024-01-01T20:53:25  LOG.ERROR    foo: Hello Bob
2024-01-01T20:53:25  LOG.WARNING  foo.bar: Hello Charly
    When another step fails         # steps/log_steps.py:40
      Assertion Failed: EXPECT: Failing step



Failing scenarios:
  Features/log/log.feature:13  Failing

0 features passed, 1 failed, 0 skipped
1 scenario passed, 1 failed, 0 skipped
3 steps passed, 1 failed, 0 skipped, 0 undefined
Took 0m0.003s