diff --git a/iocore/cache/CacheRead.cc b/iocore/cache/CacheRead.cc index 7f77ed2fa1c..6e11a6074d9 100644 --- a/iocore/cache/CacheRead.cc +++ b/iocore/cache/CacheRead.cc @@ -27,11 +27,15 @@ #include "HttpCacheSM.h" //Added to get the scope of HttpCacheSM object. #endif +#define DebugCache(fmt, ...) DebugSpecific(cont->cont_debug_on, "cache_read", "[%" PRId64 "] " fmt, cont->cont_sm_id, __VA_ARGS__) +#define DebugCacheVC(fmt, ...) DebugSpecific(_action.continuation->cont_debug_on, "cache_read", "[%" PRId64 "] " fmt, _action.continuation->cont_sm_id, __VA_ARGS__) + extern int cache_config_compatibility_4_2_0_fixup; Action * Cache::open_read(Continuation *cont, const CacheKey *key, CacheFragType type, const char *hostname, int host_len) { + DebugCache("%s", "Cache::open_read"); if (!CacheProcessor::IsCacheReady(type)) { cont->handleEvent(CACHE_EVENT_OPEN_READ_FAILED, (void *)-ECACHE_NOT_READY); return ACTION_RESULT_DONE; @@ -95,6 +99,7 @@ Action * Cache::open_read(Continuation *cont, const CacheKey *key, CacheHTTPHdr *request, CacheLookupHttpConfig *params, CacheFragType type, const char *hostname, int host_len) { + DebugCache("%s", "Cache::open_read (with params)"); if (!CacheProcessor::IsCacheReady(type)) { cont->handleEvent(CACHE_EVENT_OPEN_READ_FAILED, (void *)-ECACHE_NOT_READY); return ACTION_RESULT_DONE; @@ -164,6 +169,8 @@ Cache::open_read(Continuation *cont, const CacheKey *key, CacheHTTPHdr *request, uint32_t CacheVC::load_http_info(CacheHTTPInfoVector *info, Doc *doc, RefCountObj *block_ptr) { + DebugCacheVC("%s", "Cache::load_http_info"); + uint32_t zret = info->get_handles(doc->hdr(), doc->hlen, block_ptr); if (cache_config_compatibility_4_2_0_fixup && // manual override not engaged !this->f.doc_from_ram_cache && // it's already been done for ram cache fragments @@ -179,6 +186,7 @@ CacheVC::load_http_info(CacheHTTPInfoVector *info, Doc *doc, RefCountObj *block_ int CacheVC::openReadFromWriterFailure(int event, Event *e) { + DebugCacheVC("%s", "CacheVC::openReadFromWriterFailure"); od = nullptr; vector.clear(false); CACHE_INCREMENT_DYN_STAT(cache_read_failure_stat); @@ -191,15 +199,19 @@ CacheVC::openReadFromWriterFailure(int event, Event *e) int CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadChooseWriter"); intptr_t err = ECACHE_DOC_BUSY; CacheVC *w = nullptr; ink_assert(vol->mutex->thread_holding == mutex->thread_holding && write_vc == nullptr); - if (!od) + if (!od) { + DebugCacheVC("%s", "CacheVC::openReadChooseWriter, no OpenDirEntry"); return EVENT_RETURN; + } if (frag_type != CACHE_FRAG_TYPE_HTTP) { + DebugCacheVC("%s", "CacheVC::openReadChooseWriter, not an HTTP fragment"); ink_assert(od->num_writers == 1); w = od->writers.head; if (w->start_time > start_time || w->closed < 0) { @@ -212,22 +224,35 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE } #ifdef HTTP_CACHE else { + DebugCacheVC("%s", "CacheVC::openReadChooseWriter, dealing with an HTTP fragment"); write_vector = &od->vector; int write_vec_cnt = write_vector->count(); - for (int c = 0; c < write_vec_cnt; c++) + DebugCacheVC("CacheVC::openReadChooseWriter, write_vec_cnt = %d", write_vec_cnt); + for (int c = 0; c < write_vec_cnt; c++) { vector.insert(write_vector->get(c)); + } // check if all the writers who came before this reader have // set the http_info. for (w = (CacheVC *)od->writers.head; w; w = (CacheVC *)w->opendir_link.next) { - if (w->start_time > start_time || w->closed < 0) + DebugCacheVC("%s checking writer.., w->start_time = %d, start_time = %d, w->closed = %d", "CacheVC::openReadChooseWriter", + w->start_time, start_time, w->closed); + if (w->start_time > start_time || w->closed < 0) { continue; + } + + DebugCacheVC("%s checking writer.., cache_config_read_while_writer = %d", "CacheVC::openReadChooseWriter", + cache_config_read_while_writer); if (!w->closed && !cache_config_read_while_writer) { return -err; } - if (w->alternate_index != CACHE_ALT_INDEX_DEFAULT) + + if (w->alternate_index != CACHE_ALT_INDEX_DEFAULT) { + DebugCacheVC("%s alternate index isn't default", "CacheVC::openReadChooseWriter"); continue; + } if (!w->closed && !w->alternate.valid()) { + DebugCacheVC("%s w isn't closed and w->alternate is not valid??", "CacheVC::openReadChooseWriter"); od = nullptr; ink_assert(!write_vc); vector.clear(false); @@ -236,6 +261,8 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE // construct the vector from the writers. int alt_ndx = CACHE_ALT_INDEX_DEFAULT; if (w->f.update) { + DebugCacheVC("%s constructing vector from the writers", "CacheVC::openReadChooseWriter"); + // all Update cases. Need to get the alternate index. alt_ndx = get_alternate_index(&vector, w->update_key); // if its an alternate delete @@ -246,8 +273,11 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE } } - if (w->alternate.valid()) + if (w->alternate.valid()) { + DebugCacheVC("%s constructing vector from the writers", "CacheVC::openReadChooseWriter"); + vector.insert(&w->alternate, alt_ndx); + } } if (!vector.count()) { @@ -255,20 +285,31 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE // the writer(s) are reading the vector, so there is probably // an old vector. Since this reader came before any of the // current writers, we should return the old data + + DebugCacheVC("%s writers are reading the vector, return old data", "CacheVC::openReadChooseWriter"); od = nullptr; return EVENT_RETURN; } + + DebugCacheVC("%s no doc! (vector count is 0)", "CacheVC::openReadChooseWriter"); return -ECACHE_NO_DOC; } if (cache_config_select_alternate) { + DebugCacheVC("%s selecting from alternates..", "CacheVC::openReadChooseWriter"); alternate_index = HttpTransactCache::SelectFromAlternates(&vector, &request, params); - if (alternate_index < 0) + if (alternate_index < 0) { + DebugCacheVC("%s cache miss!", "CacheVC::openReadChooseWriter"); return -ECACHE_ALT_MISS; - } else + } + } else { alternate_index = 0; + } CacheHTTPInfo *obj = vector.get(alternate_index); + DebugCacheVC("%s got HTTP cache info for alternate index %d", "CacheVC::openReadChooseWriter", alternate_index); + for (w = (CacheVC *)od->writers.head; w; w = (CacheVC *)w->opendir_link.next) { if (obj->m_alt == w->alternate.m_alt) { + DebugCacheVC("%s found write_vc", "CacheVC::openReadChooseWriter"); write_vc = w; break; } @@ -290,6 +331,7 @@ CacheVC::openReadChooseWriter(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSE int CacheVC::openReadFromWriter(int event, Event *e) { + DebugCacheVC("%s", "CacheVC::openReadFromWriter"); if (!f.read_from_writer_called) { // The assignment to last_collision as nullptr was // made conditional after INKqa08411 @@ -323,18 +365,27 @@ CacheVC::openReadFromWriter(int event, Event *e) if (!write_vc) { int ret = openReadChooseWriter(event, e); if (ret < 0) { + DebugCacheVC("%s got error code, releasing lock", "openReadFromWriter"); MUTEX_RELEASE(lock); + DebugCacheVC("%s setting handler to openReadFromWriterFailure", "openReadFromWriter"); SET_HANDLER(&CacheVC::openReadFromWriterFailure); + DebugCacheVC("%s calling openReadFromWriterFailure with CACHE_EVENT_OPEN_READ_FAILED", "openReadFromWriter"); return openReadFromWriterFailure(CACHE_EVENT_OPEN_READ_FAILED, reinterpret_cast(ret)); } else if (ret == EVENT_RETURN) { + DebugCacheVC("%s got EVENT_RETURN, releasing lock", "openReadFromWriter"); MUTEX_RELEASE(lock); + DebugCacheVC("%s setting handler to openReadStartHead", "openReadFromWriter"); SET_HANDLER(&CacheVC::openReadStartHead); return openReadStartHead(event, e); } else if (ret == EVENT_CONT) { + DebugCacheVC("%s got EVENT_CONT. writer_lock_retry = %d, max_retries = %d", "openReadFromWriter", + writer_lock_retry, cache_config_read_while_writer_max_retries); ink_assert(!write_vc); if (writer_lock_retry < cache_config_read_while_writer_max_retries) { + DebugCacheVC("%s scheduling retry, current try is %d / %d", "openReadFromWriter", writer_lock_retry, cache_config_read_while_writer_max_retries); VC_SCHED_WRITER_RETRY(); } else { + DebugCacheVC("%s returning failure", "openReadFromWriter"); return openReadFromWriterFailure(CACHE_EVENT_OPEN_READ_FAILED, (Event *)-err); } } else @@ -469,6 +520,7 @@ CacheVC::openReadFromWriter(int event, Event *e) int CacheVC::openReadFromWriterMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadFromWriterMain"); cancel_trigger(); if (seek_to) { vio.ndone = seek_to; @@ -513,6 +565,7 @@ CacheVC::openReadFromWriterMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNU int CacheVC::openReadClose(int event, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadClose"); cancel_trigger(); if (is_io_in_progress()) { if (event != AIO_EVENT_DONE) @@ -537,6 +590,7 @@ CacheVC::openReadClose(int event, Event * /* e ATS_UNUSED */) int CacheVC::openReadReadDone(int event, Event *e) { + DebugCacheVC("%s", "CacheVC::openReadReadDone"); Doc *doc = nullptr; cancel_trigger(); @@ -616,6 +670,7 @@ CacheVC::openReadReadDone(int event, Event *e) int CacheVC::openReadMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadMain"); cancel_trigger(); Doc *doc = (Doc *)buf->data(); int64_t ntodo = vio.ntodo(); @@ -780,6 +835,7 @@ Lread : { int CacheVC::openReadStartEarliest(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadStartEarliest"); int ret = 0; Doc *doc = nullptr; cancel_trigger(); @@ -921,6 +977,7 @@ CacheVC::openReadStartEarliest(int /* event ATS_UNUSED */, Event * /* e ATS_UNUS int CacheVC::openReadVecWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { + DebugCacheVC("%s", "CacheVC::openReadVecWrite"); cancel_trigger(); set_io_not_in_progress(); ink_assert(od); @@ -974,6 +1031,7 @@ CacheVC::openReadVecWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */ int CacheVC::openReadStartHead(int event, Event *e) { + DebugCacheVC("%s", "CacheVC::openReadStartHead starting"); intptr_t err = ECACHE_NO_DOC; Doc *doc = nullptr; cancel_trigger(); @@ -981,19 +1039,26 @@ CacheVC::openReadStartHead(int event, Event *e) if (_action.cancelled) return free_CacheVC(this); { + DebugCacheVC("%s", "openReadStartHead try lock..."); CACHE_TRY_LOCK(lock, vol->mutex, mutex->thread_holding); - if (!lock.is_locked()) + if (!lock.is_locked()) { + DebugCacheVC("%s", "openReadStartHead try lock... failed! scheduling retry..."); VC_SCHED_LOCK_RETRY(); - if (!buf) + DebugCacheVC("%s", "openReadStartHead try lock... failed! scheduling retry... done!"); + } + if (!buf) { goto Lread; - if (!io.ok()) + } + if (!io.ok()) { goto Ldone; + } // an object needs to be outside the aggregation window in order to be // be evacuated as it is read if (!dir_agg_valid(vol, &dir)) { // a directory entry which is nolonger valid may have been overwritten - if (!dir_valid(vol, &dir)) + if (!dir_valid(vol, &dir)) { last_collision = nullptr; + } goto Lread; } doc = (Doc *)buf->data(); @@ -1015,18 +1080,23 @@ CacheVC::openReadStartHead(int event, Event *e) last_collision = nullptr; goto Lread; } - if (!(doc->first_key == key)) + if (!(doc->first_key == key)) { goto Lread; - if (f.lookup) + } + if (f.lookup) { goto Lookup; + } earliest_dir = dir; #ifdef HTTP_CACHE CacheHTTPInfo *alternate_tmp; if (frag_type == CACHE_FRAG_TYPE_HTTP) { + DebugCacheVC("%s", "openReadStartHead dealing with an HTTP fragment"); + uint32_t uml; ink_assert(doc->hlen); - if (!doc->hlen) + if (!doc->hlen) { goto Ldone; + } if ((uml = this->load_http_info(&vector, doc)) != doc->hlen) { if (buf) { HTTPCacheAlt *alt = reinterpret_cast(doc->hdr()); @@ -1119,6 +1189,7 @@ CacheVC::openReadStartHead(int event, Event *e) goto Lsuccess; Lread: + DebugCacheVC("%s", "openReadStartHead: in Lread"); // check for collision // INKqa07684 - Cache::lookup returns CACHE_EVENT_OPEN_READ_FAILED. // don't want to go through this BS of reading from a writer if @@ -1144,6 +1215,7 @@ CacheVC::openReadStartHead(int event, Event *e) } } Ldone: + DebugCacheVC("openReadStartHead: in Ldone, f.lookup is %d", f.lookup); if (!f.lookup) { CACHE_INCREMENT_DYN_STAT(cache_read_failure_stat); _action.continuation->handleEvent(CACHE_EVENT_OPEN_READ_FAILED, (void *)-err); @@ -1153,15 +1225,19 @@ CacheVC::openReadStartHead(int event, Event *e) } return free_CacheVC(this); Lcallreturn: + DebugCacheVC("%s", "openReadStartHead: in Lcallreturn"); return handleEvent(AIO_EVENT_DONE, nullptr); // hopefully a tail call Lsuccess: + DebugCacheVC("%s", "openReadStartHead: in Lsuccess"); SET_HANDLER(&CacheVC::openReadMain); return callcont(CACHE_EVENT_OPEN_READ); Lookup: + DebugCacheVC("%s", "openReadStartHead: in Lookup"); CACHE_INCREMENT_DYN_STAT(cache_lookup_success_stat); _action.continuation->handleEvent(CACHE_EVENT_LOOKUP, nullptr); return free_CacheVC(this); Learliest: + DebugCacheVC("%s", "openReadStartHead: in Learliest"); first_buf = buf; buf = nullptr; earliest_key = key; diff --git a/iocore/cache/P_CacheInternal.h b/iocore/cache/P_CacheInternal.h index e70460b107b..deeeff90be7 100644 --- a/iocore/cache/P_CacheInternal.h +++ b/iocore/cache/P_CacheInternal.h @@ -90,9 +90,15 @@ struct EvacuationBlock; do { \ ink_assert(!trigger); \ writer_lock_retry++; \ - ink_hrtime _t = HRTIME_MSECONDS(cache_read_while_writer_retry_delay); \ - if (writer_lock_retry > 2) \ - _t = HRTIME_MSECONDS(cache_read_while_writer_retry_delay) * 2; \ + int delay; \ + ink_hrtime _t; \ + if (writer_lock_retry > 2) { \ + delay = cache_read_while_writer_retry_delay * 2; \ + } else { \ + delay = cache_read_while_writer_retry_delay; \ + } \ + DebugCacheVC("scheduling retry in %d ms", delay); \ + _t = HRTIME_MSECONDS(delay); \ trigger = mutex->thread_holding->schedule_in_local(this, _t); \ return EVENT_CONT; \ } while (0) diff --git a/iocore/eventsystem/I_Continuation.h b/iocore/eventsystem/I_Continuation.h index 496fbe46ebe..0cf9eee5565 100644 --- a/iocore/eventsystem/I_Continuation.h +++ b/iocore/eventsystem/I_Continuation.h @@ -133,6 +133,9 @@ class Continuation : private force_VFPT_to_top */ ContFlags control_flags; + int64_t cont_sm_id; + bool cont_debug_on; + /** Receives the event code and data for an Event. diff --git a/proxy/http/HttpCacheSM.cc b/proxy/http/HttpCacheSM.cc index 7ad75a5269c..0fbbb63172e 100644 --- a/proxy/http/HttpCacheSM.cc +++ b/proxy/http/HttpCacheSM.cc @@ -34,10 +34,12 @@ #include "HttpSM.h" #include "HttpDebugNames.h" +#include "ts/ink_hrtime.h" + #define STATE_ENTER(state_name, event) \ { \ REMEMBER(event, -1); \ - Debug("http_cache", "[%" PRId64 "] [%s, %s]", master_sm->sm_id, #state_name, HttpDebugNames::get_event_name(event)); \ + DebugSM("http_cache", "[%" PRId64 "] [%s, %s]", master_sm->sm_id, #state_name, HttpDebugNames::get_event_name(event)); \ } #define __REMEMBER(x) #x @@ -45,6 +47,8 @@ #define REMEMBER(e, r) master_sm->add_history_entry(__FILE__ ":" _REMEMBER(__LINE__), e, r); +#define DebugSM(tag, ...) DebugSpecific(master_sm->debug_on, tag, __VA_ARGS__) + HttpCacheAction::HttpCacheAction() : sm(nullptr) { } @@ -121,6 +125,8 @@ HttpCacheSM::state_cache_open_read(int event, void *data) switch (event) { case CACHE_EVENT_OPEN_READ: + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_read] it's time for openRead", master_sm->sm_id); + HTTP_INCREMENT_DYN_STAT(http_current_cache_connections_stat); ink_assert((cache_read_vc == nullptr) || master_sm->t_state.redirect_info.redirect_in_process); if (cache_read_vc) { @@ -134,6 +140,8 @@ HttpCacheSM::state_cache_open_read(int event, void *data) case CACHE_EVENT_OPEN_READ_FAILED: if ((intptr_t)data == -ECACHE_DOC_BUSY) { + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_read] openRead failed with ECACHE_DOC_BUSY", master_sm->sm_id); + // Somebody else is writing the object if (open_read_tries <= master_sm->t_state.txn_conf->max_cache_open_read_retries) { // Retry to read; maybe the update finishes in time @@ -146,6 +154,9 @@ HttpCacheSM::state_cache_open_read(int event, void *data) master_sm->handleEvent(event, data); } } else { + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_read] simple miss in the cache", + master_sm->sm_id); + // Simple miss in the cache. open_read_cb = true; master_sm->handleEvent(event, data); @@ -157,7 +168,7 @@ HttpCacheSM::state_cache_open_read(int event, void *data) // than or equal to the max number of open read retries, // else treat as a cache miss. ink_assert(open_read_tries <= master_sm->t_state.txn_conf->max_cache_open_read_retries || write_locked); - Debug("http_cache", "[%" PRId64 "] [state_cache_open_read] cache open read failure %d. " + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_read] cache open read failure %d. " "retrying cache open read...", master_sm->sm_id, open_read_tries); @@ -195,7 +206,7 @@ HttpCacheSM::state_cache_open_write(int event, void *data) } else { // The cache is hosed or full or something. // Forward the failure to the main sm - Debug("http_cache", "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " "done retrying...", master_sm->sm_id, open_write_tries); open_write_cb = true; @@ -207,7 +218,7 @@ HttpCacheSM::state_cache_open_write(int event, void *data) // Retry the cache open write if the number retries is less // than or equal to the max number of open write retries ink_assert(open_write_tries <= master_sm->t_state.txn_conf->max_cache_open_write_retries); - Debug("http_cache", "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_write] cache open write failure %d. " "retrying cache open write...", master_sm->sm_id, open_write_tries); @@ -228,6 +239,9 @@ void HttpCacheSM::do_schedule_in() { ink_assert(pending_action == nullptr); + + DebugSM("http_cache", "[%" PRId64 "] [state_cache_open_read] scheduling next openRead in %" PRId64 " milliseconds", + master_sm->sm_id, master_sm->t_state.txn_conf->cache_open_read_retry_time); Action *action_handle = mutex->thread_holding->schedule_in(this, HRTIME_MSECONDS(master_sm->t_state.txn_conf->cache_open_read_retry_time)); @@ -250,8 +264,15 @@ HttpCacheSM::do_cache_open_read(const HttpCacheKey &key) } // Initialising read-while-write-inprogress flag this->readwhilewrite_inprogress = false; + + ink_hrtime start_time = ink_get_hrtime_internal(); + + DebugSM("http_cache", "[%" PRId64 "] [do_cache_open_read] trying openRead, readwhilewrite_inprogress = %d", master_sm->sm_id, this->readwhilewrite_inprogress); + DebugSM("http_cache", "[%" PRId64 "] [do_cache_open_read] trying openRead, btw master_sm->cont_sm_id is %d and this->cont_sm_id is %d", master_sm->sm_id, master_sm->cont_sm_id, this->cont_sm_id); Action *action_handle = cacheProcessor.open_read(this, &key, master_sm->t_state.cache_control.cluster_cache_local, this->read_request_hdr, this->read_config, this->read_pin_in_cache); + DebugSM("http_cache", "[%" PRId64 "] [do_cache_open_read] trying openRead... done! took %d milliseconds", master_sm->sm_id, + (int)ink_hrtime_diff_msec(start_time, ink_get_hrtime_internal())); if (action_handle != ACTION_RESULT_DONE) { pending_action = action_handle; diff --git a/proxy/http/HttpCacheSM.h b/proxy/http/HttpCacheSM.h index 190c60820bc..6f7924e1f9a 100644 --- a/proxy/http/HttpCacheSM.h +++ b/proxy/http/HttpCacheSM.h @@ -62,6 +62,11 @@ class HttpCacheSM : public Continuation init(HttpSM *sm_arg, Ptr &amutex) { master_sm = sm_arg; + if (master_sm) { + cont_sm_id = ((Continuation *)master_sm)->cont_sm_id; + cont_debug_on = ((Continuation *)master_sm)->cont_debug_on; + } + mutex = amutex; captive_action.init(this); } diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc index 0ca5f0988ee..e74f65bc7f9 100644 --- a/proxy/http/HttpSM.cc +++ b/proxy/http/HttpSM.cc @@ -402,6 +402,9 @@ HttpSM::init() // Leaving sm_id as int64_t to minimize code changes. sm_id = (int64_t)ink_atomic_increment((&next_sm_id), 1); + + cont_sm_id = sm_id; + t_state.state_machine_id = sm_id; t_state.state_machine = this; @@ -568,6 +571,8 @@ HttpSM::attach_client_session(ProxyClientTransaction *client_vc, IOBufferReader debug_on = true; } + cont_debug_on = debug_on; + start_sub_sm(); // Allocate a user agent entry in the state machine's @@ -869,11 +874,14 @@ HttpSM::state_watch_for_client_abort(int event, void *data) // We got an early EOS. NetVConnection *netvc = ua_session->get_netvc(); if (ua_session->allow_half_open()) { + DebugSM("http", "[%" PRId64 "] got early EOS, half-open allowed", sm_id); if (netvc) { + DebugSM("http", "[%" PRId64 "] got early EOS, half-open allowed, doing IO_SHUTDOWN_READ", sm_id); netvc->do_io_shutdown(IO_SHUTDOWN_READ); } ua_entry->eos = true; } else { + DebugSM("http", "[%" PRId64 "] got early EOS, half-open NOT allowed", sm_id); ua_session->do_io_close(); ua_buffer_reader = nullptr; vc_table.cleanup_entry(ua_entry); @@ -4602,12 +4610,14 @@ HttpSM::do_cache_lookup_and_read() c_url = t_state.cache_info.lookup_url; } - DebugSM("http_seq", "[HttpSM::do_cache_lookup_and_read] [%" PRId64 "] Issuing cache lookup for URL %s", sm_id, - c_url->string_get(&t_state.arena)); - HttpCacheKey key; Cache::generate_key(&key, c_url, t_state.txn_conf->cache_generation_number); + char keyHex[33]; + + DebugSM("http_seq", "[HttpSM::do_cache_lookup_and_read] [%" PRId64 "] Issuing cache lookup for URL %s, hash key %s", sm_id, + c_url->string_get(&t_state.arena), key.hash.toHexStr(keyHex)); + Action *cache_action_handle = cache_sm.open_read(&key, c_url, &t_state.hdr_info.client_request, &(t_state.cache_info.config), (time_t)((t_state.cache_control.pin_in_cache_for < 0) ? 0 : t_state.cache_control.pin_in_cache_for));