Introduce log.file config option to log to file (#837)

Author: bukka

src/lib/SoftHSM.cpp

@@ -574,10 +574,17 @@ CK_RV SoftHSM::C_Initialize(CK_VOID_PTR pInitArgs)
 		return CKR_GENERAL_ERROR;
 	}
 
+	// Configure log file (empty string = use syslog)
+	if (!setLogFile(Configuration::i()->getString("log.file", "")))
+	{
+		WARNING_MSG("Could not open log file, using syslog");
+	}
+
 	// Configure object store storage backend used by all tokens.
 	if (!ObjectStoreToken::selectBackend(Configuration::i()->getString("objectstore.backend", DEFAULT_OBJECTSTORE_BACKEND)))
 	{
 		ERROR_MSG("Could not set the storage backend");
+		closeLogFile();
 		return CKR_GENERAL_ERROR;
 	}
 
@@ -589,6 +596,7 @@ CK_RV SoftHSM::C_Initialize(CK_VOID_PTR pInitArgs)
 	if (!objectStore->isValid())
 	{
 		WARNING_MSG("Could not load the object store");
+		closeLogFile();
 		delete objectStore;
 		objectStore = NULL;
 		delete sessionObjectStore;
@@ -637,6 +645,9 @@ CK_RV SoftHSM::C_Finalize(CK_VOID_PTR pReserved)
 	CryptoFactory::reset();
 	SecureMemoryRegistry::reset();
 
+	// Close log file if open
+	closeLogFile();
+
 	isInitialised = false;
 
 	supportedMechanisms.clear();

src/lib/common/Configuration.cpp

@@ -48,6 +48,7 @@ const struct config Configuration::valid_config[] = {
 	{ "objectstore.backend",	CONFIG_TYPE_STRING },
 	{ "objectstore.umask",		CONFIG_TYPE_INT_OCTAL },
 	{ "log.level",			CONFIG_TYPE_STRING },
+	{ "log.file",			CONFIG_TYPE_STRING },
 	{ "slots.removable",		CONFIG_TYPE_BOOL },
 	{ "slots.mechanisms",		CONFIG_TYPE_STRING },
 	{ "library.reset_on_fork",	CONFIG_TYPE_BOOL },

src/lib/common/log.cpp

@@ -29,7 +29,7 @@
 
  Implements logging functions. This file is based on the concepts from
  SoftHSM v1 but extends the logging functions with support for a variable
- argument list as defined in stdarg (3).
+ argument list as defined in stdarg (3) and logging to file.
  *****************************************************************************/
 
 #include "config.h"
@@ -38,9 +38,19 @@
 #include <stdio.h>
 #include <sstream>
 #include <vector>
+#include <time.h>
+#ifdef _WIN32
+#include <windows.h>
+#include <process.h>
+#else
+#include <unistd.h>
+#endif
 #include "log.h"
+#include "MutexFactory.h"
 
 int softLogLevel = LOG_DEBUG;
+static FILE* logFile = nullptr;
+static Mutex* logMutex = nullptr;
 
 bool setLogLevel(const std::string &loglevel)
 {
@@ -69,6 +79,104 @@ bool setLogLevel(const std::string &loglevel)
 	return true;
 }
 
+bool setLogFile(const std::string &logFilePath)
+{
+	// Quick return without creating mutex for default configuration
+	if (logFilePath.empty() && logFile == nullptr)
+	{
+		return true;
+	}
+
+	if (logMutex == nullptr)
+	{
+		// Create mutex for later access
+		logMutex = MutexFactory::i()->getMutex();
+	}
+
+	if (logFile != nullptr)
+	{
+		fclose(logFile);
+		logFile = nullptr;
+	}
+
+	if (logFilePath.empty())
+	{
+		return true;
+	}
+
+	// This function needs to be called in init so it does not need locking
+	logFile = fopen(logFilePath.c_str(), "a");
+	if (logFile == nullptr)
+	{
+		syslog(LOG_ERR, "Failed to open log file: %s, using syslog only", logFilePath.c_str());
+		return false;
+	}
+
+	return true;
+}
+
+void closeLogFile()
+{
+	if (logFile != nullptr)
+	{
+		fclose(logFile);
+		logFile = nullptr;
+	}
+
+	if (logMutex != nullptr)
+	{
+		MutexFactory::i()->recycleMutex(logMutex);
+		logMutex = nullptr;
+	}
+}
+
+static const char* getLevelString(int loglevel)
+{
+	switch(loglevel)
+	{
+		case LOG_ERR: return "ERROR";
+		case LOG_WARNING: return "WARNING";
+		case LOG_INFO: return "INFO";
+		case LOG_DEBUG: return "DEBUG";
+		default: return "UNKNOWN";
+	}
+}
+
+static void writeLogToFile(const int loglevel, const char* prependText, const char* msgText)
+{
+	MutexLocker lock(logMutex);
+
+#ifdef _WIN32
+	SYSTEMTIME st;
+	GetLocalTime(&st);
+	fprintf(logFile, "%04d-%02d-%02d %02d:%02d:%02d.%03d [%d] %s: %s%s\n",
+		st.wYear, st.wMonth, st.wDay, st.wHour, st.wMinute, st.wSecond, st.wMilliseconds,
+		_getpid(), getLevelString(loglevel), prependText, msgText);
+#else
+	char basetime[32];
+	long millis;
+#ifdef CLOCK_REALTIME
+	struct timespec ts;
+	clock_gettime(CLOCK_REALTIME, &ts);
+	struct tm timeinfo;
+	localtime_r(&ts.tv_sec, &timeinfo);
+	millis = ts.tv_nsec / 1000000;
+#else
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	struct tm timeinfo;
+	localtime_r(&tv.tv_sec, &timeinfo);
+	millis = tv.tv_usec / 1000;
+#endif
+	strftime(basetime, sizeof(basetime), "%Y-%m-%d %H:%M:%S", &timeinfo);
+	fprintf(logFile, "%s.%03ld [%d] %s: %s%s\n",
+		basetime, millis,
+		(int)getpid(), getLevelString(loglevel), prependText, msgText);
+#endif
+
+	fflush(logFile);
+}
+
 void softHSMLog(const int loglevel, const char* functionName, const char* fileName, const int lineNo, const char* format, ...)
 {
 	if (loglevel > softLogLevel) return;
@@ -98,12 +206,22 @@ void softHSMLog(const int loglevel, const char* functionName, const char* fileNa
 	vsnprintf(&logMessage[0], 4096, format, args);
 	va_end(args);
 
-	// And log it
-	syslog(loglevel, "%s%s", prepend.str().c_str(), &logMessage[0]);
+	const char* msgText = &logMessage[0];
+	std::string prependStr = prepend.str();
+	const char* prependText = prependStr.c_str();
+
+	// Log to file if configured, otherwise use syslog
+	if (logFile != nullptr)
+	{
+		writeLogToFile(loglevel, prependText, msgText);
+	}
+	else
+	{
+		syslog(loglevel, "%s%s", prependText, msgText);
+	}
 
 #ifdef DEBUG_LOG_STDERR
-	fprintf(stderr, "%s%s\n", prepend.str().c_str(), &logMessage[0]);
+	fprintf(stderr, "%s%s\n", prependText, msgText);
 	fflush(stderr);
-#endif // DEBUG_LOG_STDERR
+#endif
 }
-

src/lib/common/log.h

@@ -79,6 +79,8 @@
 
 /* Function definitions */
 bool setLogLevel(const std::string &loglevel);
+bool setLogFile(const std::string &logFilePath);
+void closeLogFile();
 void softHSMLog(const int loglevel, const char* functionName, const char* fileName, const int lineNo, const char* format, ...);
 
 #endif /* !_SOFTHSM_V2_LOG_H */