[PATCH] 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 <redacted>
---

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

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.

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...

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

On 2021.08.03 17:12, Taylor Blau wrote:

On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:

quoted

[...] Therefore, log the negotiated wire protocol version via trace2,
for both clients and servers.

Seems useful, thanks.

quoted

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().

quoted

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...

quoted

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

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

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

Signed-off-by: Josh Steadmon <redacted>
---
 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

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 <redacted>
---
 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

On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon [off-list ref] wrote:

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

On Wed, Aug 04 2021, Josh Steadmon wrote:

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.

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 <redacted>
---

I know Taylor asked you to change it to a string from in int upthread in
[off-list ref], 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.:

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..

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.

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.

On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:

On Wed, Aug 04 2021, Josh Steadmon wrote:

quoted

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 <redacted>
---

I know Taylor asked you to change it to a string from in int upthread in
[off-list ref], 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.:

quoted

 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.

quoted

 	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

On Wed, Aug 04 2021, Taylor Blau wrote:

On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:

quoted

On Wed, Aug 04 2021, Josh Steadmon wrote:

quoted

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 <redacted>
---

I know Taylor asked you to change it to a string from in int upthread in
[off-list ref], 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...

quoted

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

quoted

 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.

quoted

 	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.

On 2021.08.04 18:28, Eric Sunshine wrote:

On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon [off-list ref] wrote:

quoted

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 <redacted>
---

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.

On 2021.08.05 04:47, Ævar Arnfjörð Bjarmason wrote:

On Wed, Aug 04 2021, Taylor Blau wrote:

quoted

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!

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 <redacted>
---

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

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 <redacted>
---

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 [off-list ref]

Thanks,
Taylor