{"thread":{"id":"57813","subject":"[PATCH] run-command: don't spam trace2_child_exit()","startedAt":"2022-04-28T20:58:14Z","lastAt":"2022-06-10T15:31:41Z","messageCount":10,"participants":["Josh Steadmon","Junio C Hamano","Jeff Hostetler","Ævar Arnfjörð Bjarmason"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"454598","messageId":"4616d09ffa632bd2c9e308a713c4bdf2a1328c3c.1651179450.git.steadmon@google.com","threadId":"57813","inReplyTo":null,"subject":"[PATCH] run-command: don't spam trace2_child_exit()","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-04-28T20:58:10Z","receivedAt":"2022-04-28T20:58:14Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"In rare cases, wait_or_whine() cannot determine a child process's exit\nstatus (and will return -1 in this case). This can cause Git to issue\ntrace2 child_exit events despite the fact that the child is still\nrunning. In pathological cases, we've seen > 80 million exit events in\nour trace logs for a single child process.\n\nFix this by only issuing trace2 events in finish_command_in_signal() if\nwe get a value other than -1 from wait_or_whine().\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\n run-command.c | 3 ++-\n 1 file changed, 2 insertions(+), 1 deletion(-)\n\ndiff --git a/run-command.c b/run-command.c\nindex a8501e38ce..e0fe2418a2 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -983,7 +983,8 @@ int finish_command(struct child_process *cmd)\n int finish_command_in_signal(struct child_process *cmd)\n {\n \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n-\ttrace2_child_exit(cmd, ret);\n+\tif (ret != -1)\n+\t\ttrace2_child_exit(cmd, ret);\n \treturn ret;\n }\n \n\nbase-commit: faa21c10d44184f616d391c158dcbb13b9c72ef3\n-- \n2.36.0.464.gb9c8b46e94-goog\n\n"},{"id":"454601","messageId":"xmqqr15gev94.fsf@gitster.g","threadId":"57813","inReplyTo":"4616d09ffa632bd2c9e308a713c4bdf2a1328c3c.1651179450.git.steadmon@google.com","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2022-04-28T21:46:47Z","receivedAt":"2022-04-28T21:46:56Z","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> In rare cases, wait_or_whine() cannot determine a child process's exit\n> status (and will return -1 in this case). This can cause Git to issue\n> trace2 child_exit events despite the fact that the child is still\n> running.\n\nRather, we do not even know if the child is still running when it\nhappens, right?  It is curious what \"rare cases\" makes the symptom\nappear.  Do we know?\n\nThe patch looks OK from the \"we do not know the child exited in this\ncase, so we shouldn't be reporting the child exit\" point of view, of\ncourse.  Having one event that started a child in the log and then\nhaving millions of events that reports the exit of the (same) child\nis way too broken.  With this change, we remove these phoney exit\nevents from the log.\n\nDo we know, for such a child process that caused these millions\nphoney exit events, we got a real exit event at the end?  Otherwise,\nwe'd still have a similar problem in the opposite direction, i.e. a\nchild has a start event recorded, many exit event discarded but the\nlog lacks the true exit event for the child, implying that the child\nis still running because we failed to log its exit?\n\n>  int finish_command_in_signal(struct child_process *cmd)\n>  {\n>  \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> -\ttrace2_child_exit(cmd, ret);\n> +\tif (ret != -1)\n> +\t\ttrace2_child_exit(cmd, ret);\n>  \treturn ret;\n>  }\n\nWill queue; thanks.\n"},{"id":"454792","messageId":"75f62c9e-e083-d333-6339-2d12e0788400@jeffhostetler.com","threadId":"57813","inReplyTo":"xmqqr15gev94.fsf@gitster.g","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-05-03T14:59:52Z","receivedAt":"2022-05-03T15:00:05Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 4/28/22 5:46 PM, Junio C Hamano wrote:\n> Josh Steadmon <steadmon@google.com> writes:\n> \n>> In rare cases, wait_or_whine() cannot determine a child process's exit\n>> status (and will return -1 in this case). This can cause Git to issue\n>> trace2 child_exit events despite the fact that the child is still\n>> running.\n\nI'm curious what is causing the spurious return values.\nCould you instrument wait_or_whine() and see which of the\nif/else arms are causing the -1 to be returned?\n\nThat routine is rather complicated and looks like it has 3\ndifferent ways that a -1 could be returned.\n\n\n> \n> Rather, we do not even know if the child is still running when it\n> happens, right?  It is curious what \"rare cases\" makes the symptom\n> appear.  Do we know?\n> \n> The patch looks OK from the \"we do not know the child exited in this\n> case, so we shouldn't be reporting the child exit\" point of view, of\n> course.  Having one event that started a child in the log and then\n> having millions of events that reports the exit of the (same) child\n> is way too broken.  With this change, we remove these phoney exit\n> events from the log.\n> \n> Do we know, for such a child process that caused these millions\n> phoney exit events, we got a real exit event at the end?  Otherwise,\n> we'd still have a similar problem in the opposite direction, i.e. a\n> child has a start event recorded, many exit event discarded but the\n> log lacks the true exit event for the child, implying that the child\n> is still running because we failed to log its exit?\n> \n>>   int finish_command_in_signal(struct child_process *cmd)\n>>   {\n>>   \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n>> -\ttrace2_child_exit(cmd, ret);\n>> +\tif (ret != -1)\n>> +\t\ttrace2_child_exit(cmd, ret);\n>>   \treturn ret;\n>>   }\n\nSince this is only called from pager.c and is used to setup the\npager, I have to wonder if you're only getting these spurious events\nfor the pager process or for any of the other random child processes.\n\nAnd whether they are received while the pager is alive and working\nproperly, or when you're trying to quit the pager or when the pager\nis trying to signal eof.\n\n> \n> Will queue; thanks.\n> \n"},{"id":"454880","messageId":"YnQpFwcB3V07qNi3@google.com","threadId":"57813","inReplyTo":"xmqqr15gev94.fsf@gitster.g","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-05-05T19:44:23Z","receivedAt":"2022-05-05T19:44:35Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2022.04.28 14:46, Junio C Hamano wrote:\n> Josh Steadmon <steadmon@google.com> writes:\n> \n> > In rare cases, wait_or_whine() cannot determine a child process's exit\n> > status (and will return -1 in this case). This can cause Git to issue\n> > trace2 child_exit events despite the fact that the child is still\n> > running.\n> \n> Rather, we do not even know if the child is still running when it\n> happens, right?\n\nCorrect, if you'd like me to clarify the commit message I'll send a V2.\n\n\n> It is curious what \"rare cases\" makes the symptom\n> appear.  Do we know?\n\nUnfortunately, no. The quoted 80 million exit event instance was not\nreproducible.\n\n> The patch looks OK from the \"we do not know the child exited in this\n> case, so we shouldn't be reporting the child exit\" point of view, of\n> course.  Having one event that started a child in the log and then\n> having millions of events that reports the exit of the (same) child\n> is way too broken.  With this change, we remove these phoney exit\n> events from the log.\n> \n> Do we know, for such a child process that caused these millions\n> phoney exit events, we got a real exit event at the end?\n\nWe don't know. The trace log filled up the user's disk in this case, so\nthe log was truncated.\n\n\n> Otherwise,\n> we'd still have a similar problem in the opposite direction, i.e. a\n> child has a start event recorded, many exit event discarded but the\n> log lacks the true exit event for the child, implying that the child\n> is still running because we failed to log its exit?\n\nYes, that is a weakness with this approach.\n\n\n> >  int finish_command_in_signal(struct child_process *cmd)\n> >  {\n> >  \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> > -\ttrace2_child_exit(cmd, ret);\n> > +\tif (ret != -1)\n> > +\t\ttrace2_child_exit(cmd, ret);\n> >  \treturn ret;\n> >  }\n> \n> Will queue; thanks.\n\nThanks, and sorry for the delayed reply, I've been out sick for a few\ndays.\n"},{"id":"454881","messageId":"YnQsTckTqRaKLABM@google.com","threadId":"57813","inReplyTo":"75f62c9e-e083-d333-6339-2d12e0788400@jeffhostetler.com","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-05-05T19:58:05Z","receivedAt":"2022-05-05T19:58:16Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2022.05.03 10:59, Jeff Hostetler wrote:\n> \n> \n> On 4/28/22 5:46 PM, Junio C Hamano wrote:\n> > Josh Steadmon <steadmon@google.com> writes:\n> > \n> > > In rare cases, wait_or_whine() cannot determine a child process's exit\n> > > status (and will return -1 in this case). This can cause Git to issue\n> > > trace2 child_exit events despite the fact that the child is still\n> > > running.\n> \n> I'm curious what is causing the spurious return values.\n> Could you instrument wait_or_whine() and see which of the\n> if/else arms are causing the -1 to be returned?\n> \n> That routine is rather complicated and looks like it has 3\n> different ways that a -1 could be returned.\n\nUnfortunately we haven't been able to reproduce the issue, so\ninstrumentation won't clarify the cause unless we randomly hit another\ninstance.\n\n\n> > \n> > Rather, we do not even know if the child is still running when it\n> > happens, right?  It is curious what \"rare cases\" makes the symptom\n> > appear.  Do we know?\n> > \n> > The patch looks OK from the \"we do not know the child exited in this\n> > case, so we shouldn't be reporting the child exit\" point of view, of\n> > course.  Having one event that started a child in the log and then\n> > having millions of events that reports the exit of the (same) child\n> > is way too broken.  With this change, we remove these phoney exit\n> > events from the log.\n> > \n> > Do we know, for such a child process that caused these millions\n> > phoney exit events, we got a real exit event at the end?  Otherwise,\n> > we'd still have a similar problem in the opposite direction, i.e. a\n> > child has a start event recorded, many exit event discarded but the\n> > log lacks the true exit event for the child, implying that the child\n> > is still running because we failed to log its exit?\n> > \n> > >   int finish_command_in_signal(struct child_process *cmd)\n> > >   {\n> > >   \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> > > -\ttrace2_child_exit(cmd, ret);\n> > > +\tif (ret != -1)\n> > > +\t\ttrace2_child_exit(cmd, ret);\n> > >   \treturn ret;\n> > >   }\n> \n> Since this is only called from pager.c and is used to setup the\n> pager, I have to wonder if you're only getting these spurious events\n> for the pager process or for any of the other random child processes.\n> \n> And whether they are received while the pager is alive and working\n> properly, or when you're trying to quit the pager or when the pager\n> is trying to signal eof.\n\nIt was for a pager run by `git diff`. The only other child process in\nthis instance was `git status`. I believe the events were generated\nwhile the user was not interacting with the process; IIRC the pager was\nleft running in a terminal overnight and they discovered the next\nmorning that their disk was filled up by trace logs.\n"},{"id":"455117","messageId":"ef011c3d-dd4b-f982-aa66-9167bf3e6c91@jeffhostetler.com","threadId":"57813","inReplyTo":"YnQsTckTqRaKLABM@google.com","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-05-10T20:37:33Z","receivedAt":"2022-05-10T20:37:39Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 5/5/22 3:58 PM, Josh Steadmon wrote:\n> On 2022.05.03 10:59, Jeff Hostetler wrote:\n>>\n>>\n>> On 4/28/22 5:46 PM, Junio C Hamano wrote:\n>>> Josh Steadmon <steadmon@google.com> writes:\n>>>\n>>>> In rare cases, wait_or_whine() cannot determine a child process's exit\n>>>> status (and will return -1 in this case). This can cause Git to issue\n>>>> trace2 child_exit events despite the fact that the child is still\n>>>> running.\n>>\n>> I'm curious what is causing the spurious return values.\n>> Could you instrument wait_or_whine() and see which of the\n>> if/else arms are causing the -1 to be returned?\n>>\n>> That routine is rather complicated and looks like it has 3\n>> different ways that a -1 could be returned.\n> \n> Unfortunately we haven't been able to reproduce the issue, so\n> instrumentation won't clarify the cause unless we randomly hit another\n> instance.\n> \n> \n>>>\n>>> Rather, we do not even know if the child is still running when it\n>>> happens, right?  It is curious what \"rare cases\" makes the symptom\n>>> appear.  Do we know?\n>>>\n>>> The patch looks OK from the \"we do not know the child exited in this\n>>> case, so we shouldn't be reporting the child exit\" point of view, of\n>>> course.  Having one event that started a child in the log and then\n>>> having millions of events that reports the exit of the (same) child\n>>> is way too broken.  With this change, we remove these phoney exit\n>>> events from the log.\n>>>\n>>> Do we know, for such a child process that caused these millions\n>>> phoney exit events, we got a real exit event at the end?  Otherwise,\n>>> we'd still have a similar problem in the opposite direction, i.e. a\n>>> child has a start event recorded, many exit event discarded but the\n>>> log lacks the true exit event for the child, implying that the child\n>>> is still running because we failed to log its exit?\n>>>\n>>>>    int finish_command_in_signal(struct child_process *cmd)\n>>>>    {\n>>>>    \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n>>>> -\ttrace2_child_exit(cmd, ret);\n>>>> +\tif (ret != -1)\n>>>> +\t\ttrace2_child_exit(cmd, ret);\n>>>>    \treturn ret;\n>>>>    }\n>>\n>> Since this is only called from pager.c and is used to setup the\n>> pager, I have to wonder if you're only getting these spurious events\n>> for the pager process or for any of the other random child processes.\n>>\n>> And whether they are received while the pager is alive and working\n>> properly, or when you're trying to quit the pager or when the pager\n>> is trying to signal eof.\n> \n> It was for a pager run by `git diff`. The only other child process in\n> this instance was `git status`. I believe the events were generated\n> while the user was not interacting with the process; IIRC the pager was\n> left running in a terminal overnight and they discovered the next\n> morning that their disk was filled up by trace logs.\n> \n\nThis worries me that you've found a race or infinite loop here\nand the only symptom is the child exit messages.  Suppressing\nthem solves the disk-fill problem, but might mean that there's\na lurking infinite loop or something.\n\nCan you (privately) send me the part of the log before the\ninfinite loop?  And maybe the parent and child processes too?\nI'd kinda like to understand what's happening here.\n\nJeff\n\n"},{"id":"456807","messageId":"50d872a057a558fa5519856b95abd048ddb514dc.1654625626.git.steadmon@google.com","threadId":"57813","inReplyTo":"4616d09ffa632bd2c9e308a713c4bdf2a1328c3c.1651179450.git.steadmon@google.com","subject":"[PATCH v2] run-command: don't spam trace2_child_exit()","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-06-07T18:21:57Z","receivedAt":"2022-06-07T19:54:28Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"In rare cases[1], wait_or_whine() cannot determine a child process's\nstatus (and will return -1 in this case). This can cause Git to issue\ntrace2 child_exit events despite the fact that the child may still be\nrunning. In pathological cases, we've seen > 80 million exit events in\nour trace logs for a single child process.\n\nFix this by only issuing trace2 events in finish_command_in_signal() if\nwe get a value other than -1 from wait_or_whine(). This can lead to\nmissing child_exit events in such a case, but that is preferable to\nduplicating events on a scale that threatens to fill the user's\nfilesystem with invalid trace logs.\n\n[1]: This can happen when:\n\n* waitpid() returns -1 and errno != EINTR\n* waitpid() returns an invalid PID\n* the status set by waitpid() has neither the WIFEXITED() nor\n  WIFSIGNALED() flags\n\nSigned-off-by: Josh Steadmon <steadmon@google.com>\n---\nUpdated the commit message with more details about when wait_or_whine()\ncan fail.\n\n run-command.c | 3 ++-\n 1 file changed, 2 insertions(+), 1 deletion(-)\n\ndiff --git a/run-command.c b/run-command.c\nindex a8501e38ce..e0fe2418a2 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -983,7 +983,8 @@ int finish_command(struct child_process *cmd)\n int finish_command_in_signal(struct child_process *cmd)\n {\n \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n-\ttrace2_child_exit(cmd, ret);\n+\tif (ret != -1)\n+\t\ttrace2_child_exit(cmd, ret);\n \treturn ret;\n }\n \n\nbase-commit: faa21c10d44184f616d391c158dcbb13b9c72ef3\n-- \n2.36.1.255.ge46751e96f-goog\n\n"},{"id":"456811","messageId":"Yp+ctyKvKGR2aZ/s@google.com","threadId":"57813","inReplyTo":"ef011c3d-dd4b-f982-aa66-9167bf3e6c91@jeffhostetler.com","subject":"Re: [PATCH] run-command: don't spam trace2_child_exit()","fromName":"Josh Steadmon","fromEmail":"steadmon@google.com","sentAt":"2022-06-07T18:45:11Z","receivedAt":"2022-06-07T21:06:47Z","isPatch":true,"sender":{"key":"steadmon@google.com","avatar":"https://avatars.githubusercontent.com/u/2654920?v=4"},"body":"On 2022.05.10 16:37, Jeff Hostetler wrote:\n> \n> \n> On 5/5/22 3:58 PM, Josh Steadmon wrote:\n> > On 2022.05.03 10:59, Jeff Hostetler wrote:\n> > > \n> > > \n> > > On 4/28/22 5:46 PM, Junio C Hamano wrote:\n> > > > Josh Steadmon <steadmon@google.com> writes:\n> > > > \n> > > > > In rare cases, wait_or_whine() cannot determine a child process's exit\n> > > > > status (and will return -1 in this case). This can cause Git to issue\n> > > > > trace2 child_exit events despite the fact that the child is still\n> > > > > running.\n> > > \n> > > I'm curious what is causing the spurious return values.\n> > > Could you instrument wait_or_whine() and see which of the\n> > > if/else arms are causing the -1 to be returned?\n> > > \n> > > That routine is rather complicated and looks like it has 3\n> > > different ways that a -1 could be returned.\n> > \n> > Unfortunately we haven't been able to reproduce the issue, so\n> > instrumentation won't clarify the cause unless we randomly hit another\n> > instance.\n> > \n> > \n> > > > \n> > > > Rather, we do not even know if the child is still running when it\n> > > > happens, right?  It is curious what \"rare cases\" makes the symptom\n> > > > appear.  Do we know?\n> > > > \n> > > > The patch looks OK from the \"we do not know the child exited in this\n> > > > case, so we shouldn't be reporting the child exit\" point of view, of\n> > > > course.  Having one event that started a child in the log and then\n> > > > having millions of events that reports the exit of the (same) child\n> > > > is way too broken.  With this change, we remove these phoney exit\n> > > > events from the log.\n> > > > \n> > > > Do we know, for such a child process that caused these millions\n> > > > phoney exit events, we got a real exit event at the end?  Otherwise,\n> > > > we'd still have a similar problem in the opposite direction, i.e. a\n> > > > child has a start event recorded, many exit event discarded but the\n> > > > log lacks the true exit event for the child, implying that the child\n> > > > is still running because we failed to log its exit?\n> > > > \n> > > > >    int finish_command_in_signal(struct child_process *cmd)\n> > > > >    {\n> > > > >    \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> > > > > -\ttrace2_child_exit(cmd, ret);\n> > > > > +\tif (ret != -1)\n> > > > > +\t\ttrace2_child_exit(cmd, ret);\n> > > > >    \treturn ret;\n> > > > >    }\n> > > \n> > > Since this is only called from pager.c and is used to setup the\n> > > pager, I have to wonder if you're only getting these spurious events\n> > > for the pager process or for any of the other random child processes.\n> > > \n> > > And whether they are received while the pager is alive and working\n> > > properly, or when you're trying to quit the pager or when the pager\n> > > is trying to signal eof.\n> > \n> > It was for a pager run by `git diff`. The only other child process in\n> > this instance was `git status`. I believe the events were generated\n> > while the user was not interacting with the process; IIRC the pager was\n> > left running in a terminal overnight and they discovered the next\n> > morning that their disk was filled up by trace logs.\n> > \n> \n> This worries me that you've found a race or infinite loop here\n> and the only symptom is the child exit messages.  Suppressing\n> them solves the disk-fill problem, but might mean that there's\n> a lurking infinite loop or something.\n> \n> Can you (privately) send me the part of the log before the\n> infinite loop?  And maybe the parent and child processes too?\n> I'd kinda like to understand what's happening here.\n> \n> Jeff\n\nUnfortunately we no longer have the relevant logs. This incident\nhappened in 2020 and the logs have expired. I can share some general\ndetails though:\n\nThe session started on a Friday when the user ran `git diff`. Presumably\nthe user left the pager open after they left for the weekend. On the\nfollowing Saturday we started getting ~30M child_exit events per day\nuntil their disk filled up early Monday morning.\n\nThe process was running on a VM, and I have reason to believe that the\nuser's SSH connection to the VM was broken at some point on the Saturday\nthat the spammy events started appearing. I don't know whether or not\nthe user was using any sort of session manager / terminal multiplexer\nsuch as screen or tmux. I am curious whether or not the broken SSH\nconnection could have created some kind of signal loop that caused the\npager to continuously trigger our wait_for_pager_signal() handler.\n\nI don't have any useful info beyond that, sorry. Thanks for taking a\nlook though!\n"},{"id":"456834","messageId":"220608.86pmjkt97e.gmgdl@evledraar.gmail.com","threadId":"57813","inReplyTo":"50d872a057a558fa5519856b95abd048ddb514dc.1654625626.git.steadmon@google.com","subject":"Re: [PATCH v2] run-command: don't spam trace2_child_exit()","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2022-06-07T22:09:14Z","receivedAt":"2022-06-08T00:33:50Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Tue, Jun 07 2022, Josh Steadmon wrote:\n\n> In rare cases[1], wait_or_whine() cannot determine a child process's\n> status (and will return -1 in this case). This can cause Git to issue\n> trace2 child_exit events despite the fact that the child may still be\n> running. In pathological cases, we've seen > 80 million exit events in\n> our trace logs for a single child process.\n>\n> Fix this by only issuing trace2 events in finish_command_in_signal() if\n> we get a value other than -1 from wait_or_whine(). This can lead to\n> missing child_exit events in such a case, but that is preferable to\n> duplicating events on a scale that threatens to fill the user's\n> filesystem with invalid trace logs.\n>\n> [1]: This can happen when:\n>\n> * waitpid() returns -1 and errno != EINTR\n> * waitpid() returns an invalid PID\n> * the status set by waitpid() has neither the WIFEXITED() nor\n>   WIFSIGNALED() flags\n>\n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n> Updated the commit message with more details about when wait_or_whine()\n> can fail.\n>\n>  run-command.c | 3 ++-\n>  1 file changed, 2 insertions(+), 1 deletion(-)\n>\n> diff --git a/run-command.c b/run-command.c\n> index a8501e38ce..e0fe2418a2 100644\n> --- a/run-command.c\n> +++ b/run-command.c\n> @@ -983,7 +983,8 @@ int finish_command(struct child_process *cmd)\n>  int finish_command_in_signal(struct child_process *cmd)\n>  {\n>  \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> -\ttrace2_child_exit(cmd, ret);\n> +\tif (ret != -1)\n> +\t\ttrace2_child_exit(cmd, ret);\n>  \treturn ret;\n>  }\n\nThis seems like a legitimate issue, but I really don't think we should\nsweep this under the rug like this.\n\n * Why can't we see if we logged such an event already in common_exit(),\n   if we didn't we should trace2_child_exit() (or similar). I.e. not\n   miss an event, ever.\n\n * Should this really be an \"exit\" event, aren't some of these failed\n   signal events? Per the \"should this be an exit event?\" question in my\n   related \"signal on BUG\" series.\n\n * We should have tests here, e.g. in t0210 to see the exact events we\n   emit in certain cases, we really should have a test for this. Perhaps\n   we can instrument a simulated failure with some GIT_TEST_* variables?\n"},{"id":"457028","messageId":"e1a078cc-b1b0-5ee0-9539-77fd97dd5a78@jeffhostetler.com","threadId":"57813","inReplyTo":"50d872a057a558fa5519856b95abd048ddb514dc.1654625626.git.steadmon@google.com","subject":"Re: [PATCH v2] run-command: don't spam trace2_child_exit()","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2022-06-10T15:31:30Z","receivedAt":"2022-06-10T15:31:41Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 6/7/22 2:21 PM, Josh Steadmon wrote:\n> In rare cases[1], wait_or_whine() cannot determine a child process's\n> status (and will return -1 in this case). This can cause Git to issue\n> trace2 child_exit events despite the fact that the child may still be\n> running. In pathological cases, we've seen > 80 million exit events in\n> our trace logs for a single child process.\n> \n> Fix this by only issuing trace2 events in finish_command_in_signal() if\n> we get a value other than -1 from wait_or_whine(). This can lead to\n> missing child_exit events in such a case, but that is preferable to\n> duplicating events on a scale that threatens to fill the user's\n> filesystem with invalid trace logs.\n> \n> [1]: This can happen when:\n> \n> * waitpid() returns -1 and errno != EINTR\n> * waitpid() returns an invalid PID\n> * the status set by waitpid() has neither the WIFEXITED() nor\n>    WIFSIGNALED() flags\n> \n> Signed-off-by: Josh Steadmon <steadmon@google.com>\n> ---\n> Updated the commit message with more details about when wait_or_whine()\n> can fail.\n> \n>   run-command.c | 3 ++-\n>   1 file changed, 2 insertions(+), 1 deletion(-)\n> \n> diff --git a/run-command.c b/run-command.c\n> index a8501e38ce..e0fe2418a2 100644\n> --- a/run-command.c\n> +++ b/run-command.c\n> @@ -983,7 +983,8 @@ int finish_command(struct child_process *cmd)\n>   int finish_command_in_signal(struct child_process *cmd)\n>   {\n>   \tint ret = wait_or_whine(cmd->pid, cmd->args.v[0], 1);\n> -\ttrace2_child_exit(cmd, ret);\n> +\tif (ret != -1)\n> +\t\ttrace2_child_exit(cmd, ret);\n>   \treturn ret;\n>   }\n>   \n> \n> base-commit: faa21c10d44184f616d391c158dcbb13b9c72ef3\n> \n\n\nI think there are larger bugs lurking here.\n\nfinish_command_in_signal() is only called from\nwait_for_pager_signal(), which is loaded up by\nsigchain_push_common() when the pager is started.\n\nThere are no loops or other callers here.\n\nWe sigchain-pop our handler upon first use, so even if we\nwere getting millions of PIPE signals from other chilld\nprocesses, we shouldn't be getting more than 1 message\nhere.  (Assuming that our pop is working and our call to\nraise() doesn't cause us to be called again.)\n\nThe code is behaving as if the \"s->n--\" at the bottom of\nsigchain_pop() isn't being performed and our raise() is\ncalling us again.\n\nI originally thought it might be due to unbalanced push/pops -- which\ncould happen if the process were in a \"push; do something; pop\"\nsequence and the PIPE happened in the middle of that.  But I don't\nthink that matters.\n\nSo I have to wonder if the sigchain code has a bug.\n\nThe Linux man-page states that signal(2) is not thread-safe\nand even if it were, the sigchain code here does not have any\nlocking on those global data structures.\n\nBut that might not be the problem here and it's hard to say without\nany of the original trace data.\n\nHaving said all of that I think it would be better to fix the\noriginal problem something like this (not tested):\n\n  static void wait_for_pager_signal(int signo)\n  {\n+\tstatic int handled = 0;\n+\n+\tif (handled)\n+\t\treturn;\n+\thandled = 1;\n+\n\tclose_pager_fds();\n\tfinish_command_in_signal(&pager_process);\n\tsigchain_pop(signo);\n\traise(signo);\n  }\n\nJeff\n\n"}]}