java jakarta-ee tomcat weblogic tomcat-valve

How to identify URIs of active (long-running) HTTP requests?

Imagine a webapp which (sometimes) takes long time to respond to some HTTP (POST/GET/etc) request - how would You find such a request on server side?

So far I've used tomcat AccessLogValve to see the "completed" requests, but that doesn't let me to see the "in-progress" (stuck) ones :(

For example:

with netstat I'm able to identify long-lived sockets which could give me a count of currently-stuck requests (not URIs though), but HTTP keep-alives invalidate this approach
I could stackdump the app-server (kill -3 <server_pid>) multiple times and guess which threads are running long and reverse-engineer the URIs - not a smart way either
I could inject a router/proxy in front of web-app server (substitute hostnames, clone certs) which would show me the currently-running calls - not a simple approach
I could fall into just running tcpdump continously and parsing the traffic to keep list of currently-running URIs, but what to do with httpS then?
the closest I found is tomcat7's StuckThreadDetectionValve which'd periodically reports long-running calls, but it outputs the stacktrace (not URI) and doesn't provide "live" data (e.g. only polls periodically, floods the logs and lets to see the state of 1-60 seconds ago, but not "now")

Maybe I'm just missing/overlooking one of vital/core/basic tomcat features? or maybe weblogic (or any other app-server) has something robust to offer for this?

I'm kind of lost without such simple and essential feature. Help? Please?

Solution

OK - creation of my own Valve was a proper and easy approach, sharing below. Apache did rework AccessLogValve multiple times, but all revisions follow same concept:

invoke(...) method just uses getNext().invoke(request,response) to invoke a chain of remaining valves and the actual handler/executor
log(...) method is invoked after above is complete

So we only need to:

also invoke log(...) before the getNext().invoke(request,response)
modify log(...) to distinguish "before" and "after" invocations

Easiest way would've been:

@Override
public void invoke(Request request, Response response) throws IOException, ServletException {
    log(request, response, -1); // negative time indicates "before"
    super.invoke(request, response);
}

But tomcat_6.0.16 code wasn't well-extendable, so I prefixed log-messages (in a hard-coded manner) with Thread.getName() and "before"/"after" indicator. Also I preferred to use reflection to access private AccessLogValve.getDate() :

package org.apache.catalina.valves;

import java.io.IOException;
import java.lang.reflect.Method;
import java.util.Date;
import javax.servlet.ServletException;
import org.apache.catalina.connector.Request;
import org.apache.catalina.connector.Response;

public class PreAccessLogValve extends AccessLogValve {
    @Override
    public void invoke(Request request, Response response) throws IOException, ServletException {
        long timeStart = System.currentTimeMillis();
        log(request, response, -timeStart); // negative time indicates "before" request
        getNext().invoke(request, response);
        log(request, response, System.currentTimeMillis() - timeStart); // actual (positive) - "after"
    }

    public void log(Request request, Response response, long time) {
        if (started && getEnabled() && null != logElements && (null == condition || null == request.getRequest().getAttribute(condition))) {
            StringBuffer result = new StringBuffer();
            try {
                Date date = (Date) methodGetDate.invoke(this); 
                for (int i = 0; i < logElements.length; i++) {
                    logElements[i].addElement(result, date, request, response, time);
                }
            } catch (Throwable t) { t.printStackTrace(); }
            log(Thread.currentThread().getName() + (time<0?" > ":" < ") + result.toString());
        }
    }

    private static final Method methodGetDate;
    static {
        Method m = null;
        try {
            m = AccessLogValve.class.getDeclaredMethod("getDate");
            m.setAccessible(true);
        } catch (Throwable t) { t.printStackTrace(); }
        methodGetDate = m;
    }
}

compiled above code with catalina.jar + servlet-api.jar and produced new catalina-my.jar, which was placed into tomcat/lib folder. After that - I've modified server.xml to have:

<Valve className="org.apache.catalina.valves.PreAccessLogValve"
    directory="/tmp" prefix="test." suffix=".txt"
    pattern="%a %t %m %U %s %b %D" resolveHosts="false" buffered="false"/>

Here's the sample output:

http-8007-exec-1 > 10.61.105.105 [18/Jan/2014:05:54:14 +0000] POST /admin/0$en_US/secure/enduser/search.do 200 - -1390024454470
http-8007-exec-5 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/0$en_US/secure/enduser/search.do 200 - -1390024457300
http-8007-exec-5 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/0$en_US/secure/enduser/search.do 200 13933 44
http-8007-exec-3 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/html/main.js 200 - -1390024457490
http-8007-exec-3 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/html/main.js 200 3750 0
http-8007-exec-5 > 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/images/layout/logo.gif 200 - -1390024457497
http-8007-exec-5 < 10.61.105.105 [18/Jan/2014:05:54:17 +0000] GET /admin/images/layout/logo.gif 200 1996 0
http-8007-exec-1 < 10.61.105.105 [18/Jan/2014:05:54:24 +0000] POST /admin/0$en_US/secure/enduser/search.do 200 13308 10209

This way all "in-progress" URIs can be easily retrieved at any moment:

[root@serv1 tomcat]# awk '{if(">"==$2){if($1 in S)print S[$1];S[$1]=$0}else delete S[$1]}END{for(i in S)print S[i]}' test
http-8007-exec-4 > 10.61.105.105 [18/Jan/2014:06:13:20 +0000] GET /admin/images/1x1blank.gif 200 - -13
http-8007-exec-2 > 10.61.105.105 [18/Jan/2014:06:13:16 +0000] POST /admin/servlet/handlersvr 200 - -13