Project

General

Profile

Bug #4976

osd powercycle triggers object corruption on xfs

Added by Tamilarasi muthamizhan almost 11 years ago. Updated almost 11 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Category:
librados
Target version:
-
% Done:

0%

Source:
Q/A
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

logs: ubuntu@teuthology:/a/teuthology-2013-05-09_01:00:05-rados-next-testing-basic/9325

2013-05-09T01:37:29.943 INFO:teuthology.task.rados.rados.0.out:Writing plana3332167-39 from 2072826 to 2611791 tid 3 ranges are [0~56,638473~673998,2072826~538965]
2013-05-09T01:37:29.944 INFO:teuthology.task.rados.rados.0.out:1169: oids not in use 497
2013-05-09T01:37:29.944 INFO:teuthology.task.rados.rados.0.out:Reading 22
2013-05-09T01:37:29.944 INFO:teuthology.task.rados.rados.0.out:1170: oids not in use 496
2013-05-09T01:37:29.944 INFO:teuthology.task.rados.rados.0.out:Reading 342
2013-05-09T01:37:29.944 INFO:teuthology.task.rados.rados.0.out:1171: oids not in use 495
2013-05-09T01:37:29.945 INFO:teuthology.task.rados.rados.0.out:Deleting 67 current snap is 0
2013-05-09T01:37:30.131 INFO:teuthology.orchestra.remote:Power off for plana55 completed
2013-05-09T01:37:31.224 INFO:teuthology.task.rados.rados.0.out:incorrect buffer at pos 1146884
2013-05-09T01:37:31.224 INFO:teuthology.task.rados.rados.0.err:Object 342 contents ObjNum: 341 snap: 0 seqnum: 341 prefix: plana3332167-OID: 342 snap 0
2013-05-09T01:37:31.224 INFO:teuthology.task.rados.rados.0.err: corrupt
2013-05-09T01:37:31.225 INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: In function 'virtual void ReadOp::_finish(TestOp::CallbackInfo*)' thread 7fe9cdffb700 time 2013-05-09 01:37:46.947876
2013-05-09T01:37:31.225 INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: 1053: FAILED assert(0)
2013-05-09T01:37:31.240 INFO:teuthology.task.rados.rados.0.err: ceph version 0.61-160-g5177fcb (5177fcb6bf384d5c9caed9b28f28f656823b3d64)
2013-05-09T01:37:31.240 INFO:teuthology.task.rados.rados.0.err: 1: (ReadOp::_finish(TestOp::CallbackInfo*)+0x13ce) [0x414dbe]
2013-05-09T01:37:31.241 INFO:teuthology.task.rados.rados.0.err: 2: (librados::C_AioComplete::finish(int)+0x1d) [0x7fe9d8003f4d]
2013-05-09T01:37:31.241 INFO:teuthology.task.rados.rados.0.err: 3: (Finisher::finisher_thread_entry()+0x1c0) [0x7fe9d80719d0]
2013-05-09T01:37:31.241 INFO:teuthology.task.rados.rados.0.err: 4: (()+0x7e9a) [0x7fe9d7cb6e9a]
2013-05-09T01:37:31.241 INFO:teuthology.task.rados.rados.0.err: 5: (clone()+0x6d) [0x7fe9d74cdccd]
2013-05-09T01:37:31.242 INFO:teuthology.task.rados.rados.0.err: NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
2013-05-09T01:37:31.242 INFO:teuthology.task.rados.rados.0.err:terminate called after throwing an instance of 'ceph::FailedAssertion'
2013-05-09T01:37:31.424 ERROR:teuthology.run_tasks:Manager failed: <contextlib.GeneratorContextManager object at 0x320db50>
Traceback (most recent call last):
  File "/var/lib/teuthworker/teuthology-next/teuthology/run_tasks.py", line 45, in run_tasks
    suppress = manager.__exit__(*exc_info)
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/var/lib/teuthworker/teuthology-next/teuthology/task/rados.py", line 118, in task
    running.get()
  File "/var/lib/teuthworker/teuthology-next/virtualenv/local/lib/python2.7/site-packages/gevent/greenlet.py", line 331, in get
    raise self._exception
CommandCrashedError: Command crashed: 'CEPH_CLIENT_ID=0 /home/ubuntu/cephtest/9325/enable-coredump ceph-coverage /home/ubuntu/cephtest/9325/archive/coverage ceph_test_rados --op read 45 --op write 45 --op delete 10 --op snap_create 0 --op snap_remove 0 --op rollback 0 --op setattr 0 --op rmattr 0 --op watch 0 --max-ops 4000 --objects 500 --max-in-flight 16 --size 4000000 --min-stride-size 400000 --max-stride-size 800000 --max-seconds 0'

ubuntu@teuthology:/a/teuthology-2013-05-09_01:00:05-rados-next-testing-basic/9325$ cat orig.config.yaml 
kernel:
  kdb: true
  sha1: b5b09be30cf99f9c699e825629f02e3bce555d44
machine_type: plana
nuke-on-error: true
overrides:
  ceph:
    conf:
      mon:
        debug mon: 20
        debug ms: 20
        debug paxos: 20
    fs: xfs
    log-whitelist:
    - slow request
    sha1: 6c1e4791782ce2b3e101ee80640d896bcda684de
  s3tests:
    branch: next
  workunit:
    sha1: 6c1e4791782ce2b3e101ee80640d896bcda684de
roles:
- - mon.0
  - mon.1
  - mon.2
  - mds.0
  - client.0
- - osd.0
- - osd.1
- - osd.2
tasks:
- chef: null
- clock.check: null
- install: null
- ceph: null
- thrashosds:
    chance_down: 1.0
    powercycle: true
- rados:
    clients:
    - client.0
    objects: 500
    op_weights:
      delete: 10
      read: 45
      write: 45
    ops: 4000

a.tar.gz (4.48 MB) Sage Weil, 06/03/2013 03:40 PM


Related issues

Duplicated by Ceph - Bug #5198: osd: powercycle testing triggers corrupt object data on xfs Duplicate 05/29/2013

Associated revisions

Revision de8900dc (diff)
Added by Sage Weil almost 11 years ago

os/FileStore: use fdatasync(2) instead of sync_file_range(2)

This fixes data corruption on XFS. Backported from
ffade3c85dfffa13a16edd9630a52d99eb8a413d.

Fixes: #4976
Signed-off-by: Sage Weil <>
Reviewed-by: Samuel Just <>

History

#1 Updated by Tamilarasi muthamizhan almost 11 years ago

  • Assignee set to Samuel Just

#2 Updated by Samuel Just almost 11 years ago

  • Assignee deleted (Samuel Just)

Looks like there were 4 inconsistent objects in pg 3.0

2013-05-09 01:37:39.771684 7fdc077f2700 0 log [INF] : 2.6 deep-scrub ok
2013-05-09 01:37:45.901582 7fdc077f2700 0 log [INF] : 2.8 deep-scrub ok
2013-05-09 01:37:50.763676 7fdc077f2700 0 log [INF] : 2.9 deep-scrub ok
2013-05-09 01:37:57.765040 7fdc077f2700 0 log [INF] : 2.a deep-scrub ok
2013-05-09 01:37:59.765180 7fdc077f2700 0 log [INF] : 2.b deep-scrub ok
2013-05-09 01:38:20.487161 7fdc077f2700 0 log [ERR] : 3.0 osd.0: soid a840d671/plana3332167-342/head//3 digest 3225952747 != known digest 293065042
2013-05-09 01:38:23.501161 7fdc077f2700 0 log [ERR] : 3.0 osd.0: soid 2b884b3b/plana3332167-361/head//3 digest 3120190675 != known digest 1749218233
2013-05-09 01:38:23.698283 7fdc077f2700 0 log [ERR] : 3.0 osd.0: soid 97ac4bdb/plana3332167-359/head//3 digest 4007521181 != known digest 1203775870
2013-05-09 01:38:24.470476 7fdc077f2700 0 log [ERR] : 3.0 osd.0: soid 6707116f/plana3332167-335/head//3 digest 35276847 != known digest 3722161389
2013-05-09 01:38:24.677529 7fdc077f2700 0 log [ERR] : 3.0 deep-scrub 0 missing, 4 inconsistent objects
2013-05-09 01:38:24.677535 7fdc077f2700 0 log [ERR] : 3.0 deep-scrub 4 errors

#3 Updated by Tamilarasi muthamizhan almost 11 years ago

ubuntu@teuthology:/a/teuthology-2013-05-10_01:00:06-rados-master-testing-basic/10288

#4 Updated by Tamilarasi muthamizhan almost 11 years ago

ubuntu@teuthology:/a/teuthology-2013-05-10_01:00:06-rados-master-testing-basic/10288$ cat config.yaml 
kernel: &id001
  kdb: true
  sha1: b5b09be30cf99f9c699e825629f02e3bce555d44
machine_type: plana
nuke-on-error: true
overrides:
  ceph:
    conf:
      mon:
        debug mon: 20
        debug ms: 20
        debug paxos: 20
    fs: xfs
    log-whitelist:
    - slow request
    sha1: b353da6f682d223ba14812da0fe814eca72ad6f5
  s3tests:
    branch: master
  workunit:
    sha1: b353da6f682d223ba14812da0fe814eca72ad6f5
roles:
- - mon.0
  - mon.1
  - mon.2
  - mds.0
  - client.0
- - osd.0
- - osd.1
- - osd.2
targets:
  ubuntu@plana08.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCqqzUa6OfNvqirlipO2jY32KanSfk2mSstJJdakPuKVijDoaDHvC7L14A9iNMChI/+OgVJRpBF4DI+QwrO00yj4jSGSuq/dtp6vxkX5fw1+g21uqZG7Sl6S89ytRkRs+NFoNY1jhWR0Qo4opEim9qApVSxlouG61L++IEv7zhZ62ogpknTMQhkgpHJ4w146silaCh6vnmoNsTBt+eIuVE/7vhMQep4REpw5uVZR6PVUBsJDJAkJuyAkNu3Xva7KC4W22sjzSqHKWqzNeAmPxQ8Ywvu5PWQulOtA/LF9gAVsJjbKE7+ZsXVYvTfpZtEKfOduss8dB3lP8Xez6CbUzsv
  ubuntu@plana09.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCsROY/kuvJRrw3yOos6aHDtveOLPgZ+mBs4ul/O6LTm0swWIpeiilmIeILba12z98XmkoqIGTAgZqcGx6FfNpwrOg8P2pdDg9YKT9YrdESlFZryHyu3Rjyn+lZcskMdHAoXhTUzRkHh7t9/vM5cuhq+BoO5+nAebtFCQ1mcn9w8jn6ZqnXkQiplB93UBmXqGKhbqnaGok6xJfYtV3NtmXOFBJ0keja0rOT4ylnSBExG3YBdZ4qSEaWVNeBtoDslu6K0hq5/mmNtZwJf2iXQWOkhfM3tVUbcMfwaGVEe77gzg3CeU0lT7ag1oJan9MAxzVBqOXO1ZS2h8w4zBrX7eYt
  ubuntu@plana39.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCbo4KGzlqjC+4jdO3xTeMPDlEV6kI+ybIFMu0Hp/p4phefQbrjNRM5CngnRnrEhlrj7wLlrGEO7QceuIx3rTMlsprZlw+A6ZFAWdImzQuwIXSYUyMrb89LoENVJr3IylX1w1DLDkfHSNFeXmq/t0sl1LIpIs5H52dKfxuQvTMNVYOhVzchELrXY62TVMrv2WH2tKGoKFm57OsHlxaM79LBk0IKQfWDPbs4IYYCfDQ4ySS8jHCyjk7PGDhQV1K07CfjPAhriGKYamSCTnQHyfKkkun2Ue+CB+zPW26us0iA/Lj1mDsqICfi4uiIDkljPbOEnzuOn8WaVFF9FctarNM7
  ubuntu@plana40.front.sepia.ceph.com: ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQDEwyNlwC9Utqf3PCjL2JR4wwDkzpdEJuW93DOW82vYVisYEGod454JwXeNkjqzTUk6tXeRoUM9f/C6sZS3LFgHcMYt6m0sxP8DC4qU+q0YxCw9zLY8bXKe4DDjijM62h/SnyqyOWIh9amGT7wRwZEHBV1BKvZbNxQIJ7ESkuKsk/tJfWKhq7dSw6E/+MZ4yQtXvTyaJ3pK96Hq2uoUkawv+FxXBrzG3FtTTYA8gqA1SIiV3erEIQuBK/WD74i5yK4rwpfGTo7jNc0V6wrwO1BKFj/OGjSC+2LSAkBgf8WLe6UL/dHr3bBEyzm0V4xMf5Iqb8JGvkaXNEfbFqzKC2Wv
tasks:
- internal.lock_machines:
  - 4
  - plana
- internal.save_config: null
- internal.check_lock: null
- internal.connect: null
- internal.check_conflict: null
- internal.check_ceph_data: null
- internal.vm_setup: null
- kernel: *id001
- internal.base: null
- internal.archive: null
- internal.coredump: null
- internal.syslog: null
- internal.timer: null
- chef: null
- clock.check: null
- install: null
- ceph: null
- thrashosds:
    chance_down: 1.0
    powercycle: true
- rados:
    clients:
    - client.0
    objects: 500
    op_weights:
      delete: 50
      read: 100
      rollback: 50
      snap_create: 50
      snap_remove: 50
      write: 100
    ops: 4000

#5 Updated by Sage Weil almost 11 years ago

ubuntu@teuthology:/a/teuthology-2013-05-11_01:00:07-rados-next-testing-basic/11133$ cat orig.config.yaml 
kernel:
  kdb: true
  sha1: b5b09be30cf99f9c699e825629f02e3bce555d44
machine_type: plana
nuke-on-error: true
overrides:
  ceph:
    conf:
      mon:
        debug mon: 20
        debug ms: 20
        debug paxos: 20
    fs: xfs
    log-whitelist:
    - slow request
    sha1: fd901056831586e8135e28c8f4ba9c2ec44dfcf6
  s3tests:
    branch: next
  workunit:
    sha1: fd901056831586e8135e28c8f4ba9c2ec44dfcf6
roles:
- - mon.0
  - mon.1
  - mon.2
  - mds.0
  - client.0
- - osd.0
- - osd.1
- - osd.2
tasks:
- chef: null
- clock.check: null
- install: null
- ceph: null
- thrashosds:
    chance_down: 1.0
    powercycle: true
- rados:
    clients:
    - client.0
    objects: 500
    op_weights:
      delete: 50
      read: 100
      rollback: 50
      snap_create: 50
      snap_remove: 50
      write: 100
    ops: 4000

#6 Updated by Samuel Just almost 11 years ago

  • Assignee set to Samuel Just

#7 Updated by Sage Weil almost 11 years ago

  • Subject changed from assertion in ReadOp::_finish to osd powercycle triggers object corruption on xfs

#8 Updated by Sage Weil almost 11 years ago

  • Status changed from New to In Progress
  • Assignee changed from Samuel Just to Sage Weil

ubuntu@teuthology:/a/teuthology-2013-05-31_20:00:08-rados-cuttlefish-master-basic/28270

trying to reproduce this with logs and interactive-on-error so we can inspect the (corrupt?) xfs post-reboot.

#9 Updated by Sage Weil almost 11 years ago

  • Priority changed from Urgent to Immediate

#10 Updated by Sage Weil almost 11 years ago

two writes to the object, at offset A~B and C~D, then read the whole thing. the original write appears intact, but at A+B there are a few byte sof 0's op ot the block boundary and then about 30k of random garbage, then zeros until you get to offset C

currently theory is a stray write to a random fd, probably while the fd is sitting in the flusher queue. pushed wip-4976 to lseek to a magic offset and use pwrite instead so that we can look for garbage writes at that offset...

#11 Updated by Sage Weil almost 11 years ago

  • Priority changed from Immediate to Urgent

this is looking more like an xfs bug to me.. sent something to the list.

i also think it is new in 3.9. need to try to reproduce using a 3.8 kernel.

#12 Updated by Tamilarasi muthamizhan almost 11 years ago

ubuntu@teuthology:/a/teuthology-2013-06-05_10:57:29-rados-cuttlefish-master-basic/31967

#13 Updated by Sage Weil almost 11 years ago

  • Status changed from In Progress to Fix Under Review

the problem is that sync_file_range(2) and posix_fadvaise(..DONTNEED) break xfs's internal write and zero ordering. the sync_file_range is already gone from master; remove fadvise. for cuttlefish and bobtail, just remove these calls.

#14 Updated by Greg Farnum almost 11 years ago

What do you mean "remove fadvise"? And is this a known upstream issue?

#15 Updated by Sage Weil almost 11 years ago

  • Status changed from Fix Under Review to Resolved

Also available in: Atom PDF