public inbox for cygwin@cygwin.com
 help / color / mirror / Atom feed
From: Erik Bray <erik.m.bray@gmail.com>
To: cygwin@cygwin.com
Subject: Re: Problem with zombie processes
Date: Tue, 21 Feb 2017 11:59:00 -0000	[thread overview]
Message-ID: <CAOTD34YqZMD=e-U=r56bys7GfzHKYwjVUnjkQpngE+Y9nAL+EA@mail.gmail.com> (raw)
In-Reply-To: <58AB73B5.6040104@maxrnd.com>

[-- 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

  reply	other threads:[~2017-02-21 11:59 UTC|newest]

Thread overview: 11+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2017-02-14 11:14 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 [this message]
2019-04-04 12:44                 ` E. Madison Bray

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to='CAOTD34YqZMD=e-U=r56bys7GfzHKYwjVUnjkQpngE+Y9nAL+EA@mail.gmail.com' \
    --to=erik.m.bray@gmail.com \
    --cc=cygwin@cygwin.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
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).