CSocket::OnReceive called concurrently

Question

I have a strange problem.

void MySocket::OnReceive( int nErrorCode )
{
    static CMutex mutex;
    static int depth=0;
    static int counter=0;

    CSingleLock lock(&mutex, true);
    Receive(pBuff, iBuffSize-1); 
    counter++;
    depth++; //<-- Breakpoint
    log("Onreceive: enter %d %d %d", GetCurrentThreadId(), counter, depth);
    .....
    Code handling data
    depth--;
    log("Onreceive: exit  %d %d %d", GetCurrentThreadId(), counter, depth);
}

Results in this log statement:

02/19/2014 08:33:14:982 [DEBUG] Onreceive Enter: 3200 1 2
02/19/2014 08:34:13:726 [DEBUG] Onreceive Exit : 3200 2 1 
02/19/2014 08:32:34:193 [DEBUG] Onreceive Enter: 3200 0 1 <- Log statement was created but interrupted before it was written to disk
02/19/2014 08:34:13:736 [DEBUG] Onreceive Exit : 3200 2 0

Now what happens:

1. I start the program and the debugger stops at the breakpoint
2. Step through into the log
3. Some where in the log the debugger jumps back to the break point
4. This is the second entry into the OnReceive
5. Second call completes
6. First call continues

My questions:

1. How is it possible to get two concurrent calls to OnReceive
2. Why does the Mutex not work (Due to the same threadid?)
3. And how can I have two executing paths with the same ThreadID???
4. And ofcourse, how can I fix this??

Note that this only happens if I send a lot small messages (<50Bytes) until the Send blocks. In total it's around 500KB/s. If I put a Sleep(1) after each send it doesn't happen.. but that ofcourse kills my transfer speed.

Answer 1

Ok, I found the root cause. In the Log statement a Win32 Mutex is used and the following Wait:

DWORD dwResult = MsgWaitForMultipleObjects(nNoOfHandle, handle, FALSE, dwTimeout, QS_POSTMESSAGE|QS_ALLPOSTMESSAGE|QS_SENDMESSAGE|QS_TIMER);
if (dwResult == WAIT_OBJECT_0 + nNoOfHandle) // new message is in the queue, let's clear 
{
    MSG Msg;
    while (PeekMessage(&Msg, NULL, 0, 0, PM_REMOVE))
    {
        ::TranslateMessage(&Msg);
        ::DispatchMessage(&Msg);
    }
}

This waits for the Mutex to be cleared OR for a message to be posted. CSocket posts messages to the thread when it receives data and that will call the OnReceive. So, this code produced the problem that while waiting for the mutex it would handle incoming messages and effectively call the OnReceive again.

One way of solving this was to prevent the CSocket from posting more notifications like this:

void MySocket::OnReceive(int nErrorCode)
{
    /* Remove FD_READ notifications */
    VERIFY(AsyncSelect(FD_WRITE | FD_OOB | FD_ACCEPT | FD_CONNECT | FD_CLOSE));

    OldOnReceive(nErrorCode);

    /* Restore default notifications */
    VERIFY(AsyncSelect());
}