Hi,
The changes to the async/overlapped IO in the last week have caused a problem in Girotel 2.1, Dutch online banking program. After successfully calling the bank's computer:
| 0806cfe8:Call kernel32.ClearCommError(000000e8,405953a8,405953b0) ret=60052d0f | trace:comm:ClearCommError handle 232 cbInQue = 8 cbOutQue = 0 | 0806cfe8:Ret kernel32.ClearCommError() retval=00000001 ret=60052d0f
8 characters in the in-queue.
| 0806cfe8:Call kernel32.ReadFile(000000e8,405953f0,00000008,405953a4,409032e4) ret=60052d44 | trace:file:ReadFile 232 0x405953f0 8 0x405953a4 0x409032e4
request read of 8 characters.
| trace:file:FILE_ReadFileEx file 232 to buf 0x405953f0 num 8 0x409032e4 func (nil) | trace:file:GetOverlappedResult (232 0x409032e4 0x405953a4 0) | trace:file:GetOverlappedResult waiting on 0x409032e4 | trace:file:GetOverlappedResult wait on 0x409032e4 returned 258 | 0806cfe8:Ret kernel32.ReadFile() retval=00000000 ret=60052d44 | 0806cfe8:Call kernel32.GetLastError() ret=60052d52 | 0806cfe8:Ret kernel32.GetLastError() retval=000003e5 ret=60052d52
ReadFile() returns ERROR, with gle() set to ERROR_IO_PENDING
| 0806cfe8:Call kernel32.lstrlenA(40595270 "Problemen bij aansturen van modem\n(121-997)") ret=6c37396c
Start preparing the error message ("problems communicating with modem, check your settings") for the alerting dialogbox. While clicking away this dialogbox, and the 20 subsequent ones the communications proceeds successfully.
Any suggestions?
Rein.
On Thu, 25 Apr 2002, Rein Klazes wrote:
ReadFile() returns ERROR, with gle() set to ERROR_IO_PENDING
Well the overlapped request is still pending. Since the data is there, this can only be caused by the APC not being scheduled.
Please send me a tarce with trace+comm,trace+file,trace+server.
Martin
On Thu, 25 Apr 2002 13:23:01 +0200 (CEST), you wrote:
On Thu, 25 Apr 2002, Rein Klazes wrote:
ReadFile() returns ERROR, with gle() set to ERROR_IO_PENDING
Well the overlapped request is still pending. Since the data is there, this can only be caused by the APC not being scheduled.
Please send me a tarce with trace+comm,trace+file,trace+server.
Here is the same +comm,+file now with added +server:
| 0806cfe8:Call kernel32.ClearCommError(000000e8,405953a8,405953b0) ret=60052d0f | 0806cfe8: get_handle_fd( handle=232, access=80000000 ) | 0806cfe8: get_handle_fd() = 0 { fd=18, type=1, flags=1 } | trace:comm:ClearCommError handle 232 cbInQue = 8 cbOutQue = 0 | 0806cfe8: get_serial_info( handle=232 ) | 0806cfe8: get_serial_info() = 0 { readinterval=ffffffff, readconst=00000000, readmult=00000000, writeconst=00000000, writemult=00000000, eventmask=0000003d, commerror=00000000 } | 0806cfe8: set_serial_info( handle=232, flags=4, readinterval=00000000, readconst=00000000, readmult=00000000, writeconst=0000003d, writemult=00000000, eventmask=00000000, commerror=00000000 ) | 0806cfe8: set_serial_info() = 0 | 0806cfe8:Ret kernel32.ClearCommError() retval=00000001 ret=60052d0f | 0806cfe8:Call kernel32.ReadFile(000000e8,405953f0,00000008,405953a4,409032e4) ret=60052d44 | trace:file:ReadFile 232 0x405953f0 8 0x405953a4 0x409032e4 | 0806cfe8: get_handle_fd( handle=232, access=80000000 ) | 0806cfe8: get_handle_fd() = 0 { fd=18, type=1, flags=1 } | 0806cfe8: event_op( handle=236, op=2 ) | 0806cfe8: event_op() = 0 | trace:file:FILE_ReadFileEx file 232 to buf 0x405953f0 num 8 0x409032e4 func (nil) | 0806cfe8: get_handle_fd( handle=232, access=80000000 ) | 0806cfe8: get_handle_fd() = 0 { fd=18, type=1, flags=1 } | 0806cfe8: register_async( handle=232, type=1, overlapped=0x41d615b0, count=8, status=00000103 ) | 0806cfe8: register_async() = 0 | trace:file:GetOverlappedResult (232 0x409032e4 0x405953a4 0) | trace:file:GetOverlappedResult waiting on 0x409032e4 | 0806cfe8: select( flags=14, cookie=0x405951bc, sec=1019746522, usec=250830, handles={236} ) | 0806cfe8: select() = TIMEOUT | trace:file:GetOverlappedResult wait on 0x409032e4 returned 258 | 0806cfe8:Ret kernel32.ReadFile() retval=00000000 ret=60052d44 | 0806cfe8:Call kernel32.GetLastError() ret=60052d52 | 0806cfe8:Ret kernel32.GetLastError() retval=000003e5 ret=60052d52 | 0806cfe8:Call kernel32.lstrlenA(40595270 "Problemen bij aansturen van modem\n(121-997)") ret=6c37396c | 0806cfe8:Ret kernel32.lstrlenA() retval=0000002b ret=6c37396c
I put the more complete cut of the log, beginning at the "CreateFileA COM1" at http://home.wanadoo.nl/~wijn/girotel/gt.log.bz2
Rein.
On Thu, 25 Apr 2002, Rein Klazes wrote:
Here is the same +comm,+file now with added +server:
| trace:file:FILE_ReadFileEx file 232 to buf 0x405953f0 num 8 0x409032e4 func (nil) | 0806cfe8: get_handle_fd( handle=232, access=80000000 ) | 0806cfe8: get_handle_fd() = 0 { fd=18, type=1, flags=1 } | 0806cfe8: register_async( handle=232, type=1, overlapped=0x41d615b0, count=8, status=00000103 ) | 0806cfe8: register_async() = 0
=> async request successfully registered
| trace:file:GetOverlappedResult (232 0x409032e4 0x405953a4 0) | trace:file:GetOverlappedResult waiting on 0x409032e4 | 0806cfe8: select( flags=14, cookie=0x405951bc, sec=1019746522, usec=250830, handles={236} ) | 0806cfe8: select() = TIMEOUT
=> async has not been served yet - TIMEOUT. The reason is that the file descriptot for serial port had not been polled in the meantime.
OK, I know what to do about that. When register_async is called with a new request, we must immediately look for pending events, as we do with sockets.
Thanks for spotting this, expect a patch soon.
Martin
-
Martin Wilck -
Rein Klazes