Something corrupted /var/lib/pacman/local/ [solved]

graysky · 2021-11-29 07:34:51

I am unsure what caused this, but something borked my system resulting in approx 8,000 files which now seem to be orphaned:

# lostfiles|wc -l
8113

Picking just one at random:

% pacman -Qo /usr/bin/melt
error: No package owns /usr/bin/melt

Running pacman -Qkk shows that indeed there are problems with that package's local db entry:

...
mkinitcpio: 81 total files, 0 altered files
mkinitcpio-busybox: 4 total files, 0 altered files
mkvtoolnix-cli: 170 total files, 0 altered files
error: error while reading file /var/lib/pacman/local/mlt-7.2.0-2/mtree: Unrecognized archive format
mlt: no mtree file
...

All 0-byte files here:

% ls -lh /var/lib/pacman/local/mlt-7.2.0-2
total 0
-rw-r--r-- 1 root root 0 Nov 27 11:44 desc
-rw-r--r-- 1 root root 0 Nov 27 11:44 files
-rw-r--r-- 1 root root 0 Nov  9 14:57 mtree

1) What could have caused this?
2) What is the best way to fix it (the wiki has Restore_local_database)?

I do not believe it to be hardware errors based on the error log for the device:

# smartctl -i -a /dev/nvme1n1
smartctl 7.2 2020-12-30 r5155 [x86_64-linux-5.15.5-1-minimum] (local build)
Copyright (C) 2002-20, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Number:                       Samsung SSD 950 PRO 256GB
Firmware Version:                   1B0QBXX7
PCI Vendor/Subsystem ID:            0x144d
IEEE OUI Identifier:                0x002538
Controller ID:                      1
NVMe Version:                       <1.2
Number of Namespaces:               1
Namespace 1 Size/Capacity:          256,060,514,304 [256 GB]
Namespace 1 Utilization:            81,860,100,096 [81.8 GB]
Namespace 1 Formatted LBA Size:     512
Namespace 1 IEEE EUI-64:            002538 5461b00895
Local Time is:                      Mon Nov 29 08:01:10 2021 EST
Firmware Updates (0x06):            3 Slots
Optional Admin Commands (0x0007):   Security Format Frmw_DL
Optional NVM Commands (0x001f):     Comp Wr_Unc DS_Mngmt Wr_Zero Sav/Sel_Feat
Log Page Attributes (0x01):         S/H_per_NS
Maximum Data Transfer Size:         32 Pages

Supported Power States
St Op     Max   Active     Idle   RL RT WL WT  Ent_Lat  Ex_Lat
 0 +     6.50W       -        -    0  0  0  0        5       5
 1 +     5.80W       -        -    1  1  1  1       30      30
 2 +     3.60W       -        -    2  2  2  2      100     100
 3 -   0.0700W       -        -    3  3  3  3      500    5000
 4 -   0.0050W       -        -    4  4  4  4     2000   22000

Supported LBA Sizes (NSID 0x1)
Id Fmt  Data  Metadt  Rel_Perf
 0 +     512       0         0

=== START OF SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

SMART/Health Information (NVMe Log 0x02)
Critical Warning:                   0x00
Temperature:                        43 Celsius
Available Spare:                    100%
Available Spare Threshold:          10%
Percentage Used:                    0%
Data Units Read:                    16,048,455 [8.21 TB]
Data Units Written:                 10,239,636 [5.24 TB]
Host Read Commands:                 225,546,910
Host Write Commands:                106,033,767
Controller Busy Time:               755
Power Cycles:                       1,790
Power On Hours:                     27,926
Unsafe Shutdowns:                   42
Media and Data Integrity Errors:    0
Error Information Log Entries:      3,519

Error Information (NVMe Log 0x01, 16 of 64 entries)
Num   ErrCount  SQId   CmdId  Status  PELoc          LBA  NSID    VS
  0       3519     0  0x200c  0x4004  0x000            0     0     -
  1       3518     0  0x100d  0x4004  0x000            0     0     -
  2       3517     0  0x2004  0x4004  0x000            0     0     -
  3       3516     0  0x1005  0x4004  0x000            0     0     -
  4       3515     0  0x2014  0x4004  0x000            0     0     -
  5       3514     0  0x1015  0x4004  0x000            0     0     -
  6       3513     0  0x2008  0x4004  0x000            0     0     -
  7       3512     0  0x1009  0x4004  0x000            0     0     -
  8       3511     0  0x2010  0x4004  0x000            0     0     -
  9       3510     0  0x1011  0x4004  0x000            0     0     -
 10       3509     0  0x200c  0x4004  0x000            0     0     -
 11       3508     0  0x100d  0x4004  0x000            0     0     -
 12       3507     0  0x2014  0x4004  0x000            0     0     -
 13       3506     0  0x1015  0x4004  0x000            0     0     -
 14       3505     0  0x2014  0x4004  0x000            0     0     -
 15       3504     0  0x1015  0x4004  0x000            0     0     -
... (48 entries not read)

Using nvme to read the thing gives multiple entries like this (truncated at just two):

# nvme error-log /dev/nvme1n1
Error Log Entries for device:nvme1n1 entries:64
.................
 Entry[ 0]   
.................
error_count	: 3519
sqid		: 0
cmdid		: 0x200c
status_field	: 0x2002(INVALID_FIELD: A reserved coded value or an unsupported value in a defined field)
phase_tag	: 0
parm_err_loc	: 0
lba		: 0
nsid		: 0
vs		: 0
trtype		: The transport type is not indicated or the error is not transport related.
cs		: 0
trtype_spec_info: 0
.................
 Entry[ 1]   
.................
error_count	: 3518
sqid		: 0
cmdid		: 0x100d
status_field	: 0x2002(INVALID_FIELD: A reserved coded value or an unsupported value in a defined field)
phase_tag	: 0
parm_err_loc	: 0
lba		: 0
nsid		: 0
vs		: 0
trtype		: The transport type is not indicated or the error is not transport related.
cs		: 0
trtype_spec_info: 0
.................
...

Last edited by graysky (2021-11-29 22:44:35)

graysky · 2021-11-29 12:11:48

I edited my original post. I no longer believe this was caused by an ungraceful shutdown. I based this on booting to another Arch install on a separate partition (minimal one I use for maintenance of the primary one without booting to live media) and found that it too is affected by these 0-byte issues in /var/lib/pacman/local/

Hardware failure (I am seeing nothing in dmesg nor in smartctl for this SSD)? Something more sinister?

EDIT:
Based on the timestamp of several 0-byte files corresponding to the bad entries to the 2nd partition, I believe this happened while updating (on 27-Nov for me).

Timestamp on the update from pacman.log is 2021-11-27T11:42:08-0500
Timestamp on affected files: Nov 27 11:42

Here is my pacman.log from when I suspect the problem started. I didn't see anything relevant in there but you can see tons of errors ldconfig threw on a subsequent update.

Last edited by graysky (2021-11-29 12:52:25)

Scimmia · 2021-11-29 13:19:26

Since you edited, I can't see what you were saying about an ungraceful shutdown, but that does sound like what happened. You have a bunch of files that are empty, not just in the pacman database, which means that they weren't fully written to disk.

graysky · 2021-11-29 13:33:25

@Scimmia - My edit took out a sentence like "I suspect this may have been caused by an ungraceful shutdown..." The fact that the same phenomenon happened to two different Arch installs at two different times albeit on the same physical SSD makes me think an ungraceful shutdown is not to blame.

Scimmia · 2021-11-29 13:36:14

Maybe not, but it does come down to data not being written to disk when it was powered off. Bad disk, bad controller, bad filesystems, all possibilities.

seth · 2021-11-29 14:40:51

Filesystem bug or unclean shutdown (no fsync by umount) or wrong trimming strategy.
Was the other partition mounted during the incident that caused the original problem?

graysky · 2021-11-29 14:48:55

@seth - No, that minimal installation's partition was not mounted when I initially experienced this.

seth · 2021-11-29 15:07:17

Then why are the timestamps aligned?
The bad files on the 2nd partition are 11:42 what matches the updadte in the posted pacman log (on that partition? Which system did you update?)
The bad files on the 1st partition are 11:44 - does that match the corresponding pacman log?

Are more files affected? Try eg.

find  /usr -type f -empty
find  /etc -type f -empty

Last but not least: ext4 or btrfs?

Scimmia · 2021-11-29 15:12:14

The ldconfig errors say that a bunch of libs are empty, there's probably more than that as well.

We can move on to fixing it, but if it's happened multiple times already, we need to figure out the cause first

Last edited by Scimmia (2021-11-29 15:15:06)

graysky · 2021-11-29 15:36:25

My mistake. You are right, timestamps are indeed the same. They match up with the corresponding pacman.log as well. I also have tons of files outside of the local db dir. Both partitions are ext4.

merlock · 2021-11-29 16:00:27

@graysky: is your drive formatted in F2FS? I had a bad corruption problem one time, and won't use it again.

graysky · 2021-11-29 16:14:03

No, all ext4.

seth · 2021-11-29 20:50:31

The secret factor is: why are the databases on both partitions corrupted with such close timestamps. Did you update them both around that time?

Since this is an SSD, what kind if https://wiki.archlinux.org/title/Solid_state_drive#TRIM approach do you take (and is it anything but "none")?

graysky · 2021-11-29 21:27:14

Yes, I updated them pretty close in time to each other. Regarding TRIM, I am using fstrim.timer provided by util-linux.

seth · 2021-11-29 21:50:36

In light of https://bbs.archlinux.org/viewtopic.php?id=250382 - are there any related errors in the relevant journal segment?

Also let's revisit

My edit took out a sentence like "I suspect this may have been caused by an ungraceful shutdown..." The fact that the same phenomenon happened to two different Arch installs at two different times albeit on the same physical SSD makes me think an ungraceful shutdown is not to blame.

The timestamps do not support "at two different times". So was there actually an "ungraceful shutdown" and was it in the relevant timeframe?
Because that would be an obvious explanation.

graysky · 2021-11-29 22:44:06

I agree with that, Seth. Was thinking about it earlier today. That odd bit is that I just mounted/chrooted the minimal partition to update it and I umounted it when I was finished. I restored a backup of my primary system earlier today and in doing so wiped out several days of journalctl -- of course, the data we seek was among the bad data. I formatted the minimal partition since it was too simply to just pacstrap and copy over /home/ so I also lost any data there.

I think it is pretty likely that something happened to both on that same day. I just don't have the data to prove it. I will make this as solved. Thanks to everyone who replied.

Arch Linux

#1 2021-11-29 07:34:51

Something corrupted /var/lib/pacman/local/ [solved]

#2 2021-11-29 12:11:48

Re: Something corrupted /var/lib/pacman/local/ [solved]

#3 2021-11-29 13:19:26

Re: Something corrupted /var/lib/pacman/local/ [solved]

#4 2021-11-29 13:33:25

Re: Something corrupted /var/lib/pacman/local/ [solved]

#5 2021-11-29 13:36:14

Re: Something corrupted /var/lib/pacman/local/ [solved]

#6 2021-11-29 14:40:51

Re: Something corrupted /var/lib/pacman/local/ [solved]

#7 2021-11-29 14:48:55

Re: Something corrupted /var/lib/pacman/local/ [solved]

#8 2021-11-29 15:07:17

Re: Something corrupted /var/lib/pacman/local/ [solved]

#9 2021-11-29 15:12:14

Re: Something corrupted /var/lib/pacman/local/ [solved]

#10 2021-11-29 15:36:25

Re: Something corrupted /var/lib/pacman/local/ [solved]

#11 2021-11-29 16:00:27

Re: Something corrupted /var/lib/pacman/local/ [solved]

#12 2021-11-29 16:14:03

Re: Something corrupted /var/lib/pacman/local/ [solved]

#13 2021-11-29 20:50:31

Re: Something corrupted /var/lib/pacman/local/ [solved]

#14 2021-11-29 21:27:14

Re: Something corrupted /var/lib/pacman/local/ [solved]

#15 2021-11-29 21:50:36

Re: Something corrupted /var/lib/pacman/local/ [solved]

#16 2021-11-29 22:44:06

Re: Something corrupted /var/lib/pacman/local/ [solved]

Board footer