[Bug 25083] HyperTerminal 6.3 is unable to receive characters with serial port loop back setup

wine-bugs at winehq.org wine-bugs at winehq.org
Sat Dec 13 17:27:45 CST 2014


https://bugs.winehq.org/show_bug.cgi?id=25083

Anastasius Focht <focht at gmx.net> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |focht at gmx.net
          Component|-unknown                    |ntdll
            Summary|HyperTerminal unable to     |HyperTerminal 6.3 is unable
                   |loop back on COM1 (RS-232)  |to receive characters with
                   |                            |serial port loop back setup

--- Comment #18 from Anastasius Focht <focht at gmx.net> ---
Hello folks,

confirming.

--- snip ---
$ pwd
/home/focht/.wine/drive_c/Program Files/Windows NT/HyperTerminal

$ WINEDEBUG=+tid,+seh,+relay,+tapi,+comm wine ./HyperTrm.exe >>log.txt 2>&1
...
0023:Call KERNEL32.CreateFileA(0033f3a4
"\\\\.\\com1",c0000000,00000000,00000000,00000003,40000000,00000000)
ret=10038503
0023:Ret  KERNEL32.CreateFileA() retval=000000cc ret=10038503
0023:Call KERNEL32.SetupComm(000000cc,00002000,00002000) ret=10038589
0023:trace:comm:io_control 0xcc IOCTL_SERIAL_SET_QUEUE_SIZE 0x33f328 8 (nil) 0
0x33f2b0
0023:fixme:comm:set_queue_size insize 8192 outsize 8192 unimplemented stub
0023:Ret  KERNEL32.SetupComm() retval=00000001 ret=10038589
0023:Call KERNEL32.GetCommConfig(000000cc,0033f324,0033f380) ret=10038734
...
0023:trace:comm:GetCommState OK
0023:trace:comm:dump_dcb bytesize=8 baudrate=115200 fParity=0 Parity=0
stopbits=1
0023:trace:comm:dump_dcb ~IXON ~IXOFF
0023:trace:comm:dump_dcb fOutxCtsFlow=0 fRtsControl=1
0023:trace:comm:dump_dcb fOutxDsrFlow=0 fDtrControl=1
0023:trace:comm:dump_dcb ~CRTSCTS
0023:Ret  KERNEL32.GetCommConfig() retval=00000001 ret=10038734
0023:Call KERNEL32.SetCommConfig(000000cc,0033f324,00000034) ret=1003878a
0023:trace:comm:SetCommConfig (0xcc, 0x33f324, 52)
0023:trace:comm:dump_dcb bytesize=8 baudrate=115200 fParity=1 Parity=0
stopbits=1
0023:trace:comm:dump_dcb ~IXON ~IXOFF
0023:trace:comm:dump_dcb fOutxCtsFlow=0 fRtsControl=1
0023:trace:comm:dump_dcb fOutxDsrFlow=0 fDtrControl=1
0023:trace:comm:dump_dcb ~CRTSCTS
...
0023:Ret  KERNEL32.SetCommConfig() retval=00000001 ret=1003878a
0023:Call KERNEL32.SetCommTimeouts(000000cc,0033f36c) ret=100387d4
0023:trace:comm:SetCommTimeouts (0xcc, 0x33f36c)
0023:trace:comm:io_control 0xcc IOCTL_SERIAL_SET_TIMEOUTS 0x33f290 20 (nil) 0
0x33f210
0023:Ret  KERNEL32.SetCommTimeouts() retval=00000001 ret=100387d4
0023:Call KERNEL32.GetCommTimeouts(000000cc,0033f358) ret=100387ed
0023:trace:comm:GetCommTimeouts (0xcc, 0x33f358)
0023:trace:comm:io_control 0xcc IOCTL_SERIAL_GET_TIMEOUTS (nil) 0 0x33f290 20
0x33f210
0023:Ret  KERNEL32.GetCommTimeouts() retval=00000001 ret=100387ed
0023:Call KERNEL32.SetCommMask(000000cc,000000a0) ret=100385d7
0023:trace:comm:SetCommMask handle 0xcc, mask a0
0023:trace:comm:io_control 0xcc IOCTL_SERIAL_SET_WAIT_MASK 0x33f364 4 (nil) 0
0x33f2b0
0023:Ret  KERNEL32.SetCommMask() retval=00000001 ret=100385d7
0023:Call
KERNEL32.CreateThread(00000000,000007d0,10038cd1,0042fdc8,00000000,0033f4a8)
ret=10038619
0023:Ret  KERNEL32.CreateThread() retval=000000d0 ret=10038619
0023:Call KERNEL32.SetThreadPriority(000000d0,00000001) ret=1003862b 
...
0026:Starting thread proc 0x10038cd1 (arg=0x42fdc8) 
...
0026:Call KERNEL32.SetEvent(000000a0) ret=10038d07
0026:Ret  KERNEL32.SetEvent() retval=00000001 ret=10038d07 
...
0026:Call KERNEL32.SetEvent(0000009c) ret=10038d0f
0026:Ret  KERNEL32.SetEvent() retval=00000001 ret=10038d0f 
...
0026:Call KERNEL32.ResetEvent(000000a4) ret=10038d1b
0026:Ret  KERNEL32.ResetEvent() retval=00000001 ret=10038d1b
...
0026:Call KERNEL32.WaitForMultipleObjects(00000003,0042fecc,00000000,ffffffff)
ret=10038d36
0026:Ret  KERNEL32.WaitForMultipleObjects() retval=00000000 ret=10038d36
...
0026:Call KERNEL32.WaitCommEvent(000000cc,00a3ea24,00a3ea48) ret=10038ffa 
...
0026:trace:comm:io_control 0xcc IOCTL_SERIAL_WAIT_ON_MASK (nil) 0 0xa3ea24 4
0xa3ea48 
...
0026:trace:comm:get_irq_info TIOCGICOUNT err Inappropriate ioctl for device
0026:trace:comm:get_irq_info TIOCSERGETLSR err Inappropriate ioctl for device
0026:trace:comm:get_modem_status 0166 -> MS_RLSD_ON MS_DSR_ON  MS_CTS_ON  
0026:trace:comm:check_events mask 0x000000a0
0026:trace:comm:check_events old->rx          0x00000000 vs. new->rx         
0x00000000
0026:trace:comm:check_events old->tx          0x00000000 vs. new->tx         
0x00000000
0026:trace:comm:check_events old->frame       0x00000000 vs. new->frame      
0x00000000
0026:trace:comm:check_events old->overrun     0x00000000 vs. new->overrun    
0x00000000
0026:trace:comm:check_events old->parity      0x00000000 vs. new->parity     
0x00000000
0026:trace:comm:check_events old->brk         0x00000000 vs. new->brk        
0x00000000
0026:trace:comm:check_events old->buf_overrun 0x00000000 vs. new->buf_overrun
0x00000000
0026:trace:comm:check_events old->temt        0x00000001 vs. new->temt       
0x00000001 
...
0026:Ret  KERNEL32.WaitCommEvent() retval=00000000 ret=10038ffa
0026:Call KERNEL32.GetLastError() ret=10039015
0026:Ret  KERNEL32.GetLastError() retval=000003e5 ret=10039015
...
0026:Call KERNEL32.WaitForMultipleObjects(00000003,0042fecc,00000000,ffffffff)
ret=10038d36 
...
0027:Starting thread proc 0x7bc8f895 (arg=(nil))
0027:trace:comm:wait_for_event device=0xcc fd=0x0000000f mask=0x000000a0
buffer=0xa3ea24 event=0x9c irq_info=0x14f628
...
0027:trace:comm:get_irq_info TIOCGICOUNT err Inappropriate ioctl for device
0027:trace:comm:get_irq_info TIOCSERGETLSR err Inappropriate ioctl for device
0027:trace:comm:get_modem_status 0166 -> MS_RLSD_ON MS_DSR_ON  MS_CTS_ON  
0027:trace:comm:check_events mask 0x000000a0
0027:trace:comm:check_events old->rx          0x00000000 vs. new->rx         
0x00000000
0027:trace:comm:check_events old->tx          0x00000000 vs. new->tx         
0x00000000
0027:trace:comm:check_events old->frame       0x00000000 vs. new->frame      
0x00000000
0027:trace:comm:check_events old->overrun     0x00000000 vs. new->overrun    
0x00000000
0027:trace:comm:check_events old->parity      0x00000000 vs. new->parity     
0x00000000
0027:trace:comm:check_events old->brk         0x00000000 vs. new->brk        
0x00000000
0027:trace:comm:check_events old->buf_overrun 0x00000000 vs. new->buf_overrun
0x00000000
0027:trace:comm:check_events old->temt        0x00000001 vs. new->temt       
0x00000001 
...
0026:Ret  KERNEL32.WaitForMultipleObjects() retval=00000001 ret=10038d36 
...
0026:Call KERNEL32.ReadFile(000000cc,00432be8,00000050,00a3ea18,00a3ea34)
ret=10038f1c
...
0026:trace:comm:io_control 0xcc IOCTL_SERIAL_GET_TIMEOUTS (nil) 0 0xa3e788 20
0xa3e780
...
0026:Ret  KERNEL32.ReadFile() retval=00000000 ret=10038f1c 
0026:Call KERNEL32.GetLastError() ret=10038f53
...
0026:Ret  KERNEL32.GetLastError() retval=000003e5 ret=10038f53
...
0026:Call KERNEL32.WaitForMultipleObjects(00000003,0042fecc,00000000,ffffffff)
ret=10038d36
...
--- snip ---

There are 3 events being waited on:

WAIT_OBJECT_0+0 = modem status event 
WAIT_OBJECT_0+1 = read event (overlapped i/o)
WAIT_OBJECT_0+2 = write event (overlapped i/o)

The app signals the first two events on its own to initiate I/O operations
(WaitCommEvent and ReadFile).

WaitCommEvent results in a modem status APC being queued and executed
continuously on thread 0027 which is *not* the initiating thread.

ReadFile causes an async read operation registered at server for APC_ASYNC_IO
completion.

The write use-case (3rd event) works: 'WriteFile' issued from thread 0025, the
completion is fulfilled on thread 0026.

--- snip ---
0025:Call KERNEL32.WriteFile(000000cc,004331d0,00000001,0093e938,0042fe38)
ret=10038b67 
...
0026:Ret  KERNEL32.WaitForMultipleObjects() retval=00000002 ret=10038d36 
...
0025:Ret  KERNEL32.WriteFile() retval=00000001 ret=10038b67 
...
0025:Call KERNEL32.SetEvent(00000098) ret=100045b3
...
0026:Call KERNEL32.GetOverlappedResult(000000cc,0042fe38,00a3ea20,00000000)
ret=10038d7c 
...
0026:Ret  KERNEL32.GetOverlappedResult() retval=00000001 ret=10038d7c
0026:Call KERNEL32.SetEvent(00000098) ret=100045b3 
...
0026:Ret  KERNEL32.SetEvent() retval=00000001 ret=100045b3 
...
0026:Call KERNEL32.ResetEvent(000000a4) ret=10038e23
0026:Ret  KERNEL32.ResetEvent() retval=00000001 ret=10038e23
0026:Call KERNEL32.WaitForMultipleObjects(00000003,0042fecc,00000000,ffffffff)
ret=10038d36 
...
0026:Ret  KERNEL32.WaitForMultipleObjects() retval=00000002 ret=10038d36 
...
--- snip ---

The read use-case from another run, with additional server/ntdll debug channel
and custom trace added.

Debugging APCs on the client side is kind of hit-and-miss.
Adding custom debug traces is the best option here to avoid crashes and/or
nested exceptions during debugging of APC invocation.

--- snip ---
...
0026: register_async( type=1,
async={handle=00cc,event=00a0,callback=7bc45206,iosb=00a3ea34,arg=00158490,cvalue=00a3ea34},
count=80 )
0026: register_async() = PENDING
0026:trace:ntdll:NtReadFile = 0x00000103
0026:Ret  KERNEL32.ReadFile() retval=00000000 ret=10038f1c
0026:Call KERNEL32.GetLastError() ret=10038f53
0026:Ret  KERNEL32.GetLastError() retval=000003e5 ret=10038f53
0026:Call KERNEL32.WaitForMultipleObjects(00000003,0042fecc,00000000,ffffffff)
ret=10038d36
0026: select( flags=2, cookie=00a3e69c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={009c,00a0,00a4}} )
0026: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 
...
<keypress in Minicom on other serial port, loopback>
...
0026: *wakeup* signaled=192 
...
0026: select( flags=2, cookie=00a3e69c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={009c,00a0,00a4}} )
0026: select() = USER_APC { timeout=infinite,
call={APC_ASYNC_IO,func=7bc45206,user=00158490,sb=00a3ea34,status=ALERTED},
apc_handle=00d4 }
...
0026:trace:ntdll:FILE_AsyncReadService read=1, fileio->already=1,
fileio->count=80
0026:trace:ntdll:FILE_AsyncReadService status=0x103
...
0026: select( flags=2, cookie=00a3e69c, timeout=infinite, prev_apc=00d4,
result={APC_ASYNC_IO,status=PENDING,total=0,apc=00000000},
data={WAIT,handles={009c,00a0,00a4}} )
0026: select() = PENDING { timeout=infinite, call={APC_NONE}, apc_handle=0000 } 
...
<blocks until next keypress>
...
0026: *wakeup* signaled=192
0026:trace:server:server_select ret2=0xc0
0026: select( flags=2, cookie=00a3e68c, timeout=infinite, prev_apc=0000,
result={}, data={WAIT,handles={009c,00a0,00a4}} )
0026: select() = USER_APC { timeout=infinite,
call={APC_ASYNC_IO,func=7bc45206,user=001578b0,sb=00a3ea34,status=ALERTED},
apc_handle=00d4 }
--- snip ---

The data from serial port is read through the client side invoked user APC (see
added 'FILE_AsyncReadService' trace).

The second 'select' call, which is needed to determine the signalled wait
object/event for exiting 'NtWaitForMultipleObjects' doesn't work here.
It blocks in 'wait_select_reply' -> 'read', only to be unblocked by another
APC_ASYNC_IO, triggered by next keypress.

Source:
http://source.winehq.org/git/wine.git/blob/8d817997cea784bcf784759e1d3aa93c571c500e:/dlls/ntdll/server.c#l570

$ sha1sum htpe63.exe 
091514cf4c177d8700ce2cbae1fd80bda0ece7d8  htpe63.exe

$ du -sh htpe63.exe 
1.3M    htpe63.exe

$ wine --version
wine-1.7.33

Regards

-- 
Do not reply to this email, post in Bugzilla using the
above URL to reply.
You are receiving this mail because:
You are watching all bug changes.



More information about the wine-bugs mailing list