log: long-ish line broken up in multiple messages

[andreimatei]

I've got a long log line, but not all that long - maybe a few KB. The logging infra seems to break it into multiple messages. This makes for a much worse experience when I need to read it, grep in it, etc. Was there a good reason why we did this - particularly with seemingly such a low char limit? I know we used to have problem #50166 with some crap RPC service truncating 64K lines. But a) the limit there was much larger and b) shouldn't we fix that damn service instead?

I210309 03:24:55.016908 388 kv/kvserver/closedts/sidetransport/sender.go:426 â<8b>® [n2] 7300 |.LeaseSequence=7)} 151:{[n2,s2,r151/3:/Table/59/1/8{1/76653-4/18276}] %!s(roachpb.LeaseSequence=8)} 152:{[n2,s2,r152/3:/Table/5{5/2/66/7â<80>¦-6}] %!s(roachpb.LeaseSequence=4)} 153:{[n2,s2,r153/3:/Table/59/1/1{7/51276-9/8149}] %!s(roachpb.LeaseSequence=7)} 155:{[n2,s2,r155/3:/Table/57/1/{17/10/â<80>¦-21/2/-â<80>¦}] %!s(roachpb.LeaseSequence=7)} 164:{[n2,s2,r164/3:/Table/59/1/2{5/48424-7/5310}] %!s(roachpb.LeaseSequence=9)} 166:{[n2,s2,r166/3:/Table/59/1/2{7/5310-9/46996}] %!s(roachpb.LeaseSequence=9)} 169:{[n2,s2,r169/3:/Table/59/1/{77/776â<80>¦-80/192â<80>¦}] %!s(roachpb.LeaseSequence=6)} 171:{[n2,s2,r171/3:/Table/55/2/{0/1/"Aâ<80>¦-33/4/"â<80>¦}] %!s(roachpb.LeaseSequence=2)} 172:{[n2,s2,r172/3:/Table/59/1/{48/428â<80>¦-50/845â<80>¦}] %!s(roachpb.LeaseSequence=10)} 173:{[n2,s2,r173/3:/Table/59/1/5{0/84532-2/41471}] %!s(roachpb.LeaseSequence=10)} 175:{[n2,s2,r175/3:/Table/57/1/{87/6/-â<80>¦-90/4/-â<80>¦}] %!s(roachpb.LeaseSequence=7)} 177:{[n2,s2,r177/3:/Table/57/1/2{1/2/-1â<80>¦-4/1/-1â<80>¦}] %!s(roachpb.LeaseSequence=7)} 179:{[n2,s2,r179/3:/Ta
I210309 03:24:55.016908 388 kv/kvserver/closedts/sidetransport/sender.go:426 â<8b>® [n2] 7300 |ble/{59/1/97/7â<80>¦-60}] %!s(roachpb.LeaseSequence=10)} 180:{[n2,s2,r180/3:/Table/57/1/9{6/4/-8â<80>¦-9/6/-2â<80>¦}] %!s(roachpb.LeaseSequence=10)} 191:{[n2,s2,r191/3:/Table/59/1/2{3/6720-5/48424}] %!s(roachpb.LeaseSequence=9)} 198:{[n2,s2,r198/3:/Table/57/1/6{3/5/-1â<80>¦-6/6/-5â<80>¦}] %!s(roachpb.LeaseSequence=8)} 200:{[n2,s2,r200/3:/Table/57/1/66/{6/-54â<80>¦-7/-30â<80>¦}] %!s(roachpb.LeaseSequence=10)} 208:{[n2,s2,r208/3:/Table/57/1/9{3/6/-2â<80>¦-6/4/-8â<80>¦}] %!s(roachpb.LeaseSequence=10)}]â<80>º
I210309 03:24:55.016908 388 kv/kvserver/closedts/sidetransport/sender.go:426 â<8b>® [n2] 7300 +â<80>¹last sent: closed: [1615260285.016088604,0 1615260295.816088604,0?]ranges: 152, 177, 77, 148, 134, 28, 107, 175, 198, 88, 118, 87, 82, 27, 191, 20, 75, 24, 10, 21, 135, 164, 6, 95, 146, 83, 166, 30, 171, 110, 130, 125, 11, 173, 29, 153, 17, 113, 85, )â<80>º, sender state: %!s(MISSING)

Jira issue: CRDB-2674

Epic CRDB-21266

[knz]

shouldn't we fix that damn service instead?

that is properly impossible - the crdb-v1 log format is ambiguous and cannot be parsed reliably an faithfully.

That being said I agree that the log retrieval API is still broken. For one, it still accumulates all the log entries in RAM server-side before returning them to the client. That's insane. I think the next step here is to simply remove that API altogether and replace it by a better one.

When looking at this issue together with #59558 which you filed earlier, I think the better thing we can do is to fix / extend the debug merge-log tool to merge the entries properly.

[andreimatei]

that is properly impossible - the crdb-v1 log format is ambiguous and cannot be parsed reliably an faithfully.

Why is the "crdb-v1" format relevant, given that we've moved on? Also I never understood why that RPC service needs to parse anything at all.

When looking at this issue together with #59558 which you filed earlier, I think the better thing we can do is to fix / extend the debug merge-log tool to merge the entries properly.

I personally care about how log files look independently of debug merge-logs. There's a lot of opening log files in your editor.

[knz]

Why is the "crdb-v1" format relevant, given that we've moved on? Also I never understood why that RPC service needs to parse anything at all.

The RPC code only knows how to parse crdb-v1. It happens to work with crdb-v2 because crdb-v2 was designed to be compatible with crdb-v1 parsers.

Also I never understood why that RPC service needs to parse anything at all.

Because it returns structured protobuf entries, not the raw text of the log file. This is a misdesign from the start.

I personally care about how log files look independently of debug merge-logs. There's a lot of opening log files in your editor.

Hm that is also right. Let's discuss this soon.

[knz]

Here are a few notes from our discussion today:

• the max line length should be configurable
• the current default max line length is too low and should be increased
• especially, for use in tests where we probably don't want any limit at all