Re: [PATCH] mds: handle setxattr ceph.parent

[Alexandre Oliva <oliva@gnu.org>]

On Dec 20, 2013, "Yan, Zheng" <zheng.z.yan@intel.com> wrote:

> On 12/20/2013 11:35 AM, Alexandre Oliva wrote:
>> On Dec 19, 2013, "Yan, Zheng" <zheng.z.yan@intel.com> wrote:
>> 
>>> next time you encountered log corruption, please open "new issues" at http://tracker.ceph.com/
>> 
>> I have saved the dumped journal, but it contains too much information
>> I'm not supposed to or willing to share, especially with a US-based
>> company in the post-Snowden era :-(  (something like btrfs-image -s
>> might be good to have)
>> 
>> I'd be glad to try to dig info that might be useful out of it, if told
>> how to do so, but uploading the journal as taken from the cluster is not
>> an option.

> can you send out the mds log (the latest few hundreds of lines) when the mds crashed.

It didn't quite crash.  Here's what it spit out:

mds.0.cache creating system inode with ino:1
mds.0.journaler(ro) try_read_entry got 0 len entry at offset 1248878082748
mds.0.log _replay journaler got error -22, aborting
mds.0.1307 boot_start encountered an error, failing
mds.0.1307 suicide.  wanted down:dne, now up:replay

Before this, the mds was brought down along with the rest of the
cluster:

mds.0.1273 *** got signal Terminated ***
mds.0.1273 suicide.  wanted down:dne, now up:active

The --reset-journal session, that aborted because of the assertion
failure I mentioned in the patch, added the recent message log, but
there's nothing useful there: the mds asked osds for each one of the log
segments, got successful responses for them all, and then proceeded to
reset the journal.  The only oddity I found was this:

client.411305.journaler(ro) _finish_probe_end write_pos = 1248890415494 (header had 1248890413881). recovered.

For reference, here's the complete loghead info:

client.411305.journaler(ro) _finish_read_head loghead(trim 1248761741312, expire 1248761744503, write 1248890413881).  probing for end of log (from 1248890413881)...

Note how the offset at which we got the zero-len entry is not close to
either end of the (non-trimmed portion of) the log.  200.00048b1b, where
the zero-len entry was, was not only read successfully, the
corresponding file in the osds had the correct 4MB size, and the md5sum
of that file was the same on all 4 osds that contained it.  So, whatever
it was that corrupted the log happened long before the mds shutdown;
200.00048b1b's timestamp is 1387397117, while 200.00048b1e's (the tail
before the journal reset) is 1387430417; the 2 other files in between
are spaced at a nearly constant rate of 10000 seconds per 4MB.

The mds log has nothing special for that time range, but from the mon
and the osd logs I can tell that was about the time in which I rolled
back many of the osds to recent snapshots thereof, from which I'd
cleaned all traces of the user.ceph._parent.  I intended to roll back
only 2 out of the 4 replicas of each pg at a time, and wait for them to
recover, but I recall that during this process, two osds came down
before they were meant to, because of timeouts caused by the
metadata-heavy recursive setfattr.  I guess this may have caused me to
lose changes that had already been committed, by rolling back all the
osds that had those changes.

So I think by now I'm happy to announce that it was an IO error (where
IO stands for Incompetence of the Operator ;-)

Sorry about this disturbance, and thanks for asking me to investigate it
further and find a probable cause that involves no fault of Ceph's.

-- 
Alexandre Oliva, freedom fighter    http://FSFLA.org/~lxoliva/
You must be the change you wish to see in the world. -- Gandhi
Be Free! -- http://FSFLA.org/   FSF Latin America board member
Free Software Evangelist      Red Hat Brazil Compiler Engineer