Re: [ros-svn] [hbirr] 14296: - Guarded the calls to IoSetCancelRoutine with IoAcquireCancelSpinLock/IoReleaseCancelSpinLock.

[Filip Navara]

[e-mail] wrote:
> Guarded the calls to IoSetCancelRoutine with IoAcquireCancelSpinLock/IoReleaseCancelSpinLock.
> Used a fastmutex as lock for the data queue.
> Used paged pool for the data buffers.
> Allowed the server to read (and to wait) on a listening pipe.
> Implemented the non blocking read operations.
>
> Updated files:
> trunk/reactos/drivers/fs/np/create.c
> trunk/reactos/drivers/fs/np/fsctrl.c
> trunk/reactos/drivers/fs/np/npfs.c
> trunk/reactos/drivers/fs/np/npfs.h
> trunk/reactos/drivers/fs/np/rw.c

This change seems to break RPC connection reads. I'm currently busy 
working on other things so I can't look at the problem. Any help is 
appreciated... (little test application attached, source available on 
request or in PSDK examples)

- Filip

[Hartmut Birr]

Filip Navara wrote:
> This change seems to break RPC connection reads. I'm currently busy
> working on other things so I can't look at the problem. Any help is
> appreciated... (little test application attached, source available on
> request or in PSDK examples)

I think that is a bug in the rpcrt4 implementation. The receive and send
functions do check for a pending io request in a wrong way.

- Hartmut

[Filip Navara]

Hartmut Birr wrote:
> Filip Navara wrote:
> > This change seems to break RPC connection reads. I'm currently busy
> > working on other things so I can't look at the problem. Any help is
> > appreciated... (little test application attached, source available on
> > request or in PSDK examples)
>
> I think that is a bug in the rpcrt4 implementation. The receive and send
> functions do check for a pending io request in a wrong way.

It's not impossible, but the code works just fine on Windows and Wine... 
Can you point me to the code you think is wrong?

- Filip

[Hartmut Birr]

Filip Navara wrote:
> > I think that is a bug in the rpcrt4 implementation. The receive and send
> > functions do check for a pending io request in a wrong way.
>
> It's not impossible, but the code works just fine on Windows and
> Wine... Can you point me to the code you think is wrong?

rpc_message calls ReadFile/WriteFile for pipes which are open for
asynchronous requests. ReadFile/WriteFile can fail for an pending
request. If it fails, the caller must check the last status
(GetLastError()) for ERROR_IO_PENDING. An other problem is the using of
the overlapped structure. The same structure is used for read and write
requests. Sometimes the results from a write request is interpreted as a
result  from a read request. It is also a bug in GetOverlappedResult.
GetOverlappedResult must always check if the event is signaled. The
status value may contain the result from the previous request.

- Hartmut

[Gunnar Dalsnes]

> rpc_message calls ReadFile/WriteFile for pipes which are open for
> asynchronous requests. ReadFile/WriteFile can fail for an pending
> request. If it fails, the caller must check the last status
> (GetLastError()) for ERROR_IO_PENDING.

You are abusing the word "failed" here. ReadFile/WriteFile returning
FALSE and last error being ERROR_IO_PENDING just means the operation
is pending, not that anything failed:-D
> An other problem is the using of
> the overlapped structure. The same structure is used for read and write
> requests. Sometimes the results from a write request is interpreted as a
> result  from a read request. It is also a bug in GetOverlappedResult.
> GetOverlappedResult must always check if the event is signaled. The
> status value may contain the result from the previous request.

I impl/fixed GetOverlappedResult by black boxing behaviour agains win 
nt, and it should be 100% correct. Maybe someone is using it wrong or 
something else is broken?

Gunnar

[Filip Navara]

Hartmut Birr wrote:
> Filip Navara wrote:
> > > I think that is a bug in the rpcrt4 implementation. The receive and send
> > > functions do check for a pending io request in a wrong way.
> >
> > It's not impossible, but the code works just fine on Windows and
> > Wine... Can you point me to the code you think is wrong?
>
> rpc_message calls ReadFile/WriteFile for pipes which are open for
> asynchronous requests. ReadFile/WriteFile can fail for an pending
> request. If it fails, the caller must check the last status
> (GetLastError()) for ERROR_IO_PENDING.

The attached patch addresses this issue... (but it doesn't seem to help 
the test program)
> An other problem is the using of
> the overlapped structure. The same structure is used for read and write
> requests. Sometimes the results from a write request is interpreted as a
> result  from a read request.

All the read and write operatrions are de facto synchronous because 
they're always followed by GetOverlappedResult with Wait == TRUE, so 
this should never happen.
> It is also a bug in GetOverlappedResult.
> GetOverlappedResult must always check if the event is signaled. The
> status value may contain the result from the previous request.

The status value is initialized in the ReadFile / WriteFile calls, so 
again, this shouldn't be problem.

Another thing I'm afraid of are race conditions in your asynchronous 
read code in NPFS. I believe that you can get the reads out of order in 
certain conditions... Imagine this:

Process 1: Async. ReadFile -> No data available -> PENDING
Process 2: WriteFile -> Fills the internal buffers and sets the event
Process 1: Async. ReadFile <- Here the request can be satisfied before 
the worker thread realizes that there are new data and completes the 
PENDING request.

Does it make sense?

Regards,
Filip

[Hartmut Birr]

Filip Navara wrote:
> All the read and write operatrions are de facto synchronous because
> they're always followed by GetOverlappedResult with Wait == TRUE, so
> this should never happen.

Possible that is not correct. I see debug messages from read and write
request at the same time. I see also that the written length from write
request is shown as result for a read request. I've add a local
overlapped structure in RPCRT4_Send. This does fix this problem. The
test program shows now the correct result, but ros does crash at the
end. There is a bug in KeRundownThread. If a mutant or mutex is on the
threads mutant list, than ros does hang in a endless loop. If a mutant
(user mode mutex) is on the list, ros does crash because
'ASSERT(Mutant->ApcDisable)' does fail.
> > It is also a bug in GetOverlappedResult.
> > GetOverlappedResult must always check if the event is signaled. The
> > status value may contain the result from the previous request.
>
> The status value is initialized in the ReadFile / WriteFile calls, so
> again, this shouldn't be problem.

Your are right, the real problem is the using of the structure for twice.
> Another thing I'm afraid of are race conditions in your asynchronous
> read code in NPFS. I believe that you can get the reads out of order
> in certain conditions... Imagine this:
>
> Process 1: Async. ReadFile -> No data available -> PENDING
> Process 2: WriteFile -> Fills the internal buffers and sets the event
> Process 1: Async. ReadFile <- Here the request can be satisfied before
> the worker thread realizes that there are new data and completes the
> PENDING request.

Yes, that's correct. We must check if there exist already a waiter and
put the request on a list if any exist.

There is an other major bug in npfs. The fcbs have only one event. This
works perfect for non duplex pipe. In duplex mode the read and write
requests are using the same event.

- Hartmut

[Hartmut Birr]

Hartmut Birr wrote:
> Possible that is not correct. I see debug messages from read and write
> request at the same time. I see also that the written length from write
> request is shown as result for a read request. I've add a local
> overlapped structure in RPCRT4_Send. This does fix this problem.

Forgot to add the diff.

- Hartmut

Index: lib/rpcrt4/rpc_message.c
===================================================================
--- lib/rpcrt4/rpc_message.c	(revision 14297)
+++ lib/rpcrt4/rpc_message.c	(working copy)
@@ -44,6 +44,12 @@

WINE_DEFAULT_DEBUG_CHANNEL(ole);

+#undef WARN
+#define WARN DPRINT1
+
+#undef TRACE
+#define TRACE DPRINT1
+
 DWORD RPCRT4_GetHeaderSize(RpcPktHdr *Header)
 {
   static const DWORD header_sizes[] = {
@@ -247,7 +253,14 @@
 {
   PUCHAR buffer_pos;
   DWORD hdr_size, count;
+  OVERLAPPED ovl;
+  RPC_STATUS status;

+  memset(&ovl, 0, sizeof(OVERLAPPED));
+  ovl.hEvent = CreateEvent(NULL, TRUE, FALSE, NULL);
+  
+  TRACE("%x %x %x %d\n", Connection, Header, Buffer, BufferLength);
+
   buffer_pos = Buffer;
   /* The packet building functions save the packet header size, so we can use it. */
   hdr_size = Header->common.frag_len;
@@ -265,35 +278,45 @@
     }

/* transmit packet header */
-    if (!WriteFile(Connection->conn, Header, hdr_size, &count, &Connection->ovl)) {
+    if (!WriteFile(Connection->conn, Header, hdr_size, &count, &/*Connection->*/ovl) &&
+	ERROR_IO_PENDING != GetLastError()) {
       WARN("WriteFile failed with error %ld\n", GetLastError());
-      return GetLastError();
+      status = GetLastError();
+      goto done;
     }
-    if (!GetOverlappedResult(Connection->conn, &Connection->ovl, &count, TRUE)) {
+    if (!GetOverlappedResult(Connection->conn, &/*Connection->*/ovl, &count, TRUE)) {
       WARN("GetOverlappedResult failed with error %ld\n", GetLastError());
-      return GetLastError();
+      status = GetLastError();
+      goto done;
     }

/* fragment consisted of header only and is the last one */
     if (hdr_size == Header->common.frag_len &&
         Header->common.flags & RPC_FLG_LAST) {
-      return RPC_S_OK;
+      status =RPC_S_OK;
+      goto done;
     }

/* send the fragment data */
-    if (!WriteFile(Connection->conn, buffer_pos, Header->common.frag_len - hdr_size, &count, &Connection->ovl)) {
+    if (!WriteFile(Connection->conn, buffer_pos, Header->common.frag_len - hdr_size, &count, &/*Connection->*/ovl) &&
+	ERROR_IO_PENDING != GetLastError()) {
       WARN("WriteFile failed with error %ld\n", GetLastError());
-      return GetLastError();
+      status = GetLastError();
+      goto done;
     }
-    if (!GetOverlappedResult(Connection->conn, &Connection->ovl, &count, TRUE)) {
+    if (!GetOverlappedResult(Connection->conn, &/*Connection->*/ovl, &count, TRUE)) {
       WARN("GetOverlappedResult failed with error %ld\n", GetLastError());
-      return GetLastError();
+      status = GetLastError();
+      goto done;
     }

Header->common.flags &= ~RPC_FLG_FIRST;
   }

-  return RPC_S_OK;
+  status = RPC_S_OK;
+done:
+  CloseHandle(ovl.hEvent);
+  return status;
 }

/***********************************************************************
@@ -317,7 +340,8 @@
   TRACE("(%p, %p, %p)\n", Connection, Header, pMsg);

/* read packet common header */
-  if (!ReadFile(Connection->conn, &common_hdr, sizeof(common_hdr), &dwRead, &Connection->ovl)) {
+  if (!ReadFile(Connection->conn, &common_hdr, sizeof(common_hdr), &dwRead, &Connection->ovl) &&
+      ERROR_IO_PENDING != GetLastError()) {
     WARN("ReadFile failed with error %ld\n", GetLastError());
     status = RPC_S_PROTOCOL_ERROR;
     goto fail;
@@ -355,7 +379,8 @@

/* read the rest of packet header */
   if (!ReadFile(Connection->conn, &(*Header)->common + 1,
-                hdr_length - sizeof(common_hdr), &dwRead, &Connection->ovl)) {
+                hdr_length - sizeof(common_hdr), &dwRead, &Connection->ovl) &&
+      ERROR_IO_PENDING != GetLastError()) {
     WARN("ReadFile failed with error %ld\n", GetLastError());
     status = RPC_S_PROTOCOL_ERROR;
     goto fail;
@@ -405,7 +430,8 @@
     }

if (data_length == 0) dwRead = 0; else {
-      if (!ReadFile(Connection->conn, buffer_ptr, data_length, &dwRead, &Connection->ovl)) {
+      if (!ReadFile(Connection->conn, buffer_ptr, data_length, &dwRead, &Connection->ovl) &&
+	  ERROR_IO_PENDING != GetLastError()) {
         WARN("ReadFile failed with error %ld\n", GetLastError());
         status = RPC_S_PROTOCOL_ERROR;
         goto fail;
@@ -437,7 +463,8 @@
       TRACE("next header\n");

/* read the header of next packet */
-      if (!ReadFile(Connection->conn, *Header, hdr_length, &dwRead, &Connection->ovl)) {
+      if (!ReadFile(Connection->conn, *Header, hdr_length, &dwRead, &Connection->ovl) &&
+	  ERROR_IO_PENDING != GetLastError()) {
         WARN("ReadFile failed with error %ld\n", GetLastError());
         status = GetLastError();
         goto fail;