Add offline logging to aid troubleshooting

2 files changed, 180 insertions, 21 deletions

diff --git a/windows/winnet/src/winnet/netmonitor.cpp b/windows/winnet/src/winnet/netmonitor.cpp
index a6c2903397..99a31f7abb 100644
--- a/windows/winnet/src/winnet/netmonitor.cpp
+++ b/windows/winnet/src/winnet/netmonitor.cpp
@@ -2,7 +2,8 @@
 #include "netmonitor.h"
 #include <libcommon/error.h>
 #include <libcommon/memory.h>
-#include <libcommon/synchronization.h>
+#include <libcommon/string.h>
+#include <sstream>
 
 namespace
 {
@@ -28,11 +29,17 @@ bool ValidInterfaceType(const MIB_IF_ROW2 &iface)
 	return true;
 }
 
-} // anonyomus namespace
+} // anonymous namespace
 
-NetMonitor::NetMonitor(NetMonitor::Notifier notifier, bool &currentConnectivity)
-	: m_connected(false)
+NetMonitor::NetMonitor
+(
+	std::shared_ptr<common::logging::ILogSink> logSink,
+	NetMonitor::Notifier notifier,
+	bool &currentConnectivity
+)
+	: m_logSink(logSink)
 	, m_notifier(notifier)
+	, m_connected(false)
 	, m_notificationHandle(nullptr)
 {
 	m_cache = CreateCache();
@@ -43,6 +50,11 @@ NetMonitor::NetMonitor(NetMonitor::Notifier notifier, bool &currentConnectivity)
 	const auto status = NotifyIpInterfaceChange(AF_UNSPEC, Callback, this, FALSE, &m_notificationHandle);
 
 	THROW_UNLESS(NO_ERROR, status, "Register interface change notification");
+
+	if (false == m_connected)
+	{
+		LogOfflineState(m_logSink);
+	}
 }
 
 NetMonitor::~NetMonitor()
@@ -51,9 +63,23 @@ NetMonitor::~NetMonitor()
 }
 
 // static
-bool NetMonitor::CheckConnectivity()
+bool NetMonitor::CheckConnectivity(std::shared_ptr<common::logging::ILogSink> logSink)
 {
-	return CheckConnectivity(CreateCache());
+	static bool loggedOffline = false;
+
+	const auto connected = CheckConnectivity(CreateCache());
+
+	if (connected)
+	{
+		loggedOffline = false;
+	}
+	else if (false == loggedOffline)
+	{
+		LogOfflineState(logSink);
+		loggedOffline = true;
+	}
+
+	return connected;
 }
 
 // static
@@ -78,6 +104,7 @@ NetMonitor::Cache NetMonitor::CreateCache()
 	{
 		AddCacheEntry(cache, table->Table[i]);
 	}
+
 	return cache;
 }
 
@@ -126,9 +153,12 @@ void NetMonitor::updateConnectivity()
 //static
 void __stdcall NetMonitor::Callback(void *context, MIB_IPINTERFACE_ROW *hint, MIB_NOTIFICATION_TYPE updateType)
 {
-	auto thiz = reinterpret_cast<NetMonitor *>(context);
+	reinterpret_cast<NetMonitor *>(context)->callback(hint, updateType);
+}
 
-	common::sync::ScopeLock<> processingLock(thiz->m_processingMutex);
+void NetMonitor::callback(MIB_IPINTERFACE_ROW *hint, MIB_NOTIFICATION_TYPE updateType)
+{
+	std::scoped_lock<std::mutex> processingLock(m_processingMutex);
 
 	switch (updateType)
 	{
@@ -143,15 +173,15 @@ void __stdcall NetMonitor::Callback(void *context, MIB_IPINTERFACE_ROW *hint, MI
 				return;
 			}
 
-			thiz->AddCacheEntry(thiz->m_cache, iface);
+			AddCacheEntry(m_cache, iface);
 
 			break;
 		}
 		case MibDeleteInstance:
 		{
-			const auto cacheEntry = thiz->m_cache.find(hint->InterfaceLuid.Value);
+			const auto cacheEntry = m_cache.find(hint->InterfaceLuid.Value);
 
-			if (thiz->m_cache.end() != cacheEntry)
+			if (m_cache.end() != cacheEntry)
 			{
 				cacheEntry->second.connected = false;
 			}
@@ -160,9 +190,9 @@ void __stdcall NetMonitor::Callback(void *context, MIB_IPINTERFACE_ROW *hint, MI
 		}
 		case MibParameterNotification:
 		{
-			auto cacheEntry = thiz->m_cache.find(hint->InterfaceLuid.Value);
+			auto cacheEntry = m_cache.find(hint->InterfaceLuid.Value);
 
-			if (thiz->m_cache.end() == cacheEntry)
+			if (m_cache.end() == cacheEntry)
 			{
 				//
 				// A change occurred on an interface that we're not tracking.
@@ -178,7 +208,7 @@ void __stdcall NetMonitor::Callback(void *context, MIB_IPINTERFACE_ROW *hint, MI
 					return;
 				}
 
-				thiz->AddCacheEntry(thiz->m_cache, iface);
+				AddCacheEntry(m_cache, iface);
 			}
 			else
 			{
@@ -207,12 +237,134 @@ void __stdcall NetMonitor::Callback(void *context, MIB_IPINTERFACE_ROW *hint, MI
 		}
 	}
 
-	const auto previousConnectivity = thiz->m_connected;
+	const auto previousConnectivity = m_connected;
+
+	updateConnectivity();
+
+	if (previousConnectivity != m_connected)
+	{
+		m_notifier(m_connected);
+
+		if (false == m_connected)
+		{
+			LogOfflineState(m_logSink);
+		}
+	}
+}
+
+//static
+void NetMonitor::LogOfflineState(std::shared_ptr<common::logging::ILogSink> logSink)
+{
+	//
+	// There is a race condition here because logging is not done using the
+	// same data set that the online/offline logic processes.
+	//
+	// Not much of a problem really, this is temporary logging.
+	//
+
+	logSink->info("Machine is offline");
+
+	MIB_IF_TABLE2 *table;
+
+	const auto status = GetIfTable2(&table);
+
+	if (NO_ERROR != status)
+	{
+		logSink->error("Failed to acquire list of network interfaces. Aborting detailed logging");
+		return;
+	}
+
+	common::memory::ScopeDestructor sd;
 
-	thiz->updateConnectivity();
+	sd += [table]()
+	{
+		FreeMibTable(table);
+	};
 
-	if (previousConnectivity != thiz->m_connected)
+	logSink->info("Begin detailed listing of network interfaces");
+
+	for (ULONG i = 0; i < table->NumEntries; ++i)
 	{
-		thiz->m_notifier(thiz->m_connected);
+		const auto &iface = table->Table[i];
+
+		std::stringstream ss;
+
+		ss << "Detailed interface logging" << std::endl;
+		ss << "Interface ordinal " << i << std::endl;
+
+		//
+		// Don't flood the log with garbage.
+		//
+		const auto blacklist = std::vector<std::wstring>
+		{
+			L"WFP Native MAC Layer LightWeight Filter",
+			L"QoS Packet Scheduler",
+			L"WFP 802.3 MAC Layer LightWeight Filter",
+			L"Microsoft Kernel Debug Network Adapter",
+			L"Software Loopback Interface",
+			L"Microsoft Teredo Tunneling Adapter",
+			L"Microsoft IP-HTTPS Platform Adapter",
+			L"Microsoft 6to4 Adapter",
+		};
+
+		bool blacklisted = false;
+
+		for (const auto &black : blacklist)
+		{
+			if (nullptr != wcsstr(iface.Description, black.c_str()))
+			{
+				blacklisted = true;
+				break;
+			}
+		}
+
+		if (blacklisted)
+		{
+			ss << "  filtered out to avoid flooding log";
+			logSink->info(ss.str().c_str());
+
+			continue;
+		}
+
+		{
+			const auto s = std::wstring(L"  Alias: ").append(iface.Alias);
+			ss << common::string::ToAnsi(s) << std::endl;
+		}
+
+		{
+			const auto s = std::wstring(L"  \"Description\": ").append(iface.Description);
+			ss << common::string::ToAnsi(s) << std::endl;
+		}
+
+		ss << "  PhysicalAddressLength: " << iface.PhysicalAddressLength << std::endl;
+		ss << "  Type: " << iface.Type << std::endl;
+		ss << "  MediaType: " << iface.MediaType << std::endl;
+		ss << "  PhysicalMediumType: " << iface.PhysicalMediumType << std::endl;
+		ss << "  AccessType: " << iface.AccessType << std::endl;
+
+		//
+		// Bool cast prevents idiot stream from inserting literal 0/1.
+		//
+
+		ss << "  InterfaceAndOperStatusFlags.HardwareInterface: " << (bool)iface.InterfaceAndOperStatusFlags.HardwareInterface << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.FilterInterface: " << (bool)iface.InterfaceAndOperStatusFlags.FilterInterface << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.ConnectorPresent: " << (bool)iface.InterfaceAndOperStatusFlags.ConnectorPresent << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.NotAuthenticated: " << (bool)iface.InterfaceAndOperStatusFlags.NotAuthenticated << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.NotMediaConnected: " << (bool)iface.InterfaceAndOperStatusFlags.NotMediaConnected << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.Paused: " << (bool)iface.InterfaceAndOperStatusFlags.Paused << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.LowPower: " << (bool)iface.InterfaceAndOperStatusFlags.LowPower << std::endl;
+		ss << "  InterfaceAndOperStatusFlags.EndPointInterface: " << (bool)iface.InterfaceAndOperStatusFlags.EndPointInterface << std::endl;
+
+		ss << "  OperStatus: " << iface.OperStatus << std::endl;
+		ss << "  AdminStatus: " << iface.AdminStatus << std::endl;
+		ss << "  MediaConnectState: " << iface.MediaConnectState << std::endl;
+		ss << "  TransmitLinkSpeed: " << iface.TransmitLinkSpeed << std::endl;
+
+		ss << "  ReceiveLinkSpeed: " << iface.ReceiveLinkSpeed << std::endl;
+		ss << "  InUcastPkts:" << iface.InUcastPkts;
+
+		logSink->info(ss.str().c_str());
 	}
+
+	logSink->info("End detailed listing of network interfaces");
 }
diff --git a/windows/winnet/src/winnet/netmonitor.h b/windows/winnet/src/winnet/netmonitor.h
index 77e4417b31..a3e0a28281 100644
--- a/windows/winnet/src/winnet/netmonitor.h
+++ b/windows/winnet/src/winnet/netmonitor.h
@@ -1,5 +1,7 @@
 #pragma once
 
+#include <libcommon/logging/ilogsink.h>
+#include <memory>
 #include <map>
 #include <string>
 #include <cstdint>
@@ -20,13 +22,16 @@ public:
 	//
 	using Notifier = std::function<void(bool)>;
 
-	NetMonitor(Notifier notifier, bool &currentConnectivity);
+	NetMonitor(std::shared_ptr<common::logging::ILogSink> logSink, Notifier notifier, bool &currentConnectivity);
 	~NetMonitor();
 
-	static bool CheckConnectivity();
+	static bool CheckConnectivity(std::shared_ptr<common::logging::ILogSink> logSink);
 
 private:
 
+	std::shared_ptr<common::logging::ILogSink> m_logSink;
+	Notifier m_notifier;
+
 	struct CacheEntry
 	{
 		// Unique interface identifier.
@@ -44,7 +49,6 @@ private:
 	std::mutex m_processingMutex;
 	Cache m_cache;
 	bool m_connected;
-	Notifier m_notifier;
 
 	HANDLE m_notificationHandle;
 
@@ -55,4 +59,7 @@ private:
 	void updateConnectivity();
 
 	static void __stdcall Callback(void *context, MIB_IPINTERFACE_ROW *hint, MIB_NOTIFICATION_TYPE updateType);
+	void callback(MIB_IPINTERFACE_ROW *hint, MIB_NOTIFICATION_TYPE updateType);
+
+	static void LogOfflineState(std::shared_ptr<common::logging::ILogSink> logSink);
 };