Java client exception : Error Code 22: Operation not allowed at this time

Client Libraries Java Client
1

When I write to aerospike, the following exception occurs on the client :

2021-07-21 01:50:45.699 ERROR 1353572 --- [asclient thread:69] com.aerospike.client.AerospikeClient     : Error Code 22: Operation not allowed at this time

com.aerospike.client.AerospikeException: Error Code 22: Operation not allowed at this time
	at com.aerospike.client.command.WriteCommand.parseResult(WriteCommand.java:54)
	at com.aerospike.client.command.SyncCommand.execute(SyncCommand.java:84)
	at com.aerospike.client.AerospikeClient.put(AerospikeClient.java:378)
	at cn.zwb.asclient.service.impl.AerospikeServiceImpl.set(AerospikeServiceImpl.java:53)
	at cn.zwb.asclient.task.BaseTask.dealLine(BaseTask.java:999)
	at cn.zwb.asclient.task.BaseTask.lambda$null$7(BaseTask.java:631)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
  • aerospike server verison : aerospike-server-community-4.3.1.4-el7
  • aerospike client version : 4.1.11 The following is aeropike’s log :
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:172) NODE-ID bb9f3962c3e1600 CLUSTER-SIZE 5
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:250)    cluster-clock: skew-ms 3
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:277)    system-memory: free-kbytes 6725840 free-pct 42 heap-kbytes (6710588,6715200,7159808) heap-efficiency-pct 93.7
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:290)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:311)    fds: proto (22,4008,3986) heartbeat (4,12,8) fabric (96,144,48)
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:319)    heartbeat-received: self 2 foreign 75411753
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:349)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:401) {ns1} objects: all 94290706 master 49544360 prole 44746346 non-replica 0
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:459) {ns1} migrations: complete
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:486) {ns1} memory-usage: total-bytes 6034605184 index-bytes 6034605184 sindex-bytes 0 used-pct 70.25
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:547) {ns1} device-usage: used-bytes 10520484288 avail-pct 76 cache-read-pct 0.00
Jul 21 2021 01:50:31 GMT: INFO (info): (ticker.c:597) {ns1} client: tsvc (0,0) proxy (0,0,0) read (205135362,0,0,43190453) write (303781801,9,0) delete (56,0,0,0) udf (0,0,0) lang (0,0,0,0)
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:240) histogram dump: {ns1}-read (248325815 total) msec
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:257)  (00: 0248246637) (01: 0000025544) (02: 0000027538) (03: 0000025595)
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:266)  (04: 0000000449) (05: 0000000026) (06: 0000000026)
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:240) histogram dump: {ns1}-write (303781810 total) msec
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:257)  (00: 0303106988) (01: 0000139711) (02: 0000140312) (03: 0000110789)
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:257)  (04: 0000048592) (05: 0000068252) (06: 0000073380) (07: 0000093534)
Jul 21 2021 01:50:31 GMT: INFO (info): (hist.c:266)  (08: 0000000252)

I looked at this page, but it didn’t match any of them.

2

See: Client writes fail with AEROSPIKE_ERR_FAIL_FORBIDDEN

3

Hi Brain, thank you for your help.

I read the content on this page, but I didn’t find anything that fits my problem:

  • I can confirm that namespace / set is not during truncate / delete

  • In the aeropike log, you can see that

    • used-pct is 70.25, and the default stop-writes-pct is 90
    • avail-pct is 76

    I don’t think this should be achieved the stop_writes.

  • I’m doing a write operation. Will the limitation of scan parameters affect the writing?

  • I am using the community edition and have no XDR and SC feature.

  • I set the default-ttl to 180d and the nsup-period to the default value of 120

In conclusion, I don’t know why Error code 22 appears on the Java client.

4

Did you check for any warnings across the whole log file on all server nodes?

5

Yes, there are five nodes in my aerospike cluster, and all their logs are similar to the following :

Jul 21 2021 01:01:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6032767488 (6032767488 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10540098128 hwm:26843545600
Jul 21 2021 01:01:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716748 - threshold bucket 742, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:03:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6029930240 (6029930240 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10533614400 hwm:26843545600
Jul 21 2021 01:03:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716868 - threshold bucket 742, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:05:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:05:58 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716730 - threshold bucket 741, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:07:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:07:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716850 - threshold bucket 741, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:09:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:09:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716712 - threshold bucket 740, width 258 sec, count 1362314 > target 216966 (0.5 pct)
Jul 21 2021 01:11:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:11:58 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716832 - threshold bucket 740, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:13:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:13:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716694 - threshold bucket 739, width 258 sec, count 846739 > target 216966 (0.5 pct)
Jul 21 2021 01:15:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:15:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716814 - threshold bucket 739, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:17:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:17:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716676 - threshold bucket 738, width 258 sec, count 343573 > target 216966 (0.5 pct)
Jul 21 2021 01:19:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:19:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716795 - threshold bucket 738, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:21:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:21:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716916 - threshold bucket 738, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:23:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:23:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716778 - threshold bucket 737, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:25:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:25:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716897 - threshold bucket 737, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:27:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:27:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716760 - threshold bucket 736, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:29:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:29:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716880 - threshold bucket 736, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:31:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:31:58 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716742 - threshold bucket 735, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:33:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:33:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716862 - threshold bucket 735, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:35:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:35:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716724 - threshold bucket 734, width 258 sec, count 1695050 > target 216966 (0.5 pct)
Jul 21 2021 01:37:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:37:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716844 - threshold bucket 734, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:39:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:39:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716705 - threshold bucket 733, width 258 sec, count 1160568 > target 216966 (0.5 pct)
Jul 21 2021 01:41:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6028426368 (6028426368 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10531722608 hwm:26843545600
Jul 21 2021 01:41:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716826 - threshold bucket 733, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:43:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6024230720 (6024230720 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10526463936 hwm:26843545600
Jul 21 2021 01:43:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716688 - threshold bucket 732, width 258 sec, count 673496 > target 216966 (0.5 pct)
Jul 21 2021 01:45:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6023410624 (6023410624 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10525434816 hwm:26843545600
Jul 21 2021 01:45:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716807 - threshold bucket 732, width 258 sec, count 1874659 > target 216966 (0.5 pct)
Jul 21 2021 01:47:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6023410624 (6023410624 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10525434816 hwm:26843545600
Jul 21 2021 01:49:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6012581120 (6012581120 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10511840160 hwm:26843545600
Jul 21 2021 01:49:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716790 - threshold bucket 731, width 258 sec, count 1705448 > target 216120 (0.5 pct)
Jul 21 2021 01:51:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6012581120 (6012581120 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10511840160 hwm:26843545600
Jul 21 2021 01:51:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716909 - threshold bucket 731, width 258 sec, count 1705448 > target 216120 (0.5 pct)
Jul 21 2021 01:53:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6012581120 (6012581120 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10511840160 hwm:26843545600
Jul 21 2021 01:53:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716772 - threshold bucket 730, width 258 sec, count 1705448 > target 216120 (0.5 pct)
Jul 21 2021 01:55:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6012581120 (6012581120 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10511840160 hwm:26843545600
Jul 21 2021 01:55:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716892 - threshold bucket 730, width 258 sec, count 1705448 > target 216120 (0.5 pct)
Jul 21 2021 01:57:52 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6012581120 (6012581120 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10511840160 hwm:26843545600
Jul 21 2021 01:57:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716754 - threshold bucket 729, width 258 sec, count 1705448 > target 216120 (0.5 pct)
Jul 21 2021 01:59:51 GMT: WARNING (nsup): (thr_nsup.c:1265) {ns1} breached eviction hwm (memory), memory sz:6010642688 (6010642688 + 0 + 0) hwm:5153960755, index-device sz:0 hwm:0, disk sz:10507403232 hwm:26843545600
Jul 21 2021 01:59:57 GMT: WARNING (nsup): (thr_nsup.c:814) {ns1} no records below eviction void-time 364716873 - threshold bucket 729, width 258 sec, count 1705448 > target 216120 (0.5 pct)
6

Those warnings are about breaching the high water mark threshold for memory and not finding anything to evict. Those shouldn’t cause any error 22.

But, from your previous log excerpt: write (303781801,9,0) it seems you had 9 errors on this node out of ~300M writes, assuming all 9 are error 22. So it seems to happen fairly infrequently and could be based on some very transient situation where a node breaches stop writes (wild guess). Looking at the logs when the counter for the error increases may help…

7

Thank you for your help, Meher.

At present, my method is to try to write again on the Java client when an exception occurs. But I still don’t know why this exception is triggered. It only appears occasionally when writing.

The usage of all nodes in my aerospike cluster (memory used-pct 70, device avail-pct 70), which should not trigger stop writes. And I think if stop writes is triggered, I should see the corresponding warning log in the log, but I don’t see it in the log of any node.

8

Yes, you are correct. Would still be interesting to see the logs when the counter increments to check if anything suspicious that could explain it.