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.