Unable to log slow queries when LogSlowBufferedLogs is "On" and outbuf is <512

[cyril-bouthors]

Hi,

After quite a lot of test cases, we came to the conclusion that mod_log_slow is unable to log queries under the following conditions:

• outbuf is < 512 characters
• LogSlowBufferedLogs is On
• Apache version is 2.2.22
• OS version is Debian/wheezy amd64
• mod_log_slow version is between 1.0.6 and the current Git version

To reproduce the issue.

for a in $(seq 0 10 500)
do
  url="http://wheezy/?$a-$(for b in $(seq $a); do echo -n x; done)"
  wget -nv -O/dev/null $url
done

Expected behavior: see all queries in the log file.

Found behavior: only lines longer than 512 are shown:

# head /var/log/apache2/mod_slow.log
5d35:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23861 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?360-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1
5d36:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23862 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?370-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1
5d37:53997a38:0 [12/Jun/2014:12:00:24 +0200] elapsed: 0.00 cpu: 0.00(usr)/0.00(sys) pid: 23863 ip: 10.10.0.254 host: wheezy:80 reqinfo: GET /?380-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx HTTP/1.1

Here is the configuration used:

    LogSlowEnabled On
    LogSlowFileName /var/log/apache2/mod_slow.log
    LogSlowBufferedLogs On
    LogSlowLongRequestTime 0

This bug is not reproducible if LogSlowBufferedLogs is disable or if we are running Debian/sid + Apache 2.4.

In mod_log_slow.c, I've found this:

#define LOGBUF_SIZE                (512)

It's maybe related, See https://github.com/yokawasa/mod_log_slow/blob/master/mod_log_slow.c#L40

Do you think there could be a way to fix this issue with short outbuf?

Regards,

[yokawasa]

Hi Cyril,

Thank you for reporting this. Also my apologies for not responding earlier.

First, let me explain an expected behavior of buffering log function below:

When LogSlowBufferedLogs is enabled, slow log lines are temporary stored in memory buffer (size is 512 byte), and they are flushed on to slow log file when the total size of slow logs get more than 512. In other words, slow log lines are not flushed on to the log file until the total size of accumulated slow log lines in the buffer get more than 512. If single log line is more than 512, it is flushed on to the log file without being stored in temporary buffer. In addition, slow log stored in the buffer are flushed on the low in stopping Apache.

So, you may observe that even lines shorter than 512 are shown when the total size of accumulated log sizes get more than 512.

Please let me know if you have problem or concern on this issue. Any input is appreciated.

[cyril-bouthors]

According to my tests, absolutely no line is logged even after several thousands accesses.

[yokawasa]

Thanks for your feedback. Let me provide current update. Unfortunately I haven't make it reproducing the issue. I've run your script under the following conditions but I see lines shorter than 512 are logged.

• LogSlowBufferedLogs is On
• Apache version: 2.2.22
• OS version: Debian/wheezy amd64
• mod_log_slow version: the current Git version

Can you please provide the output of "httpd -V" command run on your environment for my further investigation on this issue?

The output of "httpd -V" on my environment is .. $ apache/bin/httpd -V

Server version: Apache/2.2.22 (Unix)
Server built:   Jun 29 2014 23:23:07
Server's Module Magic Number: 20051115:30
Server loaded:  APR 1.4.5, APR-Util 1.4.1
Compiled using: APR 1.4.5, APR-Util 1.4.1
Architecture:   64-bit
Server MPM:     Prefork
  threaded:     no
    forked:     yes (variable process count)

[cyril-bouthors]

On Mon, Jun 30, 2014 at 5:32 PM, Yoichi Kawasaki [email protected] wrote:

Can you please provide the output of "httpd -V" command run on your environment for my further investigation on this issue?

"httpd" is called "apache2" under Debian:

apache2 -V

Server version: Apache/2.2.22 (Debian) Server built: Feb 1 2014 21:26:10 Server's Module Magic Number: 20051115:30 Server loaded: APR 1.4.6, APR-Util 1.4.1 Compiled using: APR 1.4.6, APR-Util 1.4.1 Architecture: 64-bit Server MPM: ITK threaded: no forked: yes (variable process count) Server compiled with.... -D APACHE_MPM_DIR="server/mpm/experimental/itk" -D APR_HAS_SENDFILE -D APR_HAS_MMAP -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled) -D APR_USE_SYSVSEM_SERIALIZE -D APR_USE_PTHREAD_SERIALIZE -D APR_HAS_OTHER_CHILD -D AP_HAVE_RELIABLE_PIPED_LOGS -D DYNAMIC_MODULE_LIMIT=128 -D HTTPD_ROOT="/etc/apache2" -D SUEXEC_BIN="/usr/lib/apache2/suexec" -D DEFAULT_PIDLOG="/var/run/apache2.pid" -D DEFAULT_SCOREBOARD="logs/apache_runtime_status" -D DEFAULT_LOCKFILE="/var/run/apache2/accept.lock" -D DEFAULT_ERRORLOG="logs/error_log" -D AP_TYPES_CONFIG_FILE="mime.types"

-D SERVER_CONFIG_FILE="apache2.conf"

Cyril Bouthors - ISVTEC https://www.isvtec.com/: Web Platform Managed Services and Scalability 14 avenue de l'Opéra, 75001 Paris. 201 rue Vendôme, 69003 Lyon ☎ 01 84 16 16 17 - Ligne directe : 0x7B9EE3B0E - Fax : 01 77 72 57 24