I am not sure what kind of a connection the java client makes, but, I tried
your plugin with chrome and it behaves as expected.
[Mar 4 15:46:42.618] Server {0x2b1e80f0e700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:0, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0[Mar 4 15:46:43.169] Server
{0x2b1e8100f700} DIAG: (atstest) at event:60012, clientReqHdrBytes:2214,
clientReqBdyBytes:0, clientRspHdrBytes:1038, clientRspBdyBytes:79385,
serverReqHdrBytes:2336, serverReqBdyBytes:0, serverRspHdrBytes:967,
serverRspBdyBytes:79385[Mar 4 15:46:43.737] Server {0x2b1e8100f700} DIAG:
(atstest) at event:60012, clientReqHdrBytes:2842, clientReqBdyBytes:0,
clientRspHdrBytes:1329, clientRspBdyBytes:809,
serverReqHdrBytes:2964, serverReqBdyBytes:0, serverRspHdrBytes:1258,
serverRspBdyBytes:809
[Mar 4 15:46:43.884] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:1160,
clientRspBdyBytes:1036, serverReqHdrBytes:3403,
serverReqBdyBytes:0, serverRspHdrBytes:1089, serverRspBdyBytes:1036
[Mar 4 15:46:50.221] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:1038,
clientRspBdyBytes:79836, serverReqHdrBytes:2336,
serverReqBdyBytes:0, serverRspHdrBytes:967, serverRspBdyBytes:79836[Mar 4
15:46:50.777] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:1329,
clientRspBdyBytes:812, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:812
[Mar 4 15:46:50.967] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:1160,
clientRspBdyBytes:1036, serverReqHdrBytes:3403,
serverReqBdyBytes:0, serverRspHdrBytes:1089, serverRspBdyBytes:1036
[Mar 4 15:46:55.745] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:1038,
clientRspBdyBytes:79846, serverReqHdrBytes:2336,
serverReqBdyBytes:0, serverRspHdrBytes:967, serverRspBdyBytes:79846[Mar 4
15:46:56.249] Server {0x2b1e8100f700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:1329,
clientRspBdyBytes:808, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:808
Detailed logs are attached.
From: 毅程 <[email protected]>
To: [email protected]; Alan Carroll
<[email protected]>; Sudheer Vinukonda <[email protected]>;
[email protected]
Sent: Wednesday, March 4, 2015 7:15 AM
Subject: Re: about event hooks for https messages
Hi:
Let me attach 1. simple test plugin:testplugin.c2. client side test
script:ProxyTest.java3. the output: log.txt
>From these, we can seewhen I send 2 http requests: (http://www.ebay.com/), all
>the triggers are invoked for each request, so the sequence is following:60011-
>TS_EVENT_HTTP_TXN_START
60002- TS_EVENT_HTTP_READ_REQUEST_HDR60004-
TS_EVENT_HTTP_SEND_REQUEST_HDR60006- TS_EVENT_HTTP_READ_RESPONSE_HDR60007-
TS_EVENT_HTTP_SEND_RESPONSE_HDR60012- TS_EVENT_HTTP_TXN_CLOSE: here we have the
clientRspBodyBytes: 160167
60011- TS_EVENT_HTTP_TXN_START
60002- TS_EVENT_HTTP_READ_REQUEST_HDR60004-
TS_EVENT_HTTP_SEND_REQUEST_HDR60006- TS_EVENT_HTTP_READ_RESPONSE_HDR60007-
TS_EVENT_HTTP_SEND_RESPONSE_HDR60012- TS_EVENT_HTTP_TXN_CLOSE: here we have the
clientRspBodyBytes: 160167
when I send 2 https requests: (https://www.yahoo.com/), I got only following:
60011- TS_EVENT_HTTP_TXN_START
60002- TS_EVENT_HTTP_READ_REQUEST_HDR60012- TS_EVENT_HTTP_TXN_CLOSE: here we
have the clientRspBodyBytes: 680190 (this contains the size of 2 responses)
What I expected is I can get the same/similar hook callback for https.Please
review the test plugin code, client and log, if this is a problem, shall I open
a jira for this?
Cheng Yi
2015-03-04 6:27 GMT-08:00 Alan Carroll <[email protected]>:
To emphasize James' point, there is no HTTPS engine, there is only the HTTP
state machine. HTTPS simply has a different encoding on the wire, the internals
as far as ATS is concerned are identical and handled by the same code.
What I would suspect is that his HTTPS connections are being blinded tunneled,
not terminated, on ATS.
[Mar 4 15:40:25.563] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
born, netvc 0x2b1eb40185c0
[Mar 4 15:40:25.563] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 1 using sm [38]
[Mar 4 15:40:25.563] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:25.603] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:25.722] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2336, serverReqBdyBytes:0,
serverRspHdrBytes:967, serverRspBdyBytes:0
[Mar 4 15:40:25.723] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2336, serverReqBdyBytes:0,
serverRspHdrBytes:967, serverRspBdyBytes:0
[Mar 4 15:40:25.723] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 0
[Mar 4 15:40:25.723] Server {0x2b1e80908700} DEBUG: (http_cs) desired TCP
congestion window is 0
[Mar 4 15:40:26.079] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [27] as slave
[Mar 4 15:40:26.079] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [38]
[Mar 4 15:40:26.079] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:40:26.079] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:1038,
clientRspBdyBytes:79232, serverReqHdrBytes:2336,
serverReqBdyBytes:0, serverRspHdrBytes:967, serverRspBdyBytes:79232
[Mar 4 15:40:26.431] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
[Mar 4 15:40:26.431] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 2 using sm [39]
[Mar 4 15:40:26.431] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:26.431] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:26.598] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:0
[Mar 4 15:40:26.598] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:0
[Mar 4 15:40:26.599] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 1
[Mar 4 15:40:26.599] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [27] as slave
[Mar 4 15:40:26.599] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [39]
[Mar 4 15:40:26.599] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:40:26.599] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:1329,
clientRspBdyBytes:810, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:810
[Mar 4 15:40:26.659] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
[Mar 4 15:40:26.659] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 3 using sm [40]
[Mar 4 15:40:26.659] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:26.660] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:3403, serverReqBdyBytes:0,
serverRspHdrBytes:1089, serverRspBdyBytes:0
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:3403, serverReqBdyBytes:0,
serverRspHdrBytes:1089, serverRspBdyBytes:0
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 1
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [27] as slave
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [40]
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:40:26.756] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:1160,
clientRspBdyBytes:1036, serverReqHdrBytes:3403,
serverReqBdyBytes:0, serverRspHdrBytes:1089, serverRspBdyBytes:1036
[Mar 4 15:40:42.654] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_slave_keep_alive, VC_EVENT_EOS]
[Mar 4 15:40:45.311] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
[Mar 4 15:40:45.311] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 4 using sm [43]
[Mar 4 15:40:45.311] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:45.312] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:45.432] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2336, serverReqBdyBytes:0,
serverRspHdrBytes:967, serverRspBdyBytes:0
[Mar 4 15:40:45.432] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2336, serverReqBdyBytes:0,
serverRspHdrBytes:967, serverRspBdyBytes:0
[Mar 4 15:40:45.432] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 1
[Mar 4 15:40:45.812] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [30] as slave
[Mar 4 15:40:45.812] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [43]
[Mar 4 15:40:45.812] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:40:45.812] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2214, clientReqBdyBytes:0, clientRspHdrBytes:1038,
clientRspBdyBytes:79605, serverReqHdrBytes:2336,
serverReqBdyBytes:0, serverRspHdrBytes:967, serverRspBdyBytes:79605
[Mar 4 15:40:46.089] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
[Mar 4 15:40:46.089] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 5 using sm [44]
[Mar 4 15:40:46.089] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:46.090] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:40:46.592] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:0
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:0
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 1
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [30] as slave
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [44]
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:40:46.608] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:2842, clientReqBdyBytes:0, clientRspHdrBytes:1329,
clientRspBdyBytes:808, serverReqHdrBytes:2964, serverReqBdyBytes:0,
serverRspHdrBytes:1258, serverRspBdyBytes:808
[Mar 4 15:41:01.809] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_slave_keep_alive, VC_EVENT_EOS]
[Mar 4 15:41:15.321] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_READ_READY]
[Mar 4 15:41:15.321] Server {0x2b1e80908700} DEBUG: (http_cs) [31] Starting
transaction 6 using sm [52]
[Mar 4 15:41:15.322] Server {0x2b1e80908700} DIAG: (atstest) at event:60002,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:41:15.322] Server {0x2b1e80908700} DIAG: (atstest) at event:60004,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:0, serverReqBdyBytes:0,
serverRspHdrBytes:0, serverRspBdyBytes:0
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DIAG: (atstest) at event:60006,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:3403, serverReqBdyBytes:0,
serverRspHdrBytes:1089, serverRspBdyBytes:0
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DIAG: (atstest) at event:60007,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:0,
clientRspBdyBytes:0, serverReqHdrBytes:3403, serverReqBdyBytes:0,
serverRspHdrBytes:1089, serverRspBdyBytes:0
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DEBUG: (http_cs)
tcp_init_cwnd_set 1
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DEBUG: (http_cs) [31] attaching
server session [36] as slave
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
released by sm [52]
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DEBUG: (http_cs) [31] initiating
io for next header
[Mar 4 15:41:15.441] Server {0x2b1e80908700} DIAG: (atstest) at event:60012,
clientReqHdrBytes:3281, clientReqBdyBytes:0, clientRspHdrBytes:1160,
clientRspBdyBytes:1036, serverReqHdrBytes:3403,
serverReqBdyBytes:0, serverRspHdrBytes:1089, serverRspBdyBytes:1036
[Mar 4 15:41:30.630] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_slave_keep_alive, VC_EVENT_EOS]
[Mar 4 15:41:45.981] Server {0x2b1e80908700} DEBUG: (http_cs) [31]
[&HttpClientSession::state_keep_alive, VC_EVENT_INACTIVITY_TIMEOUT]
[Mar 4 15:41:45.981] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
closed
[Mar 4 15:41:45.981] Server {0x2b1e80908700} DEBUG: (http_cs) [31] session
destroy
