Bug #9768
Updated by Loïc Dachary over 9 years ago
<pre> $ ceph --version ceph version 0.80.6 (f93610a4421cb670b08e974c6550ee715ac528ae) $ ceph-disk prepare --mkfs ext4 /dev/sdc $ ps fauwwwx | grep mkfs root 366 0.0 0.0 40672 1548 ? Ss Oct10 0:00 udevd --daemon root 21963 0.0 0.0 40644 1360 ? S 13:57 0:00 \_ udevd --daemon root 21988 0.0 0.0 4308 636 ? S 13:57 0:00 | \_ /bin/sh /usr/sbin/ceph-disk-activate /dev/sdc1 root 21991 0.2 0.0 48736 9968 ? S 13:57 0:00 | \_ /usr/bin/python /usr/sbin/ceph-disk activate /dev/sdc1 root 22082 0.0 0.0 192040 8820 ? Sl 13:57 0:00 | \_ /usr/bin/ceph-osd --cluster ceph --mkfs --mkkey -i 6 --monmap /var/lib/ceph/tmp/mnt.5mDa2j/activate.monmap --osd-data /var/lib/ceph/tmp/mnt.5mDa2j --osd-journal /var/lib/ceph/tmp/mnt.5mDa2j/journal --osd-uuid 0b27732f-bee9-4212-9395-bad5eaeffc37 --keyring /var/lib/ceph/tmp/mnt.5mDa2j/keyring </pre> The log with debug_filestore=20 <pre> 2014-10-14 14:01:41.906165 7fbacf2077c0 0 ceph version 0.80.6 (f93610a4421cb670b08e974c6550ee715ac528ae), process ceph-osd, pid 24349 2014-10-14 14:01:41.908424 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) dump_stop 2014-10-14 14:01:41.908750 7fbacf2077c0 10 -- :/0 ready :/0 2014-10-14 14:01:41.908783 7fbacf2077c0 1 -- :/0 messenger.start 2014-10-14 14:01:41.908817 7fbacf2077c0 10 -- :/24349 shutdown :/24349 2014-10-14 14:01:41.908822 7fbacf2077c0 1 -- :/24349 mark_down_all 2014-10-14 14:01:41.908830 7fbacf2077c0 10 -- :/24349 wait: waiting for dispatch queue 2014-10-14 14:01:41.908841 7fbac9735700 10 -- :/24349 reaper_entry start 2014-10-14 14:01:41.908863 7fbac9735700 10 -- :/24349 reaper 2014-10-14 14:01:41.908868 7fbac9735700 10 -- :/24349 reaper done 2014-10-14 14:01:41.908867 7fbacf2077c0 10 -- :/24349 wait: dispatch queue is stopped 2014-10-14 14:01:41.908882 7fbac9735700 10 -- :/24349 reaper_entry done 2014-10-14 14:01:41.908953 7fbacf2077c0 10 -- :/24349 wait: closing pipes 2014-10-14 14:01:41.908975 7fbacf2077c0 10 -- :/24349 reaper 2014-10-14 14:01:41.908978 7fbacf2077c0 10 -- :/24349 reaper done 2014-10-14 14:01:41.908980 7fbacf2077c0 10 -- :/24349 wait: waiting for pipes to close 2014-10-14 14:01:41.908982 7fbacf2077c0 10 -- :/24349 wait: done. 2014-10-14 14:01:41.908983 7fbacf2077c0 1 -- :/24349 shutdown complete. 2014-10-14 14:01:41.909008 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs in /var/lib/ceph/tmp/mnt.CDjohX 2014-10-14 14:01:41.909030 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs fsid is already set to 0d11281e-1c65-4a45-952c-c0523675b15f 2014-10-14 14:01:41.968445 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) leveldb db exists/created 2014-10-14 14:01:41.968474 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) open_journal at /var/lib/ceph/tmp/mnt.CDjohX/journal 2014-10-14 14:01:41.970890 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 11: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1 2014-10-14 14:01:41.971213 7fbacf2077c0 -1 journal check: ondisk fsid 0b27732f-bee9-4212-9395-bad5eaeffc37 doesn't match expected 0d11281e-1c65-4a45-952c-c0523675b15f, invalid (someone else's?) journal 2014-10-14 14:01:41.973309 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 11: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1 2014-10-14 14:01:41.983002 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkjournal created journal on /var/lib/ceph/tmp/mnt.CDjohX/journal 2014-10-14 14:01:41.983048 7fbacf2077c0 1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mkfs done in /var/lib/ceph/tmp/mnt.CDjohX 2014-10-14 14:01:41.983064 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) basedir /var/lib/ceph/tmp/mnt.CDjohX journal /var/lib/ceph/tmp/mnt.CDjohX/journal 2014-10-14 14:01:41.983086 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount fsid is 0d11281e-1c65-4a45-952c-c0523675b15f 2014-10-14 14:01:41.990817 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: FIEMAP ioctl is supported and appears to work 2014-10-14 14:01:41.990833 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option 2014-10-14 14:01:41.996025 7fbacf2077c0 0 genericfilestorebackend(/var/lib/ceph/tmp/mnt.CDjohX) detect_features: syncfs(2) syscall fully supported (by glibc and kernel) 2014-10-14 14:01:42.014473 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) limited size xattrs 2014-10-14 14:01:42.014581 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount op_seq is 1 2014-10-14 14:01:42.034149 7fbacf2077c0 20 filestore (init)dbobjectmap: seq is 1 2014-10-14 14:01:42.034177 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) open_journal at /var/lib/ceph/tmp/mnt.CDjohX/journal 2014-10-14 14:01:42.034206 7fbacf2077c0 0 filestore(/var/lib/ceph/tmp/mnt.CDjohX) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled 2014-10-14 14:01:42.034212 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) list_collections 2014-10-14 14:01:42.034321 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000 2014-10-14 14:01:42.036454 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 17: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1 2014-10-14 14:01:42.038633 7fbacf2077c0 1 journal _open /var/lib/ceph/tmp/mnt.CDjohX/journal fd 17: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1 2014-10-14 14:01:42.038926 7fbacf2077c0 15 filestore(/var/lib/ceph/tmp/mnt.CDjohX) read meta/23c2fcde/osd_superblock/0//-1 0~0 2014-10-14 14:01:42.038999 7fbacf2077c0 -1 filestore(/var/lib/ceph/tmp/mnt.CDjohX) could not find 23c2fcde/osd_superblock/0//-1 in index: (2) No such file or directory 2014-10-14 14:01:42.039019 7fbacf2077c0 10 filestore(/var/lib/ceph/tmp/mnt.CDjohX) FileStore::read(meta/23c2fcde/osd_superblock/0//-1) open error: (2) No such file or directory 2014-10-14 14:01:42.039068 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) queue_transactions new osr(default 0x7fbad228cb98)/0x7fbad228cb98 2014-10-14 14:01:42.039082 7fbacf2077c0 5 filestore(/var/lib/ceph/tmp/mnt.CDjohX) queue_transactions (writeahead) 2 0x7fff05f7dd80 2014-10-14 14:01:47.034856 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000534 2014-10-14 14:01:47.034895 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000 2014-10-14 14:01:52.035013 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000115 2014-10-14 14:01:52.035056 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000 2014-10-14 14:01:57.035129 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry woke after 5.000073 2014-10-14 14:01:57.035161 7fbac9f36700 20 filestore(/var/lib/ceph/tmp/mnt.CDjohX) sync_entry waiting for max_interval 5.000000 .... </pre> stack trace <pre> Thread 14 (Thread 0x7f3177cd8700 (LWP 23461)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b67413b in ceph::log::Log::entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3177cd8700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 13 (Thread 0x7f3176d4e700 (LWP 23462)): #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238 #1 0x00007f317b74021b in CephContextServiceThread::entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3176d4e700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 12 (Thread 0x7f317654d700 (LWP 23463)): #0 0x00007f3178c370ed in poll () at ../sysdeps/unix/syscall-template.S:81 #1 0x00007f317b726433 in AdminSocket::entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f317654d700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 11 (Thread 0x7f317554b700 (LWP 23470)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b595dbf in WBThrottle::get_next_should_flush(boost::tuples::tuple<ghobject_t, std::tr1::shared_ptr<FDCache::FD>, WBThrottle::PendingWB, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type, boost::tuples::null_type>*) () #2 0x00007f317b596c83 in WBThrottle::entry() () #3 0x00007f317a4dc0a4 in start_thread (arg=0x7f317554b700) at pthread_create.c:309 #4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 10 (Thread 0x7f3175d4c700 (LWP 23471)): #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238 #1 0x00007f317b51fc0d in Cond::WaitInterval(CephContext*, Mutex&, utime_t) () #2 0x00007f317b4ea490 in FileStore::sync_entry() () #3 0x00007f317b52076d in FileStore::SyncThread::entry() () #4 0x00007f317a4dc0a4 in start_thread (arg=0x7f3175d4c700) at pthread_create.c:309 #5 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 9 (Thread 0x7f3174d4a700 (LWP 23476)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b613286 in FileJournal::write_thread_entry() () #2 0x00007f317b51ee8d in FileJournal::Writer::entry() () #3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3174d4a700) at pthread_create.c:309 #4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 8 (Thread 0x7f3174549700 (LWP 23477)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b2bee06 in Cond::Wait(Mutex&) () #2 0x00007f317b610eea in FileJournal::write_finish_thread_entry() () #3 0x00007f317b51efad in FileJournal::WriteFinisher::entry() () #4 0x00007f317a4dc0a4 in start_thread (arg=0x7f3174549700) at pthread_create.c:309 #5 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 7 (Thread 0x7f3173d48700 (LWP 23478)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3173d48700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 6 (Thread 0x7f3173547700 (LWP 23479)): #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238 #1 0x00007f317b71cb32 in ThreadPool::worker(ThreadPool::WorkThread*) () #2 0x00007f317b71dd90 in ThreadPool::WorkThread::entry() () #3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3173547700) at pthread_create.c:309 #4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 5 (Thread 0x7f3172d46700 (LWP 23480)): #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238 #1 0x00007f317b71cb32 in ThreadPool::worker(ThreadPool::WorkThread*) () #2 0x00007f317b71dd90 in ThreadPool::WorkThread::entry() () #3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3172d46700) at pthread_create.c:309 #4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 4 (Thread 0x7f3172545700 (LWP 23481)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3172545700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 3 (Thread 0x7f3171d44700 (LWP 23482)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b6625f8 in Finisher::finisher_thread_entry() () #2 0x00007f317a4dc0a4 in start_thread (arg=0x7f3171d44700) at pthread_create.c:309 #3 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 2 (Thread 0x7f3171543700 (LWP 23483)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b717d84 in SafeTimer::timer_thread() () #2 0x00007f317b71892d in SafeTimerThread::entry() () #3 0x00007f317a4dc0a4 in start_thread (arg=0x7f3171543700) at pthread_create.c:309 #4 0x00007f3178c3fc2d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 Thread 1 (Thread 0x7f317b01d7c0 (LWP 23460)): #0 pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 #1 0x00007f317b35bbf4 in ObjectStore::apply_transactions(ObjectStore::Sequencer*, std::list<ObjectStore::Transaction*, std::allocator<ObjectStore::Transaction*> >&, Context*) () #2 0x00007f317b2c0d08 in ObjectStore::apply_transaction(ObjectStore::Transaction&, Context*) () #3 0x00007f317b27374a in OSD::mkfs(CephContext*, ObjectStore*, std::string const&, uuid_d, int) () #4 0x00007f317b24a872 in main () </pre>