Ceph » rbd

Whoops, it was 4 TB (2^42) not 4 GB.

I'll update what I originally wrote shortly.

The tests I started running this morning finally hit number 259.
It did have the problem, but I got no messages from rbd as I
had hoped. Here is everything in /var/log/sys/log on plana09
related to running that test:

logger: run xfstest 259
kernel: [ 8766.063203] loop: Write error at byte offset 2199540084736, length 4096.
kernel: [ 8775.544935] loop: Write error at byte offset 2199540084736, length 4096.
kernel: [ 8783.747841] loop: Write error at byte offset 2199540084736, length 4096.
kernel: [ 8792.033191] loop: Write error at byte offset 2199540084736, length 4096.
kernel: [ 8793.332988] libceph: osd2 10.214.131.33:6806 socket closed (con state OPEN)
kernel: [ 8854.762482] loop: Write error at byte offset 2199540084736, length 4096.
udevd[12135]: failed to execute '/lib/udev/ceph-rbdnamer' 'ceph-rbdnamer %n': No such file or directory
libceph: osd0 10.214.131.33:6800 socket closed (con state OPEN)
kernel: [ 9008.283152] libceph: osd2 10.214.131.33:6806 socket closed (con state OPEN)
kernel: [ 9008.425846] libceph: osd3 10.214.131.29:6800 socket closed (con state OPEN)
Feb 25 10:43:21 plana09 kernel: [ 9008.518197] XFS (rbd2): Mounting Filesystem
kernel: [ 9012.473347] XFS (rbd2): Ending clean mount

(Note I am seeing the "udevd... ceph-rbdnamer" message for every test.)

I was reporting if an error code got returned from
the osd. However the loop device function that
reports the "Write error" message prints the message
if the returned number of bytes written is different
from what was requested.

I'm going to update my code to look for that condition
and print information in that case as well.

BTW fixed the rbd namer thing; pull latest teuthology.git.

BTW fixed the rbd namer thing; pull latest teuthology.git.

Well, "fixed" is generous. It had a bug, which I've repaired,
roughly:
- 'TESTDIR={tid}'.format(tdir=testdir),
+ 'TESTDIR={tdir}'.format(tdir=testdir),

Requests to write 4096 bytes came back from the osd with a
written count of 2048 bytes.

Now I'm afraid I have to make sure that the op sent to the
osd was in fact 4096 bytes, or whether the op got truncated
to 2048 bytes before getting sent to the osd...

kernel: [10684.388477] XFS (rbd2): Ending clean mount
logger: run xfstest 259
kernel: [10685.463899] loop: Write error (2048) at byte offset 2199538393088, length 4096.
kernel: [10694.227756] loop: Write error (2048) at byte offset 2199538393088, length 4096.
kernel: [10702.292614] loop: Write error (2048) at byte offset 2199538393088, length 4096.
kernel: [10703.190584] libceph: osd3 10.214.131.29:6800 socket closed (con state OPEN)
kernel: [10710.403547] loop: Write error (2048) at byte offset 2199538393088, length 4096.
kernel: [10720.122285] loop: Write error (2048) at byte offset 2199538393088, length 4096.

The output did not indicate that rbd thought it
did something wrong.

That is, the object request came back and indicated
that it had transferred 2048 bytes, and that's how
many bytes the object request seemed to think it
was supposed to have.

That means that something's probably going wrong while
building up object (and image) requests.

I'm going to look a little more closely at that code,
especially given the specific request we know is
(sometimes) triggering the problem:
write 4096 bytes at image byte offset 2199538393088
which for some reason is writing only 2048 bytes

Of course it's not going to be easy... The problem showed up
this time at offset 2199533527040 instead of 2199538393088.

The offsets written should be predicatable because mkfs.xfs
writes at offsets algorithmically based on the size of the
volume. (But I'll go verify that, just to be sure.)

logger: run xfstest 259
kernel: [ 8791.773490] loop: Write error (2048) at byte offset 2199533527040, length 4096.
kernel: [ 8797.239992] libceph: osd5 10.214.131.29:6806 socket closed (con state OPEN)
kernel: [ 8800.002233] loop: Write error (2048) at byte offset 2199533527040, length 4096.
kernel: [ 8844.351473] loop: Write error (2048) at byte offset 2199533527040, length 4096.
kernel: [ 8849.588921] libceph: osd1 10.214.131.33:6803 socket closed (con state OPEN)
kernel: [ 8849.654201] libceph: osd4 10.214.131.29:6803 socket closed (con state OPEN)
kernel: [ 8849.694890] rbd: obj_request ffff88020d3eca00 was already done
kernel: [ 8849.694890]
kernel: [ 8849.759928] rbd: obj_request ffff88021dd17400 was already done
kernel: [ 8849.759928]
Feb 25 23:45:01 plana09 CRON[12510]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
kernel: [ 8879.369612] libceph: osd1 10.214.131.33:6803 socket closed (con state OPEN)
kernel: [ 8894.720698] loop: Write error (2048) at byte offset 2199533527040, length 4096.
kernel: [ 8935.213701] loop: Write error (2048) at byte offset 2199533527040, length 4096.
kernel: [ 8969.847434] libceph: osd1 10.214.131.33:6803 socket closed (con state OPEN)
udevd[12620]: failed to execute '/lib/udev/ceph-rbdnamer' 'ceph-rbdnamer %n': No such file or directory
kernel: [ 9056.789041] libceph: osd1 10.214.131.33:6803 socket closed (con state OPEN)
kernel: [ 9057.149973] XFS (rbd2): Mounting Filesystem
kernel: [ 9057.447096] XFS (rbd2): Ending clean mount

Oh, and the "obj_request ... was already done" is new code, and I
attribute this to the connection being closed on an error injection
and a lingering watch request was re-sent and completed again.
(There is a bug open to fix this but I can't find it right now.)

The issue for not completing multiple lingering requests
more than once is http://tracker.ceph.com/issues/3967.
(Just following up on my previous post.)

ubuntu@teuthology:/a/teuthology-2013-02-28_20:00:04-regression-argonaut-master-basic/14358

I have been running tests all afternoon on two different
clusters with some code in place to catch this sort
of error and print more information if it ever occurs.
I have yet to reproduce the problem (today).

The code I've been using is based on the current "testing"
branch, but I've just updated it and will continue testing
with the result.
testing d51342b libceph: initialize data fields on last msg put

branch wip-4242 adds these commits:
82903f9 rbd: look for the magic short request
199a8b7 rbd: add rbd_img_request_print()
75bfd63 loop: print more error info with write errors
4a31501 rbd: print something when errors occur
0268ae7 rbd: add rbd_obj_request_print()
f1bb004 libceph: verify requests queued in order
d51342b libceph: initialize data fields on last msg put

I ran tests 257-259 through 100 iterations on two clusters
and the problem didn't show up. I'm now running this set
of tests in hopes of getting it to happen:
214 221 222 236 241 243 245 246 247 248 249 253 257 258 259

Once it occurs I hope to have a little more to work with.

Another 100 iterations of these tests without reproducing
the original problem:
214 221 222 236 241 243 245 246 247 248 249 253 257 258 259

I think I'm going to set this problem aside for a little while.

I just hit this again with the current testing branch.
testing e7fce31 rbd: issue a copyup for layered writes