This is an automated email from the ASF dual-hosted git repository. wkaras pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push: new 6b0d5a4184 Remove deprecated debug output functions from 14 source files. (#9658) 6b0d5a4184 is described below commit 6b0d5a4184c1f948d4759942c8dc362d8b2b3a44 Author: Walt Karas <wka...@yahooinc.com> AuthorDate: Mon May 1 12:55:53 2023 -0500 Remove deprecated debug output functions from 14 source files. (#9658) --- iocore/cache/CacheHosting.cc | 32 +++--- iocore/cache/CachePages.cc | 22 ++-- iocore/cache/CacheVol.cc | 49 +++++---- iocore/cache/Store.cc | 24 +++-- iocore/cache/test/main.cc | 13 ++- iocore/cache/test/main.h | 3 +- iocore/cache/test/test_RWW.cc | 29 ++---- iocore/dns/DNS.cc | 169 ++++++++++++++++--------------- iocore/dns/DNSConnection.cc | 9 +- iocore/dns/P_DNSProcessor.h | 15 +-- iocore/dns/SplitDNS.cc | 30 ++++-- iocore/eventsystem/UnixEventProcessor.cc | 26 +++-- 12 files changed, 240 insertions(+), 181 deletions(-) diff --git a/iocore/cache/CacheHosting.cc b/iocore/cache/CacheHosting.cc index b5713bf83a..3a47fce40a 100644 --- a/iocore/cache/CacheHosting.cc +++ b/iocore/cache/CacheHosting.cc @@ -32,6 +32,14 @@ extern int gndisks; +namespace +{ + +DbgCtl dbg_ctl_cache_hosting{"cache_hosting"}; +DbgCtl dbg_ctl_matcher{"matcher"}; + +} // end anonymous namespace + /************************************************************* * Begin class HostMatcher *************************************************************/ @@ -169,7 +177,7 @@ CacheHostMatcher::NewEntry(matcher_line *line_info) memset(static_cast<void *>(cur_d), 0, sizeof(CacheHostRecord)); return; } - Debug("cache_hosting", "hostname: %s, host record: %p", match_data, cur_d); + Dbg(dbg_ctl_cache_hosting, "hostname: %s, host record: %p", match_data, cur_d); // Fill in the matching info host_lookup->NewEntry(match_data, (line_info->type == MATCH_DOMAIN) ? true : false, cur_d); @@ -384,7 +392,7 @@ CacheHostTable::BuildTableFromString(const char *config_file_path, char *file_bu ink_assert(second_pass == numEntries); - if (is_debug_tag_set("matcher")) { + if (is_dbg_ctl_enabled(dbg_ctl_matcher)) { Print(); } return numEntries; @@ -426,7 +434,7 @@ CacheHostRecord::Init(CacheType typ) CacheVol *cachep = cp_list.head; for (; cachep; cachep = cachep->link.next) { if (cachep->scheme == type) { - Debug("cache_hosting", "Host Record: %p, Volume: %d, size: %" PRId64, this, cachep->vol_number, (int64_t)cachep->size); + Dbg(dbg_ctl_cache_hosting, "Host Record: %p, Volume: %d, size: %" PRId64, this, cachep->vol_number, (int64_t)cachep->size); cp[num_cachevols] = cachep; num_cachevols++; num_vols += cachep->num_vols; @@ -517,8 +525,8 @@ CacheHostRecord::Init(matcher_line *line_info, CacheType typ) if (cachep->vol_number == volume_number) { is_vol_present = 1; if (cachep->scheme == type) { - Debug("cache_hosting", "Host Record: %p, Volume: %d, size: %ld", this, volume_number, - (long)(cachep->size * STORE_BLOCK_SIZE)); + Dbg(dbg_ctl_cache_hosting, "Host Record: %p, Volume: %d, size: %ld", this, volume_number, + (long)(cachep->size * STORE_BLOCK_SIZE)); cp[num_cachevols] = cachep; num_cachevols++; num_vols += cachep->num_vols; @@ -780,8 +788,8 @@ ConfigVolumes::BuildListFromString(char *config_file_path, char *file_buf) } else { ink_release_assert(!"Unexpected non-HTTP cache volume"); } - Debug("cache_hosting", "added volume=%d, scheme=%d, size=%d percent=%d, ramcache enabled=%d", volume_number, scheme, size, - in_percent, ramcache_enabled); + Dbg(dbg_ctl_cache_hosting, "added volume=%d, scheme=%d, size=%d percent=%d, ramcache enabled=%d", volume_number, scheme, size, + in_percent, ramcache_enabled); } tmp = bufTok.iterNext(&i_state); @@ -1045,14 +1053,14 @@ execute_and_verify(RegressionTest *t) for (int i = 0; i < gndisks; i++) { CacheDisk *d = gdisks[i]; - if (is_debug_tag_set("cache_hosting")) { - Debug("cache_hosting", "Disk: %d: Vol Blocks: %u: Free space: %" PRIu64, i, d->header->num_diskvol_blks, d->free_space); + if (is_dbg_ctl_enabled(dbg_ctl_cache_hosting)) { + Dbg(dbg_ctl_cache_hosting, "Disk: %d: Vol Blocks: %u: Free space: %" PRIu64, i, d->header->num_diskvol_blks, d->free_space); for (int j = 0; j < static_cast<int>(d->header->num_volumes); j++) { - Debug("cache_hosting", "\tVol: %d Size: %" PRIu64, d->disk_vols[j]->vol_number, d->disk_vols[j]->size); + Dbg(dbg_ctl_cache_hosting, "\tVol: %d Size: %" PRIu64, d->disk_vols[j]->vol_number, d->disk_vols[j]->size); } for (int j = 0; j < static_cast<int>(d->header->num_diskvol_blks); j++) { - Debug("cache_hosting", "\tBlock No: %d Size: %" PRIu64 " Free: %u", d->header->vol_info[j].number, - d->header->vol_info[j].len, d->header->vol_info[j].free); + Dbg(dbg_ctl_cache_hosting, "\tBlock No: %d Size: %" PRIu64 " Free: %u", d->header->vol_info[j].number, + d->header->vol_info[j].len, d->header->vol_info[j].free); } } } diff --git a/iocore/cache/CachePages.cc b/iocore/cache/CachePages.cc index 836368da6f..7d52e8ee64 100644 --- a/iocore/cache/CachePages.cc +++ b/iocore/cache/CachePages.cc @@ -26,6 +26,12 @@ #include "Show.h" #include "I_Tasks.h" #include "CacheControl.h" +namespace +{ + +DbgCtl dbg_ctl_cache_inspector{"cache_inspector"}; + +} // end anonymous namespace struct ShowCache : public ShowCont { enum scan_type { @@ -92,8 +98,8 @@ struct ShowCache : public ShowCont { query_len = unescapifyStr(query); - Debug("cache_inspector", "query params: '%s' len %d [unescaped]", unescapedQuery, query_len); - Debug("cache_inspector", "query params: '%s' len %d [escaped]", query, query_len); + Dbg(dbg_ctl_cache_inspector, "query params: '%s' len %d [unescaped]", unescapedQuery, query_len); + Dbg(dbg_ctl_cache_inspector, "query params: '%s' len %d [escaped]", query, query_len); // remove 'C-m' s unsigned l, m; @@ -140,15 +146,15 @@ struct ShowCache : public ShowCont { } } - Debug("cache_inspector", "there were %d url(s) passed in", nstrings == 1 ? 1 : nstrings - 1); + Dbg(dbg_ctl_cache_inspector, "there were %d url(s) passed in", nstrings == 1 ? 1 : nstrings - 1); for (unsigned i = 0; i < nstrings; i++) { if (show_cache_urlstrs[i][0] == '\0') { continue; } - Debug("cache_inspector", "URL %d: '%s'", i + 1, show_cache_urlstrs[i]); + Dbg(dbg_ctl_cache_inspector, "URL %d: '%s'", i + 1, show_cache_urlstrs[i]); unescapifyStr(show_cache_urlstrs[i]); - Debug("cache_inspector", "URL %d: '%s'", i + 1, show_cache_urlstrs[i]); + Dbg(dbg_ctl_cache_inspector, "URL %d: '%s'", i + 1, show_cache_urlstrs[i]); } } @@ -617,7 +623,7 @@ ShowCache::handleCacheScanCallback(int event, Event *e) int erroffset; pcre *preq = pcre_compile(show_cache_urlstrs[s], 0, &error, &erroffset, nullptr); - Debug("cache_inspector", "matching url '%s' '%s' with regex '%s'", m, xx, show_cache_urlstrs[s]); + Dbg(dbg_ctl_cache_inspector, "matching url '%s' '%s' with regex '%s'", m, xx, show_cache_urlstrs[s]); if (preq) { int r = pcre_exec(preq, nullptr, xx, ib, 0, 0, nullptr, 0); @@ -662,7 +668,7 @@ ShowCache::handleCacheScanCallback(int event, Event *e) } } else { // TODO: Regex didn't compile, show errors ? - Debug("cache_inspector", "regex '%s' didn't compile", show_cache_urlstrs[s]); + Dbg(dbg_ctl_cache_inspector, "regex '%s' didn't compile", show_cache_urlstrs[s]); } } return res; @@ -677,7 +683,7 @@ ShowCache::handleCacheScanCallback(int event, Event *e) } } CHECK_SHOW(show("<H3>Done</H3>\n")); - Debug("cache_inspector", "scan done"); + Dbg(dbg_ctl_cache_inspector, "scan done"); complete(event, e); return EVENT_DONE; case CACHE_EVENT_SCAN_FAILED: diff --git a/iocore/cache/CacheVol.cc b/iocore/cache/CacheVol.cc index b9d3a1b8f3..607e335f71 100644 --- a/iocore/cache/CacheVol.cc +++ b/iocore/cache/CacheVol.cc @@ -26,10 +26,18 @@ #define SCAN_BUF_SIZE RECOVERY_SIZE #define SCAN_WRITER_LOCK_MAX_RETRY 5 +namespace +{ + +DbgCtl dbg_ctl_cache_scan{"cache_scan"}; +DbgCtl dbg_ctl_cache_scan_truss{"cache_scan_truss"}; + +} // end anonymous namespace + Action * Cache::scan(Continuation *cont, const char *hostname, int host_len, int KB_per_second) { - Debug("cache_scan_truss", "inside scan"); + Dbg(dbg_ctl_cache_scan_truss, "inside scan"); if (!CacheProcessor::IsCacheReady(CACHE_FRAG_TYPE_HTTP)) { cont->handleEvent(CACHE_EVENT_SCAN_FAILED, nullptr); return ACTION_RESULT_DONE; @@ -53,7 +61,7 @@ Cache::scan(Continuation *cont, const char *hostname, int host_len, int KB_per_s int CacheVC::scanVol(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { - Debug("cache_scan_truss", "inside %p:scanVol", this); + Dbg(dbg_ctl_cache_scan_truss, "inside %p:scanVol", this); if (_action.cancelled) { return free_CacheVC(this); } @@ -164,7 +172,7 @@ make_vol_map(Vol *vol) int CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { - Debug("cache_scan_truss", "inside %p:scanObject", this); + Dbg(dbg_ctl_cache_scan_truss, "inside %p:scanObject", this); Doc *doc = nullptr; void *result = nullptr; @@ -182,7 +190,7 @@ CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) CACHE_TRY_LOCK(lock, vol->mutex, mutex->thread_holding); if (!lock.is_locked()) { - Debug("cache_scan_truss", "delay %p:scanObject", this); + Dbg(dbg_ctl_cache_scan_truss, "delay %p:scanObject", this); mutex->thread_holding->schedule_in_local(this, HRTIME_MSECONDS(cache_config_mutex_retry_delay)); return EVENT_CONT; } @@ -198,7 +206,7 @@ CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) io.aiocb.aio_buf = buf->data(); io.action = this; io.thread = AIO_CALLBACK_THREAD_ANY; - Debug("cache_scan_truss", "read %p:scanObject", this); + Dbg(dbg_ctl_cache_scan_truss, "read %p:scanObject", this); goto Lread; } @@ -227,7 +235,7 @@ CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) if (doc->magic != DOC_MAGIC) { next_object_len = CACHE_BLOCK_SIZE; - Debug("cache_scan_truss", "blockskip %p:scanObject", this); + Dbg(dbg_ctl_cache_scan_truss, "blockskip %p:scanObject", this); continue; } @@ -275,7 +283,7 @@ CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) if (!hostinfo_copied) { memccpy(hname, vector.get(i)->request_get()->host_get(&hlen), 0, 500); hname[hlen] = 0; - Debug("cache_scan", "hostname = '%s', hostlen = %d", hname, hlen); + Dbg(dbg_ctl_cache_scan, "hostname = '%s', hostlen = %d", hname, hlen); hostinfo_copied = true; } vector.get(i)->object_key_get(&key); @@ -357,9 +365,9 @@ CacheVC::scanObject(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) scan_fix_buffer_offset = partial_object_len; } else { // Normal case, where we ended on a object boundary. io.aiocb.aio_offset += (reinterpret_cast<char *>(doc) - buf->data()) + next_object_len; - Debug("cache_scan_truss", "next %p:scanObject %" PRId64, this, (int64_t)io.aiocb.aio_offset); + Dbg(dbg_ctl_cache_scan_truss, "next %p:scanObject %" PRId64, this, (int64_t)io.aiocb.aio_offset); io.aiocb.aio_offset = next_in_map(vol, scan_vol_map, io.aiocb.aio_offset); - Debug("cache_scan_truss", "next_in_map %p:scanObject %" PRId64, this, (int64_t)io.aiocb.aio_offset); + Dbg(dbg_ctl_cache_scan_truss, "next_in_map %p:scanObject %" PRId64, this, (int64_t)io.aiocb.aio_offset); io.aiocb.aio_nbytes = SCAN_BUF_SIZE; io.aiocb.aio_buf = buf->data(); scan_fix_buffer_offset = 0; @@ -379,11 +387,12 @@ Lread: } offset = 0; ink_assert(ink_aio_read(&io) >= 0); - Debug("cache_scan_truss", "read %p:scanObject %" PRId64 " %zu", this, (int64_t)io.aiocb.aio_offset, (size_t)io.aiocb.aio_nbytes); + Dbg(dbg_ctl_cache_scan_truss, "read %p:scanObject %" PRId64 " %zu", this, (int64_t)io.aiocb.aio_offset, + (size_t)io.aiocb.aio_nbytes); return EVENT_CONT; Ldone: - Debug("cache_scan_truss", "done %p:scanObject", this); + Dbg(dbg_ctl_cache_scan_truss, "done %p:scanObject", this); _action.continuation->handleEvent(CACHE_EVENT_SCAN_DONE, result); Lcancel: return free_CacheVC(this); @@ -392,8 +401,8 @@ Lcancel: int CacheVC::scanRemoveDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { - Debug("cache_scan_truss", "inside %p:scanRemoveDone", this); - Debug("cache_scan", "remove done."); + Dbg(dbg_ctl_cache_scan_truss, "inside %p:scanRemoveDone", this); + Dbg(dbg_ctl_cache_scan, "remove done."); alternate.destroy(); SET_HANDLER(&CacheVC::scanObject); return handleEvent(EVENT_IMMEDIATE, nullptr); @@ -402,12 +411,12 @@ CacheVC::scanRemoveDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) int CacheVC::scanOpenWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { - Debug("cache_scan_truss", "inside %p:scanOpenWrite", this); + Dbg(dbg_ctl_cache_scan_truss, "inside %p:scanOpenWrite", this); cancel_trigger(); // get volume lock if (writer_lock_retry > SCAN_WRITER_LOCK_MAX_RETRY) { int r = _action.continuation->handleEvent(CACHE_EVENT_SCAN_OPERATION_BLOCKED, nullptr); - Debug("cache_scan", "still haven't got the writer lock, asking user.."); + Dbg(dbg_ctl_cache_scan, "still haven't got the writer lock, asking user.."); switch (r) { case CACHE_SCAN_RESULT_RETRY: writer_lock_retry = 0; @@ -421,11 +430,11 @@ CacheVC::scanOpenWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { CACHE_TRY_LOCK(lock, vol->mutex, mutex->thread_holding); if (!lock.is_locked()) { - Debug("cache_scan", "vol->mutex %p:scanOpenWrite", this); + Dbg(dbg_ctl_cache_scan, "vol->mutex %p:scanOpenWrite", this); VC_SCHED_LOCK_RETRY(); } - Debug("cache_scan", "trying for writer lock"); + Dbg(dbg_ctl_cache_scan, "trying for writer lock"); if (vol->open_write(this, false, 1)) { writer_lock_retry++; SET_HANDLER(&CacheVC::scanOpenWrite); @@ -443,7 +452,7 @@ CacheVC::scanOpenWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) vector.clear(false); // check that the directory entry was not overwritten // if so return failure - Debug("cache_scan", "got writer lock"); + Dbg(dbg_ctl_cache_scan, "got writer lock"); Dir *l = nullptr; Dir d; Doc *doc = reinterpret_cast<Doc *>(buf->data() + offset); @@ -467,7 +476,7 @@ CacheVC::scanOpenWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) return handleEvent(EVENT_IMMEDIATE, nullptr); } if (memcmp(&dir, &d, SIZEOF_DIR)) { - Debug("cache_scan", "dir entry has changed"); + Dbg(dbg_ctl_cache_scan, "dir entry has changed"); continue; } break; @@ -491,7 +500,7 @@ CacheVC::scanOpenWrite(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) int CacheVC::scanUpdateDone(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { - Debug("cache_scan_truss", "inside %p:scanUpdateDone", this); + Dbg(dbg_ctl_cache_scan_truss, "inside %p:scanUpdateDone", this); cancel_trigger(); // get volume lock CACHE_TRY_LOCK(lock, vol->mutex, mutex->thread_holding); diff --git a/iocore/cache/Store.cc b/iocore/cache/Store.cc index b85c517583..4a24447949 100644 --- a/iocore/cache/Store.cc +++ b/iocore/cache/Store.cc @@ -40,6 +40,13 @@ const char Store::VOLUME_KEY[] = "volume"; const char Store::HASH_BASE_STRING_KEY[] = "id"; +namespace +{ + +DbgCtl dbg_ctl_cache_init{"cache_init"}; + +} // end anonymous namespace + static span_error_t make_span_error(int error) { @@ -311,7 +318,7 @@ Store::read_config() ats_scoped_str storage_path(RecConfigReadConfigPath(nullptr, ts::filename::STORAGE)); Note("%s loading ...", ts::filename::STORAGE); - Debug("cache_init", "Store::read_config, fd = -1, \"%s\"", (const char *)storage_path); + Dbg(dbg_ctl_cache_init, "Store::read_config, fd = -1, \"%s\"", (const char *)storage_path); fd = ::open(storage_path, O_RDONLY); if (fd < 0) { Error("%s failed to load", ts::filename::STORAGE); @@ -340,7 +347,7 @@ Store::read_config() } // parse - Debug("cache_init", "Store::read_config: \"%s\"", path); + Dbg(dbg_ctl_cache_init, "Store::read_config: \"%s\"", path); ++n_disks_in_config; int64_t size = -1; @@ -378,10 +385,10 @@ Store::read_config() std::string pp = Layout::get()->relative(path); ns = new Span; - Debug("cache_init", "Store::read_config - ns = new Span; ns->init(\"%s\",%" PRId64 "), forced volume=%d%s%s", pp.c_str(), size, - volume_num, seed ? " id=" : "", seed ? seed : ""); + Dbg(dbg_ctl_cache_init, "Store::read_config - ns = new Span; ns->init(\"%s\",%" PRId64 "), forced volume=%d%s%s", pp.c_str(), + size, volume_num, seed ? " id=" : "", seed ? seed : ""); if ((err = ns->init(pp.c_str(), size))) { - Debug("cache_init", "Store::read_config - could not initialize storage \"%s\" [%s]", pp.c_str(), err); + Dbg(dbg_ctl_cache_init, "Store::read_config - could not initialize storage \"%s\" [%s]", pp.c_str(), err); delete ns; continue; } @@ -569,9 +576,10 @@ Span::init(const char *path, int64_t size) this->set_mmapable(ink_file_is_mmappable(S_ISDIR(sbuf.st_mode) ? static_cast<mode_t>(S_IFREG) : sbuf.st_mode)); this->pathname = ats_strdup(path); - Debug("cache_init", "initialized span '%s'", this->pathname.get()); - Debug("cache_init", "hw_sector_size=%d, size=%" PRId64 ", blocks=%" PRId64 ", disk_id=%" PRId64 "/%" PRId64 ", file_pathname=%d", - this->hw_sector_size, this->size(), this->blocks, this->disk_id[0], this->disk_id[1], this->file_pathname); + Dbg(dbg_ctl_cache_init, "initialized span '%s'", this->pathname.get()); + Dbg(dbg_ctl_cache_init, + "hw_sector_size=%d, size=%" PRId64 ", blocks=%" PRId64 ", disk_id=%" PRId64 "/%" PRId64 ", file_pathname=%d", + this->hw_sector_size, this->size(), this->blocks, this->disk_id[0], this->disk_id[1], this->file_pathname); return nullptr; diff --git a/iocore/cache/test/main.cc b/iocore/cache/test/main.cc index ab8d2c72cb..1d1657361a 100644 --- a/iocore/cache/test/main.cc +++ b/iocore/cache/test/main.cc @@ -31,6 +31,13 @@ #define THREADS 1 #define DIAGS_LOG_FILE "diags.log" +namespace +{ + +DbgCtl dbg_ctl_cache_test{"cache test"}; + +} // end anonymous namespace + // Create a new temp directory and return it std::string temp_prefix() @@ -45,7 +52,7 @@ temp_prefix() auto prefix = swoc::file::path(mkdtemp(buffer)); bool result = swoc::file::create_directories(prefix / "var" / "trafficserver", err, 0755); if (!result) { - Debug("cache test", "Failed to create directories for test: %s(%s)", prefix.c_str(), err.message().c_str()); + Dbg(dbg_ctl_cache_test, "Failed to create directories for test: %s(%s)", prefix.c_str(), err.message().c_str()); } ink_assert(result); @@ -222,7 +229,7 @@ CacheWriteTest::do_io_write(size_t size) int CacheWriteTest::start_test(int event, void *e) { - Debug("cache test", "start write test"); + Dbg(dbg_ctl_cache_test, "start write test"); HttpCacheKey key; key = generate_key(this->info); @@ -289,7 +296,7 @@ CacheReadTest::do_io_read(size_t size) int CacheReadTest::start_test(int event, void *e) { - Debug("cache test", "start read test"); + Dbg(dbg_ctl_cache_test, "start read test"); HttpCacheKey key; key = generate_key(this->info); diff --git a/iocore/cache/test/main.h b/iocore/cache/test/main.h index 1bda1920e1..6ceb55e6f9 100644 --- a/iocore/cache/test/main.h +++ b/iocore/cache/test/main.h @@ -75,7 +75,8 @@ public: int start_event(int event, void *e) { - Debug("cache_test", "cache init successfully"); + static DbgCtl dbg_ctl{"cache_test"}; + Dbg(dbg_ctl, "cache init successfully"); this->cache_init_success_callback(event, e); return 0; } diff --git a/iocore/cache/test/test_RWW.cc b/iocore/cache/test/test_RWW.cc index dab2f60719..7f7f826a54 100644 --- a/iocore/cache/test/test_RWW.cc +++ b/iocore/cache/test/test_RWW.cc @@ -28,6 +28,13 @@ #include "main.h" +namespace +{ + +DbgCtl dbg_ctl_cache_rww_test{"cache_rww_test"}; + +} // end anonymous namespace + class CacheRWWTest; class CacheRWWTest : public CacheTestHandler @@ -144,7 +151,7 @@ CacheRWWTest::process_read_event(int event, CacheTestBase *base) base->do_io_read(); break; case VC_EVENT_READ_READY: - Debug("cache_rww_test", "cache read reenable"); + Dbg(dbg_ctl_cache_rww_test, "cache read reenable"); this->_read_event = nullptr; this->_is_read_start = true; break; @@ -211,7 +218,7 @@ public: break; case VC_EVENT_WRITE_READY: if (this->_size != SMALL_FILE && !this->_wt->vc->fragment) { - Debug("cache_rww_test", "cache write reenable"); + Dbg(dbg_ctl_cache_rww_test, "cache write reenable"); base->reenable(); return; } @@ -297,22 +304,6 @@ class CacheRWWEOSTest : public CacheRWWTest { public: CacheRWWEOSTest(size_t size, const char *url = DEFAULT_URL) : CacheRWWTest(size, url) {} - /* - * test this code in openReadMain - * if (writer_done()) { - last_collision = nullptr; - while (dir_probe(&earliest_key, vol, &dir, &last_collision)) { - // write complete. this could be reached the size we set in do_io_write or someone call do_io_close with -1 (-1 means write - success) flag if (dir_offset(&dir) == dir_offset(&earliest_dir)) { DDebug("cache_read_agg", "%p: key: %X ReadMain complete: %d", - this, first_key.slice32(1), (int)vio.ndone); doc_len = vio.ndone; goto Leos; - } - } - // writer abort. server crash. someone call do_io_close() with error flag - DDebug("cache_read_agg", "%p: key: %X ReadMain writer aborted: %d", this, first_key.slice32(1), (int)vio.ndone); - goto Lerror; - } - * - */ void process_write_event(int event, CacheTestBase *base) override @@ -323,7 +314,7 @@ public: break; case VC_EVENT_WRITE_READY: if (this->_size != SMALL_FILE && !this->_wt->vc->fragment) { - Debug("cache_rww_test", "cache write reenable"); + Dbg(dbg_ctl_cache_rww_test, "cache write reenable"); base->reenable(); return; } diff --git a/iocore/dns/DNS.cc b/iocore/dns/DNS.cc index a3737b21c5..6a4a016561 100644 --- a/iocore/dns/DNS.cc +++ b/iocore/dns/DNS.cc @@ -59,6 +59,10 @@ DNS_CONN_MODE dns_conn_mode = DNS_CONN_MODE::UDP_ONLY; namespace { +DbgCtl dbg_ctl_dns{"dns"}; +DbgCtl dbg_ctl_dns_pas{"dns_pas"}; +DbgCtl dbg_ctl_dns_srv{"dns_srv"}; + const int tcp_data_length_offset = 2; // Currently only used for A and AAAA. @@ -286,21 +290,21 @@ void DNSProcessor::dns_init() { gethostname(try_server_names[0], 255); - Debug("dns", "localhost=%s", try_server_names[0]); - Debug("dns", "Round-robin nameservers = %d", dns_ns_rr); + Dbg(dbg_ctl_dns, "localhost=%s", try_server_names[0]); + Dbg(dbg_ctl_dns, "Round-robin nameservers = %d", dns_ns_rr); IpEndpoint nameserver[MAX_NAMED]; size_t nserv = 0; if (dns_ns_list) { - Debug("dns", "Nameserver list specified \"%s\"", dns_ns_list); + Dbg(dbg_ctl_dns, "Nameserver list specified \"%s\"", dns_ns_list); int i; char *last; char *ns_list = ats_strdup(dns_ns_list); char *ns = strtok_r(ns_list, " ,;\t\r", &last); for (i = 0, nserv = 0; (i < MAX_NAMED) && ns; ++i) { - Debug("dns", "Nameserver list - parsing \"%s\"", ns); + Dbg(dbg_ctl_dns, "Nameserver list - parsing \"%s\"", ns); bool err = false; int prt = DOMAIN_SERVICE_PORT; char *colon = nullptr; // where the port colon is. @@ -323,14 +327,14 @@ DNSProcessor::dns_init() *colon = '\0'; // coverity[secure_coding] if (sscanf(colon + 1, "%d%*s", &prt) != 1) { - Debug("dns", "Unable to parse port number '%s' for nameserver '%s', discardin.", colon + 1, ns); + Dbg(dbg_ctl_dns, "Unable to parse port number '%s' for nameserver '%s', discardin.", colon + 1, ns); Warning("Unable to parse port number '%s' for nameserver '%s', discarding.", colon + 1, ns); err = true; } } if (!err && 0 != ats_ip_pton(ns, &nameserver[nserv].sa)) { - Debug("dns", "Invalid IP address given for nameserver '%s', discarding", ns); + Dbg(dbg_ctl_dns, "Invalid IP address given for nameserver '%s', discarding", ns); Warning("Invalid IP address given for nameserver '%s', discarding", ns); err = true; } @@ -340,7 +344,7 @@ DNSProcessor::dns_init() ats_ip_port_cast(&nameserver[nserv].sa) = htons(prt); - Debug("dns", "Adding nameserver %s to nameserver list", ats_ip_nptop(&nameserver[nserv].sa, buff, sizeof(buff))); + Dbg(dbg_ctl_dns, "Adding nameserver %s to nameserver list", ats_ip_nptop(&nameserver[nserv].sa, buff, sizeof(buff))); ++nserv; } @@ -501,7 +505,7 @@ DNSHandler::open_con(sockaddr const *target, bool failed, int icon, bool over_tc } DNSConnection &cur_con = over_tcp ? tcpcon[icon] : udpcon[icon]; - Debug("dns", "open_con: opening connection %s", ats_ip_nptop(target, ip_text, sizeof ip_text)); + Dbg(dbg_ctl_dns, "open_con: opening connection %s", ats_ip_nptop(target, ip_text, sizeof ip_text)); if (cur_con.fd != NO_FD) { // Remove old FD from epoll fd cur_con.close(); @@ -514,7 +518,7 @@ DNSHandler::open_con(sockaddr const *target, bool failed, int icon, bool over_tc .setBindRandomPort(true) .setLocalIpv6(&local_ipv6.sa) .setLocalIpv4(&local_ipv4.sa)) < 0) { - Debug("dns", "opening connection %s FAILED for %d", ip_text, icon); + Dbg(dbg_ctl_dns, "opening connection %s FAILED for %d", ip_text, icon); if (!failed) { if (dns_ns_rr) { rr_failure(icon); @@ -529,7 +533,7 @@ DNSHandler::open_con(sockaddr const *target, bool failed, int icon, bool over_tc } else { cur_con.num = icon; ns_down[icon] = 0; - Debug("dns", "opening connection %s on fd %d SUCCEEDED for %d", ip_text, cur_con.fd, icon); + Dbg(dbg_ctl_dns, "opening connection %s on fd %d SUCCEEDED for %d", ip_text, cur_con.fd, icon); } ret = true; } @@ -559,7 +563,7 @@ DNSHandler::startEvent(int /* event ATS_UNUSED */, Event *e) { // // If this is for the default server, get it - Debug("dns", "DNSHandler::startEvent: on thread %d", e->ethread->id); + Dbg(dbg_ctl_dns, "DNSHandler::startEvent: on thread %d", e->ethread->id); this->validate_ip(); @@ -588,7 +592,7 @@ DNSHandler::startEvent(int /* event ATS_UNUSED */, Event *e) if (ats_is_ip(sa)) { open_cons(sa, false, n_con); ++n_con; - Debug("dns_pas", "opened connection to %s, n_con = %d", ats_ip_nptop(sa, buff, sizeof(buff)), n_con); + Dbg(dbg_ctl_dns_pas, "opened connection to %s, n_con = %d", ats_ip_nptop(sa, buff, sizeof(buff)), n_con); } } dns_ns_rr_init_down = 0; @@ -628,7 +632,7 @@ DNSHandler::startEvent(int /* event ATS_UNUSED */, Event *e) int DNSHandler::startEvent_sdns(int /* event ATS_UNUSED */, Event *e) { - Debug("dns", "DNSHandler::startEvent_sdns: on thread %d", e->ethread->id); + Dbg(dbg_ctl_dns, "DNSHandler::startEvent_sdns: on thread %d", e->ethread->id); this->validate_ip(); SET_HANDLER(&DNSHandler::mainEvent); @@ -662,7 +666,7 @@ void DNSHandler::retry_named(int ndx, ink_hrtime t, bool reopen) { if (reopen && ((t - last_primary_reopen) > DNS_PRIMARY_REOPEN_PERIOD)) { - Debug("dns", "retry_named: reopening DNS connection for index %d", ndx); + Dbg(dbg_ctl_dns, "retry_named: reopening DNS connection for index %d", ndx); last_primary_reopen = t; if (dns_conn_mode != DNS_CONN_MODE::TCP_ONLY) { udpcon[ndx].close(); @@ -675,13 +679,13 @@ DNSHandler::retry_named(int ndx, ink_hrtime t, bool reopen) bool over_tcp = dns_conn_mode == DNS_CONN_MODE::TCP_ONLY; int con_fd = over_tcp ? tcpcon[ndx].fd : udpcon[ndx].fd; unsigned char buffer[MAX_DNS_REQUEST_LEN]; - Debug("dns", "trying to resolve '%s' from DNS connection, ndx %d", try_server_names[try_servers], ndx); + Dbg(dbg_ctl_dns, "trying to resolve '%s' from DNS connection, ndx %d", try_server_names[try_servers], ndx); int r = _ink_res_mkquery(m_res, try_server_names[try_servers], T_A, buffer, over_tcp); try_servers = (try_servers + 1) % countof(try_server_names); ink_assert(r >= 0); if (r >= 0) { // looking for a bounce int res = SocketManager::send(con_fd, buffer, r, 0); - Debug("dns", "ping result = %d", res); + Dbg(dbg_ctl_dns, "ping result = %d", res); } } @@ -690,7 +694,7 @@ DNSHandler::try_primary_named(bool reopen) { ink_hrtime t = Thread::get_hrtime(); if (reopen && ((t - last_primary_reopen) > DNS_PRIMARY_REOPEN_PERIOD)) { - Debug("dns", "try_primary_named: reopening primary DNS connection"); + Dbg(dbg_ctl_dns, "try_primary_named: reopening primary DNS connection"); last_primary_reopen = t; open_cons(nullptr, true, 0); } @@ -699,7 +703,7 @@ DNSHandler::try_primary_named(bool reopen) bool over_tcp = dns_conn_mode == DNS_CONN_MODE::TCP_ONLY; int con_fd = over_tcp ? tcpcon[0].fd : udpcon[0].fd; last_primary_retry = t; - Debug("dns", "trying to resolve '%s' from primary DNS connection", try_server_names[try_servers]); + Dbg(dbg_ctl_dns, "trying to resolve '%s' from primary DNS connection", try_server_names[try_servers]); int r = _ink_res_mkquery(m_res, try_server_names[try_servers], T_A, buffer, over_tcp); // if try_server_names[] is not full, round-robin within the // filled entries. @@ -711,7 +715,7 @@ DNSHandler::try_primary_named(bool reopen) ink_assert(r >= 0); if (r >= 0) { // looking for a bounce int res = SocketManager::send(con_fd, buffer, r, 0); - Debug("dns", "ping result = %d", res); + Dbg(dbg_ctl_dns, "ping result = %d", res); } } } @@ -733,11 +737,11 @@ DNSHandler::switch_named(int ndx) void DNSHandler::failover() { - Debug("dns", "failover: initiating failover attempt, current name_server=%d", name_server); + Dbg(dbg_ctl_dns, "failover: initiating failover attempt, current name_server=%d", name_server); if (!ns_down[name_server]) { ip_text_buffer buff; // mark this nameserver as down - Debug("dns", "failover: Marking nameserver %d as down", name_server); + Dbg(dbg_ctl_dns, "failover: Marking nameserver %d as down", name_server); ns_down[name_server] = 1; Warning("connection to DNS server %s lost, marking as down", ats_ip_ntop(&m_res->nsaddr_list[name_server].sa, buff, sizeof(buff))); @@ -753,7 +757,7 @@ DNSHandler::failover() } sockaddr const *old_addr = &m_res->nsaddr_list[name_server].sa; name_server = (name_server + 1) % max_nscount; - Debug("dns", "failover: failing over to name_server=%d", name_server); + Dbg(dbg_ctl_dns, "failover: failing over to name_server=%d", name_server); IpEndpoint target; ats_ip_copy(&target.sa, &m_res->nsaddr_list[name_server].sa); @@ -790,7 +794,7 @@ DNSHandler::rr_failure(int ndx) if (!ns_down[ndx]) { ip_text_buffer buff; // mark this nameserver as down - Debug("dns", "rr_failure: Marking nameserver %d as down", ndx); + Dbg(dbg_ctl_dns, "rr_failure: Marking nameserver %d as down", ndx); ns_down[ndx] = 1; Warning("connection to DNS server %s lost, marking as down", ats_ip_ntop(&m_res->nsaddr_list[ndx].sa, buff, sizeof(buff))); } @@ -804,7 +808,7 @@ DNSHandler::rr_failure(int ndx) int all_down = 1; for (int i = 0; i < nscount && all_down; i++) { - Debug("dns", "nsdown[%d]=%d", i, ns_down[i]); + Dbg(dbg_ctl_dns, "nsdown[%d]=%d", i, ns_down[i]); if (!ns_down[i]) { all_down = 0; } @@ -891,7 +895,7 @@ DNSHandler::recv_dns(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) if (res <= 0) { goto Lerror; } - Debug("dns", "received packet size = %d over TCP", res); + Dbg(dbg_ctl_dns, "received packet size = %d over TCP", res); dnsc->tcp_data.done_reading += res; if (dnsc->tcp_data.done_reading < dnsc->tcp_data.total_length) { break; @@ -907,13 +911,13 @@ DNSHandler::recv_dns(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) } res = SocketManager::recvfrom(dnsc->fd, hostent_cache->buf, MAX_DNS_RESPONSE_LEN, 0, &from_ip.sa, &from_length); - Debug("dns", "DNSHandler::recv_dns res = [%d]", res); + Dbg(dbg_ctl_dns, "DNSHandler::recv_dns res = [%d]", res); if (res == -EAGAIN) { break; } if (res <= 0) { Lerror: - Debug("dns", "named error: %d", res); + Dbg(dbg_ctl_dns, "named error: %d", res); if (dns_ns_rr) { rr_failure(dnsc->num); } else if (dnsc->num == name_server) { @@ -931,10 +935,10 @@ DNSHandler::recv_dns(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) buf = hostent_cache; hostent_cache = nullptr; buf->packet_size = res; - Debug("dns", "received packet size = %d", res); + Dbg(dbg_ctl_dns, "received packet size = %d", res); Lsuccess: if (dns_ns_rr) { - Debug("dns", "round-robin: nameserver %d DNS response code = %d", dnsc->num, get_rcode(buf->buf)); + Dbg(dbg_ctl_dns, "round-robin: nameserver %d DNS response code = %d", dnsc->num, get_rcode(buf->buf)); if (good_rcode(buf->buf)) { received_one(dnsc->num); if (ns_down[dnsc->num]) { @@ -945,7 +949,7 @@ DNSHandler::recv_dns(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) } } else { if (!dnsc->num) { - Debug("dns", "primary DNS response code = %d", get_rcode(buf->buf)); + Dbg(dbg_ctl_dns, "primary DNS response code = %d", get_rcode(buf->buf)); if (good_rcode(buf->buf)) { if (name_server) { recover(); @@ -994,7 +998,7 @@ DNSHandler::mainEvent(int event, Event *e) if (t - last_primary_retry > DNS_PRIMARY_RETRY_PERIOD) { for (int i = 0; i < n_con; i++) { if (ns_down[i]) { - Debug("dns", "mainEvent: nameserver = %d is down", i); + Dbg(dbg_ctl_dns, "mainEvent: nameserver = %d is down", i); retry_named(i, t, true); } } @@ -1002,11 +1006,11 @@ DNSHandler::mainEvent(int event, Event *e) } for (int i = 0; i < n_con; i++) { if (!ns_down[i] && failover_soon(i)) { - Debug("dns", "mainEvent: nameserver = %d failover soon", name_server); + Dbg(dbg_ctl_dns, "mainEvent: nameserver = %d failover soon", name_server); if (failover_now(i)) { rr_failure(i); } else { - Debug("dns", "mainEvent: nameserver = %d no failover now - retrying", i); + Dbg(dbg_ctl_dns, "mainEvent: nameserver = %d no failover now - retrying", i); retry_named(i, t, false); ++failover_soon_number[i]; } @@ -1014,9 +1018,9 @@ DNSHandler::mainEvent(int event, Event *e) } } else { if (failover_soon(name_server)) { - Debug("dns", "mainEvent: will failover soon"); + Dbg(dbg_ctl_dns, "mainEvent: will failover soon"); if (failover_now(name_server)) { - Debug("dns", "mainEvent: failing over now to another nameserver"); + Dbg(dbg_ctl_dns, "mainEvent: failing over now to another nameserver"); failover(); } else { try_primary_named(false); @@ -1094,7 +1098,6 @@ write_dns(DNSHandler *h, bool tcp_retry) } h->in_write_dns = true; bool over_tcp = (dns_conn_mode == DNS_CONN_MODE::TCP_ONLY) || ((dns_conn_mode == DNS_CONN_MODE::TCP_RETRY) && tcp_retry); - // Debug("dns", "in_flight: %d, dns_max_dns_in_flight: %d", h->in_flight, dns_max_dns_in_flight); if (h->in_flight < dns_max_dns_in_flight) { DNSEntry *e = h->entries.head; while (e) { @@ -1168,7 +1171,7 @@ write_dns_event(DNSHandler *h, DNSEntry *e, bool over_tcp) int r = 0; if ((r = _ink_res_mkquery(h->m_res, e->qname, e->qtype, buffer, over_tcp)) <= 0) { - Debug("dns", "cannot build query: %s", e->qname); + Dbg(dbg_ctl_dns, "cannot build query: %s", e->qname); dns_result(h, e, nullptr, false); return true; } @@ -1181,16 +1184,16 @@ write_dns_event(DNSHandler *h, DNSEntry *e, bool over_tcp) } e->id[dns_retries - e->retries] = i; int con_fd = over_tcp ? h->tcpcon[h->name_server].fd : h->udpcon[h->name_server].fd; - Debug("dns", "send query (qtype=%d) for %s to fd %d", e->qtype, e->qname, con_fd); + Dbg(dbg_ctl_dns, "send query (qtype=%d) for %s to fd %d", e->qtype, e->qname, con_fd); int s = SocketManager::send(con_fd, buffer, r, 0); if (s != r) { - Debug("dns", "send() failed: qname = %s, %d != %d, nameserver= %d", e->qname, s, r, h->name_server); + Dbg(dbg_ctl_dns, "send() failed: qname = %s, %d != %d, nameserver= %d", e->qname, s, r, h->name_server); if (over_tcp) { // add the counter for tcp connection failed - Debug("dns", "tcp query failed: name_server = %d, tcp_continuous_failures = %d", h->name_server, - h->tcp_continuous_failures[h->name_server]); + Dbg(dbg_ctl_dns, "tcp query failed: name_server = %d, tcp_continuous_failures = %d", h->name_server, + h->tcp_continuous_failures[h->name_server]); ++h->tcp_continuous_failures[h->name_server]; } @@ -1207,8 +1210,8 @@ write_dns_event(DNSHandler *h, DNSEntry *e, bool over_tcp) if (over_tcp && h->tcp_continuous_failures[h->name_server] > 0) { // reset the counter for any tcp connection succeed - Debug("dns", "reset tcp_continuous_failures: name_server = %d, tcp_continuous_failures = %d", h->name_server, - h->tcp_continuous_failures[h->name_server]); + Dbg(dbg_ctl_dns, "reset tcp_continuous_failures: name_server = %d, tcp_continuous_failures = %d", h->name_server, + h->tcp_continuous_failures[h->name_server]); h->tcp_continuous_failures[h->name_server] = 0; } @@ -1230,7 +1233,7 @@ write_dns_event(DNSHandler *h, DNSEntry *e, bool over_tcp) e->timeout = h->mutex->thread_holding->schedule_in(e, HRTIME_SECONDS(dns_timeout)); } - Debug("dns", "sent qname = %s, id = %u, nameserver = %d", e->qname, e->id[dns_retries - e->retries], h->name_server); + Dbg(dbg_ctl_dns, "sent qname = %s, id = %u, nameserver = %d", e->qname, e->id[dns_retries - e->retries], h->name_server); h->sent_one(); return true; } @@ -1260,7 +1263,7 @@ DNSEntry::mainEvent(int event, Event *e) dnsH = dnsProcessor.handler; } if (!dnsH) { - Debug("dns", "handler not found, retrying..."); + Dbg(dbg_ctl_dns, "handler not found, retrying..."); SET_HANDLER(&DNSEntry::delayEvent); return handleEvent(event, e); } @@ -1278,27 +1281,27 @@ DNSEntry::mainEvent(int event, Event *e) } else { domains = nullptr; } - Debug("dns", "enqueuing query %s", qname); + Dbg(dbg_ctl_dns, "enqueuing query %s", qname); DNSEntry *dup = get_entry(dnsH, qname, qtype); if (dup) { - Debug("dns", "collapsing NS request"); + Dbg(dbg_ctl_dns, "collapsing NS request"); dup->dups.enqueue(this); } else { - Debug("dns", "adding first to collapsing queue"); + Dbg(dbg_ctl_dns, "adding first to collapsing queue"); dnsH->entries.enqueue(this); dnsProcessor.thread->schedule_imm(dnsH); } return EVENT_DONE; } case EVENT_INTERVAL: - Debug("dns", "timeout for query %s", qname); + Dbg(dbg_ctl_dns, "timeout for query %s", qname); if (dnsH->txn_lookup_timeout) { timeout = nullptr; dns_result(dnsH, this, result_ent.get(), false); // do not retry -- we are over TXN timeout on DNS alone! return EVENT_DONE; } if (written_flag) { - Debug("dns", "marking %s as not-written", qname); + Dbg(dbg_ctl_dns, "marking %s as not-written", qname); written_flag = false; --(dnsH->in_flight); DNS_DECREMENT_DYN_STAT(dns_in_flight_stat); @@ -1313,12 +1316,12 @@ Action * DNSProcessor::getby(DNSQueryData x, int type, Continuation *cont, Options const &opt) { if (type == T_PTR) { - Debug("dns", "received reverse query type = %d, timeout = %d", type, opt.timeout); + Dbg(dbg_ctl_dns, "received reverse query type = %d, timeout = %d", type, opt.timeout); } else { - Debug("dns", "received query %.*s type = %d, timeout = %d", int(x.name.size()), x.name.data(), type, opt.timeout); + Dbg(dbg_ctl_dns, "received query %.*s type = %d, timeout = %d", int(x.name.size()), x.name.data(), type, opt.timeout); if (type == T_SRV) { - Debug("dns_srv", "DNSProcessor::getby attempting an SRV lookup for %.*s, timeout = %d", int(x.name.size()), x.name.data(), - opt.timeout); + Dbg(dbg_ctl_dns_srv, "DNSProcessor::getby attempting an SRV lookup for %.*s, timeout = %d", int(x.name.size()), x.name.data(), + opt.timeout); } } DNSEntry *e = dnsEntryAllocator.alloc(); @@ -1347,7 +1350,7 @@ dns_result(DNSHandler *h, DNSEntry *e, HostEnt *ent, bool retry, bool tcp_retry) if ((!ent || !ent->good) && !cancelled) { // try to retry operation if (retry && e->retries) { - Debug("dns", "doing retry for %s", e->qname); + Dbg(dbg_ctl_dns, "doing retry for %s", e->qname); DNS_INCREMENT_DYN_STAT(dns_retries_stat); @@ -1356,18 +1359,18 @@ dns_result(DNSHandler *h, DNSEntry *e, HostEnt *ent, bool retry, bool tcp_retry) return; } else if (e->domains && *e->domains) { do { - Debug("dns", "domain extending, last tried '%s', original '%.*s'", e->qname, e->orig_qname_len, e->qname); + Dbg(dbg_ctl_dns, "domain extending, last tried '%s', original '%.*s'", e->qname, e->orig_qname_len, e->qname); // Make sure the next try fits if (e->orig_qname_len + strlen(*e->domains) + 2 > MAXDNAME) { - Debug("dns", "domain too large %.*s + %s", e->orig_qname_len, e->qname, *e->domains); + Dbg(dbg_ctl_dns, "domain too large %.*s + %s", e->orig_qname_len, e->qname, *e->domains); } else { e->qname[e->orig_qname_len] = '.'; e->qname_len = e->orig_qname_len + 1 + ink_strlcpy(e->qname + e->orig_qname_len + 1, *e->domains, MAXDNAME - (e->orig_qname_len + 1)); ++(e->domains); e->retries = dns_retries; - Debug("dns", "new name = %s retries = %d", e->qname, e->retries); + Dbg(dbg_ctl_dns, "new name = %s retries = %d", e->qname, e->retries); write_dns(h, tcp_retry); return; @@ -1409,7 +1412,7 @@ dns_result(DNSHandler *h, DNSEntry *e, HostEnt *ent, bool retry, bool tcp_retry) h->release_query_id(i); } - if (is_debug_tag_set("dns")) { + if (is_dbg_ctl_enabled(dbg_ctl_dns)) { if (is_addr_query(e->qtype)) { ip_text_buffer buff; const char *ptr = "<none>"; @@ -1418,12 +1421,12 @@ dns_result(DNSHandler *h, DNSEntry *e, HostEnt *ent, bool retry, bool tcp_retry) result = "SUCCESS"; ptr = inet_ntop(e->qtype == T_AAAA ? AF_INET6 : AF_INET, ent->ent.h_addr_list[0], buff, sizeof(buff)); } - Debug("dns", "%s result for %s = %s retry %d", result, e->qname, ptr, retry); + DbgPrint(dbg_ctl_dns, "%s result for %s = %s retry %d", result, e->qname, ptr, retry); } else { if (ent && ent->good) { - Debug("dns", "SUCCESS result for %s = %s af=%d retry %d", e->qname, ent->ent.h_name, ent->ent.h_addrtype, retry); + DbgPrint(dbg_ctl_dns, "SUCCESS result for %s = %s af=%d retry %d", e->qname, ent->ent.h_name, ent->ent.h_addrtype, retry); } else { - Debug("dns", "FAIL result for %s = <not found> retry %d", e->qname, retry); + DbgPrint(dbg_ctl_dns, "FAIL result for %s = <not found> retry %d", e->qname, retry); } } } @@ -1491,7 +1494,7 @@ DNSEntry::post(DNSHandler *h, HostEnt *ent) if (h->mutex->thread_holding == submit_thread) { MUTEX_TRY_LOCK(lock, action.mutex, h->mutex->thread_holding); if (!lock.is_locked()) { - Debug("dns", "failed lock for result %s", qname); + Dbg(dbg_ctl_dns, "failed lock for result %s", qname); return 1; } postOneEvent(0, nullptr); @@ -1507,7 +1510,7 @@ int DNSEntry::postOneEvent(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) { if (!action.cancelled) { - Debug("dns", "called back continuation for %s", qname); + Dbg(dbg_ctl_dns, "called back continuation for %s", qname); action.continuation->handleEvent(DNS_EVENT_LOOKUP, result_ent.get()); } result_ent = nullptr; @@ -1551,7 +1554,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) // Do we have an entry for this id? // if (!e || !e->written_flag) { - Debug("dns", "unknown DNS id = %u", (uint16_t)ntohs(h->id)); + Dbg(dbg_ctl_dns, "unknown DNS id = %u", (uint16_t)ntohs(h->id)); return false; // cannot count this as a success } // @@ -1565,7 +1568,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) // retrying over TCP when truncated is set if (dns_conn_mode == DNS_CONN_MODE::TCP_RETRY && h->tc == 1) { - Debug("dns", "Retrying DNS query over TCP for [%s]", e->qname); + Dbg(dbg_ctl_dns, "Retrying DNS query over TCP for [%s]", e->qname); tcp_retry = true; DNS_INCREMENT_DYN_STAT(dns_tcp_retries_stat); goto Lerror; @@ -1574,7 +1577,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) // Logs using SiteThrottled* version is helpful for noisy logs, being used here // instead of print statements to help with the possible retries when a dns code occurs if (h->rcode != NOERROR || !h->ancount) { - Debug("dns", "received rcode = %d", h->rcode); + Dbg(dbg_ctl_dns, "received rcode = %d", h->rcode); switch (h->rcode) { default: SiteThrottledWarning("UNKNOWN: DNS error %d for [%s]", h->rcode, e->qname); @@ -1582,7 +1585,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) server_ok = false; // could be server problems goto Lerror; case NOERROR: // included for completeness. - Debug("dns", "%s: DNS error %d for [%s]: %s", RCODE_NAME[h->rcode], h->rcode, e->qname, RCODE_DESCRIPTION[h->rcode]); + Dbg(dbg_ctl_dns, "%s: DNS error %d for [%s]: %s", RCODE_NAME[h->rcode], h->rcode, e->qname, RCODE_DESCRIPTION[h->rcode]); break; case SERVFAIL: // recoverable error SiteThrottledNote("%s: DNS error %d for [%s]: %s", RCODE_NAME[h->rcode], h->rcode, e->qname, RCODE_DESCRIPTION[h->rcode]); @@ -1622,7 +1625,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) buf->srv_hosts.srv_hosts_length = 0; int rname_len = -1; - Debug("dns", "Got %d DNS records for [%s]", ancount, e->qname); + Dbg(dbg_ctl_dns, "Got %d DNS records for [%s]", ancount, e->qname); // // Expand name // @@ -1650,7 +1653,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) Warning("received DNS response with query name of '%s', but response query name is '%s'", e->qname, bp); goto Lerror; } else { - Debug("dns", "query name validated properly for %s", e->qname); + Dbg(dbg_ctl_dns, "query name validated properly for %s", e->qname); } } @@ -1750,13 +1753,13 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) ink_strlcpy(reinterpret_cast<char *>(bp), reinterpret_cast<char *>(tbuf), buflen); bp += n; buflen -= n; - if (is_debug_tag_set("dns")) { + if (is_dbg_ctl_enabled(dbg_ctl_dns)) { switch (type) { case T_CNAME: - Debug("dns", "received cname = %s", tbuf); + DbgPrint(dbg_ctl_dns, "received cname = %s", tbuf); break; case T_DNAME: - Debug("dns", "received dname = %s", tbuf); + DbgPrint(dbg_ctl_dns, "received dname = %s", tbuf); break; } } @@ -1778,13 +1781,13 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) cp += n; if (!answer) { buf->ent.h_name = reinterpret_cast<char *>(bp); - Debug("dns", "received PTR name = %s", bp); + Dbg(dbg_ctl_dns, "received PTR name = %s", bp); n = strlen(reinterpret_cast<char *>(bp)) + 1; bp += n; buflen -= n; } else if (ap < &buf->host_aliases[DNS_MAX_ALIASES - 1]) { *ap++ = bp; - Debug("dns", "received PTR alias = %s", bp); + Dbg(dbg_ctl_dns, "received PTR alias = %s", bp); n = strlen(reinterpret_cast<char *>(bp)) + 1; bp += n; buflen -= n; @@ -1809,8 +1812,8 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) ++error; break; } - Debug("dns_srv", "Discovered SRV record [from NS lookup] with cost:%d weight:%d port:%d with host:%s", - ink_get16(srv_off + SRV_COST), ink_get16(srv_off + SRV_WEIGHT), ink_get16(srv_off + SRV_PORT), srv.host); + Dbg(dbg_ctl_dns_srv, "Discovered SRV record [from NS lookup] with cost:%d weight:%d port:%d with host:%s", + ink_get16(srv_off + SRV_COST), ink_get16(srv_off + SRV_WEIGHT), ink_get16(srv_off + SRV_PORT), srv.host); srv.port = ink_get16(srv_off + SRV_PORT); srv.priority = ink_get16(srv_off + SRV_COST); @@ -1836,7 +1839,7 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) buf->ent.h_addrtype = T_A == type ? AF_INET : AF_INET6; buf->ent.h_name = reinterpret_cast<char *>(bp); nn = strlen(reinterpret_cast<char *>(bp)) + 1; - Debug("dns", "received %s name = %s", QtypeName(type), bp); + Dbg(dbg_ctl_dns, "received %s name = %s", QtypeName(type), bp); bp += nn; buflen -= nn; } @@ -1852,8 +1855,8 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) break; } memcpy((*hap++ = bp), cp, n); - Debug("dns", "received %s = %s", QtypeName(type), - inet_ntop(T_AAAA == type ? AF_INET6 : AF_INET, bp, ip_string, sizeof(ip_string))); + Dbg(dbg_ctl_dns, "received %s = %s", QtypeName(type), + inet_ntop(T_AAAA == type ? AF_INET6 : AF_INET, bp, ip_string, sizeof(ip_string))); bp += n; cp += n; } @@ -1870,11 +1873,11 @@ dns_process(DNSHandler *handler, HostEnt *buf, int len) // the user gave us... // if (!buf->ent.h_name) { - Debug("dns", "inserting name = %s", e->qname); + Dbg(dbg_ctl_dns, "inserting name = %s", e->qname); ink_strlcpy(reinterpret_cast<char *>(bp), e->qname, sizeof(buf->hostbuf) - (bp - buf->hostbuf)); buf->ent.h_name = reinterpret_cast<char *>(bp); } - Debug("dns", "Returning %d DNS records for [%s]", answer, e->qname); + Dbg(dbg_ctl_dns, "Returning %d DNS records for [%s]", answer, e->qname); dns_result(handler, e, buf, retry); return server_ok; } @@ -1893,7 +1896,7 @@ ink_dns_init(ts::ModuleVersion v) { static int init_called = 0; - Debug("dns", "ink_dns_init: called with init_called = %d", init_called); + Dbg(dbg_ctl_dns, "ink_dns_init: called with init_called = %d", init_called); ink_release_assert(v.check(HOSTDB_MODULE_PUBLIC_VERSION)); if (init_called) { diff --git a/iocore/dns/DNSConnection.cc b/iocore/dns/DNSConnection.cc index 12e83f82ff..ac052b3d6a 100644 --- a/iocore/dns/DNSConnection.cc +++ b/iocore/dns/DNSConnection.cc @@ -43,6 +43,13 @@ DNSConnection::Options const DNSConnection::DEFAULT_OPTIONS; +namespace +{ + +DbgCtl dbg_ctl_dns{"dns"}; + +} // end anonymous namespace + // // Functions // @@ -143,7 +150,7 @@ DNSConnection::connect(sockaddr const *addr, Options const &opt) uint32_t p = generator.random(); p = static_cast<uint16_t>((p % (LAST_RANDOM_PORT - FIRST_RANDOM_PORT)) + FIRST_RANDOM_PORT); ats_ip_port_cast(&bind_addr.sa) = htons(p); // stuff port in sockaddr. - Debug("dns", "random port = %s", ats_ip_nptop(&bind_addr.sa, b, sizeof b)); + Dbg(dbg_ctl_dns, "random port = %s", ats_ip_nptop(&bind_addr.sa, b, sizeof b)); if (SocketManager::ink_bind(fd, &bind_addr.sa, bind_size, Proto) < 0) { continue; } diff --git a/iocore/dns/P_DNSProcessor.h b/iocore/dns/P_DNSProcessor.h index 467f4ab7be..d3bc8713ad 100644 --- a/iocore/dns/P_DNSProcessor.h +++ b/iocore/dns/P_DNSProcessor.h @@ -198,7 +198,7 @@ struct DNSHandler : public Continuation { sent_one() { ++failover_number[name_server]; - Debug("dns", "sent_one: failover_number for resolver %d is %d", name_server, failover_number[name_server]); + Dbg(_dbg_ctl_dns, "sent_one: failover_number for resolver %d is %d", name_server, failover_number[name_server]); if (failover_number[name_server] >= dns_failover_number && !crossed_failover_number[name_server]) crossed_failover_number[name_server] = Thread::get_hrtime(); } @@ -206,10 +206,10 @@ struct DNSHandler : public Continuation { bool failover_now(int i) { - if (is_debug_tag_set("dns")) { - Debug("dns", "failover_now: Considering immediate failover, target time is %" PRId64 "", - (ink_hrtime)HRTIME_SECONDS(dns_failover_period)); - Debug("dns", "\tdelta time is %" PRId64 "", (Thread::get_hrtime() - crossed_failover_number[i])); + if (is_dbg_ctl_enabled(_dbg_ctl_dns)) { + DbgPrint(_dbg_ctl_dns, "failover_now: Considering immediate failover, target time is %" PRId64 "", + (ink_hrtime)HRTIME_SECONDS(dns_failover_period)); + DbgPrint(_dbg_ctl_dns, "\tdelta time is %" PRId64 "", (Thread::get_hrtime() - crossed_failover_number[i])); } return ns_down[i] || (crossed_failover_number[i] && ((Thread::get_hrtime() - crossed_failover_number[i]) > HRTIME_SECONDS(dns_failover_period))); @@ -268,6 +268,9 @@ private: /** The event used for the periodic retry of connectivity to any down name * servers. */ PendingAction _dns_retry_event; + +private: + inline static DbgCtl _dbg_ctl_dns{"dns"}, _dbg_ctl_net_epoll{"net_epoll"}; }; /* -------------------------------------------------------------- @@ -313,5 +316,5 @@ DNSHandler::DNSHandler() } memset(&qid_in_flight, 0, sizeof(qid_in_flight)); SET_HANDLER(&DNSHandler::startEvent); - Debug("net_epoll", "inline DNSHandler::DNSHandler()"); + Dbg(_dbg_ctl_net_epoll, "inline DNSHandler::DNSHandler()"); } diff --git a/iocore/dns/SplitDNS.cc b/iocore/dns/SplitDNS.cc index 23125e9f80..51bdd6b4c5 100644 --- a/iocore/dns/SplitDNS.cc +++ b/iocore/dns/SplitDNS.cc @@ -64,7 +64,15 @@ enum SplitDNSCB_t { SDNS_ENABLE_CB, }; -static const char *SDNSResultStr[] = {"DNSServer_Undefined", "DNSServer_Specified", "DNSServer_Failed"}; +namespace +{ + +DbgCtl dbg_ctl_splitdns{"splitdns"}; +DbgCtl dbg_ctl_splitdns_config{"splitdns_config"}; + +const char *SDNSResultStr[] = {"DNSServer_Undefined", "DNSServer_Specified", "DNSServer_Failed"}; + +} // end anonymous namespace int SplitDNSConfig::m_id = 0; int SplitDNSConfig::gsplit_dns_enabled = 0; @@ -152,7 +160,7 @@ SplitDNSConfig::reconfigure() m_id = configProcessor.set(m_id, params); - if (is_debug_tag_set("splitdns_config")) { + if (is_dbg_ctl_enabled(dbg_ctl_splitdns_config)) { SplitDNSConfig::print(); } @@ -167,8 +175,8 @@ SplitDNSConfig::print() { SplitDNS *params = SplitDNSConfig::acquire(); - Debug("splitdns_config", "DNS Server Selection Config"); - Debug("splitdns_config", "\tEnabled=%d", params->m_SplitDNSlEnable); + Dbg(dbg_ctl_splitdns_config, "DNS Server Selection Config"); + Dbg(dbg_ctl_splitdns_config, "\tEnabled=%d", params->m_SplitDNSlEnable); params->m_DNSSrvrTable->Print(); SplitDNSConfig::release(params); @@ -180,7 +188,7 @@ SplitDNSConfig::print() void * SplitDNS::getDNSRecord(ts::TextView hostname) { - Debug("splitdns", "Called SplitDNS::getDNSRecord(%.*s)", int(hostname.size()), hostname.data()); + Dbg(dbg_ctl_splitdns, "Called SplitDNS::getDNSRecord(%.*s)", int(hostname.size()), hostname.data()); DNSRequestData *pRD = DNSReqAllocator.alloc(); pRD->m_pHost = hostname; @@ -194,7 +202,7 @@ SplitDNS::getDNSRecord(ts::TextView hostname) return &(res.m_rec->m_servers); } - Debug("splitdns", "Fail to match a valid splitdns rule, fallback to default dns resolver"); + Dbg(dbg_ctl_splitdns, "Fail to match a valid splitdns rule, fallback to default dns resolver"); return nullptr; } @@ -266,15 +274,15 @@ SplitDNS::findServer(RequestData *rdata, SplitDNSResult *result) result->r = DNS_SRVR_SPECIFIED; } - if (is_debug_tag_set("splitdns_config")) { + if (is_dbg_ctl_enabled(dbg_ctl_splitdns_config)) { const char *host = rdata->get_host(); switch (result->r) { case DNS_SRVR_FAIL: - Debug("splitdns_config", "Result for %s was %s", host, SDNSResultStr[result->r]); + Dbg(dbg_ctl_splitdns_config, "Result for %s was %s", host, SDNSResultStr[result->r]); break; case DNS_SRVR_SPECIFIED: - Debug("splitdns_config", "Result for %s was dns servers", host); + Dbg(dbg_ctl_splitdns_config, "Result for %s was dns servers", host); result->m_rec->Print(); break; default: @@ -518,7 +526,7 @@ SplitDNSRecord::UpdateMatch(SplitDNSResult *result, RequestData * /* rdata ATS_U result->m_rec = this; result->m_line_number = this->line_num; - Debug("splitdns_config", "Matched with %p dns node from line %d", this, this->line_num); + Dbg(dbg_ctl_splitdns_config, "Matched with %p dns node from line %d", this, this->line_num); } } @@ -530,7 +538,7 @@ SplitDNSRecord::Print() const { for (int i = 0; i < m_dnsSrvr_cnt; i++) { char ab[INET6_ADDRPORTSTRLEN]; - Debug("splitdns_config", " %s", ats_ip_ntop(&m_servers.x_server_ip[i].sa, ab, sizeof ab)); + Dbg(dbg_ctl_splitdns_config, " %s", ats_ip_ntop(&m_servers.x_server_ip[i].sa, ab, sizeof ab)); } } diff --git a/iocore/eventsystem/UnixEventProcessor.cc b/iocore/eventsystem/UnixEventProcessor.cc index 92cc795b19..493c5f116f 100644 --- a/iocore/eventsystem/UnixEventProcessor.cc +++ b/iocore/eventsystem/UnixEventProcessor.cc @@ -33,6 +33,14 @@ #include "tscore/ink_hw.h" #include "tscore/hugepages.h" +namespace +{ + +DbgCtl dbg_ctl_iocore_thread{"iocore_thread"}; +DbgCtl dbg_ctl_iocore_thread_start{"iocore_thread_start"}; + +} // end anonymous namespace + /// Global singleton. class EventProcessor eventProcessor; @@ -202,8 +210,8 @@ ThreadAffinityInitializer::do_alloc_stack(size_t stacksize) setup_stack_guard(stack_and_guard, stackguard_pages); void *stack_begin = static_cast<char *>(stack_and_guard) + stackguard_pages * pagesize; - Debug("iocore_thread", "Allocated %zu bytes (%zu bytes in guard pages) for stack {%p-%p guard, %p-%p stack}", size, - stackguard_pages * pagesize, stack_and_guard, stack_begin, stack_begin, static_cast<char *>(stack_begin) + stacksize); + Dbg(dbg_ctl_iocore_thread, "Allocated %zu bytes (%zu bytes in guard pages) for stack {%p-%p guard, %p-%p stack}", size, + stackguard_pages * pagesize, stack_and_guard, stack_begin, stack_begin, static_cast<char *>(stack_begin) + stacksize); return stack_begin; } @@ -247,7 +255,7 @@ ThreadAffinityInitializer::init() } obj_count = hwloc_get_nbobjs_by_type(ink_get_topology(), obj_type); - Debug("iocore_thread", "Affinity: %d %ss: %d PU: %d", affinity, obj_name, obj_count, ink_number_of_processors()); + Dbg(dbg_ctl_iocore_thread, "Affinity: %d %ss: %d PU: %d", affinity, obj_name, obj_count, ink_number_of_processors()); } int @@ -262,9 +270,9 @@ ThreadAffinityInitializer::set_affinity(int, Event *) int cpu_mask_len = hwloc_bitmap_snprintf(nullptr, 0, obj->cpuset) + 1; char *cpu_mask = static_cast<char *>(alloca(cpu_mask_len)); hwloc_bitmap_snprintf(cpu_mask, cpu_mask_len, obj->cpuset); - Debug("iocore_thread", "EThread: %p %s: %d CPU Mask: %s\n", t, obj_name, obj->logical_index, cpu_mask); + Dbg(dbg_ctl_iocore_thread, "EThread: %p %s: %d CPU Mask: %s\n", t, obj_name, obj->logical_index, cpu_mask); #else - Debug("iocore_thread", "EThread: %d %s: %d", _name, obj->logical_index); + Dbg(dbg_ctl_iocore_thread, "EThread: %d %s: %d", _name, obj->logical_index); #endif // HWLOC_API_VERSION hwloc_set_thread_cpubind(ink_get_topology(), t->tid, obj->cpuset, HWLOC_CPUBIND_STRICT); } else { @@ -435,7 +443,7 @@ EventProcessor::spawn_event_threads(EventType ev_type, int n_threads, size_t sta stacksize = INK_ALIGN(stacksize, ats_pagesize()); } - Debug("iocore_thread", "Thread stack size set to %zu", stacksize); + Dbg(dbg_ctl_iocore_thread, "Thread stack size set to %zu", stacksize); for (i = 0; i < n_threads; ++i) { EThread *t = new EThread(REGULAR, n_ethreads + i); @@ -453,13 +461,13 @@ EventProcessor::spawn_event_threads(EventType ev_type, int n_threads, size_t sta // the group. Some thread set up depends on knowing the total number of threads but that can't be // safely updated until all the EThread instances are created and stored in the table. for (i = 0; i < n_threads; ++i) { - Debug("iocore_thread_start", "Created %s thread #%d", tg->_name.c_str(), i + 1); + Dbg(dbg_ctl_iocore_thread_start, "Created %s thread #%d", tg->_name.c_str(), i + 1); snprintf(thr_name, MAX_THREAD_NAME_LENGTH, "[%s %d]", tg->_name.c_str(), i); void *stack = Thread_Affinity_Initializer.alloc_stack(tg->_thread[i], stacksize); tg->_thread[i]->start(thr_name, stack, stacksize); } - Debug("iocore_thread", "Created thread group '%s' id %d with %d threads", tg->_name.c_str(), ev_type, n_threads); + Dbg(dbg_ctl_iocore_thread, "Created thread group '%s' id %d with %d threads", tg->_name.c_str(), ev_type, n_threads); return ev_type; // useless but not sure what would be better. } @@ -539,7 +547,7 @@ EventProcessor::start(int n_event_threads, size_t stacksize) this->spawn_event_threads(ET_CALL, n_event_threads, stacksize); - Debug("iocore_thread", "Created event thread group id %d with %d threads", ET_CALL, n_event_threads); + Dbg(dbg_ctl_iocore_thread, "Created event thread group id %d with %d threads", ET_CALL, n_event_threads); return 0; }