Bug 61811

Summary: Environment variable for duration of SSL handshake
Product: Apache httpd-2 Reporter: Timo Coutura <timo.coutura>
Component: CoreAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: NEW ---    
Severity: enhancement CC: timo.coutura
Priority: P2    
Version: 2.4.18   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description Timo Coutura 2017-11-24 11:05:23 UTC
More fine grained logging of time spent on different phases of ssl, especially handshake.
Looked in httpd/modules/ssl/ssl_engine_kernel.c line 81:
(https://github.com/apache/httpd/blob/db4506877b6f20c78ee9ca1c12a36320a03dfb1d/modules/ssl/ssl_engine_kernel.c)

SSL_do_handshake(ssl); could be the place to take the time spent?

My mail to mailing list some time ago:

Hi Everyone,

I am looking for a way to determine the time spent on a SSL Handshake in an access log. So far i’ve discovered only env-vars and log formats (like %D) returning the overall time spent on a request. The background here is that i sometimes get requests which take up to 10 seconds, all of them being initial requests, so the handshake has to be done. The actual request to the application gets independently logged and does take some milliseconds.

I have enabled ssl logging on debug level but cannot specifically reproduce these kind of requests and parsing this debug log for time spent for the handshake is not an option on the very busy production server.

Are there any env-vars that provide more specific information on time spent in the different phases of a request?

Thank you very much in advance!

Best regards,
Timo
Comment 1 Timo Coutura 2017-11-28 13:01:55 UTC
To specify what i mean, i will show logs with LogLevel Trace.

Access Log (Notice the timestamp, especially the microseconds)
---------
[27/Nov/2017:18:14:12.634157 +0100] s:0 us:223911 - Token:- RID:RID-b22f9206-6804-434a-b532-36b5c05998e7 POST /SOME/FUNCTION CIP:XXX.XXX.XX.XX I:1327 O:3978 "python-requests/2.9.1" ssl:TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384 - true Initial U:"769217de34af97989944f3b57ddec59b" UI:"769217de34af97989944f3b57ddec59b" SESS:"01464a92-7a93-49ac-ba8f-877739f59ce3" APPV:"Monitor v1" OS:"Monitor os-version 17" D:"some.domain" P:"AND" IV:"6" [pid 28453:tid 139708415854336] k:0 L:AAAAAMCoQAsAAG8ltb4AAAFK


Error Log
---------
Earliest time i got for the corresponding connection to my request:
[Mon Nov 27 18:14:12.580268 2017] [ssl:info] [pid 28453:tid 139708415854336] [client XXX.XXX.XX.XX:XXXXX] AH01964: Connection to child 330 established (server some.domain:port)

HTTP Request Received:  
[Mon Nov 27 18:14:12.634141 2017] [core:trace5] [pid 28453:tid 139708415854336] protocol.c(645): [client XXX.XXX.XX.XX:XXXXX] Request received from client: POST /SOME/FUNCTION?param1=0000015ffe78c8b8d1441cf12
[Mon Nov 27 18:14:12.634212 2017] [setenvif:trace2] [pid 28453:tid 139708415854336] mod_setenvif.c(622): [client XXX.XXX.XX.XX:XXXXX] Setting HAS_REQUEST_ID

---------------
The timestamp seen by %t is:
18:14:12.634157

Connection for that request seems to start at:
18:14:12.580268

But request received states:
18:14:12.634141

As stated in my initial mail, i want to be able to determine the full length of a connection, not just the http request part of it. That way i'd be able, to determine which part of the process causes my problems.

I propose to introduce either (a) new ENV_VAR(s) or an extension of %t for that purpose. This way, i can statistically evaluate the findings and don't have to flood my logs with trace informations.

Please let me know, if there already is a way for this or i did something wrong with reporting. I didnt find any feature request setting, just bug reporting with level enhancement.

Best Regards,
Timo