Setting termios VMIN > 0 and VTIME > 0 on non blocking file

Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

Hello all,

opening a file (serial port) with O_NONBLOCK and subsequently setting 
termios VMIN and VTIME > 0 makes read() never ever return any data 
(returns EAGAIN indefinitely).

Don't ask my why one would want to do something like this but apparently 
the "screen" program think this is a good way of doing things...

Nevertheless not returning any data ever seems wrong.

Any insight on how it is supposed to work is welcome.

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Brian Inglis]

On 2020-03-11 14:48, Åke Rehnman via Cygwin wrote:
> opening a file (serial port) with O_NONBLOCK and subsequently setting termios
> VMIN and VTIME > 0 makes read() never ever return any data (returns EAGAIN
> indefinitely).
> Don't ask my why one would want to do something like this but apparently the
> "screen" program think this is a good way of doing things...
> Nevertheless not returning any data ever seems wrong.
> Any insight on how it is supposed to work is welcome.

VMIN > 0 || VTIME > 0 implies blocking; O_NONBLOCK implies SIGIO delivery; see:

	https://www.tldp.org/HOWTO/pdf/Serial-Programming-HOWTO.pdf
	https://www.cmrr.umn.edu/~strupp/serial.html
	https://en.wikibooks.org/wiki/Serial_Programming/termios

also read the man pages carefully and *assume* nothing; functions should work
*exactly* as documented: there be dragons!

You have to set up for, or adapt to, the expected input speed and quantity, the
interrupt response overhead (hardware, OS, and C signal), and what else you want
to be able to do at the same time.

-- 
Take care. Thanks, Brian Inglis, Calgary, Alberta, Canada

This email may be disturbing to some readers as it contains
too much technical detail. Reader discretion is advised.

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Norton Allen]

On 3/11/2020 5:55 PM, Brian Inglis wrote:
> VMIN > 0 || VTIME > 0 implies blocking; O_NONBLOCK implies SIGIO delivery; see:

While I agree with everything else you said there, I don't believe 
either of these are true, unless by 'implies' you mean that's how you 
usually do it. I have done a lot of work with non-zero VMIN and/or VTIME 
in non-blocking situations, and I've done non-blocking with different 
approaches to delivery.

-- 
=============================================================
Norton Allen (he/him/his)
Software Engineer
Harvard University School of Engineering and Applied Sciences
12 Oxford St., Link Bldg. (Office 282)
Cambridge, MA  02138
Phone: (617) 998-5553
=============================================================

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-11 22:55, Brian Inglis wrote:
> VMIN > 0 || VTIME > 0 implies blocking; O_NONBLOCK implies SIGIO 
> delivery; see:
> 	https://www.tldp.org/HOWTO/pdf/Serial-Programming-HOWTO.pdf
> 	https://www.cmrr.umn.edu/~strupp/serial.html
> 	https://en.wikibooks.org/wiki/Serial_Programming/termios
>
> also read the man pages carefully and *assume* nothing; functions should work
> *exactly* as documented: there be dragons!
>
According to https://www.cmrr.umn.edu/~strupp/serial.html "*Timeouts are 
ignored in canonical input mode or when the/NDELAY/option is set on the 
file via/open/or/fcntl/."*

This leads me to believe the current cygwin implementation is not 
correct. Changing the VMIN and VTIME should have no effect on the read() 
behavior if the file was opened with O_NOBLOCK.
**

*
*

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Norton Allen]

On 3/11/2020 9:04 PM, Åke Rehnman via Cygwin wrote:
>
> On 2020-03-11 22:55, Brian Inglis wrote:
>> VMIN > 0 || VTIME > 0 implies blocking; O_NONBLOCK implies SIGIO 
>> delivery; see:
>>     https://www.tldp.org/HOWTO/pdf/Serial-Programming-HOWTO.pdf
>>     https://www.cmrr.umn.edu/~strupp/serial.html
>>     https://en.wikibooks.org/wiki/Serial_Programming/termios
>>
>> also read the man pages carefully and *assume* nothing; functions 
>> should work
>> *exactly* as documented: there be dragons!
>>
> According to https://www.cmrr.umn.edu/~strupp/serial.html "*Timeouts 
> are ignored in canonical input mode or when the/NDELAY/option is set 
> on the file via/open/or/fcntl/."*
>
> This leads me to believe the current cygwin implementation is not 
> correct. Changing the VMIN and VTIME should have no effect on the 
> read() behavior if the file was opened with O_NOBLOCK.
> ** 


Correct me if I am wrong, but O_NDELAY is not the same as O_NONBLOCK

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-12 02:08, Norton Allen wrote:
> Correct me if I am wrong, but O_NDELAY is not the same as O_NONBLOCK 

At least for cygwin those two are exactly the same... I think...

#define _FNONBLOCK      0x4000  /* non blocking I/O (POSIX style) */
#define _FNDELAY        _FNONBLOCK      /* non blocking I/O (4.2 style) */

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Thomas Dickey]

----- Original Message -----
| From: "Åke Rehnman" <ake.rehnman@gmail.com>
| To: "cygwin" <cygwin@cygwin.com>
| Sent: Wednesday, March 11, 2020 4:48:05 PM
| Subject: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

| Hello all,
| 
| opening a file (serial port) with O_NONBLOCK and subsequently setting
| termios VMIN and VTIME > 0 makes read() never ever return any data
| (returns EAGAIN indefinitely).
| 
| Don't ask my why one would want to do something like this but apparently
| the "screen" program think this is a good way of doing things...
| 
| Nevertheless not returning any data ever seems wrong.
| 
| Any insight on how it is supposed to work is welcome.

If not "correct", it's certainly inconsistent with all other systems.
I noticed it recently:

https://invisible-island.net/ncurses/tack/CHANGES.html#t20200220

https://github.com/cygwinports/tack/issues/1

It's either recently-broken, or just coincidence :-)

-- 
Thomas E. Dickey <dickey@invisible-island.net>
http://invisible-island.net
ftp://ftp.invisible-island.net

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-12 09:05, Thomas Dickey wrote:
> If not "correct", it's certainly inconsistent with all other systems.
> I noticed it recently:
>
> https://invisible-island.net/ncurses/tack/CHANGES.html#t20200220
>
> https://github.com/cygwinports/tack/issues/1
>
> It's either recently-broken, or just coincidence :-)


Beer fine for you Thomas for copying email-addresses in the reply :-)

Looking at Linux tty line discipline reveals the VMIN and VTIME are 
ignored if O_NONBLOCK flag is set.

         if (!input_available_p(tty, 0)) {
             up_read(&tty->termios_rwsem);
             tty_buffer_flush_work(tty->port);
             down_read(&tty->termios_rwsem);
             if (!input_available_p(tty, 0)) {
                 if (test_bit(TTY_OTHER_CLOSED, &tty->flags)) {
                     retval = -EIO;
                     break;
                 }
                 if (tty_hung_up_p(file))
                     break;
                 /*
                  * Abort readers for ttys which never actually
                  * get hung up.  See __tty_hangup().
                  */
                 if (test_bit(TTY_HUPPING, &tty->flags))
                     break;
                 if (!timeout)
                     break; *<= EXIT HERE if VTIME == 0*
                 if (file->f_flags & O_NONBLOCK) {
                     retval = -EAGAIN; *<==== EXIT HERE*
                     break;
                 }
                 if (signal_pending(current)) {
                     retval = -ERESTARTSYS;
                     break;
                 }
                 up_read(&tty->termios_rwsem);

                 timeout = wait_woken(&wait, TASK_INTERRUPTIBLE, *<=== 
BLOCKING HERE!*
                         timeout);

                 down_read(&tty->termios_rwsem);
                 continue;
             }
         }

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Achim Gratz]

Thomas Dickey writes:
> It's either recently-broken, or just coincidence :-)

I've looke and it's been introduced into newlib around four years ago,
so I'd tend to favor the coincidence camp.  :-)


Regards,
Achim.
-- 
+<[Q+ Matrix-12 WAVE#46+305 Neuron microQkb Andromeda XTk Blofeld]>+

SD adaptation for Waldorf microQ V2.22R2:
http://Synth.Stromeko.net/Downloads.html#WaldorfSDada

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

Hi Åke,

On Mar 11 21:48, Åke Rehnman via Cygwin wrote:
> Hello all,
> 
> opening a file (serial port) with O_NONBLOCK and subsequently setting
> termios VMIN and VTIME > 0 makes read() never ever return any data (returns
> EAGAIN indefinitely).
> 
> Don't ask my why one would want to do something like this but apparently the
> "screen" program think this is a good way of doing things...
> 
> Nevertheless not returning any data ever seems wrong.
> 
> Any insight on how it is supposed to work is welcome.

[Please note that I can't test this myself, so we may need a bit of
 back and forth over this issue]

For a start, can you please strace the problem with a simple
testcase,like this:

  $ strace -o serio.trace <yourtestcase>

and send the source of your testcase as well as the serio.trace file
here?  It may show at which point the error code is generated.

I inspected the serial I/O read function and I only see a subtil
difference in terms of VMIN/VTIME which doesn't seem to be the culprit
at first glance.  In O_NONBLOCK mode, the underlying Windows function
ReadFile is called unconditionally.  My current hunch is this:

- If VMIN>0 && VTIME>0, the Windows equivalent of tcsetattr is
  told that VMIN>0.

- So, assuming VMIN == 2 in Windows.  If VTIME > 0, the Cygwin read
  function sets the number of bytes_to_read to 1 (this is old code,
  don't ask why).

- My assumption now is that the ReadFile function fails because it's
  supposed to return only 1 char, but VMIN is > 1.

There are two issues here.

- If my assumption is correct, the tcsetattr function must not
  set the Windows VMIN equivalent to != 0 in the O_NONBLOCK case.

- Also, as mention above, if VTIME > 0, Cygwin's read sets the number of
  bytes_to_read to 1.   Weirdly, it does so even if there are more than
  1 byte in the inbound queue.  This sounds wrong to me.

Ok, that's for a start, let's see if we can fix this behaviour.


Thanks,
Corinna
  
-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-12 12:40, Corinna Vinschen wrote:
>
> For a start, can you please strace the problem with a simple
> testcase,like this:
>
>    $ strace -o serio.trace <yourtestcase>
>
> and send the source of your testcase as well as the serio.trace file
> here?  It may show at which point the error code is generated.

Should I post those files to the mailing list? I tried emailing them to 
you directly but it bounced...

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 12 14:32, Åke Rehnman via Cygwin wrote:
> 
> On 2020-03-12 12:40, Corinna Vinschen wrote:
> > 
> > For a start, can you please strace the problem with a simple
> > testcase,like this:
> > 
> >    $ strace -o serio.trace <yourtestcase>
> > 
> > and send the source of your testcase as well as the serio.trace file
> > here?  It may show at which point the error code is generated.
> 
> Should I post those files to the mailing list? I tried emailing them to you
> directly but it bounced...

Mailing list, please.


Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

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


On 2020-03-12 15:13, Corinna Vinschen wrote:
> On Mar 12 14:32, Åke Rehnman via Cygwin wrote:
>> On 2020-03-12 12:40, Corinna Vinschen wrote:
>>> For a start, can you please strace the problem with a simple
>>> testcase,like this:
>>>
>>>     $ strace -o serio.trace <yourtestcase>
>>>
>>> and send the source of your testcase as well as the serio.trace file
>>> here?  It may show at which point the error code is generated.
>> Should I post those files to the mailing list? I tried emailing them to you
>> directly but it bounced...
> Mailing list, please.


[-- Attachment #2: test2.c --]
[-- Type: text/plain, Size: 1960 bytes --]

#include <stdio.h>
#include <error.h>
#include <errno.h>
#include <sys/select.h>
#include <fcntl.h>
#include <unistd.h>
#include <termios.h>
#include <sys/ioctl.h>

int main(int argc, char * argv[])
{
    fd_set rfds;
    struct timeval tv;
    char data[256];
    int retval;
    int fd;
    struct termios config;
    
    if (argc < 2)
        error(-1, 0, "need a port");
    fd = open(argv[1], O_RDWR | O_NONBLOCK | O_NOCTTY);
    if (fd < 0)
        error(-1, errno, "failed to open %s", argv[1]);

    if(tcgetattr(fd, &config) < 0)
        error(-1, errno, "tcgetattr failed");

    config.c_cc[VMIN]  = 100;
    config.c_cc[VTIME] = 2;
    
    if(tcsetattr(fd, TCSANOW, &config) < 0)
        error(-1, errno, "tcsetattr failed");

    while (1)
    {
        FD_ZERO(&rfds);
        FD_SET(fd, &rfds);
    
        tv.tv_sec = 1;
        tv.tv_usec = 0;
    
        retval = select(fd+1, &rfds, NULL, NULL, &tv);
    
        if (retval == -1)
            perror("select()");
        else if (retval)
        {
            int nb;
            retval = ioctl(fd, TIOCINQ, &nb);
            if (retval)
                error(-1, errno, "ioctl(TIOCINQ) failed");
            else
                fprintf(stdout,"nb=%d\n",nb);
       
            for (int i=0;i<10;i++)
            {
                retval = read(fd, data, 100);
                if (retval < 0 && errno == EAGAIN)
                {
                    fprintf(stdout,"read() returned EAGAIN\n");
                    usleep(100000);
                    continue;
                }
                else if (retval >= 0)
                {
                    retval = fwrite(data,1,retval,stdout);
                    break;
                }
                else
                {
                    error(-1, errno, "%d = read() failed", errno);
                }
            }
        }
        else
            printf("No data...\n");
    }
           
    close(fd);
    return 0;
}

[-- Attachment #3: test2.txt --]
[-- Type: text/plain, Size: 850 bytes --]

$ strace -o log2.txt ./test2.exe /dev/ttyS27
nb=7
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
nb=28
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
nb=35
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
nb=35
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN
read() returned EAGAIN

[-- Attachment #4: log2.txt --]
[-- Type: text/plain, Size: 70847 bytes --]

--- Process 43708 created
--- Process 43708 loaded C:\Windows\System32\ntdll.dll at 00000000776e0000
--- Process 43708 loaded C:\Windows\System32\kernel32.dll at 00000000775c0000
--- Process 43708 loaded C:\Windows\System32\KernelBase.dll at 000007fefd500000
--- Process 43708 loaded C:\cygwin64\bin\cygwin1.dll at 0000000180040000
    0       0 [main] test2 (43708) **********************************************
  258     258 [main] test2 (43708) Program name: C:\akre\TIOCINQtest\test2.exe (windows pid 43708)
  104     362 [main] test2 (43708) OS version:   Windows NT-6.1
   97     459 [main] test2 (43708) **********************************************
--- Process 43708 loaded C:\Windows\System32\advapi32.dll at 000007fefe240000
--- Process 43708 loaded C:\Windows\System32\msvcrt.dll at 000007fefe450000
--- Process 43708 loaded C:\Windows\System32\sechost.dll at 000007fefdb80000
--- Process 43708 loaded C:\Windows\System32\rpcrt4.dll at 000007fefe320000
--- Process 43708 loaded C:\Windows\System32\cryptbase.dll at 000007fefd0c0000
 3043    3502 [main] test2 (43708) sigprocmask: 0 = sigprocmask (0, 0x0, 0x180319EF0)
  399    3901 [main] test2 (43708) open_shared: name shared.5, n 5, shared 0x180030000 (wanted 0x180030000), h 0x84, *m 6
   68    3969 [main] test2 (43708) user_heap_info::init: heap base 0x800000000, heap top 0x800000000, heap size 0x20000000 (536870912)
   76    4045 [main] test2 (43708) open_shared: name S-1-5-21-2731407542-896203527-514956166-1000.1, n 1, shared 0x180020000 (wanted 0x180020000), h 0x80, *m 6
   37    4082 [main] test2 (43708) user_info::create: opening user shared for 'S-1-5-21-2731407542-896203527-514956166-1000' at 0x180020000
   60    4142 [main] test2 (43708) user_info::create: user shared version AB1FCCE8
   60    4202 [main] test2 (43708) fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-43708-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
   76    4278 [main] test2 (43708) fhandler_pipe::create: pipe read handle 0x9C
   32    4310 [main] test2 (43708) fhandler_pipe::create: CreateFile: name \\.\pipe\cygwin-e022582115c10879-43708-sigwait
   59    4369 [main] test2 (43708) fhandler_pipe::create: pipe write handle 0xA0
   47    4416 [main] test2 (43708) dll_crt0_0: finished dll_crt0_0 initialization
--- Process 43708 thread 4468 created
  262    4678 [sig] test2 (43708) wait_sig: entering ReadFile loop, my_readsig 0x9C, my_sendsig 0xA0
  174    4852 [main] test2 (43708) time: 1584019100 = time(0x0)
   99    4951 [main] test2 (43708) mount_info::conv_to_posix_path: conv_to_posix_path (C:\akre\TIOCINQtest, 0x0, no-add-slash)
   56    5007 [main] test2 (43708) normalize_win32_path: C:\akre\TIOCINQtest = normalize_win32_path (C:\akre\TIOCINQtest)
   37    5044 [main] test2 (43708) mount_info::conv_to_posix_path: /cygdrive/c/akre/TIOCINQtest = conv_to_posix_path (C:\akre\TIOCINQtest)
  115    5159 [main] test2 (43708) sigprocmask: 0 = sigprocmask (0, 0x0, 0x800018130)
  144    5303 [main] test2 (43708) _cygwin_istext_for_stdio: fd 0: not open
   32    5335 [main] test2 (43708) _cygwin_istext_for_stdio: fd 1: not open
   33    5368 [main] test2 (43708) _cygwin_istext_for_stdio: fd 2: not open
  118    5486 [main] test2 (43708) open_shared: name cygpid.1974, n 1974, shared 0x180010000 (wanted 0x180010000), h 0xC8, *m 2
   44    5530 [main] test2 (43708) time: 1584019100 = time(0x0)
   61    5591 [main] test2 1974 pinfo::thisproc: myself dwProcessId 43708
   80    5671 [main] test2 1974 environ_init: GetEnvironmentStrings returned 0x313EA0
   74    7125 [main] test2 1974 parse_options: glob (called func)
   95    7220 [main] test2 1974 parse_options: returning
   55    7591 [main] test2 1974 getwinenv: can't set native for HOME= since no environ yet
   58    7649 [main] test2 1974 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Users\ARE, 0x10000000, no-add-slash)
   37    7686 [main] test2 1974 normalize_win32_path: C:\Users\ARE = normalize_win32_path (C:\Users\ARE)
   42    7728 [main] test2 1974 mount_info::conv_to_posix_path: /cygdrive/c/Users/ARE = conv_to_posix_path (C:\Users\ARE)
   88    7816 [main] test2 1974 win_env::add_cache: posix /cygdrive/c/Users/ARE
   53    7869 [main] test2 1974 win_env::add_cache: native HOME=C:\Users\ARE
   36    7905 [main] test2 1974 posify_maybe: env var converted to HOME=/cygdrive/c/Users/ARE
   75    9822 [main] test2 1974 getwinenv: can't set native for PATH= since no environ yet
   60   16233 [main] test2 1974 getwinenv: can't set native for TEMP= since no environ yet
   37   16270 [main] test2 1974 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\tmp, 0x10000000, no-add-slash)
   39   16309 [main] test2 1974 normalize_win32_path: C:\cygwin64\tmp = normalize_win32_path (C:\cygwin64\tmp)
   61   16370 [main] test2 1974 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (C:\cygwin64\tmp)
   83   16453 [main] test2 1974 win_env::add_cache: posix /tmp
   36   16489 [main] test2 1974 win_env::add_cache: native TEMP=C:\cygwin64\tmp
   53   16542 [main] test2 1974 posify_maybe: env var converted to TEMP=/tmp
   61   16804 [main] test2 1974 getwinenv: can't set native for TMP= since no environ yet
   36   16840 [main] test2 1974 mount_info::conv_to_posix_path: conv_to_posix_path (C:\cygwin64\tmp, 0x10000000, no-add-slash)
   39   16879 [main] test2 1974 normalize_win32_path: C:\cygwin64\tmp = normalize_win32_path (C:\cygwin64\tmp)
   55   16934 [main] test2 1974 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (C:\cygwin64\tmp)
   83   17017 [main] test2 1974 win_env::add_cache: posix /tmp
   53   17070 [main] test2 1974 win_env::add_cache: native TMP=C:\cygwin64\tmp
   37   17107 [main] test2 1974 posify_maybe: env var converted to TMP=/tmp
   56   18335 [main] test2 1974 pinfo_init: Set nice to 0
   90   18425 [main] test2 1974 pinfo_init: pid 1974, pgid 1974, process_state 0x41
   46   18471 [main] test2 1974 App version:  3001.4, api: 0.340
   38   18509 [main] test2 1974 DLL version:  3001.5, api: 0.340
   35   18544 [main] test2 1974 DLL build:    2020-03-12 13:02
   54   18598 [main] test2 1974 dtable::extend: size 32, fds 0x180342E70
  186   18784 [main] test2 1974 __get_lcid_from_locale: LCID=0x0409
  462   19246 [main] test2 1974 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-e022582115c10879-lpc
   71   19317 [main] test2 1974 transport_layer_pipes::connect: Error opening the pipe (2)
   55   19372 [main] test2 1974 client_request::make_request: cygserver un-available
--- Process 43708 (pid: 1974) thread 37052 created
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\netapi32.dll at 000007fefc610000
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\netutils.dll at 000007fefc800000
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\srvcli.dll at 000007fefce20000
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\wkscli.dll at 000007fefc1d0000
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\samcli.dll at 000007fefc1b0000
--- Process 43708 (pid: 1974) loaded C:\Windows\System32\samlib.dll at 000007fefb760000
--- Process 43708 (pid: 1974) thread 14456 created
  105   39200 [main] test2 1974 cygheap_user::ontherange: what 2, pw 0x180343170
   94   39294 [main] test2 1974 cygheap_user::ontherange: HOME is already in the environment /cygdrive/c/Users/ARE
  240   39534 [main] test2 1974 build_argv: argv[0] = 'C:\akre\TIOCINQtest\test2.exe'
   98   39632 [main] test2 1974 build_argv: argv[1] = '/dev/ttyS27'
   92   39724 [main] test2 1974 build_argv: argc 2
  232   39956 [main] test2 1974 mount_info::conv_to_posix_path: conv_to_posix_path (C:\akre\TIOCINQtest\test2.exe, 0x10000100, no-add-slash)
   79   40035 [main] test2 1974 normalize_win32_path: C:\akre\TIOCINQtest\test2.exe = normalize_win32_path (C:\akre\TIOCINQtest\test2.exe)
   65   40100 [main] test2 1974 mount_info::conv_to_posix_path: /cygdrive/c/akre/TIOCINQtest/test2.exe = conv_to_posix_path (C:\akre\TIOCINQtest\test2.exe)
  341   40441 [main] test2 1974 build_fh_pc: created an archetype (0x1803452B0) for /dev/pty0(136/0)
  134   40575 [main] test2 1974 build_fh_pc: fh 0x180344F40, dev 00880000
  193   40768 [main] test2 1974 fhandler_pipe::create: name \\.\pipe\cygwin-e022582115c10879-pty0-from-master, size 131072, mode PIPE_TYPE_MESSAGE
  175   40943 [main] test2 1974 fhandler_pipe::create: pipe busy
  189   41132 [main] test2 1974 tty::exists: exists 1
  332   41464 [main] test2 1974 set_posix_access: ACL-Size: 124
  172   41636 [main] test2 1974 set_posix_access: Created SD-Size: 200
   98   41734 [main] test2 1974 fhandler_pty_slave::open: (800): pty output_mutex (0x14C): waiting -1 ms
  221   41955 [main] test2 1974 fhandler_pty_slave::open: (800): pty output_mutex: acquired
  114   42069 [main] test2 1974 tty::create_inuse: cygtty.slave_alive.0 0x158
  100   42169 [main] test2 1974 fhandler_pty_slave::open: (803): pty output_mutex(0x14C) released
  200   42369 [main] test2 1974 open_shared: name cygpid.1934, n 1934, shared 0x2D0000 (wanted 0x0), h 0x15C, *m 6
  155   42524 [main] test2 1974 fhandler_pty_slave::open: dup handles directly since I'm the owner
  166   42690 [main] test2 1974 fhandler_pty_slave::open: duplicated from_master 0x244->0x15C from pty_owner
  119   42809 [main] test2 1974 fhandler_pty_slave::open: duplicated from_master_cyg 0x244->0x164 from pty_owner
  104   42913 [main] test2 1974 fhandler_pty_slave::open: duplicated to_master 0x258->0x168 from pty_owner
   99   43012 [main] test2 1974 fhandler_pty_slave::open: duplicated to_master_cyg 0x260->0x16C from pty_owner
  198   43210 [main] test2 1974 fhandler_console::need_invisible: invisible_console 0
  189   43399 [main] test2 1974 fhandler_base::open_with_arch: line 470:  /dev/pty0<0x1803452B0> usecount + 1 = 1
  116   43515 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
  127   43642 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   96   43738 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
  181   43919 [main] test2 1974 _pinfo::set_ctty: old no ctty, ctty device number 0xFFFFFFFF, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
  214   44133 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty 0x0, archetype 0x1803452B0
  101   44234 [main] test2 1974 _pinfo::set_ctty: ctty was NULL
   94   44328 [main] test2 1974 _pinfo::set_ctty: line 541:  /dev/pty0<0x1803452B0> usecount + 1 = 2
   94   44422 [main] test2 1974 _pinfo::set_ctty: /dev/pty0 ctty, usecount 2
   97   44519 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1974, pid 1974, pgid 1974, tty->pgid 1972, tty->sid 1935
  115   44634 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
   91   44725 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 2
   99   44824 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
  216   45040 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
  103   45143 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
   69   45212 [main] test2 1974 _pinfo::set_ctty: old ctty /dev/pty0, ctty device number 0x880000, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
   41   45253 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1935, pid 1974, pgid 1974, tty->pgid 1974, tty->sid 1935
  161   45414 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
   98   45512 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 2
  205   45717 [main] test2 1974 build_fh_pc: found an archetype for (null)(136/0) io_handle 0x15C
  124   45841 [main] test2 1974 build_fh_pc: fh 0x180345690, dev 00880000
  114   45955 [main] test2 1974 fhandler_base::open_with_arch: line 490:  /dev/pty0<0x1803452B0> usecount + 1 = 3
  183   46138 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
  101   46239 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   93   46332 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
   94   46426 [main] test2 1974 _pinfo::set_ctty: old ctty /dev/pty0, ctty device number 0x880000, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
  213   46639 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1935, pid 1974, pgid 1974, tty->pgid 1974, tty->sid 1935
   84   46723 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
   94   46817 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 3
   98   46915 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
  104   47019 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   99   47118 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
   85   47203 [main] test2 1974 _pinfo::set_ctty: old ctty /dev/pty0, ctty device number 0x880000, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
   35   47238 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1935, pid 1974, pgid 1974, tty->pgid 1974, tty->sid 1935
   46   47284 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
  105   47389 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 3
  235   47624 [main] test2 1974 build_fh_pc: found an archetype for (null)(136/0) io_handle 0x15C
   86   47710 [main] test2 1974 build_fh_pc: fh 0x180345A00, dev 00880000
   75   47785 [main] test2 1974 fhandler_base::open_with_arch: line 490:  /dev/pty0<0x1803452B0> usecount + 1 = 4
   54   47839 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   69   47908 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   48   47956 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
   56   48012 [main] test2 1974 _pinfo::set_ctty: old ctty /dev/pty0, ctty device number 0x880000, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
  294   48306 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1935, pid 1974, pgid 1974, tty->pgid 1974, tty->sid 1935
   97   48403 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
   94   48497 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 4
  102   48599 [main] test2 1974 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
   85   48684 [main] test2 1974 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
   54   48738 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
   57   48795 [main] test2 1974 _pinfo::set_ctty: old ctty /dev/pty0, ctty device number 0x880000, tc.ntty device number 0x880000 flags & O_NOCTTY 0x0
  162   48957 [main] test2 1974 _pinfo::set_ctty: attaching ctty /dev/pty0 sid 1935, pid 1974, pgid 1974, tty->pgid 1974, tty->sid 1935
   97   49054 [main] test2 1974 _pinfo::set_ctty: cygheap->ctty now 0x1803452B0, archetype 0x1803452B0
  126   49180 [main] test2 1974 fhandler_pty_slave::open_setup: /dev/pty0 opened, usecount 4
  231   49411 [main] test2 1974 __set_errno: void dll_crt0_1(void*):989 setting errno 0
 1029   50440 [main] test2 1974 open: open(/dev/ttyS27, 0xC002)
  118   50558 [main] test2 1974 normalize_posix_path: src /dev/ttyS27
  203   50761 [main] test2 1974 normalize_posix_path: /dev/ttyS27 = normalize_posix_path (/dev/ttyS27)
  101   50862 [main] test2 1974 mount_info::conv_to_win32_path: conv_to_win32_path (/dev/ttyS27)
  121   50983 [main] test2 1974 mount_info::conv_to_win32_path: src_path /dev/ttyS27, dst \??\COM28, flags 0x0, rc 0
  151   51134 [main] test2 1974 build_fh_pc: fh 0x180345F90, dev 0075001B
  207   51341 [main] test2 1974 fhandler_serial::open: fhandler_serial::open (/dev/ttyS27, 0xC002, 00)
  221   51562 [main] test2 1974 fhandler_base::open: (\??\COM28, 0xC002)
18369   69931 [main] test2 1974 fhandler_base::set_flags: flags 0xC002, supplied_bin 0x10000
  196   70127 [main] test2 1974 fhandler_base::set_flags: filemode set to binary
  107   70234 [main] test2 1974 fhandler_base::open: 0x0 = NtCreateFile (0x2B4, 0xC0000000, \??\COM28, io, NULL, 0x0, 0x7, 0x1, 0x4000, NULL, 0)
  235   70469 [main] test2 1974 fhandler_base::open: 1 = fhandler_base::open(\??\COM28, 0xC002)
  396   70865 [main] test2 1974 fhandler_serial::open: 0x100000001 = fhandler_serial::open (/dev/ttyS27, 0xC002, 00)
  226   71091 [main] test2 1974 open: 3 = open(/dev/ttyS27, 0xC002)
  156   71247 [main] test2 1974 fhandler_serial::tcgetattr: vmin_ 0, vtime_ 0
   74   71321 [main] test2 1974 tcgetattr: iflag 0x404, oflag 0x0, cflag 0x830, lflag 0x0, VMIN 0, VTIME 0
  106   71427 [main] test2 1974 fhandler_serial::tcsetattr: action 2
  480   71907 [main] test2 1974 fhandler_serial::tcsetattr: vtime 200, vmin 100
  119   72026 [main] test2 1974 fhandler_serial::tcsetattr: ReadTotalTimeoutConstant 0, ReadIntervalTimeout 200, ReadTotalTimeoutMultiplier 0
  135   72161 [main] test2 1974 __set_errno: int tcsetattr(int, int, const termios*):158 setting errno 0
  122   72283 [main] test2 1974 tcsetattr: iflag 0x404, oflag 0x0, cflag 0x830, lflag 0x0, VMIN 100, VTIME 2
   94   72377 [main] test2 1974 tcsetattr: 0 = tcsetattr(3, 2, 0xFFFFCA80)
  109   72486 [main] test2 1974 pselect: pselect (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20, 0x0)
  155   72641 [main] test2 1974 pselect: to->tv_sec 1, to->tv_nsec 0, us 1000000
  216   72857 [main] test2 1974 dtable::select_read: /dev/ttyS27 fd 3
  131   72988 [main] test2 1974 select: sel.always_ready 0
--- Process 43708 (pid: 1974) thread 28796 created
  742   73730 [sersel] test2 1974 cygthread::stub: thread 'sersel', id 0x707C, stack_ptr 0xB7CCE0
   99   73829 [sersel] test2 1974 peek_serial: fh->overlapped_armed 0
  116   73945 [main] test2 1974 select_stuff::wait: m 4, us 1000000, wmfo_timeout -1
 9988   83933 [sersel] test2 1974 thread_serial: exiting
  107   84040 [main] test2 1974 select_stuff::wait: wait_ret 2, m = 4.  verifying
  234   84274 [main] test2 1974 set_bits: me 0x80003B2F0, testing fd 3 (/dev/ttyS27)
  133   84407 [main] test2 1974 set_bits: ready 1
  141   84548 [main] test2 1974 select_stuff::wait: res after verify 0
  107   84655 [main] test2 1974 select_stuff::wait: returning 0
   96   84751 [main] test2 1974 select: sel.wait returns 0
  107   84858 [main] test2 1974 peek_serial: fh->overlapped_armed 1
  104   84962 [main] test2 1974 peek_serial: already ready
  104   85066 [main] test2 1974 set_bits: me 0x80003B2F0, testing fd 3 (/dev/ttyS27)
  110   85176 [main] test2 1974 set_bits: ready 1
  106   85282 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  217   85499 [main] test2 1974 select_stuff::destroy: deleting select records
  157   85656 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  103   85759 [main] test2 1974 select_stuff::destroy: deleting select records
   94   85853 [main] test2 1974 pselect: 1 = select (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20)
  222   86075 [main] test2 1974 ioctl: ioctl(fd 3, cmd 0x541B)
  126   86201 [main] test2 1974 fhandler_serial::ioctl: 0 = ioctl(541B, 0xFFFFCA7C)
  122   86323 [main] test2 1974 ioctl: 0 = ioctl(3, 0x541B, ...)
  376   86699 [main] test2 1974 time: 1584019100 = time(0x0)
  186   89220 [main] test2 1974 stat64: entering
   55   89275 [main] test2 1974 normalize_posix_path: src /dev
   63   89338 [main] test2 1974 normalize_posix_path: /dev = normalize_posix_path (/dev)
   43   89381 [main] test2 1974 mount_info::conv_to_win32_path: conv_to_win32_path (/dev)
   69   89450 [main] test2 1974 mount_info::conv_to_win32_path: src_path /dev, dst C:\cygwin64\dev, flags 0x30008, rc 0
  116   89566 [main] test2 1974 symlink_info::check: 0x0 = NtCreateFile (\??\C:\cygwin64\dev)
   91   89657 [main] test2 1974 symlink_info::check: not a symlink
   38   89695 [main] test2 1974 symlink_info::check: 0 = symlink.check(C:\cygwin64\dev, 0xFFFFB200) (mount_flags 0x30008, path_flags 0x0)
  111   89806 [main] test2 1974 build_fh_pc: fh 0x180346408, dev 000000C1
   49   89855 [main] test2 1974 stat_worker: (\??\C:\cygwin64\dev, 0x180319D60, 0x180346408), file_attributes 16
  176   90031 [main] test2 1974 fhandler_base::fstat_helper: 0 = fstat (\??\C:\cygwin64\dev, 0x180319D60) st_size=0, st_mode=040755, st_ino=2251799815070549st_atim=58CCE806.BB0BC3C st_ctim=58CCE806.BB0BC3C st_mtim=58CCE806.BB0BC3C st_birthtim=58CCE723.25DBFA18
   50   90081 [main] test2 1974 stat_worker: 0 = (\??\C:\cygwin64\dev,0x180319D60)
   95   90176 [main] test2 1974 fstat64: 0 = fstat(1, 0xFFFFC550)
   70   90246 [main] test2 1974 isatty: 1 = isatty(1)
  320   90566 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 5)
   78   90644 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   45   90689 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   49   90738 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   47   90785 [main] test2 1974 write: 5 = write(1, 0x80004B450, 5)
  153   90938 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   85   91023 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
   72   91095 [main] test2 1974 fhandler_serial::raw_read: inq 100
   96   91191 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   57   91248 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   88   91336 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  243   91579 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   67   91646 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   80   91726 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   63   91789 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   82   91871 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  156   92027 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100135  192162 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  186  192348 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   83  192431 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  266  192697 [main] test2 1974 fhandler_serial::raw_read: inq 100
  262  192959 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  144  193103 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   45  193148 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  724  193872 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  158  194030 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  150  194180 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  165  194345 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  240  194585 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  280  194865 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100302  295167 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
   92  295259 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   29  295288 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
 8554  303842 [main] test2 1974 fhandler_serial::raw_read: inq 100
  165  304007 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   29  304036 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   25  304061 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  107  304168 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   36  304204 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   49  304253 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   32  304285 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   30  304315 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
   79  304394 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99778  404172 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  215  404387 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  172  404559 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  623  405182 [main] test2 1974 fhandler_serial::raw_read: inq 100
  162  405344 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  335  405679 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  188  405867 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  435  406302 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  105  406407 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   93  406500 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   89  406589 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   97  406686 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  252  406938 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99755  506693 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  197  506890 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  105  506995 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  384  507379 [main] test2 1974 fhandler_serial::raw_read: inq 100
   54  507433 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   68  507501 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   94  507595 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  340  507935 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  227  508162 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   37  508199 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   33  508232 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   32  508264 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  248  508512 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99662  608174 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  225  608399 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   43  608442 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  167  608609 [main] test2 1974 fhandler_serial::raw_read: inq 100
  377  608986 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  103  609089 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  122  609211 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  120  609331 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   41  609372 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   30  609402 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   40  609442 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   35  609477 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
   92  609569 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99659  709228 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  263  709491 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  170  709661 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  430  710091 [main] test2 1974 fhandler_serial::raw_read: inq 100
  272  710363 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   55  710418 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   29  710447 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  110  710557 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   38  710595 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  165  710760 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  140  710900 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  139  711039 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  462  711501 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100196  811697 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  240  811937 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   32  811969 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  204  812173 [main] test2 1974 fhandler_serial::raw_read: inq 100
   71  812244 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   66  812310 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   93  812403 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  532  812935 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  149  813084 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  155  813239 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  147  813386 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  161  813547 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  468  814015 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100225  914240 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  265  914505 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  164  914669 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  422  915091 [main] test2 1974 fhandler_serial::raw_read: inq 100
  165  915256 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  176  915432 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  144  915576 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  350  915926 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  102  916028 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   94  916122 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  110  916232 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  230  916462 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  324  916786 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99973 1016759 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  324 1017083 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  237 1017320 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  473 1017793 [main] test2 1974 fhandler_serial::raw_read: inq 100
  198 1017991 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  194 1018185 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  135 1018320 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  356 1018676 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  102 1018778 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   52 1018830 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   30 1018860 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   31 1018891 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  138 1019029 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99873 1118902 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  112 1119014 [main] test2 1974 pselect: pselect (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20, 0x0)
   30 1119044 [main] test2 1974 pselect: to->tv_sec 1, to->tv_nsec 0, us 1000000
   43 1119087 [main] test2 1974 dtable::select_read: /dev/ttyS27 fd 3
   28 1119115 [main] test2 1974 select: sel.always_ready 0
   71 1119186 [main] test2 1974 select_stuff::wait: m 4, us 1000000, wmfo_timeout -1
   40 1119226 [sersel] test2 1974 peek_serial: fh->overlapped_armed 0
  534 1119760 [sersel] test2 1974 thread_serial: exiting
   46 1119806 [main] test2 1974 select_stuff::wait: wait_ret 2, m = 4.  verifying
   39 1119845 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
   31 1119876 [main] test2 1974 set_bits: ready 1
   25 1119901 [main] test2 1974 select_stuff::wait: res after verify 0
   23 1119924 [main] test2 1974 select_stuff::wait: returning 0
   22 1119946 [main] test2 1974 select: sel.wait returns 0
   23 1119969 [main] test2 1974 peek_serial: fh->overlapped_armed 0
   24 1119993 [main] test2 1974 peek_serial: already ready
   23 1120016 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
   23 1120039 [main] test2 1974 set_bits: ready 1
   23 1120062 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
   52 1120114 [main] test2 1974 select_stuff::destroy: deleting select records
   36 1120150 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
   24 1120174 [main] test2 1974 select_stuff::destroy: deleting select records
   26 1120200 [main] test2 1974 pselect: 1 = select (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20)
   25 1120225 [main] test2 1974 ioctl: ioctl(fd 3, cmd 0x541B)
   30 1120255 [main] test2 1974 fhandler_serial::ioctl: 0 = ioctl(541B, 0xFFFFCA7C)
   26 1120281 [main] test2 1974 ioctl: 0 = ioctl(3, 0x541B, ...)
  101 1120382 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 6)
   33 1120415 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   27 1120442 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   29 1120471 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   28 1120499 [main] test2 1974 write: 6 = write(1, 0x80004B450, 6)
   81 1120580 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   27 1120607 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  288 1120895 [main] test2 1974 fhandler_serial::raw_read: inq 100
   45 1120940 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   28 1120968 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   32 1121000 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  102 1121102 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   28 1121130 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   26 1121156 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   30 1121186 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   27 1121213 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
   81 1121294 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99960 1221254 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  215 1221469 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  173 1221642 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  285 1221927 [main] test2 1974 fhandler_serial::raw_read: inq 100
  210 1222137 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  254 1222391 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  146 1222537 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  738 1223275 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  158 1223433 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   79 1223512 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   64 1223576 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   97 1223673 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  301 1223974 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
108415 1332389 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  135 1332524 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   37 1332561 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  193 1332754 [main] test2 1974 fhandler_serial::raw_read: inq 100
   54 1332808 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   34 1332842 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   34 1332876 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  123 1332999 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   45 1333044 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   34 1333078 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   38 1333116 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   37 1333153 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  347 1333500 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99793 1433293 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  274 1433567 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  151 1433718 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  478 1434196 [main] test2 1974 fhandler_serial::raw_read: inq 100
  161 1434357 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  192 1434549 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  146 1434695 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  500 1435195 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   82 1435277 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  143 1435420 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  111 1435531 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  140 1435671 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  432 1436103 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100212 1536315 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  278 1536593 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  154 1536747 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  646 1537393 [main] test2 1974 fhandler_serial::raw_read: inq 100
  186 1537579 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  168 1537747 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  212 1537959 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  608 1538567 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  127 1538694 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  111 1538805 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  119 1538924 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   94 1539018 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  342 1539360 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99886 1639246 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  208 1639454 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   53 1639507 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  340 1639847 [main] test2 1974 fhandler_serial::raw_read: inq 100
   59 1639906 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   51 1639957 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   33 1639990 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  119 1640109 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   40 1640149 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   47 1640196 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   40 1640236 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   33 1640269 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  112 1640381 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99881 1740262 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  139 1740401 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   35 1740436 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  209 1740645 [main] test2 1974 fhandler_serial::raw_read: inq 100
  113 1740758 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   32 1740790 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   26 1740816 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  115 1740931 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   39 1740970 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   27 1740997 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   34 1741031 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   30 1741061 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
   85 1741146 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99688 1840834 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  273 1841107 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  166 1841273 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  547 1841820 [main] test2 1974 fhandler_serial::raw_read: inq 100
  158 1841978 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  193 1842171 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  192 1842363 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  520 1842883 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   97 1842980 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  121 1843101 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  115 1843216 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  139 1843355 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  345 1843700 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100152 1943852 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  269 1944121 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  177 1944298 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  564 1944862 [main] test2 1974 fhandler_serial::raw_read: inq 100
   68 1944930 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   84 1945014 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  142 1945156 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  661 1945817 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  103 1945920 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  155 1946075 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  164 1946239 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  123 1946362 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  128 1946490 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99856 2046346 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  216 2046562 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  190 2046752 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  424 2047176 [main] test2 1974 fhandler_serial::raw_read: inq 100
   64 2047240 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  125 2047365 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  144 2047509 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  652 2048161 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  145 2048306 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  129 2048435 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  105 2048540 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  136 2048676 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  276 2048952 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99930 2148882 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  153 2149035 [main] test2 1974 pselect: pselect (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20, 0x0)
   29 2149064 [main] test2 1974 pselect: to->tv_sec 1, to->tv_nsec 0, us 1000000
   43 2149107 [main] test2 1974 dtable::select_read: /dev/ttyS27 fd 3
   23 2149130 [main] test2 1974 select: sel.always_ready 0
  329 2149459 [main] test2 1974 select_stuff::wait: m 4, us 1000000, wmfo_timeout -1
  176 2149635 [sersel] test2 1974 peek_serial: fh->overlapped_armed 0
  622 2150257 [sersel] test2 1974 thread_serial: exiting
  104 2150361 [main] test2 1974 select_stuff::wait: wait_ret 2, m = 4.  verifying
   87 2150448 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
   59 2150507 [main] test2 1974 set_bits: ready 1
   95 2150602 [main] test2 1974 select_stuff::wait: res after verify 0
  105 2150707 [main] test2 1974 select_stuff::wait: returning 0
  105 2150812 [main] test2 1974 select: sel.wait returns 0
   95 2150907 [main] test2 1974 peek_serial: fh->overlapped_armed 0
   93 2151000 [main] test2 1974 peek_serial: already ready
  103 2151103 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
  105 2151208 [main] test2 1974 set_bits: ready 1
  119 2151327 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  195 2151522 [main] test2 1974 select_stuff::destroy: deleting select records
  152 2151674 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  103 2151777 [main] test2 1974 select_stuff::destroy: deleting select records
   88 2151865 [main] test2 1974 pselect: 1 = select (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20)
   76 2151941 [main] test2 1974 ioctl: ioctl(fd 3, cmd 0x541B)
   37 2151978 [main] test2 1974 fhandler_serial::ioctl: 0 = ioctl(541B, 0xFFFFCA7C)
   28 2152006 [main] test2 1974 ioctl: 0 = ioctl(3, 0x541B, ...)
  328 2152334 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 6)
  102 2152436 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  107 2152543 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  112 2152655 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  200 2152855 [main] test2 1974 write: 6 = write(1, 0x80004B450, 6)
  148 2153003 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   29 2153032 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  269 2153301 [main] test2 1974 fhandler_serial::raw_read: inq 100
  118 2153419 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  126 2153545 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  104 2153649 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  376 2154025 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  113 2154138 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  134 2154272 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  118 2154390 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  201 2154591 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  142 2154733 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100133 2254866 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  239 2255105 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  147 2255252 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  426 2255678 [main] test2 1974 fhandler_serial::raw_read: inq 100
  153 2255831 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  171 2256002 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  149 2256151 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  398 2256549 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  122 2256671 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  129 2256800 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  116 2256916 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  143 2257059 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  375 2257434 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99887 2357321 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  170 2357491 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   46 2357537 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  198 2357735 [main] test2 1974 fhandler_serial::raw_read: inq 100
  129 2357864 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   97 2357961 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   50 2358011 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  176 2358187 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  109 2358296 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   69 2358365 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   66 2358431 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   63 2358494 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  158 2358652 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99726 2458378 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  180 2458558 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  139 2458697 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  485 2459182 [main] test2 1974 fhandler_serial::raw_read: inq 100
  150 2459332 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  117 2459449 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  120 2459569 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  404 2459973 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  130 2460103 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  123 2460226 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  154 2460380 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  100 2460480 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  341 2460821 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100079 2560900 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  281 2561181 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  151 2561332 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  622 2561954 [main] test2 1974 fhandler_serial::raw_read: inq 100
  159 2562113 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  191 2562304 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  178 2562482 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  404 2562886 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  229 2563115 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  119 2563234 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  121 2563355 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  123 2563478 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  321 2563799 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100166 2663965 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  273 2664238 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  114 2664352 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  465 2664817 [main] test2 1974 fhandler_serial::raw_read: inq 100
  174 2664991 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  100 2665091 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  105 2665196 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  373 2665569 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  129 2665698 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  113 2665811 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  119 2665930 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  120 2666050 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  352 2666402 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100057 2766459 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  216 2766675 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  184 2766859 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  430 2767289 [main] test2 1974 fhandler_serial::raw_read: inq 100
  161 2767450 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  187 2767637 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  192 2767829 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  165 2767994 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   67 2768061 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  106 2768167 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  314 2768481 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  148 2768629 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  374 2769003 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100094 2869097 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  288 2869385 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  178 2869563 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  430 2869993 [main] test2 1974 fhandler_serial::raw_read: inq 100
  138 2870131 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  215 2870346 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  180 2870526 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  549 2871075 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  227 2871302 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  114 2871416 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  113 2871529 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  133 2871662 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  352 2872014 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99939 2971953 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  281 2972234 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  140 2972374 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  413 2972787 [main] test2 1974 fhandler_serial::raw_read: inq 100
  171 2972958 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  187 2973145 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  188 2973333 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  503 2973836 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  124 2973960 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  119 2974079 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  107 2974186 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  136 2974322 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  338 2974660 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99806 3074466 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  238 3074704 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  226 3074930 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  488 3075418 [main] test2 1974 fhandler_serial::raw_read: inq 100
  113 3075531 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
   28 3075559 [main] test2 1974 fhandler_base::read: returning -1, binary mode
   65 3075624 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  729 3076353 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  143 3076496 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  129 3076625 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  100 3076725 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  110 3076835 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  257 3077092 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99865 3176957 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  267 3177224 [main] test2 1974 pselect: pselect (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20, 0x0)
  104 3177328 [main] test2 1974 pselect: to->tv_sec 1, to->tv_nsec 0, us 1000000
  209 3177537 [main] test2 1974 dtable::select_read: /dev/ttyS27 fd 3
  152 3177689 [main] test2 1974 select: sel.always_ready 0
  311 3178000 [sersel] test2 1974 peek_serial: fh->overlapped_armed 0
   68 3178068 [main] test2 1974 select_stuff::wait: m 4, us 1000000, wmfo_timeout -1
  652 3178720 [sersel] test2 1974 thread_serial: exiting
  188 3178908 [main] test2 1974 select_stuff::wait: wait_ret 2, m = 4.  verifying
   80 3178988 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
   59 3179047 [main] test2 1974 set_bits: ready 1
   61 3179108 [main] test2 1974 select_stuff::wait: res after verify 0
   44 3179152 [main] test2 1974 select_stuff::wait: returning 0
   46 3179198 [main] test2 1974 select: sel.wait returns 0
   55 3179253 [main] test2 1974 peek_serial: fh->overlapped_armed 0
   65 3179318 [main] test2 1974 peek_serial: already ready
  165 3179483 [main] test2 1974 set_bits: me 0x80003B340, testing fd 3 (/dev/ttyS27)
   42 3179525 [main] test2 1974 set_bits: ready 1
   51 3179576 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  158 3179734 [main] test2 1974 select_stuff::destroy: deleting select records
  220 3179954 [main] test2 1974 select_stuff::cleanup: calling cleanup routines
  211 3180165 [main] test2 1974 select_stuff::destroy: deleting select records
  197 3180362 [main] test2 1974 pselect: 1 = select (4, 0xFFFFCBC8, 0x0, 0x0, 0xFFFFCA20)
  103 3180465 [main] test2 1974 ioctl: ioctl(fd 3, cmd 0x541B)
  111 3180576 [main] test2 1974 fhandler_serial::ioctl: 0 = ioctl(541B, 0xFFFFCA7C)
  220 3180796 [main] test2 1974 ioctl: 0 = ioctl(3, 0x541B, ...)
  426 3181222 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 6)
  112 3181334 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  116 3181450 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
   97 3181547 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
   70 3181617 [main] test2 1974 write: 6 = write(1, 0x80004B450, 6)
  152 3181769 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   56 3181825 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  323 3182148 [main] test2 1974 fhandler_serial::raw_read: inq 100
  118 3182266 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  122 3182388 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  189 3182577 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  224 3182801 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
   60 3182861 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
   47 3182908 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  142 3183050 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  231 3183281 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  312 3183593 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99848 3283441 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  190 3283631 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  206 3283837 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  530 3284367 [main] test2 1974 fhandler_serial::raw_read: inq 100
  166 3284533 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  199 3284732 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  201 3284933 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  610 3285543 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  124 3285667 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  230 3285897 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  117 3286014 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  155 3286169 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  349 3286518 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
99942 3386460 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  175 3386635 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
   84 3386719 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  380 3387099 [main] test2 1974 fhandler_serial::raw_read: inq 100
  153 3387252 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  135 3387387 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  144 3387531 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  477 3388008 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  112 3388120 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  216 3388336 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  108 3388444 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  107 3388551 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  264 3388815 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
100175 3488990 [main] test2 1974 clock_nanosleep: 0 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  251 3489241 [main] test2 1974 read: read(3, 0xFFFFCAB0, 100) nonblocking
  149 3489390 [main] test2 1974 fhandler_serial::raw_read: ulen 100, vmin_ 100, vtime_ 200, hEvent 0x160
  513 3489903 [main] test2 1974 fhandler_serial::raw_read: inq 100
  151 3490054 [main] test2 1974 __set_errno: virtual void fhandler_serial::raw_read(void*, size_t&):135 setting errno 11
  187 3490241 [main] test2 1974 fhandler_base::read: returning -1, binary mode
  186 3490427 [main] test2 1974 read: -1 = read(3, 0xFFFFCAB0, -1), errno 11
  570 3490997 [main] test2 1974 fhandler_pty_slave::write: pty0, write(0x80004B450, 23)
  112 3491109 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex (0x14C): waiting -1 ms
  128 3491237 [main] test2 1974 fhandler_pty_slave::write: (1507): pty output_mutex: acquired
  114 3491351 [main] test2 1974 fhandler_pty_slave::write: (1522): pty output_mutex(0x14C) released
  123 3491474 [main] test2 1974 write: 23 = write(1, 0x80004B450, 23)
  139 3491613 [main] test2 1974 clock_nanosleep: clock_nanosleep (0.100000000)
29210 3520823 [sig] test2 1974 sigpacket::process: signal 2 processing
  116 3520939 [sig] test2 1974 init_cygheap::find_tls: sig 2
   72 3521011 [sig] test2 1974 sigpacket::process: using tls 0xFFFFCE00
  315 3521326 [sig] test2 1974 sigpacket::process: signal 2, signal handler 0x180062F60
  109 3521435 [sig] test2 1974 sigpacket::setup_handler: controlled interrupt. stackptr 0xFFFFE460, stack 0xFFFFE458, stackptr[-1] 0x10040133E
  175 3521610 [sig] test2 1974 proc_subproc: args: 5, 1
  125 3521735 [main] test2 1974 clock_nanosleep: 4 = clock_nanosleep(1, 0, 0.100000000, 0.d)
  100 3521835 [sig] test2 1974 proc_subproc: clear waiting threads
  106 3521941 [sig] test2 1974 proc_subproc: finished clearing
   83 3522024 [sig] test2 1974 proc_subproc: returning 1
   53 3522077 [sig] test2 1974 _cygtls::interrupt_setup: armed signal_arrived 0x170, signal 2
   26 3522103 [sig] test2 1974 sigpacket::setup_handler: signal 2 delivered
   25 3522128 [sig] test2 1974 sigpacket::process: returning 1
   27 3522155 [main] test2 1974 __set_errno: unsigned int usleep(useconds_t):186 setting errno 4
   45 3522200 [main] test2 1974 set_process_mask_delta: oldmask 0, newmask 0, deltamask 0
   55 3522255 [main] test2 1974 signal_exit: exiting due to signal 2
   59 3522314 [main] test2 1974 signal_exit: about to call do_exit (2)
   57 3522371 [main] test2 1974 do_exit: do_exit (2), exit_state 2
   86 3522457 [main] test2 1974 void: 0x0 = signal (20, 0x1)
   56 3522513 [main] test2 1974 void: 0x0 = signal (1, 0x1)
   86 3522599 [main] test2 1974 void: 0x0 = signal (2, 0x1)
   90 3522689 [main] test2 1974 void: 0x0 = signal (3, 0x1)
  108 3522797 [main] test2 1974 fhandler_base::close_with_arch: line 1183:  /dev/pty0<0x1803452B0> usecount + -1 = 3
  131 3522928 [main] test2 1974 fhandler_base::close_with_arch: not closing archetype
   80 3523008 [main] test2 1974 fhandler_base::close_with_arch: line 1183:  /dev/pty0<0x1803452B0> usecount + -1 = 2
   93 3523101 [main] test2 1974 fhandler_base::close_with_arch: not closing archetype
  196 3523297 [main] test2 1974 fhandler_base::close_with_arch: line 1183:  /dev/pty0<0x1803452B0> usecount + -1 = 1
  199 3523496 [main] test2 1974 fhandler_base::close_with_arch: not closing archetype
   42 3523538 [main] test2 1974 fhandler_base::close: closing '/dev/ttyS27' handle 0x2B4
100057 3623595 [main] test2 1974 init_cygheap::close_ctty: closing cygheap->ctty 0x1803452B0
  219 3623814 [main] test2 1974 fhandler_base::close_with_arch: closing passed in archetype 0x0, usecount 0
  100 3623914 [main] test2 1974 fhandler_pty_slave::cleanup: /dev/pty0 closed, usecount 0
  106 3624020 [main] test2 1974 fhandler_pty_slave::close: closing last open /dev/pty0 handle
  467 3624487 [main] test2 1974 fhandler_console::free_console: freed console, res 1
   54 3624541 [main] test2 1974 fhandler_pty_common::close: pty0 <0x15C,0x168> closing
  116 3624657 [main] test2 1974 dtable::delete_archetype: deleting element 0 for /dev/pty0(136/0)
  204 3624861 [main] test2 1974 getpid: 1974 = getpid()
  176 3625037 [main] test2 1974 proc_terminate: nprocs 0
  186 3625223 [main] test2 1974 proc_terminate: leaving
  224 3625447 [main] test2 1974 pinfo::exit: Calling dlls.cleanup_forkables n 0x2, exitcode 0x200
  142 3625589 [main] test2 1974 pinfo::exit: Calling ExitProcess n 0x2, exitcode 0x200
--- Process 43708 (pid: 1974) thread 37764 exited with status 0x200
--- Process 43708 (pid: 1974) thread 28796 exited with status 0x200
--- Process 43708 (pid: 1974) thread 14456 exited with status 0x200
--- Process 43708 (pid: 1974) thread 4468 exited with status 0x200
--- Process 43708 (pid: 1974) exited with status 0x200

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 12 17:42, Åke Rehnman via Cygwin wrote:
> 
> On 2020-03-12 15:13, Corinna Vinschen wrote:
> > On Mar 12 14:32, Åke Rehnman via Cygwin wrote:
> > > On 2020-03-12 12:40, Corinna Vinschen wrote:
> > > > For a start, can you please strace the problem with a simple
> > > > testcase,like this:
> > > > 
> > > >     $ strace -o serio.trace <yourtestcase>
> > > > 
> > > > and send the source of your testcase as well as the serio.trace file
> > > > here?  It may show at which point the error code is generated.
> > > Should I post those files to the mailing list? I tried emailing them to you
> > > directly but it bounced...
> > Mailing list, please.
> 

> #include <stdio.h>
> #include <error.h>
> #include <errno.h>
> #include <sys/select.h>
> #include <fcntl.h>
> #include <unistd.h>
> #include <termios.h>
> #include <sys/ioctl.h>
> [...]

Thanks!  So that's what we're up against here :)


Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-12 12:40, Corinna Vinschen wrote:
>
> I inspected the serial I/O read function and I only see a subtil
> difference in terms of VMIN/VTIME which doesn't seem to be the culprit
> at first glance.  In O_NONBLOCK mode, the underlying Windows function
> ReadFile is called unconditionally.  My current hunch is this:
>
> - If VMIN>0 && VTIME>0, the Windows equivalent of tcsetattr is
>    told that VMIN>0.
>
> - So, assuming VMIN == 2 in Windows.  If VTIME > 0, the Cygwin read
>    function sets the number of bytes_to_read to 1 (this is old code,
>    don't ask why).
Do you have a pointer to this? I can not find it...
>
> - My assumption now is that the ReadFile function fails because it's
>    supposed to return only 1 char, but VMIN is > 1.
>
> There are two issues here.
>
> - If my assumption is correct, the tcsetattr function must not
>    set the Windows VMIN equivalent to != 0 in the O_NONBLOCK case.
>
> - Also, as mention above, if VTIME > 0, Cygwin's read sets the number of
>    bytes_to_read to 1.   Weirdly, it does so even if there are more than
>    1 byte in the inbound queue.  This sounds wrong to me.
>
I think the problem is if the number of bytes requested are more than 
what is in the buffer it is going to overlap the read function (because 
of VTIME) and immediately after that CancelIO is called. Contrary to 
what is mentioned in the source code I think CancelIO is actually 
discarding data...

   /* Use CancelIo rather than PurgeComm (PURGE_RXABORT) since
          PurgeComm apparently discards in-flight bytes while CancelIo
          only stops the overlapped IO routine. */


My suggestion is the following patch:

diff --git a/winsup/cygwin/fhandler_serial.cc 
b/winsup/cygwin/fhandler_serial.cc
index 69e5768f6..afa8871bf 100644
--- a/winsup/cygwin/fhandler_serial.cc
+++ b/winsup/cygwin/fhandler_serial.cc
@@ -898,7 +898,11 @@ fhandler_serial::tcsetattr (int action, const 
struct termios *t)
    {
      memset (&to, 0, sizeof (to));

-    if ((vmin_ > 0) && (vtime_ == 0))
+       if (is_nonblocking())
+       {
+               to.ReadIntervalTimeout = MAXDWORD;
+       }
+    else if ((vmin_ > 0) && (vtime_ == 0))
        {
         /* Returns immediately with whatever is in buffer on a ReadFile();
            or blocks if nothing found.  We will keep calling 
ReadFile(); until

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
> 
> On 2020-03-12 12:40, Corinna Vinschen wrote:
> > 
> > I inspected the serial I/O read function and I only see a subtil
> > difference in terms of VMIN/VTIME which doesn't seem to be the culprit
> > at first glance.  In O_NONBLOCK mode, the underlying Windows function
> > ReadFile is called unconditionally.  My current hunch is this:
> > 
> > - If VMIN>0 && VTIME>0, the Windows equivalent of tcsetattr is
> >    told that VMIN>0.
> > 
> > - So, assuming VMIN == 2 in Windows.  If VTIME > 0, the Cygwin read
> >    function sets the number of bytes_to_read to 1 (this is old code,
> >    don't ask why).
> Do you have a pointer to this? I can not find it...

That's because it's not true.  I created this mail during lunch break
and screwed up.

> > - My assumption now is that the ReadFile function fails because it's
> >    supposed to return only 1 char, but VMIN is > 1.
> > 
> > There are two issues here.
> > 
> > - If my assumption is correct, the tcsetattr function must not
> >    set the Windows VMIN equivalent to != 0 in the O_NONBLOCK case.
> > 
> > - Also, as mention above, if VTIME > 0, Cygwin's read sets the number of
> >    bytes_to_read to 1.   Weirdly, it does so even if there are more than
> >    1 byte in the inbound queue.  This sounds wrong to me.
> > 
> I think the problem is if the number of bytes requested are more than what

To clarify: number of bytes == VMIN?

> is in the buffer it is going to overlap the read function (because of VTIME)
> and immediately after that CancelIO is called. Contrary to what is mentioned
> in the source code I think CancelIO is actually discarding data...

So far we didn't have that experience.  CancelIO is usually safe
in this regard.

>   /* Use CancelIo rather than PurgeComm (PURGE_RXABORT) since
>          PurgeComm apparently discards in-flight bytes while CancelIo
>          only stops the overlapped IO routine. */
> 
> 
> My suggestion is the following patch:
> 
> diff --git a/winsup/cygwin/fhandler_serial.cc
> b/winsup/cygwin/fhandler_serial.cc
> index 69e5768f6..afa8871bf 100644
> --- a/winsup/cygwin/fhandler_serial.cc
> +++ b/winsup/cygwin/fhandler_serial.cc
> @@ -898,7 +898,11 @@ fhandler_serial::tcsetattr (int action, const struct
> termios *t)
>    {
>      memset (&to, 0, sizeof (to));
> 
> -    if ((vmin_ > 0) && (vtime_ == 0))
> +       if (is_nonblocking())
> +       {
> +               to.ReadIntervalTimeout = MAXDWORD;
> +       }
> +    else if ((vmin_ > 0) && (vtime_ == 0))

What if you switch to !O_NONBLOCK after calling tcsetattr?  The
setting of ReadIntervalTimeout would be lost then.

Either we have to repeat calling SetCommTimeouts every time
we switch mode, or we have to do the above setting temporary
every time we call ReadFile in non blocking mode.


Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 12 15:44, Corinna Vinschen wrote:
> On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
> > I think the problem is if the number of bytes requested are more than what
> 
> To clarify: number of bytes == VMIN?
> 
> > is in the buffer it is going to overlap the read function (because of VTIME)
> > and immediately after that CancelIO is called. Contrary to what is mentioned
> > in the source code I think CancelIO is actually discarding data...
> 
> So far we didn't have that experience.  CancelIO is usually safe
> in this regard.
> 
> >   /* Use CancelIo rather than PurgeComm (PURGE_RXABORT) since
> >          PurgeComm apparently discards in-flight bytes while CancelIo
> >          only stops the overlapped IO routine. */
> > 
> > 
> > My suggestion is the following patch:
> > 
> > diff --git a/winsup/cygwin/fhandler_serial.cc
> > b/winsup/cygwin/fhandler_serial.cc
> > index 69e5768f6..afa8871bf 100644
> > --- a/winsup/cygwin/fhandler_serial.cc
> > +++ b/winsup/cygwin/fhandler_serial.cc
> > @@ -898,7 +898,11 @@ fhandler_serial::tcsetattr (int action, const struct
> > termios *t)
> >    {
> >      memset (&to, 0, sizeof (to));
> > 
> > -    if ((vmin_ > 0) && (vtime_ == 0))
> > +       if (is_nonblocking())
> > +       {
> > +               to.ReadIntervalTimeout = MAXDWORD;
> > +       }
> > +    else if ((vmin_ > 0) && (vtime_ == 0))
> 
> What if you switch to !O_NONBLOCK after calling tcsetattr?  The
> setting of ReadIntervalTimeout would be lost then.
> 
> Either we have to repeat calling SetCommTimeouts every time
> we switch mode, or we have to do the above setting temporary
> every time we call ReadFile in non blocking mode.

What about this:

diff --git a/winsup/cygwin/fhandler_serial.cc b/winsup/cygwin/fhandler_serial.cc
--- a/winsup/cygwin/fhandler_serial.cc
+++ b/winsup/cygwin/fhandler_serial.cc
@@ -68,6 +68,16 @@ fhandler_serial::raw_read (void *ptr, size_t& ulen)
 	goto err;
       else if (ev)
 	termios_printf ("error detected %x", ev);
+      else if (is_nonblocking ())
+	{
+	  if (!st.cbInQue)
+	    {
+	      tot = -1;
+	      set_errno (EAGAIN);
+	      goto out;
+	    }
+	  inq = st.cbInQue;
+	}
       else if (st.cbInQue && !vtime_)
 	inq = st.cbInQue;
       else if (!is_nonblocking () && !overlapped_armed)


Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-12 16:08, Corinna Vinschen wrote:
> On Mar 12 15:44, Corinna Vinschen wrote:
>> On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
>>> I think the problem is if the number of bytes requested are more than what
>> To clarify: number of bytes == VMIN?
no number of bytes requested from ReadFile(). As far as I know Win32 has 
no concept of VMIN.
>>
>>> is in the buffer it is going to overlap the read function (because of VTIME)
>>> and immediately after that CancelIO is called. Contrary to what is mentioned
>>> in the source code I think CancelIO is actually discarding data...
>> So far we didn't have that experience.  CancelIO is usually safe
>> in this regard.
The data is MIA somehow...
>>
>>>    /* Use CancelIo rather than PurgeComm (PURGE_RXABORT) since
>>>           PurgeComm apparently discards in-flight bytes while CancelIo
>>>           only stops the overlapped IO routine. */
>>>
>>>
>>> My suggestion is the following patch:
>>>
>>> diff --git a/winsup/cygwin/fhandler_serial.cc
>>> b/winsup/cygwin/fhandler_serial.cc
>>> index 69e5768f6..afa8871bf 100644
>>> --- a/winsup/cygwin/fhandler_serial.cc
>>> +++ b/winsup/cygwin/fhandler_serial.cc
>>> @@ -898,7 +898,11 @@ fhandler_serial::tcsetattr (int action, const struct
>>> termios *t)
>>>     {
>>>       memset (&to, 0, sizeof (to));
>>>
>>> -    if ((vmin_ > 0) && (vtime_ == 0))
>>> +       if (is_nonblocking())
>>> +       {
>>> +               to.ReadIntervalTimeout = MAXDWORD;
>>> +       }
>>> +    else if ((vmin_ > 0) && (vtime_ == 0))
>> What if you switch to !O_NONBLOCK after calling tcsetattr?  The
>> setting of ReadIntervalTimeout would be lost then.
>>
>> Either we have to repeat calling SetCommTimeouts every time
>> we switch mode, or we have to do the above setting temporary
>> every time we call ReadFile in non blocking mode.
True.
> What about this:
>
> diff --git a/winsup/cygwin/fhandler_serial.cc b/winsup/cygwin/fhandler_serial.cc
> --- a/winsup/cygwin/fhandler_serial.cc
> +++ b/winsup/cygwin/fhandler_serial.cc
> @@ -68,6 +68,16 @@ fhandler_serial::raw_read (void *ptr, size_t& ulen)
>   	goto err;
>         else if (ev)
>   	termios_printf ("error detected %x", ev);
> +      else if (is_nonblocking ())
> +	{
> +	  if (!st.cbInQue)
> +	    {
> +	      tot = -1;
> +	      set_errno (EAGAIN);
> +	      goto out;
> +	    }
> +	  inq = st.cbInQue;
> +	}
>         else if (st.cbInQue && !vtime_)
>   	inq = st.cbInQue;
>         else if (!is_nonblocking () && !overlapped_armed)

Looks promising. I will try it.

BTW there is a gremlin in the "else if (ev)" line....

/Ake

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 12 18:04, Åke Rehnman via Cygwin wrote:
> 
> On 2020-03-12 16:08, Corinna Vinschen wrote:
> > On Mar 12 15:44, Corinna Vinschen wrote:
> > > On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
> > > > I think the problem is if the number of bytes requested are more than what
> > > To clarify: number of bytes == VMIN?
> no number of bytes requested from ReadFile(). As far as I know Win32 has no
> concept of VMIN.

Right, just this weird TimeoutMultiplier, but nevertheless I wasn't sure
what you meant.

> > > > is in the buffer it is going to overlap the read function (because of VTIME)
> > > > and immediately after that CancelIO is called. Contrary to what is mentioned
> > > > in the source code I think CancelIO is actually discarding data...
> > > So far we didn't have that experience.  CancelIO is usually safe
> > > in this regard.
> The data is MIA somehow...

Yes, but we're calling CancelIo in other circumstances in Cygwin and
there were no reports of missing data.  CancelIo is just supposed to
terminate the currently running overlapped IO, not to discard any
in-flight data.  If that's different for serial IO, there would be no
way to terminate serial overlapped IO gracefully.  Well, yeah, it's
Windows, but still...

> > > > -    if ((vmin_ > 0) && (vtime_ == 0))
> > > > +       if (is_nonblocking())
> > > > +       {
> > > > +               to.ReadIntervalTimeout = MAXDWORD;
> > > > +       }
> > > > +    else if ((vmin_ > 0) && (vtime_ == 0))
> > > What if you switch to !O_NONBLOCK after calling tcsetattr?  The
> > > setting of ReadIntervalTimeout would be lost then.
> > > 
> > > Either we have to repeat calling SetCommTimeouts every time
> > > we switch mode, or we have to do the above setting temporary
> > > every time we call ReadFile in non blocking mode.
> True.
> > What about this:
> > 
> > diff --git a/winsup/cygwin/fhandler_serial.cc b/winsup/cygwin/fhandler_serial.cc
> > --- a/winsup/cygwin/fhandler_serial.cc
> > +++ b/winsup/cygwin/fhandler_serial.cc
> > @@ -68,6 +68,16 @@ fhandler_serial::raw_read (void *ptr, size_t& ulen)
> >   	goto err;
> >         else if (ev)
> >   	termios_printf ("error detected %x", ev);
> > +      else if (is_nonblocking ())
> > +	{
> > +	  if (!st.cbInQue)
> > +	    {
> > +	      tot = -1;
> > +	      set_errno (EAGAIN);
> > +	      goto out;
> > +	    }
> > +	  inq = st.cbInQue;
> > +	}
> >         else if (st.cbInQue && !vtime_)
> >   	inq = st.cbInQue;
> >         else if (!is_nonblocking () && !overlapped_armed)
> 
> Looks promising. I will try it.
> 
> BTW there is a gremlin in the "else if (ev)" line....

A gremlin?  Would you mind to explain?  Btw., if you find a bug
in the code, we do take patches :) https://cygwin.com/contrib.html


Thanks,
Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-13 11:12, Corinna Vinschen wrote:
> On Mar 12 18:04, Åke Rehnman via Cygwin wrote:
>> On 2020-03-12 16:08, Corinna Vinschen wrote:
>>> On Mar 12 15:44, Corinna Vinschen wrote:
>>>> On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
>>>>> I think the problem is if the number of bytes requested are more than what
>>>> To clarify: number of bytes == VMIN?
>> no number of bytes requested from ReadFile(). As far as I know Win32 has no
>> concept of VMIN.
> Right, just this weird TimeoutMultiplier, but nevertheless I wasn't sure
> what you meant.
>
>>>>> is in the buffer it is going to overlap the read function (because of VTIME)
>>>>> and immediately after that CancelIO is called. Contrary to what is mentioned
>>>>> in the source code I think CancelIO is actually discarding data...
>>>> So far we didn't have that experience.  CancelIO is usually safe
>>>> in this regard.
>> The data is MIA somehow...
> Yes, but we're calling CancelIo in other circumstances in Cygwin and
> there were no reports of missing data.  CancelIo is just supposed to
> terminate the currently running overlapped IO, not to discard any
> in-flight data.  If that's different for serial IO, there would be no
> way to terminate serial overlapped IO gracefully.  Well, yeah, it's
> Windows, but still...
I have scrutinized the microsoft serial driver reference implementation 
(https://github.com/microsoft/Windows-driver-samples/blob/master/serial/serial/read.c) 
and it looks to me as CancelIo does not purge any data. However since 
the driver is vendor dependent in my case FTDI it is impossible to know 
exactly what is going on since it is closed source.
>>>>> -    if ((vmin_ > 0) && (vtime_ == 0))
>>>>> +       if (is_nonblocking())
>>>>> +       {
>>>>> +               to.ReadIntervalTimeout = MAXDWORD;
>>>>> +       }
>>>>> +    else if ((vmin_ > 0) && (vtime_ == 0))
>>>> What if you switch to !O_NONBLOCK after calling tcsetattr?  The
>>>> setting of ReadIntervalTimeout would be lost then.
>>>>
>>>> Either we have to repeat calling SetCommTimeouts every time
>>>> we switch mode, or we have to do the above setting temporary
>>>> every time we call ReadFile in non blocking mode.
>> True.
>>> What about this:
>>>
>>> diff --git a/winsup/cygwin/fhandler_serial.cc b/winsup/cygwin/fhandler_serial.cc
>>> --- a/winsup/cygwin/fhandler_serial.cc
>>> +++ b/winsup/cygwin/fhandler_serial.cc
>>> @@ -68,6 +68,16 @@ fhandler_serial::raw_read (void *ptr, size_t& ulen)
>>>    	goto err;
>>>          else if (ev)
>>>    	termios_printf ("error detected %x", ev);
>>> +      else if (is_nonblocking ())
>>> +	{
>>> +	  if (!st.cbInQue)
>>> +	    {
>>> +	      tot = -1;
>>> +	      set_errno (EAGAIN);
>>> +	      goto out;
>>> +	    }
>>> +	  inq = st.cbInQue;
>>> +	}
>>>          else if (st.cbInQue && !vtime_)
>>>    	inq = st.cbInQue;
>>>          else if (!is_nonblocking () && !overlapped_armed)
>> Looks promising. I will try it.
Your patch works (for my test case and screen). Question is if we have 
to consider the case where ulen==0 ...
>>
>> BTW there is a gremlin in the "else if (ev)" line....
> A gremlin?  Would you mind to explain?  Btw., if you find a bug
> in the code, we do take patches :) https://cygwin.com/contrib.html
If we have an error event in ev it will make a blocking read even if 
VTIME==0.

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-14 11:23, Åke Rehnman wrote:
>
> On 2020-03-13 11:12, Corinna Vinschen wrote:
>> On Mar 12 18:04, Åke Rehnman via Cygwin wrote:
>>> On 2020-03-12 16:08, Corinna Vinschen wrote:
>>>> On Mar 12 15:44, Corinna Vinschen wrote:
>>>>> On Mar 12 15:20, Åke Rehnman via Cygwin wrote:
>>>>>> I think the problem is if the number of bytes requested are more 
>>>>>> than what
>>>>> To clarify: number of bytes == VMIN?
>>> no number of bytes requested from ReadFile(). As far as I know Win32 
>>> has no
>>> concept of VMIN.
>> Right, just this weird TimeoutMultiplier, but nevertheless I wasn't sure
>> what you meant.
>>
>>>>>> is in the buffer it is going to overlap the read function 
>>>>>> (because of VTIME)
>>>>>> and immediately after that CancelIO is called. Contrary to what 
>>>>>> is mentioned
>>>>>> in the source code I think CancelIO is actually discarding data...
>>>>> So far we didn't have that experience.  CancelIO is usually safe
>>>>> in this regard.
>>> The data is MIA somehow...
>> Yes, but we're calling CancelIo in other circumstances in Cygwin and
>> there were no reports of missing data.  CancelIo is just supposed to
>> terminate the currently running overlapped IO, not to discard any
>> in-flight data.  If that's different for serial IO, there would be no
>> way to terminate serial overlapped IO gracefully.  Well, yeah, it's
>> Windows, but still...
> I have scrutinized the microsoft serial driver reference 
> implementation 
> (https://github.com/microsoft/Windows-driver-samples/blob/master/serial/serial/read.c) 
> and it looks to me as CancelIo does not purge any data. However since 
> the driver is vendor dependent in my case FTDI it is impossible to 
> know exactly what is going on since it is closed source.
>>>>>> -    if ((vmin_ > 0) && (vtime_ == 0))
>>>>>> +       if (is_nonblocking())
>>>>>> +       {
>>>>>> +               to.ReadIntervalTimeout = MAXDWORD;
>>>>>> +       }
>>>>>> +    else if ((vmin_ > 0) && (vtime_ == 0))
>>>>> What if you switch to !O_NONBLOCK after calling tcsetattr?  The
>>>>> setting of ReadIntervalTimeout would be lost then.
>>>>>
>>>>> Either we have to repeat calling SetCommTimeouts every time
>>>>> we switch mode, or we have to do the above setting temporary
>>>>> every time we call ReadFile in non blocking mode.
>>> True.
>>>> What about this:
>>>>
>>>> diff --git a/winsup/cygwin/fhandler_serial.cc 
>>>> b/winsup/cygwin/fhandler_serial.cc
>>>> --- a/winsup/cygwin/fhandler_serial.cc
>>>> +++ b/winsup/cygwin/fhandler_serial.cc
>>>> @@ -68,6 +68,16 @@ fhandler_serial::raw_read (void *ptr, size_t& ulen)
>>>>        goto err;
>>>>          else if (ev)
>>>>        termios_printf ("error detected %x", ev);
>>>> +      else if (is_nonblocking ())
>>>> +    {
>>>> +      if (!st.cbInQue)
>>>> +        {
>>>> +          tot = -1;
>>>> +          set_errno (EAGAIN);
>>>> +          goto out;
>>>> +        }
>>>> +      inq = st.cbInQue;
>>>> +    }
>>>>          else if (st.cbInQue && !vtime_)
>>>>        inq = st.cbInQue;
>>>>          else if (!is_nonblocking () && !overlapped_armed)
>>> Looks promising. I will try it.
> Your patch works (for my test case and screen). Question is if we have 
> to consider the case where ulen==0 ...
>>>
>>> BTW there is a gremlin in the "else if (ev)" line....
>> A gremlin?  Would you mind to explain?  Btw., if you find a bug
>> in the code, we do take patches :) https://cygwin.com/contrib.html
> If we have an error event in ev it will make a blocking read even if 
> VTIME==0.
>
I forgot, also any CancelIo should be terminated with a blocking 
GetOverlappedResult() see this excellent blog post 
https://devblogs.microsoft.com/oldnewthing/20110202-00/?p=11613

    // took longer than 1 second - cancel it and give up
    CancelIo(h);
    WaitForSingleObject(o.hEvent, INFINITE); // added // Alternatively: 
GetOverlappedResult(h, &o, TRUE);
    return WAIT_TIMEOUT;

/Ake

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

On Mar 14 11:36, Åke Rehnman via Cygwin wrote:
> On 2020-03-14 11:23, Åke Rehnman wrote:
> > Your patch works (for my test case and screen). Question is if we have
> > to consider the case where ulen==0 ...

Thanks for testing!

> > > > BTW there is a gremlin in the "else if (ev)" line....
> > > A gremlin?  Would you mind to explain?  Btw., if you find a bug
> > > in the code, we do take patches :) https://cygwin.com/contrib.html
> > If we have an error event in ev it will make a blocking read even if
> > VTIME==0.

Ah, yeah, I was aware of that, I just ignored it for now since I'm not
sure what the best way to handle that is.

Two options come to mind, either ignoring these errors entirely, or
returning -1 with errno set to EIO, along the lines of the Linux test
for tty_io_error() at the start of tty_read.

However, I have a sinking feeling that the function needs a rewrite
anyway.

For instance, consider reading in blocking mode, which may result in
running the for loop more than once.  If the first loop successfully
read 4 bytes, and the second loop runs into an error from
ClearCommError, the function will return -1 with errno set, completely
ignoring the fact that 4 bytes have been read already.

It should return 4 in this case, and only the next run of
fhandler_serial::raw_read *might* return -1.

This code really shows its age...


> I forgot, also any CancelIo should be terminated with a blocking
> GetOverlappedResult() see this excellent blog post
> https://devblogs.microsoft.com/oldnewthing/20110202-00/?p=11613
> 
>    // took longer than 1 second - cancel it and give up
>    CancelIo(h);
>    WaitForSingleObject(o.hEvent, INFINITE); // added // Alternatively:
> GetOverlappedResult(h, &o, TRUE);
>    return WAIT_TIMEOUT;

Thanks, fixed in git.


Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Corinna Vinschen]

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

Hi Åke,

On Mar 16 10:35, Corinna Vinschen wrote:
> On Mar 14 11:36, Åke Rehnman via Cygwin wrote:
> > On 2020-03-14 11:23, Åke Rehnman wrote:
> > > > > BTW there is a gremlin in the "else if (ev)" line....
> > > > A gremlin?  Would you mind to explain?  Btw., if you find a bug
> > > > in the code, we do take patches :) https://cygwin.com/contrib.html
> > > If we have an error event in ev it will make a blocking read even if
> > > VTIME==0.
> 
> Ah, yeah, I was aware of that, I just ignored it for now since I'm not
> sure what the best way to handle that is.
> 
> Two options come to mind, either ignoring these errors entirely, or
> returning -1 with errno set to EIO, along the lines of the Linux test
> for tty_io_error() at the start of tty_read.
> 
> However, I have a sinking feeling that the function needs a rewrite
> anyway.
> 
> For instance, consider reading in blocking mode, which may result in
> running the for loop more than once.  If the first loop successfully
> read 4 bytes, and the second loop runs into an error from
> ClearCommError, the function will return -1 with errno set, completely
> ignoring the fact that 4 bytes have been read already.
> 
> It should return 4 in this case, and only the next run of
> fhandler_serial::raw_read *might* return -1.
> 
> This code really shows its age...

I have revamped the fhandler_serial::raw_read function, but I need
somebody for testing.  Any chance you volunteer for that job?
We may need a couple of days to iron out all problems, but I think
the code is more sound now than the original function.  I even
added a couple of comments to the code (*gasp*) so there's stuff
to discuss and to see why I did it that way.

For a quicker turn around we can also use Freenode IRC, see
https://cygwin.com/irc.html

Interested?


Thanks,
Corinna

-- 
Corinna Vinschen
Cygwin Maintainer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: Setting termios VMIN > 0 and VTIME > 0 on non blocking file

[Åke Rehnman]

On 2020-03-17 13:16, Corinna Vinschen wrote:
> Hi Åke,
>
> On Mar 16 10:35, Corinna Vinschen wrote:
>> On Mar 14 11:36, Åke Rehnman via Cygwin wrote:
>>> On 2020-03-14 11:23, Åke Rehnman wrote:
>>>>>> BTW there is a gremlin in the "else if (ev)" line....
>>>>> A gremlin?  Would you mind to explain?  Btw., if you find a bug
>>>>> in the code, we do take patches :) https://cygwin.com/contrib.html
>>>> If we have an error event in ev it will make a blocking read even if
>>>> VTIME==0.
>> Ah, yeah, I was aware of that, I just ignored it for now since I'm not
>> sure what the best way to handle that is.
>>
>> Two options come to mind, either ignoring these errors entirely, or
>> returning -1 with errno set to EIO, along the lines of the Linux test
>> for tty_io_error() at the start of tty_read.
>>
>> However, I have a sinking feeling that the function needs a rewrite
>> anyway.
>>
>> For instance, consider reading in blocking mode, which may result in
>> running the for loop more than once.  If the first loop successfully
>> read 4 bytes, and the second loop runs into an error from
>> ClearCommError, the function will return -1 with errno set, completely
>> ignoring the fact that 4 bytes have been read already.
>>
>> It should return 4 in this case, and only the next run of
>> fhandler_serial::raw_read *might* return -1.
>>
>> This code really shows its age...
> I have revamped the fhandler_serial::raw_read function, but I need
> somebody for testing.  Any chance you volunteer for that job?
> We may need a couple of days to iron out all problems, but I think
> the code is more sound now than the original function.  I even
> added a couple of comments to the code (*gasp*) so there's stuff
> to discuss and to see why I did it that way.
>
> For a quicker turn around we can also use Freenode IRC, see
> https://cygwin.com/irc.html
>
> Interested?

Sure, bring it on!

/Ake