Skip to content

Commit 31a36b6

Browse files
bbockelmbbockelm
authored
Merge pull request #99 from bbockelm/verbose_logging
Add some verbose logging messages
2 parents 4239359 + 5608d47 commit 31a36b6

File tree

6 files changed

+90
-75
lines changed

6 files changed

+90
-75
lines changed

‎src/CurlUtil.cc‎

Lines changed: 6 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -46,54 +46,24 @@ HandlerQueue::HandlerQueue() {
4646
m_write_fd = filedes[1];
4747
};
4848

49-
namespace {
50-
51-
// Simple debug function for getting information from libcurl; to enable, you
52-
// need to recompile with GetHandle(true);
53-
int dump_header(CURL *handle, curl_infotype type, char *data, size_t size,
54-
void *clientp) {
55-
(void)handle;
56-
(void)clientp;
57-
58-
switch (type) {
59-
case CURLINFO_HEADER_OUT:
60-
printf("Header > %s\n", std::string(data, size).c_str());
61-
break;
62-
default:
63-
printf("Info: %s", std::string(data, size).c_str());
64-
break;
49+
CURL *HandlerQueue::GetHandle() {
50+
if (!m_handles.empty()) {
51+
CURL *result = m_handles.top();
52+
m_handles.pop();
53+
return result;
6554
}
66-
return 0;
67-
}
6855

69-
} // namespace
70-
71-
CURL *GetHandle(bool verbose) {
7256
auto result = curl_easy_init();
7357
if (result == nullptr) {
7458
return result;
7559
}
7660

7761
curl_easy_setopt(result, CURLOPT_USERAGENT, "xrootd-s3/devel");
78-
curl_easy_setopt(result, CURLOPT_DEBUGFUNCTION, dump_header);
79-
if (verbose)
80-
curl_easy_setopt(result, CURLOPT_VERBOSE, 1L);
81-
8262
curl_easy_setopt(result, CURLOPT_BUFFERSIZE, 32 * 1024);
8363

8464
return result;
8565
}
8666

87-
CURL *HandlerQueue::GetHandle() {
88-
if (!m_handles.empty()) {
89-
CURL *result = m_handles.top();
90-
m_handles.pop();
91-
return result;
92-
}
93-
94-
return ::GetHandle(false);
95-
}
96-
9767
void HandlerQueue::RecycleHandle(CURL *curl) { m_handles.push(curl); }
9868

9969
void HandlerQueue::Produce(HTTPRequest *handler) {
@@ -233,7 +203,7 @@ void CurlWorker::Run() {
233203

234204
auto curl = queue.GetHandle();
235205
if (curl == nullptr) {
236-
m_logger.Log(LogMask::Debug, "Run",
206+
m_logger.Log(LogMask::Warning, "Run",
237207
"Unable to allocate a curl handle");
238208
op->Fail("E_NOMEM", "Unable to get allocate a curl handle");
239209
continue;

‎src/S3Commands.cc‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -562,6 +562,7 @@ bool AmazonS3SendMultipartPart::GetEtag(std::string &result) {
562562
AmazonS3Download::~AmazonS3Download() {}
563563

564564
bool AmazonS3Download::SendRequest(off_t offset, size_t size) {
565+
m_request_start = std::chrono::steady_clock::now();
565566
if (offset != 0 || size != 0) {
566567
std::string range;
567568
formatstr(range, "bytes=%lld-%lld", static_cast<long long int>(offset),

‎src/S3Commands.hh‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -272,6 +272,11 @@ class AmazonS3Download : public AmazonRequest {
272272

273273
virtual bool SendRequest(off_t offset, size_t size);
274274

275+
// Return the elapsed time since the request was started with SendRequest().
276+
std::chrono::steady_clock::duration getElapsedTime() const {
277+
return std::chrono::steady_clock::now() - m_request_start;
278+
}
279+
275280
protected:
276281
virtual bool IsBlocking() { return true; }
277282
virtual std::string_view *requestResult() override {
@@ -280,6 +285,7 @@ class AmazonS3Download : public AmazonRequest {
280285

281286
private:
282287
char *m_buffer{nullptr};
288+
std::chrono::steady_clock::time_point m_request_start;
283289
std::string_view m_buffer_view;
284290
};
285291

‎src/S3File.cc‎

Lines changed: 60 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -124,7 +124,7 @@ int S3File::Open(const char *path, int Oflag, mode_t Mode, XrdOucEnv &env) {
124124
}
125125

126126
ssize_t S3File::Read(void *buffer, off_t offset, size_t size) {
127-
return m_cache.Read(*this, static_cast<char *>(buffer), offset, size);
127+
return m_cache.Read(static_cast<char *>(buffer), offset, size);
128128
}
129129

130130
int S3File::Fstat(struct stat *buff) {
@@ -573,8 +573,8 @@ bool S3File::S3Cache::CouldUse(off_t req_off, size_t req_size,
573573
}
574574
}
575575

576-
void S3File::S3Cache::DownloadCaches(S3File &file, bool download_a,
577-
bool download_b, bool locked) {
576+
void S3File::S3Cache::DownloadCaches(bool download_a, bool download_b,
577+
bool locked) {
578578
if (!download_a && !download_b) {
579579
return;
580580
}
@@ -584,25 +584,25 @@ void S3File::S3Cache::DownloadCaches(S3File &file, bool download_a,
584584
lk.lock();
585585
}
586586
if (download_a) {
587-
m_a.Download(file);
587+
m_a.Download(m_parent);
588588
}
589589
if (download_b) {
590-
m_b.Download(file);
590+
m_b.Download(m_parent);
591591
}
592592
}
593593

594-
ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
595-
size_t size) {
596-
if (offset >= file.content_length) {
594+
ssize_t S3File::S3Cache::Read(char *buffer, off_t offset, size_t size) {
595+
if (offset >= m_parent.content_length) {
597596
return 0;
598597
}
599-
if (offset + static_cast<off_t>(size) > file.content_length) {
600-
size = file.content_length - offset;
598+
if (offset + static_cast<off_t>(size) > m_parent.content_length) {
599+
size = m_parent.content_length - offset;
601600
}
602-
if (file.m_log.getMsgMask() & LogMask::Debug) {
601+
if (m_parent.m_log.getMsgMask() & LogMask::Debug) {
603602
std::stringstream ss;
604-
ss << "Read request for offset=" << offset << ", size=" << size;
605-
file.m_log.Log(LogMask::Debug, "cache", ss.str().c_str());
603+
ss << "Read request for object=" << m_parent.m_object
604+
<< ", offset=" << offset << ", size=" << size;
605+
m_parent.m_log.Log(LogMask::Debug, "cache", ss.str().c_str());
606606
}
607607

608608
off_t req3_off, req4_off, req5_off, req6_off;
@@ -637,8 +637,8 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
637637
// download those bypassing the cache.
638638
bool downloaded;
639639
size_t bypass_size = req3_size;
640-
std::tie(req3_off, req3_size, downloaded) =
641-
file.DownloadBypass(req3_off, req3_size, buffer + req3_off - offset);
640+
std::tie(req3_off, req3_size, downloaded) = m_parent.DownloadBypass(
641+
req3_off, req3_size, buffer + req3_off - offset);
642642
if (req3_size < 0) {
643643
m_errors += 1;
644644
return -1;
@@ -648,8 +648,8 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
648648
m_bypass_count += 1;
649649
}
650650
bypass_size = req4_size;
651-
std::tie(req4_off, req4_size, downloaded) =
652-
file.DownloadBypass(req4_off, req4_size, buffer + req4_off - offset);
651+
std::tie(req4_off, req4_size, downloaded) = m_parent.DownloadBypass(
652+
req4_off, req4_size, buffer + req4_off - offset);
653653
if (req4_size < 0) {
654654
m_errors += 1;
655655
return -1;
@@ -659,8 +659,8 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
659659
m_bypass_count += 1;
660660
}
661661
bypass_size = req5_size;
662-
std::tie(req5_off, req5_size, downloaded) =
663-
file.DownloadBypass(req5_off, req5_size, buffer + req5_off - offset);
662+
std::tie(req5_off, req5_size, downloaded) = m_parent.DownloadBypass(
663+
req5_off, req5_size, buffer + req5_off - offset);
664664
if (req5_size < 0) {
665665
m_errors += 1;
666666
return -1;
@@ -670,8 +670,8 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
670670
m_bypass_count += 1;
671671
}
672672
bypass_size = req6_size;
673-
std::tie(req6_off, req6_size, downloaded) =
674-
file.DownloadBypass(req6_off, req6_size, buffer + req6_off - offset);
673+
std::tie(req6_off, req6_size, downloaded) = m_parent.DownloadBypass(
674+
req6_off, req6_size, buffer + req6_off - offset);
675675
if (req6_size < 0) {
676676
m_errors += 1;
677677
return -1;
@@ -690,7 +690,7 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
690690
std::unique_lock lk{m_mutex};
691691
auto next_offset = std::max(m_a.m_off, m_b.m_off) +
692692
static_cast<off_t>(m_cache_entry_size);
693-
if (next_offset < file.content_length) {
693+
if (next_offset < m_parent.content_length) {
694694
if (!m_a.m_inprogress && m_a.m_used >= m_cache_entry_size) {
695695
m_a.m_inprogress = true;
696696
m_a.m_off = next_offset;
@@ -712,7 +712,7 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
712712
m_prefetch_count++;
713713
m_prefetch_bytes += m_cache_entry_size;
714714
}
715-
DownloadCaches(file, download_a, download_b, false);
715+
DownloadCaches(download_a, download_b, false);
716716
return size;
717717
}
718718
// At this point, the only remaining data requests must be less than the
@@ -914,7 +914,7 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
914914
;
915915
download_a = true;
916916
m_a.m_inprogress = true;
917-
if (prefetch_offset < file.content_length) {
917+
if (prefetch_offset < m_parent.content_length) {
918918
m_b.m_off = prefetch_offset;
919919
prefetch_b = true;
920920
m_b.m_inprogress = true;
@@ -956,7 +956,7 @@ ssize_t S3File::S3Cache::Read(S3File &file, char *buffer, off_t offset,
956956
m_prefetch_count += 1;
957957
m_prefetch_bytes += m_cache_entry_size;
958958
}
959-
DownloadCaches(file, download_a, download_b || prefetch_b, true);
959+
DownloadCaches(download_a, download_b || prefetch_b, true);
960960
}
961961
return size;
962962
}
@@ -965,28 +965,59 @@ void S3File::S3Cache::Entry::Notify() {
965965
std::unique_lock lk(m_parent.m_mutex);
966966
m_inprogress = false;
967967
m_failed = !m_request->getErrorCode().empty();
968+
if ((m_parent.m_parent.m_log.getMsgMask() & LogMask::Warning) && m_failed) {
969+
std::stringstream ss;
970+
auto duration_ms =
971+
std::chrono::duration_cast<std::chrono::milliseconds>(
972+
m_request->getElapsedTime())
973+
.count();
974+
ss << "Finished GET for object=" << m_parent.m_parent.m_object
975+
<< ", offset=" << m_off << ", size=" << m_data.size()
976+
<< ", duration_ms=" << duration_ms << "; failed with error '"
977+
<< m_request->getErrorCode() << "'";
978+
m_parent.m_parent.m_log.Log(LogMask::Warning, "cache",
979+
ss.str().c_str());
980+
} else if (m_parent.m_parent.m_log.getMsgMask() & LogMask::Debug) {
981+
std::stringstream ss;
982+
auto duration_ms =
983+
std::chrono::duration_cast<std::chrono::milliseconds>(
984+
m_request->getElapsedTime())
985+
.count();
986+
ss << "Finished GET for object=" << m_parent.m_parent.m_object
987+
<< ", offset=" << m_off << ", size=" << m_data.size()
988+
<< ", duration_ms=" << duration_ms << "; succeeded";
989+
m_parent.m_parent.m_log.Log(LogMask::Debug, "cache", ss.str().c_str());
990+
}
968991
m_request = nullptr;
969992

970993
m_parent.m_cv.notify_all();
971994
}
972995

973996
void S3File::S3Cache::Entry::Download(S3File &file) {
974997
m_used = false;
975-
m_data.resize(m_cache_entry_size);
976-
m_request.reset(new AmazonS3NonblockingDownload<Entry>(
977-
file.m_ai, file.m_object, file.m_log, m_data.data(), *this));
978998
size_t request_size = m_cache_entry_size;
979999
if (m_off + static_cast<off_t>(request_size) > file.content_length) {
9801000
request_size = file.content_length - m_off;
9811001
}
1002+
m_data.resize(request_size);
1003+
m_request.reset(new AmazonS3NonblockingDownload<Entry>(
1004+
file.m_ai, file.m_object, file.m_log, m_data.data(), *this));
9821005
// This function is always called with m_mutex held; however,
9831006
// SendRequest can block if the threads are all busy; the threads
9841007
// will need to grab the lock to notify of completion. So, we
9851008
// must release the lock here before calling a blocking function --
9861009
// otherwise deadlock may occur.
9871010
auto off = m_off;
9881011
m_parent.m_mutex.unlock();
989-
if (!m_request->SendRequest(off, m_cache_entry_size)) {
1012+
1013+
if (file.m_log.getMsgMask() & LogMask::Debug) {
1014+
std::stringstream ss;
1015+
ss << "Issuing GET for object=" << file.m_object << ", offset=" << m_off
1016+
<< ", size=" << request_size;
1017+
file.m_log.Log(LogMask::Debug, "cache", ss.str().c_str());
1018+
}
1019+
1020+
if (!m_request->SendRequest(off, request_size)) {
9901021
m_parent.m_mutex.lock();
9911022
std::stringstream ss;
9921023
ss << "Failed to send GetObject command: "

‎src/S3File.hh‎

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -273,6 +273,9 @@ class S3File : public XrdOssDF {
273273
std::condition_variable m_cv; // Condition variable for notifying that
274274
// new downloaded data is available.
275275

276+
S3File
277+
&m_parent; // Reference to the S3File object that owns this cache.
278+
276279
// Returns `true` if the request offset would be inside the cache entry.
277280
// The request offset is assumed to be aligned to be inside a single
278281
// cache entry (that is, smaller than a cache entry and not spanning two
@@ -286,15 +289,16 @@ class S3File : public XrdOssDF {
286289
// Trigger the non-blocking download into the cache entries.
287290
// The condition variable will be notified when one of the caches
288291
// finishes.
289-
void DownloadCaches(S3File &file, bool download_a, bool download_b,
290-
bool locked);
292+
void DownloadCaches(bool download_a, bool download_b, bool locked);
291293

292294
// Trigger a blocking read from a given file
293-
ssize_t Read(S3File &file, char *buffer, off_t offset, size_t size);
295+
ssize_t Read(char *buffer, off_t offset, size_t size);
296+
297+
S3Cache(S3File &file) : m_parent(file) {}
294298

295299
// Shutdown the cache; ensure all reads are completed before
296300
// deleting the objects.
297301
~S3Cache();
298302
};
299-
S3Cache m_cache;
303+
S3Cache m_cache{*this};
300304
};

‎src/logging.cc‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -70,18 +70,21 @@ bool XrdHTTPServer::ConfigLog(XrdOucGatherConf &conf, XrdSysError &log) {
7070
} else if (!strcmp(val, "error")) {
7171
log.setMsgMask(log.getMsgMask() | LogMask::Error);
7272
} else if (!strcmp(val, "warning")) {
73-
log.setMsgMask(log.getMsgMask() | LogMask::Warning);
73+
log.setMsgMask(log.getMsgMask() | LogMask::Warning |
74+
LogMask::Error);
7475
} else if (!strcmp(val, "info")) {
75-
log.setMsgMask(log.getMsgMask() | LogMask::Info);
76+
log.setMsgMask(log.getMsgMask() | LogMask::Info | LogMask::Warning |
77+
LogMask::Error);
7678
} else if (!strcmp(val, "dump")) {
77-
log.setMsgMask(log.getMsgMask() | LogMask::Dump);
79+
log.setMsgMask(log.getMsgMask() | LogMask::Dump | LogMask::Debug |
80+
LogMask::Info | LogMask::Warning | LogMask::Error);
7881
} else if (!strcmp(val, "debug")) {
79-
log.setMsgMask(log.getMsgMask() | LogMask::Debug);
82+
log.setMsgMask(log.getMsgMask() | LogMask::Debug | LogMask::Info |
83+
LogMask::Warning | LogMask::Error);
8084
} else if (!strcmp(val, "none")) {
8185
log.setMsgMask(0);
8286
} else {
83-
log.Emsg("Config",
84-
"scitokens.trace encountered an unknown directive:", val);
87+
log.Emsg("Config", "trace encountered an unknown directive:", val);
8588
return false;
8689
}
8790
} while ((val = conf.GetToken()));

0 commit comments

Comments
 (0)