FIT: Operations like GET, UPSERT and LOCK on a already locked document are returning DOCUMENT_LOCKED_EXCEPTION while expected exception is AMBIGUOUS_TIMEOUT_EXCEPTION

com.couchbase.client.kv.LockTest.getAndLockTimeoutHasRetryReasonLocked, com.couchbase.client.kv.LockTest.upsertLockedDocumentTimeoutHasRetryReasonLocked, com.couchbase.client.kv.LockTest.verifyGetAndLockDoubleLock, com.couchbase.client.kv.TouchTest.verifyTouchingLocked

couchbase {

  name: "DocumentLockedException"

  type: SDK_DOCUMENT_LOCKED_EXCEPTION

  serialized: "ambiguous timeout (13) {\"last_dispatched_to\": \"172.23.111.139:11210\", \"last_dispatched_from\": \"172.16.1.84:62402\", \"retry_attempts\": 1, \"retry_reasons\": [\"key_value_locked\"], \"key\": \"2bdbb19a-5b97-4e70-92b0-a0ddf86c0356\", \"bucket_name\": \"default\", \"scope_name\": \"_default\", \"collection_name\": \"_default\", \"opaque\": 11, \"context_type\": \"KeyValueErrorContext\"}"

} 

exception {

  couchbase {

    name: "Couchbase::Error::AmbiguousTimeout"

    type: SDK_AMBIGUOUS_TIMEOUT_EXCEPTION

    serialized: "unable to upsert: ambiguous_timeout (13), context={\"error\":\"ambiguous_timeout (13)\",\"id\":\"e13a8556-3a83-401c-b0bb-88071996ded1\",\"scope\":\"_default\",\"collection\":\"_default\",\"bucket\":\"default\",\"opaque\":12,\"retry_attempts\":1,\"retry_reasons\":[\"kv_locked\"],\"last_dispatched_to\":\"172.23.111.138:11210\",\"last_dispatched_from\":\"172.16.1.84:63108\"}"

  }

} 

 Started test api: DEFAULT13:34:49.411 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Waiting for a result from the performer after sending upsert {  location {    specific {      collection {        bucket_name: "default"        scope_name: "_default"        collection_name: "_default"      }      id: "61fc61e0-7f76-4e4d-843f-4e3b32a802c5"    }  }  content {    convert_to_json: "{\"created\":true,\"age\":12,\"foo\":\"bar\"}"  }}return_result: true

13:34:51.722 [ cb-events] WARN           com.couchbase.tracing - [com.couchbase.tracing][OverThresholdRequestsRecordedEvent][10s] Requests over Threshold found: {"kv":{"top_requests":[{"operation_name":"remove","last_dispatch_duration_us":505377,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505377,"total_server_duration_us":8,"operation_id":"0x41","timeout_ms":30000,"last_server_duration_us":8,"total_duration_us":523619},{"operation_name":"remove","last_dispatch_duration_us":505483,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505483,"total_server_duration_us":11,"operation_id":"0x59","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":523333},{"operation_name":"remove","last_dispatch_duration_us":504253,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":504253,"total_server_duration_us":11,"operation_id":"0x48","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":522260},{"operation_name":"remove","last_dispatch_duration_us":503983,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":503983,"total_server_duration_us":11,"operation_id":"0x6c","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":520186},{"operation_name":"remove","last_dispatch_duration_us":503758,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":503758,"total_server_duration_us":11,"operation_id":"0x6e","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":519669},{"operation_name":"remove","last_dispatch_duration_us":505671,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505671,"total_server_duration_us":43,"operation_id":"0x42f","timeout_ms":30000,"last_server_duration_us":43,"total_duration_us":509449},{"operation_name":"remove","last_dispatch_duration_us":505602,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505602,"total_server_duration_us":11,"operation_id":"0x42b","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":509399},{"operation_name":"remove","last_dispatch_duration_us":505593,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505593,"total_server_duration_us":11,"operation_id":"0x427","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":509358},{"operation_name":"remove","last_dispatch_duration_us":505540,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505540,"total_server_duration_us":11,"operation_id":"0x425","timeout_ms":30000,"last_server_duration_us":11,"total_duration_us":509312},{"operation_name":"remove","last_dispatch_duration_us":505430,"last_remote_socket":"172.23.111.137:11210","last_local_id":"803A35BA00000001/00000000A9577196","last_local_socket":"172.16.1.84:63352","total_dispatch_duration_us":505430,"total_server_duration_us":8,"operation_id":"0x422","timeout_ms":30000,"last_server_duration_us":8,"total_duration_us":509201}],"total_count":21}}13:34:52.475 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Got 1 results from performer13:34:52.483 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Waiting for a result from the performer after sending return_result: truecollection_command {  collection {    bucket_name: "default"    scope_name: "_default"    collection_name: "_default"  }  get_and_lock {    location {      specific {        collection {          bucket_name: "default"          scope_name: "_default"          collection_name: "_default"        }        id: "61fc61e0-7f76-4e4d-843f-4e3b32a802c5"      }    }    duration {      seconds: 30    }    content_as {      as_json_object: true    }  }}

13:34:52.750 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Got 1 results from performer13:34:52.751 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Waiting for a result from the performer after sending upsert {  location {    specific {      collection {        bucket_name: "default"        scope_name: "_default"        collection_name: "_default"      }      id: "61fc61e0-7f76-4e4d-843f-4e3b32a802c5"    }  }  content {    convert_to_json: "{}"  }  options {    timeout_msecs: 300  }}return_result: true

13:34:53.067 [t-thread-1] INFO  ase.client.util.SdkCommandUtil - Got 1 results from performer13:34:53.077 [      main] INFO  hbase.client.util.TestListener - Finished test api: DEFAULT with result FAILED

java.lang.AssertionError: Expected: (is <SDK_UNAMBIGUOUS_TIMEOUT_EXCEPTION> or is <SDK_AMBIGUOUS_TIMEOUT_EXCEPTION>)     but: was <SDK_DOCUMENT_LOCKED_EXCEPTION>Expected :(is <SDK_UNAMBIGUOUS_TIMEOUT_EXCEPTION> or is <SDK_AMBIGUOUS_TIMEOUT_EXCEPTION>)Actual   :<SDK_DOCUMENT_LOCKED_EXCEPTION><Click to see difference>

	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)	at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6)	at com.couchbase.client.util.ExceptionValidator.assertGenericTimeout(ExceptionValidator.java:173)	at com.couchbase.client.kv.LockTest.lambda$upsertLockedDocumentTimeoutHasRetryReasonLocked$8(LockTest.java:139)	at com.couchbase.client.kv.LockTest.lambda$iterate$0(LockTest.java:46)	at org.junit.jupiter.api.AssertTimeoutPreemptively.lambda$assertTimeoutPreemptively$0(AssertTimeoutPreemptively.java:48)	at org.junit.jupiter.api.AssertTimeoutPreemptively.lambda$submitTask$3(AssertTimeoutPreemptively.java:95)	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)	at java.base/java.lang.Thread.run(Thread.java:1583) 

[INFO] ================ Test file : Start ================ 

[2024-03-20 13:34:49,311] [root] [INFO] ================ java.util.stream.Stream com.couchbase.client.kv.LockTest.upsertLockedDocumentTimeoutHasRetryReasonLocked():upsertLockedDocumentTimeoutHasRetryReasonLocked() : testStart ================ 

[2024-03-20 13:34:49,412] [root] [INFO] Run called

[2024-03-20 13:34:49,413] [executors.workload_executor_builder] [INFO] Using multi-thread executor

[2024-03-20 13:34:49,413] [executors.multi_thread_executor] [INFO] There are 1 workloads

[2024-03-20 13:34:49,413] [executors.request_executor] [INFO] Batch size is 1

[2024-03-20 13:34:49,413] [executors.multi_thread_executor] [INFO] Started thread

[2024-03-20 13:34:52,433] [executors.multi_thread_executor] [INFO] Thread 6233911296 has finished its workloads

[2024-03-20 13:34:52,434] [streaming.stream_owner] [INFO] Waiting for streams from run bc199aea-01d2-4943-9b4d-cea80cfde041

[2024-03-20 13:34:52,434] [streaming.stream_owner] [INFO] All streams from run bc199aea-01d2-4943-9b4d-cea80cfde041 have finished

[2024-03-20 13:34:52,435] [executors.multi_thread_executor] [INFO] Workloads complete

[2024-03-20 13:34:52,435] [root] [INFO] Sent all the results for this run

[2024-03-20 13:34:52,435] [root] [INFO] Run finished

[2024-03-20 13:34:52,484] [root] [INFO] Run called

[2024-03-20 13:34:52,485] [executors.workload_executor_builder] [INFO] Using multi-thread executor

[2024-03-20 13:34:52,485] [executors.multi_thread_executor] [INFO] There are 1 workloads

[2024-03-20 13:34:52,485] [executors.request_executor] [INFO] Batch size is 1

[2024-03-20 13:34:52,486] [executors.multi_thread_executor] [INFO] Started thread

[2024-03-20 13:34:52,742] [executors.multi_thread_executor] [INFO] Thread 6233911296 has finished its workloads

[2024-03-20 13:34:52,743] [streaming.stream_owner] [INFO] Waiting for streams from run 16d5c8dc-69f7-47bb-8cad-f310dee3d1e3

[2024-03-20 13:34:52,743] [streaming.stream_owner] [INFO] All streams from run 16d5c8dc-69f7-47bb-8cad-f310dee3d1e3 have finished

[2024-03-20 13:34:52,743] [executors.multi_thread_executor] [INFO] Workloads complete

[2024-03-20 13:34:52,743] [root] [INFO] Sent all the results for this run

[2024-03-20 13:34:52,743] [root] [INFO] Run finished

[2024-03-20 13:34:52,752] [root] [INFO] Run called

[2024-03-20 13:34:52,752] [executors.workload_executor_builder] [INFO] Using multi-thread executor

[2024-03-20 13:34:52,753] [executors.multi_thread_executor] [INFO] There are 1 workloads

[2024-03-20 13:34:52,753] [executors.request_executor] [INFO] Batch size is 1

[2024-03-20 13:34:52,753] [executors.multi_thread_executor] [INFO] Started thread

[2024-03-20 13:34:53,056] [executors.multi_thread_executor] [INFO] Thread 6233911296 has finished its workloads

[2024-03-20 13:34:53,057] [streaming.stream_owner] [INFO] Waiting for streams from run 43227104-0b55-4008-b129-6828b53c2cb9

[2024-03-20 13:34:53,057] [streaming.stream_owner] [INFO] All streams from run 43227104-0b55-4008-b129-6828b53c2cb9 have finished

[2024-03-20 13:34:53,057] [executors.multi_thread_executor] [INFO] Workloads complete

[2024-03-20 13:34:53,057] [root] [INFO] Sent all the results for this run

[2024-03-20 13:34:53,058] [root] [INFO] Run finished

[2024-03-20 13:34:53,084] [root] [INFO] ================ java.util.stream.Stream com.couchbase.client.kv.LockTest.upsertLockedDocumentTimeoutHasRetryReasonLocked():upsertLockedDocumentTimeoutHasRetryReasonLocked() : testEnd ================ 

[2024-03-20 13:34:53,089] [root] [INFO] ================ Test file : End ================