Log stream responses with progress.

[carlbraganza]

Fixes: #41

[carlbraganza]

/release-note-none

[carlbraganza]

/assign @PrasadG193

[carlbraganza]

Selective test output illustrating the logging:

=== RUN   TestStreamGetMetadataDeltaResponse/success
I1008 18:53:31.351617 1089848 util.go:362] GetSecretReference namespaceTemplate secret-ns, namespaceParams: map[volumesnapshot.namespace: volumesnapshotcontent.name:snapcontent-snap-2], resolved secret-ns
I1008 18:53:31.351628 1089848 util.go:391] GetSecretReference validated Secret: &SecretReference{Name:secret-name,Namespace:secret-ns,}
I1008 18:53:31.351642 1089848 get_metadata_delta.go:198] "stream response" op="GetMetadataDelta-1" namespace="" baseSnapshotName="snap-1" targetSnapshotName="snap-2" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" responseNum=1 volumeCapacityBytes=1073741824 blockMetadata="[{0,1024}]" numBlockMetadata=1
I1008 18:53:31.351649 1089848 get_metadata_delta.go:198] "stream response" op="GetMetadataDelta-1" namespace="" baseSnapshotName="snap-1" targetSnapshotName="snap-2" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" responseNum=2 volumeCapacityBytes=1073741824 blockMetadata="[{1,1024}{2,1024}]" numBlockMetadata=2
I1008 18:53:31.351654 1089848 get_metadata_delta.go:159] "stream EOF" op="GetMetadataDelta-1" namespace="" baseSnapshotName="snap-1" targetSnapshotName="snap-2" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" lastByteOffset=2 lastSize=1024 lastResponseNum=2 volumeCapacityBytes=1073741824

and

=== RUN   TestStreamGetMetadataAllocatedResponse/success
I1008 18:53:31.349395 1089848 util.go:362] GetSecretReference namespaceTemplate secret-ns, namespaceParams: map[volumesnapshot.namespace: volumesnapshotcontent.name:snapcontent-snap-1], resolved secret-ns
I1008 18:53:31.349419 1089848 util.go:391] GetSecretReference validated Secret: &SecretReference{Name:secret-name,Namespace:secret-ns,}
I1008 18:53:31.349448 1089848 get_metadata_allocated.go:177] "stream response" op="GetMetadataAllocated-1" namespace="" snapshotName="snap-1" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" responseNum=1 volumeCapacityBytes=1073741824 blockMetadata="[{0,1024}]" numBlockMetadata=1
I1008 18:53:31.349454 1089848 get_metadata_allocated.go:177] "stream response" op="GetMetadataAllocated-1" namespace="" snapshotName="snap-1" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" responseNum=2 volumeCapacityBytes=1073741824 blockMetadata="[{1,1024}{2,1024}]" numBlockMetadata=2
I1008 18:53:31.349459 1089848 get_metadata_allocated.go:138] "stream EOF" op="GetMetadataAllocated-1" namespace="" snapshotName="snap-1" startingOffset=0 maxResults=2 blockMetadataType="FIXED_LENGTH" lastByteOffset=2 lastSize=1024 lastResponseNum=2 volumeCapacityBytes=1073741824

[PrasadG193]

Can we not use json encoding?

[carlbraganza]

I had first used a JSON dump of the entire data structure but then reconsidered. JSON encoding is very verbose and would repeat the byte_offset and size_bytes labels for each entry. This is more compact and expresses the same data and we don't have to trim the output.

For example, if I replace

b.WriteString("[")
for _, bmd := range clientResp.BlockMetadata {
	b.WriteString(fmt.Sprintf("{%d,%d}", bmd.ByteOffset, bmd.SizeBytes))
}
b.WriteString("]")
...
logger.WithValues(
	...
	"blockMetadata", b.String(),
	...
).Info("stream response")

with

enc := json.NewEncoder(&b)
_ = enc.Encode(clientResp.BlockMetadata)

...
logger.WithValues(
	...
	"blockMetadata", strings.TrimSuffix(b.String(), "\n"),
	...
).Info("stream response")

then the output changes from

blockMetadata="[{1,1024}{2,1024}]"

to

blockMetadata="[{\"byte_offset\":1,\"size_bytes\":1024},{\"byte_offset\":2,\"size_bytes\":1024}]"

Also, the autogenerated field names for JSON do not use camel case but instead use underscores, which looks a bit ugly to me.

[carlbraganza]

I added a detailed trace level for the contents of the stream response loop.

[PrasadG193]

@carlbraganza I think the logs level is not specific to handler methods, right? I mean the level can be set in log in any package. Should we give generic names like - debug, info, verbose, etc?

[carlbraganza]

Klog uses a concept of a process wide verbosity level (the V function), and each -v flag increments the level used. There are no clear definitions for info, debug, etc. - these are "severity" values in the log which could be logged at any verbosity level.

I defined these constants for the handler package, with the only constraint being that

1 <= HandlerTraceLogLevel < HandlerDetailedTraceLogLevel

We could define common process wide constants to assign values to these constants later if we see the need, but for now I think most of the business logic is concentrated in the grpc/server package.

[PrasadG193]

/lgtm
/approve

[PrasadG193]

/approve

[carlbraganza]

I applied the permission change to .prow.sh and removed the invocation of the linter on the test target.

[PrasadG193]

/lgtm
/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: carlbraganza, PrasadG193

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [PrasadG193,carlbraganza]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment