You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@trafficserver.apache.org by jhasle <jh...@de.ibm.com> on 2016/03/01 16:53:18 UTC
Re: Problems with caching / retrieving from cache from a particular
origin
Thanks! I did that and it seems like for some reason it decides not to do a
cache lookup in the first place. Here is an extract of my traffic.out log
file:
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [6] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:1881
(state_send_server_request_header)> (http) [6]
[&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [6] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:1712
(state_read_server_response_header)> (http) [6]
[&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:1825
(state_read_server_response_header)> (http_seq) Done parsing server response
header
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3296
(HandleResponse)> (http_trans) [HttpTransact::HandleResponse]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3297
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response
received
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456850662,
highest_delta: 0, cluster: 1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3304
(HandleResponse)> (http_trans) [HandleResponse] response_received_time:
1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:6458
(is_response_valid)> (http_trans) [is_response_valid] No errors in response
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3322
(HandleResponse)> (http_seq) [HttpTransact::HandleResponse] Response valid
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3631
(handle_response_from_server)> (http_trans) [handle_response_from_server]
(hrfs)
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3643
(handle_response_from_server)> (http_trans) [hrfs] connection alive
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3910
(handle_forward_server_connection_open)> (http_trans)
[handle_forward_server_connection_open] (hfsco)
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:3911
(handle_forward_server_connection_open)> (http_seq)
[HttpTransact::handle_server_connection_open]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:4112
(do_hostdb_update_if_necessary)> (http) server info = 127.0.0.1:8083
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:4017
(handle_forward_server_connection_open)> (http_trans) [hfsco] cache action:
CACHE_DO_NO_ACTION
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:4571
(handle_no_cache_operation_on_forward_server_response)> (http_trans)
[handle_no_cache_operation_on_forward_server_response] (hncoofsr)
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:4572
(handle_no_cache_operation_on_forward_server_response)> (http_seq)
[handle_no_cache_operation_on_forward_server_response]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:4579
(handle_no_cache_operation_on_forward_server_response)> (http_trans)
[hncoofsr] server sent back 200
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:4586
(handle_no_cache_operation_on_forward_server_response)> (http_trans)
[hncoofsr] next action will be OS_READ_CACHE_NOOP
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:424 (calculate_document_age)> (http_age)
[calculate_document_age] age_value: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:425 (calculate_document_age)> (http_age)
[calculate_document_age] date_value: 1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:426 (calculate_document_age)> (http_age)
[calculate_document_age] response_time: 1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:427 (calculate_document_age)> (http_age)
[calculate_document_age] now: 1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:428 (calculate_document_age)> (http_age)
[calculate_document_age] now (fixed): 1456850662
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:429 (calculate_document_age)> (http_age)
[calculate_document_age] apparent_age: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:430 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_received_age: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:431 (calculate_document_age)> (http_age)
[calculate_document_age] response_delay: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:432 (calculate_document_age)> (http_age)
[calculate_document_age] corrected_initial_age: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:433 (calculate_document_age)> (http_age)
[calculate_document_age] resident_time: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:434 (calculate_document_age)> (http_age)
[calculate_document_age] current_age: 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:6729
(handle_content_length_header)> (http_trans) [handle_content_length_header]
RESPONSE cont len in hdr is 1680
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:629 (generate_and_set_squid_codes)> (http_trans)
[Squid code generation] Hit/Miss: 1, Log: 3, Hier: 2
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG:
<HttpTransactHeaders.cc:979 (add_server_header_to_response)> (http_trans)
Adding Server: ATS/6.1.1
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [6] State Transition:
SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:7709
(is_redirect_required)> (http_redirect) is_redirect_required 0
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6294
(setup_server_transfer)> (http) Setup Server Transfer
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:629
(add_producer)> (http_tunnel) [6] adding producer 'http server'
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:684
(add_consumer)> (http_tunnel) [6] adding consumer 'user agent'
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:5507
(perform_cache_write_action)> (http) [6] perform_cache_write_action
CACHE_DO_NO_ACTION
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:730
(tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:236 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:249 (set_tcp_init_cwnd)> (http_cs) desired TCP
congestion window is 0
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:988
(producer_run)> (http_tunnel) [6] [tunnel_run] producer already done
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1106
(producer_handler)> (http_tunnel) [6] producer_handler [http server
HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1146
(producer_handler)> (http_redirect) [HttpTunnel::producer_handler]
enable_redirection: [0 0 0] event: 2302
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2855
(tunnel_handler_server)> (http) [6] [&HttpSM::tunnel_handler_server,
HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG:
<HttpServerSession.cc:121 (do_io_close)> (http_ss) [6] session closing,
netvc 0x2b9290017760
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1306
(consumer_handler)> (http_tunnel) [6] consumer_handler [user agent
VC_EVENT_WRITE_COMPLETE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:3095
(tunnel_handler_ua)> (http) [6] [&HttpSM::tunnel_handler_ua,
VC_EVENT_WRITE_COMPLETE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:325 (do_io_close)> (http_cs) [6] session closed
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:73 (destroy)> (http_cs) [6] session destroy
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [6] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2794
(tunnel_handler)> (http) [6] [&HttpSM::tunnel_handler,
HTTP_TUNNEL_EVENT_DONE]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpTunnel.cc:1669
(deallocate_redirect_postdata_buffers)> (http_redirect)
[HttpTunnel::deallocate_postdata_copy_buffers]
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6678
(update_stats)> (http_seq) Skipping cop heartbeat logging & stats due to
config
[Mar 1 16:44:22.998] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6666
(kill_this)> (http) [6] deallocating sm
[Mar 1 16:44:29.091] Server {0x2b927cbd9440} DEBUG: <CacheDir.cc:1046
(mainEvent)> (cache_dir_sync) sync started
[Mar 1 16:44:29.091] Server {0x2b927cbd9440} DEBUG: <CacheDir.cc:1058
(mainEvent)> (cache_dir_sync) Dir
/opt/trafficserver/var/trafficserver/cache.db 16384:1310718: waiting for agg
buffer
[Mar 1 16:44:29.095] Server {0x2b928660f700} DEBUG: <CacheDir.cc:1046
(mainEvent)> (cache_dir_sync) sync started
[Mar 1 16:44:29.095] Server {0x2b928660f700} DEBUG: <CacheDir.cc:1064
(mainEvent)> (cache_dir_sync) pos: 26845184 Dir
/opt/trafficserver/var/trafficserver/cache.db 16384:1310718 dirty...syncing
to disk
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG:
<HttpSessionAccept.cc:60 (accept)> (http_seq) [HttpSessionAccept:mainEvent
0x2b9290017d20] accepted connection from 127.0.0.1:38723 transport type = 0
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:201 (new_connection)> (http_cs) [7] session born,
netvc 0x2b9290017d20
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG:
<HttpClientSession.cc:139 (new_transaction)> (http_cs) [7] Starting
transaction 1 using sm [7]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [7] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [7]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [7] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:579
(state_read_client_request_header)> (http) [7]
[&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:724
(state_read_client_request_header)> (http) [7] done parsing client request
header
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1066
(ModifyRequest)> (http_trans) START HttpTransact::ModifyRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456850673,
highest_delta: 0, cluster: 1456850673
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1157
(ModifyRequest)> (http_trans) END HttpTransact::ModifyRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1159
(ModifyRequest)> (http_trans) Checking if transaction wants to upgrade
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1166
(ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR;
HttpTransact::StartRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:693
(StartRemapRequest)> (http_trans) START HttpTransact::StartRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:734
(StartRemapRequest)> (http_trans) Before Remapping:
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b927ff47888: [T: 3, L: 48, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b927ff47b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b927ff478b8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b927ff47b08: [T: 2, L: 112, OBJFLAGS: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1531
(url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1533
(url_describe)> (http) USER: "", USER_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1535
(url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1537
(url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1539
(url_describe)> (http) PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1541
(url_describe)> (http) PATH: "synthetic.txt", PATH_LEN: 13,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1543
(url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1545
(url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1547
(url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b927ff478b8: [T: 4, L: 592, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http)
[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b927ff478f8, TAILBLK: 0x2b927ff478f8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} 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 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b927ff478f8: [T: 5, L: 528, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) SLOT # 0 (0x2b927ff47908), LIVE
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http)
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:746
(StartRemapRequest)> (http_trans) END HttpTransact::StartRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:747
(StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP;
HttpTransact::PerformRemap
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:753
(PerformRemap)> (http_trans) Inside PerformRemap
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:754
(PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST;
HttpTransact::EndRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:3902
(do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:760
(EndRemapRequest)> (http_trans) START HttpTransact::EndRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:766
(EndRemapRequest)> (http_trans) EndRemapRequest host is 127.0.0.1
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:878
(EndRemapRequest)> (http_trans) After Remapping:
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b927ff47888: [T: 3, L: 48, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b927ff47b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b927ff478b8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b927ff47b08: [T: 2, L: 112, OBJFLAGS: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1531
(url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1533
(url_describe)> (http) USER: "", USER_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1535
(url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1537
(url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1539
(url_describe)> (http) PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1541
(url_describe)> (http) PATH: "synthetic.txt", PATH_LEN: 13,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1543
(url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1545
(url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1547
(url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b927ff478b8: [T: 4, L: 592, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http)
[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b927ff478f8, TAILBLK: 0x2b927ff478f8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} 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 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b927ff478f8: [T: 5, L: 528, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) SLOT # 0 (0x2b927ff47908), LIVE
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http)
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:896
(EndRemapRequest)> (http_trans) END HttpTransact::EndRemapRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:902
(EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP;
HttpTransact::HandleRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1203
(HandleRequest)> (http_trans) START HttpTransact::HandleRequest
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:5278
(check_request_validity)> (http_trans) [init_stat_vars_from_req] set req
cont length to 0
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:6315
(is_request_valid)> (http_trans) [is_request_valid]no request header errors
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1224
(HandleRequest)> (http_seq) [HttpTransact::HandleRequest] request valid.
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) HTTP_HEADER 0x2b927ff47888: [T: 3, L: 48, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HTTP.cc:585
(http_hdr_describe)> (http) [TYPE: REQ, V: 10000, URL: 0x2b927ff47b08,
METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x2b927ff478b8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) URL 0x2b927ff47b08: [T: 2, L: 112, OBJFLAGS: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1529
(url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1531
(url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1533
(url_describe)> (http) USER: "", USER_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1535
(url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1537
(url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1539
(url_describe)> (http) PORT: "8083", PORT_LEN: 4, PORT_NUM: 8083
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1541
(url_describe)> (http) PATH: "synthetic.txt", PATH_LEN: 13,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1543
(url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1545
(url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1547
(url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) MIME_HEADER 0x2b927ff478b8: [T: 4, L: 592, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2602
(mime_hdr_describe)> (http)
[PBITS: 0x0000000001000000, SLACC: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF,
HEADBLK: 0x2b927ff478f8, TAILBLK: 0x2b927ff478f8]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} 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 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <HdrHeap.cc:57
(obj_describe)> (http) FIELD_BLOCK 0x2b927ff478f8: [T: 5, L: 528, OBJFLAGS:
0]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2622
(mime_field_block_describe)> (http) [FREETOP: 1, NEXTBLK: (nil)]
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2626
(mime_field_block_describe)> (http) SLOT # 0 (0x2b927ff47908), LIVE
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2635
(mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2636
(mime_field_block_describe)> (http) V: "127.0.0.1:8083", V_LEN: 14,
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2638
(mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 18, F:
1]
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <MIME.cc:2641
(mime_field_block_describe)> (http)
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <CacheControl.cc:466
(UpdateMatch)> (cache_control) Matched with for TTL_IN_CACHE at line 55
[cache-responses-to-cookies=1]
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1951
(DecideCacheLookup)> (http_trans) [DecideCacheLookup] Will NOT do cache
lookup.
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1952
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will NOT do cache lookup
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1974
(DecideCacheLookup)> (http_trans) Next action
SM_ACTION_API_CACHE_LOOKUP_COMPLETE; CallOSDNSLookup
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_API_POST_REMAP -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:2433
(CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP;
OSDNSLookup
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6984
(set_next_state)> (dns) [HttpTransact::HandleRequest] Skipping DNS lookup
for 127.0.0.1 because it's loopback
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1634
(OSDNSLookup)> (http_trans) [HttpTransact::OSDNSLookup] This was attempt 1
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1697
(OSDNSLookup)> (http_seq) [HttpTransact::OSDNSLookup] DNS Lookup successful
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1731
(OSDNSLookup)> (http_trans) [OSDNSLookup] DNS lookup for O.S. successful IP:
127.0.0.1
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1793
(OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS;
LookupSkipOpenServer
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:5183
(add_client_ip_to_outgoing_request)> (http_trans) client_ip_set = 0
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:5187
(add_client_ip_to_outgoing_request)> (http_trans) inserted request header
'Client-ip: 127.0.0.1'
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} 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 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:7789
(build_request)> (http_trans) [build_request] removing host name from url
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:7816
(build_request)> (http_trans) [build_request] request like cacheable but
keep conditional headers
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:8344
(ink_cluster_time)> (http_trans) [ink_cluster_time] local: 1456850673,
highest_delta: 0, cluster: 1456850673
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:7836
(build_request)> (http_trans) [build_request] request_sent_time: 1456850673
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:2001
(LookupSkipOpenServer)> (http_trans) Next action next;
HttpTransact::HandleResponse
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:6920
(call_transact_and_set_next_state)> (http) [7] State Transition:
SM_ACTION_API_OS_DNS -> SM_ACTION_ORIGIN_SERVER_OPEN
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:4555
(do_http_server_open)> (http_track) entered inside do_http_server_open
][IPv4]
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:4575
(do_http_server_open)> (http) [7] open connection to 127.0.0.1:
127.0.0.1:8083
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:4587
(do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending
request to server
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG:
<HttpSessionManager.cc:289 (acquire_session)> (http_ss) [acquire session]
thread pool search failed
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:4803
(do_http_server_open)> (http) calling netProcessor.connect_re
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:2541
(main_handler)> (http) [7] [HttpSM::main_handler, NET_EVENT_OPEN]
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:1618
(state_http_server_open)> (http_track) entered inside state_http_server_open
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG: <HttpSM.cc:1619
(state_http_server_open)> (http) [7] [&HttpSM::state_http_server_open,
NET_EVENT_OPEN]
[Mar 1 16:44:33.001] Server {0x2b927cbd9440} DEBUG:
<HttpServerSession.cc:91 (new_connection)> (http_ss) [7] session born, netvc
0x2b9290017760
Here is the part that is weird:
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <CacheControl.cc:466
(UpdateMatch)> (cache_control) Matched with for TTL_IN_CACHE at line 55
[cache-responses-to-cookies=1]
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1951
(DecideCacheLookup)> (http_trans) [DecideCacheLookup] Will NOT do cache
lookup.
[Mar 1 16:44:22.997] Server {0x2b927cbd9440} DEBUG: <HttpTransact.cc:1952
(DecideCacheLookup)> (http_seq) [DecideCacheLookup] Will NOT do cache lookup
Any ideas?
--
View this message in context: http://apache-traffic-server.24303.n7.nabble.com/Problems-with-caching-retrieving-from-cache-from-a-particular-origin-tp2193p2199.html
Sent from the Apache Traffic Server mailing list archive at Nabble.com.
Re: Problems with caching / retrieving from cache from a particular
origin
Posted by jhasle <jh...@de.ibm.com>.
Thanks for letting me know. However I think in my use case it is ok, since we
only use it in our testing environment behind inside a vpn. Also we only
cache urls that match a particular pattern that we previously defined.
--
View this message in context: http://apache-traffic-server.24303.n7.nabble.com/Problems-with-caching-retrieving-from-cache-from-a-particular-origin-tp2193p2207.html
Sent from the Apache Traffic Server mailing list archive at Nabble.com.
Re: Problems with caching / retrieving from cache from a particular origin
Posted by Muhammad Faisal <fa...@yahoo.com>.
Ignoring authentication has potential risks so experts suggest not to
use it.
--
Thanks
F.
irc: zoot
------ Original Message ------
From: "jhasle" <jh...@de.ibm.com>
To: users@trafficserver.apache.org
Sent: 3/2/2016 5:54:25 PM
Subject: Re: Problems with caching / retrieving from cache from a
particular origin
>Thank you so much! That was the problem and it works now.
>
>I ended up telling ATS to ignore authentication as I don't control the
>origin. I use these parameters:
>
>CONFIG proxy.config.http.auth_server_session_private INT 0
>CONFIG proxy.config.http.cache.ignore_authentication INT 1
>
>
>
>--
>View this message in context:
>http://apache-traffic-server.24303.n7.nabble.com/Problems-with-caching-retrieving-from-cache-from-a-particular-origin-tp2193p2204.html
>Sent from the Apache Traffic Server mailing list archive at Nabble.com.
Re: Problems with caching / retrieving from cache from a particular
origin
Posted by jhasle <jh...@de.ibm.com>.
Thank you so much! That was the problem and it works now.
I ended up telling ATS to ignore authentication as I don't control the
origin. I use these parameters:
CONFIG proxy.config.http.auth_server_session_private INT 0
CONFIG proxy.config.http.cache.ignore_authentication INT 1
--
View this message in context: http://apache-traffic-server.24303.n7.nabble.com/Problems-with-caching-retrieving-from-cache-from-a-particular-origin-tp2193p2204.html
Sent from the Apache Traffic Server mailing list archive at Nabble.com.
Re: Problems with caching / retrieving from cache from a particular
origin
Posted by Alan Carroll <so...@yahoo-inc.com>.
Yes. Based on that logging, the first request is cached and it is found on the second request. But once found ATS decides that authentication is needed and so doesn't use the cached data. You can see the code that does this in HttpTransact::need_to_revalidate. Ultimate what happens is ATS looks for a WWw-Authenticate header in the reply and, not finding it, refuses to serve it.
A few things to look at -
* You can turn this authentication checking off. You can do it globally or, using a plugin or potentially the existing conf-remap plugin, turn it off for just that origin.
* You can have the origin return a "Cache-Control: public" in addition to the no-cache.
* You could use a plugin (or potentially header_write) to insert the Cache-Control: public yourself.
* Alternatively, strip the authentication from the client request because, based on the response from the origin server, it is being ignored already.
But ultimately, as you noted, the authentication is the issue.
-------------
On Tuesday, March 1, 2016 12:33 PM, jhasle <jh...@de.ibm.com> wrote:
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
Re: Problems with caching / retrieving from cache from a particular
origin
Posted by jhasle <jh...@de.ibm.com>.
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.
Re: Problems with caching / retrieving from cache from a particular
origin
Posted by Alan Carroll <so...@yahoo-inc.com>.
That request is a heartbeat request, not your request. You can tell by this line
[Mar 1 16:44:33.000] Server {0x2b927cbd9440} DEBUG: <URL.cc:1541
(url_describe)> (http) PATH: "synthetic.txt", PATH_LEN: 13,
"synthetic.text" is the magic path used to indicate the heartbeat request. These happen about every 10 seconds so you need to ignore them. There is a special check for that request that generates the "Will NOT do cache lookup" message. Look forward or back in the log file to try to find your request, which should be easy to find if you know the path or host.