HDDS-4271. Avoid logging chunk content in Ozone Insight

[adoroszlai]

What changes were proposed in this pull request?

HDDS-2660 added an insight point for the datanode dispatcher. At trace level it logs all chunk content, which can be huge and contain control characters. This PR removes chunk data from such log messages.

https://issues.apache.org/jira/browse/HDDS-4271

How was this patch tested?

Started Ozone Insight (for all 3 datanodes in separate windows):

ozone insight logs -v datanode.dispatcher -f datanode=ozone_datanode_1

Ran test:

ozone freon ockg -n1 -t1 -p warmup
ozone sh key put /vol1/bucket1/passwd /etc/passwd
ozone sh key get /vol1/bucket1/passwd /tmp/passwd
diff -q /etc/passwd /tmp/passwd

Output for ozone freon ockg -n1 -t1 -p warmup:

[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|OzoneProtocolMessageDispatcher] [service=DatanodeClient] [type=WriteChunk] request is received:
cmdType: WriteChunk
traceID: ""
containerID: 1
datanodeUuid: "833184d2-c6db-409a-934e-df7699b97061"
pipelineID: "d8e8bf6c-6eca-4941-a4a6-3b0b997fbf4f"
writeChunk {
blockID {
containerID: 1
localID: 104959326432133120
blockCommitSequenceId: 0
}
chunkData {
chunkName: "104959326432133120_chunk_1"
offset: 0
len: 10240
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "327275221253"
}
}
data: "<redacted>"
}
[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|HddsDispatcher] Command WriteChunk, trace ID:
[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|OzoneProtocolMessageDispatcher] [service=DatanodeClient] [type=WriteChunk] request is processed. Response:
cmdType: WriteChunk
traceID: ""
result: SUCCESS
message: ""

Output for ozone sh key get /vol1/bucket1/passwd /tmp/passwd:

[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|OzoneProtocolMessageDispatcher] [service=DatanodeClient] [type=ReadChunk] request is received:
cmdType: ReadChunk
traceID: ""
containerID: 1
datanodeUuid: "833184d2-c6db-409a-934e-df7699b97061"
readChunk {
blockID {
containerID: 1
localID: 104959326926798849
blockCommitSequenceId: 6
}
chunkData {
chunkName: "104959326926798849_chunk_1"
offset: 0
len: 671
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "362232235315"
}
}
}
[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|HddsDispatcher] Command ReadChunk, trace ID:
[DATANODE] ... [TRACE|org.apache.hadoop.ozone.container.common.impl.HddsDispatcher|OzoneProtocolMessageDispatcher] [service=DatanodeClient] [type=ReadChunk] request is processed. Response:
cmdType: ReadChunk
traceID: ""
result: SUCCESS
readChunk {
blockID {
containerID: 1
localID: 104959326926798849
blockCommitSequenceId: 6
}
chunkData {
chunkName: "104959326926798849_chunk_1"
offset: 0
len: 671
checksumData {
type: CRC32
bytesPerChecksum: 1048576
checksums: "362232235315"
}
}
data: "<redacted>"
}

Regular CI:
https://github.com/adoroszlai/hadoop-ozone/actions/runs/282279336

[elek]

+1 Thanks for the patch @adoroszlai

My only counterargument is that it makes the debug slightly slower (and not only the TRACE but DEBUG as well).

But it should be acceptable, IMHO. When somebody enables DEBUG level, some slowness is expected.

[adoroszlai]

Thanks @elek for reviewing and committing this.

My only counterargument is that it makes the debug slightly slower (and not only the TRACE but DEBUG as well).

I don't see why, as requestPreprocessor is only called in the trace branch.

https://github.com/apache/hadoop-ozone/blob/cfff0973d4567185532078daa4cd19ee8a4b04b5/hadoop-hdds/framework/src/main/java/org/apache/hadoop/hdds/server/OzoneProtocolMessageDispatcher.java#L74-L83

[elek]

I don't see why, as requestPreprocessor is only called in the trace branch.

Ups, you are right. I missed it. In that case it will be slower (object copy) only for trace. Even more accetable ;-)