AW: Proxy problem when switching from version2 to version3
Bornemann, Hans
hans.bornemann at tu-dortmund.de
Tue Jan 23 14:13:11 CET 2018
Hi Alan,
if you like, take a look to the debug output.
first the failing proxy with version 3, then successful with version 2, proxy conf.
anything more needed?
-----
Debug Output freeradius 3 --> proxy to home server --> failing
Thu Jan 18 10:22:37 2018 : Debug: (0) Received Access-Request Id 68 from 129.217.251.242:32775 to 129.217.131.207:1812 length 304
Thu Jan 18 10:22:37 2018 : Debug: (0) User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:37 2018 : Debug: (0) Chargeable-User-Identity = 0x00
Thu Jan 18 10:22:37 2018 : Debug: (0) Location-Capable = Civic-Location
Thu Jan 18 10:22:37 2018 : Debug: (0) Calling-Station-Id = "3c-15-c2-e8-40-fe"
Thu Jan 18 10:22:37 2018 : Debug: (0) Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
Thu Jan 18 10:22:37 2018 : Debug: (0) NAS-Port = 1
Thu Jan 18 10:22:37 2018 : Debug: (0) Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Thu Jan 18 10:22:37 2018 : Debug: (0) Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
Thu Jan 18 10:22:37 2018 : Debug: (0) NAS-IP-Address = 129.217.251.242
Thu Jan 18 10:22:37 2018 : Debug: (0) NAS-Identifier = "wlc-staging"
Thu Jan 18 10:22:37 2018 : Debug: (0) Airespace-Wlan-Id = 8
Thu Jan 18 10:22:37 2018 : Debug: (0) Service-Type = Framed-User
Thu Jan 18 10:22:37 2018 : Debug: (0) Framed-MTU = 1300
Thu Jan 18 10:22:37 2018 : Debug: (0) NAS-Port-Type = Wireless-802.11
Thu Jan 18 10:22:37 2018 : Debug: (0) Tunnel-Type:0 = VLAN
Thu Jan 18 10:22:37 2018 : Debug: (0) Tunnel-Medium-Type:0 = IEEE-802
Thu Jan 18 10:22:37 2018 : Debug: (0) Tunnel-Private-Group-Id:0 = "3503"
Thu Jan 18 10:22:37 2018 : Debug: (0) EAP-Message = 0x020100180172746d6f62696c6e65747a4072746d6f62696c
Thu Jan 18 10:22:37 2018 : Debug: (0) Message-Authenticator = 0xbede1e965b3fc497b387e44d3dd44344
Thu Jan 18 10:22:37 2018 : Debug: (0) session-state: No State attribute
Thu Jan 18 10:22:37 2018 : Debug: (0) # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:37 2018 : Debug: (0) authorize {
Thu Jan 18 10:22:37 2018 : Debug: (0) if (NAS-IP-Address =~ /^129\.217\.142\./) {
Thu Jan 18 10:22:37 2018 : Debug: (0) if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:22:37 2018 : Debug: (0) if (NAS-IP-Address =~ /^129\.217\.131\./) {
Thu Jan 18 10:22:37 2018 : Debug: (0) if (NAS-IP-Address =~ /^129\.217\.131\./) -> FALSE
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess)
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Thu Jan 18 10:22:37 2018 : Debug: (0) [preprocess] = ok
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm)
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Checking for suffix after "@"
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Looking up realm "rtmobil" for User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Found realm "rtmobil"
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Adding Realm = "rtmobil"
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Proxying request from user rtmobilnetz at rtmobil to realm rtmobil
Thu Jan 18 10:22:37 2018 : Debug: (0) suffix: Preparing to proxy authentication request to realm "rtmobil"
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm)
Thu Jan 18 10:22:37 2018 : Debug: (0) [suffix] = updated
Thu Jan 18 10:22:37 2018 : Debug: (0) if (&User-Name =~ /telesec/ ) {
Thu Jan 18 10:22:37 2018 : Debug: (0) if (&User-Name =~ /telesec/ ) -> FALSE
Thu Jan 18 10:22:37 2018 : Debug: (0) else {
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: calling eapoldca (rlm_eap)
Thu Jan 18 10:22:37 2018 : Debug: (0) eapoldca: Request is supposed to be proxied to Realm rtmobil. Not doing EAP.
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: returned from eapoldca (rlm_eap)
Thu Jan 18 10:22:37 2018 : Debug: (0) [eapoldca] = noop
Thu Jan 18 10:22:37 2018 : Debug: (0) } # else = noop
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: calling sql (rlm_sql)
Thu Jan 18 10:22:37 2018 : Debug: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}
Thu Jan 18 10:22:37 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:37 2018 : Debug: XLAT-IF {
Thu Jan 18 10:22:37 2018 : Debug: attribute --> Stripped-User-Name
Thu Jan 18 10:22:37 2018 : Debug: }
Thu Jan 18 10:22:37 2018 : Debug: XLAT-ELSE {
Thu Jan 18 10:22:37 2018 : Debug: XLAT-IF {
Thu Jan 18 10:22:37 2018 : Debug: attribute --> User-Name
Thu Jan 18 10:22:37 2018 : Debug: }
Thu Jan 18 10:22:37 2018 : Debug: XLAT-ELSE {
Thu Jan 18 10:22:37 2018 : Debug: literal --> DEFAULT
Thu Jan 18 10:22:37 2018 : Debug: }
Thu Jan 18 10:22:37 2018 : Debug: }
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: --> rtmobilnetz at rtmobil
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: SQL-User-Name set to 'rtmobilnetz at rtmobil'
Thu Jan 18 10:22:37 2018 : Debug: rlm_sql (sql): Reserved connection (0)
Thu Jan 18 10:22:37 2018 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Jan 18 10:22:37 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:37 2018 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Thu Jan 18 10:22:37 2018 : Debug: attribute --> SQL-User-Name
Thu Jan 18 10:22:37 2018 : Debug: literal --> ' ORDER BY id
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: ... falling-through to group processing
Thu Jan 18 10:22:37 2018 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Thu Jan 18 10:22:37 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:37 2018 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Thu Jan 18 10:22:37 2018 : Debug: attribute --> SQL-User-Name
Thu Jan 18 10:22:37 2018 : Debug: literal --> ' ORDER BY priority
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: User not found in any groups
Thu Jan 18 10:22:37 2018 : Debug: (0) sql: ... falling-through to profile processing
Thu Jan 18 10:22:37 2018 : Debug: rlm_sql (sql): Released connection (0)
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: returned from sql (rlm_sql)
Thu Jan 18 10:22:37 2018 : Debug: (0) [sql] = notfound
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap)
Thu Jan 18 10:22:37 2018 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap)
Thu Jan 18 10:22:37 2018 : Debug: (0) [pap] = noop
Thu Jan 18 10:22:37 2018 : Debug: (0) } # authorize = updated
Thu Jan 18 10:22:37 2018 : Debug: (0) Starting proxy to home server 129.217.197.132 port 1812
Thu Jan 18 10:22:37 2018 : Debug: (0) Empty pre-proxy section in virtual server "itmc-wlan". Using default return values.
Thu Jan 18 10:22:37 2018 : Debug: (0) proxy: Trying to allocate ID (0/2)
Thu Jan 18 10:22:37 2018 : Debug: (0) proxy: request is now in proxy hash
Thu Jan 18 10:22:37 2018 : Debug: (0) proxy: allocating destination 129.217.197.132 port 1812 - Id 206
Thu Jan 18 10:22:37 2018 : Debug: (0) Proxying request to home server 129.217.197.132 port 1812 timeout 20.000000
Thu Jan 18 10:22:38 2018 : Debug: (0) Sent Access-Request Id 206 from 0.0.0.0:48124 to 129.217.197.132:1812 length 314
Thu Jan 18 10:22:38 2018 : Debug: (0) User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (0) Chargeable-User-Identity = 0x00
Thu Jan 18 10:22:38 2018 : Debug: (0) Location-Capable = Civic-Location
Thu Jan 18 10:22:38 2018 : Debug: (0) Calling-Station-Id = "3c-15-c2-e8-40-fe"
Thu Jan 18 10:22:38 2018 : Debug: (0) Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
Thu Jan 18 10:22:38 2018 : Debug: (0) NAS-Port = 1
Thu Jan 18 10:22:38 2018 : Debug: (0) Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Thu Jan 18 10:22:38 2018 : Debug: (0) Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
Thu Jan 18 10:22:38 2018 : Debug: (0) NAS-IP-Address = 129.217.251.242
Thu Jan 18 10:22:38 2018 : Debug: (0) NAS-Identifier = "wlc-staging"
Thu Jan 18 10:22:38 2018 : Debug: (0) Airespace-Wlan-Id = 8
Thu Jan 18 10:22:38 2018 : Debug: (0) Service-Type = Framed-User
Thu Jan 18 10:22:38 2018 : Debug: (0) Framed-MTU = 1300
Thu Jan 18 10:22:38 2018 : Debug: (0) NAS-Port-Type = Wireless-802.11
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Type:0 = VLAN
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Medium-Type:0 = IEEE-802
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Private-Group-Id:0 = "3503"
Thu Jan 18 10:22:38 2018 : Debug: (0) EAP-Message = 0x020100180172746d6f62696c6e65747a4072746d6f62696c
Thu Jan 18 10:22:38 2018 : Debug: (0) Message-Authenticator = 0xbede1e965b3fc497b387e44d3dd44344
Thu Jan 18 10:22:38 2018 : Debug: (0) Event-Timestamp = "Jan 18 2018 10:22:37 CET"
Thu Jan 18 10:22:38 2018 : Debug: (0) Proxy-State = 0x3638
Thu Jan 18 10:22:38 2018 : Debug: Waking up in 0.3 seconds.
Thu Jan 18 10:22:38 2018 : Proxy: (0) Marking home server 129.217.197.132 port 1812 alive
Thu Jan 18 10:22:38 2018 : Debug: (0) Clearing existing &reply: attributes
Thu Jan 18 10:22:38 2018 : Debug: (0) Received Access-Challenge Id 206 from 129.217.197.132:1812 to 129.217.131.207:48124 length 124
Thu Jan 18 10:22:38 2018 : Debug: (0) Proxy-State = 0x3638
Thu Jan 18 10:22:38 2018 : Debug: (0) Session-Timeout = 60
Thu Jan 18 10:22:38 2018 : Debug: (0) EAP-Message = 0x010200241a0102001f103a19daaaee38d70eaedc727f0ccb621f504f4f4c2d4144533031
Thu Jan 18 10:22:38 2018 : Debug: (0) State = 0x45300497000001370001020081d9c584000000000000000000000000000000100d436aee
Thu Jan 18 10:22:38 2018 : Debug: (0) Message-Authenticator = 0xe9ebcfb379a08e2bb3205a9451a1b0de
Thu Jan 18 10:22:38 2018 : Debug: (0) # Executing section post-proxy from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:38 2018 : Debug: (0) post-proxy {
Thu Jan 18 10:22:38 2018 : Debug: (0) modsingle[post-proxy]: calling attr_filter.post-proxy (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: %{Realm}
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: attribute --> Realm
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: EXPAND %{Realm}
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: --> rtmobil
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Matched entry rtmobil at line 17
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Proxy-State" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Session-Timeout" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "EAP-Message" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "State" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Message-Authenticator" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Matched entry DEFAULT at line 32
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Proxy-State = 0x3638 allowed by Proxy-State =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Proxy-State" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Session-Timeout" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: EAP-Message = 0x010200241a0102001f103a19daaaee38d70eaedc727f0ccb621f504f4f4c2d4144533031 allowed by EAP-Message =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: State = 0x45300497000001370001020081d9c584000000000000000000000000000000100d436aee allowed by State =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "State" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Message-Authenticator = 0xe9ebcfb379a08e2bb3205a9451a1b0de allowed by Message-Authenticator =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (0) attr_filter.post-proxy: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (0) modsingle[post-proxy]: returned from attr_filter.post-proxy (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: (0) [attr_filter.post-proxy] = updated
Thu Jan 18 10:22:38 2018 : Debug: (0) modsingle[post-proxy]: calling eap_wlan (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (0) eap_wlan: No pre-existing handler found
Thu Jan 18 10:22:38 2018 : Debug: (0) modsingle[post-proxy]: returned from eap_wlan (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (0) [eap_wlan] = noop
Thu Jan 18 10:22:38 2018 : Debug: (0) } # post-proxy = updated
Thu Jan 18 10:22:38 2018 : Debug: (0) session-state: Nothing to cache
Thu Jan 18 10:22:38 2018 : Debug: (0) Using Post-Auth-Type Challenge
Thu Jan 18 10:22:38 2018 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring.
Thu Jan 18 10:22:38 2018 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:38 2018 : Debug: (0) session-state: Nothing to cache
Thu Jan 18 10:22:38 2018 : Debug: (0) Sent Access-Challenge Id 68 from 129.217.131.207:1812 to 129.217.251.242:32775 length 0
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Private-Group-Id := "26"
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Type := VLAN
Thu Jan 18 10:22:38 2018 : Debug: (0) Tunnel-Medium-Type := IEEE-802
Thu Jan 18 10:22:38 2018 : Debug: (0) EAP-Message = 0x010200241a0102001f103a19daaaee38d70eaedc727f0ccb621f504f4f4c2d4144533031
Thu Jan 18 10:22:38 2018 : Debug: (0) State = 0x45300497000001370001020081d9c584000000000000000000000000000000100d436aee
Thu Jan 18 10:22:38 2018 : Debug: (0) Message-Authenticator = 0xe9ebcfb379a08e2bb3205a9451a1b0de
Thu Jan 18 10:22:38 2018 : Debug: (0) Finished request
Thu Jan 18 10:22:38 2018 : Debug: Waking up in 4.9 seconds.
Thu Jan 18 10:22:38 2018 : Debug: (1) Received Access-Request Id 69 from 129.217.251.242:32775 to 129.217.131.207:1812 length 326
Thu Jan 18 10:22:38 2018 : Debug: (1) User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) Chargeable-User-Identity = 0x00
Thu Jan 18 10:22:38 2018 : Debug: (1) Location-Capable = Civic-Location
Thu Jan 18 10:22:38 2018 : Debug: (1) Calling-Station-Id = "3c-15-c2-e8-40-fe"
Thu Jan 18 10:22:38 2018 : Debug: (1) Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Port = 1
Thu Jan 18 10:22:38 2018 : Debug: (1) Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Thu Jan 18 10:22:38 2018 : Debug: (1) Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-IP-Address = 129.217.251.242
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Identifier = "wlc-staging"
Thu Jan 18 10:22:38 2018 : Debug: (1) Airespace-Wlan-Id = 8
Thu Jan 18 10:22:38 2018 : Debug: (1) Service-Type = Framed-User
Thu Jan 18 10:22:38 2018 : Debug: (1) Framed-MTU = 1300
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Port-Type = Wireless-802.11
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Type:0 = VLAN
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Medium-Type:0 = IEEE-802
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Private-Group-Id:0 = "3503"
Thu Jan 18 10:22:38 2018 : Debug: (1) EAP-Message = 0x020200080319152b
Thu Jan 18 10:22:38 2018 : Debug: (1) State = 0x45300497000001370001020081d9c584000000000000000000000000000000100d436aee
Thu Jan 18 10:22:38 2018 : Debug: (1) Message-Authenticator = 0x31a7b8a02c1f45acee5e637c48d8f20d
Thu Jan 18 10:22:38 2018 : Debug: (1) session-state: No cached attributes
Thu Jan 18 10:22:38 2018 : Debug: (1) # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:38 2018 : Debug: (1) authorize {
Thu Jan 18 10:22:38 2018 : Debug: (1) if (NAS-IP-Address =~ /^129\.217\.142\./) {
Thu Jan 18 10:22:38 2018 : Debug: (1) if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:22:38 2018 : Debug: (1) if (NAS-IP-Address =~ /^129\.217\.131\./) {
Thu Jan 18 10:22:38 2018 : Debug: (1) if (NAS-IP-Address =~ /^129\.217\.131\./) -> FALSE
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess)
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Thu Jan 18 10:22:38 2018 : Debug: (1) [preprocess] = ok
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: calling suffix (rlm_realm)
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Checking for suffix after "@"
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Looking up realm "rtmobil" for User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Found realm "rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Adding Realm = "rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Proxying request from user rtmobilnetz at rtmobil to realm rtmobil
Thu Jan 18 10:22:38 2018 : Debug: (1) suffix: Preparing to proxy authentication request to realm "rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: returned from suffix (rlm_realm)
Thu Jan 18 10:22:38 2018 : Debug: (1) [suffix] = updated
Thu Jan 18 10:22:38 2018 : Debug: (1) if (&User-Name =~ /telesec/ ) {
Thu Jan 18 10:22:38 2018 : Debug: (1) if (&User-Name =~ /telesec/ ) -> FALSE
Thu Jan 18 10:22:38 2018 : Debug: (1) else {
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: calling eapoldca (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (1) eapoldca: Request is supposed to be proxied to Realm rtmobil. Not doing EAP.
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: returned from eapoldca (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (1) [eapoldca] = noop
Thu Jan 18 10:22:38 2018 : Debug: (1) } # else = noop
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: calling sql (rlm_sql)
Thu Jan 18 10:22:38 2018 : Debug: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: XLAT-IF {
Thu Jan 18 10:22:38 2018 : Debug: attribute --> Stripped-User-Name
Thu Jan 18 10:22:38 2018 : Debug: }
Thu Jan 18 10:22:38 2018 : Debug: XLAT-ELSE {
Thu Jan 18 10:22:38 2018 : Debug: XLAT-IF {
Thu Jan 18 10:22:38 2018 : Debug: attribute --> User-Name
Thu Jan 18 10:22:38 2018 : Debug: }
Thu Jan 18 10:22:38 2018 : Debug: XLAT-ELSE {
Thu Jan 18 10:22:38 2018 : Debug: literal --> DEFAULT
Thu Jan 18 10:22:38 2018 : Debug: }
Thu Jan 18 10:22:38 2018 : Debug: }
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: EXPAND %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: --> rtmobilnetz at rtmobil
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: SQL-User-Name set to 'rtmobilnetz at rtmobil'
Thu Jan 18 10:22:38 2018 : Debug: rlm_sql (sql): Reserved connection (1)
Thu Jan 18 10:22:38 2018 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '
Thu Jan 18 10:22:38 2018 : Debug: attribute --> SQL-User-Name
Thu Jan 18 10:22:38 2018 : Debug: literal --> ' ORDER BY id
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: ... falling-through to group processing
Thu Jan 18 10:22:38 2018 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = '
Thu Jan 18 10:22:38 2018 : Debug: attribute --> SQL-User-Name
Thu Jan 18 10:22:38 2018 : Debug: literal --> ' ORDER BY priority
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: --> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: User not found in any groups
Thu Jan 18 10:22:38 2018 : Debug: (1) sql: ... falling-through to profile processing
Thu Jan 18 10:22:38 2018 : Debug: rlm_sql (sql): Released connection (1)
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: returned from sql (rlm_sql)
Thu Jan 18 10:22:38 2018 : Debug: (1) [sql] = notfound
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: calling pap (rlm_pap)
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[authorize]: returned from pap (rlm_pap)
Thu Jan 18 10:22:38 2018 : Debug: (1) [pap] = noop
Thu Jan 18 10:22:38 2018 : Debug: (1) } # authorize = updated
Thu Jan 18 10:22:38 2018 : Debug: (1) Starting proxy to home server 129.217.197.132 port 1812
Thu Jan 18 10:22:38 2018 : Debug: (1) Empty pre-proxy section in virtual server "itmc-wlan". Using default return values.
Thu Jan 18 10:22:38 2018 : Debug: (1) proxy: Trying to allocate ID (0/2)
Thu Jan 18 10:22:38 2018 : Debug: (1) proxy: request is now in proxy hash
Thu Jan 18 10:22:38 2018 : Debug: (1) proxy: allocating destination 129.217.197.132 port 1812 - Id 189
Thu Jan 18 10:22:38 2018 : Debug: (1) Proxying request to home server 129.217.197.132 port 1812 timeout 20.000000
Thu Jan 18 10:22:38 2018 : Debug: (1) Sent Access-Request Id 189 from 0.0.0.0:48124 to 129.217.197.132:1812 length 336
Thu Jan 18 10:22:38 2018 : Debug: (1) User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:22:38 2018 : Debug: (1) Chargeable-User-Identity = 0x00
Thu Jan 18 10:22:38 2018 : Debug: (1) Location-Capable = Civic-Location
Thu Jan 18 10:22:38 2018 : Debug: (1) Calling-Station-Id = "3c-15-c2-e8-40-fe"
Thu Jan 18 10:22:38 2018 : Debug: (1) Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Port = 1
Thu Jan 18 10:22:38 2018 : Debug: (1) Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Thu Jan 18 10:22:38 2018 : Debug: (1) Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-IP-Address = 129.217.251.242
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Identifier = "wlc-staging"
Thu Jan 18 10:22:38 2018 : Debug: (1) Airespace-Wlan-Id = 8
Thu Jan 18 10:22:38 2018 : Debug: (1) Service-Type = Framed-User
Thu Jan 18 10:22:38 2018 : Debug: (1) Framed-MTU = 1300
Thu Jan 18 10:22:38 2018 : Debug: (1) NAS-Port-Type = Wireless-802.11
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Type:0 = VLAN
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Medium-Type:0 = IEEE-802
Thu Jan 18 10:22:38 2018 : Debug: (1) Tunnel-Private-Group-Id:0 = "3503"
Thu Jan 18 10:22:38 2018 : Debug: (1) EAP-Message = 0x020200080319152b
Thu Jan 18 10:22:38 2018 : Debug: (1) State = 0x45300497000001370001020081d9c584000000000000000000000000000000100d436aee
Thu Jan 18 10:22:38 2018 : Debug: (1) Message-Authenticator = 0x31a7b8a02c1f45acee5e637c48d8f20d
Thu Jan 18 10:22:38 2018 : Debug: (1) Event-Timestamp = "Jan 18 2018 10:22:38 CET"
Thu Jan 18 10:22:38 2018 : Debug: (1) Proxy-State = 0x3639
Thu Jan 18 10:22:38 2018 : Debug: Waking up in 0.3 seconds.
Thu Jan 18 10:22:38 2018 : Debug: (1) Clearing existing &reply: attributes
Thu Jan 18 10:22:38 2018 : Debug: (1) Received Access-Reject Id 189 from 129.217.197.132:1812 to 129.217.131.207:48124 length 48
Thu Jan 18 10:22:38 2018 : Debug: (1) Proxy-State = 0x3639
Thu Jan 18 10:22:38 2018 : Debug: (1) EAP-Message = 0x04020004
Thu Jan 18 10:22:38 2018 : Debug: (1) Message-Authenticator = 0x9e213d17e11b8899c78a36353803fdad
Thu Jan 18 10:22:38 2018 : Debug: (1) # Executing section post-proxy from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:38 2018 : Debug: (1) post-proxy {
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-proxy]: calling attr_filter.post-proxy (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: %{Realm}
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: attribute --> Realm
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: EXPAND %{Realm}
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: --> rtmobil
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Matched entry rtmobil at line 17
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "Proxy-State" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "EAP-Message" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "Message-Authenticator" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Matched entry DEFAULT at line 32
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Proxy-State = 0x3639 allowed by Proxy-State =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "Proxy-State" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: EAP-Message = 0x04020004 allowed by EAP-Message =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Message-Authenticator = 0x9e213d17e11b8899c78a36353803fdad allowed by Message-Authenticator =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.post-proxy: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-proxy]: returned from attr_filter.post-proxy (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: (1) [attr_filter.post-proxy] = updated
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-proxy]: calling eap_wlan (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (1) eap_wlan: No pre-existing handler found
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-proxy]: returned from eap_wlan (rlm_eap)
Thu Jan 18 10:22:38 2018 : Debug: (1) [eap_wlan] = noop
Thu Jan 18 10:22:38 2018 : Debug: (1) } # post-proxy = updated
Thu Jan 18 10:22:38 2018 : Auth: (1) Login incorrect (Home Server says so): [rtmobilnetz at rtmobil/<no User-Password attribute>] (from client wlc-management-wism2 port 1 cli 3c-15-c2-e8-40-fe)
Thu Jan 18 10:22:38 2018 : Debug: (1) Using Post-Auth-Type Reject
Thu Jan 18 10:22:38 2018 : Debug: (1) # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:22:38 2018 : Debug: (1) Post-Auth-Type REJECT {
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: %{User-Name}
Thu Jan 18 10:22:38 2018 : Debug: Parsed xlat tree:
Thu Jan 18 10:22:38 2018 : Debug: attribute --> User-Name
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: EXPAND %{User-Name}
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: --> rtmobilnetz at rtmobil
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Matched entry DEFAULT at line 11
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Private-Group-Id" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Type" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Attribute "Tunnel-Medium-Type" allowed by 0 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: EAP-Message = 0x04020004 allowed by EAP-Message =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Message-Authenticator = 0x9e213d17e11b8899c78a36353803fdad allowed by Message-Authenticator =* 0x
Thu Jan 18 10:22:38 2018 : Debug: (1) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Thu Jan 18 10:22:38 2018 : Debug: (1) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter)
Thu Jan 18 10:22:38 2018 : Debug: (1) [attr_filter.access_reject] = updated
Thu Jan 18 10:22:38 2018 : Debug: (1) } # Post-Auth-Type REJECT = updated
Thu Jan 18 10:22:38 2018 : Auth: (1) Login incorrect: [rtmobilnetz at rtmobil/<no User-Password attribute>] (from client wlc-management-wism2 port 1 cli 3c-15-c2-e8-40-fe)
Thu Jan 18 10:22:38 2018 : Debug: (1) Delaying response for 1.000000 seconds
Thu Jan 18 10:22:38 2018 : Debug: Waking up in 0.3 seconds.
Thu Jan 18 10:22:38 2018 : Debug: Waking up in 0.6 seconds.
Thu Jan 18 10:22:39 2018 : Debug: (1) Sending delayed response
Thu Jan 18 10:22:39 2018 : Debug: (1) Sent Access-Reject Id 69 from 129.217.131.207:1812 to 129.217.251.242:32775 length 44
Thu Jan 18 10:22:39 2018 : Debug: (1) EAP-Message = 0x04020004
Thu Jan 18 10:22:39 2018 : Debug: (1) Message-Authenticator = 0x9e213d17e11b8899c78a36353803fdad
Thu Jan 18 10:22:39 2018 : Debug: Waking up in 3.9 seconds.
Thu Jan 18 10:22:43 2018 : Debug: (0) Cleaning up request packet ID 68 with timestamp +50
Thu Jan 18 10:22:43 2018 : Debug: (1) Cleaning up request packet ID 69 with timestamp +51
Thu Jan 18 10:22:43 2018 : Info: Ready to process requests
Debug freeradius 2 - proxy to home server - ok
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=56, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020100180172746d6f62696c6e65747a4072746d6f62696c
Message-Authenticator = 0x5ad647c1cb63e15f0ab31291f47480c0
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 1 length 24
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] No EAP Start, assuming it's an on-going EAP conversation
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = updated
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{Stripped-User-Name} ->
Thu Jan 18 10:08:43 2018 : Info: [sql] ... expanding second conditional
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{User-Name} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] sql_set_user escaped user --> 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Reserving sql socket id: 9
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Released sql socket id: 9
Thu Jan 18 10:08:43 2018 : Info: [sql] User rtmobilnetz at rtmobil not found
Thu Jan 18 10:08:43 2018 : Info: ++[sql] = notfound
Thu Jan 18 10:08:43 2018 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this.
Thu Jan 18 10:08:43 2018 : Info: ++[pap] = noop
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = updated
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP Identity
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type tls
Thu Jan 18 10:08:43 2018 : Info: [tls] Initiate
Thu Jan 18 10:08:43 2018 : Info: [tls] Start returned 1
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 56 to 129.217.251.242 port 32775
EAP-Message = 0x010200061920
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3c9abea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 0.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=57, length=459
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020200a119800000009716030100920100008e03035a60641b5a6d658e034c219ee9a5b5eb3ef0afc88ffa56e0d6ff9b11f476954200002c00ffc02cc02bc024c023c00ac009c008c030c02fc028c027c014c013c012009d009c003d003c0035002f000a01000039000a00080006001700180019000b00020100000d00120010040102010501060104030203050306030005000501000000000012000000170000
State = 0x3c98a70a3c9abea1f795a66daa110d86
Message-Authenticator = 0xb55b58648c6498496af46a597e0a274d
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 2 length 161
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Debug: TLS Length 151
Thu Jan 18 10:08:43 2018 : Info: [peap] Length Included
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 11
Thu Jan 18 10:08:43 2018 : Info: [peap] (other): before/accept initialization
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: before/accept initialization
Thu Jan 18 10:08:43 2018 : Info: [peap] <<< Unknown TLS version [length 0092]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 read client hello A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 0039]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write server hello A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 0f5c]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write certificate A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 014d]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write key exchange A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 0004]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write server done A
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 flush data
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Jan 18 10:08:43 2018 : Debug: In SSL Handshake Phase
Thu Jan 18 10:08:43 2018 : Debug: In SSL Accept mode
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 57 to 129.217.251.242 port 32775
EAP-Message = 0x0103040019c0000010fa160303003902000035030335833298b504c882c4f7664bb0d5607a607b72eb3fdcef219a99bfeb9eb8809200c03000000dff01000100000b0004030001021603030f5c0b000f58000f5500060530820601308204e9a003020102020c1c4a3f94e98ce7fd9b7d977a300d06092a864886f70d01010b050030818c310b300906035504061302444531293027060355040a1320546563686e697363686520556e6976657273697461657420446f72746d756e64310d300b060355040b130449544d43311d301b06035504031314545520446f72746d756e64204341202d204730313124302206092a864886f70d01090116156361
EAP-Message = 0x40706b692e74752d646f72746d756e642e6465301e170d3136313131353038303632385a170d3139303730393233353930305a30818a310b3009060355040613024445311c301a06035504080c134e6f7264726865696e2d5765737466616c656e3111300f06035504070c08446f72746d756e6431293027060355040a0c20546563686e697363686520556e6976657273697461657420446f72746d756e64311f301d06035504030c16726164697573332e74752d646f72746d756e642e646530820122300d06092a864886f70d01010105000382010f003082010a0282010100dd8a4902370c77cbd05b13a4776f4907ca8b3b69b42df0e5d6c462dc
EAP-Message = 0xf5986b4e19bddf06b87e3e181d9320a1575d75070b44f957ec04c3cf4e50046f475d0c5b2eb170163b62ca2938426a5e2cc4282cfa9bc3a992eacf1a76c889a738b748a975e963b65e405ad99bb87605bccdd17ed33662966650f99069cc6fdb18ec9bcf306262578561ad48c472e593115ec42e8039469f6fe7aaffc2ec0b5b17402898867461d2e18dbf9d60d2b14d98dfd493227eaaf0272c7fab98ecb884b9f1f13cbca1f0be411f79f99b016af926d6471d9fb255370ec228902f0417d3770d0eda4d767d3d8418b7d2636f915cd6488df2bcb9aae0dbec38a0e2a69b6faff75a4d0203010001a38202613082025d30590603551d200452305030
EAP-Message = 0x11060f2b0601040181ad21822c01010403053011060f2b0601040181ad21822c0201040301300f060d2b0601040181ad21822c010104300d060b2b0601040181ad21822c1e3008060667810c01020230090603551d1304023000300e0603551d0f0101ff0404030205a0301d0603551d250416301406082b0601050507030206082b06010505070301301d0603551d0e041604149ddf5679d261d42c116d7dca1e23d317515bef82301f0603551d23041830168014fbb15c9b6de825e4a9aa3244ef0283450de606ec30210603551d11041a30188216726164697573332e74752d646f72746d756e642e64653081880603551d1f048180307e303da03b
EAP-Message = 0xa0398637687474703a2f2f63
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3d9bbea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 1.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=58, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020300061900
State = 0x3c98a70a3d9bbea1f795a66daa110d86
Message-Authenticator = 0x9d83a317c6e1bf62ee7c76cda9726457
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 3 length 6
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] Received TLS ACK
Thu Jan 18 10:08:43 2018 : Info: [peap] ACK handshake fragment handler
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 1
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 58 to 129.217.251.242 port 32775
EAP-Message = 0x010403fc19406470312e7063612e64666e2e64652f74752d646f72746d756e642d63612f7075622f63726c2f636163726c2e63726c303da03ba0398637687474703a2f2f636470322e7063612e64666e2e64652f74752d646f72746d756e642d63612f7075622f63726c2f636163726c2e63726c3081d706082b060105050701010481ca3081c7303306082b060105050730018627687474703a2f2f6f6373702e7063612e64666e2e64652f4f4353502d5365727665722f4f435350304706082b06010505073002863b687474703a2f2f636470312e7063612e64666e2e64652f74752d646f72746d756e642d63612f7075622f6361636572742f6361
EAP-Message = 0x636572742e637274304706082b06010505073002863b687474703a2f2f636470322e7063612e64666e2e64652f74752d646f72746d756e642d63612f7075622f6361636572742f6361636572742e637274300d06092a864886f70d01010b05000382010100bcbf44bca0f8dd220f4e82ee83cca847bdd8b5e22a5a02144ac9674ee1983bc6ce8fd48f9dcc095ea0ebccedb22136742485de7ebf0d13ca9761e7e0e659bee28788eaaad69db87fae62b54d15bca9b999c0a4a4580af1100b9c43977d86b74fdfcb8dc08f2010af8a5bd55403c68d7acbe153b7b98badeefc8d9fdf4c1511a5479823f2c8eaa8c69e39a95bd2a68d9460bfe162d0d99578
EAP-Message = 0xeb0652818a7a01620389b664eb78c71855ff50c95563b66a9ba50a20d021eefa295ea64e23e48bdeaa81ae08fc23ba05da989ff4b2ac579208adace73c2ed62ce116cf7db32635a10a78be707463680873caf22f5867461820a16e54ca71b1bf993d965d698e30120005223082051e30820406a00302010202040c438cd5300d06092a864886f70d0101050500305a310b300906035504061302444531133011060355040a130a44464e2d56657265696e3110300e060355040b130744464e2d504b49312430220603550403131b44464e2d56657265696e2050434120476c6f62616c202d20473031301e170d3038303530393038343535385a170d31
EAP-Message = 0x39303633303030303030305a30818c310b300906035504061302444531293027060355040a1320546563686e697363686520556e6976657273697461657420446f72746d756e64310d300b060355040b130449544d43311d301b06035504031314545520446f72746d756e64204341202d204730313124302206092a864886f70d0109011615636140706b692e74752d646f72746d756e642e646530820122300d06092a864886f70d01010105000382010f003082010a0282010100f4ba0476ee5a973fb8ae918abd1f22165fe77137645b220be30e687170303370e48a254f64a9f7ed2f97800e03caa7270c5c33780b7acdcd83c161cb76532df6a7
EAP-Message = 0x38c8f3956c305740
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3e9cbea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 2.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=59, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020400061900
State = 0x3c98a70a3e9cbea1f795a66daa110d86
Message-Authenticator = 0xc9e8ba6e82ff9ee3f60b4ac4f198b861
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 4 length 6
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] Received TLS ACK
Thu Jan 18 10:08:43 2018 : Info: [peap] ACK handshake fragment handler
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 1
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 59 to 129.217.251.242 port 32775
EAP-Message = 0x010503fc19409befa84e1efc913c27d239cf8c37a388dfe7282d6b6f8f089ff8ee47cd3e8d6ca3e4441e4c22823f5292f81e11312fb39dfdf2191696a4138d716cb57e750810a46c2b4135218ae72bbb9cb59d956fc2cb5451111e7b78f41690757257ad1aadaeaa35533e90c635a49ee20f0ba7023eea5214c02756fc3010d976c7f3a8401d23b28d3204cf423011c3554046dc1645578693b195826cab728f4b09e00f73aff9423d09a598ad3b55128b589e01262b6b37a0429e70b90203010001a38201b7308201b330120603551d130101ff040830060101ff020101300b0603551d0f040403020106301d0603551d0e04160414fbb15c9b6de825
EAP-Message = 0xe4a9aa3244ef0283450de606ec301f0603551d2304183016801449b7c6cfe83d1f7fea447b1329f7f10a703ede6430200603551d11041930178115636140706b692e74752d646f72746d756e642e64653081880603551d1f048180307e303da03ba0398637687474703a2f2f636470312e7063612e64666e2e64652f676c6f62616c2d726f6f742d63612f7075622f63726c2f636163726c2e63726c303da03ba0398637687474703a2f2f636470322e7063612e64666e2e64652f676c6f62616c2d726f6f742d63612f7075622f63726c2f636163726c2e63726c3081a206082b06010505070101048195308192304706082b06010505073002863b68
EAP-Message = 0x7474703a2f2f636470312e7063612e64666e2e64652f676c6f62616c2d726f6f742d63612f7075622f6361636572742f6361636572742e637274304706082b06010505073002863b687474703a2f2f636470322e7063612e64666e2e64652f676c6f62616c2d726f6f742d63612f7075622f6361636572742f6361636572742e637274300d06092a864886f70d010105050003820101004d463fdb53b4543fb01bd22fe95aeffe713d7a179cbf2797df89f6a32900779cd69a0fba5c6aced8c4dbcf5ccb53b81e44ac02f0fc397cadd9203b15d6fff9abade6666b9b5a74b68e2624ebfc170b0ac7de9c7375318972421bef5d8893edb41f213eab19de
EAP-Message = 0x5786d31c288355fb77e0f260ab70c5f4fe4257adf97b00e3291dea65acaf6e6122162087cee95f23214cdaa865c124f130e6e4f2532bd94bbbc10c10cfe61a89df0c1efec34181adeffc64da4d8250abd4d054997700ea7b70acdb7d072ed2c0d3ca9e4efeece28a06993d9b4296500f556e9b930e2df0e27e91c9c9a8ae115746a6d75b3845055fcd1b0c6bf36ad0c2d4faba2ca110bb0e74ee0004253082042130820309a003020102020200c7300d06092a864886f70d01010505003071310b3009060355040613024445311c301a060355040a131344657574736368652054656c656b6f6d204147311f301d060355040b1316542d54656c655365
EAP-Message = 0x6320547275737420
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3f9dbea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 3.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=60, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020500061900
State = 0x3c98a70a3f9dbea1f795a66daa110d86
Message-Authenticator = 0x0083688d4095e4f4232e1488fda2798e
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 5 length 6
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] Received TLS ACK
Thu Jan 18 10:08:43 2018 : Info: [peap] ACK handshake fragment handler
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 1
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 60 to 129.217.251.242 port 32775
EAP-Message = 0x010603fc194043656e746572312330210603550403131a44657574736368652054656c656b6f6d20526f6f742043412032301e170d3036313231393130323930305a170d3139303633303233353930305a305a310b300906035504061302444531133011060355040a130a44464e2d56657265696e3110300e060355040b130744464e2d504b49312430220603550403131b44464e2d56657265696e2050434120476c6f62616c202d2047303130820122300d06092a864886f70d01010105000382010f003082010a0282010100e99bc36785f90daef58d54c39650353d62e96e4ced94d7005b952274d420eb348fd6ecc031040b9981e2a614d252a0
EAP-Message = 0x2823848b7489045e5be0e278c178cb16cb2835397b2d9045d0eda0007a7cbf4a0e1b00c386e95c2b31117b0cf38224438c1c388b6a68009aeedc4f78abd2c6139b76adeede26e8ef01af740fc109a2f66bcebdd3cd14304ff5e5e3a4c8629b821a0327300d0265604dedd109232a96355827d376c671b6901dc4edff35867d6f33b3db0fc511c28a83a1945d416bd8d210f54cfdca51acd9bdef9283bbdaeb8b16565643cfe1d5133da61f2730cd4954dbc913349a7175c56ceaa70b98f9219d27af3ea33939486a8cadc999fbc312f2bd0203010001a381d93081d630700603551d1f046930673065a063a061865f687474703a2f2f706b692e74656c
EAP-Message = 0x657365632e64652f6367692d62696e2f736572766963652f61665f446f776e6c6f616441524c2e63726c3f2d63726c5f666f726d61743d585f353039262d6973737565723d44545f524f4f545f43415f32301d0603551d0e0416041449b7c6cfe83d1f7fea447b1329f7f10a703ede64301f0603551d2304183016801431c3791bbaf553d717e0897a2d176c0ab32b9d33300e0603551d0f0101ff04040302010630120603551d130101ff040830060101ff020102300d06092a864886f70d010105050003820101003be15a77c04817dca918ec81af5a89f0bd2892a6ca59181270ec28f2e7ae7f962ce7f25d1931f6132b74bdbd80b2b9f767c939a2
EAP-Message = 0x793be11111ee6b7891337e3b5f26277553658e3363eecf73c3b092234921507523a11f18e294853d3f33e977208da2bde6a1852940f63f7332580d096ba6da856cc03fbb8d666456244eae0d3f3235015be98c82d972594fb18685f1748556e5c3f85cf38dee47b3530570e7e54d8a698328e11309869e5ec8ea581e0c1ff9a4d45a0468fd283e8b02b658b5f6a12c37570067ab23688d63a5ef996b5cfd4b56f6ab408734d411926cec87c50a0b073372b46f0c1d542cd851c7ccbf30d34372f132bf8cce4963a800f7f21c160303014d0c000149030017410453131d6ba785c86860bfe67949a93cf5d860d6e5d46e5b3577917dc2426666e4dde09f
EAP-Message = 0xcf3ba7dc467abd28
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a389ebea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 4.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=61, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020600061900
State = 0x3c98a70a389ebea1f795a66daa110d86
Message-Authenticator = 0x5a61790459d1d162d38ceb815f045035
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 6 length 6
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] Received TLS ACK
Thu Jan 18 10:08:43 2018 : Info: [peap] ACK handshake fragment handler
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 1
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 61 to 129.217.251.242 port 32775
EAP-Message = 0x010701281900354f9c32064ed9e7d5e75c44b763b1511472eba320040101005c31aa28b4dbb9d01a95e3db398a72ce00754dc61ed011edd7c98bbe879e3e7bf20824fdf369fd8e5f5ec25fe3c3a8d2d84f50fc266c9be94e565f7fea379c03babc658a90f655a9bca8c96e97f8bd2adc108a60e3eda86058e0bdd3079b83a8f9ab854e66311ae8278acedc726537083f2350d5e8de48159547c2779406d4c384a9f2da77df9427e9c84a0f2de42f771ca63516035eb439acfa75a276ca016e0969d0a7d320bc74fd4bef2ffac9d59676436ac57fc552bc1b6cc38f7f0cc3f1f8f30dbe89f8a50dd8a97082eabf67fe2ec697d8fb55feb2e43496960d7e
EAP-Message = 0x03af69b4f875ad58a7590939f8d1d9d158c4a2b73868fb3a589c6f06e10dc168959816030300040e000000
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a399fbea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 5.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=62, length=434
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x0207008819800000007e16030300461000004241040b0ab49ba3325dfdaf81cd8bdd72b1a2d493fa6d7b9d93b17d6b05342febbdaef9eb2f310dc4d1287ba6cf71371d6b3e8bb798706401ca980310ce47ee42b8d714030300010116030300288c46983303f6f502b347d4709551ff636ad157dbe449cf43c973cfaaf4bd3ef7ad265753ddc4cead
State = 0x3c98a70a399fbea1f795a66daa110d86
Message-Authenticator = 0x171ae347783220465e00e196b1a9e966
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 7 length 136
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Debug: TLS Length 126
Thu Jan 18 10:08:43 2018 : Info: [peap] Length Included
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 11
Thu Jan 18 10:08:43 2018 : Info: [peap] <<< Unknown TLS version [length 0046]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 read client key exchange A
Thu Jan 18 10:08:43 2018 : Info: [peap] <<< Unknown TLS version [length 0001]
Thu Jan 18 10:08:43 2018 : Info: [peap] <<< Unknown TLS version [length 0010]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 read finished A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 0001]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write change cipher spec A
Thu Jan 18 10:08:43 2018 : Info: [peap] >>> Unknown TLS version [length 0010]
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 write finished A
Thu Jan 18 10:08:43 2018 : Info: [peap] TLS_accept: SSLv3 flush data
Thu Jan 18 10:08:43 2018 : Info: [peap] (other): SSL negotiation finished successfully
Thu Jan 18 10:08:43 2018 : Debug: SSL Connection Established
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 13
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_HANDLED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 62 to 129.217.251.242 port 32775
EAP-Message = 0x01080039190014030300010116030300288ba36faaaa8eca19b9006ddf468af903754172914f3e754614f283fa0cd9357f8aa05da2a0e52f22
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3a90bea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 6.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=63, length=304
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020800061900
State = 0x3c98a70a3a90bea1f795a66daa110d86
Message-Authenticator = 0x56b73b5f66b4b80486760fde696d339f
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 8 length 6
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] Received TLS ACK
Thu Jan 18 10:08:43 2018 : Info: [peap] ACK handshake is finished
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 3
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 3
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_SUCCESS
Thu Jan 18 10:08:43 2018 : Info: [peap] Session established. Decoding tunneled attributes.
Thu Jan 18 10:08:43 2018 : Info: [peap] Peap state TUNNEL ESTABLISHED
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 63 to 129.217.251.242 port 32775
EAP-Message = 0x010900281900170303001d8ba36faaaa8eca1a0d5899d2c8a1e69049e71bee2e03f50c593b8a0226
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3b91bea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 7.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=64, length=353
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020900371900170303002c8c46983303f6f503d71c1b48c58a7b0cc5a3b787a602127e5cc5077cfe572c8874d79ade89d7db1df5151a4c
State = 0x3c98a70a3b91bea1f795a66daa110d86
Message-Authenticator = 0xda187bab0fe1c2184182fca00c1cb5bd
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 9 length 55
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] Done initial handshake
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_OK
Thu Jan 18 10:08:43 2018 : Info: [peap] Session established. Decoding tunneled attributes.
Thu Jan 18 10:08:43 2018 : Info: [peap] Peap state WAITING FOR INNER IDENTITY
Thu Jan 18 10:08:43 2018 : Info: [peap] Identity - rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [peap] Got inner identity 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Info: [peap] Setting default EAP type for tunneled EAP session.
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled request
EAP-Message = 0x020900180172746d6f62696c6e65747a4072746d6f62696c
server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: [peap] Setting User-Name to rtmobilnetz at rtmobil
Sending tunneled request
EAP-Message = 0x020900180172746d6f62696c6e65747a4072746d6f62696c
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
server inner-wlan-peap {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [suffix] Looking up realm "rtmobil" for User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Found realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Adding Realm = "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Proxying request from user rtmobilnetz to realm rtmobil
Thu Jan 18 10:08:43 2018 : Info: [suffix] Preparing to proxy authentication request to realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: ++[suffix] = updated
Thu Jan 18 10:08:43 2018 : Info: ++[mschap] = noop
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request is supposed to be proxied to Realm rtmobil. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = noop
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{Stripped-User-Name} ->
Thu Jan 18 10:08:43 2018 : Info: [sql] ... expanding second conditional
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{User-Name} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] sql_set_user escaped user --> 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Reserving sql socket id: 8
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Released sql socket id: 8
Thu Jan 18 10:08:43 2018 : Info: [sql] User rtmobilnetz at rtmobil not found
Thu Jan 18 10:08:43 2018 : Info: ++[sql] = notfound
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:wlan-NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:wlan-NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++update config {
Thu Jan 18 10:08:43 2018 : Info: +++} # update config = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:wlan-NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++ ... skipping else for request 8: Preceding "if" was taken
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++[expiration] = noop
Thu Jan 18 10:08:43 2018 : Info: ++[logintime] = noop
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = updated
} # server inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled reply code 0
Thu Jan 18 10:08:43 2018 : Debug: PEAP: Tunneled authentication will be proxied to rtmobil
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Tunneled session will be proxied. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: WARNING: Empty pre-proxy section. Using default return values.
Sending Access-Request of id 22 to 129.217.197.132 port 1812
EAP-Message = 0x020900180172746d6f62696c6e65747a4072746d6f62696c
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3634
Thu Jan 18 10:08:43 2018 : Info: Proxying request 8 to home server 129.217.197.132 port 1812
Sending Access-Request of id 22 to 129.217.197.132 port 1812
EAP-Message = 0x020900180172746d6f62696c6e65747a4072746d6f62696c
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3634
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Challenge packet from host 129.217.197.132 port 1812, id=22, length=124
Proxy-State = 0x3634
Session-Timeout = 60
EAP-Message = 0x010a00241a010a001f108ab94c4fc3267e8169cea1d199664752504f4f4c2d4144533031
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Message-Authenticator = 0xbd9d88907cf10737d8c053c498a8673a
Thu Jan 18 10:08:43 2018 : Info: # Executing section post-proxy from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group post-proxy {
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %{Packet-Src-IP-Address} -> 129.217.251.242
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d -> /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %t -> Thu Jan 18 10:08:43 2018
Thu Jan 18 10:08:43 2018 : Info: ++[post_proxy_log] = ok
Thu Jan 18 10:08:43 2018 : Info: [attr_filter.post-proxy] expand: %{Realm} -> rtmobil
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry rtmobil at line 17
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry DEFAULT at line 32
Thu Jan 18 10:08:43 2018 : Info: ++[attr_filter.post-proxy] = updated
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Doing post-proxy callback
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Passing reply from proxy back into the tunnel.
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Got tunneled reply RADIUS code Access-Challenge
Tunnel-Private-Group-Id:0 := "26"
Tunnel-Type:0 := VLAN
Tunnel-Medium-Type:0 := IEEE-802
Proxy-State = 0x3634
EAP-Message = 0x010a00241a010a001f108ab94c4fc3267e8169cea1d199664752504f4f4c2d4144533031
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Message-Authenticator = 0xbd9d88907cf10737d8c053c498a8673a
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Got tunneled Access-Challenge
PEAP tunnel data out 0000: 1a 01 0a 00 1f 10 8a b9 4c 4f c3 26 7e 81 69 ce
PEAP tunnel data out 0010: a1 d1 99 66 47 52 50 4f 4f 4c 2d 41 44 53 30 31
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Reply was handled
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group post-proxy = updated
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 64 to 129.217.251.242 port 32775
EAP-Message = 0x010a0043190017030300388ba36faaaa8eca1b8ac205e1a35087ef050e5c1d41dff46abfb7964e17243d093c486c809fee94f43c644e5dd597b5fe68bb464e8a868ef1
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3492bea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 8.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=65, length=407
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020a006d190017030300628c46983303f6f504750b0f900c8378e551f1bd944e1c82f4bf52fd9269af5e9fcec96df83d0ac713ca6a69f2ea788cf44316296588be7882456b509376840d03cb08346088231b9f691f35065490d2951b949ac0f7ec1640c4d7893f230bdeb61795
State = 0x3c98a70a3492bea1f795a66daa110d86
Message-Authenticator = 0x3d925e61fc134337fdcf31e32530c77a
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 10 length 109
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] Done initial handshake
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_OK
Thu Jan 18 10:08:43 2018 : Info: [peap] Session established. Decoding tunneled attributes.
Thu Jan 18 10:08:43 2018 : Info: [peap] Peap state phase2
Thu Jan 18 10:08:43 2018 : Info: [peap] EAP type mschapv2
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled request
EAP-Message = 0x020a004e1a020a004931e961cd1959c9c3069bf68107e3a510f60000000000000000466bda68b9093af3824d2e4aa0ad5230cf96900a181daacb0072746d6f62696c6e65747a4072746d6f62696c
server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: [peap] Setting User-Name to rtmobilnetz at rtmobil
Sending tunneled request
EAP-Message = 0x020a004e1a020a004931e961cd1959c9c3069bf68107e3a510f60000000000000000466bda68b9093af3824d2e4aa0ad5230cf96900a181daacb0072746d6f62696c6e65747a4072746d6f62696c
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
server inner-wlan-peap {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [suffix] Looking up realm "rtmobil" for User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Found realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Adding Realm = "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Proxying request from user rtmobilnetz to realm rtmobil
Thu Jan 18 10:08:43 2018 : Info: [suffix] Preparing to proxy authentication request to realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: ++[suffix] = updated
Thu Jan 18 10:08:43 2018 : Info: ++[mschap] = noop
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request is supposed to be proxied to Realm rtmobil. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = noop
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{Stripped-User-Name} ->
Thu Jan 18 10:08:43 2018 : Info: [sql] ... expanding second conditional
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{User-Name} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] sql_set_user escaped user --> 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Reserving sql socket id: 7
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Released sql socket id: 7
Thu Jan 18 10:08:43 2018 : Info: [sql] User rtmobilnetz at rtmobil not found
Thu Jan 18 10:08:43 2018 : Info: ++[sql] = notfound
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:wlan-NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:wlan-NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++update config {
Thu Jan 18 10:08:43 2018 : Info: +++} # update config = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:wlan-NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++ ... skipping else for request 9: Preceding "if" was taken
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++[expiration] = noop
Thu Jan 18 10:08:43 2018 : Info: ++[logintime] = noop
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = updated
} # server inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled reply code 0
Thu Jan 18 10:08:43 2018 : Debug: PEAP: Tunneled authentication will be proxied to rtmobil
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Tunneled session will be proxied. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: WARNING: Empty pre-proxy section. Using default return values.
Sending Access-Request of id 220 to 129.217.197.132 port 1812
EAP-Message = 0x020a004e1a020a004931e961cd1959c9c3069bf68107e3a510f60000000000000000466bda68b9093af3824d2e4aa0ad5230cf96900a181daacb0072746d6f62696c6e65747a4072746d6f62696c
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3635
Thu Jan 18 10:08:43 2018 : Info: Proxying request 9 to home server 129.217.197.132 port 1812
Sending Access-Request of id 220 to 129.217.197.132 port 1812
EAP-Message = 0x020a004e1a020a004931e961cd1959c9c3069bf68107e3a510f60000000000000000466bda68b9093af3824d2e4aa0ad5230cf96900a181daacb0072746d6f62696c6e65747a4072746d6f62696c
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3635
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Challenge packet from host 129.217.197.132 port 1812, id=220, length=139
Proxy-State = 0x3635
Session-Timeout = 60
EAP-Message = 0x010b00331a030a002e533d34434246433531333243453236433136363037353236333245394632363041453232383536433233
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Message-Authenticator = 0x008aa898c0a1141888fe6cf38f403101
Thu Jan 18 10:08:43 2018 : Info: # Executing section post-proxy from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group post-proxy {
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %{Packet-Src-IP-Address} -> 129.217.251.242
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d -> /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %t -> Thu Jan 18 10:08:43 2018
Thu Jan 18 10:08:43 2018 : Info: ++[post_proxy_log] = ok
Thu Jan 18 10:08:43 2018 : Info: [attr_filter.post-proxy] expand: %{Realm} -> rtmobil
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry rtmobil at line 17
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry DEFAULT at line 32
Thu Jan 18 10:08:43 2018 : Info: ++[attr_filter.post-proxy] = updated
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Doing post-proxy callback
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Passing reply from proxy back into the tunnel.
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Got tunneled reply RADIUS code Access-Challenge
Tunnel-Private-Group-Id:0 := "26"
Tunnel-Type:0 := VLAN
Tunnel-Medium-Type:0 := IEEE-802
Proxy-State = 0x3635
EAP-Message = 0x010b00331a030a002e533d34434246433531333243453236433136363037353236333245394632363041453232383536433233
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Message-Authenticator = 0x008aa898c0a1141888fe6cf38f403101
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Got tunneled Access-Challenge
PEAP tunnel data out 0000: 1a 03 0a 00 2e 53 3d 34 43 42 46 43 35 31 33 32
PEAP tunnel data out 0010: 43 45 32 36 43 31 36 36 30 37 35 32 36 33 32 45
PEAP tunnel data out 0020: 39 46 32 36 30 41 45 32 32 38 35 36 43 32 33
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Reply was handled
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group post-proxy = updated
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 65 to 129.217.251.242 port 32775
EAP-Message = 0x010b0052190017030300478ba36faaaa8eca1c5c5759b9c4c249a64a66cdc97de32775882db10c9df3f622659db59e7bd86ab63e249e5260034ed209f549ae3e30898ec036c7017be62a9440c1b340de7ac6
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3593bea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 9.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=66, length=335
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020b00251900170303001a8c46983303f6f5052f75f8c24f8c2830b62c9232dd5ca34fbf18
State = 0x3c98a70a3593bea1f795a66daa110d86
Message-Authenticator = 0x0a34052605c5c33ebd93eb14d44f4c81
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 11 length 37
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] Done initial handshake
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_OK
Thu Jan 18 10:08:43 2018 : Info: [peap] Session established. Decoding tunneled attributes.
Thu Jan 18 10:08:43 2018 : Info: [peap] Peap state phase2
Thu Jan 18 10:08:43 2018 : Info: [peap] EAP type mschapv2
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled request
EAP-Message = 0x020b00061a03
server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: [peap] Setting User-Name to rtmobilnetz at rtmobil
Sending tunneled request
EAP-Message = 0x020b00061a03
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
server inner-wlan-peap {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [suffix] Looking up realm "rtmobil" for User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Found realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Adding Realm = "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: [suffix] Proxying request from user rtmobilnetz to realm rtmobil
Thu Jan 18 10:08:43 2018 : Info: [suffix] Preparing to proxy authentication request to realm "rtmobil"
Thu Jan 18 10:08:43 2018 : Info: ++[suffix] = updated
Thu Jan 18 10:08:43 2018 : Info: ++[mschap] = noop
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request is supposed to be proxied to Realm rtmobil. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = noop
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{Stripped-User-Name} ->
Thu Jan 18 10:08:43 2018 : Info: [sql] ... expanding second conditional
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{User-Name} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> rtmobilnetz at rtmobil
Thu Jan 18 10:08:43 2018 : Info: [sql] sql_set_user escaped user --> 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Reserving sql socket id: 6
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'rtmobilnetz at rtmobil' ORDER BY id
Thu Jan 18 10:08:43 2018 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql_mysql: query: SELECT groupname FROM radusergroup WHERE username = 'rtmobilnetz at rtmobil' ORDER BY priority
Thu Jan 18 10:08:43 2018 : Debug: rlm_sql (sql): Released sql socket id: 6
Thu Jan 18 10:08:43 2018 : Info: [sql] User rtmobilnetz at rtmobil not found
Thu Jan 18 10:08:43 2018 : Info: ++[sql] = notfound
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:wlan-NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:wlan-NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:wlan-NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++update config {
Thu Jan 18 10:08:43 2018 : Info: +++} # update config = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:wlan-NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++ ... skipping else for request 10: Preceding "if" was taken
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "")
Thu Jan 18 10:08:43 2018 : Info: expand: %{check:NT-Password} ->
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++? if ("%{check:NT-Password}" == "") -> TRUE
Thu Jan 18 10:08:43 2018 : Info: ++if ("%{check:NT-Password}" == "") {
Thu Jan 18 10:08:43 2018 : Info: +++[noop] = noop
Thu Jan 18 10:08:43 2018 : Info: ++} # if ("%{check:NT-Password}" == "") = noop
Thu Jan 18 10:08:43 2018 : Info: ++[expiration] = noop
Thu Jan 18 10:08:43 2018 : Info: ++[logintime] = noop
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = updated
} # server inner-wlan-peap
Thu Jan 18 10:08:43 2018 : Info: [peap] Got tunneled reply code 0
Thu Jan 18 10:08:43 2018 : Debug: PEAP: Tunneled authentication will be proxied to rtmobil
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Tunneled session will be proxied. Not doing EAP.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = handled
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = handled
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: WARNING: Empty pre-proxy section. Using default return values.
Sending Access-Request of id 38 to 129.217.197.132 port 1812
EAP-Message = 0x020b00061a03
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3636
Thu Jan 18 10:08:43 2018 : Info: Proxying request 10 to home server 129.217.197.132 port 1812
Sending Access-Request of id 38 to 129.217.197.132 port 1812
EAP-Message = 0x020b00061a03
User-Name = "rtmobilnetz at rtmobil"
State = 0x452f0496000001370001020081d9c584000000000000000000000000000000100d436aed
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
Message-Authenticator = 0x00000000000000000000000000000000
Proxy-State = 0x3636
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 0.9 seconds.
rad_recv: Access-Accept packet from host 129.217.197.132 port 1812, id=38, length=280
Proxy-State = 0x3636
Framed-Protocol = PPP
Service-Type = Framed-User
EAP-Message = 0x030b0004
Class = 0x897b06ee000001370001020081d9c58400000000000000000000000001d38f9bbe093fef000000000000001c
MS-Link-Utilization-Threshold = 50
MS-Link-Drop-Time-Limit = 120
MS-CHAP-Domain = "\001RETINA"
HERE 3420
HERE 3448
HERE 3467
MS-MPPE-Send-Key = 0xf344120d1add5d94421ab104cb34ed37
HERE 3420
HERE 3448
HERE 3467
MS-MPPE-Recv-Key = 0xf21c3293252983303b6cbcf1bcbb3333
MS-CHAP2-Success = 0x01533d34434246433531333243453236433136363037353236333245394632363041453232383536433233
Message-Authenticator = 0x6cd828d98d8401d1f6f09b67e94c212a
Thu Jan 18 10:08:43 2018 : Info: # Executing section post-proxy from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group post-proxy {
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %{Packet-Src-IP-Address} -> 129.217.251.242
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d -> /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /var/log/freeradius/radacct/129.217.251.242/post-proxy-detail-20180118
Thu Jan 18 10:08:43 2018 : Info: [post_proxy_log] expand: %t -> Thu Jan 18 10:08:43 2018
Thu Jan 18 10:08:43 2018 : Info: ++[post_proxy_log] = ok
Thu Jan 18 10:08:43 2018 : Info: [attr_filter.post-proxy] expand: %{Realm} -> rtmobil
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry rtmobil at line 17
Thu Jan 18 10:08:43 2018 : Debug: attr_filter: Matched entry DEFAULT at line 32
Thu Jan 18 10:08:43 2018 : Info: ++[attr_filter.post-proxy] = updated
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Doing post-proxy callback
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Passing reply from proxy back into the tunnel.
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Got tunneled reply RADIUS code Access-Accept
Tunnel-Private-Group-Id:0 := "26"
Tunnel-Type:0 := VLAN
Tunnel-Medium-Type:0 := IEEE-802
Proxy-State = 0x3636
EAP-Message = 0x030b0004
MS-MPPE-Send-Key = 0xf344120d1add5d94421ab104cb34ed37
MS-MPPE-Recv-Key = 0xf21c3293252983303b6cbcf1bcbb3333
Message-Authenticator = 0x6cd828d98d8401d1f6f09b67e94c212a
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Tunneled authentication was successful.
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] SUCCESS
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Saving tunneled attributes for later
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Reply was handled
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group post-proxy = updated
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = Accept
Thu Jan 18 10:08:43 2018 : Error: Warning: Found 2 auth-types on request for user 'rtmobilnetz at rtmobil'
Thu Jan 18 10:08:43 2018 : Info: Auth-Type = Accept, accepting the user
Thu Jan 18 10:08:43 2018 : Auth: Login OK: [rtmobilnetz at rtmobil] (from client wlc-management-wism2 port 1 cli 3c-15-c2-e8-40-fe)
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Sending Access-Challenge of id 66 to 129.217.251.242 port 32775
EAP-Message = 0x010c002e190017030300238ba36faaaa8eca1dad5d8436c834ed3299018005160165f2c94c81630e317746ffb3ba
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3c98a70a3694bea1f795a66daa110d86
Thu Jan 18 10:08:43 2018 : Info: Finished request 10.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.8 seconds.
rad_recv: Access-Request packet from host 129.217.251.242 port 32775, id=67, length=344
User-Name = "rtmobilnetz at rtmobil"
Chargeable-User-Identity = ""
Location-Capable = Civix-Location
Calling-Station-Id = "3c-15-c2-e8-40-fe"
Called-Station-Id = "6c-b2-ae-30-36-c0:ITMC-WPA2-STAGING"
NAS-Port = 1
Cisco-AVPair = "audit-session-id=81d9fbf2000000b85a60641b"
Acct-Session-Id = "5a60641b/3c:15:c2:e8:40:fe/307"
NAS-IP-Address = 129.217.251.242
NAS-Identifier = "wlc-staging"
Airespace-Wlan-Id = 8
Service-Type = Framed-User
Framed-MTU = 1300
NAS-Port-Type = Wireless-802.11
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "3503"
EAP-Message = 0x020c002e190017030300238c46983303f6f506ab3dd0d6867c3d0ffde22aafd4280172673cad608beb456f10cfec
State = 0x3c98a70a3694bea1f795a66daa110d86
Message-Authenticator = 0x1c46e2485d06f42b5c938da00d7b1ba6
Thu Jan 18 10:08:43 2018 : Info: server itmc-wlan {
Thu Jan 18 10:08:43 2018 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authorize {
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./)
Thu Jan 18 10:08:43 2018 : Info: ? Evaluating (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++? if (NAS-IP-Address =~ /^129\.217\.142\./) -> FALSE
Thu Jan 18 10:08:43 2018 : Info: ++[preprocess] = ok
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP packet type response id 12 length 46
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Continuing tunnel setup.
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authorize = ok
Thu Jan 18 10:08:43 2018 : Info: Found Auth-Type = eap_wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing group from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group authenticate {
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Request found, released from the list
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] EAP/peap
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] processing type peap
Thu Jan 18 10:08:43 2018 : Info: [peap] processing EAP-TLS
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_verify returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] Done initial handshake
Thu Jan 18 10:08:43 2018 : Info: [peap] eaptls_process returned 7
Thu Jan 18 10:08:43 2018 : Info: [peap] EAPTLS_OK
Thu Jan 18 10:08:43 2018 : Info: [peap] Session established. Decoding tunneled attributes.
Thu Jan 18 10:08:43 2018 : Info: [peap] Peap state send tlv success
Thu Jan 18 10:08:43 2018 : Info: [peap] Received EAP-TLV response.
Thu Jan 18 10:08:43 2018 : Info: [peap] Success
Thu Jan 18 10:08:43 2018 : Info: [peap] Using saved attributes from the original Access-Accept
Tunnel-Private-Group-Id:0 := "26"
Tunnel-Type:0 := VLAN
Tunnel-Medium-Type:0 := IEEE-802
Thu Jan 18 10:08:43 2018 : Info: [eap_wlan] Freeing handler
Thu Jan 18 10:08:43 2018 : Info: ++[eap_wlan] = ok
Thu Jan 18 10:08:43 2018 : Info: +} # group authenticate = ok
Thu Jan 18 10:08:43 2018 : Auth: Login OK: [rtmobilnetz at rtmobil] (from client wlc-management-wism2 port 1 cli 3c-15-c2-e8-40-fe)
Thu Jan 18 10:08:43 2018 : Info: } # server itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/itmc-wlan
Thu Jan 18 10:08:43 2018 : Info: +group post-auth {
Thu Jan 18 10:08:43 2018 : Info: ++[exec] = noop
Thu Jan 18 10:08:43 2018 : Info: +} # group post-auth = noop
Sending Access-Accept of id 67 to 129.217.251.242 port 32775
Tunnel-Private-Group-Id:0 := "26"
Tunnel-Type:0 := VLAN
Tunnel-Medium-Type:0 := IEEE-802
MS-MPPE-Recv-Key = 0x4dbed983678cb8daa6ebbfc2a2352532b17775a289d0a5c98f6d7da9a7d23377
MS-MPPE-Send-Key = 0xf11ab516c6bf4d3d56f94a5323906a542b8a6784efb7b8e60e04626844b0b0e3
EAP-Message = 0x030c0004
Message-Authenticator = 0x00000000000000000000000000000000
User-Name = "rtmobilnetz at rtmobil"
Thu Jan 18 10:08:43 2018 : Info: Finished request 11.
Thu Jan 18 10:08:43 2018 : Debug: Going to the next request
Thu Jan 18 10:08:43 2018 : Debug: Waking up in 4.8 seconds.
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 0 ID 56 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 1 ID 57 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 2 ID 58 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 3 ID 59 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 4 ID 60 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 5 ID 61 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 6 ID 62 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 7 ID 63 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 8 ID 64 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 9 ID 65 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 10 ID 66 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Cleaning up request 11 ID 67 with timestamp +81
Thu Jan 18 10:08:48 2018 : Info: Ready to process requests.
----------------------
Proxy config
...
realm rtmobil {
nostrip
auth_pool = rtmobil_pool
}
########## rtmobil ##########
home_server rtmobil {
type = auth
ipaddr = 129.217.197.132
secret = ZGel#Ex3Stx
port = 1812
response_window = 20
}
home_server_pool rtmobil_pool {
home_server = rtmobil
}
....
-----Ursprüngliche Nachricht-----
Von: Freeradius-Users [mailto:freeradius-users-bounces+hans.bornemann=tu-dortmund.de at lists.freeradius.org] Im Auftrag von Alan DeKok
Gesendet: Dienstag, 23. Januar 2018 13:55
An: FreeRadius users mailing list
Betreff: Re: Proxy problem when switching from version2 to version3
On Jan 23, 2018, at 3:48 AM, Bornemann, Hans <hans.bornemann at tu-dortmund.de> wrote:
>
> when switching to version 3 I have a little problem to find my misconfiguration.
>
> the home server says: access rejected because the freeradius sends:
>
> From wireshark on home server:
There *is* a debug log on the proxy which can give you more information. Why not post the debug output, as suggested in the documentation, FAQ, web site, "man" page, and daily on this list?
i.e. following the documentation is better than look at random third-party tools.
Also, FreeRADIUS doesn't *originate* EAP packets. It just proxies them. So if EAP is different, it's because the EAP client (i.e. laptop / desktop) is behaving differently.
> Where do I have to look in the configuration?
Read the documentation. Follow the instructions for debugging problems. Ask *good* questions.
If you have no idea what's going wrong, describe what's happening. In detail. Don't assume it's one thing, and then ask how to fix that...
Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Wichtiger Hinweis: Die Information in dieser E-Mail ist vertraulich. Sie ist ausschließlich für den Adressaten bestimmt. Sollten Sie nicht der für diese E-Mail bestimmte Adressat sein, unterrichten Sie bitte den Absender und vernichten Sie diese Mail. Vielen Dank.
Unbeschadet der Korrespondenz per E-Mail, sind unsere Erklärungen ausschließlich final rechtsverbindlich, wenn sie in herkömmlicher Schriftform (mit eigenhändiger Unterschrift) oder durch Übermittlung eines solchen Schriftstücks per Telefax erfolgen.
Important note: The information included in this e-mail is confidential. It is solely intended for the recipient. If you are not the intended recipient of this e-mail please contact the sender and delete this message. Thank you. Without prejudice of e-mail correspondence, our statements are only legally binding when they are made in the conventional written form (with personal signature) or when such documents are sent by fax.
More information about the Freeradius-Users
mailing list