Fixed logging bug with varargs and dialed back excessive trace logging in Message.

xpcPlugin/Log.cpp

@@ -29,15 +29,48 @@ namespace XPC
 		std::tm * tm = std::localtime(&now_tt);
 
 		std::stringstream ss;
-		ss << std::setfill('0') << "["
+		ss << std::setfill('0')
 			<< std::setw(2) << tm->tm_hour << ":"
 			<< std::setw(2) << tm->tm_min << ":"
 			<< std::setw(2) << tm->tm_sec << "."
-			<< std::setw(3) << ms.count() << "]";
+			<< std::setw(3) << ms.count() << "|";
 
 		std::fprintf(fd, ss.str().c_str());
 	}
 
+	static void WriteLevel(FILE* fd, int level)
+	{
+		char* str;
+		switch (level)
+		{
+		case LOG_OFF:
+			str = "  OFF|";
+			break;
+		case LOG_FATAL:
+			str = "FATAL|";
+			break;
+		case LOG_ERROR:
+			str = "ERROR|";
+			break;
+		case LOG_WARN:
+			str = " WARN|";
+			break;
+		case LOG_INFO:
+			str = " INFO|";
+			break;
+		case LOG_DEBUG:
+			str = "DEBUG|";
+			break;
+		case LOG_TRACE:
+			str = "TRACE|";
+			break;
+		default:
+			str = "  UNK|";
+			break;
+		}
+		std::fprintf(fd, str);
+	}
+
 	void Log::Initialize(const std::string& version)
 	{
 		if (LOG_LEVEL == LOG_OFF)
@@ -98,11 +131,12 @@ namespace XPC
 		}
 
 		WriteTime(fd);
-		std::fprintf(fd, "[%s] %s\n", tag.c_str(), value.c_str());
+		WriteLevel(fd, level);
+		std::fprintf(fd, "%s|%s\n", tag.c_str(), value.c_str());
 		std::fflush(fd);
 	}
 
-	void Log::FormatLine(int level, const std::string& tag, const std::string& format, ...)
+	void Log::FormatLine(int level, const std::string& tag, std::string format, ...)
 	{
 		va_list args;
 
@@ -113,7 +147,8 @@ namespace XPC
 		va_start(args, format);
 
 		WriteTime(fd);
-		std::fprintf(fd, "[%s] ", tag.c_str());
+		WriteLevel(fd, level);
+		std::fprintf(fd, "%s| ", tag.c_str());
 		std::vfprintf(fd, format.c_str(), args);
 		std::fprintf(fd, "\n");
 		std::fflush(fd);

xpcPlugin/Log.h

@@ -22,9 +22,7 @@
 #define LOG_DEBUG 5
 #define LOG_TRACE 6
 
-#ifndef LOG_LEVEL
-#define LOG_LEVEL LOG_ERROR
-#endif
+#define LOG_LEVEL LOG_TRACE
 
 namespace XPC
 {
@@ -53,7 +51,10 @@ namespace XPC
 		/// specifiers.
 		///
 		/// \param format The format string appropriate for consumption by sprintf.
-		static void FormatLine(int level, const std::string& tag, const std::string& format, ...);
+		///
+		/// \remarks Note that Visual C++ silently fails va_start when the last non-varargs
+		///          argument is a reference, so we need a value-type format here.
+		static void FormatLine(int level, const std::string& tag, const std::string format, ...);
 
 		/// Writes the specified string value, followed by a line terminator
 		/// to the XPC log file.

xpcPlugin/Message.cpp

@@ -13,44 +13,41 @@ namespace XPC
 
 	Message Message::ReadFrom(const UDPSocket& sock)
 	{
-		Log::WriteLine(LOG_TRACE, "MESG", "Reading Message");
 		Message m;
 		int len = sock.Read(m.buffer, bufferSize, &m.source);
 		m.size = len < 0 ? 0 : len;
-		Log::FormatLine(LOG_TRACE, "MESG", "Read result: %i", len);
+		if (len > 0)
+		{
+			Log::FormatLine(LOG_TRACE, "MESG", "Read message with length %i", len);
+		}
 		return m;
 	}
 
 	unsigned long Message::GetMagicNumber() const
 	{
 		unsigned long val = size < 4 ? 0 : *((unsigned long*)buffer);
-		Log::FormatLine(LOG_TRACE, "MESG", "Gettting magic number 0x%lX for message 0x%zX", val, this);
 		return val;
 	}
 
 	std::string Message::GetHead() const
 	{
 		std::string val = size < 4 ? "" : std::string((char*)buffer, 4);
-		Log::FormatLine(LOG_TRACE, "MESG", "Getting head %s for message 0x%zX", val, this);
 		return val;
 	}
 
 	const unsigned char* Message::GetBuffer() const
 	{
 		const unsigned char* val = size == 0 ? NULL : buffer;
-		Log::FormatLine(LOG_TRACE, "MESG", "Returning buffer 0x%lX for message 0x%zX", val, this);
 		return val;
 	}
 
 	std::size_t Message::GetSize() const
 	{
-		Log::FormatLine(LOG_TRACE, "MESG", "Returning size %zu for message 0x%zX", size, this);
 		return size;
 	}
 
 	struct sockaddr Message::GetSource() const
 	{
-		Log::FormatLine(LOG_TRACE, "MESG", "Returning source for message 0x%zX", this);
 		return source;
 	}
 

xpcPlugin/xpcPlugin/xpcPlugin.vcxproj

@@ -101,7 +101,7 @@
       <PrecompiledHeader>NotUsing</PrecompiledHeader>
       <WarningLevel>Level3</WarningLevel>
       <Optimization>Disabled</Optimization>
-      <PreprocessorDefinitions>IBM=1;XPLM200;_DEBUG;_WINDOWS;_USRDLL;XPCPLUGIN_EXPORTS;_CRT_SECURE_NO_WARNINGS;LOG_LEVEL=LOG_TRACE;%(PreprocessorDefinitions)</PreprocessorDefinitions>
+      <PreprocessorDefinitions>IBM=1;XPLM200;_DEBUG;_WINDOWS;_USRDLL;XPCPLUGIN_EXPORTS;_CRT_SECURE_NO_WARNINGS;%(PreprocessorDefinitions)</PreprocessorDefinitions>
       <DebugInformationFormat>OldStyle</DebugInformationFormat>
       <MultiProcessorCompilation>true</MultiProcessorCompilation>
       <OmitFramePointers />