Make webhooks more resilient

* Do not quit on subscription API errors. Instead, wait a configurable interval before retrying. * Shorten default webhook expiration and renewal intervals to reduce the chance of http 409 errors. * Handle http 409 on subscription creation by taking over the existing subscription. * Handle http 404 on subscription renewal by creating a new subscription(current behavior, listed for completeness). * Log other known http errors include 400 (bad webhook endpoint), 401 (auth failed), and 403 (too many subscriptions). * Log detailed messages when encoutering unknown http errors to assist with future debugging.
2024-06-03 14:32:24 +02:00 · 2023-10-15 08:14:02 -07:00 · 2023-10-15 08:14:02 -07:00 · 30ee83a2ae
parent 4a60654e3f
commit 30ee83a2ae
6 changed files with 362 additions and 193 deletions
--- a/5
+++ b/5
@ -48,8 +48,9 @@
 # webhook_public_url = ""
 # webhook_listening_host = ""
 # webhook_listening_port = "8888"
-# webhook_expiration_interval = "86400"
-# webhook_renewal_interval = "43200"
+# webhook_expiration_interval = "600"
+# webhook_renewal_interval = "300"
+# webhook_retry_interval = "60"
 # space_reservation = "50"
 # display_running_config = "false"
 # read_only_auth_scope = "false"
--- a/docs/USAGE.md
+++ b/docs/USAGE.md
@ -57,8 +57,8 @@ Before reading this document, please ensure you are running application version
 - [Running 'onedrive' in 'monitor' mode](#running-onedrive-in-monitor-mode)
  * [Use webhook to subscribe to remote updates in 'monitor' mode](#use-webhook-to-subscribe-to-remote-updates-in-monitor-mode)
  * [More webhook configuration options](#more-webhook-configuration-options)
-    + [webhook_listening_host and webhook_listening_port](#webhook_listening_host-and-webhook_listening_port)
-    + [webhook_expiration_interval and webhook_renewal_interval](#webhook_expiration_interval-and-webhook_renewal_interval)
+    + [Webhook listening host and port](#webhook-listening-host-and-port)
+    + [Webhook expiration, renewal and retry intervals](#webhook-expiration-renewal-and-retry-intervals)
 - [Running 'onedrive' as a system service](#running-onedrive-as-a-system-service)
  * [OneDrive service running as root user via init.d](#onedrive-service-running-as-root-user-via-initd)
  * [OneDrive service running as root user via systemd (Arch, Ubuntu, Debian, OpenSuSE, Fedora)](#onedrive-service-running-as-root-user-via-systemd-arch-ubuntu-debian-opensuse-fedora)
@ -524,8 +524,8 @@ See the [config](https://raw.githubusercontent.com/abraunegg/onedrive/master/con
 # webhook_public_url = ""
 # webhook_listening_host = ""
 # webhook_listening_port = "8888"
-# webhook_expiration_interval = "86400"
-# webhook_renewal_interval = "43200"
+# webhook_expiration_interval = "600"
+# webhook_renewal_interval = "300"
 # space_reservation = "50"
 # display_running_config = "false"
 # read_only_auth_scope = "false"
@ -891,8 +891,8 @@ By default, the application will reserve 50MB of disk space to prevent your file
 Example:
 ```text
 ...
-# webhook_expiration_interval = "86400"
-# webhook_renewal_interval = "43200"
+# webhook_expiration_interval = "600"
+# webhook_renewal_interval = "300"
 space_reservation = "10"
 ```

@ -1059,7 +1059,7 @@ For any further nginx configuration assistance, please refer to: https://docs.ng

 Below options can be optionally configured. The default is usually good enough.

-#### webhook_listening_host and webhook_listening_port
+#### Webhook listening host and port

 Set `webhook_listening_host` and `webhook_listening_port` to change the webhook listening endpoint. If `webhook_listening_host` is left empty, which is the default, the webhook will bind to `0.0.0.0`. The default `webhook_listening_port` is `8888`.

@ -1068,16 +1068,21 @@ webhook_listening_host = ""
 webhook_listening_port = "8888"
 ```

-#### webhook_expiration_interval and webhook_renewal_interval
+#### Webhook expiration, renewal and retry intervals

-Set `webhook_expiration_interval` and `webhook_renewal_interval` to change the frequency of subscription renewal. By default, the webhook asks Microsoft to keep subscriptions alive for 24 hours, and it renews subscriptions when it is less than 12 hours before their expiration.
+Set `webhook_expiration_interval` and `webhook_renewal_interval` to change the frequency of subscription renewal. Set `webhook_retry_interval` to change the delay before retrying after an error happens while communicating with Microsoft's subscription endpoints.
+
+By default, the webhook asks Microsoft to keep subscriptions alive for 10 minutes, and it renews subscriptions when it is less than 5 minutes before their expiration. When errors happen, it waits 1 minute before retrying.

 ```
-# Default expiration interval is 24 hours
-webhook_expiration_interval = "86400"
+# Default expiration interval is 10 minutes
+webhook_expiration_interval = "600"

-# Default renewal interval is 12 hours
-webhook_renewal_interval = "43200"
+# Default renewal interval is 5 minutes
+webhook_renewal_interval = "300"
+
+# Default retry interval is 1 minute
+webhook_retry_interval = "60"
 ```

 ## Running 'onedrive' as a system service
--- a/src/config.d
+++ b/src/config.d
@ -158,8 +158,9 @@ final class Config
 		stringValues["webhook_public_url"] = "";
 		stringValues["webhook_listening_host"] = "";
 		longValues["webhook_listening_port"] = 8888;
-		longValues["webhook_expiration_interval"] = 3600 * 24;
-		longValues["webhook_renewal_interval"] = 3600 * 12;
+		longValues["webhook_expiration_interval"] = 60 * 10;
+		longValues["webhook_renewal_interval"] = 60 * 5;
+		longValues["webhook_retry_interval"] = 60;
 		// Log to application output running configuration values
 		boolValues["display_running_config"] = false;
 		// Configure read-only authentication scope
--- a/src/main.d
+++ b/src/main.d
@ -808,6 +808,7 @@ int main(string[] args)
 			writeln("Config option 'webhook_listening_port'       = ", cfg.getValueLong("webhook_listening_port"));
 			writeln("Config option 'webhook_expiration_interval'  = ", cfg.getValueLong("webhook_expiration_interval"));
 			writeln("Config option 'webhook_renewal_interval'     = ", cfg.getValueLong("webhook_renewal_interval"));
+			writeln("Config option 'webhook_retry_interval'       = ", cfg.getValueLong("webhook_retry_interval"));
 		}

 		if (cfg.getValueBool("display_running_config")) {
--- a/src/onedrive.d
+++ b/src/onedrive.d
@ -201,8 +201,8 @@ final class OneDriveApi
 	private SysTime accessTokenExpiration;
 	private HTTP http;
 	private OneDriveWebhook webhook;
-	private SysTime subscriptionExpiration;
-	private Duration subscriptionExpirationInterval, subscriptionRenewalInterval;
+	private SysTime subscriptionExpiration, subscriptionLastErrorAt;
+	private Duration subscriptionExpirationInterval, subscriptionRenewalInterval, subscriptionRetryInternal;
 	private string notificationUrl;

 	// if true, every new access token is printed
@ -485,8 +485,10 @@ final class OneDriveApi
 		}

 		subscriptionExpiration = Clock.currTime(UTC());
+		subscriptionLastErrorAt = SysTime.fromUnixTime(0);
 		subscriptionExpirationInterval = dur!"seconds"(cfg.getValueLong("webhook_expiration_interval"));
 		subscriptionRenewalInterval = dur!"seconds"(cfg.getValueLong("webhook_renewal_interval"));
+		subscriptionRetryInternal = dur!"seconds"(cfg.getValueLong("webhook_retry_interval"));
 		notificationUrl = cfg.getValueString("webhook_public_url");
 	}

@ -1004,17 +1006,25 @@ final class OneDriveApi
 			spawn(&OneDriveWebhook.serve);
 		}

+		auto elapsed = Clock.currTime(UTC()) - subscriptionLastErrorAt;
+		if (elapsed < subscriptionRetryInternal) {
+			return;
+		}
+
+		try {
 			if (!hasValidSubscription()) {
 				createSubscription();
 			} else if (isSubscriptionUpForRenewal()) {
-			try {
 				renewSubscription();
+			}
 		} catch (OneDriveException e) {
-				if (e.httpStatusCode == 404) {
-					log.log("The subscription is not found on the server. Recreating subscription ...");
-					createSubscription();
-				}
-			}
+			logSubscriptionError(e);
+			subscriptionLastErrorAt = Clock.currTime(UTC());
+			log.log("Will retry creating or renewing subscription in ", subscriptionRetryInternal);
+		} catch (JSONException e) {
+			log.error("ERROR: Unexpected JSON error: ", e.msg);
+			subscriptionLastErrorAt = Clock.currTime(UTC());
+			log.log("Will retry creating or renewing subscription in ", subscriptionRetryInternal);
 		}
 	}

@ -1049,22 +1059,56 @@ final class OneDriveApi
 			"clientState": randomUUID().toString()
 		];
 		http.addRequestHeader("Content-Type", "application/json");
-		JSONValue response;

 		try {
-			response = post(url, request.toString());
-		} catch (OneDriveException e) {
-			displayOneDriveErrorMessage(e.msg, getFunctionName!({}));
-			
-			// We need to exit here, user needs to fix issue
-			log.error("ERROR: Unable to initialize subscriptions for updates. Please fix this issue.");
-			shutdown();
-			exit(-1);
-		}
+			JSONValue response = post(url, request.toString());

 			// Save important subscription metadata including id and expiration
 			subscriptionId = response["id"].str;
 			subscriptionExpiration = SysTime.fromISOExtString(response["expirationDateTime"].str);
+			log.log("Created new subscription ", subscriptionId, " with expiration: ", subscriptionExpiration.toISOExtString());
+		} catch (OneDriveException e) {
+			if (e.httpStatusCode == 409) {
+				// Take over an existing subscription on HTTP 409.
+				//
+				// Sample 409 error:
+				// {
+				// 	"error": {
+				// 			"code": "ObjectIdentifierInUse",
+				// 			"innerError": {
+				// 					"client-request-id": "615af209-467a-4ab7-8eff-27c1d1efbc2d",
+				// 					"date": "2023-09-26T09:27:45",
+				// 					"request-id": "615af209-467a-4ab7-8eff-27c1d1efbc2d"
+				// 			},
+				// 			"message": "Subscription Id c0bba80e-57a3-43a7-bac2-e6f525a76e7c already exists for the requested combination"
+				// 	}
+				// }
+
+				// Make sure the error code is "ObjectIdentifierInUse"
+				try {
+					if (e.error["error"]["code"].str != "ObjectIdentifierInUse") {
+						throw e;
+					}
+				} catch (JSONException jsonEx) {
+					throw e;
+				}
+
+				// Extract the existing subscription id from the error message
+				import std.regex;
+				auto idReg = ctRegex!(r"[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}", "i");
+				auto m = matchFirst(e.error["error"]["message"].str, idReg);
+				if (!m) {
+					throw e;
+				}
+
+				// Save the subscription id and renew it immediately since we don't know the expiration timestamp
+				subscriptionId = m[0];
+				log.log("Found existing subscription ", subscriptionId);
+				renewSubscription();
+			} else {
+				throw e;
+			}
+		}
 	}

 	private void renewSubscription() {
@ -1077,10 +1121,23 @@ final class OneDriveApi
 			"expirationDateTime": expirationDateTime.toISOExtString()
 		];
 		http.addRequestHeader("Content-Type", "application/json");
+
+		try {
 			JSONValue response = patch(url, request.toString());

 			// Update subscription expiration from the response
 			subscriptionExpiration = SysTime.fromISOExtString(response["expirationDateTime"].str);
+			log.log("Renewed subscription ", subscriptionId, " with expiration: ", subscriptionExpiration.toISOExtString());
+		} catch (OneDriveException e) {
+			if (e.httpStatusCode == 404) {
+				log.log("The subscription is not found on the server. Recreating subscription ...");
+				subscriptionId = null;
+				subscriptionExpiration = Clock.currTime(UTC());
+				createSubscription();
+			} else {
+				throw e;
+			}
+		}
 	}

 	private void deleteSubscription() {
@ -1094,6 +1151,100 @@ final class OneDriveApi
 		log.log("Deleted subscription");
 	}

+	private void logSubscriptionError(OneDriveException e) {
+		if (e.httpStatusCode == 400) {
+			// Log known 400 error where Microsoft cannot get a 200 OK from the webhook endpoint
+			//
+			// Sample 400 error:
+			// {
+			// 	"error": {
+			// 			"code": "InvalidRequest",
+			// 			"innerError": {
+			// 					"client-request-id": "<uuid>",
+			// 					"date": "<timestamp>",
+			// 					"request-id": "<uuid>"
+			// 			},
+			// 			"message": "Subscription validation request failed. Notification endpoint must respond with 200 OK to validation request."
+			// 	}
+			// }
+
+			try {
+				if (e.error["error"]["code"].str == "InvalidRequest") {
+					import std.regex;
+					auto msgReg = ctRegex!(r"Subscription validation request failed", "i");
+					auto m = matchFirst(e.error["error"]["message"].str, msgReg);
+					if (m) {
+						log.error("ERROR: Cannot create or renew subscription: Microsoft did not get 200 OK from the webhook endpoint.");
+						return;
+					}
+				}
+			} catch (JSONException) {
+				// fallthrough
+			}
+		} else if (e.httpStatusCode == 401) {
+			// Log known 401 error where authentication failed
+			//
+			// Sample 401 error:
+			// {
+			// 	"error": {
+			// 			"code": "ExtensionError",
+			// 			"innerError": {
+			// 					"client-request-id": "<uuid>",
+			// 					"date": "<timestamp>",
+			// 					"request-id": "<uuid>"
+			// 			},
+			// 			"message": "Operation: Create; Exception: [Status Code: Unauthorized; Reason: Authentication failed]"
+			// 	}
+			// }
+
+			try {
+				if (e.error["error"]["code"].str == "ExtensionError") {
+					import std.regex;
+					auto msgReg = ctRegex!(r"Authentication failed", "i");
+					auto m = matchFirst(e.error["error"]["message"].str, msgReg);
+					if (m) {
+						log.error("ERROR: Cannot create or renew subscription: Authentication failed.");
+						return;
+					}
+				}
+			} catch (JSONException) {
+				// fallthrough
+			}
+		} else if (e.httpStatusCode == 403) {
+			// Log known 403 error where the number of subscriptions on item has exceeded limit
+			//
+			// Sample 403 error:
+			// {
+			// 	"error": {
+			// 			"code": "ExtensionError",
+			// 			"innerError": {
+			// 					"client-request-id": "<uuid>",
+			// 					"date": "<timestamp>",
+			// 					"request-id": "<uuid>"
+			// 			},
+			// 			"message": "Operation: Create; Exception: [Status Code: Forbidden; Reason: Number of subscriptions on item has exceeded limit]"
+			// 	}
+			// }
+			try {
+				if (e.error["error"]["code"].str == "ExtensionError") {
+					import std.regex;
+					auto msgReg = ctRegex!(r"Number of subscriptions on item has exceeded limit", "i");
+					auto m = matchFirst(e.error["error"]["message"].str, msgReg);
+					if (m) {
+						log.error("ERROR: Cannot create or renew subscription: Number of subscriptions has exceeded limit.");
+						return;
+					}
+				}
+			} catch (JSONException) {
+				// fallthrough
+			}
+		}
+
+		// Log detailed message for unknown errors
+		log.error("ERROR: Cannot create or renew subscription.");
+		displayOneDriveErrorMessage(e.msg, getFunctionName!({}));
+	}
+
 	private void redeemToken(const(char)[] authCode)
 	{
 		const(char)[] postData =
--- a/src/util.d
+++ b/src/util.d
@ -281,6 +281,7 @@ void displayOneDriveErrorMessage(string message, string callingFunction)
 	if (errorMessage.type() == JSONType.object) {
 		// configure the error reason
 		string errorReason;
+		string errorCode;
 		string requestDate;
 		string requestId;

@ -310,6 +311,14 @@ void displayOneDriveErrorMessage(string message, string callingFunction)
 			log.error("  Error Reason:     ", errorReason);
 		}

+		// Get the error code if available
+		try {
+			// Use ["error"]["code"] as code
+			errorCode = errorMessage["error"]["code"].str;
+		} catch (JSONException e) {
+			// we dont want to do anything here
+		}
+
 		// Get the date of request if available
 		try {
 			// Use ["error"]["innerError"]["date"] as date
@ -326,7 +335,8 @@ void displayOneDriveErrorMessage(string message, string callingFunction)
 			// we dont want to do anything here
 		}

-		// Display the date and request id if available
+		// Display the error code, date and request id if available
+		if (errorCode != "")   log.error("  Error Code:       ", errorCode);
 		if (requestDate != "") log.error("  Error Timestamp:  ", requestDate);
 		if (requestId != "")   log.error("  API Request ID:   ", requestId);
 	}