Planned change of the apache LogFormat to append "the time taken to serve the request, in ms"

Announcements
1

Hello community,

We are thinking about to change the site apache LogFormat by appending field to the site
containing the “the time taken to serve the request, in ms” to apache log file ~/var/log/apache/access_log

This will help us to identify slow views, slow REST API calls etc.

details

current setting

OMD[central]:~$ grep ^LogFormat etc/apache/apache.conf
LogFormat "%{X-Forwarded-For}i %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined

proposed setting

OMD[central]:~$ grep ^LogFormat etc/apache/apache.conf
LogFormat "%{X-Forwarded-For}i %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" duration:%{ms}Tms" combined

I do believe that this is not causing any problems,
but if you are processing these log files further, who knows.

:information_source: This is just heads up to find out if anyone has got concerns about this change.

It would help us a lot for troubleshooting and introducing an extra logfile seems to be too much hassle.

KR Jodok

Internal reference is CMK-18786

8 Likes
2024 September Community Bulletin
2

That’s a good idea and I’d appreciate that. We too have some requests which take ages (like the list of crash reports in a distributed environment, for example).

If the extended format causes problems, then it is also possible to let apache write two logfiles: one in the existing format and a second one with extra (or other) information as you suggested.

1 Like
3

One big log file with all the data is a great way to avoid having to deal with any duplicate information. On the other hand, having several specialized log files can help you reduce the amount of data you have to work with later on, which makes it easier to evaluate things more quickly.

It’s probably best not to include “duration:” and “ms” in the log. These bytes don’t add any value and just waste diskspace. And I wonder if it might be more logical to use “%D” like in the stats log rather than “%{ms}Tms” to ensure the values are consistent across all logs.

As you know Checkmk records allready the execution time of each page in a compact format in the stats log.

~/etc/apache/conf.d/stats.conf

# Enables a special kind of log file for recording and checking the usage
# of the sites apache with Check_MK. Please note that this file is, when
# monitored with Check_MK, is being truncated automatically each time the
# Check_MK agent is executed.
LogFormat "%U%q|%s|%B|%D" stats
CustomLog /omd/sites/sitename/var/log/apache/stats stats

Since the stats file gets truncated by checkmk we use in addition a slightly adopted format for ad-hoc analysis.

# Enables a special log file for recording the usage of the sites apache with Check_MK.
LogFormat "%{%F %T}t|%s|%m|%D|%B|%U%q" stats_archive
CustomLog /omd/sites/sitename/var/log/apache/stats_archive stats_archive

And here’s how it looks like in the logs:

access_log

- - - [03/Oct/2024:11:33:17 +0200] "GET /sitename/check_mk/api/1.0/domain-types/bi_aggregation/actions/aggregation_state/invoke HTTP/1.1" 200 517 "-" "python-requests/2.31.0"

stats

/sitename/check_mk/api/1.0/domain-types/bi_aggregation/actions/aggregation_state/invoke|200|517|8246348

stats_archive

2024-10-03 11:33:17|200|POST|517|8246348|/sitename/check_mk/api/1.0/domain-types/bi_aggregation/actions/aggregation_state/invoke
1 Like
4

Thank you for your feedback.

We now decided to just append %D to the LogFormat
(The time taken to serve the request, in microseconds.)

https://httpd.apache.org/docs/2.4/mod/mod_log_config.html#formats

The change:

OMD[mysite]:~$ omd diff etc/apache/apache.conf 
...
< LogFormat "%{X-Forwarded-For}i %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
---
...
> LogFormat "%{X-Forwarded-For}i %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %D" combined
...

Internal reference is CMK-18786

2 Likes