rlm_couchbase skipping attribute with no map entry

19 Dec 2017

      Hi,

I am trying to set up a new freeradius server (v3.0.15) so that it will send directly to a couchbase server instead of my current old radius server setup that is sending accounting via a radius-proxy server.

Any help would be appreciated in trying to figure this out.

I have enabled the following environment settings:

LCB_OPTIONS="detailed_errcodes=1" && export LCB_OPTIONS
LCB_CNTL_DETAILED_ERRCODES=1 && export LCB_CNTL_DETAILED_ERRCODES
LCB_LOGLEVEL=5 && export LCB_LOGLEVEL

Here is the trimmed output from radius -X:

(0) Received Accounting-Request Id 65 from 127.0.0.1:55005 to 127.0.0.1:1813 length 715
(0)   User-Name = "noneexistent123@domain.com"
(0)   Acct-Status-Type = Interim-Update
(0)   Acct-Session-Id = "25466609"
(0)   Acct-Input-Octets = 211016095
(0)   Acct-Output-Octets = 3081069646
(0)   Acct-Session-Time = 2047177
(0)   Acct-Input-Packets = 179269685
(0)   Acct-Output-Packets = 322301129
(0)   Service-Type = Framed-User
(0)   Framed-Protocol = PPP
(0)   Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in"
(0)   Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out"
(0)   Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b
(0)   Tunnel-Type:0 = L2TP
(0)   Tunnel-Medium-Type:0 = IPv4
(0)   Tunnel-Client-Endpoint:0 = "192.168.242.189"
(0)   Tunnel-Server-Endpoint:0 = "192.168.80.106"
(0)   Tunnel-Assignment-Id:0 = "57524"
(0)   Tunnel-Client-Auth-Id:0 = "AR09"
(0)   Tunnel-Server-Auth-Id:0 = "company"
(0)   Acct-Tunnel-Connection = "0002758216"
(0)   Acct-Authentic = RADIUS
(0)   Acct-Delay-Time = 0
(0)   Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe 4c:9e:ff:27:41:4c#"
(0)   ERX-Dhcp-Mac-Addr = "0000.0000.0000"
(0)   Event-Timestamp = "Dec 12 2017 11:35:30 EST"
(0)   Framed-IP-Address = 192.168.225.42
(0)   Framed-IP-Netmask = 255.255.254.0
(0)   ERX-Input-Gigapkts = 0
(0)   Acct-Input-Gigawords = 4
(0)   NAS-Identifier = "lns01"
(0)   NAS-Port = 268439551
(0)   NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216"
(0)   NAS-Port-Type = Virtual
(0)   ERX-Output-Gigapkts = 0
(0)   Acct-Output-Gigawords = 103
(0)   ERX-IPv6-Acct-Input-Octets = 0
(0)   ERX-IPv6-Acct-Output-Octets = 0
(0)   ERX-IPv6-Acct-Input-Packets = 0
(0)   ERX-IPv6-Acct-Output-Packets = 0
(0)   ERX-IPv6-Acct-Input-Gigawords = 0
(0)   ERX-IPv6-Acct-Output-Gigawords = 0
(0)   ERX-Tx-Connect-Speed = 13277755
(0)   Attr-26.4874.163 = 0x000000
(0)   ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00"
(0)   NAS-IP-Address = 192.168.191.4
(0) # Executing section preacct from file /etc/raddb/sites-enabled/company
(0)   preacct {
(0)     policy username_lower_domain {
(0)       update request {
(0)         EXPAND %{tolower:%{User-Name}}
(0)            --> noneexistent123@company.com
(0)         Stripped-User-Name := noneexistent123@company.com
(0)       } # update request = noop
(0)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\\.[-[:alnum:].]+))?$/){
(0)       if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\\.[-[:alnum:].]+))?$/) -> FALSE
(0)       else {
(0)         [noop] = noop
(0)       } # else = noop
(0)     } # policy username_lower_domain = noop
(0)     policy acct_counters64_preacct {
(0)       update request {
(0)         EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}}
(0)            --> 17390885279
(0)         Acct-Input-Octets64 = 17390885279
(0)         EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}}
(0)            --> 445462701134
(0)         Acct-Output-Octets64 = 445462701134
(0)       } # update request = noop
(0)     } # policy acct_counters64_preacct = noop
(0)     policy acct_unique {
(0)       update request {
(0)         EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}}
(0)            --> 51dc686492632c94c03d1346eb471bf5
(0)         Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5
(0)       } # update request = noop
(0)     } # policy acct_unique = noop
(0)     if (NAS-Port-Id =~ /:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) {
(0)     if (NAS-Port-Id =~ /:([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}):/)  -> TRUE
(0)     if (NAS-Port-Id =~ /:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/)  {
(0)       update request {
(0)         EXPAND %{1}
(0)            --> 192.168.80.106
(0)         NAS-Port-Id := 192.168.80.106
(0)         EXPAND %{2}
(0)            --> 192.168.242.189
(0)         NAS-Identifier := 192.168.242.189
(0)       } # update request = noop
(0)     } # if (NAS-Port-Id =~ /:([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}):/)  = noop
(0)   } # preacct = noop
(0) # Executing section accounting from file /etc/raddb/sites-enabled/company
(0)   accounting {
rlm_couchbase (couchtsi): Reserved connection (0)
(0) couchtsi: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}
(0) couchtsi:    --> radacct_51dc686492632c94c03d1346eb471bf5
32450ms [I0] {32348} [INFO] (lcbio_mgr - L:410) <10.0.2.207:11210> (HE=0x5652b23dde40) Found ready connection in pool. Reusing socket and not creating new connection
32450ms [I0] {32348} [TRACE] (bootstrap - L:143) Background-polling for new configuration
32450ms [I0] {32348} [TRACE] (confmon - L:272) Refreshing current cluster map
32450ms [I0] {32348} [DEBUG] (lcbio_mgr - L:247) <10.0.2.207:11210> (HE=0x5652b23dde40) Assigning R=0x5652b2445930 SOCKET=0x5652b23df380
32450ms [I0] {32348} [DEBUG] (ioctx - L:99) <10.0.2.207:11210> (CTX=0x5652b26410d0,unknown) Pairing with SOCK=0x5652b23df380
32450ms [I0] {32348} [TRACE] (confmon - L:259) Attempting to retrieve cluster map via CCCP
32450ms [I0] {32348} [TRACE] (cccp - L:144) Re-Issuing CCCP Command on server struct 0x5652b23ebaf0 (10.0.2.207:11210)
rlm_couchbase: (get_callback) got 93 bytes
32451ms [I0] {32348} [TRACE] (confmon - L:150) Not applying configuration received via CCCP. No changes detected. A.rev=25, B.rev=25
rlm_couchbase: skipping attribute with no map entry - User-Name
rlm_couchbase: skipping attribute with no map entry - Acct-Status-Type
rlm_couchbase: skipping attribute with no map entry - Acct-Session-Id
rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets
rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets
rlm_couchbase: skipping attribute with no map entry - Acct-Session-Time
rlm_couchbase: skipping attribute with no map entry - Acct-Input-Packets
rlm_couchbase: skipping attribute with no map entry - Acct-Output-Packets
rlm_couchbase: skipping attribute with no map entry - Service-Type
rlm_couchbase: skipping attribute with no map entry - Framed-Protocol
rlm_couchbase: skipping attribute with no map entry - Filter-Id
rlm_couchbase: skipping attribute with no map entry - Filter-Id
rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.177
rlm_couchbase: skipping attribute with no map entry - Tunnel-Type
rlm_couchbase: skipping attribute with no map entry - Tunnel-Medium-Type
rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Endpoint
rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Endpoint
rlm_couchbase: skipping attribute with no map entry - Tunnel-Assignment-Id
rlm_couchbase: skipping attribute with no map entry - Tunnel-Client-Auth-Id
rlm_couchbase: skipping attribute with no map entry - Tunnel-Server-Auth-Id
rlm_couchbase: skipping attribute with no map entry - Acct-Tunnel-Connection
rlm_couchbase: skipping attribute with no map entry - Acct-Authentic
rlm_couchbase: skipping attribute with no map entry - Acct-Delay-Time
rlm_couchbase: skipping attribute with no map entry - Calling-Station-Id
rlm_couchbase: skipping attribute with no map entry - ERX-Dhcp-Mac-Addr
rlm_couchbase: skipping attribute with no map entry - Event-Timestamp
rlm_couchbase: skipping attribute with no map entry - Framed-IP-Address
rlm_couchbase: skipping attribute with no map entry - Framed-IP-Netmask
rlm_couchbase: skipping attribute with no map entry - ERX-Input-Gigapkts
rlm_couchbase: skipping attribute with no map entry - Acct-Input-Gigawords
rlm_couchbase: skipping attribute with no map entry - NAS-Identifier
rlm_couchbase: skipping attribute with no map entry - NAS-Port
rlm_couchbase: skipping attribute with no map entry - NAS-Port-Id
rlm_couchbase: skipping attribute with no map entry - NAS-Port-Type
rlm_couchbase: skipping attribute with no map entry - ERX-Output-Gigapkts
rlm_couchbase: skipping attribute with no map entry - Acct-Output-Gigawords
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Octets
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Octets
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Packets
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Packets
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Input-Gigawords
rlm_couchbase: skipping attribute with no map entry - ERX-IPv6-Acct-Output-Gigawords
rlm_couchbase: skipping attribute with no map entry - ERX-Tx-Connect-Speed
rlm_couchbase: skipping attribute with no map entry - Attr-26.4874.163
rlm_couchbase: skipping attribute with no map entry - ERX-Pppoe-Description
rlm_couchbase: skipping attribute with no map entry - NAS-IP-Address
rlm_couchbase: skipping attribute with no map entry - Stripped-User-Name
rlm_couchbase: skipping attribute with no map entry - Acct-Input-Octets64
rlm_couchbase: skipping attribute with no map entry - Acct-Output-Octets64
rlm_couchbase: skipping attribute with no map entry - Acct-Unique-Session-Id
rlm_couchbase (couchtsi): Released connection (0)
Need 10 more connections to reach 15 spares
rlm_couchbase (couchtsi): Opening additional connection (5), 1 of 15 pending slots used
32452ms [I15] {32348} [INFO] (instance - L:423) Version=2.8.3, Changeset=8ce52f9294cfef59b9ff44f3cfc18cc3ca8c2860
32452ms [I15] {32348} [INFO] (instance - L:424) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius
32452ms [I15] {32348} [DEBUG] (instance - L:284) Applying initial cntl detailed_errcodes=1
32566ms [I15] {32348} [INFO] (instance - L:137) DNS SRV lookup failed: DNS/Hostname lookup failed. Ignore this if not relying on DNS SRV records
32566ms [I15] {32348} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list
32566ms [I15] {32348} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list
32566ms [I15] {32348} [TRACE] (instance - L:117) Bootstrap hosts loaded (cccp:1, http:1)
32566ms [I15] {32348} [DEBUG] (confmon - L:85) Preparing providers (this may be called multiple times)
32566ms [I15] {32348} [DEBUG] (confmon - L:92) Provider CCCP is ENABLED
32566ms [I15] {32348} [DEBUG] (confmon - L:92) Provider HTTP is ENABLED
32566ms [I15] {32348} [TRACE] (confmon - L:272) Refreshing current cluster map
32566ms [I15] {32348} [TRACE] (confmon - L:259) Attempting to retrieve cluster map via CCCP
32566ms [I15] {32348} [INFO] (cccp - L:151) Requesting connection to node 10.0.2.207:11210 for CCCP configuration
32566ms [I15] {32348} [DEBUG] (lcbio_mgr - L:417) <10.0.2.207:11210> (HE=0x5652b2657c70) Creating new connection because none are available in the pool
32566ms [I15] {32348} [TRACE] (lcbio_mgr - L:328) <10.0.2.207:11210> (HE=0x5652b2657c70) New pool entry: I=0x5652b2658ed0
32566ms [I15] {32348} [INFO] (connection - L:467) <10.0.2.207:11210> (SOCK=0x5652b2659070) Starting. Timeout=2000000us
32566ms [I15] {32348} [DEBUG] (connection - L:232) <10.0.2.207:11210> (SOCK=0x5652b2659070) Created new socket with FD=25
32566ms [I15] {32348} [TRACE] (connection - L:333) <10.0.2.207:11210> (SOCK=0x5652b2659070) Scheduling I/O watcher for asynchronous connection completion.
32567ms [I15] {32348} [INFO] (connection - L:141) <10.0.2.207:11210> (SOCK=0x5652b2659070) Connected established
32567ms [I15] {32348} [DEBUG] (connection - L:100) <10.0.2.207:11210> (SOCK=0x5652b2659070) Successfully set TCP_NODELAY
32567ms [I15] {32348} [DEBUG] (connection - L:100) <10.0.2.207:11210> (SOCK=0x5652b2659070) Successfully set TCP_KEEPALIVE
32567ms [I15] {32348} [DEBUG] (lcbio_mgr - L:287) <10.0.2.207:11210> (HE=0x5652b2657c70) Received result for I=0x5652b2658ed0,C=(nil); E=0x0
32567ms [I15] {32348} [DEBUG] (lcbio_mgr - L:247) <10.0.2.207:11210> (HE=0x5652b2657c70) Assigning R=0x5652b2657d20 SOCKET=0x5652b2659070
32567ms [I15] {32348} [DEBUG] (ioctx - L:99) <10.0.2.207:11210> (CTX=0x5652b2659870,unknown) Pairing with SOCK=0x5652b2659070
32567ms [I15] {32348} [DEBUG] (negotiation - L:390) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) HELLO identificator: "libcouchbase/2.8.3"
32567ms [I15] {32348} [DEBUG] (negotiation - L:394) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Request feature: 0x2 (TLS)
32567ms [I15] {32348} [DEBUG] (negotiation - L:394) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Request feature: 0x6 (XATTR)
32567ms [I15] {32348} [DEBUG] (negotiation - L:394) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Request feature: 0x8 (Select Bucket)
32567ms [I15] {32348} [DEBUG] (negotiation - L:394) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Request feature: 0x7 (Error Map)
32567ms [I15] {32348} [DEBUG] (negotiation - L:394) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Request feature: 0x3 (TCP NODELAY)
32567ms [I15] {32348} [DEBUG] (negotiation - L:420) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) Server supports feature: 0x3 (TCP NODELAY)
32567ms [I15] {32348} [TRACE] (negotiation - L:565) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl,SASLREQ=0x5652b2659690) GET_ERRORMAP unsupported/disabled
32568ms [I15] {32348} [DEBUG] (ioctx - L:149) <10.0.2.207:11210> (CTX=0x5652b2659870,sasl) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
32568ms [I15] {32348} [DEBUG] (ioctx - L:99) <10.0.2.207:11210> (CTX=0x5652b2661d80,unknown) Pairing with SOCK=0x5652b2659070
32568ms [I15] {32348} [DEBUG] (ioctx - L:149) <10.0.2.207:11210> (CTX=0x5652b2661d80,bc_cccp) Destroying context. Pending Writes=0, Entered=true, Socket Refcount=1
32568ms [I15] {32348} [INFO] (lcbio_mgr - L:467) <10.0.2.207:11210> (HE=0x5652b2657c70) Placing socket back into the pool. I=0x5652b2658ed0,C=0x5652b2659070
32569ms [I15] {32348} [INFO] (confmon - L:158) Setting new configuration. Received via CCCP
32569ms [I15] {32348} [DEBUG] (bootstrap - L:56) Instance configured
32569ms [I15] {32348} [DEBUG] (confmon - L:85) Preparing providers (this may be called multiple times)
32569ms [I15] {32348} [DEBUG] (confmon - L:92) Provider CCCP is ENABLED
(0)     [couchtsi] = ok
(0)     [ok] = ok
(0)   } # accounting = ok
(0) Sent Accounting-Response Id 65 from 127.0.0.1:1813 to 127.0.0.1:55005 length 0
(0) Finished request
(0) Cleaning up request packet ID 65 with timestamp +31
Ready to process requests

**************************************************

cat /etc/raddb/mods-enabled/couchbase
couchbase {
        server = "http://10.0.2.207:8091/pools"

        bucket = "radius"

        password = "PasswordString"

        acct_key = "radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}}"

        doctype = "radacct"

        expire = 2592000

        update {
                sessionId = 'Acct-Session-Id'
                uniqueId = 'Acct-Unique-Session-Id'
                lastStatus = 'Acct-Status-Type'
                userName = 'User-Name'
                lowercaseUser = 'Stripped-User-Name'
                userDomain = 'Stripped-User-Domain'
                nasIpAddress = 'NAS-IP-Address'
                nasIdentifier = 'NAS-Identifier'
                nasPort = 'NAS-Port-Id'
                calledStationId = 'Called-Station-Id'
                callingStationId = 'Calling-Station-Id'
                framedIpAddress = 'Framed-IP-Address'
                framedRoute = 'Framed-Route'
                framedIpv6Address = 'Framed-IPv6-Prefix'
                framedIpv6Id = 'Framed-Interface-Id'
                framedV6Route = 'Delegated-IPv6-Prefix'
                multiSessionId = 'Acct-Multi-Session-Id'
                multiSessionCount = 'Acct-Link-Count'
                TerminateCause = 'Acct-Terminate-Cause'
                sessionTime = 'Acct-Session-Time'
                lastUpdated = 'Event-Timestamp'
        }

        usage {
                lastStatus = 'Acct-Status-Type'
                timeStamp = 'Event-Timestamp'
                download = 'Acct-Output-Octets64'
                upload = 'Acct-Input-Octets64'
        }

        user_key = "raduser_%{md5:%{tolower:%{%{Stripped-User-Name}:-%{User-Name}}}}"

        pool {
                start = 5
                min = 5
                max = 20
                spare = 15
                uses = 0
                lifetime = 0
                idle_timeout = 1200
        }
}

Thanks.

-Mike

rlm_couchbase skipping attribute with no map entry

Mike Lopes