freeradius with sqlite3 solving database lock issue
Hi, What are the best options to configure sqlite3 sql with freeradius? i'm having some lock errors followed by "ERROR: Hit reconnection limit" I tried to set the pool to only 1 server, since its a file db, but them i got the error "max connections2 when connecting two users at the same time. Right now i use: .... thread pool { start_servers = 5 max_servers = 25 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 1024 auto_limit_acct = yes } sql { driver = "rlm_sql_sqlite" sqlite { filename = "radius.db" busy_timeout = 200 } dialect = "sqlite" delete_stale_sessions = yes pool { start = ${thread[pool].start_servers} min = ${thread[pool].min_spare_servers} max = ${thread[pool].max_servers} spare = ${thread[pool].max_spare_servers} uses = 0 retry_delay = 30 lifetime = 0 idle_timeout = 60 } ... The errors are: Feb 12 17:41:08 PC radiusd[18187]: (2038) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 17 cli 30-10-E4-66-1A-CF) Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: Error fetching row Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: rlm_sql_sqlite: database is locked Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: SQL query failed: server error Feb 12 17:41:58 PC radiusd[18187]: (2041) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 14 cli F4-37-B7-E0-66-DF) Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: Error fetching row Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: rlm_sql_sqlite: database is locked ... Feb 12 17:56:39 PC radiusd[18187]: (2125) sql: ERROR: Hit reconnection limit You can check the entire log in http://pastebin.com/fXuZVU93 Thanks, -- Saludos / Regards / Cumprimentos, António silva
forget to point my version... FreeRADIUS Version 3.0.12 On 02/17/2017 06:14 PM, Antonio Silva wrote:
Hi,
What are the best options to configure sqlite3 sql with freeradius?
i'm having some lock errors followed by "ERROR: Hit reconnection limit"
I tried to set the pool to only 1 server, since its a file db, but them i got the error "max connections2 when connecting two users at the same time.
Right now i use: .... thread pool { start_servers = 5 max_servers = 25 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 1024 auto_limit_acct = yes }
sql { driver = "rlm_sql_sqlite" sqlite { filename = "radius.db" busy_timeout = 200 } dialect = "sqlite" delete_stale_sessions = yes pool { start = ${thread[pool].start_servers} min = ${thread[pool].min_spare_servers} max = ${thread[pool].max_servers} spare = ${thread[pool].max_spare_servers} uses = 0 retry_delay = 30 lifetime = 0 idle_timeout = 60 } ...
The errors are:
Feb 12 17:41:08 PC radiusd[18187]: (2038) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 17 cli 30-10-E4-66-1A-CF) Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: Error fetching row Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: rlm_sql_sqlite: database is locked Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: SQL query failed: server error Feb 12 17:41:58 PC radiusd[18187]: (2041) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 14 cli F4-37-B7-E0-66-DF) Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: Error fetching row Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: rlm_sql_sqlite: database is locked ... Feb 12 17:56:39 PC radiusd[18187]: (2125) sql: ERROR: Hit reconnection limit
You can check the entire log in http://pastebin.com/fXuZVU93
Thanks,
-- Saludos / Regards / Cumprimentos, António silva
On Feb 17, 2017, at 12:14 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
What are the best options to configure sqlite3 sql with freeradius?
It should just work.
i'm having some lock errors followed by "ERROR: Hit reconnection limit"
I tried to set the pool to only 1 server, since its a file db, but them i got the error "max connections2 when connecting two users at the same time.
The issue there is that sqlite can only have one writer at a time. So if you want multiple writers... you really need to use a different database.
The errors are:
Feb 12 17:41:08 PC radiusd[18187]: (2038) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 17 cli 30-10-E4-66-1A-CF) Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: Error fetching row Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: rlm_sql_sqlite: database is locked Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: SQL query failed: server error Feb 12 17:41:58 PC radiusd[18187]: (2041) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 14 cli F4-37-B7-E0-66-DF) Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: Error fetching row Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: rlm_sql_sqlite: database is locked
I think that was fixed in the v3.0.x branch. Please try that: https://github.com/FreeRADIUS/freeradius-server/archive/v3.0.x.zip Alan DeKok.
Alan, thanks for the reply. i'll try that version. As for the option to have only one writer, i tried that by changing the sql pool definition to start=min=max=1.... but i didn't change the thread pool... so i should set the thread pool to 1 as well? Regards, António On 02/17/2017 07:12 PM, Alan DeKok wrote:
On Feb 17, 2017, at 12:14 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
What are the best options to configure sqlite3 sql with freeradius? It should just work.
i'm having some lock errors followed by "ERROR: Hit reconnection limit"
I tried to set the pool to only 1 server, since its a file db, but them i got the error "max connections2 when connecting two users at the same time. The issue there is that sqlite can only have one writer at a time. So if you want multiple writers... you really need to use a different database.
The errors are:
Feb 12 17:41:08 PC radiusd[18187]: (2038) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 17 cli 30-10-E4-66-1A-CF) Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: Error fetching row Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: rlm_sql_sqlite: database is locked Feb 12 17:41:58 PC radiusd[18187]: (2042) ERROR: SQL query failed: server error Feb 12 17:41:58 PC radiusd[18187]: (2041) Login OK: [402@cm.com/<CHAP-Password>] (from client nas01 port 14 cli F4-37-B7-E0-66-DF) Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: Error fetching row Feb 12 17:41:59 PC radiusd[18187]: (2042) sql: ERROR: rlm_sql_sqlite: database is locked I think that was fixed in the v3.0.x branch. Please try that:
https://github.com/FreeRADIUS/freeradius-server/archive/v3.0.x.zip
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Feb 17, 2017, at 6:33 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
Alan, thanks for the reply.
i'll try that version.
As for the option to have only one writer, i tried that by changing the sql pool definition to start=min=max=1.... but i didn't change the thread pool... so i should set the thread pool to 1 as well?
No. The threads can still use other modules in a multi-threaded manner. Alan DeKok.
Hi, with sqlite3 is working fine using version 3.0.13, but time to time i have to restart it because is unable open sqlite file. There is no other process using this file and after the restart it works fine for a few days more. Any idea how can i track this done? LOGs: Mar 29 09:24:05 H radiusd[3167]: Need 4 more connections to reach 10 spares Mar 29 09:24:05 H radiusd[3167]: rlm_sql (sql): Opening additional connection (15497), 1 of 19 pending slots used Mar 29 09:24:05 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:24:28 H radiusd[3167]: rlm_sql (sql): Closing connection (15491): Hit idle_timeout, was idle for 78 seconds Mar 29 09:24:28 H radiusd[3167]: rlm_sql (sql): Closing connection (15494): Hit idle_timeout, was idle for 74 seconds Mar 29 09:24:28 H radiusd[3167]: rlm_sql (sql): Closing connection (15496): Hit idle_timeout, was idle for 74 seconds Mar 29 09:24:28 H radiusd[3167]: rlm_sql (sql): Closing connection (15490): Hit idle_timeout, was idle for 74 seconds Mar 29 09:24:29 H radiusd[3167]: Need 7 more connections to reach 10 spares Mar 29 09:24:29 H radiusd[3167]: rlm_sql (sql): Opening additional connection (15498), 1 of 22 pending slots used Mar 29 09:24:29 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:24:31 H radiusd[3167]: Need 6 more connections to reach 10 spares Mar 29 09:24:31 H radiusd[3167]: rlm_sql (sql): Opening additional connection (15499), 1 of 21 pending slots used Mar 29 09:24:31 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:19 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:19 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: Need 6 more connections to reach 10 spares Mar 29 09:25:20 H radiusd[3167]: rlm_sql (sql): Opening additional connection (15500), 1 of 20 pending slots used Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:20 H radiusd[3167]: (14595) sql: ERROR: Hit reconnection limit Mar 29 09:25:30 H radiusd[3167]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Mar 29 09:25:30 H radiusd[3167]: rlm_sql_sqlite: Opening SQLite database "radius.db" Mar 29 09:25:30 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Mar 29 09:25:30 H radiusd[3167]: rlm_sql (sql): Failed to reconnect (15495), no free connections are available Conf: thread pool { start_servers = 5 max_servers = 25 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 1024 auto_limit_acct = yes } sql { driver = "rlm_sql_sqlite" sqlite { filename = "radius.db" busy_timeout = 200 } dialect = "sqlite" delete_stale_sessions = yes pool { start = ${thread[pool].start_servers} min = ${thread[pool].min_spare_servers} max = ${thread[pool].max_servers} spare = ${thread[pool].max_spare_servers} uses = 0 retry_delay = 30 lifetime = 0 idle_timeout = 60 } }
On Mar 30, 2017, at 6:06 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
Hi,
with sqlite3 is working fine using version 3.0.13, but time to time i have to restart it because is unable open sqlite file. There is no other process using this file and after the restart it works fine for a few days more.
Any idea how can i track this done? ... Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file
That's an error produced by SQLite. I'm not sure why it's happening. Maybe because some file descriptors aren't being closed? But the underlying connection pool is used for all SQL modules, so it should work... Alan DeKok.
Hi, thanks for the reply. Is there a way to debug the freeradius sqlite fd operations? The strange is that it happens from time to time, initial i though it could be related to the number of users, but is not the case, it just happen even if there is only one connection open. On 03/31/2017 02:56 AM, Alan DeKok wrote:
On Mar 30, 2017, at 6:06 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
Hi,
with sqlite3 is working fine using version 3.0.13, but time to time i have to restart it because is unable open sqlite file. There is no other process using this file and after the restart it works fine for a few days more.
Any idea how can i track this done? ... Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file That's an error produced by SQLite. I'm not sure why it's happening. Maybe because some file descriptors aren't being closed?
But the underlying connection pool is used for all SQL modules, so it should work...
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Saludos / Regards / Cumprimentos, António silva
Hi, Got some extra information: Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reconnecting (9291) Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Opening SQLite database "radius.db" Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reserved connection (9275) Apr 09 10:56:36 H radiusd[4014]: (14081) sql: Executing query: UPDATE radacct SET acctupdatetime = 1491728196, acctinterval = 0, framedipaddress = '192.168.4.13', acctsessiontime = 42004, acctinputoctets Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reconnecting (9275) Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Opening SQLite database "radius.db" Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reserved connection (9292) I see lots of error "Got SQLite error code (5) when closing socket", but not always end with the error unable to open database file, but i guess is the main reason for the lock issue in the db. I try to set the db poll to only one worker, but in that case when i have two simultaneous connections instead of waiting for the timeout an try to connected i have immediately "No connections available and at max connection limit" Is this possible to do, have only one connection to db but with multiple threads? Thanks, António On 04/06/2017 06:26 PM, Antonio Silva wrote:
Hi,
thanks for the reply.
Is there a way to debug the freeradius sqlite fd operations?
The strange is that it happens from time to time, initial i though it could be related to the number of users, but is not the case, it just happen even if there is only one connection open.
On 03/31/2017 02:56 AM, Alan DeKok wrote:
On Mar 30, 2017, at 6:06 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
Hi,
with sqlite3 is working fine using version 3.0.13, but time to time i have to restart it because is unable open sqlite file. There is no other process using this file and after the restart it works fine for a few days more.
Any idea how can i track this done? ... Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file That's an error produced by SQLite. I'm not sure why it's happening. Maybe because some file descriptors aren't being closed?
But the underlying connection pool is used for all SQL modules, so it should work...
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Saludos / Regards / Cumprimentos, António silva
i just change the parameter "busy_timeout = 200" to "busy_timeout = 30000" and it seams much better, no more " Got SQLite error code (5) when closing socket" i will keep an eye for the lock issue. On 04/10/2017 03:36 PM, Antonio Silva wrote:
Hi,
Got some extra information:
Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reconnecting (9291) Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Opening SQLite database "radius.db" Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reserved connection (9275) Apr 09 10:56:36 H radiusd[4014]: (14081) sql: Executing query: UPDATE radacct SET acctupdatetime = 1491728196, acctinterval = 0, framedipaddress = '192.168.4.13', acctsessiontime = 42004, acctinputoctets Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Got SQLite error code (5) when closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reconnecting (9275) Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Opening SQLite database "radius.db" Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file Apr 09 10:56:36 H radiusd[4014]: rlm_sql_sqlite: Socket destructor called, closing socket Apr 09 10:56:36 H radiusd[4014]: rlm_sql (sql): Reserved connection (9292)
I see lots of error "Got SQLite error code (5) when closing socket", but not always end with the error unable to open database file, but i guess is the main reason for the lock issue in the db.
I try to set the db poll to only one worker, but in that case when i have two simultaneous connections instead of waiting for the timeout an try to connected i have immediately "No connections available and at max connection limit"
Is this possible to do, have only one connection to db but with multiple threads?
Thanks, António
On 04/06/2017 06:26 PM, Antonio Silva wrote:
Hi,
thanks for the reply.
Is there a way to debug the freeradius sqlite fd operations?
The strange is that it happens from time to time, initial i though it could be related to the number of users, but is not the case, it just happen even if there is only one connection open.
On 03/31/2017 02:56 AM, Alan DeKok wrote:
On Mar 30, 2017, at 6:06 PM, Antonio Silva <asilva@wirelessmundi.com> wrote:
Hi,
with sqlite3 is working fine using version 3.0.13, but time to time i have to restart it because is unable open sqlite file. There is no other process using this file and after the restart it works fine for a few days more.
Any idea how can i track this done? ... Mar 29 09:25:20 H radiusd[3167]: rlm_sql_sqlite: Error opening SQLite database "radius.db": Code 0x000e (14): unable to open database file That's an error produced by SQLite. I'm not sure why it's happening. Maybe because some file descriptors aren't being closed?
But the underlying connection pool is used for all SQL modules, so it should work...
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Saludos / Regards / Cumprimentos, António silva
participants (2)
-
Alan DeKok -
Antonio Silva