BDD - Python Behave log 为每个 Scenario 生成对应的 log 文件
- 引言
- 应用 Behave 官网 Log 配置文件
- 项目 Setup
- Feature 文件
- steps 文件
- Log 配置文件
- environment.py 文件
- behave.ini
- 执行结果
- 直接应用 Python logging 模块
- 方式 1：应用 log 配置文件
- log 配置文件
- environment.py
- Steps 文件
- 执行结果
- 方式 2：logging 方法配置
- environment.py
- 执行结果
- 方式 3：dictConfig 配置
- environment.py
- 执行结果
- 总结
引言
文章《BDD - Python Behave log 日志》只是简单的介绍了一下 log 的基本配置，而且默认是输出到 Console，这对于日常自动化测试是不够全面的，不利于 Automation Triage。今天就来了解一下更友好的日志配制，为每个 Scenario 配置不同的 log 文件，极大地方便定位 Scenario 运行失败的原因。
想了解更多 Behave 相关的文章，欢迎阅读《Python BDD Behave 系列》，持续更新中。
应用 Behave 官网 Log 配置文件
首先应用一下 Behave 官网 Log with Configfile 例子，发现所有的日志都会输出到一个固定的文件中。目前 Behave 1.2.6 版本 context.config.setup_logging() 方法还不支持动态改变 config 文件中的参数值，但是可以通过改源码来实现，可参考 Add support for value substitution in logging config file
项目 Setup
Feature 文件
log_with_config_file.feature, 3 个 Scenarios
# BDD/Features/log/log_with_config_file.feature
Feature: Logging Example
@log_test
Scenario: First Scenario
Given I have a scenario 1
When I perform an action
Then I should see the result
@log_test
Scenario Outline: Second Scenario
Given I have a scenario <number>
When I perform an action
Then I should see the result
Examples:
|number|
|2|
|3|
steps 文件
简单的日志记录
# BDD/steps/log_with_config_file_steps.py
from behave import given, when, then
import logging
from behave.configuration import LogLevel
@given("I have a scenario {number}")
def step_given_scenario(context, number):
logging.info(f"This is a log from scenario {number}")
@when("I perform an action")
def step_when_perform_action(context)
logging.info("I perform an action")
@then("I should see the result")
def step_then_see_result(context):
logging.error("I did not see the result")
Log 配置文件
behave_logging.ini
配置了文件输出，也可以配置日志输出到文件和 Console，这里日志文件是固定的 BDD/logs/behave.log
# BDD/config/behave_logging.ini
[loggers]
keys=root
[handlers]
keys=Console,File
[formatters]
keys=Brief
[logger_root]
level = DEBUG
# handlers = File
handlers = Console,File
[handler_File]
class=FileHandler
args=("BDD/logs/behave.log", 'w')
level=DEBUG
formatter=Brief
[handler_Console]
class=StreamHandler
args=(sys.stderr,)
level=DEBUG
formatter=Brief
[formatter_Brief]
format= LOG.%(levelname)-8s %(name)-10s: %(message)s
datefmt=
environment.py 文件
通过调用 Behave 方法 context.config.setup_logging() 应用上面的 log 配置文件，
# BDD/environment.py
def before_all(context):
# create log dir
os.makedirs("BDD/logs", exist_ok=True)
context.config.setup_logging(configfile="BDD/config/behave_logging.ini")
behave.ini
Behave 默认 log_capture 是 true 的，运行成功的 Scenario 是不会输出日志的。所以将该值设置为 false，确保不管 Scenario 运行成功与否，都输出日志。stdout_capture 为 false 是允许输出 print 语句，为 true 则不会输出。
# behave.ini
[behave]
paths=BDD/Features/log/log_with_config_file.feature
tags = log_test
log_capture = false
stdout_capture = false
执行结果
因为 behave.ini 已经配置了 feature 文件 path 及 tags，所以只需在项目根目录下直接运行 behave 命令就可以了。
日志按配置格式输出到 Console，同时也输出到 behave.log 文件中。
PS C:\Automation\Test> behave
Feature: Logging Example # BDD/Features/log/log_with_config_file.feature:2
@log_test
Scenario: First Scenario # BDD/Features/log/log_with_config_file.feature:5
Given I have a scenario 1 # BDD/steps/log_with_config_file_steps.py:7
LOG.INFO root : This is a log from scenario 1
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
LOG.INFO root : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
LOG.ERROR root : I did not see the result
scenario_name Second_Scenario_--_@1.1_
@log_test
Scenario Outline: Second Scenario -- @1.1 # BDD/Features/log/log_with_config_file.feature:18
Given I have a scenario 2 # BDD/steps/log_with_config_file_steps.py:7
LOG.INFO root : This is a log from scenario 2
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
LOG.INFO root : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
LOG.ERROR root : I did not see the result
scenario_name Second_Scenario_--_@1.2_
@log_test
Scenario Outline: Second Scenario -- @1.2 # BDD/Features/log/log_with_config_file.feature:19
Given I have a scenario 3 # BDD/steps/log_with_config_file_steps.py:7
LOG.INFO root : This is a log from scenario 3
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
LOG.INFO root : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
LOG.ERROR root : I did not see the result
1 feature passed, 0 failed, 0 skipped
3 scenarios passed, 0 failed, 0 skipped
9 steps passed, 0 failed, 0 skipped, 0 undefined
Took 0m0.010s
直接应用 Python logging 模块
针对不同的 Scenario 动态创建 log 文件，输出到对应的 log 文件中，这里有三种方式实现
方式 1：应用 log 配置文件
log 配置文件
注意 args=(‘%(logfilename)s’,‘w’) 文件名可通过参数来设置的，不再是固定的。
# BDD/config/logging_config.ini
[loggers]
keys=root
[handlers]
keys=consoleHandler,fileHandler
[formatters]
keys=sampleFormatter
[logger_root]
level=DEBUG
handlers=consoleHandler,fileHandler
[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=sampleFormatter
args=(sys.stdout,)
[handler_fileHandler]
class=FileHandler
level=DEBUG
formatter=sampleFormatter
args=('%(logfilename)s','w')
[formatter_sampleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt=%Y-%m-%d %H:%M:%S
[log_file_template]
path={scenario_name}_{timestamp}.log
environment.py
根据 feature 名 和 Scenario 名及其位置生成 log 文件名
logging.config.fileConfig(“BDD/config/logging.ini”, defaults={‘logfilename’: log_file}) 应用 log 配置文件和动态设置 log 输出文件名
context.logger = logging.getLogger(f"{feature_name_str}_@{scenario_location_line}") 保持 log 的上下文关系
# BDD/environment.py
def before_scenario(context, scenario):
# create log dir
feature_name_str = context.feature.name.replace(" ", "_")
log_dir = f"BDD/logs/{feature_name_str}"
os.makedirs(log_dir, exist_ok=True)
# generate log file path
scenario_name = scenario.name.replace(" ", "_")
current_time = datetime.datetime.now()
formatted_time = current_time.strftime("%Y-%m-%d-%H-%M-%S")
scenario_location_line = scenario.location.line
log_file = os.path.join(log_dir, f"{scenario_name}_{scenario_location_line}_{formatted_time}.log")
# log setup
logging.config.fileConfig("BDD/config/logging.ini", defaults={'logfilename': log_file})
context.logger = logging.getLogger(f"{feature_name_str}_@{scenario_location_line}")
Steps 文件
context.logger 拿到 logger 对象
# BDD/steps/log_with_config_file_steps.py
from behave import given, when, then
import logging
from behave.configuration import LogLevel
@given("I have a scenario {number}")
def step_given_scenario(context, number):
context.logger.info(f"This is a log from scenario {number}")
@when("I perform an action")
def step_when_perform_action(context):
context.logger.error(f"I perform an action")
@then("I should see the result")
def step_then_see_result(context):
context.logger.error("I should see the result")
执行结果
behave.ini 文件中的配置还跟之前一样，在项目根目录下直接运行 behave 命令即可。
log 有输出到终端：
PS C:Automation\Test> behave
Feature: Logging Example # BDD/Features/log/log_with_config_file.feature:2
@log_test
Scenario: First Scenario # BDD/Features/log/log_with_config_file.feature:5
Given I have a scenario 1 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:00:09 - Logging_Example_@5 - INFO - This is a log from scenario 1
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:00:09 - Logging_Example_@5 - ERROR - I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:00:10 - Logging_Example_@5 - ERROR - I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.1 # BDD/Features/log/log_with_config_file.feature:18
Given I have a scenario 2 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:00:10 - Logging_Example_@18 - INFO - This is a log from scenario 2
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:00:10 - Logging_Example_@18 - ERROR - I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:00:10 - Logging_Example_@18 - ERROR - I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.2 # BDD/Features/log/log_with_config_file.feature:19
Given I have a scenario 3 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:00:10 - Logging_Example_@19 - INFO - This is a log from scenario 3
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:00:10 - Logging_Example_@19 - ERROR - I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:00:10 - Logging_Example_@19 - ERROR - I should see the result
1 feature passed, 0 failed, 0 skipped
3 scenarios passed, 0 failed, 0 skipped
9 steps passed, 0 failed, 0 skipped, 0 undefined
Took 0m0.015s
同时，feature 名的 log 目录已经创建，并每个 Scenario 都有对应的 log 文件
方式 2：logging 方法配置
在 environment.py 文件中，通过 logging 模块方法配置 log 属性, 其它文件跟方式 1 保持不变
environment.py
# BDD/environment.py
def scenario_log_setup(scenario, log_file):
# set logger
logger = logging.getLogger(scenario.name)
logger.setLevel(logging.DEBUG)
# add handler for logger
file_handler = logging.FileHandler(log_file)
file_handler.setLevel(logging.DEBUG)
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.DEBUG)
# set format for logger
log_format = '%(asctime)s %(levelname)s : %(message)s'
formatter = logging.Formatter(log_format)
file_handler.setFormatter(formatter)
console_handler.setFormatter(formatter)
logger.addHandler(file_handler)
logger.addHandler(console_handler)
return logger
def before_scenario(context, scenario):
# create log dir
feature_name_str = context.feature.name.replace(" ", "_")
log_dir = f"BDD/logs/{feature_name_str}"
os.makedirs(log_dir, exist_ok=True)
# generate log file path
scenario_name = scenario.name.replace(" ", "_")
current_time = datetime.datetime.now()
formatted_time = current_time.strftime("%Y-%m-%d-%H-%M-%S")
scenario_location_line = scenario.location.line
log_file = os.path.join(log_dir, f"{scenario_name}_{scenario_location_line}_{formatted_time}.log")
# log setup
context.logger = scenario_log_setup(scenario, log_file)
执行结果
终端输出并写入 log 文件中
PS C:\Automation\Test> behave
Feature: Logging Example # BDD/Features/log/log_with_config_file.feature:2
@log_test
Scenario: First Scenario # BDD/Features/log/log_with_config_file.feature:5
Given I have a scenario 1 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:42:02,505 CRITICAL : This is a log from scenario 1
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:42:02,505 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:42:02,505 ERROR : I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.1 # BDD/Features/log/log_with_config_file.feature:18
Given I have a scenario 2 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:42:02,533 CRITICAL : This is a log from scenario 2
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:42:02,534 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:42:02,534 ERROR : I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.2 # BDD/Features/log/log_with_config_file.feature:19
Given I have a scenario 3 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 16:42:02,541 CRITICAL : This is a log from scenario 3
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 16:42:02,543 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 16:42:02,545 ERROR : I should see the result
1 feature passed, 0 failed, 0 skipped
3 scenarios passed, 0 failed, 0 skipped
9 steps passed, 0 failed, 0 skipped, 0 undefined
Took 0m0.018s
log 文件生成
方式 3：dictConfig 配置
在 environment.py 文件中，通过定义一个 Log Config dict 调用 logging.config.dictConfig 配置 log 属性, 其它文件跟方式 1 保持不变
environment.py
def scenario_log_setup_with_config_dict(scenario, log_file):
logging_config = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'standard': {
'format': '%(asctime)s %(levelname)s : %(message)s'
},
},
'handlers': {
'file_handler': {
'class': 'logging.FileHandler',
'filename': log_file,
'formatter': 'standard',
},
'console_handler':{
'class':'logging.StreamHandler',
'formatter': 'standard',
}
},
'loggers': {
'': {
'handlers': ['file_handler','console_handler'],
'level': 'DEBUG',
},
}
}
logging.config.dictConfig(logging_config)
return logging.getLogger(scenario.name)
def before_scenario(context, scenario):
# create log dir
feature_name_str = context.feature.name.replace(" ", "_")
log_dir = f"BDD/logs/{feature_name_str}"
os.makedirs(log_dir, exist_ok=True)
scenario_name = scenario.name.replace(" ", "_")
# generate log file path
current_time = datetime.datetime.now()
formatted_time = current_time.strftime("%Y-%m-%d-%H-%M-%S")
scenario_location_line = scenario.location.line
log_file = os.path.join(log_dir, f"{scenario_name}_{scenario_location_line}_{formatted_time}.log")
# log setup
# good 1
# logging.config.fileConfig("BDD/config/logging.ini", defaults={'logfilename': log_file})
# context.logger = logging.getLogger(f"{feature_name_str}_@{scenario_location_line}")
# good 2
# context.logger = scenario_log_setup(scenario, log_file)
# good 3
context.logger = scenario_log_setup_with_config_dict(scenario, log_file)
执行结果
终端输出并写入 log 文件中
PS C:\Automation\Test> behave
Feature: Logging Example # BDD/Features/log/log_with_config_file.feature:2
@log_test
Scenario: First Scenario # BDD/Features/log/log_with_config_file.feature:5
Given I have a scenario 1 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 17:17:31,197 CRITICAL : This is a log from scenario 1
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 17:17:31,199 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 17:17:31,202 ERROR : I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.1 # BDD/Features/log/log_with_config_file.feature:18
Given I have a scenario 2 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 17:17:31,212 CRITICAL : This is a log from scenario 2
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 17:17:31,212 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 17:17:31,212 ERROR : I should see the result
@log_test
Scenario Outline: Second Scenario -- @1.2 # BDD/Features/log/log_with_config_file.feature:19
Given I have a scenario 3 # BDD/steps/log_with_config_file_steps.py:7
2024-03-09 17:17:31,212 CRITICAL : This is a log from scenario 3
When I perform an action # BDD/steps/log_with_config_file_steps.py:14
2024-03-09 17:17:31,212 ERROR : I perform an action
Then I should see the result # BDD/steps/log_with_config_file_steps.py:22
2024-03-09 17:17:31,212 ERROR : I should see the result
1 feature passed, 0 failed, 0 skipped
3 scenarios passed, 0 failed, 0 skipped
9 steps passed, 0 failed, 0 skipped, 0 undefined
Took 0m0.004s
log 文件生成
总结
上面介绍了几种 log 处理方式， 比较推荐应用 Python logging 模块采用方式 1，应用 log 配置文件，优点就是代码可读性，可维护性更好。
