Skip to content

Commit 1166f86

Browse files
abrauneggabraunegg
authored
Enhancement: Move curl debug logging to --debug-https (#3120)
* As all the curl engine reuse is now stable, move debug logging of curl engine stack to --debug-https * Extract the DataCentre information from the http response header to use in application output * Align 'Remaining Free Space' to accommodate Data Centre output
1 parent 0216b63 commit 1166f86

File tree

5 files changed

+52
-30
lines changed

5 files changed

+52
-30
lines changed

‎.github/actions/spelling/allow.txt

+1
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ accrightslen
99
adamdruppe
1010
addrepo
1111
adr
12+
ags
1213
aip
1314
alex
1415
alpinelinux

‎src/curlEngine.d

+41-22
Original file line numberDiff line numberDiff line change
@@ -80,6 +80,25 @@ class CurlResponse {
8080
hasResponse = true;
8181
this.responseHeaders = http.responseHeaders();
8282
this.statusLine = http.statusLine;
83+
84+
// has 'microsoftDataCentre' been set yet?
85+
if (microsoftDataCentre.empty) {
86+
// Extract the 'x-ms-ags-diagnostic' header if it exists
87+
if ("x-ms-ags-diagnostic" in this.responseHeaders) {
88+
// try and extract the data centre details
89+
try {
90+
// attempt to extract the data centre location from the header
91+
auto diagHeaderData = parseJSON(this.responseHeaders["x-ms-ags-diagnostic"]);
92+
string dataCentre = diagHeaderData["ServerInfo"]["DataCenter"].str;
93+
// set the Microsoft Data Centre value
94+
microsoftDataCentre = dataCentre;
95+
} catch (Exception e) {
96+
// do nothing
97+
}
98+
}
99+
}
100+
101+
// Output the response headers only if using debug mode + debugging https itself
83102
if ((debugLogging) && (debugHTTPSResponse)) {
84103
addLogEntry("HTTP Response Headers: " ~ to!string(this.responseHeaders), ["debug"]);
85104
addLogEntry("HTTP Status Line: " ~ to!string(this.statusLine), ["debug"]);
@@ -198,7 +217,7 @@ class CurlEngine {
198217
http = HTTP(); // Directly initializes HTTP using its default constructor
199218
response = null; // Initialize as null
200219
internalThreadId = generateAlphanumericString(); // Give this CurlEngine instance a unique ID
201-
if (debugLogging) {addLogEntry("Created new CurlEngine instance id: " ~ to!string(internalThreadId), ["debug"]);}
220+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("Created new CurlEngine instance id: " ~ to!string(internalThreadId), ["debug"]);}
202221
}
203222

204223
// The destructor should only clean up resources owned directly by this CurlEngine instance
@@ -225,7 +244,7 @@ class CurlEngine {
225244
// Set timestamp of release
226245
releaseTimestamp = Clock.currTime(UTC());
227246
// Log that we are releasing this engine back to the pool
228-
if (debugLogging) {
247+
if ((debugLogging) && (debugHTTPSResponse)) {
229248
addLogEntry("CurlEngine releaseEngine() called on instance id: " ~ to!string(internalThreadId), ["debug"]);
230249
addLogEntry("CurlEngine curlEnginePool size before release: " ~ to!string(curlEnginePool.length), ["debug"]);
231250
string engineReleaseMessage = format("Release Timestamp for CurlEngine %s: %s", to!string(internalThreadId), to!string(releaseTimestamp));
@@ -236,7 +255,7 @@ class CurlEngine {
236255
cleanup(true); // Cleanup instance by resetting values and flushing cookie cache
237256
synchronized (CurlEngine.classinfo) {
238257
curlEnginePool ~= this;
239-
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool size after release: " ~ to!string(curlEnginePool.length), ["debug"]);}
258+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine curlEnginePool size after release: " ~ to!string(curlEnginePool.length), ["debug"]);}
240259
}
241260
// Perform Garbage Collection
242261
GC.collect();
@@ -334,7 +353,7 @@ class CurlEngine {
334353

335354
if (httpsDebug) {
336355
// Output what options we are using so that in the debug log this can be tracked
337-
if (debugLogging) {
356+
if ((debugLogging) && (debugHTTPSResponse)) {
338357
addLogEntry("http.dnsTimeout = " ~ to!string(dnsTimeout), ["debug"]);
339358
addLogEntry("http.connectTimeout = " ~ to!string(connectTimeout), ["debug"]);
340359
addLogEntry("http.dataTimeout = " ~ to!string(dataTimeout), ["debug"]);
@@ -456,7 +475,7 @@ class CurlEngine {
456475
// Cleanup this instance internal variables that may have been set
457476
void cleanup(bool flushCookies = false) {
458477
// Reset any values to defaults, freeing any set objects
459-
if (debugLogging) {addLogEntry("CurlEngine cleanup() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}
478+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine cleanup() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}
460479

461480
// Is the instance is stopped?
462481
if (!http.isStopped) {
@@ -493,23 +512,23 @@ class CurlEngine {
493512
// Shut down the curl instance & close any open sockets
494513
void shutdownCurlHTTPInstance() {
495514
// Log that we are attempting to shutdown this curl instance
496-
if (debugLogging) {addLogEntry("CurlEngine shutdownCurlHTTPInstance() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}
515+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine shutdownCurlHTTPInstance() called on instance id: " ~ to!string(internalThreadId), ["debug"]);}
497516

498517
// Is this curl instance is stopped?
499518
if (!http.isStopped) {
500-
if (debugLogging) {
519+
if ((debugLogging) && (debugHTTPSResponse)) {
501520
addLogEntry("HTTP instance still active: " ~ to!string(internalThreadId), ["debug"]);
502521
addLogEntry("HTTP instance isStopped state before http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);
503522
}
504523
http.shutdown();
505-
if (debugLogging) {addLogEntry("HTTP instance isStopped state post http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);}
524+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("HTTP instance isStopped state post http.shutdown(): " ~ to!string(http.isStopped), ["debug"]);}
506525
object.destroy(http); // Destroy, however we cant set to null
507-
if (debugLogging) {addLogEntry("HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}
526+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}
508527

509528
} else {
510529
// Already stopped .. destroy it
511530
object.destroy(http); // Destroy, however we cant set to null
512-
if (debugLogging) {addLogEntry("Stopped HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}
531+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("Stopped HTTP instance shutdown and destroyed: " ~ to!string(internalThreadId), ["debug"]);}
513532
}
514533
// Perform Garbage Collection
515534
GC.collect();
@@ -522,14 +541,14 @@ class CurlEngine {
522541

523542
// Get a curl instance for the OneDrive API to use
524543
CurlEngine getCurlInstance() {
525-
if (debugLogging) {addLogEntry("CurlEngine getCurlInstance() called", ["debug"]);}
544+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine getCurlInstance() called", ["debug"]);}
526545

527546
synchronized (CurlEngine.classinfo) {
528547
// What is the current pool size
529-
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool current size: " ~ to!string(curlEnginePool.length), ["debug"]);}
548+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine curlEnginePool current size: " ~ to!string(curlEnginePool.length), ["debug"]);}
530549

531550
if (curlEnginePool.empty) {
532-
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool is empty - constructing a new CurlEngine instance", ["debug"]);}
551+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine curlEnginePool is empty - constructing a new CurlEngine instance", ["debug"]);}
533552
return new CurlEngine; // Constructs a new CurlEngine with a fresh HTTP instance
534553
} else {
535554
CurlEngine curlEngine = curlEnginePool[$ - 1];
@@ -538,12 +557,12 @@ CurlEngine getCurlInstance() {
538557
// Is this engine stopped?
539558
if (curlEngine.http.isStopped) {
540559
// return a new curl engine as a stopped one cannot be used
541-
if (debugLogging) {addLogEntry("CurlEngine was in a stopped state (not usable) - constructing a new CurlEngine instance", ["debug"]);}
560+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine was in a stopped state (not usable) - constructing a new CurlEngine instance", ["debug"]);}
542561
return new CurlEngine; // Constructs a new CurlEngine with a fresh HTTP instance
543562
} else {
544563
// When was this engine last used?
545564
auto elapsedTime = Clock.currTime(UTC()) - curlEngine.releaseTimestamp;
546-
if (debugLogging) {
565+
if ((debugLogging) && (debugHTTPSResponse)) {
547566
string engineIdleMessage = format("CurlEngine %s time since last use: %s", to!string(curlEngine.internalThreadId), to!string(elapsedTime));
548567
addLogEntry(engineIdleMessage, ["debug"]);
549568
}
@@ -555,18 +574,18 @@ CurlEngine getCurlInstance() {
555574

556575
if (elapsedTime > dur!"seconds"(curlEngine.maxIdleTime)) {
557576
// Too long idle engine, clean it up and create a new one
558-
if (debugLogging) {
577+
if ((debugLogging) && (debugHTTPSResponse)) {
559578
string curlTooOldMessage = format("CurlEngine idle for > %d seconds .... destroying and returning a new curl engine instance", curlEngine.maxIdleTime);
560579
addLogEntry(curlTooOldMessage, ["debug"]);
561580
}
562581

563582
curlEngine.cleanup(true); // Cleanup instance by resetting values and flushing cookie cache
564583
curlEngine.shutdownCurlHTTPInstance(); // Assume proper cleanup of any resources used by HTTP
565-
if (debugLogging) {addLogEntry("Returning NEW curlEngine instance", ["debug"]);}
584+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("Returning NEW curlEngine instance", ["debug"]);}
566585
return new CurlEngine; // Constructs a new CurlEngine with a fresh HTTP instance
567586
} else {
568587
// return an existing curl engine
569-
if (debugLogging) {
588+
if ((debugLogging) && (debugHTTPSResponse)) {
570589
addLogEntry("CurlEngine was in a valid state - returning existing CurlEngine instance", ["debug"]);
571590
addLogEntry("Using CurlEngine instance ID: " ~ curlEngine.internalThreadId, ["debug"]);
572591
}
@@ -581,10 +600,10 @@ CurlEngine getCurlInstance() {
581600

582601
// Release all CurlEngine instances
583602
void releaseAllCurlInstances() {
584-
if (debugLogging) {addLogEntry("CurlEngine releaseAllCurlInstances() called", ["debug"]);}
603+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine releaseAllCurlInstances() called", ["debug"]);}
585604
synchronized (CurlEngine.classinfo) {
586605
// What is the current pool size
587-
if (debugLogging) {addLogEntry("CurlEngine curlEnginePool size to release: " ~ to!string(curlEnginePool.length), ["debug"]);}
606+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine curlEnginePool size to release: " ~ to!string(curlEnginePool.length), ["debug"]);}
588607
if (curlEnginePool.length > 0) {
589608
// Safely iterate and clean up each CurlEngine instance
590609
foreach (curlEngineInstance; curlEnginePool) {
@@ -602,7 +621,7 @@ void releaseAllCurlInstances() {
602621
// Perform Garbage Collection on this destroyed curl engine
603622
GC.collect();
604623
// Log release
605-
if (debugLogging) {addLogEntry("CurlEngine destroyed", ["debug"]);}
624+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine destroyed", ["debug"]);}
606625
}
607626

608627
// Clear the array after all instances have been handled
@@ -614,7 +633,7 @@ void releaseAllCurlInstances() {
614633
// Return free memory to the OS
615634
GC.minimize();
616635
// Log that all curl engines have been released
617-
if (debugLogging) {addLogEntry("CurlEngine releaseAllCurlInstances() completed", ["debug"]);}
636+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("CurlEngine releaseAllCurlInstances() completed", ["debug"]);}
618637
}
619638

620639
// Return how many curl engines there are

‎src/log.d

+1
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ version(Notifications) {
2525
__gshared bool verboseLogging = false;
2626
__gshared bool debugLogging = false;
2727
__gshared bool debugHTTPSResponse = false;
28+
__gshared string microsoftDataCentre;
2829

2930
// Private Shared Module Objects
3031
private __gshared LogBuffer logBuffer;

‎src/onedrive.d

+1-1
Original file line numberDiff line numberDiff line change
@@ -383,7 +383,7 @@ class OneDriveApi {
383383
// Release CurlEngine bask to the Curl Engine Pool
384384
void releaseCurlEngine() {
385385
// Log that this was called
386-
if (debugLogging) {addLogEntry("OneDrive API releaseCurlEngine() Called", ["debug"]);}
386+
if ((debugLogging) && (debugHTTPSResponse)) {addLogEntry("OneDrive API releaseCurlEngine() Called", ["debug"]);}
387387

388388
// Release curl instance back to the pool
389389
if (curlEngine !is null) {

‎src/sync.d

+8-7
Original file line numberDiff line numberDiff line change
@@ -3911,10 +3911,11 @@ class SyncEngine {
39113911
}
39123912

39133913
// Display accountType, defaultDriveId, defaultRootId & remainingFreeSpace for verbose logging purposes
3914-
addLogEntry("Application Version: " ~ appConfig.applicationVersion, ["verbose"]);
3915-
addLogEntry("Account Type: " ~ appConfig.accountType, ["verbose"]);
3916-
addLogEntry("Default Drive ID: " ~ appConfig.defaultDriveId, ["verbose"]);
3917-
addLogEntry("Default Root ID: " ~ appConfig.defaultRootId, ["verbose"]);
3914+
addLogEntry("Application Version: " ~ appConfig.applicationVersion, ["verbose"]);
3915+
addLogEntry("Account Type: " ~ appConfig.accountType, ["verbose"]);
3916+
addLogEntry("Default Drive ID: " ~ appConfig.defaultDriveId, ["verbose"]);
3917+
addLogEntry("Default Root ID: " ~ appConfig.defaultRootId, ["verbose"]);
3918+
addLogEntry("Microsoft Data Centre: " ~ microsoftDataCentre, ["verbose"]);
39183919

39193920
// Fetch the details from cachedOnlineDriveData
39203921
DriveDetailsCache cachedOnlineDriveData;
@@ -3923,13 +3924,13 @@ class SyncEngine {
39233924
// What do we display here for space remaining
39243925
if (cachedOnlineDriveData.quotaRemaining > 0) {
39253926
// Display the actual value
3926-
addLogEntry("Remaining Free Space: " ~ to!string(byteToGibiByte(cachedOnlineDriveData.quotaRemaining)) ~ " GB (" ~ to!string(cachedOnlineDriveData.quotaRemaining) ~ " bytes)", ["verbose"]);
3927+
addLogEntry("Remaining Free Space: " ~ to!string(byteToGibiByte(cachedOnlineDriveData.quotaRemaining)) ~ " GB (" ~ to!string(cachedOnlineDriveData.quotaRemaining) ~ " bytes)", ["verbose"]);
39273928
} else {
39283929
// zero or non-zero value or restricted
39293930
if (!cachedOnlineDriveData.quotaRestricted){
3930-
addLogEntry("Remaining Free Space: 0 KB", ["verbose"]);
3931+
addLogEntry("Remaining Free Space: 0 KB", ["verbose"]);
39313932
} else {
3932-
addLogEntry("Remaining Free Space: Not Available", ["verbose"]);
3933+
addLogEntry("Remaining Free Space: Not Available", ["verbose"]);
39333934
}
39343935
}
39353936

0 commit comments

Comments
 (0)