After Upgrade from freeradius 2 to 3 (Debian 8 - 9): TLS Alert write:fatal:unsupported certificate
Boris Lytochkin
lytboris at yandex-team.ru
Tue Dec 19 18:18:49 CET 2017
Hi.
Alan, you are absolutely correct about OIDs. But one thing drives me crazy. Robert sent me a full capture (attached) and it is really weird if you compare it to FreeRADIUS logs.
Here's client cert from capture (RADIUS protocol dump, frame #10):
Certificate: 30820345308202aea003020102020200f1300d06092a8648... (id-at-commonName=SEP64A0E7147412,id-at-organizationalUnitName=IT,id-at-organizationName=Deutsches BiomasseForschungsZentrum
geme,id-at-countryName=DE)
signedCertificate
version: v3 (2)
serialNumber: 241
And this is how it is presented in logs:
...
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: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"
...
I have no idea why FreeRADIUS peeks issuer's cert instead of real client's one. I guess something is broken in server's configuration...
On 19.12.2017 19:15, Alan DeKok wrote:
>> On Dec 19, 2017, at 5:22 AM, Gladewitz, Robert via Freeradius-Users <freeradius-users at lists.freeradius.org> wrote:
>>
>> If I understand this logs rights, the error happening on ca certificate?
> No.
>
> They're about the server certificate.
>
>> Mon Dec 18 14:41:44 2017 : ERROR: (2) eap_tls: SSL says error 26 :
>> unsupported certificate purpose
> As I said before, OpenSSL doesn't like the X509 OIDs in the certificate.
>
> The "openssl verify" returns OK, because it verifies the cert for a different purpose.
>
> No amount of poking FreeRADIUS will fix the OpenSSL code which sanity checks the certificate.
>
> Your choices are:
>
> a) fix the Cisco equipment to produce certs that OpenSSL likes
>
> b) fix the new version OpenSSL to remove this extra sanity checking
>
> c) downgrade the whole OS + OpenSSL to a version of OpenSSL which doesn't have this extra check.
>
> You can post messages to this list all you want, but nothing we can do to help. We CANNOT work around this in FreeRADIUS, because it's an OpenSSL limitation.
>
> Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
--
Boris Lytochkin
Yandex NOC
+7 (495) 739 70 00 ext. 7671
-------------- next part --------------
A non-text attachment was scrubbed...
Name: radius.1912.pcap
Type: application/octet-stream
Size: 7872 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20171219/41f59452/attachment-0001.obj>
-------------- next part --------------
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
More information about the Freeradius-Users
mailing list