{"thread":{"id":"54694","subject":"[RFC PATCH] usage: add trace2 entry upon warning()","startedAt":"2020-11-23T19:04:23Z","lastAt":"2020-11-30T16:17:47Z","messageCount":6,"participants":["Jonathan Tan","Junio C Hamano","Jeff Hostetler"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"410549","messageId":"20201123190412.101265-1-jonathantanmy@google.com","threadId":"54694","inReplyTo":null,"subject":"[RFC PATCH] usage: add trace2 entry upon warning()","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2020-11-23T19:04:12Z","receivedAt":"2020-11-23T19:04:23Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"Emit a trace2 error event whenever warning() is called, just like when\ndie(), error(), or usage() is called.\n\nThis helps debugging issues that would trigger warnings but not errors.\nIn particular, this might have helped debugging an issue I encountered\nwith commit graphs at $DAYJOB [1].\n\nThere is a tradeoff between including potentially relevant messages and\ncluttering up the trace output produced. I think that warning() messages\nshould be included in traces, because by its nature, Git is used over\nmultiple invocations of the Git tool, and a failure (currently traced)\nin a Git invocation might be caused by an unexpected interaction in a\nprevious Git invocation that only has a warning (currently untraced) as\na symptom - as is the case in [1].\n\n[1] https://lore.kernel.org/git/20200629220744.1054093-1-jonathantanmy@google.com/\n\nSigned-off-by: Jonathan Tan <jonathantanmy@google.com>\n---\nThe documentation (see the patch below) says that it is emitted when\nusage() is called, but I don't see it in the code (nor in practice). If\nnot emitting traces upon usage() is intended (which is reasonable to\nme), I'll edit the documentation (and the commit message above).\n\nI marked this as RFC mostly because this is a perhaps subjective\ntradeoff that needs to be made. I think the tradeoff should be in favor\nof tracing warning() messages, and I have explained that in the commit\nmessage.\n---\n Documentation/technical/api-trace2.txt | 2 +-\n usage.c                                | 6 ++++++\n 2 files changed, 7 insertions(+), 1 deletion(-)\n\ndiff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt\nindex 6b6085585d..c65ffafc48 100644\n--- a/Documentation/technical/api-trace2.txt\n+++ b/Documentation/technical/api-trace2.txt\n@@ -466,7 +466,7 @@ completed.)\n \n `\"error\"`::\n \tThis event is emitted when one of the `error()`, `die()`,\n-\tor `usage()` functions are called.\n+\t`warning()`, or `usage()` functions are called.\n +\n ------------\n {\ndiff --git a/usage.c b/usage.c\nindex 06665823a2..673edf5afd 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -81,6 +81,12 @@ static void error_builtin(const char *err, va_list params)\n \n static void warn_builtin(const char *warn, va_list params)\n {\n+\t/*\n+\t * We call this trace2 function first and expect it to va_copy 'params'\n+\t * before using it (because an 'ap' can only be walked once).\n+\t */\n+\ttrace2_cmd_error_va(err, params);\n+\n \tvreportf(\"warning: \", warn, params);\n }\n \n-- \n2.29.2.454.gaff20da3a2-goog\n\n"},{"id":"410566","messageId":"20201123204522.675836-1-jonathantanmy@google.com","threadId":"54694","inReplyTo":"20201123190412.101265-1-jonathantanmy@google.com","subject":"[RFC PATCH v2] usage: add trace2 entry upon warning()","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2020-11-23T20:45:22Z","receivedAt":"2020-11-23T20:45:27Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"Emit a trace2 error event whenever warning() is called, just like when\ndie(), error(), or usage() is called.\n\nThis helps debugging issues that would trigger warnings but not errors.\nIn particular, this might have helped debugging an issue I encountered\nwith commit graphs at $DAYJOB [1].\n\nThere is a tradeoff between including potentially relevant messages and\ncluttering up the trace output produced. I think that warning() messages\nshould be included in traces, because by its nature, Git is used over\nmultiple invocations of the Git tool, and a failure (currently traced)\nin a Git invocation might be caused by an unexpected interaction in a\nprevious Git invocation that only has a warning (currently untraced) as\na symptom - as is the case in [1].\n\n[1] https://lore.kernel.org/git/20200629220744.1054093-1-jonathantanmy@google.com/\n\nSigned-off-by: Jonathan Tan <jonathantanmy@google.com>\n---\nWhoops...I ran a compile for the first version but I sent the email out\nbefore looking at the results. The first version had a compile error,\nbut this one should be fine.\n---\n Documentation/technical/api-trace2.txt | 2 +-\n usage.c                                | 6 ++++++\n 2 files changed, 7 insertions(+), 1 deletion(-)\n\ndiff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt\nindex 6b6085585d..c65ffafc48 100644\n--- a/Documentation/technical/api-trace2.txt\n+++ b/Documentation/technical/api-trace2.txt\n@@ -466,7 +466,7 @@ completed.)\n \n `\"error\"`::\n \tThis event is emitted when one of the `error()`, `die()`,\n-\tor `usage()` functions are called.\n+\t`warning()`, or `usage()` functions are called.\n +\n ------------\n {\ndiff --git a/usage.c b/usage.c\nindex 06665823a2..1868a24f7a 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -81,6 +81,12 @@ static void error_builtin(const char *err, va_list params)\n \n static void warn_builtin(const char *warn, va_list params)\n {\n+\t/*\n+\t * We call this trace2 function first and expect it to va_copy 'params'\n+\t * before using it (because an 'ap' can only be walked once).\n+\t */\n+\ttrace2_cmd_error_va(warn, params);\n+\n \tvreportf(\"warning: \", warn, params);\n }\n \n-- \n2.29.2.454.gaff20da3a2-goog\n\n"},{"id":"410581","messageId":"xmqqblfnn1u3.fsf@gitster.c.googlers.com","threadId":"54694","inReplyTo":"20201123204522.675836-1-jonathantanmy@google.com","subject":"Re: [RFC PATCH v2] usage: add trace2 entry upon warning()","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-11-23T22:30:12Z","receivedAt":"2020-11-23T22:30:39Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Tan <jonathantanmy@google.com> writes:\n\n> diff --git a/usage.c b/usage.c\n> index 06665823a2..1868a24f7a 100644\n> --- a/usage.c\n> +++ b/usage.c\n> @@ -81,6 +81,12 @@ static void error_builtin(const char *err, va_list params)\n>  \n>  static void warn_builtin(const char *warn, va_list params)\n>  {\n> +\t/*\n> +\t * We call this trace2 function first and expect it to va_copy 'params'\n> +\t * before using it (because an 'ap' can only be walked once).\n> +\t */\n> +\ttrace2_cmd_error_va(warn, params);\n> +\n>  \tvreportf(\"warning: \", warn, params);\n\nWithout the comment, this would have been a huge red sign.  Given\nwhat the trace2 function does, I think cmd_error_va() has to do the\nva_copy()/va_end() dance somewhere in it, so from the caller's point\nof view, not having to va_copy()/va_end() is convenient and nice,\nbut perhaps we can eventually (not today---we have the same issue\nwith die_builtin() and error_builtin()) move the comment to the\ncallee so that other people who are writing more callers do not have\nto rediscover what to do with \"can va_lsit be used more than once?\"\nissue.  Perhaps like (I am not demonstrating the removal of dups):\n\n trace2.h | 5 +++++\n 1 file changed, 5 insertions(+)\n\ndiff --git c/trace2.h w/trace2.h\nindex b18bc5529c..10ba231122 100644\n--- c/trace2.h\n+++ w/trace2.h\n@@ -116,6 +116,11 @@ int trace2_cmd_exit_fl(const char *file, int line, int code);\n  * Emit an 'error' event.\n  *\n  * Write an error message to the TRACE2 targets.\n+ *\n+ * Note that the \"va_list ap\" the caller has is not touched, because\n+ * it is fed to each of the TRACE2 targets, which must use va_copy()\n+ * and use va_end() on the copy.  The caller can still use ap it uses\n+ * to call this funciton and and call va_end() on it when it is done.\n  */\n void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,\n \t\t\t    va_list ap);\n"},{"id":"410699","messageId":"20201124200527.890563-1-jonathantanmy@google.com","threadId":"54694","inReplyTo":"20201123190412.101265-1-jonathantanmy@google.com","subject":"[PATCH v3] usage: add trace2 entry upon warning()","fromName":"Jonathan Tan","fromEmail":"jonathantanmy@google.com","sentAt":"2020-11-24T20:05:27Z","receivedAt":"2020-11-24T20:05:32Z","isPatch":true,"sender":{"key":"jonathantanmy@fastmail.com","avatar":null},"body":"Emit a trace2 error event whenever warning() is called, just like when\ndie(), error(), or usage() is called.\n\nThis helps debugging issues that would trigger warnings but not errors.\nIn particular, this might have helped debugging an issue I encountered\nwith commit graphs at $DAYJOB [1].\n\nThere is a tradeoff between including potentially relevant messages and\ncluttering up the trace output produced. I think that warning() messages\nshould be included in traces, because by its nature, Git is used over\nmultiple invocations of the Git tool, and a failure (currently traced)\nin a Git invocation might be caused by an unexpected interaction in a\nprevious Git invocation that only has a warning (currently untraced) as\na symptom - as is the case in [1].\n\n[1] https://lore.kernel.org/git/20200629220744.1054093-1-jonathantanmy@google.com/\n\nSigned-off-by: Jonathan Tan <jonathantanmy@google.com>\n---\nThanks, Junio. That comment looks good. Here is the version with Junio's\nsuggested comment included, for everyone's reference.\n---\n Documentation/technical/api-trace2.txt | 2 +-\n trace2.h                               | 5 +++++\n usage.c                                | 6 ++++++\n 3 files changed, 12 insertions(+), 1 deletion(-)\n\ndiff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt\nindex 6b6085585d..c65ffafc48 100644\n--- a/Documentation/technical/api-trace2.txt\n+++ b/Documentation/technical/api-trace2.txt\n@@ -466,7 +466,7 @@ completed.)\n \n `\"error\"`::\n \tThis event is emitted when one of the `error()`, `die()`,\n-\tor `usage()` functions are called.\n+\t`warning()`, or `usage()` functions are called.\n +\n ------------\n {\ndiff --git a/trace2.h b/trace2.h\nindex b18bc5529c..2b5c5c4ba0 100644\n--- a/trace2.h\n+++ b/trace2.h\n@@ -116,6 +116,11 @@ int trace2_cmd_exit_fl(const char *file, int line, int code);\n  * Emit an 'error' event.\n  *\n  * Write an error message to the TRACE2 targets.\n+ * \n+ * Note that the \"va_list ap\" the caller has is not touched, because\n+ * it is fed to each of the TRACE2 targets, which must use va_copy()\n+ * and use va_end() on the copy.  The caller can still use ap it uses\n+ * to call this function and and call va_end() on it when it is done.\n  */\n void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,\n \t\t\t    va_list ap);\ndiff --git a/usage.c b/usage.c\nindex 06665823a2..1868a24f7a 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -81,6 +81,12 @@ static void error_builtin(const char *err, va_list params)\n \n static void warn_builtin(const char *warn, va_list params)\n {\n+\t/*\n+\t * We call this trace2 function first and expect it to va_copy 'params'\n+\t * before using it (because an 'ap' can only be walked once).\n+\t */\n+\ttrace2_cmd_error_va(warn, params);\n+\n \tvreportf(\"warning: \", warn, params);\n }\n \n-- \n2.29.2.454.gaff20da3a2-goog\n\n"},{"id":"410725","messageId":"xmqqzh36h04o.fsf@gitster.c.googlers.com","threadId":"54694","inReplyTo":"20201124200527.890563-1-jonathantanmy@google.com","subject":"Re: [PATCH v3] usage: add trace2 entry upon warning()","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-11-24T22:15:51Z","receivedAt":"2020-11-24T22:15:56Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jonathan Tan <jonathantanmy@google.com> writes:\n\n> Emit a trace2 error event whenever warning() is called, just like when\n> die(), error(), or usage() is called.\n>\n> This helps debugging issues that would trigger warnings but not errors.\n> In particular, this might have helped debugging an issue I encountered\n> with commit graphs at $DAYJOB [1].\n>\n> There is a tradeoff between including potentially relevant messages and\n> cluttering up the trace output produced. I think that warning() messages\n> should be included in traces, because by its nature, Git is used over\n> multiple invocations of the Git tool, and a failure (currently traced)\n> in a Git invocation might be caused by an unexpected interaction in a\n> previous Git invocation that only has a warning (currently untraced) as\n> a symptom - as is the case in [1].\n>\n> [1] https://lore.kernel.org/git/20200629220744.1054093-1-jonathantanmy@google.com/\n>\n> Signed-off-by: Jonathan Tan <jonathantanmy@google.com>\n> ---\n> Thanks, Junio. That comment looks good. Here is the version with Junio's\n> suggested comment included, for everyone's reference.\n\nHeh, I meant it as more of a #leftoverbit, not directly applicable to\nthis particular patch, but would be a good follow-up topic, as I would\nhave expected that die/warn/error should lose their own comments where\nthey call trace2_cmd_error_va() in the same patch that adds the comment\nfor callers near the function.\n\nLet's use v2 if the difference between v2 and v3 is only the\naddition of the comment before trace2_cmd_error_va() function decl\nto help the callers.\n\n"},{"id":"411001","messageId":"8b4d2300-5c55-fab5-af39-4c5921a6ea9a@jeffhostetler.com","threadId":"54694","inReplyTo":"20201123190412.101265-1-jonathantanmy@google.com","subject":"Re: [RFC PATCH] usage: add trace2 entry upon warning()","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2020-11-30T16:16:53Z","receivedAt":"2020-11-30T16:17:47Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 11/23/20 2:04 PM, Jonathan Tan wrote:\n> Emit a trace2 error event whenever warning() is called, just like when\n> die(), error(), or usage() is called.\n> \n> This helps debugging issues that would trigger warnings but not errors.\n> In particular, this might have helped debugging an issue I encountered\n> with commit graphs at $DAYJOB [1].\n> \n> There is a tradeoff between including potentially relevant messages and\n> cluttering up the trace output produced. I think that warning() messages\n> should be included in traces, because by its nature, Git is used over\n> multiple invocations of the Git tool, and a failure (currently traced)\n> in a Git invocation might be caused by an unexpected interaction in a\n> previous Git invocation that only has a warning (currently untraced) as\n> a symptom - as is the case in [1].\n> \n> [1] https://lore.kernel.org/git/20200629220744.1054093-1-jonathantanmy@google.com/\n> \n> Signed-off-by: Jonathan Tan <jonathantanmy@google.com>\n\nLGTM\n\nThanks,\nJeff\n\n"}]}