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