AeroSpike 3.14 - Error Code 11: Server not available: 11: Server not available

Operations
1

We are getting a few logs from our application that look like:

2019-02-14T10:32:49.948+00:00 kll0003 PC1 [0000007d] xpc.provevent ERROR (PROV-01001) Failed to dispatch event `AccountChangeEvent[9818687680@lte.com]` - `DAO-00003 datasource query statement failed: Error Code 11: Server not available: 11: Server not available`
2019-02-15T09:49:42.447+00:00 kll0003 PC1 [000000c8] com.bridgewatersystems.xpc.diameter.service.APNTask ERROR (JDSF-00007) Failed to process (command=272, appId=16777238, sessionId=555, requestType=1) from diameter peer `seagull`@`pso.org` : DAO-00003 datasource query statement failed: java.io.EOFException: 0: ok
2019-02-15T09:49:42.450+00:00 kll0003 PC1 ERR BPCOP(55) policy pull for 1:971727340101010@lte.com?PCRFGx=PCRFGx&APN_ID=IMS failed with results(no additional information): DAO-00003 datasource query statement failed: java.io.EOFException: 0: ok. [TimeStamp=20190215094942450] [Transaction=1408] 

Feb 14 2019 09:49:05 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:06 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 1000 ms
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38660,39544,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:284)    fds: proto (4,385,381) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:08 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:08 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:08 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:08 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:08 GMT: INFO (info): (hist.c:171)  (00: 0000000142)
Feb 14 2019 09:49:15 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:16 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 998 ms
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38655,39544,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:284)    fds: proto (4,385,381) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:18 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:18 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:18 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:18 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:18 GMT: INFO (info): (hist.c:171)  (00: 0000000142)
Feb 14 2019 09:49:25 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:26 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 999 ms
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38653,39544,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:284)    fds: proto (4,385,381) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:28 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:28 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:28 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:28 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:28 GMT: INFO (info): (hist.c:171)  (00: 0000000142)
Feb 14 2019 09:49:35 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:36 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 998 ms
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38654,39540,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:284)    fds: proto (4,386,382) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:38 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:38 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:38 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:38 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:38 GMT: INFO (info): (hist.c:171)  (00: 0000000142)
Feb 14 2019 09:49:45 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:46 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 1007 ms
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38660,39544,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:284)    fds: proto (4,386,382) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:48 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:48 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:48 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:48 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:48 GMT: INFO (info): (hist.c:171)  (00: 0000000142)
Feb 14 2019 09:49:55 GMT: INFO (nsup): (thr_sindex.c:492) {pcrf} sindex-gc start
Feb 14 2019 09:49:56 GMT: INFO (nsup): (thr_sindex.c:523) {pcrf} sindex-gc: Processed: 1, found:0, deleted: 0: Total time: 999 ms
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:167) NODE-ID bb95800a4565000 CLUSTER-SIZE 1
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:248)    system-memory: free-kbytes 15830116 free-pct 97 heap-kbytes (38658,39544,79872) heap-efficiency-pct 48.4
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:262)    in-progress: tsvc-q 0 info-q 0 nsup-delete-q 0 rw-hash 0 proxy-hash 0 tree-gc-q 0
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:284)    fds: proto (4,386,382) heartbeat (0,0,0) fabric (0,0,0)
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:293)    heartbeat-received: self 0 foreign 0
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:323)    fabric-bytes-per-second: bulk (0,0) ctrl (0,0) meta (0,0) rw (0,0)
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:347)    early-fail: demarshal 0 tsvc-client 32 tsvc-batch-sub 0 tsvc-udf-sub 0
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:378) {pcrf} objects: all 6 master 6 prole 0 non-replica 0
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:443) {pcrf} migrations: complete
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:462) {pcrf} memory-usage: total-bytes 38770 index-bytes 384 sindex-bytes 36895 data-bytes 1491 used-pct 0.00
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:585) {pcrf} client: tsvc (0,0) proxy (0,0,0) read (158,0,0,15) write (125,17,0) delete (6,0,0,0) udf (0,0,0) lang (0,0,0,0)
Feb 14 2019 09:49:58 GMT: INFO (info): (ticker.c:641) {pcrf} scan: basic (5,0,0) aggr (0,0,0) udf-bg (0,0,0)
Feb 14 2019 09:49:58 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-read (173 total) msec
Feb 14 2019 09:49:58 GMT: INFO (info): (hist.c:171)  (00: 0000000173)
Feb 14 2019 09:49:58 GMT: INFO (info): (hist.c:145) histogram dump: {pcrf}-write (142 total) msec
Feb 14 2019 09:49:58 GMT: INFO (info): (hist.c:171)  (00: 0000000142)

I am wondering what I can do to troubleshoot. We have one secondary index in use. The problem is intermittent. I know we should probably upgrade but I am getting resistance internally. I’m questioning what the best way to prove we should upgrade. I’ve seen a few articles which show an upgrade will help with this and do not believe it is bad configuration. The application only uses one secondary index:

aql> stat index pcrf audit_idx
aql> +--------------------------------+---------+
aql> | name                           | value   |
aql> +--------------------------------+---------+
aql> | "keys"                         | 2       |
aql> | "entries"                      | 2       |
aql> | "ibtr_memory_used"             | 18432   |
aql> | "nbtr_memory_used"             | 62      |
aql> | "si_accounted_memory"          | 18494   |
aql> | "load_pct"                     | 100     |
aql> | "loadtime"                     | 0       |
aql> | "write_success"                | 19      |
aql> | "write_error"                  | 0       |
aql> | "delete_success"               | 17      |
aql> | "delete_error"                 | 0       |
aql> | "stat_gc_recs"                 | 0       |
aql> | "stat_gc_time"                 | 0       |
aql> | "query_reqs"                   | 0       |
aql> | "query_avg_rec_count"          | 0       |
aql> | "query_avg_record_size"        | 0       |
aql> | "query_agg"                    | 0       |
aql> | "query_agg_avg_rec_count"      | 0       |
aql> | "query_agg_avg_record_size"    | 0       |
aql> | "query_lookups"                | 0       |
aql> | "query_lookup_avg_rec_count"   | 0       |
aql> | "query_lookup_avg_record_size" | 0       |
aql> | "histogram"                    | "false" |
aql> +--------------------------------+---------+
aql> 23 rows in set (0.001 secs)
2

This is strange for a single node cluster. I suspect that network issues between the client and server could cause this warning.

Also restarting the a client may cause this warning to appear.

Can you verify whether either of these scenarios apply?

3

We have tried restarting clients. The network seems OK at the times I’m checking it and the only indication I have to date is the intermittent error in the client logs. It is important to state I’ve seen this problem on multiple environments and networks.

4

Curious why are you still on 3.14? And what client version are you using?

5

There are many reasons to get error code 11. Usually network issues or client issues. Be sure to update to the latest client to plug some holes related to race conditions.