bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Chris Marusich]

[-- Attachment #1: Type: text/plain, Size: 1175 bytes --]

Hi,

My disk was filling up, so I tried to run "guix gc", but I got an error
instead:

--8<---------------cut here---------------start------------->8---
$ guix gc -C 25GiB
...
deleting `/gnu/store/n0gyzfw77ik35ld9d0d4737w88f11m4b-profile.drv'
deleting `/gnu/store/fl7w0dlki7c906isiiflf9ka4c49zcmi-ca-certificate-bundle.drv'
deleting `/gnu/store/ipn4xvvb3wrbx4lhzwdyyylvj42vyg6f-xdg-desktop-database.drv'
guix gc: error: executing SQLite statement: database disk image is malformed
--8<---------------cut here---------------end--------------->8---

What does this mean?  How concerned should I be?  How can I fix it?  I
looked for existing bug reports, but I didn't find anything.  I haven't
tried running the command a second time.

FYI, I was building one package using my Guix installation via "guix
build --cores=1", and another package using a Guix checkout via
"./pre-inst-env guix build --cores", when I decided to run this "guix
gc" command in another shell.  I don't know if that matters.  My
expectation is that I can run GC even when building software, thanks to
the guix-daemon's safe concurrent garbage collection algorithm.

-- 
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Ricardo Wurmus]

Chris Marusich <cmmarusich@gmail.com> writes:

> My disk was filling up, so I tried to run "guix gc", but I got an error
> instead:
>
> --8<---------------cut here---------------start------------->8---
> $ guix gc -C 25GiB
> ...
> deleting `/gnu/store/n0gyzfw77ik35ld9d0d4737w88f11m4b-profile.drv'
> deleting `/gnu/store/fl7w0dlki7c906isiiflf9ka4c49zcmi-ca-certificate-bundle.drv'
> deleting `/gnu/store/ipn4xvvb3wrbx4lhzwdyyylvj42vyg6f-xdg-desktop-database.drv'
> guix gc: error: executing SQLite statement: database disk image is malformed
> --8<---------------cut here---------------end--------------->8---
>
> What does this mean?

I think this means that the database has been corrupted.

> FYI, I was building one package using my Guix installation via "guix
> build --cores=1", and another package using a Guix checkout via
> "./pre-inst-env guix build --cores", when I decided to run this "guix
> gc" command in another shell.  I don't know if that matters.

I don’t think this is related.

> My expectation is that I can run GC even when building software,
> thanks to the guix-daemon's safe concurrent garbage collection
> algorithm.

That’s correct.

--
Ricardo

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Chris Marusich]

[-- Attachment #1: Type: text/plain, Size: 3220 bytes --]

Ricardo Wurmus <rekado@elephly.net> writes:

> Chris Marusich <cmmarusich@gmail.com> writes:
>
>> My disk was filling up, so I tried to run "guix gc", but I got an error
>> instead:
>>
>> --8<---------------cut here---------------start------------->8---
>> $ guix gc -C 25GiB
>> ...
>> deleting `/gnu/store/n0gyzfw77ik35ld9d0d4737w88f11m4b-profile.drv'
>> deleting `/gnu/store/fl7w0dlki7c906isiiflf9ka4c49zcmi-ca-certificate-bundle.drv'
>> deleting `/gnu/store/ipn4xvvb3wrbx4lhzwdyyylvj42vyg6f-xdg-desktop-database.drv'
>> guix gc: error: executing SQLite statement: database disk image is malformed
>> --8<---------------cut here---------------end--------------->8---
>>
>> What does this mean?
>
> I think this means that the database has been corrupted.

I ran it a second time.  It printed more messages, but curiously it
errored out after saying that it deleted another
xdg-desktop-database.drv:

--8<---------------cut here---------------start------------->8---
$ guix gc -C 25GiB
...
deleting `/gnu/store/d5z2lazx11qz571mwy59gwlqxidj0h4r-gtk-im-modules.drv'
deleting `/gnu/store/gc36aax38fs194ll5s17j8a8l8arm09a-gtk-icon-themes.drv'
deleting `/gnu/store/hbxvgm2pc6f6jn2fai30izc7f5kd25qd-gtk-im-modules.drv'
deleting `/gnu/store/hrc7yacy4ckmp3zi5pgmzd5ciqzv40ih-xdg-desktop-database.drv'
guix gc: error: executing SQLite statement: database disk image is malformed
--8<---------------cut here---------------end--------------->8---

I ran it a third time, and it printed:

--8<---------------cut here---------------start------------->8---
$ guix gc -C 25GiB
finding garbage collector roots...
deleting garbage...
deleting `/gnu/store/1dqflkm3029ncacx5vl9r95ldfcfs3m0-pugixml-1.9.drv'
guix gc: error: executing SQLite statement: database disk image is malformed
--8<---------------cut here---------------end--------------->8---

I ran it a fourth time, and it printed:

--8<---------------cut here---------------start------------->8---
$ guix gc -C 25GiB
...
deleting `/gnu/store/w0nbsjjb1pj9pi1aim1qcbjq93zss9pn-libwpd-0.10.2.drv'
deleting `/gnu/store/ywdgn73h9kdfcvs6cr1nfjqqj245p788-librevenge-0.0.4.drv'
deleting `/gnu/store/ryawkapgxirj6yp54zb5vak027xxk2i1-cppunit-1.14.0.drv'
deleting `/gnu/store/g2p20iss1r58r4ch2qggzyqn9d5q4kaf-cppunit-1.14.0.tar.gz.drv'
guix gc: error: executing SQLite statement: database disk image is malformed
--8<---------------cut here---------------end--------------->8---

I wonder what has brought my installation into this state.  I can't
think of a way to fix it since I don't even know what caused it, so I
will probably re-install Guix to work around the issue, but before I do
that, is there anything we can check to understand why the database
corruption has occurred?

For the record, I do sometimes abruptly power off my machine, and it
does rarely abruptly crash (I think I have reported this when it occurs,
but I can't be sure).  In such cases, when booting, I see messages
telling me that the system is recovering the journal from my ext4 file
system, and I do not recall ever seeing an error from that process, but
who knows what mischief I've been causing to my system over the years.

-- 
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Ricardo Wurmus]

Chris Marusich <cmmarusich@gmail.com> writes:

> is there anything we can check to understand why the database
> corruption has occurred?
[…]
> For the record, I do sometimes abruptly power off my machine, and it
> does rarely abruptly crash (I think I have reported this when it occurs,
> but I can't be sure).

This can be a cause of corruption.

Have you manually run fsck on the unmounted disk yet?

-- 
Ricardo

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Chris Marusich]

[-- Attachment #1: Type: text/plain, Size: 4738 bytes --]

Ricardo Wurmus <rekado@elephly.net> writes:

> Chris Marusich <cmmarusich@gmail.com> writes:
>
>> is there anything we can check to understand why the database
>> corruption has occurred?
> […]
>> For the record, I do sometimes abruptly power off my machine, and it
>> does rarely abruptly crash (I think I have reported this when it occurs,
>> but I can't be sure).
>
> This can be a cause of corruption.
>
> Have you manually run fsck on the unmounted disk yet?

Yes, I have.  The file system containing the database is my root file
system, and it is ext4.  On my system, Guix runs e2fsck on the root file
system automatically on each boot [1].  However, just to be sure, I ran
it manually on the unmounted device with the -f option to force a check.
It reported the following (I've copied this output by hand):

--8<---------------cut here---------------start------------->8---
root@spaceship ~# e2fsck -f /dev/mapper/home
e2fsck 1.45.2 (27-May-2019)
Pass 1: Checking inodes, blocks, and sizes
Inode 290237 extent tree (at level 2) could be narrower.  Optimize<y>? yes
Inode 291644 extent tree (at level 2) could be narrower.  Optimize<y>? yes
Inode 446822 extent tree (at level 1) could be narrower.  Optimize<y>? yes
Inode 3016396 extent tree (at level 2) could be narrower.  Optimize<y>? yes
Pass 1E: Optimizing extent trees
Pass 2: Checking directory structure
Problem in HTREE directory inode 12451844: block #21606 has bad min hash
Invalid HTREE directory inode 12451844 (/gnu/store/.links).  Clear HTree index<y>? yes
Pass 3: Checking directory connectivity
Pass 3A: Optimizing directories
Pass 4: Checking reference counts
Pass 5: Checking group summary information

root: ***** FILE SYSTEM WAS MODIFIED *****
root: 1761282/14000128 files (0.4% non-contiguous), 50020294/55985664 blocks
root@spaceship ~# echo $?
1
--8<---------------cut here---------------end--------------->8---

Unfortunately, when I rebooted and tried "guix gc", the same problem as
before occurred.

I saw that Mike Gerwitz encountered the same error, so I thought I would
try his work-around [2].  Before proceeding, I stopped guix-daemon
("sudo herd stop guix-daemon") and verified that no processes were
accessing the database file ("sudo fuser db.sqlite").  Then I made a
backup of my entire /var/guix directory.

I dumped the database to SQL and recreated it like so:

  sudo sqlite3 db.sqlite .dump > /tmp/db.sqlite.dump
  sudo rm db.sqlite
  sudo sqlite3 db.sqlite < /tmp/db.sqlite.dump

This succeeded without errors or warnings, and it reduced the size of
the db.sqlite file from 145 MiB to 49 MiB.  Although Mike's dump ended
with a "ROLLBACK" and needed to be manually modified, mine ended with a
"COMMIT" and did not require manual modification.

I then started guix-daemon ("sudo herd start guix-daemon") and attempted
to run "guix gc -C 1GiB", which succeeded.  I followed that up with
another "guix gc -C 40GiB", which also succeeded.

The sqlite documentation says that this method of dumping and recreating
the database is supported [3], so I think it's a valid work-around.
However, you never know...  Dumping and restoring the database file
obviously changed it, so even if the restored database is "equivalent"
to the original, it's still conceivable that the difference might cause
a problem somehow.  After all, obviously it was different enough that
guix-daemon stopped failing.  But maybe I'm being too pessimistic.

In any case, it's notable that guix-daemon claimed the database was
corrupt, even though sqlite3 didn't complain about it.  Since the size
was reduced, I suppose sqlite3 cleaned it up or optimized it somehow.
Maybe in doing so, it fixed something that guix-daemon didn't know how
to handle?  That's just a guess.

It's concerning that this "corruption" has occurred for two different
people recently.  We might want to check the Nix bug reports to see if
they've encountered a bug like this.  I did a (very) cursory search and
found only this possibly similar, but possibly unrelated issue:

https://github.com/NixOS/nixpkgs/issues/3958

It may be worth looking harder before diving too deeply into debugging.

If you can think of anything I can do to drill into the files or debug
this more, please let me know.  If the database files do not contain
sensitive information, I would also be willing to share them with you
for further debugging.

Footnotes: 
[1]  https://git.savannah.gnu.org/cgit/guix.git/tree/gnu/build/linux-boot.scm?id=afb986e77cd669c2f21953f501f7893237730ca7#n383

[2]  https://lists.gnu.org/archive/html/help-guix/2019-08/msg00012.html

[3]  https://sqlite.org/cli.html#dump

-- 
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Mike Gerwitz]

[-- Attachment #1: Type: text/plain, Size: 372 bytes --]

Sorry I hadn't seen this bug report; it was opened after I researched
this issue a couple months ago and I didn't bother checking since.

Here's the thread I posted to help-guix: <87lfwbuj27.fsf@gnu.org>.

-- 
Mike Gerwitz
Free Software Hacker+Activist | GNU Maintainer & Volunteer
GPG: D6E9 B930 028A 6C38 F43B  2388 FEF6 3574 5E6F 6D05
https://mikegerwitz.com

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 818 bytes --]

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[Chris Marusich]

[-- Attachment #1: Type: text/plain, Size: 314 bytes --]

Chris Marusich <cmmarusich@gmail.com> writes:

> I wonder what has brought my installation into this state.  I can't
> think of a way to fix it since I don't even know what caused it, so I
> will probably re-install Guix to work around the issue

I re-installed Guix to work around the issue.

-- 
Chris

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 832 bytes --]

bug#36687: guix gc: error: executing SQLite statement: database disk image is malformed

[pkill9 via Bug reports for GNU Guix]

[-- Attachment #1: Type: text/plain, Size: 341 bytes --]

Hi, I fixed this issue using sqlite3's built-in recover command:

sudo mv /var/guix/db/db.sqlite /var/guix/db/db.sqlite.bak
sqlite3 /var/guix/db/db.sqlite.bak ".recover" | sudo sqlite3 
/var/guix/db/db.sqlite

Solution was found at 
<https://stackoverflow.com/questions/18259692/how-to-recover-a-corrupt-sqlite3-database/57872238#57872238>


[-- Attachment #2: Type: text/html, Size: 681 bytes --]