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