Hi, thanks to all for the help,
Right now I'm trying to solve this issue :
https://i.imgur.com/JQorvaV.png
After that the network works (I have internet access) but the message is
always "unable to detect network"
As requested I'll attach the logs (txt file) when logging in ,
/usr/local/pf/logs/radius-acct.log
/usr/local/pf/logs/packetfence.log
and
/usr/local/pf/var/run/radiusd-acct.sock
Thanks
El vie., 12 de abr. de 2019 a la(s) 08:13, Nicolas Quiniou-Briand (
[email protected]) escribió:
> Hello,
>
> On 2019-04-11 7:26 p.m., Leandro Ude via PacketFence-users wrote:
> > I still can't get to work es network detection http message
> >
> > I still get the red message "unable to detect network" :
>
> Check packetfence.log for your MAC address to see if PF is able to
> disconnect correctly your device through RADIUS.
> --
> Nicolas Quiniou-Briand
> [email protected] :: +1.514.447.4918 *140 :: https://inverse.ca
> Inverse inc. :: Leaders behind SOGo (https://sogo.nu), PacketFence
> (https://packetfence.org) and Fingerbank (http://fingerbank.org)
>
##################################################################################
tail -f /usr/local/pf/logs/radius-acct.log
##################################################################################
Apr 12 16:33:11 packetfence acct[14237]: rlm_sql (sql): Closing connection
(138): Hit idle_timeout, was idle for 61 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_sql (sql): Closing connection
(137): Hit idle_timeout, was idle for 61 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_sql (sql): Closing connection
(136): Hit idle_timeout, was idle for 61 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_sql (sql): Opening additional
connection (139), 1 of 64 pending slots used
Apr 12 16:33:11 packetfence acct[14237]: Need 2 more connections to reach min
connections (3)
Apr 12 16:33:11 packetfence acct[14237]: rlm_sql (sql): Opening additional
connection (140), 1 of 63 pending slots used
Apr 12 16:33:11 packetfence acct[14237]: rlm_rest (rest): Closing connection
(133): Hit idle_timeout, was idle for 66 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_rest (rest): Closing connection
(132): Hit idle_timeout, was idle for 61 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_rest (rest): Closing connection
(134): Hit idle_timeout, was idle for 61 seconds
Apr 12 16:33:11 packetfence acct[14237]: rlm_rest (rest): Opening additional
connection (135), 1 of 64 pending slots used
Apr 12 16:33:11 packetfence acct[14237]: Need 2 more connections to reach min
connections (3)
Apr 12 16:33:11 packetfence acct[14237]: rlm_rest (rest): Opening additional
connection (136), 1 of 63 pending slots used
Apr 12 16:33:45 packetfence acct[14237]: Need 1 more connections to reach min
connections (3)
Apr 12 16:33:45 packetfence acct[14237]: rlm_sql (sql): Opening additional
connection (141), 1 of 62 pending slots used
Apr 12 16:33:45 packetfence acct[14237]: Need 1 more connections to reach min
connections (3)
Apr 12 16:33:45 packetfence acct[14237]: rlm_rest (rest): Opening additional
connection (137), 1 of 62 pending slots used
Apr 12 16:33:59 packetfence acct[14237]: ... adding new socket command file
/usr/local/pf/var/run/radiusd-acct.sock
Apr 12 16:33:59 packetfence acct[14237]: ... shutting down socket command file
/usr/local/pf/var/run/radiusd-acct.sock
##################################################################################
tail -f /usr/local/pf/logs/packetfence.log
##################################################################################
Apr 12 16:33:08 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Instantiate profile Registration_Portal
(pf::Connection::ProfileFactory::_from_profile)
Apr 12 16:33:08 packetfence packetfence_httpd.portal: httpd.portal(3023) WARN:
[mac:c8:5b:76:e6:45:ef] Use of uninitialized value
$pf::web::constants::URL_NETWORK_LOGOFF in string eq at
/usr/local/pf/lib/captiveportal/PacketFence/DynamicRouting/Application.pm line
303.
(captiveportal::PacketFence::DynamicRouting::Application::process_destination_url)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found authentication source(s) :
'AUTH_SOURCE_OSEUDE_AD' for realm 'null'
(pf::config::util::filter_authentication_sources)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Authenticating user using sources :
AUTH_SOURCE_OSEUDE_AD
(captiveportal::PacketFence::DynamicRouting::Module::Authentication::Login::authenticate)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] [AUTH_SOURCE_OSEUDE_AD] Authentication successful for
pfence (pf::Authentication::Source::LDAPSource::authenticate)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Authentication successful for pfence in source
AUTH_SOURCE_OSEUDE_AD (AD) (pf::authentication::authenticate)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Successfully authenticated pfence
(captiveportal::PacketFence::DynamicRouting::Module::Authentication::Login::authenticate)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence pfqueue: pfqueue(3449) INFO: [mac:unknown] Already
did a person lookup for pfence (pf::lookup::person::lookup_person)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) WARN:
[mac:c8:5b:76:e6:45:ef] Calling match with empty/invalid rule class. Defaulting
to 'authentication' (pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Using sources AUTH_SOURCE_OSEUDE_AD for matching
(pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] LDAP testing connection (pf::LDAP::expire_if)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Matched rule (catch_alll) in source
AUTH_SOURCE_OSEUDE_AD, returning actions.
(pf::Authentication::Source::match_rule)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Matched rule (catch_alll) in source
AUTH_SOURCE_OSEUDE_AD, returning actions. (pf::Authentication::Source::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) WARN:
[mac:c8:5b:76:e6:45:ef] Calling match with empty/invalid rule class. Defaulting
to 'authentication' (pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Using sources AUTH_SOURCE_OSEUDE_AD for matching
(pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] LDAP testing connection (pf::LDAP::expire_if)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Matched rule (catch_alll) in source
AUTH_SOURCE_OSEUDE_AD, returning actions. (pf::Authentication::Source::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) WARN:
[mac:c8:5b:76:e6:45:ef] Calling match with empty/invalid rule class. Defaulting
to 'authentication' (pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Using sources AUTH_SOURCE_OSEUDE_AD for matching
(pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] LDAP testing connection (pf::LDAP::expire_if)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) WARN:
[mac:c8:5b:76:e6:45:ef] Calling match with empty/invalid rule class. Defaulting
to 'authentication' (pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Using sources AUTH_SOURCE_OSEUDE_AD for matching
(pf::authentication::match)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] LDAP testing connection (pf::LDAP::expire_if)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3023) INFO:
[mac:c8:5b:76:e6:45:ef] Found source AUTH_SOURCE_OSEUDE_AD in session.
(Class::MOP::Class:::around)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] Instantiate profile Registration_Portal
(pf::Connection::ProfileFactory::_from_profile)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) WARN:
[mac:c8:5b:76:e6:45:ef] Use of uninitialized value
$pf::web::constants::URL_NETWORK_LOGOFF in string eq at
/usr/local/pf/lib/captiveportal/PacketFence/DynamicRouting/Application.pm line
303.
(captiveportal::PacketFence::DynamicRouting::Application::process_destination_url)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] No provisioner found for c8:5b:76:e6:45:ef. Continuing.
(captiveportal::PacketFence::DynamicRouting::Module::Provisioning::execute_child)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] User pfence has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] violation 1300003 force-closed for c8:5b:76:e6:45:ef
(pf::violation::violation_force_close)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) INFO:
[mac:c8:5b:76:e6:45:ef] Instantiate profile Registration_Portal
(pf::Connection::ProfileFactory::_from_profile)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3761) WARN:
[mac:c8:5b:76:e6:45:ef] Use of uninitialized value in concatenation (.) or
string at
/usr/local/pf/lib/captiveportal/PacketFence/DynamicRouting/Module/Root.pm line
89.
(captiveportal::PacketFence::DynamicRouting::Module::Root::release)
Apr 12 16:33:09 packetfence pfdhcp[6692]: t=2019-04-12T16:33:09-0300 lvl=info
msg="DHCPREQUEST for 192.168.60.85 from c8:5b:76:e6:45:ef (LAPTOP-RIK85D8U)"
pid=6692 mac=c8:5b:76:e6:45:ef
Apr 12 16:33:09 packetfence pfdhcp[6692]: t=2019-04-12T16:33:09-0300 lvl=info
msg="DHCPACK on 192.168.60.85 to c8:5b:76:e6:45:ef (LAPTOP-RIK85D8U)" pid=6692
mac=c8:5b:76:e6:45:ef
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) WARN:
[mac:unknown] locale from the URL is not supported
(pf::Portal::Session::getLanguages)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) WARN:
[mac:c8:5b:76:e6:45:ef] locale from the URL is not supported
(pf::Portal::Session::getLanguages)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] Instantiate profile Registration_Portal
(pf::Connection::ProfileFactory::_from_profile)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) WARN:
[mac:c8:5b:76:e6:45:ef] locale from the URL is not supported
(captiveportal::PacketFence::Controller::Root::getLanguages)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) WARN:
[mac:c8:5b:76:e6:45:ef] Use of uninitialized value
$pf::web::constants::URL_NETWORK_LOGOFF in string eq at
/usr/local/pf/lib/captiveportal/PacketFence/DynamicRouting/Application.pm line
303.
(captiveportal::PacketFence::DynamicRouting::Application::process_destination_url)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] Releasing device
(captiveportal::PacketFence::DynamicRouting::Module::Root::release)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] User default has authenticated on the portal.
(Class::MOP::Class:::after)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) WARN:
[mac:c8:5b:76:e6:45:ef] locale from the URL is not supported
(pf::Portal::Session::getLanguages)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] re-evaluating access (manage_register called)
(pf::enforcement::reevaluate_access)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] VLAN reassignment is forced.
(pf::enforcement::_should_we_reassign_vlan)
Apr 12 16:33:09 packetfence packetfence_httpd.portal: httpd.portal(3902) INFO:
[mac:c8:5b:76:e6:45:ef] switch port is (192.168.1.20) ifIndex 10105 connection
type: Wired MAC Auth (pf::enforcement::_vlan_reevaluation)
Apr 12 16:33:10 packetfence pfipset[6702]: t=2019-04-12T16:33:10-0300 lvl=info
msg="No Inline Network bypass ipsets reload" pid=6702
Apr 12 16:33:10 packetfence pfqueue: pfqueue(3974) INFO:
[mac:c8:5b:76:e6:45:ef] deauthenticating
(pf::Switch::Cisco::Catalyst_2960::radiusDisconnect)
Apr 12 16:33:10 packetfence pfqueue: pfqueue(3974) WARN:
[mac:c8:5b:76:e6:45:ef] Unknown vendor attribute 9/252 for unpack()
(Net::Radius::Packet::unpack)
Apr 12 16:33:10 packetfence pfqueue: Unknown vendor attribute 9/252 for unpack()
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] handling radius autz request: from switch_ip =>
(192.168.1.20), connection_type => Ethernet-NoEAP,switch_mac =>
(00:87:31:15:0f:05), mac => [c8:5b:76:e6:45:ef], port => 10105, username =>
"c85b76e645ef" (pf::radius::authorize)
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] Instantiate profile Registration_Portal
(pf::Connection::ProfileFactory::_from_profile)
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] Connection type is Ethernet-NoEAP. Getting role from
node_info (pf::role::getRegisteredRole)
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] Username was defined "c85b76e645ef" - returning role
'default' (pf::role::getRegisteredRole)
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] PID: "pfence", Status: reg Returned VLAN: (undefined),
Role: default (pf::role::fetchRoleForNode)
Apr 12 16:33:10 packetfence packetfence_httpd.aaa: httpd.aaa(7475) INFO:
[mac:c8:5b:76:e6:45:ef] (192.168.1.20) Added VLAN 10 to the returned RADIUS
Access-Accept (pf::Switch::returnRadiusAccessAccept)
Apr 12 16:33:45 packetfence pfqueue: pfqueue(3670) WARN:
[mac:c8:5b:76:e6:45:ef] Unable to match MAC address to IP '192.168.1.50'
(pf::ip4log::ip2mac)
Apr 12 16:33:45 packetfence pfqueue: pfqueue(3670) INFO:
[mac:c8:5b:76:e6:45:ef] oldip (192.168.60.85) and newip (192.168.1.50) are
different for c8:5b:76:e6:45:ef - closing ip4log entry (pf::api::update_ip4log)
##################################################################################
raddebug -t 300 -f /usr/local/pf/var/run/radiusd-acct.sock
##################################################################################
(12771) Fri Apr 12 16:33:11 2019: Debug: Received Accounting-Request Id 99 from
192.168.1.20:1646 to 192.168.1.2:1813 length 253
(12771) Fri Apr 12 16:33:11 2019: Debug: Framed-IP-Address = 192.168.60.85
(12771) Fri Apr 12 16:33:11 2019: Debug: User-Name = "c85b76e645ef"
(12771) Fri Apr 12 16:33:11 2019: Debug: Cisco-AVPair =
"audit-session-id=C0A80114000002653826964F"
(12771) Fri Apr 12 16:33:11 2019: Debug: Cisco-AVPair = "vlan-id=10"
(12771) Fri Apr 12 16:33:11 2019: Debug: Cisco-AVPair = "method=mab"
(12771) Fri Apr 12 16:33:11 2019: Debug: Called-Station-Id =
"00-87-31-15-0F-05"
(12771) Fri Apr 12 16:33:11 2019: Debug: Calling-Station-Id =
"C8-5B-76-E6-45-EF"
(12771) Fri Apr 12 16:33:11 2019: Debug: NAS-IP-Address = 192.168.1.20
(12771) Fri Apr 12 16:33:11 2019: Debug: NAS-Port-Id = "GigabitEthernet0/5"
(12771) Fri Apr 12 16:33:11 2019: Debug: NAS-Port-Type = Ethernet
(12771) Fri Apr 12 16:33:11 2019: Debug: NAS-Port = 50105
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Session-Id = "00000230"
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Status-Type = Interim-Update
(12771) Fri Apr 12 16:33:11 2019: Debug: Event-Timestamp = "Apr 12 2019
16:32:46 -03"
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Input-Octets = 120417081
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Output-Octets = 1345478751
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Input-Packets = 1071366
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Output-Packets = 1581365
(12771) Fri Apr 12 16:33:11 2019: Debug: Acct-Delay-Time = 0
(12771) Fri Apr 12 16:33:11 2019: Debug: # Executing section preacct from file
/usr/local/pf/raddb/sites-enabled/packetfence
(12771) Fri Apr 12 16:33:11 2019: Debug: preacct {
(12771) Fri Apr 12 16:33:11 2019: Debug: [preprocess] = ok
(12771) Fri Apr 12 16:33:11 2019: Debug: policy packetfence-set-tenant-id {
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> 0
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12771) Fri Apr 12 16:33:11 2019: Debug: update control {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{User-Name}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> c85b76e645ef
(12771) Fri Apr 12 16:33:11 2019: Debug: SQL-User-Name set to
'c85b76e645ef'
(12771) Fri Apr 12 16:33:11 2019: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'192.168.1.20'), 0)
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'%{Packet-Src-IP-Address}'), 0)}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> 1
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update control = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy
packetfence-set-tenant-id = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: policy set_calling_station_id {
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: 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
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: update request {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> c8:5b:76:e6:45:ef
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update request = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: [updated] = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: } # 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
(12771) Fri Apr 12 16:33:11 2019: Debug: ... skipping else: Preceding
"if" was taken
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy set_calling_station_id
= updated
(12771) Fri Apr 12 16:33:11 2019: Debug: policy rewrite_calling_station_id {
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: 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
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: update request {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> c8:5b:76:e6:45:ef
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update request = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: [updated] = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: } # 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
(12771) Fri Apr 12 16:33:11 2019: Debug: ... skipping else: Preceding
"if" was taken
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy
rewrite_calling_station_id = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: policy rewrite_called_station_id {
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: 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
(12771) Fri Apr 12 16:33:11 2019: Debug: 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))
{
(12771) Fri Apr 12 16:33:11 2019: Debug: update request {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> 00:87:31:15:0f:05
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update request = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: if ("%{8}") {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{8}
(12771) Fri Apr 12 16:33:11 2019: Debug: -->
(12771) Fri Apr 12 16:33:11 2019: Debug: if ("%{8}") -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif ( (Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif ( (Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif (Aruba-Essid-Name) {
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif (Aruba-Essid-Name) ->
FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{Cisco-AVPair}
(12771) Fri Apr 12 16:33:11 2019: Debug: -->
audit-session-id=C0A80114000002653826964F
(12771) Fri Apr 12 16:33:11 2019: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: [updated] = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: } # 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
(12771) Fri Apr 12 16:33:11 2019: Debug: ... skipping else: Preceding
"if" was taken
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy
rewrite_called_station_id = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: policy acct_unique {
(12771) Fri Apr 12 16:33:11 2019: Debug: if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{string:Class}
(12771) Fri Apr 12 16:33:11 2019: Debug: -->
(12771) Fri Apr 12 16:33:11 2019: Debug: if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: else {
(12771) Fri Apr 12 16:33:11 2019: Debug: update request {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{md5:%{User-Name},%{Calling-Station-Id},%{Acct-Session-Id}}
(12771) Fri Apr 12 16:33:11 2019: Debug: -->
5ce97061034da8db76dcd0fed4cede61
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update request = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: } # else = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy acct_unique = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: suffix: Checking for suffix after "@"
(12771) Fri Apr 12 16:33:11 2019: Debug: suffix: No '@' in User-Name =
"c85b76e645ef", skipping NULL due to config.
(12771) Fri Apr 12 16:33:11 2019: Debug: [suffix] = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: Checking for prefix before
"\"
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: No '\' in User-Name =
"c85b76e645ef", looking up realm NULL
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: Found realm "null"
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: Adding Stripped-User-Name =
"c85b76e645ef"
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: Adding Realm = "null"
(12771) Fri Apr 12 16:33:11 2019: Debug: ntdomain: Accounting realm is LOCAL
(12771) Fri Apr 12 16:33:11 2019: Debug: [ntdomain] = ok
(12771) Fri Apr 12 16:33:11 2019: Debug: [files] = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: } # preacct = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: # Executing section accounting from
file /usr/local/pf/raddb/sites-enabled/packetfence
(12771) Fri Apr 12 16:33:11 2019: Debug: accounting {
(12771) Fri Apr 12 16:33:11 2019: Debug: update {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND %{Packet-Src-IP-Address}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> 192.168.1.20
(12771) Fri Apr 12 16:33:11 2019: Debug: } # update = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: policy packetfence-set-tenant-id {
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12771) Fri Apr 12 16:33:11 2019: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(12771) Fri Apr 12 16:33:11 2019: Debug: --> 1
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(12771) Fri Apr 12 16:33:11 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: } # policy
packetfence-set-tenant-id = noop
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: EXPAND
%{tolower:type.%{Acct-Status-Type}.query}
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: --> type.interim-update.query
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: Using query template 'query'
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: EXPAND %{User-Name}
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: --> c85b76e645ef
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: SQL-User-Name set to
'c85b76e645ef'
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: EXPAND CALL acct_update (
FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}',
'%{%{Acct-Session-Time}:-0}', '%{%{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-Status-Type}','%{NAS-Identifier}', '%{Called-Station-SSID}',
'%{control:PacketFence-Tenant-Id}')
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: --> CALL acct_update (
FROM_UNIXTIME(1555097566), '192.168.60.85', '0', '0' << 32 | '120417081', '0'
<< 32 | '1345478751', '5ce97061034da8db76dcd0fed4cede61', '00000230',
'c85b76e645ef', 'null', '192.168.1.20', 'GigabitEthernet0/5', 'Ethernet', '',
'', '00:87:31:15:0f:05', 'c8:5b:76:e6:45:ef', '', '', 'Interim-Update','', '',
'1')
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: Executing query: CALL acct_update
( FROM_UNIXTIME(1555097566), '192.168.60.85', '0', '0' << 32 | '120417081', '0'
<< 32 | '1345478751', '5ce97061034da8db76dcd0fed4cede61', '00000230',
'c85b76e645ef', 'null', '192.168.1.20', 'GigabitEthernet0/5', 'Ethernet', '',
'', '00:87:31:15:0f:05', 'c8:5b:76:e6:45:ef', '', '', 'Interim-Update','', '',
'1')
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: SQL query returned: success
(12771) Fri Apr 12 16:33:11 2019: Debug: sql: 1 record(s) updated
(12771) Fri Apr 12 16:33:11 2019: Debug: [sql] = ok
(12771) Fri Apr 12 16:33:11 2019: Debug: if (noop) {
(12771) Fri Apr 12 16:33:11 2019: Debug: if (noop) -> FALSE
(12771) Fri Apr 12 16:33:11 2019: Debug: attr_filter.accounting_response:
EXPAND %{User-Name}
(12771) Fri Apr 12 16:33:11 2019: Debug: attr_filter.accounting_response:
--> c85b76e645ef
(12771) Fri Apr 12 16:33:11 2019: Debug: attr_filter.accounting_response:
Matched entry DEFAULT at line 12
(12771) Fri Apr 12 16:33:11 2019: Debug: [attr_filter.accounting_response]
= updated
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Expanding URI components
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: EXPAND http://127.0.0.1:7070
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: --> http://127.0.0.1:7070
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: EXPAND //radius/rest/accounting
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: --> //radius/rest/accounting
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/accounting";
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute "User-Name"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"NAS-IP-Address"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute "NAS-Port"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Framed-IP-Address"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Called-Station-Id"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Calling-Station-Id"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"NAS-Port-Type"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Status-Type"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Delay-Time"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Input-Octets"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Output-Octets"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Session-Id"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Input-Packets"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Output-Packets"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Event-Timestamp"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute "NAS-Port-Id"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute "Cisco-AVPair"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Returning 980 bytes of JSON data
(buffer full or chunk exceeded)
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Stripped-User-Name"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute "Realm"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"Acct-Unique-Session-Id"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Processing response header
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Status : 100 (Continue)
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Continuing...
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Processing response header
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Status : 200 (OK)
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Type : json
(application/json)
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Parsing attribute
"control:PacketFence-Authorization-Status"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: EXPAND allow
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: --> allow
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: PacketFence-Authorization-Status
:= "allow"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Parsing attribute "Reply-Message"
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: EXPAND Accounting ok
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: --> Accounting ok
(12771) Fri Apr 12 16:33:11 2019: Debug: rest: Reply-Message := "Accounting ok"
(12771) Fri Apr 12 16:33:11 2019: Debug: [rest] = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: } # accounting = updated
(12771) Fri Apr 12 16:33:11 2019: Debug: Sent Accounting-Response Id 99 from
192.168.1.2:1813 to 192.168.1.20:1646 length 0
(12771) Fri Apr 12 16:33:11 2019: Debug: Reply-Message = "Accounting ok"
(12771) Fri Apr 12 16:33:11 2019: Debug: Finished request
(12771) Fri Apr 12 16:33:12 2019: Debug: Cleaning up request packet ID 99 with
timestamp +190170
(12772) Fri Apr 12 16:33:15 2019: Debug: Received Status-Server Id 164 from
127.0.0.1:38950 to 127.0.0.1:18122 length 50
(12772) Fri Apr 12 16:33:15 2019: Debug: Message-Authenticator =
0x642288664b89cad6fd695ea418c9e560
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Statistics-Type = 15
(12772) Fri Apr 12 16:33:15 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/status
(12772) Fri Apr 12 16:33:15 2019: Debug: Autz-Type Status-Server {
(12772) Fri Apr 12 16:33:15 2019: Debug: [ok] = ok
(12772) Fri Apr 12 16:33:15 2019: Debug: } # Autz-Type Status-Server = ok
(12772) Fri Apr 12 16:33:15 2019: Debug: Sent Access-Accept Id 164 from
127.0.0.1:18122 to 127.0.0.1:38950 length 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Access-Requests =
12674
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Access-Rejects = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Access-Challenges = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Auth-Responses = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Auth-Malformed-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Auth-Invalid-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Auth-Dropped-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types
= 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Accounting-Requests
= 99
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Accounting-Responses = 99
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Acct-Malformed-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Acct-Invalid-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Acct-Dropped-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types
= 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Accepts = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Rejects = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Challenges = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Responses = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Responses = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
(12772) Fri Apr 12 16:33:15 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
(12772) Fri Apr 12 16:33:15 2019: Debug: Finished request
(12772) Fri Apr 12 16:33:20 2019: Debug: Cleaning up request packet ID 164 with
timestamp +190174
(12773) Fri Apr 12 16:33:30 2019: Debug: Received Status-Server Id 210 from
127.0.0.1:50129 to 127.0.0.1:18122 length 50
(12773) Fri Apr 12 16:33:30 2019: Debug: Message-Authenticator =
0x3e9a2d9b4fe5e0118d170987b4badc3f
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Statistics-Type = 15
(12773) Fri Apr 12 16:33:30 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/status
(12773) Fri Apr 12 16:33:30 2019: Debug: Autz-Type Status-Server {
(12773) Fri Apr 12 16:33:30 2019: Debug: [ok] = ok
(12773) Fri Apr 12 16:33:30 2019: Debug: } # Autz-Type Status-Server = ok
(12773) Fri Apr 12 16:33:30 2019: Debug: Sent Access-Accept Id 210 from
127.0.0.1:18122 to 127.0.0.1:50129 length 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Access-Requests =
12675
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Access-Rejects = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Access-Challenges = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Auth-Responses = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Auth-Malformed-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Auth-Invalid-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Auth-Dropped-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types
= 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Accounting-Requests
= 99
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Accounting-Responses = 99
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Acct-Malformed-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Acct-Invalid-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Acct-Dropped-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types
= 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Accepts = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Rejects = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Challenges = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Responses = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Responses = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
(12773) Fri Apr 12 16:33:30 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
(12773) Fri Apr 12 16:33:30 2019: Debug: Finished request
(12773) Fri Apr 12 16:33:35 2019: Debug: Cleaning up request packet ID 210 with
timestamp +190189
(12774) Fri Apr 12 16:33:45 2019: Debug: Received Status-Server Id 117 from
127.0.0.1:59646 to 127.0.0.1:18122 length 50
(12774) Fri Apr 12 16:33:45 2019: Debug: Message-Authenticator =
0x482484a6646e8f80b6460088f79990c0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Statistics-Type = 15
(12774) Fri Apr 12 16:33:45 2019: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/status
(12774) Fri Apr 12 16:33:45 2019: Debug: Autz-Type Status-Server {
(12774) Fri Apr 12 16:33:45 2019: Debug: [ok] = ok
(12774) Fri Apr 12 16:33:45 2019: Debug: } # Autz-Type Status-Server = ok
(12774) Fri Apr 12 16:33:45 2019: Debug: Sent Access-Accept Id 117 from
127.0.0.1:18122 to 127.0.0.1:59646 length 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Access-Requests =
12676
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Access-Accepts = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Access-Rejects = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Access-Challenges = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Auth-Responses = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Auth-Malformed-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Auth-Invalid-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Auth-Dropped-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Auth-Unknown-Types
= 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Accounting-Requests
= 99
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Accounting-Responses = 99
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Acct-Malformed-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Acct-Invalid-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Acct-Dropped-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: FreeRADIUS-Total-Acct-Unknown-Types
= 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Accepts = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Rejects = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Challenges = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Responses = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Responses = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
(12774) Fri Apr 12 16:33:45 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
(12774) Fri Apr 12 16:33:45 2019: Debug: Finished request
(12775) Fri Apr 12 16:33:45 2019: Debug: Received Accounting-Request Id 100
from 192.168.1.20:1646 to 192.168.1.2:1813 length 253
(12775) Fri Apr 12 16:33:45 2019: Debug: User-Name = "c85b76e645ef"
(12775) Fri Apr 12 16:33:45 2019: Debug: Cisco-AVPair =
"audit-session-id=C0A80114000002653826964F"
(12775) Fri Apr 12 16:33:45 2019: Debug: Cisco-AVPair = "vlan-id=10"
(12775) Fri Apr 12 16:33:45 2019: Debug: Cisco-AVPair = "method=mab"
(12775) Fri Apr 12 16:33:45 2019: Debug: Called-Station-Id =
"00-87-31-15-0F-05"
(12775) Fri Apr 12 16:33:45 2019: Debug: Calling-Station-Id =
"C8-5B-76-E6-45-EF"
(12775) Fri Apr 12 16:33:45 2019: Debug: NAS-IP-Address = 192.168.1.20
(12775) Fri Apr 12 16:33:45 2019: Debug: NAS-Port-Id = "GigabitEthernet0/5"
(12775) Fri Apr 12 16:33:45 2019: Debug: NAS-Port-Type = Ethernet
(12775) Fri Apr 12 16:33:45 2019: Debug: NAS-Port = 50105
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Session-Id = "00000230"
(12775) Fri Apr 12 16:33:45 2019: Debug: Framed-IP-Address = 192.168.1.50
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Status-Type = Interim-Update
(12775) Fri Apr 12 16:33:45 2019: Debug: Event-Timestamp = "Apr 12 2019
16:33:20 -03"
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Input-Octets = 120421004
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Output-Octets = 1345492978
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Input-Packets = 1071405
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Output-Packets = 1581419
(12775) Fri Apr 12 16:33:45 2019: Debug: Acct-Delay-Time = 0
(12775) Fri Apr 12 16:33:45 2019: Debug: # Executing section preacct from file
/usr/local/pf/raddb/sites-enabled/packetfence
(12775) Fri Apr 12 16:33:45 2019: Debug: preacct {
(12775) Fri Apr 12 16:33:45 2019: Debug: [preprocess] = ok
(12775) Fri Apr 12 16:33:45 2019: Debug: policy packetfence-set-tenant-id {
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> 0
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12775) Fri Apr 12 16:33:45 2019: Debug: update control {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{User-Name}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> c85b76e645ef
(12775) Fri Apr 12 16:33:45 2019: Debug: SQL-User-Name set to
'c85b76e645ef'
(12775) Fri Apr 12 16:33:45 2019: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'192.168.1.20'), 0)
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'%{Packet-Src-IP-Address}'), 0)}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> 1
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update control = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy
packetfence-set-tenant-id = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: policy set_calling_station_id {
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: 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
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: update request {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> c8:5b:76:e6:45:ef
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update request = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: [updated] = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: } # 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
(12775) Fri Apr 12 16:33:45 2019: Debug: ... skipping else: Preceding
"if" was taken
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy set_calling_station_id
= updated
(12775) Fri Apr 12 16:33:45 2019: Debug: policy rewrite_calling_station_id {
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: 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
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: update request {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> c8:5b:76:e6:45:ef
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update request = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: [updated] = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: } # 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
(12775) Fri Apr 12 16:33:45 2019: Debug: ... skipping else: Preceding
"if" was taken
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy
rewrite_calling_station_id = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: policy rewrite_called_station_id {
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: 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
(12775) Fri Apr 12 16:33:45 2019: Debug: 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))
{
(12775) Fri Apr 12 16:33:45 2019: Debug: update request {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> 00:87:31:15:0f:05
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update request = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: if ("%{8}") {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{8}
(12775) Fri Apr 12 16:33:45 2019: Debug: -->
(12775) Fri Apr 12 16:33:45 2019: Debug: if ("%{8}") -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif ( (Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) {
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif ( (Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif (Aruba-Essid-Name) {
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif (Aruba-Essid-Name) ->
FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{Cisco-AVPair}
(12775) Fri Apr 12 16:33:45 2019: Debug: -->
audit-session-id=C0A80114000002653826964F
(12775) Fri Apr 12 16:33:45 2019: Debug: elsif ( (Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: [updated] = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: } # 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
(12775) Fri Apr 12 16:33:45 2019: Debug: ... skipping else: Preceding
"if" was taken
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy
rewrite_called_station_id = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: policy acct_unique {
(12775) Fri Apr 12 16:33:45 2019: Debug: if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{string:Class}
(12775) Fri Apr 12 16:33:45 2019: Debug: -->
(12775) Fri Apr 12 16:33:45 2019: Debug: if ("%{string:Class}" =~
/ai:([0-9a-f]{32})/i) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: else {
(12775) Fri Apr 12 16:33:45 2019: Debug: update request {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{md5:%{User-Name},%{Calling-Station-Id},%{Acct-Session-Id}}
(12775) Fri Apr 12 16:33:45 2019: Debug: -->
5ce97061034da8db76dcd0fed4cede61
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update request = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: } # else = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy acct_unique = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: suffix: Checking for suffix after "@"
(12775) Fri Apr 12 16:33:45 2019: Debug: suffix: No '@' in User-Name =
"c85b76e645ef", skipping NULL due to config.
(12775) Fri Apr 12 16:33:45 2019: Debug: [suffix] = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: Checking for prefix before
"\"
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: No '\' in User-Name =
"c85b76e645ef", looking up realm NULL
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: Found realm "null"
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: Adding Stripped-User-Name =
"c85b76e645ef"
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: Adding Realm = "null"
(12775) Fri Apr 12 16:33:45 2019: Debug: ntdomain: Accounting realm is LOCAL
(12775) Fri Apr 12 16:33:45 2019: Debug: [ntdomain] = ok
(12775) Fri Apr 12 16:33:45 2019: Debug: [files] = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: } # preacct = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: # Executing section accounting from
file /usr/local/pf/raddb/sites-enabled/packetfence
(12775) Fri Apr 12 16:33:45 2019: Debug: accounting {
(12775) Fri Apr 12 16:33:45 2019: Debug: update {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND %{Packet-Src-IP-Address}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> 192.168.1.20
(12775) Fri Apr 12 16:33:45 2019: Debug: } # update = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: policy packetfence-set-tenant-id {
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(12775) Fri Apr 12 16:33:45 2019: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(12775) Fri Apr 12 16:33:45 2019: Debug: --> 1
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(12775) Fri Apr 12 16:33:45 2019: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: } # policy
packetfence-set-tenant-id = noop
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: EXPAND
%{tolower:type.%{Acct-Status-Type}.query}
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: --> type.interim-update.query
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: Using query template 'query'
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: EXPAND %{User-Name}
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: --> c85b76e645ef
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: SQL-User-Name set to
'c85b76e645ef'
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: EXPAND CALL acct_update (
FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}',
'%{%{Acct-Session-Time}:-0}', '%{%{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-Status-Type}','%{NAS-Identifier}', '%{Called-Station-SSID}',
'%{control:PacketFence-Tenant-Id}')
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: --> CALL acct_update (
FROM_UNIXTIME(1555097600), '192.168.1.50', '0', '0' << 32 | '120421004', '0' <<
32 | '1345492978', '5ce97061034da8db76dcd0fed4cede61', '00000230',
'c85b76e645ef', 'null', '192.168.1.20', 'GigabitEthernet0/5', 'Ethernet', '',
'', '00:87:31:15:0f:05', 'c8:5b:76:e6:45:ef', '', '', 'Interim-Update','', '',
'1')
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: Executing query: CALL acct_update
( FROM_UNIXTIME(1555097600), '192.168.1.50', '0', '0' << 32 | '120421004', '0'
<< 32 | '1345492978', '5ce97061034da8db76dcd0fed4cede61', '00000230',
'c85b76e645ef', 'null', '192.168.1.20', 'GigabitEthernet0/5', 'Ethernet', '',
'', '00:87:31:15:0f:05', 'c8:5b:76:e6:45:ef', '', '', 'Interim-Update','', '',
'1')
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: SQL query returned: success
(12775) Fri Apr 12 16:33:45 2019: Debug: sql: 1 record(s) updated
(12775) Fri Apr 12 16:33:45 2019: Debug: [sql] = ok
(12775) Fri Apr 12 16:33:45 2019: Debug: if (noop) {
(12775) Fri Apr 12 16:33:45 2019: Debug: if (noop) -> FALSE
(12775) Fri Apr 12 16:33:45 2019: Debug: attr_filter.accounting_response:
EXPAND %{User-Name}
(12775) Fri Apr 12 16:33:45 2019: Debug: attr_filter.accounting_response:
--> c85b76e645ef
(12775) Fri Apr 12 16:33:45 2019: Debug: attr_filter.accounting_response:
Matched entry DEFAULT at line 12
(12775) Fri Apr 12 16:33:45 2019: Debug: [attr_filter.accounting_response]
= updated
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Expanding URI components
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: EXPAND http://127.0.0.1:7070
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: --> http://127.0.0.1:7070
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: EXPAND //radius/rest/accounting
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: --> //radius/rest/accounting
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/accounting";
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute "User-Name"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"NAS-IP-Address"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute "NAS-Port"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Framed-IP-Address"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Called-Station-Id"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Calling-Station-Id"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"NAS-Port-Type"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Status-Type"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Delay-Time"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Input-Octets"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Output-Octets"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Session-Id"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Input-Packets"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Output-Packets"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Event-Timestamp"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute "NAS-Port-Id"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute "Cisco-AVPair"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Returning 1023 bytes of JSON
data (buffer full or chunk exceeded)
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Stripped-User-Name"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute "Realm"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"Acct-Unique-Session-Id"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Encoding attribute
"FreeRADIUS-Client-IP-Address"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Processing response header
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Status : 100 (Continue)
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Continuing...
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Processing response header
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Status : 200 (OK)
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Type : json
(application/json)
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Parsing attribute
"control:PacketFence-Authorization-Status"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: EXPAND allow
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: --> allow
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: PacketFence-Authorization-Status
:= "allow"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Parsing attribute "Reply-Message"
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: EXPAND Accounting ok
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: --> Accounting ok
(12775) Fri Apr 12 16:33:45 2019: Debug: rest: Reply-Message := "Accounting ok"
(12775) Fri Apr 12 16:33:45 2019: Debug: [rest] = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: } # accounting = updated
(12775) Fri Apr 12 16:33:45 2019: Debug: Sent Accounting-Response Id 100 from
192.168.1.2:1813 to 192.168.1.20:1646 length 0
(12775) Fri Apr 12 16:33:45 2019: Debug: Reply-Message = "Accounting ok"
(12775) Fri Apr 12 16:33:45 2019: Debug: Finished request
(12775) Fri Apr 12 16:33:46 2019: Debug: Cleaning up request packet ID 100 with
timestamp +190204
(12774) Fri Apr 12 16:33:50 2019: Debug: Cleaning up request packet ID 117 with
timestamp +190204
_______________________________________________
PacketFence-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/packetfence-users
