The code in rlm_couchbase.c definitely processes accounting interim-update packets. So what does the debug log show when you receive such a packet?
I knew I forgot something... Here it is, I also enabled couchbase module debug output for even more details: Sent Accounting-Request Id 163 from 0.0.0.0:60038 to 127.0.0.1:1813 length 715 (0) Received Accounting-Request Id 163 from 127.0.0.1:60038 to 127.0.0.1:1813 length 715 (0) User-Name = "noneexistent123@domain.com" (0) Acct-Status-Type = Interim-Update (0) Acct-Session-Id = "25466609" (0) Acct-Input-Octets = 211016095 (0) Acct-Output-Octets = 3081069646 (0) Acct-Session-Time = 2047177 (0) Acct-Input-Packets = 179269685 (0) Acct-Output-Packets = 322301129 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in" (0) Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out" (0) Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b (0) Tunnel-Type:0 = L2TP (0) Tunnel-Medium-Type:0 = IPv4 (0) Tunnel-Client-Endpoint:0 = "192.168.242.189" (0) Tunnel-Server-Endpoint:0 = "192.168.80.106" (0) Tunnel-Assignment-Id:0 = "57524" (0) Tunnel-Client-Auth-Id:0 = "AB99AR99" (0) Tunnel-Server-Auth-Id:0 = "domain" (0) Acct-Tunnel-Connection = "0002758216" (0) Acct-Authentic = RADIUS (0) Acct-Delay-Time = 0 (0) Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#" (0) ERX-Dhcp-Mac-Addr = "0000.0000.0000" (0) Event-Timestamp = "Dec 12 2017 11:35:30 EST" (0) Framed-IP-Address = 192.168.225.42 (0) Framed-IP-Netmask = 255.255.254.0 (0) ERX-Input-Gigapkts = 0 (0) Acct-Input-Gigawords = 4 (0) NAS-Identifier = "lns01.lan" (0) NAS-Port = 268439551 (0) NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216" (0) NAS-Port-Type = Virtual (0) ERX-Output-Gigapkts = 0 (0) Acct-Output-Gigawords = 103 (0) ERX-IPv6-Acct-Input-Octets = 0 (0) ERX-IPv6-Acct-Output-Octets = 0 (0) ERX-IPv6-Acct-Input-Packets = 0 (0) ERX-IPv6-Acct-Output-Packets = 0 (0) ERX-IPv6-Acct-Input-Gigawords = 0 (0) ERX-IPv6-Acct-Output-Gigawords = 0 (0) ERX-Tx-Connect-Speed = 13277755 (0) Attr-26.4874.163 = 0x000000 (0) ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00" (0) NAS-IP-Address = 192.168.191.4 (0) # Executing section preacct from file /etc/raddb/sites-enabled/domain (0) preacct { (0) suffix: Checking for suffix after "@" (0) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com" (0) suffix: No such realm "domain.com" (0) [suffix] = noop (0) policy username_lower_domain { (0) update request { (0) EXPAND %{tolower:%{User-Name}} (0) --> noneexistent123@domain.com (0) Stripped-User-Name := noneexistent123@domain.com (0) } # update request = noop (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){ (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) { (0) update request { (0) EXPAND %{tolower:%{3}} (0) --> domain.com (0) Stripped-User-Domain = domain.com (0) } # update request = noop (0) [updated] = updated (0) } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated (0) ... skipping else: Preceding "if" was taken (0) } # policy username_lower_domain = updated (0) policy acct_counters64_preacct { (0) update request { (0) EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}} (0) --> 17390885279 (0) Acct-Input-Octets64 = 17390885279 (0) EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}} (0) --> 445462701134 (0) Acct-Output-Octets64 = 445462701134 (0) } # update request = noop (0) } # policy acct_counters64_preacct = noop (0) policy acct_unique { (0) update request { (0) EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}} (0) --> 51dc686492632c94c03d1346eb471bf5 (0) Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5 (0) } # update request = noop (0) } # policy acct_unique = noop (0) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) { (0) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) -> FALSE (0) } # preacct = updated (0) # Executing section accounting from file /etc/raddb/sites-enabled/domain (0) accounting { (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) -> TRUE (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (0) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type} (0) linelog-domain-acct: --> messages.Interim-Update (0) linelog-domain-acct: EXPAND 'Interim-Update''%{Acct-Session-Id}''%{User-Name}''%{NAS-IP-Address}''%S''%{Acct-Session-Time}''%{%{Acct-Input-Gigawords}:-0}''%{%{Acct-Output-Gigawords}:-0}''%{%{Acct-Input-Octets}:-0}''%{%{Acct-Output-Octets}:-0}''%{Calling-Station-Id}''%{Framed-IP-Address}' (0) linelog-domain-acct: --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 08:50:02''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42' (0) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log (0) linelog-domain-acct: --> /var/log/radius/radacct/acct.log (0) [linelog-domain-acct] = ok rlm_couchbase (couchbase): Reserved connection (0) (0) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}} (0) couchbase: --> radacct_51dc686492632c94c03d1346eb471bf5 109644ms [I0] {27151} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Found ready connection in pool. Reusing socket and not creating new connection 109644ms [I0] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Assigning R=0x5601af6b0c90 SOCKET=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8b2bc0,unknown) Pairing with SOCK=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x5601af6b9580,IX=0) Setting initial timeout=2499ms rlm_couchbase: (get_callback) key does not exist (0) couchbase: ERROR: failed to execute get request or parse returned json object (0) couchbase: no existing document found - creating new json document rlm_couchbase: calculated start timestamp: Nov 18 2017 18:55:53 EST rlm_couchbase (couchbase): Released connection (0) Need 3 more connections to reach min connections (8) rlm_couchbase (couchbase): Opening additional connection (5), 1 of 123 pending slots used 109646ms [I5] {27151} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798 109646ms [I5] {27151} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius 109646ms [I5] {27151} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1 109646ms [I5] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list 109646ms [I5] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list 109760ms [I5] {27151} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed 109760ms [I5] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 109760ms [I5] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED 109760ms [I5] {27151} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED 109760ms [I5] {27151} [TRACE] (confmon - L:252) Start refresh requested 109760ms [I5] {27151} [TRACE] (confmon - L:239) Current provider is CCCP 109760ms [I5] {27151} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration 109760ms [I5] {27151} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x5601af8c7840) Creating new connection because none are available in the pool 109760ms [I5] {27151} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x5601af8c7840) Starting connection on I=0x5601af8c7cd0 109760ms [I5] {27151} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Starting. Timeout=2000000us 109760ms [I5] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Got event handler for new connection 109760ms [I5] {27151} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Scheduling asynchronous watch for socket. 109761ms [I5] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Got event handler for new connection 109761ms [I5] {27151} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Connected 109761ms [I5] {27151} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Successfuly set TCP_NODELAY 109761ms [I5] {27151} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x5601af8c7840) Received result for I=0x5601af8c7cd0,C=0x5601af8c7dd0; E=0x0 109761ms [I5] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af8c7840) Assigning R=0x5601af6b0c90 SOCKET=0x5601af8c7dd0 109761ms [I5] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8c85e0,unknown) Pairing with SOCK=0x5601af8c7dd0 109762ms [I5] {27151} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x5601af8c8490) Found feature 0x3 (TCP NODELAY) 109762ms [I5] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8c85e0,sasl) Destroying. PND=0,ENT=1,SORC=1 109762ms [I5] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8d0af0,unknown) Pairing with SOCK=0x5601af8c7dd0 109762ms [I5] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8d0af0,bc_cccp) Destroying. PND=0,ENT=1,SORC=1 109762ms [I5] {27151} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x5601af8c7840) Placing socket back into the pool. I=0x5601af8c7cd0,C=0x5601af8c7dd0 109763ms [I5] {27151} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP 109763ms [I5] {27151} [DEBUG] (bootstrap - L:56) Instance configured! 109763ms [I5] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 109763ms [I5] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED (0) [couchbase] = ok (0) } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) = ok (0) [ok] = ok (0) } # accounting = ok (0) Sent Accounting-Response Id 163 from 127.0.0.1:1813 to 127.0.0.1:60038 length 0 (0) Finished request (0) Cleaning up request packet ID 163 with timestamp +109 Ready to process requests Received Accounting-Response Id 163 from 127.0.0.1:1813 to 0.0.0.0:0 length 20 [root@radius03 radius]# cat /tmp/testacc | radclient 127.0.0.1 acct testing123 Sent Accounting-Request Id 207 from 0.0.0.0:36802 to 127.0.0.1:1813 length 715 (1) Received Accounting-Request Id 207 from 127.0.0.1:36802 to 127.0.0.1:1813 length 715 (1) User-Name = "noneexistent123@domain.com" (1) Acct-Status-Type = Interim-Update (1) Acct-Session-Id = "25466609" (1) Acct-Input-Octets = 211016095 (1) Acct-Output-Octets = 3081069646 (1) Acct-Session-Time = 2047177 (1) Acct-Input-Packets = 179269685 (1) Acct-Output-Packets = 322301129 (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in" (1) Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out" (1) Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b (1) Tunnel-Type:0 = L2TP (1) Tunnel-Medium-Type:0 = IPv4 (1) Tunnel-Client-Endpoint:0 = "192.168.242.189" (1) Tunnel-Server-Endpoint:0 = "192.168.80.106" (1) Tunnel-Assignment-Id:0 = "57524" (1) Tunnel-Client-Auth-Id:0 = "AB99AR99" (1) Tunnel-Server-Auth-Id:0 = "domain" (1) Acct-Tunnel-Connection = "0002758216" (1) Acct-Authentic = RADIUS (1) Acct-Delay-Time = 0 (1) Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#" (1) ERX-Dhcp-Mac-Addr = "0000.0000.0000" (1) Event-Timestamp = "Dec 12 2017 11:35:30 EST" (1) Framed-IP-Address = 192.168.225.42 (1) Framed-IP-Netmask = 255.255.254.0 (1) ERX-Input-Gigapkts = 0 (1) Acct-Input-Gigawords = 4 (1) NAS-Identifier = "lns01.lan" (1) NAS-Port = 268439551 (1) NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216" (1) NAS-Port-Type = Virtual (1) ERX-Output-Gigapkts = 0 (1) Acct-Output-Gigawords = 103 (1) ERX-IPv6-Acct-Input-Octets = 0 (1) ERX-IPv6-Acct-Output-Octets = 0 (1) ERX-IPv6-Acct-Input-Packets = 0 (1) ERX-IPv6-Acct-Output-Packets = 0 (1) ERX-IPv6-Acct-Input-Gigawords = 0 (1) ERX-IPv6-Acct-Output-Gigawords = 0 (1) ERX-Tx-Connect-Speed = 13277755 (1) Attr-26.4874.163 = 0x000000 (1) ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00" (1) NAS-IP-Address = 192.168.191.4 (1) # Executing section preacct from file /etc/raddb/sites-enabled/domain (1) preacct { (1) suffix: Checking for suffix after "@" (1) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com" (1) suffix: No such realm "domain.com" (1) [suffix] = noop (1) policy username_lower_domain { (1) update request { (1) EXPAND %{tolower:%{User-Name}} (1) --> noneexistent123@domain.com (1) Stripped-User-Name := noneexistent123@domain.com (1) } # update request = noop (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){ (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) { (1) update request { (1) EXPAND %{tolower:%{3}} (1) --> domain.com (1) Stripped-User-Domain = domain.com (1) } # update request = noop (1) [updated] = updated (1) } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated (1) ... skipping else: Preceding "if" was taken (1) } # policy username_lower_domain = updated (1) policy acct_counters64_preacct { (1) update request { (1) EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}} (1) --> 17390885279 (1) Acct-Input-Octets64 = 17390885279 (1) EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}} (1) --> 445462701134 (1) Acct-Output-Octets64 = 445462701134 (1) } # update request = noop (1) } # policy acct_counters64_preacct = noop (1) policy acct_unique { (1) update request { (1) EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}} (1) --> 51dc686492632c94c03d1346eb471bf5 (1) Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5 (1) } # update request = noop (1) } # policy acct_unique = noop (1) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) { (1) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) -> FALSE (1) } # preacct = updated (1) # Executing section accounting from file /etc/raddb/sites-enabled/domain (1) accounting { (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) -> TRUE (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (1) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type} (1) linelog-domain-acct: --> messages.Interim-Update (1) linelog-domain-acct: EXPAND 'Interim-Update''%{Acct-Session-Id}''%{User-Name}''%{NAS-IP-Address}''%S''%{Acct-Session-Time}''%{%{Acct-Input-Gigawords}:-0}''%{%{Acct-Output-Gigawords}:-0}''%{%{Acct-Input-Octets}:-0}''%{%{Acct-Output-Octets}:-0}''%{Calling-Station-Id}''%{Framed-IP-Address}' (1) linelog-domain-acct: --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 08:50:12''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42' (1) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log (1) linelog-domain-acct: --> /var/log/radius/radacct/acct.log (1) [linelog-domain-acct] = ok rlm_couchbase (couchbase): Reserved connection (1) (1) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}} (1) couchbase: --> radacct_51dc686492632c94c03d1346eb471bf5 119373ms [I1] {27151} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x5601af6b8b00) Found ready connection in pool. Reusing socket and not creating new connection 119373ms [I1] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af6b8b00) Assigning R=0x5601af8d0b70 SOCKET=0x5601af6b90d0 119373ms [I1] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8b1bc0,unknown) Pairing with SOCK=0x5601af6b90d0 119373ms [I1] {27151} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x5601af6b19b0,IX=0) Setting initial timeout=2499ms rlm_couchbase: (get_callback) got 651 bytes rlm_couchbase (couchbase): Released connection (1) Need 2 more connections to reach min connections (8) rlm_couchbase (couchbase): Opening additional connection (6), 1 of 122 pending slots used 119375ms [I6] {27151} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798 119375ms [I6] {27151} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius 119375ms [I6] {27151} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1 119375ms [I6] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list 119375ms [I6] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list 119489ms [I6] {27151} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed 119489ms [I6] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 119489ms [I6] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED 119489ms [I6] {27151} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED 119489ms [I6] {27151} [TRACE] (confmon - L:252) Start refresh requested 119490ms [I6] {27151} [TRACE] (confmon - L:239) Current provider is CCCP 119490ms [I6] {27151} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Creating new connection because none are available in the pool 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Starting connection on I=0x5601af8de540 119490ms [I6] {27151} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x5601af8de640) Starting. Timeout=2000000us 119490ms [I6] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8de640) Got event handler for new connection 119490ms [I6] {27151} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x5601af8de640) Scheduling asynchronous watch for socket. 119490ms [I6] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8de640) Got event handler for new connection 119490ms [I6] {27151} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x5601af8de640) Connected 119490ms [I6] {27151} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x5601af8de640) Successfuly set TCP_NODELAY 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Received result for I=0x5601af8de540,C=0x5601af8de640; E=0x0 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Assigning R=0x5601af6b0c90 SOCKET=0x5601af8de640 119490ms [I6] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8deea0,unknown) Pairing with SOCK=0x5601af8de640 119491ms [I6] {27151} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x5601af8ded00) Found feature 0x3 (TCP NODELAY) 119491ms [I6] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8deea0,sasl) Destroying. PND=0,ENT=1,SORC=1 119491ms [I6] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8e7300,unknown) Pairing with SOCK=0x5601af8de640 119492ms [I6] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8e7300,bc_cccp) Destroying. PND=0,ENT=1,SORC=1 119492ms [I6] {27151} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Placing socket back into the pool. I=0x5601af8de540,C=0x5601af8de640 119492ms [I6] {27151} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP 119492ms [I6] {27151} [DEBUG] (bootstrap - L:56) Instance configured! 119492ms [I6] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 119492ms [I6] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED (1) [couchbase] = ok (1) } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) = ok (1) [ok] = ok (1) } # accounting = ok (1) Sent Accounting-Response Id 207 from 127.0.0.1:1813 to 127.0.0.1:36802 length 0 (1) Finished request (1) Cleaning up request packet ID 207 with timestamp +119 Ready to process requests Received Accounting-Response Id 207 from 127.0.0.1:1813 to 0.0.0.0:0 length 20