SQLite throwing an 500 error code for "attempt to write to readonly database"
Opened this issue · 10 comments
esagara commented
Datasette is not working in production. Oddly enough it is functioning on the dev side of things.
Initial error was:
esagara commented
I tried restarting the application on Fly.io but that did not fix the issue. Next we tried re-deploying to production, but deployment is now failing. Here are the logs for my most recent attempt:
Waiting for logs...
2023-04-12T01:07:55.211 app[dc3b8f44] lax [info] File "/usr/local/bin/datasette", line 8, in <module>
2023-04-12T01:07:55.211 app[dc3b8f44] lax [info] sys.exit(cli())
2023-04-12T01:07:55.211 app[dc3b8f44] lax [info] ^^^^^
2023-04-12T01:07:55.211 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1130, in __call__
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] return self.main(*args, **kwargs)
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1055, in main
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] rv = self.invoke(ctx)
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] return _process_result(sub_ctx.command.invoke(sub_ctx))
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] return ctx.invoke(self.callback, **ctx.params)
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 760, in invoke
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] return __callback(*args, **kwargs)
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 143, in wrapped
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] return fn(*args, **kwargs)
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.212 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 615, in serve
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] asyncio.get_event_loop().run_until_complete(check_databases(ds))
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/asyncio/base_events.py", line 650, in run_until_complete
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] return future.result()
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 660, in check_databases
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] await database.execute_fn(check_connection)
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/database.py", line 213, in execute_fn
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] return await asyncio.get_event_loop().run_in_executor(
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:07:55.213 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] result = self.fn(*self.args, **self.kwargs)
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages datasette/database.py", line 211, in in_thread
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] return fn(conn)
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] ^^^^^^^^
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/utils/__init__.py", line 951, in check_connection
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] for r in conn.execute(
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^
2023-04-12T01:07:55.214 app[dc3b8f44] lax [info] sqlite3.OperationalError: attempt to write a readonly database
2023-04-12T01:07:56.043 app[dc3b8f44] lax [info] Starting clean up.
2023-04-12T01:07:56.043 app[dc3b8f44] lax [info] Umounting /dev/vdc from /data
2023-04-12T01:08:02.049 runner[dc3b8f44] lax [info] Starting instance
2023-04-12T01:08:02.096 runner[dc3b8f44] lax [info] Configuring virtual machine
2023-04-12T01:08:02.097 runner[dc3b8f44] lax [info] Pulling container image
2023-04-12T01:08:02.439 runner[dc3b8f44] lax [info] Unpacking image
2023-04-12T01:08:02.448 runner[dc3b8f44] lax [info] Preparing kernel init
2023-04-12T01:08:02.577 runner[dc3b8f44] lax [info] Setting up volume 'datasette'
2023-04-12T01:08:02.581 runner[dc3b8f44] lax [info] Opening encrypted volume
2023-04-12T01:08:02.757 runner[dc3b8f44] lax [info] Configuring firecracker
2023-04-12T01:08:02.898 runner[dc3b8f44] lax [info] Starting virtual machine
2023-04-12T01:08:03.081 app[dc3b8f44] lax [info] Starting init (commit: e878f33)...
2023-04-12T01:08:03.102 app[dc3b8f44] lax [info] Mounting /dev/vdc at /data w/ uid: 0, gid: 0 and chmod 0755
2023-04-12T01:08:03.107 app[dc3b8f44] lax [info] Preparing to run: `/bin/bash -c shopt -s nullglob && datasette serve --host 0.0.0.0 --cors --inspect-file inspect-data.json --metadata metadata.json /data/biglocalnews.db --create --port $PORT /data/*.db` as root
2023-04-12T01:08:03.129 app[dc3b8f44] lax [info] 2023/04/12 01:08:03 listening on [fdaa:1:2f52:a7b:c0da:4:5847:2]:22 (DNS: [fdaa::3]:53)
2023-04-12T01:08:04.270 app[dc3b8f44] lax [info] Traceback (most recent call last):
2023-04-12T01:08:04.270 app[dc3b8f44] lax [info] File "/usr/local/bin/datasette", line 8, in <module>
2023-04-12T01:08:04.270 app[dc3b8f44] lax [info] sys.exit(cli())
2023-04-12T01:08:04.270 app[dc3b8f44] lax [info] ^^^^^
2023-04-12T01:08:04.270 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1130, in __call__
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] return self.main(*args, **kwargs)
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1055, in main
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] rv = self.invoke(ctx)
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] return _process_result(sub_ctx.command.invoke(sub_ctx))
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] return ctx.invoke(self.callback, **ctx.params)
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 760, in invoke
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] return __callback(*args, **kwargs)
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.271 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 143, in wrapped
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] return fn(*args, **kwargs)
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] File "/usr/local/lib/python3
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] File "/usr/local/lib/python3 11/site-packages/datasette/cli.py", line 615, in serve
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] asyncio.get_event_loop().run_until_complete(check_databases(ds))
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/asyncio/base_events.py", line 650, in run_until_complete
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] return future.result()
2023-04-12T01:08:04.272 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 660, in check_databases
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] await database.execute_fn(check_connection)
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/database.py", line 213, in execute_fn
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] return await asyncio.get_event_loop().run_in_executor(
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
2023-04-12T01:08:04.273 app[dc3b8f44] lax [info] result = self.fn(*self.args, **self.kwargs)
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/database.py", line 211, in in_thread
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] return fn(conn)
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] ^^^^^^^^
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/utils/__init__.py", line 951, in check_connection
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] for r in conn.execute(
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] ^^^^^^^^^^^^^
2023-04-12T01:08:04.274 app[dc3b8f44] lax [info] sqlite3.OperationalError: attempt to write a readonly database
2023-04-12T01:08:05.122 app[dc3b8f44] lax [info] Starting clean up.
2023-04-12T01:08:05.127 app[dc3b8f44] lax [info] Umounting /dev/vdc from /data
esagara commented
Ben noticed the deployment was running python 3.11. I switched our python version in the Pipfile to match and re-deployed but it did not fix the issue.
esagara commented
File permissions on dev, which is still running.
simonw commented
Here's the issue in the Datasette repo:
esagara commented
New logs after trying out the fix in #2:
2023-04-13T16:31:48Z runner[99403881] lax [info]Starting instance
2023-04-13T16:31:48Z runner[99403881] lax [info]Configuring virtual machine
2023-04-13T16:31:48Z runner[99403881] lax [info]Pulling container image
2023-04-13T16:31:49Z runner[99403881] lax [info]Unpacking image
2023-04-13T16:31:49Z runner[99403881] lax [info]Preparing kernel init
2023-04-13T16:31:49Z runner[99403881] lax [info]Setting up volume 'datasette'
2023-04-13T16:31:49Z runner[99403881] lax [info]Opening encrypted volume
2023-04-13T16:31:49Z runner[99403881] lax [info]Configuring firecracker
2023-04-13T16:31:49Z runner[99403881] lax [info]Starting virtual machine
2023-04-13T16:31:49Z app[99403881] lax [info]Starting init (commit: e878f33)...
2023-04-13T16:31:49Z app[99403881] lax [info]Mounting /dev/vdc at /data w/ uid: 0, gid: 0 and chmod 0755
2023-04-13T16:31:49Z app[99403881] lax [info]Preparing to run: `/bin/bash -c shopt -s nullglob && datasette serve --host 0.0.0.0 --cors --inspect-file inspect-data.json --metadata metadata.json /data/biglocalnews.db --create --port $PORT /data/*.db` as root
2023-04-13T16:31:49Z app[99403881] lax [info]2023/04/13 16:31:49 listening on [fdaa:1:2f52:a7b:c0da:4:5847:2]:22 (DNS: [fdaa::3]:53)
2023-04-13T16:31:50Z app[99403881] lax [info]Traceback (most recent call last):
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/bin/datasette", line 8, in <module>
2023-04-13T16:31:50Z app[99403881] lax [info] sys.exit(cli())
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1130, in __call__
2023-04-13T16:31:50Z app[99403881] lax [info] return self.main(*args, **kwargs)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1055, in main
2023-04-13T16:31:50Z app[99403881] lax [info] rv = self.invoke(ctx)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1657, in invoke
2023-04-13T16:31:50Z app[99403881] lax [info] return _process_result(sub_ctx.command.invoke(sub_ctx))
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
2023-04-13T16:31:50Z app[99403881] lax [info] return ctx.invoke(self.callback, **ctx.params)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/click/core.py", line 760, in invoke
2023-04-13T16:31:50Z app[99403881] lax [info] return __callback(*args, **kwargs)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 143, in wrapped
2023-04-13T16:31:50Z app[99403881] lax [info] return fn(*args, **kwargs)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 615, in serve
2023-04-13T16:31:50Z app[99403881] lax [info] asyncio.get_event_loop().run_until_complete(check_databases(ds))
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/asyncio/base_events.py", line 650, in run_until_complete
2023-04-13T16:31:50Z app[99403881] lax [info] return future.result()
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/cli.py", line 660, in check_databases
2023-04-13T16:31:50Z app[99403881] lax [info] await database.execute_fn(check_connection)
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/database.py", line 213, in execute_fn
2023-04-13T16:31:50Z app[99403881] lax [info] return await asyncio.get_event_loop().run_in_executor(
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
2023-04-13T16:31:50Z app[99403881] lax [info] result = self.fn(*self.args, **self.kwargs)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/database.py", line 211, in in_thread
2023-04-13T16:31:50Z app[99403881] lax [info] return fn(conn)
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info] File "/usr/local/lib/python3.11/site-packages/datasette/utils/__init__.py", line 951, in check_connection
2023-04-13T16:31:50Z app[99403881] lax [info] for r in conn.execute(
2023-04-13T16:31:50Z app[99403881] lax [info] ^^^^^^^^^^^^^
2023-04-13T16:31:50Z app[99403881] lax [info]sqlite3.OperationalError: attempt to write a readonly database
2023-04-13T16:31:51Z app[99403881] lax [info]Starting clean up.
2023-04-13T16:31:51Z app[99403881] lax [info]Umounting /dev/vdc from /data
2023-04-13T16:31:52Z health[99403881] lax [error]Health check on port 8080 has failed. Your app is not responding properly. Services exposed on ports [80, 443] will have intermittent failures until the health check passes.
simonw commented
Huh... this is a different error from the one I saw from Ben. Ben's was here: https://gist.githubusercontent.com/palewire/85fc980427979ef040202651b4424895/raw/1b76628e0a3f4eb0cb625caa5741d58f92ff383b/flyio.log
Key line: conn=<sqlite3.Connection object at 0x7f68c8b21a80>, sql = 'PRAGMA schema_version', params = None: attempt to write a readonly database
But here we're seeing something different: it looks like the error is this one:
await database.execute_fn(check_connection)
Which is an error on startup, and looks to be in the check_connection() function.
Quoted:
def check_connection(conn):
tables = [
r[0]
for r in conn.execute(
"select name from sqlite_master where type='table'"
).fetchall()
]
for table in tables:
try:
conn.execute(
f"PRAGMA table_info({escape_sqlite(table)});",
)
except sqlite3.OperationalError as e:
if e.args[0] == "no such module: VirtualSpatialIndex":
raise SpatialiteConnectionProblem(e)
else:
raise ConnectionProblem(e)Again though, there's nothing in there that looks remotely like a write query.
How much disk space does the machine's volume have available?
You should be able to tell by running:
fly ssh console -s -C df
The -s should cause it to ask you to select the right machine.
simonw commented
If it's a disk space issue then a short-term fix would be to expand the volume size: https://fly.io/docs/reference/volumes/
fly volumes extend <volume-id> -s <new-size>
esagara commented
I'm checking on this, but there is an issue with Fly right now preventing the builder from launching. Fly is aware of it and hopefully should address it shortly. I will post back when I can test. My immediate thought is your hunch is spot on. I remember looking and seeing that we were getting close to the 1gb mark on the databases stored there. That is what we had allocated to the volume, so I have bumped it up to 2gb. I'll let you know when I deploy and test.
simonw commented
Running out of disk space is very likely to cause this kind of issue - I think allocating a bunch more (maybe 10 or 20GB) is the best next step
esagara commented
I just bumped the allocation up to 20gb, but am still getting the same errors that I have been seeing.