[PATCH] connect, protocol: log negotiated protocol version

[PATCH] connect, protocol: log negotiated protocol version

[Josh Steadmon]

It is useful for performance monitoring and debugging purposes to know
the wire protocol used for remote operations. This may differ from the
version set in local configuration due to differences in version and/or
configuration between the server and the client. Therefore, log the
negotiated wire protocol version via trace2, for both clients and
servers.

Signed-off-by: Josh Steadmon <steadmon@google.com>
---

Do people have a preference for logging this as an integer (and
therefore having "unknown protocol version" show up as "-1", or should I
add a protocol_version_to_string function so that we can format it
properly? For now I've erred on the side of having a smaller diff.

 connect.c  | 1 +
 protocol.c | 1 +
 2 files changed, 2 insertions(+)

diff --git a/connect.c b/connect.c
index 70b13389ba..6e23e3ff2d 100644
--- a/connect.c
+++ b/connect.c
@@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)
 		BUG("unknown protocol version");
 	}
 
+	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
 	return version;
 }
 
diff --git a/protocol.c b/protocol.c
index 052d7edbb9..3791d8499e 100644
--- a/protocol.c
+++ b/protocol.c
@@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo
 			die("protocol error: server explicitly said version 0");
 	}
 
+	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
 	return version;
 }
-- 
2.32.0.554.ge1b32706d8-goog

Re: [PATCH] connect, protocol: log negotiated protocol version

[Taylor Blau]

On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:
> [...] Therefore, log the negotiated wire protocol version via trace2,
> for both clients and servers.

Seems useful, thanks.

> Do people have a preference for logging this as an integer (and
> therefore having "unknown protocol version" show up as "-1", or should I
> add a protocol_version_to_string function so that we can format it
> properly? For now I've erred on the side of having a smaller diff.

I probably have a slight preference for converting the protocol_version
to a string and passing that along to trace2_data_string() instead. That
would let you more cleanly log "<unknown>", without needing to expose
implementation details like which enum has what value.

> diff --git a/connect.c b/connect.c
> index 70b13389ba..6e23e3ff2d 100644
> --- a/connect.c
> +++ b/connect.c
> @@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)
>  		BUG("unknown protocol version");
>  	}
>
> +	trace2_data_intmax("transfer", NULL, "negotiated-version", version);

Small nit-pick, this could come between the two switch statements, not
at the end of the function (since we know what we are going to return
before we switch on version.

(I was a little surprised to see that these functions now have the
side-effect of writing to trace2, since I would have instead expected
to see new lines added at the callers. But this makes it more
convenient, and I do not feel strongly about it)

In any case, connect.c:discover_version() is handling the client side,
but...

> diff --git a/protocol.c b/protocol.c
> index 052d7edbb9..3791d8499e 100644
> --- a/protocol.c
> +++ b/protocol.c
> @@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo
>  			die("protocol error: server explicitly said version 0");
>  	}
>
> +	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
>  	return version;
>  }
> --

This function is used by discover_version to parse the server's
response. If you are trying to log what protocol was agreed on from the
server's perspective, I think you are looking instead for
determine_protocol_version_server().

If you aren't (and are only interested in the client's point-of-view),
then I am pretty sure that this latter hunk is redundant.

Thanks,
Taylor

Re: [PATCH] connect, protocol: log negotiated protocol version

[Josh Steadmon]

On 2021.08.03 17:12, Taylor Blau wrote:
> On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:
> > [...] Therefore, log the negotiated wire protocol version via trace2,
> > for both clients and servers.
> 
> Seems useful, thanks.
> 
> > Do people have a preference for logging this as an integer (and
> > therefore having "unknown protocol version" show up as "-1", or should I
> > add a protocol_version_to_string function so that we can format it
> > properly? For now I've erred on the side of having a smaller diff.
> 
> I probably have a slight preference for converting the protocol_version
> to a string and passing that along to trace2_data_string() instead. That
> would let you more cleanly log "<unknown>", without needing to expose
> implementation details like which enum has what value.

V2 will include a format_protocol_version().


> > diff --git a/connect.c b/connect.c
> > index 70b13389ba..6e23e3ff2d 100644
> > --- a/connect.c
> > +++ b/connect.c
> > @@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)
> >  		BUG("unknown protocol version");
> >  	}
> >
> > +	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
> 
> Small nit-pick, this could come between the two switch statements, not
> at the end of the function (since we know what we are going to return
> before we switch on version.

Fixed in V2.


> (I was a little surprised to see that these functions now have the
> side-effect of writing to trace2, since I would have instead expected
> to see new lines added at the callers. But this makes it more
> convenient, and I do not feel strongly about it)
> 
> In any case, connect.c:discover_version() is handling the client side,
> but...
> 
> > diff --git a/protocol.c b/protocol.c
> > index 052d7edbb9..3791d8499e 100644
> > --- a/protocol.c
> > +++ b/protocol.c
> > @@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo
> >  			die("protocol error: server explicitly said version 0");
> >  	}
> >
> > +	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
> >  	return version;
> >  }
> > --
> 
> This function is used by discover_version to parse the server's
> response. If you are trying to log what protocol was agreed on from the
> server's perspective, I think you are looking instead for
> determine_protocol_version_server().
> 
> If you aren't (and are only interested in the client's point-of-view),
> then I am pretty sure that this latter hunk is redundant.

Thanks for catching this dumb mistake. Fixed in V2, and added tests to
make sure the trace message shows up on both client- & server-side.

> Thanks,
> Taylor

Re: [PATCH] connect, protocol: log negotiated protocol version

[Junio C Hamano]

Josh Steadmon <steadmon@google.com> writes:

> On 2021.08.03 17:12, Taylor Blau wrote:
>> On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:
> V2 will include a format_protocol_version().
> ...
> Thanks for catching this dumb mistake. Fixed in V2, and added tests to
> make sure the trace message shows up on both client- & server-side.

Thanks, both.  I was about to merge the original one to 'next' as a
"good enough" version, but you caught me just in time ;-)

[PATCH v2 0/2] log negotiated protocol version.

[Josh Steadmon]

This series adds logging of the negotiated wire protocol via trace2 on
both client and server.

Changes in V2:
* adds a format_protocol_version() helper function
* adds tests
* bug fix: actually log on the server side, rather than twice on the
  client
* moves the trace statement closer to the actual version negotiation
  code

Josh Steadmon (2):
  protocol: add protocol version formatting function
  connect, protocol: log negotiated protocol version

 connect.c                             |  3 +++
 protocol.c                            | 17 +++++++++++++++++
 protocol.h                            |  6 ++++++
 t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++
 4 files changed, 38 insertions(+)
-- 
2.32.0.554.ge1b32706d8-goog

[PATCH v2 1/2] protocol: add protocol version formatting function

[Josh Steadmon]

Add a function to get human-readable names for the various wire protocol
versions.

Signed-off-by: Josh Steadmon <steadmon@google.com>
---
 protocol.c | 14 ++++++++++++++
 protocol.h |  6 ++++++
 2 files changed, 20 insertions(+)

diff --git a/protocol.c b/protocol.c
index 052d7edbb9..7ec7ce896e 100644
--- a/protocol.c
+++ b/protocol.c
@@ -14,6 +14,20 @@ static enum protocol_version parse_protocol_version(const char *value)
 		return protocol_unknown_version;
 }
 
+const char *format_protocol_version(enum protocol_version version)
+{
+	switch (version) {
+		case protocol_v0:
+			return "0";
+		case protocol_v1:
+			return "1";
+		case protocol_v2:
+			return "2";
+		default:
+			return "UNKNOWN_VERSION";
+	}
+}
+
 enum protocol_version get_protocol_version_config(void)
 {
 	const char *value;
diff --git a/protocol.h b/protocol.h
index cef1a4a01c..22e7a70912 100644
--- a/protocol.h
+++ b/protocol.h
@@ -8,6 +8,12 @@ enum protocol_version {
 	protocol_v2 = 2,
 };
 
+/*
+ * Return a string representation for a given protocol version. Mainly used to
+ * handle protocol_unknown_version nicely.
+ */
+const char *format_protocol_version(enum protocol_version);
+
 /*
  * Used by a client to determine which protocol version to request be used when
  * communicating with a server, reflecting the configured value of the
-- 
2.32.0.554.ge1b32706d8-goog

Re: [PATCH v2 1/2] protocol: add protocol version formatting function

[Ævar Arnfjörð Bjarmason]

On Wed, Aug 04 2021, Josh Steadmon wrote:

> Add a function to get human-readable names for the various wire protocol
> versions.
>
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---
>  protocol.c | 14 ++++++++++++++
>  protocol.h |  6 ++++++
>  2 files changed, 20 insertions(+)
>
> diff --git a/protocol.c b/protocol.c
> index 052d7edbb9..7ec7ce896e 100644
> --- a/protocol.c
> +++ b/protocol.c
> @@ -14,6 +14,20 @@ static enum protocol_version parse_protocol_version(const char *value)
>  		return protocol_unknown_version;
>  }
>  
> +const char *format_protocol_version(enum protocol_version version)
> +{
> +	switch (version) {
> +		case protocol_v0:

Don't indent "case" one more than "switch".

(Looking at CodingGuidelines we only have that advice for *.sh, but we
follow it for C too).

> +			return "0";
> +		case protocol_v1:
> +			return "1";
> +		case protocol_v2:
> +			return "2";
> +		default:
> +			return "UNKNOWN_VERSION";

Using the "default" case like that is an anti-pattern, i.e. you
enumerted all arms except protocol_unknown_version, which is implicitly
covered by your "default" case.

Just list it, and don't have a "default" case, then the compiler will
complain if we ever add a new case that's not covered.

As an aside, and not strictly needed here: More generally between this
and parse_protocol_version() it seems like this would benefit from just
declaring the bidirectional mapping beween the enum fields and string
values, and then have this and that function use that. See
e.g. object_type_strings and associated functions in object.c for
another enum that has such a bidirectional lookup.

[PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Josh Steadmon]

It is useful for performance monitoring and debugging purposes to know
the wire protocol used for remote operations. This may differ from the
version set in local configuration due to differences in version and/or
configuration between the server and the client. Therefore, log the
negotiated wire protocol version via trace2, for both clients and
servers.

Signed-off-by: Josh Steadmon <steadmon@google.com>
---
 connect.c                             |  3 +++
 protocol.c                            |  3 +++
 t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++
 3 files changed, 18 insertions(+)

diff --git a/connect.c b/connect.c
index 70b13389ba..5f0e113625 100644
--- a/connect.c
+++ b/connect.c
@@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)
 		break;
 	}
 
+	trace2_data_string("transfer", NULL, "negotiated-version",
+			   format_protocol_version(version));
+
 	switch (version) {
 	case protocol_v2:
 		process_capabilities_v2(reader);
diff --git a/protocol.c b/protocol.c
index 7ec7ce896e..f52dc2d7a2 100644
--- a/protocol.c
+++ b/protocol.c
@@ -87,6 +87,9 @@ enum protocol_version determine_protocol_version_server(void)
 		string_list_clear(&list, 0);
 	}
 
+	trace2_data_string("transfer", NULL, "negotiated-version",
+			   format_protocol_version(version));
+
 	return version;
 }
 
diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh
index f1d189d5bc..88871c59b5 100755
--- a/t/t5705-session-id-in-capabilities.sh
+++ b/t/t5705-session-id-in-capabilities.sh
@@ -40,6 +40,7 @@ do
 		test -z "$(grep \"key\":\"server-sid\" tr2-client-events)" &&
 		test -z "$(grep \"key\":\"client-sid\" tr2-server-events)"
 	'
+
 done
 
 test_expect_success 'enable SID advertisement' '
@@ -73,6 +74,17 @@ do
 		grep \"key\":\"server-sid\" tr2-client-events &&
 		grep \"key\":\"client-sid\" tr2-server-events
 	'
+
+	test_expect_success "client & server log negotiated version (v${PROTO})" '
+		test_when_finished "rm -rf local tr2-client-events tr2-server-events" &&
+		cp -r "$LOCAL_PRISTINE" local &&
+		GIT_TRACE2_EVENT="$(pwd)/tr2-client-events" \
+		git -c protocol.version=$PROTO -C local fetch \
+			--upload-pack "GIT_TRACE2_EVENT=\"$(pwd)/tr2-server-events\" git-upload-pack" \
+			origin &&
+		test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-client-events)" &&
+		test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-server-events)"
+	'
 done
 
 test_done
-- 
2.32.0.554.ge1b32706d8-goog

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Eric Sunshine]

On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon <steadmon@google.com> wrote:
> It is useful for performance monitoring and debugging purposes to know
> the wire protocol used for remote operations. This may differ from the
> version set in local configuration due to differences in version and/or
> configuration between the server and the client. Therefore, log the
> negotiated wire protocol version via trace2, for both clients and
> servers.
>
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---
> diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh
> @@ -73,6 +74,17 @@ do
> +       test_expect_success "client & server log negotiated version (v${PROTO})" '
> +               test_when_finished "rm -rf local tr2-client-events tr2-server-events" &&
> +               cp -r "$LOCAL_PRISTINE" local &&
> +               GIT_TRACE2_EVENT="$(pwd)/tr2-client-events" \
> +               git -c protocol.version=$PROTO -C local fetch \
> +                       --upload-pack "GIT_TRACE2_EVENT=\"$(pwd)/tr2-server-events\" git-upload-pack" \
> +                       origin &&
> +               test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-client-events)" &&
> +               test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-server-events)"
> +       '
>  done

What are these `test` commands actually testing? Did you mean `test
-n`? Or, even better, just plain `grep` (not within a
command-substitution)?

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Josh Steadmon]

On 2021.08.04 18:28, Eric Sunshine wrote:
> On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon <steadmon@google.com> wrote:
> > It is useful for performance monitoring and debugging purposes to know
> > the wire protocol used for remote operations. This may differ from the
> > version set in local configuration due to differences in version and/or
> > configuration between the server and the client. Therefore, log the
> > negotiated wire protocol version via trace2, for both clients and
> > servers.
> >
> > Signed-off-by: Josh Steadmon <steadmon@google.com>
> > ---
> > diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh
> > @@ -73,6 +74,17 @@ do
> > +       test_expect_success "client & server log negotiated version (v${PROTO})" '
> > +               test_when_finished "rm -rf local tr2-client-events tr2-server-events" &&
> > +               cp -r "$LOCAL_PRISTINE" local &&
> > +               GIT_TRACE2_EVENT="$(pwd)/tr2-client-events" \
> > +               git -c protocol.version=$PROTO -C local fetch \
> > +                       --upload-pack "GIT_TRACE2_EVENT=\"$(pwd)/tr2-server-events\" git-upload-pack" \
> > +                       origin &&
> > +               test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-client-events)" &&
> > +               test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-server-events)"
> > +       '
> >  done
> 
> What are these `test` commands actually testing? Did you mean `test
> -n`? Or, even better, just plain `grep` (not within a
> command-substitution)?

Yes, sorry about that, just plain grep is best here. This was due to a
quick copy & paste modification, I should have spent a bit more time
thinking about the test case.

Will be fixed in V3.

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Ævar Arnfjörð Bjarmason]

On Wed, Aug 04 2021, Josh Steadmon wrote:

> It is useful for performance monitoring and debugging purposes to know
> the wire protocol used for remote operations. This may differ from the
> version set in local configuration due to differences in version and/or
> configuration between the server and the client. Therefore, log the
> negotiated wire protocol version via trace2, for both clients and
> servers.
>
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---

I know Taylor asked you to change it to a string from in int upthread in
<YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am
willing to be convinced otherwise.

It seems to me that both of these codepaths will never usefully use this
new "UNKNOWN_VERSION" string you added, i.e.:

>  connect.c                             |  3 +++
>  protocol.c                            |  3 +++
>  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++
>  3 files changed, 18 insertions(+)
>
> diff --git a/connect.c b/connect.c
> index 70b13389ba..5f0e113625 100644
> --- a/connect.c
> +++ b/connect.c
> @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)
>  		break;
>  	}
>  
> +	trace2_data_string("transfer", NULL, "negotiated-version",
> +			   format_protocol_version(version));

Right after this.

>  	switch (version) {
>  	case protocol_v2:
>  		process_capabilities_v2(reader);

We'll die here with BUG("unknown protocol version") if it's unknown..

> diff --git a/protocol.c b/protocol.c
> index 7ec7ce896e..f52dc2d7a2 100644
> --- a/protocol.c
> +++ b/protocol.c
> @@ -87,6 +87,9 @@ enum protocol_version determine_protocol_version_server(void)
>  		string_list_clear(&list, 0);
>  	}
>  
> +	trace2_data_string("transfer", NULL, "negotiated-version",
> +			   format_protocol_version(version));
> +

And this code is simply unreachable as far as logging this
"UNKNOWN_VERSION" string goes. If we did have an unknown version we'd
die right above this with:

    die("server is speaking an unknown protocol")

And if we did not have a "version " at all we'd default to protocol_v0
here, i.e. we either die already on an unknown version, or we don't log
"UNKNOWN_VERSION" at all.

>  	return version;
>  }
>  
> diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh
> index f1d189d5bc..88871c59b5 100755
> --- a/t/t5705-session-id-in-capabilities.sh
> +++ b/t/t5705-session-id-in-capabilities.sh
> @@ -40,6 +40,7 @@ do
>  		test -z "$(grep \"key\":\"server-sid\" tr2-client-events)" &&
>  		test -z "$(grep \"key\":\"client-sid\" tr2-server-events)"
>  	'
> +
>  done
>  
>  test_expect_success 'enable SID advertisement' '
> @@ -73,6 +74,17 @@ do
>  		grep \"key\":\"server-sid\" tr2-client-events &&
>  		grep \"key\":\"client-sid\" tr2-server-events
>  	'
> +
> +	test_expect_success "client & server log negotiated version (v${PROTO})" '
> +		test_when_finished "rm -rf local tr2-client-events tr2-server-events" &&
> +		cp -r "$LOCAL_PRISTINE" local &&
> +		GIT_TRACE2_EVENT="$(pwd)/tr2-client-events" \
> +		git -c protocol.version=$PROTO -C local fetch \
> +			--upload-pack "GIT_TRACE2_EVENT=\"$(pwd)/tr2-server-events\" git-upload-pack" \
> +			origin &&
> +		test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-client-events)" &&
> +		test "$(grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-server-events)"
> +	'
>  done
>  
>  test_done

So given the above I think you can come up with trace2 output where we
log "UNKNOWN_VERSION", it just seems rather useless. We'll hit a BUG()
anyway, which we also trace2 log. In terms of anyone who collect logs
surely they'll first care about logged BUG(), and second about any
version aggregation involved in such a BUG(), and it's not a big deal if
the report of versions doesn't include the "UNKNOWN VERSION" to go with
such a one-off bug.

But perhaps you and Taylor really do have a use-case for this, hence the
"willing to be convinced otherwise". I suspect the desire to log
"<unknown>" came from an assumption that we did so in any recoverable
non-BUG() case, which we won't do.

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Taylor Blau]

On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:
>
> On Wed, Aug 04 2021, Josh Steadmon wrote:
>
> > It is useful for performance monitoring and debugging purposes to know
> > the wire protocol used for remote operations. This may differ from the
> > version set in local configuration due to differences in version and/or
> > configuration between the server and the client. Therefore, log the
> > negotiated wire protocol version via trace2, for both clients and
> > servers.
> >
> > Signed-off-by: Josh Steadmon <steadmon@google.com>
> > ---
>
> I know Taylor asked you to change it to a string from in int upthread in
> <YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am
> willing to be convinced otherwise.

The conversion to log a string instead of an integer is necessary if
Josh wants to write "<unknown>" instead of -1. To me, that seemed
clearer, and I like that it makes the trace2 representation for a
protocol version separate from the protocol_version enum.

> It seems to me that both of these codepaths will never usefully use this
> new "UNKNOWN_VERSION" string you added, i.e.:
>
> >  connect.c                             |  3 +++
> >  protocol.c                            |  3 +++
> >  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++
> >  3 files changed, 18 insertions(+)
> >
> > diff --git a/connect.c b/connect.c
> > index 70b13389ba..5f0e113625 100644
> > --- a/connect.c
> > +++ b/connect.c
> > @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)
> >  		break;
> >  	}
> >
> > +	trace2_data_string("transfer", NULL, "negotiated-version",
> > +			   format_protocol_version(version));
>
> Right after this.
>
> >  	switch (version) {
> >  	case protocol_v2:
> >  		process_capabilities_v2(reader);
>
> We'll die here with BUG("unknown protocol version") if it's unknown..

Good eyes. In fact, the second switch statement shouldn't even need a
case-arm for protocol_unknown_version (but has it to cover all
enumerated values).

I didn't realize before that the unknown case really is dead code, so
we'll never log "<unknown>". And since the mapping from protocol_version
to string is identical for known values, we could probably do without
it.

And I don't much care either way. I think the benefit is really pretty
slim, and arguably my code is just adding unnecessary overhead. So I'm
happy to go with or without it, but I'd be rather sad to spend much more
of our collective time discussing it.

Thanks,
Taylor

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Ævar Arnfjörð Bjarmason]

On Wed, Aug 04 2021, Taylor Blau wrote:

> On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:
>>
>> On Wed, Aug 04 2021, Josh Steadmon wrote:
>>
>> > It is useful for performance monitoring and debugging purposes to know
>> > the wire protocol used for remote operations. This may differ from the
>> > version set in local configuration due to differences in version and/or
>> > configuration between the server and the client. Therefore, log the
>> > negotiated wire protocol version via trace2, for both clients and
>> > servers.
>> >
>> > Signed-off-by: Josh Steadmon <steadmon@google.com>
>> > ---
>>
>> I know Taylor asked you to change it to a string from in int upthread in
>> <YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am
>> willing to be convinced otherwise.
>
> The conversion to log a string instead of an integer is necessary if
> Josh wants to write "<unknown>" instead of -1. To me, that seemed
> clearer, and I like that it makes the trace2 representation for a
> protocol version separate from the protocol_version enum.

Yes, having a magic -1 value would be bad, but since it seems we'll
never get it in practice...

>> It seems to me that both of these codepaths will never usefully use this
>> new "UNKNOWN_VERSION" string you added, i.e.:
>>
>> >  connect.c                             |  3 +++
>> >  protocol.c                            |  3 +++
>> >  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++
>> >  3 files changed, 18 insertions(+)
>> >
>> > diff --git a/connect.c b/connect.c
>> > index 70b13389ba..5f0e113625 100644
>> > --- a/connect.c
>> > +++ b/connect.c
>> > @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)
>> >  		break;
>> >  	}
>> >
>> > +	trace2_data_string("transfer", NULL, "negotiated-version",
>> > +			   format_protocol_version(version));
>>
>> Right after this.
>>
>> >  	switch (version) {
>> >  	case protocol_v2:
>> >  		process_capabilities_v2(reader);
>>
>> We'll die here with BUG("unknown protocol version") if it's unknown..
>
> Good eyes. In fact, the second switch statement shouldn't even need a
> case-arm for protocol_unknown_version (but has it to cover all
> enumerated values).

I didn't check if crafting an unknown version will be found earlier, or
if we'll actually reach that "unknown" case.

> I didn't realize before that the unknown case really is dead code, so
> we'll never log "<unknown>". And since the mapping from protocol_version
> to string is identical for known values, we could probably do without
> it.
>
> And I don't much care either way. I think the benefit is really pretty
> slim, and arguably my code is just adding unnecessary overhead. So I'm
> happy to go with or without it, but I'd be rather sad to spend much more
> of our collective time discussing it.

Yeah, I just think if we can be sure it's an integer *and* a valid
version when we log it, people writing future log summarizing code will
thank us, i.e. just 0, 1, 2, and in the future maybe 3, ..., but not -1
or "<unknown>" or other values we'll trust die() etc. to handle.

Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version

[Josh Steadmon]

On 2021.08.05 04:47, Ævar Arnfjörð Bjarmason wrote:
> 
> On Wed, Aug 04 2021, Taylor Blau wrote:
> 
> > I didn't realize before that the unknown case really is dead code, so
> > we'll never log "<unknown>". And since the mapping from protocol_version
> > to string is identical for known values, we could probably do without
> > it.
> >
> > And I don't much care either way. I think the benefit is really pretty
> > slim, and arguably my code is just adding unnecessary overhead. So I'm
> > happy to go with or without it, but I'd be rather sad to spend much more
> > of our collective time discussing it.
> 
> Yeah, I just think if we can be sure it's an integer *and* a valid
> version when we log it, people writing future log summarizing code will
> thank us, i.e. just 0, 1, 2, and in the future maybe 3, ..., but not -1
> or "<unknown>" or other values we'll trust die() etc. to handle.

Sounds good, in V3 I will switch back to logging the enum value
directly, and will make sure we don't log anything if the version is
unknown. Thanks both for the discussion!

[PATCH v3] connect, protocol: log negotiated protocol version

[Josh Steadmon]

It is useful for performance monitoring and debugging purposes to know
the wire protocol used for remote operations. This may differ from the
version set in local configuration due to differences in version and/or
configuration between the server and the client. Therefore, log the
negotiated wire protocol version via trace2, for both clients and
servers.

Signed-off-by: Josh Steadmon <steadmon@google.com>
---

Changes in V3:
* remove unnecessary `test` calls in the new t5705 test cases
* remove the wire protocol version formatting function
* log the wire protocol version enum value directly, as in V0 of this
  series
* avoid logging the protocol version if negotiation fails (i.e., if we
  end up with "protocol_unknown_version")

Changes in V2:
* adds a format_protocol_version() helper function
* adds tests
* bug fix: actually log on the server side, rather than twice on the
  client
* moves the trace statement closer to the actual version negotiation
  code

 connect.c                             |  2 ++
 protocol.c                            |  2 ++
 t/t5705-session-id-in-capabilities.sh | 11 +++++++++++
 3 files changed, 15 insertions(+)

diff --git a/connect.c b/connect.c
index 70b13389ba..aff13a270e 100644
--- a/connect.c
+++ b/connect.c
@@ -164,6 +164,8 @@ enum protocol_version discover_version(struct packet_reader *reader)
 		BUG("unknown protocol version");
 	}
 
+	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
+
 	return version;
 }
 
diff --git a/protocol.c b/protocol.c
index 052d7edbb9..c53f7df5be 100644
--- a/protocol.c
+++ b/protocol.c
@@ -73,6 +73,8 @@ enum protocol_version determine_protocol_version_server(void)
 		string_list_clear(&list, 0);
 	}
 
+	trace2_data_intmax("transfer", NULL, "negotiated-version", version);
+
 	return version;
 }
 
diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh
index f1d189d5bc..eb8c79aafd 100755
--- a/t/t5705-session-id-in-capabilities.sh
+++ b/t/t5705-session-id-in-capabilities.sh
@@ -73,6 +73,17 @@ do
 		grep \"key\":\"server-sid\" tr2-client-events &&
 		grep \"key\":\"client-sid\" tr2-server-events
 	'
+
+	test_expect_success "client & server log negotiated version (v${PROTO})" '
+		test_when_finished "rm -rf local tr2-client-events tr2-server-events" &&
+		cp -r "$LOCAL_PRISTINE" local &&
+		GIT_TRACE2_EVENT="$(pwd)/tr2-client-events" \
+		git -c protocol.version=$PROTO -C local fetch \
+			--upload-pack "GIT_TRACE2_EVENT=\"$(pwd)/tr2-server-events\" git-upload-pack" \
+			origin &&
+		grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-client-events &&
+		grep \"key\":\"negotiated-version\",\"value\":\"$PROTO\" tr2-server-events
+	'
 done
 
 test_done
-- 
2.32.0.605.g8dce9f2422-goog

Re: [PATCH v3] connect, protocol: log negotiated protocol version

[Taylor Blau]

On Tue, Aug 10, 2021 at 10:20:39AM -0700, Josh Steadmon wrote:
> It is useful for performance monitoring and debugging purposes to know
> the wire protocol used for remote operations. This may differ from the
> version set in local configuration due to differences in version and/or
> configuration between the server and the client. Therefore, log the
> negotiated wire protocol version via trace2, for both clients and
> servers.
>
> Signed-off-by: Josh Steadmon <steadmon@google.com>
> ---
>
> Changes in V3:
> * remove unnecessary `test` calls in the new t5705 test cases
> * remove the wire protocol version formatting function
> * log the wire protocol version enum value directly, as in V0 of this
>   series
> * avoid logging the protocol version if negotiation fails (i.e., if we
>   end up with "protocol_unknown_version")

Nicely done. This version looks ready to be picked up by my eyes.

    Reviewed-by: Taylor Blau <me@ttaylorr.comg>

Thanks,
Taylor