Project

General

Profile

Bug #44229

monclient: _check_auth_rotating possible clock skew, rotating keys expired way too early

Added by Sage Weil over 3 years ago. Updated over 1 year ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
% Done:

0%

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

Description

seems to affect cephadm bootstrap tests

first, the error message doesn't make sense, since the bound 2020-02-20T16:39:29.638933+0000 is before all keys (including the second).

2020-02-20T17:39:29.634+0000 7ff65b8ca700 -1 monclient: _check_auth_rotating possible clock skew, rotating keys expired way too early (before 2020-02-20T16:39:29.638933+0000)
2020-02-20T17:39:29.634+0000 7ff65b8ca700 10 cephx client: build_rotating_request
2020-02-20T17:39:29.634+0000 7ff65b8ca700 10 monclient: _send_mon_message to mon.a at v2:172.21.15.172:3300/0
2020-02-20T17:39:29.634+0000 7ff65b8ca700  1 -- 172.21.15.172:0/1 --> [v2:172.21.15.172:3300/0,v1:172.21.15.172:6789/0] -- auth(proto 2 2 bytes epoch 0) v1 -- 0x557f24dde780 con 0x557f249a0000
2020-02-20T17:39:29.634+0000 7ff65b8ca700 20 monclient: _un_backoff reopen_interval_multipler now 1
2020-02-20T17:39:33.782+0000 7ff63667b700 10 monclient: tick
2020-02-20T17:39:33.782+0000 7ff63667b700 10 cephx: validate_tickets want 53 have 53 need 0
2020-02-20T17:39:33.782+0000 7ff63667b700 20 cephx client: need_tickets: want=53 have=53 need=0
2020-02-20T17:39:33.782+0000 7ff63667b700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2020-02-20T17:39:03.786277+0000)
2020-02-20T17:39:33.782+0000 7ff63667b700 10 auth: dump_rotating:
2020-02-20T17:39:33.782+0000 7ff63667b700 10 auth:  id 4 AQD7nU5eq9HAABAAwGJgrYnHS0jVLO2hG+ygVQ== expires 2020-02-20T16:55:55.012634+0000
2020-02-20T17:39:33.782+0000 7ff63667b700 10 auth:  id 5 AQALrE5eVEwYKBAAMKra4/Vm9oo9l3UliFxcsw== expires 2020-02-20T17:55:55.672678+0000
2020-02-20T17:39:33.782+0000 7ff63667b700 10 auth:  id 6 AQAcuk5euvxiFBAAb8P8rCQqeyCxyc6wXKtgSA== expires 2020-02-20T18:55:56.342029+0000
2020-02-20T17:39:33.782+0000 7ff63667b700 20 monclient: _un_backoff reopen_interval_multipler now 1
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 monclient: tick
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx: validate_tickets want 55 have 0 need 55
2020-02-20T17:39:39.634+0000 7ff65b8ca700 20 cephx client: need_tickets: want=55 have=0 need=55
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 monclient: _check_auth_tickets getting new tickets!
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx client: validate_tickets: want=55 need=55 have=0
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx: validate_tickets want 55 have 0 need 55
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx client: want=55 need=55 have=0
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx client: build_request
2020-02-20T17:39:39.634+0000 7ff65b8ca700 20 cephx client: old ticket len=96
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 cephx client: get auth session key: client_challenge 8a536ddbad576d60
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 monclient: _send_mon_message to mon.a at v2:172.21.15.172:3300/0
2020-02-20T17:39:39.634+0000 7ff65b8ca700  1 -- 172.21.15.172:0/1 --> [v2:172.21.15.172:3300/0,v1:172.21.15.172:6789/0] -- auth(proto 2 132 bytes epoch 0) v1 -- 0x557f1eb05980 con 0x557f249a0000
2020-02-20T17:39:39.634+0000 7ff65b8ca700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2020-02-20T17:39:09.639238+0000)
2020-02-20T17:39:39.634+0000 7ff65b8ca700 -1 monclient: _check_auth_rotating possible clock skew, rotating keys expired way too early (before 2020-02-20T16:39:39.639238+0000)

second, this is happening because the auth_reply messages aren't coming back, because the dispatch thread appears to be stuck.

/a/sage-2020-02-20_01:58:47-rados-wip-sage2-testing-2020-02-19-1657-distro-basic-smithi/4783296

History

#1 Updated by Sage Weil over 3 years ago

  • Status changed from New to Can't reproduce

#2 Updated by Radoslaw Zarzynski over 1 year ago

  • Status changed from Can't reproduce to New
  • Priority changed from Urgent to Normal

Perhaps this replicated in:

/home/teuthworker/archive/yuriw-2022-04-29_15:44:49-rados-wip-yuri5-testing-2022-04-28-1007-distro-default-smithi/6813824

#3 Updated by Radoslaw Zarzynski over 1 year ago 

rzarzynski@teuthology:~$ less /home/teuthworker/archive/yuriw-2022-04-29_15:44:49-rados-wip-yuri5-testing-2022-04-28-1007-distro-default-smithi/6813824/remote/smithi160/log/ceph-mgr.x.log.gz
...
2022-04-29T17:14:42.748+0000 7f25edb3c700 10 cephx client: build_rotating_request
2022-04-29T17:14:42.748+0000 7f25edb3c700 10 monclient: _send_mon_message to mon.noname-b at v2:172.21.15.160:3300/0
2022-04-29T17:14:42.748+0000 7f25edb3c700  1 -- 172.21.15.160:0/26190 --> [v2:172.21.15.160:3300/0,v1:172.21.15.160:6789/0] -- auth(proto 2 2 bytes epoch 0) v1 -- 0x5621e4565980 con 0x5621e3858800
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 monclient: tick
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx: validate_tickets want 55 have 32 need 23
2022-04-29T17:14:43.748+0000 7f25edb3c700 20 cephx client: need_tickets: want=55 have=32 need=23
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 monclient: _check_auth_tickets getting new tickets!
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx client: validate_tickets: want=55 need=23 have=32
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx: validate_tickets want 55 have 32 need 23
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx client: want=55 need=23 have=32
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx client: build_request
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx client: get service keys: want=55 need=23 have=32
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 monclient: _send_mon_message to mon.noname-b at v2:172.21.15.160:3300/0
2022-04-29T17:14:43.748+0000 7f25edb3c700  1 -- 172.21.15.160:0/26190 --> [v2:172.21.15.160:3300/0,v1:172.21.15.160:6789/0] -- auth(proto 2 165 bytes epoch 0) v1 -- 0x5621e4565b00 con 0x5621e3858800
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 monclient: _check_auth_rotating renewing rotating keys (they expired before 2022-04-29T17:14:13.751398+0000)
2022-04-29T17:14:43.748+0000 7f25edb3c700 10 cephx client: build_rotating_request

Also available in: Atom PDF