Problem with rsync 3.0.6-1 under 1.7.0-62 and 63

[Eliot Moss]

I am getting this output when trying to rsync
to any of several systems. I have RSYNC_RSH set
to use ssh, and the ssh commands work just fine.
This smells like some kind of non-matching library
issue to me ...

rsync: Failed to dup/close: Bad file descriptor (9)
rsync error: error in IPC code (code 14) at
/home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/pipe.c(72) [sender=3.0.6]
rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]: Connection reset by peer (104)
rsync error: error in IPC code (code 14) at
/home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/io.c(1525) [sender=3.0.6]

Regards -- Eliot Moss

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

[Steven Monai-5]

Eliot Moss wrote:

> I am getting this output when trying to rsync
> to any of several systems. I have RSYNC_RSH set
> to use ssh, and the ssh commands work just fine.
> This smells like some kind of non-matching library
> issue to me ...
>
> rsync: Failed to dup/close: Bad file descriptor (9)
> rsync error: error in IPC code (code 14) at
> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/pipe.c(72)
> [sender=3.0.6]
> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
> Connection reset by peer (104)
> rsync error: error in IPC code (code 14) at
> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/io.c(1525)
> [sender=3.0.6]

I am curious to know: What is the specific command-line you're using to
invoke rsync when it produces the above output?

Yours may not be a Cygwin-specific problem, as I routinely use rsync
over ssh on 1.7.0-63, and I have never seen that. The rsync mailing list
is another resource you could try. The 'rsync FAQ' and 'rsync current
issues' pages (google them) may also be of help.

-SM
--

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

[Eliot Moss]

Steven Monai wrote:

> Eliot Moss wrote:
>> I am getting this output when trying to rsync
>> to any of several systems. I have RSYNC_RSH set
>> to use ssh, and the ssh commands work just fine.
>> This smells like some kind of non-matching library
>> issue to me ...
>>
>> rsync: Failed to dup/close: Bad file descriptor (9)
>> rsync error: error in IPC code (code 14) at
>> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/pipe.c(72)
>> [sender=3.0.6]
>> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
>> Connection reset by peer (104)
>> rsync error: error in IPC code (code 14) at
>> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/io.c(1525)
>> [sender=3.0.6]
>
> I am curious to know: What is the specific command-line you're using to
> invoke rsync when it produces the above output?
>
> Yours may not be a Cygwin-specific problem, as I routinely use rsync
> over ssh on 1.7.0-63, and I have never seen that. The rsync mailing list
> is another resource you could try. The 'rsync FAQ' and 'rsync current
> issues' pages (google them) may also be of help.

Thanks for the quick response. The command line is:

rsync -avzuP UK-2009-11-richards-gist roc.cs.umass.edu:talks/

... but I get essentially the same doing other things and going
other places. It appears I cannot get through at all. (I'll have
to try another time if it's a port blocking issue from the particular
place I am.)

I could not find this in the rsync FAQs, etc.

Regards -- Eliot

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

[Steven Monai-5]

Eliot Moss wrote:

>> Eliot Moss wrote:
>>> I am getting this output when trying to rsync
>>> to any of several systems. I have RSYNC_RSH set
>>> to use ssh, and the ssh commands work just fine.
>>> This smells like some kind of non-matching library
>>> issue to me ...
>>>
>>> rsync: Failed to dup/close: Bad file descriptor (9)
>>> rsync error: error in IPC code (code 14) at
>>> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/pipe.c(72)
>>> [sender=3.0.6]
>>> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
>>> Connection reset by peer (104)
>>> rsync error: error in IPC code (code 14) at
>>> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/io.c(1525)
>>> [sender=3.0.6]

...
>  The command line is:
>
> rsync -avzuP UK-2009-11-richards-gist ${REMOTE_HOST}:talks/

I assume you ran the above command in Cygwin. (Note that I have replaced
the remote hostname with ${REMOTE_HOST}.)

Is the remote host also running Cygwin? If so, what version? If not,
then what is the remote OS ?

What output do you get when you run the following in Cygwin (after
setting REMOTE_HOST appropriately, of course):

  ssh "${REMOTE_HOST}" /bin/true | od -tx1


-SM
--


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

[Eliot Moss]

Tried two more things ...

- rsync in the opposite direction fails in the same way

- adding --protocol=29 (to match the remote end) did not
   change the behavor

Unfortunately no other version of rsync is available with
cygwin 1.7.x, so I can't simply install an earlier version.
I think I'll need to obtain source and build it myself.
Maybe later today ....

Eliot

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

[Eliot Moss]

Eliot Moss wrote:

> Tried two more things ...
>
> - rsync in the opposite direction fails in the same way
>
> - adding --protocol=29 (to match the remote end) did not
>   change the behavor
>
> Unfortunately no other version of rsync is available with
> cygwin 1.7.x, so I can't simply install an earlier version.
> I think I'll need to obtain source and build it myself.
> Maybe later today ....

Rebuilding from source had no effect -- I did apply first
the 3.0.6-1.src patch and then the cygwin patch.

So I tried strace to get more info. The first failure is
at a dup2 call immediately after a fork() call. The dup2
args are (3, 0) and Win32 returns error 6, which cygwin
translates to 9 (EBADF). Near as I can tell, fd 3 is a
socket.

The code is in piped_child in pipe.c; here is the comment
at the top of that routine:

/**
  * Create a child connected to us via its stdin/stdout.
  *
  * This is derived from CVS code
  *
  * Note that in the child STDIN is set to blocking and STDOUT
  * is set to non-blocking. This is necessary as rsh relies on stdin being blocking
  *  and ssh relies on stdout being non-blocking
  *
  * If blocking_io is set then use blocking io on both fds. That can be
  * used to cope with badly broken rsh implementations like the one on
  * Solaris.
  **/

Not sure if I am reporting the most helpful stuff, but there
it is. Any ideas on how I can help resolve this? There does
not seem to be anything like this reported in the rsync list,
so I think it's particular to cygwin, and probably to 1.7.x.

Cheers -- Eliot Moss

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

[Eliot Moss]

Eliot Moss wrote:

> Eliot Moss wrote:
>> Tried two more things ...
>>
>> - rsync in the opposite direction fails in the same way
>>
>> - adding --protocol=29 (to match the remote end) did not
>>   change the behavor
>>
>> Unfortunately no other version of rsync is available with
>> cygwin 1.7.x, so I can't simply install an earlier version.
>> I think I'll need to obtain source and build it myself.
>> Maybe later today ....
>
> Rebuilding from source had no effect -- I did apply first
> the 3.0.6-1.src patch and then the cygwin patch.
>
> So I tried strace to get more info. The first failure is
> at a dup2 call immediately after a fork() call. The dup2
> args are (3, 0) and Win32 returns error 6, which cygwin
> translates to 9 (EBADF). Near as I can tell, fd 3 is a
> socket.
>
> The code is in piped_child in pipe.c; here is the comment
> at the top of that routine:
>
> /**
>  * Create a child connected to us via its stdin/stdout.
>  *
>  * This is derived from CVS code
>  *
>  * Note that in the child STDIN is set to blocking and STDOUT
>  * is set to non-blocking. This is necessary as rsh relies on stdin
> being blocking
>  *  and ssh relies on stdout being non-blocking
>  *
>  * If blocking_io is set then use blocking io on both fds. That can be
>  * used to cope with badly broken rsh implementations like the one on
>  * Solaris.
>  **/
>
> Not sure if I am reporting the most helpful stuff, but there
> it is. Any ideas on how I can help resolve this? There does
> not seem to be anything like this reported in the rsync list,
> so I think it's particular to cygwin, and probably to 1.7.x.

Btw, this seems related to the rsync problem on close, for which
there was discussion back in August (msg 153806 is at the end of
that thread).

Cheers -- Eliot

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

[Steven Monai-5]

Eliot Moss wrote:
>  There does
> not seem to be anything like this reported in the rsync list,
> so I think it's particular to cygwin, and probably to 1.7.x.

I really think you should report what you're seeing to the rsync mailing
list. It is entirely possible that no one who has run your particular
use case before (rsync v3.0.6 failing to work with rsync v2.6.8, and
vice versa) has ever gone to the extra effort of reporting the problem.

In the best case, the rsync gurus may be able to look at your error
codes and tell right away what is going wrong. They may even agree with
your assessment that Cygwin is somehow to blame, although I'd lean more
towards a protocol mismatch hypothesis.

-SM
--

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

[Eliot Moss]

Eliot Moss wrote:

> I am getting this output when trying to rsync
> to any of several systems. I have RSYNC_RSH set
> to use ssh, and the ssh commands work just fine.
> This smells like some kind of non-matching library
> issue to me ...
>
> rsync: Failed to dup/close: Bad file descriptor (9)
> rsync error: error in IPC code (code 14) at
> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/pipe.c(72)
> [sender=3.0.6]
> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
> Connection reset by peer (104)
> rsync error: error in IPC code (code 14) at
> /home/lapo/packaging/rsync-3.0.6-1/src/rsync-3.0.6/io.c(1525)
> [sender=3.0.6]

I think that Corinna (et al.?) thought this was more likely to
be a problem in rsync introduce by its relatively recent
revision from 3.0.5 to 3.0.6.  However, I decided to try
building and running 3.0.5 myself under cygwin 1.7.0-64 and
I get the same error. This is saying to me that the problem
more likely lies in changes to cygwin than rsync, since
3.0.5 is from December 2008 ...

I can get you strace output if you want :-) ...   Eliot

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

[Corinna Vinschen-2]

On Nov 12 10:31, Eliot Moss wrote:
> I think that Corinna (et al.?) thought this was more likely to
> be a problem in rsync introduce by its relatively recent
> revision from 3.0.5 to 3.0.6.

Me?  No, I never said that.


Corinna

--
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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

[Eliot Moss]

Corinna Vinschen wrote:
> On Nov 12 10:31, Eliot Moss wrote:
>> I think that Corinna (et al.?) thought this was more likely to
>> be a problem in rsync introduce by its relatively recent
>> revision from 3.0.5 to 3.0.6.
>
> Me?  No, I never said that.

Just my possibly mistaken impression then. In any case, is
there more you'd like me to do in providing information that
might assist in debugging and fixing the problem?

Cheers -- Eliot

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

[Eliot Moss]

I went ahead and wrote a little program that narrows
down the rsync problem to a dup2 call. The program:
creates two pipes (for talking to a child process),
forks the child, and the child tries to dup2 the
pipe fds to its stdin and stdout. If it wins (which
it doesn't), it will then run sleep for 5 seconds
and quit. The parent closes some fds it doesn't need
and waits for the child, then quits. I attach the
program in question, and strace output.

Cheers -- Eliot Moss

/* #include "rsync.h" */
/* #include "ifuncs.h" */
#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/socket.h>
#include <unistd.h>
#include <fcntl.h>
#include <errno.h>

void set_blocking(int);
void set_nonblocking(int);
int fd_pair(int[2]);

int main (int argc, char *argv[]) {
  pid_t pid;
  int to_child_pipe[2];
  int from_child_pipe[2];
  char* command[3] = {
    "/usr/bin/sleep",
    "5",
    0};

  int err;
  if ((err = fd_pair(to_child_pipe)) < 0) {
    printf("error: pipe to child: %d\n", err);
    exit(-1);
  }

  if ((err = fd_pair(from_child_pipe)) < 0) {
    printf("error: pipe from child: %d\n");
    exit(-1);
  }

  pid = fork();
  if (pid == -1) {
    printf("error; fork\n");
    exit(-1);
  }

  if (pid == 0) {
    if ((err = dup2(to_child_pipe[0], 0)) < 0) {
      printf("error: first dup2 %d %d\n", err, errno);
      exit(-1);
    }
    if ((err = close(to_child_pipe[1])) < 0) {
      printf("error: first close %d\n", err);
      exit(-1);
    }
    if ((err = close(from_child_pipe[0])) < 0) {
      printf("error: second close %d\n", err);
      exit(-1);
    }
    if ((err = dup2(from_child_pipe[1], 1)) < 0) {
      printf("error: second dup2 %d\n", err);
      exit(-1);
    }
    if (to_child_pipe[0] != 0)
      close(to_child_pipe[0]);
    if (from_child_pipe[1] != 1)
      close(from_child_pipe[1]);
    /* umask(orig_umask); */
    set_blocking(0);
    execvp(command[0], command);
    printf("Failed to exec %s\n", command[0]);
    exit(-1);
  }

  if (close(from_child_pipe[1]) < 0 || close(to_child_pipe[0]) < 0) {
    printf("Failed to close\n");
    exit(-1);
  }

  int f_in = from_child_pipe[0];
  int f_out = to_child_pipe[1];

  printf("pid = %d, fin = %d, fout = %d\n", pid, f_in, f_out);
  int status;
  wait(&status);
  printf("wait got %d\n", status);
  fflush(stdout);
  exit(0);
}

int fd_pair (int fd[2]) {
  int ret = socketpair(AF_UNIX, SOCK_STREAM, 0, fd);
  if (ret == 0) {
    set_nonblocking(fd[0]);
    set_nonblocking(fd[1]);
  }
  return ret;
}

/* Set a fd into nonblocking mode. */
void set_nonblocking(int fd)
{
  int val;

  if ((val = fcntl(fd, F_GETFL)) == -1)
    return;
  if (!(val & O_NONBLOCK)) {
    val |= O_NONBLOCK;
    fcntl(fd, F_SETFL, val);
  }
}

/* Set a fd into blocking mode. */
void set_blocking(int fd)
{
  int val;

  if ((val = fcntl(fd, F_GETFL)) == -1)
    return;
  if (val & O_NONBLOCK) {
    val &= ~O_NONBLOCK;
    fcntl(fd, F_SETFL, val);
  }
}

    3       3 [main] a_test 7516 open_shared: name shared.5, n 5, shared 0x60FC0000 (wanted 0x60FC0000), h 0x1A4
  209     212 [main] a_test 7516 heap_init: heap base 0xC60000, heap top 0xC60000
   83     295 [main] a_test 7516 open_shared: name S-1-5-21-3400765896-2285074925-4230561286-1000.1, n 1, shared 0x60FD0000 (wanted 0x60FD0000), h 0x1AC
   43     338 [main] a_test 7516 user_shared_create: opening user shared for 'S-1-5-21-3400765896-2285074925-4230561286-1000' at 0x60FD0000
   41     379 [main] a_test 7516 user_shared_create: user shared version 2E710001
   51     430 [main] a_test 7516 events_init: windows_system_directory 'C:\Windows\system32\', windows_system_directory_length 20
   52     482 [main] a_test 7516 dll_crt0_0: finished dll_crt0_0 initialization
   89     571 [main] a_test 7516 _cygtls::remove: wait 0xFFFFFFFF
   48     619 [main] a_test 7516 _cygtls::remove: removed 0x28CE64 element 0
 7367    7986 [main] a_test 7516 _cygwin_istext_for_stdio: fd 0: not open
   66    8052 [main] a_test 7516 _cygwin_istext_for_stdio: fd 1: not open
   64    8116 [main] a_test 7516 _cygwin_istext_for_stdio: fd 2: not open
  325    8441 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6, no-keep-rel, no-add-slash)
   67    8508 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\tools\rsync-3.0.6 = normalize_win32_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6)
   41    8549 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/tools/rsync-3.0.6 = conv_to_posix_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6)
  104    8653 [main] a_test (7516) open_shared: name cygpid.7516, n 7516, shared 0x60FF0000 (wanted 0x60FF0000), h 0x284
  215    8868 [main] a_test 7516 **********************************************
   52    8920 [main] a_test 7516 Program name: C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.exe (pid 7516, ppid 1)
   39    8959 [main] a_test 7516 App version:  1007.0, api: 0.217
   38    8997 [main] a_test 7516 DLL version:  1007.0, api: 0.217
   39    9036 [main] a_test 7516 DLL build:    2009-11-10 13:03
   39    9075 [main] a_test 7516 OS version:   Windows NT-6.1
   39    9114 [main] a_test 7516 Heap size:    402653184
   39    9153 [main] a_test 7516 **********************************************
   38    9191 [main] a_test 7516 pinfo::thisproc: myself->dwProcessId 7516
   40    9231 [main] a_test 7516 time: 1258064094 = time (0)
 2838   12069 [main] a_test 7516 parse_options: glob (called func)
   81   12150 [main] a_test 7516 parse_options: returning
  106   12256 [main] a_test 7516 environ_init: GetEnvironmentStrings returned 0x4CA3F8
  118   12374 [main] a_test 7516 environ_init: 0xC88298: !C:=C:\cygwin\bin
   65   12439 [main] a_test 7516 environ_init: 0xC882B0: ALLUSERSPROFILE=C:\ProgramData
   61   12500 [main] a_test 7516 environ_init: 0xC882D8: ANT_HOME=/home/Eliot/bin/ant-home
   65   12565 [main] a_test 7516 environ_init: 0xC88300: APPDATA=C:\Users\Eliot\AppData\Roaming
   67   12632 [main] a_test 7516 environ_init: 0xC88330: CDPATH=.:/home/Eliot:/home/Eliot/church:/home/Eliot/courses:/home/Eliot/orgs:/home/Eliot/papers:/home/Eliot/people:/home/Eliot/projects:/home/Eliot/props:/home/Eliot/tools:/home/Eliot/courses/610
   67   12699 [main] a_test 7516 environ_init: 0xC88400: CLASSPATH=.;C:\Program Files (x86)\Java\jre6\lib\ext\QTJava.zip
   64   12763 [main] a_test 7516 environ_init: 0xC88448: COMMONPROGRAMFILES=C:\Program Files (x86)\Common Files
   64   12827 [main] a_test 7516 environ_init: 0xC88488: COMPUTERNAME=ELIOT-TABLET-09
   64   12891 [main] a_test 7516 environ_init: 0xC884B0: COMSPEC=C:\Windows\system32\cmd.exe
   64   12955 [main] a_test 7516 environ_init: 0xC884E0: CVS_RSH=sshbf
   64   13019 [main] a_test 7516 environ_init: 0xC884F8: CYGWIN=noglob
   65   13084 [main] a_test 7516 environ_init: 0xC88510: CYGWIN_ROOT=C:\cygwin
   64   13148 [main] a_test 7516 environ_init: 0xC88530: CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files
   65   13213 [main] a_test 7516 environ_init: 0xC88578: CommonProgramW6432=C:\Program Files\Common Files
   92   13305 [main] a_test 7516 environ_init: 0xC885B0: DEFLOGDIR=C:\ProgramData\McAfee\DesktopProtection
   68   13373 [main] a_test 7516 environ_init: 0xC885E8: DFSTRACINGON=FALSE
   64   13437 [main] a_test 7516 environ_init: 0xC88600: DISPLAY=:0.0
   65   13502 [main] a_test 7516 environ_init: 0xC88618: EDITOR=xemacs -nw
   64   13566 [main] a_test 7516 environ_init: 0xC88630: FORTRESS_BASE=/home/Eliot/tools/fortress
   64   13630 [main] a_test 7516 environ_init: 0xC88660: FORTRESS_HOME=C:/cygwin/home/Eliot/tools/fortress
   64   13694 [main] a_test 7516 environ_init: 0xC88698: FP_NO_HOST_CHECK=NO
   65   13759 [main] a_test 7516 getwinenv: can't set native for HOME= since no environ yet
   42   13801 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot, no-keep-rel, no-add-slash)
   35   13836 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot = normalize_win32_path (C:\cygwin\home\Eliot)
   43   13879 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot = conv_to_posix_path (C:\cygwin\home\Eliot)
   89   13968 [main] a_test 7516 win_env::add_cache: posix /home/Eliot
   39   14007 [main] a_test 7516 win_env::add_cache: native HOME=C:\cygwin\home\Eliot
   38   14045 [main] a_test 7516 posify: env var converted to HOME=/home/Eliot
   91   14136 [main] a_test 7516 environ_init: 0xC88708: HOME=/home/Eliot
   66   14202 [main] a_test 7516 environ_init: 0xC886B8: HOMEDRIVE=C:
   64   14266 [main] a_test 7516 environ_init: 0xC88720: HOMEPATH=\Users\Eliot
   65   14331 [main] a_test 7516 environ_init: 0xC88740: HOSTNAME=Eliot-Tablet-09
   67   14398 [main] a_test 7516 environ_init: 0xC88760: INFOPATH=/usr/local/info:/usr/share/info:/usr/info:/usr/local/info:/usr/share/info:/usr/info:
   65   14463 [main] a_test 7516 environ_init: 0xC887C8: JAVA_HOME=/c/Program Files/Java/jdk1.6.0
   64   14527 [main] a_test 7516 environ_init: 0xC887F8: JAVA_HOME_1_6=/c/Program Files/Java/jdk1.6.0
   64   14591 [main] a_test 7516 environ_init: 0xC88830: JAVA_HOME_1_6_0=/c/Program Files/Java/jdk1.6.0
   64   14655 [main] a_test 7516 environ_init: 0xC88868: JAVA_VERSION=1.6.0
   64   14719 [main] a_test 7516 environ_init: 0xC88880: JDK_HOME=/c/Program Files/Java/jdk1.6.0
   64   14783 [main] a_test 7516 environ_init: 0xC888B0: JDK_HOME_1_6=/c/Program Files/Java/jdk1.6.0
   69   14852 [main] a_test 7516 environ_init: 0xC888E8: JDK_HOME_1_6_0=/c/Program Files/Java/jdk1.6.0
   64   14916 [main] a_test 7516 environ_init: 0xC88920: JRE_HOME=/c/Program Files/Java/jdk1.6.0
   64   14980 [main] a_test 7516 environ_init: 0xC88950: JRE_HOME_1_6=/c/Program Files/Java/jre1.6.0
   64   15044 [main] a_test 7516 environ_init: 0xC88988: JRE_HOME_1_6_0=/c/Program Files/Java/jre1.6.0
   64   15108 [main] a_test 7516 environ_init: 0xC889C0: JVUNDER=1_6_0
   64   15172 [main] a_test 7516 environ_init: 0xC889D8: LANG=en_US.UTF-8
   64   15236 [main] a_test 7516 environ_init: 0xC889F0: LOCALAPPDATA=C:\Users\Eliot\AppData\Local
   64   15300 [main] a_test 7516 environ_init: 0xC88A20: LOGNAME=Eliot
   83   15383 [main] a_test 7516 environ_init: 0xC88A38: LOGONSERVER=\\ELIOT-TABLET-09
   90   15473 [main] a_test 7516 environ_init: 0xC88A60: MANPATH=/usr/man:/usr/local/man:/usr/share/man:/usr/local/man:/usr/share/man:/usr/man:/usr/man:/usr/local/man:/usr/share/man:/usr/local/man:/usr/share/man:/usr/man::/usr/ssl/man:/usr/X11R6/share/man:/usr/local/lib/xemacs/xeamcs-packages/man:/usr/share/xemacs/xemacs-packages/man:/usr/share/xemacs/mule-packages/man:/usr/autotool/devel/share/man:/var/cache/man:/usr/ssl/man:/usr/X11R6/share/man:/usr/local/lib/xemacs/xeamcs-packages/man:/usr/share/xemacs/xemacs-packages/man:/usr/share/xemacs/mule-packages/man:/usr/autotool/devel/share/man:/var/cache/man
   81   15554 [main] a_test 7516 environ_init: 0xC88C90: NUMBER_OF_PROCESSORS=2
   63   15617 [main] a_test 7516 environ_init: 0xC88CB0: OLDPWD=/home/Eliot/talks
   64   15681 [main] a_test 7516 environ_init: 0xC88CD0: OS=Windows_NT
   68   15749 [main] a_test 7516 environ_init: 0xC88CE8: PAPERSIZE=letter
   99   15848 [main] a_test 7516 getwinenv: can't set native for PATH= since no environ yet
   73   15921 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\bin, keep-rel, no-add-slash)
   38   15959 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\bin = normalize_win32_path (C:\cygwin\home\Eliot\bin)
   39   15998 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/bin = conv_to_posix_path (C:\cygwin\home\Eliot\bin)
   39   16037 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\miktex2.8\miktex\bin, keep-rel, no-add-slash)
   39   16076 [main] a_test 7516 normalize_win32_path: C:\miktex2.8\miktex\bin = normalize_win32_path (C:\miktex2.8\miktex\bin)
   39   16115 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/miktex2.8/miktex/bin = conv_to_posix_path (C:\miktex2.8\miktex\bin)
   38   16153 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\usr\local\bin, keep-rel, no-add-slash)
   39   16192 [main] a_test 7516 normalize_win32_path: C:\cygwin\usr\local\bin = normalize_win32_path (C:\cygwin\usr\local\bin)
   38   16230 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/local/bin = conv_to_posix_path (C:\cygwin\usr\local\bin)
   39   16269 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   39   16308 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   39   16347 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   38   16385 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   38   16423 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   39   16462 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   16501 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\usr\X11R6\bin, keep-rel, no-add-slash)
   39   16540 [main] a_test 7516 normalize_win32_path: C:\cygwin\usr\X11R6\bin = normalize_win32_path (C:\cygwin\usr\X11R6\bin)
   38   16578 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/X11R6/bin = conv_to_posix_path (C:\cygwin\usr\X11R6\bin)
   39   16617 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\bin, keep-rel, no-add-slash)
   38   16655 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\bin = normalize_win32_path (C:\cygwin\home\Eliot\bin)
   39   16694 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/bin = conv_to_posix_path (C:\cygwin\home\Eliot\bin)
   39   16733 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\miktex2.8\miktex\bin, keep-rel, no-add-slash)
   39   16772 [main] a_test 7516 normalize_win32_path: C:\miktex2.8\miktex\bin = normalize_win32_path (C:\miktex2.8\miktex\bin)
   63   16835 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/miktex2.8/miktex/bin = conv_to_posix_path (C:\miktex2.8\miktex\bin)
   39   16874 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\usr\local\bin, keep-rel, no-add-slash)
   39   16913 [main] a_test 7516 normalize_win32_path: C:\cygwin\usr\local\bin = normalize_win32_path (C:\cygwin\usr\local\bin)
   39   16952 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/local/bin = conv_to_posix_path (C:\cygwin\usr\local\bin)
   39   16991 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   38   17029 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   38   17067 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   17106 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   40   17146 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   40   17186 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   17225 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin, keep-rel, no-add-slash)
   38   17263 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\Java\jdk1.6.0_15\bin = normalize_win32_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin)
   66   17329 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin = conv_to_posix_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin)
   38   17367 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin, keep-rel, no-add-slash)
   39   17406 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\Java\jdk1.6.0_15\bin = normalize_win32_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin)
   38   17444 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin = conv_to_posix_path (C:\Program Files (x86)\Java\jdk1.6.0_15\bin)
   39   17483 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\usr\X11R6\bin, keep-rel, no-add-slash)
   40   17523 [main] a_test 7516 normalize_win32_path: C:\cygwin\usr\X11R6\bin = normalize_win32_path (C:\cygwin\usr\X11R6\bin)
   35   17558 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/X11R6/bin = conv_to_posix_path (C:\cygwin\usr\X11R6\bin)
   41   17599 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   39   17638 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   38   17676 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   17715 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\miktex2.8\miktex\bin, keep-rel, no-add-slash)
   38   17753 [main] a_test 7516 normalize_win32_path: C:\miktex2.8\miktex\bin = normalize_win32_path (C:\miktex2.8\miktex\bin)
   39   17792 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/miktex2.8/miktex/bin = conv_to_posix_path (C:\miktex2.8\miktex\bin)
   39   17831 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (%CommonProgramFiles%\Microsoft Shared\Windows Live, keep-rel, no-add-slash)
   39   17870 [main] a_test 7516 mount_info::conv_to_posix_path: %CommonProgramFiles%/Microsoft Shared/Windows Live = conv_to_posix_path (%CommonProgramFiles%\Microsoft Shared\Windows Live)
   38   17908 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\system32, keep-rel, no-add-slash)
   39   17947 [main] a_test 7516 normalize_win32_path: C:\Windows\system32 = normalize_win32_path (C:\Windows\system32)
   38   17985 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Windows/system32 = conv_to_posix_path (C:\Windows\system32)
   39   18024 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows, keep-rel, no-add-slash)
   39   18063 [main] a_test 7516 normalize_win32_path: C:\Windows = normalize_win32_path (C:\Windows)
   38   18101 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Windows = conv_to_posix_path (C:\Windows)
   39   18140 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\System32\Wbem, keep-rel, no-add-slash)
   38   18178 [main] a_test 7516 normalize_win32_path: C:\Windows\System32\Wbem = normalize_win32_path (C:\Windows\System32\Wbem)
   39   18217 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Windows/System32/Wbem = conv_to_posix_path (C:\Windows\System32\Wbem)
   39   18256 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\System32\WindowsPowerShell\v1.0\, keep-rel, add-slash)
   58   18314 [main] a_test 7516 normalize_win32_path: C:\Windows\System32\WindowsPowerShell\v1.0\ = normalize_win32_path (C:\Windows\System32\WindowsPowerShell\v1.0\)
   56   18370 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Windows/System32/WindowsPowerShell/v1.0/ = conv_to_posix_path (C:\Windows\System32\WindowsPowerShell\v1.0\)
   41   18411 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Graphviz2.24\bin, keep-rel, no-add-slash)
   39   18450 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\Graphviz2.24\bin = normalize_win32_path (C:\Program Files (x86)\Graphviz2.24\bin)
   39   18489 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Graphviz2.24/bin = conv_to_posix_path (C:\Program Files (x86)\Graphviz2.24\bin)
   39   18528 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\QuickTime\QTSystem\, keep-rel, add-slash)
   38   18566 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\QuickTime\QTSystem\ = normalize_win32_path (C:\Program Files (x86)\QuickTime\QTSystem\)
   39   18605 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/QuickTime/QTSystem/ = conv_to_posix_path (C:\Program Files (x86)\QuickTime\QTSystem\)
   39   18644 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\, keep-rel, add-slash)
   38   18682 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\ = normalize_win32_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\)
   39   18721 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/ = conv_to_posix_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\)
   40   18761 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\x64\, keep-rel, add-slash)
   45   18806 [main] a_test 7516 normalize_win32_path: C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\x64\ = normalize_win32_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\x64\)
   40   18846 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/x64/ = conv_to_posix_path (C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\x64\)
   38   18884 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files\Common Files\Microsoft Shared\Windows Live, keep-rel, no-add-slash)
   38   18922 [main] a_test 7516 normalize_win32_path: C:\Program Files\Common Files\Microsoft Shared\Windows Live = normalize_win32_path (C:\Program Files\Common Files\Microsoft Shared\Windows Live)
   40   18962 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Program Files/Common Files/Microsoft Shared/Windows Live = conv_to_posix_path (C:\Program Files\Common Files\Microsoft Shared\Windows Live)
   39   19001 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   38   19039 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   38   19077 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   19116 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\bin, keep-rel, no-add-slash)
   38   19154 [main] a_test 7516 normalize_win32_path: C:\cygwin\bin = normalize_win32_path (C:\cygwin\bin)
   38   19192 [main] a_test 7516 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (C:\cygwin\bin)
   39   19231 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\projects\tisean\bin, keep-rel, no-add-slash)
   39   19270 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\projects\tisean\bin = normalize_win32_path (C:\cygwin\home\Eliot\projects\tisean\bin)
   39   19309 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/projects/tisean/bin = conv_to_posix_path (C:\cygwin\home\Eliot\projects\tisean\bin)
   41   19350 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\tools\fortress\bin, keep-rel, no-add-slash)
   38   19388 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\tools\fortress\bin = normalize_win32_path (C:\cygwin\home\Eliot\tools\fortress\bin)
   38   19426 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/tools/fortress/bin = conv_to_posix_path (C:\cygwin\home\Eliot\tools\fortress\bin)
   39   19465 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (.\, keep-rel, add-slash)
   38   19503 [main] a_test 7516 mount_info::conv_to_posix_path: ./ = conv_to_posix_path (.\)
   92   19595 [main] a_test 7516 win_env::add_cache: posix /home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/usr/X11R6/bin:/home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/usr/X11R6/bin:/usr/bin:/cygdrive/c/miktex2.8/miktex/bin:%CommonProgramFiles%/Microsoft Shared/Windows Live:/cygdrive/c/Windows/system32:/cygdrive/c/Windows:/cygdrive/c/Windows/System32/Wbem:/cygdrive/c/Windows/System32/WindowsPowerShell/v1.0/:/cygdrive/c/Program Files (x86)/Graphviz2.24/bin:/cygdrive/c/Program Files (x86)/QuickTime/QTSystem/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/x64/:/cygdrive/c/Program Files/Common Files/Microsoft Shared/Windows Live:/usr/bin:/usr/bin:/home/Eliot/projects/tisean/bin:/home/Eliot/tools/fortress/bin:./
   41   19636 [main] a_test 7516 win_env::add_cache: native PATH=C:\cygwin\home\Eliot\bin;C:\miktex2.8\miktex\bin;C:\cygwin\usr\local\bin;C:\cygwin\bin;C:\cygwin\bin;C:\cygwin\usr\X11R6\bin;C:\cygwin\home\Eliot\bin;C:\miktex2.8\miktex\bin;C:\cygwin\usr\local\bin;C:\cygwin\bin;C:\cygwin\bin;C:\Program Files (x86)\Java\jdk1.6.0_15\bin;C:\Program Files (x86)\Java\jdk1.6.0_15\bin;C:\cygwin\usr\X11R6\bin;C:\cygwin\bin;C:\miktex2.8\miktex\bin;%CommonProgramFiles%\Microsoft Shared\Windows Live;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Graphviz2.24\bin;C:\Program Files (x86)\QuickTime\QTSystem\;C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\;C:\Program Files (x86)\Toshiba\Bluetooth Toshiba Stack\sys\x64\;C:\Program Files\Common Files\Microsoft Shared\Windows Live;C:\cygwin\bin;C:\cygwin\bin;C:\cygwin\home\Eliot\projects\tisean\bin;C:\cygwin\home\Eliot\tools\fortress\bin;.\
   42   19678 [main] a_test 7516 posify: env var converted to PATH=/home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/usr/X11R6/bin:/home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/usr/X11R6/bin:/usr/bin:/cygdrive/c/miktex2.8/miktex/bin:%CommonProgramFiles%/Microsoft Shared/Windows Live:/cygdrive/c/Windows/system32:/cygdrive/c/Windows:/cygdrive/c/Windows/System32/Wbem:/cygdrive/c/Windows/System32/WindowsPowerShell/v1.0/:/cygdrive/c/Program Files (x86)/Graphviz2.24/bin:/cygdrive/c/Program Files (x86)/QuickTime/QTSystem/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/x64/:/cygdrive/c/Program Files/Common Files/Microsoft Shared/Windows Live:/usr/bin:/usr/bin:/home/Eliot/projects/tisean/bin:/home/Eliot/tools/fortress/bin:./
  101   19779 [main] a_test 7516 environ_init: 0xC997E0: PATH=/home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/usr/X11R6/bin:/home/Eliot/bin:/cygdrive/c/miktex2.8/miktex/bin:/usr/local/bin:/usr/bin:/usr/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/cygdrive/c/Program Files (x86)/Java/jdk1.6.0_15/bin:/usr/X11R6/bin:/usr/bin:/cygdrive/c/miktex2.8/miktex/bin:%CommonProgramFiles%/Microsoft Shared/Windows Live:/cygdrive/c/Windows/system32:/cygdrive/c/Windows:/cygdrive/c/Windows/System32/Wbem:/cygdrive/c/Windows/System32/WindowsPowerShell/v1.0/:/cygdrive/c/Program Files (x86)/Graphviz2.24/bin:/cygdrive/c/Program Files (x86)/QuickTime/QTSystem/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/:/cygdrive/c/Program Files (x86)/Toshiba/Bluetooth Toshiba Stack/sys/x64/:/cygdrive/c/Program Files/Common Files/Microsoft Shared/Windows Live:/usr/bin:/usr/bin:/home/Eliot/projects/tisean/bin:/home/Eliot/tools/fortress/bin:./
   72   19851 [main] a_test 7516 environ_init: 0xC88D00: PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
   68   19919 [main] a_test 7516 environ_init: 0xC88D48: PFILES=/c/Program Files
   64   19983 [main] a_test 7516 environ_init: 0xC88D68: PRINTER=\\printserver1\bookman
   62   20045 [main] a_test 7516 environ_init: 0xC88D90: PROCESSOR_ARCHITECTURE=x86
   66   20111 [main] a_test 7516 environ_init: 0xC88DB0: PROCESSOR_ARCHITEW6432=AMD64
   63   20174 [main] a_test 7516 environ_init: 0xC88DD8: PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 23 Stepping 10, GenuineIntel
   64   20238 [main] a_test 7516 environ_init: 0xC88E28: PROCESSOR_LEVEL=6
   76   20314 [main] a_test 7516 environ_init: 0xC88E40: PROCESSOR_REVISION=170a
   65   20379 [main] a_test 7516 environ_init: 0xC88E60: PROGRAMFILES=C:\Program Files (x86)
   63   20442 [main] a_test 7516 environ_init: 0xC88E90: PROMPT=$P$G
   64   20506 [main] a_test 7516 environ_init: 0xC88EA8: PS1=\u@Toshiba$
   65   20571 [main] a_test 7516 environ_init: 0xC88EC0: PSModulePath=C:\Windows\system32\WindowsPowerShell\v1.0\Modules\
   64   20635 [main] a_test 7516 environ_init: 0xC88F08: PUBLIC=C:\Users\Public
   65   20700 [main] a_test 7516 environ_init: 0xC88F28: PWD=/home/Eliot/tools/rsync-3.0.6
   68   20768 [main] a_test 7516 environ_init: 0xC88F50: ProgramData=C:\ProgramData
   65   20833 [main] a_test 7516 environ_init: 0xC88F70: ProgramFiles(x86)=C:\Program Files (x86)
   63   20896 [main] a_test 7516 environ_init: 0xC88FA0: ProgramW6432=C:\Program Files
  644   21540 [main] a_test 7516 environ_init: 0xC88FC8: QTJAVA=C:\Program Files (x86)\Java\jre6\lib\ext\QTJava.zip
   66   21606 [main] a_test 7516 environ_init: 0xC89008: RHOST=roc
   59   21665 [main] a_test 7516 environ_init: 0xC89018: RHOSTDIR=.
   59   21724 [main] a_test 7516 environ_init: 0xC89028: RSYNC_RSH=sshbf
   58   21782 [main] a_test 7516 environ_init: 0xC89040: RUN=C:\cygwin\bin\run -p /usr/bin
   60   21842 [main] a_test 7516 environ_init: 0xC89068: SESSIONNAME=Console
   59   21901 [main] a_test 7516 environ_init: 0xC89088: SHLVL=4
   59   21960 [main] a_test 7516 environ_init: 0xC99B88: SHORTNAME=Toshiba
   59   22019 [main] a_test 7516 environ_init: 0xC99BA0: SVN_SSH=sshbf
   59   22078 [main] a_test 7516 environ_init: 0xC99BB8: SYSTEMDRIVE=C:
   59   22137 [main] a_test 7516 environ_init: 0xC99BD0: SYSTEMROOT=C:\Windows
   97   22234 [main] a_test 7516 getwinenv: can't set native for TEMP= since no environ yet
   37   22271 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\Eliot\AppData\Local\Temp, no-keep-rel, no-add-slash)
   37   22308 [main] a_test 7516 normalize_win32_path: C:\Users\Eliot\AppData\Local\Temp = normalize_win32_path (C:\Users\Eliot\AppData\Local\Temp)
   39   22347 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Users/Eliot/AppData/Local/Temp = conv_to_posix_path (C:\Users\Eliot\AppData\Local\Temp)
   80   22427 [main] a_test 7516 win_env::add_cache: posix /cygdrive/c/Users/Eliot/AppData/Local/Temp
   50   22477 [main] a_test 7516 win_env::add_cache: native TEMP=C:\Users\Eliot\AppData\Local\Temp
   36   22513 [main] a_test 7516 posify: env var converted to TEMP=/cygdrive/c/Users/Eliot/AppData/Local/Temp
   87   22600 [main] a_test 7516 environ_init: 0xC99C80: TEMP=/cygdrive/c/Users/Eliot/AppData/Local/Temp
   63   22663 [main] a_test 7516 environ_init: 0xC99BF0: TERM=xterm
   78   22741 [main] a_test 7516 environ_init: 0xC99CB8: TERMCAP=xterm-r6|xterm|xterm X11R6 version:am:km:mi:ms:xn:co#103:it#8:li#37:AL=\E[%dL:DC=\E[%dP:DL=\E[%dM:DO=\E[%dB:LE=\E[%dD:RI=\E[%dC:UP=\E[%dA:ae=^O:al=\E[L:as=^N:bl=^G:cd=\E[J:ce=\E[K:cl=\E[H\E[2J:cm=\E[%i%d;%dH:cr=^M:cs=\E[%i%d;%dr:ct=\E[3g:dc=\E[P:dl=\E[M:do=^J:ei=\E[4l:ho=\E[H:im=\E[4h:is=\E7\E[r\E[m\E[?7h\E[?1;3;4;6l\E[4l\E8\E>:k1=\EOP:k2=\EOQ:k3=\EOR:k4=\EOS:k5=\E[15~:k6=\E[17~:k7=\E[18~:k8=\E[19~:k9=\E[20~:kD=\E[3~:kI=\E[2~:kN=\E[6~:kP=\E[5~:kd=\EOB:ke=\E[?1l\E>:kh=\E[1~:kl=\EOD:kr=\EOC:ks=\E[?1h\E=:ku=\EOA:le=^H:md=\E[1m:me=\E[m:mr=\E[7m:nd=\E[C:rc=\E8:sc=\E7:se=\E[m:sf=^J:so=\E[7m:sr=\EM:ta=^I:te=\E[2J\E[?47l\E8:ti=\E7\E[?47h:ue=\E[m:up=\E[A:us=\E[4m:kb=\177:
   69   22810 [main] a_test 7516 environ_init: 0xC99C00: TEXDOCVIEW_dvi=cygstart %s
   64   22874 [main] a_test 7516 environ_init: 0xC99F68: TEXDOCVIEW_html=cygstart %s
  128   23002 [main] a_test 7516 environ_init: 0xC99F90: TEXDOCVIEW_pdf=cygstart %s
   64   23066 [main] a_test 7516 environ_init: 0xC99FB0: TEXDOCVIEW_ps=cygstart %s
   68   23134 [main] a_test 7516 environ_init: 0xC99FD0: TEXDOCVIEW_txt=cygstart %s
   69   23203 [main] a_test 7516 environ_init: 0xC99FF0: TEXINPUTS=.:/home/Eliot/tex:/home/Eliot/tex/extra-fonts:
   66   23269 [main] a_test 7516 getwinenv: can't set native for TMP= since no environ yet
   36   23305 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\Eliot\AppData\Local\Temp, no-keep-rel, no-add-slash)
   37   23342 [main] a_test 7516 normalize_win32_path: C:\Users\Eliot\AppData\Local\Temp = normalize_win32_path (C:\Users\Eliot\AppData\Local\Temp)
   37   23379 [main] a_test 7516 mount_info::conv_to_posix_path: /cygdrive/c/Users/Eliot/AppData/Local/Temp = conv_to_posix_path (C:\Users\Eliot\AppData\Local\Temp)
   81   23460 [main] a_test 7516 win_env::add_cache: posix /cygdrive/c/Users/Eliot/AppData/Local/Temp
   36   23496 [main] a_test 7516 win_env::add_cache: native TMP=C:\Users\Eliot\AppData\Local\Temp
   35   23531 [main] a_test 7516 posify: env var converted to TMP=/cygdrive/c/Users/Eliot/AppData/Local/Temp
   78   23609 [main] a_test 7516 environ_init: 0xC9A0C0: TMP=/cygdrive/c/Users/Eliot/AppData/Local/Temp
   61   23670 [main] a_test 7516 environ_init: 0xC9A0F8: TRACE_FORMAT_SEARCH_PATH=\\NTREL202.ntdev.corp.microsoft.com\34FB5F65-FFEB-4B61-BF0E-A6A76C450FAA\TraceFormat
   61   23731 [main] a_test 7516 environ_init: 0xC9A030: TZ=America/New_York
   58   23789 [main] a_test 7516 environ_init: 0xC9A050: USER=Eliot
   58   23847 [main] a_test 7516 environ_init: 0xC9A170: USERDOMAIN=Eliot-Tablet-09
   59   23906 [main] a_test 7516 environ_init: 0xC9A190: USERNAME=Eliot
   57   23963 [main] a_test 7516 environ_init: 0xC9A1A8: USERPROFILE=C:\Users\Eliot
   59   24022 [main] a_test 7516 environ_init: 0xC9A1C8: VSEDEFLOGDIR=C:\ProgramData\McAfee\DesktopProtection
   63   24085 [main] a_test 7516 environ_init: 0xC9A208: WINDIR=C:\Windows
   95   24180 [sig] a_test 7516 wait_sig: entering ReadFile loop, my_readsig 0x294, my_sendsig 0x298
   83   24263 [main] a_test 7516 environ_init: 0xC9A220: WINDOWID=10485783
   61   24324 [main] a_test 7516 environ_init: 0xC9A238: XAUTHORITY=/home/Eliot/.Xauthority
   59   24383 [main] a_test 7516 environ_init: 0xC9A260: XTERM_LOCALE=en_US.UTF-8
   59   24442 [main] a_test 7516 environ_init: 0xC9A280: XTERM_SHELL=/bin/bash
   58   24500 [main] a_test 7516 environ_init: 0xC9A2A0: XTERM_VERSION=Cygwin 6.8.99.903(250)
   59   24559 [main] a_test 7516 environ_init: 0xC9A2D0: _=/usr/bin/strace
   58   24617 [main] a_test 7516 environ_init: 0xC9A2E8: __COMPAT_LAYER=ElevateCreateProcess
   71   24688 [main] a_test 7516 pinfo_init: Set nice to 0
   40   24728 [main] a_test 7516 pinfo_init: pid 7516, pgid 7516
  130   24858 [main] a_test 7516 dtable::extend: size 32, fds 0x6120C460
  449   25307 [main] a_test 7516 pwdgrp::load: \etc\passwd curr_lines 8
   56   25363 [main] a_test 7516 pwdgrp::load: \etc\passwd load succeeded
  377   25740 [main] a_test 7516 pwdgrp::load: \etc\group curr_lines 22
   51   25791 [main] a_test 7516 pwdgrp::load: \etc\group load succeeded
   45   25836 [main] a_test 7516 cygheap_user::ontherange: what 2, pw 0xC9A6D8
   38   25874 [main] a_test 7516 cygheap_user::ontherange: HOME is already in the environment /home/Eliot
   38   25912 [main] a_test 7516 wait_for_sigthread: wait_sig_inited 0x88
   40   25952 [main] a_test 7516 wait_for_sigthread: process/signal handling enabled, state 0x41
   95   26047 [main] a_test 7516 build_argv: argv[0] = 'a_test'
   35   26082 [main] a_test 7516 build_argv: argc 1
  235   26317 [main] a_test 7516 normalize_posix_path: src /dev/tty1
   39   26356 [main] a_test 7516 normalize_posix_path: /dev/tty1 = normalize_posix_path (/dev/tty1)
   39   26395 [main] a_test 7516 mount_info::conv_to_win32_path: conv_to_win32_path (/dev/tty1)
   46   26441 [main] a_test 7516 mount_info::conv_to_win32_path: src_path /dev/tty1, dst \dev\tty1, flags 0x2, rc 0
   44   26485 [main] a_test 7516 build_fh_pc: fh 0x6120C5B8
   46   26531 [main] a_test 7516 fhandler_pipe::create_selectable: CreateNamedPipe: name \\.\pipe\cygwin-c5e39b7a9d22bafb-tty1-from-master, size 4096
  201   26732 [main] a_test 7516 fhandler_pipe::create_selectable: pipe busy
   46   26778 [main] a_test 7516 fhandler_base::set_flags: flags 0x10000, supplied_bin 0x0
   40   26818 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   39   26857 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   69   26926 [main] a_test 7516 fhandler_tty_slave::open: (514): tty output_mutex: waiting 500 ms
  113   27039 [main] a_test 7516 fhandler_tty_slave::open: (514): tty output_mutex: acquired
   50   27089 [main] a_test 7516 tty::create_inuse: cygtty.slave_alive.1 0x2A8
   41   27130 [main] a_test 7516 fhandler_tty_slave::open: (517): tty output_mutex released
   40   27170 [main] a_test 7516 client_request_attach_tty::client_request_attach_tty: created: pid = 7516, master_pid = 7676, from_master = 984, to_master = 992
   64   27234 [main] a_test 7516 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-c5e39b7a9d22bafb-lpc
   63   27297 [main] a_test 7516 transport_layer_pipes::connect: Error opening the pipe (2)
   61   27358 [main] a_test 7516 client_request::make_request: cygserver un-available
  122   27480 [main] a_test 7516 open_shared: name cygpid.7676, n 7676, shared 0x340000 (wanted 0x0), h 0x2AC
   49   27529 [main] a_test 7516 fhandler_tty_slave::open: cannot dup handles via server. using old method.
   70   27599 [main] a_test 7516 fhandler_tty_slave::open: duplicated from_master 0x3D8->0x2B4 from tty_owner
   39   27638 [main] a_test 7516 fhandler_tty_slave::open: duplicated to_master 0x3E0->0x2B8 from tty_owner
   40   27678 [main] a_test 7516 init_cygheap::manage_console_count: fhandler_tty_slave::open: console_count 1, amount 1, no ctty, avoid_freeing_console 0
   56   27734 [main] a_test 7516 fhandler_console::need_invisible: invisible_console 0
   43   27777 [main] a_test 7516 fhandler_tty_slave::open: /dev/tty1 opened, usecount 1
   39   27816 [main] a_test 7516 _pinfo::set_ctty: old no ctty
   41   27857 [main] a_test 7516 _pinfo::set_ctty: attaching ctty /dev/tty1 sid 7516, pid 7516, pgid 7516, tty->pgid 7356, tty->sid 8212
   49   27906 [main] a_test 7516 open_shared: name cygpid.8212, n 8212, shared 0x340000 (wanted 0x0), h 0x2AC
   41   27947 [main] a_test 7516 _pinfo::set_ctty: cygheap->ctty 0x0, arch 0x6120C810
   37   27984 [main] a_test 7516 _pinfo::set_ctty: ctty NULL
   34   28018 [main] a_test 7516 init_cygheap::manage_console_count: _pinfo::set_ctty: console_count 2, amount 1, ctty /dev/tty1, avoid_freeing_console 0
   37   28055 [main] a_test 7516 _pinfo::set_ctty: /dev/tty1 ctty, usecount 2
 3781   31836 [main] a_test 7516 handle_to_fn: current match 'C:' = '\Device\HarddiskVolume2'
  355   32191 [main] a_test 7516 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace, no-keep-rel, no-add-slash)
   66   32257 [main] a_test 7516 normalize_win32_path: C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace = normalize_win32_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace)
   45   32302 [main] a_test 7516 mount_info::conv_to_posix_path: /home/Eliot/tools/rsync-3.0.6/a_test.strace = conv_to_posix_path (C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace)
   38   32340 [main] a_test 7516 handle_to_fn: derived path 'C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace', posix '/home/Eliot/tools/rsync-3.0.6/a_test.strace'
   40   32380 [main] a_test 7516 normalize_posix_path: src /home/Eliot/tools/rsync-3.0.6/a_test.strace
   38   32418 [main] a_test 7516 normalize_posix_path: /home/Eliot/tools/rsync-3.0.6/a_test.strace = normalize_posix_path (/home/Eliot/tools/rsync-3.0.6/a_test.strace)
   37   32455 [main] a_test 7516 mount_info::conv_to_win32_path: conv_to_win32_path (/home/Eliot/tools/rsync-3.0.6/a_test.strace)
   43   32498 [main] a_test 7516 set_flags: flags: binary (0x2)
   37   32535 [main] a_test 7516 mount_info::conv_to_win32_path: src_path /home/Eliot/tools/rsync-3.0.6/a_test.strace, dst C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace, flags 0x3000A, rc 0
  133   32668 [main] a_test 7516 symlink_info::check: not a symlink
   96   32764 [main] a_test 7516 symlink_info::check: 0 = symlink.check (C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace, 0x2839B8) (0x3000A)
   41   32805 [main] a_test 7516 path_conv::check: this->path(C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.strace), has_acls(1)
   43   32848 [main] a_test 7516 build_fh_pc: fh 0x6120CB30
   38   32886 [main] a_test 7516 fhandler_base::set_flags: flags 0x10001, supplied_bin 0x0
   36   32922 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   36   32958 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   37   32995 [main] a_test 7516 fhandler_base::init: created new fhandler_base for handle 0x418, bin 1
  205   33200 [main] a_test 7516 normalize_posix_path: src /dev/tty1
   39   33239 [main] a_test 7516 normalize_posix_path: /dev/tty1 = normalize_posix_path (/dev/tty1)
   36   33275 [main] a_test 7516 mount_info::conv_to_win32_path: conv_to_win32_path (/dev/tty1)
   37   33312 [main] a_test 7516 mount_info::conv_to_win32_path: src_path /dev/tty1, dst \dev\tty1, flags 0x2, rc 0
   38   33350 [main] a_test 7516 build_fh_pc: fh 0x6120CD18
   38   33388 [main] a_test 7516 fhandler_tty_slave::open: copied fhandler_tty_slave archetype
   37   33425 [main] a_test 7516 fhandler_base::set_flags: flags 0x10001, supplied_bin 0x0
   36   33461 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   36   33497 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   36   33533 [main] a_test 7516 init_cygheap::manage_console_count: fhandler_tty_slave::open<arch>: console_count 3, amount 1, ctty /dev/tty1, avoid_freeing_console 0
   37   33570 [main] a_test 7516 fhandler_tty_slave::open: /dev/tty1 opened, usecount 3
   37   33607 [main] a_test 7516 _pinfo::set_ctty: old ctty /dev/tty1
   38   33645 [main] a_test 7516 _pinfo::set_ctty: attaching ctty /dev/tty1 sid 8212, pid 7516, pgid 7516, tty->pgid 7356, tty->sid 8212
   54   33699 [main] a_test 7516 open_shared: name cygpid.8212, n 8212, shared 0x340000 (wanted 0x0), h 0x2AC
  116   33815 [main] a_test 7516 fhandler_console::need_invisible: invisible_console 0
  176   33991 [main] a_test 7516 dll_crt0_1: user_data->main 0x401130
   37   34028 [main] a_test 7516 __set_errno: void dll_crt0_1(void*):935 val 0
  178   34206 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -34, its_me 1
   39   34245 [main] a_test 7516 sig_send: wakeup 0x2BC
   41   34286 [main] a_test 7516 sig_send: Waiting for pack.wakeup 0x2BC
   49   34335 [sig] a_test 7516 wait_sig: signalling pack.wakeup 0x2BC
   48   34383 [main] a_test 7516 sig_send: returning 0x0 from sending signal -34
 6132   40515 [main] a_test 7516 wsock_init: res 0
   60   40575 [main] a_test 7516 wsock_init: wVersion 514
  194   40769 [main] a_test 7516 wsock_init: wHighVersion 514
   35   40804 [main] a_test 7516 wsock_init: szDescription WinSock 2.0
   34   40838 [main] a_test 7516 wsock_init: szSystemStatus Running
   33   40871 [main] a_test 7516 wsock_init: iMaxSockets 0
   33   40904 [main] a_test 7516 wsock_init: iMaxUdpDg 0
   32   40936 [main] a_test 7516 wsock_init: lpVendorInfo 0
83369  124305 [main] a_test 7516 build_fh_pc: fh 0x6120CFA0
  143  124448 [main] a_test 7516 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   52  124500 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   49  124549 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   40  124589 [main] a_test 7516 fdsock: fd 3, name '', soc 0x35C
   71  124660 [main] a_test 7516 build_fh_pc: fh 0x6120D1D8
   63  124723 [main] a_test 7516 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   40  124763 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   38  124801 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   40  124841 [main] a_test 7516 fdsock: fd 4, name '', soc 0x350
   68  124909 [main] a_test 7516 socketpair: 0 = socketpair (...)
   51  124960 [main] a_test 7516 fhandler_base::fcntl: GETFL: 0x10002
   38  124998 [main] a_test 7516 fcntl64: 65538 = fcntl (3, 3, 0x70F30002)
   52  125050 [main] a_test 7516 fhandler_socket::ioctl: socket is now nonblocking
   35  125085 [main] a_test 7516 fhandler_socket::ioctl: 0 = ioctl_socket (8004667E, 28CB38)
   39  125124 [main] a_test 7516 fhandler_base::set_flags: flags 0x14002, supplied_bin 0x0
   39  125163 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   39  125202 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   39  125241 [main] a_test 7516 fcntl64: 0 = fcntl (3, 4, 0x14002)
   39  125280 [main] a_test 7516 fhandler_base::fcntl: GETFL: 0x10002
   39  125319 [main] a_test 7516 fcntl64: 65538 = fcntl (4, 3, 0x14002)
   68  125387 [main] a_test 7516 fhandler_socket::ioctl: socket is now nonblocking
   37  125424 [main] a_test 7516 fhandler_socket::ioctl: 0 = ioctl_socket (8004667E, 28CB38)
   40  125464 [main] a_test 7516 fhandler_base::set_flags: flags 0x14002, supplied_bin 0x0
   39  125503 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   39  125542 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   39  125581 [main] a_test 7516 fcntl64: 0 = fcntl (4, 4, 0x14002)
   41  125622 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -34, its_me 1
   39  125661 [main] a_test 7516 sig_send: wakeup 0x368
   43  125704 [main] a_test 7516 sig_send: Waiting for pack.wakeup 0x368
   41  125745 [sig] a_test 7516 wait_sig: signalling pack.wakeup 0x368
   58  125803 [main] a_test 7516 sig_send: returning 0x0 from sending signal -34
 2459  128262 [main] a_test 7516 build_fh_pc: fh 0x6120D410
   74  128336 [main] a_test 7516 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   39  128375 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   39  128414 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   40  128454 [main] a_test 7516 fdsock: fd 5, name '', soc 0x388
   66  128520 [main] a_test 7516 build_fh_pc: fh 0x6120D648
   69  128589 [main] a_test 7516 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   45  128634 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   66  128700 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   39  128739 [main] a_test 7516 fdsock: fd 6, name '', soc 0x37C
   64  128803 [main] a_test 7516 socketpair: 0 = socketpair (...)
   49  128852 [main] a_test 7516 fhandler_base::fcntl: GETFL: 0x10002
   38  128890 [main] a_test 7516 fcntl64: 65538 = fcntl (5, 3, 0x72F30002)
   51  128941 [main] a_test 7516 fhandler_socket::ioctl: socket is now nonblocking
   42  128983 [main] a_test 7516 fhandler_socket::ioctl: 0 = ioctl_socket (8004667E, 28CB38)
   44  129027 [main] a_test 7516 fhandler_base::set_flags: flags 0x14002, supplied_bin 0x0
   39  129066 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   67  129133 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   40  129173 [main] a_test 7516 fcntl64: 0 = fcntl (5, 4, 0x14002)
   36  129209 [main] a_test 7516 fhandler_base::fcntl: GETFL: 0x10002
   37  129246 [main] a_test 7516 fcntl64: 65538 = fcntl (6, 3, 0x14002)
   45  129291 [main] a_test 7516 fhandler_socket::ioctl: socket is now nonblocking
   39  129330 [main] a_test 7516 fhandler_socket::ioctl: 0 = ioctl_socket (8004667E, 28CB38)
   50  129380 [main] a_test 7516 fhandler_base::set_flags: flags 0x14002, supplied_bin 0x0
   39  129419 [main] a_test 7516 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   40  129459 [main] a_test 7516 fhandler_base::set_flags: filemode set to binary
   39  129498 [main] a_test 7516 fcntl64: 0 = fcntl (6, 4, 0x14002)
   45  129543 [main] a_test 7516 child_info::child_info: subproc_ready 0x390
   45  129588 [main] a_test 7516 fork: entering
  323  129911 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -40, its_me 1
   40  129951 [main] a_test 7516 sig_send: wakeup 0x3A8
   41  129992 [main] a_test 7516 sig_send: Waiting for pack.wakeup 0x3A8
   38  130030 [sig] a_test 7516 wait_sig: signalling pack.wakeup 0x3A8
   40  130070 [main] a_test 7516 sig_send: returning 0x0 from sending signal -40
   57  130127 [main] a_test 7516 frok::parent: priority class 32
  581  130708 [main] a_test 7516 frok::parent: stack - bottom 0x290000, top 0x28CB50, size 13488
   54  130762 [main] a_test 7516 frok::parent: CreateProcess (C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.exe, C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.exe, 0, 0, 1, 0x20, 0, 0, 0x28CAC0, 0x28CB20)
   39  130801 [main] a_test 7516 time: 1258064094 = time (0)
56242  187043 [main] a_test 7516 child_info::sync: n 2, waiting for subproc_ready(0x390) and child process(0x3B0)
    3       3 [main] a_test 5244 child_copy: cygheap - hp 0x394 low 0x6120B6C0, high 0x6120D870, res 1
   87      90 [main] a_test 5244 child_copy: done
   88     178 [main] a_test 5244 open_shared: name shared.5, n 5, shared 0x60FC0000 (wanted 0x60FC0000), h 0x188
89520   89698 [main] a_test 5244 heap_init: heap base 0xC60000, heap top 0xCA0000
  850   90548 [main] a_test 5244 open_shared: name (null), n 1, shared 0x60FD0000 (wanted 0x60FD0000), h 0x1AC
   63   90611 [main] a_test 5244 user_shared_create: opening user shared for '' at 0x60FD0000
   86   90697 [main] a_test 5244 user_shared_create: user shared version 2E710001
  179   90876 [main] a_test (5244) open_shared: name cygpid.5244, n 5244, shared 0x60FF0000 (wanted 0x60FF0000), h 0x190
  135   91011 [main] a_test 5244 **********************************************
   44   91055 [main] a_test 5244 Program name: C:\cygwin\home\Eliot\tools\rsync-3.0.6\a_test.exe (pid 5244, ppid 1)
   61   91116 [main] a_test 5244 App version:  1007.0, api: 0.217
   38   91154 [main] a_test 5244 DLL version:  1007.0, api: 0.217
   38   91192 [main] a_test 5244 DLL build:    2009-11-10 13:03
   38   91230 [main] a_test 5244 OS version:   Windows NT-6.1
   36   91266 [main] a_test 5244 Heap size:    402653184
  115   91381 [main] a_test 5244 **********************************************
   49   91430 [main] a_test 5244 pinfo::thisproc: myself->dwProcessId 5244
  120   91550 [main] a_test 5244 child_copy: dll data - hp 0x394 low 0x61146000, high 0x6114D304, res 1
202142  293692 [main] a_test 5244 child_copy: dll bss - hp 0x394 low 0x611B2000, high 0x611DC690, res 1
  343  294035 [main] a_test 5244 child_copy: user heap - hp 0x394 low 0xC60000, high 0xCA0000, res 1
   39  294074 [main] a_test 5244 child_copy: done
   46  294120 [main] a_test 5244 child_copy: data - hp 0x394 low 0x403000, high 0x403270, res 1
   45  294165 [main] a_test 5244 child_copy: bss - hp 0x394 low 0x405000, high 0x405138, res 1
   43  294208 [main] a_test 5244 child_copy: done
   43  294251 [main] a_test 5244 fixup_mmaps_after_fork: succeeded
  149  294400 [main] a_test 5244 events_init: windows_system_directory 'C:\Windows\system32\', windows_system_directory_length 20
   66  294466 [main] a_test 5244 dll_crt0_0: finished dll_crt0_0 initialization
  124  294590 [main] a_test 5244 _cygtls::remove: wait 0xFFFFFFFF
   59  294649 [main] a_test 5244 _cygtls::remove: removed 0x28CE64 element 0
14385  309034 [main] a_test 5244 frok::child: child is running.  pid 5244, ppid 0, stack here 0x28CB48
  101  309135 [main] a_test 5244 sync_with_parent: signalling parent: after longjmp
   52  309187 [main] a_test 5244 child_info::ready: signalled 0x390 that I was ready
123139  310182 [main] a_test 7516 child_info::sync: pid 5244, WFMO returned 0, res 1
  397  310579 [main] a_test 7516 open_shared: name cygpid.5244, n 5244, shared 0x1A460000 (wanted 0x0), h 0x3AC
  398  310977 [main] a_test 7516 proc_subproc: args: 1, 2673412
   90  311067 [main] a_test 7516 _pinfo::dup_proc_pipe: duped wr_proc_pipe 0x26C for pid 5244(5244)
  758  311825 [main] a_test 7516 pinfo::wait: created tracking thread for pid 5244, winpid 0x147C, rd_pipe 0x3B8
   46  311871 [main] a_test 7516 proc_subproc: added pid 5244 to proc table, slot 0
   46  311917 [main] a_test 7516 proc_subproc: returning 1
   41  311958 [main] a_test 7516 frok::parent: child is alive (but stopped)
   61  312019 [main] a_test 7516 child_copy: stack - hp 0x3B0 low 0x28CB50, high 0x290000, res 1
   39  312058 [main] a_test 7516 child_copy: done
   37  312095 [main] a_test 7516 frok::parent: copying data/bss of a linked dll
   48  312143 [main] a_test 7516 child_copy: linked dll data - hp 0x3B0 low 0x5C1E9000, high 0x5C1E9A38, res 1
   44  312187 [main] a_test 7516 child_copy: linked dll bss - hp 0x3B0 low 0x5C1EB000, high 0x5C1EB188, res 1
   38  312225 [main] a_test 7516 child_copy: done
   36  312261 [main] a_test 7516 resume_child: signalled child
   37  312298 [main] a_test 7516 child_info::sync: n 2, waiting for subproc_ready(0x390) and child process(0x3B0)
 3154  312341 [main] a_test 5244 sync_with_parent: awake
   40  312381 [main] a_test 5244 sync_with_parent: no problems
   36  312417 [main] a_test 5244 frok::child: hParent 0x394, load_dlls 0
   45  312462 [main] a_test 5244 dtable::fixup_after_fork: fd 0 (/dev/tty1)
   43  312505 [main] a_test 5244 fhandler_tty_slave::fixup_after_fork: /dev/tty1 inherited, usecount 3
   45  312550 [main] a_test 5244 dtable::fixup_after_fork: fd 2 (/dev/tty1)
 1129  313679 [main] a_test 5244 fhandler_tty_slave::fixup_after_fork: /dev/tty1 inherited, usecount 3
   43  313722 [main] a_test 5244 dtable::fixup_after_fork: fd 3 ()
   43  313765 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x330 already opened
   40  313805 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x33C already opened
   36  313841 [main] a_test 5244 fhandler_base::fixup_after_fork: inheriting '' from parent
   37  313878 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x35C already opened
   37  313915 [main] a_test 5244 dtable::fixup_after_fork: fd 4 ()
   37  313952 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x360 already opened
   36  313988 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x364 already opened
   36  314024 [main] a_test 5244 fhandler_base::fixup_after_fork: inheriting '' from parent
   37  314061 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x350 already opened
   36  314097 [main] a_test 5244 dtable::fixup_after_fork: fd 5 ()
   36  314133 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x36C already opened
   37  314170 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x370 already opened
   36  314206 [main] a_test 5244 fhandler_base::fixup_after_fork: inheriting '' from parent
   35  314241 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x388 already opened
   37  314278 [main] a_test 5244 dtable::fixup_after_fork: fd 6 ()
   40  314318 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x368 already opened
   40  314358 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x38C already opened
   37  314395 [main] a_test 5244 fhandler_base::fixup_after_fork: inheriting '' from parent
   36  314431 [main] a_test 5244 fhandler_base::fork_fixup: handle 0x37C already opened
   36  314467 [main] a_test 5244 sync_with_parent: signalling parent: performed fork fixup
   37  314504 [main] a_test 5244 child_info::ready: signalled 0x390 that I was ready
   72  314576 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9AE60 in _fixup_after_fork
   42  314618 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9AE30 in _fixup_after_fork
   39  314657 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9AE00 in _fixup_after_fork
   38  314695 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9ADD0 in _fixup_after_fork
   37  314732 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9ADA0 in _fixup_after_fork
   38  314770 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC9AD70 in _fixup_after_fork
   38  314808 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC780A8 in _fixup_after_fork
   38  314846 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0xC60008 in _fixup_after_fork
   39  314885 [main] a_test 5244 pthread_mutex::_fixup_after_fork: mutex 0x611DBDF8 in _fixup_after_fork
  183  315068 [main] a_test 5244 wait_for_sigthread: wait_sig_inited 0x90
 2913  315211 [main] a_test 7516 child_info::sync: pid 5244, WFMO returned 0, res 1
   61  315272 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -41, its_me 1
   43  315315 [main] a_test 7516 sig_send: wakeup 0x3A8
   41  315356 [main] a_test 7516 sig_send: Waiting for pack.wakeup 0x3A8
   47  315403 [sig] a_test 7516 wait_sig: signalling pack.wakeup 0x3A8
  103  315506 [main] a_test 7516 sig_send: returning 0x0 from sending signal -41
  184  315690 [main] a_test 7516 fork: 5244 = fork()
   45  315735 [main] a_test 7516 close: close (6)
   84  315819 [main] a_test 7516 fhandler_socket::close: 0 = fhandler_socket::close()
   42  315861 [main] a_test 7516 close: 0 = close (6)
   35  315896 [main] a_test 7516 close: close (3)
   81  315977 [main] a_test 7516 fhandler_socket::close: 0 = fhandler_socket::close()
   40  316017 [main] a_test 7516 close: 0 = close (3)
 5418  320486 [sig] a_test 5244 wait_sig: entering ReadFile loop, my_readsig 0x2CC, my_sendsig 0x2D0
  118  320604 [main] a_test 5244 wait_for_sigthread: process/signal handling enabled, state 0x41
   45  320649 [main] a_test 5244 fork: 0 = fork()
   48  320697 [main] a_test 5244 dtable::dup2: dup2 (3, 0)
   46  320743 [main] a_test 5244 build_fh_pc: fh 0x6120D880
   41  320784 [main] a_test 5244 fhandler_socket::dup: here
   57  320841 [main] a_test 5244 fhandler_base::dup: in fhandler_base dup
   39  320880 [main] a_test 5244 fhandler_base::dup: dup() failed, handle 35C, Win32 error 6
   37  320917 [main] a_test 5244 seterrno_from_win_error: /ext/build/netrel/src/cygwin-1.7.0-64/winsup/cygwin/fhandler.cc:1151 windows error 6
   41  320958 [main] a_test 5244 geterrno_from_win_error: windows error 6 == errno 9
   36  320994 [main] a_test 5244 __set_errno: void seterrno_from_win_error(const char*, int, DWORD):319 val 9
   38  321032 [main] a_test 5244 dtable::dup_worker: oldfh->dup failed
   36  321068 [main] a_test 5244 dtable::dup2: -1 = dup2 (3, 0)
 1768  322836 [main] a_test 5244 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-3400765896-2285074925-4230561286-1000
   57  322893 [main] a_test 5244 cygpsid::debug_print: get_sids_info: group SID = S-1-5-21-3400765896-2285074925-4230561286-513
   44  322937 [main] a_test 5244 get_info_from_sd: ACL 1A4, uid 1000, gid 513
   70  323007 [main] a_test 5244 fhandler_base::fstat_helper: 0 = fstat (, 0x28C528) st_atime=4AFC8529 st_size=56831, st_mode=0x81A4, st_ino=21110623253359417, sizeof=96
   43  323050 [main] a_test 5244 fstat64: 0 = fstat (1, 0x28C528)
  239  323289 [main] a_test 5244 close: close (0)
   44  323333 [main] a_test 5244 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 2, amount -1, ctty /dev/tty1, avoid_freeing_console 0
   37  323370 [main] a_test 5244 fhandler_tty_slave::close: /dev/tty1 closed, usecount 2
   36  323406 [main] a_test 5244 fhandler_tty_slave::close: just returning because archetype usecount is != 0
   37  323443 [main] a_test 5244 close: 0 = close (0)
  193  323636 [main] a_test 5244 fhandler_base::write: binary write
error: first dup2 -1 9
   92  323728 [main] a_test 5244 close: close (1)
   35  323763 [main] a_test 5244 fhandler_base::close: closing '/home/Eliot/tools/rsync-3.0.6/a_test.strace' handle 0x418
   37  323800 [main] a_test 5244 close: 0 = close (1)
  203  324003 [main] a_test 5244 close: close (2)
   36  324039 [main] a_test 5244 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 1, amount -1, ctty /dev/tty1, avoid_freeing_console 0
   35  324074 [main] a_test 5244 fhandler_tty_slave::close: /dev/tty1 closed, usecount 1
   36  324110 [main] a_test 5244 fhandler_tty_slave::close: just returning because archetype usecount is != 0
   35  324145 [main] a_test 5244 close: 0 = close (2)
  121  324266 [main] a_test 5244 do_exit: do_exit (65280), exit_state 0
   38  324304 [main] a_test 5244 void: 0x0 = signal (20, 0x1)
   35  324339 [main] a_test 5244 void: 0x0 = signal (1, 0x1)
   35  324374 [main] a_test 5244 void: 0x0 = signal (2, 0x1)
   35  324409 [main] a_test 5244 void: 0x0 = signal (3, 0x1)
14996  339405 [main] a_test 5244 wsock_init: res 0
24540  340557 [main] a_test 7516 cygpsid::debug_print: get_sids_info: owner SID = S-1-5-21-3400765896-2285074925-4230561286-1000
   57  340614 [main] a_test 7516 cygpsid::debug_print: get_sids_info: group SID = S-1-5-21-3400765896-2285074925-4230561286-513
   47  340661 [main] a_test 7516 get_info_from_sd: ACL 1A4, uid 1000, gid 513
  222  340883 [main] a_test 7516 fhandler_base::fstat_helper: 0 = fstat (, 0x28C528) st_atime=4AFC8529 st_size=55751, st_mode=0x81A4, st_ino=21110623253359417, sizeof=96
   44  340927 [main] a_test 7516 fstat64: 0 = fstat (1, 0x28C528)
 2323  343250 [proc_waiter] a_test 7516 cygthread::stub: thread 'proc_waiter', id 0xDFC, stack_ptr 0x1B61CDB0
 3998  343403 [main] a_test 5244 wsock_init: wVersion 514
   45  343448 [main] a_test 5244 wsock_init: wHighVersion 514
   37  343485 [main] a_test 5244 wsock_init: szDescription WinSock 2.0
   37  343522 [main] a_test 5244 wsock_init: szSystemStatus Running
   36  343558 [main] a_test 5244 wsock_init: iMaxSockets 0
   36  343594 [main] a_test 5244 wsock_init: iMaxUdpDg 0
   35  343629 [main] a_test 5244 wsock_init: lpVendorInfo 0
   63  343692 [main] a_test 5244 __set_errno: void __set_winsock_errno(const char*, int):217 val 108
   40  343732 [main] a_test 5244 __set_winsock_errno: close:1692 - winsock error 10038 -> errno 108
   37  343769 [main] a_test 5244 fhandler_socket::close: -1 = fhandler_socket::close()
   42  343811 [main] a_test 5244 __set_errno: void __set_winsock_errno(const char*, int):217 val 108
   36  343847 [main] a_test 5244 __set_winsock_errno: close:1692 - winsock error 10038 -> errno 108
   36  343883 [main] a_test 5244 fhandler_socket::close: -1 = fhandler_socket::close()
   39  343922 [main] a_test 5244 __set_errno: void __set_winsock_errno(const char*, int):217 val 108
   36  343958 [main] a_test 5244 __set_winsock_errno: close:1692 - winsock error 10038 -> errno 108
   36  343994 [main] a_test 5244 fhandler_socket::close: -1 = fhandler_socket::close()
   42  344036 [main] a_test 5244 __set_errno: void __set_winsock_errno(const char*, int):217 val 108
   36  344072 [main] a_test 5244 __set_winsock_errno: close:1692 - winsock error 10038 -> errno 108
   36  344108 [main] a_test 5244 fhandler_socket::close: -1 = fhandler_socket::close()
   36  344144 [main] a_test 5244 init_cygheap::close_ctty: closing cygheap->ctty 0x6120C810
   38  344182 [main] a_test 5244 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 0, amount -1, ctty /dev/tty1, avoid_freeing_console 0
   44  344226 [main] a_test 5244 fhandler_tty_slave::close: /dev/tty1 closed, usecount 0
   40  344266 [main] a_test 5244 fhandler_tty_slave::close: closing last open /dev/tty1 handle
   37  344303 [main] a_test 5244 fhandler_tty_common::close: tty1 <0x2B4,0x2B8> closing
   64  344367 [main] a_test 5244 sigproc_terminate: entering
   39  344406 [main] a_test 5244 sig_send: sendsig 0x2D0, pid 5244, signal -42, its_me 1
   42  344448 [main] a_test 5244 sig_send: Not waiting for sigcomplete.  its_me 1 signal -42
   37  344485 [main] a_test 5244 sig_send: returning 0x0 from sending signal -42
   38  344523 [main] a_test 5244 proc_terminate: nprocs 0
   36  344559 [main] a_test 5244 proc_terminate: leaving
   43  344602 [main] a_test 5244 __to_clock_t: dwHighDateTime 0, dwLowDateTime 312002
   36  344638 [main] a_test 5244 __to_clock_t: total 00000000 0000001F
   35  344673 [main] a_test 5244 __to_clock_t: dwHighDateTime 0, dwLowDateTime 780005
   36  344709 [main] a_test 5244 __to_clock_t: total 00000000 0000004E
  394  345103 [main] a_test 5244 pinfo::exit: Calling ExitProcess n 0xFF00, exitcode 0xFF00
 3959  347209 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -34, its_me 1
   64  347273 [main] a_test 7516 sig_send: wakeup 0x3A8
   44  347317 [main] a_test 7516 sig_send: Waiting for pack.wakeup 0x3A8
   44  347361 [sig] a_test 7516 wait_sig: signalling pack.wakeup 0x3A8
  314  347675 [main] a_test 7516 sig_send: returning 0x0 from sending signal -34
 2280  349955 [proc_waiter] a_test 7516 pinfo::maybe_set_exit_code_from_windows: pid 5244, exit value - old 0x800FF00, windows 0xDEADBEEF, cygwin 0x800FF00
  729  350684 [proc_waiter] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal 20, its_me 1
   47  350731 [proc_waiter] a_test 7516 sig_send: Not waiting for sigcomplete.  its_me 1 signal 20
   40  350771 [proc_waiter] a_test 7516 sig_send: returning 0x0 from sending signal 20
   39  350810 [proc_waiter] a_test 7516 proc_waiter: exiting wait thread for pid 5244
   43  350853 [main] a_test 7516 wait4: calling proc_subproc, pid -1, options 0
   43  350896 [main] a_test 7516 proc_subproc: args: 4, 2677524
   40  350936 [main] a_test 7516 proc_subproc: wval->pid -1, wval->options 0
   43  350979 [main] a_test 7516 checkstate: nprocs 1
   40  351019 [main] a_test 7516 stopped_or_terminated: considering pid 5244
   40  351059 [main] a_test 7516 remove_proc: removing procs[0], pid 5244, nprocs 1
   54  351113 [main] a_test 7516 checkstate: returning 1
   41  351154 [main] a_test 7516 proc_subproc: released waiting thread
   40  351194 [main] a_test 7516 proc_subproc: finished processing terminated/stopped child
   39  351233 [main] a_test 7516 proc_subproc: returning 1
   41  351274 [main] a_test 7516 wait4: 0 = WaitForSingleObject (...)
   39  351313 [main] a_test 7516 wait4: intpid -1, status 0x28CCE4, w->status 65280, options 0, res 5244
  153  351466 [main] a_test 7516 fhandler_base::write: binary write
pid = 5244, fin = 5, fout = 4
wait got 65280
  982  352448 [main] a_test 7516 close: close (0)
   42  352490 [main] a_test 7516 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 2, amount -1, ctty /dev/tty1, avoid_freeing_console 0
   41  352531 [main] a_test 7516 fhandler_tty_slave::close: /dev/tty1 closed, usecount 2
   39  352570 [main] a_test 7516 fhandler_tty_slave::close: just returning because archetype usecount is != 0
   40  352610 [main] a_test 7516 close: 0 = close (0)
  212  352822 [main] a_test 7516 close: close (1)
   38  352860 [main] a_test 7516 fhandler_base::close: closing '/home/Eliot/tools/rsync-3.0.6/a_test.strace' handle 0x418
   41  352901 [main] a_test 7516 close: 0 = close (1)
  232  353133 [main] a_test 7516 close: close (2)
   38  353171 [main] a_test 7516 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 1, amount -1, ctty /dev/tty1, avoid_freeing_console 0
  110  353281 [main] a_test 7516 fhandler_tty_slave::close: /dev/tty1 closed, usecount 1
   45  353326 [main] a_test 7516 fhandler_tty_slave::close: just returning because archetype usecount is != 0
   40  353366 [main] a_test 7516 close: 0 = close (2)
  136  353502 [main] a_test 7516 do_exit: do_exit (0), exit_state 0
   42  353544 [main] a_test 7516 void: 0x0 = signal (20, 0x1)
   39  353583 [main] a_test 7516 void: 0x0 = signal (1, 0x1)
   38  353621 [main] a_test 7516 void: 0x0 = signal (2, 0x1)
   39  353660 [main] a_test 7516 void: 0x0 = signal (3, 0x1)
  139  353799 [main] a_test 7516 fhandler_socket::close: 0 = fhandler_socket::close()
  221  354020 [main] a_test 7516 fhandler_socket::close: 0 = fhandler_socket::close()
   44  354064 [main] a_test 7516 init_cygheap::close_ctty: closing cygheap->ctty 0x6120C810
   41  354105 [main] a_test 7516 init_cygheap::manage_console_count: fhandler_tty_slave::close: console_count 0, amount -1, ctty /dev/tty1, avoid_freeing_console 0
   40  354145 [main] a_test 7516 fhandler_tty_slave::close: /dev/tty1 closed, usecount 0
   39  354184 [main] a_test 7516 fhandler_tty_slave::close: closing last open /dev/tty1 handle
   40  354224 [main] a_test 7516 fhandler_tty_common::close: tty1 <0x2B4,0x2B8> closing
   43  354267 [main] a_test 7516 do_exit: 7516 == pgrp 7516, send SIG{HUP,CONT} to stopped children
   40  354307 [main] a_test 7516 kill_pgrp: pid 7516, signal -1
 6324  360631 [main] a_test 7516 open_shared: name cygpid.3328, n 3328, shared 0x1A460000 (wanted 0x0), h 0x2B8
   97  360728 [main] a_test 7516 open_shared: name cygpid.7920, n 7920, shared 0x1A480000 (wanted 0x0), h 0x88
   65  360793 [main] a_test 7516 open_shared: name cygpid.8872, n 8872, shared 0x1A490000 (wanted 0x0), h 0x2A8
   47  360840 [main] a_test 7516 pinfo::init: execed process windows pid 8872, cygwin pid 7248
   60  360900 [main] a_test 7516 open_shared: name cygpid.7248, n 7248, shared 0x1A490000 (wanted 0x0), h 0x2A8
   64  360964 [main] a_test 7516 open_shared: name cygpid.3844, n 3844, shared 0x1A4A0000 (wanted 0x0), h 0x388
   45  361009 [main] a_test 7516 pinfo::init: execed process windows pid 3844, cygwin pid 8792
   52  361061 [main] a_test 7516 open_shared: name cygpid.8792, n 8792, shared 0x1A4A0000 (wanted 0x0), h 0x388
   63  361124 [main] a_test 7516 open_shared: name cygpid.6756, n 6756, shared 0x1A500000 (wanted 0x0), h 0x36C
   44  361168 [main] a_test 7516 pinfo::init: execed process windows pid 6756, cygwin pid 4700
   52  361220 [main] a_test 7516 open_shared: name cygpid.4700, n 4700, shared 0x1A500000 (wanted 0x0), h 0x36C
   62  361282 [main] a_test 7516 open_shared: name cygpid.4480, n 4480, shared 0x1A510000 (wanted 0x0), h 0x34C
   44  361326 [main] a_test 7516 pinfo::init: execed process windows pid 4480, cygwin pid 8900
   53  361379 [main] a_test 7516 open_shared: name cygpid.8900, n 8900, shared 0x1A510000 (wanted 0x0), h 0x34C
   62  361441 [main] a_test 7516 open_shared: name cygpid.4524, n 4524, shared 0x1A580000 (wanted 0x0), h 0x348
   44  361485 [main] a_test 7516 pinfo::init: execed process windows pid 4524, cygwin pid 2592
   52  361537 [main] a_test 7516 open_shared: name cygpid.2592, n 2592, shared 0x1A580000 (wanted 0x0), h 0x348
   62  361599 [main] a_test 7516 open_shared: name cygpid.8280, n 8280, shared 0x1A590000 (wanted 0x0), h 0x364
   43  361642 [main] a_test 7516 pinfo::init: execed process windows pid 8280, cygwin pid 7868
   53  361695 [main] a_test 7516 open_shared: name cygpid.7868, n 7868, shared 0x1A590000 (wanted 0x0), h 0x364
   62  361757 [main] a_test 7516 open_shared: name cygpid.5316, n 5316, shared 0x1A8D0000 (wanted 0x0), h 0x3A0
   44  361801 [main] a_test 7516 pinfo::init: execed process windows pid 5316, cygwin pid 5364
   52  361853 [main] a_test 7516 open_shared: name cygpid.5364, n 5364, shared 0x1A8D0000 (wanted 0x0), h 0x3A0
   62  361915 [main] a_test 7516 open_shared: name cygpid.5452, n 5452, shared 0x1A8E0000 (wanted 0x0), h 0x39C
   44  361959 [main] a_test 7516 pinfo::init: execed process windows pid 5452, cygwin pid 7676
   56  362015 [main] a_test 7516 open_shared: name cygpid.7676, n 7676, shared 0x1A8E0000 (wanted 0x0), h 0x39C
   65  362080 [main] a_test 7516 open_shared: name cygpid.8596, n 8596, shared 0x1A8F0000 (wanted 0x0), h 0x3AC
   44  362124 [main] a_test 7516 pinfo::init: execed process windows pid 8596, cygwin pid 7624
   52  362176 [main] a_test 7516 open_shared: name cygpid.7624, n 7624, shared 0x1A8F0000 (wanted 0x0), h 0x3AC
   62  362238 [main] a_test 7516 open_shared: name cygpid.7696, n 7696, shared 0x1A900000 (wanted 0x0), h 0x3C4
   43  362281 [main] a_test 7516 pinfo::init: execed process windows pid 7696, cygwin pid 8212
  269  362550 [main] a_test 7516 open_shared: name cygpid.8212, n 8212, shared 0x1A900000 (wanted 0x0), h 0x3C4
  363  362913 [main] a_test 7516 open_shared: name cygpid.6916, n 6916, shared 0x1A910000 (wanted 0x0), h 0x3CC
   52  362965 [main] a_test 7516 pinfo::init: execed process windows pid 6916, cygwin pid 8304
   55  363020 [main] a_test 7516 open_shared: name cygpid.8304, n 8304, shared 0x1A910000 (wanted 0x0), h 0x3CC
  111  363131 [main] a_test 7516 open_shared: name cygpid.1936, n 1936, shared 0x1A920000 (wanted 0x0), h 0x3D8
   47  363178 [main] a_test 7516 pinfo::init: execed process windows pid 1936, cygwin pid 8436
   53  363231 [main] a_test 7516 open_shared: name cygpid.8436, n 8436, shared 0x1A920000 (wanted 0x0), h 0x3D8
   67  363298 [main] a_test 7516 open_shared: name cygpid.3292, n 3292, shared 0x1A930000 (wanted 0x0), h 0x3EC
   45  363343 [main] a_test 7516 pinfo::init: execed process windows pid 3292, cygwin pid 612
   53  363396 [main] a_test 7516 open_shared: name cygpid.612, n 612, shared 0x1A930000 (wanted 0x0), h 0x3EC
   96  363492 [main] a_test 7516 open_shared: name cygpid.7356, n 7356, shared 0x1A940000 (wanted 0x0), h 0x3F4
   64  363556 [main] a_test 7516 open_shared: name cygpid.2612, n 2612, shared 0x1A970000 (wanted 0x0), h 0x3FC
   45  363601 [main] a_test 7516 pinfo::init: execed process windows pid 2612, cygwin pid 7356
   51  363652 [main] a_test 7516 open_shared: name cygpid.7356, n 7356, shared 0x1A970000 (wanted 0x0), h 0x3FC
   80  363732 [main] a_test 7516 __set_errno: int kill_pgrp(pid_t, siginfo_t&):309 val 3
   43  363775 [main] a_test 7516 kill_pgrp: -1 = kill (7516, -1)
  190  363965 [main] a_test 7516 sigproc_terminate: entering
   41  364006 [main] a_test 7516 sig_send: sendsig 0x298, pid 7516, signal -42, its_me 1
   44  364050 [main] a_test 7516 sig_send: Not waiting for sigcomplete.  its_me 1 signal -42
   39  364089 [main] a_test 7516 sig_send: returning 0x0 from sending signal -42
  217  364306 [main] a_test 7516 proc_terminate: nprocs 0
   43  364349 [main] a_test 7516 proc_terminate: leaving
   47  364396 [main] a_test 7516 __to_clock_t: dwHighDateTime 0, dwLowDateTime 0
   39  364435 [main] a_test 7516 __to_clock_t: total 00000000 00000000
   40  364475 [main] a_test 7516 __to_clock_t: dwHighDateTime 0, dwLowDateTime 1248008
   39  364514 [main] a_test 7516 __to_clock_t: total 00000000 0000007C
  988  365502 [main] a_test 7516 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0

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

[Corinna Vinschen-2]

On Nov 12 17:23, Eliot Moss wrote:

> I went ahead and wrote a little program that narrows
> down the rsync problem to a dup2 call. The program:
> creates two pipes (for talking to a child process),
> forks the child, and the child tries to dup2 the
> pipe fds to its stdin and stdout. If it wins (which
> it doesn't), it will then run sleep for 5 seconds
> and quit. The parent closes some fds it doesn't need
> and waits for the child, then quits. I attach the
> program in question, and strace output.
>
> Cheers -- Eliot Moss

Thanks for the testcase.  However, the problem is that I can't reproduce
any problem using your testcase.  I ran it on Windows XP SP3, Server 2008
SP1, and Windows 7.  The result is this, just with changing PIDs:

$ ./a_test
pid = 3272, fin = 5, fout = 4
wait got 0

I assume you see some error, but you didn't explicitely write what error
you see.  The strace output shows an error when closing a socket, which
is that dreaded Winsock error 10038, "socket operation on non-socket".

The reason why this operation fails must be something on your machine.
I'm just not sure how we can find out what that is, and how to avoid the
error then.  Simply ignoring error 10038 in close() doesn't sound like
a terribly good idea...


Corinna


--
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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

[Corinna Vinschen-2]

On Nov 12 17:23, Eliot Moss wrote:
>    41  320784 [main] a_test 5244 fhandler_socket::dup: here
>    57  320841 [main] a_test 5244 fhandler_base::dup: in fhandler_base dup
>    39  320880 [main] a_test 5244 fhandler_base::dup: dup() failed, handle 35C, Win32 error 6
>    37  320917 [main] a_test 5244 seterrno_from_win_error: /ext/build/netrel/src/cygwin-1.7.0-64/winsup/cygwin/fhandler.cc:1151 windows error 6
>    41  320958 [main] a_test 5244 geterrno_from_win_error: windows error 6 == errno 9

Duh!  Of course this is the actual error you see.  DuplicateHandle fails
with ERROR_INVALID_HANDLE.  The same problem occurs in close(), but on
the Winsock level where closesocket() returns with error 10038.
Ultimately this means that every socket handle is not recognized as a
handle at all in the child process for some unknown reason.

And why does that happen on some machines only, but not on others?  Is
that a BLODA problem?  Did you seriously check all possible BLODAs?
http://cygwin.com/acronyms/#BLODA
http://cygwin.com/1.7/faq/faq.using.html#faq.using.bloda

I just searched for this problem via google and it turns out that Cygwin
isn't the only software having this problem.  The second hit was already
quite interesting:

http://www.vadvbbs.com/products/vadv32/support/index.php#What_does_Invalid_Socket_Handle_mean

Anyway, it would be nice if we could avoid this problem even if a BLODA
is running.  There are three possible solutions which come to mind and
which we can test.

May I send you an URL to an experimental Cygwin DLL via PM?


Thanks,
Corinna

--
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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

[Eliot Moss]

Corinna Vinschen wrote:

> On Nov 12 17:23, Eliot Moss wrote:
>> I went ahead and wrote a little program that narrows
>> down the rsync problem to a dup2 call. The program:
>> creates two pipes (for talking to a child process),
>> forks the child, and the child tries to dup2 the
>> pipe fds to its stdin and stdout. If it wins (which
>> it doesn't), it will then run sleep for 5 seconds
>> and quit. The parent closes some fds it doesn't need
>> and waits for the child, then quits. I attach the
>> program in question, and strace output.
>>
>> Cheers -- Eliot Moss
>
> Thanks for the testcase.  However, the problem is that I can't reproduce
> any problem using your testcase.  I ran it on Windows XP SP3, Server 2008
> SP1, and Windows 7.  The result is this, just with changing PIDs:
>
> $ ./a_test
> pid = 3272, fin = 5, fout = 4
> wait got 0
>
> I assume you see some error, but you didn't explicitely write what error
> you see.  The strace output shows an error when closing a socket, which
> is that dreaded Winsock error 10038, "socket operation on non-socket".
>
> The reason why this operation fails must be something on your machine.
> I'm just not sure how we can find out what that is, and how to avoid the
> error then.  Simply ignoring error 10038 in close() doesn't sound like
> a terribly good idea...

Thank you for looking more closely!

The actual failure is earlier in the strace output, I think. If you
look for dup2 you see that the first dup2 call fails on my machine.
Can this fail because of some permissions thing? I have UAC set to
"Never notify". I am logged in as me (Eliot), and I have Administrator
rights. I get the same result from a_test if I run bash as Administrator
and run a_test.

Here is sample program output for me:

pid = 9064, fin = 5, fout = 4
error: first dup2 -1 9
wait got 65280

If I understand correctly, the wait code says the child terminated
with result -1, which corresponds with what the code does when that
dup2 fails.

Any suggestions for the next step in debugging this? I can certainly
accept that it's something about my machine, but I am rather at a loss
of where to look ...

Regards -- Eliot

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

[Eliot Moss]

Corinna Vinschen wrote:

> On Nov 12 17:23, Eliot Moss wrote:
>>    41  320784 [main] a_test 5244 fhandler_socket::dup: here
>>    57  320841 [main] a_test 5244 fhandler_base::dup: in fhandler_base dup
>>    39  320880 [main] a_test 5244 fhandler_base::dup: dup() failed, handle 35C, Win32 error 6
>>    37  320917 [main] a_test 5244 seterrno_from_win_error: /ext/build/netrel/src/cygwin-1.7.0-64/winsup/cygwin/fhandler.cc:1151 windows error 6
>>    41  320958 [main] a_test 5244 geterrno_from_win_error: windows error 6 == errno 9
>
> Duh!  Of course this is the actual error you see.  DuplicateHandle fails
> with ERROR_INVALID_HANDLE.  The same problem occurs in close(), but on
> the Winsock level where closesocket() returns with error 10038.
> Ultimately this means that every socket handle is not recognized as a
> handle at all in the child process for some unknown reason.
>
> And why does that happen on some machines only, but not on others?  Is
> that a BLODA problem?  Did you seriously check all possible BLODAs?
> http://cygwin.com/acronyms/#BLODA
> http://cygwin.com/1.7/faq/faq.using.html#faq.using.bloda
>
> I just searched for this problem via google and it turns out that Cygwin
> isn't the only software having this problem.  The second hit was already
> quite interesting:
>
> http://www.vadvbbs.com/products/vadv32/support/index.php#What_does_Invalid_Socket_Handle_mean
>
> Anyway, it would be nice if we could avoid this problem even if a BLODA
> is running.  There are three possible solutions which come to mind and
> which we can test.
>
> May I send you an URL to an experimental Cygwin DLL via PM?

Sure.

I can also report that the first time I run a_test, a Windows popup happens
asking if I want to allow this program to access the network. I click
"Allow", but it seems not to be allowing.

I wrote a variant of a_test that, before it tries the dups, tries to have
the parent send something to the child, have the child read it, write
it back on the other pipe, and have the parent read it. Since it's
nonlocking I/O, I had to put in retry loops and used sleep(1) in them,
but on garden-flavor Unix it works. On cygwin on my box the parent
writes but the child never gets the data. It's as if Windows has
quarantined it, even though I said "Allow"!

Regards -- Eliot

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

[Eliot Moss]

Oh, and in terms of BLODA, my antivirus is Symantec
with on-access scan OFF. I've not seen other issues
with it. I do have Windows Defender -- perhaps it
causes the popups. I'm not entirely clear how I can
turn it off. It was not previously a problem ...

Cheers -- E

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

[Corinna Vinschen-2]

On Nov 13 07:29, Eliot Moss wrote:
> I can also report that the first time I run a_test, a Windows popup happens
> asking if I want to allow this program to access the network. I click
> "Allow", but it seems not to be allowing.

No, that has nothing to do with it.  It's just the Windows firewall
asking.


Corinna

--
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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

[Corinna Vinschen-2]

On Nov 13 07:31, Eliot Moss wrote:
> Oh, and in terms of BLODA, my antivirus is Symantec
> with on-access scan OFF. I've not seen other issues
> with it. I do have Windows Defender -- perhaps it
> causes the popups. I'm not entirely clear how I can
> turn it off. It was not previously a problem ...

I just switched on Windows Defender with realtime protection and it
doesn't have any effect as far as a_test goes.  It still works fine
for me.

Symantec could be a problem, even if on-access scan is switched off.
It installs DLLs which hook into the OS and could have undesired side
effects, like the one we're talking about.


Corinna

--
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Project Co-Leader          cygwin AT cygwin DOT com
Red Hat

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