Consistency failure during fsck after downloading old metadata

45 views
Skip to first unread message

Rabid Mutant

unread,
Apr 9, 2020, 12:23:07 AM4/9/20
to s3ql
fsck now terminates with UNIQUE constraint failed: contents.parent_inode, contents.name_id

Running version 3.3.2
Server crashed while mounted.
Reboorted and needed fsck
fsck reported that
ERROR: Local metadata is corrupted. Remove or repair the following files manually and re-run fsck:
...2 files listed...

Deleted those two files.

Re-ran fsck; the following is the log:

```Starting fsck of s3://ap-southeast-2/pjwcloudbackup/olympus
Backend reports that file system is still mounted elsewhere. Either
the file system has not been unmounted cleanly or the data has not yet
propagated through the backend. In the later case, waiting for a while
should fix the problem, in the former case you should try to run fsck
on the computer where the file system has been mounted most recently.
You may also continue and use whatever metadata is available in the
backend. However, in that case YOU MAY LOOSE ALL DATA THAT HAS BEEN
UPLOADED OR MODIFIED SINCE THE LAST SUCCESSFULL METADATA UPLOAD.
Moreover, files and directories that you have deleted since then MAY
REAPPEAR WITH SOME OF THEIR CONTENT LOST.
Enter "continue, I know what I am doing" to use the outdated data anyway:
continue, I know what I am doing
Downloading and decompressing metadata...
Reading metadata...
..objects..
..blocks..
..inodes..
..inode_blocks..
..symlink_targets..
..names..
..contents..
> ERROR: Uncaught top-level exception:
Traceback (most recent call last):
  File "src/s3ql/deltadump.pyx", line 531, in s3ql.deltadump.load_table
  File "src/s3ql/deltadump.pyx", line 186, in s3ql.deltadump.SQLITE_CHECK_RC
apsw.ConstraintError: UNIQUE constraint failed: contents.parent_inode, contents.name_id

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/fsck.s3ql", line 11, in <module>
    load_entry_point('s3ql==3.3.2', 'console_scripts', 'fsck.s3ql')()
  File "/usr/lib64/python3.6/site-packages/s3ql-3.3.2-py3.6-linux-x86_64.egg/s3ql/fsck.py", line 1263, in main
    db = download_metadata(backend, cachepath + '.db')
  File "/usr/lib64/python3.6/site-packages/s3ql-3.3.2-py3.6-linux-x86_64.egg/s3ql/metadata.py", line 307, in download_metadata
    return restore_metadata(tmpfh, db_file)
  File "/usr/lib64/python3.6/site-packages/s3ql-3.3.2-py3.6-linux-x86_64.egg/s3ql/metadata.py", line 97, in restore_metadata
    load_table(table, columns, db=db, fh=fh)
  File "src/s3ql/deltadump.pyx", line 427, in s3ql.deltadump.load_table
  File "/usr/lib64/python3.6/contextlib.py", line 380, in __exit__
    raise exc_details[1]
  File "/usr/lib64/python3.6/contextlib.py", line 365, in __exit__
    if cb(*exc_details):
  File "/usr/lib64/python3.6/contextlib.py", line 314, in _exit_wrapper
    callback(*args, **kwds)
  File "src/s3ql/deltadump.pyx", line 473, in s3ql.deltadump.load_table.lambda11
  File "src/s3ql/deltadump.pyx", line 186, in s3ql.deltadump.SQLITE_CHECK_RC
apsw.ConstraintError: UNIQUE constraint failed: contents.parent_inode, contents.name_id
```


Any help would be apreciated, since I clearly lied and have no idea what I'm doing.

Rabid Mutant

unread,
Apr 9, 2020, 8:27:27 AM4/9/20
to s3ql
FWIW, I used s3qladm download-metadata to download the second-most-recent metatdata, and the fskc ran successfully. -- with a bunch of like the following:

Deleted spurious object 299006
...
object 298984 only exists in table but not in backend, deleting
...
WARNING: object 298991 only exists in table but not in backend, deleting

But, once complete I was about to mount etc and resume use.

Since the file system is a mirror/backup that occurs every hour, I am not particularly concerned with losing 2 hours, but I am very interested to know if this is the correct approach to have used, or if there are better approaches.

Daniel Jagszent

unread,
Apr 9, 2020, 9:01:14 AM4/9/20
to s3ql
Hi,

[...] I am not particularly concerned with losing 2 hours, but I am very interested to know if this is the correct approach to have used, or if there are better approaches.

I would probably have spend some time to try to repair the local metadata. It's a SQLite database so installing the sqlite CLI and opening the database up with that tool can help most of the time. Downloading the metadata backups should be the very last resort.
PS: do you upload metadata backups every hour (i.e. you changed --metadata-upload-interval)? Normally they get uploaded every 24 hours so you would loose up to two days, not two hours.

The error from fsck (apsw.ConstraintError: UNIQUE constraint failed: contents.parent_inode, contents.name_id) means that you somehow had two files in a directory with the same name. I have no clue how that could have happened, since that error should have occurred the moment the second file would have been created.  If you know, how that might have happened, please do tell so that we can try to fix S3QL to prevent these errors.


Rabid Mutant

unread,
Apr 9, 2020, 9:14:54 AM4/9/20
to s3ql
On Thursday, April 9, 2020 at 11:01:14 PM UTC+10, Daniel Jagszent wrote:
Hi,

[...] I am not particularly concerned with losing 2 hours, but I am very interested to know if this is the correct approach to have used, or if there are better approaches.

PS: do you upload metadata backups every hour (i.e. you changed --metadata-upload-interval)? Normally they get uploaded every 24 hours so you would loose up to two days, not two hours.

It's a mount/rsync/dismount; I'm pretty sure the unmount moves the metadata. I'd prefer every 24 hours, if that could be managed, but they are/were every hour.

 

The error from fsck (apsw.ConstraintError: UNIQUE constraint failed: contents.parent_inode, contents.name_id) means that you somehow had two files in a directory with the same name. I have no clue how that could have happened, since that error should have occurred the moment the second file would have been created.  If you know, how that might have happened, please do tell so that we can try to fix S3QL to prevent these errors.

I still have a snapshot of the old bad database I think...is there a query you could suggest to find the offending record, that might jog my memory.

I tried:

select * from contents c join contents c1 on c1.parent_inode = c.parent_inode and c1.name_id = c.name_id and c1.rowid > c.rowid;

and got a lot of rows...which is a tad scary given the constraint on the table.



 

Daniel Jagszent

unread,
Apr 9, 2020, 9:35:24 AM4/9/20
to s3ql
Hi,

> [...] It's a mount/rsync/dismount; I'm pretty sure the unmount moves
> the metadata. I'd prefer every 24 hours, if that could be managed, but
> they are/were every hour.[...]
that's correct.

> [...]
> I still have a snapshot of the old bad database I think...is there a
> query you could suggest to find the offending record, that might jog
> my memory.
> I tried:
> select * from contents c join contents c1 on c1.parent_inode =
> c.parent_inode and c1.name_id = c.name_id and c1.rowid > c.rowid;
> and got a lot of rows...which is a tad scary given the constraint on
> the table.
That SQL command looks ok to me. Maybe also try to run a "REINDEX
contents;" (https://sqlite.org/lang_reindex.html)
Also check with ".schema contents" and ".indexes contents" if that index
does exist.
(https://sqlite.org/cli.html#special_commands_to_sqlite3_dot_commands_)

Try to run the same command on the now fixed database (making a copy to
be on the safe side). It should not show any results. If that is the
case, then you somehow got many duplicate files in directories. Are the
parent_inodes all the same (problem was only in one folder) or different?

Rabid Mutant

unread,
Apr 9, 2020, 9:58:35 AM4/9/20
to s3ql

Try to run the same command on the now fixed database (making a copy to
be on the safe side). It should not show any results. If that is the
case, then you somehow got many duplicate files in directories. Are the
parent_inodes all the same (problem was only in one folder) or different?


Produces zero rows on current DB.

pragma integrity_check produces:

row 52535 missing from index sqlite_autoindex_contents_1
row 52536 missing from index sqlite_autoindex_contents_1
row 52537 missing from index sqlite_autoindex_contents_1
row 52538 missing from index sqlite_autoindex_contents_1
row 52539 missing from index sqlite_autoindex_contents_1
row 52540 missing from index sqlite_autoindex_contents_1
row 52541 missing from index sqlite_autoindex_contents_1
row 52542 missing from index sqlite_autoindex_contents_1
row 52543 missing from index sqlite_autoindex_contents_1
row 52544 missing from index sqlite_autoindex_contents_1
row 52545 missing from index sqlite_autoindex_contents_1
row 52546 missing from index sqlite_autoindex_contents_1
row 52547 missing from index sqlite_autoindex_contents_1
row 52548 missing from index sqlite_autoindex_contents_1
row 52549 missing from index sqlite_autoindex_contents_1
row 52550 missing from index sqlite_autoindex_contents_1
row 52551 missing from index sqlite_autoindex_contents_1
row 52552 missing from index sqlite_autoindex_contents_1
row 52553 missing from index sqlite_autoindex_contents_1
row 52554 missing from index sqlite_autoindex_contents_1
row 52555 missing from index sqlite_autoindex_contents_1
row 52556 missing from index sqlite_autoindex_contents_1
row 52557 missing from index sqlite_autoindex_contents_1
row 52558 missing from index sqlite_autoindex_contents_1
row 52559 missing from index sqlite_autoindex_contents_1
row 52560 missing from index sqlite_autoindex_contents_1
row 52561 missing from index sqlite_autoindex_contents_1
row 52562 missing from index sqlite_autoindex_contents_1
row 52563 missing from index sqlite_autoindex_contents_1
row 52564 missing from index sqlite_autoindex_contents_1
row 52565 missing from index sqlite_autoindex_contents_1
row 52566 missing from index sqlite_autoindex_contents_1
row 52567 missing from index sqlite_autoindex_contents_1
row 52568 missing from index sqlite_autoindex_contents_1
row 52569 missing from index sqlite_autoindex_contents_1
row 52570 missing from index sqlite_autoindex_contents_1
row 52571 missing from index sqlite_autoindex_contents_1
row 52572 missing from index sqlite_autoindex_contents_1
row 52573 missing from index sqlite_autoindex_contents_1
row 52574 missing from index sqlite_autoindex_contents_1
row 52575 missing from index sqlite_autoindex_contents_1
row 52576 missing from index sqlite_autoindex_contents_1
row 52577 missing from index sqlite_autoindex_contents_1
row 52578 missing from index sqlite_autoindex_contents_1
row 52579 missing from index sqlite_autoindex_contents_1
row 52580 missing from index sqlite_autoindex_contents_1
row 52581 missing from index sqlite_autoindex_contents_1
row 52582 missing from index sqlite_autoindex_contents_1
row 52583 missing from index sqlite_autoindex_contents_1
row 52584 missing from index sqlite_autoindex_contents_1
row 52585 missing from index sqlite_autoindex_contents_1
row 52586 missing from index sqlite_autoindex_contents_1
row 52587 missing from index sqlite_autoindex_contents_1
row 52588 missing from index sqlite_autoindex_contents_1
row 52589 missing from index sqlite_autoindex_contents_1
row 52590 missing from index sqlite_autoindex_contents_1
row 52591 missing from index sqlite_autoindex_contents_1
row 52592 missing from index sqlite_autoindex_contents_1
row 52593 missing from index sqlite_autoindex_contents_1
row 52594 missing from index sqlite_autoindex_contents_1
row 52595 missing from index sqlite_autoindex_contents_1
row 52596 missing from index sqlite_autoindex_contents_1
row 52597 missing from index sqlite_autoindex_contents_1
row 52598 missing from index sqlite_autoindex_contents_1
row 52599 missing from index sqlite_autoindex_contents_1
row 52600 missing from index sqlite_autoindex_contents_1
row 52601 missing from index sqlite_autoindex_contents_1
row 52602 missing from index sqlite_autoindex_contents_1
row 52603 missing from index sqlite_autoindex_contents_1
row 52604 missing from index sqlite_autoindex_contents_1
row 52605 missing from index sqlite_autoindex_contents_1
row 52606 missing from index sqlite_autoindex_contents_1
row 52607 missing from index sqlite_autoindex_contents_1
row 52608 missing from index sqlite_autoindex_contents_1
row 52609 missing from index sqlite_autoindex_contents_1
row 52610 missing from index sqlite_autoindex_contents_1
row 52611 missing from index sqlite_autoindex_contents_1
row 52612 missing from index sqlite_autoindex_contents_1
row 52613 missing from index sqlite_autoindex_contents_1
row 52614 missing from index sqlite_autoindex_contents_1
row 52615 missing from index sqlite_autoindex_contents_1
row 52616 missing from index sqlite_autoindex_contents_1
row 52617 missing from index sqlite_autoindex_contents_1
row 52618 missing from index sqlite_autoindex_contents_1
row 52619 missing from index sqlite_autoindex_contents_1
row 52620 missing from index sqlite_autoindex_contents_1
row 52621 missing from index sqlite_autoindex_contents_1
row 52622 missing from index sqlite_autoindex_contents_1
row 52623 missing from index sqlite_autoindex_contents_1
row 52624 missing from index sqlite_autoindex_contents_1
row 52625 missing from index sqlite_autoindex_contents_1
row 52626 missing from index sqlite_autoindex_contents_1
row 52627 missing from index sqlite_autoindex_contents_1
row 52628 missing from index sqlite_autoindex_contents_1
row 52629 missing from index sqlite_autoindex_contents_1
row 52630 missing from index sqlite_autoindex_contents_1
row 52631 missing from index sqlite_autoindex_contents_1
row 52632 missing from index sqlite_autoindex_contents_1
row 52633 missing from index sqlite_autoindex_contents_1
row 52634 missing from index sqlite_autoindex_contents_1

Further, while:

select c.* from contents c join contents c1 on c1.parent_inode = c.parent_inode and c1.name_id = c.name_id and c1.rowid > c.rowid join names n on n.id=c.name_id;

produces a lot of rows, the same query with just 'select c.parent_inode...' produces NO ROWS.

Looks like a very messed up database; at least a corrupt index I suspect.

Rabid Mutant

unread,
Apr 9, 2020, 10:05:44 AM4/9/20
to s3ql
On Thursday, April 9, 2020 at 11:58:35 PM UTC+10, Rabid Mutant wrote:

Looks like a very messed up database; at least a corrupt index I suspect.

I'm wondering if at some point the journal file got clobbered, or was not backed up.

Daniel Jagszent

unread,
Apr 9, 2020, 10:12:50 AM4/9/20
to Rabid Mutant, s3ql

> I'm wondering if at some point the journal file got clobbered, or was
> not backed up.
AFAIK S3QL does not use journaling
https://github.com/s3ql/s3ql/blob/595b774705b95be350e3b262738e929d390ba885/src/s3ql/database.py#L34


Rabid Mutant

unread,
Apr 9, 2020, 10:22:14 AM4/9/20
to s3ql
That leaves open the possibility of a corruption due to a crash then; from SQLite docs: "Without a journal, there is no way for a statement to unwind partially completed operations following a constraint error. This might also leave the database in a corrupted state."

Which is probably what happened; my mount logs show the following, which correspond to the time the corrupt DB was created (though the disks all have several GB  free, so I'm confused as to the cause of the error):

2020-04-09 11:07:59.300 30668:MainThread s3ql.metadata.dump_metadata: ..contents..
2020-04-09 11:08:04.177 30668:MainThread s3ql.metadata.dump_metadata: ..ext_attributes..
2020-04-09 11:08:04.178 30668:MainThread s3ql.metadata.upload_metadata: Compressing and uploading metadata...
2020-04-09 11:12:11.918 30668:MainThread s3ql.metadata.upload_metadata: Wrote 55.9 MiB of compressed metadata.
2020-04-09 11:12:11.918 30668:MainThread s3ql.metadata.upload_metadata: Cycling metadata backups...
2020-04-09 11:12:11.918 30668:MainThread s3ql.metadata.cycle_metadata: Backing up old metadata...
2020-04-09 11:12:25.099 30668:MainThread s3ql.mount.main: Cleaning up local metadata...
2020-04-09 11:13:19.111 30668:MainThread root.excepthook: Uncaught top-level exception:

Traceback (most recent call last):
  File "/usr/bin/mount.s3ql", line 11, in <module>
    load_entry_point('s3ql==3.3.2', 'console_scripts', 'mount.s3ql')()
  File "/usr/lib64/python3.6/site-packages/s3ql-3.3.2-py3.6-linux-x86_64.egg/s3ql/mount.py", line 263, in main
    db.execute('VACUUM')
  File "/usr/lib64/python3.6/site-packages/s3ql-3.3.2-py3.6-linux-x86_64.egg/s3ql/database.py", line 98, in execute
    self.conn.cursor().execute(*a, **kw)
  File "src/cursor.c", line 236, in resetcursor
apsw.FullError: FullError: database or disk is full


Daniel Jagszent

unread,
Apr 9, 2020, 10:30:20 AM4/9/20
to s3ql
> [...]Which is probably what happened; my mount logs show the
> following, which correspond to the time the corrupt DB was created
> (though the disks all have several GB  free, so I'm confused as to the
> cause of the error):
> [...]
> apsw.FullError: FullError: database or disk is full
Looks like the same as
https://groups.google.com/forum/#!topic/s3ql/lN5JrIq0_OU
<https://groups.google.com/forum/#%21topic/s3ql/lN5JrIq0_OU>

Do you maybe have a ramdisk /tmp ?

Rabid Mutant

unread,
Apr 9, 2020, 10:37:40 AM4/9/20
to s3ql
No. /tmp and /var/tmp are on disk. There is/was 6-7GB free, the database is 800M which not vacuumed...I suppose with s3ql cache, two copies of the database (vaccum), and some bad luck...perhaps it became full?

Daniel Jagszent

unread,
Apr 9, 2020, 11:08:11 AM4/9/20
to s3ql
HI
> [...]No. /tmp and /var/tmp are on disk. There is/was 6-7GB free, the
> database is 800M which not vacuumed...I suppose with s3ql cache, two
> copies of the database (vaccum), and some bad luck...perhaps it became
> full?
Looks like it. Especially if  you store the S3QL cache in /var/tmp, too.

Nikolaus Rath

unread,
Apr 9, 2020, 2:09:01 PM4/9/20
to s3...@googlegroups.com
On Apr 09 2020, Daniel Jagszent <dan...@jagszent.de> wrote:
> Hi,
>
>> [...] I am not particularly concerned with losing 2 hours, but I am
>> very interested to know if this is the correct approach to have used,
>> or if there are better approaches.
>
> I would probably have spend some time to try to repair the local
> metadata. It's a SQLite <https://sqlite.org/index.html> database so
> installing the sqlite CLI and opening the database up with that tool can
> help most of the time. Downloading the metadata backups should be the
> very last resort.
> PS: do you upload metadata backups every hour (i.e. you changed
> --metadata-upload-interval)? Normally they get uploaded every 24 hours
> so you would loose up to two days, not two hours.
>
> The error from fsck (apsw.ConstraintError: UNIQUE constraint failed:
> contents.parent_inode, contents.name_id) means that you somehow had two
> files in a directory with the same name. I have no clue how that could
> have happened,

My guess is that it is simple corruption of the data. The original email
said that the server crashed. This means that the SQLite database can
get corrupted.

Best,
-Nikolaus

--
GPG Fingerprint: ED31 791B 2C5C 1613 AF38 8B8A D113 FCAC 3C4E 599F

»Time flies like an arrow, fruit flies like a Banana.«

Rabid Mutant

unread,
Apr 9, 2020, 10:23:04 PM4/9/20
to s3ql
On Friday, April 10, 2020 at 4:09:01 AM UTC+10, Nikolaus Rath wrote:

My guess is that it is simple corruption of the data. The original email
said that the server crashed. This means that the SQLite database can
get corrupted.

Looking through snapshots of the database, it was corrupted 2 hours before the server was shut down (didn't crash, but an s3ql session was in progress at shutdown). The corruption was, I think, due to the device being full during an unmount, and SQLite not being able to rollback properly. This seems to fit with the history pretty well (mount.log showing device full errors, database snapshots being good before those errors, corrupt after).

Obviously I am rethinking the hourly mount/rsync/unmount cycle since it's harder to ensure unmount at system shutdown, and have not moved everything to a drive with more space.

Unfortunately, I have a lot of s3ql snapshots, which means I have a huge DB which takes about 5 minutes to sync to amazon; that time would be added to any shutdown so permanently mounting it is not a clear win.

If I do a lazy dismount, then shutdown, am I correct an fsck will still be needed? I guess the solution there would to always do an fsck before mount after system boot.

Nikolaus Rath

unread,
Apr 10, 2020, 11:00:14 AM4/10/20
to s3...@googlegroups.com
On Apr 09 2020, Rabid Mutant <rabidmuta...@gmail.com> wrote:
> On Friday, April 10, 2020 at 4:09:01 AM UTC+10, Nikolaus Rath wrote:
>>
>>
>> My guess is that it is simple corruption of the data. The original email
>> said that the server crashed. This means that the SQLite database can
>> get corrupted.
>>
>
> Looking through snapshots of the database, it was corrupted 2 hours before
> the server was shut down (didn't crash, but an s3ql session was in progress
> at shutdown). The corruption was, I think, due to the device being full
> during an unmount, and SQLite not being able to rollback properly. This
> seems to fit with the history pretty well (mount.log showing device full
> errors, database snapshots being good before those errors, corrupt after).
>
> Obviously I am rethinking the hourly mount/rsync/unmount cycle since it's
> harder to ensure unmount at system shutdown, and have not moved everything
> to a drive with more space.

What makes it hard? You probably just have to increase a timeout
somewhere...


> Unfortunately, I have a lot of s3ql snapshots, which means I have a huge DB
> which takes about 5 minutes to sync to amazon; that time would be added to
> any shutdown so permanently mounting it is not a clear win.

Shutdown only requires a metadata upload if the data has changed since
the last upload (which you can trigger with s3qlctrl without needing to
unmount), so it's not always slow.


> If I do a lazy dismount, then shutdown, am I correct an fsck will still be
> needed? I guess the solution there would to always do an fsck before mount
> after system boot.

I'd very much advise against crashing the filesystem by default. I'd
just ensure that shutdown is blocked until the file system is unmounted,
no matter if you mount temporarily or permanently.
Reply all
Reply to author
Forward
0 new messages