Using ProcessorFormatter with RotatingFileHandler misformats the events

[if-fi]

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"}