Actions
Bug #22932
closed[rbd-mirror] infinite loop is possible when formatting the status message
Added by Jason Dillaman about 6 years ago. Updated about 6 years ago.
% Done:
0%
Source:
Tags:
Backport:
luminous,jewel
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
Per Mykola Golub:
When running rbd-mirror stress test against your PR (which I suppose
is unrelated to the issue) I was observing the rbd-mirror looping
forever in this loop:
template <typename I>
bool ReplayStatusFormatter<I>::calculate_behind_master_or_send_update() {
...
while (master.tag_tid != mirror_tag_tid) {
auto tag_it = m_tag_cache.find(master.tag_tid);
if (tag_it == m_tag_cache.end()) {
send_update_tag_cache(master.tag_tid, mirror_tag_tid);
return false;
}
librbd::journal::TagData &tag_data = tag_it->second;
m_entries_behind_master += master.entry_tid;
master = cls::journal::ObjectPosition(0, tag_data.predecessor.tag_tid,
tag_data.predecessor.entry_tid);
}
The state was:
m_master_position = {object_number = 5, tag_tid = 5, entry_tid = 1}
m_mirror_position = {object_number = 3, tag_tid = 4, entry_tid = 1323}
m_tag_cache = std::map with 5 elements =
{[0] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 2, entry_tid = 0}},
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 0, entry_tid = 0}},
[2] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}},
[3] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}},
[5] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 3, entry_tid = 1}}}}
So, `master.tag_tid` went through this endless sequence:
5 -> 3 -> 1 -> 0 -> 2 -> 1 -> 0 -> 2 -> 1 ...
Updated by Jason Dillaman about 6 years ago
The tag_tid values should always be increasing, so the "while (master.tag_tid != mirror_tag_tid)" loop could really just be "while (master.tag_tid >= mirror_tag_tid)" for safety. Additionally, the tag 5 predecessor is incorrectly pointing to tag 3 because it is using the cached client commit position instead of the current commit position after a replay of the journal.
Updated by Mykola Golub about 6 years ago
- Status changed from New to In Progress
- Assignee set to Mykola Golub
Updated by Mykola Golub about 6 years ago
Below is an extract from the log file for this particular case, with the comments that show how it ended up with that tag cache:
2018-02-06 15:52:46.542 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:52:46.542 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0]
2018-02-06 15:52:46.542 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=1, mirror_tag_tid=0
2018-02-06 15:52:46.542 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update: need to update tag cache
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 1: [tid=1, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: making fake tag
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 1: [mirror_uuid=, predecessor=[mirror_uuid=]]
A fake entry inserted to m_tag_cache:
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 0, entry_tid = 0}}
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=0, mirror_tag_tid=0
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0]
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: 0 entries cleared
2018-02-06 15:52:46.546 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0], m_entries_behind_master=3
2018-02-06 15:52:46.562 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:52:46.562 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0]
2018-02-06 15:52:46.562 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-02-06 15:52:46.562 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: 0 entries cleared
2018-02-06 15:52:46.562 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0], m_entries_behind_master=3
2018-02-06 15:53:16.582 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:53:16.582 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=3, tag_tid=2, entry_tid=895]
2018-02-06 15:53:16.582 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=3, tag_tid=2, entry_tid=895], m_entries_behind_master=0
2018-02-06 15:53:46.598 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:53:46.598 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432]
2018-02-06 15:53:46.598 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=3, mirror_tag_tid=2
2018-02-06 15:53:46.598 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update: need to update tag cache
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 3: [tid=3, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 |................|
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 3: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=1, entry_tid=3]]
Entry inserted to m_tag_cache:
[3] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}}
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=1, mirror_tag_tid=2
Why didn't it use the already inserted entry for tag_tid == 1? (the problem with send_update_tag_cache: it does not check the entry already exists in the cache)
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 1: [tid=1, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: making fake tag
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 1: [mirror_uuid=, predecessor=[mirror_uuid=]]
Why it log that decoded tag 1 has empty predecessor? I expected tag_data.predecessor.tag_tid == 2 (mirror_tag_tid) at the moment. (because predecessor.commit_valid == false).
It tried to insert to m_tag_cache a fake entry:
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 2, entry_tid = 0}}
but the insert failed due to previously inserted fake entry (with predecessor.tag_tid == 0).
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=2, mirror_tag_tid=2
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432]
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=0, mirror_tag_tid=2
2018-02-06 15:53:46.598 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update: need to update tag cache
2018-02-06 15:53:46.602 7fcf89ffb700 -1 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: error retrieving tag 0: (2) No such file or directory
It tried to retrieve tag 0, due to previously inserted entry to m_tag_cache for tid = 1 (with predecessor.tag_tid == 0)
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: making fake tag
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 0: [mirror_uuid=, predecessor=[mirror_uuid=]]
A fake entry inserted to m_tag_cache:
[0] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 2, entry_tid = 0}}
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=2, mirror_tag_tid=2
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432]
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: 0 entries cleared
2018-02-06 15:53:46.602 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432], m_entries_behind_master=-2428
2018-02-06 15:53:46.618 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:53:46.618 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432]
2018-02-06 15:53:46.618 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-02-06 15:53:46.618 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: 0 entries cleared
2018-02-06 15:53:46.618 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=0, tag_tid=2, entry_tid=2432], m_entries_behind_master=-2428
2018-02-06 15:54:16.638 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:54:16.638 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=607]
2018-02-06 15:54:16.638 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=607], m_entries_behind_master=0
2018-02-06 15:54:16.710 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:54:16.710 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=607]
2018-02-06 15:54:16.710 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 format: m_master_position=[object_number=1, tag_tid=3, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=607], m_entries_behind_master=0
2018-02-06 15:54:46.746 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:54:46.746 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=5, tag_tid=5, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=1323]
2018-02-06 15:54:46.746 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=5, mirror_tag_tid=4
2018-02-06 15:54:46.746 7fcfdcf4f700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update: need to update tag cache
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 5: [tid=5, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 01 03 00 00 00 00 00 00 |................|
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 5: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=3, entry_tid=1]]
Entry inserted to m_tag_cache:
[5] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 3, entry_tid = 1}}
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=3, mirror_tag_tid=4
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 3: [tid=3, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 |................|
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 3: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=1, entry_tid=3]]
2018-02-06 15:54:46.746 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=1, mirror_tag_tid=4
2018-02-06 15:54:46.750 7fcf89ffb700 -1 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: error retrieving tag 1: (2) No such file or directory
Tag 1 does not arleady exist?
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: making fake tag
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 1: [mirror_uuid=, predecessor=[mirror_uuid=]]
It tried to insert to m_tag_cache a fake entry:
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 4, entry_tid = 0}}
but the insert failed due to previously inserted fake entry (with predecessor.tag_tid == 0).
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=4, mirror_tag_tid=4
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=5, tag_tid=5, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=1323]
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=2, mirror_tag_tid=4
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update: need to update tag cache
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: retrieved tag 2: [tid=2, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 01 01 00 00 00 00 00 00 |................|
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 2: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=1, entry_tid=3]]
Entry inserted to m_tag_cache:
[2] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}}
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=1, mirror_tag_tid=4
2018-02-06 15:54:46.750 7fcf89ffb700 -1 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: error retrieving tag 1: (2) No such file or directory
tag 1 does not arleady exist?
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: making fake tag
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 handle_update_tag_cache: decoded tag 1: [mirror_uuid=, predecessor=[mirror_uuid=]]
It tried to insert to m_tag_cache a fake entry:
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 4, entry_tid = 0}}
but the insert failed due to previously inserted fake entry (with predecessor.tag_tid == 0).
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 send_update_tag_cache: master_tag_tid=4, mirror_tag_tid=4
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 get_or_send_update:
2018-02-06 15:54:46.750 7fcf89ffb700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fcf2000d5e0 calculate_behind_master_or_send_update: m_master_position=[object_number=5, tag_tid=5, entry_tid=1], m_mirror_position=[object_number=3, tag_tid=4, entry_tid=1323]
At that moment m_tag_cache was:
m_tag_cache =
{[0] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 2, entry_tid = 0}},
[1] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = false, tag_tid = 0, entry_tid = 0}},
[2] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}},
[3] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 1, entry_tid = 3}},
[5] = {mirror_uuid = "", predecessor = {mirror_uuid = "", commit_valid = true, tag_tid = 3, entry_tid = 1}}}}
and it went to infinit loop with master.tag_tid iterating 5 -> 3 -> 1 -> 0 -> 2 -> 1 -> ...
Updated by Mykola Golub about 6 years ago
- Status changed from In Progress to Fix Under Review
Updated by Jason Dillaman about 6 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Nathan Cutler about 6 years ago
- Copied to Backport #22964: luminous: [rbd-mirror] infinite loop is possible when formatting the status message added
Updated by Nathan Cutler about 6 years ago
- Copied to Backport #22965: jewel: [rbd-mirror] infinite loop is possible when formatting the status message added
Updated by Nathan Cutler about 6 years ago
- Status changed from Pending Backport to Resolved
Actions