Project

General

Profile

Bug #24516

[rbd-mirror] object map is getting invalidated during rbd-mirror-fsx-workunit test

Added by Jason Dillaman 6 months ago. Updated about 2 months ago.

Status:
Resolved
Priority:
Normal
Target version:
-
Start date:
06/13/2018
Due date:
% Done:

0%

Source:
Tags:
Backport:
luminous,mimic
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:

Description

2018-06-13 17:16:37.723 7f03d17fa700 -1 librbd::object_map::Request: failed to update object map: (34) Numerical result out of range
2018-06-13 17:16:37.723 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03a0173e60 invalidating object map in-memory
2018-06-13 17:16:37.723 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03a0173e60 invalidating object map on-disk
2018-06-13 17:16:37.731 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03a0173e60 should_complete: r=0
2018-06-13 17:16:37.739 7f03d17fa700 -1 librbd::object_map::Request: failed to update object map: (34) Numerical result out of range
2018-06-13 17:16:37.739 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03940621a0 invalidating object map in-memory
2018-06-13 17:16:37.739 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03940621a0 invalidating object map on-disk
2018-06-13 17:16:37.743 7f03d17fa700 -1 librbd::object_map::InvalidateRequest: 0x7f03940621a0 should_complete: r=0

Related issues

Copied to rbd - Backport #36224: luminous: [rbd-mirror] object map is getting invalidated during rbd-mirror-fsx-workunit test Resolved
Copied to rbd - Backport #36225: mimic: [rbd-mirror] object map is getting invalidated during rbd-mirror-fsx-workunit test Resolved

History

#1 Updated by Jason Dillaman 3 months ago

http://qa-proxy.ceph.com/teuthology/jdillaman-2018-09-12_07:51:00-rbd-wip-24688-distro-basic-smithi/3010811/teuthology.log

2018-09-12T12:10:54.992 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.992 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.993 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4254
2018-09-12T12:10:54.994 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.994 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.994 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4254
2018-09-12T12:10:54.994 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.995 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.995 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4254
2018-09-12T12:10:54.995 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.995 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.996 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4254
2018-09-12T12:10:54.996 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.996 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.996 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4254
2018-09-12T12:10:54.999 INFO:teuthology.orchestra.run.smithi036.stdout:mapped writes DISABLED
2018-09-12T12:10:54.999 INFO:teuthology.orchestra.run.smithi036.stdout:mapped reads DISABLED
2018-09-12T12:10:54.999 INFO:teuthology.orchestra.run.smithi036.stdout:Seed set to 4255

#2 Updated by Jason Dillaman 3 months ago

  • Status changed from New to In Progress
  • Assignee set to Jason Dillaman

#3 Updated by Jason Dillaman 3 months ago

It's related to a race with an rbd-mirror daemon sync snapshot getting removed via a notification to fsx:

2018-09-14 01:18:44.474 7f72367fc700 10 librbd::ImageWatcher: 0x7f722831fc80 remote snap_create request: .rbd-mirror.b7f9cd01-e621-4e99-a16e-08565e1bfab3.b7bcae18-d464-4255-9607-a57f189f9f11
2018-09-14 01:18:44.474 7f72367fc700  5 librbd::Operations: 0x560b03eaff00 execute_snap_create: snap_name=.rbd-mirror.b7f9cd01-e621-4e99-a16e-08565e1bfab3.b7bcae18-d464-4255-9607-a57f189f9f11
2018-09-14 01:18:44.474 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_suspend_requests
2018-09-14 01:18:44.474 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_suspend_aio
2018-09-14 01:18:44.506 7f7235ffb700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 handle_suspend_aio: r=0
2018-09-14 01:18:44.506 7f7235ffb700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_append_op_event
2018-09-14 01:18:44.514 7f7235ffb700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 handle_append_op_event: r=0
2018-09-14 01:18:44.514 7f7235ffb700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_allocate_snap_id
2018-09-14 01:18:44.542 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 handle_allocate_snap_id: r=0, snap_id=315
2018-09-14 01:18:44.542 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_create_snap
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 handle_create_snap: r=0
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 update_snap_context
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 send_create_object_map
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 send_read_map: oid=rbd_object_map.106256c84198
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 should_complete: state=READ_MAP, r=0
2018-09-14 01:18:44.558 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 send_write_map: snap_oid=rbd_object_map.106256c84198.000000000000013b
2018-09-14 01:18:44.566 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 should_complete: state=WRITE_MAP, r=0
2018-09-14 01:18:44.566 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 send_add_snapshot: oid=rbd_object_map.106256c84198
2018-09-14 01:18:44.574 7f72367fc700  5 librbd::object_map::SnapshotCreateRequest: 0x7f722801bc60 should_complete: state=ADD_SNAPSHOT, r=0
2018-09-14 01:18:44.574 7f72367fc700  5 librbd::SnapshotCreateRequest: 0x7f72283481b0 handle_create_object_map: r=0

...

2018-09-14 01:18:45.802 7f72367fc700 10 librbd::ImageWatcher: 0x7f722831fc80 remote snap_remove request: .rbd-mirror.b7f9cd01-e621-4e99-a16e-08565e1bfab3.b7bcae18-d464-4255-9607-a57f189f9f11
2018-09-14 01:18:45.802 7f72367fc700  5 librbd::Operations: 0x560b03eaff00 execute_snap_remove: snap_name=.rbd-mirror.b7f9cd01-e621-4e99-a16e-08565e1bfab3.b7bcae18-d464-4255-9607-a57f189f9f11
2018-09-14 01:18:45.818 7f7235ffb700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 trash_snap:
2018-09-14 01:18:45.830 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 handle_trash_snap: r=0
2018-09-14 01:18:45.830 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 get_snap:
2018-09-14 01:18:45.838 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 handle_get_snap: r=0
2018-09-14 01:18:45.838 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 remove_object_map:
2018-09-14 01:18:45.858 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 handle_remove_object_map: r=0
2018-09-14 01:18:45.858 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 release_snap_id: snap_name=.rbd-mirror.b7f9cd01-e621-4e99-a16e-08565e1bfab3.b7bcae18-d464-4255-9607-a57f189f9f11, snap_id=315

...

2018-09-14 01:18:46.046 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 append_request: 0x7f71df31fc00
2018-09-14 01:18:46.046 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 send: completion 0x560b03d442c0, oid rbd_data.106256c84198.000000000000000d, extents [27262976,8192,27369472,8192,27475968,8192,27582464,8192,27688960,8192,27795456,8192,27901952,8192,28008448,8192,28114944,8192,28221440,8192,28327936,8192,28434432,8192,28540928,8192,28647424,8192,28753920,8192,28860416,8192,28966912,8192,29073408,8192,29179904,8192,29286400,8192,29392896,8192,29499392,8192,29605888,8192,29712384,8192,29818880,8192,29925376,8192,30031872,8192,30138368,8192,30244864,8192,30351360,8192,30457856,8192,30564352,8192,30670848,8192,30777344,8192,30883840,8192,30990336,8192,31096832,8192,31203328,8192,31309824,8192,31416320,8192,31522816,8192,31629312,8192,31735808,8192,31842304,8192,31948800,8192,32055296,8192,32161792,8192,32268288,8192,32374784,8192,32481280,8192,32587776,8192,32694272,8192,32800768,8192,32907264,8192,33013760,8192,33120256,8192,33226752,8192,33333248,8192,33439744,8192,33546240,8192,33652736,8192,33759232,8192,33865728,8192,33972224,8192,34078720,8192,34185216,8192,34291712,8192,34398208,8192,34504704,8192,34611200,8192,34717696,8192,34824192,8192,34930688,8192,35037184,8192,35143680,8192,35250176,8192,35356672,8192,35463168,8192,35569664,8192,35676160,8192,35782656,8192,35889152,8192,35995648,8192,36102144,8192,36208640,8192,36315136,8192,36421632,8192,36528128,8192,36634624,8192,36741120,8192,36847616,8192,36954112,8192,37060608,8192,37167104,8192,37273600,8192,37380096,8192,37486592,8192,37593088,8192,37699584,8192,37806080,8192,37912576,8192,38019072,8192,38125568,8192,38232064,8192,38338560,8192,38445056,8192,38551552,8192,38658048,8192,38764544,8192,38871040,8192,38977536,8192,39084032,8192,39190528,8192,39297024,8192,39403520,8192,39510016,8192,39616512,8192,39723008,8192,39829504,8192,39936000,8192,40042496,8192,40148992,8192,40255488,8192,40361984,8192,40468480,8192,40574976,8192,40681472,8192,40787968,8192,40894464,8192,41000960,8192,41107456,8192,41213952,8192,41320448,8192,41426944,8192,41533440,8192,41639936,8192,41746432,8192,41852928,8192,41959424,8192,42065920,8192,42172416,8192,42278912,8192,42385408,8192,42491904,8192,42598400,8192,42704896,8192,42811392,8192,42917888,8192,43024384,8192,43130880,8192,43237376,8192,43343872,8192,43450368,8192,43556864,8192,43663360,8192,43769856,8192,43876352,8192,43982848,8192,44089344,8192,44195840,8192,44302336,8192,44408832,8192,44515328,8192,44621824,8192,44728320,8192,44834816,8192,44941312,8192,45047808,8192,45154304,8192,45260800,8192,45367296,8192,45473792,8192,45580288,8192,45686784,8192,45793280,8192,45899776,8192,46006272,8192,46112768,8192,46219264,8192,46325760,8192,46432256,8192,46538752,8192,46645248,8192,46751744,8192,46858240,8192,46964736,8192,47071232,8192,47177728,8192,47284224,8192,47390720,8192,47497216,8192,47603712,8192,47710208,8192,47816704,8192,47923200,8192,48029696,8192,48136192,8192,48242688,8192,48349184,8192,48455680,8192,48562176,8192,48668672,8192,48775168,8192,48881664,8192,48988160,8192,49094656,8192,49201152,8192,49307648,8192,49414144,8192,49520640,8192,49627136,8192,49733632,8192,49840128,8192,49946624,8192,50053120,8192,50159616,8192,50266112,8192,50372608,8192,50479104,8192,50585600,8192,50692096,8192,50798592,8192,50905088,8192,51011584,8192,51118080,8192,51224576,8192,51331072,8192,51437568,8192,51544064,8192,51650560,8192,51757056,8192,51863552,8192,51970048,8192,52076544,8192,52183040,8192,52289536,8192,52396032,8192,52502528,8192,52609024,8192,52715520,8192,52822016,8192,52928512,8192,53035008,8192,53141504,8192,53248000,8192,53354496,8192,53460992,8192,53567488,8192,53673984,8192,53780480,8192,53886976,8192,53993472,8192,54099968,8192,54206464,8192,54312960,8192,54419456,8192]
2018-09-14 01:18:46.198 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 should_complete: oid rbd_data.106256c84198.000000000000000d, r 2097152
2018-09-14 01:18:46.198 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 should_complete: READ_FROM_PARENT
2018-09-14 01:18:46.198 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 send_object_map_head:
2018-09-14 01:18:46.198 7f7235ffb700 20 librbd::io::CopyupRequest: 0x7f71df29f100 send_object_map_head: truncate object no 13 current state 0 new state 1
2018-09-14 01:18:46.310 7f72367fc700 20 librbd::io::CopyupRequest: 0x7f71df29f100 should_complete: oid rbd_data.106256c84198.000000000000000d, r 0
2018-09-14 01:18:46.310 7f72367fc700 20 librbd::io::CopyupRequest: 0x7f71df29f100 should_complete: OBJECT_MAP_HEAD
2018-09-14 01:18:46.310 7f72367fc700 20 librbd::io::CopyupRequest: 0x7f71df29f100 send_object_map: oid rbd_data.106256c84198.000000000000000d
2018-09-14 01:18:46.310 7f72367fc700 20 librbd::ObjectMap: 0x7f71ba900170 aio_update: start=13, end=14, ->1
2018-09-14 01:18:46.310 7f72367fc700 20 librbd::object_map::UpdateRequest: 0x7f7229472aa0 update_object_map: ictx=0x560b03e9f2a0, oid=rbd_object_map.106256c84198.000000000000013b, [13,14) = ->1
2018-09-14 01:18:46.318 7f72367fc700 20 librbd::object_map::UpdateRequest: 0x7f7229472aa0 handle_update_object_map: r=-2
2018-09-14 01:18:46.318 7f72367fc700 20 librbd::object_map::Request: 0x7f7229472aa0 should_complete: r=-2
2018-09-14 01:18:46.318 7f72367fc700 -1 librbd::object_map::Request: failed to update object map: (2) No such file or directory
2018-09-14 01:18:46.318 7f72367fc700 -1 librbd::object_map::InvalidateRequest: 0x7f7228044020 invalidating object map in-memory
2018-09-14 01:18:46.318 7f72367fc700 -1 librbd::object_map::InvalidateRequest: 0x7f7228044020 invalidating object map on-disk

...

2018-09-14 01:18:46.550 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 handle_release_snap_id: r=0
2018-09-14 01:18:46.550 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 remove_snap:
2018-09-14 01:18:46.574 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 handle_remove_snap: r=0
2018-09-14 01:18:46.574 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 remove_snap_context:
2018-09-14 01:18:46.574 7f72367fc700  5 librbd::SnapshotRemoveRequest: 0x7f7228019410 should_complete: r=0

#4 Updated by Jason Dillaman 3 months ago

  • Status changed from In Progress to Need Review
  • Backport set to luminous,mimic

#5 Updated by Mykola Golub 3 months ago

  • Status changed from Need Review to Pending Backport

#6 Updated by Jason Dillaman 3 months ago

  • Status changed from Pending Backport to In Progress

There is another path where the object map is invalidated:

http://qa-proxy.ceph.com/teuthology/jdillaman-2018-09-18_19:00:21-rbd-wip-rbd-mirror-distro-basic-smithi/3039367/teuthology.log

2018-09-18 23:40:13.884 7f84f67fc700 20 librbd::io::CopyupRequest: 0x7f84e83a5d30 send_object_map: oid rbd_data.10611250bd72.000000000000017f
2018-09-18 23:40:13.884 7f84f67fc700 20 librbd::ManagedLock: 0x7f84e401d020 is_lock_owner: =1
2018-09-18 23:40:13.884 7f84f67fc700 20 librbd::ObjectMap: 0x7f84e4003c30 aio_update: start=383, end=384, ->3
2018-09-18 23:40:13.884 7f84f67fc700 20 librbd::object_map::UpdateRequest: 0x7f84e803e200 update_object_map: ictx=0x55ecd0837e60, oid=rbd_object_map.10611250bd72.00000000000001b0, [383,384) = ->3
2018-09-18 23:40:13.885 7f84f67fc700 20 librbd::ManagedLock: 0x7f84e401d020 is_lock_owner: =1
2018-09-18 23:40:13.885 7f84f67fc700 20 librbd::ObjectMap: 0x7f84e4003c30 aio_update: start=383, end=384, ->1
2018-09-18 23:40:13.885 7f84f67fc700 20 librbd::object_map::UpdateRequest: 0x7f84e8321950 update_object_map: ictx=0x55ecd0837e60, oid=rbd_object_map.10611250bd72.000000000000021c, [383,384) = ->1
2018-09-18 23:40:13.891 7f84f67fc700 20 librbd::object_map::UpdateRequest: 0x7f84e8321950 handle_update_object_map: r=-2
2018-09-18 23:40:13.891 7f84f67fc700 20 librbd::object_map::Request: 0x7f84e8321950 should_complete: r=-2
2018-09-18 23:40:13.891 7f84f67fc700 -1 librbd::object_map::Request: failed to update object map: (2) No such file or directory
2018-09-18 23:40:13.891 7f84f67fc700 -1 librbd::object_map::InvalidateRequest: 0x7f84e806df80 invalidating object map in-memory
2018-09-18 23:40:13.891 7f84f67fc700 -1 librbd::object_map::InvalidateRequest: 0x7f84e806df80 invalidating object map on-disk

#7 Updated by Jason Dillaman 3 months ago

  • Status changed from In Progress to Need Review

#8 Updated by Mykola Golub 3 months ago

  • Status changed from Need Review to Pending Backport

#9 Updated by Nathan Cutler 3 months ago

  • Copied to Backport #36224: luminous: [rbd-mirror] object map is getting invalidated during rbd-mirror-fsx-workunit test added

#10 Updated by Nathan Cutler 3 months ago

  • Copied to Backport #36225: mimic: [rbd-mirror] object map is getting invalidated during rbd-mirror-fsx-workunit test added

#11 Updated by Nathan Cutler about 2 months ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF