OSD crash when one of the PGs have problem

OSD crash when one of the PGs have problem

[Varada Kari]

Hi all,


Sorry for the long mail. Wanted to give more information in the mail. 

We are seeing an issue in our test cluster when an osd is stopped gracefully and restarted after the maintenance. 
Please note, haven't used any no out option for the cluster. 
After the reboot, not able to one of the PG, and no drive problems are read errors are logged in dmesg/kernel logs. But we are not able to read the head object of PG for some reason, sorry of lack of logs we are running with debugs with 0/0 and build with jemalloc enabled for testing. Hence a customized version.

<snip>
2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal Terminated ***
2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop telling mon we are shutting down
2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid 6975
2016-01-04 10:46:14.007516 7fad39d1e800  0 filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
2016-01-04 10:46:14.008565 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2016-01-04 10:46:14.008573 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config option
2016-01-04 10:46:14.008601 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: splice is supported
2016-01-04 10:46:14.008882 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2016-01-04 10:46:14.008921 7fad39d1e800  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize is supported and your kernel >= 3.5
2016-01-04 10:46:14.339253 7fad39d1e800  0 filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls> cls/hello/cls_hello.cc:305: loading cls_hello
2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls> cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has features 1107558400, adjusting msgr requires for clients
2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has features 1107558400, adjusting msgr requires for osds
2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable to peek at 1.29e metadata, skipping
2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened 158 pgs
2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors {default=true}
2016-01-04 10:46:16.702999 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0, counting from 0)
2016-01-04 10:46:16.703014 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
2016-01-04 10:46:16.703017 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
{
    "ops": [
        {
            "op_num": 0,
            "op_name": "mkcoll",
            "collection": "1.29e_head"
        },
        {
            "op_num": 1,
            "op_name": "coll_hint",
            "collection": "1.29e_head",
            "type": 1,
            "pg_num": 800,
            "expected_num_objects": 0
        },
        {
            "op_num": 2,
            "op_name": "touch",
            "collection": "1.29e_head",
            "oid": "1\/0000029e\/\/head"
        },
        {
            "op_num": 3,
            "op_name": "omap_setkeys",
            "collection": "1.29e_head",
            "oid": "1\/0000029e\/\/head",
            "attr_lens": {
                "_infover": 1
            }
        },
        {
            "op_num": 4,
            "op_name": "touch",
            "collection": "1.29e_head",
            "oid": "1\/0000029e\/\/head"
        },
        {
            "op_num": 5,
            "op_name": "omap_setkeys",
            "collection": "1.29e_head",
            "oid": "1\/0000029e\/\/head",
            "attr_lens": {
                "_biginfo": 196,
                "_epoch": 4,
                "_info": 847,
                "can_rollback_to": 12,
                "rollback_info_trimmed_to": 12
            }
        }
    ]
}

2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04 10:46:16.703103
os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")

 ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7fad39846a6b]
 2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
 3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
 4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
 5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56) [0x7fad398384e6]
 6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
 7: (()+0x8182) [0x7fad38609182]
 8: (clone()+0x6d) [0x7fad367fc47d]
<snip>

 On the reboot, because of the journal reply, we didn't see any transaction dump issues this time, but we are seeing the following problem.

 <snip>
2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid 9488
2016-01-04 10:47:09.310055 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
2016-01-04 10:47:09.310379 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2016-01-04 10:47:09.310384 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config option
2016-01-04 10:47:09.310398 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: splice is supported
2016-01-04 10:47:09.310869 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2016-01-04 10:47:09.310935 7f8190a3c800  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize is supported and your kernel >= 3.5
2016-01-04 10:47:09.322795 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2016-01-04 10:47:09.322828 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle( filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
2016-01-04 10:47:09.327861 7f8183ee0700  0 filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls> cls/hello/cls_hello.cc:305: loading cls_hello
2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls> cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has features 1107558400, adjusting msgr requires for clients
2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has features 1107558400, adjusting msgr requires for osds
2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened 159 pgs
2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors {default=true}
2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init, starting boot process
2016-01-04 10:47:14.117463 7f817d1f3700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state connecting
2016-01-04 10:47:15.649791 7f812eefe700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state connecting
2016-01-04 10:47:15.649826 7f812edfd700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state connecting
2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter == log.rbegin())

 ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7f8190564a6b]
 2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21) [0x7f8190173971]
 3: (boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x1f4) [0x7f81901ad584]
 4: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event(boost::statechart::event_base const&)+0x5b) [0x7f8190197bab]
 5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
 6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
 7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
 8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56) [0x7f81905564e6]
 9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
 10: (()+0x8182) [0x7f818f327182]
 11: (clone()+0x6d) [0x7f818d51a47d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
<snip>

 Whenever we restart the osd, we are hitting the problem and not able to get the osd up. Tried pg repair, which bails saying primary osd down.
 Are there any repair techniques available to get this corrected? 
 
 Thanks,
 Varada
 
 

Re: OSD crash when one of the PGs have problem

[Sage Weil]

On Wed, 20 Jan 2016, Varada Kari wrote:
> Hi all,
> 
> 
> Sorry for the long mail. Wanted to give more information in the mail. 
> 
> We are seeing an issue in our test cluster when an osd is stopped gracefully and restarted after the maintenance. 
> Please note, haven't used any no out option for the cluster. 
> After the reboot, not able to one of the PG, and no drive problems are read errors are logged in dmesg/kernel logs. But we are not able to read the head object of PG for some reason, sorry of lack of logs we are running with debugs with 0/0 and build with jemalloc enabled for testing. Hence a customized version.
> 
> <snip>
> 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal Terminated ***
> 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop telling mon we are shutting down
> 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid 6975
> 2016-01-04 10:46:14.007516 7fad39d1e800  0 filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> 2016-01-04 10:46:14.008565 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
> 2016-01-04 10:46:14.008573 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config option
> 2016-01-04 10:46:14.008601 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: splice is supported
> 2016-01-04 10:46:14.008882 7fad39d1e800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
> 2016-01-04 10:46:14.008921 7fad39d1e800  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize is supported and your kernel >= 3.5
> 2016-01-04 10:46:14.339253 7fad39d1e800  0 filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
> 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls> cls/hello/cls_hello.cc:305: loading cls_hello
> 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls> cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has features 1107558400, adjusting msgr requires for clients
> 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
> 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has features 1107558400, adjusting msgr requires for osds
> 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
> 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable to peek at 1.29e metadata, skipping

It looks like the pg's metadata didn't commit properly.  It doesn't find 
it on startup, skips the pg, and then crashes below when it tries to 
create it and the collection already exists.

Are there any changes applied on top of upstream filestore?  Also, is this 
reproducible on a later version of the code?

> 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened 158 pgs
> 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors {default=true}
> 2016-01-04 10:46:16.702999 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0, counting from 0)
> 2016-01-04 10:46:16.703014 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
> 2016-01-04 10:46:16.703017 7fad273be700  0 filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
> {
>     "ops": [
>         {
>             "op_num": 0,
>             "op_name": "mkcoll",
>             "collection": "1.29e_head"
>         },
>         {
>             "op_num": 1,
>             "op_name": "coll_hint",
>             "collection": "1.29e_head",
>             "type": 1,
>             "pg_num": 800,
>             "expected_num_objects": 0
>         },
>         {
>             "op_num": 2,
>             "op_name": "touch",
>             "collection": "1.29e_head",
>             "oid": "1\/0000029e\/\/head"
>         },
>         {
>             "op_num": 3,
>             "op_name": "omap_setkeys",
>             "collection": "1.29e_head",
>             "oid": "1\/0000029e\/\/head",
>             "attr_lens": {
>                 "_infover": 1
>             }
>         },
>         {
>             "op_num": 4,
>             "op_name": "touch",
>             "collection": "1.29e_head",
>             "oid": "1\/0000029e\/\/head"
>         },
>         {
>             "op_num": 5,
>             "op_name": "omap_setkeys",
>             "collection": "1.29e_head",
>             "oid": "1\/0000029e\/\/head",
>             "attr_lens": {
>                 "_biginfo": 196,
>                 "_epoch": 4,
>                 "_info": 847,
>                 "can_rollback_to": 12,
>                 "rollback_info_trimmed_to": 12
>             }
>         }
>     ]
> }
> 
> 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In function 'unsigned int FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04 10:46:16.703103
> os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
> 
>  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7fad39846a6b]
>  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
>  3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, unsigned long, ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
>  4: (FileStore::_do_op(FileStore::OpSequencer*, ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
>  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56) [0x7fad398384e6]
>  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
>  7: (()+0x8182) [0x7fad38609182]
>  8: (clone()+0x6d) [0x7fad367fc47d]
> <snip>
> 
>  On the reboot, because of the journal reply, we didn't see any transaction dump issues this time, but we are seeing the following problem.
> 
>  <snip>
> 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid 9488
> 2016-01-04 10:47:09.310055 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> 2016-01-04 10:47:09.310379 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
> 2016-01-04 10:47:09.310384 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config option
> 2016-01-04 10:47:09.310398 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: splice is supported
> 2016-01-04 10:47:09.310869 7f8190a3c800  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
> 2016-01-04 10:47:09.310935 7f8190a3c800  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize is supported and your kernel >= 3.5
> 2016-01-04 10:47:09.322795 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
> 2016-01-04 10:47:09.322828 7f8190a3c800  0 filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle( filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
> 2016-01-04 10:47:09.327861 7f8183ee0700  0 filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
> 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls> cls/hello/cls_hello.cc:305: loading cls_hello
> 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls> cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has features 1107558400, adjusting msgr requires for clients
> 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has features 1107558400 was 8705, adjusting msgr requires for mons
> 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has features 1107558400, adjusting msgr requires for osds
> 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
> 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened 159 pgs
> 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors {default=true}
> 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init, starting boot process
> 2016-01-04 10:47:14.117463 7f817d1f3700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state connecting
> 2016-01-04 10:47:15.649791 7f812eefe700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state connecting
> 2016-01-04 10:47:15.649826 7f812edfd700  0 -- 10.242.43.141:6825/9488 >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0 pgs=0 cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state connecting
> 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
> osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter == log.rbegin())
> 
>  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x7f8190564a6b]
>  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21) [0x7f8190173971]
>  3: (boost::statechart::simple_state<PG::RecoveryState::Stray, PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, (boost::statechart::history_mode)0>::react_impl(boost::statechart::event_base const&, void const*)+0x1f4) [0x7f81901ad584]
>  4: (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine, PG::RecoveryState::Initial, std::allocator<void>, boost::statechart::null_exception_translator>::send_event(boost::statechart::event_base const&)+0x5b) [0x7f8190197bab]
>  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>, PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
>  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
>  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
>  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56) [0x7f81905564e6]
>  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
>  10: (()+0x8182) [0x7f818f327182]
>  11: (clone()+0x6d) [0x7f818d51a47d]
>  NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
> <snip>
> 
>  Whenever we restart the osd, we are hitting the problem and not able to get the osd up. Tried pg repair, which bails saying primary osd down.
>  Are there any repair techniques available to get this corrected? 

Most likely deleting the pg directory will be sufficient to clear it up.

sage

RE: OSD crash when one of the PGs have problem

[Varada Kari]

Yes Sage. Applied Somnath's write path changes on top the jewel branch (two weeks old) and jemalloc. Haven't tried with latest changes though. With the same code, we are not able hit this issue again, when retried.  Not sure if we are hitting any race in committing change here.

Varada

> -----Original Message-----
> From: Sage Weil [mailto:sage@newdream.net]
> Sent: Wednesday, January 20, 2016 9:04 PM
> To: Varada Kari <Varada.Kari@sandisk.com>
> Cc: ceph-devel@vger.kernel.org
> Subject: Re: OSD crash when one of the PGs have problem
> 
> On Wed, 20 Jan 2016, Varada Kari wrote:
> > Hi all,
> >
> >
> > Sorry for the long mail. Wanted to give more information in the mail.
> >
> > We are seeing an issue in our test cluster when an osd is stopped gracefully
> and restarted after the maintenance.
> > Please note, haven't used any no out option for the cluster.
> > After the reboot, not able to one of the PG, and no drive problems are
> read errors are logged in dmesg/kernel logs. But we are not able to read the
> head object of PG for some reason, sorry of lack of logs we are running with
> debugs with 0/0 and build with jemalloc enabled for testing. Hence a
> customized version.
> >
> > <snip>
> > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal
> > Terminated ***
> > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop
> > telling mon we are shutting down
> > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
> > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd,
> > pid 6975
> > 2016-01-04 10:46:14.007516 7fad39d1e800  0
> > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > 2016-01-04 10:46:14.008565 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > 2016-01-04 10:46:14.008573 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config
> > option
> > 2016-01-04 10:46:14.008601 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > splice is supported
> > 2016-01-04 10:46:14.008882 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > syncfs(2) syscall fully supported (by glibc and kernel)
> > 2016-01-04 10:46:14.008921 7fad39d1e800  0
> > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize
> > is supported and your kernel >= 3.5
> > 2016-01-04 10:46:14.339253 7fad39d1e800  0
> > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal
> > mode: checkpoint is not enabled
> > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
> > cls/hello/cls_hello.cc:305: loading cls_hello
> > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
> > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
> > features 1107558400, adjusting msgr requires for clients
> > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
> > features 1107558400 was 8705, adjusting msgr requires for mons
> > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
> > features 1107558400, adjusting msgr requires for osds
> > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
> > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable
> > to peek at 1.29e metadata, skipping
> 
> It looks like the pg's metadata didn't commit properly.  It doesn't find it on
> startup, skips the pg, and then crashes below when it tries to create it and
> the collection already exists.
> 
> Are there any changes applied on top of upstream filestore?  Also, is this
> reproducible on a later version of the code?
> 
> > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened
> > 158 pgs
> > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors
> > {default=true}
> > 2016-01-04 10:46:16.702999 7fad273be700  0
> > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
> > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0, counting
> > from 0)
> > 2016-01-04 10:46:16.703014 7fad273be700  0
> > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
> > 2016-01-04 10:46:16.703017 7fad273be700  0
> filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
> > {
> >     "ops": [
> >         {
> >             "op_num": 0,
> >             "op_name": "mkcoll",
> >             "collection": "1.29e_head"
> >         },
> >         {
> >             "op_num": 1,
> >             "op_name": "coll_hint",
> >             "collection": "1.29e_head",
> >             "type": 1,
> >             "pg_num": 800,
> >             "expected_num_objects": 0
> >         },
> >         {
> >             "op_num": 2,
> >             "op_name": "touch",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head"
> >         },
> >         {
> >             "op_num": 3,
> >             "op_name": "omap_setkeys",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head",
> >             "attr_lens": {
> >                 "_infover": 1
> >             }
> >         },
> >         {
> >             "op_num": 4,
> >             "op_name": "touch",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head"
> >         },
> >         {
> >             "op_num": 5,
> >             "op_name": "omap_setkeys",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head",
> >             "attr_lens": {
> >                 "_biginfo": 196,
> >                 "_epoch": 4,
> >                 "_info": 847,
> >                 "can_rollback_to": 12,
> >                 "rollback_info_trimmed_to": 12
> >             }
> >         }
> >     ]
> > }
> >
> > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
> > function 'unsigned int
> > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int,
> > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
> > 10:46:16.703103
> > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
> >
> >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > const*)+0x8b) [0x7fad39846a6b]
> >  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned
> > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
> >  3: (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
> > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
> > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
> >  4: (FileStore::_do_op(FileStore::OpSequencer*,
> > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
> >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > [0x7fad398384e6]
> >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
> >  7: (()+0x8182) [0x7fad38609182]
> >  8: (clone()+0x6d) [0x7fad367fc47d]
> > <snip>
> >
> >  On the reboot, because of the journal reply, we didn't see any transaction
> dump issues this time, but we are seeing the following problem.
> >
> >  <snip>
> > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
> > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
> 9488
> > 2016-01-04 10:47:09.310055 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > 2016-01-04 10:47:09.310379 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > 2016-01-04 10:47:09.310384 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' config
> > option
> > 2016-01-04 10:47:09.310398 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > splice is supported
> > 2016-01-04 10:47:09.310869 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > syncfs(2) syscall fully supported (by glibc and kernel)
> > 2016-01-04 10:47:09.310935 7f8190a3c800  0
> > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: extsize
> > is supported and your kernel >= 3.5
> > 2016-01-04 10:47:09.322795 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD journal
> > mode: checkpoint is not enabled
> > 2016-01-04 10:47:09.322828 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
> > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
> > 2016-01-04 10:47:09.327861 7f8183ee0700  0
> > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
> > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
> > cls/hello/cls_hello.cc:305: loading cls_hello
> > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
> > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
> > features 1107558400, adjusting msgr requires for clients
> > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
> > features 1107558400 was 8705, adjusting msgr requires for mons
> > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
> > features 1107558400, adjusting msgr requires for osds
> > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
> > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened
> > 159 pgs
> > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors
> > {default=true}
> > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init,
> > starting boot process
> > 2016-01-04 10:47:14.117463 7f817d1f3700  0 -- 10.242.43.141:6825/9488
> > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0 pgs=0
> > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state
> > connecting
> > 2016-01-04 10:47:15.649791 7f812eefe700  0 -- 10.242.43.141:6825/9488
> > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0
> > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state
> > connecting
> > 2016-01-04 10:47:15.649826 7f812edfd700  0 -- 10.242.43.141:6825/9488
> > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0 pgs=0
> > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state
> > connecting
> > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function
> > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
> > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
> > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
> > log.rbegin())
> >
> >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > const*)+0x8b) [0x7f8190564a6b]
> >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
> > [0x7f8190173971]
> >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
> > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
> > (boost::statechart::history_mode)0>::react_impl(boost::statechart::eve
> > nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
> >  4:
> > (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine,
> > PG::RecoveryState::Initial, std::allocator<void>,
> > boost::statechart::null_exception_translator>::send_event(boost::state
> > chart::event_base const&)+0x5b) [0x7f8190197bab]
> >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
> > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
> >  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> >
> > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
> >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
> > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
> >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > [0x7f81905564e6]
> >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
> >  10: (()+0x8182) [0x7f818f327182]
> >  11: (clone()+0x6d) [0x7f818d51a47d]
> >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed
> to interpret this.
> > <snip>
> >
> >  Whenever we restart the osd, we are hitting the problem and not able to
> get the osd up. Tried pg repair, which bails saying primary osd down.
> >  Are there any repair techniques available to get this corrected?
> 
> Most likely deleting the pg directory will be sufficient to clear it up.
> 
> sage

RE: OSD crash when one of the PGs have problem

[Somnath Roy]

You are saying xfs is throwing errors in the dmesg, so, this could be a reason why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?

Thanks & Regards
Somnath

-----Original Message-----
From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-owner@vger.kernel.org] On Behalf Of Varada Kari
Sent: Wednesday, January 20, 2016 8:02 AM
To: Sage Weil
Cc: ceph-devel@vger.kernel.org
Subject: RE: OSD crash when one of the PGs have problem 

Yes Sage. Applied Somnath's write path changes on top the jewel branch (two weeks old) and jemalloc. Haven't tried with latest changes though. With the same code, we are not able hit this issue again, when retried.  Not sure if we are hitting any race in committing change here.

Varada

> -----Original Message-----
> From: Sage Weil [mailto:sage@newdream.net]
> Sent: Wednesday, January 20, 2016 9:04 PM
> To: Varada Kari <Varada.Kari@sandisk.com>
> Cc: ceph-devel@vger.kernel.org
> Subject: Re: OSD crash when one of the PGs have problem
> 
> On Wed, 20 Jan 2016, Varada Kari wrote:
> > Hi all,
> >
> >
> > Sorry for the long mail. Wanted to give more information in the mail.
> >
> > We are seeing an issue in our test cluster when an osd is stopped 
> > gracefully
> and restarted after the maintenance.
> > Please note, haven't used any no out option for the cluster.
> > After the reboot, not able to one of the PG, and no drive problems 
> > are
> read errors are logged in dmesg/kernel logs. But we are not able to 
> read the head object of PG for some reason, sorry of lack of logs we 
> are running with debugs with 0/0 and build with jemalloc enabled for 
> testing. Hence a customized version.
> >
> > <snip>
> > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal 
> > Terminated ***
> > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop 
> > telling mon we are shutting down
> > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version 
> > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, 
> > pid 6975
> > 2016-01-04 10:46:14.007516 7fad39d1e800  0
> > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > 2016-01-04 10:46:14.008565 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > 2016-01-04 10:46:14.008573 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' 
> > config option
> > 2016-01-04 10:46:14.008601 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > splice is supported
> > 2016-01-04 10:46:14.008882 7fad39d1e800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > syncfs(2) syscall fully supported (by glibc and kernel)
> > 2016-01-04 10:46:14.008921 7fad39d1e800  0
> > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: 
> > extsize is supported and your kernel >= 3.5
> > 2016-01-04 10:46:14.339253 7fad39d1e800  0
> > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD 
> > journal
> > mode: checkpoint is not enabled
> > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
> > cls/hello/cls_hello.cc:305: loading cls_hello
> > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
> > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has 
> > features 1107558400, adjusting msgr requires for clients
> > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has 
> > features 1107558400 was 8705, adjusting msgr requires for mons
> > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has 
> > features 1107558400, adjusting msgr requires for osds
> > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
> > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable 
> > to peek at 1.29e metadata, skipping
> 
> It looks like the pg's metadata didn't commit properly.  It doesn't 
> find it on startup, skips the pg, and then crashes below when it tries 
> to create it and the collection already exists.
> 
> Are there any changes applied on top of upstream filestore?  Also, is 
> this reproducible on a later version of the code?
> 
> > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened
> > 158 pgs
> > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors 
> > {default=true}
> > 2016-01-04 10:46:16.702999 7fad273be700  0
> > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not 
> > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0, 
> > counting from 0)
> > 2016-01-04 10:46:16.703014 7fad273be700  0
> > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
> > 2016-01-04 10:46:16.703017 7fad273be700  0
> filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
> > {
> >     "ops": [
> >         {
> >             "op_num": 0,
> >             "op_name": "mkcoll",
> >             "collection": "1.29e_head"
> >         },
> >         {
> >             "op_num": 1,
> >             "op_name": "coll_hint",
> >             "collection": "1.29e_head",
> >             "type": 1,
> >             "pg_num": 800,
> >             "expected_num_objects": 0
> >         },
> >         {
> >             "op_num": 2,
> >             "op_name": "touch",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head"
> >         },
> >         {
> >             "op_num": 3,
> >             "op_name": "omap_setkeys",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head",
> >             "attr_lens": {
> >                 "_infover": 1
> >             }
> >         },
> >         {
> >             "op_num": 4,
> >             "op_name": "touch",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head"
> >         },
> >         {
> >             "op_num": 5,
> >             "op_name": "omap_setkeys",
> >             "collection": "1.29e_head",
> >             "oid": "1\/0000029e\/\/head",
> >             "attr_lens": {
> >                 "_biginfo": 196,
> >                 "_epoch": 4,
> >                 "_info": 847,
> >                 "can_rollback_to": 12,
> >                 "rollback_info_trimmed_to": 12
> >             }
> >         }
> >     ]
> > }
> >
> > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In 
> > function 'unsigned int 
> > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int, 
> > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
> > 10:46:16.703103
> > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
> >
> >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > const*)+0x8b) [0x7fad39846a6b]
> >  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned 
> > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
> >  3: 
> > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
> > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
> > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
> >  4: (FileStore::_do_op(FileStore::OpSequencer*,
> > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
> >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > [0x7fad398384e6]
> >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
> >  7: (()+0x8182) [0x7fad38609182]
> >  8: (clone()+0x6d) [0x7fad367fc47d]
> > <snip>
> >
> >  On the reboot, because of the journal reply, we didn't see any 
> > transaction
> dump issues this time, but we are seeing the following problem.
> >
> >  <snip>
> > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0 
> > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
> 9488
> > 2016-01-04 10:47:09.310055 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > 2016-01-04 10:47:09.310379 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > 2016-01-04 10:47:09.310384 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole' 
> > config option
> > 2016-01-04 10:47:09.310398 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > splice is supported
> > 2016-01-04 10:47:09.310869 7f8190a3c800  0
> > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > syncfs(2) syscall fully supported (by glibc and kernel)
> > 2016-01-04 10:47:09.310935 7f8190a3c800  0
> > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features: 
> > extsize is supported and your kernel >= 3.5
> > 2016-01-04 10:47:09.322795 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD 
> > journal
> > mode: checkpoint is not enabled
> > 2016-01-04 10:47:09.322828 7f8190a3c800  0
> > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle( 
> > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
> > 2016-01-04 10:47:09.327861 7f8183ee0700  0
> > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
> > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
> > cls/hello/cls_hello.cc:305: loading cls_hello
> > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
> > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has 
> > features 1107558400, adjusting msgr requires for clients
> > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has 
> > features 1107558400 was 8705, adjusting msgr requires for mons
> > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has 
> > features 1107558400, adjusting msgr requires for osds
> > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
> > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened
> > 159 pgs
> > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors 
> > {default=true}
> > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init, 
> > starting boot process
> > 2016-01-04 10:47:14.117463 7f817d1f3700  0 -- 
> > 10.242.43.141:6825/9488
> > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0 
> > >> pgs=0
> > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state 
> > connecting
> > 2016-01-04 10:47:15.649791 7f812eefe700  0 -- 
> > 10.242.43.141:6825/9488
> > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0
> > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state 
> > connecting
> > 2016-01-04 10:47:15.649826 7f812edfd700  0 -- 
> > 10.242.43.141:6825/9488
> > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0 
> > >> pgs=0
> > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state 
> > connecting
> > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function 
> > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
> > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
> > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
> > log.rbegin())
> >
> >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > const*)+0x8b) [0x7f8190564a6b]
> >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21) 
> > [0x7f8190173971]
> >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
> > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na, 
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, 
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, 
> > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>, 
> > (boost::statechart::history_mode)0>::react_impl(boost::statechart::e
> > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
> >  4:
> > (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
> > , PG::RecoveryState::Initial, std::allocator<void>, 
> > boost::statechart::null_exception_translator>::send_event(boost::sta
> > te chart::event_base const&)+0x5b) [0x7f8190197bab]
> >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
> > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
> >  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*> 
> > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
> >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> > 
> > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
> >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > [0x7f81905564e6]
> >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
> >  10: (()+0x8182) [0x7f818f327182]
> >  11: (clone()+0x6d) [0x7f818d51a47d]
> >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is 
> > needed
> to interpret this.
> > <snip>
> >
> >  Whenever we restart the osd, we are hitting the problem and not 
> > able to
> get the osd up. Tried pg repair, which bails saying primary osd down.
> >  Are there any repair techniques available to get this corrected?
> 
> Most likely deleting the pg directory will be sufficient to clear it up.
> 
> sage

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: OSD crash when one of the PGs have problem

[Varada Kari]

Somnath,

There are no xfs errors here. 

Varada

> -----Original Message-----
> From: Somnath Roy
> Sent: Wednesday, January 20, 2016 10:34 PM
> To: Varada Kari <Varada.Kari@sandisk.com>; Sage Weil
> <sage@newdream.net>
> Cc: ceph-devel@vger.kernel.org
> Subject: RE: OSD crash when one of the PGs have problem
> 
> You are saying xfs is throwing errors in the dmesg, so, this could be a reason
> why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?
> 
> Thanks & Regards
> Somnath
> 
> -----Original Message-----
> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-
> owner@vger.kernel.org] On Behalf Of Varada Kari
> Sent: Wednesday, January 20, 2016 8:02 AM
> To: Sage Weil
> Cc: ceph-devel@vger.kernel.org
> Subject: RE: OSD crash when one of the PGs have problem
> 
> Yes Sage. Applied Somnath's write path changes on top the jewel branch
> (two weeks old) and jemalloc. Haven't tried with latest changes though. With
> the same code, we are not able hit this issue again, when retried.  Not sure if
> we are hitting any race in committing change here.
> 
> Varada
> 
> > -----Original Message-----
> > From: Sage Weil [mailto:sage@newdream.net]
> > Sent: Wednesday, January 20, 2016 9:04 PM
> > To: Varada Kari <Varada.Kari@sandisk.com>
> > Cc: ceph-devel@vger.kernel.org
> > Subject: Re: OSD crash when one of the PGs have problem
> >
> > On Wed, 20 Jan 2016, Varada Kari wrote:
> > > Hi all,
> > >
> > >
> > > Sorry for the long mail. Wanted to give more information in the mail.
> > >
> > > We are seeing an issue in our test cluster when an osd is stopped
> > > gracefully
> > and restarted after the maintenance.
> > > Please note, haven't used any no out option for the cluster.
> > > After the reboot, not able to one of the PG, and no drive problems
> > > are
> > read errors are logged in dmesg/kernel logs. But we are not able to
> > read the head object of PG for some reason, sorry of lack of logs we
> > are running with debugs with 0/0 and build with jemalloc enabled for
> > testing. Hence a customized version.
> > >
> > > <snip>
> > > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal
> > > Terminated ***
> > > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop
> > > telling mon we are shutting down
> > > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
> > > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd,
> > > pid 6975
> > > 2016-01-04 10:46:14.007516 7fad39d1e800  0
> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > > 2016-01-04 10:46:14.008565 7fad39d1e800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > > 2016-01-04 10:46:14.008573 7fad39d1e800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
> > > config option
> > > 2016-01-04 10:46:14.008601 7fad39d1e800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > splice is supported
> > > 2016-01-04 10:46:14.008882 7fad39d1e800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > syncfs(2) syscall fully supported (by glibc and kernel)
> > > 2016-01-04 10:46:14.008921 7fad39d1e800  0
> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > extsize is supported and your kernel >= 3.5
> > > 2016-01-04 10:46:14.339253 7fad39d1e800  0
> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
> > > journal
> > > mode: checkpoint is not enabled
> > > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
> > > cls/hello/cls_hello.cc:305: loading cls_hello
> > > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
> > > features 1107558400, adjusting msgr requires for clients
> > > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
> > > features 1107558400 was 8705, adjusting msgr requires for mons
> > > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
> > > features 1107558400, adjusting msgr requires for osds
> > > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
> > > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable
> > > to peek at 1.29e metadata, skipping
> >
> > It looks like the pg's metadata didn't commit properly.  It doesn't
> > find it on startup, skips the pg, and then crashes below when it tries
> > to create it and the collection already exists.
> >
> > Are there any changes applied on top of upstream filestore?  Also, is
> > this reproducible on a later version of the code?
> >
> > > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened
> > > 158 pgs
> > > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors
> > > {default=true}
> > > 2016-01-04 10:46:16.702999 7fad273be700  0
> > > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
> > > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0,
> > > counting from 0)
> > > 2016-01-04 10:46:16.703014 7fad273be700  0
> > > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
> > > 2016-01-04 10:46:16.703017 7fad273be700  0
> > filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
> > > {
> > >     "ops": [
> > >         {
> > >             "op_num": 0,
> > >             "op_name": "mkcoll",
> > >             "collection": "1.29e_head"
> > >         },
> > >         {
> > >             "op_num": 1,
> > >             "op_name": "coll_hint",
> > >             "collection": "1.29e_head",
> > >             "type": 1,
> > >             "pg_num": 800,
> > >             "expected_num_objects": 0
> > >         },
> > >         {
> > >             "op_num": 2,
> > >             "op_name": "touch",
> > >             "collection": "1.29e_head",
> > >             "oid": "1\/0000029e\/\/head"
> > >         },
> > >         {
> > >             "op_num": 3,
> > >             "op_name": "omap_setkeys",
> > >             "collection": "1.29e_head",
> > >             "oid": "1\/0000029e\/\/head",
> > >             "attr_lens": {
> > >                 "_infover": 1
> > >             }
> > >         },
> > >         {
> > >             "op_num": 4,
> > >             "op_name": "touch",
> > >             "collection": "1.29e_head",
> > >             "oid": "1\/0000029e\/\/head"
> > >         },
> > >         {
> > >             "op_num": 5,
> > >             "op_name": "omap_setkeys",
> > >             "collection": "1.29e_head",
> > >             "oid": "1\/0000029e\/\/head",
> > >             "attr_lens": {
> > >                 "_biginfo": 196,
> > >                 "_epoch": 4,
> > >                 "_info": 847,
> > >                 "can_rollback_to": 12,
> > >                 "rollback_info_trimmed_to": 12
> > >             }
> > >         }
> > >     ]
> > > }
> > >
> > > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
> > > function 'unsigned int
> > > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int,
> > > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
> > > 10:46:16.703103
> > > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
> > >
> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > > const*)+0x8b) [0x7fad39846a6b]
> > >  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned
> > > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
> > >  3:
> > > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
> > > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
> > > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
> > >  4: (FileStore::_do_op(FileStore::OpSequencer*,
> > > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
> > >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > > [0x7fad398384e6]
> > >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
> > >  7: (()+0x8182) [0x7fad38609182]
> > >  8: (clone()+0x6d) [0x7fad367fc47d]
> > > <snip>
> > >
> > >  On the reboot, because of the journal reply, we didn't see any
> > > transaction
> > dump issues this time, but we are seeing the following problem.
> > >
> > >  <snip>
> > > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
> > > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
> > 9488
> > > 2016-01-04 10:47:09.310055 7f8190a3c800  0
> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> > > 2016-01-04 10:47:09.310379 7f8190a3c800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> > > 2016-01-04 10:47:09.310384 7f8190a3c800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
> > > config option
> > > 2016-01-04 10:47:09.310398 7f8190a3c800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > splice is supported
> > > 2016-01-04 10:47:09.310869 7f8190a3c800  0
> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > syncfs(2) syscall fully supported (by glibc and kernel)
> > > 2016-01-04 10:47:09.310935 7f8190a3c800  0
> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> > > extsize is supported and your kernel >= 3.5
> > > 2016-01-04 10:47:09.322795 7f8190a3c800  0
> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
> > > journal
> > > mode: checkpoint is not enabled
> > > 2016-01-04 10:47:09.322828 7f8190a3c800  0
> > > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
> > > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
> > > 2016-01-04 10:47:09.327861 7f8183ee0700  0
> > > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
> > > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
> > > cls/hello/cls_hello.cc:305: loading cls_hello
> > > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> > > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
> > > features 1107558400, adjusting msgr requires for clients
> > > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
> > > features 1107558400 was 8705, adjusting msgr requires for mons
> > > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
> > > features 1107558400, adjusting msgr requires for osds
> > > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
> > > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened
> > > 159 pgs
> > > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors
> > > {default=true}
> > > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init,
> > > starting boot process
> > > 2016-01-04 10:47:14.117463 7f817d1f3700  0 --
> > > 10.242.43.141:6825/9488
> > > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0
> > > >> pgs=0
> > > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state
> > > connecting
> > > 2016-01-04 10:47:15.649791 7f812eefe700  0 --
> > > 10.242.43.141:6825/9488
> > > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0
> > > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state
> > > connecting
> > > 2016-01-04 10:47:15.649826 7f812edfd700  0 --
> > > 10.242.43.141:6825/9488
> > > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0
> > > >> pgs=0
> > > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state
> > > connecting
> > > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function
> > > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
> > > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
> > > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
> > > log.rbegin())
> > >
> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> > > const*)+0x8b) [0x7f8190564a6b]
> > >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
> > > [0x7f8190173971]
> > >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
> > > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
> > > (boost::statechart::history_mode)0>::react_impl(boost::statechart::e
> > > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
> > >  4:
> > >
> (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
> > > , PG::RecoveryState::Initial, std::allocator<void>,
> > > boost::statechart::null_exception_translator>::send_event(boost::sta
> > > te chart::event_base const&)+0x5b) [0x7f8190197bab]
> > >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
> > > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
> > >  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*>
> > > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
> > >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
> > > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
> > >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> > > [0x7f81905564e6]
> > >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
> > >  10: (()+0x8182) [0x7f818f327182]
> > >  11: (clone()+0x6d) [0x7f818d51a47d]
> > >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
> > > needed
> > to interpret this.
> > > <snip>
> > >
> > >  Whenever we restart the osd, we are hitting the problem and not
> > > able to
> > get the osd up. Tried pg repair, which bails saying primary osd down.
> > >  Are there any repair techniques available to get this corrected?
> >
> > Most likely deleting the pg directory will be sufficient to clear it up.
> >
> > sage
> 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the
> body of a message to majordomo@vger.kernel.org More majordomo info at
> http://vger.kernel.org/majordomo-info.html

Re: OSD crash when one of the PGs have problem

[Evgeniy Firsov]

I am able to reproduce the problem even with current, unmodified master.

Test case:
1. Start 2 OSDs, 8 PGs, pool size = 2
2. Run write workload for some time.
3. Stop workload
4. rm -rf dev/osd0/current/0.2_head/*
5. ceph osd scrub 0
6. ceph pg repair 0.2
7. Restart OSD.
8. Get "error (17) File exists not handled on operation"

On 1/20/16, 9:30 AM, "ceph-devel-owner@vger.kernel.org on behalf of Varada
Kari" <ceph-devel-owner@vger.kernel.org on behalf of
Varada.Kari@sandisk.com> wrote:

>Somnath,
>
>There are no xfs errors here.
>
>Varada
>
>> -----Original Message-----
>> From: Somnath Roy
>> Sent: Wednesday, January 20, 2016 10:34 PM
>> To: Varada Kari <Varada.Kari@sandisk.com>; Sage Weil
>> <sage@newdream.net>
>> Cc: ceph-devel@vger.kernel.org
>> Subject: RE: OSD crash when one of the PGs have problem
>> 
>> You are saying xfs is throwing errors in the dmesg, so, this could be a
>>reason
>> why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?
>> 
>> Thanks & Regards
>> Somnath
>> 
>> -----Original Message-----
>> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-
>> owner@vger.kernel.org] On Behalf Of Varada Kari
>> Sent: Wednesday, January 20, 2016 8:02 AM
>> To: Sage Weil
>> Cc: ceph-devel@vger.kernel.org
>> Subject: RE: OSD crash when one of the PGs have problem
>> 
>> Yes Sage. Applied Somnath's write path changes on top the jewel branch
>> (two weeks old) and jemalloc. Haven't tried with latest changes though.
>>With
>> the same code, we are not able hit this issue again, when retried.  Not
>>sure if
>> we are hitting any race in committing change here.
>> 
>> Varada
>> 
>> > -----Original Message-----
>> > From: Sage Weil [mailto:sage@newdream.net]
>> > Sent: Wednesday, January 20, 2016 9:04 PM
>> > To: Varada Kari <Varada.Kari@sandisk.com>
>> > Cc: ceph-devel@vger.kernel.org
>> > Subject: Re: OSD crash when one of the PGs have problem
>> >
>> > On Wed, 20 Jan 2016, Varada Kari wrote:
>> > > Hi all,
>> > >
>> > >
>> > > Sorry for the long mail. Wanted to give more information in the
>>mail.
>> > >
>> > > We are seeing an issue in our test cluster when an osd is stopped
>> > > gracefully
>> > and restarted after the maintenance.
>> > > Please note, haven't used any no out option for the cluster.
>> > > After the reboot, not able to one of the PG, and no drive problems
>> > > are
>> > read errors are logged in dmesg/kernel logs. But we are not able to
>> > read the head object of PG for some reason, sorry of lack of logs we
>> > are running with debugs with 0/0 and build with jemalloc enabled for
>> > testing. Hence a customized version.
>> > >
>> > > <snip>
>> > > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal
>> > > Terminated ***
>> > > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405 prepare_to_stop
>> > > telling mon we are shutting down
>> > > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
>> > > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd,
>> > > pid 6975
>> > > 2016-01-04 10:46:14.007516 7fad39d1e800  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>> > > 2016-01-04 10:46:14.008565 7fad39d1e800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>> > > 2016-01-04 10:46:14.008573 7fad39d1e800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>> > > config option
>> > > 2016-01-04 10:46:14.008601 7fad39d1e800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > splice is supported
>> > > 2016-01-04 10:46:14.008882 7fad39d1e800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>> > > 2016-01-04 10:46:14.008921 7fad39d1e800  0
>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > extsize is supported and your kernel >= 3.5
>> > > 2016-01-04 10:46:14.339253 7fad39d1e800  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>> > > journal
>> > > mode: checkpoint is not enabled
>> > > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>> > > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>> > > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
>> > > features 1107558400, adjusting msgr requires for clients
>> > > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>> > > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
>> > > features 1107558400, adjusting msgr requires for osds
>> > > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
>> > > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs unable
>> > > to peek at 1.29e metadata, skipping
>> >
>> > It looks like the pg's metadata didn't commit properly.  It doesn't
>> > find it on startup, skips the pg, and then crashes below when it tries
>> > to create it and the collection already exists.
>> >
>> > Are there any changes applied on top of upstream filestore?  Also, is
>> > this reproducible on a later version of the code?
>> >
>> > > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs opened
>> > > 158 pgs
>> > > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405 log_to_monitors
>> > > {default=true}
>> > > 2016-01-04 10:46:16.702999 7fad273be700  0
>> > > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
>> > > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0,
>> > > counting from 0)
>> > > 2016-01-04 10:46:16.703014 7fad273be700  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
>> > > 2016-01-04 10:46:16.703017 7fad273be700  0
>> > filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
>> > > {
>> > >     "ops": [
>> > >         {
>> > >             "op_num": 0,
>> > >             "op_name": "mkcoll",
>> > >             "collection": "1.29e_head"
>> > >         },
>> > >         {
>> > >             "op_num": 1,
>> > >             "op_name": "coll_hint",
>> > >             "collection": "1.29e_head",
>> > >             "type": 1,
>> > >             "pg_num": 800,
>> > >             "expected_num_objects": 0
>> > >         },
>> > >         {
>> > >             "op_num": 2,
>> > >             "op_name": "touch",
>> > >             "collection": "1.29e_head",
>> > >             "oid": "1\/0000029e\/\/head"
>> > >         },
>> > >         {
>> > >             "op_num": 3,
>> > >             "op_name": "omap_setkeys",
>> > >             "collection": "1.29e_head",
>> > >             "oid": "1\/0000029e\/\/head",
>> > >             "attr_lens": {
>> > >                 "_infover": 1
>> > >             }
>> > >         },
>> > >         {
>> > >             "op_num": 4,
>> > >             "op_name": "touch",
>> > >             "collection": "1.29e_head",
>> > >             "oid": "1\/0000029e\/\/head"
>> > >         },
>> > >         {
>> > >             "op_num": 5,
>> > >             "op_name": "omap_setkeys",
>> > >             "collection": "1.29e_head",
>> > >             "oid": "1\/0000029e\/\/head",
>> > >             "attr_lens": {
>> > >                 "_biginfo": 196,
>> > >                 "_epoch": 4,
>> > >                 "_info": 847,
>> > >                 "can_rollback_to": 12,
>> > >                 "rollback_info_trimmed_to": 12
>> > >             }
>> > >         }
>> > >     ]
>> > > }
>> > >
>> > > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
>> > > function 'unsigned int
>> > > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t, int,
>> > > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
>> > > 10:46:16.703103
>> > > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
>> > >
>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>> > > const*)+0x8b) [0x7fad39846a6b]
>> > >  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned
>> > > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
>> > >  3:
>> > > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
>> > > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
>> > > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
>> > >  4: (FileStore::_do_op(FileStore::OpSequencer*,
>> > > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
>> > >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>> > > [0x7fad398384e6]
>> > >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
>> > >  7: (()+0x8182) [0x7fad38609182]
>> > >  8: (clone()+0x6d) [0x7fad367fc47d]
>> > > <snip>
>> > >
>> > >  On the reboot, because of the journal reply, we didn't see any
>> > > transaction
>> > dump issues this time, but we are seeing the following problem.
>> > >
>> > >  <snip>
>> > > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
>> > > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
>> > 9488
>> > > 2016-01-04 10:47:09.310055 7f8190a3c800  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>> > > 2016-01-04 10:47:09.310379 7f8190a3c800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>> > > 2016-01-04 10:47:09.310384 7f8190a3c800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>> > > config option
>> > > 2016-01-04 10:47:09.310398 7f8190a3c800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > splice is supported
>> > > 2016-01-04 10:47:09.310869 7f8190a3c800  0
>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>> > > 2016-01-04 10:47:09.310935 7f8190a3c800  0
>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>> > > extsize is supported and your kernel >= 3.5
>> > > 2016-01-04 10:47:09.322795 7f8190a3c800  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>> > > journal
>> > > mode: checkpoint is not enabled
>> > > 2016-01-04 10:47:09.322828 7f8190a3c800  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
>> > > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
>> > > 2016-01-04 10:47:09.327861 7f8183ee0700  0
>> > > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
>> > > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>> > > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>> > > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
>> > > features 1107558400, adjusting msgr requires for clients
>> > > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>> > > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
>> > > features 1107558400, adjusting msgr requires for osds
>> > > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
>> > > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs opened
>> > > 159 pgs
>> > > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410 log_to_monitors
>> > > {default=true}
>> > > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with init,
>> > > starting boot process
>> > > 2016-01-04 10:47:14.117463 7f817d1f3700  0 --
>> > > 10.242.43.141:6825/9488
>> > > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0
>> > > >> pgs=0
>> > > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state
>> > > connecting
>> > > 2016-01-04 10:47:15.649791 7f812eefe700  0 --
>> > > 10.242.43.141:6825/9488
>> > > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0 pgs=0
>> > > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state
>> > > connecting
>> > > 2016-01-04 10:47:15.649826 7f812edfd700  0 --
>> > > 10.242.43.141:6825/9488
>> > > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0
>> > > >> pgs=0
>> > > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state
>> > > connecting
>> > > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function
>> > > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
>> > > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
>> > > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
>> > > log.rbegin())
>> > >
>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>> > > const*)+0x8b) [0x7f8190564a6b]
>> > >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
>> > > [0x7f8190173971]
>> > >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
>> > > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
>> > > (boost::statechart::history_mode)0>::react_impl(boost::statechart::e
>> > > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
>> > >  4:
>> > >
>> (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
>> > > , PG::RecoveryState::Initial, std::allocator<void>,
>> > > boost::statechart::null_exception_translator>::send_event(boost::sta
>> > > te chart::event_base const&)+0x5b) [0x7f8190197bab]
>> > >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
>> > > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
>> > >  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*>
>> > > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
>> > >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
>> > > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
>> > >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>> > > [0x7f81905564e6]
>> > >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
>> > >  10: (()+0x8182) [0x7f818f327182]
>> > >  11: (clone()+0x6d) [0x7f818d51a47d]
>> > >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>> > > needed
>> > to interpret this.
>> > > <snip>
>> > >
>> > >  Whenever we restart the osd, we are hitting the problem and not
>> > > able to
>> > get the osd up. Tried pg repair, which bails saying primary osd down.
>> > >  Are there any repair techniques available to get this corrected?
>> >
>> > Most likely deleting the pg directory will be sufficient to clear it
>>up.
>> >
>> > sage
>> 
>> --
>> To unsubscribe from this list: send the line "unsubscribe ceph-devel"
>>in the
>> body of a message to majordomo@vger.kernel.org More majordomo info at
>> http://vger.kernel.org/majordomo-info.html
>--
>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>the body of a message to majordomo@vger.kernel.org
>More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: OSD crash when one of the PGs have problem

[Evgeniy Firsov]

The same test case fail with stock Jewel branch too.

On 1/20/16, 5:02 PM, "ceph-devel-owner@vger.kernel.org on behalf of
Evgeniy Firsov" <ceph-devel-owner@vger.kernel.org on behalf of
Evgeniy.Firsov@sandisk.com> wrote:

>I am able to reproduce the problem even with current, unmodified master.
>
>Test case:
>1. Start 2 OSDs, 8 PGs, pool size = 2
>2. Run write workload for some time.
>3. Stop workload
>4. rm -rf dev/osd0/current/0.2_head/*
>5. ceph osd scrub 0
>6. ceph pg repair 0.2
>7. Restart OSD.
>8. Get "error (17) File exists not handled on operation"
>
>On 1/20/16, 9:30 AM, "ceph-devel-owner@vger.kernel.org on behalf of Varada
>Kari" <ceph-devel-owner@vger.kernel.org on behalf of
>Varada.Kari@sandisk.com> wrote:
>
>>Somnath,
>>
>>There are no xfs errors here.
>>
>>Varada
>>
>>> -----Original Message-----
>>> From: Somnath Roy
>>> Sent: Wednesday, January 20, 2016 10:34 PM
>>> To: Varada Kari <Varada.Kari@sandisk.com>; Sage Weil
>>> <sage@newdream.net>
>>> Cc: ceph-devel@vger.kernel.org
>>> Subject: RE: OSD crash when one of the PGs have problem
>>> 
>>> You are saying xfs is throwing errors in the dmesg, so, this could be a
>>>reason
>>> why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?
>>> 
>>> Thanks & Regards
>>> Somnath
>>> 
>>> -----Original Message-----
>>> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-
>>> owner@vger.kernel.org] On Behalf Of Varada Kari
>>> Sent: Wednesday, January 20, 2016 8:02 AM
>>> To: Sage Weil
>>> Cc: ceph-devel@vger.kernel.org
>>> Subject: RE: OSD crash when one of the PGs have problem
>>> 
>>> Yes Sage. Applied Somnath's write path changes on top the jewel branch
>>> (two weeks old) and jemalloc. Haven't tried with latest changes though.
>>>With
>>> the same code, we are not able hit this issue again, when retried.  Not
>>>sure if
>>> we are hitting any race in committing change here.
>>> 
>>> Varada
>>> 
>>> > -----Original Message-----
>>> > From: Sage Weil [mailto:sage@newdream.net]
>>> > Sent: Wednesday, January 20, 2016 9:04 PM
>>> > To: Varada Kari <Varada.Kari@sandisk.com>
>>> > Cc: ceph-devel@vger.kernel.org
>>> > Subject: Re: OSD crash when one of the PGs have problem
>>> >
>>> > On Wed, 20 Jan 2016, Varada Kari wrote:
>>> > > Hi all,
>>> > >
>>> > >
>>> > > Sorry for the long mail. Wanted to give more information in the
>>>mail.
>>> > >
>>> > > We are seeing an issue in our test cluster when an osd is stopped
>>> > > gracefully
>>> > and restarted after the maintenance.
>>> > > Please note, haven't used any no out option for the cluster.
>>> > > After the reboot, not able to one of the PG, and no drive problems
>>> > > are
>>> > read errors are logged in dmesg/kernel logs. But we are not able to
>>> > read the head object of PG for some reason, sorry of lack of logs we
>>> > are running with debugs with 0/0 and build with jemalloc enabled for
>>> > testing. Hence a customized version.
>>> > >
>>> > > <snip>
>>> > > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got signal
>>> > > Terminated ***
>>> > > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405
>>>prepare_to_stop
>>> > > telling mon we are shutting down
>>> > > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
>>> > > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd,
>>> > > pid 6975
>>> > > 2016-01-04 10:46:14.007516 7fad39d1e800  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>>> > > 2016-01-04 10:46:14.008565 7fad39d1e800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>>> > > 2016-01-04 10:46:14.008573 7fad39d1e800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>>> > > config option
>>> > > 2016-01-04 10:46:14.008601 7fad39d1e800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > splice is supported
>>> > > 2016-01-04 10:46:14.008882 7fad39d1e800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>>> > > 2016-01-04 10:46:14.008921 7fad39d1e800  0
>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > extsize is supported and your kernel >= 3.5
>>> > > 2016-01-04 10:46:14.339253 7fad39d1e800  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>>> > > journal
>>> > > mode: checkpoint is not enabled
>>> > > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>>> > > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>>> > > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
>>> > > features 1107558400, adjusting msgr requires for clients
>>> > > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>>> > > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
>>> > > features 1107558400, adjusting msgr requires for osds
>>> > > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
>>> > > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs
>>>unable
>>> > > to peek at 1.29e metadata, skipping
>>> >
>>> > It looks like the pg's metadata didn't commit properly.  It doesn't
>>> > find it on startup, skips the pg, and then crashes below when it
>>>tries
>>> > to create it and the collection already exists.
>>> >
>>> > Are there any changes applied on top of upstream filestore?  Also, is
>>> > this reproducible on a later version of the code?
>>> >
>>> > > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs
>>>opened
>>> > > 158 pgs
>>> > > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405
>>>log_to_monitors
>>> > > {default=true}
>>> > > 2016-01-04 10:46:16.702999 7fad273be700  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
>>> > > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0,
>>> > > counting from 0)
>>> > > 2016-01-04 10:46:16.703014 7fad273be700  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
>>> > > 2016-01-04 10:46:16.703017 7fad273be700  0
>>> > filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
>>> > > {
>>> > >     "ops": [
>>> > >         {
>>> > >             "op_num": 0,
>>> > >             "op_name": "mkcoll",
>>> > >             "collection": "1.29e_head"
>>> > >         },
>>> > >         {
>>> > >             "op_num": 1,
>>> > >             "op_name": "coll_hint",
>>> > >             "collection": "1.29e_head",
>>> > >             "type": 1,
>>> > >             "pg_num": 800,
>>> > >             "expected_num_objects": 0
>>> > >         },
>>> > >         {
>>> > >             "op_num": 2,
>>> > >             "op_name": "touch",
>>> > >             "collection": "1.29e_head",
>>> > >             "oid": "1\/0000029e\/\/head"
>>> > >         },
>>> > >         {
>>> > >             "op_num": 3,
>>> > >             "op_name": "omap_setkeys",
>>> > >             "collection": "1.29e_head",
>>> > >             "oid": "1\/0000029e\/\/head",
>>> > >             "attr_lens": {
>>> > >                 "_infover": 1
>>> > >             }
>>> > >         },
>>> > >         {
>>> > >             "op_num": 4,
>>> > >             "op_name": "touch",
>>> > >             "collection": "1.29e_head",
>>> > >             "oid": "1\/0000029e\/\/head"
>>> > >         },
>>> > >         {
>>> > >             "op_num": 5,
>>> > >             "op_name": "omap_setkeys",
>>> > >             "collection": "1.29e_head",
>>> > >             "oid": "1\/0000029e\/\/head",
>>> > >             "attr_lens": {
>>> > >                 "_biginfo": 196,
>>> > >                 "_epoch": 4,
>>> > >                 "_info": 847,
>>> > >                 "can_rollback_to": 12,
>>> > >                 "rollback_info_trimmed_to": 12
>>> > >             }
>>> > >         }
>>> > >     ]
>>> > > }
>>> > >
>>> > > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
>>> > > function 'unsigned int
>>> > > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t,
>>>int,
>>> > > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
>>> > > 10:46:16.703103
>>> > > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
>>> > >
>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>> > > const*)+0x8b) [0x7fad39846a6b]
>>> > >  2: (FileStore::_do_transaction(ObjectStore::Transaction&, unsigned
>>> > > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
>>> > >  3:
>>> > > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
>>> > > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
>>> > > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
>>> > >  4: (FileStore::_do_op(FileStore::OpSequencer*,
>>> > > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
>>> > >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>>> > > [0x7fad398384e6]
>>> > >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
>>> > >  7: (()+0x8182) [0x7fad38609182]
>>> > >  8: (clone()+0x6d) [0x7fad367fc47d]
>>> > > <snip>
>>> > >
>>> > >  On the reboot, because of the journal reply, we didn't see any
>>> > > transaction
>>> > dump issues this time, but we are seeing the following problem.
>>> > >
>>> > >  <snip>
>>> > > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
>>> > > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
>>> > 9488
>>> > > 2016-01-04 10:47:09.310055 7f8190a3c800  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>>> > > 2016-01-04 10:47:09.310379 7f8190a3c800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>>> > > 2016-01-04 10:47:09.310384 7f8190a3c800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>>> > > config option
>>> > > 2016-01-04 10:47:09.310398 7f8190a3c800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > splice is supported
>>> > > 2016-01-04 10:47:09.310869 7f8190a3c800  0
>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>>> > > 2016-01-04 10:47:09.310935 7f8190a3c800  0
>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>> > > extsize is supported and your kernel >= 3.5
>>> > > 2016-01-04 10:47:09.322795 7f8190a3c800  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>>> > > journal
>>> > > mode: checkpoint is not enabled
>>> > > 2016-01-04 10:47:09.322828 7f8190a3c800  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
>>> > > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
>>> > > 2016-01-04 10:47:09.327861 7f8183ee0700  0
>>> > > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
>>> > > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>>> > > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>>> > > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
>>> > > features 1107558400, adjusting msgr requires for clients
>>> > > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>>> > > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
>>> > > features 1107558400, adjusting msgr requires for osds
>>> > > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
>>> > > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs
>>>opened
>>> > > 159 pgs
>>> > > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410
>>>log_to_monitors
>>> > > {default=true}
>>> > > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with
>>>init,
>>> > > starting boot process
>>> > > 2016-01-04 10:47:14.117463 7f817d1f3700  0 --
>>> > > 10.242.43.141:6825/9488
>>> > > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0
>>> > > >> pgs=0
>>> > > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0 state
>>> > > connecting
>>> > > 2016-01-04 10:47:15.649791 7f812eefe700  0 --
>>> > > 10.242.43.141:6825/9488
>>> > > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0
>>>pgs=0
>>> > > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0 state
>>> > > connecting
>>> > > 2016-01-04 10:47:15.649826 7f812edfd700  0 --
>>> > > 10.242.43.141:6825/9488
>>> > > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0
>>> > > >> pgs=0
>>> > > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0 state
>>> > > connecting
>>> > > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In function
>>> > > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
>>> > > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
>>> > > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
>>> > > log.rbegin())
>>> > >
>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>> > > const*)+0x8b) [0x7f8190564a6b]
>>> > >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
>>> > > [0x7f8190173971]
>>> > >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
>>> > > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
>>> > > 
>>>(boost::statechart::history_mode)0>::react_impl(boost::statechart::e
>>> > > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
>>> > >  4:
>>> > >
>>> (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
>>> > > , PG::RecoveryState::Initial, std::allocator<void>,
>>> > > 
>>>boost::statechart::null_exception_translator>::send_event(boost::sta
>>> > > te chart::event_base const&)+0x5b) [0x7f8190197bab]
>>> > >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
>>> > > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
>>> > >  6: (OSD::process_peering_events(std::list<PG*, std::allocator<PG*>
>>> > > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
>>> > >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
>>> > > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
>>> > >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>>> > > [0x7f81905564e6]
>>> > >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
>>> > >  10: (()+0x8182) [0x7f818f327182]
>>> > >  11: (clone()+0x6d) [0x7f818d51a47d]
>>> > >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>> > > needed
>>> > to interpret this.
>>> > > <snip>
>>> > >
>>> > >  Whenever we restart the osd, we are hitting the problem and not
>>> > > able to
>>> > get the osd up. Tried pg repair, which bails saying primary osd down.
>>> > >  Are there any repair techniques available to get this corrected?
>>> >
>>> > Most likely deleting the pg directory will be sufficient to clear it
>>>up.
>>> >
>>> > sage
>>> 
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel"
>>>in the
>>> body of a message to majordomo@vger.kernel.org More majordomo info at
>>> http://vger.kernel.org/majordomo-info.html
>>--
>>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>the body of a message to majordomo@vger.kernel.org
>>More majordomo info at  http://vger.kernel.org/majordomo-info.html
>
>--
>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>the body of a message to majordomo@vger.kernel.org
>More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: OSD crash when one of the PGs have problem

[Evgeniy Firsov]

I filed a PR which fixes the bug: https://github.com/ceph/ceph/pull/7470

But there are at least two questions which need clarification:
1. I expect, and my tests confirm so far, that FileStore::_touch call is
NOT used on fast path. But there is an opinion that it might.
2. Does the fix need write_if_dirty part, which writes metadata besides
version info, such as epoch? The question is because PG::_init doesn't
have this part and writes version info only.


Thank you.

On 1/20/16, 5:07 PM, "Evgeniy Firsov" <Evgeniy.Firsov@sandisk.com> wrote:

>The same test case fail with stock Jewel branch too.
>
>On 1/20/16, 5:02 PM, "ceph-devel-owner@vger.kernel.org on behalf of
>Evgeniy Firsov" <ceph-devel-owner@vger.kernel.org on behalf of
>Evgeniy.Firsov@sandisk.com> wrote:
>
>>I am able to reproduce the problem even with current, unmodified master.
>>
>>Test case:
>>1. Start 2 OSDs, 8 PGs, pool size = 2
>>2. Run write workload for some time.
>>3. Stop workload
>>4. rm -rf dev/osd0/current/0.2_head/*
>>5. ceph osd scrub 0
>>6. ceph pg repair 0.2
>>7. Restart OSD.
>>8. Get "error (17) File exists not handled on operation"
>>
>>On 1/20/16, 9:30 AM, "ceph-devel-owner@vger.kernel.org on behalf of
>>Varada
>>Kari" <ceph-devel-owner@vger.kernel.org on behalf of
>>Varada.Kari@sandisk.com> wrote:
>>
>>>Somnath,
>>>
>>>There are no xfs errors here.
>>>
>>>Varada
>>>
>>>> -----Original Message-----
>>>> From: Somnath Roy
>>>> Sent: Wednesday, January 20, 2016 10:34 PM
>>>> To: Varada Kari <Varada.Kari@sandisk.com>; Sage Weil
>>>> <sage@newdream.net>
>>>> Cc: ceph-devel@vger.kernel.org
>>>> Subject: RE: OSD crash when one of the PGs have problem
>>>> 
>>>> You are saying xfs is throwing errors in the dmesg, so, this could be
>>>>a
>>>>reason
>>>> why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?
>>>> 
>>>> Thanks & Regards
>>>> Somnath
>>>> 
>>>> -----Original Message-----
>>>> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-
>>>> owner@vger.kernel.org] On Behalf Of Varada Kari
>>>> Sent: Wednesday, January 20, 2016 8:02 AM
>>>> To: Sage Weil
>>>> Cc: ceph-devel@vger.kernel.org
>>>> Subject: RE: OSD crash when one of the PGs have problem
>>>> 
>>>> Yes Sage. Applied Somnath's write path changes on top the jewel branch
>>>> (two weeks old) and jemalloc. Haven't tried with latest changes
>>>>though.
>>>>With
>>>> the same code, we are not able hit this issue again, when retried.
>>>>Not
>>>>sure if
>>>> we are hitting any race in committing change here.
>>>> 
>>>> Varada
>>>> 
>>>> > -----Original Message-----
>>>> > From: Sage Weil [mailto:sage@newdream.net]
>>>> > Sent: Wednesday, January 20, 2016 9:04 PM
>>>> > To: Varada Kari <Varada.Kari@sandisk.com>
>>>> > Cc: ceph-devel@vger.kernel.org
>>>> > Subject: Re: OSD crash when one of the PGs have problem
>>>> >
>>>> > On Wed, 20 Jan 2016, Varada Kari wrote:
>>>> > > Hi all,
>>>> > >
>>>> > >
>>>> > > Sorry for the long mail. Wanted to give more information in the
>>>>mail.
>>>> > >
>>>> > > We are seeing an issue in our test cluster when an osd is stopped
>>>> > > gracefully
>>>> > and restarted after the maintenance.
>>>> > > Please note, haven't used any no out option for the cluster.
>>>> > > After the reboot, not able to one of the PG, and no drive problems
>>>> > > are
>>>> > read errors are logged in dmesg/kernel logs. But we are not able to
>>>> > read the head object of PG for some reason, sorry of lack of logs we
>>>> > are running with debugs with 0/0 and build with jemalloc enabled for
>>>> > testing. Hence a customized version.
>>>> > >
>>>> > > <snip>
>>>> > > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got
>>>>signal
>>>> > > Terminated ***
>>>> > > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405
>>>>prepare_to_stop
>>>> > > telling mon we are shutting down
>>>> > > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
>>>> > > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process
>>>>ceph-osd,
>>>> > > pid 6975
>>>> > > 2016-01-04 10:46:14.007516 7fad39d1e800  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>>>> > > 2016-01-04 10:46:14.008565 7fad39d1e800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>>>> > > 2016-01-04 10:46:14.008573 7fad39d1e800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>>>> > > config option
>>>> > > 2016-01-04 10:46:14.008601 7fad39d1e800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > splice is supported
>>>> > > 2016-01-04 10:46:14.008882 7fad39d1e800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>>>> > > 2016-01-04 10:46:14.008921 7fad39d1e800  0
>>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > extsize is supported and your kernel >= 3.5
>>>> > > 2016-01-04 10:46:14.339253 7fad39d1e800  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>>>> > > journal
>>>> > > mode: checkpoint is not enabled
>>>> > > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
>>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>>>> > > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
>>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>>>> > > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
>>>> > > features 1107558400, adjusting msgr requires for clients
>>>> > > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
>>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>>>> > > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
>>>> > > features 1107558400, adjusting msgr requires for osds
>>>> > > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
>>>> > > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs
>>>>unable
>>>> > > to peek at 1.29e metadata, skipping
>>>> >
>>>> > It looks like the pg's metadata didn't commit properly.  It doesn't
>>>> > find it on startup, skips the pg, and then crashes below when it
>>>>tries
>>>> > to create it and the collection already exists.
>>>> >
>>>> > Are there any changes applied on top of upstream filestore?  Also,
>>>>is
>>>> > this reproducible on a later version of the code?
>>>> >
>>>> > > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs
>>>>opened
>>>> > > 158 pgs
>>>> > > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405
>>>>log_to_monitors
>>>> > > {default=true}
>>>> > > 2016-01-04 10:46:16.702999 7fad273be700  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
>>>> > > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0,
>>>> > > counting from 0)
>>>> > > 2016-01-04 10:46:16.703014 7fad273be700  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
>>>> > > 2016-01-04 10:46:16.703017 7fad273be700  0
>>>> > filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
>>>> > > {
>>>> > >     "ops": [
>>>> > >         {
>>>> > >             "op_num": 0,
>>>> > >             "op_name": "mkcoll",
>>>> > >             "collection": "1.29e_head"
>>>> > >         },
>>>> > >         {
>>>> > >             "op_num": 1,
>>>> > >             "op_name": "coll_hint",
>>>> > >             "collection": "1.29e_head",
>>>> > >             "type": 1,
>>>> > >             "pg_num": 800,
>>>> > >             "expected_num_objects": 0
>>>> > >         },
>>>> > >         {
>>>> > >             "op_num": 2,
>>>> > >             "op_name": "touch",
>>>> > >             "collection": "1.29e_head",
>>>> > >             "oid": "1\/0000029e\/\/head"
>>>> > >         },
>>>> > >         {
>>>> > >             "op_num": 3,
>>>> > >             "op_name": "omap_setkeys",
>>>> > >             "collection": "1.29e_head",
>>>> > >             "oid": "1\/0000029e\/\/head",
>>>> > >             "attr_lens": {
>>>> > >                 "_infover": 1
>>>> > >             }
>>>> > >         },
>>>> > >         {
>>>> > >             "op_num": 4,
>>>> > >             "op_name": "touch",
>>>> > >             "collection": "1.29e_head",
>>>> > >             "oid": "1\/0000029e\/\/head"
>>>> > >         },
>>>> > >         {
>>>> > >             "op_num": 5,
>>>> > >             "op_name": "omap_setkeys",
>>>> > >             "collection": "1.29e_head",
>>>> > >             "oid": "1\/0000029e\/\/head",
>>>> > >             "attr_lens": {
>>>> > >                 "_biginfo": 196,
>>>> > >                 "_epoch": 4,
>>>> > >                 "_info": 847,
>>>> > >                 "can_rollback_to": 12,
>>>> > >                 "rollback_info_trimmed_to": 12
>>>> > >             }
>>>> > >         }
>>>> > >     ]
>>>> > > }
>>>> > >
>>>> > > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
>>>> > > function 'unsigned int
>>>> > > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t,
>>>>int,
>>>> > > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
>>>> > > 10:46:16.703103
>>>> > > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
>>>> > >
>>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>> > > const*)+0x8b) [0x7fad39846a6b]
>>>> > >  2: (FileStore::_do_transaction(ObjectStore::Transaction&,
>>>>unsigned
>>>> > > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
>>>> > >  3:
>>>> > > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
>>>> > > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
>>>> > > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
>>>> > >  4: (FileStore::_do_op(FileStore::OpSequencer*,
>>>> > > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
>>>> > >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>>>> > > [0x7fad398384e6]
>>>> > >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
>>>> > >  7: (()+0x8182) [0x7fad38609182]
>>>> > >  8: (clone()+0x6d) [0x7fad367fc47d]
>>>> > > <snip>
>>>> > >
>>>> > >  On the reboot, because of the journal reply, we didn't see any
>>>> > > transaction
>>>> > dump issues this time, but we are seeing the following problem.
>>>> > >
>>>> > >  <snip>
>>>> > > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
>>>> > > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
>>>> > 9488
>>>> > > 2016-01-04 10:47:09.310055 7f8190a3c800  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
>>>> > > 2016-01-04 10:47:09.310379 7f8190a3c800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
>>>> > > 2016-01-04 10:47:09.310384 7f8190a3c800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
>>>> > > config option
>>>> > > 2016-01-04 10:47:09.310398 7f8190a3c800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > splice is supported
>>>> > > 2016-01-04 10:47:09.310869 7f8190a3c800  0
>>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
>>>> > > 2016-01-04 10:47:09.310935 7f8190a3c800  0
>>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
>>>> > > extsize is supported and your kernel >= 3.5
>>>> > > 2016-01-04 10:47:09.322795 7f8190a3c800  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
>>>> > > journal
>>>> > > mode: checkpoint is not enabled
>>>> > > 2016-01-04 10:47:09.322828 7f8190a3c800  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
>>>> > > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
>>>> > > 2016-01-04 10:47:09.327861 7f8183ee0700  0
>>>> > > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
>>>> > > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
>>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
>>>> > > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
>>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
>>>> > > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
>>>> > > features 1107558400, adjusting msgr requires for clients
>>>> > > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
>>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
>>>> > > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
>>>> > > features 1107558400, adjusting msgr requires for osds
>>>> > > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
>>>> > > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs
>>>>opened
>>>> > > 159 pgs
>>>> > > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410
>>>>log_to_monitors
>>>> > > {default=true}
>>>> > > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with
>>>>init,
>>>> > > starting boot process
>>>> > > 2016-01-04 10:47:14.117463 7f817d1f3700  0 --
>>>> > > 10.242.43.141:6825/9488
>>>> > > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0
>>>> > > >> pgs=0
>>>> > > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0
>>>>state
>>>> > > connecting
>>>> > > 2016-01-04 10:47:15.649791 7f812eefe700  0 --
>>>> > > 10.242.43.141:6825/9488
>>>> > > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0
>>>>pgs=0
>>>> > > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0
>>>>state
>>>> > > connecting
>>>> > > 2016-01-04 10:47:15.649826 7f812edfd700  0 --
>>>> > > 10.242.43.141:6825/9488
>>>> > > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0
>>>> > > >> pgs=0
>>>> > > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0
>>>>state
>>>> > > connecting
>>>> > > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In
>>>>function
>>>> > > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
>>>> > > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
>>>> > > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
>>>> > > log.rbegin())
>>>> > >
>>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
>>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
>>>> > > const*)+0x8b) [0x7f8190564a6b]
>>>> > >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
>>>> > > [0x7f8190173971]
>>>> > >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
>>>> > > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
>>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
>>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
>>>> > > 
>>>>(boost::statechart::history_mode)0>::react_impl(boost::statechart::e
>>>> > > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
>>>> > >  4:
>>>> > >
>>>> (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
>>>> > > , PG::RecoveryState::Initial, std::allocator<void>,
>>>> > > 
>>>>boost::statechart::null_exception_translator>::send_event(boost::sta
>>>> > > te chart::event_base const&)+0x5b) [0x7f8190197bab]
>>>> > >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
>>>> > > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
>>>> > >  6: (OSD::process_peering_events(std::list<PG*,
>>>>std::allocator<PG*>
>>>> > > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
>>>> > >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
>>>> > > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
>>>> > >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
>>>> > > [0x7f81905564e6]
>>>> > >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
>>>> > >  10: (()+0x8182) [0x7f818f327182]
>>>> > >  11: (clone()+0x6d) [0x7f818d51a47d]
>>>> > >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
>>>> > > needed
>>>> > to interpret this.
>>>> > > <snip>
>>>> > >
>>>> > >  Whenever we restart the osd, we are hitting the problem and not
>>>> > > able to
>>>> > get the osd up. Tried pg repair, which bails saying primary osd
>>>>down.
>>>> > >  Are there any repair techniques available to get this corrected?
>>>> >
>>>> > Most likely deleting the pg directory will be sufficient to clear it
>>>>up.
>>>> >
>>>> > sage
>>>> 
>>>> --
>>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel"
>>>>in the
>>>> body of a message to majordomo@vger.kernel.org More majordomo info at
>>>> http://vger.kernel.org/majordomo-info.html
>>>--
>>>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>>the body of a message to majordomo@vger.kernel.org
>>>More majordomo info at  http://vger.kernel.org/majordomo-info.html
>>
>>--
>>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
>>the body of a message to majordomo@vger.kernel.org
>>More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

Re: OSD crash when one of the PGs have problem

[Sage Weil]

On Mon, 1 Feb 2016, Evgeniy Firsov wrote:
> I filed a PR which fixes the bug: https://github.com/ceph/ceph/pull/7470
> 
> But there are at least two questions which need clarification:
> 1. I expect, and my tests confirm so far, that FileStore::_touch call is
> NOT used on fast path. But there is an opinion that it might.

The depends entirely on the librados client... they might send a 'touch' 
op and expect it to be fast.  We shouldn't do the fdcache.clear() in the 
general case.  Note that simply restarting the OSD clears it, and it is 
pretty unlikely we'll have a directory deleted and repaired on a running 
ceph-osd daemon in quick enough succession to be in the cache anyway.

> 2. Does the fix need write_if_dirty part, which writes metadata besides
> version info, such as epoch? The question is because PG::_init doesn't
> have this part and writes version info only.

It's looks right as-is to me!

sage


> 
> 
> Thank you.
> 
> On 1/20/16, 5:07 PM, "Evgeniy Firsov" <Evgeniy.Firsov@sandisk.com> wrote:
> 
> >The same test case fail with stock Jewel branch too.
> >
> >On 1/20/16, 5:02 PM, "ceph-devel-owner@vger.kernel.org on behalf of
> >Evgeniy Firsov" <ceph-devel-owner@vger.kernel.org on behalf of
> >Evgeniy.Firsov@sandisk.com> wrote:
> >
> >>I am able to reproduce the problem even with current, unmodified master.
> >>
> >>Test case:
> >>1. Start 2 OSDs, 8 PGs, pool size = 2
> >>2. Run write workload for some time.
> >>3. Stop workload
> >>4. rm -rf dev/osd0/current/0.2_head/*
> >>5. ceph osd scrub 0
> >>6. ceph pg repair 0.2
> >>7. Restart OSD.
> >>8. Get "error (17) File exists not handled on operation"
> >>
> >>On 1/20/16, 9:30 AM, "ceph-devel-owner@vger.kernel.org on behalf of
> >>Varada
> >>Kari" <ceph-devel-owner@vger.kernel.org on behalf of
> >>Varada.Kari@sandisk.com> wrote:
> >>
> >>>Somnath,
> >>>
> >>>There are no xfs errors here.
> >>>
> >>>Varada
> >>>
> >>>> -----Original Message-----
> >>>> From: Somnath Roy
> >>>> Sent: Wednesday, January 20, 2016 10:34 PM
> >>>> To: Varada Kari <Varada.Kari@sandisk.com>; Sage Weil
> >>>> <sage@newdream.net>
> >>>> Cc: ceph-devel@vger.kernel.org
> >>>> Subject: RE: OSD crash when one of the PGs have problem
> >>>> 
> >>>> You are saying xfs is throwing errors in the dmesg, so, this could be
> >>>>a
> >>>>reason
> >>>> why ceph is not able to read PG metadata for leveldb->xfs, isn't it ?
> >>>> 
> >>>> Thanks & Regards
> >>>> Somnath
> >>>> 
> >>>> -----Original Message-----
> >>>> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-
> >>>> owner@vger.kernel.org] On Behalf Of Varada Kari
> >>>> Sent: Wednesday, January 20, 2016 8:02 AM
> >>>> To: Sage Weil
> >>>> Cc: ceph-devel@vger.kernel.org
> >>>> Subject: RE: OSD crash when one of the PGs have problem
> >>>> 
> >>>> Yes Sage. Applied Somnath's write path changes on top the jewel branch
> >>>> (two weeks old) and jemalloc. Haven't tried with latest changes
> >>>>though.
> >>>>With
> >>>> the same code, we are not able hit this issue again, when retried.
> >>>>Not
> >>>>sure if
> >>>> we are hitting any race in committing change here.
> >>>> 
> >>>> Varada
> >>>> 
> >>>> > -----Original Message-----
> >>>> > From: Sage Weil [mailto:sage@newdream.net]
> >>>> > Sent: Wednesday, January 20, 2016 9:04 PM
> >>>> > To: Varada Kari <Varada.Kari@sandisk.com>
> >>>> > Cc: ceph-devel@vger.kernel.org
> >>>> > Subject: Re: OSD crash when one of the PGs have problem
> >>>> >
> >>>> > On Wed, 20 Jan 2016, Varada Kari wrote:
> >>>> > > Hi all,
> >>>> > >
> >>>> > >
> >>>> > > Sorry for the long mail. Wanted to give more information in the
> >>>>mail.
> >>>> > >
> >>>> > > We are seeing an issue in our test cluster when an osd is stopped
> >>>> > > gracefully
> >>>> > and restarted after the maintenance.
> >>>> > > Please note, haven't used any no out option for the cluster.
> >>>> > > After the reboot, not able to one of the PG, and no drive problems
> >>>> > > are
> >>>> > read errors are logged in dmesg/kernel logs. But we are not able to
> >>>> > read the head object of PG for some reason, sorry of lack of logs we
> >>>> > are running with debugs with 0/0 and build with jemalloc enabled for
> >>>> > testing. Hence a customized version.
> >>>> > >
> >>>> > > <snip>
> >>>> > > 2015-12-27 13:14:39.684307 7f5ae47ff700 -1 osd.1 405 *** Got
> >>>>signal
> >>>> > > Terminated ***
> >>>> > > 2015-12-27 13:14:39.779307 7f5ae47ff700  0 osd.1 405
> >>>>prepare_to_stop
> >>>> > > telling mon we are shutting down
> >>>> > > 2016-01-04 10:46:13.966959 7fad39d1e800  0 ceph version
> >>>> > > 10.0.0(7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process
> >>>>ceph-osd,
> >>>> > > pid 6975
> >>>> > > 2016-01-04 10:46:14.007516 7fad39d1e800  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> >>>> > > 2016-01-04 10:46:14.008565 7fad39d1e800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> >>>> > > 2016-01-04 10:46:14.008573 7fad39d1e800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
> >>>> > > config option
> >>>> > > 2016-01-04 10:46:14.008601 7fad39d1e800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > splice is supported
> >>>> > > 2016-01-04 10:46:14.008882 7fad39d1e800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
> >>>> > > 2016-01-04 10:46:14.008921 7fad39d1e800  0
> >>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > extsize is supported and your kernel >= 3.5
> >>>> > > 2016-01-04 10:46:14.339253 7fad39d1e800  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
> >>>> > > journal
> >>>> > > mode: checkpoint is not enabled
> >>>> > > 2016-01-04 10:46:14.532510 7fad39d1e800  0 <cls>
> >>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
> >>>> > > 2016-01-04 10:46:14.534168 7fad39d1e800  0 <cls>
> >>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> >>>> > > 2016-01-04 10:46:14.535626 7fad39d1e800  0 osd.1 405 crush map has
> >>>> > > features 1107558400, adjusting msgr requires for clients
> >>>> > > 2016-01-04 10:46:14.535634 7fad39d1e800  0 osd.1 405 crush map has
> >>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
> >>>> > > 2016-01-04 10:46:14.535639 7fad39d1e800  0 osd.1 405 crush map has
> >>>> > > features 1107558400, adjusting msgr requires for osds
> >>>> > > 2016-01-04 10:46:14.954060 7fad39d1e800  0 osd.1 405 load_pgs
> >>>> > > 2016-01-04 10:46:15.634892 7fad39d1e800 -1 osd.1 405 load_pgs
> >>>>unable
> >>>> > > to peek at 1.29e metadata, skipping
> >>>> >
> >>>> > It looks like the pg's metadata didn't commit properly.  It doesn't
> >>>> > find it on startup, skips the pg, and then crashes below when it
> >>>>tries
> >>>> > to create it and the collection already exists.
> >>>> >
> >>>> > Are there any changes applied on top of upstream filestore?  Also,
> >>>>is
> >>>> > this reproducible on a later version of the code?
> >>>> >
> >>>> > > 2016-01-04 10:46:16.334253 7fad39d1e800  0 osd.1 405 load_pgs
> >>>>opened
> >>>> > > 158 pgs
> >>>> > > 2016-01-04 10:46:16.336960 7fad39d1e800 -1 osd.1 405
> >>>>log_to_monitors
> >>>> > > {default=true}
> >>>> > > 2016-01-04 10:46:16.702999 7fad273be700  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1)  error (17) File exists not
> >>>> > > handled on operation 0x7fad2c83f1c0 (201318686.0.0, or op 0,
> >>>> > > counting from 0)
> >>>> > > 2016-01-04 10:46:16.703014 7fad273be700  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) unexpected error code
> >>>> > > 2016-01-04 10:46:16.703017 7fad273be700  0
> >>>> > filestore(/var/lib/ceph/osd/ceph-1)  transaction dump:
> >>>> > > {
> >>>> > >     "ops": [
> >>>> > >         {
> >>>> > >             "op_num": 0,
> >>>> > >             "op_name": "mkcoll",
> >>>> > >             "collection": "1.29e_head"
> >>>> > >         },
> >>>> > >         {
> >>>> > >             "op_num": 1,
> >>>> > >             "op_name": "coll_hint",
> >>>> > >             "collection": "1.29e_head",
> >>>> > >             "type": 1,
> >>>> > >             "pg_num": 800,
> >>>> > >             "expected_num_objects": 0
> >>>> > >         },
> >>>> > >         {
> >>>> > >             "op_num": 2,
> >>>> > >             "op_name": "touch",
> >>>> > >             "collection": "1.29e_head",
> >>>> > >             "oid": "1\/0000029e\/\/head"
> >>>> > >         },
> >>>> > >         {
> >>>> > >             "op_num": 3,
> >>>> > >             "op_name": "omap_setkeys",
> >>>> > >             "collection": "1.29e_head",
> >>>> > >             "oid": "1\/0000029e\/\/head",
> >>>> > >             "attr_lens": {
> >>>> > >                 "_infover": 1
> >>>> > >             }
> >>>> > >         },
> >>>> > >         {
> >>>> > >             "op_num": 4,
> >>>> > >             "op_name": "touch",
> >>>> > >             "collection": "1.29e_head",
> >>>> > >             "oid": "1\/0000029e\/\/head"
> >>>> > >         },
> >>>> > >         {
> >>>> > >             "op_num": 5,
> >>>> > >             "op_name": "omap_setkeys",
> >>>> > >             "collection": "1.29e_head",
> >>>> > >             "oid": "1\/0000029e\/\/head",
> >>>> > >             "attr_lens": {
> >>>> > >                 "_biginfo": 196,
> >>>> > >                 "_epoch": 4,
> >>>> > >                 "_info": 847,
> >>>> > >                 "can_rollback_to": 12,
> >>>> > >                 "rollback_info_trimmed_to": 12
> >>>> > >             }
> >>>> > >         }
> >>>> > >     ]
> >>>> > > }
> >>>> > >
> >>>> > > 2016-01-04 10:46:16.731323 7fad273be700 -1 os/FileStore.cc: In
> >>>> > > function 'unsigned int
> >>>> > > FileStore::_do_transaction(ObjectStore::Transaction&, uint64_t,
> >>>>int,
> >>>> > > ThreadPool::TPHandle*)' thread 7fad273be700 time 2016-01-04
> >>>> > > 10:46:16.703103
> >>>> > > os/FileStore.cc: 3017: FAILED assert(0 == "unexpected error")
> >>>> > >
> >>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> >>>> > > const*)+0x8b) [0x7fad39846a6b]
> >>>> > >  2: (FileStore::_do_transaction(ObjectStore::Transaction&,
> >>>>unsigned
> >>>> > > long, int, ThreadPool::TPHandle*)+0xa48) [0x7fad3968bf58]
> >>>> > >  3:
> >>>> > > (FileStore::_do_transactions(std::list<ObjectStore::Transaction*,
> >>>> > > std::allocator<ObjectStore::Transaction*> >&, unsigned long,
> >>>> > > ThreadPool::TPHandle*)+0x64) [0x7fad396932a4]
> >>>> > >  4: (FileStore::_do_op(FileStore::OpSequencer*,
> >>>> > > ThreadPool::TPHandle&)+0x2c3) [0x7fad39693583]
> >>>> > >  5: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> >>>> > > [0x7fad398384e6]
> >>>> > >  6: (ThreadPool::WorkThread::entry()+0x10) [0x7fad398393b0]
> >>>> > >  7: (()+0x8182) [0x7fad38609182]
> >>>> > >  8: (clone()+0x6d) [0x7fad367fc47d]
> >>>> > > <snip>
> >>>> > >
> >>>> > >  On the reboot, because of the journal reply, we didn't see any
> >>>> > > transaction
> >>>> > dump issues this time, but we are seeing the following problem.
> >>>> > >
> >>>> > >  <snip>
> >>>> > > 2016-01-04 10:47:09.302400 7f8190a3c800  0 ceph version 10.0.0
> >>>> > > (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5), process ceph-osd, pid
> >>>> > 9488
> >>>> > > 2016-01-04 10:47:09.310055 7f8190a3c800  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) backend xfs (magic 0x58465342)
> >>>> > > 2016-01-04 10:47:09.310379 7f8190a3c800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > FIEMAP ioctl is disabled via 'filestore fiemap' config option
> >>>> > > 2016-01-04 10:47:09.310384 7f8190a3c800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > SEEK_DATA/SEEK_HOLE is disabled via 'filestore seek data hole'
> >>>> > > config option
> >>>> > > 2016-01-04 10:47:09.310398 7f8190a3c800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > splice is supported
> >>>> > > 2016-01-04 10:47:09.310869 7f8190a3c800  0
> >>>> > > genericfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > syncfs(2) syscall fully supported (by glibc and kernel)
> >>>> > > 2016-01-04 10:47:09.310935 7f8190a3c800  0
> >>>> > > xfsfilestorebackend(/var/lib/ceph/osd/ceph-1) detect_features:
> >>>> > > extsize is supported and your kernel >= 3.5
> >>>> > > 2016-01-04 10:47:09.322795 7f8190a3c800  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) mount: enabling WRITEAHEAD
> >>>> > > journal
> >>>> > > mode: checkpoint is not enabled
> >>>> > > 2016-01-04 10:47:09.322828 7f8190a3c800  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) disabling wbthrottle(
> >>>> > > filestore_wbthrottle_enable = 0 ) since do_fast_sync is enabled
> >>>> > > 2016-01-04 10:47:09.327861 7f8183ee0700  0
> >>>> > > filestore(/var/lib/ceph/osd/ceph-1) ## Fast sync is enabled ##
> >>>> > > 2016-01-04 10:47:09.392333 7f8190a3c800  0 <cls>
> >>>> > > cls/hello/cls_hello.cc:305: loading cls_hello
> >>>> > > 2016-01-04 10:47:09.393968 7f8190a3c800  0 <cls>
> >>>> > > cls/cephfs/cls_cephfs.cc:136: loading cephfs_size_scan
> >>>> > > 2016-01-04 10:47:09.394528 7f8190a3c800  0 osd.1 410 crush map has
> >>>> > > features 1107558400, adjusting msgr requires for clients
> >>>> > > 2016-01-04 10:47:09.394536 7f8190a3c800  0 osd.1 410 crush map has
> >>>> > > features 1107558400 was 8705, adjusting msgr requires for mons
> >>>> > > 2016-01-04 10:47:09.394552 7f8190a3c800  0 osd.1 410 crush map has
> >>>> > > features 1107558400, adjusting msgr requires for osds
> >>>> > > 2016-01-04 10:47:09.458215 7f8190a3c800  0 osd.1 410 load_pgs
> >>>> > > 2016-01-04 10:47:10.935841 7f8190a3c800  0 osd.1 410 load_pgs
> >>>>opened
> >>>> > > 159 pgs
> >>>> > > 2016-01-04 10:47:10.936696 7f8190a3c800 -1 osd.1 410
> >>>>log_to_monitors
> >>>> > > {default=true}
> >>>> > > 2016-01-04 10:47:13.942139 7f8190a3c800  0 osd.1 410 done with
> >>>>init,
> >>>> > > starting boot process
> >>>> > > 2016-01-04 10:47:14.117463 7f817d1f3700  0 --
> >>>> > > 10.242.43.141:6825/9488
> >>>> > > >> 10.242.43.143:6821/40041 pipe(0x7f8141c0e000 sd=83 :6825 s=0
> >>>> > > >> pgs=0
> >>>> > > cs=0 l=0 c=0x7f8141c14180).accept connect_seq 0 vs existing 0
> >>>>state
> >>>> > > connecting
> >>>> > > 2016-01-04 10:47:15.649791 7f812eefe700  0 --
> >>>> > > 10.242.43.141:6825/9488
> >>>> > > >> 10.242.43.141:6801/6106 pipe(0x7f8141c0e000 sd=93 :6825 s=0
> >>>>pgs=0
> >>>> > > cs=0 l=0 c=0x7f8141c14480).accept connect_seq 0 vs existing 0
> >>>>state
> >>>> > > connecting
> >>>> > > 2016-01-04 10:47:15.649826 7f812edfd700  0 --
> >>>> > > 10.242.43.141:6825/9488
> >>>> > > >> 10.242.43.141:6821/6925 pipe(0x7f8141c1c000 sd=137 :6825 s=0
> >>>> > > >> pgs=0
> >>>> > > cs=0 l=0 c=0x7f8141c14780).accept connect_seq 0 vs existing 0
> >>>>state
> >>>> > > connecting
> >>>> > > 2016-01-04 10:47:15.924059 7f81527ed700 -1 osd/PGLog.h: In
> >>>>function
> >>>> > > 'void PGLog::IndexedLog::claim_log_and_clear_rollback_info(const
> >>>> > > pg_log_t&)' thread 7f81527ed700 time 2016-01-04 10:47:15.906256
> >>>> > > osd/PGLog.h: 89: FAILED assert(rollback_info_trimmed_to_riter ==
> >>>> > > log.rbegin())
> >>>> > >
> >>>> > >  ceph version 10.0.0 (7eb76e73fd5b6e990ceba9d45e5a1fec92145fa5)
> >>>> > >  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char
> >>>> > > const*)+0x8b) [0x7f8190564a6b]
> >>>> > >  2: (PG::RecoveryState::Stray::react(PG::MLogRec const&)+0xa21)
> >>>> > > [0x7f8190173971]
> >>>> > >  3: (boost::statechart::simple_state<PG::RecoveryState::Stray,
> >>>> > > PG::RecoveryState::Started, boost::mpl::list<mpl_::na, mpl_::na,
> >>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> >>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na,
> >>>> > > mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na, mpl_::na>,
> >>>> > > 
> >>>>(boost::statechart::history_mode)0>::react_impl(boost::statechart::e
> >>>> > > ve nt_base const&, void const*)+0x1f4) [0x7f81901ad584]
> >>>> > >  4:
> >>>> > >
> >>>> (boost::statechart::state_machine<PG::RecoveryState::RecoveryMachine
> >>>> > > , PG::RecoveryState::Initial, std::allocator<void>,
> >>>> > > 
> >>>>boost::statechart::null_exception_translator>::send_event(boost::sta
> >>>> > > te chart::event_base const&)+0x5b) [0x7f8190197bab]
> >>>> > >  5: (PG::handle_peering_event(std::shared_ptr<PG::CephPeeringEvt>,
> >>>> > > PG::RecoveryCtx*)+0x1ce) [0x7f81901412ce]
> >>>> > >  6: (OSD::process_peering_events(std::list<PG*,
> >>>>std::allocator<PG*>
> >>>> > > > const&, ThreadPool::TPHandle&)+0x267) [0x7f81900cb677]
> >>>> > >  7: (OSD::PeeringWQ::_process(std::list<PG*, std::allocator<PG*> >
> >>>> > > const&, ThreadPool::TPHandle&)+0x18) [0x7f819010fed8]
> >>>> > >  8: (ThreadPool::worker(ThreadPool::WorkThread*)+0xa56)
> >>>> > > [0x7f81905564e6]
> >>>> > >  9: (ThreadPool::WorkThread::entry()+0x10) [0x7f81905573b0]
> >>>> > >  10: (()+0x8182) [0x7f818f327182]
> >>>> > >  11: (clone()+0x6d) [0x7f818d51a47d]
> >>>> > >  NOTE: a copy of the executable, or `objdump -rdS <executable>` is
> >>>> > > needed
> >>>> > to interpret this.
> >>>> > > <snip>
> >>>> > >
> >>>> > >  Whenever we restart the osd, we are hitting the problem and not
> >>>> > > able to
> >>>> > get the osd up. Tried pg repair, which bails saying primary osd
> >>>>down.
> >>>> > >  Are there any repair techniques available to get this corrected?
> >>>> >
> >>>> > Most likely deleting the pg directory will be sufficient to clear it
> >>>>up.
> >>>> >
> >>>> > sage
> >>>> 
> >>>> --
> >>>> To unsubscribe from this list: send the line "unsubscribe ceph-devel"
> >>>>in the
> >>>> body of a message to majordomo@vger.kernel.org More majordomo info at
> >>>> http://vger.kernel.org/majordomo-info.html
> >>>--
> >>>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> >>>the body of a message to majordomo@vger.kernel.org
> >>>More majordomo info at  http://vger.kernel.org/majordomo-info.html
> >>
> >>--
> >>To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> >>the body of a message to majordomo@vger.kernel.org
> >>More majordomo info at  http://vger.kernel.org/majordomo-info.html
> >
> 
>