{"thread":{"id":"56209","subject":"[PATCH] connect, protocol: log negotiated protocol version","startedAt":"2021-08-03T20:13:07Z","lastAt":"2021-08-16T18:03:34Z","messageCount":16,"participants":["Josh Steadmon","Taylor Blau","Junio C Hamano","Eric Sunshine","Ævar Arnfjörð Bjarmason"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"431879","messageId":"f79ab95af6da3da710da2112cfcae4a042b7f7fb.1628020616.git.steadmon@google.com","threadId":"56209","inReplyTo":null,"subject":"[PATCH] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-03T20:13:02Z","receivedAt":"2021-08-03T20:13:07Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"It is useful for performance monitoring and debugging purposes to know\nthe wire protocol used for remote operations. This may differ from the\nversion set in local configuration due to differences in version and/or\nconfiguration between the server and the client. Therefore, log the\nnegotiated wire protocol version via trace2, for both clients and\nservers.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n\nDo people have a preference for logging this as an integer (and\ntherefore having \"unknown protocol version\" show up as \"-1\", or should I\nadd a protocol_version_to_string function so that we can format it\nproperly? For now I've erred on the side of having a smaller diff.\n\n connect.c  | 1 +\n protocol.c | 1 +\n 2 files changed, 2 insertions(+)\n\ndiff --git a/connect.c b/connect.c\nindex 70b13389ba..6e23e3ff2d 100644\n--- a/connect.c\n+++ b/connect.c\n@@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)\n \t\tBUG(\"unknown protocol version\");\n \t}\n \n+\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n \treturn version;\n }\n \ndiff --git a/protocol.c b/protocol.c\nindex 052d7edbb9..3791d8499e 100644\n--- a/protocol.c\n+++ b/protocol.c\n@@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo\n \t\t\tdie(\"protocol error: server explicitly said version 0\");\n \t}\n \n+\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n \treturn version;\n }\n-- \n2.32.0.554.ge1b32706d8-goog\n\n"},{"id":"431883","messageId":"YQmxSxTswHE/gTet@nand.local","threadId":"56209","inReplyTo":"f79ab95af6da3da710da2112cfcae4a042b7f7fb.1628020616.git.steadmon@google.com","subject":"Re: [PATCH] connect, protocol: log negotiated protocol version","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2021-08-03T21:12:43Z","receivedAt":"2021-08-03T21:12:46Z","isPatch":true,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:\n> [...] Therefore, log the negotiated wire protocol version via trace2,\n> for both clients and servers.\n\nSeems useful, thanks.\n\n> Do people have a preference for logging this as an integer (and\n> therefore having \"unknown protocol version\" show up as \"-1\", or should I\n> add a protocol_version_to_string function so that we can format it\n> properly? For now I've erred on the side of having a smaller diff.\n\nI probably have a slight preference for converting the protocol_version\nto a string and passing that along to trace2_data_string() instead. That\nwould let you more cleanly log \"<unknown>\", without needing to expose\nimplementation details like which enum has what value.\n\n> diff --git a/connect.c b/connect.c\n> index 70b13389ba..6e23e3ff2d 100644\n> --- a/connect.c\n> +++ b/connect.c\n> @@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)\n>  \t\tBUG(\"unknown protocol version\");\n>  \t}\n>\n> +\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n\nSmall nit-pick, this could come between the two switch statements, not\nat the end of the function (since we know what we are going to return\nbefore we switch on version.\n\n(I was a little surprised to see that these functions now have the\nside-effect of writing to trace2, since I would have instead expected\nto see new lines added at the callers. But this makes it more\nconvenient, and I do not feel strongly about it)\n\nIn any case, connect.c:discover_version() is handling the client side,\nbut...\n\n> diff --git a/protocol.c b/protocol.c\n> index 052d7edbb9..3791d8499e 100644\n> --- a/protocol.c\n> +++ b/protocol.c\n> @@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo\n>  \t\t\tdie(\"protocol error: server explicitly said version 0\");\n>  \t}\n>\n> +\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n>  \treturn version;\n>  }\n> --\n\nThis function is used by discover_version to parse the server's\nresponse. If you are trying to log what protocol was agreed on from the\nserver's perspective, I think you are looking instead for\ndetermine_protocol_version_server().\n\nIf you aren't (and are only interested in the client's point-of-view),\nthen I am pretty sure that this latter hunk is redundant.\n\nThanks,\nTaylor\n"},{"id":"431988","messageId":"YQsIscghtbpKI/OI@google.com","threadId":"56209","inReplyTo":"YQmxSxTswHE/gTet@nand.local","subject":"Re: [PATCH] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-04T21:37:53Z","receivedAt":"2021-08-04T21:38:04Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2021.08.03 17:12, Taylor Blau wrote:\n> On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:\n> > [...] Therefore, log the negotiated wire protocol version via trace2,\n> > for both clients and servers.\n> \n> Seems useful, thanks.\n> \n> > Do people have a preference for logging this as an integer (and\n> > therefore having \"unknown protocol version\" show up as \"-1\", or should I\n> > add a protocol_version_to_string function so that we can format it\n> > properly? For now I've erred on the side of having a smaller diff.\n> \n> I probably have a slight preference for converting the protocol_version\n> to a string and passing that along to trace2_data_string() instead. That\n> would let you more cleanly log \"<unknown>\", without needing to expose\n> implementation details like which enum has what value.\n\nV2 will include a format_protocol_version().\n\n\n> > diff --git a/connect.c b/connect.c\n> > index 70b13389ba..6e23e3ff2d 100644\n> > --- a/connect.c\n> > +++ b/connect.c\n> > @@ -164,6 +164,7 @@ enum protocol_version discover_version(struct packet_reader *reader)\n> >  \t\tBUG(\"unknown protocol version\");\n> >  \t}\n> >\n> > +\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n> \n> Small nit-pick, this could come between the two switch statements, not\n> at the end of the function (since we know what we are going to return\n> before we switch on version.\n\nFixed in V2.\n\n\n> (I was a little surprised to see that these functions now have the\n> side-effect of writing to trace2, since I would have instead expected\n> to see new lines added at the callers. But this makes it more\n> convenient, and I do not feel strongly about it)\n> \n> In any case, connect.c:discover_version() is handling the client side,\n> but...\n> \n> > diff --git a/protocol.c b/protocol.c\n> > index 052d7edbb9..3791d8499e 100644\n> > --- a/protocol.c\n> > +++ b/protocol.c\n> > @@ -89,5 +89,6 @@ enum protocol_version determine_protocol_version_client(const char *server_respo\n> >  \t\t\tdie(\"protocol error: server explicitly said version 0\");\n> >  \t}\n> >\n> > +\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n> >  \treturn version;\n> >  }\n> > --\n> \n> This function is used by discover_version to parse the server's\n> response. If you are trying to log what protocol was agreed on from the\n> server's perspective, I think you are looking instead for\n> determine_protocol_version_server().\n> \n> If you aren't (and are only interested in the client's point-of-view),\n> then I am pretty sure that this latter hunk is redundant.\n\nThanks for catching this dumb mistake. Fixed in V2, and added tests to\nmake sure the trace message shows up on both client- & server-side.\n\n> Thanks,\n> Taylor\n"},{"id":"431992","messageId":"xmqqh7g4naao.fsf@gitster.g","threadId":"56209","inReplyTo":"YQsIscghtbpKI/OI@google.com","subject":"Re: [PATCH] connect, protocol: log negotiated protocol version","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-08-04T21:56:47Z","receivedAt":"2021-08-04T21:56:58Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Josh Steadmon <steadmon@google.com> writes:\n\n> On 2021.08.03 17:12, Taylor Blau wrote:\n>> On Tue, Aug 03, 2021 at 01:13:02PM -0700, Josh Steadmon wrote:\n> V2 will include a format_protocol_version().\n> ...\n> Thanks for catching this dumb mistake. Fixed in V2, and added tests to\n> make sure the trace message shows up on both client- & server-side.\n\nThanks, both.  I was about to merge the original one to 'next' as a\n\"good enough\" version, but you caught me just in time ;-)\n\n"},{"id":"431994","messageId":"cover.1628115064.git.steadmon@google.com","threadId":"56209","inReplyTo":"f79ab95af6da3da710da2112cfcae4a042b7f7fb.1628020616.git.steadmon@google.com","subject":"[PATCH v2 0/2] log negotiated protocol version.","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-04T22:17:07Z","receivedAt":"2021-08-04T22:17:15Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"This series adds logging of the negotiated wire protocol via trace2 on\nboth client and server.\n\nChanges in V2:\n* adds a format_protocol_version() helper function\n* adds tests\n* bug fix: actually log on the server side, rather than twice on the\n  client\n* moves the trace statement closer to the actual version negotiation\n  code\n\nJosh Steadmon (2):\n  protocol: add protocol version formatting function\n  connect, protocol: log negotiated protocol version\n\n connect.c                             |  3 +++\n protocol.c                            | 17 +++++++++++++++++\n protocol.h                            |  6 ++++++\n t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++\n 4 files changed, 38 insertions(+)\n-- \n2.32.0.554.ge1b32706d8-goog\n\n"},{"id":"431995","messageId":"63f98062788a7c5d44fafecfde78077bdce2af73.1628115065.git.steadmon@google.com","threadId":"56209","inReplyTo":"cover.1628115064.git.steadmon@google.com","subject":"[PATCH v2 1/2] protocol: add protocol version formatting function","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-04T22:17:08Z","receivedAt":"2021-08-04T22:17:23Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"Add a function to get human-readable names for the various wire protocol\nversions.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n protocol.c | 14 ++++++++++++++\n protocol.h |  6 ++++++\n 2 files changed, 20 insertions(+)\n\ndiff --git a/protocol.c b/protocol.c\nindex 052d7edbb9..7ec7ce896e 100644\n--- a/protocol.c\n+++ b/protocol.c\n@@ -14,6 +14,20 @@ static enum protocol_version parse_protocol_version(const char *value)\n \t\treturn protocol_unknown_version;\n }\n \n+const char *format_protocol_version(enum protocol_version version)\n+{\n+\tswitch (version) {\n+\t\tcase protocol_v0:\n+\t\t\treturn \"0\";\n+\t\tcase protocol_v1:\n+\t\t\treturn \"1\";\n+\t\tcase protocol_v2:\n+\t\t\treturn \"2\";\n+\t\tdefault:\n+\t\t\treturn \"UNKNOWN_VERSION\";\n+\t}\n+}\n+\n enum protocol_version get_protocol_version_config(void)\n {\n \tconst char *value;\ndiff --git a/protocol.h b/protocol.h\nindex cef1a4a01c..22e7a70912 100644\n--- a/protocol.h\n+++ b/protocol.h\n@@ -8,6 +8,12 @@ enum protocol_version {\n \tprotocol_v2 = 2,\n };\n \n+/*\n+ * Return a string representation for a given protocol version. Mainly used to\n+ * handle protocol_unknown_version nicely.\n+ */\n+const char *format_protocol_version(enum protocol_version);\n+\n /*\n  * Used by a client to determine which protocol version to request be used when\n  * communicating with a server, reflecting the configured value of the\n-- \n2.32.0.554.ge1b32706d8-goog\n\n"},{"id":"431996","messageId":"d138b2615c1af288627b9a2f8f7dd3d2fed184d7.1628115065.git.steadmon@google.com","threadId":"56209","inReplyTo":"cover.1628115064.git.steadmon@google.com","subject":"[PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-04T22:17:09Z","receivedAt":"2021-08-04T22:17:23Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"It is useful for performance monitoring and debugging purposes to know\nthe wire protocol used for remote operations. This may differ from the\nversion set in local configuration due to differences in version and/or\nconfiguration between the server and the client. Therefore, log the\nnegotiated wire protocol version via trace2, for both clients and\nservers.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n connect.c                             |  3 +++\n protocol.c                            |  3 +++\n t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++\n 3 files changed, 18 insertions(+)\n\ndiff --git a/connect.c b/connect.c\nindex 70b13389ba..5f0e113625 100644\n--- a/connect.c\n+++ b/connect.c\n@@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)\n \t\tbreak;\n \t}\n \n+\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n+\t\t\t   format_protocol_version(version));\n+\n \tswitch (version) {\n \tcase protocol_v2:\n \t\tprocess_capabilities_v2(reader);\ndiff --git a/protocol.c b/protocol.c\nindex 7ec7ce896e..f52dc2d7a2 100644\n--- a/protocol.c\n+++ b/protocol.c\n@@ -87,6 +87,9 @@ enum protocol_version determine_protocol_version_server(void)\n \t\tstring_list_clear(&list, 0);\n \t}\n \n+\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n+\t\t\t   format_protocol_version(version));\n+\n \treturn version;\n }\n \ndiff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh\nindex f1d189d5bc..88871c59b5 100755\n--- a/t/t5705-session-id-in-capabilities.sh\n+++ b/t/t5705-session-id-in-capabilities.sh\n@@ -40,6 +40,7 @@ do\n \t\ttest -z \"$(grep \\\"key\\\":\\\"server-sid\\\" tr2-client-events)\" &&\n \t\ttest -z \"$(grep \\\"key\\\":\\\"client-sid\\\" tr2-server-events)\"\n \t'\n+\n done\n \n test_expect_success 'enable SID advertisement' '\n@@ -73,6 +74,17 @@ do\n \t\tgrep \\\"key\\\":\\\"server-sid\\\" tr2-client-events &&\n \t\tgrep \\\"key\\\":\\\"client-sid\\\" tr2-server-events\n \t'\n+\n+\ttest_expect_success \"client & server log negotiated version (v${PROTO})\" '\n+\t\ttest_when_finished \"rm -rf local tr2-client-events tr2-server-events\" &&\n+\t\tcp -r \"$LOCAL_PRISTINE\" local &&\n+\t\tGIT_TRACE2_EVENT=\"$(pwd)/tr2-client-events\" \\\n+\t\tgit -c protocol.version=$PROTO -C local fetch \\\n+\t\t\t--upload-pack \"GIT_TRACE2_EVENT=\\\"$(pwd)/tr2-server-events\\\" git-upload-pack\" \\\n+\t\t\torigin &&\n+\t\ttest \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-client-events)\" &&\n+\t\ttest \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-server-events)\"\n+\t'\n done\n \n test_done\n-- \n2.32.0.554.ge1b32706d8-goog\n\n"},{"id":"432001","messageId":"CAPig+cSqm5cUmAVG6f73oZ+mi9pBJrOg2va2a_Op4=wNFyHfZQ@mail.gmail.com","threadId":"56209","inReplyTo":"d138b2615c1af288627b9a2f8f7dd3d2fed184d7.1628115065.git.steadmon@google.com","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-08-04T22:28:45Z","receivedAt":"2021-08-04T22:29:00Z","isPatch":true,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon <steadmon@google.com> wrote:\n> It is useful for performance monitoring and debugging purposes to know\n> the wire protocol used for remote operations. This may differ from the\n> version set in local configuration due to differences in version and/or\n> configuration between the server and the client. Therefore, log the\n> negotiated wire protocol version via trace2, for both clients and\n> servers.\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n> diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh\n> @@ -73,6 +74,17 @@ do\n> +       test_expect_success \"client & server log negotiated version (v${PROTO})\" '\n> +               test_when_finished \"rm -rf local tr2-client-events tr2-server-events\" &&\n> +               cp -r \"$LOCAL_PRISTINE\" local &&\n> +               GIT_TRACE2_EVENT=\"$(pwd)/tr2-client-events\" \\\n> +               git -c protocol.version=$PROTO -C local fetch \\\n> +                       --upload-pack \"GIT_TRACE2_EVENT=\\\"$(pwd)/tr2-server-events\\\" git-upload-pack\" \\\n> +                       origin &&\n> +               test \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-client-events)\" &&\n> +               test \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-server-events)\"\n> +       '\n>  done\n\nWhat are these `test` commands actually testing? Did you mean `test\n-n`? Or, even better, just plain `grep` (not within a\ncommand-substitution)?\n"},{"id":"432013","messageId":"87czqsn5k9.fsf@evledraar.gmail.com","threadId":"56209","inReplyTo":"63f98062788a7c5d44fafecfde78077bdce2af73.1628115065.git.steadmon@google.com","subject":"Re: [PATCH v2 1/2] protocol: add protocol version formatting function","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-08-04T23:32:00Z","receivedAt":"2021-08-04T23:39:07Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Wed, Aug 04 2021, Josh Steadmon wrote:\n\n> Add a function to get human-readable names for the various wire protocol\n> versions.\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n>  protocol.c | 14 ++++++++++++++\n>  protocol.h |  6 ++++++\n>  2 files changed, 20 insertions(+)\n>\n> diff --git a/protocol.c b/protocol.c\n> index 052d7edbb9..7ec7ce896e 100644\n> --- a/protocol.c\n> +++ b/protocol.c\n> @@ -14,6 +14,20 @@ static enum protocol_version parse_protocol_version(const char *value)\n>  \t\treturn protocol_unknown_version;\n>  }\n>  \n> +const char *format_protocol_version(enum protocol_version version)\n> +{\n> +\tswitch (version) {\n> +\t\tcase protocol_v0:\n\nDon't indent \"case\" one more than \"switch\".\n\n(Looking at CodingGuidelines we only have that advice for *.sh, but we\nfollow it for C too).\n\n> +\t\t\treturn \"0\";\n> +\t\tcase protocol_v1:\n> +\t\t\treturn \"1\";\n> +\t\tcase protocol_v2:\n> +\t\t\treturn \"2\";\n> +\t\tdefault:\n> +\t\t\treturn \"UNKNOWN_VERSION\";\n\nUsing the \"default\" case like that is an anti-pattern, i.e. you\nenumerted all arms except protocol_unknown_version, which is implicitly\ncovered by your \"default\" case.\n\nJust list it, and don't have a \"default\" case, then the compiler will\ncomplain if we ever add a new case that's not covered.\n\nAs an aside, and not strictly needed here: More generally between this\nand parse_protocol_version() it seems like this would benefit from just\ndeclaring the bidirectional mapping beween the enum fields and string\nvalues, and then have this and that function use that. See\ne.g. object_type_strings and associated functions in object.c for\nanother enum that has such a bidirectional lookup.\n"},{"id":"432014","messageId":"87a6lwn52u.fsf@evledraar.gmail.com","threadId":"56209","inReplyTo":"d138b2615c1af288627b9a2f8f7dd3d2fed184d7.1628115065.git.steadmon@google.com","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-08-04T23:40:51Z","receivedAt":"2021-08-04T23:49:35Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Wed, Aug 04 2021, Josh Steadmon wrote:\n\n> It is useful for performance monitoring and debugging purposes to know\n> the wire protocol used for remote operations. This may differ from the\n> version set in local configuration due to differences in version and/or\n> configuration between the server and the client. Therefore, log the\n> negotiated wire protocol version via trace2, for both clients and\n> servers.\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n\nI know Taylor asked you to change it to a string from in int upthread in\n<YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am\nwilling to be convinced otherwise.\n\nIt seems to me that both of these codepaths will never usefully use this\nnew \"UNKNOWN_VERSION\" string you added, i.e.:\n\n>  connect.c                             |  3 +++\n>  protocol.c                            |  3 +++\n>  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++\n>  3 files changed, 18 insertions(+)\n>\n> diff --git a/connect.c b/connect.c\n> index 70b13389ba..5f0e113625 100644\n> --- a/connect.c\n> +++ b/connect.c\n> @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)\n>  \t\tbreak;\n>  \t}\n>  \n> +\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n> +\t\t\t   format_protocol_version(version));\n\nRight after this.\n\n>  \tswitch (version) {\n>  \tcase protocol_v2:\n>  \t\tprocess_capabilities_v2(reader);\n\nWe'll die here with BUG(\"unknown protocol version\") if it's unknown..\n\n> diff --git a/protocol.c b/protocol.c\n> index 7ec7ce896e..f52dc2d7a2 100644\n> --- a/protocol.c\n> +++ b/protocol.c\n> @@ -87,6 +87,9 @@ enum protocol_version determine_protocol_version_server(void)\n>  \t\tstring_list_clear(&list, 0);\n>  \t}\n>  \n> +\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n> +\t\t\t   format_protocol_version(version));\n> +\n\nAnd this code is simply unreachable as far as logging this\n\"UNKNOWN_VERSION\" string goes. If we did have an unknown version we'd\ndie right above this with:\n\n    die(\"server is speaking an unknown protocol\")\n\nAnd if we did not have a \"version \" at all we'd default to protocol_v0\nhere, i.e. we either die already on an unknown version, or we don't log\n\"UNKNOWN_VERSION\" at all.\n\n>  \treturn version;\n>  }\n>  \n> diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh\n> index f1d189d5bc..88871c59b5 100755\n> --- a/t/t5705-session-id-in-capabilities.sh\n> +++ b/t/t5705-session-id-in-capabilities.sh\n> @@ -40,6 +40,7 @@ do\n>  \t\ttest -z \"$(grep \\\"key\\\":\\\"server-sid\\\" tr2-client-events)\" &&\n>  \t\ttest -z \"$(grep \\\"key\\\":\\\"client-sid\\\" tr2-server-events)\"\n>  \t'\n> +\n>  done\n>  \n>  test_expect_success 'enable SID advertisement' '\n> @@ -73,6 +74,17 @@ do\n>  \t\tgrep \\\"key\\\":\\\"server-sid\\\" tr2-client-events &&\n>  \t\tgrep \\\"key\\\":\\\"client-sid\\\" tr2-server-events\n>  \t'\n> +\n> +\ttest_expect_success \"client & server log negotiated version (v${PROTO})\" '\n> +\t\ttest_when_finished \"rm -rf local tr2-client-events tr2-server-events\" &&\n> +\t\tcp -r \"$LOCAL_PRISTINE\" local &&\n> +\t\tGIT_TRACE2_EVENT=\"$(pwd)/tr2-client-events\" \\\n> +\t\tgit -c protocol.version=$PROTO -C local fetch \\\n> +\t\t\t--upload-pack \"GIT_TRACE2_EVENT=\\\"$(pwd)/tr2-server-events\\\" git-upload-pack\" \\\n> +\t\t\torigin &&\n> +\t\ttest \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-client-events)\" &&\n> +\t\ttest \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-server-events)\"\n> +\t'\n>  done\n>  \n>  test_done\n\nSo given the above I think you can come up with trace2 output where we\nlog \"UNKNOWN_VERSION\", it just seems rather useless. We'll hit a BUG()\nanyway, which we also trace2 log. In terms of anyone who collect logs\nsurely they'll first care about logged BUG(), and second about any\nversion aggregation involved in such a BUG(), and it's not a big deal if\nthe report of versions doesn't include the \"UNKNOWN VERSION\" to go with\nsuch a one-off bug.\n\nBut perhaps you and Taylor really do have a use-case for this, hence the\n\"willing to be convinced otherwise\". I suspect the desire to log\n\"<unknown>\" came from an assumption that we did so in any recoverable\nnon-BUG() case, which we won't do.\n"},{"id":"432039","messageId":"YQs+VQIYDO3pkCNS@nand.local","threadId":"56209","inReplyTo":"87a6lwn52u.fsf@evledraar.gmail.com","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2021-08-05T01:26:45Z","receivedAt":"2021-08-05T01:26:50Z","isPatch":true,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:\n>\n> On Wed, Aug 04 2021, Josh Steadmon wrote:\n>\n> > It is useful for performance monitoring and debugging purposes to know\n> > the wire protocol used for remote operations. This may differ from the\n> > version set in local configuration due to differences in version and/or\n> > configuration between the server and the client. Therefore, log the\n> > negotiated wire protocol version via trace2, for both clients and\n> > servers.\n> >\n> > Signed-off-by: Josh Steadmon <steadmon@google.com>\n> > ---\n>\n> I know Taylor asked you to change it to a string from in int upthread in\n> <YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am\n> willing to be convinced otherwise.\n\nThe conversion to log a string instead of an integer is necessary if\nJosh wants to write \"<unknown>\" instead of -1. To me, that seemed\nclearer, and I like that it makes the trace2 representation for a\nprotocol version separate from the protocol_version enum.\n\n> It seems to me that both of these codepaths will never usefully use this\n> new \"UNKNOWN_VERSION\" string you added, i.e.:\n>\n> >  connect.c                             |  3 +++\n> >  protocol.c                            |  3 +++\n> >  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++\n> >  3 files changed, 18 insertions(+)\n> >\n> > diff --git a/connect.c b/connect.c\n> > index 70b13389ba..5f0e113625 100644\n> > --- a/connect.c\n> > +++ b/connect.c\n> > @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)\n> >  \t\tbreak;\n> >  \t}\n> >\n> > +\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n> > +\t\t\t   format_protocol_version(version));\n>\n> Right after this.\n>\n> >  \tswitch (version) {\n> >  \tcase protocol_v2:\n> >  \t\tprocess_capabilities_v2(reader);\n>\n> We'll die here with BUG(\"unknown protocol version\") if it's unknown..\n\nGood eyes. In fact, the second switch statement shouldn't even need a\ncase-arm for protocol_unknown_version (but has it to cover all\nenumerated values).\n\nI didn't realize before that the unknown case really is dead code, so\nwe'll never log \"<unknown>\". And since the mapping from protocol_version\nto string is identical for known values, we could probably do without\nit.\n\nAnd I don't much care either way. I think the benefit is really pretty\nslim, and arguably my code is just adding unnecessary overhead. So I'm\nhappy to go with or without it, but I'd be rather sad to spend much more\nof our collective time discussing it.\n\nThanks,\nTaylor\n"},{"id":"432046","messageId":"874kc4mwqc.fsf@evledraar.gmail.com","threadId":"56209","inReplyTo":"YQs+VQIYDO3pkCNS@nand.local","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-08-05T02:47:16Z","receivedAt":"2021-08-05T02:49:51Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Wed, Aug 04 2021, Taylor Blau wrote:\n\n> On Thu, Aug 05, 2021 at 01:40:51AM +0200, Ævar Arnfjörð Bjarmason wrote:\n>>\n>> On Wed, Aug 04 2021, Josh Steadmon wrote:\n>>\n>> > It is useful for performance monitoring and debugging purposes to know\n>> > the wire protocol used for remote operations. This may differ from the\n>> > version set in local configuration due to differences in version and/or\n>> > configuration between the server and the client. Therefore, log the\n>> > negotiated wire protocol version via trace2, for both clients and\n>> > servers.\n>> >\n>> > Signed-off-by: Josh Steadmon <steadmon@google.com>\n>> > ---\n>>\n>> I know Taylor asked you to change it to a string from in int upthread in\n>> <YQmxSxTswHE/gTet@nand.local>, but I really don't see the point. But am\n>> willing to be convinced otherwise.\n>\n> The conversion to log a string instead of an integer is necessary if\n> Josh wants to write \"<unknown>\" instead of -1. To me, that seemed\n> clearer, and I like that it makes the trace2 representation for a\n> protocol version separate from the protocol_version enum.\n\nYes, having a magic -1 value would be bad, but since it seems we'll\nnever get it in practice...\n\n>> It seems to me that both of these codepaths will never usefully use this\n>> new \"UNKNOWN_VERSION\" string you added, i.e.:\n>>\n>> >  connect.c                             |  3 +++\n>> >  protocol.c                            |  3 +++\n>> >  t/t5705-session-id-in-capabilities.sh | 12 ++++++++++++\n>> >  3 files changed, 18 insertions(+)\n>> >\n>> > diff --git a/connect.c b/connect.c\n>> > index 70b13389ba..5f0e113625 100644\n>> > --- a/connect.c\n>> > +++ b/connect.c\n>> > @@ -150,6 +150,9 @@ enum protocol_version discover_version(struct packet_reader *reader)\n>> >  \t\tbreak;\n>> >  \t}\n>> >\n>> > +\ttrace2_data_string(\"transfer\", NULL, \"negotiated-version\",\n>> > +\t\t\t   format_protocol_version(version));\n>>\n>> Right after this.\n>>\n>> >  \tswitch (version) {\n>> >  \tcase protocol_v2:\n>> >  \t\tprocess_capabilities_v2(reader);\n>>\n>> We'll die here with BUG(\"unknown protocol version\") if it's unknown..\n>\n> Good eyes. In fact, the second switch statement shouldn't even need a\n> case-arm for protocol_unknown_version (but has it to cover all\n> enumerated values).\n\nI didn't check if crafting an unknown version will be found earlier, or\nif we'll actually reach that \"unknown\" case.\n\n> I didn't realize before that the unknown case really is dead code, so\n> we'll never log \"<unknown>\". And since the mapping from protocol_version\n> to string is identical for known values, we could probably do without\n> it.\n>\n> And I don't much care either way. I think the benefit is really pretty\n> slim, and arguably my code is just adding unnecessary overhead. So I'm\n> happy to go with or without it, but I'd be rather sad to spend much more\n> of our collective time discussing it.\n\nYeah, I just think if we can be sure it's an integer *and* a valid\nversion when we log it, people writing future log summarizing code will\nthank us, i.e. just 0, 1, 2, and in the future maybe 3, ..., but not -1\nor \"<unknown>\" or other values we'll trust die() etc. to handle.\n"},{"id":"432211","messageId":"YQ2mjmwoRYO4jqaH@google.com","threadId":"56209","inReplyTo":"CAPig+cSqm5cUmAVG6f73oZ+mi9pBJrOg2va2a_Op4=wNFyHfZQ@mail.gmail.com","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-06T21:15:58Z","receivedAt":"2021-08-06T21:16:09Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2021.08.04 18:28, Eric Sunshine wrote:\n> On Wed, Aug 4, 2021 at 6:17 PM Josh Steadmon <steadmon@google.com> wrote:\n> > It is useful for performance monitoring and debugging purposes to know\n> > the wire protocol used for remote operations. This may differ from the\n> > version set in local configuration due to differences in version and/or\n> > configuration between the server and the client. Therefore, log the\n> > negotiated wire protocol version via trace2, for both clients and\n> > servers.\n> >\n> > Signed-off-by: Josh Steadmon <steadmon@google.com>\n> > ---\n> > diff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh\n> > @@ -73,6 +74,17 @@ do\n> > +       test_expect_success \"client & server log negotiated version (v${PROTO})\" '\n> > +               test_when_finished \"rm -rf local tr2-client-events tr2-server-events\" &&\n> > +               cp -r \"$LOCAL_PRISTINE\" local &&\n> > +               GIT_TRACE2_EVENT=\"$(pwd)/tr2-client-events\" \\\n> > +               git -c protocol.version=$PROTO -C local fetch \\\n> > +                       --upload-pack \"GIT_TRACE2_EVENT=\\\"$(pwd)/tr2-server-events\\\" git-upload-pack\" \\\n> > +                       origin &&\n> > +               test \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-client-events)\" &&\n> > +               test \"$(grep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-server-events)\"\n> > +       '\n> >  done\n> \n> What are these `test` commands actually testing? Did you mean `test\n> -n`? Or, even better, just plain `grep` (not within a\n> command-substitution)?\n\nYes, sorry about that, just plain grep is best here. This was due to a\nquick copy & paste modification, I should have spent a bit more time\nthinking about the test case.\n\nWill be fixed in V3.\n"},{"id":"432212","messageId":"YQ2oFttZBFVZtEHm@google.com","threadId":"56209","inReplyTo":"874kc4mwqc.fsf@evledraar.gmail.com","subject":"Re: [PATCH v2 2/2] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-06T21:22:30Z","receivedAt":"2021-08-06T21:22:40Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2021.08.05 04:47, Ævar Arnfjörð Bjarmason wrote:\n> \n> On Wed, Aug 04 2021, Taylor Blau wrote:\n> \n> > I didn't realize before that the unknown case really is dead code, so\n> > we'll never log \"<unknown>\". And since the mapping from protocol_version\n> > to string is identical for known values, we could probably do without\n> > it.\n> >\n> > And I don't much care either way. I think the benefit is really pretty\n> > slim, and arguably my code is just adding unnecessary overhead. So I'm\n> > happy to go with or without it, but I'd be rather sad to spend much more\n> > of our collective time discussing it.\n> \n> Yeah, I just think if we can be sure it's an integer *and* a valid\n> version when we log it, people writing future log summarizing code will\n> thank us, i.e. just 0, 1, 2, and in the future maybe 3, ..., but not -1\n> or \"<unknown>\" or other values we'll trust die() etc. to handle.\n\nSounds good, in V3 I will switch back to logging the enum value\ndirectly, and will make sure we don't log anything if the version is\nunknown. Thanks both for the discussion!\n"},{"id":"432387","messageId":"48180cecc7a8013ec19ed8fc19842d81b356ebd7.1628615309.git.steadmon@google.com","threadId":"56209","inReplyTo":"f79ab95af6da3da710da2112cfcae4a042b7f7fb.1628020616.git.steadmon@google.com","subject":"[PATCH v3] connect, protocol: log negotiated protocol version","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2021-08-10T17:20:39Z","receivedAt":"2021-08-10T17:20:44Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"It is useful for performance monitoring and debugging purposes to know\nthe wire protocol used for remote operations. This may differ from the\nversion set in local configuration due to differences in version and/or\nconfiguration between the server and the client. Therefore, log the\nnegotiated wire protocol version via trace2, for both clients and\nservers.\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n\nChanges in V3:\n* remove unnecessary `test` calls in the new t5705 test cases\n* remove the wire protocol version formatting function\n* log the wire protocol version enum value directly, as in V0 of this\n  series\n* avoid logging the protocol version if negotiation fails (i.e., if we\n  end up with \"protocol_unknown_version\")\n\nChanges in V2:\n* adds a format_protocol_version() helper function\n* adds tests\n* bug fix: actually log on the server side, rather than twice on the\n  client\n* moves the trace statement closer to the actual version negotiation\n  code\n\n connect.c                             |  2 ++\n protocol.c                            |  2 ++\n t/t5705-session-id-in-capabilities.sh | 11 +++++++++++\n 3 files changed, 15 insertions(+)\n\ndiff --git a/connect.c b/connect.c\nindex 70b13389ba..aff13a270e 100644\n--- a/connect.c\n+++ b/connect.c\n@@ -164,6 +164,8 @@ enum protocol_version discover_version(struct packet_reader *reader)\n \t\tBUG(\"unknown protocol version\");\n \t}\n \n+\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n+\n \treturn version;\n }\n \ndiff --git a/protocol.c b/protocol.c\nindex 052d7edbb9..c53f7df5be 100644\n--- a/protocol.c\n+++ b/protocol.c\n@@ -73,6 +73,8 @@ enum protocol_version determine_protocol_version_server(void)\n \t\tstring_list_clear(&list, 0);\n \t}\n \n+\ttrace2_data_intmax(\"transfer\", NULL, \"negotiated-version\", version);\n+\n \treturn version;\n }\n \ndiff --git a/t/t5705-session-id-in-capabilities.sh b/t/t5705-session-id-in-capabilities.sh\nindex f1d189d5bc..eb8c79aafd 100755\n--- a/t/t5705-session-id-in-capabilities.sh\n+++ b/t/t5705-session-id-in-capabilities.sh\n@@ -73,6 +73,17 @@ do\n \t\tgrep \\\"key\\\":\\\"server-sid\\\" tr2-client-events &&\n \t\tgrep \\\"key\\\":\\\"client-sid\\\" tr2-server-events\n \t'\n+\n+\ttest_expect_success \"client & server log negotiated version (v${PROTO})\" '\n+\t\ttest_when_finished \"rm -rf local tr2-client-events tr2-server-events\" &&\n+\t\tcp -r \"$LOCAL_PRISTINE\" local &&\n+\t\tGIT_TRACE2_EVENT=\"$(pwd)/tr2-client-events\" \\\n+\t\tgit -c protocol.version=$PROTO -C local fetch \\\n+\t\t\t--upload-pack \"GIT_TRACE2_EVENT=\\\"$(pwd)/tr2-server-events\\\" git-upload-pack\" \\\n+\t\t\torigin &&\n+\t\tgrep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-client-events &&\n+\t\tgrep \\\"key\\\":\\\"negotiated-version\\\",\\\"value\\\":\\\"$PROTO\\\" tr2-server-events\n+\t'\n done\n \n test_done\n-- \n2.32.0.605.g8dce9f2422-goog\n\n"},{"id":"432821","messageId":"YRqocoVEi1knSQa+@nand.local","threadId":"56209","inReplyTo":"48180cecc7a8013ec19ed8fc19842d81b356ebd7.1628615309.git.steadmon@google.com","subject":"Re: [PATCH v3] connect, protocol: log negotiated protocol version","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2021-08-16T18:03:30Z","receivedAt":"2021-08-16T18:03:34Z","isPatch":true,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Tue, Aug 10, 2021 at 10:20:39AM -0700, Josh Steadmon wrote:\n> It is useful for performance monitoring and debugging purposes to know\n> the wire protocol used for remote operations. This may differ from the\n> version set in local configuration due to differences in version and/or\n> configuration between the server and the client. Therefore, log the\n> negotiated wire protocol version via trace2, for both clients and\n> servers.\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n>\n> Changes in V3:\n> * remove unnecessary `test` calls in the new t5705 test cases\n> * remove the wire protocol version formatting function\n> * log the wire protocol version enum value directly, as in V0 of this\n>   series\n> * avoid logging the protocol version if negotiation fails (i.e., if we\n>   end up with \"protocol_unknown_version\")\n\nNicely done. This version looks ready to be picked up by my eyes.\n\n    Reviewed-by: Taylor Blau <me@ttaylorr.comg>\n\nThanks,\nTaylor\n"}]}