cs3org / wopiserver

A vendor-neutral application gateway compatible with the WOPI specifications.
Apache License 2.0
55 stars 26 forks source link

fix duplicate logging entries #92

Closed xoxys closed 2 years ago

xoxys commented 2 years ago

Background: https://github.com/Pylons/waitress/issues/151

For waitress it's required to add a log handler to the root logger (which is recommended in general) otherwise waitress will add its own handler. As a result, there exists a waitress handler and a flask handler which are both used for logging.

Result with debug log level:

❯ python3 src/wopiserver.py
{"time": "2022-10-11T11:18:20.548", "host": "superion", "level": "INFO", "process": "wopiserver", "module": "wopiserver", "msg": "WOPI Server starting in unsecure/embedded mode", "port": "8880", "wopiurl": "https://your-wopi-server.org:8443", "version": "git"}
{"time": "2022-10-11T11:18:25.721", "host": "superion", "level": "DEBUG", "process": "wopiserver", "module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"}
DEBUG:wopiserver:"module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"
{"time": "2022-10-11T11:18:26.087", "host": "superion", "level": "DEBUG", "process": "wopiserver", "module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"}
DEBUG:wopiserver:"module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"

To fix it, this PR is removing the flask log handler and adding a proper handler to the root logger if waitress is used.

Result:

❯ python3 src/wopiserver.py
{"time": "2022-10-11T11:20:30.725", "host": "superion", "level": "INFO", "process": "wopiserver", "module": "wopiserver", "msg": "WOPI Server starting in unsecure/embedded mode", "port": "8880", "wopiurl": "https://your-wopi-server.org:8443", "version": "git"}
{"time": "2022-10-11T11:20:38.280", "host": "superion", "level": "DEBUG", "process": "wopiserver", "module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"}
{"time": "2022-10-11T11:20:38.639", "host": "superion", "level": "DEBUG", "process": "wopiserver", "module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"}
{"time": "2022-10-11T11:20:39.029", "host": "superion", "level": "DEBUG", "process": "wopiserver", "module": "wopiserver", "msg": "Accessed index page", "client": "127.0.0.1"}
xoxys commented 2 years ago

As a matter of fact, we do see a few duplicate logs, only at the start of the process in flask mode. I wonder if something could be done (though it's very minor).

The first log entry WOPI Server starting in unsecure/embedded mode is duplicated because Flask immediately restart the server, but that's related to the debug mode behavior of Flask and IMO not a logging issue.

image

glpatcern commented 2 years ago

The first log entry WOPI Server starting in unsecure/embedded mode is duplicated because Flask immediately restart the server, but that's related to the debug mode behavior of Flask and IMO not a logging issue.

Right, thanks for that - and indeed not really an issue for this PR.

xoxys commented 2 years ago

@glpatcern Could we get a tag for this change?

glpatcern commented 2 years ago

@xoxys sure, I wanted to tag today after merging two more completed PRs.

xoxys commented 2 years ago

Cool, thanks!