trafficserver-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From jhasle <jhan...@de.ibm.com>
Subject Re: Problems with caching / retrieving from cache from a particular origin
Date Tue, 01 Mar 2016 18:33:06 GMT
Ok this is a bit much, but it should cover the logs of two requests to the
problematic source. First a request directly after server restart, so of
course it is not in the cache. The second is directly afterwards, so it
could be retrieved from cache. Sorry I had to anynomize data the urls, its
etc.:


I think the problem is here. Probably an authentication issue:


[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2433
(CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3997
(do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858970,
highest_delta: 0, cluster: 1456858970
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
xxxHostIPxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1799
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
HandleCacheOpenReadHit
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2572
(HandleCacheOpenReadHit)> (http_seq) [HttpTransact::HandleCacheOpenReadHit]
Authentication needed
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3059
(HandleCacheOpenReadMiss)> (http_trans) [HandleCacheOpenReadMiss] --- MISS
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3061
(HandleCacheOpenReadMiss)> (http_seq)
[HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 192.168.99.1'
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5209
(add_client_ip_to_outgoing_request)> (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's
(192.168.99.1) to the X-Forwards header
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url


But here is a fuller excerpt:

+++++++++ Incoming Request +++++++++
-- State Machine Id: 1
GET https://xxxHostxxx/xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*

[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1903
(DecideCacheLookup)> (http_trans) [DecideCacheLookup] Will do cache lookup.
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1904
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will do cache lookup
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1947
(DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; __null
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4403
(do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read]
[1] Issuing cache lookup for URL https://xxxHostxxx/xxxApiParamsxxx
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <Cache.cc:3121
(key_to_vol)> (cache_hosting) Generic volume: 1b0ed18d for host: xxxHostxxx
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpCacheSM.cc:102
(state_cache_open_read)> (http_cache) [1]
[&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler,
CACHE_EVENT_OPEN_READ_FAILED]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2473
(state_cache_open_read)> (http) [1] [&HttpSM::state_cache_open_read,
CACHE_EVENT_OPEN_READ_FAILED]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2508
(state_cache_open_read)> (http) [1] cache_open_read -
CACHE_EVENT_OPEN_READ_FAILED
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2509
(state_cache_open_read)> (http) [state_cache_open_read] open read failed.
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1] calling plugin on hook
TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK at hook 0x1ae1f60
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2161
(HandleCacheOpenRead)> (http_trans) [HttpTransact::HandleCacheOpenRead]
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2191
(HandleCacheOpenRead)> (http_trans) CacheOpenRead -- miss
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2198
(HandleCacheOpenRead)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_CACHE_LOOKUP -> SM_ACTION_DNS_LOOKUP
[Mar  1 19:02:47.332] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3997
(do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <DNS.cc:1096 (getby)>
(dns) received query xxxHostxxx type = 1, timeout = 0
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <DNS.cc:1062
(mainEvent)> (dns) enqueing query xxxHostxxx
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <DNS.cc:1068
(mainEvent)> (dns) adding first to collapsing queue
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <DNS.cc:982
(write_dns_event)> (dns) send query (qtype=1) for xxxHostxxx to fd 28
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <DNS.cc:1014
(write_dns_event)> (dns) sent qname = xxxHostxxx, id = 60141, nameserver = 0
[Mar  1 19:02:47.347] Server {0x2b4950510440} DEBUG: <P_DNSProcessor.h:229
(sent_one)> (dns) sent_one: failover_number for resolver 0 is 1
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:762 (recv_dns)>
(dns) received packet size = 57
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:764 (recv_dns)>
(dns) round-robin: nameserver 0 DNS response code = 0
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:1555
(dns_process)> (dns) received A name = xxxHostxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:1572
(dns_process)> (dns) received A = xxxHostIPxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:1185
(dns_result)> (dns) SUCCESS result for xxxHostxxx = xxxHostIPxxx retry 0
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <DNS.cc:1273
(postEvent)> (dns) called back continuation for xxxHostxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, EVENT_HOST_DB_LOOKUP]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2115
(state_hostdb_lookup)> (http) [1] [&HttpSM::state_hostdb_lookup,
EVENT_HOST_DB_LOOKUP]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858967,
highest_delta: 0, cluster: 1456858967
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
xxxHostIPxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1801
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
HandleCacheOpenReadMiss
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3059
(HandleCacheOpenReadMiss)> (http_trans) [HandleCacheOpenReadMiss] --- MISS
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3061
(HandleCacheOpenReadMiss)> (http_seq)
[HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 192.168.99.1'
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5209
(add_client_ip_to_outgoing_request)> (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's
(192.168.99.1) to the X-Forwards header
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7821
(build_request)> (http_trans) [build_request] request not like cacheable and
conditional headers not removed
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858967,
highest_delta: 0, cluster: 1456858967
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7836
(build_request)> (http_trans) [build_request] request_sent_time: 1456858967
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 1
GET /xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1
Via: http/1.1 e06f5a03fe1f[AC110002] (ApacheTrafficServer/6.1.1 [uScMs f p
eN:t cCMi p s ])

[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4530
(do_cache_prepare_action)> (http_cache_write) [1] writing to cache with URL
https://xxxHostxxx/xxxApiParamsxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:555
(new_CacheVC)> (cache_new) new 0x1dccbb0
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <Cache.cc:3121
(key_to_vol)> (cache_hosting) Generic volume: 1b0ed18d for host: xxxHostxxx
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpCacheSM.cc:161
(state_cache_open_write)> (http_cache) [1]
[&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2363
(state_cache_open_write)> (http) [1] [&HttpSM : state_cache_open_write,
CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3025
(handle_cache_write_lock)> (http_trans) Next action next; __null
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_CACHE_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4555
(do_http_server_open)> (http_track) entered inside do_http_server_open
][IPv4]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4575
(do_http_server_open)> (http) [1] open connection to xxxHostxxx:
xxxHostIPxxx:443
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4587
(do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending
request to server
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4630
(do_http_server_open)> (http_ss_auth) Setting server session to private for
authorization header
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4793
(do_http_server_open)> (http) calling sslNetProcessor.connect_re
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, NET_EVENT_OPEN]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1618
(state_http_server_open)> (http_track) entered inside state_http_server_open
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1619
(state_http_server_open)> (http) [1] [&HttpSM::state_http_server_open,
NET_EVENT_OPEN]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:91 (new_connection)> (http_ss) [1] session born, netvc
0x1defb70
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:5726
(attach_server_session)> (http_ss) Setting server session to private
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1] calling plugin on hook
TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x1ae1f80
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:47.406] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 1
GET /xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1
Via: http/1.1 e06f5a03fe1f[AC110002] (ApacheTrafficServer/6.1.1 [uScMs f p
eN:t cCMi p s ])

[Mar  1 19:02:47.844] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:47.844] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1881
(state_send_server_request_header)> (http) [1]
[&HttpSM::state_send_server_request_header, VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:47.844] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1962
(state_send_server_request_header)> (http_ss) read complete due to 0 byte
do_io_read
[Mar  1 19:02:47.844] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:47.844] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1881
(state_send_server_request_header)> (http) [1]
[&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1712
(state_read_server_response_header)> (http) [1]
[&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1825
(state_read_server_response_header)> (http_seq) Done parsing server response
header
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1] calling plugin on hook
TS_HTTP_READ_RESPONSE_HDR_HOOK at hook 0x1ae1fe0
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [1] calling plugin on hook
TS_HTTP_READ_RESPONSE_HDR_HOOK at hook 0x1ae1fa0
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [1] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [1] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3296
(HandleResponse)> (http_trans) [HttpTransact::HandleResponse]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3297
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response
received
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858968,
highest_delta: 0, cluster: 1456858968
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3304
(HandleResponse)> (http_trans) [HandleResponse] response_received_time:
1456858968
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
Connection: Keep-Alive
Transfer-Encoding: chunked
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:47 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72

[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6458
(is_response_valid)> (http_trans) [is_response_valid] No errors in response
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3322
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response valid
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5711
(initialize_state_variables_from_response)> (http_hdrs)
[initialize_state_variables_from_response]Server is keep-alive.
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5752
(initialize_state_variables_from_response)> (http_hdrs)
[init_state_vars_from_resp] transfer encoding: chunked!
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3631
(handle_response_from_server)> (http_trans) [handle_response_from_server]
(hrfs)
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3643
(handle_response_from_server)> (http_trans) [hrfs] connection alive
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3910
(handle_forward_server_connection_open)> (http_trans)
[handle_forward_server_connection_open] (hfsco)
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3911
(handle_forward_server_connection_open)> (http_seq)
[HttpTransact::handle_server_connection_open] 
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4112
(do_hostdb_update_if_necessary)> (http) server info = xxxHostIPxxx:443
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3996
(handle_forward_server_connection_open)> (http_trans) [hfsco] cache action:
CACHE_DO_WRITE
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4116
(handle_cache_operation_on_forward_server_response)> (http_trans)
[handle_cache_operation_on_forward_server_response] (hcoofsr)
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4117
(handle_cache_operation_on_forward_server_response)> (http_seq)
[handle_cache_operation_on_forward_server_response]
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6154
(is_response_cacheable)> (http_trans) [is_response_cacheable] client permits
storing
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6266
(is_response_cacheable)> (http_trans) [is_response_cacheable] YES by default 
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4126
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
response is cacheable
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4268
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
response code: 200
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4457
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
cache write
+++++++++ Cached Request Hdr +++++++++
-- State Machine Id: 1
GET https://xxxHostxxx/xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1

[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:424 (calculate_document_age)> (http_age)
[calculate_document_age] age_value:              0
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:425 (calculate_document_age)> (http_age)
[calculate_document_age] date_value:             1456858967
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:426 (calculate_document_age)> (http_age)
[calculate_document_age] response_time:          1456858968
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:427 (calculate_document_age)> (http_age)
[calculate_document_age] now:                    1456858968
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:428 (calculate_document_age)> (http_age)
[calculate_document_age] now (fixed):            1456858968
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:429 (calculate_document_age)> (http_age)
[calculate_document_age] apparent_age:           1
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:430 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_received_age: 1
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:431 (calculate_document_age)> (http_age)
[calculate_document_age] response_delay:         1
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:432 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_initial_age:  2
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:433 (calculate_document_age)> (http_age)
[calculate_document_age] resident_time:          0
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:434 (calculate_document_age)> (http_age)
[calculate_document_age] current_age:            2
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:629 (generate_and_set_squid_codes)> (http_trans)
[Squid code generation] Hit/Miss: 1, Log: 3, Hier: 2
[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:979 (add_server_header_to_response)> (http_trans)
Adding Server: ATS/6.1.1
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
Connection: Keep-Alive
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:47 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72

+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:47 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72
Age: 2
Transfer-Encoding: chunked
Connection: keep-alive
Via: https/1.1 e06f5a03fe1f (ApacheTrafficServer/6.1.1 [uScMsSfWpSeN:t cCMi
p sS])
Server: ATS/6.1.1

[Mar  1 19:02:48.184] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [1] State Transition:
SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpSM.cc:7709
(is_redirect_required)> (http_redirect) is_redirect_required 0
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpSM.cc:7403
(do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6294
(setup_server_transfer)> (http) Setup Server Transfer
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:629
(add_producer)> (http_tunnel) [1] adding producer 'http server'
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:684
(add_consumer)> (http_tunnel) [1] adding consumer 'user agent'
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpSM.cc:5507
(perform_cache_write_action)> (http) [1] perform_cache_write_action
CACHE_DO_WRITE
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:684
(add_consumer)> (http_tunnel) [1] adding consumer 'cache write'
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:730
(tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:818
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.chunked_reader->read_avail() = 420
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:828
(producer_run)> (http_tunnel) [producer_run] do_dechunking::Copied header of
size 420
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:236 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:249 (set_tcp_init_cwnd)> (http_cs) desired TCP
congestion window is 0
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:956
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.chunked_reader->read_avail() = 420
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:960
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.skip_bytes = 420
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.185] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 4050 bytes
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:262
(read_chunk)> (http_chunk) completed read of chunk of 4050 bytes
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:48.187] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.188] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 453 bytes
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:262
(read_chunk)> (http_chunk) completed read of chunk of 453 bytes
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.189] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [1] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [1] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 0 bytes
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:295
(read_trailer)> (http_chunk) completed read of trailers
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 102
[Mar  1 19:02:48.325] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2855
(tunnel_handler_server)> (http) [1] [&HttpSM::tunnel_handler_server,
VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [cache write
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3302
(tunnel_handler_cache_write)> (http) [1]
[&HttpSM::tunnel_handler_cache_write, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:567
(free_CacheVC)> (cache_free) free 0x1dccbb0
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:163 (release)> (http_ss) Releasing session,
private_session=1, sharing_match=1
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:121 (do_io_close)> (http_ss) [1] session closing,
netvc 0x1defb70
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [1] consumer_handler [user agent
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3095
(tunnel_handler_ua)> (http) [1] [&HttpSM::tunnel_handler_ua,
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:498 (release)> (http_cs) [1] session released by sm
[1]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:236 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:527 (release)> (http_cs) [1] initiating io for next
header
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [1] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2794
(tunnel_handler)> (http) [1] [&HttpSM::tunnel_handler,
HTTP_TUNNEL_EVENT_DONE]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8975
(add_new_stat_block)> (http_trans) Adding new large stat block
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6639
(kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Mar  1 19:02:48.326] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6666
(kill_this)> (http) [1] deallocating sm
[Mar  1 19:02:48.327] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:409 (state_keep_alive)> (http_cs) [1]
[&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Mar  1 19:02:48.327] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:325 (do_io_close)> (http_cs) [1] session closed
[Mar  1 19:02:48.327] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:73 (destroy)> (http_cs) [1] session destroy
[Mar  1 19:02:50.663] Server {0x2b4950510440} DEBUG:
<ProtocolProbeSessionAccept.cc:161 (mainEvent)> (http) probe needs data,
read..
[Mar  1 19:02:50.663] Server {0x2b4950510440} DEBUG:
<HttpSessionAccept.cc:60 (accept)> (http_seq) [HttpSessionAccept:mainEvent
0x2b4968017d20] accepted connection from 192.168.99.1:49293 transport type =
1
[Mar  1 19:02:50.663] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:201 (new_connection)> (http_cs) [2] session born,
netvc 0x2b4968017d20
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:139 (new_transaction)> (http_cs) [2] Starting
transaction 1 using sm [2]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [2]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:724
(state_read_client_request_header)> (http) [2] done parsing client request
header
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1066
(ModifyRequest)> (http_trans) START HttpTransact::ModifyRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858970,
highest_delta: 0, cluster: 1456858970
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1157
(ModifyRequest)> (http_trans) END HttpTransact::ModifyRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1159
(ModifyRequest)> (http_trans) Checking if transaction wants to upgrade
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1166
(ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR;
HttpTransact::StartRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [2] calling plugin on hook
TS_HTTP_READ_REQUEST_HDR_HOOK at hook 0x1ae1fc0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [2] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [2] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:693
(StartRemapRequest)> (http_trans) START HttpTransact::StartRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:734
(StartRemapRequest)> (http_trans) Before Remapping:
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb9888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2b4953fb9b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb98b8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb9b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "", HOST_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "cde/tcde-api-v1/api/tweets/search", PATH_LEN:
33,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY:
"q=posted:2016-02-10T00:00:00Z,2016-02-13T00:00:00Z%20%23iphone%20sort:posted,desc&from=0&size=1",
QUERY_LEN: 95,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb98b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0008000001000081, SLACC: 0xFF1FFFF3FFFFFFFFFFFFFFFFFFF2FFFF,
HEADBLK: 0x2b4953fb98f8, TAILBLK: 0x2b4953fb98f8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb98f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 4, NEXTBLK: (nil)]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb9908), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "192.168.99.100:8080", V_LEN: 19, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 27, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 1 (0x2b4953fb9928), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Authorization", N_LEN: 13, N_IDX:
8, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "Basic xxxAuthxxx", V_LEN: 50, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 67, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 2 (0x2b4953fb9948), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "curl/7.43.0", V_LEN: 11, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 3 (0x2b4953fb9968), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:746
(StartRemapRequest)> (http_trans) END HttpTransact::StartRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:747
(StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP;
HttpTransact::PerformRemap
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:753
(PerformRemap)> (http_trans) Inside PerformRemap
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:754
(PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST;
HttpTransact::EndRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3902
(do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:760
(EndRemapRequest)> (http_trans) START HttpTransact::EndRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:766
(EndRemapRequest)> (http_trans) EndRemapRequest host is xxxHostxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:878
(EndRemapRequest)> (http_trans) After Remapping:
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb9888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2b4953fb9b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb98b8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb9b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 2, SWKSIDX: 98,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "https", SCHEME_LEN: 5,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "xxxHostxxx", HOST_LEN: 23,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "tcde-api-v1/api/tweets/search", PATH_LEN: 29,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY:
"q=posted:2016-02-10T00:00:00Z,2016-02-13T00:00:00Z%20%23iphone%20sort:posted,desc&from=0&size=1",
QUERY_LEN: 95,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb98b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0008000001000081, SLACC: 0xFF1FFFF3FFFFFFFFFFFFFFFFFFF2FFFF,
HEADBLK: 0x2b4953fb98f8, TAILBLK: 0x2b4953fb98f8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb98f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 4, NEXTBLK: (nil)]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb9908), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "xxxHostxxx", V_LEN: 23, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 31, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 1 (0x2b4953fb9928), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Authorization", N_LEN: 13, N_IDX:
8, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "Basic xxxAuthxxx", V_LEN: 50, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 67, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 2 (0x2b4953fb9948), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "curl/7.43.0", V_LEN: 11, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 3 (0x2b4953fb9968), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:896
(EndRemapRequest)> (http_trans) END HttpTransact::EndRemapRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:902
(EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP;
HttpTransact::HandleRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1203
(HandleRequest)> (http_trans) START HttpTransact::HandleRequest
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5278
(check_request_validity)> (http_trans) [init_stat_vars_from_req] set req
cont length to 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6315
(is_request_valid)> (http_trans) [is_request_valid]no request header errors
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1224
(HandleRequest)> (http_seq) [HttpTransact::HandleRequest] request valid.
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb9888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x2b4953fb9b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb98b8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb9b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 2, SWKSIDX: 98,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "https", SCHEME_LEN: 5,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "xxxHostxxx", HOST_LEN: 23,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "tcde-api-v1/api/tweets/search", PATH_LEN: 29,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY:
"q=posted:2016-02-10T00:00:00Z,2016-02-13T00:00:00Z%20%23iphone%20sort:posted,desc&from=0&size=1",
QUERY_LEN: 95,
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb98b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0008000001000081, SLACC: 0xFF1FFFF3FFFFFFFFFFFFFFFFFFF2FFFF,
HEADBLK: 0x2b4953fb98f8, TAILBLK: 0x2b4953fb98f8]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb98f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 4, NEXTBLK: (nil)]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb9908), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "xxxHostxxx", V_LEN: 23, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 31, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 1 (0x2b4953fb9928), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Authorization", N_LEN: 13, N_IDX:
8, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "Basic xxxAuthxxx", V_LEN: 50, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 67, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 2 (0x2b4953fb9948), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "curl/7.43.0", V_LEN: 11, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 3 (0x2b4953fb9968), LIVE    
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F:
1]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <CacheControl.cc:466
(UpdateMatch)> (cache_control) Matched with for TTL_IN_CACHE at line 55
[cache-responses-to-cookies=1]
+++++++++ Incoming Request +++++++++
-- State Machine Id: 2
GET https://xxxHostxxx/xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*

[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1903
(DecideCacheLookup)> (http_trans) [DecideCacheLookup] Will do cache lookup.
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1904
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will do cache lookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1947
(DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; __null
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4403
(do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read]
[2] Issuing cache lookup for URL https://xxxHostxxx/xxxApiParamsxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <Cache.cc:3121
(key_to_vol)> (cache_hosting) Generic volume: 1b0ed18d for host: xxxHostxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:555
(new_CacheVC)> (cache_new) new 0x1dccbb0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <Cache.cc:2383
(handleReadDone)> (cache_read) Read complete on fragment
6B3404B8A2129E72476A3BC094FF93E4. Length: data payload=4503 this
fragment=7919 total doc=4503 prefix=3416
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:183 (SelectFromAlternates)> (http_match)
[SelectFromAlternates] # alternates = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:184 (SelectFromAlternates)> (http_seq)
[SelectFromAlternates] 1 alternates for this cached doc
[alts] There are 1 alternates for this request header.
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:407 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: Accept match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:408 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: Accept match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:409 (calculate_quality_of_match)> (http_alternate)
Content-Type and Accept 1.000000
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:411 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: AcceptCharset match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:412 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: AcceptCharset match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:413 (calculate_quality_of_match)> (http_alternate)
Content-Type and Accept-Charset 1.000000
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:415 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: AcceptEncoding match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:416 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: AcceptEncoding match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:417 (calculate_quality_of_match)> (http_alternate)
Content-Encoding and Accept-Encoding 1.000000
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:419 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: AcceptLanguage match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:420 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: AcceptLanguage match = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:421 (calculate_quality_of_match)> (http_alternate)
Content-Language and Accept-Language 1.000000
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:423 (calculate_quality_of_match)> (http_alternate)
Mult's Quality Factor: 1.000000
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:424 (calculate_quality_of_match)> (http_alternate)
----------End of Alternate----------
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:471 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: CalcVariability says variability = 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:472 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: CalcVariability says variability = 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:473 (calculate_quality_of_match)> (http_match)    
CalcQualityOfMatch: Returning final Q = 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:474 (calculate_quality_of_match)> (http_seq)    
CalcQualityOfMatch: Returning final Q = 1
[alts] ---- alternate #1 (Q = 1) has these request/response hdrs:
GET https://xxxHostxxx/xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1

HTTP/1.1 200 OK
X-Backside-Transport: OK OK
Connection: Keep-Alive
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:47 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72

[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG:
<HttpTransactCache.cc:262 (SelectFromAlternates)> (http_seq)
[SelectFromAlternates] Chosen alternate # 0
[alts] and the winner is alternate number 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <CacheRead.cc:1104
(openReadStartHead)> (cache_read) CacheReadStartHead - read
6B3404B8A2129E72476A3BC094FF93E4 target C436FC1916840E23B96CD80510BC57B8 -
single 7919 of 4503 bytes, 0 fragments
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpCacheSM.cc:102
(state_cache_open_read)> (http_cache) [2]
[&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2473
(state_cache_open_read)> (http) [2] [&HttpSM::state_cache_open_read,
CACHE_EVENT_OPEN_READ]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2483
(state_cache_open_read)> (http) [2] cache_open_read - CACHE_EVENT_OPEN_READ
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2161
(HandleCacheOpenRead)> (http_trans) [HttpTransact::HandleCacheOpenRead]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2202
(HandleCacheOpenRead)> (http_trans) CacheOpenRead -- hit
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2203
(HandleCacheOpenRead)> (http_trans) Next action
SM_ACTION_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_CACHE_LOOKUP -> SM_ACTION_API_READ_CACHE_HDR
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2355
(HandleCacheOpenReadHitFreshness)> (http_seq)
[HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2377
(HandleCacheOpenReadHitFreshness)> (http_trans)
[HandleCacheOpenReadHitFreshness] request_sent_time      : 1456858967
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2378
(HandleCacheOpenReadHitFreshness)> (http_trans)
[HandleCacheOpenReadHitFreshness] response_received_time : 1456858968
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7329
(what_is_document_freshness)> (http_match) [..._document_freshness]
ttl-in-cache = 31536000, resident time = 2
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2388
(HandleCacheOpenReadHitFreshness)> (http_seq)
[HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2476
(need_to_revalidate)> (http_seq) [HttpTransact::HandleCacheOpenReadHit]
Authentication needed
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2415
(HandleCacheOpenReadHitFreshness)> (http_trans) Next action
SM_ACTION_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_READ_CACHE_HDR -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [2] calling plugin on hook
TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK at hook 0x1ae1f60
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [2] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [2] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2433
(CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3997
(do_hostdb_lookup)> (http_seq) [HttpSM::do_hostdb_lookup] Doing DNS Lookup
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858970,
highest_delta: 0, cluster: 1456858970
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
xxxHostIPxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1799
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
HandleCacheOpenReadHit
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2572
(HandleCacheOpenReadHit)> (http_seq) [HttpTransact::HandleCacheOpenReadHit]
Authentication needed
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3059
(HandleCacheOpenReadMiss)> (http_trans) [HandleCacheOpenReadMiss] --- MISS
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3061
(HandleCacheOpenReadMiss)> (http_seq)
[HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 192.168.99.1'
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5209
(add_client_ip_to_outgoing_request)> (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's
(192.168.99.1) to the X-Forwards header
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7821
(build_request)> (http_trans) [build_request] request not like cacheable and
conditional headers not removed
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858970,
highest_delta: 0, cluster: 1456858970
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7836
(build_request)> (http_trans) [build_request] request_sent_time: 1456858970
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 2
GET /xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1
Via: http/1.1 e06f5a03fe1f[AC110002] (ApacheTrafficServer/6.1.1 [uScMs f p
eN:t cCMi p s ])

[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4530
(do_cache_prepare_action)> (http_cache_write) [2] writing to cache with URL
https://xxxHostxxx/xxxApiParamsxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:555
(new_CacheVC)> (cache_new) new 0x1dcc800
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <Cache.cc:3121
(key_to_vol)> (cache_hosting) Generic volume: 1b0ed18d for host: xxxHostxxx
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpCacheSM.cc:161
(state_cache_open_write)> (http_cache) [2]
[&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2363
(state_cache_open_write)> (http) [2] [&HttpSM : state_cache_open_write,
CACHE_EVENT_OPEN_WRITE]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3025
(handle_cache_write_lock)> (http_trans) Next action next; __null
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_CACHE_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4555
(do_http_server_open)> (http_track) entered inside do_http_server_open
][IPv4]
[Mar  1 19:02:50.664] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4575
(do_http_server_open)> (http) [2] open connection to xxxHostxxx:
xxxHostIPxxx:443
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4587
(do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending
request to server
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4630
(do_http_server_open)> (http_ss_auth) Setting server session to private for
authorization header
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4793
(do_http_server_open)> (http) calling sslNetProcessor.connect_re
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, NET_EVENT_OPEN]
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1618
(state_http_server_open)> (http_track) entered inside state_http_server_open
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1619
(state_http_server_open)> (http) [2] [&HttpSM::state_http_server_open,
NET_EVENT_OPEN]
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:91 (new_connection)> (http_ss) [2] session born, netvc
0x1defb70
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:5726
(attach_server_session)> (http_ss) Setting server session to private
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [2] calling plugin on hook
TS_HTTP_SEND_REQUEST_HDR_HOOK at hook 0x1ae1f80
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [2] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:50.665] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [2] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 2
GET /xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1
Via: http/1.1 e06f5a03fe1f[AC110002] (ApacheTrafficServer/6.1.1 [uScMs f p
eN:t cCMi p s ])

[Mar  1 19:02:51.140] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:51.140] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1881
(state_send_server_request_header)> (http) [2]
[&HttpSM::state_send_server_request_header, VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:51.140] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1962
(state_send_server_request_header)> (http_ss) read complete due to 0 byte
do_io_read
[Mar  1 19:02:51.140] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.140] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1881
(state_send_server_request_header)> (http) [2]
[&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1712
(state_read_server_response_header)> (http) [2]
[&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1825
(state_read_server_response_header)> (http_seq) Done parsing server response
header
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [2] calling plugin on hook
TS_HTTP_READ_RESPONSE_HDR_HOOK at hook 0x1ae1fe0
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [2] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [2] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1376
(state_api_callout)> (http) [2] calling plugin on hook
TS_HTTP_READ_RESPONSE_HDR_HOOK at hook 0x1ae1fa0
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1271
(state_api_callback)> (http) [2] [&HttpSM::state_api_callback,
HTTP_API_CONTINUE]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1311
(state_api_callout)> (http) [2] [&HttpSM::state_api_callout,
HTTP_API_CONTINUE]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3296
(HandleResponse)> (http_trans) [HttpTransact::HandleResponse]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3297
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response
received
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858971,
highest_delta: 0, cluster: 1456858971
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3304
(HandleResponse)> (http_trans) [HandleResponse] response_received_time:
1456858971
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 2
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
Connection: Keep-Alive
Transfer-Encoding: chunked
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:50 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72

[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6458
(is_response_valid)> (http_trans) [is_response_valid] No errors in response
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3322
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response valid
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5711
(initialize_state_variables_from_response)> (http_hdrs)
[initialize_state_variables_from_response]Server is keep-alive.
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5752
(initialize_state_variables_from_response)> (http_hdrs)
[init_state_vars_from_resp] transfer encoding: chunked!
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3631
(handle_response_from_server)> (http_trans) [handle_response_from_server]
(hrfs)
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3643
(handle_response_from_server)> (http_trans) [hrfs] connection alive
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3910
(handle_forward_server_connection_open)> (http_trans)
[handle_forward_server_connection_open] (hfsco)
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3911
(handle_forward_server_connection_open)> (http_seq)
[HttpTransact::handle_server_connection_open] 
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4112
(do_hostdb_update_if_necessary)> (http) server info = xxxHostIPxxx:443
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:3996
(handle_forward_server_connection_open)> (http_trans) [hfsco] cache action:
CACHE_DO_WRITE
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4116
(handle_cache_operation_on_forward_server_response)> (http_trans)
[handle_cache_operation_on_forward_server_response] (hcoofsr)
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4117
(handle_cache_operation_on_forward_server_response)> (http_seq)
[handle_cache_operation_on_forward_server_response]
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6154
(is_response_cacheable)> (http_trans) [is_response_cacheable] client permits
storing
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6266
(is_response_cacheable)> (http_trans) [is_response_cacheable] YES by default 
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4126
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
response is cacheable
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4268
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
response code: 200
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:4457
(handle_cache_operation_on_forward_server_response)> (http_trans) [hcoofsr]
cache write
+++++++++ Cached Request Hdr +++++++++
-- State Machine Id: 2
GET https://xxxHostxxx/xxxApiParamsxxx HTTP/1.1
Host: xxxHostxxx
Authorization: Basic xxxAuthxxx
User-Agent: curl/7.43.0
Accept: */*
Client-ip: 192.168.99.1
X-Forwarded-For: 192.168.99.1

[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:424 (calculate_document_age)> (http_age)
[calculate_document_age] age_value:              0
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:425 (calculate_document_age)> (http_age)
[calculate_document_age] date_value:             1456858970
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:426 (calculate_document_age)> (http_age)
[calculate_document_age] response_time:          1456858971
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:427 (calculate_document_age)> (http_age)
[calculate_document_age] now:                    1456858971
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:428 (calculate_document_age)> (http_age)
[calculate_document_age] now (fixed):            1456858971
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:429 (calculate_document_age)> (http_age)
[calculate_document_age] apparent_age:           1
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:430 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_received_age: 1
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:431 (calculate_document_age)> (http_age)
[calculate_document_age] response_delay:         1
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:432 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_initial_age:  2
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:433 (calculate_document_age)> (http_age)
[calculate_document_age] resident_time:          0
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:434 (calculate_document_age)> (http_age)
[calculate_document_age] current_age:            2
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:629 (generate_and_set_squid_codes)> (http_trans)
[Squid code generation] Hit/Miss: 1, Log: 3, Hier: 2
[Mar  1 19:02:51.483] Server {0x2b4950510440} DEBUG:
<HttpTransactHeaders.cc:979 (add_server_header_to_response)> (http_trans)
Adding Server: ATS/6.1.1
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 2
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
Connection: Keep-Alive
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:50 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72

+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 2
HTTP/1.1 200 OK
X-Backside-Transport: OK OK
X-Powered-By: Servlet/3.0
Content-Type: application/json;charset=UTF-8
X-Cde-Batch-Size: 1
Date: Tue, 01 Mar 2016 19:02:50 GMT
Cache-Control: no-cache="set-cookie, set-cookie2"
X-Client-IP: 92.74.171.72
Age: 2
Transfer-Encoding: chunked
Connection: keep-alive
Via: https/1.1 e06f5a03fe1f (ApacheTrafficServer/6.1.1 [uScMsSfWpSeN:t cCMi
p sS])
Server: ATS/6.1.1

[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [2] State Transition:
SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpSM.cc:7709
(is_redirect_required)> (http_redirect) is_redirect_required 0
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpSM.cc:7403
(do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6294
(setup_server_transfer)> (http) Setup Server Transfer
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:629
(add_producer)> (http_tunnel) [2] adding producer 'http server'
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:684
(add_consumer)> (http_tunnel) [2] adding consumer 'user agent'
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpSM.cc:5507
(perform_cache_write_action)> (http) [2] perform_cache_write_action
CACHE_DO_WRITE
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:567
(free_CacheVC)> (cache_free) free 0x1dccbb0
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:684
(add_consumer)> (http_tunnel) [2] adding consumer 'cache write'
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:730
(tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:818
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.chunked_reader->read_avail() = 420
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:828
(producer_run)> (http_tunnel) [producer_run] do_dechunking::Copied header of
size 420
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:236 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:249 (set_tcp_init_cwnd)> (http_cs) desired TCP
congestion window is 0
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:956
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.chunked_reader->read_avail() = 420
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:960
(producer_run)> (http_tunnel) [producer_run] do_dechunking
p->chunked_handler.skip_bytes = 420
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [2] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [2] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.484] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [2] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [2] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 4050 bytes
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:262
(read_chunk)> (http_chunk) completed read of chunk of 4050 bytes
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.486] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [2] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [2] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [2] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [2] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 453 bytes
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:262
(read_chunk)> (http_chunk) completed read of chunk of 453 bytes
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 100
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [user agent
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.487] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [cache write
VC_EVENT_WRITE_READY]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [2] producer_handler [http server
VC_EVENT_READ_READY]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1041
(producer_handler_chunked)> (http_tunnel) [2] producer_handler_chunked [http
server VC_EVENT_READ_READY]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:188
(read_size)> (http_chunk) read chunk size of 0 bytes
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:295
(read_trailer)> (http_chunk) completed read of trailers
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [1 0 0] event: 102
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2855
(tunnel_handler_server)> (http) [2] [&HttpSM::tunnel_handler_server,
VC_EVENT_READ_COMPLETE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [cache write
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3302
(tunnel_handler_cache_write)> (http) [2]
[&HttpSM::tunnel_handler_cache_write, VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <P_CacheInternal.h:567
(free_CacheVC)> (cache_free) free 0x1dcc800
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:163 (release)> (http_ss) Releasing session,
private_session=1, sharing_match=1
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:121 (do_io_close)> (http_ss) [2] session closing,
netvc 0x1defb70
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [2] consumer_handler [user agent
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3095
(tunnel_handler_ua)> (http) [2] [&HttpSM::tunnel_handler_ua,
VC_EVENT_WRITE_COMPLETE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:498 (release)> (http_cs) [2] session released by sm
[2]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:236 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:527 (release)> (http_cs) [2] initiating io for next
header
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [2] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2794
(tunnel_handler)> (http) [2] [&HttpSM::tunnel_handler,
HTTP_TUNNEL_EVENT_DONE]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8975
(add_new_stat_block)> (http_trans) Adding new large stat block
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6639
(kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Mar  1 19:02:51.629] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6666
(kill_this)> (http) [2] deallocating sm
[Mar  1 19:02:51.630] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:409 (state_keep_alive)> (http_cs) [2]
[&HttpClientSession::state_keep_alive, VC_EVENT_EOS]
[Mar  1 19:02:51.630] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:325 (do_io_close)> (http_cs) [2] session closed
[Mar  1 19:02:51.630] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:73 (destroy)> (http_cs) [2] session destroy
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG:
<HttpSessionAccept.cc:60 (accept)> (http_seq) [HttpSessionAccept:mainEvent
0x2b4968017d20] accepted connection from 127.0.0.1:38463 transport type = 0
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:201 (new_connection)> (http_cs) [3] session born,
netvc 0x2b4968017d20
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG:
<HttpClientSession.cc:139 (new_transaction)> (http_cs) [3] Starting
transaction 1 using sm [3]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [3] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [3]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [3] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [3]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:724
(state_read_client_request_header)> (http) [3] done parsing client request
header
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1066
(ModifyRequest)> (http_trans) START HttpTransact::ModifyRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858976,
highest_delta: 0, cluster: 1456858976
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1157
(ModifyRequest)> (http_trans) END HttpTransact::ModifyRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1159
(ModifyRequest)> (http_trans) Checking if transaction wants to upgrade
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1166
(ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR;
HttpTransact::StartRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:693
(StartRemapRequest)> (http_trans) START HttpTransact::StartRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:734
(StartRemapRequest)> (http_trans) Before Remapping:
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb6888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b4953fb6b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb68b8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb6b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "127.0.0.1", HOST_LEN: 9,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "synthetic.txt", PATH_LEN: 13,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb68b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b4953fb68f8, TAILBLK: 0x2b4953fb68f8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb68f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb6908), LIVE    
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:746
(StartRemapRequest)> (http_trans) END HttpTransact::StartRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:747
(StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP;
HttpTransact::PerformRemap
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:753
(PerformRemap)> (http_trans) Inside PerformRemap
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:754
(PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST;
HttpTransact::EndRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:3902
(do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:760
(EndRemapRequest)> (http_trans) START HttpTransact::EndRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:766
(EndRemapRequest)> (http_trans) EndRemapRequest host is 127.0.0.1
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:878
(EndRemapRequest)> (http_trans) After Remapping:
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb6888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b4953fb6b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb68b8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb6b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "127.0.0.1", HOST_LEN: 9,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "synthetic.txt", PATH_LEN: 13,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb68b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b4953fb68f8, TAILBLK: 0x2b4953fb68f8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb68f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb6908), LIVE    
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:896
(EndRemapRequest)> (http_trans) END HttpTransact::EndRemapRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:902
(EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP;
HttpTransact::HandleRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1203
(HandleRequest)> (http_trans) START HttpTransact::HandleRequest
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5278
(check_request_validity)> (http_trans) [init_stat_vars_from_req] set req
cont length to 0
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:6315
(is_request_valid)> (http_trans) [is_request_valid]no request header errors
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1224
(HandleRequest)> (http_seq) [HttpTransact::HandleRequest] request valid.
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b4953fb6888: [T: 3, L:   48, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b4953fb6b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b4953fb68b8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b4953fb6b08: [T: 2, L:  112, OBJFLAGS: 0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1531
(url_describe)> (http) 	SCHEME: "http", SCHEME_LEN: 4,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1533
(url_describe)> (http) 	USER: "", USER_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1535
(url_describe)> (http) 	PASSWORD: "", PASSWORD_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1537
(url_describe)> (http) 	HOST: "127.0.0.1", HOST_LEN: 9,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1539
(url_describe)> (http) 	PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1541
(url_describe)> (http) 	PATH: "synthetic.txt", PATH_LEN: 13,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1543
(url_describe)> (http) 	PARAMS: "", PARAMS_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1545
(url_describe)> (http) 	QUERY: "", QUERY_LEN: 0,
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <URL.cc:1547
(url_describe)> (http) 	FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b4953fb68b8: [T: 4, L:  592, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http) 
	[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b4953fb68f8, TAILBLK: 0x2b4953fb68f8]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2607
(mime_hdr_describe)> (http) 	[CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0,
T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b4953fb68f8: [T: 5, L:  528, OBJFLAGS:
0]  
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) 	SLOT # 0 (0x2b4953fb6908), LIVE    
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14, 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http) 
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <CacheControl.cc:466
(UpdateMatch)> (cache_control) Matched with for TTL_IN_CACHE at line 55
[cache-responses-to-cookies=1]
[Mar  1 19:02:56.005] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1951
(DecideCacheLookup)> (http_trans) [DecideCacheLookup] Will NOT do cache
lookup.
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1952
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will NOT do cache lookup
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1974
(DecideCacheLookup)> (http_trans) Next action
SM_ACTION_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_API_POST_REMAP -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2433
(CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6984
(set_next_state)> (dns) [HttpTransact::HandleRequest] Skipping DNS lookup
for 127.0.0.1 because it's loopback
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
127.0.0.1
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:1793
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
LookupSkipOpenServer
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 127.0.0.1'
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:5209
(add_client_ip_to_outgoing_request)> (http_trans)
[add_client_ip_to_outgoing_request] Appended connecting client's (127.0.0.1)
to the X-Forwards header
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7816
(build_request)> (http_trans) [build_request] request like cacheable but
keep conditional headers
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456858976,
highest_delta: 0, cluster: 1456858976
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:7836
(build_request)> (http_trans) [build_request] request_sent_time: 1456858976
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpTransact.cc:2001
(LookupSkipOpenServer)> (http_trans) Next action next;
HttpTransact::HandleResponse
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [3] State Transition:
SM_ACTION_API_OS_DNS -> SM_ACTION_ORIGIN_SERVER_OPEN
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4555
(do_http_server_open)> (http_track) entered inside do_http_server_open
][IPv4]
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4575
(do_http_server_open)> (http) [3] open connection to 127.0.0.1:
127.0.0.1:8083
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4587
(do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending
request to server
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG:
<HttpSessionManager.cc:289 (acquire_session)> (http_ss) [acquire session]
thread pool search failed
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:4803
(do_http_server_open)> (http) calling netProcessor.connect_re
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [3] [HttpSM::main_handler, NET_EVENT_OPEN]
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1618
(state_http_server_open)> (http_track) entered inside state_http_server_open
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG: <HttpSM.cc:1619
(state_http_server_open)> (http) [3] [&HttpSM::state_http_server_open,
NET_EVENT_OPEN]
[Mar  1 19:02:56.006] Server {0x2b4950510440} DEBUG:
<HttpServerSession.cc:91 (new_connection)> (http_ss) [3] session born, netvc
0x2b4968017a40





--
View this message in context: http://apache-traffic-server.24303.n7.nabble.com/Problems-with-caching-retrieving-from-cache-from-a-particular-origin-tp2193p2202.html
Sent from the Apache Traffic Server mailing list archive at Nabble.com.

Mime
View raw message