Ceph

Three more things. If there are no connection failures
injected this problem does not occur.

When socket error injection is active, I am used to seeing
a handful of these messages, two or three at a time, or
maybe dozens of them between file system mounts (but typically
10 seconds or more apart). The behavior I'm talking about
is hundreds of reports over the course of a second or two.

Oddly, I ran some tests with some patches Josh just
reported today in e-mail that he reviewed, and the
problem did not seem to be there. It's possible this
behavior is in some of my newest patches, which I have not
yet posted for review.

(I've been trying to do a lot at once so I could have
gotten confused about that. I'll need to verify this
before going too far with the testing branch.)

Just a little update.

I've been testing the "testing" branch with groups of the
xfstests I use to see if I could limit what's required to
reproduce the problem. So far I haven't hit the problem.

So far I've done these groups:

 1-9 11-15 017 19-21
 26-29 31-34 41 46-48 50-54 56 61 63-67 69 70
 74
 75
 76 78 79 84-89
 91

I was going to try a complete run on a separate cluster
while I wait for these, but I am unable to allocate 3
nodes.

I seem to have hit this problem again while attempting to test
my most recent changes. It arose while running xfstest 70 but
that may not necessarily be the issue.

So this may be a new problem in code not yet committed. I'll
track it down before committing those new changes.

I am bisecting this today. I'm going to take notes here to
make sure I don't screw it up.

I started with the "wip-reviewed" branch I was testing before,
which contains the 13 patches that Josh reviewed but which I
have not committed yet:

addc14c libceph: make message data be a pointer
811fde6 libceph: use only ceph_msg_data_advance()
950510c libceph: kill last of ceph_msg_pos
fbdcddf libceph: kill most of ceph_msg_pos
98f8eb9 libceph: use cursor resid for loop condition
b227450 libceph: collapse all data items into one
3856487 libceph: get rid of read helpers
9f7d792 libceph: no outbound zero data
bec9c87 libceph: use cursor for inbound data pages
b88051a libceph: kill ceph message bio_iter, bio_seg
04655f9 libceph: use cursor for bio reads
42573a7 libceph: record residual bytes for all message data types
15b53ed libceph: drop pages parameter

I was able to reproduce the problem while running test 74, having
provided the following yaml file (which corresponds to the last
commit, addc14c):

interactive-on-error:
roles:
- [mon.a, mon.c, osd.0, osd.1, osd.2]
- [mon.b, mds.a, osd.3, osd.4, osd.5]
- [client.0]
kernel:
  mon:
    branch: wip-reviewed
    kdb: true
  client:
    branch: wip-reviewed
    kdb: true
overrides:
  ceph:
    conf:
      osd:
        osd op complaint time: 120
    fs: btrfs
    log-whitelist:
    - clocks not synchronized
    - old request
tasks:
- install:
- ceph:
    branch: next
    conf:
        global:
            ms inject socket failures: 2500
        mon:
            debug mon: 10
            debug paxos: 
        osd:
            debug ms: 1
            debug journal: 20
            osd debug op order: true
- rbd:
    all:
- rbd.xfstests:
    client.0:
        count: 1
        tests: 56 61 63-67 69 70 74-76 78 79

Verified that I reproduced the problem when reducing the list of
tests to this (again, while running test 74):
tests: 70 74-76
So from here on out that's what I'll be running.

After a few iterations I have concluded it's this patch
where the problems start to appear:
811fde6 libceph: use only ceph_msg_data_advance()
I am repeating the test (and iterating several times
over it) with its predecessor commit to verify that.

Meanwhile I'll try to see what's going on with that one.

OK, I screwed up, and that's why I was taking notes.

The bad commit was this one, NOT the one I said before:

950510c libceph: kill last of ceph_msg_pos

This one changed some details of handling message
CRC's so it's a reasonable place for something like
this to go wrong.

Its predecessor commit was this:
fbdcddf libceph: kill most of ceph_msg_pos
I am going to commit up to and including that commit
to the "testing" branch. Then I'll try to fix this
CRC one.

I have confirmed that the osds are reporting crc errors
at the time these repeated connection closes are occurring.

2013-03-29 08:12:15.779075 7f4e14865700 0 bad crc in data 3831343678 != exp 621
212944
2013-03-29 08:12:15.800400 7f4e14865700 0 bad crc in data 3831343678 != exp 387
0950775
2013-03-29 08:12:15.820265 7f4e14865700 0 bad crc in data 3831343678 != exp 273
6929673
2013-03-29 08:12:15.843569 7f4e14865700 0 bad crc in data 1244014471 != exp 231
8485120
2013-03-29 08:12:25.531742 7f4e14865700 0 bad crc in data 2131376592 != exp 160
9367935
2013-03-29 08:12:25.595346 7f4e14865700 0 bad crc in data 3947293918 != exp 146
7719174
2013-03-29 08:12:25.621507 7f4e14865700 0 bad crc in data 2131376592 != exp 119

OK, I found the problem. It was subtle.

The patch in question got rid of the last remaining
piece of the "ceph_msg_pos" structure, which kept
track of whether the crc needed to be computed.

Instead, in the new code when the send or receive
routine requests the next piece of a data item to
be sent or received, it is informed whether the
result is moving onto a new piece. (A piece is
a page for a pagelist or a page array, or a
segment of a bio in a bio list.)

That was effectively what was happening previously;
the did_page_crc flag was cleared when you moved
onto a new piece, and set after the crc for the
piece had been calculated.

The subtle difference is that in the sending case,
the crc for the piece is calculated before
actually sending the data. The problem occurs if
the attempt to send returns 0, in which case
sending stops and resumes again next time con_work()
is called.

The old code set that did_page_crc flag when the
crc was calculated, meaning it would not be done
again (even when 0 bytes got sent on a previous
attempt). In the new code, sending 0 bytes does
not change which piece of data you're operating on,
and this means the need_crc flag doesn't get cleared.
So the crc would get computed twice if an attempt to
send a new piece sent 0 bytes.

The solution is easy though--just hold off calculating
the crc for a piece until after we know at least one
byte has been sent.

I'm going to keep this bug fix as a separate patch
to follow the one with the bug, and will post it
for review shortly.