Merge remote-tracking branch 'origin/topic/timw/storage-timeout-testing'

* origin/topic/timw/storage-timeout-testing:
  Fix handling of timeout conditions from storage backends
  Reformat plugin.storage btest to be more consistent with other storage tests

CHANGES

@@ -1,3 +1,9 @@
+7.2.0-dev.436 | 2025-03-27 14:07:11 -0700
+
+  * Fix handling of timeout conditions from storage backends (Tim Wojtulewicz, Corelight)
+
+  * Reformat plugin.storage btest to be more consistent with other storage tests (Tim Wojtulewicz, Corelight)
+
 7.2.0-dev.433 | 2025-03-27 12:40:40 -0700
 
   * Remove "experimental" from the QUIC history field's comment string (Christian Kreibich, Corelight)

VERSION

@@ -1 +1 @@
-7.2.0-dev.433
+7.2.0-dev.436

src/storage/Backend.cc

@@ -28,10 +28,8 @@ ResultCallback::ResultCallback(zeek::detail::trigger::TriggerPtr trigger, const
     : trigger(std::move(trigger)), assoc(assoc) {}
 
 void ResultCallback::Timeout() {
-    static const auto& op_result_type = zeek::id::find_type<zeek::RecordType>("Storage::OperationResult");
-
     if ( ! IsSyncCallback() )
-        trigger->Cache(assoc, OperationResult::MakeVal(ReturnCode::TIMEOUT).release());
+        trigger->Cache(assoc, OperationResult::MakeVal(ReturnCode::TIMEOUT).get());
 }
 
 void ResultCallback::Complete(OperationResult res) {
@@ -121,7 +119,11 @@ OperationResult Backend::Erase(ResultCallback* cb, ValPtr key) {
 }
 
 void Backend::CompleteCallback(ResultCallback* cb, const OperationResult& data) const {
-    cb->Complete(data);
+    if ( data.code == ReturnCode::TIMEOUT )
+        cb->Timeout();
+    else
+        cb->Complete(data);
+
     if ( ! cb->IsSyncCallback() ) {
         delete cb;
     }

src/storage/storage-async.bif

@@ -55,7 +55,11 @@ static void handle_async_result(const IntrusivePtr<Backend>& backend, ResultCall
         // it didn't report back IN_PROGRESS.
         // 2. The backend doesn't support async. This means we already blocked in order
         // to get here already.
-        cb->Complete(op_result);
+        // Also check for timeout conditions.
+        if ( op_result.code == ReturnCode::TIMEOUT )
+            cb->Timeout();
+        else
+            cb->Complete(op_result);
         delete cb;
     }
     else if ( run_state::reading_traces ) {

testing/btest/Baseline/plugins.storage/output

@@ -1,5 +1,18 @@
 ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
 open result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<opaque of BackendHandleVal>]
+put result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<uninitialized>]
+get result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=value5678]
+get result same as inserted, T
+
+erase result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<uninitialized>]
+get result after erase, [code=Storage::KEY_NOT_FOUND, error_str=<uninitialized>, value=<uninitialized>]
+
+close result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<uninitialized>]
 results of trying to use closed handle: get: Storage::NOT_CONNECTED, put: Storage::NOT_CONNECTED, erase: Storage::NOT_CONNECTED
+
 open result 2, [code=Storage::OPERATION_FAILED, error_str=Failed to open backend Storage::STORAGEDUMMY: open_fail was set to true, returning error, value=<opaque of BackendHandleVal>]
-close result of closed handle, [code=Storage::NOT_CONNECTED, error_str=Backend is closed, value=<uninitialized>]
+close result on closed handle, [code=Storage::NOT_CONNECTED, error_str=Backend is closed, value=<uninitialized>]
+
+open result 3, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<opaque of BackendHandleVal>]
+put timed out
+close result, [code=Storage::SUCCESS, error_str=<uninitialized>, value=<uninitialized>]

testing/btest/plugins/storage-plugin/src/StorageDummy.cc

@@ -21,8 +21,8 @@ BackendPtr StorageDummy::Instantiate(std::string_view tag) { return make_intrusi
  * with a corresponding message.
  */
 OperationResult StorageDummy::DoOpen(OpenResultCallback* cb, RecordValPtr options) {
-    RecordValPtr backend_options = options->GetField<RecordVal>("dummy");
-    bool open_fail = backend_options->GetField<BoolVal>("open_fail")->Get();
+    RecordValPtr dummy_options = options->GetField<RecordVal>("dummy");
+    bool open_fail = dummy_options->GetField<BoolVal>("open_fail")->Get();
     if ( open_fail )
         return {ReturnCode::OPERATION_FAILED, "open_fail was set to true, returning error"};
 
@@ -44,6 +44,11 @@ OperationResult StorageDummy::DoClose(ResultCallback* cb) {
  */
 OperationResult StorageDummy::DoPut(ResultCallback* cb, ValPtr key, ValPtr value, bool overwrite,
                                     double expiration_time) {
+    RecordValPtr dummy_options = backend_options->GetField<RecordVal>("dummy");
+    bool timeout_put = dummy_options->GetField<BoolVal>("timeout_put")->Get();
+    if ( timeout_put )
+        return {ReturnCode::TIMEOUT};
+
     auto json_key = key->ToJSON()->ToStdString();
     auto json_value = value->ToJSON()->ToStdString();
     data[json_key] = json_value;

testing/btest/plugins/storage.zeek

@@ -8,10 +8,12 @@
 # @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output
 # @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff zeek-stderr
 
+@load base/frameworks/storage/async
 @load base/frameworks/storage/sync
 
 type StorageDummyOpts : record {
 	open_fail: bool;
+	timeout_put: bool;
 };
 
 redef record Storage::BackendOptions += {
@@ -20,41 +22,66 @@ redef record Storage::BackendOptions += {
 
 event zeek_init() {
 	local opts : Storage::BackendOptions;
-	opts$dummy = [$open_fail = F];
+	opts$dummy = [$open_fail = F, $timeout_put = F];
 
 	local key = "key1234";
 	local value = "value5678";
 
-	# Test basic operation. The second get() should return an error
-	# as the key should have been erased.
-	local open_res = Storage::Sync::open_backend(Storage::STORAGEDUMMY, opts, string, string);
-	print "open result", open_res;
-	local b = open_res$value;
-	local put_res = Storage::Sync::put(b, [$key=key, $value=value, $overwrite=F]);
-	local get_res = Storage::Sync::get(b, key);
-	if ( get_res$code != Storage::SUCCESS ) {
-		print("Got an invalid value in response!");
-	}
+	# Basic operation. Open, put, and get the value back.
+	local res = Storage::Sync::open_backend(Storage::STORAGEDUMMY, opts, string, string);
+	print "open result", res;
+	local b = res$value;
 
-	local erase_res = Storage::Sync::erase(b, key);
-	get_res = Storage::Sync::get(b, key);
-	Storage::Sync::close_backend(b);
+	res = Storage::Sync::put(b, [$key=key, $value=value, $overwrite=F]);
+	print "put result", res;
 
-	if ( get_res$code != Storage::SUCCESS && get_res?$error_str )
-		Reporter::error(get_res$error_str);
+	res = Storage::Sync::get(b, key);
+	print "get result", res;
+	if ( res$code == Storage::SUCCESS && res?$value )
+		print "get result same as inserted", value == (res$value as string);
+	print "";
+
+	# Erase the key and attempt to get it back.
+	res = Storage::Sync::erase(b, key);
+	print "erase result", res;
+	res = Storage::Sync::get(b, key);
+	print "get result after erase", res;
+	print "";
+
+	# Close the handle and test trying to use the closed handle.
+	res = Storage::Sync::close_backend(b);
+	print "close result", res;
 
 	# Test attempting to use the closed handle.
-	put_res = Storage::Sync::put(b, [$key="a", $value="b", $overwrite=F]);
-	get_res = Storage::Sync::get(b, "a");
-	erase_res = Storage::Sync::erase(b, "a");
+	local put_res = Storage::Sync::put(b, [$key="a", $value="b", $overwrite=F]);
+	local get_res = Storage::Sync::get(b, "a");
+	local erase_res = Storage::Sync::erase(b, "a");
 
 	print(fmt("results of trying to use closed handle: get: %s, put: %s, erase: %s",
 	          get_res$code, put_res$code, erase_res$code));
+	print "";
 
 	# Test failing to open the handle and test closing an invalid handle.
-	opts$dummy$open_fail = T;
-	open_res = Storage::Sync::open_backend(Storage::STORAGEDUMMY, opts, string, string);
-	print "open result 2", open_res;
-	local close_res = Storage::Sync::close_backend(open_res$value);
-	print "close result of closed handle", close_res;
+	opts$dummy = [$open_fail = T, $timeout_put = F];
+	res = Storage::Sync::open_backend(Storage::STORAGEDUMMY, opts, string, string);
+	print "open result 2", res;
+	res = Storage::Sync::close_backend(res$value);
+	print "close result on closed handle", res;
+	print "";
+
+	# Test timing out an async put request.
+	opts$dummy = [$open_fail = F, $timeout_put = T];
+	res = Storage::Sync::open_backend(Storage::STORAGEDUMMY, opts, string, string);
+	print "open result 3", res;
+	b = res$value;
+
+	when [b, key, value] ( local res2 = Storage::Async::put(b, [$key=key, $value=value]) ) {
+		local when_res = Storage::Sync::close_backend(b);
+		print "FAIL: should not happen: close result", when_res;
+	}
+	timeout 5sec {
+		print "put timed out";
+		local to_res = Storage::Sync::close_backend(b);
+		print "close result", to_res;
+	}
 }