It's 2 years on and I'm assuming the fluentd python logger has changed, I get a slightly different issue now and every Google search points back to this discussion.
When using your example in a gunicorn config file
access_log_format = '{"remote_ip":"%(h)s","request_id":"%({X-Request-Id}i)s","response_code":"%(s)s","request_method":"%(m)s","request_path":"%(U)s","request_querystring":"%(q)s","request_timetaken":"%(D)s","response_length":"%(B)s"}'
I get the desired behaviour of reading this as json and merging it with the fluentd json data, however the gunicorn fields aren't populated
{"tags": [], "level": "INFO", "host": "ubuntu", "logger": "gunicorn.access", "remote_ip":"%(h)s","request_id":"%({X-Request-Id}i)s","response_code":"%(s)s","request_method":"%(m)s","request_path":"%(U)s","request_querystring":"%(q)s","request_timetaken":"%(D)s","response_length":"%(B)s"}
It looks like the reason for this is that Gunicorn passes access_log_format as the message to the logger, and all the parameters (safe_atoms) as additional params, e.g.
/gunicorn/glogging.py
safe_atoms = self.atoms_wrapper_class(
self.atoms(resp, req, environ, request_time)
)
try:
# safe_atoms = {"s": "200", "m": "GET", ...}
self.access_log.info(self.cfg.access_log_format, safe_atoms)
however, if FluentRecordFormatter sees the string as valid json, it will read it using json.loads but ignores any arguments that are passed
/fluent/handler.py
def _format_msg_json(self, record, msg):
try:
json_msg = json.loads(str(msg)) # <------- doesn't merge params
if isinstance(json_msg, dict):
return json_msg
else:
return self._format_msg_default(record, msg)
except ValueError:
return self._format_msg_default(record, msg)
Compare this to the default Python formatter which calls record.message = record.getMessage() which in turn merges the arguments in
/Lib/logging/init.py
def getMessage(self):
"""
Return the message for this LogRecord.
Return the message for this LogRecord after merging any user-supplied
arguments with the message.
"""
msg = str(self.msg)
if self.args:
msg = msg % self.args # <------ args get merged in
return msg
I've logged an issue with the fluent-logger-python project.
Workaround
Use a logging filter to perform the merge before it's passed to FluentRecordFormatter.
logger = logging.getLogger('fluent.test')
class ContextFilter(logging.Filter):
def filter(self, record):
record.msg = record.msg % record.args
return True
fluent_handler = handler.FluentHandler('app.follow', host='localhost', port=24224)
formatter = handler.FluentRecordFormatter()
fluent_handler.setFormatter(formatter)
merge_filter = ContextFilter()
fluent_handler.addFilter(merge_filter)
logger.addHandler(fluent_handler)
Edit: Logging Filter Doesn't Work
After using the workaround of a logging filter for a bit, I started receiving errors like
ValueError: unsupported format character ';' (0x3b) at index 166
It turns out that FluentRecordFormatter does call the base getMessage implementation, merging arguments into the message
def format(self, record):
# Compute attributes handled by parent class.
super(FluentRecordFormatter, self).format(record) # <------ record.messge = record.msg % record.args
# Add ours
record.hostname = self.hostname
# Apply format
data = self._formatter(record)
self._structuring(data, record)
return data
The problem is that _format_msg_json(self, record, msg) uses the record.msg attribute which is the unmerged data, whereas record.message is the merged data. This creates a problem that my logging filter was merging / formatting the data but then the log formatter was also trying to do that and occasionally seeing invalid syntax.
Workaround 2: Don't Use Json
I've entirely given up on outputting json from gunicorn / python logging. Instead I'm using Fluentd's parser to parse the json, e.g.
<filter *.gunicorn.access>
@type parser
key_name message
reserve_time true
reserve_data true
remove_key_name_field true
hash_value_field access_log
<parse>
@type regexp
expression /^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^ ]*) +\S*)?" (?<code>[^ ]*) (?<size>[^ ]*) "(?<referer>[^\"]*)" "(?<agent>[^\"]*)"$/
time_format %d/%b/%Y:%H:%M:%S %z
</parse>
</filter>
You can read about what the options are doing here: https://docs.fluentd.org/filter/parser
