Serial and pread

[Izak Burger]

Hello,

I'm currently debugging a problem with serial comms over wine, and I see 
that when a serial device is opened (in server/serial.c) the 
serial_get_info function returns a type of FD_TYPE_DEFAULT, which in 
turn causes the serial device to be read from and written to with pread 
and pwrite in dlls/ntdll/file.c.  Will this even work?  I mean, how can 
you write or read to a serial port while using an offset?

In any case, I changed the code to return FD_TYPE_SOCKET instead ( I 
thought a serial port is probably a lot more like a socket than it is a 
file) and now I get some activity on the serial port (before there was 
nothing), but it still does not work as it should.  Not to worry, I just 
wanted to ask if all the trouble people were having with async serial 
comms might not be related to this?

Any ideas greatly appreciated.

regards,
Izak

[Alexandre Julliard]

Izak Burger  writes:
> I'm currently debugging a problem with serial comms over wine, and I
> see that when a serial device is opened (in server/serial.c) the
> serial_get_info function returns a type of FD_TYPE_DEFAULT, which in
> turn causes the serial device to be read from and written to with
> pread and pwrite in dlls/ntdll/file.c.  Will this even work?  I mean,
> how can you write or read to a serial port while using an offset?

You can't, the pread() call is supposed to fail with ESPIPE, in which
case we fall back to a normal read. Doesn't this work for you?  What
error does the pread() call return?

[Izak Burger]

I end up showing my ignorance :-)

Ok, I see how it is supposed to work, so I changed it back to 
FD_TYPE_DEFAULT.  It looks like my real troubles is caused by the 
snippet of code that decides when the read is successful:

if (io_status->Information >= fileio->count
     || fileio->fd_type == FD_TYPE_SOCKET )
       io_status->u.Status = STATUS_SUCCESS;
else
       io_status->u.Status = STATUS_PENDING;

For the app in question, when I turn on debugging for ntdll I get:

trace:ntdll:FILE_AsyncReadService 0x42295b4f 0x42295fe1 1
trace:ntdll:FILE_AsyncReadService read 1 more bytes 7/1040 so far, 
io_status->u.Status=0x103

trace:ntdll:FILE_AsyncReadService 0x42295b4f 0x42295fe1 1
trace:ntdll:FILE_AsyncReadService read 1 more bytes 8/1040 so far, 
io_status->u.Status=0x103

trace:ntdll:FILE_AsyncReadService 0x42295b4f 0x42295fe1 1
trace:ntdll:FILE_AsyncReadService read 1 more bytes 9/1040 so far, 
io_status->u.Status=0x103

The tracing of io_status->u.Status was added by myself.  I'm not sure if 
the problem is not perhaps caused by the fact that u.Status is always 
0x103 (STATUS_PENDING) and never becomes 0x0 (STATUS_SUCCESS).  Of 
course, if I change the FD_TYPE to FD_TYPE_SOCKET, the result is always 
STATUS_SUCCESS, which is probably what the app wants.  Not knowing much 
about the API or how Windows implements it (haven't programmed in the 
windows environment for 7 years now) I'm not even sure if this is some 
kind of a windows quirk exploited by this app.

If my experience with unix in general is anything to go by, then it 
would be acceptable to provide a 1040 byte buffer, and read as much data 
into it as you can (which is almost always less than the 1040 you 
_could_ theoretically read in one go), then return STATUS_SUCCESS.  Is 
it the same for windows?  Obviously the above code will return 
STATUS_PENDING until it has read 1040 bytes, and only then will it 
return STATUS_SUCCESS.

A bit of background: the software is supposed to talk to a Casio point 
of sale system.  This POS device pumps out the letter "C" on the serial 
port, about once every 5 seconds.  That is why the ntdll trace above 
shows a character by character receive.  I get the feeling the app is 
really just waiting for the first "C" to arrive, but after 60 seconds it 
times out.  The app is of course closed source, and I get the feeling 
the actual communication is done by code in a .dll file provided by 
Casio.  Ie, no chance of fixing up the windows app.

regards,
Izak

Alexandre Julliard wrote:
> You can't, the pread() call is supposed to fail with ESPIPE, in which
> case we fall back to a normal read. Doesn't this work for you?  What
> error does the pread() call return?

[Mike McCormack]

Hi Izak,

The wineserver may also change the status of the request to 
STATUS_SUCCESS after a certain timeout is reached.  The problem is most 
likely that the timeout is not being calculated properly.

The code to do that is in server/async.c and server/serial.c.

The timeouts are set by the SetCommTimeouts call.  Try using the +serial 
debug channel to see what timeouts are being set.  The parameters to the 
ReadFile command may also be important - check whether it is being 
called with an overlapped structure or not.

Mike

Izak Burger wrote:
> trace:ntdll:FILE_AsyncReadService 0x42295b4f 0x42295fe1 1
> trace:ntdll:FILE_AsyncReadService read 1 more bytes 9/1040 so far, 
> io_status->u.Status=0x103
>
> The tracing of io_status->u.Status was added by myself.  I'm not sure if 
> the problem is not perhaps caused by the fact that u.Status is always 
> 0x103 (STATUS_PENDING) and never becomes 0x0 (STATUS_SUCCESS).  Of 
> course, if I change the FD_TYPE to FD_TYPE_SOCKET, the result is always 
> STATUS_SUCCESS, which is probably what the app wants.  Not knowing much 
> about the API or how Windows implements it (haven't programmed in the 
> windows environment for 7 years now) I'm not even sure if this is some 
> kind of a windows quirk exploited by this app.
>
> If my experience with unix in general is anything to go by, then it 
> would be acceptable to provide a 1040 byte buffer, and read as much data 
> into it as you can (which is almost always less than the 1040 you 
> _could_ theoretically read in one go), then return STATUS_SUCCESS.  Is 
> it the same for windows?  Obviously the above code will return 
> STATUS_PENDING until it has read 1040 bytes, and only then will it 
> return STATUS_SUCCESS.

[Izak Burger]

Thanks for the speedy reply.

Mike McCormack wrote:
> The wineserver may also change the status of the request to 
> STATUS_SUCCESS after a certain timeout is reached.  The problem is most 
> likely that the timeout is not being calculated properly.
>
> The code to do that is in server/async.c and server/serial.c.

I cannot actually find the place where that happens (setting the status 
to STATUS_SUCCESS), but I guess I will eventually.
> The timeouts are set by the SetCommTimeouts call.  Try using the
> +serial debug channel to see what timeouts are being set.  The

Ok.  I had to set +comm to get that info, and modified the code to dump 
the contents of the COMMTIMEOUTS structure:

trace:comm:SetCommTimeouts ReadIntervalTimeout=4294967295
trace:comm:SetCommTimeouts ReadTotalTimeoutMultiplier=0
trace:comm:SetCommTimeouts ReadTotalTimeoutConstant=0
trace:comm:SetCommTimeouts WriteTotalTimeoutMultiplier=0
trace:comm:SetCommTimeouts WriteTotalTimeoutConstant=5000

MSDN says this means to return immediately with whatever is there.
> ReadFile command may also be important - check whether it is being 
> called with an overlapped structure or not.

It is called with an overlapped structure:
trace:file:ReadFile 0x88 0x42295ff1 1040 0x4081ace0 0x42295b5f
                                                     ^^^^^^^^^^
regards,
Izak

[Mike McCormack]

Izak Burger wrote:
> Ok.  I had to set +comm to get that info, and modified the code to dump 
> the contents of the COMMTIMEOUTS structure:
>
> trace:comm:SetCommTimeouts ReadIntervalTimeout=4294967295
> trace:comm:SetCommTimeouts ReadTotalTimeoutMultiplier=0
> trace:comm:SetCommTimeouts ReadTotalTimeoutConstant=0
> trace:comm:SetCommTimeouts WriteTotalTimeoutMultiplier=0
> trace:comm:SetCommTimeouts WriteTotalTimeoutConstant=5000
>
> MSDN says this means to return immediately with whatever is there.
> > ReadFile command may also be important - check whether it is being 
> > called with an overlapped structure or not.
>
> It is called with an overlapped structure:
> trace:file:ReadFile 0x88 0x42295ff1 1040 0x4081ace0 0x42295b5f

Hi Izak,

It appears we don't handle this case properly.  We only handle 
ReadIntervalTimeout=MAXDWORD in non-overlapped mode.  Can you try the 
following (untested) patch and see if it fixes the problem?

Mike

Index: server/serial.c
===================================================================
RCS file: /home/wine/wine/server/serial.c,v
retrieving revision 1.33
diff -u -r1.33 serial.c
--- server/serial.c	8 Apr 2004 19:09:04 -0000	1.33
+++ server/serial.c	14 Apr 2004 10:25:45 -0000
@@ -273,6 +273,28 @@
         if ( !async )
             return;

+        /*
+         * The following combination of timeout values means we're try to
+         * read as much data as is available, then return immediately.
+         */
+        if ( (serial->readinterval == MAXDWORD) &&
+              (serial->readmult == 0) && (serial->readconst == 0) )
+        {
+            struct pollfd pfd;
+
+            pfd.fd = get_unix_fd(fd);
+            pfd.events = POLLIN;
+            pfd.revents = 0;
+            poll( &pfd, 1, 0 );
+
+            if ( !(pfd.revents & POLLIN) )
+            {
+                async_notify( async, STATUS_SUCCESS);
+                destroy_async( async );
+                return;
+            }
+        }
+
         async->status = STATUS_PENDING;
         if(!async->q)
         {

[Izak Burger]

Nope, now the app just dies with very little trace as to why.  Not to 
worry, I just need to go eat some lunch or something and get my head 
clear.  This conversation has given me a much clearer understanding of 
what goes on.

Mike McCormack wrote:
> Izak Burger wrote:
> > Ok.  I had to set +comm to get that info, and modified the code to 
> > dump the contents of the COMMTIMEOUTS structure:
> >
> > trace:comm:SetCommTimeouts ReadIntervalTimeout=4294967295
> > trace:comm:SetCommTimeouts ReadTotalTimeoutMultiplier=0
> > trace:comm:SetCommTimeouts ReadTotalTimeoutConstant=0
> > trace:comm:SetCommTimeouts WriteTotalTimeoutMultiplier=0
> > trace:comm:SetCommTimeouts WriteTotalTimeoutConstant=5000
> >
> > MSDN says this means to return immediately with whatever is there.
> > > ReadFile command may also be important - check whether it is being 
> > > called with an overlapped structure or not.
> >
> > It is called with an overlapped structure:
> > trace:file:ReadFile 0x88 0x42295ff1 1040 0x4081ace0 0x42295b5f
>
> Hi Izak,
>
> It appears we don't handle this case properly.  We only handle 
> ReadIntervalTimeout=MAXDWORD in non-overlapped mode.  Can you try the 
> following (untested) patch and see if it fixes the problem?
>
> Mike
> Index: server/serial.c
>
> RCS file: /home/wine/wine/server/serial.c,v
> retrieving revision 1.33
> diff -u -r1.33 serial.c
> --- server/serial.c	8 Apr 2004 19:09:04 -0000	1.33
> +++ server/serial.c	14 Apr 2004 10:25:45 -0000
> @@ -273,6 +273,28 @@
>          if ( !async )
>              return;
> -
>    /*
> -
>     * The following combination of timeout values means we're try to
> -
>     * read as much data as is available, then return immediately.
> -
>     */
> -
>    if ( (serial->readinterval == MAXDWORD) &&
> -
>          (serial->readmult == 0) && (serial->readconst == 0) )
> -
>    {
> -
>        struct pollfd pfd;
> -
> -
>        pfd.fd = get_unix_fd(fd);
> -
>        pfd.events = POLLIN;
> -
>        pfd.revents = 0;
> -
>        poll( &pfd, 1, 0 );
> -
> -
>        if ( !(pfd.revents & POLLIN) )
> -
>        {
> -
>            async_notify( async, STATUS_SUCCESS);
> -
>            destroy_async( async );
> -
>            return;
> -
>        }
> -
>    }
> -
>    async->status = STATUS_PENDING;
>    if(!async->q)
>    {

[Izak Burger]

Hello,

Me again.

Here is a patch that makes it work.  I'm probably doing something 
terrible here, but it solves the problem for now.  I'm piggy-backing on 
the code for handling FD_TYPE_SOCKET, because I noticed that if I treat 
a serial port with:

ReadIntervalTimeout=MAXDWORD
ReadTotalTimeoutMultiplier=0
ReadTotalTimeoutConstant=0

as a socket it will do exactly what I expect.  If there is another 
better way to do it, please do tell :-)  In my opinion, the problem is 
that the decision as to whether to set the state to STATUS_PENDING or 
STATUS_SUCCESS happens while file io is being done, and the information 
needed to make the decision requires that you know something about the 
serial device while doing file_io.

I can now communicate with the POS, but the app still crashes and dumps 
me in the debugger when it exits.  I don't really care about that though :-)

regards,
Izak

Izak Burger wrote:
> Nope, now the app just dies with very little trace as to why.  Not to 
> worry, I just need to go eat some lunch or something and get my head 
> clear.  This conversation has given me a much clearer understanding of 
> what goes on.
>
> Mike McCormack wrote:
> > Izak Burger wrote:
> > > Ok.  I had to set +comm to get that info, and modified the code to 
> > > dump the contents of the COMMTIMEOUTS structure:
> > >
> > > trace:comm:SetCommTimeouts ReadIntervalTimeout=4294967295
> > > trace:comm:SetCommTimeouts ReadTotalTimeoutMultiplier=0
> > > trace:comm:SetCommTimeouts ReadTotalTimeoutConstant=0
> > > trace:comm:SetCommTimeouts WriteTotalTimeoutMultiplier=0
> > > trace:comm:SetCommTimeouts WriteTotalTimeoutConstant=5000
> > >
> > > MSDN says this means to return immediately with whatever is there.
> > > > ReadFile command may also be important - check whether it is being 
> > > > called with an overlapped structure or not.
> > >
> > > It is called with an overlapped structure:
> > > trace:file:ReadFile 0x88 0x42295ff1 1040 0x4081ace0 0x42295b5f
> >
> > Hi Izak,
> >
> > It appears we don't handle this case properly.  We only handle 
> > ReadIntervalTimeout=MAXDWORD in non-overlapped mode.  Can you try the 
> > following (untested) patch and see if it fixes the problem?
> >
> > Mike
> > Index: server/serial.c
> >
> > RCS file: /home/wine/wine/server/serial.c,v
> > retrieving revision 1.33
> > diff -u -r1.33 serial.c
> > --- server/serial.c    8 Apr 2004 19:09:04 -0000    1.33
> > +++ server/serial.c    14 Apr 2004 10:25:45 -0000
> > @@ -273,6 +273,28 @@
> >          if ( !async )
> >              return;
> > -
> >    /*
> > -
> >     * The following combination of timeout values means we're 
> >
> > try to
> > -
> >     * read as much data as is available, then return immediately.
> > -
> >     */
> > -
> >    if ( (serial->readinterval == MAXDWORD) &&
> > -
> >          (serial->readmult == 0) && (serial->readconst == 0) )
> > -
> >    {
> > -
> >        struct pollfd pfd;
> > -
> > -
> >        pfd.fd = get_unix_fd(fd);
> > -
> >        pfd.events = POLLIN;
> > -
> >        pfd.revents = 0;
> > -
> >        poll( &pfd, 1, 0 );
> > -
> > -
> >        if ( !(pfd.revents & POLLIN) )
> > -
> >        {
> > -
> >            async_notify( async, STATUS_SUCCESS);
> > -
> >            destroy_async( async );
> > -
> >            return;
> > -
> >        }
> > -
> >    }
> > -
> >    async->status = STATUS_PENDING;
> >    if(!async->q)
> >    {

--- wine.old/server/serial.c	2004-04-08 21:09:04.000000000 +0200
+++ wine/server/serial.c	2004-04-21 11:08:12.000000000 +0200
@@ -213,6 +213,18 @@
               (serial->readmult == 0) && (serial->readconst == 0)) )
         *flags |= FD_FLAG_TIMEOUT;

+    /* MSDN says: A value of MAXDWORD, combined with zero values for both the
+     * ReadTotalTimeoutConstant and ReadTotalTimeoutMultiplier members,
+     * specifies that the read operation is to return immediately with the
+     * characters that have already been received, even if no characters have
+     * been received.  
+     *
+     * This will happen if we treat the serial device as if it
+     * is a socket*/
+    if ( (serial->readinterval == MAXDWORD) &&
+        (serial->readmult == 0) && (serial->readconst == 0) ){
+        return FD_TYPE_SOCKET;
+    }
     return FD_TYPE_DEFAULT;
 }