Skip to content

Remove log duplication with ap_log_error() and friends#941

Open
michael-o wants to merge 1 commit intoGrahamDumpleton:developfrom
michael-o:remove-log-duplication
Open

Remove log duplication with ap_log_error() and friends#941
michael-o wants to merge 1 commit intoGrahamDumpleton:developfrom
michael-o:remove-log-duplication

Conversation

@michael-o
Copy link
Copy Markdown
Contributor

@michael-o michael-o commented Feb 14, 2026

Previously, every log line contained the string 'mod_wsgi' along with the current pid. Both duplicate error log format parameters %P (current pid) and %m (the module logging). Hence, remove the duplication.

Moreover, I have fixed a few messages for position for args or consistent style.

Log sample after change:
httpd-error.log:

2026-02-14 22:24:13.492295 [pid: 90361, tid: 35041079296] [wsgi:debug] src/server/mod_wsgi.c(8545): Socket for 'kona' is '/var/run/wsgi.90361.0.1.sock'.
2026-02-14 22:24:13.492347 [pid: 90361, tid: 35041079296] [wsgi:debug] src/server/mod_wsgi.c(8614): Listen backlog for socket '/var/run/wsgi.90361.0.1.sock' is 100.
2026-02-14 22:24:13.493053 [pid: 90364, tid: 35041079296] [wsgi:info] Starting process 'kona' with uid=1001, gid=1001 and threads=5.
2026-02-14 22:24:13.493508 [pid: 90364, tid: 35041079296] [wsgi:info] Python home /usr/local/kona/app/.venv.
2026-02-14 22:24:13.493810 [pid: 90364, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:24:13.495049 [pid: 90365, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:24:13.495418 [pid: 90366, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:24:13.495687 [pid: 90367, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:24:13.529998 [pid: 90366, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:24:13.530169 [pid: 90365, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:24:13.530196 [pid: 90367, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:24:14.504023 [pid: 90373, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:24:14.518709 [pid: 90373, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:29:57.879876 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=90364) has died, deregister and restart it.
2026-02-14 22:29:57.879957 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=90364) terminated normally, exit code 0
2026-02-14 22:29:57.879985 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=90364) has been deregistered and will no longer be monitored.
2026-02-14 22:29:57.880955 [pid: 91649, tid: 35041079296] [wsgi:info] Starting process 'kona' with uid=1001, gid=1001 and threads=5.
2026-02-14 22:29:57.881471 [pid: 91649, tid: 35041079296] [wsgi:info] Python home /usr/local/kona/app/.venv.
2026-02-14 22:29:57.881799 [pid: 91649, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:30:57.496932 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91649) has died, deregister and restart it.
2026-02-14 22:30:57.496994 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91649) terminated normally, exit code 0
2026-02-14 22:30:57.497004 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91649) has been deregistered and will no longer be monitored.
2026-02-14 22:30:57.498151 [pid: 91902, tid: 35041079296] [wsgi:info] Starting process 'kona' with uid=1001, gid=1001 and threads=5.
2026-02-14 22:30:57.498665 [pid: 91902, tid: 35041079296] [wsgi:info] Python home /usr/local/kona/app/.venv.
2026-02-14 22:30:57.498976 [pid: 91902, tid: 35041079296] [wsgi:info] Initializing Python.
2026-02-14 22:32:00.122037 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91902) has died, deregister and restart it.
2026-02-14 22:32:00.122103 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91902) terminated by signal 9
2026-02-14 22:32:00.122130 [pid: 90361, tid: 35041079296] [wsgi:info] Process 'kona' (pid=91902) has been deregistered and will no longer be monitored.
2026-02-14 22:32:00.123113 [pid: 92143, tid: 35041079296] [wsgi:info] Starting process 'kona' with uid=1001, gid=1001 and threads=5.
2026-02-14 22:32:00.123620 [pid: 92143, tid: 35041079296] [wsgi:info] Python home /usr/local/kona/app/.venv.
2026-02-14 22:32:00.123933 [pid: 92143, tid: 35041079296] [wsgi:info] Initializing Python.

vhost-error.log:

2026-02-14 22:24:13.510299 [pid: 90364, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:24:13.519895 [pid: 90364, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:24:13.533654 [pid: 90364, tid: 35041079296] [wsgi:info] Create interpreter 'kona'.
2026-02-14 22:24:13.542629 [pid: 90364, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:24:13.543102 [pid: 90364, tid: 35041079296] [wsgi:info] Loading Python script '/usr/local/kona/wsgi/kona.wsgi' for process 'kona' and application 'kona'.
2026-02-14 22:24:15.337069 [pid: 90364, tid: 36794413312] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 0 in daemon process 'kona'.
2026-02-14 22:24:15.337121 [pid: 90364, tid: 36794415104] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 1 in daemon process 'kona'.
2026-02-14 22:24:15.337149 [pid: 90364, tid: 36794416896] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 2 in daemon process 'kona'.
2026-02-14 22:24:15.337192 [pid: 90364, tid: 36794418688] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 3 in daemon process 'kona'.
2026-02-14 22:24:15.337244 [pid: 90364, tid: 36794420480] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 4 in daemon process 'kona'.
2026-02-14 22:29:56.672170 [pid: 90364, tid: 36794418688] [wsgi:info] [client: 10.64.3.54:36062] [cid: rnrkV4+E0Sk, rid: aZDpVIzb7kryvze0UJXqZwAAWBM] Force restart of process 'kona'.
2026-02-14 22:29:56.672232 [pid: 90364, tid: 35041079296] [wsgi:info] Shutdown requested 'kona'.
2026-02-14 22:29:56.672254 [pid: 90366, tid: 35696445440] [wsgi:info] [client: 10.64.3.54:36062] [cid: rnrkV4+E0Sk, rid: aZDpVIzb7kryvze0UJXqZwAAWBM] Connect after WSGI daemon process restart, attempt #1.
2026-02-14 22:29:56.672263 [pid: 90364, tid: 36794418688] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 3 in daemon process 'kona'.
2026-02-14 22:29:56.672297 [pid: 90364, tid: 36794413312] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 0 in daemon process 'kona'.
2026-02-14 22:29:56.672301 [pid: 90364, tid: 36794420480] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 4 in daemon process 'kona'.
2026-02-14 22:29:56.672411 [pid: 90364, tid: 35041079296] [wsgi:info] Stopping process 'kona'.
2026-02-14 22:29:56.672431 [pid: 90364, tid: 35041079296] [wsgi:info] Destroying interpreters.
2026-02-14 22:29:56.672442 [pid: 90364, tid: 35041079296] [wsgi:info] Destroy interpreter 'kona'.
2026-02-14 22:29:56.672471 [pid: 90364, tid: 35041079296] [wsgi:info] End interpreter 'kona'.
2026-02-14 22:29:56.672414 [pid: 90364, tid: 36794416896] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 2 in daemon process 'kona'.
2026-02-14 22:29:56.672418 [pid: 90364, tid: 36794415104] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 1 in daemon process 'kona'.
2026-02-14 22:29:57.133738 [pid: 90364, tid: 35041079296] [wsgi:info] Cleanup interpreter ''.
2026-02-14 22:29:57.133872 [pid: 90364, tid: 35041079296] [wsgi:info] Terminating Python.
2026-02-14 22:29:57.141310 [pid: 90364, tid: 35041079296] [wsgi:info] Python has shutdown.
2026-02-14 22:29:57.141379 [pid: 90364, tid: 35041079296] [wsgi:info] Exiting process 'kona'.
2026-02-14 22:29:57.897903 [pid: 91649, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:29:57.907305 [pid: 91649, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:29:57.920778 [pid: 91649, tid: 35041079296] [wsgi:info] Create interpreter 'kona'.
2026-02-14 22:29:57.929432 [pid: 91649, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:29:57.929883 [pid: 91649, tid: 35041079296] [wsgi:info] Loading Python script '/usr/local/kona/wsgi/kona.wsgi' for process 'kona' and application 'kona'.
2026-02-14 22:29:59.708672 [pid: 91649, tid: 36889547008] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 0 in daemon process 'kona'.
2026-02-14 22:29:59.708816 [pid: 91649, tid: 36889548800] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 1 in daemon process 'kona'.
2026-02-14 22:29:59.708854 [pid: 91649, tid: 36889550592] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 2 in daemon process 'kona'.
2026-02-14 22:29:59.708890 [pid: 91649, tid: 36889552384] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 3 in daemon process 'kona'.
2026-02-14 22:29:59.708930 [pid: 91649, tid: 36889554176] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 4 in daemon process 'kona'.
2026-02-14 22:30:56.730069 [pid: 91649, tid: 35041079296] [wsgi:info] Shutdown requested 'kona'.
2026-02-14 22:30:56.730300 [pid: 91649, tid: 35041079296] [wsgi:info] Stopping process 'kona'.
2026-02-14 22:30:56.730300 [pid: 91649, tid: 36889554176] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 4 in daemon process 'kona'.
2026-02-14 22:30:56.730304 [pid: 91649, tid: 36889550592] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 2 in daemon process 'kona'.
2026-02-14 22:30:56.730301 [pid: 91649, tid: 36889552384] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 3 in daemon process 'kona'.
2026-02-14 22:30:56.730306 [pid: 91649, tid: 36889548800] [wsgi:debug] src/server/mod_wsgi.c(9156): Exiting thread 1 in daemon process 'kona'.
2026-02-14 22:30:56.730322 [pid: 91649, tid: 35041079296] [wsgi:info] Destroying interpreters.
2026-02-14 22:30:56.730424 [pid: 91649, tid: 35041079296] [wsgi:info] Destroy interpreter 'kona'.
2026-02-14 22:30:56.730460 [pid: 91649, tid: 35041079296] [wsgi:info] End interpreter 'kona'.
2026-02-14 22:30:57.214328 [pid: 91649, tid: 35041079296] [wsgi:info] Cleanup interpreter ''.
2026-02-14 22:30:57.214486 [pid: 91649, tid: 35041079296] [wsgi:info] Terminating Python.
2026-02-14 22:30:57.221727 [pid: 91649, tid: 35041079296] [wsgi:info] Python has shutdown.
2026-02-14 22:30:57.221790 [pid: 91649, tid: 35041079296] [wsgi:info] Exiting process 'kona'.
2026-02-14 22:30:57.515110 [pid: 91902, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:30:57.524637 [pid: 91902, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:30:57.538273 [pid: 91902, tid: 35041079296] [wsgi:info] Create interpreter 'kona'.
2026-02-14 22:30:57.547050 [pid: 91902, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:30:57.547507 [pid: 91902, tid: 35041079296] [wsgi:info] Loading Python script '/usr/local/kona/wsgi/kona.wsgi' for process 'kona' and application 'kona'.
2026-02-14 22:30:59.334109 [pid: 91902, tid: 36861343744] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 1 in daemon process 'kona'.
2026-02-14 22:30:59.334084 [pid: 91902, tid: 36861341952] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 0 in daemon process 'kona'.
2026-02-14 22:30:59.334146 [pid: 91902, tid: 36861345536] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 2 in daemon process 'kona'.
2026-02-14 22:30:59.334166 [pid: 91902, tid: 36861347328] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 3 in daemon process 'kona'.
2026-02-14 22:30:59.334193 [pid: 91902, tid: 36861349120] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 4 in daemon process 'kona'.
2026-02-14 22:32:00.140119 [pid: 92143, tid: 35041079296] [wsgi:info] Attach interpreter ''.
2026-02-14 22:32:00.149611 [pid: 92143, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:32:00.163227 [pid: 92143, tid: 35041079296] [wsgi:info] Create interpreter 'kona'.
2026-02-14 22:32:00.171995 [pid: 92143, tid: 35041079296] [wsgi:info] Adding '/usr/local/kona/app' to path.
2026-02-14 22:32:00.172455 [pid: 92143, tid: 35041079296] [wsgi:info] Loading Python script '/usr/local/kona/wsgi/kona.wsgi' for process 'kona' and application 'kona'.
2026-02-14 22:32:01.968997 [pid: 92143, tid: 36214612224] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 0 in daemon process 'kona'.
2026-02-14 22:32:01.969024 [pid: 92143, tid: 36214614016] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 1 in daemon process 'kona'.
2026-02-14 22:32:01.969055 [pid: 92143, tid: 36214615808] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 2 in daemon process 'kona'.
2026-02-14 22:32:01.969079 [pid: 92143, tid: 36214617600] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 3 in daemon process 'kona'.
2026-02-14 22:32:01.969115 [pid: 92143, tid: 36214619392] [wsgi:debug] src/server/mod_wsgi.c(9175): Started thread 4 in daemon process 'kona'.

All information is retained through ErrorLogFormat:

"%{cu}t [pid: %P, tid: %T] [%-m:%l] [client:\ %a] [cid:\ %{c}L,\ rid:\ %-L] %7F: %E: %M"

Previously, every log line contained the string 'mod_wsgi' along with the
current pid. Both duplicate error log format parameters '%P' (current pid) and
'%m' (the module logging). Hence, remove the duplication.
@michael-o
Copy link
Copy Markdown
Contributor Author

If necessary, I can move the message fixes into a separate PR.

@michael-o
Copy link
Copy Markdown
Contributor Author

@GrahamDumpleton Any chance to have this reviewed?

@GrahamDumpleton
Copy link
Copy Markdown
Owner

GrahamDumpleton commented Mar 31, 2026

Why it is the format it is, is because Apache 1.3, when all this code was mostly written, did not have a way of logging process ID as part of error log format. That pid/tid is shown at all, is only because it got added to default error log format in Apache 2.4.

That messages are logged with "mod_wsgi" prefix in them is again because Apache 1.3 didn't have a way to log what Apache module error messages were coming from. Apache 2.4 changed this as well and it started logging "wsgi:info" etc.

One could eliminate both things and get rid of the whole "mod_wsgi (pid=%d): " prefix, but the concern is whether this could break things where people have existing error log parsers which are used to seeing the existing format and match on that in some way when extracting information from the error logs.

The other option for now is a configuration directive for mod_wsgi changes the format it uses. You might well be the only person who ever uses it though.

@GrahamDumpleton
Copy link
Copy Markdown
Owner

The only other option which can be used to signal the change is to release mod_wsgi as 6.0 on next release. Mainly because has been so long since a release, but also use it as a point to introduce other significant changes, such as officially no longer supporting Windows.

@michael-o
Copy link
Copy Markdown
Contributor Author

Why it is the format it is, is because Apache 1.3, when all this code was mostly written, did not have a way of logging process ID as part of error log format. That pid/tid is shown at all, is only because it got added to default error log format in Apache 2.4.

That messages are logged with "mod_wsgi" prefix in them is again because Apache 1.3 didn't have a way to log what Apache module error messages were coming from. Apache 2.4 changed this as well and it started logging "wsgi:info" etc.

Oh, didn't even know that. I started with 2.x and mod_wsgi with 2.4.

One could eliminate both things and get rid of the whole "mod_wsgi (pid=%d): " prefix, but the concern is whether this could break things where people have existing error log parsers which are used to seeing the existing format and match on that in some way when extracting information from the error logs.

True, I do use fluent-bit on the error log to Victoria Logs, but the wsgi prefix is part of the message because pid is a separate field.

The other option for now is a configuration directive for mod_wsgi changes the format it uses. You might well be the only person who ever uses it though.

I agree, too little benefit for too much work.

@michael-o
Copy link
Copy Markdown
Contributor Author

The only other option which can be used to signal the change is to release mod_wsgi as 6.0 on next release. Mainly because has been so long since a release, but also use it as a point to introduce other significant changes, such as officially no longer supporting Windows.

I'd be in favor of that. I didn't even expect mod_wsgi to run on Windows.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants