Hi,
I try both, I have a few clients which I want to Authenticate via EAP-TLS
and a many Clients which I want to auth via PEAP with Active Directory.
Today I am playing with PEAP with machine accounts and user accounts
because it's more important for me :)
EAP-TLS is used for our Mobile Devices (iPhones for example)
if I do a radtest the authentification works, so maybe it's a
misconfiguration on the switch or on my Windows 7 client?
*radtest -t mschap -x fritob <password> 127.0.0.1:18120
<http://127.0.0.1:18120> 12 testing123*
Sending Access-Request of id 95 to 127.0.0.1 port 1812
User-Name = "fritob"
NAS-IP-Address = 127.0.0.1
NAS-Port = 12
Message-Authenticator = 0x00000000000000000000000000000000
MS-CHAP-Challenge = 0x14011e295903c91d
MS-CHAP-Response =
0x00010000000000000000000000000000000000000000000000007f1cf8f0751c4b4138cd12138d1da4425011806de60a56b1
rad_recv: Access-Accept packet from host 127.0.0.1 port 18120, id=95,
length=20
*So here are the config files:*
*cat /usr/local/pf/raddb/proxy.conf*
# -*- text -*-
##
## proxy.conf -- proxy radius and realm configuration directives
##
## $Id$
#######################################################################
#
# Proxy server configuration
#
# This entry controls the servers behaviour towards ALL other servers
# to which it sends proxy requests.
#
proxy server {
#
# Note that as of 2.0, the "synchronous", "retry_delay",
# "retry_count", and "dead_time" have all been deprecated.
# For backwards compatibility, they are are still accepted
# by the server, but they ONLY apply to the old-style realm
# configuration. i.e. realms with "authhost" and/or "accthost"
# entries.
#
# i.e. "retry_delay" and "retry_count" have been replaced
# with per-home-server configuration. See the "home_server"
# example below for details.
#
# i.e. "dead_time" has been replaced with a per-home-server
# "revive_interval". We strongly recommend that this not
# be used, however. The new method is much better.
#
# In 2.0, the server is always "synchronous", and setting
# "synchronous = no" is impossible. This simplifies the
# server and increases the stability of the network.
# However, it means that the server (i.e. proxy) NEVER
# originates packets. It proxies packets ONLY when it receives
# a packet or a re-transmission from the NAS. If the NAS never
# re-transmits, the proxy never re-transmits, either. This can
# affect fail-over, where a packet does *not* fail over to a
# second home server.. because the NAS never retransmits the
# packet.
#
# If you need to set "synchronous = no", please send a
# message to the list <freeradius-***@lists.freeradius.org>
# explaining why this feature is vital for your network.
#
# If a realm exists, but there are no live home servers for
# it, we can fall back to using the "DEFAULT" realm. This is
# most useful for accounting, where the server can proxy
# accounting requests to home servers, but if they're down,
# use a DEFAULT realm that is LOCAL (i.e. accthost = LOCAL),
# and then store the packets in the "detail" file. That data
# can be later proxied to the home servers by radrelay, when
# those home servers come back up again.
# Setting this to "yes" may have issues for authentication.
# i.e. If you are proxying for two different ISP's, and then
# act as a general dial-up for Gric. If one of the first two
# ISP's has their RADIUS server go down, you do NOT want to
# proxy those requests to GRIC. Instead, you probably want
# to just drop the requests on the floor. In that case, set
# this value to 'no'.
#
# allowed values: {yes, no}
#
default_fallback = no
}
#######################################################################
#
# Configuration for the proxy realms.
#
# As of 2.0. the old-style "realms" file is deprecated, and is not
# used by FreeRADIUS.
#
# As of 2.0, the "realm" configuration has changed. Instead of
# specifying "authhost" and "accthost" in a realm section, the home
# servers are specified seperately in a "home_server" section. For
# backwards compatibility, you can still use the "authhost" and
# "accthost" directives. If you only have one home server for a
# realm, it is easier to use the old-style configuration.
#
# However, if you have multiple servers for a realm, we STRONGLY
# suggest moving to the new-style configuration.
#
#
# Load-balancing and failover between home servers is handled via
# a "home_server_pool" section.
#
# Finally, The "realm" section defines the realm, some options, and
# indicates which server pool should be used for the realm.
#
# This change means that simple configurations now require multiple
# sections to define a realm. However, complex configurations
# are much simpler than before, as multiple realms can share the same
# server pool.
#
# That is, realms point to server pools, and server pools point to
# home servers. Multiple realms can point to one server pool. One
# server pool can point to multiple home servers. Each home server
# can appear in one or more pools.
#
######################################################################
#
# This section defines a "Home Server" which is another RADIUS
# server that gets sent proxied requests. In earlier versions
# of FreeRADIUS, home servers were defined in "realm" sections,
# which was awkward. In 2.0, they have been made independent
# from realms, which is better for a number of reasons.
#
home_server localhost {
#
# Home servers can be sent Access-Request packets
# or Accounting-Request packets.
#
# Allowed values are:
# auth - Handles Access-Request packets
# acct - Handles Accounting-Request packets
# auth+acct - Handles Access-Request packets at "port",
# and Accounting-Request packets at "port + 1"
# coa - Handles CoA-Request and Disconnect-Request packets.
# See also raddb/sites-available/originate-coa
type = auth
#
# Configure ONE OF the following entries:
#
# IPv4 address
#
ipaddr = 127.0.0.1
# OR IPv6 address
# ipv6addr = ::1
# OR virtual server
# virtual_server = foo
# Note that while both ipaddr and ipv6addr will accept
# both addresses and host names, we do NOT recommend
# using host names. When you specify a host name, the
# server has to do a DNS lookup to find the IP address
# of the home server. If the DNS server is slow or
# unresponsive, it means that FreeRADIUS will NOT be
# able to determine the address, and will therefore NOT
# start.
#
# Also, the mapping of host name to address is done ONCE
# when the server starts. If DNS is later updated to
# change the address, FreeRADIUS will NOT discover that
# until after a re-start, or a HUP.
#
# If you specify a virtual_server here, then requests
# will be proxied internally to that virtual server.
# These requests CANNOT be proxied again, however. The
# intent is to have the local server handle packets
# when all home servers are dead.
#
# Requests proxied to a virtual server will be passed
# through the pre-proxy and post-proxy sections, just
# like any other request. See also the sample "realm"
# configuration, below.
#
# None of the rest of the home_server configuration is used
# for the "virtual_server" configuration.
#
# The port to which packets are sent.
#
# Usually 1812 for type "auth", and 1813 for type "acct".
# Older servers may use 1645 and 1646.
# Use 3799 for type "coa"
#
port = 1812
#
# The shared secret use to "encrypt" and "sign" packets between
# FreeRADIUS and the home server.
#
# The secret can be any string, up to 8k characters in length.
#
# Control codes can be entered vi octal encoding,
# e.g. "\101\102" == "AB"
# Quotation marks can be entered by escaping them,
# e.g. "foo\"bar"
# Spaces or other "special" characters can be entered
# by putting quotes around the string.
# e.g. "foo bar"
# "foo;bar"
#
secret = testing123
############################################################
#
# The rest of the configuration items listed here are optional,
# and do not have to appear in every home server definition.
#
############################################################
#
# You can optionally specify the source IP address used when
# proxying requests to this home server. When the src_ipaddr
# it set, the server will automatically create a proxy
# listener for that IP address.
#
# If you specify this field for one home server, you will
# likely need to specify it for ALL home servers.
#
# If you don't care about the source IP address, leave this
# entry commented.
#
# src_ipaddr = 127.0.0.1
# RFC 5080 suggests that all clients SHOULD include it in an
# Access-Request. The configuration item below tells the
# proxying server (i.e. this one) whether or not the home
# server requires a Message-Authenticator attribute. If it
# is required (value set to "yes"), then all Access-Request
# packets sent to that home server will have a
# Message-Authenticator attribute.
#
# We STRONGLY recommend that this flag be set to "yes"
# for ALL home servers. Doing so will have no performance
# impact on the proxy or on the home servers. It will,
# however, allow administrators to detect problems earlier.
#
# allowed values: yes, no
require_message_authenticator = yes
#
# If the home server does not respond to a request within
# this time, this server will initiate "zombie_period".
#
# The response window is large because responses MAY be slow,
# especially when proxying across the Internet.
#
# Useful range of values: 5 to 60
response_window = 20
#
# If you want the old behavior of the server rejecting
# proxied requests after "response_window" timeout, set
# the following configuration item to "yes".
#
# This configuration WILL be removed in a future release
# If you believe you need it, email the freeradius-users
# list, and explain why it should stay in the server.
#
# no_response_fail = no
#
# If the home server does not respond to ANY packets during
# the "zombie period", it will be considered to be dead.
#
# A home server that is marked "zombie" will be used for
# proxying as a low priority. If there are live servers,
# they will always be preferred to a zombie. Requests will
# be proxied to a zombie server ONLY when there are no
# live servers.
#
# Any request that is proxied to a home server will continue
# to be sent to that home server until the home server is
# marked dead. At that point, it will fail over to another
# server, if a live server is available. If none is available,
# then the "post-proxy-type fail" handler will be called.
#
# If "status_check" below is something other than "none", then
# the server will start sending status checks at the start of
# the zombie period. It will continue sending status checks
# until the home server is marked "alive".
#
# Useful range of values: 20 to 120
zombie_period = 40
############################################################
#
# As of 2.0, FreeRADIUS supports RADIUS layer "status
# checks". These are used by a proxy server to see if a home
# server is alive.
#
# These status packets are sent ONLY if the proxying server
# believes that the home server is dead. They are NOT sent
# if the proxying server believes that the home server is
# alive. They are NOT sent if the proxying server is not
# proxying packets.
#
# If the home server responds to the status check packet,
# then it is marked alive again, and is returned to use.
#
############################################################
#
# Some home servers do not support status checks via the
# Status-Server packet. Others may not have a "test" user
# configured that can be used to query the server, to see if
# it is alive. For those servers, we have NO WAY of knowing
# when it becomes alive again. Therefore, after the server
# has been marked dead, we wait a period of time, and mark
# it alive again, in the hope that it has come back to
# life.
#
# If it has NOT come back to life, then FreeRADIUS will wait
# for "zombie_period" before marking it dead again. During
# the "zombie_period", ALL AUTHENTICATIONS WILL FAIL, because
# the home server is still dead. There is NOTHING that can
# be done about this, other than to enable the status checks,
# as documented below.
#
# e.g. if "zombie_period" is 40 seconds, and "revive_interval"
# is 300 seconds, the for 40 seconds out of every 340, or about
# 10% of the time, all authentications will fail.
#
# If the "zombie_period" and "revive_interval" configurations
# are set smaller, than it is possible for up to 50% of
# authentications to fail.
#
# As a result, we recommend enabling status checks, and
# we do NOT recommend using "revive_interval".
#
# The "revive_interval" is used ONLY if the "status_check"
# entry below is "none". Otherwise, it will not be used,
# and should be deleted.
#
# Useful range of values: 60 to 3600
revive_interval = 120
#
# The proxying server (i.e. this one) can do periodic status
# checks to see if a dead home server has come back alive.
#
# If set to "none", then the other configuration items listed
# below are not used, and the "revive_interval" time is used
# instead.
#
# If set to "status-server", the Status-Server packets are
# sent. Many RADIUS servers support Status-Server. If a
# server does not support it, please contact the server
# vendor and request that they add it.
#
# If set to "request", then Access-Request, or Accounting-Request
# packets are sent, depending on the "type" entry above (auth/acct).
#
# Allowed values: none, status-server, request
status_check = status-server
#
# If the home server does not support Status-Server packets,
# then the server can still send Access-Request or
# Accounting-Request packets, with a pre-defined user name.
#
# This practice is NOT recommended, as it may potentially let
# users gain network access by using these "test" accounts!
#
# If it is used, we recommend that the home server ALWAYS
# respond to these Access-Request status checks with
# Access-Reject. The status check just needs an answer, it
# does not need an Access-Accept.
#
# For Accounting-Request status checks, only the username
# needs to be set. The rest of the accounting attribute are
# set to default values. The home server that receives these
# accounting packets SHOULD NOT treat them like normal user
# accounting packets. i.e It should probably NOT log them to
# a database.
#
# username = "test_user_please_reject_me"
# password = "this is really secret"
#
# Configure the interval between sending status check packets.
#
# Setting it too low increases the probability of spurious
# fail-over and fallback attempts.
#
# Useful range of values: 6 to 120
check_interval = 30
#
# Configure the number of status checks in a row that the
# home server needs to respond to before it is marked alive.
#
# If you want to mark a home server as alive after a short
# time period of being responsive, it is best to use a small
# "check_interval", and a large value for
# "num_answers_to_alive". Using a long "check_interval" and
# a small number for "num_answers_to_alive" increases the
# probability of spurious fail-over and fallback attempts.
#
# Useful range of values: 3 to 10
num_answers_to_alive = 3
#
# Limit the total number of outstanding packets to the home
# server.
#
# if ((#request sent) - (#requests received)) > max_outstanding
# then stop sending more packets to the home server
#
# This lets us gracefully fall over when the home server
# is overloaded.
max_outstanding = 65536
#
# The configuration items in the next sub-section are used ONLY
# when "type = coa". It is ignored for all other type of home
# servers.
#
# See RFC 5080 for the definitions of the following terms.
# RAND is a function (internal to FreeRADIUS) returning
# random numbers between -0.1 and +0.1
#
# First Re-transmit occurs after:
#
# RT = IRT + RAND*IRT
#
# Subsequent Re-transmits occur after:
#
# RT = 2 * RTprev + RAND * RTprev
#
# Re-trasnmits are capped at:
#
# if (MRT && (RT > MRT)) RT = MRT + RAND * MRT
#
# For a maximum number of attempts: MRC
#
# For a maximum (total) period of time: MRD.
#
coa {
# Initial retransmit interval: 1..5
irt = 2
# Maximum Retransmit Timeout: 1..30 (0 == no maximum)
mrt = 16
# Maximum Retransmit Count: 1..20 (0 == retransmit forever)
mrc = 5
# Maximum Retransmit Duration: 5..60
mrd = 30
}
}
# Sample virtual home server.
#
#
#home_server virtual.example.com {
# virtual_server = virtual.example.com
#}
######################################################################
#
# This section defines a pool of home servers that is used
# for fail-over and load-balancing. In earlier versions of
# FreeRADIUS, fail-over and load-balancing were defined per-realm.
# As a result, if a server had 5 home servers, each of which served
# the same 10 realms, you would need 50 "realm" entries.
#
# In version 2.0, you would need 5 "home_server" sections,
# 10 'realm" sections, and one "home_server_pool" section to tie the
# two together.
#
home_server_pool my_auth_failover {
#
# The type of this pool controls how home servers are chosen.
#
# fail-over - the request is sent to the first live
# home server in the list. i.e. If the first home server
# is marked "dead", the second one is chosen, etc.
#
# load-balance - the least busy home server is chosen,
# where "least busy" is counted by taking the number of
# requests sent to that home server, and subtracting the
# number of responses received from that home server.
#
# If there are two or more servers with the same low
# load, then one of those servers is chosen at random.
# This configuration is most similar to the old
# "round-robin" method, though it is not exactly the same.
#
# Note that load balancing does not work well with EAP,
# as EAP requires packets for an EAP conversation to be
# sent to the same home server. The load balancing method
# does not keep state in between packets, meaning that
# EAP packets for the same conversation may be sent to
# different home servers. This will prevent EAP from
# working.
#
# For non-EAP authentication methods, and for accounting
# packets, we recommend using "load-balance". It will
# ensure the highest availability for your network.
#
# client-balance - the home server is chosen by hashing the
# source IP address of the packet. If that home server
# is down, the next one in the list is used, just as
# with "fail-over".
#
# There is no way of predicting which source IP will map
# to which home server.
#
# This configuration is most useful to do simple load
# balancing for EAP sessions, as the EAP session will
# always be sent to the same home server.
#
# client-port-balance - the home server is chosen by hashing
# the source IP address and source port of the packet.
# If that home server is down, the next one in the list
# is used, just as with "fail-over".
#
# This method provides slightly better load balancing
# for EAP sessions than "client-balance". However, it
# also means that authentication and accounting packets
# for the same session MAY go to different home servers.
#
# keyed-balance - the home server is chosen by hashing (FNV)
# the contents of the Load-Balance-Key attribute from the
# control items. The request is then sent to home server
# chosen by taking:
#
# server = (hash % num_servers_in_pool).
#
# If there is no Load-Balance-Key in the control items,
# the load balancing method is identical to "load-balance".
#
# For most non-EAP authentication methods, The User-Name
# attribute provides a good key. An "unlang" policy can
# be used to copy the User-Name to the Load-Balance-Key
# attribute. This method may not work for EAP sessions,
# as the User-Name outside of the TLS tunnel is often
# static, e.g. "***@realm".
#
#
# The default type is fail-over.
type = fail-over
#
# A virtual_server may be specified here. If so, the
# "pre-proxy" and "post-proxy" sections are called when
# the request is proxied, and when a response is received.
#
# This lets you have one policy for all requests that are proxied
# to a home server. This policy is completely independent of
# any policies used to receive, or process the request.
#
#virtual_server = pre_post_proxy_for_pool
#
# Next, a list of one or more home servers. The names
# of the home servers are NOT the hostnames, but the names
# of the sections. (e.g. home_server foo {...} has name "foo".
#
# Note that ALL home servers listed here have to be of the same
# type. i.e. they all have to be "auth", or they all have to
# be "acct", or the all have to be "auth+acct".
#
home_server = localhost
# Additional home servers can be listed.
# There is NO LIMIT to the number of home servers that can
# be listed, though using more than 10 or so will become
# difficult to manage.
#
# home_server = foo.example.com
# home_server = bar.example.com
# home_server = baz.example.com
# home_server = ...
#
# If ALL home servers are dead, then this "fallback" home server
# is used. If set, it takes precedence over any realm-based
# fallback, such as the DEFAULT realm.
#
# For reasons of stability, this home server SHOULD be a virtual
# server. Otherwise, the fallback may itself be dead!
#
#fallback = virtual.example.com
}
######################################################################
#
#
# This section defines a new-style "realm". Note the in version 2.0,
# there are many fewer configuration items than in 1.x for a realm.
#
# Automatic proxying is done via the "realms" module (see "man
# rlm_realm"). To manually proxy the request put this entry in the
# "users" file:
#
#
#DEFAULT Proxy-To-Realm := "realm_name"
#
#
realm example.com {
#
# Realms point to pools of home servers.
#
# For authentication, the "auth_pool" configuration item
# should point to a "home_server_pool" that was previously
# defined. All of the home servers in the "auth_pool" must
# be of type "auth".
#
# For accounting, the "acct_pool" configuration item
# should point to a "home_server_pool" that was previously
# defined. All of the home servers in the "acct_pool" must
# be of type "acct".
#
# If you have a "home_server_pool" where all of the home servers
# are of type "auth+acct", you can just use the "pool"
# configuration item, instead of specifying both "auth_pool"
# and "acct_pool".
auth_pool = my_auth_failover
# acct_pool = acct
#
# Normally, when an incoming User-Name is matched against the
# realm, the realm name is "stripped" off, and the "stripped"
# user name is used to perform matches.
#
# e.g. User-Name = "***@example.com" will result in two new
# attributes being created by the "realms" module:
#
# Stripped-User-Name = "bob"
# Realm = "example.com"
#
# The Stripped-User-Name is then used as a key in the "users"
# file, for example.
#
# If you do not want this to happen, uncomment "nostrip" below.
#
# nostrip
# There are no more configuration entries for a realm.
}
#
# This is a sample entry for iPass.
# Note that you have to define "ipass_auth_pool" and
# "ipass_acct_pool", along with home_servers for them, too.
#
#realm IPASS {
# nostrip
#
# auth_pool = ipass_auth_pool
# acct_pool = ipass_acct_pool
#}
#
# This realm is used mainly to cancel proxying. You can have
# the "realm suffix" module configured to proxy all requests for
# a realm, and then later cancel the proxying, based on other
# configuration.
#
# For example, you want to terminate PEAP or EAP-TTLS locally,
# you can add the following to the "users" file:
#
# DEFAULT EAP-Type == PEAP, Proxy-To-Realm := LOCAL
#
realm LOCAL {
# If we do not specify a server pool, the realm is LOCAL, and
# requests are not proxied to it.
}
#
# This realm is for requests which don't have an explicit realm
# prefix or suffix. User names like "bob" will match this one.
#
#realm NULL {
# authhost = radius.company.com:1600
# accthost = radius.company.com:1601
# secret = testing123
#}
#
# This realm is for ALL OTHER requests.
#
#realm DEFAULT {
# authhost = radius.company.com:1600
# accthost = radius.company.com:1601
# secret = testing123
#}
# This realm "proxies" requests internally to a virtual server.
# The pre-proxy and post-proxy sections are run just as with any
# other kind of home server. The virtual server then receives
# the request, and replies, just as with any other packet.
#
# Once proxied internally like this, the request CANNOT be proxied
# internally or externally.
#
#realm virtual.example.com {
# virtual_server = virtual.example.com
#}
#
#
# Regular expressions may also be used as realm names. If these are used,
# then the "find matching realm" process is as follows:
#
# 1) Look for a non-regex realm with an *exact* match for the name.
# If found, it is used in preference to any regex matching realm.
#
# 2) Look for a regex realm, in the order that they are listed
# in the configuration files. Any regex match is performed in
# a case-insensitive fashion.
#
# 3) If no realm is found, return the DEFAULT realm, if any.
#
# The order of the realms matters in step (2). For example, defining
# two realms ".*\.example.net$" and ".*\.test\.example\.net$" will result
in
# the second realm NEVER matching. This is because all of the realms
# which match the second regex also match the first one. Since the
# first regex matches, it is returned.
#
# The solution is to list the realms in the opposite order,. e.g.
# ".*\.test\.example.net$", followed by ".*\.example\.net$".
#
#
# Some helpful rules:
#
# - always place a '~' character at the start of the realm name.
# This signifies that it is a regex match, and not an exact match
# for the realm.
#
# - place the regex in double quotes. This helps the configuration
# file parser ignore any "special" characters in the regex.
# Yes, this rule is different than the normal "unlang" rules for
# regular expressions. That may be fixed in a future release.
#
# - use two back-slashes '\\' whenever you need one backslash in the
# regex. e.g. "~.*\\.example\\.net$", and not "~\.example\.net$".
# This is because the regex is in a double-quoted string, and normal
# rules apply for double-quoted strings.
#
# - If you are matching domain names, use two backslashes in front of
# every '.' (dot or period). This is because '.' has special meaning
# in a regular expression: match any character. If you do not do this,
# then "~.*.example.net$" will match "fooXexampleYnet", which is likely
# not what you want
#
# - If you are matching domain names, put a '$' at the end of the regex
# that matches the domain name. This tells the regex matching code
# that the realm ENDS with the domain name, so it does not match
# realms with the domain name in the middle. e.g. "~.*\\.example\\.net"
# will match "test.example.netFOO", which is likely not what you want.
# Using "~(.*\\.)example\\.net$" is better.
#
# The more regex realms that are defined, the more time it takes to
# process them. You should define as few regex realms as possible
# in order to maximize server performance.
#
#realm "~(.*\\.)*example\\.net$" {
# auth_pool = my_auth_failover
#}
$INCLUDE proxy.conf.inc
*cat /usr/local/pf/raddb/proxy.conf.inc *
# This file is generated from a template at
/usr/local/pf/conf/radiusd/proxy.conf.inc
# Any changes made to this file will be lost on restart
realm BS {
strip
}
realm bs.firma.de {
strip
}
*and my logfile:*
*raddebug -f /usr/local/pf/var/run/radiusd.sock*
Tue Mar 22 15:46:41 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=224, length=270
Tue Mar 22 15:46:41 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:41 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:41 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:41 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:41 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x0201002101686f73742f35302d3035342e62732e667261756e686f6665722e6465
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x29be7811f63988eca058a8f510b23103
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:41 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: server packetfence {
Tue Mar 22 15:46:41 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authorize {
Tue Mar 22 15:46:41 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 0:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:41 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:41 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 0:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:41 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:41 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:41 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP packet type response id 1
length 33
Tue Mar 22 15:46:41 2016 : Debug: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = updated
Tue Mar 22 15:46:41 2016 : Debug: ++[files] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[expiration] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[logintime] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Packet-Src-IP-Address} ->
10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: ++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++update control {
Tue Mar 22 15:46:41 2016 : Debug: ++} # update control = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[packetfence] = noop
Tue Mar 22 15:46:41 2016 : Debug: +} # group authorize = updated
Tue Mar 22 15:46:41 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:41 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP Identity
Tue Mar 22 15:46:41 2016 : Debug: [eap] processing type tls
Tue Mar 22 15:46:41 2016 : Debug: [tls] Initiate
Tue Mar 22 15:46:41 2016 : Debug: [tls] Start returned 1
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:41 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:41 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:41 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=224, length=0
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x010200061920
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a2204a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: Finished request 0.
Tue Mar 22 15:46:41 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=225, length=364
Tue Mar 22 15:46:41 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:41 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:41 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:41 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:41 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x0202006d198000000063160301005e0100005a030156f15ad08bacf2f992ca21fdd8798f05db603003ce8a71db857a6e6718f62b17000018c014c0130035002fc00ac00900380032000a00130005000401000019000a0006000400170018000b0002010000170000ff01000100
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x84c3e622417ad4c05dc9c7c4512d6702
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a2204a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: server packetfence {
Tue Mar 22 15:46:41 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authorize {
Tue Mar 22 15:46:41 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 1:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:41 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:41 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 1:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:41 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:41 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:41 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP packet type response id 2
length 109
Tue Mar 22 15:46:41 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:41 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:41 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:41 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:41 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:41 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:41 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:41 2016 : Debug: [peap] Length Included
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_verify returned 11
Tue Mar 22 15:46:41 2016 : Debug: [peap] (other): before/accept
initialization
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: before/accept
initialization
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 read client
hello A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 write server
hello A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 write
certificate A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 write key
exchange A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 write server
done A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: SSLv3 flush data
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: Need to read more
data: SSLv3 read client certificate A
Tue Mar 22 15:46:41 2016 : Debug: [peap] TLS_accept: Need to read more
data: SSLv3 read client certificate A
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_process returned 13
Tue Mar 22 15:46:41 2016 : Debug: [peap] EAPTLS_HANDLED
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:41 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:41 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:41 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=225, length=0
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x0103040019c000000e13160301003902000035030156f15ad195fbfd15b1375e7c8a749d8e805cd69007bfb8e50b60da4db06c17b200c01400000dff01000100000b0004030001021603010c770b000c73000c700005fc308205f8308204e0a00302010202131d00000adba1ef04e10d7a48ef000000000adb300d06092a864886f70d0101050500305931123010060a0992268993f22c64011916026465311a3018060a0992268993f22c640119160a667261756e686f66657231123010060a0992268993f22c64011916026273311330110603550403130a42532d555345522d4341301e170d3136303332313134343931315a170d31363037323230
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x38333631365a3081b8310b3009060355040613024445311530130603550408130c427261756e73636877656967311530130603550407130c427261756e7363687765696731163014060355040a130d467261756e686f66657220425331143012060355040b130b49542d48656c706465736b311d301b060355040313146e61632e62732e667261756e686f6665722e6465312e302c06092a864886f70d010901161f746f626961732e66726965646540776b692e667261756e686f6665722e646530820122300d06092a864886f70d01010105000382010f003082010a0282010100bda42879d0d2a2d08524de05fb42a1e73dae71a334393a2163fb5f
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x00ecbda44098fa03e45e4099c77d347c809c01b95f194f8667274e7edbf1265fac8288fa25084448301d45e4ebbdd08dcc6bf2a5a62eba15c30215f05d7b44655365ff19245a01b9054755bf8aadf452158e286ecfa2d85079889991b7c6761f84aed949da2a46863d923ad85234190378c05caeda713edf457e1877aacb34b3d82955efc6fc61013a0be86d47b23596d627a8baf235d0bfb65aebcaa5314babc864add8a612a941e79a8d1bf54b5648d3875940940ef9db872e930c56869e36d5d2423a2f69512802545c0d7f201802b63906f0a5d384f6e46e35ce47910e18fdde21da970203010001a382025730820253301d0603551d0e04160414
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x196297c4f998dd6a7caed3af43663c5c0fcd7078301f0603551d230418301680145a5cf40f8e5b58a712c14f3a1a7bfe9f03eb6b77308201000603551d1f0481f83081f53081f2a081efa081ec8681b86c6461703a2f2f2f434e3d42532d555345522d43412c434e3d5355422d43412c434e3d4344502c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d62732c44433d667261756e686f6665722c44433d64653f63657274696669636174655265766f636174696f6e4c6973743f626173653f6f626a656374436c6173733d63524c446973747269
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x627574696f6e506f696e7486
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a3214a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: Finished request 1.
Tue Mar 22 15:46:41 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=226, length=261
Tue Mar 22 15:46:41 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:41 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:41 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:41 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:41 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x020300061900
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0xba34febafa6c7b27723bbfd719cbbd21
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a3214a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: server packetfence {
Tue Mar 22 15:46:41 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authorize {
Tue Mar 22 15:46:41 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 2:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:41 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:41 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 2:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:41 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:41 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:41 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP packet type response id 3
length 6
Tue Mar 22 15:46:41 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:41 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:41 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:41 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:41 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:41 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:41 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:41 2016 : Debug: [peap] Received TLS ACK
Tue Mar 22 15:46:41 2016 : Debug: [peap] ACK handshake fragment handler
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_verify returned 1
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_process returned 13
Tue Mar 22 15:46:41 2016 : Debug: [peap] EAPTLS_HANDLED
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:41 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:41 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:41 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=226, length=0
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x010403fc19402f687474703a2f2f63726c2e62732e667261756e686f6665722e64652f63726c642f42532d555345522d43412e63726c3081c406082b060105050701010481b73081b43081b106082b060105050730028681a46c6461703a2f2f2f434e3d42532d555345522d43412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d62732c44433d667261756e686f6665722c44433d64653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x302106092b060104018237140204141e12005700650062005300650072007600650072300e0603551d0f0101ff0404030205a030130603551d25040c300a06082b06010505070301300d06092a864886f70d010105050003820101005c353fc1894e93f49aa3c97b2db09f14c34d92616ef0bcda12cf5fee5be8885e4fd52e6f95218429078d0b7f2104c557be03900cbd920d589118b8a9d2c46fb0336ef6bfffd34eede4ccc531f5f2341ca3c11e638ef6f20ef9ab7c5875e1b35584bdcb0ea1a1caa8fb118b2bf50b43423df187d96a85efdc92792e5fbdc89224c1bd902ab683915d032b61a68a30a103e32beec790099a35d5a8b102ec7af24ea5
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x70554d7032eb6d2618f02964b0dd336898b7c92a682355dc5d6b6005701e5531911cc442009f4a53f9234abb363c35d9005a58d74d0489098b5dda89953ead25ce4bf6f9fd97bfd7ec13fec3e87ae72ccaf38a6d987348fe09094c9f32435400066e3082066a30820452a00302010202131600000002a2530b77dfe94e1a000000000002300d06092a864886f70d0101050500305931123010060a0992268993f22c64011916026465311a3018060a0992268993f22c640119160a667261756e686f66657231123010060a0992268993f22c64011916026273311330110603550403130a42532d524f4f542d4341301e170d3135303732323038323631
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x365a170d3136303732323038333631365a305931123010060a0992268993f22c64011916026465311a3018060a0992268993f22c640119160a667261756e686f66657231123010060a0992268993f22c64011916026273311330110603550403130a42532d555345522d434130820122300d06092a864886f70d01010105000382010f003082010a0282010100b9412186cae8e5ce9a45e2698602870c2d0e4acde17e6db24f3ac01793708bdb9e850627a1cb2e8ca8b841d0abb55e983018a321017e7be35e15d9186d9574ccbd09a8883d7bb38a046a2e969ff22e5c570365c9d101c74e2fdfe8d6088d589dfe11911f9d69bd194d5742681ee9c153
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x8ae9ecc78c335e48
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a0264a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: Finished request 2.
Tue Mar 22 15:46:41 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=227, length=261
Tue Mar 22 15:46:41 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:41 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:41 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:41 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:41 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x020400061900
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x1dbb0fb5343ee865f2548b12995b5412
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a0264a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: server packetfence {
Tue Mar 22 15:46:41 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authorize {
Tue Mar 22 15:46:41 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 3:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:41 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:41 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 3:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:41 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:41 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:41 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP packet type response id 4
length 6
Tue Mar 22 15:46:41 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:41 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:41 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:41 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:41 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:41 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:41 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:41 2016 : Debug: [peap] Received TLS ACK
Tue Mar 22 15:46:41 2016 : Debug: [peap] ACK handshake fragment handler
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_verify returned 1
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_process returned 13
Tue Mar 22 15:46:41 2016 : Debug: [peap] EAPTLS_HANDLED
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:41 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:41 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:41 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=227, length=0
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x010503fc1940c06266bc658bb6f6ed540b30ab6f251e55b2469a485db3f2b2ea8d4fd5cf28d0a8abb4b6d7964ad5ebc29c7fa758cd2e4deb71c0ac27c16c3df659ff3e4f4cf4ac59344a6e01d27114e682217a38930a57a0e6ec7018350509352a6a256910bf0a41da1f978a7b9105b2b5efae03e5db67a9a9ca9ee6f4a70a3722519d68fe8daf9d669986b1bd090203010001a382022930820225301006092b06010401823715010403020100301d0603551d0e041604145a5cf40f8e5b58a712c14f3a1a7bfe9f03eb6b77301906092b0601040182371402040c1e0a00530075006200430041300b0603551d0f040403020186300f0603551d130101
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0xff040530030101ff301f0603551d230418301680145890387e9296c26eb52b7f17c97f2ad90eded9083081d00603551d1f0481c83081c53081c2a081bfa081bc8681b96c6461703a2f2f2f434e3d42532d524f4f542d43412c434e3d526f6f742d43412c434e3d4344502c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d62732c44433d667261756e686f6665722c44433d64653f63657274696669636174655265766f636174696f6e4c6973743f626173653f6f626a656374436c6173733d63524c446973747269627574696f6e506f696e7430
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x81c406082b060105050701010481b73081b43081b106082b060105050730028681a46c6461703a2f2f2f434e3d42532d524f4f542d43412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d62732c44433d667261756e686f6665722c44433d64653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479300d06092a864886f70d01010505000382020100a4473ebb784ebaa377863e90a742037701dc636f990a5e1154accd872749a3b16b6da2
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0xd23cbf39b0482f09e8321ca8f605d599e3065c0fe9d9fbde219716c16e9ffd8d29168e198d04367b748073a94b6f626fa8f436b149f153f994c482464ce819455950554028a155e23d569bba5b78b8394d0fa6eeaa55e837798ed0adb3d8d08bfc5eb041fa05a0d593bb64eec62af08e86287337f3d983535002cbe16747bf6b79d0baa2b7cdbd8eba2840f85d5832b206763c15c402c604bf20798cda13eb57807c7cdae60fce27aea8ab4d4f491f19f6360409927be543f094cfa0fe9c535cf2ae7ccbf5d0905cd35a9f82923a7e924dddf287a96ee15a8c5e56848ed86a70ba4cb6ca192611c9882591842e76fbc42729e51364394fb10d1f92fb7e
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0xb66307790b8fcbbf
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a1274a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: Finished request 3.
Tue Mar 22 15:46:41 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=228, length=261
Tue Mar 22 15:46:41 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:41 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:41 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:41 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:41 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message = 0x020500061900
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0xf2bc1df613ac51c736eb2b3134119b3d
Tue Mar 22 15:46:41 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:41 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a1274a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:41 2016 : Debug: server packetfence {
Tue Mar 22 15:46:41 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authorize {
Tue Mar 22 15:46:41 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 4:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:41 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:41 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:41 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:41 2016 : Debug: ++++update request {
Tue Mar 22 15:46:41 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:41 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:41 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:41 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:41 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:41 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:41 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:41 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:41 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:41 2016 : Debug: +++ ... skipping else for request 4:
Preceding "if" was taken
Tue Mar 22 15:46:41 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:41 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:41 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:41 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:41 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:41 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP packet type response id 5
length 6
Tue Mar 22 15:46:41 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:41 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:41 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:41 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:41 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:41 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:41 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:41 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:41 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:41 2016 : Debug: [peap] Received TLS ACK
Tue Mar 22 15:46:41 2016 : Debug: [peap] ACK handshake fragment handler
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_verify returned 1
Tue Mar 22 15:46:41 2016 : Debug: [peap] eaptls_process returned 13
Tue Mar 22 15:46:41 2016 : Debug: [peap] EAPTLS_HANDLED
Tue Mar 22 15:46:41 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:41 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:41 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:41 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=228, length=0
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x0106023719000e3c4fddd95c2f71a82e46feee5173b1809de12c6eaab3370993c6bd872938d4f2f8d7c44a2acad288c004661c4c689d5ff2b8215da77ccb918bffba93348c05411c8686c7e81c7f568f194c56fe3b0a528f0a14ede9b22633f6253c226a635cdae2c5138f7502da5cb22eb1f1b2afe29c6d216e24aee3849783bc94c16159e5047d531c8252c94e56abe31eeb77513fe7e32f063f144816cf17fbc5e73ee25378b76709d03bf88c136a71681d4aab7a818be20459bc3be1055adb87027eac9b68716a993e4d4859609e7610312b811014bde6be62e80a54160301014b0c0001470300174104b4d8bfd6b0ba56fa301919feff784cdf89
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0x23fd88c9b928cbd8dd3adf84185da72ae0131b884eb9c8f5d9948abe66c09d997eaf0d2a1fd813daf3fccc7b1c543d01001d1796430d3b686a1dc1f67811550bc5f5d74229646609b22980dab835dee035dc03b221a5e3b3038ff88c781f93832f53aa2e32c7dd6bbc531873cda291fd1c067ebbe817357caeab1d2680315e3e424eb0ad66b677e5ec0b8886dfc2dba88fa6828825370e3c0a841bf8d50c3e0a9c2817aa1125656ee8dc57a24f52b6bd8cb538ff2d46c72d3d0a5efb74f1280089ba553c497b635092d5450cfa7cb621573476e55f2dde74dc4f28dc00794854f9292ee1ee8910dd069230937e6cbafe135289dbea87867abfd4b672dd
Tue Mar 22 15:46:41 2016 : Debug: EAP-Message =
0xb4a3da0b6d160ef12cc5c4c6d9a698117fa7359c727223164a543d73dea1b9fa52d94386d9d46813a295427a1b9b18bef765f6ec16030100040e000000
Tue Mar 22 15:46:41 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:41 2016 : Debug: State = 0xa22253f5a6244a6a4076fa9399b28ee2
Tue Mar 22 15:46:41 2016 : Debug: Finished request 4.
Tue Mar 22 15:46:42 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=229, length=399
Tue Mar 22 15:46:42 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:42 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:42 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:42 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:42 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:42 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:42 2016 : Debug: EAP-Message =
0x020600901980000000861603010046100000424104d72232fa3e9efb481d847b1a9cd85e453f92f0cae3713e08bb27ec90ad9db7055be968bb127f5aab00536fa7e935f6cb3d12778bfeaf3ddcb22e26a8df2804771403010001011603010030b67fc67a93442ecc26d157e233db313601b1622c6b11e3ede3d79eac4a5625e8f8dc43a839bc706efa70cf598a6dcd80
Tue Mar 22 15:46:42 2016 : Debug: Message-Authenticator =
0x21284d7e13d4261f9b3466e8f307ec52
Tue Mar 22 15:46:42 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:42 2016 : Debug: State = 0xa22253f5a6244a6a4076fa9399b28ee2
Tue Mar 22 15:46:42 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:42 2016 : Debug: server packetfence {
Tue Mar 22 15:46:42 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:42 2016 : Debug: +group authorize {
Tue Mar 22 15:46:42 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:42 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:42 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:42 2016 : Debug: ++++update request {
Tue Mar 22 15:46:42 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:42 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:42 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:42 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:42 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:42 2016 : Debug: +++ ... skipping else for request 5:
Preceding "if" was taken
Tue Mar 22 15:46:42 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:42 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:42 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:42 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:42 2016 : Debug: ++++update request {
Tue Mar 22 15:46:42 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:42 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:42 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:42 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:42 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:42 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:42 2016 : Debug: +++ ... skipping else for request 5:
Preceding "if" was taken
Tue Mar 22 15:46:42 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:42 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:42 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:42 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:42 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:42 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:42 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:42 2016 : Debug: [eap] EAP packet type response id 6
length 144
Tue Mar 22 15:46:42 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:42 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:42 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:42 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:42 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:42 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:42 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:42 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:42 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:42 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:42 2016 : Debug: [peap] Length Included
Tue Mar 22 15:46:42 2016 : Debug: [peap] eaptls_verify returned 11
Tue Mar 22 15:46:42 2016 : Debug: [peap] TLS_accept: SSLv3 read client
key exchange A
Tue Mar 22 15:46:42 2016 : Debug: [peap] TLS_accept: SSLv3 read
finished A
Tue Mar 22 15:46:42 2016 : Debug: [peap] TLS_accept: SSLv3 write change
cipher spec A
Tue Mar 22 15:46:42 2016 : Debug: [peap] TLS_accept: SSLv3 write
finished A
Tue Mar 22 15:46:42 2016 : Debug: [peap] TLS_accept: SSLv3 flush data
Tue Mar 22 15:46:42 2016 : Debug: [peap] (other): SSL negotiation
finished successfully
Tue Mar 22 15:46:42 2016 : Debug: [peap] eaptls_process returned 13
Tue Mar 22 15:46:42 2016 : Debug: [peap] EAPTLS_HANDLED
Tue Mar 22 15:46:42 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:42 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:42 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:42 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=229, length=0
Tue Mar 22 15:46:42 2016 : Debug: EAP-Message =
0x0107004119001403010001011603010030f610139ba0a53f5cd5d3d6b2b5d27aa06310dd0b71c416b9e2463a709ac6e8ba177592c0486fe297ed1d87431cf3a9fc
Tue Mar 22 15:46:42 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:42 2016 : Debug: State = 0xa22253f5a7254a6a4076fa9399b28ee2
Tue Mar 22 15:46:42 2016 : Debug: Finished request 5.
Tue Mar 22 15:46:42 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=230, length=261
Tue Mar 22 15:46:42 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:42 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:42 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:42 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:42 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:42 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:42 2016 : Debug: EAP-Message = 0x020700061900
Tue Mar 22 15:46:42 2016 : Debug: Message-Authenticator =
0x5cef8d6322d33121f203cd7d82f2885d
Tue Mar 22 15:46:42 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:42 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:42 2016 : Debug: State = 0xa22253f5a7254a6a4076fa9399b28ee2
Tue Mar 22 15:46:42 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:42 2016 : Debug: server packetfence {
Tue Mar 22 15:46:42 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:42 2016 : Debug: +group authorize {
Tue Mar 22 15:46:42 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:42 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:42 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:42 2016 : Debug: ++++update request {
Tue Mar 22 15:46:42 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:42 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:42 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:42 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:42 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:42 2016 : Debug: +++ ... skipping else for request 6:
Preceding "if" was taken
Tue Mar 22 15:46:42 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:42 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:42 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:42 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:42 2016 : Debug: ++++update request {
Tue Mar 22 15:46:42 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:42 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:42 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:42 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:42 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:42 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:42 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:42 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:42 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:42 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:42 2016 : Debug: +++ ... skipping else for request 6:
Preceding "if" was taken
Tue Mar 22 15:46:42 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:42 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:42 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:42 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:42 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:42 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:42 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:42 2016 : Debug: [eap] EAP packet type response id 7
length 6
Tue Mar 22 15:46:42 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:42 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:42 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:42 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:42 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:42 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:42 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:42 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:42 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:42 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:42 2016 : Debug: [peap] Received TLS ACK
Tue Mar 22 15:46:42 2016 : Debug: [peap] ACK handshake is finished
Tue Mar 22 15:46:42 2016 : Debug: [peap] eaptls_verify returned 3
Tue Mar 22 15:46:42 2016 : Debug: [peap] eaptls_process returned 3
Tue Mar 22 15:46:42 2016 : Debug: [peap] EAPTLS_SUCCESS
Tue Mar 22 15:46:42 2016 : Debug: [peap] Session established. Decoding
tunneled attributes.
Tue Mar 22 15:46:42 2016 : Debug: [peap] Peap state TUNNEL ESTABLISHED
Tue Mar 22 15:46:42 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:42 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:42 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:42 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=230, length=0
Tue Mar 22 15:46:42 2016 : Debug: EAP-Message =
0x0108002b19001703010020183249d82de7dcc3bc1cb5a65bbaec2c40f2d9d48acf0f027c54600421b87377
Tue Mar 22 15:46:42 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:42 2016 : Debug: State = 0xa22253f5a42a4a6a4076fa9399b28ee2
Tue Mar 22 15:46:42 2016 : Debug: Finished request 6.
Tue Mar 22 15:46:43 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=231, length=330
Tue Mar 22 15:46:43 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:43 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:43 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:43 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:43 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:43 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:43 2016 : Debug: EAP-Message =
0x0208004b19001703010040e5752b6fa34d1b423a2afb1d4e170d52e7a2cb04f74ecb7555d802fa8d9c895bf758eb966af98498aaa0d504440d61493f38014fb44aaadb72f6e31d5a2b87d1
Tue Mar 22 15:46:43 2016 : Debug: Message-Authenticator =
0x17fdb520eb233478d02bd49a936cf137
Tue Mar 22 15:46:43 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:43 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:43 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:43 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:43 2016 : Debug: State = 0xa22253f5a42a4a6a4076fa9399b28ee2
Tue Mar 22 15:46:43 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:43 2016 : Debug: server packetfence {
Tue Mar 22 15:46:43 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:43 2016 : Debug: +group authorize {
Tue Mar 22 15:46:43 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:43 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:43 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:43 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:43 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:43 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:43 2016 : Debug: ++++update request {
Tue Mar 22 15:46:43 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:43 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:43 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:43 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:43 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:43 2016 : Debug: +++ ... skipping else for request 7:
Preceding "if" was taken
Tue Mar 22 15:46:43 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:43 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:43 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:43 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:43 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:43 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:43 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:43 2016 : Debug: ++++update request {
Tue Mar 22 15:46:43 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:43 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:43 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:43 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:43 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:43 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:43 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:43 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:43 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:43 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:43 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:43 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:43 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:43 2016 : Debug: +++ ... skipping else for request 7:
Preceding "if" was taken
Tue Mar 22 15:46:43 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:43 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:43 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:43 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:43 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:43 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:43 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:43 2016 : Debug: [eap] EAP packet type response id 8
length 75
Tue Mar 22 15:46:43 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:43 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:43 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:43 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:43 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:43 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:43 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:43 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:43 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:43 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:43 2016 : Debug: [peap] eaptls_verify returned 7
Tue Mar 22 15:46:43 2016 : Debug: [peap] Done initial handshake
Tue Mar 22 15:46:43 2016 : Debug: [peap] eaptls_process returned 7
Tue Mar 22 15:46:43 2016 : Debug: [peap] EAPTLS_OK
Tue Mar 22 15:46:43 2016 : Debug: [peap] Session established. Decoding
tunneled attributes.
Tue Mar 22 15:46:43 2016 : Debug: [peap] Peap state WAITING FOR INNER
IDENTITY
Tue Mar 22 15:46:43 2016 : Debug: [peap] Identity - host/50-054.bs.firma.de
Tue Mar 22 15:46:43 2016 : Debug: [peap] Got inner identity 'host/
50-054.bs.firma.de'
Tue Mar 22 15:46:43 2016 : Debug: [peap] Setting default EAP type for
tunneled EAP session.
Tue Mar 22 15:46:43 2016 : Debug: [peap] Setting User-Name to host/
50-054.bs.firma.de
Tue Mar 22 15:46:43 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:43 2016 : Debug: +group authorize {
Tue Mar 22 15:46:43 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:43 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:43 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:43 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:43 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:43 2016 : Debug: ++[packetfence-multi-domain] = updated
Tue Mar 22 15:46:43 2016 : Debug: [eap] EAP packet type response id 8
length 33
Tue Mar 22 15:46:43 2016 : Debug: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Tue Mar 22 15:46:43 2016 : Debug: ++[eap] = updated
Tue Mar 22 15:46:43 2016 : Debug: ++[files] = noop
Tue Mar 22 15:46:43 2016 : Debug: ++[expiration] = noop
Tue Mar 22 15:46:43 2016 : Debug: ++[logintime] = noop
Tue Mar 22 15:46:43 2016 : Debug: +} # group authorize = updated
Tue Mar 22 15:46:43 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:43 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:43 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:43 2016 : Debug: [eap] EAP Identity
Tue Mar 22 15:46:43 2016 : Debug: [eap] processing type mschapv2
Tue Mar 22 15:46:43 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:43 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:43 2016 : Debug: [peap] Got tunneled Access-Challenge
Tue Mar 22 15:46:43 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:43 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:43 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:43 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=231, length=0
Tue Mar 22 15:46:43 2016 : Debug: EAP-Message =
0x0109005b19001703010050776a63f6394c393e7c0ebf49f12352beab1c1b0f3af1fbf77026b220ab3139d2231153d1415a7fe04ab375285ad7a948647fad99ad96b862141bb2e9789f23c7366947f9dca073b86ccf5d396917adb9
Tue Mar 22 15:46:43 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:43 2016 : Debug: State = 0xa22253f5a52b4a6a4076fa9399b28ee2
Tue Mar 22 15:46:43 2016 : Debug: Finished request 7.
Tue Mar 22 15:46:45 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=232, length=378
Tue Mar 22 15:46:45 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:45 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:45 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:45 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:45 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:45 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:45 2016 : Debug: EAP-Message =
0x0209007b19001703010070dd95888c050e5f7955bd509cd67f565dd3f5f05ae99225f7929a9e3b7aa6b2bd4512167191b7a4c264725b4fdf794a4dede6a86e066a533d8919ea96a50a8a3630f7c513694c1ff7d128096be568cb76568a1387511a9205fd3746569d06d81ed3b0fb32dc991e00cca6da9c515d6b69
Tue Mar 22 15:46:45 2016 : Debug: Message-Authenticator =
0xc0feeebd0a57cc15cddd1d7400d8f833
Tue Mar 22 15:46:45 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:45 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:45 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:45 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:45 2016 : Debug: State = 0xa22253f5a52b4a6a4076fa9399b28ee2
Tue Mar 22 15:46:45 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:45 2016 : Debug: server packetfence {
Tue Mar 22 15:46:45 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:45 2016 : Debug: +group authorize {
Tue Mar 22 15:46:45 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:45 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:45 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:45 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:45 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:45 2016 : Debug: ++++update request {
Tue Mar 22 15:46:45 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:45 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:45 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:45 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:45 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:45 2016 : Debug: +++ ... skipping else for request 8:
Preceding "if" was taken
Tue Mar 22 15:46:45 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:45 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:45 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:45 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:45 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:45 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:45 2016 : Debug: ++++update request {
Tue Mar 22 15:46:45 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:45 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:45 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:45 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:45 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:45 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:45 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:45 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:45 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:45 2016 : Debug: +++ ... skipping else for request 8:
Preceding "if" was taken
Tue Mar 22 15:46:45 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:45 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:45 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:45 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:45 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:45 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:45 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:45 2016 : Debug: [eap] EAP packet type response id 9
length 123
Tue Mar 22 15:46:45 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:45 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:45 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:45 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:45 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:45 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:45 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:45 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:45 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:45 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:45 2016 : Debug: [peap] eaptls_verify returned 7
Tue Mar 22 15:46:45 2016 : Debug: [peap] Done initial handshake
Tue Mar 22 15:46:45 2016 : Debug: [peap] eaptls_process returned 7
Tue Mar 22 15:46:45 2016 : Debug: [peap] EAPTLS_OK
Tue Mar 22 15:46:45 2016 : Debug: [peap] Session established. Decoding
tunneled attributes.
Tue Mar 22 15:46:45 2016 : Debug: [peap] Peap state phase2
Tue Mar 22 15:46:45 2016 : Debug: [peap] EAP type mschapv2
Tue Mar 22 15:46:45 2016 : Debug: [peap] Setting User-Name to host/
50-054.bs.firma.de
Tue Mar 22 15:46:45 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:45 2016 : Debug: +group authorize {
Tue Mar 22 15:46:45 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:45 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:45 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:45 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:45 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:45 2016 : Debug: ++[packetfence-multi-domain] = updated
Tue Mar 22 15:46:45 2016 : Debug: [eap] EAP packet type response id 9
length 87
Tue Mar 22 15:46:45 2016 : Debug: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Tue Mar 22 15:46:45 2016 : Debug: ++[eap] = updated
Tue Mar 22 15:46:45 2016 : Debug: ++[files] = noop
Tue Mar 22 15:46:45 2016 : Debug: ++[expiration] = noop
Tue Mar 22 15:46:45 2016 : Debug: ++[logintime] = noop
Tue Mar 22 15:46:45 2016 : Debug: +} # group authorize = updated
Tue Mar 22 15:46:45 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:45 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:45 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:45 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:45 2016 : Debug: [eap] EAP/mschapv2
Tue Mar 22 15:46:45 2016 : Debug: [eap] processing type mschapv2
Tue Mar 22 15:46:45 2016 : Debug: [mschapv2] # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:45 2016 : Debug: [mschapv2] +group MS-CHAP {
Tue Mar 22 15:46:45 2016 : Debug: ++[packetfence] = noop
Tue Mar 22 15:46:45 2016 : Debug: ++? if (PacketFence-Domain)
Tue Mar 22 15:46:45 2016 : Debug: ? Evaluating (PacketFence-Domain) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: ++? if (PacketFence-Domain) -> TRUE
Tue Mar 22 15:46:45 2016 : Debug: ++if (PacketFence-Domain) {
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] Creating challenge hash
with username: host/50-054.bs.firma.de
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] Client is using
MS-CHAPv2 for host/50-054.bs.firma.de, we need NT-Password
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] expand:
/chroots/%{PacketFence-Domain} -> /chroots/BS
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] expand:
--username=%{mschap:User-Name:-None} -> --username=50-054$
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] Creating challenge hash
with username: host/50-054.bs.firma.de
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] expand:
--challenge=%{mschap:Challenge:-00} -> --challenge=f201acf99bf602b7
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] expand:
--nt-response=%{mschap:NT-Response:-00} ->
--nt-response=2190023828c29bd54696acd0779d2e80fde27ac72532c9e0
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] Exec: program returned:
139
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] External script failed.
Tue Mar 22 15:46:45 2016 : Debug: [chrooted_mschap] FAILED:
MS-CHAP2-Response is incorrect
Tue Mar 22 15:46:45 2016 : Debug: +++[chrooted_mschap] = reject
Tue Mar 22 15:46:45 2016 : Debug: ++} # if (PacketFence-Domain) = reject
Tue Mar 22 15:46:45 2016 : Debug: +} # group MS-CHAP = reject
Tue Mar 22 15:46:45 2016 : Debug: [eap] Freeing handler
Tue Mar 22 15:46:45 2016 : Debug: ++[eap] = reject
Tue Mar 22 15:46:45 2016 : Debug: +} # group authenticate = reject
Tue Mar 22 15:46:45 2016 : Debug: Failed to authenticate the user.
Tue Mar 22 15:46:45 2016 : Debug: Using Post-Auth-Type Reject
Tue Mar 22 15:46:45 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 15:46:45 2016 : Debug: +group REJECT {
Tue Mar 22 15:46:45 2016 : Debug: [sql] expand: %{User-Name} -> host/
50-054.bs.firma.de
Tue Mar 22 15:46:45 2016 : Debug: [sql] sql_set_user escaped user --> 'host/
50-054.bs.firma.de'
Tue Mar 22 15:46:45 2016 : Debug: [sql] expand: %{check:Post-Auth-Type} ->
Reject
Tue Mar 22 15:46:45 2016 : Debug: [sql] 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) VALUES (
'%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}',
'%{control:PacketFence-Computer-Name}', '%{request:User-Name}',
'%{request:Stripped-User-Name}', '%{request:Realm}',
'Radius-Access-Request', '%{control:PacketFence-Switch-Id}',
'%{control:PacketFence-Switch-Mac}',
'%{control:PacketFence-Switch-Ip-Address}',
'%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{req
`#Tue Mar 22 15:46:45 2016 : Debug: ++[sql] = ok
Tue Mar 22 15:46:45 2016 : Debug: [attr_filter.access_reject] expand:
%{User-Name} -> host/50-054.bs.firma.de
Tue Mar 22 15:46:45 2016 : Debug: ++[attr_filter.access_reject] = updated
Tue Mar 22 15:46:45 2016 : Debug: +} # group REJECT = updated
Tue Mar 22 15:46:45 2016 : Debug: [peap] Tunneled authentication was
rejected.
Tue Mar 22 15:46:45 2016 : Debug: [peap] FAILURE
Tue Mar 22 15:46:45 2016 : Debug: ++[eap] = handled
Tue Mar 22 15:46:45 2016 : Debug: +} # group authenticate = handled
Tue Mar 22 15:46:45 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:45 2016 : Debug: Sending Access-Challenge packet to host
10.130.1.15 port 1645, id=232, length=0
Tue Mar 22 15:46:45 2016 : Debug: EAP-Message =
0x010a002b1900170301002025a2f60d2efaa13301e9621fc6b2b1a4fc062331b77b867b61403e376d146234
Tue Mar 22 15:46:45 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:45 2016 : Debug: State = 0xa22253f5aa284a6a4076fa9399b28ee2
Tue Mar 22 15:46:45 2016 : Debug: Finished request 8.
Tue Mar 22 15:46:46 2016 : Debug: Cleaning up request 0 ID 224 with
timestamp +78
Tue Mar 22 15:46:46 2016 : Debug: Cleaning up request 1 ID 225 with
timestamp +78
Tue Mar 22 15:46:46 2016 : Debug: Cleaning up request 2 ID 226 with
timestamp +78
Tue Mar 22 15:46:46 2016 : Debug: Cleaning up request 3 ID 227 with
timestamp +78
Tue Mar 22 15:46:46 2016 : Debug: Cleaning up request 4 ID 228 with
timestamp +78
Tue Mar 22 15:46:46 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=233, length=298
Tue Mar 22 15:46:46 2016 : Debug: User-Name = "host/50-054.bs.firma.de"
Tue Mar 22 15:46:46 2016 : Debug: Service-Type = Framed-User
Tue Mar 22 15:46:46 2016 : Debug: Cisco-AVPair = "service-type=Framed"
Tue Mar 22 15:46:46 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:46:46 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:46:46 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:46:46 2016 : Debug: EAP-Message =
0x020a002b19001703010020075a5b9a84d4e91954b3dceda8b0798280f97e2c13eb2b243801ff9bc484935e
Tue Mar 22 15:46:46 2016 : Debug: Message-Authenticator =
0xd662585844325234572c6af1abedec4b
Tue Mar 22 15:46:46 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BB0D10F206"
Tue Mar 22 15:46:46 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:46:46 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:46:46 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:46:46 2016 : Debug: State = 0xa22253f5aa284a6a4076fa9399b28ee2
Tue Mar 22 15:46:46 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:46:46 2016 : Debug: server packetfence {
Tue Mar 22 15:46:46 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:46 2016 : Debug: +group authorize {
Tue Mar 22 15:46:46 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:46:46 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:46:46 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:46 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:46:46 2016 : Debug: ++++update request {
Tue Mar 22 15:46:46 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:46:46 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:46:46 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:46 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:46 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:46:46 2016 : Debug: +++ ... skipping else for request 9:
Preceding "if" was taken
Tue Mar 22 15:46:46 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:46:46 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:46:46 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:46:46 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:46:46 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:46:46 2016 : Debug: ++++update request {
Tue Mar 22 15:46:46 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:46:46 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:46:46 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:46:46 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:46:46 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:46:46 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Framed
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:46:46 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:46:46 2016 : Debug: +++ ... skipping else for request 9:
Preceding "if" was taken
Tue Mar 22 15:46:46 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:46:46 2016 : Debug: [suffix] No '@' in User-Name = "host/
50-054.bs.firma.de", skipping NULL due to config.
Tue Mar 22 15:46:46 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:46:46 2016 : Debug: [ntdomain] No '\' in User-Name = "host/
50-054.bs.firma.de", looking up realm NULL
Tue Mar 22 15:46:46 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:46:46 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:46:46 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:46:46 2016 : Debug: [eap] EAP packet type response id 10
length 43
Tue Mar 22 15:46:46 2016 : Debug: [eap] Continuing tunnel setup.
Tue Mar 22 15:46:46 2016 : Debug: ++[eap] = ok
Tue Mar 22 15:46:46 2016 : Debug: +} # group authorize = ok
Tue Mar 22 15:46:46 2016 : Debug: Found Auth-Type = EAP
Tue Mar 22 15:46:46 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:46 2016 : Debug: +group authenticate {
Tue Mar 22 15:46:46 2016 : Debug: [eap] Request found, released from the
list
Tue Mar 22 15:46:46 2016 : Debug: [eap] EAP/peap
Tue Mar 22 15:46:46 2016 : Debug: [eap] processing type peap
Tue Mar 22 15:46:46 2016 : Debug: [peap] processing EAP-TLS
Tue Mar 22 15:46:46 2016 : Debug: [peap] eaptls_verify returned 7
Tue Mar 22 15:46:46 2016 : Debug: [peap] Done initial handshake
Tue Mar 22 15:46:46 2016 : Debug: [peap] eaptls_process returned 7
Tue Mar 22 15:46:46 2016 : Debug: [peap] EAPTLS_OK
Tue Mar 22 15:46:46 2016 : Debug: [peap] Session established. Decoding
tunneled attributes.
Tue Mar 22 15:46:46 2016 : Debug: [peap] Peap state send tlv failure
Tue Mar 22 15:46:46 2016 : Debug: [peap] Received EAP-TLV response.
Tue Mar 22 15:46:46 2016 : Debug: [peap] The users session was previously
rejected: returning reject (again.)
Tue Mar 22 15:46:46 2016 : Debug: [peap] *** This means you need to read
the PREVIOUS messages in the debug output
Tue Mar 22 15:46:46 2016 : Debug: [peap] *** to find out the reason why
the user was rejected.
Tue Mar 22 15:46:46 2016 : Debug: [peap] *** Look for "reject" or "fail".
Those earlier messages will tell you.
Tue Mar 22 15:46:46 2016 : Debug: [peap] *** what went wrong, and how to
fix the problem.
Tue Mar 22 15:46:46 2016 : Debug: [eap] Handler failed in EAP/peap
Tue Mar 22 15:46:46 2016 : Debug: [eap] Failed in EAP select
Tue Mar 22 15:46:46 2016 : Debug: ++[eap] = invalid
Tue Mar 22 15:46:46 2016 : Debug: +} # group authenticate = invalid
Tue Mar 22 15:46:46 2016 : Debug: Failed to authenticate the user.
Tue Mar 22 15:46:46 2016 : Debug: } # server packetfence
Tue Mar 22 15:46:46 2016 : Debug: Using Post-Auth-Type Reject
Tue Mar 22 15:46:46 2016 : Debug: # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:46:46 2016 : Debug: +group REJECT {
Tue Mar 22 15:46:46 2016 : Debug: ++? if (!EAP-Type || (EAP-Type !=
EAP-TTLS && EAP-Type != PEAP))
Tue Mar 22 15:46:46 2016 : Debug: ? Evaluating !(EAP-Type ) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (EAP-Type != EAP-TTLS ) ->
TRUE
Tue Mar 22 15:46:46 2016 : Debug: ?? Evaluating (EAP-Type != PEAP) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: ++? if (!EAP-Type || (EAP-Type !=
EAP-TTLS && EAP-Type != PEAP)) -> FALSE
Tue Mar 22 15:46:46 2016 : Debug: [attr_filter.access_reject] expand:
%{User-Name} -> host/50-054.bs.firma.de
Tue Mar 22 15:46:46 2016 : Debug: ++[attr_filter.access_reject] = updated
Tue Mar 22 15:46:46 2016 : Debug: +} # group REJECT = updated
Tue Mar 22 15:46:46 2016 : Debug: Delaying reject of request 9 for 1 seconds
Tue Mar 22 15:46:47 2016 : Debug: Cleaning up request 5 ID 229 with
timestamp +79
Tue Mar 22 15:46:47 2016 : Debug: Cleaning up request 6 ID 230 with
timestamp +79
Tue Mar 22 15:46:47 2016 : Debug: Sending delayed reject for request 9
Tue Mar 22 15:46:47 2016 : Debug: Sending Access-Reject packet to host
10.130.1.15 port 1645, id=233, length=0
Tue Mar 22 15:46:47 2016 : Debug: EAP-Message = 0x040a0004
Tue Mar 22 15:46:47 2016 : Debug: Message-Authenticator =
0x00000000000000000000000000000000
Tue Mar 22 15:46:48 2016 : Debug: Cleaning up request 7 ID 231 with
timestamp +80
Tue Mar 22 15:46:50 2016 : Debug: Cleaning up request 8 ID 232 with
timestamp +82
Tue Mar 22 15:46:52 2016 : Debug: Cleaning up request 9 ID 233 with
timestamp +83
Tue Mar 22 15:47:00 2016 : Debug: Received Access-Request packet from host
10.130.1.15 port 1645, id=234, length=241
Tue Mar 22 15:47:00 2016 : Debug: User-Name = "ecf4bb42a164"
Tue Mar 22 15:47:00 2016 : Debug: User-Password = "ecf4bb42a164"
Tue Mar 22 15:47:00 2016 : Debug: Service-Type = Call-Check
Tue Mar 22 15:47:00 2016 : Debug: Cisco-AVPair = "service-type=Call Check"
Tue Mar 22 15:47:00 2016 : Debug: Framed-MTU = 1500
Tue Mar 22 15:47:00 2016 : Debug: Called-Station-Id = "00-1F-27-D1-E3-0D"
Tue Mar 22 15:47:00 2016 : Debug: Calling-Station-Id = "EC-F4-BB-42-A1-64"
Tue Mar 22 15:47:00 2016 : Debug: Message-Authenticator =
0x0d736a48019f3d6bb6d7085e2f43df05
Tue Mar 22 15:47:00 2016 : Debug: Cisco-AVPair =
"audit-session-id=0A82010F000000BC0D1127C3"
Tue Mar 22 15:47:00 2016 : Debug: NAS-Port-Type = Ethernet
Tue Mar 22 15:47:00 2016 : Debug: NAS-Port = 50013
Tue Mar 22 15:47:00 2016 : Debug: NAS-Port-Id = "GigabitEthernet0/13"
Tue Mar 22 15:47:00 2016 : Debug: NAS-IP-Address = 10.130.1.15
Tue Mar 22 15:47:00 2016 : Debug: server packetfence {
Tue Mar 22 15:47:00 2016 : Debug: # Executing section authorize from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:47:00 2016 : Debug: +group authorize {
Tue Mar 22 15:47:00 2016 : Debug: ++policy rewrite.calling_station_id {
Tue Mar 22 15:47:00 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
Tue Mar 22 15:47:00 2016 : Debug: ?? Evaluating (Calling-Station-Id) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: expand: %{Calling-Station-Id} ->
EC-F4-BB-42-A1-64
Tue Mar 22 15:47:00 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:47:00 2016 : Debug: expand: ^%{config:policy.mac-addr}$ ->
^([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})$
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating ("%{Calling-Station-Id}" =~
/^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: +++? if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: +++if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
Tue Mar 22 15:47:00 2016 : Debug: ++++update request {
Tue Mar 22 15:47:00 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
EC:F4:BB:42:A1:64
Tue Mar 22 15:47:00 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> ec:f4:bb:42:a1:64
Tue Mar 22 15:47:00 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:47:00 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:47:00 2016 : Debug: +++} # if ((Calling-Station-Id) &&
"%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
Tue Mar 22 15:47:00 2016 : Debug: +++ ... skipping else for request 10:
Preceding "if" was taken
Tue Mar 22 15:47:00 2016 : Debug: ++} # policy rewrite.calling_station_id =
updated
Tue Mar 22 15:47:00 2016 : Debug: ++policy set.called_station_ssid {
Tue Mar 22 15:47:00 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i)
Tue Mar 22 15:47:00 2016 : Debug: ?? Evaluating (Called-Station-Id) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: expand: %{Called-Station-Id} ->
00-1F-27-D1-E3-0D
Tue Mar 22 15:47:00 2016 : Debug: expand: policy.mac-addr -> policy.mac-addr
Tue Mar 22 15:47:00 2016 : Debug: expand:
^%{config:policy.mac-addr}(:(.+))?$ ->
^([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})(:(.+))?$
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating ("%{Called-Station-Id}" =~
/^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: +++? if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: +++if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) {
Tue Mar 22 15:47:00 2016 : Debug: ++++update request {
Tue Mar 22 15:47:00 2016 : Debug: expand: %{1}:%{2}:%{3}:%{4}:%{5}:%{6} ->
00:1F:27:D1:E3:0D
Tue Mar 22 15:47:00 2016 : Debug: expand:
%{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} -> 00:1f:27:d1:e3:0d
Tue Mar 22 15:47:00 2016 : Debug: ++++} # update request = noop
Tue Mar 22 15:47:00 2016 : Debug: ++++? if ("%{8}")
Tue Mar 22 15:47:00 2016 : Debug: expand: %{8} ->
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating ("%{8}") -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? if ("%{8}") -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:47:00 2016 : Debug: ?? Evaluating (Colubris-AVPair) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ? Skipping ("%{Colubris-AVPair}" =~
/^ssid=(.*)$/i)
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif ((Colubris-AVPair) &&
"%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif (Aruba-Essid-Name)
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif (Aruba-Essid-Name) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i)
Tue Mar 22 15:47:00 2016 : Debug: ?? Evaluating (Cisco-AVPair) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: expand: %{Cisco-AVPair} ->
service-type=Call Check
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating ("%{Cisco-AVPair}" =~
/^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++? elsif ((Cisco-AVPair) &&
"%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE
Tue Mar 22 15:47:00 2016 : Debug: ++++[updated] = updated
Tue Mar 22 15:47:00 2016 : Debug: +++} # if ((Called-Station-Id) &&
"%{Called-Station-Id}" =~ /^%{config:policy.mac-addr}(:(.+))?$/i) = updated
Tue Mar 22 15:47:00 2016 : Debug: +++ ... skipping else for request 10:
Preceding "if" was taken
Tue Mar 22 15:47:00 2016 : Debug: ++} # policy set.called_station_ssid =
updated
Tue Mar 22 15:47:00 2016 : Debug: [suffix] No '@' in User-Name =
"ecf4bb42a164", skipping NULL due to config.
Tue Mar 22 15:47:00 2016 : Debug: ++[suffix] = noop
Tue Mar 22 15:47:00 2016 : Debug: [ntdomain] No '\' in User-Name =
"ecf4bb42a164", looking up realm NULL
Tue Mar 22 15:47:00 2016 : Debug: [ntdomain] No such realm "NULL"
Tue Mar 22 15:47:00 2016 : Debug: ++[ntdomain] = noop
Tue Mar 22 15:47:00 2016 : Debug: ++[preprocess] = ok
Tue Mar 22 15:47:00 2016 : Debug: [eap] No EAP-Message, not doing EAP
Tue Mar 22 15:47:00 2016 : Debug: ++[eap] = noop
Tue Mar 22 15:47:00 2016 : Debug: [files] users: Matched entry DEFAULT at
line 2
Tue Mar 22 15:47:00 2016 : Debug: ++[files] = ok
Tue Mar 22 15:47:00 2016 : Debug: ++[expiration] = noop
Tue Mar 22 15:47:00 2016 : Debug: ++[logintime] = noop
Tue Mar 22 15:47:00 2016 : Debug: ++update request {
Tue Mar 22 15:47:00 2016 : Debug: expand: %{Packet-Src-IP-Address} ->
10.130.1.15
Tue Mar 22 15:47:00 2016 : Debug: ++} # update request = noop
Tue Mar 22 15:47:00 2016 : Debug: ++update control {
Tue Mar 22 15:47:00 2016 : Debug: ++} # update control = noop
Tue Mar 22 15:47:00 2016 : Debug: ++[packetfence] = noop
Tue Mar 22 15:47:00 2016 : Debug: +} # group authorize = updated
Tue Mar 22 15:47:00 2016 : Debug: Found Auth-Type = Accept
Tue Mar 22 15:47:00 2016 : Debug: Auth-Type = Accept, accepting the user
Tue Mar 22 15:47:00 2016 : Debug: } # server packetfence
Tue Mar 22 15:47:00 2016 : Debug: # Executing section post-auth from file
/usr/local/pf/raddb//sites-enabled/packetfence
Tue Mar 22 15:47:00 2016 : Debug: +group post-auth {
Tue Mar 22 15:47:00 2016 : Debug: ++[exec] = noop
Tue Mar 22 15:47:00 2016 : Debug: ++? if (!EAP-Type || (EAP-Type !=
EAP-TTLS && EAP-Type != PEAP))
Tue Mar 22 15:47:00 2016 : Debug: ? Evaluating !(EAP-Type ) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: ?? Skipping (EAP-Type != EAP-TTLS )
Tue Mar 22 15:47:00 2016 : Debug: ?? Skipping (EAP-Type != PEAP)
Tue Mar 22 15:47:00 2016 : Debug: ++? if (!EAP-Type || (EAP-Type !=
EAP-TTLS && EAP-Type != PEAP)) -> TRUE
Tue Mar 22 15:47:00 2016 : Debug: ++if (!EAP-Type || (EAP-Type != EAP-TTLS
&& EAP-Type != PEAP)) {
Tue Mar 22 15:47:00 2016 : Debug: +++update control {
Tue Mar 22 15:47:00 2016 : Debug: +++} # update control = noop
Tue Mar 22 15:47:15 2016 : Debug: +++[packetfence] = ok
Tue Mar 22 15:47:15 2016 : Debug: [sql] expand: %{User-Name} -> ecf4bb42a164
Tue Mar 22 15:47:15 2016 : Debug: [sql] sql_set_user escaped user -->
'ecf4bb42a164'
Tue Mar 22 15:47:15 2016 : Debug: [sql] expand: %{check:Post-Auth-Type} ->
Tue Mar 22 15:47:15 2016 : Debug: [sql] ... expanding second conditional
Tue Mar 22 15:47:15 2016 : Debug: [sql] 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) VALUES (
'%{request:Calling-Station-Id}', '%{request:Framed-IP-Address}',
'%{control:PacketFence-Computer-Name}', '%{request:User-Name}',
'%{request:Stripped-User-Name}', '%{request:Realm}',
'Radius-Access-Request', '%{control:PacketFence-Switch-Id}',
'%{control:PacketFence-Switch-Mac}',
'%{control:PacketFence-Switch-Ip-Address}',
'%{Packet-Src-IP-Address}', '%{request:Called-Station-Id}', '%{req
8J??Tue Mar 22 15:47:15 2016 : Debug: +++[sql] = ok
Tue Mar 22 15:47:15 2016 : Debug: ++} # if (!EAP-Type || (EAP-Type !=
EAP-TTLS && EAP-Type != PEAP)) = ok
Tue Mar 22 15:47:15 2016 : Debug: +} # group post-auth = ok
Tue Mar 22 15:47:15 2016 : Debug: Sending Access-Accept packet to host
10.130.1.15 port 1645, id=234, length=0
Tue Mar 22 15:47:15 2016 : Debug: Tunnel-Private-Group-Id:0 = "7"
Tue Mar 22 15:47:15 2016 : Debug: Tunnel-Medium-Type:0 = IEEE-802
Tue Mar 22 15:47:15 2016 : Debug: Tunnel-Type:0 = VLAN
Tue Mar 22 15:47:15 2016 : Debug: Finished request 10.
Tue Mar 22 15:47:16 2016 : Debug: Child is finally responsive for request 10
Post by Louis MunroTobias,
Are you still trying to authenticate using certificates (i.e. EAP-TLS)?
What you sent below is a PEAP authentication, not EAP-TLS.
There is no way to help you without seeing more though.
Post the full output of the authentication, that is the price to pay.
We donât necessarily need the output for every packet in the PEAP exchange
but we do need the ones where the actual ntlm_authentication happens.
Itâs better to post too much than too little.
Please post the contents of your raddb/proxy.conf and raddb/proxy.conf.inc.
Donât mess with the NULL realm unless you know why you are doing that.
Itâs not necessarily an error if itâs not found.
As far as the messages below indicate, you are using and incorrect username or password.
That is all I can tell from what you sent.
Regards,
--
Louis Munro
+1.514.447.4918 x125 :: +1 (866) 353-6153 x125
Inverse inc. :: Leaders behind SOGo (www.sogo.nu) and PacketFence (
www.packetfence.org)
Hi,
yesterday I successfully included our own CA Certificates on PacketFence
(thank you very much for helping me so fast :) )
Know I stuck at the Active Directory Auth (user and machine account)
1) Added an AD Source (sAMAccountName as Username, I also
tried ServicePrincipalName for machine accounts)
2) Added Radios Domain (join was Successfully)
3) Check Bind: "chroot /chroots/BS/ ntlm_auth --username=fritob" this works as expected
4) added to realm: BS.firma.de <http://bs.firma.de/> and BS and as Source
my user source and when I tried to auth machine accounts my machine account
source (configured like in the documentation)
5) Configured 802.1x PEAP on Windows 7
6) Try to authenticate against Packetfence
B002F4642C1050FB999F6AF5B3502F9F
For debugging I startet raddebug -f /usr/local/pf/var/run/radiusd.sock
+group authenticate {
Tue Mar 22 12:41:05 2016 : Debug: [eap] Request found, released from the list
Tue Mar 22 12:41:05 2016 : Debug: [eap] EAP/mschapv2
Tue Mar 22 12:41:05 2016 : Debug: [eap] processing type mschapv2
Tue Mar 22 12:41:05 2016 : Debug: [mschapv2] # Executing group from file
/usr/local/pf/raddb//sites-enabled/packetfence-tunnel
Tue Mar 22 12:41:05 2016 : Debug: [mschapv2] +group MS-CHAP {
Tue Mar 22 12:41:05 2016 : Debug: ++[packetfence] = noop
Tue Mar 22 12:41:05 2016 : Debug: ++? if (PacketFence-Domain)
Tue Mar 22 12:41:05 2016 : Debug: ? Evaluating (PacketFence-Domain) -> TRUE
Tue Mar 22 12:41:05 2016 : Debug: ++? if (PacketFence-Domain) -> TRUE
Tue Mar 22 12:41:05 2016 : Debug: ++if (PacketFence-Domain) {
Tue Mar 22 12:41:05 2016 : Debug: [chrooted_mschap] Creating challenge
hash with username: fritob
Tue Mar 22 12:41:05 2016 : Debug: [chrooted_mschap] Client is using
MS-CHAPv2 for fritob, we need NT-Password
/chroots/%{PacketFence-Domain} -> /chroots/BS
--username=%{mschap:User-Name:-None} -> --username=fritob
Tue Mar 22 12:41:05 2016 : Debug: [chrooted_mschap] Creating challenge
hash with username: fritob
--challenge=%{mschap:Challenge:-00} -> --challenge=14324b2eb43c63a4
--nt-response=%{mschap:NT-Response:-00} ->
--nt-response=3887c019f4e3f2e3c00262aa73060926bbff08f8bce2e2b1
Tue Mar 22 12:41:05 2016 : Debug: [chrooted_mschap] Exec: program returned: 139
Tue Mar 22 12:41:05 2016 : Debug: [chrooted_mschap] External script failed.
MS-CHAP2-Response is incorrect
Tue Mar 22 12:41:05 2016 : Debug: +++[chrooted_mschap] = reject
When I tried to auth against the machine account, I got the error message
that realm null is not found on the Server, so I created a third realm with
identifier NULL and as source my AD and as Domain my Domain. After that i
Tue Mar 22 13:27:55 2016 : Debug: [chrooted_mschap] Creating challenge
hash with username: host/50-054.bs.firma.de
Tue Mar 22 13:27:55 2016 : Debug: [chrooted_mschap] Client is using
MS-CHAPv2 for host/50-054.bs.firma.de, we need NT-Password
/chroots/%{PacketFence-Domain} -> /chroots/BS
--username=%{mschap:User-Name:-None} -> --username=50-054$
Tue Mar 22 13:27:55 2016 : Debug: [chrooted_mschap] Creating challenge
hash with username: host/50-054.bs.firma.de
--challenge=%{mschap:Challenge:-00} -> --challenge=bdc5c224cf471a88
--nt-response=%{mschap:NT-Response:-00} ->
--nt-response=b40a7d6be6d0d05292de52356df5e5590238293b3acba4cc
Tue Mar 22 13:27:55 2016 : Debug: [chrooted_mschap] Exec: program returned: 139
Tue Mar 22 13:27:55 2016 : Debug: [chrooted_mschap] External script failed.
MS-CHAP2-Response is incorrect
What's going wrong there :/ I would be very thankful if someone can give me a hint :)
If you need the full log, I can send it but it's very very long (1303 rows) :D
Greeting,
Tobias
------------------------------------------------------------------------------
Transform Data into Opportunity.
Accelerate data analysis in your applications with
Intel Data Analytics Acceleration Library.
Click to learn more.
http://pubads.g.doubleclick.net/gampad/clk?id=278785351&iu=/4140_______________________________________________
PacketFence-users mailing list
https://lists.sourceforge.net/lists/listinfo/packetfence-users
------------------------------------------------------------------------------
Transform Data into Opportunity.
Accelerate data analysis in your applications with
Intel Data Analytics Acceleration Library.
Click to learn more.
http://pubads.g.doubleclick.net/gampad/clk?id=278785351&iu=/4140
_______________________________________________
PacketFence-users mailing list
https://lists.sourceforge.net/lists/listinfo/packetfence-users