Ceph

Can you restart osd.6 and osd.46 with

debug osd = 20
debug filestore = 20
debug ms = 1

and attach both logs?

From what I see, it looks like the on-disk state of osd.46 is pretty wonky. Was there a powercycle of any kind?
-Sam

Yeah, if it didn't crash you'll probably also have to start the other osds. I asked for osd.6 and osd.46 because osd.46 was the primary for the pg on which osd.6 crashed, and was responsible for sending a problematic message. I need logs on the crasher and the primary from startup until the crash for at least one problem pg.

This time it crashed on a message from osd 64, did you happen to have the logging on for that one as well? If not, can you restart 4, 46, 64 with logging, reproduce, and attach the logs?

Can you post a recursive ls on osd.64's current/0.504_head directory?

Also, can you restart osd.12 and osd.17 and post the logs from that (same log levels).

on osd.64, the Directory current/0.504_head is empty.

Is there a non-empty 504_head on any osd (perhaps 12 or 17?)

i made a list with the directory content on the osds:

hostname: osd
---------------
kaa-63: osd.40, contains directory-tree (DIR_4/...) with data-files
kaa-64: osd.41, empty
kaa-55: osd.28, empty
kaa-59: osd.23, contains only data-files (no tree)
kaa-82: osd.59, empty
kaa-98: osd.3, contains directory-tree (DIR_4/...) with data-files
kaa-101: osd.6, contains only some data-files (no tree)
kaa-13: osd.14, empty
kaa-19: osd.64, empty
kaa-17: osd.18, contains directory-tree (DIR_4/...) with data-files
kaa-49: osd.38, empty

Ok, it looks like these pgs had an osd (or osds) power cycled in a way that caused the pg metadata to go significantly back in time. That broken metadata was then propagated to other osds as part of recovery. I suspect that your controllers/drives/fs are not passing barriers correctly, and that is messing up the transaction system in the osd and leveldb. I don't see a simple way to recover the cluster.

You can identify the broken pgs by looking at the logs on the crashing osds and tracing the thread which asserts back to a line with merge_log. That line should identify the broken pg. You can then look for that pg across the cluster and remove the empty ones. That might or might not improve the situation.

Thanks for your help! After deleting some empty directories and removing a half full one, now all OSDs came up. I am proceeding with a complete deep-scrub and repair all pgs as neccessary.
Regarding barriers: I disabled the write-cache on all disks and used xfs default mount-options, so barriers should be active. Eventually i missed some controller settings, will recheck on this.

Were you able to localize all of the affected pgs to one or two osds at some point in the past? Also, what controllers/firmware/fs/kernel version are you using (you aren't the first to see mysterious pg metadata misbehavior, I'm wondering whether we can extract some form of pattern from the noise)?

The broken fs/controller/disk theory is the best I've got at the moment, but it's pretty much impossible to falsify making it a pretty lousy theory as theories go. Let me know if think of anything else that might be interesting. Particularly, it would be interesting if all of the affected pgs had an osd or two in common. Can you also post a ceph pg dump?

i am still having problems with the cluster, but this time there is a growing number of inconsistencies, which started with 3 pgs, all located on osd.1. the only crash involved was the "assert(m)". the list of inconsistencies kept growing over the last days and is now spread over more and more osds. i keep seeing messages like this for all pg's which have inconsistencies:

2014-06-16 08:37:29.388617 osd.60 192.168.1.83:6800/13195 231 : [ERR] 0.32e 52 tried to pull f7e4532e/100002162ae.00000000/head//0 but got (2) No such file or directory
2014-06-16 08:38:44.923609 osd.32 192.168.1.44:6800/10930 102 : [ERR] 0.b09 34 tried to pull ede50b09/100002162b1.0000000e/head//0 but got (2) No such file or directory

i am still not sure about how to work around the "hit suicide timeout". before the timeout, i see many messages like this one affecting connections to all the other OSDs:

submit_message osd_ping(ping e197257 stamp 2014-06-16 09:52:48.651395) v2 remote, 192.168.1.24:6803/3030718, failed lossy con, dropping message 0x7fdfec0028a0

there were more and more inconsistencies with missing files and i am unsure how to repair them. for example there were missing files from 2 shards on the primary osd for pg 0.7f1:

96 ceph-osd: 2014-06-16 10:45:20.300934 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 1 missing 3a5ff7f1/100002254e8.0000212d/head//0
96 ceph-osd: 2014-06-16 10:45:20.300942 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 66 missing 3a5ff7f1/100002254e8.0000212d/head//0
96 ceph-osd: 2014-06-16 10:45:20.300945 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 1 missing deaff7f1/10000213cae.00001924/head//0
96 ceph-osd: 2014-06-16 10:45:20.300949 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 66 missing deaff7f1/10000213cae.00001924/head//0
96 ceph-osd: 2014-06-16 10:45:20.300952 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 1 missing 9fdff7f1/100001fa418.000014ed/head//0
96 ceph-osd: 2014-06-16 10:45:20.300956 7f7c73ff7700  0 log [ERR] : 0.7f1 shard 66 missing 9fdff7f1/100001fa418.000014ed/head//0
96 ceph-osd: 2014-06-16 10:45:20.302293 7f7c73ff7700  0 log [ERR] : 0.7f1 deep-scrub 809 missing, 0 inconsistent objects
96 ceph-osd: 2014-06-16 10:45:20.302301 7f7c73ff7700  0 log [ERR] : 0.7f1 deep-scrub 1618 errors

i found another copy with the missing files, so i replaced the bad copy with the other one. this resolved the issue with shard 1, but it still reports files from shard 66 missing. so for example the file "./DIR_1/DIR_F/DIR_7/DIR_F/100001fa418.000014ed__head_9FDFF7F1__0" exists, but it still says "0.7f1 shard 66 missing 9fdff7f1/100001fa418.000014ed/head//0". is this the correct directory?

over the weekend, i will run some more stress-tests. eventually, i resolved the problem with the suicide timeouts (eventually resulting from temporary hangs in our nfs-root). lets see, if this stops new inconsistencies.

shard 66 here is osd 66. You mean that ./DIR_1/DIR_F/DIR_7/DIR_F/100001fa418.000014ed__head_9FDFF7F1__0 exists on osd 66? Does ./DIR_1/DIR_F/DIR_7/DIR_F/DIR_F? What filesystem are you using?

Can you dump the xattrs on that file?

osd 66 has also a bad copy, only osd 28 had the copy containing the corresponding file. osd.66 is btrfs, while osd.28 and osd.1 are xfs. i copied the pg from osd.28 with rsync to osd.1 preserving xattrs. the xattr dump is as follows:

# file: DIR_1/DIR_F/DIR_7/DIR_F/100001fa418.000014ed__head_9FDFF7F1__0
user.ceph._=0sDQjhAAAABAM1AAAAAAAAABQAAAAxMDAwMDFmYTQxOC4wMDAwMTRlZP7/////////8fffnwAAAAAAAAAAAAAAAAAFAxQAAAAAAAAAAAAAAP////8AAAAAAAAAAAAAAACY7gMAAAAAAIyQAgCX7gMAAAAAAIyQAgACAhUAAAAIgCsrAAAAAAAcJWYAAAAAAAEAAAAAAEAAAAAAACwgblOUQt8dAgIVAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAmO4DAAAAAAAAAAAAAAAAAAAEAAAA
user.ceph.snapset=0sAgIZAAAAAQAAAAAAAAABAAAAAAAAAAAAAAAAAAAAAA==

osd.66 and osd.1 (before my rsync from osd.28) had no subdirectory structure. the few files left on these hosts were directly in the 0.7f1_head directory.

Why was there an rsync? Can you explain the sequence of events?

- pg 0.7f1 incomplete on [1,66,28]
- determined from logs, that there were missing files from shard 1 and 66 on osd.1
- the data size on osd.28 is 3.2GB compared to 453MB on osd.1 and osd.28 (why are both copies so small?)
- looked at directory structure on osds and found, that files only seemed to exist on osd.28
- ceph osd noout and stop ceph-osd on osd.1, osd.66 and osd.28
- made backup copy of 0.7f1_head on osd.1 and osd.28
- deleted directory 0.7f1_head from osd.1 and osd.28
- restarted osds
- directory size on osd.1 and osd.66 after recovery still 453MB
- stopped osds
- rsync aX of 0.7f1_head from osd.28 to osd.1
start osds
- see in logs, that objects from shard 66 are still missing, but files are on disk

When did those things happen?

after the initial bugreport, i repaired all pgs made a deep scrub on all osds, after which all pgs were active+clean, which was on the june 5th i think. there were no disk errors or reboots until this inconsistent pg apperead, only some asserts, which i mentioned earlier. i am gathering the exact time and some information on asserts right now from our SQL logs, but it might take an hour or so.

another thing: just now, i noticed again some partial network congestion on our hosts, which led again to failed asserts (the one in merge_log, one assert(r == 0), the rest i did not check). But this time the OSDs restarted without error. i am waiting for the deep-scrub to finish, to see if this resulted in new inconsistencies.
we are running ceph on this system for over a year now and with 0.61 or 0.72 i never had inconsistent pgs (except of course with bad sectors).

Have you been running the xfs/btrfs mix the whole time?

for testing purposes, i installed btrfs on osd.63 to osd.69 since 2014-05-28 and on osd.57 since 2014-05-13. snapshots were disabled with "filestore btrfs snap = false" due to kernel errors with snapshots.

the network congestion yesterday seems to have caused another chain effect since this morning nearly all OSDs were down. i am looking into it. if you think, btrfs is a possible cause, i will disable These osds for now.

I think your pg info and logs at some point became badly corrupted for some pgs. I think that is causing the asserts. I wonder whether it might also be causing the missing or inconsistent objects. Would it be possible to attempt to reproduce from a new cluster?

can the pg info and logs be corrupt, even if all pgs are active+clean and a deep-scrub on all osds runs through without inconsistencies? if yes, then i may have no choice but to try and backup all our data. i am not sure yet, how to find enough free space for that.

after this downtime this morning, there are 16 new inconsistent pgs found after deep-scrubbing. reproducing this is quite simple here, since we have nfsroot and lowering the Server threads causes the Clients to hang waiting for nfsroot to responds. this causes lags in the OSDs, so some are marked auto out or some hit the assert "suicide timeout". following this, some OSDs crash due to other asserts and pgs are moved "wildly" and copied partly since an ever changing number of OSDs is up (since eventually unreachable) until issues are resolved. what happens if an osd is to be scheduled to receive a pg, but the original hosts are reachable again? what happens if one of the target hosts hit an assert during this temporary movement? what happens if data is written during this time? (i have size = 3 and min_size = 2). what if some partly copied pgs are then replicated to more and more hosts, until the main pg comes up again? i know, with correct logging, the whole cluster should replay the whole process to the main pgs, once it comes up, clean the temporary copies and resume. but what if during this replay the pg is unreachable again (or some assert occurs for whatever reason)?

still, i do not know, why ceph should hang at all in this case, since i cannot see any periodic file access besides the osds local storage or "/proc". eventually the os performs a cache refresh for the "/" dirent during some file open and this might hang. eventually a random long sleep at a file open might simulate the behavior.

Reproducing these network congestions via nfs threads on purpose is unwise, since some of our users have their programs abort when this happens.

Possibly? I've never seen a ceph cluster behave anything like this. Are your osd journals on the nfs root?

How did you deploy the cluster originally?

Is it true that your inconsistencies are correlated with network congestion which would also cause the nfs root to hang?

most journals are on local block devices /dev/sda -> /dev/vg/ceph-journal, some few are still on files, but also local storage /dev/sda -> /dev/vg/ceph (xfs or btrfs) -> /local/ceph/Journal
for journals i have journal aio and filestore fiemap enabled. can that be a problem? (from logs: "detect_features: FIEMAP ioctl is supported and appears to work"), so i though that usage might be safe.

the inconsistencies are strongly correlated with the hangs of the nfs root. and so are also the asserts. i am currently investigating how to work around these hangs.

what do you mean with "how did you deploy the cluster"?

Was it ceph-deploy?

Are you using journal_force_aio?

I wonder whether the nfs hangs are interfering somehow with the journal aio stuff, you might try disabling aio.

no, i am not using ceph-deploy, since there was no version for gentoo. so i used the following commands to init new osds:

UUID=$(ceph osd create)
ceph-osd -i $UUID --mkfs --mkkey
ceph auth add osd.$UUID osd \'allow *\' mon \'allow rwx\' -i /local/ceph/keyring
ceph osd in $UUID

http://tracker.ceph.com/issues/2535 seems to be the reason why fiemap defaults to disabled. You may want to disable that as well.

There probably is a ceph bug in here somewhere, but I think most of your trouble is related to your environment somehow breaking the OSD filesystem assumptions either through a kernel bug or otherwise.

okay, so i am disabling aio and fiemap. regarding Journal files: i checked again and i am only using block devices as journals. i seem to have updated all hosts sometime ago.

Each journal is on it's own block device? Or on a partition?

Journal and storage are on the the same hard drive. used lvm to create a lv for the Journal and another lv for normal ceph storage (and a third for /etc, /var and /tmp).

Interestingly, 3.14.4 appears to have some changes to fs/aio.cc.

i am running 3.14.7 at the moment, since there were some bugs with the cephfs kernel client, which forced me to upgrade.
the last one, "aio: fix potential leak in aio_run_iocb()" looks good imho. cannot say anything about the older changes.

Are you seeing different results now?

the cluster is in really bad shape, which happend basically before i switched the config options. we are now trying to backup all data and then i will do tests again with a clean system. i am afraid this might take a few days.

health HEALTH_ERR 27 pgs degraded; 2 pgs down; 63 pgs inconsistent; 5 pgs peering; 1 pgs recovering; 61 pgs stale; 5 pgs stuck inactive; 61 pgs stuck stale; 33 pgs stuck unclean; 1 requests are blocked > 32 sec; recovery 3/8522468 objects degraded (0.000%); 1/2835474 unfound (0.000%); 31170 scrub Errors

today, we had further network problems and inconsistent pg count is still increasing:

health HEALTH_ERR 312 pgs degraded; 2 pgs down; 3 pgs incomplete; 64 pgs inconsistent; 5 pgs peering; 1 pgs recovering; 61 pgs stale; 8 pgs stuck inactive; 61 pgs stuck stale; 321 pgs stuck unclean; 3 requests are blocked > 32 sec; recovery 187536/8520135 objects degraded (2.201%); 1/2835164 unfound (0.000%); 32010 scrub errors; 2/70 in osds are down; noout flag(s) set

Yeah, reproducing on a clean cluster would probably be a good next step.

I have recreated everything from scratch and restored our backups. Initial crash-stress-tests ran fine. ("killall -9 ceph-osd" on random 20% of all OSDs every 10 minutes or restart if not running) So balancing seems to work correctly. I have now all the nodes included (xfs as well as btrfs with snapshots disabled), aio enabled, fiemap disabled. The cluster has also survived one or two network congestions without incomplete PGs.

Anything new? Would you consider reenabling fiemap to see whether that makes the issues come back?

everything was still running good today, but i guess we had not much load the last days. i run my stress test again with fiemap enabled. not really sure if it can catch reproduce bug .. but we will see.

still everything running ok, as indicated by a deep-scrub of all pgs. very strange.

i just read, that setting tunables to optimal could cause inconsistent pgs. i actually had set the tunables to optimal some time after upgrading to 0.80, to get better data distribution. the upgrade took place 2 weeks before the problems started and after setting optimal tunables the cluster definitely returned to HEALTH_OK. in what exact circumstances did this problem occur? i updated all nodes at the same time following the exact order in the release notes.

still no inconsistencies. everything is running fine now. but there is now another one, who might have similar problems (see original bug #8229)