I’ve been adjusting some configuration settings to better understand how to minimize the issue.
In this test, my configuration is:
couchbase.max_persistent = 25
couchbase.persistent_timeout = 180000
Logs for 1 request
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"don't cleanup idle connections. max_persistent=25, num_persistent=0","thread_id":63465,"time":"2025-03-24 20:14:57.935852194.852194"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"open cluster, id: "4b3bc7-c247-1042-a383-31fe167cd892cf", core version: "1.0.4", {"bootstrap_nodes":[{"hostname":"10.42.0.11","port":"11210"},{"hostname":"10.42.0.12","port":"11210"},{"hostname":"10.42.0.13","port":"11210"}],"options":{"analytics_timeout":"75000ms","bootstrap_timeout":"10000ms","config_idle_redial_timeout":"300000ms","config_poll_floor":"50ms","config_poll_interval":"2500ms","connect_timeout":"10000ms","disable_mozilla_ca_certificates":false,"dns_config":{"nameserver":"127.0.0.11","port":53,"timeout":"500ms"},"dump_configuration":false,"enable_clustermap_notification":true,"enable_compression":true,"enable_dns_srv":false,"enable_metrics":true,"enable_mutation_tokens":true,"enable_tcp_keep_alive":true,"enable_tls":false,"enable_tracing":true,"enable_unordered_execution":true,"idle_http_connection_timeout":"4500ms","key_value_durable_timeout":"10000ms","key_value_timeout":"2500ms","management_timeout":"75000ms","max_http_connections":0,"metrics_options":{"emit_interval":"600000ms"},"network":"auto","query_timeout":"75000ms","resolve_timeout":"2000ms","search_timeout":"75000ms","show_queries":false,"tcp_keep_alive_interval":"60000ms","tls_verify":"peer","tracing_options":{"analytics_threshold":"1000ms","key_value_threshold":"500ms","management_threshold":"1000ms","orphaned_emit_interval":"10000ms","orphaned_sample_size":64,"query_threshold":"1000ms","search_threshold":"1000ms","threshold_emit_interval":"10000ms","threshold_sample_size":64,"view_threshold":"1000ms"},"transactions_options":{"cleanup_config":{"cleanup_client_attempts":true,"cleanup_lost_attempts":true,"cleanup_window":"60000ms","collections":[]},"durability_level":"majority","query_config":{"scan_consistency":"request_plus"},"timeout":"15000000000ns"},"trust_certificate":"","use_ip_protocol":"any","user_agent_extra":"php_sdk/4.2.5/c9704a8a;php/8.1.31/n","view_timeout":"75000ms"}}","thread_id":72424,"time":"2025-03-24 20:14:57.936230988.230988"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11:11210> attempt to establish MCBP connection","thread_id":72424,"time":"2025-03-24 20:14:57.936304987.304987"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11:11210> connecting to 10.42.0.11:11210 ("10.42.0.11:11210"), timeout=10000ms","thread_id":72425,"time":"2025-03-24 20:14:57.936348389.348389"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11:11210> connected to 10.42.0.11:11210","thread_id":72425,"time":"2025-03-24 20:14:57.936484330.484330"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11/10.42.0.11:11210> user_agent={"a":"php/4.2.5 (cxx/1.0.4;Linux/x86_64;bssl/0x1010107f;php_sdk/4.2.5/c9704a8a;php/8.1.31/n)","i":"4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164"}, requested_features=[tcp_nodelay, xattr, xerror, select_bucket, json, duplex, alt_request_support, tracing, sync_replication, vattr, collections, subdoc_create_as_deleted, preserve_ttl, subdoc_replica_read, subdoc_binary_xattr, unordered_execution, clustermap_change_notification, deduplicate_not_my_vbucket_clustermap, snappy, mutation_seqno]","thread_id":72425,"time":"2025-03-24 20:14:57.936528818.528818"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11/10.42.0.11:11210> supported_features=[tcp_nodelay, mutation_seqno, xattr, xerror, select_bucket, snappy, json, duplex, clustermap_change_notification, unordered_execution, tracing, alt_request_support, sync_replication, collections, preserve_ttl, vattr, subdoc_create_as_deleted]","thread_id":72425,"time":"2025-03-24 20:14:57.936756674.756674"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/6ef27f-74f4-fb43-b789-7cee345d654164/plain/-] <10.42.0.11/10.42.0.11:11210> detected network is "default"","thread_id":72425,"time":"2025-03-24 20:14:57.940215782.215782"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[attempt_cleanup] - cleanup attempts loop starting...","thread_id":72427,"time":"2025-03-24 20:14:57.940366014.366014"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"persistent connection miss, created new connection: handle=0x5559f18dad00, connection_hash=9460d2d6e5c13cdc7b4616b2f3bff243321681dfec47119afe68abbfa1d8d220, connection_string="couchbase://10.42.0.11,10.42.0.12,10.42.0.13", expires_at="2025-03-24 20:17:57.935841480" (180000000000ns), destructor_id=15, num_persistent=1","thread_id":63465,"time":"2025-03-24 20:14:57.940384912.384912"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11:11210> attempt to establish MCBP connection","thread_id":63465,"time":"2025-03-24 20:14:57.940896067.896067"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11:11210> connecting to 10.42.0.11:11210 ("10.42.0.11:11210"), timeout=10000ms","thread_id":72425,"time":"2025-03-24 20:14:57.940921597.921597"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11:11210> connected to 10.42.0.11:11210","thread_id":72425,"time":"2025-03-24 20:14:57.941024954.24954"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11/10.42.0.11:11210> user_agent={"a":"php/4.2.5 (cxx/1.0.4;Linux/x86_64;bssl/0x1010107f;php_sdk/4.2.5/c9704a8a;php/8.1.31/n)","i":"4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291"}, requested_features=[tcp_nodelay, xattr, xerror, select_bucket, json, duplex, alt_request_support, tracing, sync_replication, vattr, collections, subdoc_create_as_deleted, preserve_ttl, subdoc_replica_read, subdoc_binary_xattr, unordered_execution, clustermap_change_notification, deduplicate_not_my_vbucket_clustermap, snappy, mutation_seqno]","thread_id":72425,"time":"2025-03-24 20:14:57.941053212.53212"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11/10.42.0.11:11210> supported_features=[tcp_nodelay, mutation_seqno, xattr, xerror, select_bucket, snappy, json, duplex, clustermap_change_notification, unordered_execution, tracing, alt_request_support, sync_replication, collections, preserve_ttl, vattr, subdoc_create_as_deleted]","thread_id":72425,"time":"2025-03-24 20:14:57.941240602.240602"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/eb443b-9153-2f44-f10d-b1e61b2d7dd291/plain/web] <10.42.0.11/10.42.0.11:11210> selected bucket: test","thread_id":72425,"time":"2025-03-24 20:14:57.943676201.676201"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] initialize configuration rev=1:2722","thread_id":72425,"time":"2025-03-24 20:14:57.944124470.124470"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] rev=1:2722, preserve session="eb443b-9153-2f44-f10d-b1e61b2d7dd291", address="10.42.0.11:11210", index=0->0","thread_id":72425,"time":"2025-03-24 20:14:57.944268997.268997"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] rev=1:2722, add session="25287a-7659-9649-d3f5-2ac0e1ae575660", address="10.42.0.12:11210", index=1","thread_id":72425,"time":"2025-03-24 20:14:57.944286749.286749"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12:11210> attempt to establish MCBP connection","thread_id":72425,"time":"2025-03-24 20:14:57.944289656.289656"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] rev=1:2722, add session="979966-46d1-2d4d-7a4f-5c0e856a9a40c2", address="10.42.0.13:11210", index=2","thread_id":72425,"time":"2025-03-24 20:14:57.944296362.296362"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13:11210> attempt to establish MCBP connection","thread_id":72425,"time":"2025-03-24 20:14:57.944297528.297528"}
Mar 24 20:14:57 web php[63465]: {"level":"warning","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] unable to find connected session with GCCCP support, retry in 2500ms","thread_id":72425,"time":"2025-03-24 20:14:57.944310659.310659"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12:11210> connecting to 10.42.0.12:11210 ("10.42.0.12:11210"), timeout=10000ms","thread_id":72425,"time":"2025-03-24 20:14:57.944340265.340265"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13:11210> connecting to 10.42.0.13:11210 ("10.42.0.13:11210"), timeout=10000ms","thread_id":72425,"time":"2025-03-24 20:14:57.944405416.405416"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12:11210> connected to 10.42.0.12:11210","thread_id":72425,"time":"2025-03-24 20:14:57.944532430.532430"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12/10.42.0.12:11210> user_agent={"a":"php/4.2.5 (cxx/1.0.4;Linux/x86_64;bssl/0x1010107f;php_sdk/4.2.5/c9704a8a;php/8.1.31/n)","i":"4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660"}, requested_features=[tcp_nodelay, xattr, xerror, select_bucket, json, duplex, alt_request_support, tracing, sync_replication, vattr, collections, subdoc_create_as_deleted, preserve_ttl, subdoc_replica_read, subdoc_binary_xattr, unordered_execution, clustermap_change_notification, deduplicate_not_my_vbucket_clustermap, snappy, mutation_seqno]","thread_id":72425,"time":"2025-03-24 20:14:57.944632731.632731"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13:11210> connected to 10.42.0.13:11210","thread_id":72425,"time":"2025-03-24 20:14:57.944647368.647368"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13/10.42.0.13:11210> user_agent={"a":"php/4.2.5 (cxx/1.0.4;Linux/x86_64;bssl/0x1010107f;php_sdk/4.2.5/c9704a8a;php/8.1.31/n)","i":"4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2"}, requested_features=[tcp_nodelay, xattr, xerror, select_bucket, json, duplex, alt_request_support, tracing, sync_replication, vattr, collections, subdoc_create_as_deleted, preserve_ttl, subdoc_replica_read, subdoc_binary_xattr, unordered_execution, clustermap_change_notification, deduplicate_not_my_vbucket_clustermap, snappy, mutation_seqno]","thread_id":72425,"time":"2025-03-24 20:14:57.944663709.663709"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12/10.42.0.12:11210> supported_features=[tcp_nodelay, mutation_seqno, xattr, xerror, select_bucket, snappy, json, duplex, clustermap_change_notification, unordered_execution, tracing, alt_request_support, sync_replication, collections, preserve_ttl, vattr, subdoc_create_as_deleted]","thread_id":72425,"time":"2025-03-24 20:14:57.944868424.868424"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13/10.42.0.13:11210> supported_features=[tcp_nodelay, mutation_seqno, xattr, xerror, select_bucket, snappy, json, duplex, clustermap_change_notification, unordered_execution, tracing, alt_request_support, sync_replication, collections, preserve_ttl, vattr, subdoc_create_as_deleted]","thread_id":72425,"time":"2025-03-24 20:14:57.944881735.881735"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12/10.42.0.12:11210> selected bucket: test","thread_id":72425,"time":"2025-03-24 20:14:57.952030860.30860"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/25287a-7659-9649-d3f5-2ac0e1ae575660/plain/web] <10.42.0.12/10.42.0.12:11210> the stream is not ready yet, put the message into pending buffer, opaque=8","thread_id":72425,"time":"2025-03-24 20:14:57.952469971.469971"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/979966-46d1-2d4d-7a4f-5c0e856a9a40c2/plain/web] <10.42.0.13/10.42.0.13:11210> selected bucket: test","thread_id":72425,"time":"2025-03-24 20:14:57.952889000.889000"}
Mar 24 20:14:57 web php[63465]: {"level":"debug","message":"[4b3bc7-c247-1042-a383-31fe167cd892cf/web] will update the configuration old=1:2722 -> new=1:2726","thread_id":72425,"time":"2025-03-24 20:14:57.953311371.311371"}
After enabling logging for a single request, I noticed that the system attempts to clean up persistent connections. However, it sometimes reduces the connection count connections (only 3 or less connections). I’m unsure if I’m missing something.
Any insights would be appreciated.