Problem with rlm_counter (FR3)

27 Feb 2014

      After recent fixes, i have a problem with FR3 and rlm_counter.
My configuration in mods-enabled/counter:

counter daily {
        filename = ${db_dir}/db.daily
        key = User-Name
        count_attribute = Acct-Session-Time
        reset = daily
        counter_name = Daily-Session-Time
        check_name = Max-Daily-Session
        reply_name = Session-Timeout
        #allowed_service_type = Framed-User
        cache_size = 5000
}

my sites-enabled/default configuration is as i found after a compile.
Before "expiration" i just added "daily".

Radclient command that i'm using for tests:

echo "User-Name = marco,User-Password = XXXXXXXX" |
/usr/local/bin/radclient localhost:1812 auth testing123

If i comment "daily" in the authorize section i have:

Received reply ID 141, code 2, length = 32
Idle-Timeout = 600
 Session-Timeout = 120

if I uncomment "daily" i have:

Received reply ID 124, code 2, length = 38
 Idle-Timeout = 600
Session-Timeout = 120
Session-Timeout = 120

So "Session-Timeout" is duplicated. What happens?
"marco" user belongs to a group named "Users" that have a radgroupreply
"Session-Timeout" = 120

This is a complete log when "daily" is commented:

rad_recv: Access-Request packet from host 127.0.0.1 port 43737, id=141,
length=51
User-Name = 'marco@prova'
 User-Password = 'XXXXXXXX'
(1) # Executing section authorize from file
/etc/freeradius//sites-enabled/default
(1)   authorize {
(1)   filter_username filter_username {
(1)    ? if (!User-Name)
(1)    ? if (!User-Name)  -> FALSE
(1)    ? if (User-Name != "%{tolower:%{User-Name}}")
(1) expand: "%{tolower:%{User-Name}}" -> 'marco@prova'
(1)    ? if (User-Name != "%{tolower:%{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 =~ /\\.$/)
(1)    ? if (User-Name =~ /\\.$/)   -> FALSE
(1)    ? if (User-Name =~ /@\\./)
(1)    ? if (User-Name =~ /@\\./)   -> FALSE
(1)   } # filter_username filter_username = notfound
(1)   [preprocess] = ok
(1)   [chap] = noop
(1)   [mschap] = noop
(1)   [digest] = noop
(1) suffix : Looking up realm "prova" for User-Name = "marco@prova"
(1) suffix : Found realm "prova"
(1) suffix : Adding Stripped-User-Name = "marco"
(1) suffix : Adding Realm = "prova"
(1) suffix : Authentication realm is LOCAL
(1)   [suffix] = ok
(1) eap : No EAP-Message, not doing EAP
(1)   [eap] = noop
(1)   [files] = noop
(1) sql : expand: "%{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}" ->
'marco'
(1) sql : SQL-User-Name set to 'marco'
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" -> 'SELECT id, username,
attribute, value, op FROM radcheck WHERE username = 'marco' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'marco' 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" -> 'SELECT id, username,
attribute, value, op FROM radreply WHERE username = 'marco' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'marco' ORDER BY id'
(1) sql : expand: "SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority" -> 'SELECT groupname FROM
radusergroup WHERE username = 'marco' ORDER BY priority'
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE
username = 'marco' ORDER BY priority'
(1) sql : User found in the group table
(1) sql : expand: "SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" -> 'SELECT id,
groupname, attribute, Value, op FROM radgroupcheck WHERE groupname =
'Users' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, Value, op
FROM radgroupcheck WHERE groupname = 'Users' ORDER BY id'
(1) sql : Group "Users" check items matched
(1) sql : expand: "SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" -> 'SELECT id,
groupname, attribute, value, op FROM radgroupreply WHERE groupname =
'Users' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, value, op
FROM radgroupreply WHERE groupname = 'Users' ORDER BY id'
(1) sql : Group "Users" reply items processed
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (0): Too many free connections (5 > 3)
rlm_sql_mysql: Socket destructor called, closing socket
(1)   [sql] = ok
(1)   [expiration] = noop
(1)   [logintime] = noop
(1)   [pap] = updated
(1)  } #  authorize = updated
(1) Found Auth-Type = PAP
(1) # Executing group from file /etc/freeradius//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/freeradius//sites-enabled/default
(1)   post-auth {
(1)   [-sql] = noop
(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 = noop
Sending Access-Accept of id 141 from 127.0.0.1 port 1812 to 127.0.0.1 port
43737
Idle-Timeout = 600
Session-Timeout = 120
(1) Finished request 1.
Waking up in 0.3 seconds.
Waking up in 4.6 seconds.
(1) Cleaning up request packet ID 141 with timestamp +58

Instead, this is a complete log when "daily" is enabled:

rad_recv: Access-Request packet from host 127.0.0.1 port 34562, id=124,
length=45
User-Name = 'marco'
User-Password = 'mc68hc908'
(1) # Executing section authorize from file
/etc/freeradius//sites-enabled/default
(1)   authorize {
(1)   filter_username filter_username {
(1)    ? if (!User-Name)
(1)    ? if (!User-Name)  -> FALSE
(1)    ? if (User-Name != "%{tolower:%{User-Name}}")
(1) expand: "%{tolower:%{User-Name}}" -> 'marco'
(1)    ? if (User-Name != "%{tolower:%{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 =~ /\\.$/)
(1)    ? if (User-Name =~ /\\.$/)   -> FALSE
(1)    ? if (User-Name =~ /@\\./)
(1)    ? if (User-Name =~ /@\\./)   -> FALSE
(1)   } # filter_username filter_username = notfound
(1)   [preprocess] = ok
(1)   [chap] = noop
(1)   [mschap] = noop
(1)   [digest] = noop
(1) suffix : No '@' in User-Name = "marco", 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: "%{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}}" ->
'marco'
(1) sql : SQL-User-Name set to 'marco'
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" -> 'SELECT id, username,
attribute, value, op FROM radcheck WHERE username = 'marco' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radcheck WHERE username = 'marco' 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" -> 'SELECT id, username,
attribute, value, op FROM radreply WHERE username = 'marco' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op
FROM radreply WHERE username = 'marco' ORDER BY id'
(1) sql : expand: "SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority" -> 'SELECT groupname FROM
radusergroup WHERE username = 'marco' ORDER BY priority'
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE
username = 'marco' ORDER BY priority'
(1) sql : User found in the group table
(1) sql : expand: "SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" -> 'SELECT id,
groupname, attribute, Value, op FROM radgroupcheck WHERE groupname =
'Users' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, Value, op
FROM radgroupcheck WHERE groupname = 'Users' ORDER BY id'
(1) sql : Group "Users" check items matched
(1) sql : expand: "SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" -> 'SELECT id,
groupname, attribute, value, op FROM radgroupreply WHERE groupname =
'Users' ORDER BY id'
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, value, op
FROM radgroupreply WHERE groupname = 'Users' ORDER BY id'
(1) sql : Group "Users" reply items processed
rlm_sql (sql): Released connection (4)
(1)   [sql] = ok
rlm_counter: Entering module authorize code
rlm_counter: Searching the database for key 'marco'
rlm_counter: Could not find the requested key in the database
rlm_counter: Check item = 120, Count = 0
rlm_counter: res is greater than zero
rlm_counter: (Check item - counter) is greater than zero
rlm_counter: Authorized user marco, check_item=120, counter=0
rlm_counter: Sent Reply-Item for user marco, Type=Session-Timeout, value=120
(1)   [daily] = ok
(1)   [expiration] = noop
(1)   [logintime] = noop
(1)   [pap] = updated
(1)  } #  authorize = updated
(1) Found Auth-Type = PAP
(1) # Executing group from file /etc/freeradius//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/freeradius//sites-enabled/default
(1)   post-auth {
(1)   [-sql] = noop
(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 = noop
Sending Access-Accept of id 124 from 127.0.0.1 port 1812 to 127.0.0.1 port
34562
Idle-Timeout = 600
Session-Timeout = 120
Session-Timeout = 120
(1) Finished request 1.
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(0) Cleaning up request packet ID 198 with timestamp +5

Thanks

Problem with rlm_counter (FR3)

Marco Marino