PMM-8673 Send pbm logs to pmm #289

Dasio · 2021-08-24T11:43:53Z

https://jira.percona.com/browse/PMM-8673

pmm: percona/pmm#775
managed: percona/pmm-managed#822

jobs/mongodb_backup_job.go

maxkondr · 2021-09-01T15:21:54Z

jobs/mongodb_backup_job.go

+				continue
+			}
+			for _, log := range logs {
+				_, err = fmt.Fprintf(&buffer, "%s [%s:%s] %s\n", time.Unix(log.TS, 0), log.RS, log.Node, log.Msg)


why the original log format is dropped here?
So end-user will see another format on UI that he used to see using DB tool output.

I think is unnecessary to include info about event name from pbm. Because here it will be always the same.
Also parse JSON output seems better for manipulation. But sure, we can omit JSON from invoking pbm logs and just send raw logs..

but in such a case end-user will see the different result in pbm output vs GUI

yes, that's issue?
Here https://confluence.percona.com/display/PMM/Backup+Management in 10.API it's said
standardize (post-process) logs formats but, that will be hard to do it anyway. Eg. in xtrabackup lines don't have timestamp (I think, would need double check it)

Most likely modified log is equal to log that pbm-agent writes to the stdout, but because we collect it with pbm tool it adds some information. If so, then IMHO better to cut off these additions.

logs from pbm-agent itself

2021-09-10T11:03:44.000+0200 I [backup/2021-09-10T09:03:26Z] backup started 2021-09-10T11:03:47.000+0200 D [backup/2021-09-10T09:03:26Z] wait for tmp users {1631264627 2} 2021-09-10T11:03:47.315+0200 Setting num cpus to 12 2021-09-10T11:03:47.000+0200 I [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T11:03:47.354+0200 enqueued collection 'admin.pbmPITRChunks' 2021-09-10T11:03:47.354+0200 enqueued collection 'admin.system.users' 2021-09-10T11:03:47.355+0200 enqueued collection 'admin.pbmAgents' 2021-09-10T11:03:47.355+0200 enqueued collection 'admin.system.profile' 2021-09-10T11:03:47.356+0200 enqueued collection 'admin.pbmOpLog' 2021-09-10T11:03:47.356+0200 enqueued collection 'admin.pbmLog' 2021-09-10T11:03:47.356+0200 enqueued collection 'admin.system.version' 2021-09-10T11:03:47.357+0200 enqueued collection 'admin.pbmRUsers' 2021-09-10T11:03:47.357+0200 enqueued collection 'admin.pbmCmd' 2021-09-10T11:03:47.358+0200 enqueued collection 'admin.pbmBackups' 2021-09-10T11:03:47.358+0200 enqueued collection 'admin.pbmConfig' 2021-09-10T11:03:47.358+0200 enqueued collection 'admin.pbmLock' 2021-09-10T11:03:47.358+0200 enqueued collection 'admin.pbmLockOp' 2021-09-10T11:03:47.359+0200 enqueued collection 'admin.pbmBackups.old' 2021-09-10T11:03:47.359+0200 enqueued collection 'config.system.profile' 2021-09-10T11:03:47.360+0200 enqueued collection 'config.image_collection' 2021-09-10T11:03:47.365+0200 archive prelude admin.system.profile 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmCmd 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmLock 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmBackups.old 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmPITRChunks 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmConfig 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmLockOp 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmAgents 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmLog 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmRUsers 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmBackups 2021-09-10T11:03:47.365+0200 archive prelude config.image_collection 2021-09-10T11:03:47.365+0200 archive prelude admin.pbmOpLog 2021-09-10T11:03:47.365+0200 archive prelude config.system.profile 2021-09-10T11:03:47.365+0200 archive prelude admin.system.users 2021-09-10T11:03:47.365+0200 archive prelude admin.system.version 2021-09-10T11:03:47.369+0200 writing admin.system.users to archive on stdout 2021-09-10T11:03:47.370+0200 Mux open namespace admin.system.users 2021-09-10T11:03:47.370+0200 counted 1 document in admin.system.users 2021-09-10T11:03:47.371+0200 Mux close namespace admin.system.users 2021-09-10T11:03:47.371+0200 done dumping admin.system.users (1 document) 2021-09-10T11:03:47.371+0200 writing admin.system.version to archive on stdout 2021-09-10T11:03:47.374+0200 Mux open namespace admin.system.version 2021-09-10T11:03:47.375+0200 counted 2 documents in admin.system.version 2021-09-10T11:03:47.375+0200 Mux close namespace admin.system.version 2021-09-10T11:03:47.375+0200 done dumping admin.system.version (2 documents) 2021-09-10T11:03:47.375+0200 dumping up to 6 collections in parallel 2021-09-10T11:03:47.375+0200 writing admin.system.profile to archive on stdout 2021-09-10T11:03:47.379+0200 Mux open namespace admin.system.profile 2021-09-10T11:03:47.379+0200 counted 741 documents in admin.system.profile 2021-09-10T11:03:47.385+0200 Mux close namespace admin.system.profile 2021-09-10T11:03:47.385+0200 done dumping admin.system.profile (742 documents) 2021-09-10T11:03:47.385+0200 writing admin.pbmRUsers to archive on stdout 2021-09-10T11:03:47.389+0200 Mux open namespace admin.pbmRUsers 2021-09-10T11:03:47.390+0200 counted 1 document in admin.pbmRUsers 2021-09-10T11:03:47.390+0200 Mux close namespace admin.pbmRUsers 2021-09-10T11:03:47.390+0200 done dumping admin.pbmRUsers (1 document) 2021-09-10T11:03:47.390+0200 writing admin.pbmLog to archive on stdout 2021-09-10T11:03:47.391+0200 writing admin.pbmBackups.old to archive on stdout 2021-09-10T11:03:47.391+0200 writing config.system.profile to archive on stdout 2021-09-10T11:03:47.393+0200 writing admin.pbmOpLog to archive on stdout 2021-09-10T11:03:47.394+0200 Mux open namespace admin.pbmBackups.old 2021-09-10T11:03:47.394+0200 Mux open namespace admin.pbmLog 2021-09-10T11:03:47.394+0200 Mux open namespace config.system.profile 2021-09-10T11:03:47.395+0200 counted 1 document in admin.pbmBackups.old 2021-09-10T11:03:47.395+0200 counted 649 documents in config.system.profile 2021-09-10T11:03:47.395+0200 writing admin.pbmCmd to archive on stdout 2021-09-10T11:03:47.395+0200 counted 120 documents in admin.pbmLog 2021-09-10T11:03:47.395+0200 Mux close namespace admin.pbmBackups.old 2021-09-10T11:03:47.395+0200 done dumping admin.pbmBackups.old (1 document) 2021-09-10T11:03:47.396+0200 writing admin.pbmAgents to archive on stdout 2021-09-10T11:03:47.396+0200 writing admin.pbmBackups to archive on stdout 2021-09-10T11:03:47.397+0200 Mux open namespace admin.pbmAgents 2021-09-10T11:03:47.397+0200 Mux close namespace admin.pbmLog 2021-09-10T11:03:47.397+0200 Mux open namespace admin.pbmOpLog 2021-09-10T11:03:47.397+0200 done dumping admin.pbmLog (120 documents) 2021-09-10T11:03:47.398+0200 Mux open namespace admin.pbmBackups 2021-09-10T11:03:47.398+0200 counted 8 documents in admin.pbmOpLog 2021-09-10T11:03:47.398+0200 writing admin.pbmConfig to archive on stdout 2021-09-10T11:03:47.398+0200 Mux open namespace admin.pbmCmd 2021-09-10T11:03:47.398+0200 counted 2 documents in admin.pbmBackups 2021-09-10T11:03:47.398+0200 counted 8 documents in admin.pbmCmd 2021-09-10T11:03:47.398+0200 counted 1 document in admin.pbmAgents 2021-09-10T11:03:47.398+0200 done dumping admin.pbmOpLog (8 documents) 2021-09-10T11:03:47.398+0200 Mux close namespace admin.pbmOpLog 2021-09-10T11:03:47.399+0200 Mux open namespace admin.pbmConfig 2021-09-10T11:03:47.399+0200 Mux close namespace admin.pbmBackups 2021-09-10T11:03:47.399+0200 done dumping admin.pbmBackups (2 documents) 2021-09-10T11:03:47.399+0200 writing admin.pbmLock to archive on stdout 2021-09-10T11:03:47.399+0200 Mux close namespace admin.pbmAgents 2021-09-10T11:03:47.399+0200 Mux close namespace admin.pbmCmd 2021-09-10T11:03:47.399+0200 done dumping admin.pbmCmd (8 documents) 2021-09-10T11:03:47.399+0200 done dumping admin.pbmAgents (1 document) 2021-09-10T11:03:47.399+0200 writing admin.pbmPITRChunks to archive on stdout 2021-09-10T11:03:47.399+0200 counted 1 document in admin.pbmConfig 2021-09-10T11:03:47.399+0200 writing admin.pbmLockOp to archive on stdout 2021-09-10T11:03:47.399+0200 writing config.image_collection to archive on stdout 2021-09-10T11:03:47.399+0200 Mux close namespace admin.pbmConfig 2021-09-10T11:03:47.399+0200 done dumping admin.pbmConfig (1 document) 2021-09-10T11:03:47.402+0200 Mux close namespace config.system.profile 2021-09-10T11:03:47.402+0200 done dumping config.system.profile (650 documents) 2021-09-10T11:03:47.403+0200 Mux open namespace admin.pbmLock 2021-09-10T11:03:47.404+0200 counted 1 document in admin.pbmLock 2021-09-10T11:03:47.404+0200 Mux close namespace admin.pbmLock 2021-09-10T11:03:47.404+0200 done dumping admin.pbmLock (1 document) 2021-09-10T11:03:47.404+0200 Mux open namespace admin.pbmPITRChunks 2021-09-10T11:03:47.405+0200 counted 0 documents in admin.pbmPITRChunks 2021-09-10T11:03:47.405+0200 Mux open namespace config.image_collection 2021-09-10T11:03:47.405+0200 Mux close namespace admin.pbmPITRChunks 2021-09-10T11:03:47.405+0200 done dumping admin.pbmPITRChunks (0 documents) 2021-09-10T11:03:47.405+0200 counted 0 documents in config.image_collection 2021-09-10T11:03:47.406+0200 Mux open namespace admin.pbmLockOp 2021-09-10T11:03:47.406+0200 Mux close namespace config.image_collection 2021-09-10T11:03:47.406+0200 done dumping config.image_collection (0 documents) 2021-09-10T11:03:47.406+0200 counted 0 documents in admin.pbmLockOp 2021-09-10T11:03:47.407+0200 Mux close namespace admin.pbmLockOp 2021-09-10T11:03:47.407+0200 done dumping admin.pbmLockOp (0 documents) 2021-09-10T11:03:47.407+0200 dump phase III: the oplog 2021-09-10T11:03:47.407+0200 finishing dump 2021-09-10T11:03:47.407+0200 Mux finish 2021-09-10T11:03:47.407+0200 mux completed successfully 2021-09-10T11:03:47.000+0200 I [backup/2021-09-10T09:03:26Z] mongodump finished, waiting for the oplog 2021-09-10T11:03:50.000+0200 D [backup/2021-09-10T09:03:26Z] set oplog span to {1631264624 4} / {1631264627 6} 2021-09-10T11:03:50.000+0200 I [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T11:03:51.000+0200 D [backup/2021-09-10T09:03:26Z] epoch set to {1631264631 1} 2021-09-10T11:03:52.000+0200 I [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T11:03:53.000+0200 I [backup/2021-09-10T09:03:26Z] dropping tmp collections 2021-09-10T11:03:53.000+0200 I [backup/2021-09-10T09:03:26Z] backup finished 2021-09-10T11:03:53.000+0200 D [backup/2021-09-10T09:03:26Z] releasing lock

Logs from pbm logs

2021-09-10T09:03:44Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] backup started 2021-09-10T09:03:47Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T09:03:47Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] mongodump finished, waiting for the oplog 2021-09-10T09:03:50Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T09:03:52Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] s3.uploadPartSize is set to 10485760 (~10Mb) 2021-09-10T09:03:53Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] dropping tmp collections 2021-09-10T09:03:53Z I [rs0/mongo1:27017] [backup/2021-09-10T09:03:26Z] backup finished

I wanted to omit [backup/2021-09-10T09:03:26Z] but I can get logs at is.

still I prefer parse JSON output, because in the future, there should be ID of log and based on it, I'll do paging

Aha, so original pbm-agent also has [backup/2021-09-10T09:03:26Z], then better to send logs as is. Without any modifications.

I reconstructed original message from JSON output.

jobs/mongodb_backup_job.go

maxkondr · 2021-09-07T14:48:54Z

jobs/mongodb_backup_job.go

+				continue
+			}
+			for _, log := range logs {
+				_, err = fmt.Fprintf(&buffer, "%s [%s:%s] %s\n", time.Unix(log.TS, 0), log.RS, log.Node, log.Msg)


but in such a case end-user will see the different result in pbm output vs GUI

jobs/mongodb_backup_job.go

github-actions · 2021-09-14T15:05:57Z

jobs/mongodb_backup_job.go

-	output, err := exec.CommandContext(nCtx, pbmBin, "status", "--mongodb-uri="+dbURL.String()).CombinedOutput() // #nosec G204
-	if err != nil {
-		return false, errors.Wrapf(err, "pbm status error: %s", string(output))
+func (j *MongoDBBackupJob) streamLogs(ctx context.Context, send Send, name string, backupFinished <-chan struct{}) error {


🚫 [golangci-lint] _{reported by reviewdog 🐶}
Function 'streamLogs' is too long (76 > 60) (funlen)

github-actions · 2021-09-14T15:05:58Z

jobs/pbm_helpers.go

+		"--mongodb-uri="+dbURL.String(),
+		"--file="+confFile,
+	).CombinedOutput()
+


🚫 [golangci-lint] _{reported by reviewdog 🐶}
File is not gofumpt-ed (gofumpt)

jobs/pbm_helpers.go

jobs/mongodb_backup_job.go

jobs/pbm_helpers.go

github-actions · 2021-09-15T14:02:01Z

jobs/pbm_helpers.go

+			return ctx.Err()
+		}
+	}
+}


🚫 [golangci-lint] _{reported by reviewdog 🐶}
File is not gofumpt-ed (gofumpt)

jobs/pbm_helpers.go

jobs/mongodb_backup_job.go

jobs/pbm_helpers.go

jobs/mongodb_backup_job.go

jobs/pbm_helpers.go

Dasio · 2021-09-22T07:16:05Z

jobs/pbm_helpers.go

+
+func pbmBackupFinished(name string) pbmStatusCondition {
+	started := false
+	snapshotStarted := false


There is bug in pbm 1.6.0, when first state is error and then starting -> ... done, so it's to prevent from catching first wrong error state
Fixed in master

jobs/pbm_helpers.go

github-actions · 2021-09-23T11:40:43Z

jobs/pbm_helpers.go

+	if err != nil {
+		return "", errors.Wrap(err, "failed to create pbm configuration file")
+	}
+	defer tmp.Close() //nolint:errcheck


🚫 [golangci-lint] _{reported by reviewdog 🐶}
G307: Deferring unsafe method "Close" on type "*os.File" (gosec)

jobs/mongodb_backup_job.go

oter · 2021-10-01T09:03:53Z

jobs/pbm_helpers.go

+	args = append(args, "--out=json", "--mongodb-uri="+dbURL.String())
+	cmd := exec.CommandContext(nCtx, pbmBin, args...) // #nosec G204
+
+	b, err := cmd.Output()


maybe use CombinedOutput?

It seems that there is no need for that here. ExitError contains stderr.

PMM-8673 Send pbm logs to pmm

ba6d273

github-actions bot reviewed Aug 24, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

jobs/mongodb_backup_job.go Show resolved Hide resolved

maxkondr reviewed Sep 1, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

maxkondr reviewed Sep 1, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

Dasio added 2 commits September 6, 2021 10:45

PMM-8673 Send chunkID

6f5f94f

PMM-8673 Split logs

a8b3580

maxkondr reviewed Sep 7, 2021

View reviewed changes

Merge branch 'master' into PMM-8673-mongodb-logs

6d362f4

Dasio mentioned this pull request Sep 8, 2021

PMM-8673 MongoDB logs percona/pmm-managed#822

Merged

2 tasks

artemgavrilov reviewed Sep 8, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

Dasio added 8 commits September 13, 2021 11:33

PMM-8673 Fix waiting for backup finish

776a828

PMM-8673 Handle no backup started

2911355

PMM-8673 Remove regexp from restore

665afe4

PMM-8673 Better restore handling

e0fa265

PMM-8673 Adjust log format

03176f4

PMM-8673 Send chunk id for last log

93a60e6

PMM-8673 Fix log output

e9c564c

PMM-8673 Header

8a6407b

github-actions bot reviewed Sep 14, 2021

View reviewed changes

Dasio added 2 commits September 15, 2021 12:07

PMM-8673 Tail=0(unlimited) for logs

000a3c9

PMM-8673 log

0982fa0

Dasio commented Sep 15, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

Dasio marked this pull request as ready for review September 15, 2021 10:44

Dasio requested a review from BupycHuk as a code owner September 15, 2021 10:44

Dasio requested review from artemgavrilov and oter September 15, 2021 10:44

Dasio commented Sep 15, 2021

View reviewed changes

jobs/pbm_helpers.go Outdated Show resolved Hide resolved

PMM-8673 Better restore handling

faee77d

github-actions bot reviewed Sep 15, 2021

View reviewed changes

artemgavrilov reviewed Sep 16, 2021

View reviewed changes

jobs/pbm_helpers.go Outdated Show resolved Hide resolved

jobs/pbm_helpers.go Show resolved Hide resolved

jobs/pbm_helpers.go Outdated Show resolved Hide resolved

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

jobs/mongodb_backup_job.go Show resolved Hide resolved

PMM-8673 Message -> Data

b11a468

github-actions bot reviewed Sep 17, 2021

View reviewed changes

jobs/pbm_helpers.go Show resolved Hide resolved

PMM-8673 Removed time

fbae456

github-actions bot reviewed Sep 21, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

PMM-8673 Send end log always

7194e91

github-actions bot reviewed Sep 21, 2021

View reviewed changes

jobs/mongodb_backup_job.go Outdated Show resolved Hide resolved

PMM-8673 Check error state only after snapshot started

fd3dab1

github-actions bot reviewed Sep 21, 2021

View reviewed changes

jobs/pbm_helpers.go Show resolved Hide resolved

Dasio commented Sep 22, 2021

View reviewed changes

Dasio requested a review from artemgavrilov September 22, 2021 07:16

artemgavrilov reviewed Sep 22, 2021

View reviewed changes

jobs/pbm_helpers.go Outdated Show resolved Hide resolved

artemgavrilov approved these changes Sep 22, 2021

View reviewed changes

PMM-8673 Removed backup finish check

80cba8e

github-actions bot reviewed Sep 23, 2021

View reviewed changes

artemgavrilov self-assigned this Sep 23, 2021

artemgavrilov mentioned this pull request Sep 27, 2021

PMM-8673 mongodb backup logs percona/pmm#775

Merged

2 tasks

PMM-8673 Update pmm dependency

767859a

artemgavrilov requested a review from maxkondr September 28, 2021 09:40

oter suggested changes Oct 1, 2021

View reviewed changes

oter and others added 3 commits October 1, 2021 13:22

Merge branch 'master' into PMM-8673-mongodb-logs

e5f14f4

PMM-8673 Fix mongo backup restore job

90e2d1c

PMM-8673 Fix race

d39ac9f

artemgavrilov requested a review from oter October 1, 2021 16:06

BupycHuk approved these changes Oct 5, 2021

View reviewed changes

PMM-8673 Update pmm dependency

506794d

BupycHuk merged commit b400c05 into master Oct 5, 2021

BupycHuk deleted the PMM-8673-mongodb-logs branch October 5, 2021 10:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

PMM-8673 Send pbm logs to pmm #289

PMM-8673 Send pbm logs to pmm #289

Dasio commented Aug 24, 2021 •

edited

Loading

maxkondr Sep 1, 2021

Dasio Sep 2, 2021

maxkondr Sep 7, 2021

Dasio Sep 8, 2021

artemgavrilov Sep 8, 2021

Dasio Sep 10, 2021

artemgavrilov Sep 13, 2021

Dasio Sep 14, 2021

maxkondr Sep 7, 2021

github-actions bot Sep 14, 2021

github-actions bot Sep 14, 2021

github-actions bot Sep 15, 2021

Dasio Sep 22, 2021

github-actions bot Sep 23, 2021

oter Oct 1, 2021

artemgavrilov Oct 1, 2021

PMM-8673 Send pbm logs to pmm #289

PMM-8673 Send pbm logs to pmm #289

Conversation

Dasio commented Aug 24, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot Sep 14, 2021

Choose a reason for hiding this comment

github-actions bot Sep 14, 2021

Choose a reason for hiding this comment

github-actions bot Sep 15, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot Sep 23, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Dasio commented Aug 24, 2021 •

edited

Loading