kolibri
kolibri copied to clipboard
learningequality
Separate or disable request logging
Observed behavior
Requests are part of logging (at least, debug logging).
…
Errors and logs
Example of $KOLIBRI_HOME/logs/kolibri.txt after kolbri start --debug
INFO 2022-06-09 04:45:57,915 kolibri.utils.options Option RUN_MODE in section [Deployment] being overridden by environment variable KOLIBRI_RUN_MODE
INFO 2022-06-09 04:46:27,756 cherrypy.access 34.78.159.78 - - "GET /api/public/info/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,770 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/morangoinfo/1/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,966 cherrypy.access 34.78.159.78 - - "GET /api/public/v1/facility/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,989 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/certificates/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,012 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/nonces/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,059 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/syncsessions/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,173 root Completed stage 'initializing'
INFO 2022-06-09 04:46:28,179 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/transfersessions/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,190 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/transfersessions/f8e8afedd74e4f4394305384139345dc/" 200 0 "" "python-request
s/2.21.0"
INFO 2022-06-09 04:46:28,213 root Starting stage 'serializing'
INFO 2022-06-09 04:46:41,550 root Completed stage 'serializing'
INFO 2022-06-09 04:46:41,594 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/transfersessions/f8e8afedd74e4f4394305384139345dc/" 200 0 "" "python-request
s/2.21.0"
INFO 2022-06-09 04:46:41,616 root Starting stage 'queuing'
INFO 2022-06-09 04:51:29,592 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 04:59:39,808 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:08:42,641 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:13:33,317 root Completed stage 'queuing'
INFO 2022-06-09 05:17:19,640 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:25:20,605 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:33:21,590 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
ERROR 2022-06-09 05:36:46,516 django.security.DisallowedHost Invalid HTTP_HOST header: 'Cheroot/unknown:8080'. The domain name provided is not valid according
to RFC 1034/1035.
Desired behavior
I'd like the option of a) turning off request logging, or b) with reqeust logging enabled, writing them to a file that's distinct from the file used for application logging. Using the example above, in $KOLIBRI_HOME/logs/kolibri.txt I'd see:
INFO 2022-06-09 04:45:57,915 kolibri.utils.options Option RUN_MODE in section [Deployment] being overridden by environment variable KOLIBRI_RUN_MODE
INFO 2022-06-09 04:46:28,173 root Completed stage 'initializing'
NFO 2022-06-09 04:46:28,213 root Starting stage 'serializing'
INFO 2022-06-09 04:46:41,550 root Completed stage 'serializing'
INFO 2022-06-09 04:46:41,616 root Starting stage 'queuing'
INFO 2022-06-09 05:13:33,317 root Completed stage 'queuing'
ERROR 2022-06-09 05:36:46,516 django.security.DisallowedHost Invalid HTTP_HOST header: 'Cheroot/unknown:8080'. The domain name provided is not valid according
to RFC 1034/1035.
And in, say, $KOLIBRI_HOME/logs/requests.txt I'd see:
INFO 2022-06-09 04:46:27,756 cherrypy.access 34.78.159.78 - - "GET /api/public/info/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,770 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/morangoinfo/1/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,966 cherrypy.access 34.78.159.78 - - "GET /api/public/v1/facility/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:27,989 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/certificates/" 200 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,012 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/nonces/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,059 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/syncsessions/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,179 cherrypy.access 34.78.159.78 - - "POST /api/morango/v1/transfersessions/" 201 0 "" "python-requests/2.21.0"
INFO 2022-06-09 04:46:28,190 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/transfersessions/f8e8afedd74e4f4394305384139345dc/" 200 0 "" "python-request
s/2.21.0"
INFO 2022-06-09 04:46:41,594 cherrypy.access 34.78.159.78 - - "GET /api/morango/v1/transfersessions/f8e8afedd74e4f4394305384139345dc/" 200 0 "" "python-request
s/2.21.0"
INFO 2022-06-09 04:51:29,592 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 04:59:39,808 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:08:42,641 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
INFO 2022-06-09 05:17:19,640 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:25:20,605 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
INFO 2022-06-09 05:33:21,590 cherrypy.access 76.176.148.197 - - "PUT /api/auth/session/current/" 200 0 "http://104.199.49.151:8080/fr-fr/auth/" "Mozilla/5.0 (X
11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/97.0.4692.71 Safari/537.36"
Hi @socketbox! I would like to work on this. Could you please point me towards the necessary files :smiley:.
Hi @camperjett - this involves impacting the logging configuration, which gets used before any other parts of the app are started. Because of this, we have used environment variables to affect this in the past. I would suggest adding another environment variable to disable request logging. This will be slightly easier to implement than the original suggestion in the issue, and should also meet the need, as requests can be logged by other mechanisms.
We enumerate all pure environment variables used to configure Kolibri here: https://github.com/learningequality/kolibri/blob/develop/kolibri/utils/env.py#L58 so you should add an additional entry for KOLIBRI_DISABLE_REQUEST_LOGGING, with an appropriate description.
You would then need to add an entry for cherrypy.access to the logging configuration here: https://github.com/learningequality/kolibri/blob/develop/kolibri/utils/logger.py#L238 and make sure that in the case that the environment variable is set, it prevents all log output from that module, and in the case that it is not, it logs precisely once for each call.
Hi @socketbox. Sorry for replying after more than a month. I understood that adding a new environment variable will help checking if we want to log requests or not, so the variable KOLIBRI_DISABLE_REQUEST_LOGGING should be set to disable the same. But I do not quite fully understand what the logging configuration does. Could you please help me on that? Like what does the "handlers": DEFAULT_HANDLERS, "level": DEFAULT_LEVEL, "propagate": False, means?
For complete details of what the different elements of the logging configuration mean, see the Python documentation here! https://docs.python.org/3/library/logging.config.html#dictionary-schema-details
handlers describes which of the handlers specified in the top level handlers entry this particular logging entry should use - generally we use the same handlers for everything, so no need to edit this.
level describes the minimum severity of messages to log. This could be something like "INFO" which would mean any call to logging.info, logging.warn, logging.error would get logged, anything of a 'lower' log level would not get logged. If we limited it just to "ERROR" we would only see log messages marked as errors or more servere.
The propagate value indicates whether messages that are caught by this configuration should also be passed to configurations of parent modules - we use False here to prevent duplicate logging from occurring.
Hi @socketbox! I have done the changes. I was wondering how to add a custom flag like --disable-request in the command kolibri start?