Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Nicholas Williams]

[-- Attachment #1: Type: text/plain, Size: 2410 bytes --]

Hello,

We have a Python (installed and run through Cygwin) process running on Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:

0 [main] python3 28481 dofork: child -1 - forked process 16856 died unexpectedly, retry 0, exit code 0xC0000142, errno 11
…
    subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
     <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
     <>with Popen(*popenargs, **kwargs) as process: <>
File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
     <>self._execute_child(args, executable, preexec_fn, close_fds, <>
File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
    self.pid = _posixsubprocess.fork_exec(
BlockingIOError: [Errno 11] Resource temporarily unavailable

Setting aside for a minute the various reasons this might be happening occasionally, which we cannot solve for at this moment, the error number (EAGAIN) indicates that you should “try again.” So that’s exactly what we did. We added a try/catch to the Python code to catch the BlockingIOError and, if and only if the error number is EAGAIN, we try up to two more times. This fixed the problem and caused the application to stop quitting. We output a warning to our log so that we don’t forget about the problem, but the warning only ever appears once, so retrying a single time seems to help.

However … even though Python handles the dofork error, turns it into a Python exception, and our code catches the Python exception and handles it properly, Cygwin (not Python … Cygwin) still outputs a message to stderr right before our warning message. This Cygwin error message shows up as an error in our log tracking:

0 [main] python3 15042 dofork: child -1 - forked process 6780 died unexpectedly, retry 0, exit code 0xC0000142, errno 11
06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]

I’m sure there could be any number of things I might be missing, but IMO, if the process calling dofork properly handles the error raised by dofork, Cygwin should not be outputting an error message to stderr.

Thoughts?

Thanks,

Nick

 <>

Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Andrey Repin]

Greetings, Nicholas Williams!

> We have a Python (installed and run through Cygwin) process running on
> Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:

> 0 [main] python3 28481 dofork: child -1 - forked process 16856 died
> unexpectedly, retry 0, exit code 0xC0000142, errno 11
> …
>     subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
> File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
>      <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
> File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
>      <>with Popen(*popenargs, **kwargs) as process: <>
> File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
>      <>self._execute_child(args, executable, preexec_fn, close_fds, <>
> File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
>     self.pid = _posixsubprocess.fork_exec(
> BlockingIOError: [Errno 11] Resource temporarily unavailable

> Setting aside for a minute the various reasons this might be happening
> occasionally, which we cannot solve for at this moment, the error number
> (EAGAIN) indicates that you should “try again.” So that’s exactly what we
> did. We added a try/catch to the Python code to catch the BlockingIOError
> and, if and only if the error number is EAGAIN, we try up to two more times.
> This fixed the problem and caused the application to stop quitting. We
> output a warning to our log so that we don’t forget about the problem, but
> the warning only ever appears once, so retrying a single time seems to help.

> However … even though Python handles the dofork error, turns it into a
> Python exception, and our code catches the Python exception and handles it
> properly, Cygwin (not Python … Cygwin) still outputs a message to stderr
> right before our warning message. This Cygwin error message shows up as an error in our log tracking:

> 0 [main] python3 15042 dofork: child -1 - forked process 6780 died
> unexpectedly, retry 0, exit code 0xC0000142, errno 11
> 06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]

> I’m sure there could be any number of things I might be missing, but IMO,
> if the process calling dofork properly handles the error raised by dofork,
> Cygwin should not be outputting an error message to stderr.

> Thoughts?

My inexperienced and uneducated thought would be that forking code is fragile
and some parts of it prone to misbehavior. When an unforeseen error is
detected, it's better to report it sooner, than to get bitten by it later.

Regarding your specific issue, if you create a STC[1] (a minimally enough
version of your code that, say, fork a process thousands of times, which
reliable reproduce the issue) somebody else could run to test the cause, that
would be wonderful.

(If, however, you could find and fix the cause, that would be even more wonderful!)

[1] https://www.cygwin.com/acronyms/#STC


-- 
With best regards,
Andrey Repin
Monday, June 17, 2024 10:52:05

Sorry for my terrible english...

Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Dale Lobb (Sys Admin)]

Greetings, Nicholas;

> From: Cygwin <cygwin-bounces+dale.lobb=bryanhealth.org@cygwin.com> On Behalf Of Andrey Repin via Cygwin
> Sent: Monday, June 17, 2024 2:58 AM
> To: Nicholas Williams <nicholas.williams@zaxiom.com>; cygwin@cygwin.com
> Cc: Andrey Repin <anrdaemon@yandex.ru>
> Subject: EXTERNAL SENDER: Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled
>
> Greetings, Nicholas Williams! > We have a Python (installed and run through Cygwin) process running on > Windows Server 2022 that was very, very occasionally failing when subprocess. check_output was called: > 0 [main] python3 28481
> 
> Greetings, Nicholas Williams!
>
> > We have a Python (installed and run through Cygwin) process running on
> > Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:
>
> > 0 [main] python3 28481 dofork: child -1 - forked process 16856 died
> > unexpectedly, retry 0, exit code 0xC0000142, errno 11
> > …
> >     subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
> > File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
> >      <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
> > File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
> >      <>with Popen(*popenargs, **kwargs) as process: <>
> > File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
> >      <>self._execute_child(args, executable, preexec_fn, close_fds, <>
> > File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
> >     self.pid = _posixsubprocess.fork_exec(
> > BlockingIOError: [Errno 11] Resource temporarily unavailable
>
> > Setting aside for a minute the various reasons this might be happening
> > occasionally, which we cannot solve for at this moment, the error number
> > (EAGAIN) indicates that you should “try again.” So that’s exactly what we
> > did. We added a try/catch to the Python code to catch the BlockingIOError
> > and, if and only if the error number is EAGAIN, we try up to two more times.
> > This fixed the problem and caused the application to stop quitting. We
> > output a warning to our log so that we don’t forget about the problem, but
> > the warning only ever appears once, so retrying a single time seems to help.
>
> > However … even though Python handles the dofork error, turns it into a
> > Python exception, and our code catches the Python exception and handles it
> > properly, Cygwin (not Python … Cygwin) still outputs a message to stderr
> > right before our warning message. This Cygwin error message shows up as an error in our log tracking:
>
> > 0 [main] python3 15042 dofork: child -1 - forked process 6780 died
> > unexpectedly, retry 0, exit code 0xC0000142, errno 11
> > 06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]
>
> > I’m sure there could be any number of things I might be missing, but IMO,
> > if the process calling dofork properly handles the error raised by dofork,
> > Cygwin should not be outputting an error message to stderr.
>
> > Thoughts?
>
> My inexperienced and uneducated thought would be that forking code is fragile
> and some parts of it prone to misbehavior. When an unforeseen error is
> detected, it's better to report it sooner, than to get bitten by it later.
>
> Regarding your specific issue, if you create a STC[1] (a minimally enough
> version of your code that, say, fork a process thousands of times, which
> reliable reproduce the issue) somebody else could run to test the cause, that
> would be wonderful.
>
> (If, however, you could find and fix the cause, that would be even more wonderful!)
>

  I have seen this exact issue on every Windows  2019 or 2022
server where I have installed new versions of Cygwin since fall of 2023.
Admittedly, that has only been 3 or 4 machines, but it sure seems like
a pattern.  I have resisted upgrading old Cygwin installations for fear
that they also would start to exhibit this fork problem.

https://cygwin.com/pipermail/cygwin/2023-September/254417.html

  The only thing I have found that decreases the frequency of the
errors is to increase the amount of RAM assigned to the machine.
It does not eliminate the issue.  I've tried a ton of different
options with re-basing the Cygwin executables, to no avail.


Best Regards,

Dale




________________________________

CONFIDENTIALITY NOTICE: This e-mail message, including any attachments, is for the sole use of the intended recipients and may contain confidential and privileged information. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message.

Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Dan Shelton]

On Mon, 17 Jun 2024 at 18:03, Dale Lobb (Sys Admin) via Cygwin
<cygwin@cygwin.com> wrote:
>
> Greetings, Nicholas;
>
> > From: Cygwin <cygwin-bounces+dale.lobb=bryanhealth.org@cygwin.com> On Behalf Of Andrey Repin via Cygwin
> > Sent: Monday, June 17, 2024 2:58 AM
> > To: Nicholas Williams <nicholas.williams@zaxiom.com>; cygwin@cygwin.com
> > Cc: Andrey Repin <anrdaemon@yandex.ru>
> > Subject: EXTERNAL SENDER: Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled
> >
> > Greetings, Nicholas Williams! > We have a Python (installed and run through Cygwin) process running on > Windows Server 2022 that was very, very occasionally failing when subprocess. check_output was called: > 0 [main] python3 28481
> >
> > Greetings, Nicholas Williams!
> >
> > > We have a Python (installed and run through Cygwin) process running on
> > > Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:
> >
> > > 0 [main] python3 28481 dofork: child -1 - forked process 16856 died
> > > unexpectedly, retry 0, exit code 0xC0000142, errno 11
> > > …
> > >     subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
> > > File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
> > >      <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
> > > File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
> > >      <>with Popen(*popenargs, **kwargs) as process: <>
> > > File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
> > >      <>self._execute_child(args, executable, preexec_fn, close_fds, <>
> > > File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
> > >     self.pid = _posixsubprocess.fork_exec(
> > > BlockingIOError: [Errno 11] Resource temporarily unavailable
> >
> > > Setting aside for a minute the various reasons this might be happening
> > > occasionally, which we cannot solve for at this moment, the error number
> > > (EAGAIN) indicates that you should “try again.” So that’s exactly what we
> > > did. We added a try/catch to the Python code to catch the BlockingIOError
> > > and, if and only if the error number is EAGAIN, we try up to two more times.
> > > This fixed the problem and caused the application to stop quitting. We
> > > output a warning to our log so that we don’t forget about the problem, but
> > > the warning only ever appears once, so retrying a single time seems to help.
> >
> > > However … even though Python handles the dofork error, turns it into a
> > > Python exception, and our code catches the Python exception and handles it
> > > properly, Cygwin (not Python … Cygwin) still outputs a message to stderr
> > > right before our warning message. This Cygwin error message shows up as an error in our log tracking:
> >
> > > 0 [main] python3 15042 dofork: child -1 - forked process 6780 died
> > > unexpectedly, retry 0, exit code 0xC0000142, errno 11
> > > 06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]

Does python require fork(), or can it use posix_spawn() in this case?

Dan
-- 
Dan Shelton - Cluster Specialist Win/Lin/Bsd

Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Nicholas Williams]

[-- Attachment #1: Type: text/plain, Size: 6077 bytes --]

Andrey and Dale,

> On Jun 17, 2024, at 11:03, Dale Lobb (Sys Admin) <Dale.Lobb@bryanhealth.org> wrote:
> 
> Greetings, Nicholas;
> 
>> From: Cygwin <cygwin-bounces+dale.lobb=bryanhealth.org@cygwin.com <mailto:cygwin-bounces+dale.lobb=bryanhealth.org@cygwin.com>> On Behalf Of Andrey Repin via Cygwin
>> Sent: Monday, June 17, 2024 2:58 AM
>> To: Nicholas Williams <nicholas.williams@zaxiom.com <mailto:nicholas.williams@zaxiom.com>>; cygwin@cygwin.com <mailto:cygwin@cygwin.com>
>> Cc: Andrey Repin <anrdaemon@yandex.ru <mailto:anrdaemon@yandex.ru>>
>> Subject: EXTERNAL SENDER: Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled
>> 
>> Greetings, Nicholas Williams! > We have a Python (installed and run through Cygwin) process running on > Windows Server 2022 that was very, very occasionally failing when subprocess. check_output was called: > 0 [main] python3 28481
>> 
>> Greetings, Nicholas Williams!
>> 
>>> We have a Python (installed and run through Cygwin) process running on
>>> Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:
>> 
>>> 0 [main] python3 28481 dofork: child -1 - forked process 16856 died
>>> unexpectedly, retry 0, exit code 0xC0000142, errno 11
>>> …
>>>    subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
>>> File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
>>>     <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
>>> File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
>>>     <>with Popen(*popenargs, **kwargs) as process: <>
>>> File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
>>>     <>self._execute_child(args, executable, preexec_fn, close_fds, <>
>>> File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
>>>    self.pid = _posixsubprocess.fork_exec(
>>> BlockingIOError: [Errno 11] Resource temporarily unavailable
>> 
>>> Setting aside for a minute the various reasons this might be happening
>>> occasionally, which we cannot solve for at this moment, the error number
>>> (EAGAIN) indicates that you should “try again.” So that’s exactly what we
>>> did. We added a try/catch to the Python code to catch the BlockingIOError
>>> and, if and only if the error number is EAGAIN, we try up to two more times.
>>> This fixed the problem and caused the application to stop quitting. We
>>> output a warning to our log so that we don’t forget about the problem, but
>>> the warning only ever appears once, so retrying a single time seems to help.
>> 
>>> However … even though Python handles the dofork error, turns it into a
>>> Python exception, and our code catches the Python exception and handles it
>>> properly, Cygwin (not Python … Cygwin) still outputs a message to stderr
>>> right before our warning message. This Cygwin error message shows up as an error in our log tracking:
>> 
>>> 0 [main] python3 15042 dofork: child -1 - forked process 6780 died
>>> unexpectedly, retry 0, exit code 0xC0000142, errno 11
>>> 06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]
>> 
>>> I’m sure there could be any number of things I might be missing, but IMO,
>>> if the process calling dofork properly handles the error raised by dofork,
>>> Cygwin should not be outputting an error message to stderr.
>> 
>>> Thoughts?
>> 
>> My inexperienced and uneducated thought would be that forking code is fragile
>> and some parts of it prone to misbehavior. When an unforeseen error is
>> detected, it's better to report it sooner, than to get bitten by it later.
>> 
>> Regarding your specific issue, if you create a STC[1] (a minimally enough
>> version of your code that, say, fork a process thousands of times, which
>> reliable reproduce the issue) somebody else could run to test the cause, that
>> would be wonderful.
>> 
>> (If, however, you could find and fix the cause, that would be even more wonderful!)
>> 
> 
>  I have seen this exact issue on every Windows  2019 or 2022
> server where I have installed new versions of Cygwin since fall of 2023.
> Admittedly, that has only been 3 or 4 machines, but it sure seems like
> a pattern.  I have resisted upgrading old Cygwin installations for fear
> that they also would start to exhibit this fork problem.
> 
> https://cygwin.com/pipermail/cygwin/2023-September/254417.html
> 
>  The only thing I have found that decreases the frequency of the
> errors is to increase the amount of RAM assigned to the machine.
> It does not eliminate the issue.  I've tried a ton of different
> options with re-basing the Cygwin executables, to no avail.
> 
> 
> Best Regards,
> 
> Dale

To be clear, the problem I’m reporting *IS NOT* the fork failure. Sure, there might be a bug there, or it might just be that we have a resource exhaustion problem that we haven’t been able to identify yet. We’ll figure that out eventually; for now, we have successfully worked around the problem by retrying.

The problem I’m reporting is that Cygwin, for some reason, prints an error message to stderr whenever fork fails, instead of letting the application calling fork do its own error handling. This means that, even though we catch the Python exception and retry (successfully), an error message still gets written to stderr and ends up in our logs. This error message is coming from this Cygwin code:

https://github.com/cygwin/cygwin/blob/7e3c833592b282355a57dd34459b152e4e078d19/winsup/cygwin/fork.cc#L381-L382

In our opinion, low-level system calls like this shouldn’t be writing to stderr. That’s what errno is for (which this call does properly set)—for the application making the system call to decide what to do about the error. That application can always decide to print an error. The system call should not. There appears to be no way for us to disable this error printing.

Nick

Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled

[Nicholas Williams]

Dan,

> On Jun 18, 2024, at 09:44, Dan Shelton via Cygwin <cygwin@cygwin.com> wrote:
> 
> On Mon, 17 Jun 2024 at 18:03, Dale Lobb (Sys Admin) via Cygwin
> <cygwin@cygwin.com> wrote:
>> 
>> Greetings, Nicholas;
>> 
>>> From: Cygwin <cygwin-bounces+dale.lobb=bryanhealth.org@cygwin.com> On Behalf Of Andrey Repin via Cygwin
>>> Sent: Monday, June 17, 2024 2:58 AM
>>> To: Nicholas Williams <nicholas.williams@zaxiom.com>; cygwin@cygwin.com
>>> Cc: Andrey Repin <anrdaemon@yandex.ru>
>>> Subject: EXTERNAL SENDER: Re: Cygwin outputting message to stderr on dofork EAGAIN failure even when Python exception is caught and handled
>>> 
>>> Greetings, Nicholas Williams! > We have a Python (installed and run through Cygwin) process running on > Windows Server 2022 that was very, very occasionally failing when subprocess. check_output was called: > 0 [main] python3 28481
>>> 
>>> Greetings, Nicholas Williams!
>>> 
>>>> We have a Python (installed and run through Cygwin) process running on
>>>> Windows Server 2022 that was very, very occasionally failing when subprocess.check_output was called:
>>> 
>>>> 0 [main] python3 28481 dofork: child -1 - forked process 16856 died
>>>> unexpectedly, retry 0, exit code 0xC0000142, errno 11
>>>> …
>>>>    subprocess.check_output(["cygpath", "-w", directory.name], encoding="utf-8").strip()
>>>> File "/usr/lib/python3.9/subprocess.py", line 424, in check_output <>
>>>>     <>return run(*popenargs, stdout=PIPE, timeout=timeout, check=True, <>
>>>> File "/usr/lib/python3.9/subprocess.py", line 505, in run <>
>>>>     <>with Popen(*popenargs, **kwargs) as process: <>
>>>> File "/usr/lib/python3.9/subprocess.py", line 951, in __init__ <>
>>>>     <>self._execute_child(args, executable, preexec_fn, close_fds, <>
>>>> File "/usr/lib/python3.9/subprocess.py", line 1754, in _execute_child
>>>>    self.pid = _posixsubprocess.fork_exec(
>>>> BlockingIOError: [Errno 11] Resource temporarily unavailable
>>> 
>>>> Setting aside for a minute the various reasons this might be happening
>>>> occasionally, which we cannot solve for at this moment, the error number
>>>> (EAGAIN) indicates that you should “try again.” So that’s exactly what we
>>>> did. We added a try/catch to the Python code to catch the BlockingIOError
>>>> and, if and only if the error number is EAGAIN, we try up to two more times.
>>>> This fixed the problem and caused the application to stop quitting. We
>>>> output a warning to our log so that we don’t forget about the problem, but
>>>> the warning only ever appears once, so retrying a single time seems to help.
>>> 
>>>> However … even though Python handles the dofork error, turns it into a
>>>> Python exception, and our code catches the Python exception and handles it
>>>> properly, Cygwin (not Python … Cygwin) still outputs a message to stderr
>>>> right before our warning message. This Cygwin error message shows up as an error in our log tracking:
>>> 
>>>> 0 [main] python3 15042 dofork: child -1 - forked process 6780 died
>>>> unexpectedly, retry 0, exit code 0xC0000142, errno 11
>>>> 06/16 13:57:53. 87520: WARNING: Retrying command in 2 seconds due to EAGAIN: [the command we’re running]
> 
> Does python require fork(), or can it use posix_spawn() in this case?

I imagine this would be question for the CPython development team. While I have a basic understanding of C programming in Python (for the purposes of writing extensions), I do not know why subprocess.Popen is written in this way, and I do not know enough to question their choice here. It uses fork, and for now I have to live with that.

Thanks,

Nick