Ceph » RADOS

I will reproduce, fix and verify this bug. Then will send code review of bugfix.

Hi Song,

Could you please confirm the ceph version with the output of "ceph-mds --version"?

Ilya Dryomov wrote:

Hi Song,

Could you please confirm the ceph version with the output of "ceph-mds --version"?

hi，llya
Sorry, Because we've made changes，I can't get the version the way you say it is。Is the following method possible?

[root@ceph1 ~]# rpm -qa | grep ceph-mds
ceph-mds-15.2.0-1.0.2.3.0_2104292130.el8.x86_64

So you are running the original octopus release with custom patches added in?

Ilya Dryomov wrote:

So you are running the original octopus release with custom patches added in?

just a little change, I think the bug has nothing to do with it. As I described, I think the mon leader sync rotate secret keys failed, but I just saw "trigger_propose not active, will propose later",I don't know Whether there will be a propose again and When to propose again.

But it is the original octopus release with no substantial backports, correct?

In particular, can you confirm that you don't have any of

https://tracker.ceph.com/issues/50452
https://github.com/ceph/ceph/compare/cbc7f727842f93130fcfbbad64de0959ee4a02d3...f3a4166379b12d4a7bba667fe761e5b660552db1

changes included in your build?

Ilya Dryomov wrote:

But it is the original octopus release with no substantial backports, correct?

In particular, can you confirm that you don't have any of

https://tracker.ceph.com/issues/50452
https://github.com/ceph/ceph/compare/cbc7f727842f93130fcfbbad64de0959ee4a02d3...f3a4166379b12d4a7bba667fe761e5b660552db1

changes included in your build?

Indeed, there is no change above in our build,I saw these changes, do you think bug is fixed by changes above? or is there a definite patch that can solve this problem?

No, it's the other way around -- there is some suspicion that https://tracker.ceph.com/issues/50390 is caused by these changes because it appeared right after they got merged.

The fact that you don't have them in your build means that either your bug is different from https://tracker.ceph.com/issues/50390 or that these changes have nothing to do with failures to obtain rotating service keys that you and Patrick are seeing.

I posted https://github.com/ceph/ceph/pull/41368, please take a look. It's probably not going to solve an edge case of restarting multiple daemons repeatedly, but it's definitely a step towards that.

Ilya Dryomov wrote:

I posted https://github.com/ceph/ceph/pull/41368, please take a look. It's probably not going to solve an edge case of restarting multiple daemons repeatedly, but it's definitely a step towards that.

hi，llya
I've seen this commit,It really can't solve this bug,Thank you all the same

wenge song wrote:

Ilya Dryomov wrote:

I posted https://github.com/ceph/ceph/pull/41368, please take a look. It's probably not going to solve an edge case of restarting multiple daemons repeatedly, but it's definitely a step towards that.

hi，llya
I've seen this commit,It really can't solve this bug,Thank you all the same

hi llya
I posted https://github.com/ceph/ceph/pull/41438, please review. I change the code and can't repeat this bug.

Can you share the full monitor logs? Specifically, I'm interested in the log where the following excerpt came from

2021-05-12T15:07:43.654+0800 7f5f761f9700 10 mon.a@0(leader).auth v5687 check_rotate updated rotating
2021-05-12T15:07:43.654+0800 7f5f761f9700 10 mon.a@0(leader).paxosservice(auth 5508..5687) propose_pending
2021-05-12T15:07:43.654+0800 7f5f761f9700 10 mon.a@0(leader).auth v5687 encode_pending v 5688
2021-05-12T15:07:43.669+0800 7f5f761f9700 10 mon.a@0(leader) e3 log_health updated 0 previous 0
2021-05-12T15:07:43.669+0800 7f5f761f9700 5 mon.a@0(leader).paxos(paxos updating c 409133..409838) queue_pending_finisher 0x557067a8a690
2021-05-12T15:07:43.669+0800 7f5f761f9700 10 mon.a@0(leader).paxos(paxos updating c 409133..409838) trigger_propose not active, will propose later

but also all peon monitor logs as well.

Just to be clear, are you saying that if the proposal with the new keys doesn't get sent because trigger_propose() returns false, the peon monitors don't get new keys until the next renewal (i.e. 120 seconds later in your case)?

Because ordinarily trigger_propose() would simply delay the proposal, not discard it entirely. Are you seeing the proposal with the new keys being discarded?

Ilya Dryomov wrote:

Can you share the full monitor logs? Specifically, I'm interested in the log where the following excerpt came from

[...]

but also all peon monitor logs as well.

thanks for your review and reply,I need reproduce this bug again for more logs.

Ilya Dryomov wrote:

Just to be clear, are you saying that if the proposal with the new keys doesn't get sent because trigger_propose() returns false, the peon monitors don't get new keys until the next renewal (i.e. 120 seconds later in your case)?

Because ordinarily trigger_propose() would simply delay the proposal, not discard it entirely. Are you seeing the proposal with the new keys being discarded?

You are right,I didn't seen the proposal with the new keys being discarded,but when the new keys rotating and trigger_propose return false. mds and osd unable get new keys from peon moniter,I think mon leader did not push new secret to other peon mon in time or other reason cause push it failed,so I modified code to try pushing new secret for more times. Maybe I got it wrong,So need more in-depth discussion.

wenge song wrote:

mds.b unable to obtain rotating service keys,this is mds.b log

2021-05-24T18:48:22.934+0800 7f4853f19700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2021-05-24T18:47:52.934877+0800)

The logs that you provided are weird. Some log messages that should be there are not there. For example, I don't see a single update_from_paxos log message, but they should be there given that mon.b was restarted multiple times and other log messages at "debug mon = 10" level are there.

And some log messages seem to have had their log level adjusted. For example, _rotate_secret and _check_rotating_secrets log messages are not 0 upstream.

Please remove all modifications to the logging infrastructure and reproduce with "debug mon = 30", "debug monc = 30", "debug auth = 30" and "debug ms = 1" on all daemons. Don't selectively enable only certain log messages -- I'd like to see all of them.

Out of curiosity, how many iterations of bugshell does it take to reproduce? I might try it on the weekend, but it would be a lot easier if you provide a set of verbose logs of course.

Ilya Dryomov wrote:

Out of curiosity, how many iterations of bugshell does it take to reproduce? I might try it on the weekend, but it would be a lot easier if you provide a set of verbose logs of course.

It's not a fixed iterations of bugshel，I reproduced it in seventy-six iterations of bugshel last time。Maybe you can try it.As a reminder, you need run the bugshell on two ceph nodes. I will reproduce it again to provide more detailed logs in my spare time.

These logs are still weird. Now there is plenty of update_from_paxos log messages but virtually no paxosservice log messages. This can't be how it actually ran...

What modifications did you apply to the logging infrastructure? Are you somehow enabling logging on a per file basis?

Please remove all modifications to the logging infrastructure so that all log messages which correspond to "debug mon = 30", "debug monc = 30", "debug auth = 30" and "debug ms = 1" make it to the log file.

Yes, "debug paxos = 30" would definitely help! Sorry, I missed it because the previous set of logs that you shared had them (perhaps not at 30 but still) so I just assumed they would stay enabled.

Basically the ask is a set of logs that is as verbose as possible so that anyone who looks at it doesn't end up scratching their head wondering whether a particular log line is missing because it didn't get executed or because it simply wasn't enabled.

We ran into this issue, too. Our environment is a multi-host cluster (v15.2.9). Sometimes, we can observe that "unable to obtain rotating service keys" errors happened on mds and osds because these daemons seemed to actually keep getting older version of rotating keys which already expired. They were unable to get correct version of rotating keys. Until next key renewal (within an hour), they finally got new and correct version of rotating keys and were able to boot successfully.