Hacktoberfest 2026: the issues maintainers tagged for October, open and beginner-friendly. Browse Hacktoberfest issues

Using `ProcessorFormatter` with `RotatingFileHandler` misformats the events

Open
  • Is something wrong?
#119 0 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Assessment

Difficulty
3/5
Estimated time
1-2 days
Newbie friendliness
45/100
Issue type
Bug
Clarity
Mostly clear
Activity status
Stale
Tech stack
python
Domain
backend

Research direction

Start by tracing how ProcessorFormatter interacts with logging.handlers.RotatingFileHandler during rollover; the report says these events are formatted twice and shows the nested output in both log files. Reproduce the configuration and compare the output before and after rollover. Done means each event is formatted once in both the plain and JSON log files.

Written by the indexing model from the issue text.

Description

I have the following configuration:


structlog.configure(
    processors=[
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.UnicodeEncoder(encoding='utf-8', errors='backslashreplace'),
        structlog.processors.TimeStamper(fmt='iso'),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    context_class=structlog.threadlocal.wrap_dict(dict),
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

pre_chain = [
    # Add the log level and a timestamp to the event_dict if the log entry
    # is not from structlog.
    structlog.stdlib.add_log_level,
    structlog.processors.TimeStamper(fmt='iso'),
]

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': False,

    'formatters': {        
        'plain_struct': {
            "()": structlog.stdlib.ProcessorFormatter,
            "foreign_pre_chain": pre_chain,
            "processor": structlog.dev.ConsoleRenderer(colors=False, pad_event=0),
        },
        'json_struct': {
            "()": structlog.stdlib.ProcessorFormatter,
            "foreign_pre_chain": pre_chain,
            "processor": structlog.processors.JSONRenderer(sort_keys=True),
        }
     },

    'filters': {
    },

    'handlers': {
        # Handler to log all the Website generic information
        'log_generic': {
              'class': 'logging.handlers.RotatingFileHandler',
              'level': 'DEBUG',
              'formatter': 'plain_struct',
              'filters': [],
              'maxBytes': 1024*1024,
              'filename': os.path.join(app.config.get('LOG_LOCATION'), 'app_debug.log')
        },

        # Handler to log all the Website generic information in json format
        'log_json': {
            'class': 'logging.handlers.RotatingFileHandler',
            'level': 'DEBUG',
            'formatter': 'json_struct',
            'filters': [],
            'maxBytes': 1024 * 1024,
            'filename': os.path.join(app.config.get('LOG_LOCATION'), 'app_json.log')
        },
    },

    'loggers': {
        # logs website errors and debug logs
        'fbu': {
            'handlers': ['log_json', 'log_generic'],
            'level': 'DEBUG',
            'propagate': False
        },
    }
}

Due to some specifics in the RotatingFileHandler internal implementation, the log messages go through formatting twice, and I end up with those log messages in both files:

app_debug.log:

2017-05-14T21:03:26.563866Z [info     ] 2017-05-14T21:03:26.563745Z [info     ] {"event": "{\"event\": \"I am here\", \"level\": \"info\", \"logger\": \"fbu.process\", \"timestamp\": \"2017-05-14T21:03:26.562886Z\"}", "level": "info", "timestamp": "2017-05-14T21:03:26.563333Z"}

app_json.log:

{"event": "{\"event\": \"I am here\", \"level\": \"info\", \"logger\": \"fbu.process\", \"timestamp\": \"2017-05-14T21:03:26.562886Z\"}", "level": "info", "timestamp": "2017-05-14T21:03:26.563333Z"}
Dominant language
Python
Stars
5k
Forks
302
Avg merge
17m
Merged PRs (30d)
4

Getting set up

This project ships no dev container, Dockerfile or contributing guide, so setting up is up to you: start from its README, and see our first-contribution guide for the general steps.

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from hynek/structlog

All issues in hynek/structlog

Similar issues

More Python issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.