debug merge-logs fails in 21.2 and 22.1 and 22.2

[andf-crl]

Describe the problem

cockroach debug merge-logs appears to no longer be able to ingest & merge logs as prepared by cockroach debug zip since 21.2. Roughly:

$ cockroach debug zip debug.zip
$ unzip debug.zip
$ cockroach debug merge-logs debug/nodes/*/logs/*

Errors in latest v21.2 and v22.1 with error message:

   ERROR: decoding on line 2: malformed log entry
   Failed running "debug merge-logs"

The same works properly in latest v21.1.

To Reproduce

In each case, I tested with log files generated by identical cockroach version as used to attempt merge with cockroach debug merge-logs. I am following our documentation example.

## MY ENVIRONMENT. I have three symlinks:
$ ls -l `which cockroach-22.1`
lrwxr-xr-x  1 andf  staff  45 Jun 29 12:45 /Users/andf/crl/cockroach-22.1 -> cockroach-v22.1.2.darwin-10.9-amd64/cockroach
$ ls -l `which cockroach-21.2`
lrwxr-xr-x  1 andf  staff  46 Jun 30 11:43 /Users/andf/crl/cockroach-21.2 -> cockroach-v21.2.12.darwin-10.9-amd64/cockroach
$ ls -l `which cockroach-21.1`
lrwxr-xr-x  1 andf  staff  46 Jun 30 11:43 /Users/andf/crl/cockroach-21.1 -> cockroach-v21.1.19.darwin-10.9-amd64/cockroach

## Start 21.1:
$ cockroach-21.1 start --insecure --store=/Users/andf/staging/27210/data/node1 --listen-addr=localhost:26457 --http-addr=localhost:8280 --join=localhost:26457,localhost:26458,localhost:26459 --background
$ cockroach-21.1 start --insecure --store=/Users/andf/staging/27210/data/node2 --listen-addr=localhost:26458 --http-addr=localhost:8281 --join=localhost:26457,localhost:26458,localhost:26459 --background
$ cockroach-21.1 start --insecure --store=/Users/andf/staging/27210/data/node3 --listen-addr=localhost:26459 --http-addr=localhost:8282 --join=localhost:26457,localhost:26458,localhost:26459 --background

## Zip together, unzip, merge-logs for 21.1:
$ cockroach-21.1 debug zip debug211.zip --host=localhost:26457 --insecure
$ unzip debug211.zip -d debug211
$ cockroach-21.1 debug merge-logs debug211/debug/nodes/*/logs/*
# WORKS!

## Start 21.2:
$ cockroach-21.2 start --insecure --store=/Users/andf/staging/27704/data/node1 --listen-addr=localhost:26357 --http-addr=localhost:8180 --join=localhost:26357,localhost:26358,localhost:26359 --background
$ cockroach-21.2 start --insecure --store=/Users/andf/staging/27704/data/node3 --listen-addr=localhost:26359 --http-addr=localhost:8182 --join=localhost:26357,localhost:26358,localhost:26359 --background
$ cockroach-21.2 start --insecure --store=/Users/andf/staging/27704/data/node2 --listen-addr=localhost:26358 --http-addr=localhost:8181 --join=localhost:26357,localhost:26358,localhost:26359 --background

## Zip together, unzip, merge-logs for 21.2:
$ cockroach-21.2 debug zip debug212.zip --host=localhost:26357 --insecure
$ unzip debug212.zip -d debug212
$ cockroach-21.2 debug merge-logs debug212/debug/nodes/*/logs/*
   ERROR: decoding on line 2: malformed log entry
   Failed running "debug merge-logs"

## Start 22.1:
$ cockroach-22.1 start --insecure --store=/Users/andf/staging/27937/data/node1 --listen-addr=localhost:26257 --http-addr=localhost:8080 --join=localhost:26257,localhost:26258,localhost:26259 --background
$ cockroach-22.1 start --insecure --store=/Users/andf/staging/27937/data/node3 --listen-addr=localhost:26259 --http-addr=localhost:8082 --join=localhost:26257,localhost:26258,localhost:26259 --background
$ cockroach-22.1 start --insecure --store=/Users/andf/staging/27937/data/node2 --listen-addr=localhost:26258 --http-addr=localhost:8081 --join=localhost:26257,localhost:26258,localhost:26259 --background

## Zip together, unzip, merge-logs for 22.1:
$ cockroach-22.1 debug zip debug221.zip --host=localhost:26257 --insecure
$ unzip debug221.zip -d debug221
$ cockroach-22.1 debug merge-logs debug221/debug/nodes/*/logs/*
   ERROR: decoding on line 2: malformed log entry
   Failed running "debug merge-logs"

## Curious, I noticed that you can get merge logs to report the file it choked on by passing unrelated
## constraint flags to it, like timestamps:
$ cockroach-22.1 debug merge-logs debug221/debug/nodes/*/logs/* --from="220713 12:36:28.208553" --to="220713 19:36:29.232864"
   ERROR: error while processing file debug211/debug/nodes/1/logs/cockroach-health.crlMBP- 
   C02G70F6ML7JMjI3.andf.2022-07-13T19_24_54Z.013482.log: decoding on line 2: malformed log entry
   Failed running "debug merge-logs"

## Then I could examine the mentioned file's line 2:
$ head -2 debug/nodes/1/logs/cockroach-health.crlMBP-C02G70F6ML7JMjI3.andf.2022-07-13T19_24_54Z.013482.log
   I220713 19:24:54.182068 78 util/log/file_sync_buffer.go:238 ⋮ [config] file created at: 2022/07/13 19:24:54
   I220713 19:24:54.182094 78 util/log/file_sync_buffer.go:238 ⋮ [config] running on machine: ‹crlMBP-C02G70F6ML7JMjI3.local›

## Initially thought special <> characters (i.e. the redactable markers) might be the problem, but removing them did not get merge-logs running again. So here I am!

Does the end user have a guess?
Perhaps v2 log format is unexpected in some fashion by merge-logs. Initially suspected redactable markers, but removing them did not fix.

Expected behavior
cockroach merge-logs merges cockroach logs.

Environment:

$ cockroach-22.1 --version
cockroach version details:
Build Tag:        v22.1.2
Build Time:       2022/06/22 16:09:32
Distribution:     CCL
Platform:         darwin amd64 (x86_64-apple-darwin19)
Go Version:       go1.17.11
C Compiler:       Clang 10.0.0
Build Commit ID:  fc456a26830067b6dfbb8cd87e093a28d9b833d1
Build Type:       release

$ cockroach-21.2 --version
cockroach version details:
Build Tag:        v21.2.12
Build Time:       2022/06/06 12:53:38
Distribution:     CCL
Platform:         darwin amd64 (x86_64-apple-darwin19)
Go Version:       go1.16.6
C Compiler:       Clang 10.0.0
Build Commit ID:  4f97a101e6c1ba12f1ff133d69beee4333b7216e
Build Type:       release

$ cockroach-21.1 --version
cockroach version details:
Build Tag:        v21.1.19
Build Time:       2022/05/09 15:04:47
Distribution:     CCL
Platform:         darwin amd64 (x86_64-apple-darwin19)
Go Version:       go1.15.14
C Compiler:       Clang 10.0.0
Build Commit ID:  bf2bef135b5be9c73ccc445f2d996781ee59e94f
Build Type:       release

Additional context
Thanks team! Please also let me know if we need to update our documentation.

Jira issue: CRDB-17634

[andf-crl]

Ah, maybe to be addressed in this ongoing work: PR #73027

[andf-crl]

Problem continues in v22.1.5.

[daniel-crlabs]

This problem still exists on 22.2.3:

❯ ~/Downloads/cockroach-v22.2.3.darwin-10.9-amd64/cockroach debug merge-logs debug/nodes/*/logs/* --from="230208 18:49:00" --to="230208 18:52:00" > merged_logs_230208_1849-1852.txt
ERROR: error while processing file debug/nodes/174/logs/crdb.ip-*******.crdb.2023-02-08T06_51_34Z.1700550.log: decoding on line 2: malformed log entry
Failed running "debug merge-logs"

[abarganier]

Noted by @ajwerner on Slack:

It works if you specify the format. I think you need to say --format=crdb-v1. Like I think it supports both but the auto detection might be busted. I’ve never had a problem getting it to work after futzing with that flag.

We should look into the auto detection to start.

[daniel-crlabs]

Thanks for the input, I've tried and it worked with the --format.

❯ ~/Downloads/cockroach-v22.2.3.darwin-10.9-amd64/cockroach debug merge-logs debug/nodes/*/logs/* --from="230208 18:49:00" --to="230208 18:52:00" --format=crdb-v1 > merged_logs_230208_1849-1852.txt