Ceph

I have some more logs - unfortunatelly, the mon is unable to start up and rejoin the cluster after this assert.

This is definitely something wrong in the store: 'version' contains the last committed version on the store, while mdsmap.epoch contains the version of the current in-memory mdsmap.

The only 2 scenarios in which this could happen that would make some sort of sense are as follow:

• the monitor went through a sync and it managed not to sync the mds keys -- or, at least, mdsmon:last_committed -- which would be a bug!
• the monitor synchronized from a monitor with an older state of the store -- which should be impossible, given we only synchronize from someone with a paxos version higher than the one we have.

The reason why these are the only two that so far have made sense is because in-between bootstraps, resets and the sorts, the paxos services keep their in-memory state to some extent. For instance, the OSDMonitor keeps its in-memory 'osdmap' although it discards its pending value; same goes for the MDSMonitor, keeping its mdsmap. This is not a problem, and it even acts as a checkpoint that comes in hand to guarantee the correctness of a sync: we thus guarantee that we will assert on update_from_paxos() if whatever version we have on the store is lower than whatever we have in memory, given that if we have said version in memory and it is greater then we must currently have a past-state of the store.

I cannot ascertain what might have happened here without a store dump from a majority of monitors in the cluster including the one that have asserted out, as the logs don't really provide the necessary insight. Trying to reproduce it has been an unfruitful task too.

However, an easy conclusion we can take from both scenarios is that we have no good way to assess whether a full-store sync guarantees that all keys have been synchronized. They should, given we take a snapshot of the store and iterate over it, but that alone is no longer enough for me to blindly believe in it. We should maybe consider making the store sync somewhat more service-aware instead of doing a full-store sync regardless of what we are synchronizing.

Feedback appreciated before setting this to Need More Info.

i think the blind sync is still the way forward.. the more we make it aware of what is on top the harder it is to do different things (like break up PGMap).

is there a more complete log that would shed more light?

der, we have a complete log from the teuthology failure.

Sage thought there were logs on teuthology, on the directory from the initial report from Tamil. That run must have been killed, and in fact there are no logs, thus marking this Need More Info.

Also, as we haven't seen this since, Sage suggests to mark this as High instead of Urgent.

I've been able to reproduce this on some locked nodes that were hammering the monitors pretty hard for the past week.

The job itself was the following:

nuke-on-error: false
interactive-on-error: true
overrides:
  ceph:
    conf:
      global:
        ms inject socket failures: 5000
      mon:
        debug mon: 20
        debug ms: 1
        debug paxos: 20
    fs: xfs
    log-whitelist:
    - slow request
    branch: master
  install:
    ceph:
      branch: master
  workunit:
    branch: master
roles:
- - mon.a
  - mon.c
  - osd.0
  - osd.1
  - osd.2
- - mon.b
  - mds.a
  - osd.3
  - osd.4
  - osd.5
  - client.0
- - mon.d
  - mon.e
  - osd.6
  - osd.7
- - osd.8
  - osd.9
  - osd.10
  - mon.f
- - osd.11
  - osd.12
  - osd.13
  - mon.g
tasks:
- chef: null
- clock.check: null
- install: null
- ceph: null
- mon_thrash:
    revive_delay: 20
    thrash_delay: 1
    store-thrash: true
    thrash-many: true
    store-thrash-probability: 100
- rados:
    clients:
    - client.0
    objects: 50
    op_weights:
      delete: 50
      read: 100
      rollback: 50
      snap_create: 50
      snap_remove: 50
      write: 100
    ops: 4000

I grabbed the logs and the stores to my desktop, and here are the notes I've been taking so far:

The monitor (mon.d) doesn't have much of anything in its store besides a couple of paxos and pgmap stuff -- no mdsmap at all, so it's no wonder it all goes to crap.

mon.d appears to have gone through a couple of syncs. The first appears to have succeeded, bringing it up to version 2062 like most of the monitors in the cluster; however, while attempting to form quorum, a sync was triggered due to mon.a having version 2074.

mon.d's synchronization was started but mon.a instructed mon.d to retry the sync; mon.d never retried the sync, which may have been due to an election getting in the way? Truth is, mon.d eventually bootstrapped and joined the cluster as it was. It's hard to assess if the store got corrupted during the first sync, or if it was the one that was never retried that was the ultimate culprit.

Update: even though the synchronization had to be retried, we cleared the whole store prior to sending the sync_start message to the leader. This means that we get to only become aware that we should retry after clearing the whole store, and if we are killed in-between that we may end up with an empty store. Now, why would we end up with some deleted values anyway is beyond me. Maybe one of those leveldb bugs that bring deleted keys back to life after a compaction?!

this should have been fixed with the recent mon sync and other changes