BDD - Python Behave log 为每个 Scenario 生成对应的 log 文件

引言

文章《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.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 配置文件，优点就是代码可读性，可维护性更好。