Ceph » RADOS

More instances from last night's master:
- http://pulpito.ceph.com/jspray-2017-05-23_22:31:39-fs-master-distro-basic-smithi/1222341

• fs/snaps/{begin.yaml clusters/fixed-2-ucephfs.yaml mount/fuse.yaml objectstore/filestore-xfs.yaml overrides/{debug.yaml frag_enable.yaml whitelist_wrongly_marked_down.yaml} tasks/snaptests.yaml}

- http://pulpito.ceph.com/jspray-2017-05-23_22:31:39-fs-master-distro-basic-smithi/1222394

• fs/thrash/{begin.yaml ceph-thrash/default.yaml clusters/mds-1active-1standby.yaml mount/fuse.yaml msgr-failures/osd-mds-delay.yaml objectstore/filestore-xfs.yaml overrides/{debug.yaml frag_enable.yaml whitelist_wrongly_marked_down.yaml} tasks/cfuse_workunit_snaptests.yaml}

John, sorry. i missed this. will take a look at it next monday.

rerunning at http://pulpito.ceph.com/kchai-2017-06-19_09:40:27-fs-master---basic-smithi/

all passed modulo a valgrind error in ceph-mds, see /a/kchai-2017-06-19_09:40:27-fs-master---basic-smithi/1300881/remote/smithi113/log/valgrind/mds.a.log.gz, tracked at #20338

Unless there was a patch, I wouldn't be too sure this is fixed -- it was an intermittent failure.

2017-05-16T10:15:48.418 INFO:tasks.ceph.osd.1.smithi158.stderr: 2: (std::enable_if<denc_traits<osd_reqid_t, void>::supported&&(!denc_traits<osd_reqid_t, void>::featured), void>::type decode<osd_reqid_t, denc_traits<osd_reqid_t, void> >(osd_reqid_t&, ceph::buffer::list::iterator&)+0x198) [0x55c29ab7f0b8]

77fbfc29d15e3b9b05f7434bea8792077a18aa42 does not contain the denc changes i introduced in 77fbfc29d15e3b9b05f7434bea8792077a18aa42. so it's not caused by my change. but i don't think my change will fix it either. as osd_reqid_t does have traits::need_contiguous = true.

also, the payload can never be discontiguous. see AsyncConnection::process(), case STATE_OPEN_MESSAGE_READ_FRONT:

        {
          // read front
          unsigned front_len = current_header.front_len;
          if (front_len) {
            if (!front.length())
              front.push_back(buffer::create(front_len));

            r = read_until(front_len, front.c_str());
            if (r < 0) {
              ldout(async_msgr->cct, 1) << __func__ << " read message front failed" << dendl;
              goto fail;
            } else if (r > 0) {
              break;
            }

            ldout(async_msgr->cct, 20) << __func__ << " got front " << front.length() << dendl;
          }
          state = STATE_OPEN_MESSAGE_READ_MIDDLE;
        }

so i am not sure how this could happen.

Here's another one:

/a/pdonnell-2017-06-27_19:50:40-fs-wip-pdonnell-20170627---basic-smithi/1333648

fs/snaps/{begin.yaml clusters/fixed-2-ucephfs.yaml mount/fuse.yaml objectstore/bluestore.yaml overrides/{debug.yaml frag_enable.yaml whitelist_wrongly_marked_down.yaml} tasks/snaptests.yaml}

i will look at this issue again later on if no progress has been made before then.

Another one: /ceph/teuthology-archive/pdonnell-2017-07-07_20:24:01-fs-wip-pdonnell-20170706-distro-basic-smithi/1372305/teuthology.log

fs/snaps/{begin.yaml clusters/fixed-2-ucephfs.yaml mount/fuse.yaml objectstore/filestore-xfs.yaml overrides/{debug.yaml frag_enable.yaml whitelist_wrongly_marked_down.yaml} tasks/snaptests.yaml}

i am able to reproduce this issue using qa/workunits/fs/snaps/untar_snap_rm.sh. but not always...

i found that the header.version of the MOSDRepOpReply message being decoded was 1. but i am using a vstart cluster for testing, so all OSDs are luminous. hence the header.version should be 2. i think that's why the reqid failed to decode.

We set it to 1 if the MSODRepOpReply is encoded with features that do not contain SERVER_LUMINOUS.

...which I think a connection from a client won't have? Not sure if that's related or not.

MSODRepOpReply is always sent by OSD.

core dump from osd.1

(gdb)  f 13
#13 0x000055ca58c13634 in decode_message (cct=0x55ca62c50d20, crcflags=3, header=..., footer=..., front=..., middle=..., data=..., conn=0x55ca63e1f800)
    at /var/ceph/ceph/src/msg/Message.cc:839
(gdb) p header
$20 = (ceph_msg_header &) @0x55ca63e20b58: {seq = {v = 1}, tid = {v = 5074}, type = {v = 113}, priority = {v = 196}, version = {v = 1}, front_len = {v = 111}, middle_len = {
    v = 0}, data_len = {v = 0}, data_off = {v = 0}, src = {type = 4 '\004', num = {v = 2}}, compat_version = {v = 1}, reserved = {v = 0}, crc = {v = 1040714380}}
(gdb) p p.p
$57 = {_raw = 0x55ca6563ea30, _off = 0, _len = 111}
(gdb) p *(ceph::buffer::raw*)0x55ca6563ea30
$3 = {_vptr.raw = 0x55ca59d37308 <vtable for ceph::buffer::raw_combined+16>, data = 0x55ca6563e9c0 "\025", len = 111, nref = {<std::__atomic_base<unsigned int>> = {
      static _S_alignment = 4, _M_i = 2}, <No data fields>}, mempool = 10, crc_spinlock = {<std::__atomic_flag_base> = {_M_i = false}, <No data fields>},
  crc_map = std::map with 1 element = {[{first = 0, second = 111}] = {first = 0, second = 2758781822}}}
(gdb)  p (uint32_t[2])(*0x55ca6563e9c0)
$61 = {21, 16}

log from osd.2.log. and the address of osd.1 is 127.0.0.1:6805

2017-07-19 14:55:07.735281 7fd565533700  1 -- 127.0.0.1:6814/1050987 --> 127.0.0.1:6805/50779 -- osd_repop_reply(client.4120.0:8880 1.0 e21/16 ack, result = 0) v2 -- 0x5607cc551c00 con 0

in this case, assuming the header is not corrupted. it was sent from osd.2 per the "src" field.

assuming "header.version>=2", if we decode the payload, the epoch and min_epoch are 21 and 16 respectively. which matches the previous messages sent from osd.2.

if i dump the first 49 bytes header without the trailing crc, and run it through ceph_crc32c(), the returned digest is 1040714380. which matches with header.crc.

$ grep 'osd_repop_reply' osd.*.log | grep -w v1

also, nobody claims that it ever sends or receives a v1 osd_repop_reply.

occasionally, i see

2017-07-19 09:31:31.611176 7fc8d016d700 10 osd.1 15 OSD::ms_get_authorizer type=osd
2017-07-19 09:31:31.611362 7fc8cf16b700 -1 failed to decode message of type 70 v3: buffer::malformed_input: void osd_peer_stat_t::decode(ceph::buffer::list::iterator&) no longer understand old encoding version 1 < struct_compat
2017-07-19 09:31:31.611381 7fc8d016d700 10 osd.1 15  new session (outgoing) 0x5643b88e0000 con=0x5643ba960800 addr=127.0.0.1:6826/31872
2017-07-19 09:31:31.611455 7fc

in jenkins' make check output. type 70 is MSG_OSD_PING. not sure if this is related.