Content
i.The problem troubled me for nearly two weeks
ii.The thing behind our back
iii.The SIN of the threads in LSP
iv.Append
i.The problem troubled me for nearly two weeks
----------------------------------------------
?After install the lsp(whether the layered sample or LSP sample in PSDK), you
?will got WriteErrorMessage randomly if you print a document through Standard
?TCP/IP port using LPR protocol.
?Note that for the layered sample it appeared only when you install the Release
?version dll but not Debug version one. And if you attach a debugger(e.g.
?WinDbg, and also Softice) to the spoolsv.exe, this problem run somewhere you
?can't find him.
ii.The thing behind our back
----------------------------
?This section i assume that you are familar with Winsock and overlapped IO and
?also threads.
?From the debug log i printed to DbgView when error message box appeared &
?Trace in and out spoolsv with WinDbg, i just found a strange behaviour of the
?spooler.
?After we start a print job, the spooler running as the following process:
?// **************** Pseudcode begin ******************************************
?// Assume we print DebugSpoolsv.txt with content "Spoolsv.bug"
?
?// Spoolsv will create a thread named PortThread to do this job,
?// actually the code was in tcpmon.dll
?
?// The PortThread
?WSAOVERLAPPED ol;
?
?ol.hEvent = CreateEvent;
?
?// The following 4 send operation was a trascation of LPR protocol
?// Each one is overlapped, and NOTE that
?// ** 4 send operations use only ONE overlapped struct and were sent quickly
?// one after another if it THINK that the send completed **
?ResetEvent(ol.hEvent);
?WSASend(10 bytes, &ol); // In fact this is the start job command in LPR
?select // !!!Here please think it over
牋牋牋牋 // what's wrong after install the MS lsp sample
牋牋牋牋 // Tips: After install the MS lsp sample, it create another thread to
牋牋牋牋 //牋 process overlapped IO, so now we have TWO threads and the BAD
牋牋牋牋 // news is we got a Race Condition here!!!
?WSARecv
?
?ResetEvent(ol.hEvent);
?WSASend(26 bytes, &ol); // Control file command in LPR
?select
?WSARecv
?
?ResetEvent(ol.hEvent);
?WSASend(124 bytes, &ol); // Control file content
?select
?WSARecv
?
?ResetEvent(ol.hEvent);
?WSASend(38 bytes, &ol); // Data file command in LPR
?select
?WSARecv
?
?// After pending all 4 data block
?// spooler will expect the event comes into signaled to learn that
?// * The final 38 bytes overlapped sending?completed *
?WaitForSingleObject(ol.hEvent) // with timeout 5s
?
?// Then spooler check the bytecount of last overlapped operation
?WSAGetOverlappedResult(&ol, &cbTransfer);
?if (cbTransfer != 38) ERROR;
?
?// **************** Pseudcode end ********************************************
?
?I will only tell you after install the lsp, cbTransfer got from
?WSAGetOverlapped will randomly be 124, so bingo, we got a error messagebox.
?
?If you learn the processing of lsp, you will know why -_-
?
iii.The SIN of the threads in LSP
---------------------------------
?So because the spoolsv use TWO mechanism for send and recv, we have also TWO
?threads to do these jobs.
?
?How to sovle it? The key issue here is how to sync the threads when the
?winsock client do these foo things?
?
?It is said that MS guys are writting a new version sample for lsp, are they
?trying to fix it?
?
iv.Append-Debugoutput of LPR after install the lsp
--------------------------------------------------
OutputGrammar:
?num) - num is thread id
燱SPSend addrol{ol.hevent, ol.internal, ol.internalhigh} bytesOfsend
? addrol is address of OVERLAPPED struct ol
? hevent is ol.hEvent
? internal is ol.Internal
? internalhigh is ol.InternalHigh
燱SPUCompleteOverlappedRequest addrol[ol.hevent,ol.internal,ol.internalhigh
?>ol.hevent,ol.internal,ol.internalhigh]
燱SPGetOverlappedResult addrol{ol.hevent,ol.internalhigh}
****************** LOG for OK begin ********************************************
(464)WSPSend 0x00287534{0x00000230,0x00000103,0} 10?BR>(464)WSPSelect: Could read here?BR>(1488)WPUCompleteOverlappedRequest 0x00287534[0x00000230,0x00000103,0?BR>->0x00000230,0x00000000,10]?BR>(464)WSPRecv: OK?BR>(464)WSPSend 0x00287534{0x00000230,0x00000103,0} 26?BR>(464)WSPSelect: Could read here?BR>(464)WSPRecv: OK?BR>(464)WSPSend 0x00287534{0x00000230,0x00000103,0} 124?BR>(1488)WPUCompleteOverlappedRequest 0x00287534[0x00000230,0x00000103,0?BR>(464)WSPSelect: Could read here?BR>->0x00000230,0x00000000,26]?BR>(464)WSPRecv: OK?BR>(464)WSPSend 0x00287534{0x00000230,0x00000103,0} 38?BR>(1488)WPUCompleteOverlappedRequest 0x00287534[0x00000230,0x00000103,0?BR>(464)WSPSelect: Could read here?BR>->0x00000230,0x00000000,124]?BR>(464)WSPRecv: OK?BR>(1488)WPUCompleteOverlappedRequest 0x00287534[0x00000230,0x00000000,124?BR>->0x00000230,0x00000000,38]?BR>(464)WSPGetOverlappedResult 0x00287534{0x00000230,38}?BR>(464)WSPSend 0x00287534{0x00000230,0x00000103,0} 2710?BR>(1488)WPUCompleteOverlappedRequest 0x00287534[0x00000230,0x00000103,0?BR>(464)WSPGetOverlappedResult 0x00287534{0x00000230,2710}?BR>(464)WSPSelect: Could read here?BR>->0x00000230,0x00000000,2710]?BR>(464)WSPRecv: OK?BR>****************** LOG for OK end **********************************************