Skip to content

Commit c9d9467

Browse files
dankmeme01dankmeme01
committed
always print verbose request logs on failures, other log changes
1 parent b1734ae commit c9d9467

File tree

1 file changed

+72
-40
lines changed

1 file changed

+72
-40
lines changed

‎loader/src/utils/web.cpp‎

Lines changed: 72 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,11 @@ using namespace arc;
3838

3939
static std::atomic<bool> g_knownIpv6Support{false};
4040
static std::atomic<bool> g_knownHostileToDOH{false};
41+
static std::atomic<bool> g_verboseLogging{false};
42+
43+
static bool verboseLog() {
44+
return g_verboseLogging.load(std::memory_order::relaxed);
45+
}
4146

4247
static long unwrapProxyType(ProxyType type) {
4348
switch (type) {
@@ -171,6 +176,7 @@ class WebResponse::Impl {
171176
int m_code;
172177
ByteVector m_data;
173178
std::string m_errMessage;
179+
utils::StringBuffer<8> m_logs; // always heap
174180
utils::StringMap<std::vector<std::string>> m_headers;
175181
RequestTimings m_timings;
176182

@@ -402,6 +408,10 @@ std::string_view WebResponse::errorMessage() const {
402408
return m_impl->m_errMessage;
403409
}
404410

411+
std::string_view WebResponse::verboseLogs() const {
412+
return m_impl->m_logs.view();
413+
}
414+
405415
RequestTimings const& WebResponse::timings() const {
406416
return m_impl->m_timings;
407417
}
@@ -705,44 +715,48 @@ class WebRequest::Impl {
705715
}
706716

707717
// Verbose logging
708-
if (Mod::get()->getSettingValue<bool>("verbose-curl-logs")) {
709-
curl_easy_setopt(curl, CURLOPT_VERBOSE, 1L);
710-
curl_easy_setopt(curl, CURLOPT_DEBUGFUNCTION, +[](CURL* handle, curl_infotype type, char* data, size_t size, void* clientp) {
711-
while (size > 0 && (data[size - 1] == '\n' || data[size - 1] == '\r')) {
712-
size--; // remove trailing newline
713-
}
718+
curl_easy_setopt(curl, CURLOPT_VERBOSE, 1L);
719+
curl_easy_setopt(curl, CURLOPT_DEBUGFUNCTION, +[](CURL* handle, curl_infotype type, char* data, size_t size, void* clientp) {
720+
while (size > 0 && (data[size - 1] == '\n' || data[size - 1] == '\r')) {
721+
size--; // remove trailing newline
722+
}
714723

715-
switch (type) {
716-
case CURLINFO_TEXT:
717-
log::debug("[Curl] {}", std::string_view(data, size));
718-
break;
719-
case CURLINFO_HEADER_IN:
720-
log::debug("[Curl] Header in: {}", std::string_view(data, size));
721-
break;
722-
case CURLINFO_HEADER_OUT:
723-
log::debug("[Curl] Header out: {}", std::string_view(data, size));
724-
break;
725-
case CURLINFO_DATA_IN:
726-
log::trace("[Curl] Data in ({} bytes)", size);
727-
break;
728-
case CURLINFO_DATA_OUT:
729-
log::trace("[Curl] Data out ({} bytes)", size);
730-
break;
731-
case CURLINFO_SSL_DATA_IN:
732-
log::trace("[Curl] SSL data in ({} bytes)", size);
733-
break;
734-
case CURLINFO_SSL_DATA_OUT:
735-
log::trace("[Curl] SSL data out ({} bytes)", size);
736-
break;
737-
case CURLINFO_END:
738-
log::debug("[Curl] End of info");
739-
break;
740-
default:
741-
log::debug("[Curl] Unknown info type: {}", static_cast<int>(type));
742-
break;
743-
}
744-
});
745-
}
724+
// skip data
725+
if (type == CURLINFO_DATA_IN || type == CURLINFO_DATA_OUT || type == CURLINFO_SSL_DATA_IN || type == CURLINFO_SSL_DATA_OUT) {
726+
return 0;
727+
}
728+
729+
std::string_view content(data, size);
730+
if (verboseLog()) {
731+
log::debug("[Curl] {}", content);
732+
}
733+
734+
if (!clientp) {
735+
return 0;
736+
}
737+
738+
auto& rlogs = static_cast<ResponseData*>(clientp)->response.m_impl->m_logs;
739+
740+
switch (type) {
741+
case CURLINFO_TEXT:
742+
rlogs.append(content);
743+
rlogs.append('\n');
744+
break;
745+
case CURLINFO_HEADER_IN:
746+
rlogs.append("Header in: {}\n", content);
747+
break;
748+
case CURLINFO_HEADER_OUT:
749+
rlogs.append("Header out: {}\n", content);
750+
break;
751+
case CURLINFO_END:
752+
rlogs.append("--- End of info ---\n");
753+
break;
754+
default: break;
755+
}
756+
757+
return 0;
758+
});
759+
curl_easy_setopt(curl, CURLOPT_DEBUGDATA, requestData);
746760

747761
// If an error happens, we want to get a more specific description of the issue
748762
curl_easy_setopt(curl, CURLOPT_ERRORBUFFER, m_errorBuf);
@@ -1202,6 +1216,11 @@ class WebRequestsManager::Impl {
12021216

12031217
m_worker = async::runtime().spawn(this->workerFunc(std::move(rx), std::move(crx)));
12041218
m_worker.setName("Geode Web Worker");
1219+
1220+
g_verboseLogging.store(Mod::get()->getSettingValue<bool>("verbose-curl-logs"));
1221+
listenForSettingChanges<bool>("verbose-curl-logs", [this](bool value) {
1222+
g_verboseLogging.store(value);
1223+
});
12051224
}
12061225

12071226
// Note for future people: this is currently leaked because cleanup is unsafe in statics
@@ -1235,21 +1254,27 @@ class WebRequestsManager::Impl {
12351254
req->curl = handle;
12361255
curl_easy_setopt(handle, CURLOPT_PRIVATE, req.get());
12371256

1238-
// log::debug("Added request ({})", req->request->m_url);
1257+
if (verboseLog()) {
1258+
log::debug("Added request ({})", req->request->m_url);
1259+
}
12391260
curl_multi_add_handle(m_multiHandle, handle);
12401261
m_activeRequests.insert(std::move(req));
12411262
this->workerKickCurl();
12421263
}
12431264

12441265
void workerCancelRequest(std::shared_ptr<RequestData> req) {
1245-
// log::debug("Cancelled request ({})", req->request->m_url);
1266+
if (verboseLog()) {
1267+
log::debug("Cancelled request ({})", req->request->m_url);
1268+
}
12461269
req->onError(GeodeWebError::REQUEST_CANCELLED, "Request cancelled");
12471270

12481271
this->cleanupRequest(std::move(req));
12491272
}
12501273

12511274
void cleanupRequest(std::shared_ptr<RequestData> req) {
1252-
// log::debug("Removing request ({})", req->request->m_url);
1275+
if (verboseLog()) {
1276+
log::debug("Removing request ({})", req->request->m_url);
1277+
}
12531278
m_activeRequests.erase(req);
12541279

12551280
auto curl = std::exchange(req->curl, nullptr);
@@ -1323,6 +1348,8 @@ class WebRequestsManager::Impl {
13231348
std::string_view err = curl_easy_strerror(msg->data.result);
13241349
log::error("cURL failure, error: {}", err);
13251350
log::warn("Error buffer: {}", errorBuf);
1351+
log::warn("Verbose request logs:\n{}", requestData.response.verboseLogs());
1352+
13261353
requestData.onError(
13271354
// Make all CURL error codes negatives to not conflict with HTTP codes
13281355
msg->data.result * -1,
@@ -1353,6 +1380,7 @@ class WebRequestsManager::Impl {
13531380

13541381
arc::selectee(this->workerPollSockets(), [this](PollReadiness readiness) {
13551382
auto [fd, ready] = readiness;
1383+
// log::debug("socket activity, fd: {}, ready: {}", fd, (int)ready);
13561384
int ev = 0;
13571385
if (ready & Interest::Readable) ev |= CURL_CSELECT_IN;
13581386
if (ready & Interest::Writable) ev |= CURL_CSELECT_OUT;
@@ -1383,6 +1411,8 @@ class WebRequestsManager::Impl {
13831411
auto& driver = Runtime::current()->ioDriver();
13841412
auto it = m_sockets.find(s);
13851413

1414+
log::trace("socket callback, socket: {}, what: {}, registered: {}", (int)s, what, it != m_sockets.end());
1415+
13861416
if (what == CURL_POLL_REMOVE) {
13871417
// remove the socket, which unregisters it from the io driver as well
13881418
if (it != m_sockets.end()) {
@@ -1411,6 +1441,8 @@ class WebRequestsManager::Impl {
14111441
}
14121442

14131443
void timerCallback(CURLM* multi, long timeout_ms) {
1444+
// log::trace("timer callback, wake in {}ms", timeout_ms);
1445+
14141446
if (timeout_ms == -1) {
14151447
m_nextWakeup = asp::Instant::farFuture();
14161448
} else {

0 commit comments

Comments
 (0)