I needed to create a system, where log messages generated in an embedded system are logged remotely on a server and stored in the rotated log files. Due to restrictions in network communication, the log messages had to be transported via HTTP protocol. The server runs already a Flask based HTTP server, and therefore I wanted to integrate the logging system with Flask-based web applicattion.
The Python logging module offers the dedicated HTTPhandler class for that purpose. Basing on the logging documentation, I have created the first implementation.
The server part:
from flask import Flask
from flask import Response
from flask import request
import logging
import logging.handlers
app = Flask(__name__)
@app.route('/')
def hello_world():
return 'logging server'
@app.route('/log', methods=['POST'])
def handle_log():
if request.method == 'POST':
rd=request.form.to_dict()
record = logging.makeLogRecord(rd)
log1.handle(record)
return "OK"
log1=logging.getLogger('MTEST')
log1.setLevel(logging.DEBUG)
fh=logging.handlers.RotatingFileHandler('logs','a',maxBytes=10000000,backupCount=10)
formatter = logging.Formatter('%(asctime)s %(name)-15s %(levelname)-8s %(message)s')
rfh.setFormatter(formatter)
log1.addHandler(rfh)
log1.error("First error generated locally")
app.run()
The client part:
import logging, logging.handlers
myLogger = logging.getLogger('MTEST')
myLogger.setLevel(logging.DEBUG)
httpHandler = logging.handlers.HTTPHandler('localhost:5000',url='/log',method="POST")
myLogger.addHandler(httpHandler)
myLogger.info('Small info message')
myLogger.debug('Small debug message')
myLogger.erro('Small error message')
However, with that implementation the server reported the following errors (I copied one of four almost identical error messages) and only the locally generated error message was logged.
Traceback (most recent call last):
File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
if self.shouldRollover(record):
File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
msg = "%s\n" % self.format(record)
File "/usr/lib/python2.7/logging/__init__.py", line 741, in format
return fmt.format(record)
File "/usr/lib/python2.7/logging/__init__.py", line 465, in format
record.message = record.getMessage()
File "/usr/lib/python2.7/logging/__init__.py", line 329, in getMessage
msg = msg % self.args
TypeError: not all arguments converted during string formatting
I have added printing of the form data transmitted to the server and the attributes of the created LogRecord object. It appeared, that the args attribute is transmitted as empty tupple and not created.
To cure that I have modified the handle_log routine:
@app.route('/log', methods=['POST'])
def handle_log():
if request.method == 'POST':
rd=request.form.to_dict()
rd['args']=""
record = logging.makeLogRecord(rd)
log1.handle(record)
return "OK"
Logging still wasn't working, but the errors produced by the server have changed:
Logged from file test1.py, line 9
127.0.0.1 - - [10/Jul/2018 23:52:51] "POST /log HTTP/1.0" 200 -
Traceback (most recent call last):
File "/usr/lib/python2.7/logging/handlers.py", line 76, in emit
if self.shouldRollover(record):
File "/usr/lib/python2.7/logging/handlers.py", line 156, in shouldRollover
msg = "%s\n" % self.format(record)
File "/usr/lib/python2.7/logging/__init__.py", line 741, in format
return fmt.format(record)
File "/usr/lib/python2.7/logging/__init__.py", line 467, in format
record.asctime = self.formatTime(record, self.datefmt)
File "/usr/lib/python2.7/logging/__init__.py", line 423, in formatTime
ct = self.converter(record.created)
TypeError: a float is required
To check, what is wrong, I have added the filter printing the created LogRecord object:
from flask import Flask
from flask import Response
from flask import request
import logging
import logging.handlers
app = Flask(__name__)
@app.route('/')
def hello_world():
return 'logging server'
@app.route('/log', methods=['POST'])
def handle_log():
if request.method == 'POST':
rd=request.form.to_dict()
rd['args']=""
record = logging.makeLogRecord(rd)
log1.handle(record)
return "OK"
class myflt(logging.Filter):
def filter(self,rec):
print(rec.__dict__)
return 1
log1=logging.getLogger('MTEST')
log1.setLevel(logging.DEBUG)
rfh=logging.handlers.RotatingFileHandler('logs','a',maxBytes=10000000,backupCount=10)
formatter = logging.Formatter('%(asctime)s %(name)-15s %(levelname)-8s %(message)s')
rfh.setFormatter(formatter)
log1.addHandler(rfh)
log1.addFilter(myflt())
log1.error("First error generated locally")
app.run()
After that, I could compare the LogRecord objects created for the locally generated message:
{'threadName': 'MainThread', 'name': 'MTEST', 'thread': 139678016341824, 'created': 1531259894.112536, 'process': 5595, 'processName': 'MainProcess', 'args': (), 'module': 'srv1', 'filename': 'srv1.py', 'levelno': 40, 'exc_text': None, 'pathname': 'srv1.py', 'lineno': 37, 'msg': 'First error generated locally', 'exc_info': None, 'funcName': '<module>', 'relativeCreated': 44.27504539489746, 'levelname': 'ERROR', 'msecs': 112.53595352172852}
And for the remotely generated message:
{'relativeCreated': u'12.3879909515', 'process': u'5597', 'module': u'test1', 'funcName': u'<module>', 'filename': u'test1.py', 'levelno': u'10', 'processName': u'MainProcess', 'lineno': u'9', 'msg': u'Small debug message', 'args': '', 'exc_text': u'None', 'name': u'MTEST', 'thread': u'140221336438592', 'created': u'1531259898.51', 'threadName': u'MainThread', 'msecs': u'511.312007904', 'pathname': u'test1.py', 'exc_info': u'None', 'levelname': u'DEBUG'}
It appears, that the transmission of the log record via HTTPHandler converts all numbers into strings, and therefore the makeLogRecord function is not able to correctly recreate the LogRecord object in the server.
What is the proper way to transmit the log messages via HTTPHandler so that they may be properly handled by e.g., RotatingFileHandler in a remote machine?
