Ceph

what was the assert?

2014-09-22 16:00:20.680448 7fee6abcf700 0 -- 10.10.10.7:6808/25820 >> 10.10.10.16:0/1007485 pipe(0xba12a00 sd=628 :6808 s=0 pgs=0 cs=0 l=1 c=0x5031b6e0).accept replacing existing (lossy) channel (new one lossy=1)
2014-09-22 16:08:54.105116 7feeca125700 -1 journal aio to 165552576~80 got (8192) Unknown error 8192
2014-09-22 16:08:54.334038 7feeca125700 -1 os/FileJournal.cc: In function 'void FileJournal::write_finish_thread_entry()' thread 7feeca125700 time 2014-09-22 16:08:54.118638
os/FileJournal.cc: 1377: FAILED assert(0 == "unexpected aio error")

ceph version 0.67.10 (9d446bd416c52cd785ccf048ca67737ceafcdd7f)
 1: (FileJournal::write_finish_thread_entry()+0x6d7) [0x766c67]
 2: (FileJournal::WriteFinisher::entry()+0xd) [0x69cbad]
 3: (()+0x7e9a) [0x7feed27dfe9a]
 4: (clone()+0x6d) [0x7feed0ffc31d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

• align_bl related pull request https://github.com/ceph/ceph/pull/2501
• rebuild_align fix (back from 2013) https://github.com/ceph/ceph/commit/66a9fbe2c7ba59b7cd034c17865adce3432cd2c#diff-a8f8811d06c3d3b3a6754a7f2e446f66R833

Sheldon, could you upload the full log somewhere if you still have it ?

journal aio to 165552576~80 got (8192) Unknown error 8192

Maybe iterating the bufferptr can return bufferptr beyond the size of the bufferlist ? In which case it creates an iovec totaling 8192 or more, hence the return value.

I don't see how it could be related to a problem in align_bl or bufferlist::rebuild_align. The worst these could do is to not align the buffer but it will not change the length of the bufferlist.

Iterating over the bufferptr is fragile. If for whatever reason the bufferlist is made of two bufferptr, has a length of 80 which is entirely in the first bufferptr, the second bufferptr will be written as well although it is supposed to contain nothing. A bufferlist can operate normally with extra bufferptr that are just ignored by normal operations.

Reading the buffer.{h,cc} code it looks like the caller is protected from a situation where a bufferptr leftover can be found.

Exploring the idea that maybe the buffers pointed to by the iovec are overriden, mixed up

None of the commits in FileJournal.cc from dumpling to master fix something that could cause a problem of that nature.

https://github.com/ceph/ceph/commit/66a9fbe2c7ba59b7cd034c17865adce3432cd2cb and https://github.com/ceph/ceph/commit/cd30e5fbb1d2d29b4fc0c2b13fa3b9b4493c24f0 were not backported to dumpling. As a result https://github.com/ceph/ceph/blob/dumpling/src/os/FileJournal.cc#L940 may not align the bufferlist as expected. I'll need to figure out how bad it is to not align the buffer.

• https://code.google.com/p/kernel/wiki/AIOUserGuide claims alignment is required if using DIRECT_IO (which is the case for FileJournal)

https://github.com/ceph/ceph/pull/2611 seems like a good candidate for backport.

It turns out that the alignment requirement has to be enforced indeed. On a 3.13 linux kernel the following:

  #define _GNU_SOURCE        /* syscall() is not POSIX */

  #include <stdio.h>        /* for perror() */
  #include <unistd.h>        /* for syscall() */
  #include <sys/syscall.h>    /* for __NR_* definitions */
  #include <linux/aio_abi.h>    /* for AIO types and constants */
  #include <fcntl.h>        /* O_RDWR */
  #include <string.h>        /* memset() */
  #include <inttypes.h>    /* uint64_t */

  inline int io_setup(unsigned nr, aio_context_t *ctxp)
  {
      return syscall(__NR_io_setup, nr, ctxp);
  }

  inline int io_destroy(aio_context_t ctx) 
  {
      return syscall(__NR_io_destroy, ctx);
  }

  inline int io_submit(aio_context_t ctx, long nr,  struct iocb **iocbpp) 
  {
      return syscall(__NR_io_submit, ctx, nr, iocbpp);
  }

  inline int io_getevents(aio_context_t ctx, long min_nr, long max_nr,
          struct io_event *events, struct timespec *timeout)
  {
      return syscall(__NR_io_getevents, ctx, min_nr, max_nr, events, timeout);
  }

int main(int argc, char** argv)
  {
      aio_context_t ctx;
      struct iocb cb;
      struct iocb *cbs[1];
      char *data;
      struct io_event events[1];
      int ret;
      int fd;

      fd = open("/tmp/testfile", O_RDWR | O_CREAT | O_DIRECT, 0644);
      if (fd < 0) {
          perror("open error");
          return -1;
      }

      ctx = 0;

      ret = io_setup(128, &ctx);
      if (ret < 0) {
          perror("io_setup error");
          return -1;
      }

        ret = posix_memalign((void**)&data, 2048, 8192);
        if (ret)
          perror("posix_memalign");

        if (!strcmp(argv[1], "noalign"))
          data++;

      /* setup I/O control block */
      memset(&cb, 0, sizeof(cb));
      cb.aio_fildes = fd;
      cb.aio_lio_opcode = IOCB_CMD_PWRITE;

    /* command-specific options */
      cb.aio_buf = (uint64_t)data;
      cb.aio_offset = 0;
      cb.aio_nbytes = 4096;

      cbs[0] = &cb;

      ret = io_submit(ctx, 1, cbs);
      if (ret != 1) {
        if (ret < 0)
              perror("io_submit error");
        else
            fprintf(stderr, "could not sumbit IOs");
        return  -1;
    }

    /* get the reply */
    ret = io_getevents(ctx, 1, 1, events, NULL);
    printf("number of events %d\n", ret);

        printf("res = %d, res2 = %d\n", (int)events[0].res, (int)events[0].res2);

    ret = io_destroy(ctx);
    if (ret < 0) {
        perror("io_destroy error");
        return -1;
    }

     return 0;
  }

gcc -o /tmp/2 /tmp/2.c ; /tmp/2 align ; /tmp/2 noalign 
number of events 1
res = 4096, res2 = 0
number of events 1
res = -22, res2 = 0

Although aio: protect reqs_available updates from changes in interrupt handlers looks like something that could indeed corrupt the returned event, it was introduced a month before being fixed" and the odds that the kernel used has this problem are small. I'm not even sure a stable release was published in the interval.

The aio: v4 ensure access to ctx->ring_pages is correctly serialised for migration buf fix could mix the content of the buffers but not their length.

linux kernel is 3.12.7 and libaio is 0.3.109-2ubuntu1

linux 3.12.7 has been released january 2014. The patches to aio.c that could have been related

• http://tracker.ceph.com/issues/9570#note-20
• http://tracker.ceph.com/issues/9570#note-21

are not. The bug they fix cannot lead to that kind of problem.

What probably happens is that the aio_info that is sent to io_submit is overriden while waiting for the write to complete.

A theory that does not explain the problem, for the record.

<loicd> is it safe to assume the address of an element in a std::list will always point to the same element even when previous elements in the list are erased https://github.com/ceph/ceph/blob/giant/src/os/FileJournal.cc#L1406 ?
<sage> loicd: yeah.. the iterators are stable as long as the referenced element isn't removed
<sage> the ls.erase(p++) pattern is used all over the place
<loicd> but https://github.com/ceph/ceph/blob/giant/src/os/FileJournal.cc#L1304 is not an iterator
<loicd> and it is given to io_submit https://github.com/ceph/ceph/blob/giant/src/os/FileJournal.cc#L1318
<loicd> and surfaces later via io_getevents https://github.com/ceph/ceph/blob/giant/src/os/FileJournal.cc#L1367
<loicd> and I wonder if the content pointed to by the pointer could have changed in the meantime
<loicd> I think it can't happen if the events are received in the same order they are submitted
<loicd> not even
<sjusthm> loicd: it's stable
<loicd> sjusthm: ok :-)

New facts from http://tracker.ceph.com/issues/12100

http://tracker.ceph.com/issues/12100#note-2

The 1 minute load average before the crash was between 1 and 10.
Around the moment the crash happens (15:00:25) the load spikes, going up to 500, while CPU-nice counters go up significantly, too. It stays that hight until I restart the service.
At the moment of restart (15:08:29) the nice-counters drop back to 0 and the load tanks as well.

http://tracker.ceph.com/issues/12100#note-3

the hanging processes do not trigger an automatic respawning.

http://tracker.ceph.com/issues/12100#note-7

last night we saw a crash with this same trace again on one of the 48 OSDs... :(

After about 10 minutes it came back, this time without manual intervention. Probably Upstart took care of it.

I.e. the OSD dumps the trace but does not abort immediately. But seems to abort and be restarted after some time.

http://tracker.ceph.com/issues/12100#note-18

This is a hardware problem--we are correct in failing in this case.

Loic Dachary wrote:

journal aio to 165552576~80 got (8192) Unknown error 8192
meaning an attempt to write 80 bytes at offset 165552576 claims to have written 8192 bytes instead.

It's the other way around: 8192 is valid, while 165552576 and 80
(aio_info::off and aio_info::len) are invalid. It attempted to write
8192 bytes and succeeded, but didn't pass the ai->len check.

What I think happens is aio_info gets freed, turning event[i].obj into
a dangling pointer and making "if (event[i].res != ai->len)" the first
use-after-free. The question then is how aio_info gets freed. I'm not
familiar with this code, but from a quick look it seems that critical
sections are properly protected with aio_lock and, because aio_info is
embedded in the list entry, the same iocb can't be submitted twice.

Looking at check_aio_completion(), what would explain the evidence at
hand is a bug in the kernel, where the completion for the iocb somehow
gets delivered more than once. With a small tweak to fs/aio.c to make
it do exactly that I managed to reproduce this, down to the same bad
ai->len:

journal aio to 140381878795808~80 wrote 4096
journal aio to 139193344~80 wrote 4202496

There is at least one report of something similar going on on SO [1].
The answer is wrong - the kernel preserves both obj and data pointers
and both can be used for storing user context - but OP sounds credible
and describes exactly the issue I suspect we are having.

All of the occurrences (#9570, first half of #12100) are on ~3.13.*,
which is around the time fixes for a bunch of refactoring work were
landing into fs/aio.c. I haven't found anything of the above nature
though, so who knows - tracking this down for sure without a core dump
and a more verbose log isn't really feasible.

[1] http://stackoverflow.com/questions/29780028/io-getevents-returns-a-completion-event-twice

@Ilya

If you were to hit this kind of crash not often but sometimes which is quite annoying, what would you do to know what's exactly going on?

I'd try with a newer kernel - as new as the environment allows. If it's still a problem, I'd bump in-memory (the number to the right of "/") debug level for journal to 30 and make sure I get a core dump when OSD hits that assert.