diff --git a/netwerk/base/src/nsSocketTransport.cpp b/netwerk/base/src/nsSocketTransport.cpp index cd366fad0548..9dc03c4d362f 100644 --- a/netwerk/base/src/nsSocketTransport.cpp +++ b/netwerk/base/src/nsSocketTransport.cpp @@ -96,6 +96,22 @@ static PRIntervalTime gConnectTimeout = -1; static char gIOBuffer[MAX_IO_BUFFER_SIZE]; +#if defined(PR_LOGGING) +// +// Log module for SocketTransport logging... +// +// To enable logging (see prlog.h for full details): +// +// set NSPR_LOG_MODULES=nsSocketTransport:5 +// set NSPR_LOG_FILE=nspr.log +// +// this enables PR_LOG_DEBUG level information and places all output in +// the file nspr.log +// +static PRLogModuleInfo* gSocketLog = nsnull; + +#endif /* PR_LOGGING */ + static NS_DEFINE_IID(kISupportsIID, NS_ISUPPORTS_IID); @@ -140,11 +156,28 @@ nsSocketTransport::nsSocketTransport() gConnectTimeout = PR_MillisecondsToInterval(CONNECT_TIMEOUT_IN_MS); gTimeoutIsInitialized = 1; } + +#if defined(PR_LOGGING) + // + // Initialize the global PRLogModule for socket transport logging + // if necessary... + // + if (nsnull == gSocketLog) { + gSocketLog = PR_NewLogModule("nsSocketTransport"); + } +#endif /* PR_LOGGING */ + + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Creating nsSocketTransport [this=%x].\n", this)); + } nsSocketTransport::~nsSocketTransport() { + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Deleting nsSocketTransport [this=%x].\n", this)); + NS_IF_RELEASE(mReadListener); NS_IF_RELEASE(mReadStream); NS_IF_RELEASE(mReadContext); @@ -202,6 +235,12 @@ nsresult nsSocketTransport::Init(nsSocketTransportService* aService, } } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Initializing nsSocketTransport [this=%x]. rv = %x. \t" + "aHost = %s.\t" + "aPort = %d.\n", + this, rv, aHost, aPort)); + return rv; } @@ -217,11 +256,20 @@ nsresult nsSocketTransport::Process(PRInt16 aSelectFlags) // Lock(); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::Process() [this=%x].\t" + "aSelectFlags = %x.\t" + "CurrentState = %d\n", + this, aSelectFlags, mCurrentState)); + // // If the transport has been suspended, then return NS_OK immediately... // This removes the transport from the select list... // if (mSuspendCount) { + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Transport [this=%x] is suspended.\n", this)); + done = PR_TRUE; rv = NS_OK; } @@ -336,6 +384,11 @@ nsresult nsSocketTransport::Process(PRInt16 aSelectFlags) aSelectFlags = 0; } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::Process() [this=%x]. rv = %x.\t" + "CurrentState = %d\n\n", + this, rv, mCurrentState)); + // Leave the socket transport lock... Unlock(); @@ -362,6 +415,11 @@ nsresult nsSocketTransport::doResolveHost(void) nsresult rv = NS_OK; NS_ASSERTION(eSocketState_WaitDNS == mCurrentState, "Wrong state."); + + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::doResolveHost() [this=%x].\n", + this)); + // // Initialize the port used for the connection... // @@ -385,12 +443,23 @@ nsresult nsSocketTransport::doResolveHost(void) // XXX: What should happen here? The GetHostByName(...) succeeded but // there are *no* A records... } + + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Host name resolved [this=%x]. Name is %s\n", this, mHostName)); } // DNS lookup failed... else { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("Host name resolution FAILURE [this=%x].\n", this)); + rv = NS_ERROR_FAILURE; } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::doResolveHost() [this=%x].\t" + "rv = %x.\n\n", + this, rv)); + return rv; } @@ -416,6 +485,12 @@ nsresult nsSocketTransport::doConnection(PRInt16 aSelectFlags) nsresult rv = NS_OK; NS_ASSERTION(eSocketState_WaitConnect == mCurrentState, "Wrong state."); + + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::doConnection() [this=%x].\t" + "aSelectFlags = %x.\n", + this, aSelectFlags)); + // // Step 1: // Create a new TCP socket structure (if necessary)... @@ -451,6 +526,8 @@ nsresult nsSocketTransport::doConnection(PRInt16 aSelectFlags) // Initiate the connect() to the host... // // This is only done the first time doConnection(...) is called. + // If aSelectFlags == 0 then this is the first time... Otherwise, + // PR_Poll(...) would have set the flags non-zero. // if (NS_SUCCEEDED(rv) && (0 == aSelectFlags)) { status = PR_Connect(mSocketFD, &mNetAddress, gConnectTimeout); @@ -479,6 +556,10 @@ nsresult nsSocketTransport::doConnection(PRInt16 aSelectFlags) // else { // Connection refused... + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("Connection Refused [this=%x]. PRErrorCode = %x\n", + this, code)); + rv = NS_ERROR_CONNECTION_REFUSED; } } @@ -489,6 +570,9 @@ nsresult nsSocketTransport::doConnection(PRInt16 aSelectFlags) // else if (NS_SUCCEEDED(rv) && aSelectFlags) { if (PR_POLL_EXCEPT & aSelectFlags) { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("Connection Refused via PR_POLL_EXCEPT. [this=%x].\n", this)); + rv = NS_ERROR_CONNECTION_REFUSED; } // @@ -502,6 +586,11 @@ nsresult nsSocketTransport::doConnection(PRInt16 aSelectFlags) } } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::doConnection() [this=%x].\t" + "rv = %x.\n\n", + this, rv)); + return rv; } @@ -529,10 +618,18 @@ nsresult nsSocketTransport::doRead(PRInt16 aSelectFlags) NS_ASSERTION(eSocketState_WaitReadWrite == mCurrentState, "Wrong state."); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::doRead() [this=%x].\t" + "aSelectFlags = %x.\n", + this, aSelectFlags)); + // // Check for an error during PR_Poll(...) // if (PR_POLL_EXCEPT & aSelectFlags) { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("PR_Read() failed via PR_POLL_EXCEPT. [this=%x].\n", this)); + // XXX: What should this error code be? rv = NS_ERROR_FAILURE; } @@ -574,6 +671,10 @@ nsresult nsSocketTransport::doRead(PRInt16 aSelectFlags) rv = NS_BASE_STREAM_WOULD_BLOCK; } else { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("PR_Read() failed. [this=%x]. PRErrorCode = %x\n", + this, code)); + // XXX: What should this error code be? rv = NS_ERROR_FAILURE; } @@ -608,6 +709,11 @@ nsresult nsSocketTransport::doRead(PRInt16 aSelectFlags) mSelectFlags |= (PR_POLL_READ | PR_POLL_EXCEPT); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::doRead() [this=%x]. rv = %x.\t" + "Total bytes read: %d\n\n", + this, rv, totalBytesWritten)); + return rv; } @@ -628,26 +734,37 @@ nsresult nsSocketTransport::doRead(PRInt16 aSelectFlags) //----- nsresult nsSocketTransport::doWrite(PRInt16 aSelectFlags) { - PRUint32 bytesRead; + PRUint32 bytesRead, totalBytesRead; PRInt32 len; PRErrorCode code; nsresult rv = NS_OK; NS_ASSERTION(eSocketState_WaitReadWrite == mCurrentState, "Wrong state."); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::doWrite() [this=%x].\t" + "aSelectFlags = %x.\n", + this, aSelectFlags)); + // // Check for an error during PR_Poll(...) // if (PR_POLL_EXCEPT & aSelectFlags) { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("PR_Write() failed via PR_POLL_EXCEPT. [this=%x].\n", this)); + // XXX: What should this error code be? rv = NS_ERROR_FAILURE; } + totalBytesRead = 0; while (NS_OK == rv) { rv = mWriteStream->Read(gIOBuffer, sizeof(gIOBuffer), &bytesRead); if (NS_SUCCEEDED(rv)) { if (bytesRead > 0) { + totalBytesRead += bytesRead; len = PR_Write(mSocketFD, gIOBuffer, bytesRead); + if (len < 0) { code = PR_GetError(); @@ -655,6 +772,11 @@ nsresult nsSocketTransport::doWrite(PRInt16 aSelectFlags) rv = NS_BASE_STREAM_WOULD_BLOCK; } else { + PR_LOG(gSocketLog, PR_LOG_ERROR, + ("PR_Write() failed. [this=%x]. PRErrorCode = %x\n", + this, code)); + + // XXX: What should this error code be? rv = NS_ERROR_FAILURE; } } @@ -677,6 +799,11 @@ nsresult nsSocketTransport::doWrite(PRInt16 aSelectFlags) mSelectFlags |= (PR_POLL_WRITE | PR_POLL_EXCEPT); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::doWrite() [this=%x]. rv = %x.\t" + "Total bytes written: %d\n\n", + this, rv, totalBytesRead)); + return rv; } @@ -719,7 +846,15 @@ NS_IMPL_THREADSAFE_ISUPPORTS(nsSocketTransport, nsITransport::GetIID()); NS_IMETHODIMP nsSocketTransport::Cancel(void) { - return NS_ERROR_NOT_IMPLEMENTED; + nsresult rv = NS_OK; + + rv = NS_ERROR_NOT_IMPLEMENTED; + + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Canceling nsSocketTransport [this=%x]. rv = %x\n", + this, rv)); + + return rv; } NS_IMETHODIMP @@ -741,6 +876,11 @@ nsSocketTransport::Suspend(void) rv = mService->AddToWorkQ(this); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Suspending nsSocketTransport [this=%x]. rv = %x\t" + "mSuspendCount = %d.\n", + this, rv, mSuspendCount)); + // Leave the socket transport lock... Unlock(); @@ -770,6 +910,11 @@ nsSocketTransport::Resume(void) rv = NS_ERROR_FAILURE; } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("Resuming nsSocketTransport [this=%x]. rv = %x\t" + "mSuspendCount = %d.\n", + this, rv, mSuspendCount)); + // Leave the socket transport lock... Unlock(); @@ -794,6 +939,9 @@ nsSocketTransport::AsyncRead(nsISupports* aContext, // Enter the socket transport lock... Lock(); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::AsyncRead() [this=%x].\n", this)); + // If a read is already in progress then fail... if (mReadListener) { rv = NS_ERROR_IN_PROGRESS; @@ -821,6 +969,10 @@ nsSocketTransport::AsyncRead(nsISupports* aContext, rv = mService->AddToWorkQ(this); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::AsyncRead() [this=%x]. rv = %x.\n", + this, rv)); + // Leave the socket transport lock... Unlock(); @@ -839,6 +991,9 @@ nsSocketTransport::AsyncWrite(nsIInputStream* aFromStream, // Enter the socket transport lock... Lock(); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::AsyncWrite() [this=%x].\n", this)); + // If a write is already in progress then fail... if (mWriteStream) { rv = NS_ERROR_IN_PROGRESS; @@ -864,6 +1019,10 @@ nsSocketTransport::AsyncWrite(nsIInputStream* aFromStream, rv = mService->AddToWorkQ(this); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::AsyncWrite() [this=%x]. rv = %x.\n", + this, rv)); + // Leave the socket transport lock... Unlock(); @@ -879,6 +1038,10 @@ nsSocketTransport::OpenInputStream(nsIInputStream* *result) // Enter the socket transport lock... Lock(); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::OpenInputStream() [this=%x].\n", + this)); + // If a read is already in progress then fail... if (mReadListener) { rv = NS_ERROR_IN_PROGRESS; @@ -898,7 +1061,8 @@ nsSocketTransport::OpenInputStream(nsIInputStream* *result) rv = NS_NewSyncStreamListener(&mReadListener, &stream); // XXX: This is sorta nasty... if (NS_SUCCEEDED(rv)) { - rv = stream->QueryInterface(nsIByteBufferInputStream::GetIID(), (void**)&mReadStream); + rv = stream->QueryInterface(nsIByteBufferInputStream::GetIID(), + (void**)&mReadStream); } *result = mReadStream; } @@ -909,6 +1073,11 @@ nsSocketTransport::OpenInputStream(nsIInputStream* *result) rv = mService->AddToWorkQ(this); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::OpenInputStream() [this=%x].\t" + "rv = %x.\n", + this, rv)); + // Leave the socket transport lock... Unlock(); @@ -924,6 +1093,10 @@ nsSocketTransport::OpenOutputStream(nsIOutputStream* *result) // Enter the socket transport lock... Lock(); + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("+++ Entering nsSocketTransport::OpenOutputStream() [this=%x].\n", + this)); + // If a write is already in progress then fail... if (mWriteStream) { rv = NS_ERROR_IN_PROGRESS; @@ -950,6 +1123,11 @@ nsSocketTransport::OpenOutputStream(nsIOutputStream* *result) rv = mService->AddToWorkQ(this); } + PR_LOG(gSocketLog, PR_LOG_DEBUG, + ("--- Leaving nsSocketTransport::OpenOutputStream() [this=%x].\t" + "rv = %x.\n", + this, rv)); + // Leave the socket transport lock... Unlock();