Why would DUN drop RTS and DTR immediately after connect?

In my USB modem driver, I’ve noticed that after my device reports the “CONNECT” string, I get IOCTL_SERIAL_CLR_RTS and IOCTL_SERIAL_CLR_DTR from dialup networking. This in turn hangs up my device and I get kicked off.

If I switch to usbser.sys and view everything with PortMon, I can see that DUN issues IOCTL_SERIAL_SET_RTS and IOCTL_SERIAL_SET_DTR in the same exact place.

What would be causing it to drop those signals? I’ve matched my response to IOCTL_SERIAL_GET_PROPERTIES to usbser’s so I’m assuming it’s not attempting some sort of handshaking.

The modem log looks like this:

03-30-2007 18:51:45.674 - Send: ATD*##***##
03-30-2007 18:51:45.704 - Recv: CONNECT
03-30-2007 18:51:45.704 - Interpreted response: Connect
03-30-2007 18:51:45.704 - Receive Connect but CD was low, Waiting for signal to go high
03-30-2007 18:51:45.724 - CD has been raised
03-30-2007 18:51:45.724 - Connection established at 12000000bps.
03-30-2007 18:51:45.724 - Error-control off or unknown.
03-30-2007 18:51:45.724 - Data compression off or unknown.
03-30-2007 18:51:45.775 - CD dropped–Remote modem hung up. ModemStatus=00000030

However the ModemStatus of 00000030 comes after the DTR/RTS clear. Initially I report 000000B0 (CTS + DSR + DCD), which is what usbser.sys is already reporting.

Here’s the backtrace when I get the DTR/RTS calls from DUN. It probably isn’t too helpful, but maybe.

I guess I’m asking if someone could “take a peek” inside the DUN code and figure out under what conditions I would get a lowered DTR and RTS after the CONNECT string is received?

kd> kb
ChildEBP RetAddr Args to Child
b4872a98 b45f6938 877d81c8 00000004 00000024 xxxmodem!XxxEvtClrDtr [y:\xxxmodem\ioctl.c @ 26]
b4872af8 b44ceba4 787c5ca8 786e0a28 00000000 xxxmodem!XxxEvtIoDeviceControl+0x7f8 [y:\xxxmodem\ioctl.c @ 431]
b4872b1c b44cff7c 787c5ca8 786e0a28 00000000 Wdf01000!FxIoQueueIoDeviceControl::Invoke+0x30
b4872b4c b44d2598 786e0a28 8791f5d0 8783a350 Wdf01000!FxIoQueue::DispatchRequestToDriver+0x445
b4872b68 b44d3d2c 8783a300 b44f9188 8783a350 Wdf01000!FxIoQueue::DispatchEvents+0x485
b4872b84 b44d4e67 00000000 8780b5d0 87841888 Wdf01000!FxIoQueue::QueueRequest+0x237
b4872ba8 b44c3d9a 87841888 b4872c00 8041dded Wdf01000!FxPkgIo::Dispatch+0x377
b4872bb4 8041dded 8780b5d0 87841888 87865250 Wdf01000!FxDevice::Dispatch+0x7f
b4872bc8 f6ad4a1e 878419d0 87841888 f6ad30a0 nt!IopfCallDriver+0x35
b4872bd4 f6ad30a0 87865250 87841888 87865250 Modem!UniCheckPassThrough+0x4e
b4872c00 8041dded 87865250 87841888 87841888 Modem!UniIoControl+0xf8
b4872c14 804ae9b6 878419d0 00000000 87841888 nt!IopfCallDriver+0x35
b4872c28 804af820 87865250 87841888 877cb808 nt!IopSynchronousServiceTail+0x60
b4872d00 804a73a8 00000854 00000240 00000000 nt!IopXxxControlFile+0x5e4
b4872d34 80465014 00000854 00000240 00000000 nt!NtDeviceIoControlFile+0x28
b4872d34 77f88403 00000854 00000240 00000000 nt!KiSystemService+0xc4
WARNING: Frame IP not in any known module. Following frames may be wrong.
00dff64c 7c59f348 00000854 00000006 00dff810 0x77f88403
00dff6b0 7567820b 00000854 00dff888 00dff934 0x7c59f348
00dff8b8 7572523e 000e4734 00000000 00dff8e0 0x7567820b
00dff8d8 75721755 000e4b18 0010afc8 00dff934 0x7572523e

So, I figured this out. After comparing responses to various communications functions, I noticed that GetCommState() was filling out part of my DCB with random garbage, even though the data I was copying into the output buffer in my KMDF IOCTL queue handler was clearly all zeroes.

Included in the garbage data was some erroneous values for XoffLim, fAbortOnError, and basically all of the event characters (XoffChar, etc.) Presumably, returning garbage here confuses dialup networking, and was causing it to issue CLR_DTR and CLR_RTS immediately after connect, probably in an attempt to do some sort of flow control (my theory).

So why was this garbage data showing up in the DCB struct? Well, apparently, GetCommState(), like its evil cousin mscomm32.ocx, doesn’t like IOCTL_GET_SERIAL_CHARS or IOCTL_GET_SERIAL_HANDFLOW to be pended and then completed later. I suspect it was seeing FALSE/997 here (ERROR_IO_PENDING) and then going off and doing unpredictable things.

So, I added a WDM IRP preprocess callback for these two IOCTLs and copied the real data right into SystemBuffer, completed them synchronously, and now it works just fine. I get SET_DTR and SET_RTS just like usbser.sys now in that same place.

I have to admit, though, that this is getting a little tedious – I wonder how many other applications are going to crap out in the future because KMDF pends every IRP it receives before placing them in a WDF queue, and the application is expecting a synchronous response even though the handle was opened overlapped.

Doron, I think a good feature to have would be, if a queue is currently empty and an IRP comes in, that the KMDF queue callback is operating in the context of the IRP callback itself. Then, by default, the driver has the same behavior as any WDM counterpart.

Chris, KMDF already processes requests in the caller’s context when it can. The problem is that we always mark the request as pending and returns STATUS_PENDING. I will look into what we can do, but this would be a major architectural change. I will also look into having a sample that demonstrates what to do using the current version of KMDF

d

Doron Holan wrote:

Chris, KMDF already processes requests in the caller’s context when
it can. The problem is that we always mark the request as pending
and returns STATUS_PENDING. I will look into what we can do, but
this would be a major architectural change. I will also look into having
a sample that demonstrates what to do using the current version
of KMDF.

Ok. What about the bug in GetCommState()? (That *is* a bug, right?)

I wrote:

Ok. What about the bug in GetCommState()? (That *is* a
bug, right?)

(The reason I ask is – I don’t see how you could develop a KMDF modem driver without encountering this problem, and KMDF is apparently required for a modem logo, so…)

Chris, I just looked at the source of GetCommState(). It correctly handles the pending case for all of the IOCTLs it sends; it will wait for the IOCTL to complete if pending is returned and processing the output buffer.

d

Doron Holan wrote:

Chris, I just looked at the source of GetCommState(). It correctly
handles the pending case for all of the IOCTLs it sends; it will wait
for the IOCTL to complete if pending is returned and processing the
output buffer.

Ok. That’s odd, then. Changing to preprocessing those two IOCTLs definitely cleared up my problem, so I assumed that was the cause. (You’re looking at the 2K or XP source, right?)

Let me ask you this. It seems like that function sends the get baud rate, get serial_handflow, and get serial_chars IOCTLs. Baud rate was working okay when pended, but handflow and chars were not. Is there any difference in the processing between those?

Or, is there any other reason why this could occur? I thought maybe it was a bug in modem.sys, but I set my device up as a serial port (and not a modem) and I still saw the issue.

Is GetCommState() return TRUE back to DUN? The API sends the following in this order:
IOCTL_SERIAL_GET_BAUD_RATE
IOCTL_SERIAL_GET_LINE_CONTROL
IOCTL_SERIAL_GET_CHARS
IOCTL_SERIAL_GET_HANDFLOW

Each IOCTL follows the same pattern of

localevent = CreateEvent(NULL, TRUE, FALSE, NULL);

if (SendIOCTL(…) == STATUS_PENDING) { WaitForSingleObject(localevent));

d

Doron Holan wrote:

Is GetCommState() return TRUE back to DUN? The API sends the following
in this order:

Doron, I checked, and GetCommState() returns TRUE and GetLastError() is 0 when the data from my driver is not (seemingly) copied into the DCB struct.

One other thing I did notice (which I suppose makes sense in a way, given what you’re saying about the implementation in GetCommState()) – it actually doesn’t matter if I open my handle overlapped, or not. Either way, the struct is still partially filled with garbage unless I handle the IRP itself.

I mean, this is what my code looks like inside the IOCTL queue handler, I don’t think there’s anything wrong with it, is there? The SERIAL_CHARS struct is part of my device extension and is zeroed out in AddDevice. If I dump the bytes from requestBuffer, I can see they are all zeroes when I call WdfRequestComplete():

============

PVOID requestBuffer;
size_t bufSize;

case IOCTL_SERIAL_GET_CHARS:

status = WdfRequestRetrieveOutputBuffer(
Request, sizeof(SERIAL_CHARS),
&requestBuffer, &bufSize));

if (!NT_SUCCESS(status)) break;

RtlCopyMemory(requestBuffer, &pDeviceExt->
SerialChars, sizeof(SERIAL_CHARS));

break;

============

IOCTL_SERIAL_GET_HANDFLOW is almost identical, only the sizeof() argument and the variable name in my device extension change.

-Chris

Are you setting Information to the number of bytes written when completing the request?

d

Doron Holan wrote:

Are you setting Information to the number of bytes written when
completing the request?

Shoot. No!! Aargh… Yes, that was it. (In my IRP handler, I’m setting Information. Thus my assumption about that being the cause…!)