Project

General

Profile

Actions
Copy link

Bug #36699

closed

the remote cluster could be stop sync after 3 or 4 days

Added by 俊 王 over 5 years ago. Updated about 5 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Target version:
-
% Done:

0%

Source:
Community (user)
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
Ceph - v12.2.7
ceph-qa-suite:
rbd
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Recently,I am working in test of cinder replication with rbd mirror.But after 3 or 4 days,the remote cluster could be stop sync.The status of rbd daemon is active, but there is no more debug info to be writed into log file.

Actions
Copy link
 #1

Updated by 俊 王 over 5 years ago

rbd mirror daemon is active.

Actions
Copy link
 #2

Updated by 俊 王 over 5 years ago

俊 王 wrote:

rbd mirror daemon is active.

After I restart mirror daemon,evrything is OK now.

Actions
Copy link
 #3

Updated by 俊 王 over 5 years ago

I created two clusters in six vms with default configuration, by ceph-deploy.Then I use local cluster to be cinder's backend, and remote cluster is secondary.At first, I create replication-type volume with cinder-cli,and the remote cluster sync fast.But after 3 or 4 days,the remote cluster is no more sync with local,and the rbd-mirror-log file is 0 byte. I restart the rbd mirror daemon, the sync is beginning to work well, and the log file's size is growing.

Actions
Copy link
 #4

Updated by 俊 王 over 5 years ago

local:ceph.conf
-------------------------------
fsid = 160ddc5c-8f0d-4fec-be41-7fd0fd1fe6d9
mon_initial_members = mirror-ceph1-vm1, mirror-ceph1-vm2, mirror-ceph1-vm3
mon_host = 192.168.122.104,192.168.122.52,192.168.122.9
auth_cluster_required = cephx
auth_service_required = cephx
auth_client_required = cephx
-------------------------------

remote:ceph.conf
-------------------------------
[global]
fsid = 5e3b0999-afe1-4681-8eb4-38b382a39fab
mon_initial_members = mirror-ceph2-vm1, mirror-ceph2-vm2, mirror-ceph2-vm3
mon_host = 192.168.122.178,192.168.122.47,192.168.122.172
auth_cluster_required = cephx
auth_service_required = cephx
auth_client_required = cephx
mon_allow_pool_delete = true
rbd_default_data_pool = test_vms
-------------------------------

cinder.conf
-------------------------------
[mirror-ceph1]
replication_device = backend_id:mirror-ceph2, conf:/etc/ceph/mirror-ceph2.conf, user:cinder
volume_driver = cinder.volume.drivers.rbd.RBDDriver
volume_backend_name = mirror-ceph1
rbd_cluster_name = mirror-ceph1
rbd_pool = volumes
rbd_user = cinder
rbd_ceph_conf = /etc/ceph/mirror-ceph1.conf
rbd_flatten_volume_from_snapshot = false
rbd_secret_uuid = e19ed07c-12aa-4dce-bf92-311438f2ae38
rbd_max_clone_depth = 5
rbd_store_chunk_size = 4
rados_connect_timeout = 1
rados_connection_retries = 3
rados_connection_interval = 5
------------------------------

Actions
Copy link
 #5

Updated by 俊 王 over 5 years ago

rbd mirror daemon log:
---------------------------
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.464998 7f94877ce700 1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465009 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465018 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465022 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:32 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:32.543205 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40beca0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.391266 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e401cfc0 [2/17d1ccab-87e7-49f9-a61c-da787f3fd5ea] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.412414 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40c13b0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.455938 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e40393c0 [2/2660fb8a-7145-494a-aa23-2aef28792d9a] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.598931 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40ad170 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.632911 7f94edcb3700 -1 rbd::mirror::ImageReplayer: 0x7f94e403ab80 [2/9e239cf4-6b89-4824-9e1c-a32ec8daf7d9] operator(): start failed: (17) File exists

Actions
Copy link
 #6

Updated by liuzhong chen over 5 years ago

俊 王 wrote:

rbd mirror daemon log:
---------------------------
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.464998 7f94877ce700 1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465009 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465018 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465022 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:32 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:32.543205 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40beca0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.391266 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e401cfc0 [2/17d1ccab-87e7-49f9-a61c-da787f3fd5ea] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.412414 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40c13b0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.455938 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e40393c0 [2/2660fb8a-7145-494a-aa23-2aef28792d9a] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.598931 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40ad170 handle_get_remote_tags: split-brain detected - skipping image replaysplit-brain
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.632911 7f94edcb3700 -1 rbd::mirror::ImageReplayer: 0x7f94e403ab80 [2/9e239cf4-6b89-4824-9e1c-a32ec8daf7d9] operator(): start failed: (17) File exists

look at " handle_get_remote_tags: split-brain detected -- skipping image replay" in mirror daemon log, mirror image has split-brain detected,you must use "rbd mirror resync" to solve split-brain first.

Actions
Copy link
 #7

Updated by 俊 王 over 5 years ago

liuzhong chen wrote:

俊 王 wrote:

rbd mirror daemon log:
---------------------------
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.464998 7f94877ce700 1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465009 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465018 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
Nov 5 11:23:24 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:24.465022 7f94877ce700 -1 rbd::mirror::ImageReplayer: 0x7f94e4082120 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
Nov 5 11:23:32 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:32.543205 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40beca0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.391266 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e401cfc0 [2/17d1ccab-87e7-49f9-a61c-da787f3fd5ea] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.412414 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40c13b0 handle_get_remote_tags: split-brain detected - skipping image replay
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.455938 7f94edcb3700 1 rbd::mirror::ImageReplayer: 0x7f94e40393c0 [2/2660fb8a-7145-494a-aa23-2aef28792d9a] operator(): start failed: (17) File exists
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.598931 7f949aff5700 -1 rbd::mirror::image_replayer::BootstrapRequest: 0x7f94e40ad170 handle_get_remote_tags: split-brain detected - skipping image replaysplit-brain
Nov 5 11:23:33 mirror-ceph2-vm1 rbd-mirror: 2018-11-05 11:23:33.632911 7f94edcb3700 -1 rbd::mirror::ImageReplayer: 0x7f94e403ab80 [2/9e239cf4-6b89-4824-9e1c-a32ec8daf7d9] operator(): start failed: (17) File exists

look at " handle_get_remote_tags: split-brain detected -- skipping image replay" in mirror daemon log, mirror image has split-brain detected,you must use "rbd mirror resync" to solve split-brain first.

OK, I'll try it,and still focus on it

Actions
Copy link
 #8

Updated by Nathan Cutler over 5 years ago

  • Project changed from Ceph to rbd
  • Category deleted (cephx)
Actions
Copy link
 #9

Updated by Jason Dillaman over 5 years ago

  • Status changed from New to Need More Info

It appears like your "rbd-mirror" daemon does not have write access to the local cluster and/or pool: "Operation not permitted". Can you add "debug rbd = 20" to your "rbd-mirror" daemon so that I can see where in "librbd" that error is occurring?

Actions
Copy link
 #10

Updated by 俊 王 over 5 years ago

Jason Dillaman wrote:

It appears like your "rbd-mirror" daemon does not have write access to the local cluster and/or pool: "Operation not permitted". Can you add "debug rbd = 20" to your "rbd-mirror" daemon so that I can see where in "librbd" that error is occurring?

OK,thank you for your message

Actions
Copy link
 #11

Updated by 俊 王 over 5 years ago

Look at this log.The pool named test_vms is still sync,but mirror-pool-test is already stop.

=============
[root@mirror-ceph1-vm3 ~]# rbd mirror image status mirror-pool-test/image1
image1:
global_id: 95d21b92-8f07-492c-98a3-a34e8e85880e
state: up+stopped
description: local image is primary
last_update: 2018-11-07 17:50:32

=============

=============
2018-11-07 03:26:04.092484 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_start_replay: r=0
2018-11-07 03:26:04.092492 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] update_mirror_image_status:
2018-11-07 03:26:04.092494 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] start_mirror_image_status_update:
2018-11-07 03:26:04.092495 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] queue_mirror_image_status_update:
2018-11-07 03:26:04.092498 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] reschedule_update_status_task:
2018-11-07 03:26:04.092501 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] start_mirror_image_status_update: already sending update
2018-11-07 03:26:04.092503 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] reschedule_update_status_task: canceled task
2018-11-07 03:26:04.092508 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] finish_mirror_image_status_update: waiting on 1 in-flight updates
2018-11-07 03:26:04.092586 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_start_replay: m_remote_journaler=[metadata=[oid=journal.206956b8b4567, initialized=1, order=24, splay_width=4, pool_id=-1, minimum_set=0, active_set=0, client_id=4e5cd4d1-80ee-4803-aacf-77c6b319d969, commit_tid=0, commit_interval=5, commit_position=[positions=[]], registered_clients=[[id=, commit_position=[positions=[[object_number=3, tag_tid=3, entry_tid=3], [object_number=2, tag_tid=3, entry_tid=2], [object_number=1, tag_tid=3, entry_tid=1], [object_number=0, tag_tid=3, entry_tid=0]]], state=connected], [id=4e5cd4d1-80ee-4803-aacf-77c6b319d969, commit_position=[positions=[]], state=connected]]]]
2018-11-07 03:26:04.092610 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_start_replay: start succeeded
2018-11-07 03:26:04.092703 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 get_or_send_update:
2018-11-07 03:26:04.092712 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 calculate_behind_master_or_send_update: m_master_position=[object_number=3, tag_tid=3, entry_tid=3], m_mirror_position=[object_number=0, tag_tid=0, entry_tid=0]
2018-11-07 03:26:04.092726 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 send_update_tag_cache: master_tag_tid=3, mirror_tag_tid=0
2018-11-07 03:26:04.092750 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 get_or_send_update: need to update tag cache
2018-11-07 03:26:04.092752 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] send_mirror_status_update: waiting for replay status
2018-11-07 03:26:04.093512 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 handle_update_tag_cache: retrieved tag 3: [tid=3, tag_class=0, data=00000000 00 00 00 00 00 00 00 00 01 02 00 00 00 00 00 00 |................|
00000010 00 00 00 00 00 00 00 00 00 |.........|
00000019
]

2018-11-07 03:26:04.093525 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 handle_update_tag_cache: decoded tag 3: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=2, entry_tid=0]]
2018-11-07 03:26:04.093528 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 send_update_tag_cache: master_tag_tid=2, mirror_tag_tid=0
2018-11-07 03:26:04.094474 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 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 |................|
00000010 00 01 00 00 00 00 00 00 00 |.........|
00000019
]
2018-11-07 03:26:04.094492 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 handle_update_tag_cache: decoded tag 2: [mirror_uuid=, predecessor=[mirror_uuid=, tag_tid=1, entry_tid=1]]
2018-11-07 03:26:04.094497 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 send_update_tag_cache: master_tag_tid=1, mirror_tag_tid=0
2018-11-07 03:26:04.094663 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_ready: enter
2018-11-07 03:26:04.094673 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] preprocess_entry: preprocessing entry tid=1
2018-11-07 03:26:04.094690 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_preprocess_entry_ready: r=0
2018-11-07 03:26:04.094694 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] process_entry: processing entry tid=1
2018-11-07 03:26:04.094772 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_ready:
2018-11-07 03:26:04.094775 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_ready: enter
2018-11-07 03:26:04.094780 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] preprocess_entry: preprocessing entry tid=2
2018-11-07 03:26:04.094783 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_preprocess_entry_ready: r=0
2018-11-07 03:26:04.094785 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] process_entry: processing entry tid=2
2018-11-07 03:26:04.094810 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: commit_tid=1, r=-1
2018-11-07 03:26:04.094812 7fd5c37d6700 -1 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
2018-11-07 03:26:04.094815 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: r=-1
2018-11-07 03:26:04.094816 7fd5c37d6700 -1 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
2018-11-07 03:26:04.094818 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] set_state_description: -1 failed to commit journal event
2018-11-07 03:26:04.094820 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] on_stop_journal_replay: enter
2018-11-07 03:26:04.094821 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] set_state_description: 0

2018-11-07 03:26:04.094822 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] update_mirror_image_status:
2018-11-07 03:26:04.094823 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] start_mirror_image_status_update: shut down in-progress: ignoring update
2018-11-07 03:26:04.094824 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] reschedule_update_status_task:
2018-11-07 03:26:04.094825 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] shut_down: r=0
2018-11-07 03:26:04.094827 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] shut_down: waiting for in-flight status update
2018-11-07 03:26:04.094829 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: commit_tid=2, r=-1
2018-11-07 03:26:04.094830 7fd5c37d6700 -1 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_safe: failed to commit journal event: (1) Operation not permitted
2018-11-07 03:26:04.094832 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: r=-1
2018-11-07 03:26:04.094833 7fd5c37d6700 -1 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_complete: replay encountered an error: (1) Operation not permitted
2018-11-07 03:26:04.094834 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] set_state_description: -1 failed to commit journal event
2018-11-07 03:26:04.094835 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] on_stop_journal_replay: enter
2018-11-07 03:26:04.094838 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_process_entry_ready:
2018-11-07 03:26:04.094839 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_replay_ready: enter
2018-11-07 03:26:04.094840 7fd5c37d6700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] on_stop_journal_replay: enter
2018-11-07 03:26:04.095978 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 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 |................|
00000010 00 00 00 00 00 00 00 00 00 |.........|
00000019
]
2018-11-07 03:26:04.095999 7fd5c8fe1700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x7fd5f0052510 handle_update_tag_cache: decoded tag 1: [mirror_uuid=, predecessor=[mirror_uuid=]]
2018-11-07 03:26:04.096002 7fd5c8fe1700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] operator(): replay status ready: r=0
2018-11-07 03:26:04.096004 7fd5c8fe1700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] send_mirror_status_update: status=[state=up+error, description=stopping replay, last_update=0.000000]
2018-11-07 03:26:04.100191 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_mirror_status_update: r=0
2018-11-07 03:26:04.100216 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] finish_mirror_image_status_update:
2018-11-07 03:26:04.100218 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] shut_down: r=0

2018-11-07 03:26:04.100270 7fd5c37d6700 20 rbd::mirror::image_replayer::CloseImageRequest: 0x7fd5f00160d0 close_image
2018-11-07 03:26:04.118768 7fd5c37d6700 20 rbd::mirror::image_replayer::CloseImageRequest: 0x7fd5f00160d0 handle_close_image: r=0
2018-11-07 03:26:04.122816 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] update_mirror_image_status:
2018-11-07 03:26:04.122822 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] start_mirror_image_status_update:
2018-11-07 03:26:04.122823 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] queue_mirror_image_status_update:
2018-11-07 03:26:04.122825 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] reschedule_update_status_task:
2018-11-07 03:26:04.122827 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_shut_down: waiting for in-flight status update
2018-11-07 03:26:04.122830 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] send_mirror_status_update: status=[state=up+error, description=failed to commit journal event, last_update=0.000000]
2018-11-07 03:26:04.127064 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_mirror_status_update: r=0
2018-11-07 03:26:04.127075 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] finish_mirror_image_status_update:
2018-11-07 03:26:04.127077 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] reschedule_update_status_task:
2018-11-07 03:26:04.127079 7fd5cffef700 20 rbd::mirror::ImageReplayer: 0x7fd618012970 [6/f74f8b68-9e42-46c1-be88-1badf73360b0] handle_shut_down: stop complete
2018-11-07 03:26:04.913851 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 execute_timer_task:
2018-11-07 03:26:04.913878 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 is_leader: 1
2018-11-07 03:26:04.913884 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 notify_heartbeat:
2018-11-07 03:26:04.913888 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 is_leader: 1
2018-11-07 03:26:04.914813 7fd5cffef700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 handle_notify: notify_id=1245540658303, handle=93831259513440, notifier_id=190580
2018-11-07 03:26:04.914821 7fd5cffef700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 handle_notify: our own notification, ignoring
2018-11-07 03:26:04.915632 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 handle_notify_heartbeat: r=0
2018-11-07 03:26:04.915640 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 is_leader: 1
2018-11-07 03:26:04.915642 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 handle_notify_heartbeat: 3 acks received, 0 timed out
2018-11-07 03:26:04.915649 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 notify: 190592
2018-11-07 03:26:04.915653 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 notify: 194239
2018-11-07 03:26:04.915673 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cae45f30 schedule_timer_task: scheduling heartbeat after 5 sec (task 0x7fd6181233a0)
2018-11-07 03:26:04.915683 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 handle_notify: 190592
2018-11-07 03:26:04.915686 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 schedule_remove_task:
2018-11-07 03:26:04.915687 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 cancel_remove_task: 0x7fd618179a80
2018-11-07 03:26:04.915698 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 schedule_remove_task: scheduling instance 190592 remove after 30 sec (task 0x7fd618179a80)
2018-11-07 03:26:04.915702 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 handle_notify: 194239
2018-11-07 03:26:04.915703 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 schedule_remove_task:
2018-11-07 03:26:04.915704 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 cancel_remove_task: 0x7fd6180d3750

2018-11-07 03:26:04.915709 7fd6277fe700 20 rbd::mirror::Instances: 0x5556cae475e0 schedule_remove_task: scheduling instance 194239 remove after 30 sec (task 0x7fd6180d3750)
2018-11-07 03:26:04.996204 7fd626ffd700 20 rbd::mirror::ServiceDaemon: 0x5556ca9596d0 update_status:
2018-11-07 03:26:05.163069 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 execute_timer_task:
2018-11-07 03:26:05.163086 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 is_leader: 1
2018-11-07 03:26:05.163089 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 notify_heartbeat:
2018-11-07 03:26:05.163090 7fd626ffd700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 is_leader: 1
2018-11-07 03:26:05.164216 7fd5ef7fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 handle_notify: notify_id=1245540661012, handle=140556428651536, notifier_id=190577
2018-11-07 03:26:05.164224 7fd5ef7fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 handle_notify: our own notification, ignoring
2018-11-07 03:26:05.164980 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 handle_notify_heartbeat: r=0
2018-11-07 03:26:05.164992 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 is_leader: 1
2018-11-07 03:26:05.164995 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 handle_notify_heartbeat: 3 acks received, 0 timed out
2018-11-07 03:26:05.165001 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 notify: 194221
2018-11-07 03:26:05.165005 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 notify: 195024
2018-11-07 03:26:05.165022 7fd6277fe700 20 rbd::mirror::LeaderWatcher: 0x5556cac22e00 schedule_timer_task: scheduling heartbeat after 5 sec (task 0x7fd61808fcb0)
2018-11-07 03:26:05.165031 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 handle_notify: 194221
2018-11-07 03:26:05.165034 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 schedule_remove_task:
2018-11-07 03:26:05.165036 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 cancel_remove_task: 0x7fd618160a50
2018-11-07 03:26:05.165047 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 schedule_remove_task: scheduling instance 194221 remove after 30 sec (task 0x7fd618160a50)
2018-11-07 03:26:05.165052 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 handle_notify: 195024
2018-11-07 03:26:05.165054 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 schedule_remove_task:
2018-11-07 03:26:05.165055 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 cancel_remove_task: 0x7fd618037d60
2018-11-07 03:26:05.165062 7fd6277fe700 20 rbd::mirror::Instances: 0x7fd5d8057830 schedule_remove_task: scheduling instance 195024 remove after 30 sec (task 0x7fd618037d60)
2018-11-07 03:26:06.211390 7fd626ffd700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] queue_mirror_image_status_update:
2018-11-07 03:26:06.211436 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cae94bd0 get_or_send_update:
2018-11-07 03:26:06.211462 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cae94bd0 calculate_behind_master_or_send_update: m_master_position=[object_number=0, tag_tid=11, entry_tid=20], m_mirror_position=[object_number=0, tag_tid=11, entry_tid=20]
2018-11-07 03:26:06.211471 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cae94bd0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-11-07 03:26:06.211473 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cae94bd0 calculate_behind_master_or_send_update: 0 entries cleared
2018-11-07 03:26:06.211476 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cae94bd0 format: m_master_position=[object_number=0, tag_tid=11, entry_tid=20], m_mirror_position=[object_number=0, tag_tid=11, entry_tid=20], m_entries_behind_master=0
2018-11-07 03:26:06.211493 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] operator(): replay status ready: r=-17
2018-11-07 03:26:06.211499 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] send_mirror_status_update: status=[state=up+replaying, description=replaying, master_position=[object_number=0, tag_tid=11, entry_tid=20], mirror_position=[object_number=0, tag_tid=11, entry_tid=20], entries_behind_master=0, last_update=0.000000]

2018-11-07 03:26:06.215647 7fd626ffd700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] queue_mirror_image_status_update:
2018-11-07 03:26:06.215695 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cac1e8a0 get_or_send_update:
2018-11-07 03:26:06.215714 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cac1e8a0 calculate_behind_master_or_send_update: m_master_position=[object_number=29, tag_tid=10, entry_tid=98897], m_mirror_position=[object_number=29, tag_tid=10, entry_tid=98897]
2018-11-07 03:26:06.215718 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cac1e8a0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-11-07 03:26:06.215719 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cac1e8a0 calculate_behind_master_or_send_update: 0 entries cleared
2018-11-07 03:26:06.215721 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556cac1e8a0 format: m_master_position=[object_number=29, tag_tid=10, entry_tid=98897], m_mirror_position=[object_number=29, tag_tid=10, entry_tid=98897], m_entries_behind_master=0
2018-11-07 03:26:06.215727 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] operator(): replay status ready: r=-17
2018-11-07 03:26:06.215731 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] send_mirror_status_update: status=[state=up+replaying, description=replaying, master_position=[object_number=29, tag_tid=10, entry_tid=98897], mirror_position=[object_number=29, tag_tid=10, entry_tid=98897], entries_behind_master=0, last_update=0.000000]
2018-11-07 03:26:06.217132 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] handle_mirror_status_update: r=0

2018-11-07 03:26:06.217146 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] reschedule_update_status_task:
2018-11-07 03:26:06.217150 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] start_mirror_image_status_update:
2018-11-07 03:26:06.217167 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618082d40 [2/077625f4-b9f9-45a2-b8c0-7cc7d901fcdf] finish_mirror_image_status_update: waiting on 1 in-flight updates
2018-11-07 03:26:06.219910 7fd626ffd700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] queue_mirror_image_status_update:
2018-11-07 03:26:06.219972 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556caede6e0 get_or_send_update:
2018-11-07 03:26:06.220023 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556caede6e0 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=1, entry_tid=3]
2018-11-07 03:26:06.220030 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556caede6e0 calculate_behind_master_or_send_update: clearing tags not needed any more (below mirror position)
2018-11-07 03:26:06.220032 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556caede6e0 calculate_behind_master_or_send_update: 0 entries cleared
2018-11-07 03:26:06.220035 7fd6277fe700 20 rbd::mirror::image_replayer::ReplayStatusFormatter: 0x5556caede6e0 format: m_master_position=[object_number=3, tag_tid=1, entry_tid=3], m_mirror_position=[object_number=3, tag_tid=1, entry_tid=3], m_entries_behind_master=0

2018-11-07 03:26:06.220051 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] operator(): replay status ready: r=-17
2018-11-07 03:26:06.220058 7fd6277fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] send_mirror_status_update: status=[state=up+replaying, description=replaying, master_position=[object_number=3, tag_tid=1, entry_tid=3], mirror_position=[object_number=3, tag_tid=1, entry_tid=3], entries_behind_master=0, last_update=0.000000]
2018-11-07 03:26:06.222054 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] handle_mirror_status_update: r=0
2018-11-07 03:26:06.222066 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] reschedule_update_status_task:
2018-11-07 03:26:06.222070 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] start_mirror_image_status_update:
2018-11-07 03:26:06.222083 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd61813f330 [2/b03569f6-3b2b-478c-bd71-692b1d3f270e] finish_mirror_image_status_update: waiting on 1 in-flight updates
2018-11-07 03:26:06.225627 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] handle_mirror_status_update: r=0
2018-11-07 03:26:06.225640 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] reschedule_update_status_task:
2018-11-07 03:26:06.225644 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] start_mirror_image_status_update:
2018-11-07 03:26:06.225656 7fd5ef7fe700 20 rbd::mirror::ImageReplayer: 0x7fd618140420 [2/c9453634-c2e6-424c-96ab-9d823bc1efc8] finish_mirror_image_status_update: waiting on 1 in-flight updates
2018-11-07 03:26:06.506203 7fd63a61c340 20 rbd::mirror::ClusterWatcher:0x5556ca9fe060 refresh_pools: enter
2018-11-07 03:26:06.509329 7fd63a61c340 20 librbd::api::Mirror: peer_list:
2018-11-07 03:26:06.511456 7fd63a61c340 20 librbd::api::Mirror: peer_list:
2018-11-07 03:26:06.512862 7fd63a61c340 10 rbd::mirror::ClusterWatcher:0x5556ca9fe060 read_pool_peers: mirroring is disabled for pool mirror-pool-test
2018-11-07 03:26:06.512871 7fd63a61c340 20 rbd::mirror::Mirror: 0x5556ca9578f0 update_pool_replayers: enter

=============

Actions
Copy link
 #12

Updated by Jason Dillaman over 5 years ago

I still require the librbd debug logs in addition to the rbd-mirror debug logs.

Actions
Copy link
 #13

Updated by 俊 王 over 5 years ago

Jason Dillaman wrote:

I still require the librbd debug logs in addition to the rbd-mirror debug logs.

I was set confg like this:
"ceph daemon /var/run/ceph/ceph-client.rbd-mirror.ceph2.asok config set debug_rbd 20"

but only rbd-mirror bug logs in ceph-client.rbd-mirror.ceph2.log.Is it wrong?

Actions
Copy link
 #14

Updated by Mykola Golub over 5 years ago

俊 王 wrote:

I was set confg like this:
"ceph daemon /var/run/ceph/ceph-client.rbd-mirror.ceph2.asok config set debug_rbd 20"

but only rbd-mirror bug logs in ceph-client.rbd-mirror.ceph2.log.Is it wrong?

rbd-mirror has many ceph contexts: one global, and 2 (local, remote) for every pool. Every context has it's own log settings and is controlled by it's own admin socket. It looks like in your case you were operating with asok for the global context, so you changed the rbd log level only for this context, which is actually is not very interesting. You need to find the asok for the local context for the affected pool. For this you try run:

  ceph daemon /var/run/ceph/ceph-client.rbd-mirror.ceph2.asok rbd mirror status

and look for lines like this:
        {
            "pool": "<THE AFFECTED POOL NAME>",
            ...
            "local_cluster_admin_socket": "/var/run/ceph/ceph-client.rbd-mirror.ceph2.XXXXX.asok",
            "remote_cluster_admin_socket": "/var/run/ceph/ceph-client.rbd-mirror.ceph2.YYYYY.asok",

And then run `config set debug_rbd 20` using the socket specified as "local_cluster_admin_socket".

Or you can just scan /var/run/ceph/ for all rbd-mirror asok files and set the debug level on all of them.

Actions
Copy link
 #15

Updated by Mykola Golub over 5 years ago

And it will probably be better to attach the full log instead of pasting.

Actions
Copy link
 #16

Updated by 俊 王 over 5 years ago

Mykola Golub wrote:

And it will probably be better to attach the full log instead of pasting.

thanks,I'll try it.

Actions
Copy link
 #17

Updated by 俊 王 over 5 years ago

It's normal in these days.Is there any possible that my physical machine's memory is useless,and rbd-mirror's threads were killed by the vm's kernel?

Actions
Copy link
 #18

Updated by 俊 王 over 5 years ago

俊 王 wrote:

It's normal in these days.Is there any possible that my physical machine's memory is useless,and rbd-mirror's threads were killed by the vm's kernel?

sorry,memory is used up.

Actions
Copy link
 #19

Updated by Jason Dillaman about 5 years ago

  • Status changed from Need More Info to Closed
Actions
Copy link

Also available in: Atom PDF