trafficserver-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From jhasle <jhan...@de.ibm.com>
Subject Re: Problems with caching / retrieving from cache from a particular origin
Date Tue, 01 Mar 2016 15:53:18 GMT
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.

Mime
View raw message