Freeradius on Ubuntu 19.10

19 Dec 2019

      Hello,

I'll be trying the latest Freeradius on Ubuntu 19.10 and I can't seem to be
able to connect.

Can someone please help me? Something seems to have changed.

Many Thanks,

(4) Received Access-Request Id 128 from 127.0.0.1:48822 to 127.0.0.1:1812
length 157

(4)   User-Name = "houman"

(4)   NAS-Port-Type = Virtual

(4)   Service-Type = Framed-User

(4)   NAS-Port = 3

(4)   NAS-Port-Id = "X-1"

(4)   NAS-IP-Address = 172.31.20.12

(4)   Called-Station-Id = "172.31.20.12[4500]"

(4)   Calling-Station-Id = "185.76.230.248[38823]"

(4)   Acct-Session-Id = "1576757594-3"

(4)   EAP-Message = 0x0200000b01686f756d616e

(4)   NAS-Identifier = "strongSwan"

(4)   Message-Authenticator = 0x7e6d9c86703eecf1dc78e34980d98a68

(4) # Executing section authorize from file
/etc/freeradius/3.0/sites-enabled/default

(4)   authorize {

(4)     update control {

(4)       EXPAND %l

(4)          --> 1576757818

(4)       &Current-Timestamp := 1576757818

(4)     } # update control = noop

(4)     update request {

rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 90
seconds

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 90
seconds

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 90
seconds

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 90
seconds

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 90
seconds

rlm_sql (sql): You probably need to lower "min"

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 90
seconds

rlm_sql (sql): You probably need to lower "min"

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 90
seconds

rlm_sql (sql): You probably need to lower "min"

rlm_sql_mysql: Socket destructor called, closing socket

rlm_sql (sql): 0 of 0 connections in use.  You  may need to increase "spare"

rlm_sql (sql): Opening additional connection (7), 1 of 32 pending slots used

rlm_sql_mysql: Starting connect to MySQL server

rlm_sql_mysql: Connected to database 'radius_db' on xx.xxx.xx.xx via
TCP/IP, server version 8.0.18, protocol version 10

rlm_sql (sql): Reserved connection (7)

rlm_sql (sql): Released connection (7)

Need 2 more connections to reach min connections (3)

rlm_sql (sql): Opening additional connection (8), 1 of 31 pending slots used

rlm_sql_mysql: Starting connect to MySQL server

rlm_sql_mysql: Connected to database 'radius_db' on xx.xxx.xx.xx via
TCP/IP, server version 8.0.18, protocol version 10

(4)       EXPAND %{User-Name}

(4)          --> houman

(4)       SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (7)

(4)       Executing select query: SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='houman'

rlm_sql (sql): Released connection (7)

(4)       EXPAND %{sql:SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='%{User-Name}'}

(4)          --> 1735689600

(4)       &Expires-Timestamp := 1735689600

(4)     } # update request = noop

(4)     if (&control:Current-Timestamp > &request:Expires-Timestamp) {

(4)     if (&control:Current-Timestamp > &request:Expires-Timestamp)  ->
FALSE

(4)     policy filter_username {

(4)       if (&User-Name) {

(4)       if (&User-Name)  -> TRUE

(4)       if (&User-Name)  {

(4)         if (&User-Name =~ / /) {

(4)         if (&User-Name =~ / /)  -> FALSE

(4)         if (&User-Name =~ /@[^@]*@/ ) {

(4)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE

(4)         if (&User-Name =~ /\.\./ ) {

(4)         if (&User-Name =~ /\.\./ )  -> FALSE

(4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {

(4)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   ->
FALSE

(4)         if (&User-Name =~ /\.$/)  {

(4)         if (&User-Name =~ /\.$/)   -> FALSE

(4)         if (&User-Name =~ /@\./)  {

(4)         if (&User-Name =~ /@\./)   -> FALSE

(4)       } # if (&User-Name)  = noop

(4)     } # policy filter_username = noop

(4)     [preprocess] = ok

(4)     [chap] = noop

(4)     [mschap] = noop

(4)     [digest] = noop

(4) suffix: Checking for suffix after "@"

(4) suffix: No '@' in User-Name = "houman", looking up realm NULL

(4) suffix: No such realm "NULL"

(4)     [suffix] = noop

(4) eap: Peer sent EAP Response (code 2) ID 0 length 11

(4) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the
rest of authorize

(4)     [eap] = ok

(4)   } # authorize = ok

(4) Found Auth-Type = eap

(4) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(4)   authenticate {

(4) eap: Peer sent packet with method EAP Identity (1)

(4) eap: Calling submodule eap_md5 to process data

(4) eap_md5: Issuing MD5 Challenge

(4) eap: Sending EAP Request (code 1) ID 1 length 22

(4) eap: EAP session adding &reply:State = 0xa17deb22a17ceffe

(4)     [eap] = handled

(4)   } # authenticate = handled

(4) Using Post-Auth-Type Challenge

(4) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(4)   Challenge { ... } # empty sub-section is ignored

(4) Sent Access-Challenge Id 128 from 127.0.0.1:1812 to 127.0.0.1:48822
length 0

(4)   EAP-Message = 0x0101001604103a8af45976daf8a272f4e1044cbca4ea

(4)   Message-Authenticator = 0x00000000000000000000000000000000

(4)   State = 0xa17deb22a17ceffef01faedaf7cde45b

(4) Finished request

Waking up in 4.9 seconds.

(5) Received Access-Request Id 129 from 127.0.0.1:48822 to 127.0.0.1:1812
length 170

(5)   User-Name = "houman"

(5)   NAS-Port-Type = Virtual

(5)   Service-Type = Framed-User

(5)   NAS-Port = 3

(5)   NAS-Port-Id = "X-1"

(5)   NAS-IP-Address = 172.31.20.12

(5)   Called-Station-Id = "172.31.20.12[4500]"

(5)   Calling-Station-Id = "185.76.230.248[38823]"

(5)   Acct-Session-Id = "1576757594-3"

(5)   EAP-Message = 0x02010006031a

(5)   NAS-Identifier = "strongSwan"

(5)   State = 0xa17deb22a17ceffef01faedaf7cde45b

(5)   Message-Authenticator = 0x72dac90f5d0d96fc8992a391980d751b

(5) session-state: No cached attributes

(5) # Executing section authorize from file
/etc/freeradius/3.0/sites-enabled/default

(5)   authorize {

(5)     update control {

(5)       EXPAND %l

(5)          --> 1576757818

(5)       &Current-Timestamp := 1576757818

(5)     } # update control = noop

(5)     update request {

rlm_sql (sql): Reserved connection (8)

rlm_sql (sql): Released connection (8)

(5)       EXPAND %{User-Name}

(5)          --> houman

(5)       SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (7)

(5)       Executing select query: SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='houman'

rlm_sql (sql): Released connection (7)

(5)       EXPAND %{sql:SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='%{User-Name}'}

(5)          --> 1735689600

(5)       &Expires-Timestamp := 1735689600

(5)     } # update request = noop

(5)     if (&control:Current-Timestamp > &request:Expires-Timestamp) {

(5)     if (&control:Current-Timestamp > &request:Expires-Timestamp)  ->
FALSE

(5)     policy filter_username {

(5)       if (&User-Name) {

(5)       if (&User-Name)  -> TRUE

(5)       if (&User-Name)  {

(5)         if (&User-Name =~ / /) {

(5)         if (&User-Name =~ / /)  -> FALSE

(5)         if (&User-Name =~ /@[^@]*@/ ) {

(5)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE

(5)         if (&User-Name =~ /\.\./ ) {

(5)         if (&User-Name =~ /\.\./ )  -> FALSE

(5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {

(5)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   ->
FALSE

(5)         if (&User-Name =~ /\.$/)  {

(5)         if (&User-Name =~ /\.$/)   -> FALSE

(5)         if (&User-Name =~ /@\./)  {

(5)         if (&User-Name =~ /@\./)   -> FALSE

(5)       } # if (&User-Name)  = noop

(5)     } # policy filter_username = noop

(5)     [preprocess] = ok

(5)     [chap] = noop

(5)     [mschap] = noop

(5)     [digest] = noop

(5) suffix: Checking for suffix after "@"

(5) suffix: No '@' in User-Name = "houman", looking up realm NULL

(5) suffix: No such realm "NULL"

(5)     [suffix] = noop

(5) eap: Peer sent EAP Response (code 2) ID 1 length 6

(5) eap: No EAP Start, assuming it's an on-going EAP conversation

(5)     [eap] = updated

(5) sql: EXPAND %{User-Name}

(5) sql:    --> houman

(5) sql: SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (8)

(5) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck
WHERE username = '%{SQL-User-Name}' ORDER BY id

(5) sql:    --> SELECT id, username, attribute, value, op FROM radcheck
WHERE username = 'houman' ORDER BY id

(5) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'houman' ORDER BY id

(5) sql: User found in radcheck table

(5) sql: Conditional check items matched, merging assignment check items

(5) sql:   Cleartext-Password := "houman@lovesyou"

(5) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply
WHERE username = '%{SQL-User-Name}' ORDER BY id

(5) sql:    --> SELECT id, username, attribute, value, op FROM radreply
WHERE username = 'houman' ORDER BY id

(5) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'houman' ORDER BY id

rlm_sql (sql): Reserved connection (7)

rlm_sql (sql): Released connection (7)

(5) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority

(5) sql:    --> SELECT groupname FROM radusergroup WHERE username =
'houman' ORDER BY priority

(5) sql: Executing select query: SELECT groupname FROM radusergroup WHERE
username = 'houman' ORDER BY priority

(5) sql: User not found in any groups

rlm_sql (sql): Released connection (8)

(5)     [sql] = ok

(5)     [expiration] = noop

(5)     [logintime] = noop

(5) pap: WARNING: Auth-Type already set.  Not setting to PAP

(5)     [pap] = noop

(5)   } # authorize = updated

(5) Found Auth-Type = eap

(5) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(5)   authenticate {

(5) eap: Expiring EAP session with state 0xa17deb22a17ceffe

(5) eap: Finished EAP session with state 0xa17deb22a17ceffe

(5) eap: Previous EAP request found for state 0xa17deb22a17ceffe, released
from the list

(5) eap: Peer sent packet with method EAP NAK (3)

(5) eap: Found mutually acceptable type MSCHAPv2 (26)

(5) eap: Calling submodule eap_mschapv2 to process data

(5) eap_mschapv2: Issuing Challenge

(5) eap: Sending EAP Request (code 1) ID 2 length 43

(5) eap: EAP session adding &reply:State = 0xa17deb22a07ff1fe

(5)     [eap] = handled

(5)   } # authenticate = handled

(5) Using Post-Auth-Type Challenge

(5) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(5)   Challenge { ... } # empty sub-section is ignored

(5) Sent Access-Challenge Id 129 from 127.0.0.1:1812 to 127.0.0.1:48822
length 0

(5)   EAP-Message =
0x0102002b1a01020026109ea8499d23b221fe286e0553b2afd879667265657261646975732d332e302e3139

(5)   Message-Authenticator = 0x00000000000000000000000000000000

(5)   State = 0xa17deb22a07ff1fef01faedaf7cde45b

(5) Finished request

Waking up in 4.8 seconds.

(6) Received Access-Request Id 130 from 127.0.0.1:48822 to 127.0.0.1:1812
length 229

(6)   User-Name = "houman"

(6)   NAS-Port-Type = Virtual

(6)   Service-Type = Framed-User

(6)   NAS-Port = 3

(6)   NAS-Port-Id = "X-1"

(6)   NAS-IP-Address = 172.31.20.12

(6)   Called-Station-Id = "172.31.20.12[4500]"

(6)   Calling-Station-Id = "185.76.230.248[38823]"

(6)   Acct-Session-Id = "1576757594-3"

(6)   EAP-Message =
0x020200411a0202003c316473cdfd9ba7577369c536ec1a3732170000000000000000bdd8d54efc713f6c117e2db89759acfa868367fc3920267200686f756d616e

(6)   NAS-Identifier = "strongSwan"

(6)   State = 0xa17deb22a07ff1fef01faedaf7cde45b

(6)   Message-Authenticator = 0xe167fa7a298b2393526a662c1298ce92

(6) session-state: No cached attributes

(6) # Executing section authorize from file
/etc/freeradius/3.0/sites-enabled/default

(6)   authorize {

(6)     update control {

(6)       EXPAND %l

(6)          --> 1576757818

(6)       &Current-Timestamp := 1576757818

(6)     } # update control = noop

(6)     update request {

rlm_sql (sql): Reserved connection (8)

rlm_sql (sql): Released connection (8)

(6)       EXPAND %{User-Name}

(6)          --> houman

(6)       SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (7)

(6)       Executing select query: SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='houman'

rlm_sql (sql): Released connection (7)

(6)       EXPAND %{sql:SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='%{User-Name}'}

(6)          --> 1735689600

(6)       &Expires-Timestamp := 1735689600

(6)     } # update request = noop

(6)     if (&control:Current-Timestamp > &request:Expires-Timestamp) {

(6)     if (&control:Current-Timestamp > &request:Expires-Timestamp)  ->
FALSE

(6)     policy filter_username {

(6)       if (&User-Name) {

(6)       if (&User-Name)  -> TRUE

(6)       if (&User-Name)  {

(6)         if (&User-Name =~ / /) {

(6)         if (&User-Name =~ / /)  -> FALSE

(6)         if (&User-Name =~ /@[^@]*@/ ) {

(6)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE

(6)         if (&User-Name =~ /\.\./ ) {

(6)         if (&User-Name =~ /\.\./ )  -> FALSE

(6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {

(6)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   ->
FALSE

(6)         if (&User-Name =~ /\.$/)  {

(6)         if (&User-Name =~ /\.$/)   -> FALSE

(6)         if (&User-Name =~ /@\./)  {

(6)         if (&User-Name =~ /@\./)   -> FALSE

(6)       } # if (&User-Name)  = noop

(6)     } # policy filter_username = noop

(6)     [preprocess] = ok

(6)     [chap] = noop

(6)     [mschap] = noop

(6)     [digest] = noop

(6) suffix: Checking for suffix after "@"

(6) suffix: No '@' in User-Name = "houman", looking up realm NULL

(6) suffix: No such realm "NULL"

(6)     [suffix] = noop

(6) eap: Peer sent EAP Response (code 2) ID 2 length 65

(6) eap: No EAP Start, assuming it's an on-going EAP conversation

(6)     [eap] = updated

(6) sql: EXPAND %{User-Name}

(6) sql:    --> houman

(6) sql: SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (8)

(6) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck
WHERE username = '%{SQL-User-Name}' ORDER BY id

(6) sql:    --> SELECT id, username, attribute, value, op FROM radcheck
WHERE username = 'houman' ORDER BY id

(6) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'houman' ORDER BY id

(6) sql: User found in radcheck table

(6) sql: Conditional check items matched, merging assignment check items

(6) sql:   Cleartext-Password := "houman@lovesyou"

(6) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply
WHERE username = '%{SQL-User-Name}' ORDER BY id

(6) sql:    --> SELECT id, username, attribute, value, op FROM radreply
WHERE username = 'houman' ORDER BY id

(6) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'houman' ORDER BY id

rlm_sql (sql): Reserved connection (7)

rlm_sql (sql): Released connection (7)

(6) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority

(6) sql:    --> SELECT groupname FROM radusergroup WHERE username =
'houman' ORDER BY priority

(6) sql: Executing select query: SELECT groupname FROM radusergroup WHERE
username = 'houman' ORDER BY priority

(6) sql: User not found in any groups

rlm_sql (sql): Released connection (8)

(6)     [sql] = ok

(6)     [expiration] = noop

(6)     [logintime] = noop

(6) pap: WARNING: Auth-Type already set.  Not setting to PAP

(6)     [pap] = noop

(6)   } # authorize = updated

(6) Found Auth-Type = eap

(6) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(6)   authenticate {

(6) eap: Expiring EAP session with state 0xa17deb22a07ff1fe

(6) eap: Finished EAP session with state 0xa17deb22a07ff1fe

(6) eap: Previous EAP request found for state 0xa17deb22a07ff1fe, released
from the list

(6) eap: Peer sent packet with method EAP MSCHAPv2 (26)

(6) eap: Calling submodule eap_mschapv2 to process data

(6) eap_mschapv2: # Executing group from file
/etc/freeradius/3.0/sites-enabled/default

(6) eap_mschapv2:   authenticate {

(6) mschap: Found Cleartext-Password, hashing to create NT-Password

(6) mschap: Found Cleartext-Password, hashing to create LM-Password

(6) mschap: Creating challenge hash with username: houman

(6) mschap: Client is using MS-CHAPv2

(6) mschap: Adding MS-CHAPv2 MPPE keys

(6) eap_mschapv2:     [mschap] = ok

(6) eap_mschapv2:   } # authenticate = ok

(6) eap_mschapv2: MSCHAP Success

(6) eap: Sending EAP Request (code 1) ID 3 length 51

(6) eap: EAP session adding &reply:State = 0xa17deb22a37ef1fe

(6)     [eap] = handled

(6)   } # authenticate = handled

(6) Using Post-Auth-Type Challenge

(6) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(6)   Challenge { ... } # empty sub-section is ignored

(6) Sent Access-Challenge Id 130 from 127.0.0.1:1812 to 127.0.0.1:48822
length 0

(6)   EAP-Message =
0x010300331a0302002e533d33303232453237443943444437313237423132413042323041304536444630314333323741323538

(6)   Message-Authenticator = 0x00000000000000000000000000000000

(6)   State = 0xa17deb22a37ef1fef01faedaf7cde45b

(6) Finished request

Waking up in 4.7 seconds.

(7) Received Access-Request Id 131 from 127.0.0.1:48822 to 127.0.0.1:1812
length 170

(7)   User-Name = "houman"

(7)   NAS-Port-Type = Virtual

(7)   Service-Type = Framed-User

(7)   NAS-Port = 3

(7)   NAS-Port-Id = "X-1"

(7)   NAS-IP-Address = 172.31.20.12

(7)   Called-Station-Id = "172.31.20.12[4500]"

(7)   Calling-Station-Id = "185.76.230.248[38823]"

(7)   Acct-Session-Id = "1576757594-3"

(7)   EAP-Message = 0x020300061a03

(7)   NAS-Identifier = "strongSwan"

(7)   State = 0xa17deb22a37ef1fef01faedaf7cde45b

(7)   Message-Authenticator = 0x23f98c032ec4bbd63d42cd63c25f36f7

(7) session-state: No cached attributes

(7) # Executing section authorize from file
/etc/freeradius/3.0/sites-enabled/default

(7)   authorize {

(7)     update control {

(7)       EXPAND %l

(7)          --> 1576757818

(7)       &Current-Timestamp := 1576757818

(7)     } # update control = noop

(7)     update request {

rlm_sql (sql): Reserved connection (8)

rlm_sql (sql): Released connection (8)

(7)       EXPAND %{User-Name}

(7)          --> houman

(7)       SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (7)

(7)       Executing select query: SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='houman'

rlm_sql (sql): Released connection (7)

(7)       EXPAND %{sql:SELECT UNIX_TIMESTAMP(expires_at) FROM
main_db.`user` WHERE main_db.`user`.username ='%{User-Name}'}

(7)          --> 1735689600

(7)       &Expires-Timestamp := 1735689600

(7)     } # update request = noop

(7)     if (&control:Current-Timestamp > &request:Expires-Timestamp) {

(7)     if (&control:Current-Timestamp > &request:Expires-Timestamp)  ->
FALSE

(7)     policy filter_username {

(7)       if (&User-Name) {

(7)       if (&User-Name)  -> TRUE

(7)       if (&User-Name)  {

(7)         if (&User-Name =~ / /) {

(7)         if (&User-Name =~ / /)  -> FALSE

(7)         if (&User-Name =~ /@[^@]*@/ ) {

(7)         if (&User-Name =~ /@[^@]*@/ )  -> FALSE

(7)         if (&User-Name =~ /\.\./ ) {

(7)         if (&User-Name =~ /\.\./ )  -> FALSE

(7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))  {

(7)         if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/))   ->
FALSE

(7)         if (&User-Name =~ /\.$/)  {

(7)         if (&User-Name =~ /\.$/)   -> FALSE

(7)         if (&User-Name =~ /@\./)  {

(7)         if (&User-Name =~ /@\./)   -> FALSE

(7)       } # if (&User-Name)  = noop

(7)     } # policy filter_username = noop

(7)     [preprocess] = ok

(7)     [chap] = noop

(7)     [mschap] = noop

(7)     [digest] = noop

(7) suffix: Checking for suffix after "@"

(7) suffix: No '@' in User-Name = "houman", looking up realm NULL

(7) suffix: No such realm "NULL"

(7)     [suffix] = noop

(7) eap: Peer sent EAP Response (code 2) ID 3 length 6

(7) eap: No EAP Start, assuming it's an on-going EAP conversation

(7)     [eap] = updated

(7) sql: EXPAND %{User-Name}

(7) sql:    --> houman

(7) sql: SQL-User-Name set to 'houman'

rlm_sql (sql): Reserved connection (8)

(7) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck
WHERE username = '%{SQL-User-Name}' ORDER BY id

(7) sql:    --> SELECT id, username, attribute, value, op FROM radcheck
WHERE username = 'houman' ORDER BY id

(7) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'houman' ORDER BY id

(7) sql: User found in radcheck table

(7) sql: Conditional check items matched, merging assignment check items

(7) sql:   Cleartext-Password := "houman@lovesyou"

(7) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply
WHERE username = '%{SQL-User-Name}' ORDER BY id

(7) sql:    --> SELECT id, username, attribute, value, op FROM radreply
WHERE username = 'houman' ORDER BY id

(7) sql: Executing select query: SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'houman' ORDER BY id

rlm_sql (sql): Reserved connection (7)

rlm_sql (sql): Released connection (7)

Need 1 more connections to reach min connections (3)

rlm_sql (sql): Opening additional connection (9), 1 of 30 pending slots used

rlm_sql_mysql: Starting connect to MySQL server

rlm_sql_mysql: Connected to database 'radius_db' on xx.xxx.xx.xx via
TCP/IP, server version 8.0.18, protocol version 10

(7) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority

(7) sql:    --> SELECT groupname FROM radusergroup WHERE username =
'houman' ORDER BY priority

(7) sql: Executing select query: SELECT groupname FROM radusergroup WHERE
username = 'houman' ORDER BY priority

(7) sql: User not found in any groups

rlm_sql (sql): Released connection (8)

(7)     [sql] = ok

(7)     [expiration] = noop

(7)     [logintime] = noop

(7) pap: WARNING: Auth-Type already set.  Not setting to PAP

(7)     [pap] = noop

(7)   } # authorize = updated

(7) Found Auth-Type = eap

(7) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(7)   authenticate {

(7) eap: Expiring EAP session with state 0xa17deb22a37ef1fe

(7) eap: Finished EAP session with state 0xa17deb22a37ef1fe

(7) eap: Previous EAP request found for state 0xa17deb22a37ef1fe, released
from the list

(7) eap: Peer sent packet with method EAP MSCHAPv2 (26)

(7) eap: Calling submodule eap_mschapv2 to process data

(7) eap: Sending EAP Success (code 3) ID 3 length 4

(7) eap: Freeing handler

(7)     [eap] = ok

(7)   } # authenticate = ok

(7) # Executing section post-auth from file
/etc/freeradius/3.0/sites-enabled/default

(7)   post-auth {

(7)     update reply {

(7)       Acct-Interim-Interval = 300

(7)     } # update reply = noop

(7)     if (session-state:User-Name && reply:User-Name && request:User-Name
&& (reply:User-Name == request:User-Name)) {

(7)     if (session-state:User-Name && reply:User-Name && request:User-Name
&& (reply:User-Name == request:User-Name))  -> FALSE

(7)     update {

(7)       No attributes updated for RHS &session-state:

(7)     } # update = noop

(7)     policy sql_session_start.post-auth {

(7)       policy acct_unique {

(7)         update request {

(7)           &Tmp-String-9 := "ai:"

(7)         } # update request = noop

(7)         if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) &&
("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {

(7)         EXPAND %{hex:&Class}

(7)            -->

(7)         EXPAND ^%{hex:&Tmp-String-9}

(7)            --> ^61693a

(7)         if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) &&
("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i))  -> FALSE

(7)         else {

(7)           update request {

(7)             EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}

(7)                --> 4777c724ef84c2fd714218f9256dac76

(7)             &Acct-Unique-Session-Id := 4777c724ef84c2fd714218f9256dac76

(7)           } # update request = noop

(7)         } # else = noop

(7)       } # policy acct_unique = noop

(7) sql: EXPAND
%{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}

(7) sql:    --> type.post-auth.query

(7) sql: Using query template 'query'

rlm_sql (sql): Reserved connection (8)

(7) sql: EXPAND %{User-Name}

(7) sql:    --> houman

(7) sql: SQL-User-Name set to 'houman'

(7) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime,
acctstoptime, acctsessiontime, acctauthentic, connectinfo_start,
connectinfo_stop,
acctinputoctets, acctoutputoctets, calledstationid, callingstationid,
acctterminatecause, servicetype, framedprotocol, framedipaddress,
framedipv6address, framedipv6prefix, framedinterfaceid, delegatedipv6prefix)
VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}',
'%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}',
NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}',
FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, NULL, 0, '',
'%{Connect-Info}', NULL, 0, 0, '%{Called-Station-Id}',
'%{Calling-Station-Id}', NULL, '%{Service-Type}', NULL, '', '', '', '', '')

(7) sql:    --> INSERT INTO radacct (acctsessionid, acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime,
acctstoptime, acctsessiontime, acctauthentic, connectinfo_start,
connectinfo_stop,
acctinputoctets, acctoutputoctets, calledstationid, callingstationid,
acctterminatecause, servicetype, framedprotocol, framedipaddress,
framedipv6address, framedipv6prefix, framedinterfaceid, delegatedipv6prefix)
VALUES('1576757594-3', '4777c724ef84c2fd714218f9256dac76', 'houman', '',
'172.31.20.12', NULLIF('X-1', ''), 'Virtual', FROM_UNIXTIME(1576757818),
NULL, NULL, 0, '', '', NULL, 0, 0, '172.31.20.12=5B4500=5D',
'185.76.230.248=5B38823=5D', NULL, 'Framed-User', NULL, '', '', '', '', '')

(7) sql: Executing query: INSERT INTO radacct (acctsessionid,
acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime,
acctstoptime, acctsessiontime, acctauthentic, connectinfo_start,
connectinfo_stop,
acctinputoctets, acctoutputoctets, calledstationid, callingstationid,
acctterminatecause, servicetype, framedprotocol, framedipaddress,
framedipv6address, framedipv6prefix, framedinterfaceid, delegatedipv6prefix)
VALUES('1576757594-3', '4777c724ef84c2fd714218f9256dac76', 'houman', '',
'172.31.20.12', NULLIF('X-1', ''), 'Virtual', FROM_UNIXTIME(1576757818),
NULL, NULL, 0, '', '', NULL, 0, 0, '172.31.20.12=5B4500=5D',
'185.76.230.248=5B38823=5D', NULL, 'Framed-User', NULL, '', '', '', '', '')

(7) sql: ERROR: rlm_sql_mysql: ERROR 1054 (Unknown column
'framedipv6address' in 'field list'): 42S22

(7) sql: SQL query returned: server error

rlm_sql (sql): Released connection (8)

(7)       [sql.accounting] = fail

(7)     } # policy sql_session_start.post-auth = fail

(7)   } # post-auth = fail

(7) Using Post-Auth-Type Reject

(7) # Executing group from file /etc/freeradius/3.0/sites-enabled/default

(7)   Post-Auth-Type REJECT {

(7) sql: EXPAND .query

(7) sql:    --> .query

(7) sql: Using query template 'query'

rlm_sql (sql): Reserved connection (7)

(7) sql: EXPAND %{User-Name}

(7) sql:    --> houman

(7) sql: SQL-User-Name set to 'houman'

(7) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')

(7) sql:    --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'houman', '', 'Access-Reject', '2019-12-19 12:16:58')

(7) sql: Executing query: INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( 'houman', '', 'Access-Reject', '2019-12-19 12:16:58')

(7) sql: SQL query returned: success

(7) sql: 1 record(s) updated

rlm_sql (sql): Released connection (7)

(7)     [sql] = ok

(7) attr_filter.access_reject: EXPAND %{User-Name}

(7) attr_filter.access_reject:    --> houman

(7) attr_filter.access_reject: Matched entry DEFAULT at line 11

(7)     [attr_filter.access_reject] = updated

(7)     [eap] = noop

(7)     policy remove_reply_message_if_eap {

(7)       if (&reply:EAP-Message && &reply:Reply-Message) {

(7)       if (&reply:EAP-Message && &reply:Reply-Message)  -> FALSE

(7)       else {

(7)         [noop] = noop

(7)       } # else = noop

(7)     } # policy remove_reply_message_if_eap = noop

(7)   } # Post-Auth-Type REJECT = updated

(7) Delaying response for 1.000000 seconds

Waking up in 0.1 seconds.

Waking up in 0.8 seconds.

(7) Sending delayed response

(7) Sent Access-Reject Id 131 from 127.0.0.1:1812 to 127.0.0.1:48822 length
44

(7)   EAP-Message = 0x03030004

(7)   Message-Authenticator = 0x00000000000000000000000000000000

Waking up in 3.5 seconds.

(4) Cleaning up request packet ID 128 with timestamp +95

Waking up in 0.1 seconds.

(5) Cleaning up request packet ID 129 with timestamp +95

Waking up in 0.1 seconds.

(6) Cleaning up request packet ID 130 with timestamp +95

Waking up in 0.2 seconds.

(7) Cleaning up request packet ID 131 with timestamp +95

Ready to process requests

Freeradius on Ubuntu 19.10

Houman