Project

General

Profile

Bug #61547

Logs produce non-human-readable timestamps after monitor upgrade

Added by Laura Flores 9 months ago. Updated 8 months ago.

Status:
Resolved
Priority:
Normal
Category:
-
Target version:
-
% Done:

0%

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

Description

During the gibba upgrade to the Reef RC (4a02f3f496d9039326c49bf1fbe140388cd2f619), some of the logs produced non-human-readable timestamps after the first monitor upgraded:

2023-05-31T14:12:32.191450+0000 mgr.gibba006.afdywy (mgr.605280) 34 : cephadm [INF] Upgrade: It appears safe to stop mon.gibba001
2023-05-31T14:12:33.657602+0000 mgr.gibba006.afdywy (mgr.605280) 36 : cephadm [INF] Upgrade: Updating mon.gibba001
2023-05-31T14:12:33.944734+0000 mgr.gibba006.afdywy (mgr.605280) 37 : cephadm [INF] Deploying daemon mon.gibba001 on gibba001
1685542365.4473732 mgr.gibba006.afdywy (mgr.263747) 1 : cephadm 1 [31/May/2023:14:12:45] ENGINE Bus STARTING
1685542365.5504844 mgr.gibba006.afdywy (mgr.263747) 2 : cephadm 1 [31/May/2023:14:12:45] ENGINE Serving on http://172.21.2.106:8765
1685542365.6612306 mgr.gibba006.afdywy (mgr.263747) 3 : cephadm 1 [31/May/2023:14:12:45] ENGINE Serving on https://172.21.2.106:7150
1685542365.6613004 mgr.gibba006.afdywy (mgr.263747) 4 : cephadm 1 [31/May/2023:14:12:45] ENGINE Bus STARTED
1685542384.1099322 mgr.gibba006.afdywy (mgr.263747) 15 : cephadm 1 Updating gibba001:/etc/ceph/ceph.conf

ceph.cephadm.log View (157 KB) Laura Flores, 05/31/2023 10:56 PM


Related issues

Related to RADOS - Bug #58436: ceph cluster log reporting log level in numeric format for the clog messages Fix Under Review
Copied to RADOS - Backport #61579: reef: Logs produce non-human-readable timestamps after monitor upgrade Resolved

History

#1 Updated by Laura Flores 9 months ago

#2 Updated by Laura Flores 9 months ago

  • Assignee set to Laura Flores

#3 Updated by Laura Flores 9 months ago

Mgr log is on gibba006 under /root/tracker_61547, and ceph.log and mon log are on gibba001 under /root/tracker_61547. The cephadm and cluster logs had this issue, but mon and mgr logs didn’t.

#4 Updated by Laura Flores 9 months ago

A good place to look for a regression might be under src/log.

#5 Updated by Laura Flores 9 months ago

Also happened in the ceph.audit.log (on gibba001 under /root/tracker_61547).

#6 Updated by Radoslaw Zarzynski 9 months ago

On freshly built and deployed Reef RC vstart.sh cluster the timestamps in monitor's log look human readable:

2023-06-01T14:26:33.215+0000 7f59e8936700 10 mon.a@0(leader).mgrstat update_from_paxos v2413 service_map e13 0 progress events
2023-06-01T14:26:33.215+0000 7f59e8936700 10 mon.a@0(leader).mgrstat check_subs
2023-06-01T14:26:33.215+0000 7f59e8936700 10 mon.a@0(leader).mgrstat check_sub next 14 vs service_map.epoch 13
2023-06-01T14:26:33.215+0000 7f59e8936700 10 mon.a@0(leader).health update_from_paxos
2023-06-01T14:26:33.215+0000 7f59e8936700 10 mon.a@0(leader).log v2424 create_pending v 2425
2023-06-01T14:26:33.215+0000 7f59e8936700  7 mon.a@0(leader).log v2424 _updated_log for mgr.4106 127.0.0.1:0/1862718
2023-06-01T14:26:33.215+0000 7f59e8936700  2 mon.a@0(leader) e1 send_reply 0x2d824b0 0x356fb00 log(last 2413) v1
2023-06-01T14:26:33.215+0000 7f59e8936700  1 -- [v2:127.0.0.1:40048/0,v1:127.0.0.1:40049/0] --> 127.0.0.1:0/1862718 -- log(last 2413) v1 -- 0x356fb00 con 0x2d95400

However, in cluster log:

[rzarzynski@o06 build]$ head -n 10 /home/rzarzynski/ceph2/build/out/cluster.mon.a.log 
1685624754.0103514 mon.a (mon.0) 0 : cluster 1 mkfs 8e98fb5c-28cb-4052-8af6-e59f444c5f99
1685624754.0057294 mon.a (mon.0) 1 : cluster 1 mon.a is new leader, mons a in quorum (ranks 0)
1685624754.0091364 mon.a (mon.0) 2 : cluster 1 mon.a is new leader, mons a in quorum (ranks 0)
1685624754.009511 mon.a (mon.0) 3 : cluster 0 monmap e1: 1 mons at {a=[v2:127.0.0.1:40048/0,v1:127.0.0.1:40049/0]} removed_ranks: {}
1685624754.011898 mon.a (mon.0) 4 : cluster 0 fsmap 
1685624754.014718 mon.a (mon.0) 5 : cluster 0 osdmap e1: 0 total, 0 up, 0 in
1685624754.0152752 mon.a (mon.0) 6 : cluster 0 mgrmap e1: no daemons active
1685624754.1650403 mon.a (mon.0) 7 : audit 1 from='client.? 127.0.0.1:0/713798795' entity='client.admin' cmd=[{"prefix": "config assimilate-conf"}]: dispatch
1685624754.1673815 mon.a (mon.0) 8 : audit 1 from='client.? 127.0.0.1:0/713798795' entity='client.admin' cmd='[{"prefix": "config assimilate-conf"}]': finished
1685624754.360453 mon.a (mon.0) 9 : audit 1 from='client.? 127.0.0.1:0/1589453529' entity='client.admin' cmd=[{"prefix": "auth add", "entity": "mgr.x", "caps": ["mon", "allow profile mgr", "mds", "allow *", "osd", "allow *"]}]: dispatch

#7 Updated by Laura Flores 9 months ago

I verified that this problem does not exist on a v17.2.6 cluster. This indicates one of the commits since v17.2.6 is a problem.
My next steps will be going through commits (probably using the bisect method) to find which commit may be responsible.

#8 Updated by Neha Ojha 9 months ago

  • Related to Bug #58436: ceph cluster log reporting log level in numeric format for the clog messages added

#9 Updated by Laura Flores 9 months ago

Adding a note that this bug is not restricted to upgrades. We discovered it upon upgrading the monitor to Reef, but fresh Reef vstart deployments also experience the bug.

#10 Updated by Radoslaw Zarzynski 9 months ago

  • Status changed from New to In Progress

#11 Updated by Laura Flores 9 months ago

Git bisect ended with:

[lflores@folio01 ceph]$ git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[6e223a6802152fc689ecdbf38fb4a410123844c7] common/Journald: include msg/msg_fmt.h

Which is from PR https://github.com/ceph/ceph/pull/47830.

#12 Updated by Radoslaw Zarzynski 9 months ago

  • Status changed from In Progress to Fix Under Review
  • Pull request ID set to 51892

#13 Updated by Radoslaw Zarzynski 9 months ago

  • Status changed from Fix Under Review to Pending Backport
  • Backport set to reef

#14 Updated by Backport Bot 9 months ago

  • Copied to Backport #61579: reef: Logs produce non-human-readable timestamps after monitor upgrade added

#15 Updated by Backport Bot 9 months ago

  • Tags set to backport_processed

#16 Updated by Laura Flores 9 months ago

  • Assignee changed from Laura Flores to Radoslaw Zarzynski

#18 Updated by Laura Flores 8 months ago

  • Status changed from Pending Backport to Resolved

Also available in: Atom PDF