The UDM REST API writes two log lines for every request: Examples: 07.09.24 09:18:15 INFO ( 31) : 201 [f8ea7ec26857] POST /udm/users/user/ (0.0.0.0) 1412.62ms 07.09.24 09:18:15 INFO ( 13) :201 POST /udm/users/user/ (10.244.0.6) 1415.08ms 07.09.24 09:48:44 INFO ( 31) : 200 [ca6d75371400] GET /udm/users/user/uid=richardkane199,cn=users,dc=univention-organization,dc=intranet (0.0.0.0) 55.10ms 07.09.24 09:48:44 INFO ( 13) :200 GET /udm/users/user/uid=richardkane199,cn=users,dc=univention-organization,dc=intranet (10.244.0.6) 79.45ms The processes: 2041190 ? S 0:02 /usr/bin/python3 -m univention.admin.rest -l de_DE.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-de-de.socket 2041192 ? Sl 579:53 /usr/bin/python3 -m univention.admin.rest -l en_US.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-en-us.socket 2041227 ? Sl 1:14 /usr/bin/python3 -m univention.admin.rest -l en_US.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-en-us.socket # multiprocessing manager 2041242 ? Sl 0:17 /usr/bin/python3 -m univention.admin.rest -l de_DE.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-de-de.socket # multiprocessing manager It is very confusing to have to optically match duplicate lines and filter them out in the mind. There should be only one log line per request. The format and the content are both not the same for the two lines. My guess is that one line is created by the "multiprocessing manager" and one line by the worker processes. The difference between the lines (ignoring the different formatting) are: * One line contains the request ID, the other not. No request ID is important. Every line must have it. * The request timing of one line is higher that the other. It probably includes the time for the IPC between manager and worker. That time is the correct one, the other not relevant. Change the UDM REST API so it writes only one line per request. That line must include the request ID. If the line contains a timing it should measure the time between receiving the request and sending the result - that includes the time for the IPC.
(In reply to Daniel Tröder from comment #0) > My guess is that one line is created by the "multiprocessing manager" and > one line by the worker processes. Wrong guess. 797 ? Ss 0:00 /usr/bin/python3 -m univention.admin.rest.server 1076 ? Sl 0:08 /usr/bin/python3 -m univention.admin.rest.server # multiprocessing manager 1112 ? S 0:00 /usr/bin/python3 -m univention.admin.rest -l en_US.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-en-us.socket 1113 ? S 0:00 /usr/bin/python3 -m univention.admin.rest -l de_DE.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-de-de.socket 1459 ? Sl 0:08 /usr/bin/python3 -m univention.admin.rest -l en_US.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-en-us.socket # multiprocessing manager 1610 ? Sl 0:09 /usr/bin/python3 -m univention.admin.rest -l de_DE.UTF-8 -c 1 -d 2 -s /var/run/univention-directory-manager-rest-de-de.socket # multiprocessing manager There is one gateway process "univention.admin.rest.server", which selects the correct language and forwards the request to the language-specific UDM REST API e.g.: "univention.admin.rest -l en_US.UTF-8". So the request log line without request ID is the gateway process. I didn't find it appropriate to enable logging of the request ID there as well as it affects performance to add these context information. These lines can be ignored. However they may be useful, if there would be a problem in the gateway process. Then one would like to have the information in which component a request was stuck. This never happened. Maybe we can just add a UCR variable, which by default, hides the logs of the gateway process - so that we can enable them, if we have (to debug) troubles in that area. > * The request timing of one line is higher that the other. It probably > includes the time for the IPC between manager and worker. That time is the > correct one, the other not relevant. Well, it included the time from the gateway server processing - a minimal offset. I think we should drop the gateway process logging. You will have a third logging of the request in the apache access log, which is another different timing. Otherwise it is a lot of effort to realize this because we have to deactivate access logging in the actual server process - this makes debugging harder - and we have to additionally activate the context-aware logging in the gateway process.
> So the request log line without request ID is the gateway process. > I didn't find it appropriate to enable logging of the request ID there as well as it affects performance to add these context information. These lines can be ignored. > However they may be useful, if there would be a problem in the gateway process. Then one would like to have the information in which component a request was stuck. > This never happened. > Maybe we can just add a UCR variable, which by default, hides the logs of the gateway process - so that we can enable them, if we have (to debug) troubles in that area. I cannot imagine why adding a string to a log line costs performance. However, the log line is useless without a request ID because we cannot associate it with a specific request when there are many parallel requests. A configuration that disables logging is bad for support. You must know when to enable it, which probably requires a deeper understanding. Until then, you may be losing information. I suggest setting the gateway process's logging handler to WARNING instead of INFO, at least for the module that creates the access log. That way, we'll get error messages without a configuration change, and we will not see the duplicate access log.
(In reply to Daniel Tröder from comment #3) > I cannot imagine why adding a string to a log line costs performance. Because in async applications, to "remember" the request ID you have to store the whole stack in a context and switch between them. At least, this is what I read about in the tornado docs, somewhen back implementing that feature. I don't find it anymore, I only find this similar note: https://github.com/tornadoweb/tornado/issues/2216#issuecomment-352198092
I see. That doesn't seem to be a problem for frameworks using the standard library asyncio framework, because they can simply use contextvars from the standard library (e.g., https://github.com/snok/asgi-correlation-id). At least there seems to be no relevant performance impact. Anyway, changing the handler log level should fix this without any relevant code or performance change.
Tornado uses asyncio and we are using the "contextvars" module for adding the request ID. Maybe my information about performance is just historical and we don't have any problem.
The UDM REST API gateway process now simply ignores logging the access-log in case the request was successful. univention-directory-manager-rest (12.3.0) c0a3d9cc59ef | feat(udm-rest): remove duplicated access log entry
OK - changes OK - advisory OK - tests
<https://errata.software-univention.de/#/?erratum=5.2x235>