Hi Alan, Thanks for the quick reply...
Try 3.0.11. It has a number of issues fixed over 3.0.4. We run a central repository mirror in each data centre with fairly strict policies about installing packages (only RPMs) not on the central repo but I'll enquire about letting me at least test installing from source as a test.
And.... what does the debug output of the *server* say?
From the RADIUS server debug on both versions the only difference I have seen between the old ver 1 and the new ver 3 is that the "Tunnel-Password" and the two "Cisco-AVPair" values are enclosed in single quote on ver 3 and double quotes on ver 1 The other difference I see is on the Cisco debug radius in that the test against the ver 1 server Cisco shows " RADIUS: Tunnel-Password [69] 53 00:*" but against ver 3 server it shows " RADIUS: Tunnel-Password [69] 52 00:*" - 53 verse 52 for the Tunnel-Password attribute length. The Tunnel-Password is just a 32 byte randomly generated string.
This is the "radiusd -Xxx" debug from the ver 3 server for the test I run on the Cisco router... Received Access-Request Id 21 from 172.16.0.1:1645 to 172.16.0.2:18122 length 57 User-Password = 'cisco' User-Name = 'user-name' NAS-IP-Address = 172.16.0.1 Mon Apr 18 15:38:27 2016 : Debug: (0) Received Access-Request packet from host 172.16.0.1 port 1645, id=21, length=57 Mon Apr 18 15:38:27 2016 : Debug: (0) User-Password = 'cisco' Mon Apr 18 15:38:27 2016 : Debug: (0) User-Name = 'user-name' Mon Apr 18 15:38:27 2016 : Debug: (0) NAS-IP-Address = 172.16.0.1 Mon Apr 18 15:38:27 2016 : Debug: (0) # Executing section authorize from file /etc/raddb-vpnclient_za/sites-enabled/default Mon Apr 18 15:38:27 2016 : Debug: (0) authorize { Mon Apr 18 15:38:27 2016 : Debug: (0) filter_username filter_username { Mon Apr 18 15:38:27 2016 : Debug: (0) if (!&User-Name) Mon Apr 18 15:38:27 2016 : Debug: (0) if (!&User-Name) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ / /) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ / /) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /@.*@/ ) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /\\.\\./ ) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Apr 18 15:38:27 2016 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /\\.$/) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /\\.$/) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /@\\./) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&User-Name =~ /@\\./) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) } # filter_username filter_username = notfound Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [preprocess] = ok Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [chap] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [mschap] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling digest (rlm_digest) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from digest (rlm_digest) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [digest] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) suffix : Checking for suffix after "@" Mon Apr 18 15:38:27 2016 : Debug: (0) suffix : No '@' in User-Name = "user-name", looking up realm NULL Mon Apr 18 15:38:27 2016 : Debug: (0) suffix : No such realm "NULL" Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [suffix] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) eap : No EAP-Message, not doing EAP Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [eap] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling files (rlm_files) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [files] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling sql (rlm_sql) for request 0 Mon Apr 18 15:38:27 2016 : Debug: %{User-Name} Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: attribute --> User-Name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND %{User-Name} Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> user-name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : SQL-User-Name set to 'user-name' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: FROM 1 TO 5 MAX 6 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining SQL-User-Name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING SQL-User-Name FROM 0 TO 5 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: TO in 5 out 6 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[0] = User-Password Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[1] = User-Name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[2] = NAS-IP-Address Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[3] = Event-Timestamp Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[4] = Huntgroup-Name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[5] = SQL-User-Name Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Reserved connection (4) Mon Apr 18 15:38:27 2016 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Mon Apr 18 15:38:27 2016 : Debug: attribute --> SQL-User-Name Mon Apr 18 15:38:27 2016 : Debug: literal --> ' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user-name' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user-name' ORDER BY id' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : User found in radcheck table Mon Apr 18 15:38:27 2016 : Debug: (0) sql : Check items matched Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: FROM 1 TO 0 MAX 1 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Cleartext-Password Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Cleartext-Password FROM 0 TO 0 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: TO in 0 out 1 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[0] = Cleartext-Password Mon Apr 18 15:38:27 2016 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = ' Mon Apr 18 15:38:27 2016 : Debug: attribute --> SQL-User-Name Mon Apr 18 15:38:27 2016 : Debug: literal --> ' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'user-name' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radreply WHERE username = 'user-name' ORDER BY id' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ... falling-through to group processing Mon Apr 18 15:38:27 2016 : Debug: SELECT groupname FROM usergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: literal --> SELECT groupname FROM usergroup WHERE username = ' Mon Apr 18 15:38:27 2016 : Debug: attribute --> SQL-User-Name Mon Apr 18 15:38:27 2016 : Debug: literal --> ' ORDER BY priority Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND SELECT groupname FROM usergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> SELECT groupname FROM usergroup WHERE username = 'user-name' ORDER BY priority Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Executing query: 'SELECT groupname FROM usergroup WHERE username = 'user-name' ORDER BY priority' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : User found in the group table Mon Apr 18 15:38:27 2016 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = ' Mon Apr 18 15:38:27 2016 : Debug: attribute --> Sql-Group Mon Apr 18 15:38:27 2016 : Debug: literal --> ' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'user-name-nas' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'user-name-nas' ORDER BY id' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : Group "user-name-nas" check items matched Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: FROM 1 TO 1 MAX 2 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Huntgroup-Name Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Huntgroup-Name FROM 0 TO 1 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: TO in 1 out 2 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[0] = Cleartext-Password Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[1] = Huntgroup-Name Mon Apr 18 15:38:27 2016 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: Parsed xlat tree: Mon Apr 18 15:38:27 2016 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = ' Mon Apr 18 15:38:27 2016 : Debug: attribute --> Sql-Group Mon Apr 18 15:38:27 2016 : Debug: literal --> ' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: (0) sql : --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'user-name-nas' ORDER BY id Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'user-name-nas' ORDER BY id' Mon Apr 18 15:38:27 2016 : Debug: (0) sql : Group "user-name-nas" reply items processed Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: FROM 5 TO 0 MAX 5 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Service-Type Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Service-Type FROM 0 TO 0 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Tunnel-Type Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Tunnel-Type FROM 1 TO 1 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Tunnel-Password Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Tunnel-Password FROM 2 TO 2 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Cisco-AVPair Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Cisco-AVPair FROM 3 TO 3 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: Examining Cisco-AVPair Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: APPENDING Cisco-AVPair FROM 4 TO 4 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: TO in 0 out 5 Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[0] = Service-Type Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[1] = Tunnel-Type Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[2] = Tunnel-Password Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[3] = Cisco-AVPair Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ::: to[4] = Cisco-AVPair Mon Apr 18 15:38:27 2016 : Debug: (0) sql : ... falling-through to profile processing Mon Apr 18 15:38:27 2016 : Debug: rlm_sql (sql): Released connection (4) Mon Apr 18 15:38:27 2016 : Info: rlm_sql (sql): Closing connection (0), from 1 unused connections Mon Apr 18 15:38:27 2016 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from sql (rlm_sql) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [sql] = ok Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [expiration] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [logintime] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [pap] = updated Mon Apr 18 15:38:27 2016 : Debug: (0) } # authorize = updated Mon Apr 18 15:38:27 2016 : Debug: (0) Found Auth-Type = PAP Mon Apr 18 15:38:27 2016 : Debug: (0) # Executing group from file /etc/raddb-vpnclient_za/sites-enabled/default Mon Apr 18 15:38:27 2016 : Debug: (0) Auth-Type PAP { Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authenticate]: calling pap (rlm_pap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) pap : Login attempt with password "cisco" Mon Apr 18 15:38:27 2016 : Debug: (0) pap : Comparing with "known good" Cleartext-Password "cisco" Mon Apr 18 15:38:27 2016 : Debug: (0) pap : User authenticated successfully Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[authenticate]: returned from pap (rlm_pap) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [pap] = ok Mon Apr 18 15:38:27 2016 : Debug: (0) } # Auth-Type PAP = ok Mon Apr 18 15:38:27 2016 : Auth: (0) Login OK: [user-name] (from client cavalier port 0) Mon Apr 18 15:38:27 2016 : Debug: (0) # Executing section post-auth from file /etc/raddb-vpnclient_za/sites-enabled/default Mon Apr 18 15:38:27 2016 : Debug: (0) post-auth { Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[post-auth]: calling exec (rlm_exec) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[post-auth]: returned from exec (rlm_exec) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [exec] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) remove_reply_message_if_eap remove_reply_message_if_eap { Mon Apr 18 15:38:27 2016 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) Mon Apr 18 15:38:27 2016 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Mon Apr 18 15:38:27 2016 : Debug: (0) else else { Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[post-auth]: calling noop (rlm_always) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) modsingle[post-auth]: returned from noop (rlm_always) for request 0 Mon Apr 18 15:38:27 2016 : Debug: (0) [noop] = noop Mon Apr 18 15:38:27 2016 : Debug: (0) } # else else = noop Mon Apr 18 15:38:27 2016 : Debug: (0) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop Mon Apr 18 15:38:27 2016 : Debug: (0) } # post-auth = noop Mon Apr 18 15:38:27 2016 : Debug: (0) Sending Access-Accept packet to host 172.16.0.1 port 1645, id=21, length=0 Mon Apr 18 15:38:27 2016 : Debug: (0) Service-Type = Outbound-User Mon Apr 18 15:38:27 2016 : Debug: (0) Tunnel-Type = ESP Mon Apr 18 15:38:27 2016 : Debug: (0) Tunnel-Password = 'xbHLhNm79ZNZi2CYw7TWFPSiRGX0Toee' Mon Apr 18 15:38:27 2016 : Debug: (0) Cisco-AVPair = 'ipsec:key-exchange=ike' Mon Apr 18 15:38:27 2016 : Debug: (0) Cisco-AVPair = 'ipsec:key-exchange=preshared-key' Sending Access-Accept Id 21 from 172.16.0.2:18122 to 172.16.0.1:1645 Service-Type = Outbound-User Tunnel-Type = ESP Tunnel-Password = 'xbHLhNm79ZNZi2CYw7TWFPSiRGX0Toee' Cisco-AVPair = 'ipsec:key-exchange=ike' Cisco-AVPair = 'ipsec:key-exchange=preshared-key' Mon Apr 18 15:38:27 2016 : Debug: (0) Finished request Mon Apr 18 15:38:27 2016 : Debug: Waking up in 0.3 seconds. Mon Apr 18 15:38:27 2016 : Debug: Waking up in 4.6 seconds. Mon Apr 18 15:38:32 2016 : Debug: (0) Cleaning up request packet ID 21 with timestamp +56 Mon Apr 18 15:38:32 2016 : Info: Ready to process requests
Please send me a packet trace from 1.1.3 and 3.0.4. Are you referring to a tcpflow to capture the traffic?
Rhys McWilliams ---------------------------------------------------------------------- This message and any attachments are intended only for the use of the addressee and may contain information that is privileged and confidential. If the reader of the message is not the intended recipient or an authorized representative of the intended recipient, you are hereby notified that any dissemination of this communication is strictly prohibited. If you have received this communication in error, notify the sender immediately by return email and delete the message and any attachments from your system.