Dear List,
I am newbie in this system admin and linux, I have an issue on populating my sql radaacct but I have the logs in the freeradius redact logs info. Also, from the sqlcounter logs, i find error on query “strftime” but not able to find this attribute on the query input.
I had attached the debug output for your reference, I had tested two account one from the local file and one from sql database. Appreciate if can help me to resolve and clarify. Thanks in advance.
======
Listening on auth address * port 1812 as server default
Listening on acct address * port 1813 as server default
Listening on auth address :: port 1812 as server default
Listening on acct address :: port 1813 as server default
Listening on auth address 127.0.0.1 port 18120 as server inner-tunnel
Opening new proxy socket 'proxy address * port 0'
Listening on proxy address * port 39297
Ready to process requests
Received Access-Request Id 177 from 172.16.0.254:57376 to 172.16.0.254:1812 length 74
User-Name = 'demo'
User-Password = '12345678'
NAS-IP-Address = 172.16.0.254
NAS-Port = 1812
Message-Authenticator = 0x845ee06875d56edc2c6daf33533aeb00
(0) Received Access-Request packet from host 172.16.0.254 port 57376, id=177, length=74
(0) User-Name = 'demo'
(0) User-Password = '12345678'
(0) NAS-IP-Address = 172.16.0.254
(0) NAS-Port = 1812
(0) Message-Authenticator = 0x845ee06875d56edc2c6daf33533aeb00
(0) # Executing section authorize from file /etc/raddb/sites-enabled/default
(0) authorize {
(0) filter_username filter_username {
(0) if (!&User-Name)
(0) if (!&User-Name) -> FALSE
(0) if (&User-Name =~ / /)
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@.*@/ )
(0) if (&User-Name =~ /@.*@/ ) -> FALSE
(0) if (&User-Name =~ /\\.\\./ )
(0) if (&User-Name =~ /\\.\\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/))
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE
(0) if (&User-Name =~ /\\.$/)
(0) if (&User-Name =~ /\\.$/) -> FALSE
(0) if (&User-Name =~ /(a)\\./)
(0) if (&User-Name =~ /(a)\\./) -> FALSE
(0) } # filter_username filter_username = notfound
(0) [preprocess] = ok
(0) [chap] = noop
(0) [mschap] = noop
(0) [digest] = noop
(0) suffix : Checking for suffix after "@"
(0) suffix : No '@' in User-Name = "demo", looking up realm NULL
(0) suffix : No such realm "NULL"
(0) [suffix] = noop
(0) eap : No EAP-Message, not doing EAP
(0) [eap] = noop
(0) files : users: Matched entry demo at line 97
(0) files : EXPAND Hello, %{User-Name}
(0) files : --> Hello, demo
(0) [files] = ok
(0) sql : EXPAND %{User-Name}
(0) sql : --> demo
(0) sql : SQL-User-Name set to 'demo'
rlm_sql (sql): Reserved connection (4)
(0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'demo' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'demo' ORDER BY id'
(0) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(0) sql : --> SELECT groupname FROM radusergroup WHERE username = 'demo' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'demo' ORDER BY priority'
(0) sql : User not found in any groups
rlm_sql (sql): Released connection (4)
(0) [sql] = notfound
(0) WARNING: dailycounter : Couldn't find control attribute 'control:Max-Daily-Session'
(0) [dailycounter] = noop
(0) [expiration] = noop
(0) [logintime] = noop
(0) [pap] = updated
(0) } # authorize = updated
(0) Found Auth-Type = PAP
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0) Auth-Type PAP {
(0) pap : Login attempt with password
(0) pap : User authenticated successfully
(0) [pap] = ok
(0) } # Auth-Type PAP = ok
(0) # Executing section post-auth from file /etc/raddb/sites-enabled/default
(0) post-auth {
(0) sql : EXPAND .query
(0) sql : --> .query
(0) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(0) sql : EXPAND %{User-Name}
(0) sql : --> demo
(0) sql : SQL-User-Name set to 'demo'
(0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'demo', '12345678', 'Access-Accept', '2015-05-26 19:25:30')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'demo', '12345678', 'Access-Accept', '2015-05-26 19:25:30')'
rlm_sql (sql): Released connection (4)
(0) [sql] = ok
(0) [exec] = noop
(0) remove_reply_message_if_eap remove_reply_message_if_eap {
(0) if (&reply:EAP-Message && &reply:Reply-Message)
(0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(0) else else {
(0) [noop] = noop
(0) } # else else = noop
(0) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(0) } # post-auth = ok
(0) Sending Access-Accept packet to host 172.16.0.254 port 57376, id=177, length=0
(0) Reply-Message = 'Hello, demo'
Sending Access-Accept Id 177 from 172.16.0.254:1812 to 172.16.0.254:57376
Reply-Message = 'Hello, demo'
(0) Finished request
Waking up in 0.3 seconds.
Waking up in 4.6 seconds.
(0) Cleaning up request packet ID 177 with timestamp +11
Ready to process requests
Received Access-Request Id 234 from 172.16.0.254:48395 to 172.16.0.254:1812 length 74
User-Name = 'test'
User-Password = 'testpwd'
NAS-IP-Address = 172.16.0.254
NAS-Port = 1812
Message-Authenticator = 0x2980277e22bbee005e9ea4d1a425034b
(1) Received Access-Request packet from host 172.16.0.254 port 48395, id=234, length=74
(1) User-Name = 'test'
(1) User-Password = 'testpwd'
(1) NAS-IP-Address = 172.16.0.254
(1) NAS-Port = 1812
(1) Message-Authenticator = 0x2980277e22bbee005e9ea4d1a425034b
(1) # Executing section authorize from file /etc/raddb/sites-enabled/default
(1) authorize {
(1) filter_username filter_username {
(1) if (!&User-Name)
(1) if (!&User-Name) -> FALSE
(1) if (&User-Name =~ / /)
(1) if (&User-Name =~ / /) -> FALSE
(1) if (&User-Name =~ /@.*@/ )
(1) if (&User-Name =~ /@.*@/ ) -> FALSE
(1) if (&User-Name =~ /\\.\\./ )
(1) if (&User-Name =~ /\\.\\./ ) -> FALSE
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/))
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE
(1) if (&User-Name =~ /\\.$/)
(1) if (&User-Name =~ /\\.$/) -> FALSE
(1) if (&User-Name =~ /(a)\\./)
(1) if (&User-Name =~ /(a)\\./) -> FALSE
(1) } # filter_username filter_username = notfound
(1) [preprocess] = ok
(1) [chap] = noop
(1) [mschap] = noop
(1) [digest] = noop
(1) suffix : Checking for suffix after "@"
(1) suffix : No '@' in User-Name = "test", looking up realm NULL
(1) suffix : No such realm "NULL"
(1) [suffix] = noop
(1) eap : No EAP-Message, not doing EAP
(1) [eap] = noop
(1) [files] = noop
(1) sql : EXPAND %{User-Name}
(1) sql : --> test
(1) sql : SQL-User-Name set to 'test'
rlm_sql (sql): Reserved connection (4)
(1) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(1) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id'
(1) sql : User found in radcheck table
(1) sql : Check items matched
(1) sql : EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id
(1) sql : --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id'
(1) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(1) sql : --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority'
(1) sql : User not found in any groups
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (0), from 2 unused connections
rlm_sql_mysql: Socket destructor called, closing socket
(1) [sql] = ok
sqlcounter_expand: 'SELECT SUM(acctsessiontime - GREATEST((1432569600 - strftime('%%s', acctstarttime)), 0)) FROM radacct WHERE username = '%{User-Name}' AND (strftime('%%s', acctstarttime) + acctsessiontime) > 1432569600'
(1) dailycounter : EXPAND %{User-Name}
(1) dailycounter : --> test
(1) dailycounter : SQL-User-Name set to 'test'
rlm_sql (sql): Reserved connection (4)
rlm_sql (sql): Executing query: 'SELECT SUM(acctsessiontime - GREATEST((1432569600 - strftime('%s', acctstarttime)), 0)) FROM radacct WHERE username = 'test' AND (strftime('%s', acctstarttime) + acctsessiontime) > 1432569600'
rlm_sql_mysql: MYSQL check_error: 1305 received
rlm_sql (sql): FUNCTION radius.strftime does not exist
(1) ERROR: dailycounter : SQL query failed: FUNCTION radius.strftime does not exist
rlm_sql (sql): Released connection (4)
(1) dailycounter : EXPAND %{sql:SELECT SUM(acctsessiontime - GREATEST((1432569600 - strftime('%%s', acctstarttime)), 0)) FROM radacct WHERE username = '%{User-Name}' AND (strftime('%%s', acctstarttime) + acctsessiontime) > 1432569600}
(1) dailycounter : -->
(1) dailycounter : No integer found in result string "". May be first session, setting counter to 0
(1) dailycounter : Allowing user, control:Max-Daily-Session value (300) is greater than counter value (0)
(1) dailycounter : Setting reply:Session-Timeout value to 300
(1) [dailycounter] = ok
(1) [expiration] = noop
(1) [logintime] = noop
(1) [pap] = updated
(1) } # authorize = updated
(1) Found Auth-Type = PAP
(1) # Executing group from file /etc/raddb/sites-enabled/default
(1) Auth-Type PAP {
(1) pap : Login attempt with password
(1) pap : User authenticated successfully
(1) [pap] = ok
(1) } # Auth-Type PAP = ok
(1) # Executing section post-auth from file /etc/raddb/sites-enabled/default
(1) post-auth {
(1) sql : EXPAND .query
(1) sql : --> .query
(1) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(1) sql : EXPAND %{User-Name}
(1) sql : --> test
(1) sql : SQL-User-Name set to 'test'
(1) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(1) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', 'testpwd', 'Access-Accept', '2015-05-26 19:26:07')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'test', 'testpwd', 'Access-Accept', '2015-05-26 19:26:07')'
rlm_sql (sql): Released connection (4)
(1) [sql] = ok
(1) [exec] = noop
(1) remove_reply_message_if_eap remove_reply_message_if_eap {
(1) if (&reply:EAP-Message && &reply:Reply-Message)
(1) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(1) else else {
(1) [noop] = noop
(1) } # else else = noop
(1) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(1) } # post-auth = ok
(1) Sending Access-Accept packet to host 172.16.0.254 port 48395, id=234, length=0
(1) Session-Timeout = 300
Sending Access-Accept Id 234 from 172.16.0.254:1812 to 172.16.0.254:48395
Session-Timeout = 300
(1) Finished request
Waking up in 0.3 seconds.
Waking up in 4.6 seconds.
(1) Cleaning up request packet ID 234 with timestamp +48
Ready to process requests
========
Kind Regards,
Larry
