python bottle always logs to console, no logging to file

Question

In a python project with multiple threads my logging works well to write to a logger file. Basically based on Logging, StreamHandler and standard streams

Part of my project is a bottle web server which runs well also. But every bottle call writes a log to the console like this:

 192.168.178.20 - - [26/Jun/2015 20:22:17] "GET /edit?addJob HTTP/1.1" 200 48028

How to handle this the same way as with the other code, so the bottle logs go also to the logger file?

Cabanatuan

You accepted ayb's answer, but please consider changing that. No need to accept mine (unless you think it's the best correct answer), but I'd rather not see future visitors to this question be misled by ayb's code, which should not be used except in the most lightweight of applications (and even then, it's a questionable practice). – Greasy

Answer 1

If you're rolling your own solution, you should write a simple Bottle plugin that emits log lines to a logging logger. Here's an example that sets up a basic logger, defines the logging plugin, and creates a Bottle app with that plugin installed on all routes.

from bottle import Bottle, request, response
from datetime import datetime
from functools import wraps
import logging

logger = logging.getLogger('myapp')

# set up the logger
logger.setLevel(logging.INFO)
file_handler = logging.FileHandler('myapp.log')
formatter = logging.Formatter('%(msg)s')
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(formatter)
logger.addHandler(file_handler)

def log_to_logger(fn):
    '''
    Wrap a Bottle request so that a log line is emitted after it's handled.
    (This decorator can be extended to take the desired logger as a param.)
    '''
    @wraps(fn)
    def _log_to_logger(*args, **kwargs):
        request_time = datetime.now()
        actual_response = fn(*args, **kwargs)
        # modify this to log exactly what you need:
        logger.info('%s %s %s %s %s' % (request.remote_addr,
                                        request_time,
                                        request.method,
                                        request.url,
                                        response.status))
        return actual_response
    return _log_to_logger

app = Bottle()
app.install(log_to_logger)

@app.route('/')
def home():
    return ['hello, world']

app.run(host='0.0.0.0', port='8080', quiet=True)

Running that code yields what you want:

% python myapp.py &
% curl -v http://localhost:8080/
% tail myapp.log    
127.0.0.1 2015-06-27 16:57:09.983249 GET http://localhost:8080/ 200 OK

Greasy

Tested, works! Going to add some statements so a normal 'print' will log also to the file. – Cabanatuan

Did you removed the 'print' I added? I'm trying to use your solution with starting the bottle program on a thread ... going to post it below – Cabanatuan

This solution may be used in threads with no issues. Not sure what you're asking about the "print," sorry. You added a "print" somewhere? – Greasy

tried to add/edit in your listing "print = logger.info" etc ... but somehow it was rejected. – Cabanatuan

print = logging.info is a red flag. (Seriously, don't do it.) What are you trying to accomplish? – Greasy

Let us continue this discussion in chat. – Cabanatuan

Answer 2

I'm trying to use Ron's solution with starting the bottle program on a thread:

tWeb = Thread(target=runWeb, args=('192.168.178.16', 5003)).start()

with

def runWeb(aserver, aport):
    run(host=aserver, port=aport, debug=True)

but that fails. Any 'print' goes to the file, but not the 'yield' (see above), it goes to the console.

Also changing "debug=True" to "quiet=True" only changes to: there is no output on the console at all.

Cabanatuan

@Ron Any idea what prevents outputting the 'yield' to the log file? – Cabanatuan

What yield are you talking about? I don't see a yield anywhere. – Greasy

Upps, please see your comment "Running that code yields what you want" above ... part of it you posted "127.0.0.1 2015-06-27 16:57:09.983249 GET localhost:8080 200 OK" ... and that's what I'm missing when starting the bottle part in a thread .. see my answer above. – Cabanatuan

So if I understand correctly, you are using 'print' statements? Why aren't you using logging statements instead? Print is not a good way to log. – Greasy

I found it helpful to enable the 'print' statements also going to the log file with just en/disabling "print = logger.info" – Cabanatuan

Okay, suit yourself. :) – Greasy

Answer 3

Ron's solution logs only requests which were handled by the routes. If you want to log everything, including 404 file not found, you should consider a simple WSGI middleware like wsgi-request-logger.

#!/usr/bin/python3

import bottle
from bottle import route
from requestlogger import WSGILogger, ApacheFormatter
import waitress
import logging
import sys


@route('/hello')
def hello():
    return 'Hello World'


waitress.serve(WSGILogger(
    bottle.default_app(), [logging.StreamHandler(sys.stdout)],
    ApacheFormatter(), propagate=False
))

The output looks the following way:

192.168.190.102 - - [09/Mar/2023:09:39:10 +0200] "GET /hello HTTP/1.1" 200 11 "" "curl/7.68.0" 0/228
192.168.190.102 - - [09/Mar/2023:09:39:14 +0200] "GET /zzz HTTP/1.1" 404 731 "" "curl/7.68.0" 0/9617

If you want to log to a file, you can add another logging handler in the list or replace the existing one completely. Here is an example of a handler which logs to a file in a fashion similar to the Apache access logs:

#!/usr/bin/python3

import waitress
import bottle
from bottle import route
from requestlogger import WSGILogger, ApacheFormatter
import logging
import sys
from logging.handlers import TimedRotatingFileHandler


@route('/hello')
def hello():
    return 'Hello World'


logging_handlers = [
    logging.StreamHandler(sys.stdout),
    TimedRotatingFileHandler('access.log', 'd', 7)
]

waitress.serve(WSGILogger(
    bottle.default_app(), logging_handlers,
    ApacheFormatter(), propagate=False
))

I don't know what's the performance impact of the middleware.

Compressive

Answer 4

You running builtin server right ? Then you can make a simple plugin :

from bottle import request, response, route, install, run
from datetime import datetime


def logger(func):
    def wrapper(*args, **kwargs):
        log = open('log.txt', 'a')
        log.write('%s %s %s %s %s \n' % (request.remote_addr, datetime.now().strftime('%H:%M'),
                                         request.method, request.url, response.status))
        log.close()
        req = func(*args, **kwargs)
        return req
    return wrapper

install(logger)


@route('/')
def index():
    return 'Hello, World'

run(quiet=True)

Or try this one

Shinar

Yes, that works. But I see a conflict because the way this solution writes to a log would be writing to the same log file as with the main part of the project (see referenced link above). The bottle project is started on one of some threads and I think the "bottle logs" should be handled by the main project part also. – Cabanatuan

WARNING: do not do this, unless you REALLY don't care about performance. This code opens a file on every single request, which is a terrible idea. – Greasy