pipe handling errors

pipe handling errors

[Nellis, Kenneth]

When running a bash pipeline using the latest 64-bit packages, 
I occasionally get output like the following:

1479561950 [waitproc] -bash 10000 sig_send: error sending signal 20, pipe handle 0x2710, nb 132, packsize 0, Win32 error 109

That one was the result of: strings <binary file> | grep <pattern> | sort | uniq -c

Here's a different one that I got twice when sending "strings" 
output to "grep" and once sending "strings" output to "wc -l":

605884587 [main] -bash 10000 sig_send: error sending signal -66, pipe handle 0x2710, nb 132, packsize 0, Win32 error 0

I haven't found them to be repeatable.

I just tried on 32-bit Cygwin and got the following twice in a row, 
but not a third time, so I suspect a race condition.

      1 [main] -bash 9528 sig_send: error sending signal -34, pipe handle 0x2538, nb 152, packsize 0, Win32 error 0
25098461 [main] -bash 9528 sig_send: error sending signal -34, pipe handle 0x2538, nb 152, packsize 0, Win32 error 0

The initial "1" on the first one looks interesting. 
This one also was: strings <binary file> | grep <pattern>

The common element in all these examples was generating the pipeline data
with "strings". I don't recall whether strings was always involved or not.

Not a big concern because the generated output looks correct, 
but a tad annoying. Thought it worth reporting.

FWIW, on 64-bit:
Cygwin64> uname -a
CYGWIN_NT-6.1 COR900GFY5 1.7.30(0.272/5/3) 2014-05-23 10:36 x86_64 Cygwin
Cygwin64> cygcheck -f `which strings`
binutils-2.24.51-4
Cygwin64>

On 32-bit:
Cygwin32> uname -a
CYGWIN_NT-6.1-WOW64 COR900GFY5 1.7.30(0.272/5/3) 2014-05-23 10:36 i686 Cygwin
Cygwin32> cygcheck -f `which strings`
binutils-2.24.51-4
Cygwin32>

--Ken Nellis

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

Re: pipe handling errors

[Corinna Vinschen]

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

On Jul 14 17:40, Nellis, Kenneth wrote:
> When running a bash pipeline using the latest 64-bit packages, 
> I occasionally get output like the following:
> 
> 1479561950 [waitproc] -bash 10000 sig_send: error sending signal 20, pipe handle 0x2710, nb 132, packsize 0, Win32 error 109
> 
> That one was the result of: strings <binary file> | grep <pattern> | sort | uniq -c
> 
> Here's a different one that I got twice when sending "strings" 
> output to "grep" and once sending "strings" output to "wc -l":
> 
> 605884587 [main] -bash 10000 sig_send: error sending signal -66, pipe handle 0x2710, nb 132, packsize 0, Win32 error 0
> 
> I haven't found them to be repeatable.
> 
> I just tried on 32-bit Cygwin and got the following twice in a row, 
> but not a third time, so I suspect a race condition.
> 
>       1 [main] -bash 9528 sig_send: error sending signal -34, pipe handle 0x2538, nb 152, packsize 0, Win32 error 0
> 25098461 [main] -bash 9528 sig_send: error sending signal -34, pipe handle 0x2538, nb 152, packsize 0, Win32 error 0
> 
> The initial "1" on the first one looks interesting. 
> This one also was: strings <binary file> | grep <pattern>
> 
> The common element in all these examples was generating the pipeline data
> with "strings". I don't recall whether strings was always involved or not.
> 
> Not a big concern because the generated output looks correct, 
> but a tad annoying. Thought it worth reporting.
> 
> FWIW, on 64-bit:
> Cygwin64> uname -a
> CYGWIN_NT-6.1 COR900GFY5 1.7.30(0.272/5/3) 2014-05-23 10:36 x86_64 Cygwin
> Cygwin64> cygcheck -f `which strings`
> binutils-2.24.51-4
> Cygwin64>
> 
> On 32-bit:
> Cygwin32> uname -a
> CYGWIN_NT-6.1-WOW64 COR900GFY5 1.7.30(0.272/5/3) 2014-05-23 10:36 i686 Cygwin
> Cygwin32> cygcheck -f `which strings`
> binutils-2.24.51-4
> Cygwin32>

I know that we got this message more often in the past, but I'm totally
unable to reproduce it these days.  I tried with 1.7.30 as well as the
latest snapshots.

I'm wondering if a pipe could be intercepted by a virus checker or
something like that.  Whatever it is, would you mind to give the latest
developer snapshot DLL (2014-07-15) from http://cygwin.com/snapshots/ a
try?  Chris has fixed a typo in the above debug message.  If it still
happens for you, maybe the new output helps better to find the cause.


Thanks,
Corinna

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

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

RE: pipe handling errors

[Nellis, Kenneth]

From: Corinna Vinschen
> On Jul 14 17:40, Nellis, Kenneth wrote:
> > When running a bash pipeline using the latest 64-bit packages, I 
> > occasionally get output like the following:
> > 
> > 1479561950 [waitproc] -bash 10000 sig_send: error sending signal 20, 
> > pipe handle 0x2710, nb 132, packsize 0, Win32 error 109
> > 
> <snip>
> 
> I know that we got this message more often in the past, but I'm totally 
> unable to reproduce it these days.  I tried with 1.7.30 as well as the
> latest snapshots.
> 
> I'm wondering if a pipe could be intercepted by a virus checker or something 
> like that.  Whatever it is, would you mind to give the latest developer 
> snapshot DLL (2014-07-15) from http://cygwin.com/snapshots/ a try?  Chris 
> has fixed a typo in the above debug message.  If it still happens for you, 
> maybe the new output helps better to find the cause.

FYI, got it again this morning, this time with the suggested snapshot:

      0 [main] -bash 8812 sig_send: error sending signal -66, pid 8812, pipe handle 0x80, nb 0, packsize 176, Win32 error 0

Cygwin64> uname -srvmo
CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 09:22:44 x86_64 Cygwin
Cygwin64>

Re: pipe handling errors

[Corinna Vinschen]

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

Hi Kenneth,

On Jul 15 13:50, Nellis, Kenneth wrote:
> From: Corinna Vinschen
> > On Jul 14 17:40, Nellis, Kenneth wrote:
> > > When running a bash pipeline using the latest 64-bit packages, I 
> > > occasionally get output like the following:
> > > 
> > > 1479561950 [waitproc] -bash 10000 sig_send: error sending signal 20, 
> > > pipe handle 0x2710, nb 132, packsize 0, Win32 error 109
> > > 
> > <snip>
> > 
> > I know that we got this message more often in the past, but I'm totally 
> > unable to reproduce it these days.  I tried with 1.7.30 as well as the
> > latest snapshots.
> > 
> > I'm wondering if a pipe could be intercepted by a virus checker or something 
> > like that.  Whatever it is, would you mind to give the latest developer 
> > snapshot DLL (2014-07-15) from http://cygwin.com/snapshots/ a try?  Chris 
> > has fixed a typo in the above debug message.  If it still happens for you, 
> > maybe the new output helps better to find the cause.
> 
> FYI, got it again this morning, this time with the suggested snapshot:
> 
>       0 [main] -bash 8812 sig_send: error sending signal -66, pid 8812, pipe handle 0x80, nb 0, packsize 176, Win32 error 0
> 
> Cygwin64> uname -srvmo
> CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 09:22:44 x86_64 Cygwin
> Cygwin64>

Thanks.  I just created another snapshot which is supposed to fix this
issue (curtesy cgf).  Can you give it a try, please?


Thanks,
Corinna

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

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

RE: pipe handling errors

[Nellis, Kenneth]

From: Corinna Vinschen
> Hi Kenneth,
> 
> On Jul 15 13:50, Nellis, Kenneth wrote:
> > From: Corinna Vinschen
> > > On Jul 14 17:40, Nellis, Kenneth wrote:
> > > > When running a bash pipeline using the latest 64-bit packages, I 
> > > > occasionally get output like the following:
> > > > 
> > > > 1479561950 [waitproc] -bash 10000 sig_send: error sending signal 
> > > > 20, pipe handle 0x2710, nb 132, packsize 0, Win32 error 109
> > > > 
> > > <snip>
> > > 
> > > I know that we got this message more often in the past, but I'm 
> > > totally unable to reproduce it these days.  I tried with 1.7.30 as 
> > > well as the latest snapshots.
> > > 
> > > I'm wondering if a pipe could be intercepted by a virus checker or 
> > > something like that.  Whatever it is, would you mind to give the 
> > > latest developer snapshot DLL (2014-07-15) from 
> > > http://cygwin.com/snapshots/ a try?  Chris has fixed a typo in the 
> > > above debug message.  If it still happens for you, maybe the new output helps better to find the cause.
> > 
> > FYI, got it again this morning, this time with the suggested snapshot:
> > 
> >       0 [main] -bash 8812 sig_send: error sending signal -66, pid 
> > 8812, pipe handle 0x80, nb 0, packsize 176, Win32 error 0
> > 
> > Cygwin64> uname -srvmo
> > CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 09:22:44 x86_64 Cygwin
> > Cygwin64>
> 
> Thanks.  I just created another snapshot which is supposed to fix this issue (curtesy cgf).  Can you give it a try, please?

Well, I'm getting different results with the latest snapshot. Instead of 
getting the error message, I'm getting a hang for maybe a minute before it 
continues.

I used the following command to encourage a failure:

clear; for f in $(find */Debug -name '*Subsystem'); do echo === $f ===; strings $f | grep '\.cpp$' | sort | uniq -c | sort -n; done

9 invocations of this resulted in 3 hangs. During the last such hang, 
ps output showed the following (from a 2nd mintty window):

Cygwin64> ps
      PID    PPID    PGID     WINPID   TTY     UID    STIME COMMAND
     6268   11100    8800      10808  pty0    12779 14:41:03 /usr/bin/sort <defunct>
     1812    2968    1812      10924  pty1    12779 14:41:49 /usr/bin/ps
     2968   10840    2968      10340  pty1    12779 14:41:41 /usr/bin/bash
     5208   11100    8800       5212  pty0    12779 14:41:03 /usr/bin/grep <defunct>
    11196       1   11196      11196  ?       12779 14:37:15 /usr/bin/mintty
     7752   11100    8800      10324  pty0    12779 14:41:03 /usr/bin/sort <defunct>
    10840       1   10840      10840  ?       12779 14:41:41 /usr/bin/mintty
    11100   11196   11100       6260  pty0    12779 14:37:15 /usr/bin/bash
     9536   11100    8800      10368  pty0    12779 14:41:03 /usr/bin/uniq <defunct>
Cygwin64>

After it completed, it showed the following

Cygwin64> ps
      PID    PPID    PGID     WINPID   TTY     UID    STIME COMMAND
     2968   10840    2968      10340  pty1    12779 14:41:41 /usr/bin/bash
    10316    2968   10316       3152  pty1    12779 14:42:08 /usr/bin/ps
    11196       1   11196      11196  ?       12779 14:37:15 /usr/bin/mintty
    10840       1   10840      10840  ?       12779 14:41:41 /usr/bin/mintty
I   11100   11196   11100       6260  pty0    12779 14:37:15 /usr/bin/bash
Cygwin64>

Just to confirm I was using the later snapshot:
Cygwin64> uname -srvmo
CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 15:34:37 x86_64 Cygwin
Cygwin64>

--Ken Nellis

RE: pipe handling errors

[Nellis, Kenneth]

From: Nellis, Kenneth
<snip>
> Well, I'm getting different results with the latest snapshot. 
> Instead of getting the error message, I'm getting a hang for maybe a minute before it continues.
> 
> I used the following command to encourage a failure:
> 
> clear; for f in $(find */Debug -name '*Subsystem'); do echo === $f ===; strings $f | grep '\.cpp$' | sort | uniq -c | sort -n; done
<snip>

Thought it might be useful to add that I can fairly easily get the same 
minute-long hang with a simpler command:

Cygwin64> strings *Subsystem | wc -l

--Ken Nellis

RE: pipe handling errors

[Nellis, Kenneth]

At the risk of annoying folks uninterested in this problem,
here is a simpler test case:

Cygwin64> date; seq 10000 | wc -l; date
Tue Jul 15 15:30:03 EDT 2014
10000
Tue Jul 15 15:31:03 EDT 2014
Cygwin64>

The output ("10000") occurs immediately and then the hang
for precisely one minute before the 2nd date.

As before:

Cygwin64> uname -srvmo
CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 15:34:37 x86_64 Cygwin
Cygwin64>

--Ken Nellis

Re: pipe handling errors

[Christopher Faylor]

On Tue, Jul 15, 2014 at 07:17:48PM +0000, Nellis, Kenneth wrote:
>From: Nellis, Kenneth
><snip>
>> Well, I'm getting different results with the latest snapshot. 
>> Instead of getting the error message, I'm getting a hang for maybe a minute before it continues.
>> 
>> I used the following command to encourage a failure:
>> 
>> clear; for f in $(find */Debug -name '*Subsystem'); do echo === $f ===; strings $f | grep '\.cpp$' | sort | uniq -c | sort -n; done
><snip>
>
>Thought it might be useful to add that I can fairly easily get the same 
>minute-long hang with a simpler command:
>
>Cygwin64> strings *Subsystem | wc -l

What's your cwd when you run this command?

cgf

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

RE: pipe handling errors

[Nellis, Kenneth]

From: Christopher Faylor
>On Tue, Jul 15, 2014 at 07:17:48PM +0000, Nellis, Kenneth wrote:
>>From: Nellis, Kenneth
>><snip>
>>> Well, I'm getting different results with the latest snapshot. 
>>> Instead of getting the error message, I'm getting a hang for maybe a minute before it continues.
>>> 
>>> I used the following command to encourage a failure:
>>> 
>>> clear; for f in $(find */Debug -name '*Subsystem'); do echo === $f 
>>> ===; strings $f | grep '\.cpp$' | sort | uniq -c | sort -n; done
>><snip>
>>
>>Thought it might be useful to add that I can fairly easily get the same 
>>minute-long hang with a simpler command:
>>
>>Cygwin64> strings *Subsystem | wc -l
>
>What's your cwd when you run this command?

Well, it *was* on a network drive, but that appears to be irrelevant:

Cygwin64> date; seq 10000 | wc -l; date
Tue Jul 15 16:31:52 EDT 2014
10000
Tue Jul 15 16:32:52 EDT 2014
Cygwin64> pwd
/home/knellis
Cygwin64> cygpath -w $PWD
C:\cygwin\home\knellis
Cygwin64> uname -srvmo
CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 15:34:37 x86_64 Cygwin
Cygwin64>

--Ken Nellis

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

Re: pipe handling errors

[Christopher Faylor]

On Tue, Jul 15, 2014 at 08:40:32PM +0000, Nellis, Kenneth wrote:
>From: Christopher Faylor
>>On Tue, Jul 15, 2014 at 07:17:48PM +0000, Nellis, Kenneth wrote:
>>>From: Nellis, Kenneth
>>><snip>
>>>> Well, I'm getting different results with the latest snapshot. 
>>>> Instead of getting the error message, I'm getting a hang for maybe a minute before it continues.
>>>> 
>>>> I used the following command to encourage a failure:
>>>> 
>>>> clear; for f in $(find */Debug -name '*Subsystem'); do echo === $f 
>>>> ===; strings $f | grep '\.cpp$' | sort | uniq -c | sort -n; done
>>><snip>
>>>
>>>Thought it might be useful to add that I can fairly easily get the same 
>>>minute-long hang with a simpler command:
>>>
>>>Cygwin64> strings *Subsystem | wc -l
>>
>>What's your cwd when you run this command?
>
>Well, it *was* on a network drive, but that appears to be irrelevant:
>
>Cygwin64> date; seq 10000 | wc -l; date
>Tue Jul 15 16:31:52 EDT 2014
>10000
>Tue Jul 15 16:32:52 EDT 2014
>Cygwin64> pwd
>/home/knellis
>Cygwin64> cygpath -w $PWD
>C:\cygwin\home\knellis
>Cygwin64> uname -srvmo
>CYGWIN_NT-6.1 1.7.31s(0.273/5/3) 20140715 15:34:37 x86_64 Cygwin
>Cygwin64>

Yes, I saw that, but I can't duplicate the problem with that command sequence.

cgf

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

Re: pipe handling errors

[Christopher Faylor]

On Tue, Jul 15, 2014 at 06:05:27PM -0400, Christopher Faylor wrote:
>Yes, I saw that, but I can't duplicate the problem with that command sequence.

I took a stab at another change which may ameliorate the problem.  Please
try the latest snapshot.

cgf

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

RE: pipe handling errors

[Nellis, Kenneth]

From: Christopher Faylor
>On Tue, Jul 15, 2014 at 06:05:27PM -0400, Christopher Faylor wrote:
>>Yes, I saw that, but I can't duplicate the problem with that command sequence.
>
>I took a stab at another change which may ameliorate the problem.  Please try the latest snapshot.

Indeed, with this snapshot I was not able to reproduce the problem. Thank you!

Cygwin64> uname -srvmo
CYGWIN_NT-6.1 1.7.31s(0.272/5/3) 20140716 11:15:29 x86_64 Cygwin
Cygwin64>

--Ken Nellis

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

Re: pipe handling errors

[Christopher Faylor]

On Wed, Jul 16, 2014 at 12:44:25PM +0000, Nellis, Kenneth wrote:
>From: Christopher Faylor
>>On Tue, Jul 15, 2014 at 06:05:27PM -0400, Christopher Faylor wrote:
>>>Yes, I saw that, but I can't duplicate the problem with that command sequence.
>>
>>I took a stab at another change which may ameliorate the problem.  Please try the latest snapshot.
>
>Indeed, with this snapshot I was not able to reproduce the problem. Thank you!
>
>Cygwin64> uname -srvmo
>CYGWIN_NT-6.1 1.7.31s(0.272/5/3) 20140716 11:15:29 x86_64 Cygwin

Good to hear.  Thanks for confirming.

For the curious, I increased the size of the signal pipe buffer.  I
should have done that when I made signal pipes "nowait" to work around
problems with gdb a couple of releases ago.  I also made the signal
sender retry if WriteFile returns success but the number of bytes sent
was not what was requested (since these are message-style pipes the
size should always be either zero or correct).

Increasing the size of the buffer should have been enough to fix the
problem but, when possible, I like to use two forms of protection when I
fix a bug.

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

Re: pipe handling errors

[Corinna Vinschen]

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

On Jul 16 13:36, Ti Strga wrote:
> Christopher Faylor wrote:
> > Increasing the size of the buffer should have been enough to fix the
> > problem but, when possible, I like to use two forms of protection when I
> > fix a bug.
> 
> I recall someone on a project here doing a bugfix with a commit log like:
> 
>     yyyy-mm-dd The Guy's Name <blah@blah>
> 
>     Fix #nnnnn
>     foo.cc (func1):  Belt.
>     bar.cc (func2):  Suspenders.
> 
> Anyhow, I'm looking forward to trying out the fix myself.  We've been
> getting those errors here but not nearly as often.

Just try the latest developer snapshot Cygwin DLL:

http://cygwin.com/snapshots/


Corinna

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

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: pipe handling errors

[Ti Strga]

Christopher Faylor wrote:
> Increasing the size of the buffer should have been enough to fix the
> problem but, when possible, I like to use two forms of protection when I
> fix a bug.

I recall someone on a project here doing a bugfix with a commit log like:

    yyyy-mm-dd The Guy's Name <blah@blah>

    Fix #nnnnn
    foo.cc (func1):  Belt.
    bar.cc (func2):  Suspenders.

Anyhow, I'm looking forward to trying out the fix myself.  We've been
getting those errors here but not nearly as often.

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