Actions
Bug #17691
closedbad backtrace on inode
% Done:
0%
Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Seen this in testing:
http://pulpito.ceph.com/pdonnell-2016-10-25_02:25:11-fs:recovery-master---basic-mira/493889/
2016-10-25T02:38:23.539 INFO:teuthology.orchestra.run.mira012:Running: 'sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 0 ceph --cluster ceph --admin-daemon /var/run/ceph/ceph-mds.b.asok scrub_path / repair recursive' 2016-10-25T02:38:23.665 INFO:tasks.ceph.mds.b.mira012.stderr:2016-10-25 02:38:23.659097 7f7881a5d700 -1 log_channel(cluster) log [ERR] : scrub: inode wrongly marked free: 0x10000000001 2016-10-25T02:38:23.665 INFO:tasks.ceph.mds.b.mira012.stderr:2016-10-25 02:38:23.659131 7f7881a5d700 -1 log_channel(cluster) log [ERR] : inode table repaired for inode: 0x10000000001 2016-10-25T02:38:23.666 INFO:tasks.ceph.mds.b.mira012.stderr:2016-10-25 02:38:23.659583 7f7881a5d700 -1 log_channel(cluster) log [ERR] : scrub: inode wrongly marked free: 0x10000000002 2016-10-25T02:38:23.666 INFO:tasks.ceph.mds.b.mira012.stderr:2016-10-25 02:38:23.659591 7f7881a5d700 -1 log_channel(cluster) log [ERR] : inode table repaired for inode: 0x10000000002 2016-10-25T02:38:23.669 INFO:tasks.ceph.mds.b.mira012.stderr:2016-10-25 02:38:23.663835 7f7881a5d700 -1 mds.0.scrubstack _validate_inode_done scrub error on inode [inode 1 [...2,head] / auth v14 snaprealm=0x558e117d9600 dirtyparent f(v0 m2016-10-25 02:37:59.449168 3=3+0) n(v0 1=0+1) (iversion lock) | request=0 lock=0 dirfrag=1 dirtyparent=1 scrubqueue=0 authpin=0 0x558e119b25e8]: {"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":0,"ondisk_value":"(5)1:[]\/\/","memoryvalue":"(5)1:[]\/\/","error_str":"On-disk backtrace is divergent or newer"},"raw_stats":{"checked":true,"passed":true,"read_ret_val":0,"ondisk_value.dirstat":"f(v0 m2016-10-25 02:37:59.449168 3=3+0)","ondisk_value.rstat":"n(v0 1=0+1)","memory_value.dirrstat":"f(v0 m2016-10-25 02:37:59.449168 3=3+0)","memory_value.rstat":"n(v0 1=0+1)","error_str":""},"return_code":0} 2016-10-25T02:38:23.676 INFO:tasks.cephfs.filesystem:_json_asok output: 2016-10-25T02:38:23.677 DEBUG:tasks.cephfs.cephfs_test_case:No log hits yet, waiting... 2016-10-25T02:38:28.423 INFO:teuthology.orchestra.run.mira012:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf' 2016-10-25T02:38:28.428 INFO:teuthology.orchestra.run.mira075:Running: 'sudo logrotate /etc/logrotate.d/ceph-test.conf' 2016-10-25T02:38:38.695 INFO:teuthology.orchestra.run.mira012.stdout: cluster 3e4479b7-df08-4cc4-92e2-bf1ca289acf3 2016-10-25T02:38:38.695 INFO:teuthology.orchestra.run.mira012.stdout: health HEALTH_OK 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: monmap e1: 1 mons at {a=172.21.3.116:6789/0} 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: election epoch 3, quorum 0 a 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: fsmap e31: 1/1/1 up {0=b=up:active}, 1 up:standby 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: mgr no daemons active 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: osdmap e23: 3 osds: 3 up, 3 in 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: flags sortbitwise,require_jewel_osds,require_kraken_osds 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: pgmap v43: 24 pgs, 3 pools, 18457 kB data, 26 objects 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: 436 MB used, 2792 GB / 2793 GB avail 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: 24 active+clean 2016-10-25T02:38:38.696 INFO:teuthology.orchestra.run.mira012.stdout: client io 701 B/s rd, 233 B/s wr, 0 op/s rd, 0 op/s wr 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout: 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.035883 mon.0 [INF] fsmap e31: 1/1/1 up {0=b=up:active}, 1 up:standby 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:24.042209 mon.0 [INF] pgmap v44: 24 pgs: 24 active+clean; 18457 kB data, 436 MB used, 2792 GB / 2793 GB avail; 2396 B/s rd, 326 B/s wr, 2 op/s 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:26.050277 mon.0 [INF] mds.0 172.21.3.116:6805/1391193353 up:active 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:26.050515 mon.0 [INF] fsmap e32: 1/1/1 up {0=b=up:active}, 1 up:standby 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.659099 mds.0 [ERR] scrub: inode wrongly marked free: 0x10000000001 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.659132 mds.0 [ERR] inode table repaired for inode: 0x10000000001 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.659585 mds.0 [ERR] scrub: inode wrongly marked free: 0x10000000002 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.659591 mds.0 [ERR] inode table repaired for inode: 0x10000000002 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.662151 mds.0 [WRN] bad backtrace on inode [inode 1 [...2,head] / auth v14 snaprealm=0x558e117d9600 f(v0 m2016-10-25 02:37:59.449168 3=3+0) n(v0 1=0+1) (iversion lock) | request=0 lock=0 dirfrag=1 scrubqueue=0 authpin=0 0x558e119b25e8], rewriting it at 2016-10-25T02:38:38.697 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.663803 mds.0 [WRN] Scrub error on inode [inode 1 [...2,head] / auth v14 snaprealm=0x558e117d9600 dirtyparent f(v0 m2016-10-25 02:37:59.449168 3=3+0) n(v0 1=0+1) (iversion lock) | request=0 lock=0 dirfrag=1 dirtyparent=1 scrubqueue=0 authpin=0 0x558e119b25e8] () see mds.b log for details 2016-10-25T02:38:38.698 INFO:teuthology.orchestra.run.mira012.stdout:2016-10-25 02:38:23.663854 mds.0 [INF] scrub complete with tag ''
MDS log is here: /ceph/teuthology-archive/pdonnell-2016-10-25_02:25:11-fs:recovery-master---basic-mira/493889/remote/mira012/log/ceph-mds.b.log.gz
This might be a duplicate of #17562. Not sure.
Updated by John Spray over 7 years ago
- Status changed from New to In Progress
- Assignee set to John Spray
Sorry, that's happening because I merged my backtrace repair PR before the ceph-qa-suite piece, so the log message isn't whitelisted yet -- didn't realise any existing tests were touching that case.
Updated by John Spray over 7 years ago
- Status changed from In Progress to Resolved
Actions