hugapi / hug

Embrace the APIs of the future. Hug aims to make developing APIs as simple as possible, but no simpler.
MIT License
6.86k stars 387 forks source link

Problems with logging middleware #593

Open JJ opened 7 years ago

JJ commented 7 years ago

All this has been uploaded to https://github.com/JJ/tests-python, just in case. Anyway. I'm trying to set up a logging middleware using jsonlogger this way:

""" Define logger en JSON """
class Logger(object):
    def __init__(self):
        self.logger = logging.getLogger()
        logHandler = logging.StreamHandler()
        formatter = jsonlogger.JsonFormatter()
        logHandler.setFormatter(formatter)
        self.logger.addHandler(logHandler)

    def info(self, content):
        self.logger.info(content)

@hug.middleware_class()
class CustomLogger(LogMiddleware):
    def __init__(self, logger=Logger()):
        super().__init__(logger=logger)

As far as I understand it, it should work out of the box. However, this is what I get in the console:

Serving on port 8000...
127.0.0.1 - - [19/Nov/2017 10:19:41] "GET / HTTP/1.1" 200 16
127.0.0.1 - - [19/Nov/2017 10:19:50] "GET /status HTTP/1.1" 200 16

Am I doing anything wrong? Shouldn't that thing be in another format? I have followed the instructions here https://github.com/madzak/python-json-logger

Update

I have added this:

    def process_request(self, request, response):
        """Logs the basic endpoint requested"""
        self.logger.info({ 'method': request.method,
                           'uri': request.relative_uri,
                           'type': request.content_type } )

    def process_response(self, request, response, resource):
        """Logs the basic data returned by the API"""
        self.logger.info( {'remote_addr':request.remote_addr,
                           't': current_time,
                           'method': request.method,
                           'uri': request.relative_uri,
                           'status': response.status,
                           'user-agent': request.user_agent })

but it still seems to yield the same result

JJ commented 7 years ago

More info here: 4 different loggers are apparently created. If I insert I'm here into __init__, I get

> Reloading due to file change: hugitos.py
I'm here
I'm here
I'm here
I'm here
Serving on port 8000...

I have also inserted debugging code in info, and it apparently is not called...

JJ commented 7 years ago

OK, I got it to work, although not entirely satisfactorily. Here's the class

@hug.middleware_class()
class CustomLogger(LogMiddleware):
    def __init__(self):
        logger = logging.getLogger()
        logger.setLevel(logging.INFO)
        logHandler = logging.StreamHandler()
        formatter = jsonlogger.JsonFormatter()
        logHandler.setFormatter(formatter)
        logger.addHandler(logHandler)
        super().__init__(logger=logger)

    def _generate_combined_log(self, request, response):
        """Given a request/response pair, generate a logging format similar to the NGINX combined style."""
        current_time = datetime.utcnow()
        return {'remote_addr':request.remote_addr,
                'time': current_time,
                'method': request.method,
                'uri': request.relative_uri,
                'status': response.status,
                'user-agent': request.user_agent }

No need to declare info, just the combined log (in this case). Key issue here is to declare the information level, I guess. In fact info does not get called at all, apparently. Anyway, here's the output

{"message": "Requested: GET / text/plain"}
{"message": null, "remote_addr": "127.0.0.1", "time": "2017-11-19T11:08:18.005052", "method": "GET", "uri": "/", "status": "200 OK", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:57.0) Gecko/20100101 Firefox/57.0"}
127.0.0.1 - - [19/Nov/2017 12:08:18] "GET / HTTP/1.1" 200 16

It gets two messages, one for the request and another for the response, second one with message "null", and still the initial plain_text . Maybe it's because I use addHandler. Let me check that

JJ commented 7 years ago

Well no it's not. I can't remove it. But that could be because reasons. Anyway, problem is this way I can't properly send output to some JSON-only logger...

JJ commented 6 years ago

Any reaction to this? Also, I'd like to find the way to log to a file, and I can't figure it out...