Add new logs to recovery path

[davidmrdavid]

We've seen a few cases where partitions fail to transition from the Starting to the Started state, instead going straight to Terminated. In these cases, it appears the partition is getting stuck in the recover step.

To help with diagnosing future cases, I'm adding a log after fht.RecoverAsync is called so we can know for certain if we're returning from that call.

I've also added a Details column to the FasterAzureStorageAccessCompleted which contains more verbose information on the total range of data we're trying to access.

[davidmrdavid]

I like this new Position column, but I worry about two things:

(1) The fact that this is in a new column may exacerbate our column corruption issues. Are you against re-using a pre-existing column like Details? / do you see a reason why Position should be its own column if it's mostly "0" for most operations?

(2) Since a sufficiently large Read operation will be split into several smaller reads, I would like to emit a kind of "operation ID" to the storage access logs so that we can group smaller reads as part of a larger operation. A position column sort of gives us this same data (we can assume that a sequence of reads with increasing starting positions come from the same large read operation) but it isn't as fool proof as an "operation ID" field. Do we have an ID like this (I see a candidate id parameter in ReadFromBlobAsync) and can we log it if so?

[davidmrdavid]

Suggested change

	[Event(266, Level = EventLevel.Verbose, Version = 3)]
	public void FasterAzureStorageAccessCompleted(string Account, string TaskHub, int PartitionId, string Intent, long Position, long Size, string Operation, string Target, double Latency, int Attempt, string AppName, string ExtensionVersion)
	[Event(266, Level = EventLevel.Verbose, Version = 2)]
	public void FasterAzureStorageAccessCompleted(string Account, string TaskHub, int PartitionId, string Intent, long Position, long Size, string Operation, string Target, double Latency, int Attempt, string AppName, string ExtensionVersion)

Should this have been Version=2?

[sebastianburckhardt]

just in case you already ran this in the cloud I decided to bump the version again

[davidmrdavid]

Oh I didn't run it on Azure yet

[davidmrdavid]

Help me understand: why is position here destinationAddress +offset and not sourceAddress + offset? Perhaps I misunderstand what source and destination correspond to in this case?

[sebastianburckhardt]

the position is meant to be the offset within the page blob in storage.

Since this is a write (from an in-memory stream to the page blob), the page blob position in this case is the destination.

[davidmrdavid]

If "the page blob position [...] is the destination", then is it a problem that it we currently have var position = destinationAddress + offset instead of just destination?

[sebastianburckhardt]

The write is broken into smaller chunks because there is a max on how many bytes can be written in a single access (see WriteToBlobAsync which then calls WritePortionToBlobUnsafeAsync multiple times)

[sebastianburckhardt]

do you see a reason why Position should be its own column if it's mostly "0" for most operations

quantitatively speaking, not sure if "most" operations will have zero (there are often a lot of page blob accesses).

In ETW writing an integer is a lot more efficient than writing a string (even if the integer is zero).

I am not sure if this still matters once the data reaches Kusto. I got the impression at times that it is better to keep columns typed consistently. If its all numbers Kusto can detect that (e.g. column ElapsedMs is typed as 'real'). However, it may also be that writing an empty string is better than writing 0. Not sure really.

I don't have a strong opinion on this.

I would like to emit a kind of "operation ID" to the storage access logs so that we can group smaller reads as part of a larger operation.

That is possible but I am not sure it is worth it long term (we already have it in the detailed tracing).

If you really want to add this also then it may not be worth it to keep separate columns

[davidmrdavid]

I would like to emit a kind of "operation ID" to the storage access logs so that we can group smaller reads as part of a larger operation.

That is possible but I am not sure it is worth it long term (we already have it in the detailed tracing).

If you really want to add this also then it may not be worth it to keep separate columns

Yeah I think I would like to add this "operation ID" simply because most customers don't have detailed tracing enabled (for good reason!) which means we may be missing key information when diagnosing an already mitigated incident. In that case, I think we agree it may be best to merge the columns / add them to Details. Mind if I add this to the PR or do you want to add it yourself?

[sebastianburckhardt]

I have revised this according to PR feedback.

[davidmrdavid]

LGTM