json encoding (Freeradius 3.0.13)

22 Nov 2016

      Hi All,

i am trying to implement cisco Device sensor
(http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...)
that allow to have endpoint data like DHCP, LLDP in the radius
accounting packet.

I am able to receive these specific attributes but when i want to send
them to my api (PacketFence) through rlm_rest module , it looks that
these attributes are not well encoded.

You can see in the raddebug trace this attribute Cisco-AVPair =
"dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received
from the cisco switch which is encoded to that
"dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+"
and i am not able to decode it.

On my side i did some test with a perl json encoding code and the
encoding string is suppose to be
\\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+

Do i miss something in the Freeradius configuration in order to make it
work ?

Thanks,

Regards

Fabrice

Here my raddebug trace:

Tue Nov 22 15:19:40 2016 : Debug: (0) Received Accounting-Request Id 77
from 172.20.135.3:2940 to 172.20.135.1:1813 length 555
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dc-profile-name=HP-Device"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dc-device-name=MSFT 5.0"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dc-device-class-tag=HP-Device"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dc-certainty-metric=10"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dc-opaque=\000\000\000\002\000\000\000\000\000\000\000"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair = "dc-protocol-map=9"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dhcp-option=\000<\000\010MSFT 5.0"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"dhcp-option=\000\014\000\tinverse-8"
Tue Nov 22 15:19:40 2016 : Debug: (0)   User-Name = "101f74b2f6a5"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair =
"audit-session-id=AC158904000001485B34CE42"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair = "vlan-id=138"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Cisco-AVPair = "method=mab"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Called-Station-Id =
"DC-A5-F4-34-55-08"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Calling-Station-Id =
"10-1F-74-B2-F6-A5"
Tue Nov 22 15:19:40 2016 : Debug: (0)   NAS-IP-Address = 172.20.135.77
Tue Nov 22 15:19:40 2016 : Debug: (0)   NAS-Port-Id = "GigabitEthernet1/0/8"
Tue Nov 22 15:19:40 2016 : Debug: (0)   NAS-Port-Type = Ethernet
Tue Nov 22 15:19:40 2016 : Debug: (0)   NAS-Port = 50108
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Session-Id = "000003B1"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Terminate-Cause = Lost-Carrier
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Status-Type = Stop
Tue Nov 22 15:19:40 2016 : Debug: (0)   Event-Timestamp = "nov 22 2016
15:26:16 EST"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Session-Time = 1133
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Input-Octets = 97158148
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Output-Octets = 166844207
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Input-Packets = 744486
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Output-Packets = 1682264
Tue Nov 22 15:19:40 2016 : Debug: (0)   Acct-Delay-Time = 0
Tue Nov 22 15:19:40 2016 : Debug: (0)   Proxy-State = 0x313339
Tue Nov 22 15:19:40 2016 : Debug: (0) # Executing section preacct from
file raddb//sites-enabled/packetfence
Tue Nov 22 15:19:40 2016 : Debug: (0)   preacct {
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: calling
preprocess (rlm_preprocess)
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: returned
from preprocess (rlm_preprocess)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [preprocess] = ok
Tue Nov 22 15:19:40 2016 : Debug: (0)     policy rewrite_called_station_id {
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
{
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
-> TRUE
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
{
Tue Nov 22 15:19:40 2016 : Debug: (0)         update request {
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Called-Station-Id !* ANY
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              --> dc:a5:f4:34:55:08
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Called-Station-Id :=
dc:a5:f4:34:55:08
Tue Nov 22 15:19:40 2016 : Debug: (0)         } # update request = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)         if ("%{8}") {
Tue Nov 22 15:19:40 2016 : Debug: (0)         EXPAND %{8}
Tue Nov 22 15:19:40 2016 : Debug: (0)            -->
Tue Nov 22 15:19:40 2016 : Debug: (0)         if ("%{8}")  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif (Aruba-Essid-Name) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif (Aruba-Essid-Name) 
-> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Cisco-AVPair)  &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         EXPAND %{Cisco-AVPair}
Tue Nov 22 15:19:40 2016 : Debug: (0)            -->
dc-profile-name=HP-Device
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Cisco-AVPair)  &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[preacct]:
calling updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[preacct]:
returned from updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         [updated] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       } # if ((&Called-Station-Id)
&& (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
= updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       ... skipping else: Preceding
"if" was taken
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # policy
rewrite_called_station_id = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)     policy acct_unique {
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
Tue Nov 22 15:19:40 2016 : Debug: (0)       EXPAND %{string:Class}
Tue Nov 22 15:19:40 2016 : Debug: (0)          -->
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)       else {
Tue Nov 22 15:19:40 2016 : Debug: (0)         update request {
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              -->
ddbfe7a1d200b1fb1576b92057e0bcc6
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Acct-Unique-Session-Id
:= ddbfe7a1d200b1fb1576b92057e0bcc6
Tue Nov 22 15:19:40 2016 : Debug: (0)         } # update request = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)       } # else = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # policy acct_unique = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: calling
suffix (rlm_realm)
Tue Nov 22 15:19:40 2016 : Debug: (0) suffix: Checking for suffix after "@"
Tue Nov 22 15:19:40 2016 : Debug: (0) suffix: No '@' in User-Name =
"101f74b2f6a5", skipping NULL due to config.
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: returned
from suffix (rlm_realm)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [suffix] = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: calling
ntdomain (rlm_realm)
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Checking for prefix
before "\"
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: No '\' in User-Name =
"101f74b2f6a5", looking up realm NULL
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Found realm "null"
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Adding
Stripped-User-Name = "101f74b2f6a5"
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Adding Realm = "null"
Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Accounting realm is LOCAL
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: returned
from ntdomain (rlm_realm)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [ntdomain] = ok
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: calling
files (rlm_files)
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[preacct]: returned
from files (rlm_files)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [files] = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)   } # preacct = updated
Tue Nov 22 15:19:40 2016 : Debug: (0) # Executing section accounting
from file raddb//sites-enabled/packetfence
Tue Nov 22 15:19:40 2016 : Debug: (0)   accounting {
Tue Nov 22 15:19:40 2016 : Debug: (0)     policy set_calling_station_id {
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&User-Name &&
(&User-Name =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
{
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&User-Name &&
(&User-Name =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
-> TRUE
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&User-Name &&
(&User-Name =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
{
Tue Nov 22 15:19:40 2016 : Debug: (0)         update request {
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              --> 10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           &User-Name :=
10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           Overwriting value
"101f74b2f6a5" with "10:1f:74:b2:f6:a5"
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              --> 10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Calling-Station-Id =
10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           Refusing to overwrite
(use :=)
Tue Nov 22 15:19:40 2016 : Debug: (0)         } # update request = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
calling updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
returned from updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         [updated] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       } # if (&User-Name &&
(&User-Name =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
= updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       ... skipping else: Preceding
"if" was taken
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # policy
set_calling_station_id = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)     policy
rewrite_calling_station_id {
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&Calling-Station-Id &&
(&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i))
{
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&Calling-Station-Id &&
(&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
-> TRUE
Tue Nov 22 15:19:40 2016 : Debug: (0)       if (&Calling-Station-Id &&
(&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
{
Tue Nov 22 15:19:40 2016 : Debug: (0)         update request {
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              --> 10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Calling-Station-Id :=
10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0)           Overwriting value
"10-1F-74-B2-F6-A5" with "10:1f:74:b2:f6:a5"
Tue Nov 22 15:19:40 2016 : Debug: (0)         } # update request = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
calling updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
returned from updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         [updated] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       } # if (&Calling-Station-Id
&& (&Calling-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) 
= updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       ... skipping else: Preceding
"if" was taken
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # policy
rewrite_calling_station_id = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)     policy rewrite_called_station_id {
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i))
{
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
-> TRUE
Tue Nov 22 15:19:40 2016 : Debug: (0)       if ((&Called-Station-Id) &&
(&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
{
Tue Nov 22 15:19:40 2016 : Debug: (0)         update request {
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Called-Station-Id !* ANY
Tue Nov 22 15:19:40 2016 : Debug: (0)           EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
Tue Nov 22 15:19:40 2016 : Debug: (0)              --> dc:a5:f4:34:55:08
Tue Nov 22 15:19:40 2016 : Debug: (0)           &Called-Station-Id :=
dc:a5:f4:34:55:08
Tue Nov 22 15:19:40 2016 : Debug: (0)         } # update request = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)         if ("%{8}") {
Tue Nov 22 15:19:40 2016 : Debug: (0)         EXPAND %{8}
Tue Nov 22 15:19:40 2016 : Debug: (0)            -->
Tue Nov 22 15:19:40 2016 : Debug: (0)         if ("%{8}")  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Colubris-AVPair)
&& "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif (Aruba-Essid-Name) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif (Aruba-Essid-Name) 
-> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Cisco-AVPair)  &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
Tue Nov 22 15:19:40 2016 : Debug: (0)         EXPAND %{Cisco-AVPair}
Tue Nov 22 15:19:40 2016 : Debug: (0)            -->
dc-profile-name=HP-Device
Tue Nov 22 15:19:40 2016 : Debug: (0)         elsif ( (Cisco-AVPair)  &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
calling updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         modsingle[accounting]:
returned from updated (rlm_always)
Tue Nov 22 15:19:40 2016 : Debug: (0)         [updated] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       } # if ((&Called-Station-Id)
&& (&Called-Station-Id =~
/^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) 
= updated
Tue Nov 22 15:19:40 2016 : Debug: (0)       ... skipping else: Preceding
"if" was taken
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # policy
rewrite_called_station_id = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)     update {
Tue Nov 22 15:19:40 2016 : Debug: (0)       EXPAND %{Packet-Src-IP-Address}
Tue Nov 22 15:19:40 2016 : Debug: (0)          --> 172.20.135.3
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&request:FreeRADIUS-Client-IP-Address := 172.20.135.3
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&control:PacketFence-RPC-Server = 127.0.0.1
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&control:PacketFence-RPC-Port = 7070
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&control:PacketFence-RPC-User = packet
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&control:PacketFence-RPC-Pass = fence
Tue Nov 22 15:19:40 2016 : Debug: (0)      
&control:PacketFence-RPC-Proto = http
Tue Nov 22 15:19:40 2016 : Debug: (0)     } # update = noop
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]: calling
sql (rlm_sql)
Tue Nov 22 15:19:40 2016 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: xlat --> tolower
Tue Nov 22 15:19:40 2016 : Debug: {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> type.
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Status-Type
Tue Nov 22 15:19:40 2016 : Debug:     literal --> .query
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND
%{tolower:type.%{Acct-Status-Type}.query}
Tue Nov 22 15:19:40 2016 : Debug: (0) sql:    --> type.stop.query
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: Using query template 'query'
Tue Nov 22 15:19:40 2016 : Debug: rlm_sql (sql): Reserved connection (1)
Tue Nov 22 15:19:40 2016 : Debug: %{User-Name}
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: attribute --> User-Name
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND %{User-Name}
Tue Nov 22 15:19:40 2016 : Debug: (0) sql:    --> 10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: SQL-User-Name set to
'10:1f:74:b2:f6:a5'
Tue Nov 22 15:19:40 2016 : Debug: CALL acct_stop (
FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}',
%{%{Acct-Session-Time}:-NULL}, '%{%{Acct-Input-Gigawords}:-0}' << 32 |
'%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}', '%{Acct-Unique-Session-Id}',
'%{Acct-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}',
'%{NAS-Port-Type}', '%{Acct-Authentic}', '%{Connect-Info}',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}',
'%{Framed-Protocol}', '%{Acct-Terminate-Cause}', '%{Acct-Status-Type}')
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: literal --> CALL acct_stop (
FROM_UNIXTIME(
Tue Nov 22 15:19:40 2016 : Debug: xlat --> integer
Tue Nov 22 15:19:40 2016 : Debug: {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> Event-Timestamp
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ), '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Framed-IP-Address
Tue Nov 22 15:19:40 2016 : Debug: literal --> ',
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Session-Time
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> NULL
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> , '
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Input-Gigawords
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> 0
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ' << 32 | '
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Input-Octets
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> 0
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Output-Gigawords
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> 0
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ' << 32 | '
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> Acct-Output-Octets
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     literal --> 0
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Unique-Session-Id
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Session-Id
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> SQL-User-Name
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Realm
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-IP-Address
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: if {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> NAS-Port-Id
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: else {
Tue Nov 22 15:19:40 2016 : Debug:     attribute --> NAS-Port
Tue Nov 22 15:19:40 2016 : Debug: }
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-Port-Type
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Authentic
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Connect-Info
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Called-Station-Id
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Calling-Station-Id
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Service-Type
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Framed-Protocol
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Terminate-Cause
Tue Nov 22 15:19:40 2016 : Debug: literal --> ', '
Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Status-Type
Tue Nov 22 15:19:40 2016 : Debug: literal --> ')
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND CALL acct_stop (
FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}',
%{%{Acct-Session-Time}:-NULL}, '%{%{Acct-Input-Gigawords}:-0}' << 32 |
'%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}', '%{Acct-Unique-Session-Id}',
'%{Acct-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}',
'%{NAS-Port-Type}', '%{Acct-Authentic}', '%{Connect-Info}',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}',
'%{Framed-Protocol}', '%{Acct-Terminate-Cause}', '%{Acct-Status-Type}')
Tue Nov 22 15:19:40 2016 : Debug: (0) sql:    --> CALL acct_stop (
FROM_UNIXTIME(1479846376), '', 1133, '0' << 32 | '97158148', '0' << 32 |
'166844207', 'ddbfe7a1d200b1fb1576b92057e0bcc6', '000003B1',
'10:1f:74:b2:f6:a5', 'null', '172.20.135.77', 'GigabitEthernet1/0/8',
'Ethernet', '', '', 'dc:a5:f4:34:55:08', '10:1f:74:b2:f6:a5', '', '',
'Lost-Carrier', 'Stop')
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: Executing query: CALL
acct_stop ( FROM_UNIXTIME(1479846376), '', 1133, '0' << 32 | '97158148',
'0' << 32 | '166844207', 'ddbfe7a1d200b1fb1576b92057e0bcc6', '000003B1',
'10:1f:74:b2:f6:a5', 'null', '172.20.135.77', 'GigabitEthernet1/0/8',
'Ethernet', '', '', 'dc:a5:f4:34:55:08', '10:1f:74:b2:f6:a5', '', '',
'Lost-Carrier', 'Stop')
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: SQL query returned: success
Tue Nov 22 15:19:40 2016 : Debug: (0) sql: 1 record(s) updated
Tue Nov 22 15:19:40 2016 : Debug: rlm_sql (sql): Released connection (1)
Tue Nov 22 15:19:40 2016 : Info: rlm_sql (sql): Need 4 more connections
to reach 10 spares
Tue Nov 22 15:19:40 2016 : Info: rlm_sql (sql): Opening additional
connection (6), 1 of 58 pending slots used
Tue Nov 22 15:19:40 2016 : Debug: rlm_sql_mysql: Starting connect to
MySQL server
Tue Nov 22 15:19:40 2016 : Debug: rlm_sql_mysql: Connected to database
'pf' on 127.0.0.1 via TCP/IP, server version 5.5.50-MariaDB, protocol
version 10
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]:
returned from sql (rlm_sql)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [sql] = ok
Tue Nov 22 15:19:40 2016 : Debug: (0)     if (noop) {
Tue Nov 22 15:19:40 2016 : Debug: (0)     if (noop)  -> FALSE
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]: calling
attr_filter.accounting_response (rlm_attr_filter)
Tue Nov 22 15:19:40 2016 : Debug: %{User-Name}
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: attribute --> User-Name
Tue Nov 22 15:19:40 2016 : Debug: (0) attr_filter.accounting_response:
EXPAND %{User-Name}
Tue Nov 22 15:19:40 2016 : Debug: (0)
attr_filter.accounting_response:    --> 10:1f:74:b2:f6:a5
Tue Nov 22 15:19:40 2016 : Debug: (0) attr_filter.accounting_response:
Matched entry DEFAULT at line 12
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]:
returned from attr_filter.accounting_response (rlm_attr_filter)
Tue Nov 22 15:19:40 2016 : Debug: (0)    
[attr_filter.accounting_response] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]: calling
rest (rlm_rest)
Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Reserved connection (0)
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Expanding URI components
Tue Nov 22 15:19:40 2016 : Debug: http://127.0.0.1:7070
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: literal --> http://127.0.0.1:7070
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND http://127.0.0.1:7070
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:    --> http://127.0.0.1:7070
Tue Nov 22 15:19:40 2016 : Debug: //radius/rest/accounting
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: literal --> //radius/rest/accounting
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND //radius/rest/accounting
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:    --> //radius/rest/accounting
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/accounting"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Adding custom headers:
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   X-FreeRADIUS-Section:
accounting
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   X-FreeRADIUS-Server:
packetfence
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Request body content-type
will be "application/json"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "User-Name"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 17
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "10:1f:74:b2:f6:a5"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"NAS-IP-Address"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : ipaddr
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 13
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "172.20.135.77"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-Port"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 5
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 50108
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Called-Station-Id"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 17
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "dc:a5:f4:34:55:08"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Calling-Station-Id"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 17
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "10:1f:74:b2:f6:a5"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Proxy-State"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : octets
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 8
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "0x313339"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"NAS-Port-Type"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 2
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 15
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Status-Type"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 1
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 2
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Delay-Time"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 1
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 0
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Input-Octets"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 8
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 97158148
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Output-Octets"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 9
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 166844207
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Session-Id"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 8
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "000003B1"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Session-Time"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 4
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 1133
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Input-Packets"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 6
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 744486
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Output-Packets"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 7
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 1682264
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Terminate-Cause"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : integer
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 1
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : 2
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Event-Timestamp"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : date
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 24
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "nov 22 2016
15:26:16 EST"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-Port-Id"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: JSON Data:
{"User-Name":{"type":"string","value":["10:1f:74:b2:f6:a5"]},"NAS-IP-Address":{"type":"ipaddr","value":["172.20.135.77"]},"NAS-Port":{"type":"integer","value":[50108]},"Called-Station-Id":{"type":"string","value":["dc:a5:f4:34:55:08"]},"Calling-Station-Id":{"type":"string","value":["10:1f:74:b2:f6:a5"]},"Proxy-State":{"type":"octets","value":["0x313339"]},"NAS-Port-Type":{"type":"integer","value":[15]},"Acct-Status-Type":{"type":"integer","value":[2]},"Acct-Delay-Time":{"type":"integer","value":[0]},"Acct-Input-Octets":{"type":"integer","value":[97158148]},"Acct-Output-Octets":{"type":"integer","value":[166844207]},"Acct-Session-Id":{"type":"string","value":["000003B1"]},"Acct-Session-Time":{"type":"integer","value":[1133]},"Acct-Input-Packets":{"type":"integer","value":[744486]},"Acct-Output-Packets":{"type":"integer","value":[1682264]},"Acct-Terminate-Cause":{"type":"integer","value":[2]},"Event-Timestamp":{"type":"date","value":["nov
22 2016 15:26:16 EST"]},"NAS-Port-Id":{"type":"string","value":[
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Returning 1015 bytes of JSON
data (buffer full or chunk exceeded)
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 22
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"GigabitEthernet1\/0\/8"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Cisco-AVPair"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 25
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dc-profile-name=HP-Device"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 23
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dc-device-name=MSFT 5.0"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 29
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dc-device-class-tag=HP-Device"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 22
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dc-certainty-metric=10"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 82
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dc-opaque=\u0000\u0000\u0000\u0002\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 17
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "dc-protocol-map=9"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 84
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 35
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dhcp-option=\u0000<\u0000\bMSFT 5.0"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 37
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"dhcp-option=\u0000\f\u0000\tinverse-8"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 41
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"audit-session-id=AC158904000001485B34CE42"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 11
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "vlan-id=138"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 10
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "method=mab"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Stripped-User-Name"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 12
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "101f74b2f6a5"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Realm"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 4
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "null"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"Acct-Unique-Session-Id"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 32
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  :
"ddbfe7a1d200b1fb1576b92057e0bcc6"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : ipaddr
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 12
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "172.20.135.3"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: JSON Data:
"GigabitEthernet1\/0\/8"]},"Cisco-AVPair":{"type":"string","value":["dc-profile-name=HP-Device","dc-device-name=MSFT
5.0","dc-device-class-tag=HP-Device","dc-certainty-metric=10","dc-opaque=\u0000\u0000\u0000\u0002\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000","dc-protocol-map=9","dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+","dhcp-option=\u0000<\u0000\bMSFT
5.0","dhcp-option=\u0000\f\u0000\tinverse-8","audit-session-id=AC158904000001485B34CE42","vlan-id=138","method=mab"]},"Stripped-User-Name":{"type":"string","value":["101f74b2f6a5"]},"Realm":{"type":"string","value":["null"]},"Acct-Unique-Session-Id":{"type":"string","value":["ddbfe7a1d200b1fb1576b92057e0bcc6"]},"FreeRADIUS-Client-IP-Address":{"type":"ipaddr","value":["172.20.135.3"]}}
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Returning 791 bytes of JSON data
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Processing response header
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Status : 100 (Continue)
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Continuing...
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Processing response header
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Status : 200 (OK)
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : json
(application/json)
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Parsing attribute
"Reply-Message"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 13
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "Accounting ok"
Tue Nov 22 15:19:40 2016 : Debug: Accounting ok
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: literal --> Accounting ok
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND Accounting ok
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:    --> Accounting ok
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Reply-Message := "Accounting ok"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Parsing attribute
"reply:PacketFence-Authorization-Status"
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Type   : string
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Length : 5
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:   Value  : "allow"
Tue Nov 22 15:19:40 2016 : Debug: allow
Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree:
Tue Nov 22 15:19:40 2016 : Debug: literal --> allow
Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND allow
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:    --> allow
Tue Nov 22 15:19:40 2016 : Debug: (0) rest:
PacketFence-Authorization-Status := "allow"
Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Released connection (0)
Tue Nov 22 15:19:40 2016 : Info: rlm_rest (rest): Need 5 more
connections to reach 10 spares
Tue Nov 22 15:19:40 2016 : Info: rlm_rest (rest): Opening additional
connection (5), 1 of 59 pending slots used
Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Connecting to
"http://127.0.0.1:7070/"
Tue Nov 22 15:19:40 2016 : Debug: (0)     modsingle[accounting]:
returned from rest (rlm_rest)
Tue Nov 22 15:19:40 2016 : Debug: (0)     [rest] = updated
Tue Nov 22 15:19:40 2016 : Debug: (0)   } # accounting = updated
Tue Nov 22 15:19:40 2016 : Debug: (0) Sent Accounting-Response Id 77
from 172.20.135.1:1813 to 172.20.135.3:2940 length 0
Tue Nov 22 15:19:40 2016 : Debug: (0)   Reply-Message = "Accounting ok"
Tue Nov 22 15:19:40 2016 : Debug: (0)   PacketFence-Authorization-Status
= "allow"
Tue Nov 22 15:19:40 2016 : Debug: (0)   Proxy-State = 0x313339
Tue Nov 22 15:19:40 2016 : Debug: (0) Finished request
Tue Nov 22 15:19:40 2016 : Debug: (0) Cleaning up request packet ID 77
with timestamp +20
Tue Nov 22 15:19:40 2016 : Info: Ready to process requests

-- 
Fabrice Durand
fdurand@inverse.ca ::  +1.514.447.4918 (x135) ::  www.inverse.ca
Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu) and PacketFence (http://packetfence.org)