Improve debugging of named pipe operations and bbackupctl pipe interaction.

4 files changed, 67 insertions, 39 deletions

diff --git a/bin/bbackupctl/bbackupctl.cpp b/bin/bbackupctl/bbackupctl.cpp
index b00e90ba..b07f65a4 100644
--- a/bin/bbackupctl/bbackupctl.cpp
+++ b/bin/bbackupctl/bbackupctl.cpp
@@ -220,6 +220,9 @@ int main(int argc, const char *argv[])
 		return 1;
 	}
 
+	BOX_TRACE("Current state: " <<
+		BackupDaemon::GetStateName(currentState));
+
 	Command command = Default;
 	std::string commandName(argv[0]);
 
@@ -237,21 +240,8 @@ int main(int argc, const char *argv[])
 	}
 	else if (commandName == "status")
 	{
-		std::string stateName;
-
-		#define STATE(x) case BackupDaemon::State_ ## x: stateName = #x; break;
-		switch (currentState)
-		{
-		STATE(Initialising);
-		STATE(Idle);
-		STATE(Connected);
-		STATE(Error);
-		STATE(StorageLimitExceeded);
-		default:
-			stateName = "unknown";
-			break;
-		}
-		BOX_NOTICE("state " << currentState << " " << stateName);
+		BOX_NOTICE("state " <<
+			BackupDaemon::GetStateName(currentState));
 		command = NoCommand;
 	}
 
@@ -277,8 +267,7 @@ int main(int argc, const char *argv[])
 			// send a sync command
 			commandName = "force-sync";
 			std::string cmd = commandName + "\n";
-			connection.Write(cmd.c_str(), cmd.size(),
-				PROTOCOL_DEFAULT_TIMEOUT);
+			connection.Write(cmd, PROTOCOL_DEFAULT_TIMEOUT);
 			connection.WriteAllBuffered();
 
 			if (currentState != 0)
@@ -317,6 +306,23 @@ int main(int argc, const char *argv[])
 	while(command != NoCommand && !finished && !getLine.IsEOF() &&
 		getLine.GetLine(line, false, PROTOCOL_DEFAULT_TIMEOUT))
 	{
+		BOX_TRACE("Received line: " << line);
+
+		if(line.substr(0, 6) == "state ")
+		{
+			std::string state_str = line.substr(6);
+			int state_num;
+			if(sscanf(state_str.c_str(), "%d", &state_num) == 1)
+			{
+				BOX_INFO("Daemon state changed to: " <<
+					BackupDaemon::GetStateName(state_num));
+			}
+			else
+			{
+				BOX_WARNING("Failed to parse line: " << line);
+			}
+		}
+
 		switch (command)
 		{
 			case WaitForSyncStart:
diff --git a/bin/bbackupd/BackupDaemon.h b/bin/bbackupd/BackupDaemon.h
index a6cb8d46..ba46dec2 100644
--- a/bin/bbackupd/BackupDaemon.h
+++ b/bin/bbackupd/BackupDaemon.h
@@ -109,6 +109,25 @@ public:
 	};
 
 	int GetState() {return mState;}
+	static std::string GetStateName(int state)
+	{
+		std::string stateName;
+
+		#define STATE(x) case BackupDaemon::State_ ## x: stateName = #x; break;
+		switch (state)
+		{
+		STATE(Initialising);
+		STATE(Idle);
+		STATE(Connected);
+		STATE(Error);
+		STATE(StorageLimitExceeded);
+		default:
+			stateName = "unknown";
+		}
+		#undef STATE
+
+		return stateName;
+	}
 
 	// Allow other classes to call this too
 	void NotifySysadmin(SysadminNotifier::EventCode Event);
diff --git a/lib/server/WinNamedPipeListener.h b/lib/server/WinNamedPipeListener.h
index d18f0054..fab11a87 100644
--- a/lib/server/WinNamedPipeListener.h
+++ b/lib/server/WinNamedPipeListener.h
@@ -64,9 +64,9 @@ private:
 
 		if (handle == INVALID_HANDLE_VALUE)
 		{
-			BOX_LOG_WIN_ERROR("Failed to create named pipe " <<
-				socket);
-			THROW_EXCEPTION(ServerException, SocketOpenError)
+			THROW_WIN_FILE_ERRNO("Failed to create named pipe",
+				socket, GetLastError(), ServerException,
+				SocketOpenError);
 		}
 
 		return handle;
diff --git a/lib/server/WinNamedPipeStream.cpp b/lib/server/WinNamedPipeStream.cpp
index 14da2dd0..a3e7575e 100644
--- a/lib/server/WinNamedPipeStream.cpp
+++ b/lib/server/WinNamedPipeStream.cpp
@@ -88,10 +88,9 @@ WinNamedPipeStream::WinNamedPipeStream(HANDLE hNamedPipe)
 
 		if (err != ERROR_IO_PENDING)
 		{
-			BOX_ERROR("Failed to start overlapped read: " <<
-				GetErrorMessage(err));
 			Close();
-			THROW_EXCEPTION(ConnectionException, 
+			THROW_WIN_ERROR_NUMBER("Failed to start overlapped "
+				"read", err, ConnectionException,
 				SocketReadError)
 		}
 	}
@@ -261,10 +260,16 @@ bool WinNamedPipeStream::WaitForOverlappedOperation(OVERLAPPED& Overlapped,
 	DWORD waitResult = WaitForSingleObject(Overlapped.hEvent, Timeout);
 	DWORD NumBytesTransferred = -1;
 
+	if (waitResult == WAIT_FAILED)
+	{
+		THROW_WIN_ERROR_NUMBER("Failed to wait for overlapped I/O",
+			GetLastError(), ServerException, Internal);
+	}
+
 	if (waitResult == WAIT_ABANDONED)
 	{
-		THROW_EXCEPTION_MESSAGE(ServerException, BadSocketHandle,
-			"Wait for command socket read abandoned by system");
+		THROW_EXCEPTION_MESSAGE(ServerException, Internal,
+			"Wait for overlapped I/O abandoned by system");
 	}
 
 	if (waitResult == WAIT_TIMEOUT)
@@ -277,7 +282,7 @@ bool WinNamedPipeStream::WaitForOverlappedOperation(OVERLAPPED& Overlapped,
 	if (waitResult != WAIT_OBJECT_0)
 	{
 		THROW_EXCEPTION_MESSAGE(ServerException, BadSocketHandle,
-			"Failed to wait for command socket read: unknown "
+			"Failed to wait for overlapped I/O: unknown "
 			"result code: " << waitResult);
 	}
 
@@ -306,12 +311,12 @@ bool WinNamedPipeStream::WaitForOverlappedOperation(OVERLAPPED& Overlapped,
 		err == ERROR_BROKEN_PIPE)
 	{
 		BOX_INFO(BOX_WIN_ERRNO_MESSAGE(err,
-			"Control client disconnected"));
+			"Named pipe peer disconnected"));
 		Close();
 		return true;
 	}
 
-	THROW_WIN_ERROR_NUMBER("Failed to wait for OVERLAPPED operation "
+	THROW_WIN_ERROR_NUMBER("Failed to wait for overlapped I/O "
 		"to complete", err, ConnectionException, SocketReadError);
 }
 
@@ -333,18 +338,20 @@ int WinNamedPipeStream::Read(void *pBuffer, int NBytes, int Timeout)
 	
 	if (mSocketHandle == INVALID_HANDLE_VALUE || !mIsConnected) 
 	{
-		THROW_EXCEPTION(ServerException, BadSocketHandle)
+		THROW_EXCEPTION_MESSAGE(ServerException, BadSocketHandle,
+			"Tried to read from closed pipe");
 	}
 
 	if (mReadClosed)
 	{
-		THROW_EXCEPTION(ConnectionException, SocketShutdownError)
+		THROW_EXCEPTION_MESSAGE(ConnectionException,
+			SocketShutdownError, "Tried to read from closing pipe");
 	}
 
 	// ensure safe to cast NBytes to unsigned
 	if (NBytes < 0)
 	{
-		THROW_EXCEPTION(CommonException, AssertFailed)
+		THROW_EXCEPTION(CommonException, AssertFailed);
 	}
 
 	int64_t NumBytesRead;
@@ -526,8 +533,7 @@ void WinNamedPipeStream::Close()
 
 	if (!CancelIo(mSocketHandle))
 	{
-		BOX_ERROR("Failed to cancel outstanding I/O: " <<
-			GetErrorMessage(GetLastError()));
+		BOX_LOG_WIN_ERROR("Failed to cancel outstanding I/O");
 	}
 
 	if (mReadableEvent == INVALID_HANDLE_VALUE)
@@ -537,16 +543,14 @@ void WinNamedPipeStream::Close()
 	}
 	else if (!CloseHandle(mReadableEvent))
 	{
-		BOX_ERROR("Failed to destroy Readable event: " <<
-			GetErrorMessage(GetLastError()));
+		BOX_LOG_WIN_ERROR("Failed to destroy Readable event");
 	}
 
 	mReadableEvent = INVALID_HANDLE_VALUE;
 
 	if (!FlushFileBuffers(mSocketHandle))
 	{
-		BOX_ERROR("Failed to FlushFileBuffers: " <<
-			GetErrorMessage(GetLastError()));
+		BOX_LOG_WIN_ERROR("Failed to FlushFileBuffers");
 	}
 
 	if (!DisconnectNamedPipe(mSocketHandle))
@@ -554,8 +558,7 @@ void WinNamedPipeStream::Close()
 		DWORD err = GetLastError();
 		if (err != ERROR_PIPE_NOT_CONNECTED)
 		{
-			BOX_ERROR("Failed to DisconnectNamedPipe: " <<
-				GetErrorMessage(err));
+			BOX_LOG_WIN_ERROR("Failed to DisconnectNamedPipe");
 		}
 	}