Project

General

Profile

Actions

Bug #17691

closed

bad backtrace on inode

Added by Patrick Donnelly over 7 years ago. Updated over 7 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
-
Target version:
-
% 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.

Actions #1

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.

Actions #2

Updated by John Spray over 7 years ago

  • Status changed from In Progress to Resolved
Actions

Also available in: Atom PDF