Ceph » Linux kernel client

2015-02-13 11:08:23.489822 7f73903df700  1 -- 10.214.135.8:6805/31779 <== client.4111 10.214.131.10:0/1389565972 76 ==== osd_op(client.4111.1:32938 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 4096000~98304] 0.50046e9a ondisk+write e62) v4 ==== 208+0+98304 (3323975164 0 0) 0x493b700 con 0x4d72940
2015-02-13 11:08:23.498053 7f739af21700  1 -- 10.214.135.8:6805/31779 --> 10.214.131.10:0/1389565972 -- osd_op_reply(32934 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 2523136~524288] v62'1652 uv1652 ondisk = 0) v6 -- ?+0 0x62902c0 con 0x4d72940
2015-02-13 11:08:23.508830 7f739af21700  1 -- 10.214.135.8:6805/31779 --> 10.214.131.10:0/1389565972 -- osd_op_reply(32935 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 3047424~524288] v62'1653 uv1653 ondisk = 0) v6 -- ?+0 0x511b180 con 0x4d72940
2015-02-13 11:08:23.516003 7f739af21700  1 -- 10.214.135.8:6805/31779 --> 10.214.131.10:0/1389565972 -- osd_op_reply(32936 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 3571712~524288] v62'1654 uv1654 ondisk = 0) v6 -- ?+0 0x66df180 con 0x4d72940
2015-02-13 11:08:23.516795 7f739af21700  1 -- 10.214.135.8:6805/31779 --> 10.214.131.10:0/1389565972 -- osd_op_reply(32938 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 4096000~98304] v62'1655 uv1655 ondisk = 0) v6 -- ?+0 0x4c22840 con 0x4d72940
2015-02-13 11:08:29.692828 7f73903df700  1 -- 10.214.135.8:6805/31779 <== client.4111 10.214.131.10:0/1389565972 196 ==== osd_op(client.4111.1:32775 rb.0.100c.238e1f29.000000000089 [set-alloc-hint object_size 4194304 write_size 4194304,write 0~372736] 0.50046e9a RETRY=1 ondisk+retry+write e63) v4 ==== 208+0+372736 (102131416 0 0) 0x5dd4a80 con 0x4d72940

I spotted two things in the logs:

No OSD logs gives a reference to the first try of this write.
the kern.log of the client describe the connection as closed
around the same time.
It must have been internally dropped and postponed for retry
by the client code because the connection has been closed.

This lead me to a naive question:

After the socket is closed and reopenned in con_work:

if (fault)                                                                                  
            con_fault(con);                                                                        
        mutex_unlock(&con->mutex);

if (fault)                                                                                  
            con_fault_finish(con);

What kind of garanties do we have that
ceph_osdc_start_request( will not take the osdc->request_mutex before
osd_reset( take it and insert requests in the unsent queue and then
submit them to us before osd_reset does it for the already submited
requests ?

A race condition doing out of order request ?

ceph_con_send( will be called by ceph_osdc_start_request and since the connection is not closed anymore
it will list_add_tail(&msg->list_head, &con->out_queue); then when osd_reset will kick it will have no choice but to queue the previous messages in con->out_queue after the newer one.
Then con_work() will send send in the reverse order.

I am missing something ?

Everything in messenger.c uses con->mutex

osd_reset() will clear out_queue before kicking and then requeue the old ones and the new one (in that order).

I don't think this tickets is caused by the race I point to but I want to push
my own reasoning until it break.

The following code is outside of con->mutex.
if (fault)
con_fault_finish(con);

Also

ceph_msgr_wq = alloc_workqueue("ceph-msgr", WQ_MEM_RECLAIM, 0);

O means we can have up to 256 different work items picked up at the same time.

What would prevent the workqueue to process an item just added to con->out_queue
before the reset is done ?

since:

/* if there wasn't anything waiting to send before, queue * new work */
if (con_flag_test_and_set(con, CON_FLAG_WRITE_PENDING) == 0)
queue_con(con);

in ceph_con_send().

Ok I find it :)

con->work is the same so executions are serialized to the same worker so no worries.

I have run into the same issue some months ago and track down the cause for it while debugging another issue.

Assume we have OSD 1-5.

Now lets say we have 3 incomming requests that are assigned TID 1-3, that are mapped to 2 OSDs as this:

TID 1 -> osd.1
TID 2 -> osd.2
TID 3 -> osd.2

Now assume the connection to osd.1 breaks down before TID 1 can be sent, for example because osd.1 has crashed. In the meantime TID 2+3 are be sent to osd.2.

As soon the messenger is informed about a new osdmap because of the crashed osd, tid 1 will be remapped to another osd. If that osd is osd.2 it will become a out of order TID and will crash osd.2 with that stacktrace.

Back then i wrote a patch, that would assign new TIDs in kick_requests to keep TIDs in order. But it turned out that this was not necessary for the problem i investigated, so i haven't cleaned it up for submission. And as im not sure if that approach is the right way anyway and you have to activate additional debugging anyway to run into this issue, it seemed not to be so important to get it out.

If there is any interest i can send it to ceph-devel as RFC-patch as it is.

It won't be an out of order tid on osd2 because while tids are per-client, the tid order is per-object. osds generally won't have a problem servicing a request with say tid 1000 after a request with tid 1500, if tid 1000 request just got remapped.

The code in question is (slower than I'd like) getting rewritten, but I still wanted to reproduce this to make sure it's fixed in the new version when it's ready. I did more than a 100 runs with a yaml from #12691 on same speced boxes with no luck. I tried only the current testing kernel though, what remains is to try exactly the kernel it triggered on.

It has been some timce since i looked at the code, but your right, it shouldn't be a problem. But nonetheless i have been running into this assert quite alot. And i had added code to the kernel messenger to see the TIDs of the sent messages and i always could always trace back this out of order asserts to the wrong TID-order on kernel side.

I have to recheck why this happened in my case.

May I ask why haven't you reported this issue, if you've been running into it "quite alot"? There's a good chance if would've been fixed by now...

I'd like to see those logs and the diffs you applied to the kernel to generate them, if possible. If you could also provide matching osd logs, it would be great.