Sending accounting and interim usage to couchbase.
Mike Lopes
mlopes at teksavvy.ca
Mon Jan 22 15:08:36 CET 2018
> 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 at 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 at 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 at domain.com
(0) Stripped-User-Name := noneexistent123 at 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 at 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 at 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 at 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 at 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 at domain.com
(1) Stripped-User-Name := noneexistent123 at 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 at 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
More information about the Freeradius-Users
mailing list