Sending accounting and interim usage to couchbase.
Hi guys, I've been progressing on the modernisation of our radius infrastructure but I'm stumped, once again. I am trying to migrate configurations from an older Freeradius 3.0.3 to 3.0.15. During this time I discovered that this: # Configuration items are in the format: # <element name> = '<radius attribute>' Was changed to this: # Configuration items are in the format: # <radius attribute> = '<element name>' In mods-available/couchbase.. Thanks to Alan DeKok for pointing that out to me :) But now I am left wondering if some other things changed. I reviewed the changelogs from 3.0.3 to 3.0.15 and couldn't spot anything in regards to my issue with couchbase as well as the change above. In our production setup we have the following in our /etc/raddb/mods-enabled/couchbase: map { 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' } On the new servers, I am using the following: update { Acct-Session-Id = 'sessionId' Acct-Unique-Session-Id = 'uniqueId' Acct-Status-Type = 'lastStatus' User-Name = 'userName' Stripped-User-Name = 'lowercaseUser' Stripped-User-Domain = 'userDomain' NAS-IP-Address = 'nasIpAddress' NAS-Identifier = 'nasIdentifier' NAS-Port-Id = 'nasPort' Called-Station-Id = 'calledStationId' Calling-Station-Id = 'callingStationId' Framed-IP-Address = 'framedIpAddress' Framed-Route = 'framedRoute' Framed-IPv6-Prefix = 'framedIpv6Address' Framed-Interface-Id = 'framedIpv6Id' Delegated-IPv6-Prefix = 'framedV6Route' Acct-Multi-Session-Id = 'multiSessionId' Acct-Link-Count = 'multiSessionCount' Acct-Terminate-Cause = 'TerminateCause' Acct-Session-Time = 'sessionTime' Event-Timestamp = 'lastUpdated' } usage { Acct-Status-Type = 'lastStatus' Event-Timestamp = 'timeStamp' Acct-Output-Octets64 = 'download' Acct-Input-Octets64 = 'upload' Now on my new server, it completely skips over the usage part and I'm no longer getting the interim updates into our couchbase server. I'm assuming that what used to work, no longer works. So it may have moved or remove. Or probably, it I missed something in another file, possibly in mods-config. Could someone point me in the right direction? Thanks! -Mike
On Jan 22, 2018, at 8:33 AM, Mike Lopes <mlopes@teksavvy.ca> wrote: ...
On the new servers, I am using the following: ... usage { Acct-Status-Type = 'lastStatus' Event-Timestamp = 'timeStamp' Acct-Output-Octets64 = 'download' Acct-Input-Octets64 = 'upload'
I don't think that was ever supported. The "usage" block certainly wasn't in the original commit 6ee87931c.
Now on my new server, it completely skips over the usage part and I'm no longer getting the interim updates into our couchbase server. I'm assuming that what used to work, no longer works. So it may have moved or remove. Or probably, it I missed something in another file, possibly in mods-config.
The code in rlm_couchbase.c definitely processes accounting interim-update packets. So what does the debug log show when you receive such a packet? Alan DeKok.
The code in rlm_couchbase.c definitely processes accounting interim-update packets. So what does the debug log show when you receive such a packet?
I knew I forgot something... Here it is, I also enabled couchbase module debug output for even more details: Sent Accounting-Request Id 163 from 0.0.0.0:60038 to 127.0.0.1:1813 length 715 (0) Received Accounting-Request Id 163 from 127.0.0.1:60038 to 127.0.0.1:1813 length 715 (0) User-Name = "noneexistent123@domain.com" (0) Acct-Status-Type = Interim-Update (0) Acct-Session-Id = "25466609" (0) Acct-Input-Octets = 211016095 (0) Acct-Output-Octets = 3081069646 (0) Acct-Session-Time = 2047177 (0) Acct-Input-Packets = 179269685 (0) Acct-Output-Packets = 322301129 (0) Service-Type = Framed-User (0) Framed-Protocol = PPP (0) Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in" (0) Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out" (0) Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b (0) Tunnel-Type:0 = L2TP (0) Tunnel-Medium-Type:0 = IPv4 (0) Tunnel-Client-Endpoint:0 = "192.168.242.189" (0) Tunnel-Server-Endpoint:0 = "192.168.80.106" (0) Tunnel-Assignment-Id:0 = "57524" (0) Tunnel-Client-Auth-Id:0 = "AB99AR99" (0) Tunnel-Server-Auth-Id:0 = "domain" (0) Acct-Tunnel-Connection = "0002758216" (0) Acct-Authentic = RADIUS (0) Acct-Delay-Time = 0 (0) Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#" (0) ERX-Dhcp-Mac-Addr = "0000.0000.0000" (0) Event-Timestamp = "Dec 12 2017 11:35:30 EST" (0) Framed-IP-Address = 192.168.225.42 (0) Framed-IP-Netmask = 255.255.254.0 (0) ERX-Input-Gigapkts = 0 (0) Acct-Input-Gigawords = 4 (0) NAS-Identifier = "lns01.lan" (0) NAS-Port = 268439551 (0) NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216" (0) NAS-Port-Type = Virtual (0) ERX-Output-Gigapkts = 0 (0) Acct-Output-Gigawords = 103 (0) ERX-IPv6-Acct-Input-Octets = 0 (0) ERX-IPv6-Acct-Output-Octets = 0 (0) ERX-IPv6-Acct-Input-Packets = 0 (0) ERX-IPv6-Acct-Output-Packets = 0 (0) ERX-IPv6-Acct-Input-Gigawords = 0 (0) ERX-IPv6-Acct-Output-Gigawords = 0 (0) ERX-Tx-Connect-Speed = 13277755 (0) Attr-26.4874.163 = 0x000000 (0) ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00" (0) NAS-IP-Address = 192.168.191.4 (0) # Executing section preacct from file /etc/raddb/sites-enabled/domain (0) preacct { (0) suffix: Checking for suffix after "@" (0) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com" (0) suffix: No such realm "domain.com" (0) [suffix] = noop (0) policy username_lower_domain { (0) update request { (0) EXPAND %{tolower:%{User-Name}} (0) --> noneexistent123@domain.com (0) Stripped-User-Name := noneexistent123@domain.com (0) } # update request = noop (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){ (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE (0) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) { (0) update request { (0) EXPAND %{tolower:%{3}} (0) --> domain.com (0) Stripped-User-Domain = domain.com (0) } # update request = noop (0) [updated] = updated (0) } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated (0) ... skipping else: Preceding "if" was taken (0) } # policy username_lower_domain = updated (0) policy acct_counters64_preacct { (0) update request { (0) EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}} (0) --> 17390885279 (0) Acct-Input-Octets64 = 17390885279 (0) EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}} (0) --> 445462701134 (0) Acct-Output-Octets64 = 445462701134 (0) } # update request = noop (0) } # policy acct_counters64_preacct = noop (0) policy acct_unique { (0) update request { (0) EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}} (0) --> 51dc686492632c94c03d1346eb471bf5 (0) Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5 (0) } # update request = noop (0) } # policy acct_unique = noop (0) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) { (0) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) -> FALSE (0) } # preacct = updated (0) # Executing section accounting from file /etc/raddb/sites-enabled/domain (0) accounting { (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) -> TRUE (0) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (0) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type} (0) linelog-domain-acct: --> messages.Interim-Update (0) linelog-domain-acct: EXPAND 'Interim-Update''%{Acct-Session-Id}''%{User-Name}''%{NAS-IP-Address}''%S''%{Acct-Session-Time}''%{%{Acct-Input-Gigawords}:-0}''%{%{Acct-Output-Gigawords}:-0}''%{%{Acct-Input-Octets}:-0}''%{%{Acct-Output-Octets}:-0}''%{Calling-Station-Id}''%{Framed-IP-Address}' (0) linelog-domain-acct: --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 08:50:02''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42' (0) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log (0) linelog-domain-acct: --> /var/log/radius/radacct/acct.log (0) [linelog-domain-acct] = ok rlm_couchbase (couchbase): Reserved connection (0) (0) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}} (0) couchbase: --> radacct_51dc686492632c94c03d1346eb471bf5 109644ms [I0] {27151} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Found ready connection in pool. Reusing socket and not creating new connection 109644ms [I0] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Assigning R=0x5601af6b0c90 SOCKET=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8b2bc0,unknown) Pairing with SOCK=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x5601af6b9580,IX=0) Setting initial timeout=2499ms rlm_couchbase: (get_callback) key does not exist (0) couchbase: ERROR: failed to execute get request or parse returned json object (0) couchbase: no existing document found - creating new json document rlm_couchbase: calculated start timestamp: Nov 18 2017 18:55:53 EST rlm_couchbase (couchbase): Released connection (0) Need 3 more connections to reach min connections (8) rlm_couchbase (couchbase): Opening additional connection (5), 1 of 123 pending slots used 109646ms [I5] {27151} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798 109646ms [I5] {27151} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius 109646ms [I5] {27151} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1 109646ms [I5] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list 109646ms [I5] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list 109760ms [I5] {27151} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed 109760ms [I5] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 109760ms [I5] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED 109760ms [I5] {27151} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED 109760ms [I5] {27151} [TRACE] (confmon - L:252) Start refresh requested 109760ms [I5] {27151} [TRACE] (confmon - L:239) Current provider is CCCP 109760ms [I5] {27151} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration 109760ms [I5] {27151} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x5601af8c7840) Creating new connection because none are available in the pool 109760ms [I5] {27151} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x5601af8c7840) Starting connection on I=0x5601af8c7cd0 109760ms [I5] {27151} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Starting. Timeout=2000000us 109760ms [I5] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Got event handler for new connection 109760ms [I5] {27151} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Scheduling asynchronous watch for socket. 109761ms [I5] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Got event handler for new connection 109761ms [I5] {27151} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Connected 109761ms [I5] {27151} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x5601af8c7dd0) Successfuly set TCP_NODELAY 109761ms [I5] {27151} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x5601af8c7840) Received result for I=0x5601af8c7cd0,C=0x5601af8c7dd0; E=0x0 109761ms [I5] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af8c7840) Assigning R=0x5601af6b0c90 SOCKET=0x5601af8c7dd0 109761ms [I5] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8c85e0,unknown) Pairing with SOCK=0x5601af8c7dd0 109762ms [I5] {27151} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x5601af8c8490) Found feature 0x3 (TCP NODELAY) 109762ms [I5] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8c85e0,sasl) Destroying. PND=0,ENT=1,SORC=1 109762ms [I5] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8d0af0,unknown) Pairing with SOCK=0x5601af8c7dd0 109762ms [I5] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8d0af0,bc_cccp) Destroying. PND=0,ENT=1,SORC=1 109762ms [I5] {27151} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x5601af8c7840) Placing socket back into the pool. I=0x5601af8c7cd0,C=0x5601af8c7dd0 109763ms [I5] {27151} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP 109763ms [I5] {27151} [DEBUG] (bootstrap - L:56) Instance configured! 109763ms [I5] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 109763ms [I5] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED (0) [couchbase] = ok (0) } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) = ok (0) [ok] = ok (0) } # accounting = ok (0) Sent Accounting-Response Id 163 from 127.0.0.1:1813 to 127.0.0.1:60038 length 0 (0) Finished request (0) Cleaning up request packet ID 163 with timestamp +109 Ready to process requests Received Accounting-Response Id 163 from 127.0.0.1:1813 to 0.0.0.0:0 length 20 [root@radius03 radius]# cat /tmp/testacc | radclient 127.0.0.1 acct testing123 Sent Accounting-Request Id 207 from 0.0.0.0:36802 to 127.0.0.1:1813 length 715 (1) Received Accounting-Request Id 207 from 127.0.0.1:36802 to 127.0.0.1:1813 length 715 (1) User-Name = "noneexistent123@domain.com" (1) Acct-Status-Type = Interim-Update (1) Acct-Session-Id = "25466609" (1) Acct-Input-Octets = 211016095 (1) Acct-Output-Octets = 3081069646 (1) Acct-Session-Time = 2047177 (1) Acct-Input-Packets = 179269685 (1) Acct-Output-Packets = 322301129 (1) Service-Type = Framed-User (1) Framed-Protocol = PPP (1) Filter-Id = "IPV4-ingress:dsl-default-in-si-1/1/0.1073813193-in" (1) Filter-Id = "IPV4-egress:dsl-default-out-si-1/1/0.1073813193-out" (1) Attr-26.4874.177 = 0x506f72742053706565643a2031303030303030306b (1) Tunnel-Type:0 = L2TP (1) Tunnel-Medium-Type:0 = IPv4 (1) Tunnel-Client-Endpoint:0 = "192.168.242.189" (1) Tunnel-Server-Endpoint:0 = "192.168.80.106" (1) Tunnel-Assignment-Id:0 = "57524" (1) Tunnel-Client-Auth-Id:0 = "AB99AR99" (1) Tunnel-Server-Auth-Id:0 = "domain" (1) Acct-Tunnel-Connection = "0002758216" (1) Acct-Authentic = RADIUS (1) Acct-Delay-Time = 0 (1) Calling-Station-Id = "GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#" (1) ERX-Dhcp-Mac-Addr = "0000.0000.0000" (1) Event-Timestamp = "Dec 12 2017 11:35:30 EST" (1) Framed-IP-Address = 192.168.225.42 (1) Framed-IP-Netmask = 255.255.254.0 (1) ERX-Input-Gigapkts = 0 (1) Acct-Input-Gigawords = 4 (1) NAS-Identifier = "lns01.lan" (1) NAS-Port = 268439551 (1) NAS-Port-Id = "Ip:192.168.80.106:192.168.242.189:57524:10046:22601:33289:2758216" (1) NAS-Port-Type = Virtual (1) ERX-Output-Gigapkts = 0 (1) Acct-Output-Gigawords = 103 (1) ERX-IPv6-Acct-Input-Octets = 0 (1) ERX-IPv6-Acct-Output-Octets = 0 (1) ERX-IPv6-Acct-Input-Packets = 0 (1) ERX-IPv6-Acct-Output-Packets = 0 (1) ERX-IPv6-Acct-Input-Gigawords = 0 (1) ERX-IPv6-Acct-Output-Gigawords = 0 (1) ERX-Tx-Connect-Speed = 13277755 (1) Attr-26.4874.163 = 0x000000 (1) ERX-Pppoe-Description = "pppoe 00:00:00:00:00:00" (1) NAS-IP-Address = 192.168.191.4 (1) # Executing section preacct from file /etc/raddb/sites-enabled/domain (1) preacct { (1) suffix: Checking for suffix after "@" (1) suffix: Looking up realm "domain.com" for User-Name = "noneexistent123@domain.com" (1) suffix: No such realm "domain.com" (1) [suffix] = noop (1) policy username_lower_domain { (1) update request { (1) EXPAND %{tolower:%{User-Name}} (1) --> noneexistent123@domain.com (1) Stripped-User-Name := noneexistent123@domain.com (1) } # update request = noop (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/){ (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) -> TRUE (1) if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) { (1) update request { (1) EXPAND %{tolower:%{3}} (1) --> domain.com (1) Stripped-User-Domain = domain.com (1) } # update request = noop (1) [updated] = updated (1) } # if (User-Name =~ /^([^@]*)(@([-[:alnum:]]+\.[-[:alnum:].]+))?$/) = updated (1) ... skipping else: Preceding "if" was taken (1) } # policy username_lower_domain = updated (1) policy acct_counters64_preacct { (1) update request { (1) EXPAND %{expr:(%{%{Acct-Input-Gigawords}:-0} * 4294967296) + %{%{Acct-Input-Octets}:-0}} (1) --> 17390885279 (1) Acct-Input-Octets64 = 17390885279 (1) EXPAND %{expr:(%{%{Acct-Output-Gigawords}:-0} * 4294967296) + %{%{Acct-Output-Octets}:-0}} (1) --> 445462701134 (1) Acct-Output-Octets64 = 445462701134 (1) } # update request = noop (1) } # policy acct_counters64_preacct = noop (1) policy acct_unique { (1) update request { (1) EXPAND %{md5:%{Stripped-User-Name},%{Acct-Session-ID},%{NAS-IP-Address}} (1) --> 51dc686492632c94c03d1346eb471bf5 (1) Acct-Unique-Session-Id := 51dc686492632c94c03d1346eb471bf5 (1) } # update request = noop (1) } # policy acct_unique = noop (1) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) { (1) if (NAS-Port-Id =~ /^ip:([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):([0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}\.[0-9]{1,3}):/) -> FALSE (1) } # preacct = updated (1) # Executing section accounting from file /etc/raddb/sites-enabled/domain (1) accounting { (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) -> TRUE (1) if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) { (1) linelog-domain-acct: EXPAND messages.%{Acct-Status-Type} (1) linelog-domain-acct: --> messages.Interim-Update (1) linelog-domain-acct: EXPAND 'Interim-Update''%{Acct-Session-Id}''%{User-Name}''%{NAS-IP-Address}''%S''%{Acct-Session-Time}''%{%{Acct-Input-Gigawords}:-0}''%{%{Acct-Output-Gigawords}:-0}''%{%{Acct-Input-Octets}:-0}''%{%{Acct-Output-Octets}:-0}''%{Calling-Station-Id}''%{Framed-IP-Address}' (1) linelog-domain-acct: --> 'Interim-Update''25466609''noneexistent123@domain.com''192.168.191.4''2018-01-22 08:50:12''2047177''4''103''211016095''3081069646''GigabitEthernet 1/0.12502026:1250-2026#587204111###pppoe ff:ff:ff:27:41:4c#''192.168.225.42' (1) linelog-domain-acct: EXPAND /var/log/radius/radacct/acct.log (1) linelog-domain-acct: --> /var/log/radius/radacct/acct.log (1) [linelog-domain-acct] = ok rlm_couchbase (couchbase): Reserved connection (1) (1) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}} (1) couchbase: --> radacct_51dc686492632c94c03d1346eb471bf5 119373ms [I1] {27151} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x5601af6b8b00) Found ready connection in pool. Reusing socket and not creating new connection 119373ms [I1] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af6b8b00) Assigning R=0x5601af8d0b70 SOCKET=0x5601af6b90d0 119373ms [I1] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8b1bc0,unknown) Pairing with SOCK=0x5601af6b90d0 119373ms [I1] {27151} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x5601af6b19b0,IX=0) Setting initial timeout=2499ms rlm_couchbase: (get_callback) got 651 bytes rlm_couchbase (couchbase): Released connection (1) Need 2 more connections to reach min connections (8) rlm_couchbase (couchbase): Opening additional connection (6), 1 of 122 pending slots used 119375ms [I6] {27151} [INFO] (instance - L:401) Version=2.7.1, Changeset=63c54b1b63db427ab3cf9a131c08ad591044b798 119375ms [I6] {27151} [INFO] (instance - L:402) Effective connection string: couchbase+explicit://10.0.2.207,/radius?. Bucket=radius 119375ms [I6] {27151} [DEBUG] (instance - L:273) Applying initial cntl detailed_errcodes=1 119375ms [I6] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:8091 to initial HTTP bootstrap list 119375ms [I6] {27151} [DEBUG] (instance - L:77) Adding host 10.0.2.207:11210 to initial CCCP bootstrap list 119489ms [I6] {27151} [INFO] (instance - L:135) DNS SRV lookup failed: DNS/Hostname lookup failed 119489ms [I6] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 119489ms [I6] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED 119489ms [I6] {27151} [DEBUG] (confmon - L:90) Provider HTTP is ENABLED 119489ms [I6] {27151} [TRACE] (confmon - L:252) Start refresh requested 119490ms [I6] {27151} [TRACE] (confmon - L:239) Current provider is CCCP 119490ms [I6] {27151} [INFO] (cccp - L:144) Requesting connection to node 10.0.2.207:11210 for CCCP configuration 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:416) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Creating new connection because none are available in the pool 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:321) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Starting connection on I=0x5601af8de540 119490ms [I6] {27151} [INFO] (connection - L:450) <10.0.2.207:11210> (SOCK=0x5601af8de640) Starting. Timeout=2000000us 119490ms [I6] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8de640) Got event handler for new connection 119490ms [I6] {27151} [TRACE] (connection - L:314) <10.0.2.207:11210> (SOCK=0x5601af8de640) Scheduling asynchronous watch for socket. 119490ms [I6] {27151} [TRACE] (connection - L:267) <10.0.2.207:11210> (SOCK=0x5601af8de640) Got event handler for new connection 119490ms [I6] {27151} [INFO] (connection - L:116) <10.0.2.207:11210> (SOCK=0x5601af8de640) Connected 119490ms [I6] {27151} [DEBUG] (connection - L:123) <10.0.2.207:11210> (SOCK=0x5601af8de640) Successfuly set TCP_NODELAY 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:271) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Received result for I=0x5601af8de540,C=0x5601af8de640; E=0x0 119490ms [I6] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Assigning R=0x5601af6b0c90 SOCKET=0x5601af8de640 119490ms [I6] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8deea0,unknown) Pairing with SOCK=0x5601af8de640 119491ms [I6] {27151} [DEBUG] (negotiation - L:378) <10.0.2.207:11210> (SASLREQ=0x5601af8ded00) Found feature 0x3 (TCP NODELAY) 119491ms [I6] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8deea0,sasl) Destroying. PND=0,ENT=1,SORC=1 119491ms [I6] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8e7300,unknown) Pairing with SOCK=0x5601af8de640 119492ms [I6] {27151} [DEBUG] (ioctx - L:151) <10.0.2.207:11210> (CTX=0x5601af8e7300,bc_cccp) Destroying. PND=0,ENT=1,SORC=1 119492ms [I6] {27151} [INFO] (lcbio_mgr - L:491) <10.0.2.207:11210> (HE=0x5601af8ddfd0) Placing socket back into the pool. I=0x5601af8de540,C=0x5601af8de640 119492ms [I6] {27151} [INFO] (confmon - L:153) Setting new configuration. Received via CCCP 119492ms [I6] {27151} [DEBUG] (bootstrap - L:56) Instance configured! 119492ms [I6] {27151} [DEBUG] (confmon - L:83) Preparing providers (this may be called multiple times) 119492ms [I6] {27151} [DEBUG] (confmon - L:90) Provider CCCP is ENABLED (1) [couchbase] = ok (1) } # if (Acct-Status-Type == "Start" || Acct-Status-Type == "Stop" || Acct-Status-Type == "Interim-Update" || Acct-Session-Time != 0) = ok (1) [ok] = ok (1) } # accounting = ok (1) Sent Accounting-Response Id 207 from 127.0.0.1:1813 to 127.0.0.1:36802 length 0 (1) Finished request (1) Cleaning up request packet ID 207 with timestamp +119 Ready to process requests Received Accounting-Response Id 207 from 127.0.0.1:1813 to 0.0.0.0:0 length 20
On Jan 22, 2018, at 9:08 AM, Mike Lopes <mlopes@teksavvy.ca> wrote:
The code in rlm_couchbase.c definitely processes accounting interim-update packets. So what does the debug log show when you receive such a packet?
I knew I forgot something... Here it is, I also enabled couchbase module debug output for even more details:
Sent Accounting-Request Id 163 from 0.0.0.0:60038 to 127.0.0.1:1813 length 715 (0) Received Accounting-Request Id 163 from 127.0.0.1:60038 to 127.0.0.1:1813 length 715 (0) User-Name = "noneexistent123@domain.com" (0) Acct-Status-Type = Interim-Update
That's good...
rlm_couchbase (couchbase): Reserved connection (0) (0) couchbase: EXPAND radacct_%{%{Acct-Unique-Session-Id}:-%{Acct-Session-Id}} (0) couchbase: --> radacct_51dc686492632c94c03d1346eb471bf5 109644ms [I0] {27151} [INFO] (lcbio_mgr - L:407) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Found ready connection in pool. Reusing socket and not creating new connection 109644ms [I0] {27151} [DEBUG] (lcbio_mgr - L:223) <10.0.2.207:11210> (HE=0x5601af6ac6f0) Assigning R=0x5601af6b0c90 SOCKET=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (ioctx - L:101) <10.0.2.207:11210> (CTX=0x5601af8b2bc0,unknown) Pairing with SOCK=0x5601af6acd60 109644ms [I0] {27151} [DEBUG] (server - L:499) <10.0.2.207:11210> (SRV=0x5601af6b9580,IX=0) Setting initial timeout=2499ms rlm_couchbase: (get_callback) key does not exist (0) couchbase: ERROR: failed to execute get request or parse returned json object (0) couchbase: no existing document found - creating new json document rlm_couchbase: calculated start timestamp: Nov 18 2017 18:55:53 EST
That's fine.
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. Alan DeKok.
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
On Jan 22, 2018, at 11:24 AM, Mike Lopes <mlopes@teksavvy.ca> wrote:
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. ... Mon Jan 22 10:56:36 2018 : Debug: (1) couchbase: assigning string 'Acct-Session-Id' as string
That's good.
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" }'
That's good. Which means it stores that document.. If not, it would say: if (cb_error != LCB_SUCCESS) { RERROR("failed to store document (%s): %s (0x%x)", dockey, lcb_strerror(NULL, cb_error), cb_error); So that seems to work. Is that entry not going to the DB? Alan DeKok.
Hi,
So that seems to work.
Is that entry not going to the DB?
Here's what is in couchbase using the 3.0.15: { "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" } Here's what I am supposed to be seeing and what is currently showing in production: { "docType": "clientacct", "startTimestamp": "Jan 18 2018 10:32:52 EST", "stopTimestamp": "Jan 18 2018 10:53:10 EST", "userName": "noneexistent123@domain.com", "lastStatus": 2, "sessionId": "3196850", "callingStationId": "GigabitEthernet 0/0.20222005:2022-2005#587203677###pppoe ff:ff:ff:38:67:c9#", "lastUpdated": "Jan 18 2018 10:53:10 EST", "framedIpAddress": "192.168.185.183", "nasIdentifier": "lns01.lan", "nasPort": "Ip:192.168.216.26:192.168.208.55:23554:11465:36823:3605:4018467", "nasIpAddress": "192.168.191.4", "lowercaseUser": "noneexistent123@domain.com", "UserDomain": "domain.com", "uniqueId": "45385ecca5f5078d4ee7a0472d3e5a5b", "sessionTime": 1218, "userDomain": "domain.com", "usageUpdate": [ { "lastStatus": 3, "timeStamp": "Jan 18 2018 10:42:29 EST", "upload": 322453, "download": 3820958 }, { "lastStatus": 3, "timeStamp": "Jan 18 2018 10:52:29 EST", "upload": 722166, "download": 7699190 } ], "TerminateCause": 2 } I'm starting to think that the production servers have an in house customized/patched rlm_couchbase module. I'm going to investigate that possibility. On another note, could you point me to documentation on how I can achieve accounting and interim-updates to couchbase? When I click on the documentation link here: https://freeradius.org/modules/?s=couchbase&mod=rlm_couchbase it brings me to modules documentation home where there's nothing on couchbase. Thanks again for your assistance. -Mike
On Jan 22, 2018, at 1:34 PM, Mike Lopes <mlopes@teksavvy.ca> wrote:
I'm starting to think that the production servers have an in house customized/patched rlm_couchbase module. I'm going to investigate that possibility.
Looks like it. If you find it. send the code back so that others can benefit from fixes / features.
On another note, could you point me to documentation on how I can achieve accounting and interim-updates to couch base?
It just always writes the same json document, based on the "update" section.
When I click on the documentation link here: https://freeradius.org/modules/?s=couchbase&mod=rlm_couchbase it brings me to modules documentation home where there's nothing on couchbase.
Ah... there is (as of yet) no documentation. We're... gradually... working on that. Alan DeKok.
On Jan 22, 2018, at 1:34 PM, Mike Lopes <mlopes@teksavvy.ca> wrote:
I'm starting to think that the production servers have an in house customized/patched rlm_couchbase module. I'm going to investigate that possibility.
Looks like it.
If you find it. send the code back so that others can benefit from fixes / features.
I found something that was added to /src/modules/rlm_couchbase/mod.c and src/modules/rlm_couchbase/rlm_couchbase.c How do I go about submitting it? I have a patch format diff. -Mike
On Jan 22, 2018, at 2:33 PM, Mike Lopes <mlopes@teksavvy.ca> wrote:
I found something that was added to /src/modules/rlm_couchbase/mod.c and src/modules/rlm_couchbase/rlm_couchbase.c
How do I go about submitting it? I have a patch format diff.
Github is preferred. But otherwise send a patch (gzipped) off-list, and I'll take a look. Alan DeKok.
participants (2)
-
Alan DeKok -
Mike Lopes