Mon Dec 18 14:41:42 2017 : Debug: (0) Received Access-Request Id 125 from 172.24.3.197:1645 to 172.28.0.65:1912 length 289
Mon Dec 18 14:41:42 2017 : Debug: (0)   User-Name = "CP-7965G-SEP64A0E7147412"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Service-Type = Framed-User
Mon Dec 18 14:41:42 2017 : Debug: (0)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Framed-MTU = 1500
Mon Dec 18 14:41:42 2017 : Debug: (0)   Called-Station-Id = "00-08-30-EA-22-88"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Calling-Station-Id = "64-A0-E7-14-74-12"
Mon Dec 18 14:41:42 2017 : Debug: (0)   EAP-Message = 0x0201001d0143502d37393635472d534550363441304537313437343132
Mon Dec 18 14:41:42 2017 : Debug: (0)   Message-Authenticator = 0x4487425618792c5678fb29333692d0ec
Mon Dec 18 14:41:42 2017 : Debug: (0)   Cisco-AVPair = "audit-session-id=AC1803C500005B2241232FB2"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Framed-IP-Address = 172.31.0.121
Mon Dec 18 14:41:42 2017 : Debug: (0)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:42 2017 : Debug: (0)   NAS-Port-Id = "GigabitEthernet1/0/8"
Mon Dec 18 14:41:42 2017 : Debug: (0)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:42 2017 : Debug: (0)   NAS-Port = 50108
Mon Dec 18 14:41:42 2017 : Debug: (0) session-state: No State attribute
Mon Dec 18 14:41:42 2017 : Debug: (0) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (0)   authorize {
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:42 2017 : Debug: (0) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:42 2017 : Debug: (0) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:42 2017 : Debug: (0) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:42 2017 : Debug: (0)     [files8021x] = ok
Mon Dec 18 14:41:42 2017 : Debug: (0)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:42 2017 : Debug: (0)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:42 2017 : Debug: (0)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:42 2017 : Debug: (0)       update request {
Mon Dec 18 14:41:42 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:42 2017 : Debug: (0)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: (0)            -->
Mon Dec 18 14:41:42 2017 : Debug: (0)         SQL-User-Name set to ''
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Reserved connection (1)
Mon Dec 18 14:41:42 2017 : Debug: (0)         Executing select query: SELECT REPLACE('64-A0-E7-14-74-12','-','')
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Released connection (1)
Mon Dec 18 14:41:42 2017 : Info: Need 4 more connections to reach 10 spares
Mon Dec 18 14:41:42 2017 : Info: rlm_sql (sql8021x): Opening additional connection (6), 1 of 26 pending slots used
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql_mysql: Connected to database 'radius8021x' on Localhost via UNIX socket, server version 10.1.29-MariaDB-6, protocol version 10
Mon Dec 18 14:41:42 2017 : Debug: (0)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:42 2017 : Debug: (0)            --> 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (0)         Stripped-User-Name = 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (0)       } # update request = noop
Mon Dec 18 14:41:42 2017 : Debug: (0)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:42 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: SQL-User-Name set to '64A0E7147412'
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Reserved connection (2)
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: User found in radcheck table
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:42 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: User found in the group table
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:42 2017 : Debug: (0) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Released connection (2)
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:42 2017 : Debug: (0)     [sql8021x] = ok
Mon Dec 18 14:41:42 2017 : Debug: (0)   } # authorize = ok
Mon Dec 18 14:41:42 2017 : Debug: (0) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:42 2017 : Debug: (0) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (0)   authenticate {
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:42 2017 : Debug: (0) eap8021xciscophone: Peer sent packet with method EAP Identity (1)
Mon Dec 18 14:41:42 2017 : Debug: (0) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:42 2017 : Debug: (0) eap_tls: Initiating new EAP-TLS session
Mon Dec 18 14:41:42 2017 : Debug: (0) eap_tls: Setting verify mode to require certificate from client
Mon Dec 18 14:41:42 2017 : Debug: (0) eap_tls: [eaptls start] = request
Mon Dec 18 14:41:42 2017 : Debug: (0) eap8021xciscophone: Sending EAP Request (code 1) ID 2 length 6
Mon Dec 18 14:41:42 2017 : Debug: (0) eap8021xciscophone: EAP session adding &reply:State = 0xbf887800bf8a754d
Mon Dec 18 14:41:42 2017 : Debug: (0)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:42 2017 : Debug: (0)     [eap8021xciscophone] = handled
Mon Dec 18 14:41:42 2017 : Debug: (0)   } # authenticate = handled
Mon Dec 18 14:41:42 2017 : Debug: (0) Using Post-Auth-Type Challenge
Mon Dec 18 14:41:42 2017 : Debug: (0) Post-Auth-Type sub-section not found.  Ignoring.
Mon Dec 18 14:41:42 2017 : Debug: (0) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (0) session-state: Nothing to cache
Mon Dec 18 14:41:42 2017 : Debug: (0) Sent Access-Challenge Id 125 from 172.28.0.65:1912 to 172.24.3.197:1645 length 0
Mon Dec 18 14:41:42 2017 : Debug: (0)   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:42 2017 : Debug: (0)   Tunnel-Type = VLAN
Mon Dec 18 14:41:42 2017 : Debug: (0)   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:42 2017 : Debug: (0)   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:42 2017 : Debug: (0)   EAP-Message = 0x010200060d20
Mon Dec 18 14:41:42 2017 : Debug: (0)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:42 2017 : Debug: (0)   State = 0xbf887800bf8a754d1da3e6082112a4af
Mon Dec 18 14:41:42 2017 : Debug: (0) Finished request
Mon Dec 18 14:41:42 2017 : Debug: Waking up in 4.9 seconds.
Mon Dec 18 14:41:42 2017 : Debug: (1) Received Access-Request Id 126 from 172.24.3.197:1645 to 172.28.0.65:1912 length 340
Mon Dec 18 14:41:42 2017 : Debug: (1)   User-Name = "CP-7965G-SEP64A0E7147412"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Service-Type = Framed-User
Mon Dec 18 14:41:42 2017 : Debug: (1)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Framed-MTU = 1500
Mon Dec 18 14:41:42 2017 : Debug: (1)   Called-Station-Id = "00-08-30-EA-22-88"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Calling-Station-Id = "64-A0-E7-14-74-12"
Mon Dec 18 14:41:42 2017 : Debug: (1)   EAP-Message = 0x0202003e0d8000000034160301002f0100002b03015a37c59630591d7ef6337793e2dc96b9f96e5568b41fbc610730aa4b6367f0320000040035002f0100
Mon Dec 18 14:41:42 2017 : Debug: (1)   Message-Authenticator = 0x9d3b637dc7765394443e3dddca0e1ab9
Mon Dec 18 14:41:42 2017 : Debug: (1)   Cisco-AVPair = "audit-session-id=AC1803C500005B2241232FB2"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Framed-IP-Address = 172.31.0.121
Mon Dec 18 14:41:42 2017 : Debug: (1)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:42 2017 : Debug: (1)   NAS-Port-Id = "GigabitEthernet1/0/8"
Mon Dec 18 14:41:42 2017 : Debug: (1)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:42 2017 : Debug: (1)   NAS-Port = 50108
Mon Dec 18 14:41:42 2017 : Debug: (1)   State = 0xbf887800bf8a754d1da3e6082112a4af
Mon Dec 18 14:41:42 2017 : Debug: (1) session-state: No cached attributes
Mon Dec 18 14:41:42 2017 : Debug: (1) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (1)   authorize {
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:42 2017 : Debug: (1) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:42 2017 : Debug: (1) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:42 2017 : Debug: (1) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:42 2017 : Debug: (1)     [files8021x] = ok
Mon Dec 18 14:41:42 2017 : Debug: (1)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:42 2017 : Debug: (1)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:42 2017 : Debug: (1)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:42 2017 : Debug: (1)       update request {
Mon Dec 18 14:41:42 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:42 2017 : Debug: (1)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: (1)            -->
Mon Dec 18 14:41:42 2017 : Debug: (1)         SQL-User-Name set to ''
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Reserved connection (3)
Mon Dec 18 14:41:42 2017 : Debug: (1)         Executing select query: SELECT REPLACE('64-A0-E7-14-74-12','-','')
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Released connection (3)
Mon Dec 18 14:41:42 2017 : Debug: (1)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:42 2017 : Debug: (1)            --> 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (1)         Stripped-User-Name = 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (1)       } # update request = noop
Mon Dec 18 14:41:42 2017 : Debug: (1)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:42 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> 64A0E7147412
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: SQL-User-Name set to '64A0E7147412'
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Reserved connection (4)
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: User found in radcheck table
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:42 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: User found in the group table
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:42 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:42 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:42 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:42 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:42 2017 : Debug: (1) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:42 2017 : Debug: rlm_sql (sql8021x): Released connection (4)
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:42 2017 : Debug: (1)     [sql8021x] = ok
Mon Dec 18 14:41:42 2017 : Debug: (1)   } # authorize = ok
Mon Dec 18 14:41:42 2017 : Debug: (1) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:42 2017 : Debug: (1) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (1)   authenticate {
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Expiring EAP session with state 0xbf887800bf8a754d
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Finished EAP session with state 0xbf887800bf8a754d
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Previous EAP request found for state 0xbf887800bf8a754d, released from the list
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Peer sent packet with method EAP TLS (13)
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: Continuing EAP-TLS
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: Peer sent flags --L
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: Peer indicated complete TLS record size will be 52 bytes
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: Got complete TLS record (52 bytes)
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: [eaptls verify] = length included
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: (other): before SSL initialization
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: before SSL initialization
Mon Dec 18 14:41:42 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: before SSL initialization
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: <<< recv TLS 1.2  [length 002f]
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS read client hello
Mon Dec 18 14:41:42 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: >>> send TLS 1.0 Handshake [length 002a], ServerHello
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write server hello
Mon Dec 18 14:41:42 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: >>> send TLS 1.0 Handshake [length 02f8], Certificate
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write certificate
Mon Dec 18 14:41:42 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: >>> send TLS 1.0 Handshake [length 00a7], CertificateRequest
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write certificate request
Mon Dec 18 14:41:42 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: >>> send TLS 1.0 Handshake [length 0004], ServerHelloDone
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write server done
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: TLS_accept: Need to read more data: SSLv3/TLS write server done
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: In SSL Handshake Phase
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: In SSL Accept mode
Mon Dec 18 14:41:42 2017 : Debug: (1) eap_tls: [eaptls process] = handled
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: Sending EAP Request (code 1) ID 3 length 1003
Mon Dec 18 14:41:42 2017 : Debug: (1) eap8021xciscophone: EAP session adding &reply:State = 0xbf887800be8b754d
Mon Dec 18 14:41:42 2017 : Debug: (1)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:42 2017 : Debug: (1)     [eap8021xciscophone] = handled
Mon Dec 18 14:41:42 2017 : Debug: (1)   } # authenticate = handled
Mon Dec 18 14:41:42 2017 : Debug: (1) Using Post-Auth-Type Challenge
Mon Dec 18 14:41:42 2017 : Debug: (1) Post-Auth-Type sub-section not found.  Ignoring.
Mon Dec 18 14:41:42 2017 : Debug: (1) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:42 2017 : Debug: (1) session-state: Nothing to cache
Mon Dec 18 14:41:42 2017 : Debug: (1) Sent Access-Challenge Id 126 from 172.28.0.65:1912 to 172.24.3.197:1645 length 0
Mon Dec 18 14:41:42 2017 : Debug: (1)   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:42 2017 : Debug: (1)   Tunnel-Type = VLAN
Mon Dec 18 14:41:42 2017 : Debug: (1)   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:42 2017 : Debug: (1)   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:42 2017 : Debug: (1)   EAP-Message = 0x010303eb0d80000003e1160301002a020000260301a172d9ce08f5e286981de646112061154f2d203cb03958d7dea1ca419ae55a450000350016030102f80b0002f40002f10002ee308202ea30820253a003020102020900a663e941aa84c0b4300d06092a864886f70d0101050500308198310b300906
Mon Dec 18 14:41:42 2017 : Debug: (1)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:42 2017 : Debug: (1)   State = 0xbf887800be8b754d1da3e6082112a4af
Mon Dec 18 14:41:42 2017 : Debug: (1) Finished request
Mon Dec 18 14:41:42 2017 : Debug: Waking up in 4.9 seconds.
Mon Dec 18 14:41:44 2017 : Debug: (2) Received Access-Request Id 127 from 172.24.3.197:1645 to 172.28.0.65:1912 length 1619
Mon Dec 18 14:41:44 2017 : Debug: (2)   User-Name = "CP-7965G-SEP64A0E7147412"
Mon Dec 18 14:41:44 2017 : Debug: (2)   Service-Type = Framed-User
Mon Dec 18 14:41:44 2017 : Debug: (2)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:44 2017 : Debug: (2)   Framed-MTU = 1500
Mon Dec 18 14:41:44 2017 : Debug: (2)   Called-Station-Id = "00-08-30-EA-22-88"
Mon Dec 18 14:41:44 2017 : Debug: (2)   Calling-Station-Id = "64-A0-E7-14-74-12"
Mon Dec 18 14:41:44 2017 : Debug: (2)   EAP-Message = 0x020305330d800000052916030103530b00034f00034c00034930820345308202aea003020102020200f1300d06092a864886f70d0101050500308198310b30090603550406130244453140303e060355040a0c374465757473636865732042696f6d61737365466f72736368756e67735a656e7472756d
Mon Dec 18 14:41:44 2017 : Debug: (2)   Message-Authenticator = 0xf4dab3d360bab887d88f055fbe530662
Mon Dec 18 14:41:44 2017 : Debug: (2)   Cisco-AVPair = "audit-session-id=AC1803C500005B2241232FB2"
Mon Dec 18 14:41:44 2017 : Debug: (2)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:44 2017 : Debug: (2)   Framed-IP-Address = 172.31.0.121
Mon Dec 18 14:41:44 2017 : Debug: (2)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:44 2017 : Debug: (2)   NAS-Port-Id = "GigabitEthernet1/0/8"
Mon Dec 18 14:41:44 2017 : Debug: (2)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:44 2017 : Debug: (2)   NAS-Port = 50108
Mon Dec 18 14:41:44 2017 : Debug: (2)   State = 0xbf887800be8b754d1da3e6082112a4af
Mon Dec 18 14:41:44 2017 : Debug: (2) session-state: No cached attributes
Mon Dec 18 14:41:44 2017 : Debug: (2) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:44 2017 : Debug: (2)   authorize {
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:44 2017 : Debug: (2) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:44 2017 : Debug: (2) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:44 2017 : Debug: (2) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:44 2017 : Debug: (2)     [files8021x] = ok
Mon Dec 18 14:41:44 2017 : Debug: (2)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:44 2017 : Debug: (2)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:44 2017 : Debug: (2)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:44 2017 : Debug: (2)       update request {
Mon Dec 18 14:41:44 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:44 2017 : Debug: (2)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:44 2017 : Debug: (2)            -->
Mon Dec 18 14:41:44 2017 : Debug: (2)         SQL-User-Name set to ''
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql (sql8021x): Reserved connection (0)
Mon Dec 18 14:41:44 2017 : Debug: (2)         Executing select query: SELECT REPLACE('64-A0-E7-14-74-12','-','')
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql (sql8021x): Released connection (0)
Mon Dec 18 14:41:44 2017 : Info: Need 3 more connections to reach 10 spares
Mon Dec 18 14:41:44 2017 : Info: rlm_sql (sql8021x): Opening additional connection (7), 1 of 25 pending slots used
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql_mysql: Connected to database 'radius8021x' on Localhost via UNIX socket, server version 10.1.29-MariaDB-6, protocol version 10
Mon Dec 18 14:41:44 2017 : Debug: (2)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:44 2017 : Debug: (2)            --> 64A0E7147412
Mon Dec 18 14:41:44 2017 : Debug: (2)         Stripped-User-Name = 64A0E7147412
Mon Dec 18 14:41:44 2017 : Debug: (2)       } # update request = noop
Mon Dec 18 14:41:44 2017 : Debug: (2)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:44 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> 64A0E7147412
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: SQL-User-Name set to '64A0E7147412'
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql (sql8021x): Reserved connection (5)
Mon Dec 18 14:41:44 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:44 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:44 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: User found in radcheck table
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:44 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:44 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:44 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '64A0E7147412' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:44 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:44 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:44 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '64A0E7147412' ORDER BY priority
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: User found in the group table
Mon Dec 18 14:41:44 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:44 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:44 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:44 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:44 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:44 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:44 2017 : Debug: (2) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:44 2017 : Debug: rlm_sql (sql8021x): Released connection (5)
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:44 2017 : Debug: (2)     [sql8021x] = ok
Mon Dec 18 14:41:44 2017 : Debug: (2)   } # authorize = ok
Mon Dec 18 14:41:44 2017 : Debug: (2) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:44 2017 : Debug: (2) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:44 2017 : Debug: (2)   authenticate {
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Expiring EAP session with state 0xbf887800be8b754d
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Finished EAP session with state 0xbf887800be8b754d
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Previous EAP request found for state 0xbf887800be8b754d, released from the list
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Peer sent packet with method EAP TLS (13)
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: Continuing EAP-TLS
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: Peer sent flags --L
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: Peer indicated complete TLS record size will be 1321 bytes
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: Got complete TLS record (1321 bytes)
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: [eaptls verify] = length included
Mon Dec 18 14:41:44 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: TLS_accept: SSLv3/TLS write server done
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: <<< recv TLS 1.0 Handshake [length 0353], Certificate
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: Creating attributes from certificate OIDs
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls:   TLS-Cert-Serial := "5871a15a20dc203cceb13b568ad905f9"
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls:   TLS-Cert-Expiration := "220309050842Z"
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls:   TLS-Cert-Subject := "/C=DE/O=Deutsches BiomasseForschungsZentrum gemeinnuetzige GmbH/OU=IT/CN=CAPF-1b0db5b4/ST=Sachsen/L=Leipzig"
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls:   TLS-Cert-Issuer := "/C=DE/O=Deutsches BiomasseForschungsZentrum gemeinnuetzige GmbH/OU=IT/CN=CAPF-1b0db5b4/ST=Sachsen/L=Leipzig"
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls:   TLS-Cert-Common-Name := "CAPF-1b0db5b4"
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls:   SSL says error 26 : unsupported certificate purpose
Mon Dec 18 14:41:44 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:44 2017 : Debug: (2) eap_tls: >>> send TLS 1.0 Alert [length 0002], fatal unsupported_certificate
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: TLS Alert write:fatal:unsupported certificate
Mon Dec 18 14:41:44 2017 : Error: tls: TLS_accept: Error in error
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: Failed in __FUNCTION__ (SSL_read): ../ssl/statem/statem_srvr.c[2896]:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: System call (I/O) error (-1)
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: TLS receive handshake failed during operation
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: [eaptls process] = fail
Mon Dec 18 14:41:44 2017 : ERROR: (2) eap8021xciscophone: Failed continuing EAP TLS (13) session.  EAP sub-module failed
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Sending EAP Failure (code 4) ID 3 length 4
Mon Dec 18 14:41:44 2017 : Debug: (2) eap8021xciscophone: Failed in EAP select
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:44 2017 : Debug: (2)     [eap8021xciscophone] = invalid
Mon Dec 18 14:41:44 2017 : Debug: (2)   } # authenticate = invalid
Mon Dec 18 14:41:44 2017 : Debug: (2) Failed to authenticate the user
Mon Dec 18 14:41:44 2017 : Debug: (2) Using Post-Auth-Type Reject
Mon Dec 18 14:41:44 2017 : Debug: (2) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:44 2017 : Debug: (2)   Post-Auth-Type REJECT {
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter)
Mon Dec 18 14:41:44 2017 : Debug: %{User-Name}
Mon Dec 18 14:41:44 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:44 2017 : Debug: attribute --> User-Name
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: EXPAND %{User-Name}
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject:    --> CP-7965G-SEP64A0E7147412
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Matched entry DEFAULT at line 11
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "Tunnel-Medium-Type" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "Tunnel-Type" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "Tunnel-Private-Group-Id" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "Cisco-AVPair" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: EAP-Message = 0x04030004 allowed by EAP-Message =* 0x
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x
Mon Dec 18 14:41:44 2017 : Debug: (2) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Mon Dec 18 14:41:44 2017 : Debug: (2)     modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter)
Mon Dec 18 14:41:44 2017 : Debug: (2)     [attr_filter.access_reject] = updated
Mon Dec 18 14:41:44 2017 : Debug: (2)   } # Post-Auth-Type REJECT = updated
Mon Dec 18 14:41:44 2017 : Debug: (2) Delaying response for 1.000000 seconds
Mon Dec 18 14:41:44 2017 : Debug: Waking up in 0.3 seconds.
Mon Dec 18 14:41:44 2017 : Debug: Waking up in 0.6 seconds.
Mon Dec 18 14:41:45 2017 : Debug: (2) Sending delayed response
Mon Dec 18 14:41:45 2017 : Debug: (2) Sent Access-Reject Id 127 from 172.28.0.65:1912 to 172.24.3.197:1645 length 44
Mon Dec 18 14:41:45 2017 : Debug: (2)   EAP-Message = 0x04030004
Mon Dec 18 14:41:45 2017 : Debug: (2)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:45 2017 : Debug: Waking up in 1.5 seconds.
Mon Dec 18 14:41:47 2017 : Debug: (0) Cleaning up request packet ID 125 with timestamp +27
Mon Dec 18 14:41:47 2017 : Debug: (1) Cleaning up request packet ID 126 with timestamp +27
Mon Dec 18 14:41:47 2017 : Debug: Waking up in 2.4 seconds.
Mon Dec 18 14:41:49 2017 : Debug: (2) Cleaning up request packet ID 127 with timestamp +29
Mon Dec 18 14:41:49 2017 : Info: Ready to process requests
Mon Dec 18 14:41:50 2017 : Debug: (3) Received Access-Request Id 128 from 172.24.3.197:1645 to 172.28.0.65:1912 length 290
Mon Dec 18 14:41:50 2017 : Debug: (3)   User-Name = "CP-7965G-SEP0008308BD7A4"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Service-Type = Framed-User
Mon Dec 18 14:41:50 2017 : Debug: (3)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Framed-MTU = 1500
Mon Dec 18 14:41:50 2017 : Debug: (3)   Called-Station-Id = "00-08-30-EA-22-A4"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Calling-Station-Id = "00-08-30-8B-D7-A4"
Mon Dec 18 14:41:50 2017 : Debug: (3)   EAP-Message = 0x0201001d0143502d37393635472d534550303030383330384244374134
Mon Dec 18 14:41:50 2017 : Debug: (3)   Message-Authenticator = 0x5a0887751830bd9fcf63bc366f6130bf
Mon Dec 18 14:41:50 2017 : Debug: (3)   Cisco-AVPair = "audit-session-id=AC1803C50000441FC27B09BA"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Framed-IP-Address = 172.31.0.39
Mon Dec 18 14:41:50 2017 : Debug: (3)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:50 2017 : Debug: (3)   NAS-Port-Id = "GigabitEthernet1/0/36"
Mon Dec 18 14:41:50 2017 : Debug: (3)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:50 2017 : Debug: (3)   NAS-Port = 50136
Mon Dec 18 14:41:50 2017 : Debug: (3) session-state: No State attribute
Mon Dec 18 14:41:50 2017 : Debug: (3) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (3)   authorize {
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:50 2017 : Debug: (3) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:50 2017 : Debug: (3) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:50 2017 : Debug: (3) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:50 2017 : Debug: (3)     [files8021x] = ok
Mon Dec 18 14:41:50 2017 : Debug: (3)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:50 2017 : Debug: (3)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:50 2017 : Debug: (3)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:50 2017 : Debug: (3)       update request {
Mon Dec 18 14:41:50 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:50 2017 : Debug: (3)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: (3)            -->
Mon Dec 18 14:41:50 2017 : Debug: (3)         SQL-User-Name set to ''
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Reserved connection (1)
Mon Dec 18 14:41:50 2017 : Debug: (3)         Executing select query: SELECT REPLACE('00-08-30-8B-D7-A4','-','')
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Released connection (1)
Mon Dec 18 14:41:50 2017 : Info: Need 2 more connections to reach 10 spares
Mon Dec 18 14:41:50 2017 : Info: rlm_sql (sql8021x): Opening additional connection (8), 1 of 24 pending slots used
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql_mysql: Connected to database 'radius8021x' on Localhost via UNIX socket, server version 10.1.29-MariaDB-6, protocol version 10
Mon Dec 18 14:41:50 2017 : Debug: (3)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:50 2017 : Debug: (3)            --> 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (3)         Stripped-User-Name = 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (3)       } # update request = noop
Mon Dec 18 14:41:50 2017 : Debug: (3)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:50 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: SQL-User-Name set to '0008308BD7A4'
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Reserved connection (6)
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: User found in radcheck table
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:50 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: User found in the group table
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:50 2017 : Debug: (3) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Released connection (6)
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:50 2017 : Debug: (3)     [sql8021x] = ok
Mon Dec 18 14:41:50 2017 : Debug: (3)   } # authorize = ok
Mon Dec 18 14:41:50 2017 : Debug: (3) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:50 2017 : Debug: (3) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (3)   authenticate {
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:50 2017 : Debug: (3) eap8021xciscophone: Peer sent packet with method EAP Identity (1)
Mon Dec 18 14:41:50 2017 : Debug: (3) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:50 2017 : Debug: (3) eap_tls: Initiating new EAP-TLS session
Mon Dec 18 14:41:50 2017 : Debug: (3) eap_tls: Setting verify mode to require certificate from client
Mon Dec 18 14:41:50 2017 : Debug: (3) eap_tls: [eaptls start] = request
Mon Dec 18 14:41:50 2017 : Debug: (3) eap8021xciscophone: Sending EAP Request (code 1) ID 2 length 6
Mon Dec 18 14:41:50 2017 : Debug: (3) eap8021xciscophone: EAP session adding &reply:State = 0x5a334e475a314398
Mon Dec 18 14:41:50 2017 : Debug: (3)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:50 2017 : Debug: (3)     [eap8021xciscophone] = handled
Mon Dec 18 14:41:50 2017 : Debug: (3)   } # authenticate = handled
Mon Dec 18 14:41:50 2017 : Debug: (3) Using Post-Auth-Type Challenge
Mon Dec 18 14:41:50 2017 : Debug: (3) Post-Auth-Type sub-section not found.  Ignoring.
Mon Dec 18 14:41:50 2017 : Debug: (3) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (3) session-state: Nothing to cache
Mon Dec 18 14:41:50 2017 : Debug: (3) Sent Access-Challenge Id 128 from 172.28.0.65:1912 to 172.24.3.197:1645 length 0
Mon Dec 18 14:41:50 2017 : Debug: (3)   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:50 2017 : Debug: (3)   Tunnel-Type = VLAN
Mon Dec 18 14:41:50 2017 : Debug: (3)   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:50 2017 : Debug: (3)   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:50 2017 : Debug: (3)   EAP-Message = 0x010200060d20
Mon Dec 18 14:41:50 2017 : Debug: (3)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:50 2017 : Debug: (3)   State = 0x5a334e475a314398fdc3afa66e535834
Mon Dec 18 14:41:50 2017 : Debug: (3) Finished request
Mon Dec 18 14:41:50 2017 : Debug: Waking up in 4.9 seconds.
Mon Dec 18 14:41:50 2017 : Debug: (4) Received Access-Request Id 129 from 172.24.3.197:1645 to 172.28.0.65:1912 length 341
Mon Dec 18 14:41:50 2017 : Debug: (4)   User-Name = "CP-7965G-SEP0008308BD7A4"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Service-Type = Framed-User
Mon Dec 18 14:41:50 2017 : Debug: (4)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Framed-MTU = 1500
Mon Dec 18 14:41:50 2017 : Debug: (4)   Called-Station-Id = "00-08-30-EA-22-A4"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Calling-Station-Id = "00-08-30-8B-D7-A4"
Mon Dec 18 14:41:50 2017 : Debug: (4)   EAP-Message = 0x0202003e0d8000000034160301002f0100002b03015a37c59ed8a32d93005b0361f1868790379fa13411b0e09e85a5b61e49e849d10000040035002f0100
Mon Dec 18 14:41:50 2017 : Debug: (4)   Message-Authenticator = 0xf980416852d1c455752e47cda02242ad
Mon Dec 18 14:41:50 2017 : Debug: (4)   Cisco-AVPair = "audit-session-id=AC1803C50000441FC27B09BA"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Framed-IP-Address = 172.31.0.39
Mon Dec 18 14:41:50 2017 : Debug: (4)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:50 2017 : Debug: (4)   NAS-Port-Id = "GigabitEthernet1/0/36"
Mon Dec 18 14:41:50 2017 : Debug: (4)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:50 2017 : Debug: (4)   NAS-Port = 50136
Mon Dec 18 14:41:50 2017 : Debug: (4)   State = 0x5a334e475a314398fdc3afa66e535834
Mon Dec 18 14:41:50 2017 : Debug: (4) session-state: No cached attributes
Mon Dec 18 14:41:50 2017 : Debug: (4) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (4)   authorize {
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:50 2017 : Debug: (4) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:50 2017 : Debug: (4) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:50 2017 : Debug: (4) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:50 2017 : Debug: (4)     [files8021x] = ok
Mon Dec 18 14:41:50 2017 : Debug: (4)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:50 2017 : Debug: (4)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:50 2017 : Debug: (4)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:50 2017 : Debug: (4)       update request {
Mon Dec 18 14:41:50 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:50 2017 : Debug: (4)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: (4)            -->
Mon Dec 18 14:41:50 2017 : Debug: (4)         SQL-User-Name set to ''
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Reserved connection (2)
Mon Dec 18 14:41:50 2017 : Debug: (4)         Executing select query: SELECT REPLACE('00-08-30-8B-D7-A4','-','')
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Released connection (2)
Mon Dec 18 14:41:50 2017 : Debug: (4)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:50 2017 : Debug: (4)            --> 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (4)         Stripped-User-Name = 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (4)       } # update request = noop
Mon Dec 18 14:41:50 2017 : Debug: (4)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:50 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> 0008308BD7A4
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: SQL-User-Name set to '0008308BD7A4'
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Reserved connection (3)
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: User found in radcheck table
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:50 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: User found in the group table
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:50 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:50 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:50 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:50 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:50 2017 : Debug: (4) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:50 2017 : Debug: rlm_sql (sql8021x): Released connection (3)
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:50 2017 : Debug: (4)     [sql8021x] = ok
Mon Dec 18 14:41:50 2017 : Debug: (4)   } # authorize = ok
Mon Dec 18 14:41:50 2017 : Debug: (4) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:50 2017 : Debug: (4) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (4)   authenticate {
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Expiring EAP session with state 0x5a334e475a314398
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Finished EAP session with state 0x5a334e475a314398
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Previous EAP request found for state 0x5a334e475a314398, released from the list
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Peer sent packet with method EAP TLS (13)
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: Continuing EAP-TLS
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: Peer sent flags --L
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: Peer indicated complete TLS record size will be 52 bytes
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: Got complete TLS record (52 bytes)
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: [eaptls verify] = length included
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: (other): before SSL initialization
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: before SSL initialization
Mon Dec 18 14:41:50 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: before SSL initialization
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: <<< recv TLS 1.2  [length 002f]
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: SSLv3/TLS read client hello
Mon Dec 18 14:41:50 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: >>> send TLS 1.0 Handshake [length 002a], ServerHello
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: SSLv3/TLS write server hello
Mon Dec 18 14:41:50 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: >>> send TLS 1.0 Handshake [length 02f8], Certificate
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: SSLv3/TLS write certificate
Mon Dec 18 14:41:50 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: >>> send TLS 1.0 Handshake [length 00a7], CertificateRequest
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: SSLv3/TLS write certificate request
Mon Dec 18 14:41:50 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: >>> send TLS 1.0 Handshake [length 0004], ServerHelloDone
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: SSLv3/TLS write server done
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: TLS_accept: Need to read more data: SSLv3/TLS write server done
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: In SSL Handshake Phase
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: In SSL Accept mode
Mon Dec 18 14:41:50 2017 : Debug: (4) eap_tls: [eaptls process] = handled
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: Sending EAP Request (code 1) ID 3 length 1003
Mon Dec 18 14:41:50 2017 : Debug: (4) eap8021xciscophone: EAP session adding &reply:State = 0x5a334e475b304398
Mon Dec 18 14:41:50 2017 : Debug: (4)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:50 2017 : Debug: (4)     [eap8021xciscophone] = handled
Mon Dec 18 14:41:50 2017 : Debug: (4)   } # authenticate = handled
Mon Dec 18 14:41:50 2017 : Debug: (4) Using Post-Auth-Type Challenge
Mon Dec 18 14:41:50 2017 : Debug: (4) Post-Auth-Type sub-section not found.  Ignoring.
Mon Dec 18 14:41:50 2017 : Debug: (4) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:50 2017 : Debug: (4) session-state: Nothing to cache
Mon Dec 18 14:41:50 2017 : Debug: (4) Sent Access-Challenge Id 129 from 172.28.0.65:1912 to 172.24.3.197:1645 length 0
Mon Dec 18 14:41:50 2017 : Debug: (4)   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:50 2017 : Debug: (4)   Tunnel-Type = VLAN
Mon Dec 18 14:41:50 2017 : Debug: (4)   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:50 2017 : Debug: (4)   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:50 2017 : Debug: (4)   EAP-Message = 0x010303eb0d80000003e1160301002a0200002603010760b8a28d25a805c3223d1cb208675e38873a9bbeed5824a2aa6cbba6c57a3e0000350016030102f80b0002f40002f10002ee308202ea30820253a003020102020900a663e941aa84c0b4300d06092a864886f70d0101050500308198310b300906
Mon Dec 18 14:41:50 2017 : Debug: (4)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:50 2017 : Debug: (4)   State = 0x5a334e475b304398fdc3afa66e535834
Mon Dec 18 14:41:50 2017 : Debug: (4) Finished request
Mon Dec 18 14:41:50 2017 : Debug: Waking up in 4.9 seconds.
Mon Dec 18 14:41:53 2017 : Debug: (5) Received Access-Request Id 130 from 172.24.3.197:1645 to 172.28.0.65:1912 length 1619
Mon Dec 18 14:41:53 2017 : Debug: (5)   User-Name = "CP-7965G-SEP0008308BD7A4"
Mon Dec 18 14:41:53 2017 : Debug: (5)   Service-Type = Framed-User
Mon Dec 18 14:41:53 2017 : Debug: (5)   Cisco-AVPair = "service-type=Framed"
Mon Dec 18 14:41:53 2017 : Debug: (5)   Framed-MTU = 1500
Mon Dec 18 14:41:53 2017 : Debug: (5)   Called-Station-Id = "00-08-30-EA-22-A4"
Mon Dec 18 14:41:53 2017 : Debug: (5)   Calling-Station-Id = "00-08-30-8B-D7-A4"
Mon Dec 18 14:41:53 2017 : Debug: (5)   EAP-Message = 0x020305320d800000052816030103520b00034e00034b00034830820344308202ada00302010202015d300d06092a864886f70d0101050500308198310b30090603550406130244453140303e060355040a0c374465757473636865732042696f6d61737365466f72736368756e67735a656e7472756d20
Mon Dec 18 14:41:53 2017 : Debug: (5)   Message-Authenticator = 0xae0eb7ef123307c8109a35d51d4fb5fb
Mon Dec 18 14:41:53 2017 : Debug: (5)   Cisco-AVPair = "audit-session-id=AC1803C50000441FC27B09BA"
Mon Dec 18 14:41:53 2017 : Debug: (5)   Cisco-AVPair = "method=dot1x"
Mon Dec 18 14:41:53 2017 : Debug: (5)   Framed-IP-Address = 172.31.0.39
Mon Dec 18 14:41:53 2017 : Debug: (5)   NAS-IP-Address = 172.24.3.197
Mon Dec 18 14:41:53 2017 : Debug: (5)   NAS-Port-Id = "GigabitEthernet1/0/36"
Mon Dec 18 14:41:53 2017 : Debug: (5)   NAS-Port-Type = Ethernet
Mon Dec 18 14:41:53 2017 : Debug: (5)   NAS-Port = 50136
Mon Dec 18 14:41:53 2017 : Debug: (5)   State = 0x5a334e475b304398fdc3afa66e535834
Mon Dec 18 14:41:53 2017 : Debug: (5) session-state: No cached attributes
Mon Dec 18 14:41:53 2017 : Debug: (5) # Executing section authorize from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:53 2017 : Debug: (5)   authorize {
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authorize]: calling files8021x (rlm_files)
Mon Dec 18 14:41:53 2017 : Debug: (5) files8021x: users: Matched entry DEFAULT at line 51
Mon Dec 18 14:41:53 2017 : Debug: (5) files8021x: ::: FROM 0 TO 0 MAX 0
Mon Dec 18 14:41:53 2017 : Debug: (5) files8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authorize]: returned from files8021x (rlm_files)
Mon Dec 18 14:41:53 2017 : Debug: (5)     [files8021x] = ok
Mon Dec 18 14:41:53 2017 : Debug: (5)     if ( &Calling-Station-Id != '' ) {
Mon Dec 18 14:41:53 2017 : Debug: (5)     if ( &Calling-Station-Id != '' )  -> TRUE
Mon Dec 18 14:41:53 2017 : Debug: (5)     if ( &Calling-Station-Id != '' )  {
Mon Dec 18 14:41:53 2017 : Debug: (5)       update request {
Mon Dec 18 14:41:53 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:53 2017 : Debug: (5)         EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:53 2017 : Debug: (5)            -->
Mon Dec 18 14:41:53 2017 : Debug: (5)         SQL-User-Name set to ''
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql (sql8021x): Reserved connection (4)
Mon Dec 18 14:41:53 2017 : Debug: (5)         Executing select query: SELECT REPLACE('00-08-30-8B-D7-A4','-','')
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql (sql8021x): Released connection (4)
Mon Dec 18 14:41:53 2017 : Info: Need 1 more connections to reach 10 spares
Mon Dec 18 14:41:53 2017 : Info: rlm_sql (sql8021x): Opening additional connection (9), 1 of 23 pending slots used
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql_mysql: Connected to database 'radius8021x' on Localhost via UNIX socket, server version 10.1.29-MariaDB-6, protocol version 10
Mon Dec 18 14:41:53 2017 : Debug: (5)         EXPAND %{sql8021x:SELECT REPLACE('%{Calling-Station-Id}','-','')}
Mon Dec 18 14:41:53 2017 : Debug: (5)            --> 0008308BD7A4
Mon Dec 18 14:41:53 2017 : Debug: (5)         Stripped-User-Name = 0008308BD7A4
Mon Dec 18 14:41:53 2017 : Debug: (5)       } # update request = noop
Mon Dec 18 14:41:53 2017 : Debug: (5)     } # if ( &Calling-Station-Id != '' )  = noop
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authorize]: calling sql8021x (rlm_sql)
Mon Dec 18 14:41:53 2017 : Debug: %{Stripped-User-Name}
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: attribute --> Stripped-User-Name
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND %{Stripped-User-Name}
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> 0008308BD7A4
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: SQL-User-Name set to '0008308BD7A4'
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql (sql8021x): Reserved connection (0)
Mon Dec 18 14:41:53 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Mon Dec 18 14:41:53 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:53 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: User found in radcheck table
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Conditional check items matched, merging assignment check items
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Service-Type := Framed-User
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: FROM 1 TO 1 MAX 2
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Service-Type
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: APPENDING Service-Type FROM 0 TO 1
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: TO in 1 out 1
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:53 2017 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '
Mon Dec 18 14:41:53 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:53 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '0008308BD7A4' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ... falling-through to group processing
Mon Dec 18 14:41:53 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Mon Dec 18 14:41:53 2017 : Debug: attribute --> SQL-User-Name
Mon Dec 18 14:41:53 2017 : Debug: literal --> ' ORDER BY priority
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Executing select query: SELECT groupname FROM radusergroup WHERE username = '0008308BD7A4' ORDER BY priority
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: User found in the group table
Mon Dec 18 14:41:53 2017 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '
Mon Dec 18 14:41:53 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:53 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Group "9800": Conditional check items matched
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Group "9800": Merging assignment check items
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Auth-Type := eap8021xciscophone
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: FROM 1 TO 2 MAX 3
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Auth-Type
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: OVERWRITING Auth-Type FROM 0 TO 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: TO in 2 out 2
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: to[0] = Auth-Type
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: to[1] = Service-Type
Mon Dec 18 14:41:53 2017 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '
Mon Dec 18 14:41:53 2017 : Debug: attribute --> sql8021x-SQL-Group
Mon Dec 18 14:41:53 2017 : Debug: literal --> ' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{sql8021x-SQL-Group}' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:    --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '9800' ORDER BY id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: Group "9800": Merging reply items
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Tunnel-Medium-Type = IEEE-802
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Tunnel-Type = VLAN
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Tunnel-Private-Group-Id = "980"
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x:   Cisco-AVPair = "device-traffic-class=voice"
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: FROM 4 TO 0 MAX 4
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Tunnel-Medium-Type
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: APPENDING Tunnel-Medium-Type FROM 0 TO 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Tunnel-Type
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: APPENDING Tunnel-Type FROM 1 TO 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Tunnel-Private-Group-Id
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: APPENDING Tunnel-Private-Group-Id FROM 2 TO 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: Examining Cisco-AVPair
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: APPENDING Cisco-AVPair FROM 3 TO 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ::: TO in 0 out 0
Mon Dec 18 14:41:53 2017 : Debug: (5) sql8021x: ... falling-through to profile processing
Mon Dec 18 14:41:53 2017 : Debug: rlm_sql (sql8021x): Released connection (0)
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authorize]: returned from sql8021x (rlm_sql)
Mon Dec 18 14:41:53 2017 : Debug: (5)     [sql8021x] = ok
Mon Dec 18 14:41:53 2017 : Debug: (5)   } # authorize = ok
Mon Dec 18 14:41:53 2017 : Debug: (5) Found Auth-Type = eap8021xciscophone
Mon Dec 18 14:41:53 2017 : Debug: (5) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:53 2017 : Debug: (5)   authenticate {
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authenticate]: calling eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Expiring EAP session with state 0x5a334e475b304398
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Finished EAP session with state 0x5a334e475b304398
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Previous EAP request found for state 0x5a334e475b304398, released from the list
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Peer sent packet with method EAP TLS (13)
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Calling submodule eap_tls to process data
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: Continuing EAP-TLS
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: Peer sent flags --L
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: Peer indicated complete TLS record size will be 1320 bytes
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: Got complete TLS record (1320 bytes)
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: [eaptls verify] = length included
Mon Dec 18 14:41:53 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: TLS_accept: SSLv3/TLS write server done
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: <<< recv TLS 1.0 Handshake [length 0352], Certificate
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: Creating attributes from certificate OIDs
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls:   TLS-Cert-Serial := "5871a15a20dc203cceb13b568ad905f9"
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls:   TLS-Cert-Expiration := "220309050842Z"
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls:   TLS-Cert-Subject := "/C=DE/O=Deutsches BiomasseForschungsZentrum gemeinnuetzige GmbH/OU=IT/CN=CAPF-1b0db5b4/ST=Sachsen/L=Leipzig"
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls:   TLS-Cert-Issuer := "/C=DE/O=Deutsches BiomasseForschungsZentrum gemeinnuetzige GmbH/OU=IT/CN=CAPF-1b0db5b4/ST=Sachsen/L=Leipzig"
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls:   TLS-Cert-Common-Name := "CAPF-1b0db5b4"
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls:   SSL says error 26 : unsupported certificate purpose
Mon Dec 18 14:41:53 2017 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 0
Mon Dec 18 14:41:53 2017 : Debug: (5) eap_tls: >>> send TLS 1.0 Alert [length 0002], fatal unsupported_certificate
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls: TLS Alert write:fatal:unsupported certificate
Mon Dec 18 14:41:53 2017 : Error: tls: TLS_accept: Error in error
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls: Failed in __FUNCTION__ (SSL_read): ../ssl/statem/statem_srvr.c[2896]:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls: System call (I/O) error (-1)
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls: TLS receive handshake failed during operation
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap_tls: [eaptls process] = fail
Mon Dec 18 14:41:53 2017 : ERROR: (5) eap8021xciscophone: Failed continuing EAP TLS (13) session.  EAP sub-module failed
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Sending EAP Failure (code 4) ID 3 length 4
Mon Dec 18 14:41:53 2017 : Debug: (5) eap8021xciscophone: Failed in EAP select
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[authenticate]: returned from eap8021xciscophone (rlm_eap)
Mon Dec 18 14:41:53 2017 : Debug: (5)     [eap8021xciscophone] = invalid
Mon Dec 18 14:41:53 2017 : Debug: (5)   } # authenticate = invalid
Mon Dec 18 14:41:53 2017 : Debug: (5) Failed to authenticate the user
Mon Dec 18 14:41:53 2017 : Debug: (5) Using Post-Auth-Type Reject
Mon Dec 18 14:41:53 2017 : Debug: (5) # Executing group from file /etc/freeradius/3.0/conf.d/dbfz-radiusXX.leipzig.dbfz.de.8021x
Mon Dec 18 14:41:53 2017 : Debug: (5)   Post-Auth-Type REJECT {
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter)
Mon Dec 18 14:41:53 2017 : Debug: %{User-Name}
Mon Dec 18 14:41:53 2017 : Debug: Parsed xlat tree:
Mon Dec 18 14:41:53 2017 : Debug: attribute --> User-Name
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: EXPAND %{User-Name}
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject:    --> CP-7965G-SEP0008308BD7A4
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Matched entry DEFAULT at line 11
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "Tunnel-Medium-Type" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "Tunnel-Type" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "Tunnel-Private-Group-Id" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "Cisco-AVPair" allowed by 0 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: EAP-Message = 0x04030004 allowed by EAP-Message =* 0x
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x
Mon Dec 18 14:41:53 2017 : Debug: (5) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Mon Dec 18 14:41:53 2017 : Debug: (5)     modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter)
Mon Dec 18 14:41:53 2017 : Debug: (5)     [attr_filter.access_reject] = updated
Mon Dec 18 14:41:53 2017 : Debug: (5)   } # Post-Auth-Type REJECT = updated
Mon Dec 18 14:41:53 2017 : Debug: (5) Delaying response for 1.000000 seconds
Mon Dec 18 14:41:53 2017 : Debug: Waking up in 0.3 seconds.
Mon Dec 18 14:41:53 2017 : Debug: Waking up in 0.6 seconds.
Mon Dec 18 14:41:54 2017 : Debug: (5) Sending delayed response
Mon Dec 18 14:41:54 2017 : Debug: (5) Sent Access-Reject Id 130 from 172.28.0.65:1912 to 172.24.3.197:1645 length 44
Mon Dec 18 14:41:54 2017 : Debug: (5)   EAP-Message = 0x04030004
Mon Dec 18 14:41:54 2017 : Debug: (5)   Message-Authenticator = 0x00000000000000000000000000000000
Mon Dec 18 14:41:54 2017 : Debug: Waking up in 1.6 seconds.
Mon Dec 18 14:41:55 2017 : Debug: (3) Cleaning up request packet ID 128 with timestamp +35
Mon Dec 18 14:41:55 2017 : Debug: (4) Cleaning up request packet ID 129 with timestamp +35
Mon Dec 18 14:41:55 2017 : Debug: Waking up in 2.3 seconds.