two questions about migration from FR 2.X to 3.X
Anton Kiryushkin
swood at fotofor.biz
Fri Nov 3 12:05:57 CET 2017
Okay, thanks for your answer about the printer. It's bad news for him, but
good for me.
Returning to the question about a mschap. I have the next debug log:
Thu Nov 2 21:43:58 2017 : Debug: (138) Received Access-Request Id 166 from
192.168.1.2:58178 to 192.168.4.3:1812 length 294
Thu Nov 2 21:43:58 2017 : Debug: (138) User-Name = "user"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port = 96
Thu Nov 2 21:43:58 2017 : Debug: (138) State =
0x00729277067a8792b93b4156e0f7d618
Thu Nov 2 21:43:58 2017 : Debug: (138) EAP-Message =
0x020800731500170303006895b8c9fdff2c09f408380c8566150c90227a2acf00e9c0f952828448742f5bbe06780afedd931d703bc924ae15884e0be7bad9e7e815f271fd40879f6dd9fb6c745da9610115e99c44689ecf1eb5e846f0154d6730ac16769a43aa3934be6c2c54b85ca702492f4c
Thu Nov 2 21:43:58 2017 : Debug: (138) Message-Authenticator =
0xdf453c3234f42d3628829ce35fb70e79
Thu Nov 2 21:43:58 2017 : Debug: (138) Acct-Session-Id =
"8O2.1x818b430100008423"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Id = "ge-0/0/13.0"
Thu Nov 2 21:43:58 2017 : Debug: (138) Calling-Station-Id =
"d0-50-99-2c-ff-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) Called-Station-Id =
"88-e0-f3-b0-d6-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-IP-Address = 192.168.1.2
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Identifier = "sw-"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Type = Ethernet
Thu Nov 2 21:43:58 2017 : Debug: (138) session-state: No cached attributes
Thu Nov 2 21:43:58 2017 : Debug: (138) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Thu Nov 2 21:43:58 2017 : Debug: (138) authorize {
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
preprocess (rlm_preprocess)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from preprocess (rlm_preprocess)
Thu Nov 2 21:43:58 2017 : Debug: (138) [preprocess] = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
chap (rlm_chap)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from chap (rlm_chap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [chap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [mschap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
suffix (rlm_realm)
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: Checking for suffix after
"@"
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: No '@' in User-Name =
"user", looking up realm NULL
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: No such realm "NULL"
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from suffix (rlm_realm)
Thu Nov 2 21:43:58 2017 : Debug: (138) [suffix] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Peer sent EAP Response (code
2) ID 8 length 115
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Continuing tunnel setup
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [eap] = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
sql-wifi (rlm_sql)
Thu Nov 2 21:43:58 2017 : Debug: %{User-Name}
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: attribute --> User-Name
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND %{User-Name}
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> user
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: SQL-User-Name set to
'user'
Thu Nov 2 21:43:58 2017 : Debug: rlm_sql (sql-wifi): Reserved connection
(2)
Thu Nov 2 21:43:58 2017 : Debug: SELECT wifi_id as id, username,
'Cleartext-Password' as attribute, password, ':=' as op FROM wifiusers
WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: literal --> SELECT wifi_id as id,
username, 'Cleartext-Password' as attribute, password, ':=' as op FROM
wifiusers WHERE username = '
Thu Nov 2 21:43:58 2017 : Debug: attribute --> SQL-User-Name
Thu Nov 2 21:43:58 2017 : Debug: literal --> ' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND SELECT wifi_id as
id, username, 'Cleartext-Password' as attribute, password, ':=' as op FROM
wifiusers WHERE username = '%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> SELECT wifi_id as
id, username, 'Cleartext-Password' as attribute, password, ':=' as op FROM
wifiusers WHERE username = 'user' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Executing select query:
SELECT wifi_id as id, username, 'Cleartext-Password' as attribute,
password, ':=' as op FROM wifiusers WHERE username = 'user' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: User found in radcheck
table
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Conditional check items
matched, merging assignment check items
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Cleartext-Password :=
"password"
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: FROM 1 TO 1 MAX 2
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: Examining
Cleartext-Password
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: APPENDING
Cleartext-Password FROM 0 TO 1
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: TO in 1 out 1
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: to[0] = Auth-Type
Thu Nov 2 21:43:58 2017 : Debug: SELECT id, UserName, Attribute, Value, op
FROM wifi_attrs WHERE Username = '%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: literal --> SELECT id, UserName,
Attribute, Value, op FROM wifi_attrs WHERE Username = '
Thu Nov 2 21:43:58 2017 : Debug: attribute --> SQL-User-Name
Thu Nov 2 21:43:58 2017 : Debug: literal --> ' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND SELECT id,
UserName, Attribute, Value, op FROM wifi_attrs WHERE Username =
'%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> SELECT id,
UserName, Attribute, Value, op FROM wifi_attrs WHERE Username = 'user'
ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Executing select query:
SELECT id, UserName, Attribute, Value, op FROM wifi_attrs WHERE Username =
'user' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ... falling-through to
group processing
Thu Nov 2 21:43:58 2017 : Debug: SELECT 'GroupWifi' as GroupName FROM
wifiusers WHERE UserName='%{SQL-User-Name}'
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: literal --> SELECT 'GroupWifi' as
GroupName FROM wifiusers WHERE UserName='
Thu Nov 2 21:43:58 2017 : Debug: attribute --> SQL-User-Name
Thu Nov 2 21:43:58 2017 : Debug: literal --> '
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND SELECT 'GroupWifi'
as GroupName FROM wifiusers WHERE UserName='%{SQL-User-Name}'
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> SELECT 'GroupWifi'
as GroupName FROM wifiusers WHERE UserName='user'
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Executing select query:
SELECT 'GroupWifi' as GroupName FROM wifiusers WHERE UserName='user'
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: User found in the group
table
Thu Nov 2 21:43:58 2017 : Debug: SELECT wifi_id as id, 'GroupWifi' as
GroupName, 'Cleartext-Password' as attribute, password, ':=' as op
FROM wifiusers WHERE Username = '%{SQL-User-Name}'
ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: literal --> SELECT wifi_id as id,
'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password, ':='
as op FROM wifiusers WHERE Username = '
Thu Nov 2 21:43:58 2017 : Debug: attribute --> SQL-User-Name
Thu Nov 2 21:43:58 2017 : Debug: literal --> ' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND SELECT wifi_id as
id, 'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password,
':=' as op FROM wifiusers WHERE Username =
'%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> SELECT wifi_id as
id, 'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password,
':=' as op FROM wifiusers WHERE Username = 'user'
ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Executing select query:
SELECT wifi_id as id, 'GroupWifi' as GroupName, 'Cleartext-Password' as
attribute, password, ':=' as op FROM wifiusers WHERE
Username = 'user' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Group "GroupWifi":
Conditional check items matched
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Group "GroupWifi":
Merging assignment check items
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Cleartext-Password :=
"password"
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: FROM 1 TO 2 MAX 3
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: Examining
Cleartext-Password
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: OVERWRITING
Cleartext-Password FROM 0 TO 1
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: TO in 2 out 2
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: to[0] = Auth-Type
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: to[1] =
Cleartext-Password
Thu Nov 2 21:43:58 2017 : Debug: SELECT wifi_id as id, 'GroupWifi' as
GroupName, 'Cleartext-Password' as attribute, password, ':=' as op
FROM wifiusers WHERE Username = '%{SQL-User-Name}'
ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: literal --> SELECT wifi_id as id,
'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password, ':='
as op FROM wifiusers WHERE Username = '
Thu Nov 2 21:43:58 2017 : Debug: attribute --> SQL-User-Name
Thu Nov 2 21:43:58 2017 : Debug: literal --> ' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: EXPAND SELECT wifi_id as
id, 'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password,
':=' as op FROM wifiusers WHERE Username =
'%{SQL-User-Name}' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: --> SELECT wifi_id as
id, 'GroupWifi' as GroupName, 'Cleartext-Password' as attribute, password,
':=' as op FROM wifiusers WHERE Username = 'user'
ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Executing select query:
SELECT wifi_id as id, 'GroupWifi' as GroupName, 'Cleartext-Password' as
attribute, password, ':=' as op FROM wifiusers WHERE
Username = 'user' ORDER BY id
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Group "GroupWifi":
Merging reply items
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: Cleartext-Password :=
"password"
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: FROM 1 TO 0 MAX 1
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: Examining
Cleartext-Password
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: APPENDING
Cleartext-Password FROM 0 TO 0
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ::: TO in 0 out 0
Thu Nov 2 21:43:58 2017 : Debug: (138) sql-wifi: ... falling-through to
profile processing
Thu Nov 2 21:43:58 2017 : Debug: rlm_sql (sql-wifi): Released connection
(2)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from sql-wifi (rlm_sql)
Thu Nov 2 21:43:58 2017 : Debug: (138) [sql-wifi] = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
pap (rlm_pap)
Thu Nov 2 21:43:58 2017 : WARNING: (138) pap: Auth-Type already set. Not
setting to PAP
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: returned
from pap (rlm_pap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [pap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) } # authorize = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) Found Auth-Type = eap
Thu Nov 2 21:43:58 2017 : Debug: (138) # Executing group from file
/etc/raddb/sites-enabled/default
Thu Nov 2 21:43:58 2017 : Debug: (138) authenticate {
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authenticate]:
calling eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Expiring EAP session with
state 0xacf07a2badf260fe
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Finished EAP session with
state 0x00729277067a8792
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Previous EAP request found for
state 0x00729277067a8792, released from the list
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Peer sent packet with method
EAP TTLS (21)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Calling submodule eap_ttls to
process data
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Authenticate
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Continuing EAP-TLS
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Peer sent flags ---
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: [eaptls verify] = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Done initial handshake
Thu Nov 2 21:43:58 2017 : Debug: Ignoring cbtls_msg call with pseudo
content type 256, version 0
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: [eaptls process] = ok
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Session established.
Proceeding to decode tunneled attributes
TTLS tunnel data in 0000: 00 00 00 4f 40 00 00 4e 02 02 00 46 1a 02 02 00
TTLS tunnel data in 0010: 41 31 31 36 ff 7e 4e d5 c6 a5 ac 8a 61 c3 88 fb
TTLS tunnel data in 0020: 88 a4 00 00 00 00 00 00 00 00 81 5c 45 83 b9 97
TTLS tunnel data in 0030: 70 9d eb 90 9a ba db 83 1f 25 d9 1c 11 72 89 3a
TTLS tunnel data in 0040: 99 3b 00 61 2e 73 6f 6c 64 61 74 6b 69 6e 00 00
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Got tunneled request
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: EAP-Message =
0x020200461a02020041313136ff7e4ed5c6a5ac8a61c388fb88a40000000000000000815c4583b997709deb909abadb831f25d91c1172893a993b00612e736f6c6461746b696e
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: FreeRADIUS-Proxied-To =
127.0.0.1
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_ttls: Sending tunneled request
Thu Nov 2 21:43:58 2017 : Debug: (138) Virtual server inner-tunnel
received request
Thu Nov 2 21:43:58 2017 : Debug: (138) EAP-Message =
0x020200461a02020041313136ff7e4ed5c6a5ac8a61c388fb88a40000000000000000815c4583b997709deb909abadb831f25d91c1172893a993b00612e736f6c6461746b696e
Thu Nov 2 21:43:58 2017 : Debug: (138) FreeRADIUS-Proxied-To = 127.0.0.1
Thu Nov 2 21:43:58 2017 : Debug: (138) User-Name = "user"
Thu Nov 2 21:43:58 2017 : Debug: (138) State =
0xacf07a2badf260feda2e8d2e021e6186
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port = 96
Thu Nov 2 21:43:58 2017 : Debug: (138) Acct-Session-Id =
"8O2.1x818b430100008423"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Id = "ge-0/0/13.0"
Thu Nov 2 21:43:58 2017 : Debug: (138) Calling-Station-Id =
"d0-50-99-2c-ff-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) Called-Station-Id =
"88-e0-f3-b0-d6-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-IP-Address = 192.168.1.2
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Identifier = "sw-"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Type = Ethernet
Thu Nov 2 21:43:58 2017 : Debug: (138) Event-Timestamp = "Nov 2 2017
21:43:58 UTC"
Thu Nov 2 21:43:58 2017 : WARNING: (138) Outer and inner identities are
the same. User privacy is compromised.
Thu Nov 2 21:43:58 2017 : Debug: (138) FreeRADIUS-Proxied-To = 127.0.0.1
Thu Nov 2 21:43:58 2017 : Debug: (138) User-Name = "user"
Thu Nov 2 21:43:58 2017 : Debug: (138) State =
0xacf07a2badf260feda2e8d2e021e6186
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port = 96
Thu Nov 2 21:43:58 2017 : Debug: (138) Acct-Session-Id =
"8O2.1x818b430100008423"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Id = "ge-0/0/13.0"
Thu Nov 2 21:43:58 2017 : Debug: (138) Calling-Station-Id =
"d0-50-99-2c-ff-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) Called-Station-Id =
"88-e0-f3-b0-d6-00"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-IP-Address = 192.168.1.2
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Identifier = "sw-"
Thu Nov 2 21:43:58 2017 : Debug: (138) NAS-Port-Type = Ethernet
Thu Nov 2 21:43:58 2017 : Debug: (138) Event-Timestamp = "Nov 2 2017
21:43:58 UTC"
Thu Nov 2 21:43:58 2017 : WARNING: (138) Outer and inner identities are
the same. User privacy is compromised.
Thu Nov 2 21:43:58 2017 : Debug: (138) server inner-tunnel {
Thu Nov 2 21:43:58 2017 : Debug: (138) session-state: No cached
attributes
Thu Nov 2 21:43:58 2017 : Debug: (138) # Executing section authorize
from file /etc/raddb/sites-enabled/inner-tunnel
Thu Nov 2 21:43:58 2017 : Debug: (138) authorize {
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
chap (rlm_chap)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from chap (rlm_chap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [chap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [mschap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
unix (rlm_unix)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from unix (rlm_unix)
Thu Nov 2 21:43:58 2017 : Debug: (138) [unix] = notfound
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
suffix (rlm_realm)
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: Checking for suffix after
"@"
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: No '@' in User-Name =
"user", looking up realm NULL
Thu Nov 2 21:43:58 2017 : Debug: (138) suffix: No such realm "NULL"
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from suffix (rlm_realm)
Thu Nov 2 21:43:58 2017 : Debug: (138) [suffix] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) update control {
Thu Nov 2 21:43:58 2017 : Debug: (138) Proxy-To-Realm := LOCAL
Thu Nov 2 21:43:58 2017 : Debug: (138) } # update control = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Peer sent EAP Response (code
2) ID 2 length 70
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: No EAP Start, assuming it's an
on-going EAP conversation
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [eap] = updated
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
files (rlm_files)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from files (rlm_files)
Thu Nov 2 21:43:58 2017 : Debug: (138) [files] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
expiration (rlm_expiration)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from expiration (rlm_expiration)
Thu Nov 2 21:43:58 2017 : Debug: (138) [expiration] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
logintime (rlm_logintime)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from logintime (rlm_logintime)
Thu Nov 2 21:43:58 2017 : Debug: (138) [logintime] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]: calling
pap (rlm_pap)
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authorize]:
returned from pap (rlm_pap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [pap] = noop
Thu Nov 2 21:43:58 2017 : Debug: (138) } # authorize = updated
Thu Nov 2 21:43:58 2017 : Debug: (138) Found Auth-Type = eap
Thu Nov 2 21:43:58 2017 : Debug: (138) # Executing group from file
/etc/raddb/sites-enabled/inner-tunnel
Thu Nov 2 21:43:58 2017 : Debug: (138) authenticate {
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authenticate]:
calling eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Expiring EAP session with
state 0xacf07a2badf260fe
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Finished EAP session with
state 0xacf07a2badf260fe
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Previous EAP request found for
state 0xacf07a2badf260fe, released from the list
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Peer sent packet with method
EAP MSCHAPv2 (26)
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Calling submodule eap_mschapv2
to process data
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_mschapv2: # Executing group
from file /etc/raddb/sites-enabled/inner-tunnel
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_mschapv2: Auth-Type MS-CHAP {
Thu Nov 2 21:43:58 2017 : Debug: (138) eap_mschapv2:
modsingle[authenticate]: calling mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : WARNING: (138) mschap: No Cleartext-Password
configured. Cannot create NT-Password
Thu Nov 2 21:43:58 2017 : WARNING: (138) mschap: No Cleartext-Password
configured. Cannot create LM-Password
Thu Nov 2 21:43:58 2017 : Debug: (138) mschap: Creating challenge hash
with username: user
Thu Nov 2 21:43:58 2017 : Debug: (138) mschap: Client is using MS-CHAPv2
Thu Nov 2 21:43:58 2017 : ERROR: (138) mschap: FAILED: No NT/LM-Password.
Cannot perform authentication
Thu Nov 2 21:43:58 2017 : ERROR: (138) mschap: MS-CHAP2-Response is
incorrect
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authenticate]:
returned from mschap (rlm_mschap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [mschap] = reject
Thu Nov 2 21:43:58 2017 : Debug: (138) } # Auth-Type MS-CHAP = reject
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Sending EAP Failure (code 4)
ID 2 length 4
Thu Nov 2 21:43:58 2017 : Debug: (138) eap: Freeing handler
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[authenticate]:
returned from eap (rlm_eap)
Thu Nov 2 21:43:58 2017 : Debug: (138) [eap] = reject
Thu Nov 2 21:43:58 2017 : Debug: (138) } # authenticate = reject
Thu Nov 2 21:43:58 2017 : Debug: (138) Failed to authenticate the user
Thu Nov 2 21:43:58 2017 : Debug: (138) Using Post-Auth-Type Reject
Thu Nov 2 21:43:58 2017 : Debug: (138) # Executing group from file
/etc/raddb/sites-enabled/inner-tunnel
Thu Nov 2 21:43:58 2017 : Debug: (138) Post-Auth-Type REJECT {
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[post-auth]: calling
attr_filter.access_reject (rlm_attr_filter)
Thu Nov 2 21:43:58 2017 : Debug: %{User-Name}
Thu Nov 2 21:43:58 2017 : Debug: Parsed xlat tree:
Thu Nov 2 21:43:58 2017 : Debug: attribute --> User-Name
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject: EXPAND
%{User-Name}
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject: -->
user
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject: Matched
entry DEFAULT at line 11
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject:
Attribute "MS-CHAP-Error" allowed by 0 rules, disallowed by 0 rules
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject:
EAP-Message = 0x04020004 allowed by EAP-Message =* 0x
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject:
Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject:
Message-Authenticator = 0x00000000000000000000000000000000 allowed by
Message-Authenticator =* 0x
Thu Nov 2 21:43:58 2017 : Debug: (138) attr_filter.access_reject:
Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules
Thu Nov 2 21:43:58 2017 : Debug: (138) modsingle[post-auth]:
returned from attr_filter.access_reject (rlm_attr_filter)
Thu Nov 2 21:43:58 2017 : Debug: (138) [attr_filter.access_reject] =
updated
Thu Nov 2 21:43:58 2017 : Debug: (138) } # Post-Auth-Type REJECT =
updated
Thu Nov 2 21:43:58 2017 : Auth: (138) Login incorrect (mschap: FAILED:
No NT/LM-Password. Cannot perform authentication): [user/<via Auth-Type =
eap>] (from client EX port 96 cli d0-50-99-2c-ff-00 via TLS tunnel)
2017-11-03 13:49 GMT+03:00 Alan DeKok <aland at deployingradius.com>:
> On Nov 3, 2017, at 6:39 AM, Anton Kiryushkin <swood at fotofor.biz> wrote:
> >
> > I have two question about migration from oldest to newest version.
> > 1. After migration, the process authorization by MSCHAP-V2 wrote that
> can't
> > make NT-password:
>
> The error is saying "No Cleartext-Password". i.e. you didn't tell the
> server what the users "known good" password is.
>
> > This happened in inner-tunnel site with config:
>
> What does the *rest* of the debug output say? Reading that will tell
> you what's happening.
>
> > But I have the same config on FR 2.X in it worked. Could tell me why?
>
> Read the debug output.
>
> > The second question with another client. I've got the next error message:
> >
> > Thu Nov 2 21:44:19 2017 : ERROR: (159) eap_peap: Failed in __FUNCTION__
> > (SSL_read): s3_srvr.c[1240]:error:1408A0E3:SSL
> > routines:ssl3_get_client_hello:parse tlsext
> > Thu Nov 2 21:44:19 2017 : ERROR: (159) eap_peap: System call (I/O) error
> > (-1)
>
> Weird. It looks like that "tlsext" field is malformed.
>
> > Thu Nov 2 21:44:19 2017 : ERROR: (159) eap_peap: TLS receive handshake
> > failed during operation
> > Thu Nov 2 21:44:19 2017 : ERROR: (159) eap_peap: [eaptls process] = fail
> > Thu Nov 2 21:44:19 2017 : ERROR: (159) eap: Failed continuing EAP PEAP
> > (25) session. EAP sub-module failed
> >
> > This is printer Canon 5240i and I can't change his software. As well as
> in
> > the previous question, all work with FR 2.X.
>
> Let me guess: you also changed operating systems, and OpenSSL versions
> at the same time.
>
> Older OpenSSL versions were more forgiving of bad data. Newer OpenSSL
> versions are more strict.
>
> This is (unfortunately) an OpenSSL thing. Nothing in FreeRADIUS will
> cause that error.
>
> The short answer is that the client is broken. It doesn't implement
> PEAP / SSL correctly.
>
> Alan DeKok.
>
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/
> list/users.html
--
Best regards,
Anton Kiryushkin
More information about the Freeradius-Users
mailing list