RE: Sending accounting and interim usage to couchbase.

22 Jan 2018


      ...
...
rlm_couchbase (couchbase): Released connection (0)
...
That's weird.
...
Try running "radiusd -Xx".  This is one of the few times where more information may be useful.  It *should* print out what attributes it's converting to json, along with the final document it's writing to couch base.
Beware wall of text.  Also, I left all the all the info from the packet, meaning it contains a lot more stuff that I usually do not need to send to couchbase. 

Sent Accounting-Request Id 106 from 0.0.0.0:42535 to 127.0.0.1:1813 length 715
Mon Jan 22 10:56:36 2018 : Debug: (1) Received Accounting-Request Id 106 from 127.0.0.1:42535 to 127.0.0.1:1813 length 715
Mon Jan 22 10:56:36 2018 : Debug: (1)   User-Name = "noneexistent123@domain.com"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Status-Type = Interim-Update
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Session-Id = "25466609"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Input-Octets = 211016095
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Output-Octets = 3081069646
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Session-Time = 2047177
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Input-Packets = 179269685
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Output-Packets = 322301129
Mon Jan 22 10:56:36 2018 : Debug: (1)   Service-Type = Framed-User
Mon Jan 22 10:56:36 2018 : Debug: (1)   Framed-Protocol = PPP
Mon Jan 22 10:56:36 2018 : Debug: (1)   Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Type:0 = L2TP
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Medium-Type:0 = IPv4
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Client-Endpoint:0 = "192.168.242.189"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Server-Endpoint:0 = "192.168.80.106"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Assignment-Id:0 = "57524"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Client-Auth-Id:0 = "AB99AR99"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Tunnel-Server-Auth-Id:0 = "domain"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Tunnel-Connection = "0002758216"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Authentic = RADIUS
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Delay-Time = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#"
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-Dhcp-Mac-Addr = "0000.0000.0000"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Event-Timestamp = "Dec 12 2017 11:35:30 EST"
Mon Jan 22 10:56:36 2018 : Debug: (1)   Framed-IP-Address = 192.168.225.42
Mon Jan 22 10:56:36 2018 : Debug: (1)   Framed-IP-Netmask = 255.255.254.0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-Input-Gigapkts = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Input-Gigawords = 4
Mon Jan 22 10:56:36 2018 : Debug: (1)   NAS-Identifier = "lns01.lan"
Mon Jan 22 10:56:36 2018 : Debug: (1)   NAS-Port = 268439551
Mon Jan 22 10:56:36 2018 : Debug: (1)   NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216"
Mon Jan 22 10:56:36 2018 : Debug: (1)   NAS-Port-Type = Virtual
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-Output-Gigapkts = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   Acct-Output-Gigawords = 103
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Input-Octets = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Output-Octets = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Input-Packets = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Output-Packets = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Input-Gigawords = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-IPv6-Acct-Output-Gigawords = 0
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-Tx-Connect-Speed = 13277755
Mon Jan 22 10:56:36 2018 : Debug: (1)   Attr-26.4874.163 = 0x000000
Mon Jan 22 10:56:36 2018 : Debug: (1)   ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00"
Mon Jan 22 10:56:36 2018 : Debug: (1)   NAS-IP-Address = 192.168.191.4
Mon Jan 22 10:56:36 2018 : Debug: (1) # Executing section preacct from file /etc/raddb/sites-enabled/domain
Mon Jan 22 10:56:36 2018 : Debug: (1)   preacct {
Mon Jan 22 10:56:36 2018 : Debug: (1)     modsingle[preacct]: calling suffix (rlm_realm)
Mon Jan 22 10:56:36 2018 : Debug: (1) suffix: Checking for suffix after "@"
Mon Jan 22 10:56:36 2018 : Debug: (1) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com"
Mon Jan 22 10:56:36 2018 : Debug: (1) suffix: No such realm "domain.com"
Mon Jan 22 10:56:36 2018 : Debug: (1)     modsingle[preacct]: returned from suffix (rlm_realm)
Mon Jan 22 10:56:36 2018 : Debug: (1)     [suffix] = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)     policy username_lower_domain {
Mon Jan 22 10:56:36 2018 : Debug: (1)       update request {
Mon Jan 22 10:56:36 2018 : Debug: (1)         EXPAND %{tolower:%{User-Name}}
Mon Jan 22 10:56:36 2018 : Debug: (1)            --> noneexistent123@domain.com
Mon Jan 22 10:56:36 2018 : Debug: (1)         &Stripped-User-Name := noneexistent123@domain.com
Mon Jan 22 10:56:36 2018 : Debug: (1)       } # update request = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){
Mon Jan 22 10:56:36 2018 : Debug: (1)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE
Mon Jan 22 10:56:36 2018 : Debug: (1)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) {
Mon Jan 22 10:56:36 2018 : Debug: (1)         update request {
Mon Jan 22 10:56:36 2018 : Debug: (1)           EXPAND %{tolower:%{3}}
Mon Jan 22 10:56:36 2018 : Debug: (1)              --> domain.com
Mon Jan 22 10:56:36 2018 : Debug: (1)           &Stripped-User-Domain = domain.com
Mon Jan 22 10:56:36 2018 : Debug: (1)         } # update request = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)         modsingle[preacct]: calling updated (rlm_always)
Mon Jan 22 10:56:36 2018 : Debug: (1)         modsingle[preacct]: returned from updated (rlm_always)
Mon Jan 22 10:56:36 2018 : Debug: (1)         [updated] = updated
Mon Jan 22 10:56:36 2018 : Debug: (1)       } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated
Mon Jan 22 10:56:36 2018 : Debug: (1)       ... skipping else: Preceding "if" was taken
Mon Jan 22 10:56:36 2018 : Debug: (1)     } # policy username_lower_domain = updated
Mon Jan 22 10:56:36 2018 : Debug: (1)     policy acct_counters64_preacct {
Mon Jan 22 10:56:36 2018 : Debug: (1)       update request {
Mon Jan 22 10:56:36 2018 : Debug: (1)         EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}}
Mon Jan 22 10:56:36 2018 : Debug: (1)            --> 17390885279
Mon Jan 22 10:56:36 2018 : Debug: (1)         &Acct-Input-Octets64 = 17390885279
Mon Jan 22 10:56:36 2018 : Debug: (1)         EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}}
Mon Jan 22 10:56:36 2018 : Debug: (1)            --> 445462701134
Mon Jan 22 10:56:36 2018 : Debug: (1)         &Acct-Output-Octets64 = 445462701134
Mon Jan 22 10:56:36 2018 : Debug: (1)       } # update request = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)     } # policy acct_counters64_preacct = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)     policy acct_unique {
Mon Jan 22 10:56:36 2018 : Debug: (1)       update request {
Mon Jan 22 10:56:36 2018 : Debug: (1)         EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}}
Mon Jan 22 10:56:36 2018 : Debug: (1)            --> 51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:36 2018 : Debug: (1)         &Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:36 2018 : Debug: (1)       } # update request = noop
Mon Jan 22 10:56:36 2018 : Debug: (1)     } # policy acct_unique = noop
Mon Jan 22 10:56:36 2018 : Debug: (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}):/) {
Mon Jan 22 10:56:36 2018 : Debug: (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
Mon Jan 22 10:56:36 2018 : Debug: (1)   } # preacct = updated
Mon Jan 22 10:56:36 2018 : Debug: (1) # Executing section accounting from file /etc/raddb/sites-enabled/domain
Mon Jan 22 10:56:36 2018 : Debug: (1)   accounting {
Mon Jan 22 10:56:36 2018 : Debug: (1)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) {
Mon Jan 22 10:56:36 2018 : Debug: (1)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  -> TRUE
Mon Jan 22 10:56:36 2018 : Debug: (1)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  {
Mon Jan 22 10:56:36 2018 : Debug: (1)       modsingle[accounting]: calling linelog-domain-acct (rlm_linelog)
Mon Jan 22 10:56:36 2018 : Debug: messages.%{Acct-Status-Type}
Mon Jan 22 10:56:36 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:36 2018 : Debug: literal --> messages.
Mon Jan 22 10:56:36 2018 : Debug: attribute --> Acct-Status-Type
Mon Jan 22 10:56:36 2018 : Debug: (1) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type}
Mon Jan 22 10:56:36 2018 : Debug: (1) linelog-domain-acct:    --> messages.Interim-Update
Mon Jan 22 10:56:36 2018 : Debug: '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}'
Mon Jan 22 10:56:36 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:36 2018 : Debug: literal --> 'Interim-Update''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> Acct-Session-Id
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> User-Name
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> NAS-IP-Address
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: percent --> S
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> Acct-Session-Time
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Input-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:36 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Output-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:36 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Input-Octets
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:36 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Output-Octets
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:36 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> Calling-Station-Id
Mon Jan 22 10:56:36 2018 : Debug: literal --> ''
Mon Jan 22 10:56:36 2018 : Debug: attribute --> Framed-IP-Address
Mon Jan 22 10:56:36 2018 : Debug: literal --> '
Mon Jan 22 10:56:36 2018 : Debug: (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}'
Mon Jan 22 10:56:36 2018 : Debug: (1) linelog-domain-acct:    --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 10:56:36''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42'
Mon Jan 22 10:56:36 2018 : Debug: /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:36 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:36 2018 : Debug: literal --> /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:36 2018 : Debug: (1) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:36 2018 : Debug: (1) linelog-domain-acct:    --> /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:36 2018 : Debug: (1)       modsingle[accounting]: returned from linelog-domain-acct (rlm_linelog)
Mon Jan 22 10:56:36 2018 : Debug: (1)       [linelog-domain-acct] = ok
Mon Jan 22 10:56:36 2018 : Debug: (1)       modsingle[accounting]: calling couchbase (rlm_couchbase)
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase (couchbase): Reserved connection (1)
Mon Jan 22 10:56:36 2018 : Debug: radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}
Mon Jan 22 10:56:36 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:36 2018 : Debug: literal --> radacct_
Mon Jan 22 10:56:36 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Unique-Session-Id
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:36 2018 : Debug:       attribute --> Acct-Session-Id
Mon Jan 22 10:56:36 2018 : Debug: }
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase:    --> radacct_51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: fetching document radacct_51dc686492632c94c03d1346eb471bf5
106137ms [I1] {28498} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x561c892bc6d0) Found ready connection in pool. Reusing socket and not creating new connection
106137ms [I1] {28498} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x561c892bc6d0) Assigning R=0x561c892b5010 SOCKET=0x561c892bcca0
106137ms [I1] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894b6150,unknown) Pairing with SOCK=0x561c892bcca0
106137ms [I1] {28498} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x561c892b5550,IX=0) Setting initial timeout=2499ms
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: (get_callback) key does not exist
Mon Jan 22 10:56:36 2018 : ERROR: (1) couchbase: failed to execute get request or parse returned json object
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: no existing document found - creating new json document
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: calculated start timestamp: Nov 18 2017 18:55:53 EST
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute User-Name => userName
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'User-Name' as string
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Acct-Status-Type => lastStatus
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: creating new int64 for unsigned 32 bit int/byte/short 'Acct-Status-Type'
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Acct-Session-Id => sessionId
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Acct-Session-Id' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Acct-Session-Time => sessionTime
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: creating new int64 for unsigned 32 bit int/byte/short 'Acct-Session-Time'
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Packets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Packets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Service-Type
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Framed-Protocol
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Filter-Id
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Filter-Id
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.177
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Type
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Medium-Type
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Endpoint
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Endpoint
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Assignment-Id
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Auth-Id
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Auth-Id
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Tunnel-Connection
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Authentic
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Delay-Time
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Calling-Station-Id => callingStationId
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Calling-Station-Id' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Dhcp-Mac-Addr
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Event-Timestamp => lastUpdated
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning unhandled 'Event-Timestamp' as string
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Framed-IP-Address => framedIpAddress
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning unhandled 'Framed-IP-Address' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Framed-IP-Netmask
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Input-Gigapkts
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute NAS-Identifier => nasIdentifier
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'NAS-Identifier' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - NAS-Port
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute NAS-Port-Id => nasPort
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'NAS-Port-Id' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - NAS-Port-Type
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Output-Gigapkts
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Octets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Octets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Packets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Packets
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Gigawords
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Tx-Connect-Speed
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.163
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Pppoe-Description
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute NAS-IP-Address => nasIpAddress
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning unhandled 'NAS-IP-Address' as string
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Stripped-User-Name => lowercaseUser
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Stripped-User-Name' as string
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Stripped-User-Domain => userDomain
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Stripped-User-Domain' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets64
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets64
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: mapped attribute Acct-Unique-Session-Id => uniqueId
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Acct-Unique-Session-Id' as string
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Module-Failure-Message
Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: setting 'radacct_51dc686492632c94c03d1346eb471bf5' => '{ "docType": "clientacct", "startTimestamp": "Nov 18 2017 18:55:53 EST", "stopTimestamp": null, "userName": "noneexistent123@domain.com", "lastStatus": 3, "sessionId": "25466609", "sessionTime": 2047177, "callingStationId": "GigabitEthernet 1\/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#", "lastUpdated": "Dec 12 2017 11:35:30 EST", "framedIpAddress": "192.168.225.42", "nasIdentifier": "lns01.lan", "nasPort": "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216", "nasIpAddress": "192.168.191.4", "lowercaseUser": "noneexistent123@domain.com", "userDomain": "domain.com", "uniqueId": "51dc686492632c94c03d1346eb471bf5" }'
Mon Jan 22 10:56:36 2018 : Debug: rlm_couchbase (couchbase): Released connection (1)
Mon Jan 22 10:56:36 2018 : Info: Need 2 more connections to reach min connections (8)
Mon Jan 22 10:56:36 2018 : Info: rlm_couchbase (couchbase): Opening additional connection (6), 1 of 122 pending slots used
106138ms [I6] {28498} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798
106138ms [I6] {28498} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius
106138ms [I6] {28498} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1
106138ms [I6] {28498} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list
106139ms [I6] {28498} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list
106253ms [I6] {28498} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed
106253ms [I6] {28498} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times)
106253ms [I6] {28498} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED
106253ms [I6] {28498} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED
106253ms [I6] {28498} [TRACE] (confmon - L:252) Start refresh requested
106253ms [I6] {28498} [TRACE] (confmon - L:239) Current provider is CCCP
106253ms [I6] {28498} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration
106253ms [I6] {28498} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x561c894e1ee0) Creating new connection because none are available in the pool
106253ms [I6] {28498} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x561c894e1ee0) Starting connection on I=0x561c894d4380
106253ms [I6] {28498} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Starting. Timeout=2000000us
106253ms [I6] {28498} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Got event handler for new connection
106253ms [I6] {28498} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Scheduling asynchronous watch for socket.
106253ms [I6] {28498} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Got event handler for new connection
106254ms [I6] {28498} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Connected
106254ms [I6] {28498} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x561c894d7ba0) Successfuly set TCP_NODELAY
106254ms [I6] {28498} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x561c894e1ee0) Received result for I=0x561c894d4380,C=0x561c894d7ba0; E=0x0
106254ms [I6] {28498} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x561c894e1ee0) Assigning R=0x561c894d4580 SOCKET=0x561c894d7ba0
106254ms [I6] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894e2a50,unknown) Pairing with SOCK=0x561c894d7ba0
106255ms [I6] {28498} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x561c894e28b0) Found feature 0x3 (TCP NODELAY)
106255ms [I6] {28498} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x561c894e2a50,sasl) Destroying. PND=0,ENT=1,SORC=1
106255ms [I6] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894eae70,unknown) Pairing with SOCK=0x561c894d7ba0
106255ms [I6] {28498} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x561c894eae70,bc_cccp) Destroying. PND=0,ENT=1,SORC=1
106255ms [I6] {28498} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x561c894e1ee0) Placing socket back into the pool. I=0x561c894d4380,C=0x561c894d7ba0
106255ms [I6] {28498} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP
106255ms [I6] {28498} [DEBUG] (bootstrap - L:56) Instance configured!
106255ms [I6] {28498} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times)
106255ms [I6] {28498} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED
Mon Jan 22 10:56:36 2018 : Debug: (1)       modsingle[accounting]: returned from couchbase (rlm_couchbase)
Mon Jan 22 10:56:36 2018 : Debug: (1)       [couchbase] = ok
Mon Jan 22 10:56:36 2018 : Debug: (1)     } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  = ok
Mon Jan 22 10:56:36 2018 : Debug: (1)     modsingle[accounting]: calling ok (rlm_always)
Mon Jan 22 10:56:36 2018 : Debug: (1)     modsingle[accounting]: returned from ok (rlm_always)
Mon Jan 22 10:56:36 2018 : Debug: (1)     [ok] = ok
Mon Jan 22 10:56:36 2018 : Debug: (1)   } # accounting = ok
Mon Jan 22 10:56:36 2018 : Debug: (1) Sent Accounting-Response Id 106 from 127.0.0.1:1813 to 127.0.0.1:42535 length 0
Mon Jan 22 10:56:36 2018 : Debug: (1) Finished request
Mon Jan 22 10:56:36 2018 : Debug: (1) Cleaning up request packet ID 106 with timestamp +106
Mon Jan 22 10:56:36 2018 : Info: Ready to process requests
Received Accounting-Response Id 106 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 53 from 0.0.0.0:33142 to 127.0.0.1:1813 length 715
Mon Jan 22 10:56:46 2018 : Debug: (2) Received Accounting-Request Id 53 from 127.0.0.1:33142 to 127.0.0.1:1813 length 715
Mon Jan 22 10:56:46 2018 : Debug: (2)   User-Name = "noneexistent123@domain.com"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Status-Type = Interim-Update
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Session-Id = "25466609"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Input-Octets = 211016095
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Output-Octets = 3081069646
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Session-Time = 2047177
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Input-Packets = 179269685
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Output-Packets = 322301129
Mon Jan 22 10:56:46 2018 : Debug: (2)   Service-Type = Framed-User
Mon Jan 22 10:56:46 2018 : Debug: (2)   Framed-Protocol = PPP
Mon Jan 22 10:56:46 2018 : Debug: (2)   Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Type:0 = L2TP
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Medium-Type:0 = IPv4
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Client-Endpoint:0 = "192.168.242.189"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Server-Endpoint:0 = "192.168.80.106"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Assignment-Id:0 = "57524"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Client-Auth-Id:0 = "AB99AR99"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Tunnel-Server-Auth-Id:0 = "domain"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Tunnel-Connection = "0002758216"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Authentic = RADIUS
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Delay-Time = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#"
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-Dhcp-Mac-Addr = "0000.0000.0000"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Event-Timestamp = "Dec 12 2017 11:35:30 EST"
Mon Jan 22 10:56:46 2018 : Debug: (2)   Framed-IP-Address = 192.168.225.42
Mon Jan 22 10:56:46 2018 : Debug: (2)   Framed-IP-Netmask = 255.255.254.0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-Input-Gigapkts = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Input-Gigawords = 4
Mon Jan 22 10:56:46 2018 : Debug: (2)   NAS-Identifier = "lns01.lan"
Mon Jan 22 10:56:46 2018 : Debug: (2)   NAS-Port = 268439551
Mon Jan 22 10:56:46 2018 : Debug: (2)   NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216"
Mon Jan 22 10:56:46 2018 : Debug: (2)   NAS-Port-Type = Virtual
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-Output-Gigapkts = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   Acct-Output-Gigawords = 103
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Input-Octets = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Output-Octets = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Input-Packets = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Output-Packets = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Input-Gigawords = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-IPv6-Acct-Output-Gigawords = 0
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-Tx-Connect-Speed = 13277755
Mon Jan 22 10:56:46 2018 : Debug: (2)   Attr-26.4874.163 = 0x000000
Mon Jan 22 10:56:46 2018 : Debug: (2)   ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00"
Mon Jan 22 10:56:46 2018 : Debug: (2)   NAS-IP-Address = 192.168.191.4
Mon Jan 22 10:56:46 2018 : Debug: (2) # Executing section preacct from file /etc/raddb/sites-enabled/domain
Mon Jan 22 10:56:46 2018 : Debug: (2)   preacct {
Mon Jan 22 10:56:46 2018 : Debug: (2)     modsingle[preacct]: calling suffix (rlm_realm)
Mon Jan 22 10:56:46 2018 : Debug: (2) suffix: Checking for suffix after "@"
Mon Jan 22 10:56:46 2018 : Debug: (2) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com"
Mon Jan 22 10:56:46 2018 : Debug: (2) suffix: No such realm "domain.com"
Mon Jan 22 10:56:46 2018 : Debug: (2)     modsingle[preacct]: returned from suffix (rlm_realm)
Mon Jan 22 10:56:46 2018 : Debug: (2)     [suffix] = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)     policy username_lower_domain {
Mon Jan 22 10:56:46 2018 : Debug: (2)       update request {
Mon Jan 22 10:56:46 2018 : Debug: (2)         EXPAND %{tolower:%{User-Name}}
Mon Jan 22 10:56:46 2018 : Debug: (2)            --> noneexistent123@domain.com
Mon Jan 22 10:56:46 2018 : Debug: (2)         &Stripped-User-Name := noneexistent123@domain.com
Mon Jan 22 10:56:46 2018 : Debug: (2)       } # update request = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){
Mon Jan 22 10:56:46 2018 : Debug: (2)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE
Mon Jan 22 10:56:46 2018 : Debug: (2)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) {
Mon Jan 22 10:56:46 2018 : Debug: (2)         update request {
Mon Jan 22 10:56:46 2018 : Debug: (2)           EXPAND %{tolower:%{3}}
Mon Jan 22 10:56:46 2018 : Debug: (2)              --> domain.com
Mon Jan 22 10:56:46 2018 : Debug: (2)           &Stripped-User-Domain = domain.com
Mon Jan 22 10:56:46 2018 : Debug: (2)         } # update request = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)         modsingle[preacct]: calling updated (rlm_always)
Mon Jan 22 10:56:46 2018 : Debug: (2)         modsingle[preacct]: returned from updated (rlm_always)
Mon Jan 22 10:56:46 2018 : Debug: (2)         [updated] = updated
Mon Jan 22 10:56:46 2018 : Debug: (2)       } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated
Mon Jan 22 10:56:46 2018 : Debug: (2)       ... skipping else: Preceding "if" was taken
Mon Jan 22 10:56:46 2018 : Debug: (2)     } # policy username_lower_domain = updated
Mon Jan 22 10:56:46 2018 : Debug: (2)     policy acct_counters64_preacct {
Mon Jan 22 10:56:46 2018 : Debug: (2)       update request {
Mon Jan 22 10:56:46 2018 : Debug: (2)         EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}}
Mon Jan 22 10:56:46 2018 : Debug: (2)            --> 17390885279
Mon Jan 22 10:56:46 2018 : Debug: (2)         &Acct-Input-Octets64 = 17390885279
Mon Jan 22 10:56:46 2018 : Debug: (2)         EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}}
Mon Jan 22 10:56:46 2018 : Debug: (2)            --> 445462701134
Mon Jan 22 10:56:46 2018 : Debug: (2)         &Acct-Output-Octets64 = 445462701134
Mon Jan 22 10:56:46 2018 : Debug: (2)       } # update request = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)     } # policy acct_counters64_preacct = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)     policy acct_unique {
Mon Jan 22 10:56:46 2018 : Debug: (2)       update request {
Mon Jan 22 10:56:46 2018 : Debug: (2)         EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}}
Mon Jan 22 10:56:46 2018 : Debug: (2)            --> 51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:46 2018 : Debug: (2)         &Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:46 2018 : Debug: (2)       } # update request = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)     } # policy acct_unique = noop
Mon Jan 22 10:56:46 2018 : Debug: (2)     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}):/) {
Mon Jan 22 10:56:46 2018 : Debug: (2)     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
Mon Jan 22 10:56:46 2018 : Debug: (2)   } # preacct = updated
Mon Jan 22 10:56:46 2018 : Debug: (2) # Executing section accounting from file /etc/raddb/sites-enabled/domain
Mon Jan 22 10:56:46 2018 : Debug: (2)   accounting {
Mon Jan 22 10:56:46 2018 : Debug: (2)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) {
Mon Jan 22 10:56:46 2018 : Debug: (2)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  -> TRUE
Mon Jan 22 10:56:46 2018 : Debug: (2)     if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  {
Mon Jan 22 10:56:46 2018 : Debug: (2)       modsingle[accounting]: calling linelog-domain-acct (rlm_linelog)
Mon Jan 22 10:56:46 2018 : Debug: messages.%{Acct-Status-Type}
Mon Jan 22 10:56:46 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:46 2018 : Debug: literal --> messages.
Mon Jan 22 10:56:46 2018 : Debug: attribute --> Acct-Status-Type
Mon Jan 22 10:56:46 2018 : Debug: (2) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type}
Mon Jan 22 10:56:46 2018 : Debug: (2) linelog-domain-acct:    --> messages.Interim-Update
Mon Jan 22 10:56:46 2018 : Debug: '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}'
Mon Jan 22 10:56:46 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:46 2018 : Debug: literal --> 'Interim-Update''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> Acct-Session-Id
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> User-Name
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> NAS-IP-Address
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: percent --> S
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> Acct-Session-Time
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Input-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:46 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Output-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:46 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Input-Octets
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:46 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Output-Octets
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:46 2018 : Debug:       literal --> 0
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> Calling-Station-Id
Mon Jan 22 10:56:46 2018 : Debug: literal --> ''
Mon Jan 22 10:56:46 2018 : Debug: attribute --> Framed-IP-Address
Mon Jan 22 10:56:46 2018 : Debug: literal --> '
Mon Jan 22 10:56:46 2018 : Debug: (2) 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}'
Mon Jan 22 10:56:46 2018 : Debug: (2) linelog-domain-acct:    --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 10:56:46''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42'
Mon Jan 22 10:56:46 2018 : Debug: /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:46 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:46 2018 : Debug: literal --> /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:46 2018 : Debug: (2) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:46 2018 : Debug: (2) linelog-domain-acct:    --> /var/log/radius/radacct/acct.log
Mon Jan 22 10:56:46 2018 : Debug: (2)       modsingle[accounting]: returned from linelog-domain-acct (rlm_linelog)
Mon Jan 22 10:56:46 2018 : Debug: (2)       [linelog-domain-acct] = ok
Mon Jan 22 10:56:46 2018 : Debug: (2)       modsingle[accounting]: calling couchbase (rlm_couchbase)
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase (couchbase): Reserved connection (2)
Mon Jan 22 10:56:46 2018 : Debug: radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}
Mon Jan 22 10:56:46 2018 : Debug: Parsed xlat tree:
Mon Jan 22 10:56:46 2018 : Debug: literal --> radacct_
Mon Jan 22 10:56:46 2018 : Debug: XLAT-IF {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Unique-Session-Id
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: XLAT-ELSE {
Mon Jan 22 10:56:46 2018 : Debug:       attribute --> Acct-Session-Id
Mon Jan 22 10:56:46 2018 : Debug: }
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase:    --> radacct_51dc686492632c94c03d1346eb471bf5
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: fetching document radacct_51dc686492632c94c03d1346eb471bf5
116967ms [I2] {28498} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x561c892b1bb0) Found ready connection in pool. Reusing socket and not creating new connection
116967ms [I2] {28498} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x561c892b1bb0) Assigning R=0x561c894d7bf0 SOCKET=0x561c892b9440
116967ms [I2] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894b5bf0,unknown) Pairing with SOCK=0x561c892b9440
116967ms [I2] {28498} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x561c892b2720,IX=0) Setting initial timeout=2499ms
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: (get_callback) got 651 bytes
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: parsed json body from couchbase: { "docType": "clientacct", "startTimestamp": "Nov 18 2017 18:55:53 EST", "stopTimestamp": null, "userName": "noneexistent123@domain.com", "lastStatus": 3, "sessionId": "25466609", "sessionTime": 2047177, "callingStationId": "GigabitEthernet 1\/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#", "lastUpdated": "Dec 12 2017 11:35:30 EST", "framedIpAddress": "192.168.225.42", "nasIdentifier": "lns01.lan", "nasPort": "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216", "nasIpAddress": "192.168.191.4", "lowercaseUser": "noneexistent123@domain.com", "userDomain": "domain.com", "uniqueId": "51dc686492632c94c03d1346eb471bf5" }
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute User-Name => userName
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'User-Name' as string
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Acct-Status-Type => lastStatus
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: creating new int64 for unsigned 32 bit int/byte/short 'Acct-Status-Type'
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Acct-Session-Id => sessionId
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'Acct-Session-Id' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Acct-Session-Time => sessionTime
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: creating new int64 for unsigned 32 bit int/byte/short 'Acct-Session-Time'
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Packets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Packets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Service-Type
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Framed-Protocol
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Filter-Id
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Filter-Id
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.177
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Type
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Medium-Type
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Endpoint
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Endpoint
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Assignment-Id
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Auth-Id
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Auth-Id
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Tunnel-Connection
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Authentic
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Delay-Time
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Calling-Station-Id => callingStationId
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'Calling-Station-Id' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Dhcp-Mac-Addr
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Event-Timestamp => lastUpdated
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning unhandled 'Event-Timestamp' as string
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Framed-IP-Address => framedIpAddress
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning unhandled 'Framed-IP-Address' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Framed-IP-Netmask
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Input-Gigapkts
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute NAS-Identifier => nasIdentifier
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'NAS-Identifier' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - NAS-Port
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute NAS-Port-Id => nasPort
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'NAS-Port-Id' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - NAS-Port-Type
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Output-Gigapkts
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Octets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Octets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Packets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Packets
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Gigawords
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Tx-Connect-Speed
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.163
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - ERX-Pppoe-Description
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute NAS-IP-Address => nasIpAddress
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning unhandled 'NAS-IP-Address' as string
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Stripped-User-Name => lowercaseUser
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'Stripped-User-Name' as string
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Stripped-User-Domain => userDomain
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'Stripped-User-Domain' as string
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets64
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets64
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: mapped attribute Acct-Unique-Session-Id => uniqueId
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: assigning string 'Acct-Unique-Session-Id' as string
Mon Jan 22 10:56:46 2018 : Debug: (2) couchbase: setting 'radacct_51dc686492632c94c03d1346eb471bf5' => '{ "docType": "clientacct", "startTimestamp": "Nov 18 2017 18:55:53 EST", "stopTimestamp": null, "userName": "noneexistent123@domain.com", "lastStatus": 3, "sessionId": "25466609", "sessionTime": 2047177, "callingStationId": "GigabitEthernet 1\/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#", "lastUpdated": "Dec 12 2017 11:35:30 EST", "framedIpAddress": "192.168.225.42", "nasIdentifier": "lns01.lan", "nasPort": "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216", "nasIpAddress": "192.168.191.4", "lowercaseUser": "noneexistent123@domain.com", "userDomain": "domain.com", "uniqueId": "51dc686492632c94c03d1346eb471bf5" }'
Mon Jan 22 10:56:46 2018 : Debug: rlm_couchbase (couchbase): Released connection (2)
Mon Jan 22 10:56:46 2018 : Info: Need 1 more connections to reach min connections (8)
Mon Jan 22 10:56:46 2018 : Info: rlm_couchbase (couchbase): Opening additional connection (7), 1 of 121 pending slots used
116969ms [I7] {28498} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798
116969ms [I7] {28498} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius
116969ms [I7] {28498} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1
116969ms [I7] {28498} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list
116969ms [I7] {28498} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list
117084ms [I7] {28498} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed
117084ms [I7] {28498} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times)
117084ms [I7] {28498} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED
117084ms [I7] {28498} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED
117084ms [I7] {28498} [TRACE] (confmon - L:252) Start refresh requested
117084ms [I7] {28498} [TRACE] (confmon - L:239) Current provider is CCCP
117084ms [I7] {28498} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration
117084ms [I7] {28498} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x561c894e6db0) Creating new connection because none are available in the pool
117084ms [I7] {28498} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x561c894e6db0) Starting connection on I=0x561c894e7280
117084ms [I7] {28498} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x561c894e7380) Starting. Timeout=2000000us
117084ms [I7] {28498} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x561c894e7380) Got event handler for new connection
117084ms [I7] {28498} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x561c894e7380) Scheduling asynchronous watch for socket.
117084ms [I7] {28498} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x561c894e7380) Got event handler for new connection
117084ms [I7] {28498} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x561c894e7380) Connected
117084ms [I7] {28498} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x561c894e7380) Successfuly set TCP_NODELAY
117084ms [I7] {28498} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x561c894e6db0) Received result for I=0x561c894e7280,C=0x561c894e7380; E=0x0
117084ms [I7] {28498} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x561c894e6db0) Assigning R=0x561c894d4580 SOCKET=0x561c894e7380
117084ms [I7] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894e7be0,unknown) Pairing with SOCK=0x561c894e7380
117085ms [I7] {28498} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x561c894e7a40) Found feature 0x3 (TCP NODELAY)
117085ms [I7] {28498} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x561c894e7be0,sasl) Destroying. PND=0,ENT=1,SORC=1
117085ms [I7] {28498} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x561c894e7ee0,unknown) Pairing with SOCK=0x561c894e7380
117086ms [I7] {28498} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x561c894e7ee0,bc_cccp) Destroying. PND=0,ENT=1,SORC=1
117086ms [I7] {28498} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x561c894e6db0) Placing socket back into the pool. I=0x561c894e7280,C=0x561c894e7380
117086ms [I7] {28498} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP
117086ms [I7] {28498} [DEBUG] (bootstrap - L:56) Instance configured!
117086ms [I7] {28498} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times)
117086ms [I7] {28498} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED
Mon Jan 22 10:56:47 2018 : Debug: (2)       modsingle[accounting]: returned from couchbase (rlm_couchbase)
Mon Jan 22 10:56:47 2018 : Debug: (2)       [couchbase] = ok
Mon Jan 22 10:56:47 2018 : Debug: (2)     } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0)  = ok
Mon Jan 22 10:56:47 2018 : Debug: (2)     modsingle[accounting]: calling ok (rlm_always)
Mon Jan 22 10:56:47 2018 : Debug: (2)     modsingle[accounting]: returned from ok (rlm_always)
Mon Jan 22 10:56:47 2018 : Debug: (2)     [ok] = ok
Mon Jan 22 10:56:47 2018 : Debug: (2)   } # accounting = ok
Mon Jan 22 10:56:47 2018 : Debug: (2) Sent Accounting-Response Id 53 from 127.0.0.1:1813 to 127.0.0.1:33142 length 0
Mon Jan 22 10:56:47 2018 : Debug: (2) Finished request
Mon Jan 22 10:56:47 2018 : Debug: (2) Cleaning up request packet ID 53 with timestamp +116
Mon Jan 22 10:56:47 2018 : Info: Ready to process requests
Received Accounting-Response Id 53 from 127.0.0.1:1813 to 0.0.0.0:0 length 20

RE: Sending accounting and interim usage to couchbase.

Mike Lopes