Skip to content

Instantly share code, notes, and snippets.

@ywkaras

ywkaras/TS_debug_output.txt

Last active August 22, 2018 23:13
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save ywkaras/41ac8fc3f65b8fa937fa3c426d49e10f to your computer and use it in GitHub Desktop.
Save ywkaras/41ac8fc3f65b8fa937fa3c426d49e10f to your computer and use it in GitHub Desktop.
Download ZIP
Caching with Accept-Encoding
Raw
curl_commands.txt
# For www.ae-0.com , conf_remap sets normalize_ae=0
# For www.ae-1.com , conf_rempa sets normalize_ae=1
curl --verbose --ipv4 --http1.1 --proxy localhost:61998 --header "N: 2" --header "Accept-Encoding: deflate" http://www.ae-0.com/argh
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 61998 (#0)
> GET http://www.ae-0.com/argh HTTP/1.1
> Host: www.ae-0.com
> User-Agent: curl/7.59.0
> Accept: */*
> Proxy-Connection: Keep-Alive
> N: 2
> Accept-Encoding: deflate
>
< HTTP/1.1 200 OK
< Cache-Control: max-age=32000000
< Vary: Accept-Encoding
< Content-Length: 128
< Date: Wed, 22 Aug 2018 23:02:49 GMT
< Age: 0
< Proxy-Connection: keep-alive
< Server: ATS/9.0.0
<
{ [128 bytes data]
100 128 100 128 0 0 1641 0 --:--:-- --:--:-- --:--:-- 1641
* Connection #0 to host localhost left intact
curl --verbose --ipv4 --http1.1 --proxy localhost:61998 --header "N: 2a" --header "Accept-Encoding: AlanWhatTheHell" http://www.ae-0.com/argh
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 127.0.0.1...
* TCP_NODELAY set
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Connected to localhost (127.0.0.1) port 61998 (#0)
> GET http://www.ae-0.com/argh HTTP/1.1
> Host: www.ae-0.com
> User-Agent: curl/7.59.0
> Accept: */*
> Proxy-Connection: Keep-Alive
> N: 2a
> Accept-Encoding: AlanWhatTheHell
>
< HTTP/1.1 200 OK
< Cache-Control: max-age=32000000
< Vary: Accept-Encoding
< Content-Length: 128
< Date: Wed, 22 Aug 2018 23:02:49 GMT
< Age: 1
< Proxy-Connection: keep-alive
< Server: ATS/9.0.0
<
{ [128 bytes data]
100 128 100 128 0 0 1600 0 --:--:-- --:--:-- --:--:-- 1580
* Connection #0 to host localhost left intact
curl --verbose --ipv4 --http1.1 --proxy localhost:61998 --header "N: 3" http://www.ae-0.com/argh
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 61998 (#0)
> GET http://www.ae-0.com/argh HTTP/1.1
> Host: www.ae-0.com
> User-Agent: curl/7.59.0
> Accept: */*
> Proxy-Connection: Keep-Alive
> N: 3
>
< HTTP/1.1 200 OK
< Cache-Control: max-age=32000000
< Vary: Accept-Encoding
< Content-Length: 128
< Date: Wed, 22 Aug 2018 23:02:49 GMT
< Age: 1
< Proxy-Connection: keep-alive
< Server: ATS/9.0.0
<
{ [128 bytes data]
100 128 100 128 0 0 2133 0 --:--:-- --:--:-- --:--:-- 2133
* Connection #0 to host localhost left intact
curl --verbose --ipv4 --http1.1 --proxy localhost:61998 --header "N: 4" --header "Accept-Encoding: deflate" http://www.ae-1.com/argh
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 61998 (#0)
> GET http://www.ae-1.com/argh HTTP/1.1
> Host: www.ae-1.com
> User-Agent: curl/7.59.0
> Accept: */*
> Proxy-Connection: Keep-Alive
> N: 4
> Accept-Encoding: deflate
>
< HTTP/1.1 200 OK
< Cache-Control: max-age=32000000
< Vary: Accept-Encoding
< Content-Length: 128
< Date: Wed, 22 Aug 2018 23:02:49 GMT
< Age: 1
< Proxy-Connection: keep-alive
< Server: ATS/9.0.0
<
{ [128 bytes data]
100 128 100 128 0 0 2064 0 --:--:-- --:--:-- --:--:-- 2064
* Connection #0 to host localhost left intact
Raw
TS_debug_output.txt
[Aug 22 23:02:49.590] {0x7f48ba4dd740} DEBUG: <Cache.cc:3161 (ink_cache_init)> (cache_init) proxy.config.cache.ram_cache.size = -1 = 0Mb
[Aug 22 23:02:49.590] {0x7f48ba4dd740} DEBUG: <Cache.cc:3169 (ink_cache_init)> (cache_init) proxy.config.cache.limits.http.max_alts = 5
[Aug 22 23:02:49.590] {0x7f48ba4dd740} DEBUG: <Cache.cc:3173 (ink_cache_init)> (cache_init) cache_config_ram_cache_cutoff = 4194304 = 4Mb
[Aug 22 23:02:49.590] {0x7f48ba4dd740} DEBUG: <Cache.cc:3176 (ink_cache_init)> (cache_init) proxy.config.cache.permit.pinning = 0
[Aug 22 23:02:49.590] {0x7f48ba4dd740} DEBUG: <Cache.cc:3179 (ink_cache_init)> (cache_init) proxy.config.cache.dir.sync_frequency = 60
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3182 (ink_cache_init)> (cache_init) proxy.config.cache.select_alternate = 1
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3186 (ink_cache_init)> (cache_init) proxy.config.cache.max_doc_size = 0 = 0Mb
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3189 (ink_cache_init)> (cache_init) proxy.config.cache.mutex_retry_delay = 2ms
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3192 (ink_cache_init)> (cache_init) proxy.config.cache.read_while_writer.max_retries = 10
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3195 (ink_cache_init)> (cache_init) proxy.config.cache.read_while_writer_retry.delay = 50ms
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3198 (ink_cache_init)> (cache_init) proxy.config.cache.hit_evacuate_percent = 0
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3201 (ink_cache_init)> (cache_init) proxy.config.cache.hit_evacuate_size_limit = 0
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3215 (ink_cache_init)> (cache_init) proxy.config.cache.max_disk_errors = 5
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3218 (ink_cache_init)> (cache_init) proxy.config.cache.agg_write_backlog = 5242880
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3221 (ink_cache_init)> (cache_init) proxy.config.cache.enable_checksum = 0
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3224 (ink_cache_init)> (cache_init) proxy.config.cache.alt_rewrite_max_size = 4096
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Cache.cc:3229 (ink_cache_init)> (cache_init) proxy.config.cache.enable_read_while_writer = 1
[Aug 22 23:02:49.591] {0x7f48ba4dd740} DEBUG: <Store.cc:329 (read_config)> (cache_init) Store::read_config, fd = -1, "/Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/config/storage.config"
[Aug 22 23:02:49.592] {0x7f48ba4dd740} DEBUG: <Store.cc:361 (read_config)> (cache_init) Store::read_config: "storage"
[Aug 22 23:02:49.592] {0x7f48ba4dd740} DEBUG: <Store.cc:397 (read_config)> (cache_init) Store::read_config - ns = new Span; ns->init("/Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/storage",268435456), forced volume=-1
[Aug 22 23:02:49.592] {0x7f48ba4dd740} DEBUG: <Store.cc:586 (init)> (cache_init) initialized span '/Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/storage'
[Aug 22 23:02:49.592] {0x7f48ba4dd740} DEBUG: <Store.cc:588 (init)> (cache_init) hw_sector_size=4194304, size=268435456, blocks=32768, disk_id=74/4312277625, file_pathname=0
[Aug 22 23:02:49.624] {0x7f48ba4dd740} DEBUG: <Cache.cc:706 (start_internal)> (cache_hosting) Disk: 0:/Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/storage/cache.db, blocks: 32767
[Aug 22 23:02:49.626] {0x7f48b5229700} DEBUG: <Cache.cc:2774 (cplist_reconfigure)> (cache_hosting) blocks = 32766
[Aug 22 23:02:49.626] {0x7f48b5229700} DEBUG: <Cache.cc:828 (diskInitialized)> (cache_hosting) Disk: 0:/Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/storage/cache.db: Vol Blocks: 1: Free space: 0
[Aug 22 23:02:49.626] {0x7f48b5229700} DEBUG: <Cache.cc:830 (diskInitialized)> (cache_hosting) Vol: 0 Size: 32766
[Aug 22 23:02:49.626] {0x7f48b5229700} DEBUG: <Cache.cc:834 (diskInitialized)> (cache_hosting) Block No: 0 Size: 32766 Free: 0
[Aug 22 23:02:49.626] {0x7f48b5229700} DEBUG: <Cache.cc:2075 (open)> (cache_init) Cache::open - proxy.config.cache.min_average_object_size = 8000
[Aug 22 23:02:49.627] {0x7f48b5229700} DEBUG: <Cache.cc:1269 (init)> (cache_init) Vol /Users/wkaras/REPOS/TS/tests/_sandbox/normalize_ae2/ts/storage/cache.db 16384:32766: allocating 352256 directory bytes for a 268419072 byte volume (0.131234%)
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <CacheHosting.cc:424 (Init)> (cache_hosting) Host Record: 0x7f4890028a78, Volume: 0, size: 32766
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:1895 (build_vol_hash_table)> (cache_init) build_vol_hash_table index 0 mapped to 0 requested 32707 got 32707
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:881 (cacheInitialized)> (cache_init) CacheProcessor::cacheInitialized - theCache, total_size = 32766 = 255 MB
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:909 (cacheInitialized)> (cache_init) CacheProcessor::cacheInitialized - caches_ready=0x9, gnvol=1
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:928 (cacheInitialized)> (cache_init) CacheProcessor::cacheInitialized - cache_config_ram_cache_size == AUTO_SIZE_RAM_CACHE
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:934 (cacheInitialized)> (cache_init) CacheProcessor::cacheInitialized - ram_cache_bytes = 352256 = 0Mb
[Aug 22 23:02:49.632] {0x7f48b4d82700} DEBUG: <Cache.cc:940 (cacheInitialized)> (cache_init) CacheProcessor::cacheInitialized - total_cache_bytes = 268066816 = 255Mb
[Aug 22 23:02:49.865] {0x7f48b41b8700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read..
[Aug 22 23:02:49.865] {0x7f48b41b8700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7f4864019ce0] accepted connection from 127.0.0.1:51506 transport type = 1
[Aug 22 23:02:49.866] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:199 (new_connection)> (http_cs) [0] session born, netvc 0x7f4864019ce0
[Aug 22 23:02:49.866] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Aug 22 23:02:49.866] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:466 (release)> (http_cs) [0] data already in buffer, starting new transaction
[Aug 22 23:02:49.871] {0x7f48b41b8700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [0] Starting transaction 1 using sm [0]
[Aug 22 23:02:49.871] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Aug 22 23:02:49.871] {0x7f48b41b8700} DEBUG: <HttpSM.cc:603 (state_read_client_request_header)> (http) [0] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Aug 22 23:02:49.871] {0x7f48b41b8700} DEBUG: <HttpSM.cc:750 (state_read_client_request_header)> (http) [0] done parsing client request header
[Aug 22 23:02:49.871] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:973 (ModifyRequest)> (http_trans) [0] START HttpTransact::ModifyRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1047 (ModifyRequest)> (http_trans) [0] END HttpTransact::ModifyRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1048 (ModifyRequest)> (http_trans) [0] Checking if transaction wants to upgrade
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1056 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:599 (StartRemapRequest)> (http_trans) [0] START HttpTransact::StartRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:619 (StartRemapRequest)> (http_trans) [0] Before Remapping:
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x10a1888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x10a1b08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x10a18b8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x10a1b08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "www.ae-0.com", HOST_LEN: 12,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x10a18b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x10a18f8, TAILBLK: 0x10a18f8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x10a18f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x10a1908), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "www.ae-0.com", V_LEN: 12,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 20, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x10a1928), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x10a1948), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x10a1968), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x10a1988), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2", V_LEN: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x10a19a8), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:630 (StartRemapRequest)> (http_trans) [0] END HttpTransact::StartRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:637 (PerformRemap)> (http_trans) [0] Inside PerformRemap
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:638 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpSM.cc:3982 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:644 (EndRemapRequest)> (http_trans) [0] START HttpTransact::EndRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:650 (EndRemapRequest)> (http_trans) [0] EndRemapRequest host is 127.0.0.1
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:788 (EndRemapRequest)> (http_trans) [0] After Remapping:
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x10a1888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x10a1b08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x10a18b8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x10a1b08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x10a18b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x10a18f8, TAILBLK: 0x10a18f8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x10a18f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x10a1908), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x10a1928), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x10a1948), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x10a1968), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x10a1988), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2", V_LEN: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x10a19a8), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:807 (EndRemapRequest)> (http_trans) [0] END HttpTransact::EndRemapRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:813 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1093 (HandleRequest)> (http_trans) [0] START HttpTransact::HandleRequest
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:5108 (check_request_validity)> (http_trans) [0] [init_stat_vars_from_req] set req cont length to 0
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:6171 (is_request_valid)> (http_trans) [0] [is_request_valid] no request header errors
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1115 (HandleRequest)> (http_seq) [0] [HttpTransact::HandleRequest] request valid.
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x10a1888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x10a1b08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x10a18b8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x10a1b08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x10a18b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x10a18f8, TAILBLK: 0x10a18f8]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x10a18f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x10a1908), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x10a1928), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x10a1948), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x10a1968), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x10a1988), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2", V_LEN: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x10a19a8), LIVE
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:49.872] {0x7f48b41b8700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 0
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
Proxy-Connection: Keep-Alive
N: 2
Accept-Encoding: deflate
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1819 (DecideCacheLookup)> (http_trans) [0] [DecideCacheLookup] Will do cache lookup.
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1820 (DecideCacheLookup)> (http_seq) [0] [DecideCacheLookup] Will do cache lookup
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1863 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4524 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [0] Issuing cache lookup for URL http://127.0.0.1:62000/argh
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <Cache.cc:3073 (key_to_vol)> (cache_hosting) Generic volume: 90028a78d for host: 127.0.0.1
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpCacheSM.cc:116 (state_cache_open_read)> (http_cache) [0] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ_FAILED]
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2504 (state_cache_open_read)> (http) [0] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ_FAILED]
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2538 (state_cache_open_read)> (http) [0] cache_open_read - CACHE_EVENT_OPEN_READ_FAILED with ECACHE_NO_DOC (-20400)
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2540 (state_cache_open_read)> (http) [state_cache_open_read] open read failed.
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2074 (HandleCacheOpenRead)> (http_trans) [0] [HttpTransact::HandleCacheOpenRead]
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2104 (HandleCacheOpenRead)> (http_trans) [0] CacheOpenRead -- miss
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2963 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:4913 (get_ka_info_from_config)> (http_trans) [0] get_ka_info_from_config, server_info->http_version 65537, check_hostdb 0
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3020 (HandleCacheOpenReadMiss)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_DNS_LOOKUP
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1538 (OSDNSLookup)> (http_trans) [0] [HttpTransact::OSDNSLookup] This was attempt 0
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1608 (OSDNSLookup)> (http_seq) [0] [HttpTransact::OSDNSLookup] DNS Lookup successful
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1648 (OSDNSLookup)> (http_trans) [0] [OSDNSLookup] DNS lookup for O.S. successful IP: 127.0.0.1
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:1717 (OSDNSLookup)> (http_trans) Next action SM_ACTION_API_OS_DNS; HandleCacheOpenReadMiss
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2961 (HandleCacheOpenReadMiss)> (http_trans) [0] [HandleCacheOpenReadMiss] --- MISS
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2963 (HandleCacheOpenReadMiss)> (http_seq) [0] [HttpTransact::HandleCacheOpenReadMiss] Miss in cache
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:5014 (add_client_ip_to_outgoing_request)> (http_trans) [0] client_ip_set = 0
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:5024 (add_client_ip_to_outgoing_request)> (http_trans) [0] inserted request header 'Client-ip: 127.0.0.1'
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:5038 (add_client_ip_to_outgoing_request)> (http_trans) [0] [add_client_ip_to_outgoing_request] Appended connecting client's (127.0.0.1) to the X-Forwards header
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:7578 (build_request)> (http_trans) [0] [build_request] removing host name from url
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:7591 (build_request)> (http_trans) [0] [build_request] request like cacheable and conditional headers removed
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:7616 (build_request)> (http_trans) [0] [build_request] request_sent_time: 1534978969
+++++++++ Proxy's Request +++++++++
-- State Machine Id: 0
GET /argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: http/1.1 linuxkit-025000000001[c4db1edf-ee48-45a1-9b2e-c661a2ad63f8] (ApacheTrafficServer/9.0.0)
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_CACHE_ISSUE_WRITE
[Aug 22 23:02:49.873] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4640 (do_cache_prepare_action)> (http_cache_write) [0] writing to cache with URL http://127.0.0.1:62000/argh
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <P_CacheInternal.h:556 (new_CacheVC)> (cache_new) new 0x7f4888117c40
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <Cache.cc:3073 (key_to_vol)> (cache_hosting) Generic volume: 90028a78d for host: 127.0.0.1
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpCacheSM.cc:176 (state_cache_open_write)> (http_cache) [0] [&HttpCacheSM::state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, CACHE_EVENT_OPEN_WRITE]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2395 (state_cache_open_write)> (http) [0] [&HttpSM : state_cache_open_write, CACHE_EVENT_OPEN_WRITE]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:2931 (handle_cache_write_lock)> (http_trans) Next action next; nullptr
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_CACHE_ISSUE_WRITE -> SM_ACTION_ORIGIN_SERVER_OPEN
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4673 (do_http_server_open)> (http_track) entered inside do_http_server_open ][ipv4]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4704 (do_http_server_open)> (http) [0] open connection to 127.0.0.1: 127.0.0.1:62000
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4716 (do_http_server_open)> (http_seq) [HttpSM::do_http_server_open] Sending request to server
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSessionManager.cc:322 (acquire_session)> (http_ss) [acquire session] thread pool search failed
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:5024 (do_http_server_open)> (http) calling netProcessor.connect_re
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, NET_EVENT_OPEN]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1730 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1731 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, NET_EVENT_OPEN]
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpServerSession.cc:83 (new_connection)> (http_ss) [0] session born, netvc 0x7f48640199c0
[Aug 22 23:02:49.874] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1771 (state_http_server_open)> (http) [0] setting handler for TCP handshake
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_READY]
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1730 (state_http_server_open)> (http_track) entered inside state_http_server_open
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1731 (state_http_server_open)> (http) [0] [&HttpSM::state_http_server_open, VC_EVENT_WRITE_READY]
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1784 (state_http_server_open)> (http_ss) [0] TCP Handshake complete
+++++++++ Proxy's Request after hooks +++++++++
-- State Machine Id: 0
GET /argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
Via: http/1.1 linuxkit-025000000001[c4db1edf-ee48-45a1-9b2e-c661a2ad63f8] (ApacheTrafficServer/9.0.0)
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.875] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2003 (state_send_server_request_header)> (http) [0] [&HttpSM::state_send_server_request_header, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1845 (state_read_server_response_header)> (http) [0] [&HttpSM::state_read_server_response_header, VC_EVENT_READ_READY]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:1950 (state_read_server_response_header)> (http_seq) Done parsing server response header
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3119 (HandleResponse)> (http_trans) [0] [HttpTransact::HandleResponse]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3120 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response received
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3127 (HandleResponse)> (http_trans) [0] [HandleResponse] response_received_time: 1534978969
+++++++++ Incoming O.S. Response +++++++++
-- State Machine Id: 0
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:6328 (is_response_valid)> (http_trans) [0] [is_response_valid] No errors in response
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3144 (HandleResponse)> (http_seq) [0] [HttpTransact::HandleResponse] Response valid
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:5570 (initialize_state_variables_from_response)> (http_hdrs) [0] [initialize_state_variables_from_response]Server is keep-alive.
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3437 (handle_response_from_server)> (http_trans) [0] [handle_response_from_server] (hrfs)
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3449 (handle_response_from_server)> (http_trans) [0] [hrfs] connection alive
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3717 (handle_forward_server_connection_open)> (http_trans) [0] [handle_forward_server_connection_open] (hfsco)
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3718 (handle_forward_server_connection_open)> (http_seq) [0] [HttpTransact::handle_server_connection_open]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:4196 (do_hostdb_update_if_necessary)> (http) server info = 127.0.0.1:62000
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3804 (handle_forward_server_connection_open)> (http_trans) [0] [hfsco] cache action: CACHE_DO_WRITE
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3933 (handle_cache_operation_on_forward_server_response)> (http_trans) [0] [handle_cache_operation_on_forward_server_response] (hcoofsr)
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3934 (handle_cache_operation_on_forward_server_response)> (http_seq) [0] [handle_cache_operation_on_forward_server_response]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:6008 (is_response_cacheable)> (http_trans) [0] [is_response_cacheable] client permits storing
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:6065 (is_response_cacheable)> (http_trans) [0] [is_response_cacheable] YES by response cache control
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:3943 (handle_cache_operation_on_forward_server_response)> (http_trans) [0] [hcoofsr] response is cacheable
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:4086 (handle_cache_operation_on_forward_server_response)> (http_trans) [0] [hcoofsr] response code: 200
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:4276 (handle_cache_operation_on_forward_server_response)> (http_trans) [0] [hcoofsr] cache write
+++++++++ Cached Request Hdr +++++++++
-- State Machine Id: 0
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978969
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978969
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransact.cc:6567 (handle_content_length_header)> (http_trans) [0] [handle_content_length_header] RESPONSE cont len in hdr is 128
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: 1, Log: 3, Hier: 2
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 0
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 0
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
Age: 0
Proxy-Connection: keep-alive
Server: ATS/9.0.0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [0] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SERVER_READ
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:7597 (do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:6516 (setup_server_transfer)> (http) Setup Server Transfer
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [0] adding producer 'http server'
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [0] adding consumer 'user agent'
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:5731 (perform_cache_write_action)> (http) [0] perform_cache_write_action CACHE_DO_WRITE
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [0] adding consumer 'cache write'
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:1017 (producer_run)> (http_tunnel) [0] [tunnel_run] producer already done
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:1144 (producer_handler)> (http_tunnel) [0] producer_handler [http server HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [0 0 0] event: 2302
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2913 (tunnel_handler_server)> (http) [0] [&HttpSM::tunnel_handler_server, HTTP_TUNNEL_EVENT_PRECOMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpServerSession.cc:177 (release)> (http_ss) Releasing session, private_session=0, sharing_match=1
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSessionManager.cc:160 (releaseSession)> (http_ss) [0] [release session] session placed into shared pool
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <Cache.cc:370 (reenable)> (cache_reenable) reenable 0x7f4888117c40
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [0] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:3179 (tunnel_handler_ua)> (http) [0] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <ProxyClientTransaction.cc:67 (release)> (http_txn) [0] session released by sm [0]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:469 (release)> (http_cs) [0] initiating io for next header
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [0] consumer_handler [cache write VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:3394 (tunnel_handler_cache_write)> (http) [0] [&HttpSM::tunnel_handler_cache_write, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <Cache.cc:361 (do_io_close)> (cache_close) do_io_close 0x7f4888117c40 -1 1
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [0] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:2862 (tunnel_handler)> (http) [0] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:6866 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <HttpSM.cc:6892 (kill_this)> (http) [0] deallocating sm
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <CacheWrite.cc:1135 (openWriteCloseDir)> (cache_stats) Fragment = 0
[Aug 22 23:02:49.877] {0x7f48b41b8700} DEBUG: <P_CacheInternal.h:568 (free_CacheVC)> (cache_free) free 0x7f4888117c40
[Aug 22 23:02:49.904] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:415 (state_keep_alive)> (http_cs) [0] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS]
[Aug 22 23:02:49.904] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:316 (do_io_close)> (http_cs) [0] session closed
[Aug 22 23:02:49.904] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:93 (destroy)> (http_cs) [0] session destroy
[Aug 22 23:02:49.904] {0x7f48b41b8700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read..
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7f4864019ce0] accepted connection from 127.0.0.1:51510 transport type = 1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:199 (new_connection)> (http_cs) [1] session born, netvc 0x7f4864019ce0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:466 (release)> (http_cs) [1] data already in buffer, starting new transaction
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [1] Starting transaction 1 using sm [1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [1] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:603 (state_read_client_request_header)> (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:750 (state_read_client_request_header)> (http) [1] done parsing client request header
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:973 (ModifyRequest)> (http_trans) [1] START HttpTransact::ModifyRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1047 (ModifyRequest)> (http_trans) [1] END HttpTransact::ModifyRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1048 (ModifyRequest)> (http_trans) [1] Checking if transaction wants to upgrade
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1056 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:599 (StartRemapRequest)> (http_trans) [1] START HttpTransact::StartRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:619 (StartRemapRequest)> (http_trans) [1] Before Remapping:
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109e888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109eb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109e8b8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109eb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "www.ae-0.com", HOST_LEN: 12,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109e8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109e8f8, TAILBLK: 0x109e8f8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109e8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109e908), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "www.ae-0.com", V_LEN: 12,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 20, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109e928), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109e948), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109e968), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109e988), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2a", V_LEN: 2,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 7, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109e9a8), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "AlanWhatTheHell", V_LEN: 15,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 34, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:630 (StartRemapRequest)> (http_trans) [1] END HttpTransact::StartRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:637 (PerformRemap)> (http_trans) [1] Inside PerformRemap
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:638 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:3982 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:644 (EndRemapRequest)> (http_trans) [1] START HttpTransact::EndRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:650 (EndRemapRequest)> (http_trans) [1] EndRemapRequest host is 127.0.0.1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:788 (EndRemapRequest)> (http_trans) [1] After Remapping:
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109e888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109eb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109e8b8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109eb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109e8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109e8f8, TAILBLK: 0x109e8f8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109e8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109e908), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109e928), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109e948), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109e968), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109e988), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2a", V_LEN: 2,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 7, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109e9a8), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "AlanWhatTheHell", V_LEN: 15,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 34, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:807 (EndRemapRequest)> (http_trans) [1] END HttpTransact::EndRemapRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:813 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1093 (HandleRequest)> (http_trans) [1] START HttpTransact::HandleRequest
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:5108 (check_request_validity)> (http_trans) [1] [init_stat_vars_from_req] set req cont length to 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:6171 (is_request_valid)> (http_trans) [1] [is_request_valid] no request header errors
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1115 (HandleRequest)> (http_seq) [1] [HttpTransact::HandleRequest] request valid.
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109e888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109eb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109e8b8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109eb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109e8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109e8f8, TAILBLK: 0x109e8f8]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109e8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109e908), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109e928), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109e948), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109e968), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109e988), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "2a", V_LEN: 2,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 7, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109e9a8), LIVE
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "AlanWhatTheHell", V_LEN: 15,
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 34, F: 1]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 1
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
Proxy-Connection: Keep-Alive
N: 2a
Accept-Encoding: AlanWhatTheHell
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1819 (DecideCacheLookup)> (http_trans) [1] [DecideCacheLookup] Will do cache lookup.
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1820 (DecideCacheLookup)> (http_seq) [1] [DecideCacheLookup] Will do cache lookup
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:1863 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:4524 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [1] Issuing cache lookup for URL http://127.0.0.1:62000/argh
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <Cache.cc:3073 (key_to_vol)> (cache_hosting) Generic volume: 90028a78d for host: 127.0.0.1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <P_CacheInternal.h:556 (new_CacheVC)> (cache_new) new 0x7f4888117880
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <Cache.cc:2319 (handleReadDone)> (cache_read) Read complete on fragment 341F96F1FAF2DCFF8CC193F3826F7F32. Length: data payload=128 this fragment=2520 total doc=128 prefix=2392
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:180 (SelectFromAlternates)> (http_match) [SelectFromAlternates] # alternates = 1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:181 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] 1 alternates for this cached doc
[alts] There are 1 alternates for this request header.
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:345 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT CHARSET (not in request nor cache)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:856 (calculate_quality_of_accept_encoding_match)> (http_match) [calculate_quality_accept_encoding_match]: response hdr does not have content-encoding.
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:383 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT LANGUAGE (not in request nor cache)
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:396 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:397 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:398 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept 1.000000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:400 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:401 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:402 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept-Charset 1.001000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:404 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptEncoding match = 0.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:405 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptEncoding match = 0.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:406 (calculate_quality_of_match)> (http_alternate) Content-Encoding and Accept-Encoding 0.001000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:408 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:409 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:410 (calculate_quality_of_match)> (http_alternate) Content-Language and Accept-Language 1.001000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:412 (calculate_quality_of_match)> (http_alternate) Mult's Quality Factor: 0.001002
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:413 (calculate_quality_of_match)> (http_alternate) ----------End of Alternate----------
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:1185 (CalcVariability)> (http_match) Vary list of 1 elements
Str ["Accept-Encoding", len 15]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:1201 (CalcVariability)> (http_match) Vary: Accept-Encoding
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:461 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:462 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:463 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Returning final Q = 0.001002
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:464 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Returning final Q = 0.001002
[alts] ---- alternate #1 (Q = 0.001002) has these request/response hdrs:
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactCache.cc:252 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] Chosen alternate # 0
[alts] and the winner is alternate number 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <CacheRead.cc:1151 (openReadStartHead)> (cache_read) CacheReadStartHead - read 341F96F1FAF2DCFF8CC193F3826F7F32 target E433DCCC670A1B274035460021C0E568 - single 2520 of 128 bytes, 0 fragments
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpCacheSM.cc:116 (state_cache_open_read)> (http_cache) [1] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [1] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:2504 (state_cache_open_read)> (http) [1] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:2514 (state_cache_open_read)> (http) [1] cache_open_read - CACHE_EVENT_OPEN_READ
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2074 (HandleCacheOpenRead)> (http_trans) [1] [HttpTransact::HandleCacheOpenRead]
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2112 (HandleCacheOpenRead)> (http_trans) [1] CacheOpenRead -- hit
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2113 (HandleCacheOpenRead)> (http_trans) Next action SM_ACTION_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_API_READ_CACHE_HDR
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2266 (HandleCacheOpenReadHitFreshness)> (http_seq) [1] [HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2288 (HandleCacheOpenReadHitFreshness)> (http_trans) [1] [HandleCacheOpenReadHitFreshness] request_sent_time : 1534978969
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2289 (HandleCacheOpenReadHitFreshness)> (http_trans) [1] [HandleCacheOpenReadHitFreshness] response_received_time : 1534978969
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:6992 (calculate_document_freshness_limit)> (http_match) [1] calculate_document_freshness_limit --- max_age set, freshness_limit = 32000000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7084 (calculate_document_freshness_limit)> (http_match) [1] calculate_document_freshness_limit --- final freshness_limit = 31536000
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.101] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7164 (what_is_document_freshness)> (http_match) [1] [what_is_document_freshness] fresh_limit: 31536000 current_age: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7211 (what_is_document_freshness)> (http_match) [1] [..._document_freshness] initial age limit: 31536000
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7267 (what_is_document_freshness)> (http_match) [1] document_freshness --- current_age = 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7268 (what_is_document_freshness)> (http_match) [1] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7269 (what_is_document_freshness)> (http_match) [1] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7270 (what_is_document_freshness)> (http_seq) [1] document_freshness --- current_age = 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7271 (what_is_document_freshness)> (http_seq) [1] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7272 (what_is_document_freshness)> (http_seq) [1] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:7291 (what_is_document_freshness)> (http_match) [1] [..._document_freshness] document is fresh; returning FRESHNESS_FRESH
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2299 (HandleCacheOpenReadHitFreshness)> (http_seq) [1] [HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2380 (need_to_revalidate)> (http_seq) [1] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2330 (HandleCacheOpenReadHitFreshness)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; HttpTransact::HandleCacheOpenReadHit
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_READ_CACHE_HDR -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2478 (HandleCacheOpenReadHit)> (http_seq) [1] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2548 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- needs_auth = 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2549 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- needs_revalidate = 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2550 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- response_returnable = 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2551 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- needs_cache_auth = 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2552 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- send_revalidate = 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2659 (HandleCacheOpenReadHit)> (http_trans) [1] CacheOpenRead --- HIT-FRESH
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2661 (HandleCacheOpenReadHit)> (http_seq) [1] [HttpTransact::HandleCacheOpenReadHit] Serve from cache
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:2758 (build_response_from_cache)> (http_trans) [1] [build_response_from_cache] Match! Serving full document.
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransact.cc:6567 (handle_content_length_header)> (http_trans) [1] [handle_content_length_header] RESPONSE cont len in hdr is 128
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: 0, Log: 1, Hier: 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 1
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
Age: 1
Proxy-Connection: keep-alive
Server: ATS/9.0.0
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_SERVE_FROM_CACHE
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:5731 (perform_cache_write_action)> (http) [1] perform_cache_write_action CACHE_DO_SERVE
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:7597 (do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [1] adding producer 'cache read'
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [1] adding consumer 'user agent'
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:1144 (producer_handler)> (http_tunnel) [1] producer_handler [cache read VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:3354 (tunnel_handler_cache_read)> (http) [1] [&HttpSM::tunnel_handler_cache_read, VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <Cache.cc:361 (do_io_close)> (cache_close) do_io_close 0x7f4888117880 -1 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <P_CacheInternal.h:568 (free_CacheVC)> (cache_free) free 0x7f4888117880
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [1] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:3179 (tunnel_handler_ua)> (http) [1] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <ProxyClientTransaction.cc:67 (release)> (http_txn) [1] session released by sm [1]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:469 (release)> (http_cs) [1] initiating io for next header
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [1] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:2862 (tunnel_handler)> (http) [1] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:6866 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Aug 22 23:02:50.102] {0x7f48b552f700} DEBUG: <HttpSM.cc:6892 (kill_this)> (http) [1] deallocating sm
[Aug 22 23:02:50.133] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:415 (state_keep_alive)> (http_cs) [1] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS]
[Aug 22 23:02:50.133] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:316 (do_io_close)> (http_cs) [1] session closed
[Aug 22 23:02:50.133] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:93 (destroy)> (http_cs) [1] session destroy
[Aug 22 23:02:50.133] {0x7f48b552f700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read..
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7f4864019ce0] accepted connection from 127.0.0.1:51512 transport type = 1
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:199 (new_connection)> (http_cs) [2] session born, netvc 0x7f4864019ce0
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:466 (release)> (http_cs) [2] data already in buffer, starting new transaction
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [2] Starting transaction 1 using sm [2]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [2] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpSM.cc:603 (state_read_client_request_header)> (http) [2] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpSM.cc:750 (state_read_client_request_header)> (http) [2] done parsing client request header
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:973 (ModifyRequest)> (http_trans) [2] START HttpTransact::ModifyRequest
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1047 (ModifyRequest)> (http_trans) [2] END HttpTransact::ModifyRequest
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1048 (ModifyRequest)> (http_trans) [2] Checking if transaction wants to upgrade
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1056 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:599 (StartRemapRequest)> (http_trans) [2] START HttpTransact::StartRemapRequest
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HttpTransact.cc:619 (StartRemapRequest)> (http_trans) [2] Before Remapping:
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109d088: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109d308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109d0b8]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109d308: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "www.ae-0.com", HOST_LEN: 12,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109d0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000001, SLACC: 0xFFFFFFF2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109d0f8, TAILBLK: 0x109d0f8]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109d0f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 5, NEXTBLK: (nil)]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109d108), LIVE
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "www.ae-0.com", V_LEN: 12,
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 20, F: 1]
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.302] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109d128), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109d148), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109d168), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109d188), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "3", V_LEN: 1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:630 (StartRemapRequest)> (http_trans) [2] END HttpTransact::StartRemapRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:637 (PerformRemap)> (http_trans) [2] Inside PerformRemap
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:638 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:3982 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:644 (EndRemapRequest)> (http_trans) [2] START HttpTransact::EndRemapRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:650 (EndRemapRequest)> (http_trans) [2] EndRemapRequest host is 127.0.0.1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:788 (EndRemapRequest)> (http_trans) [2] After Remapping:
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109d088: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109d308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109d0b8]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109d308: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109d0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000001, SLACC: 0xFFFFFFF2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109d0f8, TAILBLK: 0x109d0f8]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109d0f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 5, NEXTBLK: (nil)]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109d108), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109d128), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109d148), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109d168), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109d188), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "3", V_LEN: 1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:807 (EndRemapRequest)> (http_trans) [2] END HttpTransact::EndRemapRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:813 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1093 (HandleRequest)> (http_trans) [2] START HttpTransact::HandleRequest
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:5108 (check_request_validity)> (http_trans) [2] [init_stat_vars_from_req] set req cont length to 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:6171 (is_request_valid)> (http_trans) [2] [is_request_valid] no request header errors
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1115 (HandleRequest)> (http_seq) [2] [HttpTransact::HandleRequest] request valid.
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109d088: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109d308, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109d0b8]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109d308: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109d0b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000001, SLACC: 0xFFFFFFF2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109d0f8, TAILBLK: 0x109d0f8]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109d0f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 5, NEXTBLK: (nil)]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109d108), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109d128), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109d148), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109d168), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109d188), LIVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "3", V_LEN: 1,
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 2
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
Proxy-Connection: Keep-Alive
N: 3
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1819 (DecideCacheLookup)> (http_trans) [2] [DecideCacheLookup] Will do cache lookup.
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1820 (DecideCacheLookup)> (http_seq) [2] [DecideCacheLookup] Will do cache lookup
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:1863 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:4524 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [2] Issuing cache lookup for URL http://127.0.0.1:62000/argh
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <Cache.cc:3073 (key_to_vol)> (cache_hosting) Generic volume: 90028a78d for host: 127.0.0.1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <P_CacheInternal.h:556 (new_CacheVC)> (cache_new) new 0x7f48881174c0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:180 (SelectFromAlternates)> (http_match) [SelectFromAlternates] # alternates = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:181 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] 1 alternates for this cached doc
[alts] There are 1 alternates for this request header.
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:345 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT CHARSET (not in request nor cache)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:383 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT LANGUAGE (not in request nor cache)
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:396 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:397 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:398 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept 1.000000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:400 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:401 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:402 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept-Charset 1.001000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:404 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptEncoding match = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:405 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptEncoding match = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:406 (calculate_quality_of_match)> (http_alternate) Content-Encoding and Accept-Encoding 1.000000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:408 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:409 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:410 (calculate_quality_of_match)> (http_alternate) Content-Language and Accept-Language 1.001000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:412 (calculate_quality_of_match)> (http_alternate) Mult's Quality Factor: 1.002001
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:413 (calculate_quality_of_match)> (http_alternate) ----------End of Alternate----------
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:1185 (CalcVariability)> (http_match) Vary list of 1 elements
Str ["Accept-Encoding", len 15]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:1201 (CalcVariability)> (http_match) Vary: Accept-Encoding
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:461 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:462 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:463 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Returning final Q = 1.002
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:464 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Returning final Q = 1.002
[alts] ---- alternate #1 (Q = 1.002) has these request/response hdrs:
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactCache.cc:252 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] Chosen alternate # 0
[alts] and the winner is alternate number 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <CacheRead.cc:1151 (openReadStartHead)> (cache_read) CacheReadStartHead - read 341F96F1FAF2DCFF8CC193F3826F7F32 target E433DCCC670A1B274035460021C0E568 - single 2520 of 128 bytes, 0 fragments
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpCacheSM.cc:116 (state_cache_open_read)> (http_cache) [2] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [2] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:2504 (state_cache_open_read)> (http) [2] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:2514 (state_cache_open_read)> (http) [2] cache_open_read - CACHE_EVENT_OPEN_READ
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2074 (HandleCacheOpenRead)> (http_trans) [2] [HttpTransact::HandleCacheOpenRead]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2112 (HandleCacheOpenRead)> (http_trans) [2] CacheOpenRead -- hit
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2113 (HandleCacheOpenRead)> (http_trans) Next action SM_ACTION_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_API_READ_CACHE_HDR
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2266 (HandleCacheOpenReadHitFreshness)> (http_seq) [2] [HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2288 (HandleCacheOpenReadHitFreshness)> (http_trans) [2] [HandleCacheOpenReadHitFreshness] request_sent_time : 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2289 (HandleCacheOpenReadHitFreshness)> (http_trans) [2] [HandleCacheOpenReadHitFreshness] response_received_time : 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:6992 (calculate_document_freshness_limit)> (http_match) [2] calculate_document_freshness_limit --- max_age set, freshness_limit = 32000000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7084 (calculate_document_freshness_limit)> (http_match) [2] calculate_document_freshness_limit --- final freshness_limit = 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7164 (what_is_document_freshness)> (http_match) [2] [what_is_document_freshness] fresh_limit: 31536000 current_age: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7211 (what_is_document_freshness)> (http_match) [2] [..._document_freshness] initial age limit: 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7267 (what_is_document_freshness)> (http_match) [2] document_freshness --- current_age = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7268 (what_is_document_freshness)> (http_match) [2] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7269 (what_is_document_freshness)> (http_match) [2] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7270 (what_is_document_freshness)> (http_seq) [2] document_freshness --- current_age = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7271 (what_is_document_freshness)> (http_seq) [2] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7272 (what_is_document_freshness)> (http_seq) [2] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:7291 (what_is_document_freshness)> (http_match) [2] [..._document_freshness] document is fresh; returning FRESHNESS_FRESH
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2299 (HandleCacheOpenReadHitFreshness)> (http_seq) [2] [HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2380 (need_to_revalidate)> (http_seq) [2] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2330 (HandleCacheOpenReadHitFreshness)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; HttpTransact::HandleCacheOpenReadHit
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_READ_CACHE_HDR -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2478 (HandleCacheOpenReadHit)> (http_seq) [2] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2548 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- needs_auth = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2549 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- needs_revalidate = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2550 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- response_returnable = 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2551 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- needs_cache_auth = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2552 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- send_revalidate = 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2659 (HandleCacheOpenReadHit)> (http_trans) [2] CacheOpenRead --- HIT-FRESH
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2661 (HandleCacheOpenReadHit)> (http_seq) [2] [HttpTransact::HandleCacheOpenReadHit] Serve from cache
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:2758 (build_response_from_cache)> (http_trans) [2] [build_response_from_cache] Match! Serving full document.
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransact.cc:6567 (handle_content_length_header)> (http_trans) [2] [handle_content_length_header] RESPONSE cont len in hdr is 128
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: B, Log: ., Hier: 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 2
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 2
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
Age: 1
Proxy-Connection: keep-alive
Server: ATS/9.0.0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [2] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_SERVE_FROM_CACHE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:5731 (perform_cache_write_action)> (http) [2] perform_cache_write_action CACHE_DO_SERVE
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:7597 (do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [2] adding producer 'cache read'
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [2] adding consumer 'user agent'
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:1144 (producer_handler)> (http_tunnel) [2] producer_handler [cache read VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:3354 (tunnel_handler_cache_read)> (http) [2] [&HttpSM::tunnel_handler_cache_read, VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <Cache.cc:361 (do_io_close)> (cache_close) do_io_close 0x7f48881174c0 -1 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <P_CacheInternal.h:568 (free_CacheVC)> (cache_free) free 0x7f48881174c0
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [2] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:3179 (tunnel_handler_ua)> (http) [2] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <ProxyClientTransaction.cc:67 (release)> (http_txn) [2] session released by sm [2]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:469 (release)> (http_cs) [2] initiating io for next header
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [2] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:2862 (tunnel_handler)> (http) [2] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:6866 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Aug 22 23:02:50.303] {0x7f48b542d700} DEBUG: <HttpSM.cc:6892 (kill_this)> (http) [2] deallocating sm
[Aug 22 23:02:50.330] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:415 (state_keep_alive)> (http_cs) [2] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS]
[Aug 22 23:02:50.330] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:316 (do_io_close)> (http_cs) [2] session closed
[Aug 22 23:02:50.330] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:93 (destroy)> (http_cs) [2] session destroy
[Aug 22 23:02:50.330] {0x7f48b542d700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.425] {0x7f48b532b700} DEBUG: <ProtocolProbeSessionAccept.cc:139 (mainEvent)> (http) probe needs data, read..
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSessionAccept.cc:58 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x7f4864019ce0] accepted connection from 127.0.0.1:51514 transport type = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:199 (new_connection)> (http_cs) [3] session born, netvc 0x7f4864019ce0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:466 (release)> (http_cs) [3] data already in buffer, starting new transaction
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <ProxyClientTransaction.cc:52 (new_transaction)> (http_txn) [3] Starting transaction 1 using sm [3]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [3] [HttpSM::main_handler, VC_EVENT_READ_READY]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:603 (state_read_client_request_header)> (http) [3] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:750 (state_read_client_request_header)> (http) [3] done parsing client request header
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:973 (ModifyRequest)> (http_trans) [3] START HttpTransact::ModifyRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1047 (ModifyRequest)> (http_trans) [3] END HttpTransact::ModifyRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1048 (ModifyRequest)> (http_trans) [3] Checking if transaction wants to upgrade
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1056 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:599 (StartRemapRequest)> (http_trans) [3] START HttpTransact::StartRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:619 (StartRemapRequest)> (http_trans) [3] Before Remapping:
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109b888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109bb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109b8b8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109bb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "www.ae-1.com", HOST_LEN: 12,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109b8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109b8f8, TAILBLK: 0x109b8f8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109b8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109b908), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "www.ae-1.com", V_LEN: 12,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 20, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109b928), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109b948), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109b968), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109b988), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "4", V_LEN: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109b9a8), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:630 (StartRemapRequest)> (http_trans) [3] END HttpTransact::StartRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:631 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:637 (PerformRemap)> (http_trans) [3] Inside PerformRemap
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:638 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:3982 (do_remap_request)> (http_seq) [HttpSM::do_remap_request] Remapping request
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:644 (EndRemapRequest)> (http_trans) [3] START HttpTransact::EndRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:650 (EndRemapRequest)> (http_trans) [3] EndRemapRequest host is 127.0.0.1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:788 (EndRemapRequest)> (http_trans) [3] After Remapping:
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109b888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109bb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109b8b8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109bb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109b8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109b8f8, TAILBLK: 0x109b8f8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109b8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109b908), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109b928), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109b948), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109b968), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109b988), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "4", V_LEN: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109b9a8), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:807 (EndRemapRequest)> (http_trans) [3] END HttpTransact::EndRemapRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:813 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1093 (HandleRequest)> (http_trans) [3] START HttpTransact::HandleRequest
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:5108 (check_request_validity)> (http_trans) [3] [init_stat_vars_from_req] set req cont length to 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:6171 (is_request_valid)> (http_trans) [3] [is_request_valid] no request header errors
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1115 (HandleRequest)> (http_seq) [3] [HttpTransact::HandleRequest] request valid.
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) HTTP_HEADER 0x109b888: [T: 3, L: 48, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HTTP.cc:570 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x109bb08, METHOD: "GET", METHOD_LEN: 3, FIELDS: 0x109b8b8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) URL 0x109bb08: [T: 2, L: 112, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1597 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1599 (url_describe)> (http) SCHEME: "http", SCHEME_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1600 (url_describe)> (http) USER: "", USER_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1602 (url_describe)> (http) PASSWORD: "", PASSWORD_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1603 (url_describe)> (http) HOST: "127.0.0.1", HOST_LEN: 9,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1605 (url_describe)> (http) PORT: "62000", PORT_LEN: 5, PORT_NUM: 62000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1606 (url_describe)> (http) PATH: "argh", PATH_LEN: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1608 (url_describe)> (http) PARAMS: "", PARAMS_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1610 (url_describe)> (http) QUERY: "", QUERY_LEN: 0,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <URL.cc:1612 (url_describe)> (http) FRAGMENT: "", FRAGMENT_LEN: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) MIME_HEADER 0x109b8b8: [T: 4, L: 592, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2694 (mime_hdr_describe)> (http)
[PBITS: 0x0008010001000005, SLACC: 0xFFFFF5F2FFFFFFFF3FFFFFFFFFF1FFFF, HEADBLK: 0x109b8f8, TAILBLK: 0x109b8f8]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2699 (mime_hdr_describe)> (http) [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HdrHeap.cc:56 (obj_describe)> (http) FIELD_BLOCK 0x109b8f8: [T: 5, L: 528, OBJFLAGS: 0]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2715 (mime_field_block_describe)> (http) [FREETOP: 6, NEXTBLK: (nil)]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 0 (0x109b908), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "127.0.0.1:62000", V_LEN: 15,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 23, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 1 (0x109b928), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "curl/7.59.0", V_LEN: 11,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 25, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 2 (0x109b948), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 3 (0x109b968), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Proxy-Connection", N_LEN: 16, N_IDX: 50,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "Keep-Alive", V_LEN: 10,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 30, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 4 (0x109b988), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "N", N_LEN: 1, N_IDX: -1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "4", V_LEN: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 6, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2719 (mime_field_block_describe)> (http) SLOT # 5 (0x109b9a8), LIVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2728 (mime_field_block_describe)> (http) [N: "Accept-Encoding", N_LEN: 15, N_IDX: 1,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2729 (mime_field_block_describe)> (http) V: "deflate", V_LEN: 7,
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2731 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 26, F: 1]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <MIME.cc:2734 (mime_field_block_describe)> (http)
+++++++++ Incoming Request +++++++++
-- State Machine Id: 3
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
Proxy-Connection: Keep-Alive
N: 4
Accept-Encoding: deflate
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1819 (DecideCacheLookup)> (http_trans) [3] [DecideCacheLookup] Will do cache lookup.
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1820 (DecideCacheLookup)> (http_seq) [3] [DecideCacheLookup] Will do cache lookup
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:1863 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_CACHE_LOOKUP; nullptr
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_CACHE_LOOKUP
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:4524 (do_cache_lookup_and_read)> (http_seq) [HttpSM::do_cache_lookup_and_read] [3] Issuing cache lookup for URL http://127.0.0.1:62000/argh
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Cache.cc:3073 (key_to_vol)> (cache_hosting) Generic volume: 90028a78d for host: 127.0.0.1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <P_CacheInternal.h:556 (new_CacheVC)> (cache_new) new 0x7f4888117100
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:180 (SelectFromAlternates)> (http_match) [SelectFromAlternates] # alternates = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:181 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] 1 alternates for this cached doc
[alts] There are 1 alternates for this request header.
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:345 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT CHARSET (not in request nor cache)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:844 (calculate_quality_of_accept_encoding_match)> (http_alternate) Exact match for ACCEPT ENCODING
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:383 (calculate_quality_of_match)> (http_alternate) Exact match for ACCEPT LANGUAGE (not in request nor cache)
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:396 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:397 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Accept match = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:398 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept 1.000000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:400 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:401 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptCharset match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:402 (calculate_quality_of_match)> (http_alternate) Content-Type and Accept-Charset 1.001000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:404 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptEncoding match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:405 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptEncoding match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:406 (calculate_quality_of_match)> (http_alternate) Content-Encoding and Accept-Encoding 1.001000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:408 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:409 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: AcceptLanguage match = 1.001
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:410 (calculate_quality_of_match)> (http_alternate) Content-Language and Accept-Language 1.001000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:412 (calculate_quality_of_match)> (http_alternate) Mult's Quality Factor: 1.003003
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:413 (calculate_quality_of_match)> (http_alternate) ----------End of Alternate----------
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:1185 (CalcVariability)> (http_match) Vary list of 1 elements
Str ["Accept-Encoding", len 15]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:1201 (CalcVariability)> (http_match) Vary: Accept-Encoding
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:461 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:462 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: CalcVariability says variability = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:463 (calculate_quality_of_match)> (http_match) CalcQualityOfMatch: Returning final Q = 1.003
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:464 (calculate_quality_of_match)> (http_seq) CalcQualityOfMatch: Returning final Q = 1.003
[alts] ---- alternate #1 (Q = 1.003) has these request/response hdrs:
GET http://127.0.0.1:62000/argh HTTP/1.1
Host: 127.0.0.1:62000
User-Agent: curl/7.59.0
Accept: */*
N: 2
Accept-Encoding: deflate
Client-ip: 127.0.0.1
X-Forwarded-For: 127.0.0.1
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactCache.cc:252 (SelectFromAlternates)> (http_seq) [SelectFromAlternates] Chosen alternate # 0
[alts] and the winner is alternate number 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <CacheRead.cc:1151 (openReadStartHead)> (cache_read) CacheReadStartHead - read 341F96F1FAF2DCFF8CC193F3826F7F32 target E433DCCC670A1B274035460021C0E568 - single 2520 of 128 bytes, 0 fragments
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpCacheSM.cc:116 (state_cache_open_read)> (http_cache) [3] [&HttpCacheSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [3] [HttpSM::main_handler, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:2504 (state_cache_open_read)> (http) [3] [&HttpSM::state_cache_open_read, CACHE_EVENT_OPEN_READ]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:2514 (state_cache_open_read)> (http) [3] cache_open_read - CACHE_EVENT_OPEN_READ
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2074 (HandleCacheOpenRead)> (http_trans) [3] [HttpTransact::HandleCacheOpenRead]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2112 (HandleCacheOpenRead)> (http_trans) [3] CacheOpenRead -- hit
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2113 (HandleCacheOpenRead)> (http_trans) Next action SM_ACTION_API_READ_CACHE_HDR; HandleCacheOpenReadHitFreshness
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_CACHE_LOOKUP -> SM_ACTION_API_READ_CACHE_HDR
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2266 (HandleCacheOpenReadHitFreshness)> (http_seq) [3] [HttpTransact::HandleCacheOpenReadHitFreshness] Hit in cache
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2288 (HandleCacheOpenReadHitFreshness)> (http_trans) [3] [HandleCacheOpenReadHitFreshness] request_sent_time : 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2289 (HandleCacheOpenReadHitFreshness)> (http_trans) [3] [HandleCacheOpenReadHitFreshness] response_received_time : 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:6992 (calculate_document_freshness_limit)> (http_match) [3] calculate_document_freshness_limit --- max_age set, freshness_limit = 32000000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7084 (calculate_document_freshness_limit)> (http_match) [3] calculate_document_freshness_limit --- final freshness_limit = 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7164 (what_is_document_freshness)> (http_match) [3] [what_is_document_freshness] fresh_limit: 31536000 current_age: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7211 (what_is_document_freshness)> (http_match) [3] [..._document_freshness] initial age limit: 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7267 (what_is_document_freshness)> (http_match) [3] document_freshness --- current_age = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7268 (what_is_document_freshness)> (http_match) [3] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7269 (what_is_document_freshness)> (http_match) [3] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7270 (what_is_document_freshness)> (http_seq) [3] document_freshness --- current_age = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7271 (what_is_document_freshness)> (http_seq) [3] document_freshness --- age_limit = 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7272 (what_is_document_freshness)> (http_seq) [3] document_freshness --- fresh_limit = 31536000
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:7291 (what_is_document_freshness)> (http_match) [3] [..._document_freshness] document is fresh; returning FRESHNESS_FRESH
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2299 (HandleCacheOpenReadHitFreshness)> (http_seq) [3] [HttpTransact::HandleCacheOpenReadHitFreshness] Fresh copy
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2380 (need_to_revalidate)> (http_seq) [3] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2330 (HandleCacheOpenReadHitFreshness)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; HttpTransact::HandleCacheOpenReadHit
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_API_READ_CACHE_HDR -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2478 (HandleCacheOpenReadHit)> (http_seq) [3] [HttpTransact::HandleCacheOpenReadHit] Authentication not needed
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2548 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- needs_auth = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2549 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- needs_revalidate = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2550 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- response_returnable = 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2551 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- needs_cache_auth = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2552 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- send_revalidate = 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2659 (HandleCacheOpenReadHit)> (http_trans) [3] CacheOpenRead --- HIT-FRESH
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2661 (HandleCacheOpenReadHit)> (http_seq) [3] [HttpTransact::HandleCacheOpenReadHit] Serve from cache
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:2758 (build_response_from_cache)> (http_trans) [3] [build_response_from_cache] Match! Serving full document.
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:438 (calculate_document_age)> (http_age) [calculate_document_age] age_value: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:439 (calculate_document_age)> (http_age) [calculate_document_age] date_value: 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:440 (calculate_document_age)> (http_age) [calculate_document_age] response_time: 1534978969
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:441 (calculate_document_age)> (http_age) [calculate_document_age] now: 1534978970
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:442 (calculate_document_age)> (http_age) [calculate_document_age] now (fixed): 1534978970
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:443 (calculate_document_age)> (http_age) [calculate_document_age] apparent_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:444 (calculate_document_age)> (http_age) [calculate_document_age] corrected_received_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:445 (calculate_document_age)> (http_age) [calculate_document_age] response_delay: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:446 (calculate_document_age)> (http_age) [calculate_document_age] corrected_initial_age: 0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:447 (calculate_document_age)> (http_age) [calculate_document_age] resident_time: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:448 (calculate_document_age)> (http_age) [calculate_document_age] current_age: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransact.cc:6567 (handle_content_length_header)> (http_trans) [3] [handle_content_length_header] RESPONSE cont len in hdr is 128
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:638 (generate_and_set_squid_codes)> (http_trans) [Squid code generation] Hit/Miss: B, Log: ., Hier: 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTransactHeaders.cc:1220 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.0.0
+++++++++ Base Header for Building Response +++++++++
-- State Machine Id: 3
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
+++++++++ Proxy's Response 2 +++++++++
-- State Machine Id: 3
HTTP/1.1 200 OK
Cache-Control: max-age=32000000
Vary: Accept-Encoding
Content-Length: 128
Date: Wed, 22 Aug 2018 23:02:49 GMT
Age: 1
Proxy-Connection: keep-alive
Server: ATS/9.0.0
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7143 (call_transact_and_set_next_state)> (http) [3] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_SERVE_FROM_CACHE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:5731 (perform_cache_write_action)> (http) [3] perform_cache_write_action CACHE_DO_SERVE
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:7597 (do_redirect)> (http_redirect) [HttpSM::do_redirect]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:655 (add_producer)> (http_tunnel) [3] adding producer 'cache read'
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:710 (add_consumer)> (http_tunnel) [3] adding consumer 'user agent'
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:757 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:1144 (producer_handler)> (http_tunnel) [3] producer_handler [cache read VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:1188 (producer_handler)> (http_redirect) [HttpTunnel::producer_handler] enable_redirection: [1 0 0] event: 102
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:3354 (tunnel_handler_cache_read)> (http) [3] [&HttpSM::tunnel_handler_cache_read, VC_EVENT_READ_COMPLETE]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Cache.cc:361 (do_io_close)> (cache_close) do_io_close 0x7f4888117100 -1 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <P_CacheInternal.h:568 (free_CacheVC)> (cache_free) free 0x7f4888117100
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpTunnel.cc:1350 (consumer_handler)> (http_tunnel) [3] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <HttpSM.cc:3179 (tunnel_handler_ua)> (http) [3] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <ProxyClientTransaction.cc:67 (release)> (http_txn) [3] session released by sm [3]
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:02:50.426] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:469 (release)> (http_cs) [3] initiating io for next header
[Aug 22 23:02:50.427] {0x7f48b532b700} DEBUG: <HttpSM.cc:2573 (main_handler)> (http) [3] [HttpSM::main_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.427] {0x7f48b532b700} DEBUG: <HttpSM.cc:2862 (tunnel_handler)> (http) [3] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Aug 22 23:02:50.427] {0x7f48b532b700} DEBUG: <HttpSM.cc:8059 (clear)> (http_redirect) [PostDataBuffers::clear]
[Aug 22 23:02:50.427] {0x7f48b532b700} DEBUG: <HttpSM.cc:6866 (kill_this)> (http_seq) [HttpSM::update_stats] Logging transaction
[Aug 22 23:02:50.427] {0x7f48b532b700} DEBUG: <HttpSM.cc:6892 (kill_this)> (http) [3] deallocating sm
[Aug 22 23:02:50.456] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:415 (state_keep_alive)> (http_cs) [3] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS]
[Aug 22 23:02:50.456] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:316 (do_io_close)> (http_cs) [3] session closed
[Aug 22 23:02:50.456] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:93 (destroy)> (http_cs) [3] session destroy
[Aug 22 23:02:50.456] {0x7f48b532b700} DEBUG: <Http1ClientSession.cc:229 (do_io_write)> (http_cs) tcp_init_cwnd_set 1
[Aug 22 23:03:20.611] {0x7f48b41b8700} DEBUG: <HttpSessionManager.cc:218 (eventHandler)> (http_ss) [0] [session_pool] session 0x7f4888124f40 received io notice [VC_EVENT_EOS]
[Aug 22 23:03:20.611] {0x7f48b41b8700} DEBUG: <HttpServerSession.cc:150 (do_io_close)> (http_ss) [0] session close: nevtc 0x7f48640199c0
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment