LCB does not time out ops when lcb_open still in progress

Description

I've noticed that when calling lcb_open against a bucket which does not exist, lcb is trying to connect (which is fine of course), but for some reason it seems to not time out ops that are scheduled in the meantime.

Consider the code in https://github.com/couchbaselabs/couchbase-rs/blob/master/couchbase/examples/kv.rs#L14, but instead of opening "travel-sample", just choose a name which does not exist. The following logs show what LCB is doing in this case:

Blocking waiting for file lock on build directory Compiling couchbase-sys v1.0.0-alpha.4 (/Users/michaelnitschinger/couchbase/code/rust/couchbase-rs/couchbase-sys) Compiling couchbase v1.0.0-alpha.4 (/Users/michaelnitschinger/couchbase/code/rust/couchbase-rs/couchbase) Finished dev [unoptimized + debuginfo] target(s) in 33.74s Running `target/debug/examples/kv` [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb] Using libcouchbase IO transport [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Version=0.3.0_163_g1bb1c24783, Changeset=1bb1c247832e774468840bf9cfa667a3b9bd97ae [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Effective connection string: couchbase://127.0.0.1. Bucket=(null) [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:8091 to initial HTTP bootstrap list [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:11210 to initial CCCP bootstrap list [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Requested network configuration: heuristic [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times) [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Provider HTTP is ENABLED [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Requesting connection to node 127.0.0.1:11210 for CCCP configuration [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Creating new connection because none are available in the pool [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=fb42ab7724540ac0) Starting. Timeout=2000000us [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=fb42ab7724540ac0) Created new socket with FD=4 [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=fb42ab7724540ac0) Connected established [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=fb42ab7724540ac0) Successfully set TCP_NODELAY [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=fb42ab7724540ac0) Successfully set TCP_KEEPALIVE [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Received result for I=0x7f9015d043c0,C=0x0; E=0x0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Assigning R=0x7f9015d05400 SOCKET=0x7f9015d056e0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06dc0,unknown) Pairing with SOCK=fb42ab7724540ac0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06dc0,sasl,SASLREQ=0x7f9015c06b50) HELO identificator: {"a":"libcouchbase/0.3.0_163_g1bb1c24783 (Darwin-19.4.0; x86_64; Clang 11.0.3.11030032)","i":"7e679f657d216d0b/fb42ab7724540ac0"}, features: 0x02 (TLS), 0x06 (XATTR), 0x0b (JSON), 0x08 (Select bucket), 0x07 (XERROR), 0x03 (TCP nodelay), 0x0a (Snappy), 0x04 (Mutation seqno), 0x0f (Tracing), 0x12 (Collections) [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06dc0,sasl,SASLREQ=0x7f9015c06b50) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON), 0x0f (Tracing) [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06dc0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06fb0,unknown) Pairing with SOCK=fb42ab7724540ac0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015c06fb0,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Placing socket back into the pool. I=0x7f9015d043c0,C=0x7f9015d056e0 [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Setting new configuration. Received via CCCP [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times) [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Selected network configuration: "default" [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::instance] Starting bucket bind for foobar [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times) [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Found ready connection in pool. Reusing socket and not creating new connection [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f9015d052c0) Assigning R=0x7f9015e06d10 SOCKET=0x7f9015d056e0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f9015e06e10,unknown) Pairing with SOCK=fb42ab7724540ac0 [2020-07-16T12:39:02Z DEBUG couchbase::io::lcb::instance] Finished bucket bind for foobar [2020-07-16T12:39:02Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:02Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:02Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:04Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:04Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:04Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:07Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:07Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:07Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:07Z ERROR couchbase::io::lcb::callbacks] Failed to bootstrap client=0x7f9015d04450. Error=LCB_ERR_TIMEOUT (201) (Last=LCB_ERR_AUTHENTICATION_FAILURE (206)), Message=Failed to bootstrap in time [2020-07-16T12:39:07Z DEBUG couchbase::io::lcb::callbacks] Libcouchbase notified of completed bucket open attempt for bucket Some("foobar") (status: 0xc9) [2020-07-16T12:39:09Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:09Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:09Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:12Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:12Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:12Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:14Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:14Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:14Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:17Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:17Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:17Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:19Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:19Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:19Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:22Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:22Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:22Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:24Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:24Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:24Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:27Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:27Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:27Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap [2020-07-16T12:39:29Z ERROR couchbase::io::lcb::callbacks] <NOHOST:NOPORT> (CTX=0x0,) Could not get configuration: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:29Z INFO couchbase::io::lcb::callbacks] Provider 'CCCP' failed: LCB_ERR_AUTHENTICATION_FAILURE (206) [2020-07-16T12:39:29Z WARN couchbase::io::lcb::callbacks] Received authentication error during bootstrap .....

Environment

None

Gerrit Reviews

None

Release Notes Description

None

Activity

Brett Lawson July 20, 2021 at 6:21 PM

Relatedly, it seems that the same behaviour is exhibited to lcb_connect as well. Specifically if you specify an incorrect host with a long kv_connect_timeout, the operation does not fail until bootstrapping fails (which actually doesn't seem to adhere to kv_connect_timeout either).

Pinned fields
Click on the next to a field label to start pinning.

Details

Assignee

Story Points

Components

Reporter

Affects versions

Priority

Instabug

Open Instabug

PagerDuty

Sentry

Zendesk Support

Created July 16, 2020 at 12:39 PM
Updated September 20, 2023 at 5:17 PM
Instabug