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

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.

See: Client writes fail with AEROSPIKE_ERR_FAIL_FORBIDDEN

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.

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

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)

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…

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.

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.

© 2021 Copyright Aerospike, Inc. | All rights reserved. Creators of the Aerospike Database.