[CCBC-1334] Lcb authorized error replaced to generic autent err, while issuing bad permission for user - Couchbase database

Alexis Deltour added a comment - 15/Nov/20 8:18 AM

Issue found during Lcb 3.0.6 migration in couchbase client at Amadeus IT. On the previous Lcb 2.x, it was possible to have a better granularity on rbac authorization issue.

Alexis Deltour added a comment - 15/Nov/20 8:18 AM Issue found during Lcb 3.0.6 migration in couchbase client at Amadeus IT. On the previous Lcb 2.x, it was possible to have a better granularity on rbac authorization issue.

Sergey Avseyev added a comment - 23/Nov/20 6:52 AM

Alexis Deltour, what is the usecase? Our team decided to use the same error code for EACCESS (0x24), AUTH_ERROR (0x20) and AUTH_STALE (0x1f). Why this differentiation is necessary?

you still can get access to the KV error code anyway.

const lcb_KEY_VALUE_ERROR_CONTEXT *ctx;

lcb_respget_error_context(resp, &ctx);

uint16_t kv_status_code = 0;

lcb_errctx_kv_status_code(ctx, &kv_status_code);

if (kv_status_code ==  PROTOCOL_BINARY_RESPONSE_EACCESS) {

    // some EACCESS-specific code

Sergey Avseyev added a comment - 23/Nov/20 6:52 AM Alexis Deltour , what is the usecase? Our team decided to use the same error code for EACCESS (0x24), AUTH_ERROR (0x20) and AUTH_STALE (0x1f). Why this differentiation is necessary? you still can get access to the KV error code anyway. const lcb_KEY_VALUE_ERROR_CONTEXT *ctx; lcb_respget_error_context(resp, &ctx); uint16_t kv_status_code = 0; lcb_errctx_kv_status_code(ctx, &kv_status_code); if (kv_status_code == PROTOCOL_BINARY_RESPONSE_EACCESS) { // some EACCESS-specific code }

Alexis Deltour added a comment - 24/Nov/20 5:47 AM

We would like to differentiate authentication error (considered as fatal on our side) from permission (rbac) issue on operations, the second one is not throwing any exception (as it could be recoverable by tuning Rbac on server side). However we will try to use the error context on our side. Thx for the response.

Alexis Deltour added a comment - 24/Nov/20 5:47 AM We would like to differentiate authentication error (considered as fatal on our side) from permission (rbac) issue on operations, the second one is not throwing any exception (as it could be recoverable by tuning Rbac on server side). However we will try to use the error context on our side. Thx for the response.

Alexis Deltour added a comment - 27/Nov/20 5:06 AM - edited

Hi Sergey Avseyev,

Apparently, i am not able to retrieve the status code if LCB error is LCB_ERR_AUTHENTICATION_FAILURE.

But it is working only if rc != LCB_ERR_AUTHENTICATION_FAILURE (cf. logs below with

Permission status code detected: 36 / PROTOCOL_BINARY_RESPONSE_EACCESS / 0x24)

2020/11/27 12:43:02.827854   test MDW TST TST <ConnectionTest.cpp#737 TID#0> Set key Key with value Value/5/0

2020/11/27 12:43:02.827904   test MDW DBG lcbio_mgr <manager.cc#494 TID#0> < xxxx:11210> (HE=0x395f710) Creating new connection because none are available in the pool

2020/11/27 12:43:02.827916   test MDW DBG lcbio_mgr <manager.cc#406 TID#0> < xxxx:11210> (HE=0x395f710) New pool entry: I=0x39662a0

2020/11/27 12:43:02.827921   test MDW INFO connection <connect.cc#487 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Starting. Timeout=2000000us

2020/11/27 12:43:02.827932   test MDW DBG connection <connect.cc#252 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Created new socket with FD=16

2020/11/27 12:43:02.827955   test MDW DBG connection <connect.cc#352 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Scheduling I/O watcher for asynchronous connection completion.

2020/11/27 12:43:02.828503   test MDW INFO connection <connect.cc#155 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Connected established

2020/11/27 12:43:02.828515   test MDW DBG connection <connect.cc#108 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Successfully set TCP_NODELAY

2020/11/27 12:43:02.828523   test MDW DBG connection <connect.cc#108 TID#0> < xxxx:11210> (SOCK=f80333bd28ccb5e9) Successfully set TCP_KEEPALIVE

2020/11/27 12:43:02.828525   test MDW DBG lcbio_mgr <manager.cc#362 TID#0> < xxxx:11210> (HE=0x395f710) Received result for I=0x39662a0,C=(nil); E=0x0

2020/11/27 12:43:02.828532   test MDW DBG lcbio_mgr <manager.cc#322 TID#0> < xxxx:11210> (HE=0x395f710) Assigning R=0x3980550 SOCKET=0x3966480

2020/11/27 12:43:02.828536   test MDW DBG server <mcserver.cc#944 TID#0> < xxxx:11210> (SRV=0x397d0c0) Session not yet negotiated. Negotiating

2020/11/27 12:43:02.828541   test MDW DBG ioctx <ctx.c#95 TID#0> < xxxx:11210> (CTX=0x39713f0,unknown) Pairing with SOCK=f80333bd28ccb5e9

2020/11/27 12:43:02.828568   test MDW DBG negotiation <negotiate.cc#460 TID#0> < xxxx:11210> (CTX=0x39713f0,sasl,SASLREQ=0x39664f0) HELO identificator: {"a":"libcouchbase/3.0.6 (Linux-3.10.0-1127.13.1.el7.x86_64; x86_64; GNU 4.9.4)","i":"d405612f430f21d2/f80333bd28ccb5e9"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x0e (Unordered execution), 0x17 (Create as Deleted)

2020/11/27 12:43:02.829362   test MDW DBG negotiation <negotiate.cc#491 TID#0> < xxxx:11210> (CTX=0x39713f0,sasl,SASLREQ=0x39664f0) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing)

2020/11/27 12:43:02.836365   test MDW DBG negotiation <negotiate.cc#543 TID#0> < xxxx:11210> (CTX=0x39713f0,sasl,SASLREQ=0x39664f0) Sending SELECT_BUCKET "adeltour-br3"

2020/11/27 12:43:02.836767   test MDW DBG ioctx <ctx.c#140 TID#0> < xxxx:11210> (CTX=0x39713f0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1

2020/11/27 12:43:02.836781   test MDW DBG ioctx <ctx.c#95 TID#0> < xxxx:11210> (CTX=0x3971cf0,unknown) Pairing with SOCK=f80333bd28ccb5e9

2020/11/27 12:43:02.837220   test MDW DBG TST <StoreOperations.cpp#213 TID#0> Received response (Set) for key "Key" ; lcb error: LCB_ERR_NOT_AUTHORIZED (220): Not authorized for operation, global elapsed time: [9ms]

2020/11/27 12:43:02.837272   test MDW DBG TST <BaseOperations.cpp#365 TID#0> Permission status code detected: 36, rc: 220

2020/11/27 12:43:02.837281   test MDW DBG TST <BaseOperations.cpp#368 TID#0> Permission status code detected: 36

2020/11/27 12:43:02.837291   test MDW ERROR [18/kKVClientError_PermissionError] TST <ErrorManager.cpp#369 TID#0> Error: LCB_ERR_NOT_AUTHORIZED (220): Not authorized for operation ; Failed to perform, as part of Set query, the operation for key [Key], on master server [ xxxx:11210], global elapsed time: [9ms]

logs with rc == LCB_ERR_AUTHENTICATION_FAILURE

=> retries occured and it seems status code /PROTOCOL_BINARY_RESPONSE_EACCESS/0x24 is lost:

2020/11/27 12:39:38.401340   test MDW TST TST <ConnectionTest.cpp#737 TID#0> Set key Key with value Value/5/0

2020/11/27 12:39:38.401390   test MDW DBG lcbio_mgr <manager.cc#494 TID#0> < xxxx:11210> (HE=0x3f80e50) Creating new connection because none are available in the pool

2020/11/27 12:39:38.401402   test MDW DBG lcbio_mgr <manager.cc#406 TID#0> < xxxx:11210> (HE=0x3f80e50) New pool entry: I=0x3f7e670

2020/11/27 12:39:38.401408   test MDW INFO connection <connect.cc#487 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Starting. Timeout=2000000us

2020/11/27 12:39:38.401419   test MDW DBG connection <connect.cc#252 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Created new socket with FD=16

2020/11/27 12:39:38.401442   test MDW DBG connection <connect.cc#352 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Scheduling I/O watcher for asynchronous connection completion.

2020/11/27 12:39:38.402135   test MDW INFO connection <connect.cc#155 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Connected established

2020/11/27 12:39:38.402145   test MDW DBG connection <connect.cc#108 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Successfully set TCP_NODELAY

2020/11/27 12:39:38.402148   test MDW DBG connection <connect.cc#108 TID#0> < xxxx:11210> (SOCK=1cc8eac39e8d22c6) Successfully set TCP_KEEPALIVE

2020/11/27 12:39:38.402150   test MDW DBG lcbio_mgr <manager.cc#362 TID#0> < xxxx:11210> (HE=0x3f80e50) Received result for I=0x3f7e670,C=(nil); E=0x0

2020/11/27 12:39:38.402153   test MDW DBG lcbio_mgr <manager.cc#322 TID#0> < xxxx:11210> (HE=0x3f80e50) Assigning R=0x3f87000 SOCKET=0x3f9ddc0

2020/11/27 12:39:38.402156   test MDW DBG server <mcserver.cc#944 TID#0> < xxxx:11210> (SRV=0x3f9ab80) Session not yet negotiated. Negotiating

2020/11/27 12:39:38.402161   test MDW DBG ioctx <ctx.c#95 TID#0> < xxxx:11210> (CTX=0x3f85380,unknown) Pairing with SOCK=1cc8eac39e8d22c6

2020/11/27 12:39:38.402187   test MDW DBG negotiation <negotiate.cc#460 TID#0> < xxxx:11210> (CTX=0x3f85380,sasl,SASLREQ=0x3fa6eb0) HELO identificator: {"a":"libcouchbase/3.0.6 (Linux-3.10.0-1127.13.1.el7.x86_64; x86_64; GNU 4.9.4)","i":"0b79cb366d37484d/1cc8eac39e8d22c6"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x0e (Unordered execution), 0x17 (Create as Deleted)

2020/11/27 12:39:38.403032   test MDW DBG negotiation <negotiate.cc#491 TID#0> < xxxx:11210> (CTX=0x3f85380,sasl,SASLREQ=0x3fa6eb0) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing)

2020/11/27 12:39:38.409675   test MDW DBG negotiation <negotiate.cc#543 TID#0> < xxxx:11210> (CTX=0x3f85380,sasl,SASLREQ=0x3fa6eb0) Sending SELECT_BUCKET "adeltour-br3"

2020/11/27 12:39:38.410263   test MDW DBG ioctx <ctx.c#140 TID#0> < xxxx:11210> (CTX=0x3f85380,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1

2020/11/27 12:39:38.410276   test MDW DBG ioctx <ctx.c#95 TID#0> < xxxx:11210> (CTX=0x3f86140,unknown) Pairing with SOCK=1cc8eac39e8d22c6

2020/11/27 12:39:38.410722   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=1

2020/11/27 12:39:38.410732   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 9 ms

2020/11/27 12:39:38.410736   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.421331   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=2

2020/11/27 12:39:38.421345   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 19 ms

2020/11/27 12:39:38.421349   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.442369   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=3

2020/11/27 12:39:38.442398   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 29 ms

2020/11/27 12:39:38.442403   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.473074   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=4

2020/11/27 12:39:38.473087   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 39 ms

2020/11/27 12:39:38.473091   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.513791   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=5

2020/11/27 12:39:38.513804   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 49 ms

2020/11/27 12:39:38.513808   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.564519   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=6

2020/11/27 12:39:38.564533   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 59 ms

2020/11/27 12:39:38.564538   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.625212   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=7

2020/11/27 12:39:38.625227   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 69 ms

2020/11/27 12:39:38.625232   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.695937   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=8

2020/11/27 12:39:38.695954   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 79 ms

2020/11/27 12:39:38.695960   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.776815   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=9

2020/11/27 12:39:38.776829   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 89 ms

2020/11/27 12:39:38.776835   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.867666   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=10

2020/11/27 12:39:38.867682   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 99 ms

2020/11/27 12:39:38.867687   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:38.968617   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=11

2020/11/27 12:39:38.968642   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 109 ms

2020/11/27 12:39:38.968651   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.080148   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=12

2020/11/27 12:39:39.080189   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 119 ms

2020/11/27 12:39:39.080198   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.201084   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=13

2020/11/27 12:39:39.201107   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 129 ms

2020/11/27 12:39:39.201114   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.332137   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=14

2020/11/27 12:39:39.332163   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 139 ms

2020/11/27 12:39:39.332172   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.473834   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=15

2020/11/27 12:39:39.473853   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 149 ms

2020/11/27 12:39:39.473860   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.624866   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=16

2020/11/27 12:39:39.624882   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 159 ms

2020/11/27 12:39:39.624889   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.785812   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=17

2020/11/27 12:39:39.785830   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 169 ms

2020/11/27 12:39:39.785837   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:39.956819   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=18

2020/11/27 12:39:39.956843   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 179 ms

2020/11/27 12:39:39.956852   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:40.138430   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f85620 to retry queue. Try count=19

2020/11/27 12:39:40.138452   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 189 ms

2020/11/27 12:39:40.138461   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:40.329603   test MDW DBG retryq <retryq.cc#388 TID#0> Adding PKT=0x3f9de30 to retry queue. Try count=20

2020/11/27 12:39:40.329625   test MDW DBG retryq <retryq.cc#200 TID#0> Next tick in 71 ms

2020/11/27 12:39:40.329634   test MDW DBG server <mcserver.cc#499 TID#0> < xxxx:11210> (CTX=0x3f86140,memcached,SRV=0x3f9ab80,IX=2) Server sent us reply for a timed-out command. (OP=0x1, RC=0x24, SEQ=0)

2020/11/27 12:39:40.401746   test MDW WARN retryq <retryq.cc#163 TID#0> Failing command (seq=0) from retry queue: LCB_ERR_AUTHENTICATION_FAILURE (206)

2020/11/27 12:39:40.401862   test MDW DBG TST <StoreOperations.cpp#213 TID#0> Received response (Set) for key "Key" ; lcb error: LCB_ERR_AUTHENTICATION_FAILURE (206): Authentication error, global elapsed time: [2000ms]

2020/11/27 12:39:40.401910   test MDW DBG TST <BaseOperations.cpp#365 TID#0> Permission status code detected: 4, rc: 206

2020/11/27 12:39:40.402734   test MDW ERROR [5/kKVClientError_AuthenticationError] TST <ErrorManager.cpp#376 TID#0> Error: 206 LCB_ERR_AUTHENTICATION_FAILURE (206): Authentication error : Failed to perform, as part of Set query, the operation for key [Key], on master server [xxxx:11210], global elapsed time: [2000ms]

same code for both

Alexis Deltour added a comment - 27/Nov/20 5:06 AM - edited Hi Sergey Avseyev , Apparently, i am not able to retrieve the status code if LCB error is LCB_ERR_AUTHENTICATION_FAILURE. But it is working only if rc != LCB_ERR_AUTHENTICATION_FAILURE (cf. logs below with Permission status code detected: 36 / PROTOCOL_BINARY_RESPONSE_EACCESS / 0x24) 2020 / 11 / 27 12 : 43 : 02.827854 test MDW TST TST <ConnectionTest.cpp# 737 TID# 0 > Set key Key with value Value/ 5 / 0 2020 / 11 / 27 12 : 43 : 02.827904 test MDW DBG lcbio_mgr <manager.cc# 494 TID# 0 > < xxxx: 11210 > (HE= 0x395f710 ) Creating new connection because none are available in the pool 2020 / 11 / 27 12 : 43 : 02.827916 test MDW DBG lcbio_mgr <manager.cc# 406 TID# 0 > < xxxx: 11210 > (HE= 0x395f710 ) New pool entry: I= 0x39662a0 2020 / 11 / 27 12 : 43 : 02.827921 test MDW INFO connection <connect.cc# 487 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Starting. Timeout=2000000us 2020 / 11 / 27 12 : 43 : 02.827932 test MDW DBG connection <connect.cc# 252 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Created new socket with FD= 16 2020 / 11 / 27 12 : 43 : 02.827955 test MDW DBG connection <connect.cc# 352 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Scheduling I/O watcher for asynchronous connection completion. 2020 / 11 / 27 12 : 43 : 02.828503 test MDW INFO connection <connect.cc# 155 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Connected established 2020 / 11 / 27 12 : 43 : 02.828515 test MDW DBG connection <connect.cc# 108 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Successfully set TCP_NODELAY 2020 / 11 / 27 12 : 43 : 02.828523 test MDW DBG connection <connect.cc# 108 TID# 0 > < xxxx: 11210 > (SOCK=f80333bd28ccb5e9) Successfully set TCP_KEEPALIVE 2020 / 11 / 27 12 : 43 : 02.828525 test MDW DBG lcbio_mgr <manager.cc# 362 TID# 0 > < xxxx: 11210 > (HE= 0x395f710 ) Received result for I= 0x39662a0 ,C=(nil); E= 0x0 2020 / 11 / 27 12 : 43 : 02.828532 test MDW DBG lcbio_mgr <manager.cc# 322 TID# 0 > < xxxx: 11210 > (HE= 0x395f710 ) Assigning R= 0x3980550 SOCKET= 0x3966480 2020 / 11 / 27 12 : 43 : 02.828536 test MDW DBG server <mcserver.cc# 944 TID# 0 > < xxxx: 11210 > (SRV= 0x397d0c0 ) Session not yet negotiated. Negotiating 2020 / 11 / 27 12 : 43 : 02.828541 test MDW DBG ioctx <ctx.c# 95 TID# 0 > < xxxx: 11210 > (CTX= 0x39713f0 ,unknown) Pairing with SOCK=f80333bd28ccb5e9 2020 / 11 / 27 12 : 43 : 02.828568 test MDW DBG negotiation <negotiate.cc# 460 TID# 0 > < xxxx: 11210 > (CTX= 0x39713f0 ,sasl,SASLREQ= 0x39664f0 ) HELO identificator: { "a" : "libcouchbase/3.0.6 (Linux-3.10.0-1127.13.1.el7.x86_64; x86_64; GNU 4.9.4)" , "i" : "d405612f430f21d2/f80333bd28ccb5e9" }, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x0e (Unordered execution), 0x17 (Create as Deleted) 2020 / 11 / 27 12 : 43 : 02.829362 test MDW DBG negotiation <negotiate.cc# 491 TID# 0 > < xxxx: 11210 > (CTX= 0x39713f0 ,sasl,SASLREQ= 0x39664f0 ) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing) 2020 / 11 / 27 12 : 43 : 02.836365 test MDW DBG negotiation <negotiate.cc# 543 TID# 0 > < xxxx: 11210 > (CTX= 0x39713f0 ,sasl,SASLREQ= 0x39664f0 ) Sending SELECT_BUCKET "adeltour-br3" 2020 / 11 / 27 12 : 43 : 02.836767 test MDW DBG ioctx <ctx.c# 140 TID# 0 > < xxxx: 11210 > (CTX= 0x39713f0 ,sasl) Destroying context. Pending Writes= 0 , Entered= true , Socket Refcount= 1 2020 / 11 / 27 12 : 43 : 02.836781 test MDW DBG ioctx <ctx.c# 95 TID# 0 > < xxxx: 11210 > (CTX= 0x3971cf0 ,unknown) Pairing with SOCK=f80333bd28ccb5e9 2020 / 11 / 27 12 : 43 : 02.837220 test MDW DBG TST <StoreOperations.cpp# 213 TID# 0 > Received response (Set) for key "Key" ; lcb error: LCB_ERR_NOT_AUTHORIZED ( 220 ): Not authorized for operation, global elapsed time: [9ms] 2020 / 11 / 27 12 : 43 : 02.837272 test MDW DBG TST <BaseOperations.cpp# 365 TID# 0 > Permission status code detected: 36 , rc: 220 2020 / 11 / 27 12 : 43 : 02.837281 test MDW DBG TST <BaseOperations.cpp# 368 TID# 0 > Permission status code detected: 36 2020 / 11 / 27 12 : 43 : 02.837291 test MDW ERROR [ 18 /kKVClientError_PermissionError] TST <ErrorManager.cpp# 369 TID# 0 > Error: LCB_ERR_NOT_AUTHORIZED ( 220 ): Not authorized for operation ; Failed to perform, as part of Set query, the operation for key [Key], on master server [ xxxx: 11210 ], global elapsed time: [9ms] logs with rc == LCB_ERR_AUTHENTICATION_FAILURE => retries occured and it seems status code / PROTOCOL_BINARY_RESPONSE_EACCESS /0x24 is lost: 2020 / 11 / 27 12 : 39 : 38.401340 test MDW TST TST <ConnectionTest.cpp# 737 TID# 0 > Set key Key with value Value/ 5 / 0 2020 / 11 / 27 12 : 39 : 38.401390 test MDW DBG lcbio_mgr <manager.cc# 494 TID# 0 > < xxxx: 11210 > (HE= 0x3f80e50 ) Creating new connection because none are available in the pool 2020 / 11 / 27 12 : 39 : 38.401402 test MDW DBG lcbio_mgr <manager.cc# 406 TID# 0 > < xxxx: 11210 > (HE= 0x3f80e50 ) New pool entry: I= 0x3f7e670 2020 / 11 / 27 12 : 39 : 38.401408 test MDW INFO connection <connect.cc# 487 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Starting. Timeout=2000000us 2020 / 11 / 27 12 : 39 : 38.401419 test MDW DBG connection <connect.cc# 252 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Created new socket with FD= 16 2020 / 11 / 27 12 : 39 : 38.401442 test MDW DBG connection <connect.cc# 352 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Scheduling I/O watcher for asynchronous connection completion. 2020 / 11 / 27 12 : 39 : 38.402135 test MDW INFO connection <connect.cc# 155 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Connected established 2020 / 11 / 27 12 : 39 : 38.402145 test MDW DBG connection <connect.cc# 108 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Successfully set TCP_NODELAY 2020 / 11 / 27 12 : 39 : 38.402148 test MDW DBG connection <connect.cc# 108 TID# 0 > < xxxx: 11210 > (SOCK=1cc8eac39e8d22c6) Successfully set TCP_KEEPALIVE 2020 / 11 / 27 12 : 39 : 38.402150 test MDW DBG lcbio_mgr <manager.cc# 362 TID# 0 > < xxxx: 11210 > (HE= 0x3f80e50 ) Received result for I= 0x3f7e670 ,C=(nil); E= 0x0 2020 / 11 / 27 12 : 39 : 38.402153 test MDW DBG lcbio_mgr <manager.cc# 322 TID# 0 > < xxxx: 11210 > (HE= 0x3f80e50 ) Assigning R= 0x3f87000 SOCKET= 0x3f9ddc0 2020 / 11 / 27 12 : 39 : 38.402156 test MDW DBG server <mcserver.cc# 944 TID# 0 > < xxxx: 11210 > (SRV= 0x3f9ab80 ) Session not yet negotiated. Negotiating 2020 / 11 / 27 12 : 39 : 38.402161 test MDW DBG ioctx <ctx.c# 95 TID# 0 > < xxxx: 11210 > (CTX= 0x3f85380 ,unknown) Pairing with SOCK=1cc8eac39e8d22c6 2020 / 11 / 27 12 : 39 : 38.402187 test MDW DBG negotiation <negotiate.cc# 460 TID# 0 > < xxxx: 11210 > (CTX= 0x3f85380 ,sasl,SASLREQ= 0x3fa6eb0 ) HELO identificator: { "a" : "libcouchbase/3.0.6 (Linux-3.10.0-1127.13.1.el7.x86_64; x86_64; GNU 4.9.4)" , "i" : "0b79cb366d37484d/1cc8eac39e8d22c6" }, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x0f (Tracing), 0x0e (Unordered execution), 0x17 (Create as Deleted) 2020 / 11 / 27 12 : 39 : 38.403032 test MDW DBG negotiation <negotiate.cc# 491 TID# 0 > < xxxx: 11210 > (CTX= 0x3f85380 ,sasl,SASLREQ= 0x3fa6eb0 ) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0b (JSON), 0x0e (Unordered execution), 0x0f (Tracing) 2020 / 11 / 27 12 : 39 : 38.409675 test MDW DBG negotiation <negotiate.cc# 543 TID# 0 > < xxxx: 11210 > (CTX= 0x3f85380 ,sasl,SASLREQ= 0x3fa6eb0 ) Sending SELECT_BUCKET "adeltour-br3" 2020 / 11 / 27 12 : 39 : 38.410263 test MDW DBG ioctx <ctx.c# 140 TID# 0 > < xxxx: 11210 > (CTX= 0x3f85380 ,sasl) Destroying context. Pending Writes= 0 , Entered= true , Socket Refcount= 1 2020 / 11 / 27 12 : 39 : 38.410276 test MDW DBG ioctx <ctx.c# 95 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,unknown) Pairing with SOCK=1cc8eac39e8d22c6 2020 / 11 / 27 12 : 39 : 38.410722 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 1 2020 / 11 / 27 12 : 39 : 38.410732 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 9 ms 2020 / 11 / 27 12 : 39 : 38.410736 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.421331 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 2 2020 / 11 / 27 12 : 39 : 38.421345 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 19 ms 2020 / 11 / 27 12 : 39 : 38.421349 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.442369 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 3 2020 / 11 / 27 12 : 39 : 38.442398 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 29 ms 2020 / 11 / 27 12 : 39 : 38.442403 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.473074 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 4 2020 / 11 / 27 12 : 39 : 38.473087 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 39 ms 2020 / 11 / 27 12 : 39 : 38.473091 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.513791 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 5 2020 / 11 / 27 12 : 39 : 38.513804 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 49 ms 2020 / 11 / 27 12 : 39 : 38.513808 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.564519 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 6 2020 / 11 / 27 12 : 39 : 38.564533 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 59 ms 2020 / 11 / 27 12 : 39 : 38.564538 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.625212 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 7 2020 / 11 / 27 12 : 39 : 38.625227 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 69 ms 2020 / 11 / 27 12 : 39 : 38.625232 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.695937 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 8 2020 / 11 / 27 12 : 39 : 38.695954 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 79 ms 2020 / 11 / 27 12 : 39 : 38.695960 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.776815 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 9 2020 / 11 / 27 12 : 39 : 38.776829 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 89 ms 2020 / 11 / 27 12 : 39 : 38.776835 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.867666 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 10 2020 / 11 / 27 12 : 39 : 38.867682 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 99 ms 2020 / 11 / 27 12 : 39 : 38.867687 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 38.968617 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 11 2020 / 11 / 27 12 : 39 : 38.968642 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 109 ms 2020 / 11 / 27 12 : 39 : 38.968651 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.080148 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 12 2020 / 11 / 27 12 : 39 : 39.080189 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 119 ms 2020 / 11 / 27 12 : 39 : 39.080198 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.201084 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 13 2020 / 11 / 27 12 : 39 : 39.201107 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 129 ms 2020 / 11 / 27 12 : 39 : 39.201114 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.332137 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 14 2020 / 11 / 27 12 : 39 : 39.332163 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 139 ms 2020 / 11 / 27 12 : 39 : 39.332172 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.473834 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 15 2020 / 11 / 27 12 : 39 : 39.473853 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 149 ms 2020 / 11 / 27 12 : 39 : 39.473860 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.624866 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 16 2020 / 11 / 27 12 : 39 : 39.624882 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 159 ms 2020 / 11 / 27 12 : 39 : 39.624889 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.785812 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 17 2020 / 11 / 27 12 : 39 : 39.785830 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 169 ms 2020 / 11 / 27 12 : 39 : 39.785837 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 39.956819 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 18 2020 / 11 / 27 12 : 39 : 39.956843 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 179 ms 2020 / 11 / 27 12 : 39 : 39.956852 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 40.138430 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f85620 to retry queue. Try count= 19 2020 / 11 / 27 12 : 39 : 40.138452 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 189 ms 2020 / 11 / 27 12 : 39 : 40.138461 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 40.329603 test MDW DBG retryq <retryq.cc# 388 TID# 0 > Adding PKT= 0x3f9de30 to retry queue. Try count= 20 2020 / 11 / 27 12 : 39 : 40.329625 test MDW DBG retryq <retryq.cc# 200 TID# 0 > Next tick in 71 ms 2020 / 11 / 27 12 : 39 : 40.329634 test MDW DBG server <mcserver.cc# 499 TID# 0 > < xxxx: 11210 > (CTX= 0x3f86140 ,memcached,SRV= 0x3f9ab80 ,IX= 2 ) Server sent us reply for a timed-out command. (OP= 0x1 , RC= 0x24 , SEQ= 0 ) 2020 / 11 / 27 12 : 39 : 40.401746 test MDW WARN retryq <retryq.cc# 163 TID# 0 > Failing command (seq= 0 ) from retry queue: LCB_ERR_AUTHENTICATION_FAILURE ( 206 ) 2020 / 11 / 27 12 : 39 : 40.401862 test MDW DBG TST <StoreOperations.cpp# 213 TID# 0 > Received response (Set) for key "Key" ; lcb error: LCB_ERR_AUTHENTICATION_FAILURE ( 206 ): Authentication error, global elapsed time: [2000ms] 2020 / 11 / 27 12 : 39 : 40.401910 test MDW DBG TST <BaseOperations.cpp# 365 TID# 0 > Permission status code detected: 4 , rc: 206 2020 / 11 / 27 12 : 39 : 40.402734 test MDW ERROR [ 5 /kKVClientError_AuthenticationError] TST <ErrorManager.cpp# 376 TID# 0 > Error: 206 LCB_ERR_AUTHENTICATION_FAILURE ( 206 ): Authentication error : Failed to perform, as part of Set query, the operation for key [Key], on master server [xxxx: 11210 ], global elapsed time: [2000ms] same code for both

Sergey Avseyev added a comment - 02/Dec/20 5:59 AM

Alexis Deltour, hi. You are right (as always), the status from the protocol frame is not preserved inside retry queue, and is not available when we purge the command by time out. I added patch to preserve this code, so it will be accessible in next release: http://review.couchbase.org/c/libcouchbase/+/141361

Sergey Avseyev added a comment - 02/Dec/20 5:59 AM Alexis Deltour , hi. You are right (as always), the status from the protocol frame is not preserved inside retry queue, and is not available when we purge the command by time out. I added patch to preserve this code, so it will be accessible in next release: http://review.couchbase.org/c/libcouchbase/+/141361

Alexis Deltour added a comment - 02/Dec/20 6:30 AM

thx a lot Sergey, i think we are about to finish the 3.x migration in Amadeus

Alexis Deltour added a comment - 02/Dec/20 6:30 AM thx a lot Sergey, i think we are about to finish the 3.x migration in Amadeus

Couchbase Build Team added a comment - 10/Feb/21 2:39 AM

Build couchbase-server-7.0.0-4433 contains libcouchbase commit 2022118 with commit message:
~~CCBC-1334~~: preserve status of KV protocol response for retry queue

Couchbase Build Team added a comment - 10/Feb/21 2:39 AM Build couchbase-server-7.0.0-4433 contains libcouchbase commit 2022118 with commit message: CCBC-1334 : preserve status of KV protocol response for retry queue

Couchbase C client library libcouchbase

Lcb authorized error replaced to generic autent err, while issuing bad permission for user

Details

Description

Attachments

Attachments

Gerrit Reviews

Activity

People

Dates

Gerrit Reviews

PagerDuty