im using packetfence 8.0.1
my user from other university complain can't connect to eduroam with local
REALM my university.
from raddebug output i see error message like this.
(79) Wed Jun 6 10:17:11 2018: ERROR: rest: Server returned:
(79) Wed Jun 6 10:17:11 2018: ERROR: rest: {"Reply-Message":"Network
device does not support this mode of
operation","control:PacketFence-Eap-Type":26,"control:PacketFence-Authorization-Status":"allow","control:PacketFence-Mac":"64:cc:2e:4f:39:3b","control:PacketFence-Switch-Ip-Address":"10.43.1.2","control:PacketFence-Request-Time":1528255031,"control:PacketFence-UserName":"
ae...@xyz.edu
","control:PacketFence-Connection-Type":"Ethernet-EAP","control:PacketFence-Switch-Mac":"38:ff:36:c2:33:69","control:PacketFence-Switch-Id":"10.43.1.2"}
packetfence log:
Jun 6 10:16:48 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
INFO: [mac:64:cc:2e:4f:39:3b] handling radius autz request: from switch_ip
=> (10.43.1.2), connection_type => Ethernet-EAP,switch_mac =>
(38:ff:36:c2:33:69), mac => [64:cc:2e:4f:39:3b], port => , username => "
ae...@xyz.edu" (pf::radius::authorize)
Jun 6 10:16:48 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
ERROR: [mac:64:cc:2e:4f:39:3b] Wired 802.1X is not supported on switch type
pf::Switch::Ruckus. Please let us know what hardware you are using.
(pf::Switch::supportsWiredDot1x)
Jun 6 10:16:48 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
WARN: [mac:64:cc:2e:4f:39:3b] (10.43.1.2) Sending REJECT since switch is
unsupported (pf::radius::_switchUnsupportedReply)
Jun 6 10:17:11 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
WARN: [mac:64:cc:2e:4f:39:3b] Use of uninitialized value $nas_port in
concatenation (.) or string at /usr/local/pf/lib/pf/Switch.pm line 2545.
(pf::Switch::NasPortToIfIndex)
Jun 6 10:17:11 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
WARN: [mac:64:cc:2e:4f:39:3b] Use of uninitialized value $port in
concatenation (.) or string at /usr/local/pf/lib/pf/radius.pm line 179.
(pf::radius::authorize)
Jun 6 10:17:11 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
INFO: [mac:64:cc:2e:4f:39:3b] handling radius autz request: from switch_ip
=> (10.43.1.2), connection_type => Ethernet-EAP,switch_mac =>
(38:ff:36:c2:33:69), mac => [64:cc:2e:4f:39:3b], port => , username => "
ae...@xyz.edu" (pf::radius::authorize)
Jun 6 10:17:11 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
ERROR: [mac:64:cc:2e:4f:39:3b] Wired 802.1X is not supported on switch type
pf::Switch::Ruckus. Please let us know what hardware you are using.
(pf::Switch::supportsWiredDot1x)
Jun 6 10:17:11 PacketFence-ZEN packetfence_httpd.aaa: httpd.aaa(2986)
WARN: [mac:64:cc:2e:4f:39:3b] (10.43.1.2) Sending REJECT since switch is
unsupported (pf::radius::_switchUnsupportedReply)
please give me some advice.
thanks.
(79) Wed Jun 6 10:17:11 2018: Debug: User-Name = "ae...@xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: Calling-Station-Id = "64-CC-2E-4F-39-3B"
(79) Wed Jun 6 10:17:11 2018: Debug: NAS-IP-Address = 10.43.1.2
(79) Wed Jun 6 10:17:11 2018: Debug: Called-Station-Id =
"38-FF-36-C2-33-69:eduroam"
(79) Wed Jun 6 10:17:11 2018: Debug: NAS-Identifier = "38-FF-36-C2-33-69"
(79) Wed Jun 6 10:17:11 2018: Debug: EAP-Message =
0x0208002b190017030100207800450c2f957824b9747d285f35b4bfb1a1714f27697c43619591d46a9f04b5
(79) Wed Jun 6 10:17:11 2018: Debug: State =
0x70b0dfa877b8c6efcac40832d6116756
(79) Wed Jun 6 10:17:11 2018: Debug: Message-Authenticator =
0x6b35bdb3c5284feb0f9c21eff24ae78b
(79) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3831
(79) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3534
(79) Wed Jun 6 10:17:11 2018: Debug: session-state: No cached attributes
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing section authorize from file
/usr/local/pf/raddb/sites-enabled/eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: authorize {
(79) Wed Jun 6 10:17:11 2018: Debug: update {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{Packet-Src-IP-Address}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 103.220.23.60
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %l
(79) Wed Jun 6 10:17:11 2018: Debug: --> 1528255031
(79) Wed Jun 6 10:17:11 2018: Debug: } # update = noop
(79) Wed Jun 6 10:17:11 2018: Debug: policy rewrite_calling_station_id {
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: Debug: update request {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 64:cc:2e:4f:39:3b
(79) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(79) Wed Jun 6 10:17:11 2018: Debug: [updated] = updated
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy rewrite_calling_station_id
= updated
(79) Wed Jun 6 10:17:11 2018: Debug: policy rewrite_called_station_id {
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: Debug: update request {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 38:ff:36:c2:33:69
(79) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(79) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(79) Wed Jun 6 10:17:11 2018: Debug: update request {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{Called-Station-Id}:%{8}
(79) Wed Jun 6 10:17:11 2018: Debug: -->
38:ff:36:c2:33:69:eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(79) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if ("%{8}") = noop
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: [updated] = updated
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy rewrite_called_station_id
= updated
(79) Wed Jun 6 10:17:11 2018: Debug: policy filter_username {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) -> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) {
(79) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (&User-Name) = updated
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy filter_username = updated
(79) Wed Jun 6 10:17:11 2018: Debug: policy filter_password {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) -> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy filter_password = updated
(79) Wed Jun 6 10:17:11 2018: Debug: [preprocess] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Checking for suffix after "@"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Looking up realm "xyz.edu" for
User-Name = "ae...@xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Found realm "xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Stripped-User-Name =
"aegis"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Realm = "xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Authentication realm is LOCAL
(79) Wed Jun 6 10:17:11 2018: Debug: [suffix] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: ntdomain: Request already has destination
realm set. Ignoring
(79) Wed Jun 6 10:17:11 2018: Debug: [ntdomain] = noop
(79) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) {
(79) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) {
(79) Wed Jun 6 10:17:11 2018: Debug: update control {
(79) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if ( Realm == "xyz.edu" ) =
noop
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (User-Name =~ /@/) = noop
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if" was
taken
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent EAP Response (code 2) ID 8
length 43
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Continuing tunnel setup
(79) Wed Jun 6 10:17:11 2018: Debug: [eap] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: } # authorize = ok
(79) Wed Jun 6 10:17:11 2018: WARNING: You set Proxy-To-Realm = default, but
it is a LOCAL realm! Cancelling proxy request.
(79) Wed Jun 6 10:17:11 2018: Debug: Found Auth-Type = eap
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: authenticate {
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Expiring EAP session with state
0xaddf81e0acd79b2f
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Finished EAP session with state
0x70b0dfa877b8c6ef
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Previous EAP request found for state
0x70b0dfa877b8c6ef, released from the list
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent packet with method EAP
PEAP (25)
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Calling submodule eap_peap to
process data
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Continuing EAP-TLS
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: [eaptls verify] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Done initial handshake
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: [eaptls process] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Session established. Decoding
tunneled attributes
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: PEAP state phase2
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: EAP method MSCHAPv2 (26)
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Got tunneled request
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: EAP-Message = 0x020800061a03
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Setting User-Name to
ae...@xyz.edu
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Sending tunneled request to
packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: EAP-Message = 0x020800061a03
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: FreeRADIUS-Proxied-To =
127.0.0.1
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: User-Name = "ae...@xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: State =
0xaddf81e0acd79b2f2f0623373d293571
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Calling-Station-Id :=
"64:cc:2e:4f:39:3b"
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: NAS-IP-Address = 10.43.1.2
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: NAS-Identifier =
"38-FF-36-C2-33-69"
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Called-Station-Id :=
"38:ff:36:c2:33:69:eduroam"
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Event-Timestamp = "Jun 6
2018 10:17:11 WIB"
(79) Wed Jun 6 10:17:11 2018: Debug: Virtual server packetfence-tunnel
received request
(79) Wed Jun 6 10:17:11 2018: Debug: EAP-Message = 0x020800061a03
(79) Wed Jun 6 10:17:11 2018: Debug: FreeRADIUS-Proxied-To = 127.0.0.1
(79) Wed Jun 6 10:17:11 2018: Debug: User-Name = "ae...@xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: State =
0xaddf81e0acd79b2f2f0623373d293571
(79) Wed Jun 6 10:17:11 2018: Debug: Calling-Station-Id :=
"64:cc:2e:4f:39:3b"
(79) Wed Jun 6 10:17:11 2018: Debug: NAS-IP-Address = 10.43.1.2
(79) Wed Jun 6 10:17:11 2018: Debug: NAS-Identifier = "38-FF-36-C2-33-69"
(79) Wed Jun 6 10:17:11 2018: Debug: Called-Station-Id :=
"38:ff:36:c2:33:69:eduroam"
(79) Wed Jun 6 10:17:11 2018: Debug: Event-Timestamp = "Jun 6 2018 10:17:11
WIB"
(79) Wed Jun 6 10:17:11 2018: WARNING: Outer and inner identities are the
same. User privacy is compromised.
(79) Wed Jun 6 10:17:11 2018: Debug: server packetfence-tunnel {
(79) Wed Jun 6 10:17:11 2018: Debug: session-state: No cached attributes
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing section authorize from file
/usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: authorize {
(79) Wed Jun 6 10:17:11 2018: Debug: policy filter_username {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) -> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ )
-> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) {
(79) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) ->
FALSE
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (&User-Name) = notfound
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy filter_username =
notfound
(79) Wed Jun 6 10:17:11 2018: Debug: [mschap] = noop
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Checking for suffix after "@"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Looking up realm "xyz.edu" for
User-Name = "ae...@xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Found realm "xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Stripped-User-Name =
"aegis"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Realm = "xyz.edu"
(79) Wed Jun 6 10:17:11 2018: Debug: suffix: Authentication realm is LOCAL
(79) Wed Jun 6 10:17:11 2018: Debug: [suffix] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: ntdomain: Request already has destination
realm set. Ignoring
(79) Wed Jun 6 10:17:11 2018: Debug: [ntdomain] = noop
(79) Wed Jun 6 10:17:11 2018: Debug: update control {
(79) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent EAP Response (code 2) ID 8
length 6
(79) Wed Jun 6 10:17:11 2018: Debug: eap: No EAP Start, assuming it's an
on-going EAP conversation
(79) Wed Jun 6 10:17:11 2018: Debug: [eap] = updated
(79) Wed Jun 6 10:17:11 2018: Debug: policy rewrite_called_station_id {
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: 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))
{
(79) Wed Jun 6 10:17:11 2018: Debug: update request {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 38:ff:36:c2:33:69
(79) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(79) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(79) Wed Jun 6 10:17:11 2018: Debug: update request {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{Called-Station-Id}:%{8}
(79) Wed Jun 6 10:17:11 2018: Debug: -->
38:ff:36:c2:33:69:eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(79) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if ("%{8}") = noop
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(79) Wed Jun 6 10:17:11 2018: Debug: [updated] = updated
(79) Wed Jun 6 10:17:11 2018: 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
(79) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy
rewrite_called_station_id = updated
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: EXPAND
(&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(!(itbStatus=Blocked))(itbProxyStatus=TRUE)(&(|(!(itbStatus=Alumni))(&(itbStatus=Alumni)(|(itbStatus=Dosen)(itbStatus=Karyawan)(itbStatus=Peneliti))))))
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: -->
(&(uid=aegis)(!(itbStatus=Blocked))(itbProxyStatus=TRUE)(&(|(!(itbStatus=Alumni))(&(itbStatus=Alumni)(|(itbStatus=Dosen)(itbStatus=Karyawan)(itbStatus=Peneliti))))))
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: Performing search in
"ou=people,dc=itb,dc=ac,dc=id" with filter
"(&(uid=aegis)(!(itbStatus=Blocked))(itbProxyStatus=TRUE)(&(|(!(itbStatus=Alumni))(&(itbStatus=Alumni)(|(itbStatus=Dosen)(itbStatus=Karyawan)(itbStatus=Peneliti))))))",
scope "sub"
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: Waiting for search result...
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: User object found at DN
"uid=aegis,ou=people,dc=itb,dc=ac,dc=id"
(79) Wed Jun 6 10:17:11 2018: Debug: ldap: Processing user attributes
(79) Wed Jun 6 10:17:11 2018: Debug: [ldap] = updated
(79) Wed Jun 6 10:17:11 2018: Debug: if (updated) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (updated) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (updated) {
(79) Wed Jun 6 10:17:11 2018: Debug: update control {
(79) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (updated) = noop
(79) Wed Jun 6 10:17:11 2018: Debug: pap: Converted:
&control:Password-With-Header -> &control:SSHA1-Password
(79) Wed Jun 6 10:17:11 2018: Debug: pap: Removing
&control:Password-With-Header
(79) Wed Jun 6 10:17:11 2018: Debug: pap: No {...} in Password-With-Header,
re-writing to Cleartext-Password
(79) Wed Jun 6 10:17:11 2018: Debug: pap: Removing
&control:Password-With-Header
(79) Wed Jun 6 10:17:11 2018: Debug: pap: Normalizing SSHA1-Password from
base64 encoding, 32 bytes -> 24 bytes
(79) Wed Jun 6 10:17:11 2018: WARNING: pap: Auth-Type already set. Not
setting to PAP
(79) Wed Jun 6 10:17:11 2018: Debug: [pap] = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # authorize = updated
(79) Wed Jun 6 10:17:11 2018: WARNING: You set Proxy-To-Realm = local, but
it is a LOCAL realm! Cancelling proxy request.
(79) Wed Jun 6 10:17:11 2018: Debug: Found Auth-Type = eap
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: authenticate {
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Expiring EAP session with state
0xaddf81e0acd79b2f
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Finished EAP session with state
0xaddf81e0acd79b2f
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Previous EAP request found for state
0xaddf81e0acd79b2f, released from the list
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent packet with method EAP
MSCHAPv2 (26)
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Calling submodule eap_mschapv2 to
process data
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Sending EAP Success (code 3) ID 8
length 4
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Freeing handler
(79) Wed Jun 6 10:17:11 2018: Debug: [eap] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: } # authenticate = ok
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing section post-auth from file
/usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: post-auth {
(79) Wed Jun 6 10:17:11 2018: Debug: policy packetfence-set-tenant-id {
(79) Wed Jun 6 10:17:11 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{%{control:PacketFence-Tenant-Id}:-0}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 0
(79) Wed Jun 6 10:17:11 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") {
(79) Wed Jun 6 10:17:11 2018: Debug: update control {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{User-Name}
(79) Wed Jun 6 10:17:11 2018: Debug: --> ae...@xyz.edu
(79) Wed Jun 6 10:17:11 2018: Debug: SQL-User-Name set to
'ae...@xyz.edu'
(79) Wed Jun 6 10:17:11 2018: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'103.220.23.60'), 0)
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id FROM radius_nas WHERE nasname =
'%{Packet-Src-IP-Address}'), 0)}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 0
(79) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (
"%{%{control:PacketFence-Tenant-Id}:-0}" == "0") = noop
(79) Wed Jun 6 10:17:11 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(79) Wed Jun 6 10:17:11 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) -> TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (
&control:PacketFence-Tenant-Id == 0 ) {
(79) Wed Jun 6 10:17:11 2018: Debug: update control {
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{User-Name}
(79) Wed Jun 6 10:17:11 2018: Debug: --> ae...@xyz.edu
(79) Wed Jun 6 10:17:11 2018: Debug: SQL-User-Name set to
'ae...@xyz.edu'
(79) Wed Jun 6 10:17:11 2018: Debug: Executing select query:
SELECT IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <=
INET_ATON('103.220.23.60') and INET_ATON('103.220.23.60') <= end_ip order by
range_length limit 1), 1)
(79) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{sql: SELECT
IFNULL((SELECT tenant_id from radius_nas WHERE start_ip <=
INET_ATON('%{Packet-Src-IP-Address}') and INET_ATON('%{Packet-Src-IP-Address}')
<= end_ip order by range_length limit 1), 1)}
(79) Wed Jun 6 10:17:11 2018: Debug: --> 1
(79) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (
&control:PacketFence-Tenant-Id == 0 ) = noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy
packetfence-set-tenant-id = noop
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Expanding URI components
(79) Wed Jun 6 10:17:11 2018: Debug: rest: EXPAND http://127.0.0.1:7070
(79) Wed Jun 6 10:17:11 2018: Debug: rest: --> http://127.0.0.1:7070
(79) Wed Jun 6 10:17:11 2018: Debug: rest: EXPAND //radius/rest/authorize
(79) Wed Jun 6 10:17:11 2018: Debug: rest: --> //radius/rest/authorize
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Sending HTTP POST to
"http://127.0.0.1:7070//radius/rest/authorize";
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "User-Name"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "NAS-IP-Address"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "State"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute
"Called-Station-Id"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute
"Calling-Station-Id"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "NAS-Identifier"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "Event-Timestamp"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "EAP-Message"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute
"FreeRADIUS-Proxied-To"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "EAP-Type"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute
"Stripped-User-Name"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "Realm"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute "SQL-User-Name"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Encoding attribute
"Called-Station-SSID"
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Processing response header
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Status : 401 (Unauthorized)
(79) Wed Jun 6 10:17:11 2018: Debug: rest: Type : json (application/json)
(79) Wed Jun 6 10:17:11 2018: ERROR: rest: Server returned:
(79) Wed Jun 6 10:17:11 2018: ERROR: rest: {"Reply-Message":"Network device
does not support this mode of
operation","control:PacketFence-Eap-Type":26,"control:PacketFence-Authorization-Status":"allow","control:PacketFence-Mac":"64:cc:2e:4f:39:3b","control:PacketFence-Switch-Ip-Address":"10.43.1.2","control:PacketFence-Request-Time":1528255031,"control:PacketFence-UserName":"ae...@xyz.edu","control:PacketFence-Connection-Type":"Ethernet-EAP","control:PacketFence-Switch-Mac":"38:ff:36:c2:33:69","control:PacketFence-Switch-Id":"10.43.1.2"}
(79) Wed Jun 6 10:17:11 2018: Debug: [rest] = invalid
(79) Wed Jun 6 10:17:11 2018: Debug: } # post-auth = invalid
(79) Wed Jun 6 10:17:11 2018: Debug: Using Post-Auth-Type Reject
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: Post-Auth-Type REJECT {
(79) Wed Jun 6 10:17:11 2018: Debug: update {
(79) Wed Jun 6 10:17:11 2018: Debug: } # update = noop
(79) Wed Jun 6 10:17:11 2018: Debug: policy packetfence-audit-log-reject
{
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name != "dummy") {
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name != "dummy") ->
TRUE
(79) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name != "dummy") {
(79) Wed Jun 6 10:17:11 2018: Debug: policy request-timing {
(79) Wed Jun 6 10:17:11 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(79) Wed Jun 6 10:17:11 2018: ERROR: Failed retrieving values
required to evaluate condition
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy request-timing = noop
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND type.reject.query
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> type.reject.query
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: Using query template 'query'
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND %{User-Name}
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> ae...@xyz.edu
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: SQL-User-Name set to
'ae...@xyz.edu'
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}',
'%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}',
'%{request:Stripped-User-Name}', '%{request:Realm}',
'Radius-Access-Request',
'%{%{control:PacketFence-Switch-Id}:-N/A}',
'%{%{control:PacketFence-Switch-Mac}:-N/A}',
'%{%{control:PacketFence-Switch-Ip-Address}:-N/A}',
'%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}',
'%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}',
'%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}',
'%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}',
'%{%{control:PacketFence-Connection-Type}:-N/A}',
'%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject',
'%{request:Module-Failure-Message}', '%{control:Auth-Type}',
'%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}',
'%{%{control:PacketFence-Status}:-N/A}',
'%{%{control:PacketFence-Profile}:-N/A}',
'%{%{control:PacketFence-Source}:-N/A}',
'%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}',
'%{request:PacketFence-Domain}', '',
'%{pairs:&request:[*]}','%{pairs:&reply:[*]}',
'%{%{control:PacketFence-Request-Time}:-N/A}',
'%{control:PacketFence-Tenant-Id}')
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'64:cc:2e:4f:39:3b', '', 'N/A', 'ae...@xyz.edu', 'aegis',
'xyz.edu', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A',
'103.220.23.60', '38:ff:36:c2:33:69:eduroam', '64:cc:2e:4f:39:3b',
'', 'eduroam', '', 'N/A', '', 'N/A',
'10.43.1.2', '38-FF-36-C2-33-69', 'Reject', 'rest: Server
returned:', 'eap', 'MSCHAPv2', 'N/A', 'N/A', 'N/A',
'N/A', '0', '0', '', '', 'User-Name =3D =22ae...@xyz.edu=22=2C
NAS-IP-Address =3D 10.43.1.2=2C State =3D 0xaddf81e0acd79b2f2f0623373d293571=2C
Called-Station-Id =3D =2238:ff:36:c2:33:69:eduroam=22=2C Calling-Station-Id =3D
=2264:cc:2e:4f:39:3b=22=2C NAS-Identifier =3D =2238-FF-36-C2-33-69=22=2C
Event-Timestamp =3D =22Jun 6 2018 10:17:11 WIB=22=2C EAP-Message =3D
0x020800061a03=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C EAP-Type =3D
MSCHAPv2=2C Stripped-User-Name =3D =22aegis=22=2C Realm =3D =22xyz.edu=22=2C
Called-Station-SSID =3D =22eduroam=22=2C Module-Failure-Message =3D =22rest:
Server returned:=22=2C Module-Failure-Message =3D =22rest:
=7B=5C=22Reply-Message=5C=22:=5C=22Network device does not support this mode of
operation=5C=22=2C=5C=22control:PacketFence-Eap-Type=5C=22:26=2C=5C=22control:PacketFence-Authorization-Status=5C=22:=5C=22allow=5C=22=2C=5C=22control:PacketFence-Mac=5C=22:=5C=2264:cc:2e:4f:39:3b=5C=22=2C=5C=22control:PacketFence-Switch-Ip-Address=5C=22:=5C=2210.43.1.2=5C=22=2C=5C=22control:PacketFence-Request-Time=5C=22:1528255031=2C=5C=22control:PacketFence-UserName=5C=22:=5C=22ae...@xyz.edu=5C=22=2C=5C=22control:PacketFence-Connection-Type=5C=22:=5C=22Ethernet-EAP=5C=22=2C=5C=22control:PacketFence-Switch-Mac=5C=22:=5C=2238:ff:36:c2:33:69=5C=22=2C=5C=22control:PacketFence-Switch-Id=5C=22:=5C=2210.43.1.2=5C=22=7D=22=2C
User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D
=22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name
=3D =22ae...@xyz.edu=22','MS-MPPE-Encryption-Policy =3D Encryption-Required=2C
MS-MPPE-Encryption-Types =3D 4=2C MS-MPPE-Send-Key =3D
0x46b2ca0b028ce59004fa83778d364c8c=2C MS-MPPE-Recv-Key =3D
0x45b6c0a1d769065ddd22b46c84982d80=2C EAP-Message =3D 0x03080004=2C
Message-Authenticator =3D 0x00000000000000000000000000000000=2C
Stripped-User-Name =3D =22aegis=22', 'N/A', '1')
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: Executing query: INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'64:cc:2e:4f:39:3b', '', 'N/A', 'ae...@xyz.edu', 'aegis',
'xyz.edu', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A',
'103.220.23.60', '38:ff:36:c2:33:69:eduroam', '64:cc:2e:4f:39:3b',
'', 'eduroam', '', 'N/A', '', 'N/A',
'10.43.1.2', '38-FF-36-C2-33-69', 'Reject', 'rest: Server
returned:', 'eap', 'MSCHAPv2', 'N/A', 'N/A', 'N/A',
'N/A', '0', '0', '', '', 'User-Name =3D =22ae...@xyz.edu=22=2C
NAS-IP-Address =3D 10.43.1.2=2C State =3D 0xaddf81e0acd79b2f2f0623373d293571=2C
Called-Station-Id =3D =2238:ff:36:c2:33:69:eduroam=22=2C Calling-Station-Id =3D
=2264:cc:2e:4f:39:3b=22=2C NAS-Identifier =3D =2238-FF-36-C2-33-69=22=2C
Event-Timestamp =3D =22Jun 6 2018 10:17:11 WIB=22=2C EAP-Message =3D
0x020800061a03=2C FreeRADIUS-Proxied-To =3D 127.0.0.1=2C EAP-Type =3D
MSCHAPv2=2C Stripped-User-Name =3D =22aegis=22=2C Realm =3D =22xyz.edu=22=2C
Called-Station-SSID =3D =22eduroam=22=2C Module-Failure-Message =3D =22rest:
Server returned:=22=2C Module-Failure-Message =3D =22rest:
=7B=5C=22Reply-Message=5C=22:=5C=22Network device does not support this mode of
operation=5C=22=2C=5C=22control:PacketFence-Eap-Type=5C=22:26=2C=5C=22control:PacketFence-Authorization-Status=5C=22:=5C=22allow=5C=22=2C=5C=22control:PacketFence-Mac=5C=22:=5C=2264:cc:2e:4f:39:3b=5C=22=2C=5C=22control:PacketFence-Switch-Ip-Address=5C=22:=5C=2210.43.1.2=5C=22=2C=5C=22control:PacketFence-Request-Time=5C=22:1528255031=2C=5C=22control:PacketFence-UserName=5C=22:=5C=22ae...@xyz.edu=5C=22=2C=5C=22control:PacketFence-Connection-Type=5C=22:=5C=22Ethernet-EAP=5C=22=2C=5C=22control:PacketFence-Switch-Mac=5C=22:=5C=2238:ff:36:c2:33:69=5C=22=2C=5C=22control:PacketFence-Switch-Id=5C=22:=5C=2210.43.1.2=5C=22=7D=22=2C
User-Password =3D =22=2A=2A=2A=2A=2A=2A=22=2C Module-Failure-Message =3D
=22Failed retrieving values required to evaluate condition=22=2C SQL-User-Name
=3D =22ae...@xyz.edu=22','MS-MPPE-Encryption-Policy =3D Encryption-Required=2C
MS-MPPE-Encryption-Types =3D 4=2C MS-MPPE-Send-Key =3D
0x46b2ca0b028ce59004fa83778d364c8c=2C MS-MPPE-Recv-Key =3D
0x45b6c0a1d769065ddd22b46c84982d80=2C EAP-Message =3D 0x03080004=2C
Message-Authenticator =3D 0x00000000000000000000000000000000=2C
Stripped-User-Name =3D =22aegis=22', 'N/A', '1')
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: SQL query returned: success
(79) Wed Jun 6 10:17:11 2018: Debug: sql_reject: 1 record(s) updated
(79) Wed Jun 6 10:17:11 2018: Debug: [sql_reject] = ok
(79) Wed Jun 6 10:17:11 2018: Debug: } # if (&User-Name != "dummy") =
ok
(79) Wed Jun 6 10:17:11 2018: Debug: } # policy
packetfence-audit-log-reject = ok
(79) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: EXPAND
%{User-Name}
(79) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: -->
ae...@xyz.edu
(79) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: Matched entry
DEFAULT at line 11
(79) Wed Jun 6 10:17:11 2018: Debug: [attr_filter.access_reject] =
updated
(79) Wed Jun 6 10:17:11 2018: Debug: update outer.session-state {
(79) Wed Jun 6 10:17:11 2018: Debug: } # update outer.session-state =
noop
(79) Wed Jun 6 10:17:11 2018: Debug: } # Post-Auth-Type REJECT = updated
(79) Wed Jun 6 10:17:11 2018: Debug: } # server packetfence-tunnel
(79) Wed Jun 6 10:17:11 2018: Debug: Virtual server sending reply
(79) Wed Jun 6 10:17:11 2018: Debug: EAP-Message = 0x03080004
(79) Wed Jun 6 10:17:11 2018: Debug: Message-Authenticator =
0x00000000000000000000000000000000
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Got tunneled reply code 3
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: EAP-Message = 0x03080004
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Message-Authenticator =
0x00000000000000000000000000000000
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Tunneled authentication was
rejected
(79) Wed Jun 6 10:17:11 2018: Debug: eap_peap: FAILURE
(79) Wed Jun 6 10:17:11 2018: Debug: eap: Sending EAP Request (code 1) ID 9
length 43
(79) Wed Jun 6 10:17:11 2018: Debug: eap: EAP session adding &reply:State =
0x70b0dfa878b9c6ef
(79) Wed Jun 6 10:17:11 2018: Debug: [eap] = handled
(79) Wed Jun 6 10:17:11 2018: Debug: } # authenticate = handled
(79) Wed Jun 6 10:17:11 2018: Debug: Using Post-Auth-Type Challenge
(79) Wed Jun 6 10:17:11 2018: Debug: Post-Auth-Type sub-section not found.
Ignoring.
(79) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/eduroam
(79) Wed Jun 6 10:17:11 2018: Debug: session-state: Saving cached attributes
(79) Wed Jun 6 10:17:11 2018: Debug: Module-Failure-Message := "rest: Server
returned:"
(79) Wed Jun 6 10:17:11 2018: Debug: Sent Access-Challenge Id 232 from
10.10.59.25:11812 to 103.220.23.60:38600 length 0
(79) Wed Jun 6 10:17:11 2018: Debug: EAP-Message =
0x0109002b19001703010020ce6c6b26ad457bece93e8747d643d7bc259a65b7b1b848525552004db07dbb1d
(79) Wed Jun 6 10:17:11 2018: Debug: Message-Authenticator =
0x00000000000000000000000000000000
(79) Wed Jun 6 10:17:11 2018: Debug: State =
0x70b0dfa878b9c6efcac40832d6116756
(79) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3831
(79) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3534
(79) Wed Jun 6 10:17:11 2018: Debug: Finished request
(80) Wed Jun 6 10:17:11 2018: Debug: Received Access-Request Id 215 from
103.220.23.60:38600 to 10.10.59.25:11812 length 197
(80) Wed Jun 6 10:17:11 2018: Debug: User-Name = "ae...@xyz.edu"
(80) Wed Jun 6 10:17:11 2018: Debug: Calling-Station-Id = "64-CC-2E-4F-39-3B"
(80) Wed Jun 6 10:17:11 2018: Debug: NAS-IP-Address = 10.43.1.2
(80) Wed Jun 6 10:17:11 2018: Debug: Called-Station-Id =
"38-FF-36-C2-33-69:eduroam"
(80) Wed Jun 6 10:17:11 2018: Debug: NAS-Identifier = "38-FF-36-C2-33-69"
(80) Wed Jun 6 10:17:11 2018: Debug: EAP-Message =
0x0209002b19001703010020772b440950bfd172fd554e5e3d16cc2c56f42405f1f347ea683bac0f62065b7b
(80) Wed Jun 6 10:17:11 2018: Debug: State =
0x70b0dfa878b9c6efcac40832d6116756
(80) Wed Jun 6 10:17:11 2018: Debug: Message-Authenticator =
0xf2e3aa7e8c541d12bf4268a60792ecdc
(80) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3832
(80) Wed Jun 6 10:17:11 2018: Debug: Proxy-State = 0x3939
(80) Wed Jun 6 10:17:11 2018: Debug: Restoring &session-state
(80) Wed Jun 6 10:17:11 2018: Debug: &session-state:Module-Failure-Message
:= "rest: Server returned:"
(80) Wed Jun 6 10:17:11 2018: Debug: # Executing section authorize from file
/usr/local/pf/raddb/sites-enabled/eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: authorize {
(80) Wed Jun 6 10:17:11 2018: Debug: update {
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{Packet-Src-IP-Address}
(80) Wed Jun 6 10:17:11 2018: Debug: --> 103.220.23.60
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND %l
(80) Wed Jun 6 10:17:11 2018: Debug: --> 1528255031
(80) Wed Jun 6 10:17:11 2018: Debug: } # update = noop
(80) Wed Jun 6 10:17:11 2018: Debug: policy rewrite_calling_station_id {
(80) Wed Jun 6 10:17:11 2018: 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))
{
(80) Wed Jun 6 10:17:11 2018: 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
(80) Wed Jun 6 10:17:11 2018: 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))
{
(80) Wed Jun 6 10:17:11 2018: Debug: update request {
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(80) Wed Jun 6 10:17:11 2018: Debug: --> 64:cc:2e:4f:39:3b
(80) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(80) Wed Jun 6 10:17:11 2018: Debug: [updated] = updated
(80) Wed Jun 6 10:17:11 2018: 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
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy rewrite_calling_station_id
= updated
(80) Wed Jun 6 10:17:11 2018: Debug: policy rewrite_called_station_id {
(80) Wed Jun 6 10:17:11 2018: 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))
{
(80) Wed Jun 6 10:17:11 2018: 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
(80) Wed Jun 6 10:17:11 2018: 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))
{
(80) Wed Jun 6 10:17:11 2018: Debug: update request {
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}}
(80) Wed Jun 6 10:17:11 2018: Debug: --> 38:ff:36:c2:33:69
(80) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(80) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(80) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") -> TRUE
(80) Wed Jun 6 10:17:11 2018: Debug: if ("%{8}") {
(80) Wed Jun 6 10:17:11 2018: Debug: update request {
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND
%{Called-Station-Id}:%{8}
(80) Wed Jun 6 10:17:11 2018: Debug: -->
38:ff:36:c2:33:69:eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: EXPAND %{8}
(80) Wed Jun 6 10:17:11 2018: Debug: --> eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: } # update request = noop
(80) Wed Jun 6 10:17:11 2018: Debug: } # if ("%{8}") = noop
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping elsif: Preceding
"if" was taken
(80) Wed Jun 6 10:17:11 2018: Debug: [updated] = updated
(80) Wed Jun 6 10:17:11 2018: 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
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy rewrite_called_station_id
= updated
(80) Wed Jun 6 10:17:11 2018: Debug: policy filter_username {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) -> TRUE
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ / /) -> FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) ->
FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.\./ ) ->
FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) {
(80) Wed Jun 6 10:17:11 2018: Debug: if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /\.$/) ->
FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Name =~ /@\./) ->
FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: } # if (&User-Name) = updated
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy filter_username = updated
(80) Wed Jun 6 10:17:11 2018: Debug: policy filter_password {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&User-Password &&
(&User-Password != "%{string:User-Password}")) -> FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy filter_password = updated
(80) Wed Jun 6 10:17:11 2018: Debug: [preprocess] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Checking for suffix after "@"
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Looking up realm "xyz.edu" for
User-Name = "ae...@xyz.edu"
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Found realm "xyz.edu"
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Stripped-User-Name =
"aegis"
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Adding Realm = "xyz.edu"
(80) Wed Jun 6 10:17:11 2018: Debug: suffix: Authentication realm is LOCAL
(80) Wed Jun 6 10:17:11 2018: Debug: [suffix] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: ntdomain: Request already has destination
realm set. Ignoring
(80) Wed Jun 6 10:17:11 2018: Debug: [ntdomain] = noop
(80) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) -> TRUE
(80) Wed Jun 6 10:17:11 2018: Debug: if (User-Name =~ /@/) {
(80) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) {
(80) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) -> TRUE
(80) Wed Jun 6 10:17:11 2018: Debug: if ( Realm == "xyz.edu" ) {
(80) Wed Jun 6 10:17:11 2018: Debug: update control {
(80) Wed Jun 6 10:17:11 2018: Debug: } # update control = noop
(80) Wed Jun 6 10:17:11 2018: Debug: } # if ( Realm == "xyz.edu" ) =
noop
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if"
was taken
(80) Wed Jun 6 10:17:11 2018: Debug: } # if (User-Name =~ /@/) = noop
(80) Wed Jun 6 10:17:11 2018: Debug: ... skipping else: Preceding "if" was
taken
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent EAP Response (code 2) ID 9
length 43
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Continuing tunnel setup
(80) Wed Jun 6 10:17:11 2018: Debug: [eap] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: } # authorize = ok
(80) Wed Jun 6 10:17:11 2018: WARNING: You set Proxy-To-Realm = default, but
it is a LOCAL realm! Cancelling proxy request.
(80) Wed Jun 6 10:17:11 2018: Debug: Found Auth-Type = eap
(80) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: authenticate {
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Expiring EAP session with state
0x70b0dfa878b9c6ef
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Finished EAP session with state
0x70b0dfa878b9c6ef
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Previous EAP request found for state
0x70b0dfa878b9c6ef, released from the list
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Peer sent packet with method EAP
PEAP (25)
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Calling submodule eap_peap to
process data
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Continuing EAP-TLS
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: [eaptls verify] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Done initial handshake
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: [eaptls process] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Session established. Decoding
tunneled attributes
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: PEAP state send tlv failure
(80) Wed Jun 6 10:17:11 2018: Debug: eap_peap: Received EAP-TLV response
(80) Wed Jun 6 10:17:11 2018: ERROR: eap_peap: The users session was
previously rejected: returning reject (again.)
(80) Wed Jun 6 10:17:11 2018: ERROR: eap: Failed continuing EAP PEAP (25)
session. EAP sub-module failed
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Sending EAP Failure (code 4) ID 9
length 4
(80) Wed Jun 6 10:17:11 2018: Debug: eap: Failed in EAP select
(80) Wed Jun 6 10:17:11 2018: Debug: [eap] = invalid
(80) Wed Jun 6 10:17:11 2018: Debug: } # authenticate = invalid
(80) Wed Jun 6 10:17:11 2018: Debug: Failed to authenticate the user
(80) Wed Jun 6 10:17:11 2018: Debug: Using Post-Auth-Type Reject
(80) Wed Jun 6 10:17:11 2018: Debug: # Executing group from file
/usr/local/pf/raddb/sites-enabled/eduroam
(80) Wed Jun 6 10:17:11 2018: Debug: Post-Auth-Type REJECT {
(80) Wed Jun 6 10:17:11 2018: Debug: policy request-timing {
(80) Wed Jun 6 10:17:11 2018: Debug: if
(control:PacketFence-Request-Time != 0) {
(80) Wed Jun 6 10:17:11 2018: Debug: if
(control:PacketFence-Request-Time != 0) -> FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy request-timing = noop
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND type.reject.query
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> type.reject.query
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: Using query template 'query'
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND %{User-Name}
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> ae...@xyz.edu
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: SQL-User-Name set to
'ae...@xyz.edu'
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: EXPAND INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}',
'%{%{control:PacketFence-Computer-Name}:-N/A}', '%{request:User-Name}',
'%{request:Stripped-User-Name}', '%{request:Realm}',
'Radius-Access-Request',
'%{%{control:PacketFence-Switch-Id}:-N/A}',
'%{%{control:PacketFence-Switch-Mac}:-N/A}',
'%{%{control:PacketFence-Switch-Ip-Address}:-N/A}',
'%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}',
'%{request:Calling-Station-Id}', '%{request:NAS-Port-Type}',
'%{request:Called-Station-SSID}', '%{request:NAS-Port-Id}',
'%{%{control:PacketFence-IfIndex}:-N/A}', '%{request:NAS-Port}',
'%{%{control:PacketFence-Connection-Type}:-N/A}',
'%{request:NAS-IP-Address}', '%{request:NAS-Identifier}', 'Reject',
'%{request:Module-Failure-Message}', '%{control:Auth-Type}',
'%{request:EAP-Type}', '%{%{control:PacketFence-Role}:-N/A}',
'%{%{control:PacketFence-Status}:-N/A}',
'%{%{control:PacketFence-Profile}:-N/A}',
'%{%{control:PacketFence-Source}:-N/A}',
'%{%{control:PacketFence-AutoReg}:-0}', '%{%{control:PacketFence-IsPhone}:-0}',
'%{request:PacketFence-Domain}', '',
'%{pairs:&request:[*]}','%{pairs:&reply:[*]}',
'%{%{control:PacketFence-Request-Time}:-N/A}',
'%{control:PacketFence-Tenant-Id}')
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: --> INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'64:cc:2e:4f:39:3b', '', 'N/A', 'ae...@xyz.edu', 'aegis',
'xyz.edu', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A',
'103.220.23.60', '38:ff:36:c2:33:69:eduroam', '64:cc:2e:4f:39:3b',
'', 'eduroam', '', 'N/A', '', 'N/A',
'10.43.1.2', '38-FF-36-C2-33-69', 'Reject', 'eap_peap: The
users session was previously rejected: returning reject =28again.=29', 'eap',
'PEAP', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0',
'', '', 'User-Name =3D =22ae...@xyz.edu=22=2C Calling-Station-Id =3D
=2264:cc:2e:4f:39:3b=22=2C NAS-IP-Address =3D 10.43.1.2=2C NAS-Identifier =3D
=2238-FF-36-C2-33-69=22=2C EAP-Message =3D
0x0209002b19001703010020772b440950bfd172fd554e5e3d16cc2c56f42405f1f347ea683bac0f62065b7b=2C
State =3D 0x70b0dfa878b9c6efcac40832d6116756=2C Message-Authenticator =3D
0xf2e3aa7e8c541d12bf4268a60792ecdc=2C Proxy-State =3D 0x3832=2C Proxy-State =3D
0x3939=2C FreeRADIUS-Client-IP-Address =3D 103.220.23.60=2C Called-Station-Id
=3D =2238:ff:36:c2:33:69:eduroam=22=2C Called-Station-SSID =3D =22eduroam=22=2C
Event-Timestamp =3D =22Jun 6 2018 10:17:11 WIB=22=2C Stripped-User-Name =3D
=22aegis=22=2C Realm =3D =22xyz.edu=22=2C EAP-Type =3D PEAP=2C
Module-Failure-Message =3D =22eap_peap: The users session was previously
rejected: returning reject =28again.=29=22=2C Module-Failure-Message =3D
=22eap: Failed continuing EAP PEAP =2825=29 session. EAP sub-module
failed=22=2C SQL-User-Name =3D =22ae...@xyz.edu=22','EAP-Message =3D
0x04090004=2C Message-Authenticator =3D 0x00000000000000000000000000000000=2C
Proxy-State =3D 0x3832=2C Proxy-State =3D 0x3939', '0', '')
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: Executing query: INSERT INTO
radius_audit_log ( mac, ip, computer_name, user_name,
stripped_user_name, realm, event_type, switch_id,
switch_mac, switch_ip_address, radius_source_ip_address,
called_station_id, calling_station_id, nas_port_type, ssid,
nas_port_id, ifindex, nas_port, connection_type,
nas_ip_address, nas_identifier, auth_status, reason, auth_type,
eap_type, role, node_status, profile, source,
auto_reg, is_phone, pf_domain, uuid, radius_request,
radius_reply, request_time, tenant_id) VALUES (
'64:cc:2e:4f:39:3b', '', 'N/A', 'ae...@xyz.edu', 'aegis',
'xyz.edu', 'Radius-Access-Request', 'N/A', 'N/A', 'N/A',
'103.220.23.60', '38:ff:36:c2:33:69:eduroam', '64:cc:2e:4f:39:3b',
'', 'eduroam', '', 'N/A', '', 'N/A',
'10.43.1.2', '38-FF-36-C2-33-69', 'Reject', 'eap_peap: The
users session was previously rejected: returning reject =28again.=29', 'eap',
'PEAP', 'N/A', 'N/A', 'N/A', 'N/A', '0', '0',
'', '', 'User-Name =3D =22ae...@xyz.edu=22=2C Calling-Station-Id =3D
=2264:cc:2e:4f:39:3b=22=2C NAS-IP-Address =3D 10.43.1.2=2C NAS-Identifier =3D
=2238-FF-36-C2-33-69=22=2C EAP-Message =3D
0x0209002b19001703010020772b440950bfd172fd554e5e3d16cc2c56f42405f1f347ea683bac0f62065b7b=2C
State =3D 0x70b0dfa878b9c6efcac40832d6116756=2C Message-Authenticator =3D
0xf2e3aa7e8c541d12bf4268a60792ecdc=2C Proxy-State =3D 0x3832=2C Proxy-State =3D
0x3939=2C FreeRADIUS-Client-IP-Address =3D 103.220.23.60=2C Called-Station-Id
=3D =2238:ff:36:c2:33:69:eduroam=22=2C Called-Station-SSID =3D =22eduroam=22=2C
Event-Timestamp =3D =22Jun 6 2018 10:17:11 WIB=22=2C Stripped-User-Name =3D
=22aegis=22=2C Realm =3D =22xyz.edu=22=2C EAP-Type =3D PEAP=2C
Module-Failure-Message =3D =22eap_peap: The users session was previously
rejected: returning reject =28again.=29=22=2C Module-Failure-Message =3D
=22eap: Failed continuing EAP PEAP =2825=29 session. EAP sub-module
failed=22=2C SQL-User-Name =3D =22ae...@xyz.edu=22','EAP-Message =3D
0x04090004=2C Message-Authenticator =3D 0x00000000000000000000000000000000=2C
Proxy-State =3D 0x3832=2C Proxy-State =3D 0x3939', '0', '')
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: SQL query returned: success
(80) Wed Jun 6 10:17:11 2018: Debug: sql_reject: 1 record(s) updated
(80) Wed Jun 6 10:17:11 2018: Debug: [sql_reject] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: EXPAND
%{User-Name}
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: -->
ae...@xyz.edu
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.access_reject: Matched entry
DEFAULT at line 11
(80) Wed Jun 6 10:17:11 2018: Debug: [attr_filter.access_reject] = updated
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.packetfence_post_auth: EXPAND
%{User-Name}
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.packetfence_post_auth: -->
ae...@xyz.edu
(80) Wed Jun 6 10:17:11 2018: Debug: attr_filter.packetfence_post_auth:
Matched entry DEFAULT at line 10
(80) Wed Jun 6 10:17:11 2018: Debug: [attr_filter.packetfence_post_auth] =
updated
(80) Wed Jun 6 10:17:11 2018: Debug: [eap] = noop
(80) Wed Jun 6 10:17:11 2018: Debug: policy remove_reply_message_if_eap {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&reply:EAP-Message &&
&reply:Reply-Message) {
(80) Wed Jun 6 10:17:11 2018: Debug: if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
(80) Wed Jun 6 10:17:11 2018: Debug: else {
(80) Wed Jun 6 10:17:11 2018: Debug: [noop] = noop
(80) Wed Jun 6 10:17:11 2018: Debug: } # else = noop
(80) Wed Jun 6 10:17:11 2018: Debug: } # policy
remove_reply_message_if_eap = noop
(80) Wed Jun 6 10:17:11 2018: Debug: linelog: EXPAND
messages.%{%{reply:Packet-Type}:-default}
(80) Wed Jun 6 10:17:11 2018: Debug: linelog: --> messages.Access-Reject
(80) Wed Jun 6 10:17:11 2018: Debug: linelog: EXPAND
[mac:%{Calling-Station-Id}] Rejected user: %{User-Name}
(80) Wed Jun 6 10:17:11 2018: Debug: linelog: --> [mac:64:cc:2e:4f:39:3b]
Rejected user: ae...@xyz.edu
(80) Wed Jun 6 10:17:11 2018: Debug: [linelog] = ok
(80) Wed Jun 6 10:17:11 2018: Debug: } # Post-Auth-Type REJECT = updated
(80) Wed Jun 6 10:17:11 2018: Debug: Delaying response for 1.000000 seconds
(80) Wed Jun 6 10:17:12 2018: Debug: Sending delayed response
(80) Wed Jun 6 10:17:12 2018: Debug: Sent Access-Reject Id 215 from
10.10.59.25:11812 to 103.220.23.60:38600 length 52
(80) Wed Jun 6 10:17:12 2018: Debug: EAP-Message = 0x04090004
(80) Wed Jun 6 10:17:12 2018: Debug: Message-Authenticator =
0x00000000000000000000000000000000
(80) Wed Jun 6 10:17:12 2018: Debug: Proxy-State = 0x3832
(80) Wed Jun 6 10:17:12 2018: Debug: Proxy-State = 0x3939
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot
_______________________________________________
PacketFence-users mailing list
PacketFence-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/packetfence-users
