Sending accounting and interim usage to couchbase.
Mike Lopes
mlopes at teksavvy.ca
Mon Jan 22 17:24:04 CET 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 at 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 at 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 at domain.com
Mon Jan 22 10:56:36 2018 : Debug: (1) &Stripped-User-Name := noneexistent123 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at domain.com
Mon Jan 22 10:56:46 2018 : Debug: (2) &Stripped-User-Name := noneexistent123 at 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 at 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 at 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 at 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 at 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 at 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
More information about the Freeradius-Users
mailing list