Sep 282006
 

I want a module/plugin for Apache 1.3 that will log requests when they arrive. The Apache logs are written after the request has been responded to. What I need is a log entry when the request is made. httpd is core dumping about 10 times a day. I’m trying to find out why. I figure that logging the PID and the request before processing the request will make tracking down the problem fairly simple.

I’m asking for help in finding or writing a small module/plugin/whatever to do this. Thanks.

Website Pin Facebook Twitter Myspace Friendfeed Technorati del.icio.us Digg Google StumbleUpon Premium Responsive

  5 Responses to “WTD: Apache module/plugin to log requests when they arrive”

  1. Can’t you do a post-mortem analysis of a core file? That will lead you directly to the problem. Or, if you fail to persuade Apache to start writing core files, just attach gdb to a running child, and wait for a crash. I used both of these strategies before.

    Or, you can prepend a one liner to all your php scripts, that will log just what you want… I believe your Apache is crashing in mod_php or elsewhere, not in a core httpd code…

  2. Apache is writing the core files.

    The one-liner in the PHP scripts is a very good idea. I’ll try that.

    Thank you.

  3. DOH!

    As I went to code this, I remembered why it won’t work. I was logging the database queries with the PID. The PID being logged was not that of the httpd process. I’m assuming it was that of the PostgreSQL process. Then I thought: well, I should try it anyway. And it works… Here is the code I’m using:

    openlog(‘FRESHPORTS PID’, LOG_PID | LOG_NDELAY, LOG_SYSLOG);
    syslog(LOG_NOTICE, $_SERVER[“REQUEST_URI”]);
    closelog();

    In /var/log/messages, I’m seeing:

    Sep 29 08:29:29 polo FRESHPORTS PID[97197]: /
    Sep 29 08:33:44 polo FRESHPORTS PID[23632]: /

    $ ps auwx | grep 23632
    www 23632 0.0 1.7 14076 8632 ?? S 8:29AM 0:00.03 /usr/local/sbin/httpd -DSSL

    I’ll run this a bit longer in beta before moving it to proproduction. Thanks.

  4. Does anyone see a pattern? ;)

    $ tail -F /var/log/messages | grep “kernel: pid”
    Sep 29 05:57:06 havoc kernel: pid 12570 (httpd), uid 80: exited on signal 6
    ^C
    $ grep 12570 /var/log/messages
    Sep 29 05:54:04 havoc FRESHPORTS PID[12570]: /commits.php
    Sep 29 05:54:27 havoc FRESHPORTS PID[12570]: /search.php?query=trac&search=go&num=10&stype=name&method=match&deleted=excludedeleted&start=11&casesensitivity=caseinsensitive
    Sep 29 05:55:46 havoc FRESHPORTS PID[12570]: /news.php
    Sep 29 05:55:51 havoc FRESHPORTS PID[12570]: /news.php
    Sep 29 05:56:11 havoc FRESHPORTS PID[12570]: /games/crack-attack/
    Sep 29 05:56:20 havoc FRESHPORTS PID[12570]: /ports-deleted.php
    Sep 29 05:57:06 havoc kernel: pid 12570 (httpd), uid 80: exited on signal 6
    $ tail -F /var/log/messages | grep “kernel: pid”

    $ tail -F /var/log/messages | grep “kernel: pid”
    Sep 29 05:57:45 havoc kernel: pid 12564 (httpd), uid 80: exited on signal 6

    $ grep 12564 /var/log/messages
    Sep 29 05:53:57 havoc FRESHPORTS PID[12564]: /science/minc
    Sep 29 05:54:06 havoc FRESHPORTS PID[12564]: /www/mod_dav/
    Sep 29 05:54:09 havoc FRESHPORTS PID[12564]: /news.php
    Sep 29 05:54:36 havoc FRESHPORTS PID[12564]: /rss/
    Sep 29 05:54:40 havoc FRESHPORTS PID[12564]: /news.php
    Sep 29 05:54:59 havoc FRESHPORTS PID[12564]: /search.php?query=tracker&search=go&num=10&stype=name&method=match&deleted=excludedeleted&start=1&casesensitivity=caseinsensitive
    Sep 29 05:55:59 havoc FRESHPORTS PID[12564]: /rss/ports-new.php
    Sep 29 05:56:06 havoc FRESHPORTS PID[12564]: /
    Sep 29 05:56:10 havoc FRESHPORTS PID[12564]: /news.php
    Sep 29 05:56:37 havoc FRESHPORTS PID[12564]: /news.php
    Sep 29 05:56:44 havoc FRESHPORTS PID[12564]: /news.php
    Sep 29 05:56:56 havoc FRESHPORTS PID[12564]: /ports-deleted.php
    Sep 29 05:57:45 havoc kernel: pid 12564 (httpd), uid 80: exited on signal 6

    $ tail -F /var/log/messages | grep “kernel: pid”
    Sep 29 05:58:27 havoc kernel: pid 13440 (httpd), uid 80: exited on signal 6

    $ tail -F /var/log/messages | grep “kernel: pid”
    Sep 29 05:58:27 havoc kernel: pid 13440 (httpd), uid 80: exited on signal 6
    ^C
    $ grep 13440 /var/log/messages
    Sep 29 05:57:43 havoc FRESHPORTS PID[13440]: /security/altivore/files.php?message_id=200405231542.i4NFg832094829@repoman.freebsd.org
    Sep 29 05:57:43 havoc FRESHPORTS PID[13440]: /ports-deleted.php
    Sep 29 05:58:27 havoc kernel: pid 13440 (httpd), uid 80: exited on signal 6

    $ tail -F /var/log/messages | grep “kernel: pid”

    Sep 29 05:59:07 havoc kernel: pid 12919 (httpd), uid 80: exited on signal 6

    $ grep 12919 /var/log/messages
    Sep 29 05:53:55 havoc FRESHPORTS PID[12919]: /
    Sep 29 05:54:14 havoc FRESHPORTS PID[12919]: /net-im/centericq/
    Sep 29 05:54:31 havoc FRESHPORTS PID[12919]: /news.php
    Sep 29 05:54:34 havoc FRESHPORTS PID[12919]: /
    Sep 29 05:55:30 havoc FRESHPORTS PID[12919]: /categories.php
    Sep 29 05:55:41 havoc FRESHPORTS PID[12919]: /
    Sep 29 05:56:16 havoc FRESHPORTS PID[12919]: /www/sarg
    Sep 29 05:56:42 havoc FRESHPORTS PID[12919]: /news.php
    Sep 29 05:57:03 havoc FRESHPORTS PID[12919]: /sysutils/cpuburn/
    Sep 29 05:58:29 havoc FRESHPORTS PID[12919]: /ports-deleted.php
    Sep 29 05:59:07 havoc kernel: pid 12919 (httpd), uid 80: exited on signal 6

  5. The famous ports-deleted.php :)