* Problem with zombie processes
@ 2017-02-14 11:14 Erik Bray
2017-02-14 19:25 ` Mark Geisert
0 siblings, 1 reply; 11+ messages in thread
From: Erik Bray @ 2017-02-14 11:14 UTC (permalink / raw)
To: cygwin
Hi all,
I encountered a strange bug concerning zombie child processes during
my testing. Specifically, it came up in the context of trying to read
the /proc/<pid> entries of processes that should be zombified but not
reaped yet (i.e. they have received and processed a SIGKILL or SIGTERM
but have not been wait()ed on yet).
In some cases it's still possible to read, for example,
/proc/<pid>/stat of the zombie process, while in other cases it fails
with errno 22 (EINVAL). In the latter case, this is coming from the
OpenProcess() call in format_process_stat() (or similarly in other
format_process_* methods) indicating that Windows has already removed
the process object from its process table. Or equivalently, there are
no more open handles to the child process.
What I don't understand is if this is intentional or not. I feel like
Cygwin should try to keep the Windows process object alive as long as
it's a zombie process. But in some cases it does and in some cases it
doesn't.
The attached Python script shows two such cases, and I don't
understand quite where they differ. In one case, stdout from the
child process is being sent to the parent over a pipe. In the second
case stdout from the child is sent to /dev/null. In the first case
the process object is kept alive and I can read its /proc entries. In
the latter case it dies even before wait(). I'm not sure what the
difference is in terms of keeping the process object alive.
If Cygwin can't guarantee that the Windows process object is kept
around while the process is in zombie state, it would be nice, as an
alternative, to change the error handling in the format_process_*
methods to return as much info as it can, with other fields zero'd
out, rather than an error.
Best,
Erik
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-14 11:14 Problem with zombie processes Erik Bray
@ 2017-02-14 19:25 ` Mark Geisert
2017-02-17 11:00 ` Erik Bray
0 siblings, 1 reply; 11+ messages in thread
From: Mark Geisert @ 2017-02-14 19:25 UTC (permalink / raw)
To: cygwin
Erik Bray wrote:
> The attached Python script
??
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-14 19:25 ` Mark Geisert
@ 2017-02-17 11:00 ` Erik Bray
2017-02-17 15:06 ` Doug Henderson
2017-02-17 22:06 ` Mark Geisert
0 siblings, 2 replies; 11+ messages in thread
From: Erik Bray @ 2017-02-17 11:00 UTC (permalink / raw)
To: cygwin
[-- Attachment #1: Type: text/plain, Size: 199 bytes --]
On Tue, Feb 14, 2017 at 8:25 PM, Mark Geisert <mark@maxrnd.com> wrote:
> Erik Bray wrote:
>>
>> The attached Python script
>
>
> ??
D'oh! Here is the script. It at least demonstrates the problem.
[-- Attachment #2: test.py --]
[-- Type: application/octet-stream, Size: 594 bytes --]
from __future__ import print_function
import os
import subprocess as sp
devnul = open(os.devnull, 'r+')
print("Test 1: stdout piped to parent")
p = sp.Popen(['yes'], stdout=sp.PIPE)
print("child pid: %d" % p.pid)
print("sending SIGKILL")
p.send_signal(9)
stat = '/proc/%d/stat' % p.pid
print("reading", stat)
print(open(stat).read())
p.wait()
print("=" * 80)
print("Test 2: stdout piped to /dev/null")
p = sp.Popen(['yes'], stdout=devnul)
print("child pid: %d" % p.pid)
print("killing")
p.send_signal(9)
stat = '/proc/%d/stat' % p.pid
print("reading", stat)
print(open(stat).read())
p.wait()
[-- Attachment #3: Type: text/plain, Size: 219 bytes --]
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-17 11:00 ` Erik Bray
@ 2017-02-17 15:06 ` Doug Henderson
2017-02-17 22:06 ` Mark Geisert
1 sibling, 0 replies; 11+ messages in thread
From: Doug Henderson @ 2017-02-17 15:06 UTC (permalink / raw)
To: cygwin
On 17 February 2017 at 04:00, Erik Bray wrote:
> On Tue, Feb 14, 2017 at 8:25 PM, Mark Geisert wrote:
>> Erik Bray wrote:
>>>
>>> The attached Python script
>>
>>
>> ??
>
> D'oh! Here is the script. It at least demonstrates the problem.
>
If you add a few "time.sleep(1)" statements before and after sending
the kill signals, you should observe consistent behavior. Without the
delay (and forced context switches) the main process may run before
the child process state has settled before and after the kill signals.
On Win7, with the delays, I see consistent behavior for both cases.
Test 1 always succeeds. Test 2 always fails with "IOError or OSError
[Errno 22] invalid argument" for python or python3 (respectively).
While not a explanation of the different results for test1 and test2, I HTH.
Doug
--
Doug Henderson, Calgary, Alberta, Canada - from gmail.com
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-17 11:00 ` Erik Bray
2017-02-17 15:06 ` Doug Henderson
@ 2017-02-17 22:06 ` Mark Geisert
2017-02-20 9:46 ` Erik Bray
1 sibling, 1 reply; 11+ messages in thread
From: Mark Geisert @ 2017-02-17 22:06 UTC (permalink / raw)
To: cygwin
Erik Bray wrote:
> On Tue, Feb 14, 2017 at 8:25 PM, Mark Geisert <XXXX@XXXXXX.XXX> wrote:
Please don't quote raw email addresses. We try to avoid feeding spammers.
>> Erik Bray wrote:
>>>
>>> The attached Python script
>>
>> ??
>
> D'oh! Here is the script. It at least demonstrates the problem.
>
[...]
Thanks! Running this script repeatedly on my system (Win7, 2 cores / 4 HT
threads) showed no differences between your Test 1 and Test 2. Each Test
concludes in one of three ways, seemingly randomly: (1) read of /proc/<pid>/stat
succeeds and process status is displayed, (2) read fails with Python IOError,
(3) read apparently succeeds but there's no process data displayed.
An strace of your script shows Python itself is calling wait4() to reap the
child process. So, as Doug suggested on another thread, the script's actions
are just subject to the whims of process scheduling and vary from run to run.
..mark
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-17 22:06 ` Mark Geisert
@ 2017-02-20 9:46 ` Erik Bray
2017-02-20 10:54 ` Mark Geisert
0 siblings, 1 reply; 11+ messages in thread
From: Erik Bray @ 2017-02-20 9:46 UTC (permalink / raw)
To: cygwin
On Fri, Feb 17, 2017 at 11:06 PM, Mark Geisert <mark@maxrnd.com> wrote:
> Erik Bray wrote:
>>
>> On Tue, Feb 14, 2017 at 8:25 PM, Mark Geisert <XXXX@XXXXXX.XXX> wrote:
>
>
> Please don't quote raw email addresses. We try to avoid feeding spammers.
Sorry--normally replies on this ML are just back to the ML itself (my
preference as well) so I wasn't expecting it.
>>> Erik Bray wrote:
>>>>
>>>>
>>>> The attached Python script
>>>
>>>
>>> ??
>>
>>
>> D'oh! Here is the script. It at least demonstrates the problem.
>>
> [...]
>
> Thanks! Running this script repeatedly on my system (Win7, 2 cores / 4 HT
> threads) showed no differences between your Test 1 and Test 2. Each Test
> concludes in one of three ways, seemingly randomly: (1) read of
> /proc/<pid>/stat succeeds and process status is displayed, (2) read fails
> with Python IOError, (3) read apparently succeeds but there's no process
> data displayed.
>
> An strace of your script shows Python itself is calling wait4() to reap the
> child process. So, as Doug suggested on another thread, the script's
> actions are just subject to the whims of process scheduling and vary from
> run to run.
You're right. The first time I was testing this, for whatever reason,
I was getting *very* consistent results. Test 1 *always* succeeded
and test 2 always fails. But trying it now, I am getting similar
results.
What I was going by was the docs for ExitProcess [1] which states:
"Exiting a process does not necessarily remove the process object from
the operating system. A process object is deleted when the last handle
to the process is closed."
So my guess was that Cygwin might try to hold on to a handle to a
child process at least until it's been explicitly wait()ed. But that
does not seem to be the case after all.
Anyways, I think it would be nicer if /proc returned at least partial
information on zombie processes, rather than an error. I have a patch
to this effect for /proc/<pid>/stat, and will add a few more as well.
To me /proc/<pid>/stat was the most important because that's the
easiest way to check the process's state in the first place! Now I
also have to catch EINVAL as well and assume that means a zombie
process.
Thanks,
Erik
[1] https://msdn.microsoft.com/en-us/library/windows/desktop/ms682658(v=vs.85).aspx
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-20 9:46 ` Erik Bray
@ 2017-02-20 10:54 ` Mark Geisert
2017-02-20 15:23 ` Erik Bray
0 siblings, 1 reply; 11+ messages in thread
From: Mark Geisert @ 2017-02-20 10:54 UTC (permalink / raw)
To: cygwin
Erik Bray wrote:
> On Fri, Feb 17, 2017 at 11:06 PM, Mark Geisert <REMOVED> wrote:
>> Erik Bray wrote:
>>>
>>> On Tue, Feb 14, 2017 at 8:25 PM, Mark Geisert <XXXX@XXXXXX.XXX> wrote:
>>
>>
>> Please don't quote raw email addresses. We try to avoid feeding spammers.
>
> Sorry--normally replies on this ML are just back to the ML itself (my
> preference as well) so I wasn't expecting it.
Reiterating this: Please manually remove quoted email addresses from your replies.
>>>> Erik Bray wrote:
>>>>>
>>>>>
>>>>> The attached Python script
>>>>
>>>>
>>>> ??
>>>
>>>
>>> D'oh! Here is the script. It at least demonstrates the problem.
>>>
>> [...]
>>
>> Thanks! Running this script repeatedly on my system (Win7, 2 cores / 4 HT
>> threads) showed no differences between your Test 1 and Test 2. Each Test
>> concludes in one of three ways, seemingly randomly: (1) read of
>> /proc/<pid>/stat succeeds and process status is displayed, (2) read fails
>> with Python IOError, (3) read apparently succeeds but there's no process
>> data displayed.
>>
>> An strace of your script shows Python itself is calling wait4() to reap the
>> child process. So, as Doug suggested on another thread, the script's
>> actions are just subject to the whims of process scheduling and vary from
>> run to run.
>
> You're right. The first time I was testing this, for whatever reason,
> I was getting *very* consistent results. Test 1 *always* succeeded
> and test 2 always fails. But trying it now, I am getting similar
> results.
>
> What I was going by was the docs for ExitProcess [1] which states:
>
> "Exiting a process does not necessarily remove the process object from
> the operating system. A process object is deleted when the last handle
> to the process is closed."
>
> So my guess was that Cygwin might try to hold on to a handle to a
> child process at least until it's been explicitly wait()ed. But that
> does not seem to be the case after all.
You might have missed a subtlety in what I said above. The Python interpreter
itself is calling wait4() to reap your child process. Cygwin has told Python
one of its children has died. You won't get the chance to wait() for it
yourself. Cygwin *does* have a handle to the process, but it gets closed as
part of Python calling wait4().
> Anyways, I think it would be nicer if /proc returned at least partial
> information on zombie processes, rather than an error. I have a patch
> to this effect for /proc/<pid>/stat, and will add a few more as well.
> To me /proc/<pid>/stat was the most important because that's the
> easiest way to check the process's state in the first place! Now I
> also have to catch EINVAL as well and assume that means a zombie
> process.
The file /proc/<pid>/stat is there until Cygwin finishes cleanup of the child
due to Python having wait()ed for it. When you run your test script, pay
attention to the process state character in those cases where you successfully
read the stat file. It's often S (stopped, I think) or R (running) but I also
see Z (zombie) sometimes. Your script is in a race with Cygwin, and you cannot
guarantee you'll see a killed process's state before Cygwin cleans it up.
One way around this *might* be to install a SIGCHLD handler in your Python
script. If that's possible, that should tell you when your child exits.
..mark
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-20 10:54 ` Mark Geisert
@ 2017-02-20 15:23 ` Erik Bray
2017-02-20 22:54 ` Mark Geisert
0 siblings, 1 reply; 11+ messages in thread
From: Erik Bray @ 2017-02-20 15:23 UTC (permalink / raw)
To: cygwin
[-- Attachment #1: Type: text/plain, Size: 2746 bytes --]
On Mon, Feb 20, 2017 at 11:54 AM, Mark Geisert wrote:
>> So my guess was that Cygwin might try to hold on to a handle to a
>> child process at least until it's been explicitly wait()ed. But that
>> does not seem to be the case after all.
>
>
> You might have missed a subtlety in what I said above. The Python
> interpreter itself is calling wait4() to reap your child process. Cygwin
> has told Python one of its children has died. You won't get the chance to
> wait() for it yourself. Cygwin *does* have a handle to the process, but it
> gets closed as part of Python calling wait4().
To be clear, wait4() is not called from Python until the script
explicitly calls p.wait().
In other words, when run this step by step (e.g. in gdb) I don't see a
wait4() call until the point where the script explicitly waits(). I
don't see any reason Python would do this behind the scenes.
>> Anyways, I think it would be nicer if /proc returned at least partial
>> information on zombie processes, rather than an error. I have a patch
>> to this effect for /proc/<pid>/stat, and will add a few more as well.
>> To me /proc/<pid>/stat was the most important because that's the
>> easiest way to check the process's state in the first place! Now I
>> also have to catch EINVAL as well and assume that means a zombie
>> process.
>
>
> The file /proc/<pid>/stat is there until Cygwin finishes cleanup of the
> child due to Python having wait()ed for it. When you run your test script,
> pay attention to the process state character in those cases where you
> successfully read the stat file. It's often S (stopped, I think) or R
> (running) but I also see Z (zombie) sometimes. Your script is in a race
> with Cygwin, and you cannot guarantee you'll see a killed process's state
> before Cygwin cleans it up.
>
> One way around this *might* be to install a SIGCHLD handler in your Python
> script. If that's possible, that should tell you when your child exits.
Perhaps the Python script is a red herring. I just wrote it to
demonstrate the problem. The difference between where I send stdout
to is strange, but you're likely right that it just comes down to
subtle timing differences. Here's a C program that demonstrates the
same issue more reliably. Interestingly, it works when I run it in
strace (probably just because of the strace overhead) but not when I
run it normally.
My point in all this is I'm confused why Cygwin would give up its
handles to the Windows process before wait() has been called.
(In fact, it's pretty confusing to have fopen returning EINVAL which
according to [1] it should only be doing if the mode string were
invalid.)
Thanks,
Erik
[1] http://pubs.opengroup.org/onlinepubs/9699919799/functions/fopen.html
[-- Attachment #2: test.c --]
[-- Type: text/x-csrc, Size: 1260 bytes --]
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <time.h>
#include <string.h>
#include <signal.h>
#include <fcntl.h>
#include <sys/wait.h>
#include <sys/errno.h>
int do_parent(pid_t);
void do_child(int);
int main(void) {
int devnul;
pid_t pid;
devnul = open("/dev/null", O_WRONLY);
pid = fork();
if (pid) {
/* Parent */
return do_parent(pid);
} else {
/* Child */
do_child(devnul);
}
}
int do_parent(pid_t child_pid) {
FILE *f;
char buf[120];
char filename[20];
printf("child pid: %d\n", child_pid);
sleep(5);
printf("sending SIGKILL\n");
kill(child_pid, SIGKILL);
sprintf(filename, "/proc/%d/stat", child_pid);
printf("reading %s\n", filename);
f = fopen(filename, "r");
if (f == NULL) {
printf("fopen error [%d]: %s\n", errno, strerror(errno));
if (!access(filename, R_OK)) {
printf("but the file exists and is readable\n");
}
} else {
fread(buf, sizeof(char), 120, f);
printf(buf);
}
return wait4(child_pid, NULL, 0, NULL);
}
void do_child(int out) {
char *argv[1];
argv[0] = "/usr/bin/yes";
dup2(out, 1);
execv(argv[0], argv);
exit(0);
}
[-- Attachment #3: Type: text/plain, Size: 219 bytes --]
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-20 15:23 ` Erik Bray
@ 2017-02-20 22:54 ` Mark Geisert
2017-02-21 11:59 ` Erik Bray
0 siblings, 1 reply; 11+ messages in thread
From: Mark Geisert @ 2017-02-20 22:54 UTC (permalink / raw)
To: cygwin
Erik Bray wrote:
> On Mon, Feb 20, 2017 at 11:54 AM, Mark Geisert wrote:
>>> So my guess was that Cygwin might try to hold on to a handle to a
>>> child process at least until it's been explicitly wait()ed. But that
>>> does not seem to be the case after all.
>>
>>
>> You might have missed a subtlety in what I said above. The Python
>> interpreter itself is calling wait4() to reap your child process. Cygwin
>> has told Python one of its children has died. You won't get the chance to
>> wait() for it yourself. Cygwin *does* have a handle to the process, but it
>> gets closed as part of Python calling wait4().
>
> To be clear, wait4() is not called from Python until the script
> explicitly calls p.wait().
> In other words, when run this step by step (e.g. in gdb) I don't see a
> wait4() call until the point where the script explicitly waits(). I
> don't see any reason Python would do this behind the scenes.
You're right. I missed the wait in your script and ASSumed too much of the
Python interpreter :-( .
>>> Anyways, I think it would be nicer if /proc returned at least partial
>>> information on zombie processes, rather than an error. I have a patch
>>> to this effect for /proc/<pid>/stat, and will add a few more as well.
>>> To me /proc/<pid>/stat was the most important because that's the
>>> easiest way to check the process's state in the first place! Now I
>>> also have to catch EINVAL as well and assume that means a zombie
>>> process.
>>
>>
>> The file /proc/<pid>/stat is there until Cygwin finishes cleanup of the
>> child due to Python having wait()ed for it. When you run your test script,
>> pay attention to the process state character in those cases where you
>> successfully read the stat file. It's often S (stopped, I think) or R
>> (running) but I also see Z (zombie) sometimes. Your script is in a race
>> with Cygwin, and you cannot guarantee you'll see a killed process's state
>> before Cygwin cleans it up.
>>
>> One way around this *might* be to install a SIGCHLD handler in your Python
>> script. If that's possible, that should tell you when your child exits.
>
> Perhaps the Python script is a red herring. I just wrote it to
> demonstrate the problem. The difference between where I send stdout
> to is strange, but you're likely right that it just comes down to
> subtle timing differences. Here's a C program that demonstrates the
> same issue more reliably. Interestingly, it works when I run it in
> strace (probably just because of the strace overhead) but not when I
> run it normally.
>
> My point in all this is I'm confused why Cygwin would give up its
> handles to the Windows process before wait() has been called.
>
> (In fact, it's pretty confusing to have fopen returning EINVAL which
> according to [1] it should only be doing if the mode string were
> invalid.)
>
> Thanks,
> Erik
>
> [1] http://pubs.opengroup.org/onlinepubs/9699919799/functions/fopen.html
O.K., you may be on to something amiss in the Cygwin DLL. Thanks for the STC in
C; that'll help somebody looking further at this. I'm out of ideas. It might
be possible to reduce strace overhead somewhat by selecting a smaller set of
trace options than the default.
..mark
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-20 22:54 ` Mark Geisert
@ 2017-02-21 11:59 ` Erik Bray
2019-04-04 12:44 ` E. Madison Bray
0 siblings, 1 reply; 11+ messages in thread
From: Erik Bray @ 2017-02-21 11:59 UTC (permalink / raw)
To: cygwin
[-- Attachment #1: Type: text/plain, Size: 3572 bytes --]
On Mon, Feb 20, 2017 at 11:54 PM, Mark Geisert wrote:
> Erik Bray wrote:
>>
>> On Mon, Feb 20, 2017 at 11:54 AM, Mark Geisert wrote:
>>>>
>>>> So my guess was that Cygwin might try to hold on to a handle to a
>>>> child process at least until it's been explicitly wait()ed. But that
>>>> does not seem to be the case after all.
>>>
>>>
>>>
>>> You might have missed a subtlety in what I said above. The Python
>>> interpreter itself is calling wait4() to reap your child process. Cygwin
>>> has told Python one of its children has died. You won't get the chance
>>> to
>>> wait() for it yourself. Cygwin *does* have a handle to the process, but
>>> it
>>> gets closed as part of Python calling wait4().
>>
>>
>> To be clear, wait4() is not called from Python until the script
>> explicitly calls p.wait().
>> In other words, when run this step by step (e.g. in gdb) I don't see a
>> wait4() call until the point where the script explicitly waits(). I
>> don't see any reason Python would do this behind the scenes.
>
>
> You're right. I missed the wait in your script and ASSumed too much of the
> Python interpreter :-( .
>
>
>>>> Anyways, I think it would be nicer if /proc returned at least partial
>>>> information on zombie processes, rather than an error. I have a patch
>>>> to this effect for /proc/<pid>/stat, and will add a few more as well.
>>>> To me /proc/<pid>/stat was the most important because that's the
>>>> easiest way to check the process's state in the first place! Now I
>>>> also have to catch EINVAL as well and assume that means a zombie
>>>> process.
>>>
>>>
>>>
>>> The file /proc/<pid>/stat is there until Cygwin finishes cleanup of the
>>> child due to Python having wait()ed for it. When you run your test
>>> script,
>>> pay attention to the process state character in those cases where you
>>> successfully read the stat file. It's often S (stopped, I think) or R
>>> (running) but I also see Z (zombie) sometimes. Your script is in a race
>>> with Cygwin, and you cannot guarantee you'll see a killed process's state
>>> before Cygwin cleans it up.
>>>
>>> One way around this *might* be to install a SIGCHLD handler in your
>>> Python
>>> script. If that's possible, that should tell you when your child exits.
>>
>>
>> Perhaps the Python script is a red herring. I just wrote it to
>> demonstrate the problem. The difference between where I send stdout
>> to is strange, but you're likely right that it just comes down to
>> subtle timing differences. Here's a C program that demonstrates the
>> same issue more reliably. Interestingly, it works when I run it in
>> strace (probably just because of the strace overhead) but not when I
>> run it normally.
>>
>> My point in all this is I'm confused why Cygwin would give up its
>> handles to the Windows process before wait() has been called.
>>
>> (In fact, it's pretty confusing to have fopen returning EINVAL which
>> according to [1] it should only be doing if the mode string were
>> invalid.)
>>
>> Thanks,
>> Erik
>>
>> [1] http://pubs.opengroup.org/onlinepubs/9699919799/functions/fopen.html
>
>
> O.K., you may be on to something amiss in the Cygwin DLL. Thanks for the
> STC in C; that'll help somebody looking further at this. I'm out of ideas.
> It might be possible to reduce strace overhead somewhat by selecting a
> smaller set of trace options than the default.
Note: My previous test program had a bug in do_child() (not correctly
terminating the argv array). The attached program fixes the bug.
I've also attached a (truncated) strace log from it.
[-- Attachment #2: test.c --]
[-- Type: text/x-csrc, Size: 1272 bytes --]
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <time.h>
#include <string.h>
#include <signal.h>
#include <fcntl.h>
#include <sys/wait.h>
#include <sys/errno.h>
int do_parent(pid_t);
void do_child(int);
int main(void) {
int devnul;
pid_t pid;
devnul = open("/dev/null", O_WRONLY);
pid = fork();
if (pid) {
/* Parent */
return do_parent(pid);
} else {
/* Child */
do_child(devnul);
}
}
int do_parent(pid_t child_pid) {
FILE *f;
char buf[120];
char filename[20];
printf("child pid: %d\n", child_pid);
sleep(10);
printf("sending SIGKILL\n");
kill(child_pid, SIGKILL);
sleep(10);
sprintf(filename, "/proc/%d/stat", child_pid);
printf("reading %s\n", filename);
f = fopen(filename, "r");
if (f == NULL) {
printf("fopen error [%d]: %s\n", errno, strerror(errno));
if (!access(filename, R_OK)) {
printf("but the file exists and is readable\n");
}
} else {
fread(buf, sizeof(char), 120, f);
printf(buf);
}
return wait4(child_pid, NULL, 0, NULL);
}
void do_child(int out) {
char *argv[2] = { "/usr/bin/yes", NULL };
dup2(out, 1);
execv(argv[0], argv);
exit(0);
}
[-- Attachment #3: test.exe.strace --]
[-- Type: application/octet-stream, Size: 80832 bytes --]
--- Process 5888 created
--- Process 5888 loaded C:\Windows\System32\ntdll.dll at 00007FF992A20000
--- Process 5888 loaded C:\Windows\System32\kernel32.dll at 00007FF991B80000
--- Process 5888 loaded C:\Windows\System32\KernelBase.dll at 00007FF98F940000
--- Process 5888 thread 8392 created
--- Process 5888 loaded C:\cygwin64\bin\cygwin1.dll at 0000000180040000
2 2 [main] test (5888) **********************************************
214 216 [main] test (5888) Program name: C:\cygwin64-test\home\Erik M. Bray\test.exe (windows pid 5888)
43 259 [main] test (5888) OS version: Windows NT-10.0
36 295 [main] test (5888) **********************************************
86 381 [main] test (5888) sigprocmask: 0 = sigprocmask (0, 0x0, 0x1802E2BB0)
352 733 [main] test 5888 open_shared: name shared.5, n 5, shared 0x180030000 (wanted 0x180030000), h 0xB8, *m 6
63 796 [main] test 5888 user_heap_info::init: heap base 0x600000000, heap top 0x600000000, heap size 0x20000000 (536870912)
80 876 [main] test 5888 open_shared: name S-1-5-21-1150923390-1632126722-2651444992-1001.1, n 1, shared 0x180020000 (wanted 0x180020000), h 0xB4, *m 6
51 927 [main] test 5888 user_info::create: opening user shared for 'S-1-5-21-1150923390-1632126722-2651444992-1001' at 0x180020000
34 961 [main] test 5888 user_info::create: user shared version AB1FCCE8
80 1041 [main] test 5888 fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-5888-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
98 1139 [main] test 5888 fhandler_pipe::create: pipe read handle 0xCC
59 1198 [main] test 5888 fhandler_pipe::create: CreateFile: name \\.\pipe\cygwin-e022582115c10879-5888-sigwait
78 1276 [main] test 5888 fhandler_pipe::create: pipe write handle 0x44
38 1314 [main] test 5888 dll_crt0_0: finished dll_crt0_0 initialization
--- Process 5888 thread 7408 created
253 1567 [sig] test 5888 wait_sig: entering ReadFile loop, my_readsig 0xCC, my_sendsig 0x44
118 1685 [main] test 5888 time: 1487678069 = time(0x0)
78 1763 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64-test\home\Erik M. Bray, 0x0, no-add-slash)
54 1817 [main] test 5888 normalize_win32_path: C:\cygwin64-test\home\Erik M. Bray = normalize_win32_path (C:\cygwin64-test\home\Erik M. Bray)
28 1845 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/cygwin64-test/home/Erik M. Bray = conv_to_posix_path (C:\cygwin64-test\home\Erik M. Bray)
42 1887 [main] test 5888 sigprocmask: 0 = sigprocmask (0, 0x0, 0x600018130)
134 2021 [main] test 5888 _cygwin_istext_for_stdio: fd 0: not open
24 2045 [main] test 5888 _cygwin_istext_for_stdio: fd 1: not open
20 2065 [main] test 5888 _cygwin_istext_for_stdio: fd 2: not open
79 2144 [main] test (5888) open_shared: name cygpid.5888, n 5888, shared 0x180010000 (wanted 0x180010000), h 0xF4, *m 2
25 2169 [main] test (5888) time: 1487678069 = time(0x0)
33 2202 [main] test 5888 pinfo::thisproc: myself dwProcessId 5888
104 2306 [main] test 5888 environ_init: GetEnvironmentStrings returned 0x77FFE0
43 2349 [main] test 5888 environ_init: 0x6000284F0: ALLUSERSPROFILE=C:\ProgramData
38 2387 [main] test 5888 environ_init: 0x600028520: APPDATA=C:\Users\Erik M. Bray\AppData\Roaming
39 2426 [main] test 5888 environ_init: 0x600028560: COMMONPROGRAMFILES=C:\Program Files\Common Files
38 2464 [main] test 5888 environ_init: 0x6000285A0: COMPUTERNAME=NAVI-BRICK
38 2502 [main] test 5888 environ_init: 0x6000285C0: COMSPEC=C:\WINDOWS\system32\cmd.exe
38 2540 [main] test 5888 environ_init: 0x6000285F0: CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files
39 2579 [main] test 5888 environ_init: 0x600028640: CommonProgramW6432=C:\Program Files\Common Files
40 2619 [main] test 5888 parse_options: glob (called func)
37 2656 [main] test 5888 parse_options: returning
19 2675 [main] test 5888 environ_init: 0x600028680: CYGWIN=noglob
38 2713 [main] test 5888 environ_init: 0x6000286C0: DOCKER_TOOLBOX_INSTALL_PATH=C:\Program Files\Docker Toolbox
75 2788 [main] test 5888 environ_init: 0x600028710: EXECIGNORE=*.dll
41 2829 [main] test 5888 environ_init: 0x600028730: FPPUILang=en-US
38 2867 [main] test 5888 environ_init: 0x600028750: FPS_BROWSER_APP_PROFILE_STRING=Internet Explorer
37 2904 [main] test 5888 environ_init: 0x600028790: FPS_BROWSER_USER_PROFILE_STRING=Default
57 2961 [main] test 5888 environ_init: 0x6000287C0: FP_NO_HOST_CHECK=NO
39 3000 [main] test 5888 getwinenv: can't set native for HOME= since no environ yet
24 3024 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\Erik M. Bray\Home, 0x10000000, no-add-slash)
21 3045 [main] test 5888 normalize_win32_path: C:\Users\Erik M. Bray\Home = normalize_win32_path (C:\Users\Erik M. Bray\Home)
20 3065 [main] test 5888 mount_info::conv_to_posix_path: /home/embray = conv_to_posix_path (C:\Users\Erik M. Bray\Home)
56 3121 [main] test 5888 win_env::add_cache: posix /home/embray
20 3141 [main] test 5888 win_env::add_cache: native HOME=C:\Users\Erik M. Bray\Home
20 3161 [main] test 5888 posify_maybe: env var converted to HOME=/home/embray
64 3225 [main] test 5888 environ_init: 0x600028860: HOME=/home/embray
38 3263 [main] test 5888 environ_init: 0x6000287E0: HOMEDRIVE=C:
37 3300 [main] test 5888 environ_init: 0x600028880: HOMEPATH=\Users\Erik M. Bray
37 3337 [main] test 5888 environ_init: 0x6000288B0: HOSTNAME=NAVI-Brick
37 3374 [main] test 5888 environ_init: 0x6000288D0: INFOPATH=/usr/local/info:/usr/share/info:/usr/info
38 3412 [main] test 5888 environ_init: 0x600028910: LANG=en_US.UTF-8
37 3449 [main] test 5888 environ_init: 0x600028930: LESS=-Q
37 3486 [main] test 5888 environ_init: 0x600028950: LOCALAPPDATA=C:\Users\Erik M. Bray\AppData\Local
37 3523 [main] test 5888 environ_init: 0x600028990: LOGONSERVER=\\NAVI-BRICK
37 3560 [main] test 5888 environ_init: 0x6000289C0: LP_USER=erik-m-bray+ubuntu
37 3597 [main] test 5888 environ_init: 0x6000289F0: NUMBER_OF_PROCESSORS=8
37 3634 [main] test 5888 environ_init: 0x600028A10: OLDPWD=/home/embray
37 3671 [main] test 5888 environ_init: 0x600028A30: OOBEUILang=en-US
55 3726 [main] test 5888 environ_init: 0x600028A50: ORIGINAL_PATH=/cygdrive/c/Program Files/Docker/Docker/Resources/bin:/cygdrive/c/Program Files (x86)/Intel/iCLS Client:/cygdrive/c/Program Files/Intel/iCLS Client:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem:/cygdrive/c/WINDOWS/System32/WindowsPowerShell/v1.0:/cygdrive/c/Program Files (x86)/Hewlett-Packard/HP Performance Advisor:/cygdrive/c/Program Files (x86)/ATI Technologies/ATI.ACE/Core-Static:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files/Intel/WiFi/bin:/cygdrive/c/Program Files/Common Files/Intel/WirelessCommon:/cygdrive/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit:/cygdrive/c/Program Files/MiKTeX 2.9/miktex/bin/x64:/cygdrive/c/Program Files (x86)/Windows Kits/10/Windows Performance Toolkit:/cygdrive/c/Program Files (x86)/Windows Kits/10/Microsoft Application Virtualization/Sequencer:/cygdrive/c/HashiCorp/Vagrant/bin:/cygdrive/c/Program Files (x86)/HP/HP Performance Advisor:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Programs/Python/Launcher:/cygdrive/c/Program Files/Docker Toolbox:/cygdrive/c/Program Files (x86)/Microsoft Visual Studio 14.0/VC/bin:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Microsoft/WindowsApps
44 3770 [main] test 5888 environ_init: 0x600029030: OS=Windows_NT
37 3807 [main] test 5888 environ_init: 0x600029050: OneDrive=C:\Users\Erik M. Bray\OneDrive
37 3844 [main] test 5888 environ_init: 0x600029080: OnlineServices=Online Services
53 3897 [main] test 5888 getwinenv: can't set native for PATH= since no environ yet
43 3940 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\usr\local\bin, 0x10000100, no-add-slash)
21 3961 [main] test 5888 normalize_win32_path: C:\cygwin64\usr\local\bin = normalize_win32_path (C:\cygwin64\usr\local\bin)
21 3982 [main] test 5888 mount_info::conv_to_posix_path: /usr/local/bin = conv_to_posix_path (C:\cygwin64\usr\local\bin)
21 4003 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\bin, 0x10000100, no-add-slash)
20 4023 [main] test 5888 normalize_win32_path: C:\cygwin64\bin = normalize_win32_path (C:\cygwin64\bin)
20 4043 [main] test 5888 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin64\bin)
21 4064 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Docker\Docker\Resources\bin, 0x10000100, no-add-slash)
20 4084 [main] test 5888 normalize_win32_path: C:\Program Files\Docker\Docker\Resources\bin = normalize_win32_path (C:\Program Files\Docker\Docker\Resources\bin)
21 4105 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Docker/Docker/Resources/bin = conv_to_posix_path (C:\Program Files\Docker\Docker\Resources\bin)
21 4126 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Intel\iCLS Client, 0x10000100, no-add-slash)
20 4146 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Intel\iCLS Client = normalize_win32_path (C:\Program Files (x86)\Intel\iCLS Client)
21 4167 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Intel/iCLS Client = conv_to_posix_path (C:\Program Files (x86)\Intel\iCLS Client)
22 4189 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Intel\iCLS Client, 0x10000100, no-add-slash)
19 4208 [main] test 5888 normalize_win32_path: C:\Program Files\Intel\iCLS Client = normalize_win32_path (C:\Program Files\Intel\iCLS Client)
19 4227 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Intel/iCLS Client = conv_to_posix_path (C:\Program Files\Intel\iCLS Client)
20 4247 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\WINDOWS\system32, 0x10000100, no-add-slash)
20 4267 [main] test 5888 normalize_win32_path: C:\WINDOWS\system32 = normalize_win32_path (C:\WINDOWS\system32)
20 4287 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/WINDOWS/system32 = conv_to_posix_path (C:\WINDOWS\system32)
21 4308 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\WINDOWS, 0x10000100, no-add-slash)
19 4327 [main] test 5888 normalize_win32_path: C:\WINDOWS = normalize_win32_path (C:\WINDOWS)
21 4348 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/WINDOWS = conv_to_posix_path (C:\WINDOWS)
20 4368 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\WINDOWS\System32\Wbem, 0x10000100, no-add-slash)
20 4388 [main] test 5888 normalize_win32_path: C:\WINDOWS\System32\Wbem = normalize_win32_path (C:\WINDOWS\System32\Wbem)
21 4409 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/WINDOWS/System32/Wbem = conv_to_posix_path (C:\WINDOWS\System32\Wbem)
20 4429 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\WINDOWS\System32\WindowsPowerShell\v1.0, 0x10000100, no-add-slash)
22 4451 [main] test 5888 normalize_win32_path: C:\WINDOWS\System32\WindowsPowerShell\v1.0 = normalize_win32_path (C:\WINDOWS\System32\WindowsPowerShell\v1.0)
20 4471 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/WINDOWS/System32/WindowsPowerShell/v1.0 = conv_to_posix_path (C:\WINDOWS\System32\WindowsPowerShell\v1.0)
21 4492 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Hewlett-Packard\HP Performance Advisor, 0x10000100, no-add-slash)
22 4514 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Hewlett-Packard\HP Performance Advisor = normalize_win32_path (C:\Program Files (x86)\Hewlett-Packard\HP Performance Advisor)
21 4535 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Hewlett-Packard/HP Performance Advisor = conv_to_posix_path (C:\Program Files (x86)\Hewlett-Packard\HP Performance Advisor)
22 4557 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static, 0x10000100, no-add-slash)
20 4577 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static = normalize_win32_path (C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static)
21 4598 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/ATI Technologies/ATI.ACE/Core-Static = conv_to_posix_path (C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static)
21 4619 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Intel\Intel(R) Management Engine Components\DAL, 0x10000100, no-add-slash)
20 4639 [main] test 5888 normalize_win32_path: C:\Program Files\Intel\Intel(R) Management Engine Components\DAL = normalize_win32_path (C:\Program Files\Intel\Intel(R) Management Engine Components\DAL)
21 4660 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/DAL = conv_to_posix_path (C:\Program Files\Intel\Intel(R) Management Engine Components\DAL)
20 4680 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL, 0x10000100, no-add-slash)
21 4701 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL = normalize_win32_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL)
21 4722 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL = conv_to_posix_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL)
21 4743 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Intel\Intel(R) Management Engine Components\IPT, 0x10000100, no-add-slash)
20 4763 [main] test 5888 normalize_win32_path: C:\Program Files\Intel\Intel(R) Management Engine Components\IPT = normalize_win32_path (C:\Program Files\Intel\Intel(R) Management Engine Components\IPT)
21 4784 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/IPT = conv_to_posix_path (C:\Program Files\Intel\Intel(R) Management Engine Components\IPT)
20 4804 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT, 0x10000100, no-add-slash)
21 4825 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT = normalize_win32_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT)
20 4845 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/IPT = conv_to_posix_path (C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT)
21 4866 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Intel\WiFi\bin, 0x10000100, no-add-slash)
20 4886 [main] test 5888 normalize_win32_path: C:\Program Files\Intel\WiFi\bin = normalize_win32_path (C:\Program Files\Intel\WiFi\bin)
21 4907 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Intel/WiFi/bin = conv_to_posix_path (C:\Program Files\Intel\WiFi\bin)
21 4928 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Common Files\Intel\WirelessCommon, 0x10000100, no-add-slash)
45 4973 [main] test 5888 normalize_win32_path: C:\Program Files\Common Files\Intel\WirelessCommon = normalize_win32_path (C:\Program Files\Common Files\Intel\WirelessCommon)
25 4998 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Common Files/Intel/WirelessCommon = conv_to_posix_path (C:\Program Files\Common Files\Intel\WirelessCommon)
22 5020 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit, 0x10000100, no-add-slash)
20 5040 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit = normalize_win32_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit)
21 5061 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit = conv_to_posix_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit)
20 5081 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\MiKTeX 2.9\miktex\bin\x64, 0x10000100, no-add-slash)
21 5102 [main] test 5888 normalize_win32_path: C:\Program Files\MiKTeX 2.9\miktex\bin\x64 = normalize_win32_path (C:\Program Files\MiKTeX 2.9\miktex\bin\x64)
20 5122 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/MiKTeX 2.9/miktex/bin/x64 = conv_to_posix_path (C:\Program Files\MiKTeX 2.9\miktex\bin\x64)
21 5143 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit, 0x10000100, no-add-slash)
20 5163 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit = normalize_win32_path (C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit)
28 5191 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Windows Kits/10/Windows Performance Toolkit = conv_to_posix_path (C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit)
49 5240 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer, 0x10000100, no-add-slash)
46 5286 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer = normalize_win32_path (C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer)
40 5326 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Windows Kits/10/Microsoft Application Virtualization/Sequencer = conv_to_posix_path (C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer)
29 5355 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\HashiCorp\Vagrant\bin, 0x10000100, no-add-slash)
21 5376 [main] test 5888 normalize_win32_path: C:\HashiCorp\Vagrant\bin = normalize_win32_path (C:\HashiCorp\Vagrant\bin)
21 5397 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/HashiCorp/Vagrant/bin = conv_to_posix_path (C:\HashiCorp\Vagrant\bin)
20 5417 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\HP\HP Performance Advisor, 0x10000100, no-add-slash)
21 5438 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\HP\HP Performance Advisor = normalize_win32_path (C:\Program Files (x86)\HP\HP Performance Advisor)
20 5458 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/HP/HP Performance Advisor = conv_to_posix_path (C:\Program Files (x86)\HP\HP Performance Advisor)
21 5479 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\Erik M. Bray\AppData\Local\Programs\Python\Launcher, 0x10000100, no-add-slash)
21 5500 [main] test 5888 normalize_win32_path: C:\Users\Erik M. Bray\AppData\Local\Programs\Python\Launcher = normalize_win32_path (C:\Users\Erik M. Bray\AppData\Local\Programs\Python\Launcher)
22 5522 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Users/Erik M. Bray/AppData/Local/Programs/Python/Launcher = conv_to_posix_path (C:\Users\Erik M. Bray\AppData\Local\Programs\Python\Launcher)
22 5544 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Docker Toolbox, 0x10000100, no-add-slash)
21 5565 [main] test 5888 normalize_win32_path: C:\Program Files\Docker Toolbox = normalize_win32_path (C:\Program Files\Docker Toolbox)
21 5586 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Docker Toolbox = conv_to_posix_path (C:\Program Files\Docker Toolbox)
21 5607 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Microsoft Visual Studio 14.0\VC\bin, 0x10000100, no-add-slash)
21 5628 [main] test 5888 normalize_win32_path: C:\Program Files (x86)\Microsoft Visual Studio 14.0\VC\bin = normalize_win32_path (C:\Program Files (x86)\Microsoft Visual Studio 14.0\VC\bin)
20 5648 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Microsoft Visual Studio 14.0/VC/bin = conv_to_posix_path (C:\Program Files (x86)\Microsoft Visual Studio 14.0\VC\bin)
21 5669 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\Erik M. Bray\AppData\Local\Microsoft\WindowsApps, 0x10000100, no-add-slash)
21 5690 [main] test 5888 normalize_win32_path: C:\Users\Erik M. Bray\AppData\Local\Microsoft\WindowsApps = normalize_win32_path (C:\Users\Erik M. Bray\AppData\Local\Microsoft\WindowsApps)
18 5708 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/Users/Erik M. Bray/AppData/Local/Microsoft/WindowsApps = conv_to_posix_path (C:\Users\Erik M. Bray\AppData\Local\Microsoft\WindowsApps)
21 5729 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\lib\lapack, 0x10000100, no-add-slash)
21 5750 [main] test 5888 normalize_win32_path: C:\cygwin64\lib\lapack = normalize_win32_path (C:\cygwin64\lib\lapack)
25 5775 [main] test 5888 mount_info::conv_to_posix_path: /usr/lib/lapack = conv_to_posix_path (C:\cygwin64\lib\lapack)
75 5850 [main] test 5888 win_env::add_cache: posix /usr/local/bin:/usr/bin:/cygdrive/c/Program Files/Docker/Docker/Resources/bin:/cygdrive/c/Program Files (x86)/Intel/iCLS Client:/cygdrive/c/Program Files/Intel/iCLS Client:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem:/cygdrive/c/WINDOWS/System32/WindowsPowerShell/v1.0:/cygdrive/c/Program Files (x86)/Hewlett-Packard/HP Performance Advisor:/cygdrive/c/Program Files (x86)/ATI Technologies/ATI.ACE/Core-Static:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files/Intel/WiFi/bin:/cygdrive/c/Program Files/Common Files/Intel/WirelessCommon:/cygdrive/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit:/cygdrive/c/Program Files/MiKTeX 2.9/miktex/bin/x64:/cygdrive/c/Program Files (x86)/Windows Kits/10/Windows Performance Toolkit:/cygdrive/c/Program Files (x86)/Windows Kits/10/Microsoft Application Virtualization/Sequencer:/cygdrive/c/HashiCorp/Vagrant/bin:/cygdrive/c/Program Files (x86)/HP/HP Performance Advisor:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Programs/Python/Launcher:/cygdrive/c/Program Files/Docker Toolbox:/cygdrive/c/Program Files (x86)/Microsoft Visual Studio 14.0/VC/bin:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Microsoft/WindowsApps:/usr/lib/lapack
31 5881 [main] test 5888 win_env::add_cache: native PATH=C:\cygwin64\usr\local\bin;C:\cygwin64\bin;C:\Program Files\Docker\Docker\Resources\bin;C:\Program Files (x86)\Intel\iCLS Client;C:\Program Files\Intel\iCLS Client;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0;C:\Program Files (x86)\Hewlett-Packard\HP Performance Advisor;C:\Program Files (x86)\ATI Technologies\ATI.ACE\Core-Static;C:\Program Files\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\DAL;C:\Program Files\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files (x86)\Intel\Intel(R) Management Engine Components\IPT;C:\Program Files\Intel\WiFi\bin;C:\Program Files\Common Files\Intel\WirelessCommon;C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit;C:\Program Files\MiKTeX 2.9\miktex\bin\x64;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit;C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer;C:\HashiCorp\Vagrant\bin;C:\Program Files (x86)\HP\HP Performance Advisor;C:\Users\Erik M. Bray\AppData\Local\Programs\Python\Launcher;C:\Program Files\Docker Toolbox;C:\Program Files (x86)\Microsoft Visual Studio 14.0\VC\bin;C:\Users\Erik M. Bray\AppData\Local\Microsoft\WindowsApps;C:\cygwin64\lib\lapack
27 5908 [main] test 5888 posify_maybe: env var converted to PATH=/usr/local/bin:/usr/bin:/cygdrive/c/Program Files/Docker/Docker/Resources/bin:/cygdrive/c/Program Files (x86)/Intel/iCLS Client:/cygdrive/c/Program Files/Intel/iCLS Client:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem:/cygdrive/c/WINDOWS/System32/WindowsPowerShell/v1.0:/cygdrive/c/Program Files (x86)/Hewlett-Packard/HP Performance Advisor:/cygdrive/c/Program Files (x86)/ATI Technologies/ATI.ACE/Core-Static:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files/Intel/WiFi/bin:/cygdrive/c/Program Files/Common Files/Intel/WirelessCommon:/cygdrive/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit:/cygdrive/c/Program Files/MiKTeX 2.9/miktex/bin/x64:/cygdrive/c/Program Files (x86)/Windows Kits/10/Windows Performance Toolkit:/cygdrive/c/Program Files (x86)/Windows Kits/10/Microsoft Application Virtualization/Sequencer:/cygdrive/c/HashiCorp/Vagrant/bin:/cygdrive/c/Program Files (x86)/HP/HP Performance Advisor:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Programs/Python/Launcher:/cygdrive/c/Program Files/Docker Toolbox:/cygdrive/c/Program Files (x86)/Microsoft Visual Studio 14.0/VC/bin:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Microsoft/WindowsApps:/usr/lib/lapack
80 5988 [main] test 5888 environ_init: 0x60003A110: PATH=/usr/local/bin:/usr/bin:/cygdrive/c/Program Files/Docker/Docker/Resources/bin:/cygdrive/c/Program Files (x86)/Intel/iCLS Client:/cygdrive/c/Program Files/Intel/iCLS Client:/cygdrive/c/WINDOWS/system32:/cygdrive/c/WINDOWS:/cygdrive/c/WINDOWS/System32/Wbem:/cygdrive/c/WINDOWS/System32/WindowsPowerShell/v1.0:/cygdrive/c/Program Files (x86)/Hewlett-Packard/HP Performance Advisor:/cygdrive/c/Program Files (x86)/ATI Technologies/ATI.ACE/Core-Static:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/DAL:/cygdrive/c/Program Files/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files (x86)/Intel/Intel(R) Management Engine Components/IPT:/cygdrive/c/Program Files/Intel/WiFi/bin:/cygdrive/c/Program Files/Common Files/Intel/WirelessCommon:/cygdrive/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit:/cygdrive/c/Program Files/MiKTeX 2.9/miktex/bin/x64:/cygdrive/c/Program Files (x86)/Windows Kits/10/Windows Performance Toolkit:/cygdrive/c/Program Files (x86)/Windows Kits/10/Microsoft Application Virtualization/Sequencer:/cygdrive/c/HashiCorp/Vagrant/bin:/cygdrive/c/Program Files (x86)/HP/HP Performance Advisor:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Programs/Python/Launcher:/cygdrive/c/Program Files/Docker Toolbox:/cygdrive/c/Program Files (x86)/Microsoft Visual Studio 14.0/VC/bin:/cygdrive/c/Users/Erik M. Bray/AppData/Local/Microsoft/WindowsApps:/usr/lib/lapack
71 6059 [main] test 5888 environ_init: 0x6000290B0: PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
48 6107 [main] test 5888 environ_init: 0x600029100: PRINTER=Sharp MX-3114N
39 6146 [main] test 5888 environ_init: 0x600029120: PROCESSOR_ARCHITECTURE=AMD64
40 6186 [main] test 5888 environ_init: 0x600029150: PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 60 Stepping 3, GenuineIntel
38 6224 [main] test 5888 environ_init: 0x6000291A0: PROCESSOR_LEVEL=6
38 6262 [main] test 5888 environ_init: 0x6000291C0: PROCESSOR_REVISION=3c03
38 6300 [main] test 5888 environ_init: 0x6000291E0: PROFILEREAD=true
37 6337 [main] test 5888 environ_init: 0x600029200: PROGRAMFILES=C:\Program Files
38 6375 [main] test 5888 environ_init: 0x600029230: PS1=\[\e]0;\w\a\]\n\[\e[32m\]\u@\h \[\e[33m\]\w\[\e[0m\]\n\$
42 6417 [main] test 5888 environ_init: 0x600029280: PSModulePath=C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\;C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer\AppvPkgConverter;C:\Program Files (x86)\Windows Kits\10\Microsoft Application Virtualization\Sequencer\AppvSequencer
39 6456 [main] test 5888 environ_init: 0x6000293A0: PTSMINSTALLPATH_X86=C:\Program Files (x86)\Hewlett-Packard\HP ProtectTools Security Manager\
37 6493 [main] test 5888 environ_init: 0x600029410: PUBLIC=C:\Users\Public
38 6531 [main] test 5888 environ_init: 0x600029430: PWD=/cygdrive/c/cygwin64-test/home/Erik M. Bray
38 6569 [main] test 5888 environ_init: 0x600029470: ProgramData=C:\ProgramData
38 6607 [main] test 5888 environ_init: 0x6000294A0: ProgramFiles(x86)=C:\Program Files (x86)
38 6645 [main] test 5888 environ_init: 0x6000294E0: ProgramW6432=C:\Program Files
51 6696 [main] test 5888 environ_init: 0x600029510: RegionCode=EMEA
48 6744 [main] test 5888 environ_init: 0x600029530: SESSIONNAME=Console
36 6780 [main] test 5888 environ_init: 0x600029550: SHELL=/bin/bash
37 6817 [main] test 5888 environ_init: 0x600029570: SHLVL=1
38 6855 [main] test 5888 environ_init: 0x600029590: SSH_AGENT_PID=11280
37 6892 [main] test 5888 environ_init: 0x60003A710: SSH_AUTH_SOCK=/tmp/ssh-FeqxqetmO32v/agent.8372
38 6930 [main] test 5888 environ_init: 0x6000295B0: SYSTEMDRIVE=C:
38 6968 [main] test 5888 environ_init: 0x60003A750: SYSTEMROOT=C:\WINDOWS
37 7005 [main] test 5888 getwinenv: can't set native for TEMP= since no environ yet
21 7026 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\tmp, 0x10000000, no-add-slash)
20 7046 [main] test 5888 normalize_win32_path: C:\cygwin64\tmp = normalize_win32_path (C:\cygwin64\tmp)
21 7067 [main] test 5888 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (C:\cygwin64\tmp)
54 7121 [main] test 5888 win_env::add_cache: posix /tmp
20 7141 [main] test 5888 win_env::add_cache: native TEMP=C:\cygwin64\tmp
20 7161 [main] test 5888 posify_maybe: env var converted to TEMP=/tmp
73 7234 [main] test 5888 environ_init: 0x60003A7D0: TEMP=/tmp
40 7274 [main] test 5888 environ_init: 0x60003A770: TERM=xterm-256color
38 7312 [main] test 5888 getwinenv: can't set native for TMP= since no environ yet
21 7333 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\tmp, 0x10000000, no-add-slash)
21 7354 [main] test 5888 normalize_win32_path: C:\cygwin64\tmp = normalize_win32_path (C:\cygwin64\tmp)
21 7375 [main] test 5888 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (C:\cygwin64\tmp)
55 7430 [main] test 5888 win_env::add_cache: posix /tmp
20 7450 [main] test 5888 win_env::add_cache: native TMP=C:\cygwin64\tmp
20 7470 [main] test 5888 posify_maybe: env var converted to TMP=/tmp
54 7524 [main] test 5888 environ_init: 0x60003A850: TMP=/tmp
38 7562 [main] test 5888 environ_init: 0x60003A7F0: TZ=Europe/Paris
79 7641 [main] test 5888 environ_init: 0x60003A870: UOIPME_REG_PATH=C:\Program Files\Intel Corporation\USB over IP
43 7684 [main] test 5888 environ_init: 0x60003A8C0: USER=Erik M. Bray
38 7722 [main] test 5888 environ_init: 0x60003A8E0: USERDOMAIN=NAVI-BRICK
38 7760 [main] test 5888 environ_init: 0x60003A900: USERDOMAIN_ROAMINGPROFILE=NAVI-BRICK
37 7797 [main] test 5888 environ_init: 0x60003A930: USERNAME=Erik M. Bray
37 7834 [main] test 5888 environ_init: 0x60003A950: USERPROFILE=C:\Users\Erik M. Bray
38 7872 [main] test 5888 environ_init: 0x60003A980: VBOX_MSI_INSTALL_PATH=C:\Program Files\Oracle\VirtualBox\
37 7909 [main] test 5888 environ_init: 0x60003A9D0: VIRTUALENVWRAPPER_HOOK_DIR=/home/embray/.virtualenvs
38 7947 [main] test 5888 environ_init: 0x60003AA10: VIRTUALENVWRAPPER_PROJECT_FILENAME=.project
37 7984 [main] test 5888 environ_init: 0x60003AA50: VIRTUALENVWRAPPER_SCRIPT=/usr/bin/virtualenvwrapper.sh
37 8021 [main] test 5888 environ_init: 0x60003AA90: VIRTUALENVWRAPPER_WORKON_CD=1
38 8059 [main] test 5888 environ_init: 0x60003AAC0: VS140COMNTOOLS=C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\Tools\
38 8097 [main] test 5888 environ_init: 0x60003AB20: WINDIR=C:\WINDOWS
38 8135 [main] test 5888 environ_init: 0x60003AB40: WORKON_HOME=/home/embray/.virtualenvs
44 8179 [main] test 5888 environ_init: 0x60003AB70: _=/usr/bin/strace
49 8228 [main] test 5888 environ_init: 0x60003AB90: platformcode=TA
39 8267 [main] test 5888 environ_init: 0x60003ABB0: windows_tracing_flags=3
38 8305 [main] test 5888 environ_init: 0x60003ABD0: windows_tracing_logfile=C:\BVTBin\Tests\installpackage\csilogfile.log
26 8331 [main] test 5888 pinfo_init: Set nice to 0
20 8351 [main] test 5888 pinfo_init: pid 5888, pgid 5888, process_state 0x41
20 8371 [main] test 5888 App version: 2006.0, api: 0.304
21 8392 [main] test 5888 DLL version: 2006.0, api: 0.304
19 8411 [main] test 5888 DLL build: 2016-08-31 14:32
25 8436 [main] test 5888 dtable::extend: size 32, fds 0x180308E90
102 8538 [main] test 5888 __get_lcid_from_locale: LCID=0x0409
281 8819 [main] test 5888 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-e022582115c10879-lpc
46 8865 [main] test 5888 transport_layer_pipes::connect: Error opening the pipe (2)
39 8904 [main] test 5888 client_request::make_request: cygserver un-available
--- Process 5888 loaded C:\Windows\System32\advapi32.dll at 00007FF992380000
--- Process 5888 loaded C:\Windows\System32\msvcrt.dll at 00007FF992090000
--- Process 5888 loaded C:\Windows\System32\sechost.dll at 00007FF9916A0000
--- Process 5888 loaded C:\Windows\System32\rpcrt4.dll at 00007FF991C40000
--- Process 5888 thread 7392 created
--- Process 5888 loaded C:\Windows\System32\netapi32.dll at 00007FF986640000
--- Process 5888 loaded C:\Windows\System32\samcli.dll at 00007FF985E80000
--- Process 5888 loaded C:\Windows\System32\ucrtbase.dll at 00007FF98FBD0000
--- Process 5888 loaded C:\Windows\System32\samlib.dll at 00007FF98C220000
--- Process 5888 loaded C:\Windows\System32\netutils.dll at 00007FF98E2A0000
5637 14541 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Erik M. Bray:S-1-5-21-1150923390-1632126722-2651444992-1001:197609:>
438 14979 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Medium Mandatory Level:S-1-16-8192:401408:>
562 15541 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Device Administrators:S-1-5-21-1150923390-1632126722-2651444992-1000:197608:>
355 15896 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Hyper-V Administrators:S-1-5-32-578:578:>
352 16248 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Performance Log Users:S-1-5-32-559:559:>
337 16585 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Users:S-1-5-32-545:545:>
35 16620 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <INTERACTIVE:S-1-5-4:4:>
32 16652 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <CONSOLE LOGON:S-1-2-1:66049:>
43 16695 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Authenticated Users:S-1-5-11:11:>
42 16737 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <This Organization:S-1-5-15:15:>
35 16772 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <MicrosoftAccount+erik.m.bray@gmail.com:S-1-11-96-3623454863-58364-18864-2661722203-1597581903-2950428236-2770348138-2877493263-2799120648-38302705:68593:>
44 16816 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Local account:S-1-5-113:113:>
60 16876 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <LOCAL:S-1-2-0:66048:>
62 16938 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Cloud Account Authentication:S-1-5-64-36:262180:>
562 17500 [main] test 5888 pwdgrp::fetch_account_from_windows: NetLocalGroupGetInfo(None) 1376
39 17539 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <None:S-1-5-21-1150923390-1632126722-2651444992-513:197121:>
55 17594 [main] test 5888 cygheap_user::ontherange: what 2, pw 0x180309160
37 17631 [main] test 5888 cygheap_user::ontherange: HOME is already in the environment /home/embray
111 17742 [main] test 5888 build_argv: argv[0] = 'C:\cygwin64-test\home\Erik M. Bray\test.exe'
29 17771 [main] test 5888 build_argv: argc 1
65 17836 [main] test 5888 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64-test\home\Erik M. Bray\test.exe, 0x10000100, no-add-slash)
29 17865 [main] test 5888 normalize_win32_path: C:\cygwin64-test\home\Erik M. Bray\test.exe = normalize_win32_path (C:\cygwin64-test\home\Erik M. Bray\test.exe)
31 17896 [main] test 5888 mount_info::conv_to_posix_path: /cygdrive/c/cygwin64-test/home/Erik M. Bray/test.exe = conv_to_posix_path (C:\cygwin64-test\home\Erik M. Bray\test.exe)
181 18077 [main] test 5888 build_fh_pc: created an archetype (0x18030B3A0) for /dev/pty5(136/5)
51 18128 [main] test 5888 build_fh_pc: fh 0x18030B030, dev 00880005
69 18197 [main] test 5888 fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-pty5-from-master, size 131072, mode PIPE_TYPE_MESSAGE
75 18272 [main] test 5888 fhandler_pipe::create: pipe busy
31 18303 [main] test 5888 tty::exists: exists 1
82 18385 [main] test 5888 set_posix_access: ACL-Size: 124
64 18449 [main] test 5888 set_posix_access: Created SD-Size: 200
29 18478 [main] test 5888 fhandler_pty_slave::open: (393): pty output_mutex (0x12C): waiting -1 ms
32 18510 [main] test 5888 fhandler_pty_slave::open: (393): pty output_mutex: acquired
36 18546 [main] test 5888 tty::create_inuse: cygtty.slave_alive.5 0x138
31 18577 [main] test 5888 fhandler_pty_slave::open: (396): pty output_mutex(0x12C) released
71 18648 [main] test 5888 open_shared: name cygpid.16064, n 16064, shared 0x20000 (wanted 0x0), h 0x13C, *m 6
44 18692 [main] test 5888 fhandler_pty_slave::open: dup handles directly since I'm the owner
49 18741 [main] test 5888 fhandler_pty_slave::open: duplicated from_master 0x370->0x13C from pty_owner
30 18771 [main] test 5888 fhandler_pty_slave::open: duplicated to_master 0x37C->0x144 from pty_owner
29 18800 [main] test 5888 fhandler_pty_slave::open: duplicated to_master_cyg 0x384->0x148 from pty_owner
79 18879 [main] test 5888 fhandler_console::need_invisible: invisible_console 0
42 18921 [main] test 5888 fhandler_base::open_with_arch: line 473: /dev/pty5<0x18030B3A0> usecount + 1 = 1
36 18957 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
29 18986 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
29 19015 [main] test 5888 fhandler_base::set_flags: filemode set to binary
28 19043 [main] test 5888 _pinfo::set_ctty: old no ctty, ctty device number 0xFFFFFFFF, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
29 19072 [main] test 5888 _pinfo::set_ctty: cygheap->ctty 0x0, archetype 0x18030B3A0
49 19121 [main] test 5888 _pinfo::set_ctty: ctty was NULL
61 19182 [main] test 5888 _pinfo::set_ctty: line 479: /dev/pty5<0x18030B3A0> usecount + 1 = 2
38 19220 [main] test 5888 _pinfo::set_ctty: /dev/pty5 ctty, usecount 2
54 19274 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 5888, pid 5888, pgid 5888, tty->pgid 8416, tty->sid 15016
36 19310 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
30 19340 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 2
32 19372 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
28 19400 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
29 19429 [main] test 5888 fhandler_base::set_flags: filemode set to binary
29 19458 [main] test 5888 _pinfo::set_ctty: old ctty /dev/pty5, ctty device number 0x880005, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
31 19489 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 15016, pid 5888, pgid 8416, tty->pgid 8416, tty->sid 15016
29 19518 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
29 19547 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 2
80 19627 [main] test 5888 build_fh_pc: found an archetype for (null)(136/5) io_handle 0x13C
55 19682 [main] test 5888 build_fh_pc: fh 0x18030B780, dev 00880005
42 19724 [main] test 5888 fhandler_base::open_with_arch: line 493: /dev/pty5<0x18030B3A0> usecount + 1 = 3
31 19755 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
28 19783 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
29 19812 [main] test 5888 fhandler_base::set_flags: filemode set to binary
29 19841 [main] test 5888 _pinfo::set_ctty: old ctty /dev/pty5, ctty device number 0x880005, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
30 19871 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 15016, pid 5888, pgid 8416, tty->pgid 8416, tty->sid 15016
31 19902 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
28 19930 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 3
31 19961 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
28 19989 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
28 20017 [main] test 5888 fhandler_base::set_flags: filemode set to binary
29 20046 [main] test 5888 _pinfo::set_ctty: old ctty /dev/pty5, ctty device number 0x880005, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
30 20076 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 15016, pid 5888, pgid 8416, tty->pgid 8416, tty->sid 15016
30 20106 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
28 20134 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 3
82 20216 [main] test 5888 build_fh_pc: found an archetype for (null)(136/5) io_handle 0x13C
51 20267 [main] test 5888 build_fh_pc: fh 0x18030BAF0, dev 00880005
60 20327 [main] test 5888 fhandler_base::open_with_arch: line 493: /dev/pty5<0x18030B3A0> usecount + 1 = 4
36 20363 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
30 20393 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
29 20422 [main] test 5888 fhandler_base::set_flags: filemode set to binary
29 20451 [main] test 5888 _pinfo::set_ctty: old ctty /dev/pty5, ctty device number 0x880005, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
31 20482 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 15016, pid 5888, pgid 8416, tty->pgid 8416, tty->sid 15016
29 20511 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
29 20540 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 4
32 20572 [main] test 5888 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
28 20600 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
28 20628 [main] test 5888 fhandler_base::set_flags: filemode set to binary
29 20657 [main] test 5888 _pinfo::set_ctty: old ctty /dev/pty5, ctty device number 0x880005, tc.ntty device number 0x880005 flags & O_NOCTTY 0x0
39 20696 [main] test 5888 _pinfo::set_ctty: attaching ctty /dev/pty5 sid 15016, pid 5888, pgid 8416, tty->pgid 8416, tty->sid 15016
36 20732 [main] test 5888 _pinfo::set_ctty: cygheap->ctty now 0x18030B3A0, archetype 0x18030B3A0
45 20777 [main] test 5888 fhandler_pty_slave::open_setup: /dev/pty5 opened, usecount 4
118 20895 [main] test 5888 __set_errno: void dll_crt0_1(void*):979 setting errno 0
589 21484 [main] test 5888 open: open(/dev/null, 0x1)
47 21531 [main] test 5888 normalize_posix_path: src /dev/null
41 21572 [main] test 5888 normalize_posix_path: /dev/null = normalize_posix_path (/dev/null)
42 21614 [main] test 5888 mount_info::conv_to_win32_path: conv_to_win32_path (/dev/null)
22 21636 [main] test 5888 mount_info::conv_to_win32_path: src_path /dev/null, dst \Device\Null, flags 0x2, rc 0
38 21674 [main] test 5888 build_fh_pc: fh 0x18030BEA0, dev 00010003
25 21699 [main] test 5888 fhandler_base::open: (\Device\Null, 0x8001)
29 21728 [main] test 5888 fhandler_base::set_flags: flags 0x8001, supplied_bin 0x10000
22 21750 [main] test 5888 fhandler_base::set_flags: filemode set to binary
22 21772 [main] test 5888 fhandler_base::open: 0x0 = NtCreateFile (0x150, 0x40120080, \Device\Null, io, NULL, 0x0, 0x7, 0x1, 0x4020, NULL, 0)
22 21794 [main] test 5888 fhandler_base::open: 1 = fhandler_base::open(\Device\Null, 0x8001)
21 21815 [main] test 5888 open: 3 = open(/dev/null, 0x8001)
30 21845 [main] test 5888 child_info::child_info: subproc_ready 0x154
26 21871 [main] test 5888 fork: entering
323 22194 [main] test 5888 sig_send: sendsig 0x44, pid 5888, signal -72, its_me 1
23 22217 [main] test 5888 sig_send: wakeup 0x16C
26 22243 [main] test 5888 sig_send: Waiting for pack.wakeup 0x16C
34 22277 [sig] test 5888 wait_sig: signalling pack.wakeup 0x16C
34 22311 [main] test 5888 sig_send: returning 0x0 from sending signal -72
33 22344 [main] test 5888 frok::parent: priority class 32
93 22437 [main] test 5888 frok::parent: stack - bottom 0x100000000, top 0xFFFFC950, addr 0xFFE00000, guardsize 0x3000
26 22463 [main] test 5888 frok::parent: CreateProcessW (C:\cygwin64-test\home\Erik M. Bray\test.exe, C:\cygwin64-test\home\Erik M. Bray\test.exe, 0, 0, 1, 0x420, 0, 0, 0xFFFFC890, 0xFFFFC830)
1559 24022 [main] test 5888 frok::parent: forked pid 16648
49 24071 [main] test 5888 child_info::sync: n 2, waiting for subproc_ready(0x154) and child process(0x174)
--- Process 16648 created
--- Process 16648 loaded C:\Windows\System32\ntdll.dll at 00007FF992A20000
--- Process 16648 loaded C:\Windows\System32\kernel32.dll at 00007FF991B80000
--- Process 16648 loaded C:\Windows\System32\KernelBase.dll at 00007FF98F940000
--- Process 16648 thread 10440 created
--- Process 16648 loaded C:\cygwin64\bin\cygwin1.dll at 0000000180040000
1 1 [main] test (16648) **********************************************
58 59 [main] test (16648) Program name: C:\cygwin64-test\home\Erik M. Bray\test.exe (windows pid 16648)
31 90 [main] test (16648) OS version: Windows NT-10.0
21 111 [main] test (16648) **********************************************
74 185 [main] test (16648) sigprocmask: 0 = sigprocmask (0, 0x0, 0x1802E2BB0)
156 341 [main] test 16648 child_copy: cygheap - hp 0x158 low 0x180302408, high 0x18030C110, res 1
25 366 [main] test 16648 child_copy: done
69 435 [main] test 16648 open_shared: name shared.5, n 5, shared 0x180030000 (wanted 0x180030000), h 0xAC, *m 6
34 469 [main] test 16648 user_heap_info::init: heap base 0x600000000, heap top 0x600050000, heap size 0x20000000 (536870912)
34 503 [main] test 16648 open_shared: name (null), n 1, shared 0x180020000 (wanted 0x180020000), h 0xB4, *m 6
27 530 [main] test 16648 user_info::create: opening user shared for '' at 0x180020000
23 553 [main] test 16648 user_info::create: user shared version AB1FCCE8
49 602 [main] test (16648) open_shared: name cygpid.16648, n 16648, shared 0x180010000 (wanted 0x180010000), h 0xB8, *m 2
47 649 [main] test (16648) time: 1487678069 = time(0x0)
27 676 [main] test 16648 pinfo::thisproc: myself dwProcessId 16648
69 745 [main] test 16648 child_copy: dll data - hp 0x158 low 0x1801F2000, high 0x1801FE130, res 1
195 940 [main] test 16648 child_copy: dll bss - hp 0x158 low 0x18029C000, high 0x1802E54F0, res 1
190 1130 [main] test 16648 child_copy: user heap - hp 0x158 low 0x600000000, high 0x600050000, res 1
23 1153 [main] test 16648 child_copy: done
28 1181 [main] test 16648 child_copy: data - hp 0x158 low 0x100402000, high 0x100402068, res 1
27 1208 [main] test 16648 child_copy: bss - hp 0x158 low 0x100407000, high 0x1004071C0, res 1
21 1229 [main] test 16648 child_copy: done
22 1251 [main] test 16648 fixup_mmaps_after_fork: succeeded
37 1288 [main] test 16648 fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-16648-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
68 1356 [main] test 16648 fhandler_pipe::create: pipe read handle 0xC8
22 1378 [main] test 16648 fhandler_pipe::create: CreateFile: name \\.\pipe\cygwin-e022582115c10879-16648-sigwait
51 1429 [main] test 16648 fhandler_pipe::create: pipe write handle 0xCC
30 1459 [main] test 16648 dll_crt0_0: finished dll_crt0_0 initialization
--- Process 16648 thread 15460 created
191 1650 [sig] test 16648 wait_sig: entering ReadFile loop, my_readsig 0xC8, my_sendsig 0xCC
99 1749 [main] test 16648 sync_with_parent: signalling parent: after longjmp
44 1793 [main] test 16648 child_info::ready: signalled 0x154 that I was ready
4397 28468 [main] test 5888 child_info::sync: pid 16648, WFMO returned 0, exit_code 0x103, res 1
50 28518 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x20000 (wanted 0x0), h 0x188, *m 6
67 28585 [main] test 5888 time: 1487678069 = time(0x0)
31 28616 [main] test 5888 proc_subproc: args: 1, -14256
--- Process 5888 thread 17180 created
164 28780 [main] test 5888 pinfo::wait: created tracking thread for pid 16648, winpid 0x4108, rd_proc_pipe 0x3CC
36 28816 [main] test 5888 proc_subproc: added pid 16648 to proc table, slot 0
34 28850 [main] test 5888 proc_subproc: returning 1
24 28874 [main] test 5888 frok::parent: child is alive (but stopped)
32 28906 [main] test 5888 child_copy: stack - hp 0x174 low 0xFFFFC950, high 0x100000000, res 1
27 28933 [main] test 5888 child_copy: done
27 28960 [main] test 5888 resume_child: signalled child
503 2296 [main] test 16648 sync_with_parent: awake
34 28994 [waitproc] test 5888 cygthread::stub: thread 'waitproc', id 0x431C, stack_ptr 0x106CCD0
33 2329 [main] test 16648 sync_with_parent: no problems
40 29034 [main] test 5888 child_info::sync: n 2, waiting for subproc_ready(0x154) and child process(0x174)
42 2371 [main] test 16648 frok::child: child is running. pid 16648, ppid 5888, stack here 0xFFFFC928
31 2402 [main] test 16648 frok::child: hParent 0x158, load_dlls 0
26 2428 [main] test 16648 dtable::fixup_after_fork: fd 0 (/dev/pty5)
25 2453 [main] test 16648 fhandler_pty_slave::fixup_after_fork: /dev/pty5 inherited, usecount 4
22 2475 [main] test 16648 dtable::fixup_after_fork: fd 1 (/dev/pty5)
22 2497 [main] test 16648 fhandler_pty_slave::fixup_after_fork: /dev/pty5 inherited, usecount 4
22 2519 [main] test 16648 dtable::fixup_after_fork: fd 2 (/dev/pty5)
19 2538 [main] test 16648 fhandler_pty_slave::fixup_after_fork: /dev/pty5 inherited, usecount 4
23 2561 [main] test 16648 sync_with_parent: signalling parent: performed fork fixup
24 2585 [main] test 16648 child_info::ready: signalled 0x154 that I was ready
223 29257 [main] test 5888 child_info::sync: pid 16648, WFMO returned 0, exit_code 0x103, res 1
28 29285 [main] test 5888 sig_send: sendsig 0x44, pid 5888, signal -73, its_me 1
37 29322 [main] test 5888 sig_send: wakeup 0x178
35 29357 [main] test 5888 sig_send: Waiting for pack.wakeup 0x178
31 29388 [sig] test 5888 wait_sig: signalling pack.wakeup 0x178
40 29428 [main] test 5888 sig_send: returning 0x0 from sending signal -73
213 29641 [main] test 5888 fork: 16648 = fork()
475 3060 [main] test 16648 fork: 0 = fork()
36 3096 [main] test 16648 dtable::dup3: dup3 (3, 1, 0x800)
132 29773 [main] test 5888 time: 1487678069 = time(0x0)
42 3138 [main] test 16648 fhandler_base::dup: in fhandler_base dup
30 3168 [main] test 16648 fhandler_base::set_close_on_exec: set close_on_exec for /dev/null to 0
31 3199 [main] test 16648 dtable::dup_worker: duped '/dev/null' old 0x150, new 0x120
30 3229 [main] test 16648 dtable::dup3: newfh->io_handle 0x120, oldfh->io_handle 0x150, new win32_name 0x18030C340, old win32_name 0x18030B000
33 3262 [main] test 16648 close: close(1)
32 3294 [main] test 16648 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 3
28 3322 [main] test 16648 fhandler_base::close_with_arch: not closing archetype
28 3350 [main] test 16648 close: 0 = close(1)
31 3381 [main] test 16648 dtable::dup3: 1 = dup3(3, 1, 0x0)
27 3408 [main] test 16648 dup2: 1 = dup2(3, 1)
31 3439 [main] test 16648 spawnve: spawnve (/usr/bin/yes, /usr/bin/yes, 0x6000281A0)
31 3470 [main] test 16648 child_info_spawn::worker: mode = 3, prog_arg = /usr/bin/yes
31 3501 [main] test 16648 perhaps_suffix: prog '/usr/bin/yes'
33 3534 [main] test 16648 normalize_posix_path: src /usr/bin/yes
31 3565 [main] test 16648 normalize_posix_path: /usr/bin/yes = normalize_posix_path (/usr/bin/yes)
28 3593 [main] test 16648 mount_info::conv_to_win32_path: conv_to_win32_path (/usr/bin/yes)
39 3632 [main] test 16648 set_flags: flags: binary (0x2)
32 3664 [main] test 16648 mount_info::conv_to_win32_path: src_path /usr/bin/yes, dst C:\cygwin64\bin\yes, flags 0x2000A, rc 0
109 3773 [main] test 16648 symlink_info::check: 0xC0000034 = NtCreateFile (\??\C:\cygwin64\bin\yes)
37 3810 [main] test 16648 symlink_info::check: 0xC0000034 = NtQueryInformationFile (\??\C:\cygwin64\bin\yes)
48 3858 [main] test 16648 symlink_info::check: 0x0 = NtCreateFile (\??\C:\cygwin64\bin\yes.exe)
758 30531 [main] test 5888 pwdgrp::fetch_account_from_windows: line: <Administrators:S-1-5-32-544:544:>
40 3898 [main] test 16648 symlink_info::check: not a symlink
63 30594 [main] test 5888 stat64: entering
23 30617 [main] test 5888 normalize_posix_path: src /dev
64 3962 [main] test 16648 symlink_info::check: 0 = symlink.check(C:\cygwin64\bin\yes.exe, 0xFFFFACA0) (0x2000A)
33 30650 [main] test 5888 normalize_posix_path: /dev = normalize_posix_path (/dev)
32 3994 [main] test 16648 path_conv::check: this->path(C:\cygwin64\bin\yes.exe), has_acls(1)
36 30686 [main] test 5888 mount_info::conv_to_win32_path: conv_to_win32_path (/dev)
34 4028 [main] test 16648 perhaps_suffix: buf C:\cygwin64\bin\yes.exe, suffix found '.exe'
37 30723 [main] test 5888 set_flags: flags: binary (0x2)
33 30756 [main] test 5888 mount_info::conv_to_win32_path: src_path /dev, dst C:\cygwin64\dev, flags 0x3000A, rc 0
58 30814 [main] test 5888 symlink_info::check: 0x0 = NtCreateFile (\??\C:\cygwin64\dev)
132 4160 [main] test 16648 child_info_spawn::worker: priority class 32
52 30866 [main] test 5888 symlink_info::check: not a symlink
53 4213 [main] test 16648 fhandler_console::need_invisible: invisible_console 0
36 30902 [main] test 5888 symlink_info::check: 0 = symlink.check(C:\cygwin64\dev, 0xFFFFB230) (0x43000A)
35 4248 [main] test 16648 build_env: envp 0x6000281A0
30 4278 [main] test 16648 spenv::retrieve: no_envblock 1
43 30945 [main] test 5888 build_fh_pc: fh 0x18030C1A8, dev 000000C1
28 4306 [main] test 16648 spenv::retrieve: duping existing value for 'HOMEDRIVE='
40 30985 [main] test 5888 stat_worker: (\??\C:\cygwin64\dev, 0x1802E2A20, 0x18030C1A8), file_attributes 16
28 4334 [main] test 16648 spenv::retrieve: no_envblock 1
28 4362 [main] test 16648 spenv::retrieve: duping existing value for 'HOMEPATH='
33 4395 [main] test 16648 spenv::retrieve: no_envblock 1
83 31068 [main] test 5888 fhandler_base::fstat_helper: 0 = fstat (\??\C:\cygwin64\dev, 0x1802E2A20) st_size=0, st_mode=040755, st_ino=562949953536516st_atim=57696141.1B43B4B0 st_ctim=57696141.1B43B4B0 st_mtim=57696141.1B43B4B0 st_birthtim=5769612C.1F3F08BC
25 4420 [main] test 16648 spenv::retrieve: duping existing value for 'LOGONSERVER='
32 31100 [main] test 5888 stat_worker: 0 = (\??\C:\cygwin64\dev,0x1802E2A20)
29 4449 [main] test 16648 spenv::retrieve: no_envblock 1
38 31138 [main] test 5888 fstat64: 0 = fstat(1, 0xFFFFC560)
46 4495 [main] test 16648 spenv::retrieve: no_envblock 1
47 31185 [main] test 5888 isatty: 1 = isatty(1)
34 4529 [main] test 16648 spenv::retrieve: no_envblock 1
28 4557 [main] test 16648 spenv::retrieve: duping existing value for 'SYSTEMROOT='
30 4587 [main] test 16648 spenv::retrieve: no_envblock 1
17 4604 [main] test 16648 spenv::retrieve: duping existing value for 'USERDOMAIN='
111 31296 [main] test 5888 fhandler_pty_slave::write: pty5, write(0x60003AE70, 17)
29 4633 [main] test 16648 spenv::retrieve: no_envblock 1
32 31328 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex (0x12C): waiting -1 ms
31 4664 [main] test 16648 spenv::retrieve: duping existing value for 'USERNAME='
27 31355 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex: acquired
26 4690 [main] test 16648 spenv::retrieve: no_envblock 1
24 31379 [main] test 5888 fhandler_pty_common::process_opost_output: (1940): pty output_mutex(0x12C) released
27 4717 [main] test 16648 spenv::retrieve: duping existing value for 'USERPROFILE='
34 31413 [main] test 5888 write: 17 = write(1, 0x60003AE70, 17)
35 4752 [main] test 16648 spenv::retrieve: no_envblock 1
27 4779 [main] test 16648 spenv::retrieve: duping existing value for 'WINDIR='
31 4810 [main] test 16648 build_env: env count 4, bytes 1570
129 31542 [main] test 5888 clock_nanosleep: clock_nanosleep (10.000000000)
73 4883 [main] test 16648 build_env: envp 0x18030B780, envc 78
34 4917 [main] test 16648 child_info::child_info: subproc_ready 0x158
1507 6424 [main] test 16648 child_info_spawn::worker: pid 16648, prog_arg /usr/bin/yes, cmd line (null))
48 6472 [main] test 16648! child_info_spawn::worker: new process name \\?\C:\cygwin64\bin\yes.exe
--- Process 14908 created
33 6505 [main] test 16648! child_info_spawn::worker: spawned windows pid 14908
85 6590 [main] test 16648! child_info::sync: n 2, waiting for subproc_ready(0x158) and child process(0x14C)
--- Process 14908 loaded C:\Windows\System32\ntdll.dll at 00007FF992A20000
--- Process 14908 loaded C:\Windows\System32\kernel32.dll at 00007FF991B80000
--- Process 14908 loaded C:\Windows\System32\KernelBase.dll at 00007FF98F940000
--- Process 14908 thread 6608 created
--- Process 14908 thread 7968 created
--- Process 14908 loaded C:\cygwin64\bin\cygwin1.dll at 0000000180040000
--- Process 14908 loaded C:\cygwin64\bin\cygintl-8.dll at 00000003FF3F0000
--- Process 14908 thread 2928 created
--- Process 14908 loaded C:\cygwin64\bin\cygiconv-2.dll at 00000005461D0000
1 1 [main] yes (14908) **********************************************
66 67 [main] yes (14908) Program name: C:\cygwin64\bin\yes.exe (windows pid 14908)
42 109 [main] yes (14908) OS version: Windows NT-10.0
35 144 [main] yes (14908) **********************************************
86 230 [main] yes (14908) sigprocmask: 0 = sigprocmask (0, 0x0, 0x1802E2BB0)
180 410 [main] yes 14908 child_copy: cygheap - hp 0x154 low 0x180302408, high 0x18030E260, res 1
30 440 [main] yes 14908 child_copy: done
94 534 [main] yes 14908 open_shared: name shared.5, n 5, shared 0x180030000 (wanted 0x180030000), h 0xAC, *m 6
52 586 [main] yes 14908 user_heap_info::init: heap base 0x600000000, heap top 0x600000000, heap size 0x20000000 (536870912)
40 626 [main] yes 14908 open_shared: name (null), n 1, shared 0x180020000 (wanted 0x180020000), h 0xB4, *m 6
31 657 [main] yes 14908 user_info::create: opening user shared for '' at 0x180020000
30 687 [main] yes 14908 user_info::create: user shared version AB1FCCE8
52 739 [main] yes (14908) open_shared: name (null), n 16648, shared 0x180010000 (wanted 0x180010000), h 0x124, *m 6
40 779 [main] yes 16648 pinfo::thisproc: myself dwProcessId 14908
101 880 [main] yes 16648 time: 1487678069 = time(0x0)
193 1073 [main] yes 16648 open_shared: name cygpid.14908, n 14908, shared 0x20000 (wanted 0x0), h 0xBC, *m 5
37 1110 [main] yes 16648 fhandler_pty_slave::fixup_after_fork: /dev/pty5 inherited, usecount 3
32 1142 [main] yes 16648 fhandler_base::fixup_after_exec: here for '/dev/null'
38 1180 [main] yes 16648 fhandler_pty_slave::fixup_after_fork: /dev/pty5 inherited, usecount 3
40 1220 [main] yes 16648 fhandler_base::fixup_after_exec: here for '/dev/null'
33 1253 [main] yes 16648 child_info::ready: signalled 0x158 that I was ready
4144 10734 [main] test 16648! child_info::sync: pid 14908, WFMO returned 0, exit_code 0x103, res 1
30 10764 [main] test 16648! fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 2
60 1313 [main] yes 16648 fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-14908-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
33 10797 [main] test 16648! fhandler_base::close_with_arch: not closing archetype
38 10835 [main] test 16648! fhandler_base::close: closing '/dev/null' handle 0x120
27 10862 [main] test 16648! fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 1
81 1394 [main] yes 16648 fhandler_pipe::create: pipe read handle 0xCC
21 10883 [main] test 16648! fhandler_base::close_with_arch: not closing archetype
26 1420 [main] yes 16648 fhandler_pipe::create: CreateFile: name \\.\pipe\cygwin-e022582115c10879-14908-sigwait
18 10901 [main] test 16648! fhandler_base::close: closing '/dev/null' handle 0x150
33 10934 [main] test 16648! proc_terminate: nprocs 0
61 1481 [main] yes 16648 fhandler_pipe::create: pipe write handle 0xD4
30 10964 [main] test 16648! proc_terminate: leaving
34 10998 [main] test 16648! pinfo::maybe_set_exit_code_from_windows: pid 16648, exit value - old 0x0, windows 0xDEADBEEF, cygwin 0x0
54 1535 [main] yes 16648 dll_crt0_0: finished dll_crt0_0 initialization
51 11049 [main] test 16648! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
--- Process 16648 thread 1480 exited with status 0x0
--- Process 16648 thread 10440 exited with status 0x0
--- Process 16648 exited with status 0x0
--- Process 14908 thread 2496 created
305 1840 [sig] yes 16648 wait_sig: entering ReadFile loop, my_readsig 0xCC, my_sendsig 0xD4
174 2014 [main] yes 16648 sigprocmask: 0 = sigprocmask (0, 0x0, 0x600000150)
208 2222 [main] yes 16648 _cygwin_istext_for_stdio: fd 0: opened as binary
36 2258 [main] yes 16648 _cygwin_istext_for_stdio: fd 1: opened as binary
35 2293 [main] yes 16648 _cygwin_istext_for_stdio: fd 2: opened as binary
146 2439 [main] yes 16648 parse_options: glob (called func)
58 2497 [main] yes 16648 parse_options: returning
38 2535 [main] yes 16648 pinfo_init: pid 16648, pgid 8416, process_state 0xC1
29 2564 [main] yes 16648 App version: 2005.0, api: 0.297
89 2653 [main] yes 16648 DLL version: 2006.0, api: 0.304
43 2696 [main] yes 16648 DLL build: 2016-08-31 14:32
126 2822 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
513 3335 [main] yes 16648 __set_errno: void dll_crt0_1(void*):979 setting errno 0
443 3778 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
88 3866 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
108 3974 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
136 4110 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
106 4216 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
116 4332 [main] yes 16648 __get_lcid_from_locale: LCID=0x0409
561 4893 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
52 4945 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
41 9994976 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
... repeats for a while ...
38 9995014 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
9999636 10031178 [main] test 5888 clock_nanosleep: 0 = clock_nanosleep(1, 0, 10.000000000, 0.d)
63 9995077 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
51 9995128 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
56 9995184 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
154 10031332 [main] test 5888 fhandler_pty_slave::write: pty5, write(0x60003AE70, 16)
31 10031363 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex (0x12C): waiting -1 ms
51 9995235 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
27 10031390 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex: acquired
26 10031416 [main] test 5888 fhandler_pty_common::process_opost_output: (1940): pty output_mutex(0x12C) released
55 9995290 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
30 10031446 [main] test 5888 write: 16 = write(1, 0x60003AE70, 16)
56 9995346 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
52 9995398 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
104 10031550 [main] test 5888 kill0: kill (16648, 9)
48 9995446 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
43 10031593 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x150000 (wanted 0x0), h 0x19C, *m 6
53 9995499 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
64 10031657 [main] test 5888 sig_send: 1 = SetNamedPipeHandleState (0x190, PIPE_NOWAIT, NULL, NULL)
33 10031690 [main] test 5888 sig_send: sendsig 0x190, pid 16648, signal 9, its_me 0
56 9995555 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
30 10031720 [main] test 5888 sig_send: Not waiting for sigcomplete. its_me 0 signal 9
25 10031745 [main] test 5888 sig_send: returning 0x0 from sending signal 9
53 9995608 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
26 10031771 [main] test 5888 _pinfo::kill: 0 = _pinfo::kill (9), pid 16648, process_state 0xC1
36 9995644 [sig] yes 16648 sigpacket::process: signal 9 processing
37 10031808 [main] test 5888 clock_nanosleep: clock_nanosleep (10.000000000)
101 9995745 [sig] yes 16648 sigpacket::process: signal 9, signal handler 0x18005C300
27 9995772 [main] yes 16648 write: 1024 = write(1, 0xFFFFC7D0, 1024)
25 9995797 [sig] yes 16648 sigpacket::setup_handler: controlled interrupt. stackptr 0xFFFFE460, stack 0xFFFFE458, stackptr[-1] 0x100404260
27 9995824 [sig] yes 16648 proc_subproc: args: 5, 1
28 9995852 [sig] yes 16648 proc_subproc: clear waiting threads
24 9995876 [sig] yes 16648 proc_subproc: finished clearing
23 9995899 [sig] yes 16648 proc_subproc: returning 1
23 9995922 [sig] yes 16648 _cygtls::interrupt_setup: armed signal_arrived 0x118, signal 9
24 9995946 [sig] yes 16648 sigpacket::setup_handler: signal 9 delivered
24 9995970 [sig] yes 16648 sigpacket::process: returning 1
27 9995997 [main] yes 16648 set_process_mask_delta: oldmask 0, newmask 0, deltamask 0
41 9996038 [main] yes 16648 signal_exit: exiting due to signal 9
24 9996062 [main] yes 16648 signal_exit: about to call do_exit (9)
24 9996086 [main] yes 16648 do_exit: do_exit (9), exit_state 2
21 9996107 [main] yes 16648 void: 0x0 = signal (20, 0x1)
21 9996128 [main] yes 16648 void: 0x0 = signal (1, 0x1)
20 9996148 [main] yes 16648 void: 0x0 = signal (2, 0x1)
21 9996169 [main] yes 16648 void: 0x0 = signal (3, 0x1)
23 9996192 [main] yes 16648 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 2
20 9996212 [main] yes 16648 fhandler_base::close_with_arch: not closing archetype
31 9996243 [main] yes 16648 fhandler_base::close: closing '/dev/null' handle 0x120
26 9996269 [main] yes 16648 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 1
20 9996289 [main] yes 16648 fhandler_base::close_with_arch: not closing archetype
23 9996312 [main] yes 16648 fhandler_base::close: closing '/dev/null' handle 0x150
23 9996335 [main] yes 16648 init_cygheap::close_ctty: closing cygheap->ctty 0x18030B3A0
19 9996354 [main] yes 16648 fhandler_base::close_with_arch: closing passed in archetype 0x0, usecount 0
21 9996375 [main] yes 16648 fhandler_pty_slave::cleanup: /dev/pty5 closed, usecount 0
27 9996402 [main] yes 16648 fhandler_pty_slave::close: closing last open /dev/pty5 handle
50 9996452 [main] yes 16648 fhandler_console::free_console: freed console, res 1
24 9996476 [main] yes 16648 fhandler_pty_common::close: pty5 <0x13C,0x144> closing
26 9996502 [main] yes 16648 dtable::delete_archetype: deleting element 0 for /dev/pty5(136/5)
38 9996540 [main] yes 16648 getpid: 16648 = getpid()
26 9996566 [main] yes 16648 proc_terminate: nprocs 0
20 9996586 [main] yes 16648 proc_terminate: leaving
37 9996623 [main] yes 16648 pinfo::exit: Calling ExitProcess n 0x9, exitcode 0x9
--- Process 14908 thread 2928 exited with status 0x9
--- Process 14908 thread 6608 exited with status 0x9
--- Process 14908 thread 7968 exited with status 0x9
--- Process 14908 thread 12532 exited with status 0x9
--- Process 14908 exited with status 0x9
1931 10033739 [waitproc] test 5888 pinfo::maybe_set_exit_code_from_windows: pid 16648, exit value - old 0x8000009, windows 0xDEADBEEF, cygwin 0x8000009
38 10033777 [waitproc] test 5888 sig_send: sendsig 0x44, pid 5888, signal 20, its_me 1
29 10033806 [waitproc] test 5888 sig_send: Not waiting for sigcomplete. its_me 1 signal 20
21 10033827 [waitproc] test 5888 sig_send: returning 0x0 from sending signal 20
22 10033849 [waitproc] test 5888 proc_waiter: exiting wait thread for pid 16648
25 10033874 [sig] test 5888 sigpacket::process: signal 20 processing
22 10033896 [sig] test 5888 init_cygheap::find_tls: sig 20
22 10033918 [sig] test 5888 sigpacket::process: using tls 0xFFFFCE00
53 10033971 [sig] test 5888 sigpacket::process: signal 20 default is currently ignore
21 10033992 [sig] test 5888 sigpacket::process: returning 1
28 10034020 [sig] test 5888 proc_subproc: args: 5, 0
20 10034040 [sig] test 5888 proc_subproc: looking for processes to reap, nprocs 1
21 10034061 [sig] test 5888 proc_subproc: finished processing terminated/stopped child
20 10034081 [sig] test 5888 proc_subproc: returning 1
9998450 20032531 [main] test 5888 clock_nanosleep: 0 = clock_nanosleep(1, 0, 10.000000000, 0.d)
311 20032842 [main] test 5888 fhandler_pty_slave::write: pty5, write(0x60003AE70, 25)
86 20032928 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex (0x12C): waiting -1 ms
74 20033002 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex: acquired
78 20033080 [main] test 5888 fhandler_pty_common::process_opost_output: (1940): pty output_mutex(0x12C) released
90 20033170 [main] test 5888 write: 25 = write(1, 0x60003AE70, 25)
317 20033487 [main] test 5888 open: open(/proc/16648/stat, 0x0)
47 20033534 [main] test 5888 normalize_posix_path: src /proc/16648/stat
42 20033576 [main] test 5888 normalize_posix_path: /proc/16648/stat = normalize_posix_path (/proc/16648/stat)
40 20033616 [main] test 5888 mount_info::conv_to_win32_path: conv_to_win32_path (/proc/16648/stat)
34 20033650 [main] test 5888 fhandler_proc::get_proc_fhandler: get_proc_fhandler(/proc/16648/stat)
49 20033699 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x150000 (wanted 0x0), h 0x190, *m 6
40 20033739 [main] test 5888 set_flags: flags: binary (0x2)
25 20033764 [main] test 5888 mount_info::conv_to_win32_path: src_path /proc/16648/stat, dst /proc/16648/stat, flags 0x2, rc 0
32 20033796 [main] test 5888 build_fh_pc: fh 0x18030C1A8, dev 000000FE
24 20033820 [main] test 5888 fhandler_process::exists: exists (/proc/16648/stat)
27 20033847 [main] test 5888 build_fh_pc: fh 0x18030C1A8, dev 000000FE
26 20033873 [main] test 5888 fhandler_base::set_flags: flags 0x18000, supplied_bin 0x0
22 20033895 [main] test 5888 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
22 20033917 [main] test 5888 fhandler_base::set_flags: filemode set to binary
32 20033949 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x150000 (wanted 0x0), h 0x190, *m 6
30 20033979 [main] test 5888 time: 1487678089 = time(0x0)
33 20034012 [main] test 5888 seterrno_from_win_error: /home/corinna/src/cygwin/cygwin-2.6.0/cygwin-2.6.0-1.x86_64/src/newlib-cygwin/winsup/cygwin/fhandler_process.cc:1103 windows error 87
28 20034040 [main] test 5888 geterrno_from_win_error: windows error 87 == errno 22
22 20034062 [main] test 5888 format_process_stat: OpenProcess: ret 87
31 20034093 [main] test 5888 fhandler_process::open: 0 = fhandler_proc::open(0x8000, 0666)
25 20034118 [main] test 5888 open: -1 = open(/proc/16648/stat, 0x8000), errno 22
186 20034304 [main] test 5888 fhandler_pty_slave::write: pty5, write(0x60003AE70, 35)
22 20034326 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex (0x12C): waiting -1 ms
22 20034348 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex: acquired
23 20034371 [main] test 5888 fhandler_pty_common::process_opost_output: (1940): pty output_mutex(0x12C) released
24 20034395 [main] test 5888 write: 35 = write(1, 0x60003AE70, 35)
104 20034499 [main] test 5888 normalize_posix_path: src /proc/16648/stat
21 20034520 [main] test 5888 normalize_posix_path: /proc/16648/stat = normalize_posix_path (/proc/16648/stat)
22 20034542 [main] test 5888 mount_info::conv_to_win32_path: conv_to_win32_path (/proc/16648/stat)
22 20034564 [main] test 5888 fhandler_proc::get_proc_fhandler: get_proc_fhandler(/proc/16648/stat)
28 20034592 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x150000 (wanted 0x0), h 0x190, *m 6
31 20034623 [main] test 5888 set_flags: flags: binary (0x2)
24 20034647 [main] test 5888 mount_info::conv_to_win32_path: src_path /proc/16648/stat, dst /proc/16648/stat, flags 0x2, rc 0
24 20034671 [main] test 5888 build_fh_pc: fh 0x18030C1A8, dev 000000FE
22 20034693 [main] test 5888 fhandler_process::exists: exists (/proc/16648/stat)
24 20034717 [main] test 5888 build_fh_pc: fh 0x18030C1A8, dev 000000FE
23 20034740 [main] test 5888 fhandler_process::exists: exists (/proc/16648/stat)
22 20034762 [main] test 5888 time: 1487678089 = time(0x0)
27 20034789 [main] test 5888 open_shared: name cygpid.16648, n 16648, shared 0x150000 (wanted 0x0), h 0x190, *m 6
30 20034819 [main] test 5888 fhandler_base::fhaccess: returning 0
25 20034844 [main] test 5888 access: returning 0
113 20034957 [main] test 5888 fhandler_pty_slave::write: pty5, write(0x60003AE70, 36)
23 20034980 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex (0x12C): waiting -1 ms
29 20035009 [main] test 5888 fhandler_pty_common::process_opost_output: (1901): pty output_mutex: acquired
30 20035039 [main] test 5888 fhandler_pty_common::process_opost_output: (1940): pty output_mutex(0x12C) released
25 20035064 [main] test 5888 write: 36 = write(1, 0x60003AE70, 36)
106 20035170 [main] test 5888 wait4: calling proc_subproc, pid 16648, options 0
26 20035196 [main] test 5888 proc_subproc: args: 6, -7152
32 20035228 [main] test 5888 proc_subproc: wval->pid 16648, wval->options 0
35 20035263 [main] test 5888 checkstate: nprocs 1
25 20035288 [main] test 5888 stopped_or_terminated: considering pid 16648, pgid 8416, w->pid 16648
26 20035314 [main] test 5888 remove_proc: removing procs[0], pid 16648, nprocs 1
63 20035377 [main] test 5888 checkstate: returning 1
26 20035403 [main] test 5888 proc_subproc: released waiting thread
22 20035425 [main] test 5888 proc_subproc: finished processing terminated/stopped child
22 20035447 [main] test 5888 proc_subproc: returning 1
25 20035472 [main] test 5888 wait4: 0 = cygwait (...)
31 20035503 [main] test 5888 wait4: 16648 = wait4(16648, 0x9, 0, 0x0)
106 20035609 [main] test 5888 do_exit: do_exit (2048), exit_state 1
29 20035638 [main] test 5888 void: 0x0 = signal (20, 0x1)
23 20035661 [main] test 5888 void: 0x0 = signal (1, 0x1)
26 20035687 [main] test 5888 void: 0x0 = signal (2, 0x1)
21 20035708 [main] test 5888 void: 0x0 = signal (3, 0x1)
27 20035735 [main] test 5888 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 3
24 20035759 [main] test 5888 fhandler_base::close_with_arch: not closing archetype
27 20035786 [main] test 5888 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 2
22 20035808 [main] test 5888 fhandler_base::close_with_arch: not closing archetype
27 20035835 [main] test 5888 fhandler_base::close_with_arch: line 1140: /dev/pty5<0x18030B3A0> usecount + -1 = 1
22 20035857 [main] test 5888 fhandler_base::close_with_arch: not closing archetype
30 20035887 [main] test 5888 fhandler_base::close: closing '/dev/null' handle 0x150
30 20035917 [main] test 5888 init_cygheap::close_ctty: closing cygheap->ctty 0x18030B3A0
25 20035942 [main] test 5888 fhandler_base::close_with_arch: closing passed in archetype 0x0, usecount 0
22 20035964 [main] test 5888 fhandler_pty_slave::cleanup: /dev/pty5 closed, usecount 0
21 20035985 [main] test 5888 fhandler_pty_slave::close: closing last open /dev/pty5 handle
47 20036032 [main] test 5888 fhandler_console::free_console: freed console, res 1
29 20036061 [main] test 5888 fhandler_pty_common::close: pty5 <0x13C,0x144> closing
29 20036090 [main] test 5888 dtable::delete_archetype: deleting element 0 for /dev/pty5(136/5)
30 20036120 [main] test 5888 getpid: 5888 = getpid()
25 20036145 [main] test 5888 proc_terminate: nprocs 0
21 20036166 [main] test 5888 proc_terminate: leaving
33 20036199 [main] test 5888 pinfo::exit: Calling ExitProcess n 0x800, exitcode 0x8
--- Process 5888 thread 7392 exited with status 0x8
--- Process 5888 thread 17180 exited with status 0x8
--- Process 5888 thread 8392 exited with status 0x8
--- Process 5888 thread 12860 exited with status 0x8
--- Process 5888 exited with status 0x8
[-- Attachment #4: Type: text/plain, Size: 219 bytes --]
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Problem with zombie processes
2017-02-21 11:59 ` Erik Bray
@ 2019-04-04 12:44 ` E. Madison Bray
0 siblings, 0 replies; 11+ messages in thread
From: E. Madison Bray @ 2019-04-04 12:44 UTC (permalink / raw)
To: cygwin
On Tue, Feb 21, 2017 at 12:58 PM Erik Bray wrote:
>
> On Mon, Feb 20, 2017 at 11:54 PM, Mark Geisert wrote:
> > Erik Bray wrote:
> >>
> >> On Mon, Feb 20, 2017 at 11:54 AM, Mark Geisert wrote:
> >>>>
> >>>> So my guess was that Cygwin might try to hold on to a handle to a
> >>>> child process at least until it's been explicitly wait()ed. But that
> >>>> does not seem to be the case after all.
> >>>
> >>>
> >>>
> >>> You might have missed a subtlety in what I said above. The Python
> >>> interpreter itself is calling wait4() to reap your child process. Cygwin
> >>> has told Python one of its children has died. You won't get the chance
> >>> to
> >>> wait() for it yourself. Cygwin *does* have a handle to the process, but
> >>> it
> >>> gets closed as part of Python calling wait4().
> >>
> >>
> >> To be clear, wait4() is not called from Python until the script
> >> explicitly calls p.wait().
> >> In other words, when run this step by step (e.g. in gdb) I don't see a
> >> wait4() call until the point where the script explicitly waits(). I
> >> don't see any reason Python would do this behind the scenes.
> >
> >
> > You're right. I missed the wait in your script and ASSumed too much of the
> > Python interpreter :-( .
> >
> >
> >>>> Anyways, I think it would be nicer if /proc returned at least partial
> >>>> information on zombie processes, rather than an error. I have a patch
> >>>> to this effect for /proc/<pid>/stat, and will add a few more as well.
> >>>> To me /proc/<pid>/stat was the most important because that's the
> >>>> easiest way to check the process's state in the first place! Now I
> >>>> also have to catch EINVAL as well and assume that means a zombie
> >>>> process.
> >>>
> >>>
> >>>
> >>> The file /proc/<pid>/stat is there until Cygwin finishes cleanup of the
> >>> child due to Python having wait()ed for it. When you run your test
> >>> script,
> >>> pay attention to the process state character in those cases where you
> >>> successfully read the stat file. It's often S (stopped, I think) or R
> >>> (running) but I also see Z (zombie) sometimes. Your script is in a race
> >>> with Cygwin, and you cannot guarantee you'll see a killed process's state
> >>> before Cygwin cleans it up.
> >>>
> >>> One way around this *might* be to install a SIGCHLD handler in your
> >>> Python
> >>> script. If that's possible, that should tell you when your child exits.
> >>
> >>
> >> Perhaps the Python script is a red herring. I just wrote it to
> >> demonstrate the problem. The difference between where I send stdout
> >> to is strange, but you're likely right that it just comes down to
> >> subtle timing differences. Here's a C program that demonstrates the
> >> same issue more reliably. Interestingly, it works when I run it in
> >> strace (probably just because of the strace overhead) but not when I
> >> run it normally.
> >>
> >> My point in all this is I'm confused why Cygwin would give up its
> >> handles to the Windows process before wait() has been called.
> >>
> >> (In fact, it's pretty confusing to have fopen returning EINVAL which
> >> according to [1] it should only be doing if the mode string were
> >> invalid.)
> >>
> >> Thanks,
> >> Erik
> >>
> >> [1] http://pubs.opengroup.org/onlinepubs/9699919799/functions/fopen.html
> >
> >
> > O.K., you may be on to something amiss in the Cygwin DLL. Thanks for the
> > STC in C; that'll help somebody looking further at this. I'm out of ideas.
> > It might be possible to reduce strace overhead somewhat by selecting a
> > smaller set of trace options than the default.
>
> Note: My previous test program had a bug in do_child() (not correctly
> terminating the argv array). The attached program fixes the bug.
> I've also attached a (truncated) strace log from it.
With apologies for re-raising a 2 year old thread; I've finally been
back to working on my port of psutil [1]. I was getting some
confusing errors reading the /proc/[pid]/stat files of recently
created processes that had quickly become zombified. I had completely
forgotten about this issue until I saw that trying to read the stat
file was resulting in EINVAL ("invalid argument") and something about
that ringed a bell.
So, I can confirm that this is still an issue. Apparently I wrote
that I had a patch to Cygwin for this. I have no idea where that
patch is but I'll look for it, or try to reproduce it. I think the
idea for the patch was to at least make a zombie process's stat file
readable so that the status flag ("Z") can be read, and maybe fill the
remaining fields with 0.
Once I find and/or reproduce that patch I'll submit it to cygwin-patches.
[1] https://psutil.readthedocs.io/en/latest/
--
Problem reports: http://cygwin.com/problems.html
FAQ: http://cygwin.com/faq/
Documentation: http://cygwin.com/docs.html
Unsubscribe info: http://cygwin.com/ml/#unsubscribe-simple
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2019-04-04 12:44 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-02-14 11:14 Problem with zombie processes Erik Bray
2017-02-14 19:25 ` Mark Geisert
2017-02-17 11:00 ` Erik Bray
2017-02-17 15:06 ` Doug Henderson
2017-02-17 22:06 ` Mark Geisert
2017-02-20 9:46 ` Erik Bray
2017-02-20 10:54 ` Mark Geisert
2017-02-20 15:23 ` Erik Bray
2017-02-20 22:54 ` Mark Geisert
2017-02-21 11:59 ` Erik Bray
2019-04-04 12:44 ` E. Madison Bray
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).