couchbase-rs icon indicating copy to clipboard operation
couchbase-rs copied to clipboard

Published 20 hours ago • verified publisher icon couchbaselabs

Stopped Working on 1.0.0-alpha.3

Open baer-devl opened this issue 5 years ago • 21 comments

I recently tried to update from old alpha to newer on my project. Now I cant run it anymore as it will block on any operation I try. To exclude that the issue comes from my project- i cloned the actual repository, change the login data for my actual Couchbase-Instance and try to run the example 'kv' with the very same result.

cargo run --example kv
    Updating crates.io index
   Compiling autocfg v1.0.0
   Compiling proc-macro2 v1.0.8
   Compiling memchr v2.3.0
   Compiling unicode-xid v0.2.0
   Compiling libc v0.2.66
   Compiling cfg-if v0.1.10
   Compiling cc v1.0.50
   Compiling lazy_static v1.4.0
   Compiling syn v1.0.14
   Compiling version_check v0.1.5
   Compiling glob v0.3.0
   Compiling log v0.4.8
   Compiling regex-syntax v0.6.14
   Compiling quick-error v1.2.3
   Compiling bitflags v1.2.1
   Compiling getrandom v0.1.14
   Compiling bindgen v0.52.0
   Compiling termcolor v1.1.0
   Compiling peeking_take_while v0.1.2
   Compiling shlex v0.1.1
   Compiling rustc-hash v1.1.0
   Compiling proc-macro-nested v0.1.3
   Compiling lazycell v1.2.1
   Compiling ppv-lite86 v0.2.6
   Compiling autocfg v0.1.7
   Compiling futures-sink v0.3.4
   Compiling futures-core v0.3.4
   Compiling serde v1.0.104
   Compiling futures-task v0.3.4
   Compiling futures-io v0.3.4
   Compiling doc-comment v0.3.1
   Compiling slab v0.4.2
   Compiling ryu v1.0.2
   Compiling pin-utils v0.1.0-alpha.4
   Compiling itoa v0.4.5
   Compiling thread_local v1.0.1
   Compiling num-traits v0.2.11
   Compiling num-integer v0.1.42
   Compiling num-bigint v0.2.6
   Compiling num-iter v0.1.40
   Compiling num-complex v0.2.4
   Compiling num-rational v0.2.3
   Compiling cmake v0.1.42
   Compiling nom v4.2.3
   Compiling humantime v1.3.0
   Compiling clang-sys v0.28.1
   Compiling libloading v0.5.2
   Compiling couchbase v1.0.0-alpha.4 (/home/baer/tmp/couchbase-rs/couchbase)
   Compiling futures-channel v0.3.4
   Compiling crossbeam-utils v0.7.0
   Compiling c2-chacha v0.2.3
   Compiling aho-corasick v0.7.8
   Compiling quote v1.0.2
   Compiling atty v0.2.14
   Compiling which v3.1.0
   Compiling rand_core v0.5.1
   Compiling regex v1.3.4
   Compiling cexpr v0.3.6
   Compiling rand_chacha v0.2.1
   Compiling crossbeam-channel v0.4.0
   Compiling env_logger v0.7.1
   Compiling serde_json v1.0.47
   Compiling rand v0.7.3
   Compiling uuid v0.8.1
   Compiling proc-macro-hack v0.5.11
   Compiling snafu-derive v0.6.2
   Compiling serde_derive v1.0.104
   Compiling num v0.2.1
   Compiling futures-macro v0.3.4
   Compiling parse_duration v2.0.1
   Compiling futures-util v0.3.4
   Compiling snafu v0.6.2
   Compiling futures-executor v0.3.4
   Compiling futures v0.3.4
   Compiling couchbase-sys v1.0.0-alpha.4 (/home/baer/tmp/couchbase-rs/couchbase-sys)
warning: couldn't execute `llvm-config --prefix` (error: No such file or directory (os error 2))
warning: set the LLVM_CONFIG_PATH environment variable to a valid `llvm-config` executable
    Finished dev [unoptimized + debuginfo] target(s) in 2m 20s
     Running `/tmp/couchbase-rs/target/debug/examples/kv`
[2020-02-12T10:30:23Z ERROR couchbase::io::lcb::callbacks] The instance has been associated with the bucket already, sorry
^C

rustc 1.41.0 (5e1a79984 2020-01-27) cargo 1.41.0 (626f0f40e 2019-12-03) Community Edition 6.0.0 build 1693

Any Idea what is causing this Error?

baer-devl avatar Feb 12 '20 10:02 baer-devl

I run the kv-example with debug-level again:

RUST_LOG=debug cargo run --example kv
warning: couldn't execute `llvm-config --prefix` (error: No such file or directory (os error 2))
warning: set the LLVM_CONFIG_PATH environment variable to a valid `llvm-config` executable
   Compiling couchbase v1.0.0-alpha.4 (/home/baer/tmp/couchbase-rs/couchbase)
    Finished dev [unoptimized + debuginfo] target(s) in 3.29s
     Running `/home/baer/tmp/couchbase-rs/target/debug/examples/kv`
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb] Using libcouchbase IO transport
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Version=0.3.0_114_g071d71eefa, Changeset=071d71eefa98431666d03f382001580fdd41408a
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Effective connection string: couchbase://127.0.0.1. Bucket=(null)
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:8091 to initial HTTP bootstrap list
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:11210 to initial CCCP bootstrap list
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Requested network configuration: heuristic
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Provider HTTP is ENABLED
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Requesting connection to node 127.0.0.1:11210 for CCCP configuration
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Creating new connection because none are available in the pool
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=c9b1349eceed9186) Starting. Timeout=2000000us
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=c9b1349eceed9186) Created new socket with FD=3
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=c9b1349eceed9186) Connected established
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=c9b1349eceed9186) Successfully set TCP_NODELAY
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=c9b1349eceed9186) Successfully set TCP_KEEPALIVE
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Received result for I=0x7f1b700045b0,C=(nil); E=0x0
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Assigning R=0x7f1b700044e0 SOCKET=0x7f1b70004770
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b700053b0,unknown) Pairing with SOCK=c9b1349eceed9186
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b700053b0,sasl,SASLREQ=0x7f1b700051d0) HELO identificator: {"a":"libcouchbase/0.3.0_114_g071d71eefa (Linux-5.4.15-arch1-1; x86_64; GNU 9.2.0)","i":"a99d80289e79f3d8/c9b1349eceed9186"}, 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-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b700053b0,sasl,SASLREQ=0x7f1b700051d0) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON)
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b700053b0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b7001f760,unknown) Pairing with SOCK=c9b1349eceed9186
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b7001f760,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Placing socket back into the pool. I=0x7f1b700045b0,C=0x7f1b70004770
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Setting new configuration. Received via CCCP
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-12T11:01:06Z INFO  couchbase::io::lcb::callbacks] Selected network configuration: "default"
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb::callbacks] Completed bucket open attempt (status: 0x0)
[2020-02-12T11:01:06Z DEBUG couchbase::io::lcb] Starting bucket open for uplink
[2020-02-12T11:01:06Z ERROR couchbase::io::lcb::callbacks] The instance has been associated with the bucket already, sorry
[2020-02-12T11:01:08Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Found ready connection in pool. Reusing socket and not creating new connection
[2020-02-12T11:01:08Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7f1b70004390) Assigning R=0x7f1b700046a0 SOCKET=0x7f1b70004770
[2020-02-12T11:01:08Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7f1b70012c00,unknown) Pairing with SOCK=c9b1349eceed9186
^C

baer-devl avatar Feb 12 '20 11:02 baer-devl

Additionally I can see that the bucket gets a new connection when i run the example, also one CPU thread is running on 100% and keeps on going. No requests or anything else that I can see on the statistic-page from the Couchbase UI.

baer-devl avatar Feb 12 '20 14:02 baer-devl

@baer-devl thanks for sharing! I'll look into it as soon as I can

daschl avatar Feb 17 '20 16:02 daschl

@baer-devl I've added some more debugging around bootstrap, can you please retry with the latest master and send the debug logs again? Thanks!

daschl avatar Feb 18 '20 06:02 daschl

@daschl thanks for the response! I updated to the latest master and ran the same example again:

     Running `target/debug/examples/kv`
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb] Using libcouchbase IO transport
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Version=0.3.0_119_gbfbd76497d, Changeset=bfbd76497d97e0b24b05acf41d7da71c4af28df5
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Effective connection string: couchbase://127.0.0.1. Bucket=(null)
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:8091 to initial HTTP bootstrap list
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Adding host 127.0.0.1:11210 to initial CCCP bootstrap list
[2020-02-18T13:28:16Z TRACE couchbase::io::lcb::callbacks] Bootstrap hosts loaded (cccp:1, http:1)
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Requested network configuration: heuristic
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Provider HTTP is ENABLED
[2020-02-18T13:28:16Z TRACE couchbase::io::lcb::callbacks] Refreshing current cluster map
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Requesting connection to node 127.0.0.1:11210 for CCCP configuration
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7fd08c004330) Creating new connection because none are available in the pool
[2020-02-18T13:28:16Z TRACE couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7fd08c004330) New pool entry: I=0x7fd08c004550
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Starting. Timeout=2000000us
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Created new socket with FD=3
[2020-02-18T13:28:16Z TRACE couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Scheduling I/O watcher for asynchronous connection completion.
[2020-02-18T13:28:16Z TRACE couchbase::io::lcb::callbacks] Attempting to retrieve cluster map via CCCP
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Connected established
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Successfully set TCP_NODELAY
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (SOCK=4fcbe7bffc72a57e) Successfully set TCP_KEEPALIVE
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7fd08c004330) Received result for I=0x7fd08c004550,C=(nil); E=0x0
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7fd08c004330) Assigning R=0x7fd08c004480 SOCKET=0x7fd08c004710
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c005500,unknown) Pairing with SOCK=4fcbe7bffc72a57e
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c005500,sasl,SASLREQ=0x7fd08c005320) HELO identificator: {"a":"libcouchbase/0.3.0_119_gbfbd76497d (Linux-5.5.4-arch1-1; x86_64; GNU 9.2.1)","i":"76eb33cf4cadf56c/4fcbe7bffc72a57e"}, 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-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c005500,sasl,SASLREQ=0x7fd08c005320) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON)
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c005500,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c015340,unknown) Pairing with SOCK=4fcbe7bffc72a57e
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (CTX=0x7fd08c015340,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] <127.0.0.1:11210> (HE=0x7fd08c004330) Placing socket back into the pool. I=0x7fd08c004550,C=0x7fd08c004710
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Setting new configuration. Received via CCCP
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-18T13:28:16Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-18T13:28:16Z INFO  couchbase::io::lcb::callbacks] Selected network configuration: "default"
... terminated by signal SIGSEGV (Address boundary error)

Unfortunately I cannot run it in gdb to give you more information as I struggle to setup it correctly to find the correct libcouchbase.so.6 (which gdb is complaining about). Maybe you have an advice to solve this?

However, when I run the same code with info|warn|error debugging levels, same result as previously- it stucks somewhere on full CPU thread. It seems like your additional debug information tries to read from a null-pointer: -> issue is here: couchbase/src/io/lcb/callbacks.rs -> bucket_name_for_instance(instance)

baer-devl avatar Feb 18 '20 13:02 baer-devl

@baer-devl this is good info, looks like there is no bucket name associated after the callback is complete. Let me push another more defensive change

daschl avatar Feb 18 '20 14:02 daschl

Can you try on top of https://github.com/couchbaselabs/couchbase-rs/commit/b2f8491012e76678f7f6bd096dafbd10edc4e741 ?

daschl avatar Feb 18 '20 14:02 daschl

Output is as follows:

     Running `target/debug/examples/kv`
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb] Using libcouchbase IO transport
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Version=0.3.0_120_gb2f8491012, Changeset=b2f8491012e76678f7f6bd096dafbd10edc4e741
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Effective connection string: couchbase://couchbase-intern. Bucket=(null)
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] DNS SRV lookup failed: LCB_ERR_UNKNOWN_HOST (1049). Ignore this if not relying on DNS SRV records
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Adding host couchbase-intern:8091 to initial HTTP bootstrap list
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Adding host couchbase-intern:11210 to initial CCCP bootstrap list
[2020-02-18T14:09:47Z TRACE couchbase::io::lcb::callbacks] Bootstrap hosts loaded (cccp:1, http:1)
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Requested network configuration: heuristic
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Provider HTTP is ENABLED
[2020-02-18T14:09:47Z TRACE couchbase::io::lcb::callbacks] Refreshing current cluster map
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Requesting connection to node couchbase-intern:11210 for CCCP configuration
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Creating new connection because none are available in the pool
[2020-02-18T14:09:47Z TRACE couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) New pool entry: I=0x7f7f30004770
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Starting. Timeout=2000000us
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Created new socket with FD=3
[2020-02-18T14:09:47Z TRACE couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Scheduling I/O watcher for asynchronous connection completion.
[2020-02-18T14:09:47Z TRACE couchbase::io::lcb::callbacks] Attempting to retrieve cluster map via CCCP
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Connected established
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Successfully set TCP_NODELAY
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (SOCK=fca4f394178fc1f2) Successfully set TCP_KEEPALIVE
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Received result for I=0x7f7f30004770,C=(nil); E=0x0
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Assigning R=0x7f7f300044f0 SOCKET=0x7f7f30004930
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30005cb0,unknown) Pairing with SOCK=fca4f394178fc1f2
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30005cb0,sasl,SASLREQ=0x7f7f30005ad0) HELO identificator: {"a":"libcouchbase/0.3.0_120_gb2f8491012 (Linux-5.5.4-arch1-1; x86_64; GNU 9.2.1)","i":"4fc63b6ac9af5875/fca4f394178fc1f2"}, 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-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30005cb0,sasl,SASLREQ=0x7f7f30005ad0) Server supports features: 0x03 (TCP nodelay), 0x04 (Mutation seqno), 0x06 (XATTR), 0x07 (XERROR), 0x08 (Select bucket), 0x0a (Snappy), 0x0b (JSON)
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30005cb0,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f300204c0,unknown) Pairing with SOCK=fca4f394178fc1f2
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f300204c0,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Placing socket back into the pool. I=0x7f7f30004770,C=0x7f7f30004930
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Setting new configuration. Received via CCCP
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Preparing providers (this may be called multiple times)
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Provider CCCP is ENABLED
[2020-02-18T14:09:47Z INFO  couchbase::io::lcb::callbacks] Selected network configuration: "default"
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb::callbacks] Libcouchbase notified of completed bucket open attempt for bucket None (status: 0x0)
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb] Starting bucket open for travel-sample
[2020-02-18T14:09:47Z ERROR couchbase::io::lcb::callbacks] The instance has been associated with the bucket already, sorry
[2020-02-18T14:09:47Z DEBUG couchbase::io::lcb] Finished bucket open for travel-sample
[2020-02-18T14:09:49Z TRACE couchbase::io::lcb::callbacks] Background-polling for new configuration
[2020-02-18T14:09:49Z TRACE couchbase::io::lcb::callbacks] Refreshing current cluster map
[2020-02-18T14:09:49Z TRACE couchbase::io::lcb::callbacks] Attempting to retrieve cluster map via CCCP
[2020-02-18T14:09:49Z TRACE couchbase::io::lcb::callbacks] Re-Issuing CCCP Command on server struct 0x7f7f30010610 (couchbase-intern:11210)
[2020-02-18T14:09:49Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Found ready connection in pool. Reusing socket and not creating new connection
[2020-02-18T14:09:49Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (HE=0x7f7f30004360) Assigning R=0x7f7f300044f0 SOCKET=0x7f7f30004930
[2020-02-18T14:09:49Z DEBUG couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30013b10,unknown) Pairing with SOCK=fca4f394178fc1f2
[2020-02-18T14:09:49Z TRACE couchbase::io::lcb::callbacks] Not applying configuration received via CCCP. No changes detected. A.rev=73, B.rev=73
[2020-02-18T14:09:51Z TRACE couchbase::io::lcb::callbacks] <couchbase-intern:11210> (CTX=0x7f7f30013b10,memcached,SRV=0x7f7f30010610,IX=0) Scheduling next timeout for 2500 ms. This is not an error
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Background-polling for new configuration
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Refreshing current cluster map
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Not applying configuration received via CCCP. No changes detected. A.rev=73, B.rev=73
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Attempting to retrieve cluster map via CCCP
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Re-Issuing CCCP Command on server struct 0x7f7f30010610 (couchbase-intern:11210)
[2020-02-18T14:09:52Z TRACE couchbase::io::lcb::callbacks] Not applying configuration received via CCCP. No changes detected. A.rev=73, B.rev=73
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Background-polling for new configuration
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Refreshing current cluster map
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Not applying configuration received via CCCP. No changes detected. A.rev=73, B.rev=73
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Attempting to retrieve cluster map via CCCP
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Re-Issuing CCCP Command on server struct 0x7f7f30010610 (couchbase-intern:11210)
[2020-02-18T14:09:54Z TRACE couchbase::io::lcb::callbacks] Not applying configuration received via CCCP. No changes detected. A.rev=73, B.rev=73
^C

baer-devl avatar Feb 18 '20 14:02 baer-devl

@baer-devl ok looks like I need to reproduce this as close as possible. Can you provide some more info on:

  • Which services you are running
  • Which OS you are using
  • How you modified the original kv example?

daschl avatar Feb 18 '20 14:02 daschl

Services:

  • Community Edition 6.0.0 build 1693 with fresh travle-sample bucket
  • Arch Linux x64 - systemd -> not sure what information you want?
  • Changes:
-    let cluster = Cluster::connect("couchbase://10.143.193.101", "Administrator", "password");
+    let cluster = Cluster::connect("couchbase://couchbase-intern", "travel-sample", "travel");

baer-devl avatar Feb 18 '20 15:02 baer-devl

@baer-devl did you create a user with the same name of the bucket?

I think I could reproduce the issue if I also create a user of the same name as the bucket. Can you to verify try to create a user with a different name?

daschl avatar Feb 18 '20 15:02 daschl

@daschl sry that I missed this detail, yes I did! I also tried different access levels (default: Application Access bucket travel-sample, Full Admin, All Buckets, Read-Only Admin) - no difference

baer-devl avatar Feb 18 '20 15:02 baer-devl

@baer-devl the access level should not make a difference, I think something is tripping it up with the same user name as the bucket name. I'll go look into it but for now I can unblock you I think if you use a different username than the bucket name.

daschl avatar Feb 18 '20 15:02 daschl

@daschl You are right thank you! If I use the user "test" I just created, it works! Out of curiosity, how does this make a difference?

baer-devl avatar Feb 18 '20 15:02 baer-devl

@baer-devl I'm looking into this with @avsej from the libcouchbase side, but what's going on is that during KV auth the server "auto-selects" a bucket if the user name is the same as the bucket name. This is for backwards compatibility with old clients, where we did not have RBAC. Back in the days we only had bucket-level credentials so it is a bit difficult to distinguish those cases.

In any case the SDK should handle that so we are currently trying to figure out the root cause.

daschl avatar Feb 18 '20 15:02 daschl

@daschl Thanks for the info! Retrospectively it was luck that I also used the same user-name for the travel-sample. As my origin problem resulted from another bucket (where the user-name was also the same). Guess we wouldn't found the cause otherwise! :smile:

baer-devl avatar Feb 18 '20 15:02 baer-devl

Is it necessary to use different user than the bucket name with the latest release. We are trying to set up a sample code with rust to do performance comparison with vertx, go and rust.

I am very newbie to rust and is thinking of using async api using warp to see the performance.

himanshumps avatar Mar 11 '20 13:03 himanshumps

@himanshumps I'm trying to fix the issue for the next release so that the user doesn't have to worry about it.

daschl avatar Mar 11 '20 13:03 daschl

Any updates on this @daschl

himanshumps avatar Aug 31 '20 13:08 himanshumps

@himanshumps I've recently pushed a alpha.4, can you try if it works there?

daschl avatar Aug 31 '20 13:08 daschl

The issue is still there with alpha 4 release.

himanshumps avatar Jun 05 '21 05:06 himanshumps