threads / patch / 56209

patchconnect, protocol: log negotiated protocol version

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

## tl;dr

16 messages between Aug 3, 2021 and Aug 16, 2021. Diffs are folded; open one to read it.

replies: 15people: 5as markdown or json

Josh Steadmon· Aug 3, 2021, 20:13 UTC · lore

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(+)
Show changes to 2 files +2 −0

connect.c, protocol.c

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
Taylor Blau· Aug 3, 2021, 21:12 UTC · re: Josh Steadmon · lore

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

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.

Show 9 quoted lines
> 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...

Show 12 quoted lines
> 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

Josh Steadmon· Aug 4, 2021, 21:37 UTC · re: Taylor Blau · lore

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

On 2021.08.03 17:12, Taylor Blau wrote:
Show 15 quoted lines
> 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().
Show 13 quoted lines
> > 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.
Show 28 quoted lines
> (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
Junio C Hamano· Aug 4, 2021, 21:56 UTC · re: Josh Steadmon · lore

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

Josh Steadmon <steadmon@google.com> writes:
Show 6 quoted lines
> 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 ;-)

Josh Steadmon· Aug 4, 2021, 22:17 UTC · re: Josh Steadmon · lore

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

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
Josh Steadmon· Aug 4, 2021, 22:17 UTC · re: Josh Steadmon · lore

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

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(+)
Show changes to 2 files +20 −0

protocol.c, protocol.h

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
Ævar Arnfjörð Bjarmason· Aug 4, 2021, 23:32 UTC · re: Josh Steadmon · lore

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

On Wed, Aug 04 2021, Josh Steadmon wrote:
Show 21 quoted lines
> 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).

Show 7 quoted lines
> +			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.

Josh Steadmon· Aug 4, 2021, 22:17 UTC · re: Josh Steadmon · lore

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

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(+)
Show changes to 3 files +18 −0

connect.c, protocol.c, t/t5705-session-id-in-capabilities.sh

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
Eric Sunshine· Aug 4, 2021, 22:28 UTC · re: Josh Steadmon · lore

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

On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon <steadmon@google.com> wrote:
Show 22 quoted lines
> 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)?

Josh Steadmon· Aug 6, 2021, 21:15 UTC · re: Eric Sunshine · lore

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

On 2021.08.04 18:28, Eric Sunshine wrote:
Show 27 quoted lines
> 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.
Ævar Arnfjörð Bjarmason· Aug 4, 2021, 23:40 UTC · re: Josh Steadmon · lore

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

On Wed, Aug 04 2021, Josh Steadmon wrote:
Show 9 quoted lines
> 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.:

Show 15 quoted lines
>  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..
Show 11 quoted lines
> 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.

Show 33 quoted lines
>  	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.

Taylor Blau· Aug 5, 2021, 01:26 UTC · re: Ævar Arnfjörð Bjarmason · lore

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

On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:
Show 16 quoted lines
>
> 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.

Show 26 quoted lines
> 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

Ævar Arnfjörð Bjarmason· Aug 5, 2021, 02:47 UTC · re: Taylor Blau · lore

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

On Wed, Aug 04 2021, Taylor Blau wrote:
Show 22 quoted lines
> 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...

Show 30 quoted lines
>> 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.

Show 9 quoted lines
> 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.

Josh Steadmon· Aug 6, 2021, 21:22 UTC · re: Ævar Arnfjörð Bjarmason · lore

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

On 2021.08.05 04:47, Ævar Arnfjörð Bjarmason wrote:
Show 17 quoted lines
> 
> 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!

Josh Steadmon· Aug 10, 2021, 17:20 UTC · re: Josh Steadmon · lore

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

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(+)
Show changes to 3 files +15 −0

connect.c, protocol.c, t/t5705-session-id-in-capabilities.sh

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
Taylor Blau· Aug 16, 2021, 18:03 UTC · re: Josh Steadmon · lore

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

On Tue, Aug 10, 2021 at 10:20:39AM -0700, Josh Steadmon wrote:
Show 17 quoted lines
> 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

← back to recent threads