Cisco-AVPair and Access-Accept
Eugene M. Zheganin
emz at norma.perm.ru
Tue Nov 8 14:43:02 CET 2016
Hi.
I'm trying to restrict a wireless user to a specific SSID. I have a
freeradius 3.0.11 server that was configured some time ago when it was
running a 2.x version, and this feature was working, then I ported the
configs. Now it doesn't work for some reason, and I'm desperately trying
to figure out why. It has an PgSQL backend configured and pretty much
all of my tweaks are saved there.
So, now about what do I see.
Seems like when using radtest sequence everything is working as intended:
===Cut===
# radtest -t eap-md5 foobar XXXXX localhost 666 s0m3s3cr3t
Loading input data...
Read 1 element(s) from input: stdin
Loaded: 1 input element(s).
Adding new socket: src: 0.0.0.0:0, dst: 127.0.0.1:1812
Added new socket: 6 (num sockets: 1)
Transaction: 0, sending packet: 0 (id: 54)...
Sent Access-Request Id 54 from 0.0.0.0:16248 to 127.0.0.1:1812 length 99
User-Name = "foobar"
User-Password = "XXXXX"
NAS-IP-Address = 192.168.3.22
NAS-Port = 666
Message-Authenticator = 0x00
EAP-Code = Response
EAP-Type-Identity = 0x3839303238333234323133
EAP-Message = 0x021f0010013839303238333234323133
Transaction: 0, received packet (id: 54).
Received Access-Challenge Id 54 from 127.0.0.1:1812 to 0.0.0.0:16248
length 80
EAP-Message = 0x012000160410cc18e96bf6909c2fe2f185b7207c2811
Message-Authenticator = 0x9cccd86e57512c5ebea735dd2c4b5766
State = 0x95e1ebea95c1ef71bbd0a746eddfb07e
EAP-Id = 32
EAP-Code = Request
EAP-Type-MD5-Challenge = 0x10cc18e96bf6909c2fe2f185b7207c2811
Transaction: 0, sending packet: 1 (id: 247)...
Sent Access-Request Id 247 from 0.0.0.0:16248 to 127.0.0.1:1812 length 123
User-Name = "foobar"
User-Password = "XXXXX"
NAS-IP-Address = 192.168.3.22
NAS-Port = 666
Message-Authenticator = 0x00
EAP-Code = Response
EAP-Type-MD5-Challenge = 0x10ea04a9bf38cdd98629a7190157fc268b
EAP-Id = 32
State = 0x95e1ebea95c1ef71bbd0a746eddfb07e
EAP-Message = 0x022000160410ea04a9bf38cdd98629a7190157fc268b
Transaction: 0, received packet (id: 247).
Received Access-Accept Id 247 from 127.0.0.1:1812 to 0.0.0.0:16248 length 75
Cisco-AVPair = "ssid=vivat"
EAP-Message = 0x03200004
Message-Authenticator = 0x65764b79391e1dadd0ae0cab4a25d2a4
User-Name = "foobar"
EAP-Id = 32
EAP-Code = Success
Main loop: done.
===Cut===
Everything is in place: Cisco-AVPair = "ssid=vivat" is present in
Access-Accept message. But when it comes to the actual exchange with
Cisco AP, it is present only in some messages, but not in the last
Access-Accept message. Here's the output from the radiusd -X (my message
doesn't end with this huge block of text, so please read below too):
===Cut===
(89) session-state: No cached attributes
(89) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(89) authorize {
(89) policy filter_username {
(89) if (!&User-Name) {
(89) if (!&User-Name) -> FALSE
(89) if (&User-Name =~ / /) {
(89) if (&User-Name =~ / /) -> FALSE
(89) if (&User-Name =~ /@.*@/ ) {
(89) if (&User-Name =~ /@.*@/ ) -> FALSE
(89) if (&User-Name =~ /\\.\\./ ) {
(89) if (&User-Name =~ /\\.\\./ ) -> FALSE
(89) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) {
(89) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
-> FALSE
(89) if (&User-Name =~ /\\.$/) {
(89) if (&User-Name =~ /\\.$/) -> FALSE
(89) if (&User-Name =~ /@\\./) {
(89) if (&User-Name =~ /@\\./) -> FALSE
(89) } # policy filter_username = notfound
(89) [preprocess] = ok
(89) [chap] = noop
(89) [mschap] = noop
(89) [digest] = noop
(89) suffix: Checking for suffix after "@"
(89) suffix: No '@' in User-Name = "foobar", looking up realm NULL
(89) suffix: No such realm "NULL"
(89) [suffix] = noop
(89) eap: Peer sent EAP Response (code 2) ID 10 length 107
(89) eap: Continuing tunnel setup
(89) [eap] = ok
(89) } # authorize = ok
(89) Found Auth-Type = eap
(89) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(89) authenticate {
(89) eap: Expiring EAP session with state 0xe59bffd0e591e5ca
(89) eap: Finished EAP session with state 0x8fd58b5b87df9215
(89) eap: Previous EAP request found for state 0x8fd58b5b87df9215,
released from the list
(89) eap: Peer sent packet with method EAP PEAP (25)
(89) eap: Calling submodule eap_peap to process data
(89) eap_peap: Continuing EAP-TLS
(89) eap_peap: [eaptls verify] = ok
(89) eap_peap: Done initial handshake
(89) eap_peap: [eaptls process] = ok
(89) eap_peap: Session established. Decoding tunneled attributes
(89) eap_peap: PEAP state phase2
(89) eap_peap: EAP method MSCHAPv2 (26)
(89) eap_peap: Got tunneled request
(89) eap_peap: EAP-Message =
0x020a00461a020a00413164683e249719e1424a4f04aa609ee5610000000000000000d98c65626c0650346ebf7aa6c322f6bd97c564ad4a64afc1003839303238333234323133
(89) eap_peap: Setting User-Name to foobar
(89) eap_peap: Sending tunneled request to inner-tunnel
(89) eap_peap: EAP-Message =
0x020a00461a020a00413164683e249719e1424a4f04aa609ee5610000000000000000d98c65626c0650346ebf7aa6c322f6bd97c564ad4a64afc1003839303238333234323133
(89) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1
(89) eap_peap: User-Name = "foobar"
(89) eap_peap: State = 0x6ba19a7c6bab8024eb49697d02fb30b2
(89) Virtual server inner-tunnel received request
(89) EAP-Message =
0x020a00461a020a00413164683e249719e1424a4f04aa609ee5610000000000000000d98c65626c0650346ebf7aa6c322f6bd97c564ad4a64afc1003839303238333234323133
(89) FreeRADIUS-Proxied-To = 127.0.0.1
(89) User-Name = "foobar"
(89) State = 0x6ba19a7c6bab8024eb49697d02fb30b2
(89) WARNING: Outer and inner identities are the same. User privacy is
compromised.
(89) server inner-tunnel {
(89) session-state: No cached attributes
(89) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(89) authorize {
(89) [chap] = noop
(89) [mschap] = noop
(89) suffix: Checking for suffix after "@"
(89) suffix: No '@' in User-Name = "foobar", looking up realm NULL
(89) suffix: No such realm "NULL"
(89) [suffix] = noop
(89) update control {
(89) Proxy-To-Realm := LOCAL
(89) } # update control = noop
(89) eap: Peer sent EAP Response (code 2) ID 10 length 70
(89) eap: No EAP Start, assuming it's an on-going EAP conversation
(89) [eap] = updated
(89) [files] = noop
(89) sql: EXPAND %{User-Name}
(89) sql: --> foobar
(89) sql: SQL-User-Name set to 'foobar'
rlm_sql (sql): Reserved connection (3)
(89) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(89) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = 'foobar' ORDER BY id
(89) sql: Executing select query: SELECT id, UserName, Attribute, Value,
Op FROM radcheck WHERE Username = 'foobar' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 5
(89) sql: User found in radcheck table
(89) sql: Conditional check items matched, merging assignment check items
(89) sql: Cleartext-Password := "XXXXX"
(89) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(89) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = 'foobar' ORDER BY id
(89) sql: Executing select query: SELECT id, UserName, Attribute, Value,
Op FROM radreply WHERE Username = 'foobar' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(89) sql: EXPAND SELECT GroupName FROM radusergroup WHERE
UserName='%{SQL-User-Name}' ORDER BY priority
(89) sql: --> SELECT GroupName FROM radusergroup WHERE
UserName='foobar' ORDER BY priority
(89) sql: Executing select query: SELECT GroupName FROM radusergroup
WHERE UserName='foobar' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 1
(89) sql: User found in the group table
(89) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM
radgroupcheck WHERE GroupName = '%{Sql-Group}' ORDER BY id
(89) sql: --> SELECT id, GroupName, Attribute, Value, op FROM
radgroupcheck WHERE GroupName = 'public-wifi' ORDER BY id
(89) sql: Executing select query: SELECT id, GroupName, Attribute,
Value, op FROM radgroupcheck WHERE GroupName = 'public-wifi' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(89) sql: Group "public-wifi": Conditional check items matched
(89) sql: Group "public-wifi": Merging assignment check items
(89) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id
(89) sql: --> SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = 'public-wifi' ORDER BY id
(89) sql: Executing select query: SELECT id, GroupName, Attribute,
Value, op FROM radgroupreply WHERE GroupName = 'public-wifi' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
(89) sql: Group "public-wifi": Merging reply items
(89) sql: Cisco-AVPair = "ssid=vivat"
(89) sql: Simultaneous-Use := 1
rlm_sql (sql): Released connection (3)
(89) [sql] = ok
(89) [expiration] = noop
(89) [logintime] = noop
(89) noresetcounter: WARNING: Couldn't find check attribute,
control:Max-All-Session, doing nothing...
(89) [noresetcounter] = noop
(89) pap: WARNING: Auth-Type already set. Not setting to PAP
(89) [pap] = noop
(89) } # authorize = updated
(89) Found Auth-Type = eap
(89) # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(89) authenticate {
(89) eap: Expiring EAP session with state 0xe59bffd0e591e5ca
(89) eap: Finished EAP session with state 0x6ba19a7c6bab8024
(89) eap: Previous EAP request found for state 0x6ba19a7c6bab8024,
released from the list
(89) eap: Peer sent packet with method EAP MSCHAPv2 (26)
(89) eap: Calling submodule eap_mschapv2 to process data
(89) eap_mschapv2: # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(89) eap_mschapv2: Auth-Type MS-CHAP {
(89) mschap: Found Cleartext-Password, hashing to create NT-Password
(89) mschap: Found Cleartext-Password, hashing to create LM-Password
(89) mschap: Creating challenge hash with username: foobar
(89) mschap: Client is using MS-CHAPv2
(89) mschap: Adding MS-CHAPv2 MPPE keys
(89) [mschap] = ok
(89) } # Auth-Type MS-CHAP = ok
(89) MSCHAP Success
(89) eap: Sending EAP Request (code 1) ID 11 length 51
(89) eap: EAP session adding &reply:State = 0x6ba19a7c6aaa8024
(89) [eap] = handled
(89) } # authenticate = handled
(89) } # server inner-tunnel
(89) Virtual server sending reply
(89) Cisco-AVPair = "ssid=vivat"
(89) Simultaneous-Use = 1
(89) EAP-Message =
0x010b00331a030a002e533d41443344413037333132463933303143393530353131383337313442324445464131393430423343
(89) Message-Authenticator = 0x00000000000000000000000000000000
(89) State = 0x6ba19a7c6aaa8024eb49697d02fb30b2
(89) eap_peap: Got tunneled reply code 11
(89) eap_peap: Cisco-AVPair = "ssid=vivat"
(89) eap_peap: Simultaneous-Use = 1
(89) eap_peap: EAP-Message =
0x010b00331a030a002e533d41443344413037333132463933303143393530353131383337313442324445464131393430423343
(89) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(89) eap_peap: State = 0x6ba19a7c6aaa8024eb49697d02fb30b2
(89) eap_peap: Got tunneled reply RADIUS code 11
(89) eap_peap: Cisco-AVPair = "ssid=vivat"
(89) eap_peap: Simultaneous-Use = 1
(89) eap_peap: EAP-Message =
0x010b00331a030a002e533d41443344413037333132463933303143393530353131383337313442324445464131393430423343
(89) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(89) eap_peap: State = 0x6ba19a7c6aaa8024eb49697d02fb30b2
(89) eap_peap: Got tunneled Access-Challenge
(89) eap: Sending EAP Request (code 1) ID 11 length 91
(89) eap: EAP session adding &reply:State = 0x8fd58b5b86de9215
(89) [eap] = handled
(89) } # authenticate = handled
(89) Using Post-Auth-Type Challenge
(89) Post-Auth-Type sub-section not found. Ignoring.
(89) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(89) Sent Access-Challenge Id 254 from 192.168.6.144:1812 to
192.168.6.150:1645 length 0
(89) EAP-Message =
0x010b005b19001703010050656716e02838a7522fcd13490f1dba51f91b56e37051fa10585c76459287436e8c326917890fcf38cf35cc531b729d4224a90bd8f9cb2ca2cf5ddc799baa5035360f255734b399a66285f3e608b95092
(89) Message-Authenticator = 0x00000000000000000000000000000000
(89) State = 0x8fd58b5b86de92156a8b280739c58aaf
(89) Finished request
Waking up in 4.8 seconds.
(90) Received Access-Request Id 255 from 192.168.6.150:1645 to
192.168.6.144:1812 length 251
(90) User-Name = "foobar"
(90) Framed-MTU = 1400
(90) Called-Station-Id = "001f.ca27.9ea0"
(90) Calling-Station-Id = "2c20.0b2a.a0c2"
(90) Cisco-AVPair = "ssid=irma"
(90) WISPr-Location-Name = "First floor, Hyper, Perm"
(90) Service-Type = Login-User
(90) Message-Authenticator = 0x856525b7e21a444be06ff736c2a08952
(90) EAP-Message =
0x020b002b19001703010020da2c83c5e5598f4a88b319137aec7e134578362f376c816596640bad33010fde
(90) NAS-Port-Type = Wireless-802.11
(90) NAS-Port = 859591
(90) NAS-Port-Id = "859591"
(90) State = 0x8fd58b5b86de92156a8b280739c58aaf
(90) NAS-IP-Address = 192.168.6.150
(90) NAS-Identifier = "kosm65-hyper-ap1"
(90) session-state: No cached attributes
(90) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(90) authorize {
(90) policy filter_username {
(90) if (!&User-Name) {
(90) if (!&User-Name) -> FALSE
(90) if (&User-Name =~ / /) {
(90) if (&User-Name =~ / /) -> FALSE
(90) if (&User-Name =~ /@.*@/ ) {
(90) if (&User-Name =~ /@.*@/ ) -> FALSE
(90) if (&User-Name =~ /\\.\\./ ) {
(90) if (&User-Name =~ /\\.\\./ ) -> FALSE
(90) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) {
(90) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
-> FALSE
(90) if (&User-Name =~ /\\.$/) {
(90) if (&User-Name =~ /\\.$/) -> FALSE
(90) if (&User-Name =~ /@\\./) {
(90) if (&User-Name =~ /@\\./) -> FALSE
(90) } # policy filter_username = notfound
(90) [preprocess] = ok
(90) [chap] = noop
(90) [mschap] = noop
(90) [digest] = noop
(90) suffix: Checking for suffix after "@"
(90) suffix: No '@' in User-Name = "foobar", looking up realm NULL
(90) suffix: No such realm "NULL"
(90) [suffix] = noop
(90) eap: Peer sent EAP Response (code 2) ID 11 length 43
(90) eap: Continuing tunnel setup
(90) [eap] = ok
(90) } # authorize = ok
(90) Found Auth-Type = eap
(90) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(90) authenticate {
(90) eap: Expiring EAP session with state 0xe59bffd0e591e5ca
(90) eap: Finished EAP session with state 0x8fd58b5b86de9215
(90) eap: Previous EAP request found for state 0x8fd58b5b86de9215,
released from the list
(90) eap: Peer sent packet with method EAP PEAP (25)
(90) eap: Calling submodule eap_peap to process data
(90) eap_peap: Continuing EAP-TLS
(90) eap_peap: [eaptls verify] = ok
(90) eap_peap: Done initial handshake
(90) eap_peap: [eaptls process] = ok
(90) eap_peap: Session established. Decoding tunneled attributes
(90) eap_peap: PEAP state phase2
(90) eap_peap: EAP method MSCHAPv2 (26)
(90) eap_peap: Got tunneled request
(90) eap_peap: EAP-Message = 0x020b00061a03
(90) eap_peap: Setting User-Name to foobar
(90) eap_peap: Sending tunneled request to inner-tunnel
(90) eap_peap: EAP-Message = 0x020b00061a03
(90) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1
(90) eap_peap: User-Name = "foobar"
(90) eap_peap: State = 0x6ba19a7c6aaa8024eb49697d02fb30b2
(90) Virtual server inner-tunnel received request
(90) EAP-Message = 0x020b00061a03
(90) FreeRADIUS-Proxied-To = 127.0.0.1
(90) User-Name = "foobar"
(90) State = 0x6ba19a7c6aaa8024eb49697d02fb30b2
(90) WARNING: Outer and inner identities are the same. User privacy is
compromised.
(90) server inner-tunnel {
(90) session-state: No cached attributes
(90) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(90) authorize {
(90) [chap] = noop
(90) [mschap] = noop
(90) suffix: Checking for suffix after "@"
(90) suffix: No '@' in User-Name = "foobar", looking up realm NULL
(90) suffix: No such realm "NULL"
(90) [suffix] = noop
(90) update control {
(90) Proxy-To-Realm := LOCAL
(90) } # update control = noop
(90) eap: Peer sent EAP Response (code 2) ID 11 length 6
(90) eap: No EAP Start, assuming it's an on-going EAP conversation
(90) [eap] = updated
(90) [files] = noop
(90) sql: EXPAND %{User-Name}
(90) sql: --> foobar
(90) sql: SQL-User-Name set to 'foobar'
rlm_sql (sql): Reserved connection (4)
(90) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(90) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radcheck
WHERE Username = 'foobar' ORDER BY id
(90) sql: Executing select query: SELECT id, UserName, Attribute, Value,
Op FROM radcheck WHERE Username = 'foobar' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 5
(90) sql: User found in radcheck table
(90) sql: Conditional check items matched, merging assignment check items
(90) sql: Cleartext-Password := "XXXXX"
(90) sql: EXPAND SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = '%{SQL-User-Name}' ORDER BY id
(90) sql: --> SELECT id, UserName, Attribute, Value, Op FROM radreply
WHERE Username = 'foobar' ORDER BY id
(90) sql: Executing select query: SELECT id, UserName, Attribute, Value,
Op FROM radreply WHERE Username = 'foobar' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(90) sql: EXPAND SELECT GroupName FROM radusergroup WHERE
UserName='%{SQL-User-Name}' ORDER BY priority
(90) sql: --> SELECT GroupName FROM radusergroup WHERE
UserName='foobar' ORDER BY priority
(90) sql: Executing select query: SELECT GroupName FROM radusergroup
WHERE UserName='foobar' ORDER BY priority
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 1 , fields = 1
(90) sql: User found in the group table
(90) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM
radgroupcheck WHERE GroupName = '%{Sql-Group}' ORDER BY id
(90) sql: --> SELECT id, GroupName, Attribute, Value, op FROM
radgroupcheck WHERE GroupName = 'public-wifi' ORDER BY id
(90) sql: Executing select query: SELECT id, GroupName, Attribute,
Value, op FROM radgroupcheck WHERE GroupName = 'public-wifi' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 0 , fields = 5
(90) sql: Group "public-wifi": Conditional check items matched
(90) sql: Group "public-wifi": Merging assignment check items
(90) sql: EXPAND SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id
(90) sql: --> SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = 'public-wifi' ORDER BY id
(90) sql: Executing select query: SELECT id, GroupName, Attribute,
Value, op FROM radgroupreply WHERE GroupName = 'public-wifi' ORDER BY id
rlm_sql_postgresql: Status: PGRES_TUPLES_OK
rlm_sql_postgresql: query affected rows = 2 , fields = 5
(90) sql: Group "public-wifi": Merging reply items
(90) sql: Cisco-AVPair = "ssid=vivat"
(90) sql: Simultaneous-Use := 1
rlm_sql (sql): Released connection (4)
(90) [sql] = ok
(90) [expiration] = noop
(90) [logintime] = noop
(90) noresetcounter: WARNING: Couldn't find check attribute,
control:Max-All-Session, doing nothing...
(90) [noresetcounter] = noop
(90) pap: WARNING: Auth-Type already set. Not setting to PAP
(90) [pap] = noop
(90) } # authorize = updated
(90) Found Auth-Type = eap
(90) # Executing group from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(90) authenticate {
(90) eap: Expiring EAP session with state 0xe59bffd0e591e5ca
(90) eap: Finished EAP session with state 0x6ba19a7c6aaa8024
(90) eap: Previous EAP request found for state 0x6ba19a7c6aaa8024,
released from the list
(90) eap: Peer sent packet with method EAP MSCHAPv2 (26)
(90) eap: Calling submodule eap_mschapv2 to process data
(90) eap: Sending EAP Success (code 3) ID 11 length 4
(90) eap: Freeing handler
(90) [eap] = ok
(90) } # authenticate = ok
(90) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
(90) post-auth {
(90) sql: EXPAND .query
(90) sql: --> .query
(90) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (0)
(90) sql: EXPAND %{User-Name}
(90) sql: --> foobar
(90) sql: SQL-User-Name set to 'foobar'
(90) sql: EXPAND INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES('%{User-Name}', '%{%{User-Password}:-Chap-Password}',
'%{reply:Packet-Type}', NOW())
(90) sql: --> INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES('foobar', 'Chap-Password', 'Access-Accept', NOW())
(90) sql: Executing query: INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES('foobar', 'Chap-Password', 'Access-Accept', NOW())
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 1
(90) sql: SQL query returned: success
(90) sql: 1 record(s) updated
rlm_sql (sql): Released connection (0)
(90) [sql] = ok
(90) } # post-auth = ok
(90) Login OK: [foobar] (from client kosm65-hyper-ap1 port 0 via TLS
tunnel)
(90) } # server inner-tunnel
(90) Virtual server sending reply
(90) Cisco-AVPair = "ssid=vivat"
(90) Simultaneous-Use = 1
(90) MS-MPPE-Encryption-Policy = Encryption-Allowed
(90) MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(90) MS-MPPE-Send-Key = 0x06b51149dd60a7dd863fbdf63d4e5aae
(90) MS-MPPE-Recv-Key = 0x2aa6f2b25652dbed7cc71d010c2ba3b0
(90) EAP-Message = 0x030b0004
(90) Message-Authenticator = 0x00000000000000000000000000000000
(90) User-Name = "foobar"
(90) eap_peap: Got tunneled reply code 2
(90) eap_peap: Cisco-AVPair = "ssid=vivat"
(90) eap_peap: Simultaneous-Use = 1
(90) eap_peap: MS-MPPE-Encryption-Policy = Encryption-Allowed
(90) eap_peap: MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(90) eap_peap: MS-MPPE-Send-Key = 0x06b51149dd60a7dd863fbdf63d4e5aae
(90) eap_peap: MS-MPPE-Recv-Key = 0x2aa6f2b25652dbed7cc71d010c2ba3b0
(90) eap_peap: EAP-Message = 0x030b0004
(90) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(90) eap_peap: User-Name = "foobar"
(90) eap_peap: Got tunneled reply RADIUS code 2
(90) eap_peap: Cisco-AVPair = "ssid=vivat"
(90) eap_peap: Simultaneous-Use = 1
(90) eap_peap: MS-MPPE-Encryption-Policy = Encryption-Allowed
(90) eap_peap: MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(90) eap_peap: MS-MPPE-Send-Key = 0x06b51149dd60a7dd863fbdf63d4e5aae
(90) eap_peap: MS-MPPE-Recv-Key = 0x2aa6f2b25652dbed7cc71d010c2ba3b0
(90) eap_peap: EAP-Message = 0x030b0004
(90) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000
(90) eap_peap: User-Name = "foobar"
(90) eap_peap: Tunneled authentication was successful
(90) eap_peap: SUCCESS
(90) eap: Sending EAP Request (code 1) ID 12 length 43
(90) eap: EAP session adding &reply:State = 0x8fd58b5b85d99215
(90) [eap] = handled
(90) } # authenticate = handled
(90) Using Post-Auth-Type Challenge
(90) Post-Auth-Type sub-section not found. Ignoring.
(90) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(90) Sent Access-Challenge Id 255 from 192.168.6.144:1812 to
192.168.6.150:1645 length 0
(90) EAP-Message =
0x010c002b19001703010020e91613a106bb295cae7b0a87d027ebd712cc411de499bb18808b90b53cc2f15e
(90) Message-Authenticator = 0x00000000000000000000000000000000
(90) State = 0x8fd58b5b85d992156a8b280739c58aaf
(90) Finished request
Waking up in 4.7 seconds.
(91) Received Access-Request Id 0 from 192.168.6.150:1645 to
192.168.6.144:1812 length 251
(91) User-Name = "foobar"
(91) Framed-MTU = 1400
(91) Called-Station-Id = "001f.ca27.9ea0"
(91) Calling-Station-Id = "2c20.0b2a.a0c2"
(91) Cisco-AVPair = "ssid=irma"
(91) WISPr-Location-Name = "First floor, Hyper, Perm"
(91) Service-Type = Login-User
(91) Message-Authenticator = 0x3154a2b0721aee2ca63c2e6768d81709
(91) EAP-Message =
0x020c002b19001703010020ff094574edca9264a4ba9029f063f398dab865c21940041c73d7f143fc9a963b
(91) NAS-Port-Type = Wireless-802.11
(91) NAS-Port = 859591
(91) NAS-Port-Id = "859591"
(91) State = 0x8fd58b5b85d992156a8b280739c58aaf
(91) NAS-IP-Address = 192.168.6.150
(91) NAS-Identifier = "kosm65-hyper-ap1"
(91) session-state: No cached attributes
(91) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(91) authorize {
(91) policy filter_username {
(91) if (!&User-Name) {
(91) if (!&User-Name) -> FALSE
(91) if (&User-Name =~ / /) {
(91) if (&User-Name =~ / /) -> FALSE
(91) if (&User-Name =~ /@.*@/ ) {
(91) if (&User-Name =~ /@.*@/ ) -> FALSE
(91) if (&User-Name =~ /\\.\\./ ) {
(91) if (&User-Name =~ /\\.\\./ ) -> FALSE
(91) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) {
(91) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
-> FALSE
(91) if (&User-Name =~ /\\.$/) {
(91) if (&User-Name =~ /\\.$/) -> FALSE
(91) if (&User-Name =~ /@\\./) {
(91) if (&User-Name =~ /@\\./) -> FALSE
(91) } # policy filter_username = notfound
(91) [preprocess] = ok
(91) [chap] = noop
(91) [mschap] = noop
(91) [digest] = noop
(91) suffix: Checking for suffix after "@"
(91) suffix: No '@' in User-Name = "foobar", looking up realm NULL
(91) suffix: No such realm "NULL"
(91) [suffix] = noop
(91) eap: Peer sent EAP Response (code 2) ID 12 length 43
(91) eap: Continuing tunnel setup
(91) [eap] = ok
(91) } # authorize = ok
(91) Found Auth-Type = eap
(91) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(91) authenticate {
(91) eap: Expiring EAP session with state 0xe59bffd0e591e5ca
(91) eap: Finished EAP session with state 0x8fd58b5b85d99215
(91) eap: Previous EAP request found for state 0x8fd58b5b85d99215,
released from the list
(91) eap: Peer sent packet with method EAP PEAP (25)
(91) eap: Calling submodule eap_peap to process data
(91) eap_peap: Continuing EAP-TLS
(91) eap_peap: [eaptls verify] = ok
(91) eap_peap: Done initial handshake
(91) eap_peap: [eaptls process] = ok
(91) eap_peap: Session established. Decoding tunneled attributes
(91) eap_peap: PEAP state send tlv success
(91) eap_peap: Received EAP-TLV response
(91) eap_peap: Success
(91) eap_peap: No information to cache: session caching will be disabled
for session 85f521474efac4e2d92b4333ade31b11457b502efa6f66a4fe382c1035a654ca
(91) eap: Sending EAP Success (code 3) ID 12 length 4
(91) eap: Freeing handler
(91) [eap] = ok
(91) } # authenticate = ok
(91) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(91) post-auth {
(91) sql: EXPAND .query
(91) sql: --> .query
(91) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (5)
(91) sql: EXPAND %{User-Name}
(91) sql: --> foobar
(91) sql: SQL-User-Name set to 'foobar'
(91) sql: EXPAND INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES('%{User-Name}', '%{%{User-Password}:-Chap-Password}',
'%{reply:Packet-Type}', NOW())
(91) sql: --> INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES('foobar', 'Chap-Password', 'Access-Accept', NOW())
(91) sql: Executing query: INSERT INTO radpostauth (username, pass,
reply, authdate) VALUES('foobar', 'Chap-Password', 'Access-Accept', NOW())
rlm_sql_postgresql: Status: PGRES_COMMAND_OK
rlm_sql_postgresql: query affected rows = 1
(91) sql: SQL query returned: success
(91) sql: 1 record(s) updated
rlm_sql (sql): Released connection (5)
(91) [sql] = ok
(91) [exec] = noop
(91) policy remove_reply_message_if_eap {
(91) if (&reply:EAP-Message && &reply:Reply-Message) {
(91) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(91) else {
(91) [noop] = noop
(91) } # else = noop
(91) } # policy remove_reply_message_if_eap = noop
(91) } # post-auth = ok
(91) Login OK: [foobar] (from client kosm65-hyper-ap1 port 859591 cli
2c20.0b2a.a0c2)
(91) Sent Access-Accept Id 0 from 192.168.6.144:1812 to
192.168.6.150:1645 length 0
(91) MS-MPPE-Recv-Key =
0xc82a301b5b4493b1aea74d7f93996bec688a0dfe8c4858989d4dca2e2d8436f0
(91) MS-MPPE-Send-Key =
0x1abe38ea076f9ba252e4bd2d42bb73aa9ad2ae4812b80b808e496b4c7e80e1aa
(91) EAP-Message = 0x030c0004
(91) Message-Authenticator = 0x00000000000000000000000000000000
(91) User-Name = "foobar"
(91) Finished request
Waking up in 4.7 seconds.
===Cut===
What bothers me is that after the line
Login OK: [foobar] (from client kosm65-hyper-ap1 port 0 via TLS tunnel)
I see a full Access-Accept answer, which does contain the Cisco-AVPair
attribute. But then for some reason there is a second Access-Request
from the same AP, and this time freeradius answers with a short
Access-Accept message, after a line
Login OK: [foobar] (from client kosm65-hyper-ap1 port 859591 cli
2c20.0b2a.a0c2)
Why does this happens and how do I fix it ?
Thanks.
Eugene.
More information about the Freeradius-Users
mailing list