Log instead of warn of unsupported extensions

Currently we produce a warning every time an unsupported extension is
used. The original bug (b/139528538) called for logging these structs
silently unless a debugger's attached.

So I've replaced all of our warnings for unsupported structs with
calls to LOG_TRAP. This is an update to TRACE_ASSERT. LOG_TRAP will
never emit to the debug log, instead it will only print to a file if
writing to files is enabled for logv.

Bug: b/148415347
Change-Id: Ib4ad2b20b3dffce4fac597c891b2f5ee23e032c4
Reviewed-on: https://swiftshader-review.googlesource.com/c/SwiftShader/+/41348
Tested-by: Sean Risser <srisser@google.com>
Presubmit-Ready: Sean Risser <srisser@google.com>
Kokoro-Presubmit: kokoro <noreply+kokoro@google.com>
Reviewed-by: Nicolas Capens <nicolascapens@google.com>

src/System/Debug.cpp

diff --git a/src/System/Debug.cpp b/src/System/Debug.cpp
index 8be91a1..1b91e14 100644
--- a/src/System/Debug.cpp
+++ b/src/System/Debug.cpp
@@ -98,11 +98,13 @@
 
 enum class Level
 {
+	Verbose,
 	Debug,
 	Info,
 	Warn,
 	Error,
 	Fatal,
+	Disabled,
 };
 
 #ifdef __ANDROID__
@@ -125,6 +127,8 @@
 		case Level::Fatal:
 			__android_log_write(ANDROID_LOG_FATAL, "SwiftShader", msg);
 			break;
+		default:
+			break;
 	}
 }
 #else
@@ -141,32 +145,32 @@
 		case Level::Fatal:
 			fprintf(stderr, "%s", msg);
 			break;
+		default:
+			break;
 	}
 }
 #endif
 
 void logv(Level level, const char *format, va_list args)
 {
-	if(static_cast<int>(level) < static_cast<int>(Level::SWIFTSHADER_LOGGING_LEVEL))
+	if(static_cast<int>(level) >= static_cast<int>(Level::SWIFTSHADER_LOGGING_LEVEL))
 	{
-		return;
-	}
-
 #ifndef SWIFTSHADER_DISABLE_TRACE
-	char buffer[2048];
-	vsnprintf(buffer, sizeof(buffer), format, args);
+		char buffer[2048];
+		vsnprintf(buffer, sizeof(buffer), format, args);
 
 #	if defined(__ANDROID__)
-	logv_android(level, buffer);
+		logv_android(level, buffer);
 #	elif defined(_WIN32)
-	logv_std(level, buffer);
-	::OutputDebugString(buffer);
+		logv_std(level, buffer);
+		::OutputDebugString(buffer);
 #	else
-	logv_std(level, buffer);
+		logv_std(level, buffer);
 #	endif
+	}
 
-	const bool traceToFile = false;
-	if(traceToFile)
+	const Level traceToFileLevel = Level::Disabled;
+	if(static_cast<int>(level) >= static_cast<int>(traceToFileLevel))
 	{
 		FILE *file = fopen(TRACE_OUTPUT_FILE, "a");
 
@@ -210,8 +214,10 @@
 	::abort();
 }
 
-void trace_assert(const char *format, ...)
+void log_trap(const char *format, ...)
 {
+	// If enabled, log_assert will log all messages, and otherwise ignore them
+	// unless a debugger is attached.
 	static std::atomic<bool> asserted = { false };
 	if(IsUnderDebugger() && !asserted.exchange(true))
 	{
@@ -227,7 +233,7 @@
 	{
 		va_list vararg;
 		va_start(vararg, format);
-		logv(Level::Fatal, format, vararg);
+		logv(Level::Verbose, format, vararg);
 		va_end(vararg);
 	}
 }

src/System/Debug.hpp

diff --git a/src/System/Debug.hpp b/src/System/Debug.hpp
index 85ea4a4..6556326 100644
--- a/src/System/Debug.hpp
+++ b/src/System/Debug.hpp
@@ -47,8 +47,8 @@
 // Outputs the message to the debugging log and stderr, and calls abort().
 void abort(const char *format, ...) CHECK_PRINTF_ARGS;
 
-// Outputs text to the debugging log, and asserts once if a debugger is attached.
-void trace_assert(const char *format, ...) CHECK_PRINTF_ARGS;
+// Outputs text to the debugging log, and traps once if a debugger is attached.
+void log_trap(const char *format, ...) CHECK_PRINTF_ARGS;
 
 }  // namespace sw
 
@@ -59,7 +59,7 @@
 #	define TRACE_ASSERT(message, ...) (void(0))
 #else
 #	define TRACE(message, ...) sw::trace("%s:%d TRACE: " message "\n", __FILE__, __LINE__, ##__VA_ARGS__)
-#	define TRACE_ASSERT(message, ...) sw::trace_assert("%s:%d %s TRACE_ASSERT: " message "\n", __FILE__, __LINE__, __func__, ##__VA_ARGS__)
+#	define LOG_TRAP(message, ...) sw::log_trap("%s:%d %s TRACE_ASSERT: " message "\n", __FILE__, __LINE__, __func__, ##__VA_ARGS__)
 #endif
 
 // A macro to print a warning message to the debugging log and stderr to denote

src/Vulkan/libVulkan.cpp

diff --git a/src/Vulkan/libVulkan.cpp b/src/Vulkan/libVulkan.cpp
index 937f482..c583748 100644
--- a/src/Vulkan/libVulkan.cpp
+++ b/src/Vulkan/libVulkan.cpp
@@ -243,7 +243,7 @@
 			}
 			break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -392,7 +392,7 @@
 				//  Vulkan structures in this Specification."
 				break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(createInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(createInfo->sType).c_str());
 				break;
 		}
 	}
@@ -752,7 +752,7 @@
 			break;
 			default:
 				// "the [driver] must skip over, without processing (other than reading the sType and pNext members) any structures in the chain with sType values not defined by [supported extenions]"
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -782,7 +782,7 @@
 		auto extInfo = reinterpret_cast<VkBaseInStructure const *>(queueCreateInfo.pNext);
 		while(extInfo)
 		{
-			WARN("pCreateInfo->pQueueCreateInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
+			LOG_TRAP("pCreateInfo->pQueueCreateInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
 			extInfo = extInfo->pNext;
 		}
 
@@ -968,7 +968,7 @@
 				break;
 			}
 			default:
-				WARN("pAllocateInfo->pNext sType = %s", vk::Stringify(allocationInfo->sType).c_str());
+				LOG_TRAP("pAllocateInfo->pNext sType = %s", vk::Stringify(allocationInfo->sType).c_str());
 				break;
 		}
 
@@ -1209,7 +1209,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pCreateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -1352,7 +1352,7 @@
 	while(extInfo)
 	{
 		// Vulkan 1.2: "pNext must be NULL"
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1406,7 +1406,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1443,7 +1443,7 @@
 				// Do nothing. Should be handled by vk::Buffer::Create().
 				break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 				break;
 		}
 		nextInfo = nextInfo->pNext;
@@ -1474,7 +1474,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1529,7 +1529,7 @@
 				break;
 			default:
 				// "the [driver] must skip over, without processing (other than reading the sType and pNext members) any structures in the chain with sType values not defined by [supported extenions]"
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -1633,7 +1633,7 @@
 			}
 			break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -1665,7 +1665,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pCreateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -1694,7 +1694,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1811,7 +1811,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pCreateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -1850,7 +1850,7 @@
 			}
 			break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -1883,7 +1883,7 @@
 				ASSERT(!vk::Cast(device)->hasExtension(VK_EXT_DESCRIPTOR_INDEXING_EXTENSION_NAME));
 				break;
 			default:
-				WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
+				LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extensionCreateInfo->sType).c_str());
 				break;
 		}
 
@@ -1909,7 +1909,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1946,7 +1946,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pAllocateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pAllocateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pAllocateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -1984,7 +1984,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pCreateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -2055,7 +2055,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pCreateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -2086,7 +2086,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pAllocateInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pAllocateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pAllocateInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -2109,7 +2109,7 @@
 	auto *nextInfo = reinterpret_cast<const VkBaseInStructure *>(pBeginInfo->pNext);
 	while(nextInfo)
 	{
-		WARN("pBeginInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
+		LOG_TRAP("pBeginInfo->pNext sType = %s", vk::Stringify(nextInfo->sType).c_str());
 		nextInfo = nextInfo->pNext;
 	}
 
@@ -2467,7 +2467,7 @@
 				// SwiftShader only has a single physical device, so this extension does nothing in this case.
 				break;
 			default:
-				WARN("pRenderPassBegin->pNext sType = %s", vk::Stringify(renderPassBeginInfo->sType).c_str());
+				LOG_TRAP("pRenderPassBegin->pNext sType = %s", vk::Stringify(renderPassBeginInfo->sType).c_str());
 				break;
 		}
 
@@ -2540,7 +2540,7 @@
 		auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pBindInfos[i].pNext);
 		while(extInfo)
 		{
-			WARN("pBindInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
+			LOG_TRAP("pBindInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
 			extInfo = extInfo->pNext;
 		}
 
@@ -2598,7 +2598,7 @@
 #endif
 
 				default:
-					WARN("pBindInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
+					LOG_TRAP("pBindInfos[%d].pNext sType = %s", i, vk::Stringify(extInfo->sType).c_str());
 					break;
 			}
 			extInfo = extInfo->pNext;
@@ -2650,7 +2650,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -2666,7 +2666,7 @@
 			}
 			break;
 			default:
-				WARN("pMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
+				LOG_TRAP("pMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
 				break;
 		}
 
@@ -2684,7 +2684,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -2700,7 +2700,7 @@
 			}
 			break;
 			default:
-				WARN("pMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
+				LOG_TRAP("pMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
 				break;
 		}
 
@@ -2718,14 +2718,14 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
 	auto extensionRequirements = reinterpret_cast<VkBaseInStructure const *>(pSparseMemoryRequirements->pNext);
 	while(extensionRequirements)
 	{
-		WARN("pSparseMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
+		LOG_TRAP("pSparseMemoryRequirements->pNext sType = %s", vk::Stringify(extensionRequirements->sType).c_str());
 		extensionRequirements = extensionRequirements->pNext;
 	}
 
@@ -2820,7 +2820,7 @@
 				                             sizeof(deviceExtensionProperties) / sizeof(deviceExtensionProperties[0])));
 				break;
 			default:
-				WARN("pFeatures->pNext sType = %s", vk::Stringify(extensionFeatures->sType).c_str());
+				LOG_TRAP("pFeatures->pNext sType = %s", vk::Stringify(extensionFeatures->sType).c_str());
 				break;
 		}
 
@@ -2918,7 +2918,7 @@
 			break;
 			default:
 				// "the [driver] must skip over, without processing (other than reading the sType and pNext members) any structures in the chain with sType values not defined by [supported extenions]"
-				WARN("pProperties->pNext sType = %s", vk::Stringify(extensionProperties->sType).c_str());
+				LOG_TRAP("pProperties->pNext sType = %s", vk::Stringify(extensionProperties->sType).c_str());
 				break;
 		}
 
@@ -2936,7 +2936,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pFormatProperties->pNext);
 	while(extInfo)
 	{
-		WARN("pFormatProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pFormatProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -2983,7 +2983,7 @@
 			}
 			break;
 			default:
-				WARN("pImageFormatInfo->pNext sType = %s", vk::Stringify(extensionFormatInfo->sType).c_str());
+				LOG_TRAP("pImageFormatInfo->pNext sType = %s", vk::Stringify(extensionFormatInfo->sType).c_str());
 				break;
 		}
 
@@ -3016,7 +3016,7 @@
 			}
 			break;
 			default:
-				WARN("pImageFormatProperties->pNext sType = %s", vk::Stringify(extensionProperties->sType).c_str());
+				LOG_TRAP("pImageFormatProperties->pNext sType = %s", vk::Stringify(extensionProperties->sType).c_str());
 				break;
 		}
 
@@ -3042,7 +3042,7 @@
 		auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pQueueFamilyProperties->pNext);
 		while(extInfo)
 		{
-			WARN("pQueueFamilyProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+			LOG_TRAP("pQueueFamilyProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 			extInfo = extInfo->pNext;
 		}
 	}
@@ -3064,7 +3064,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pMemoryProperties->pNext);
 	while(extInfo)
 	{
-		WARN("pMemoryProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pMemoryProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -3081,7 +3081,7 @@
 		auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pProperties->pNext);
 		while(extInfo)
 		{
-			WARN("pProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+			LOG_TRAP("pProperties->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 			extInfo = extInfo->pNext;
 		}
 	}
@@ -3112,7 +3112,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pQueueInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pQueueInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pQueueInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -3137,7 +3137,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}
 
@@ -3171,7 +3171,7 @@
 	auto extInfo = reinterpret_cast<VkBaseInStructure const *>(pCreateInfo->pNext);
 	while(extInfo)
 	{
-		WARN("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
+		LOG_TRAP("pCreateInfo->pNext sType = %s", vk::Stringify(extInfo->sType).c_str());
 		extInfo = extInfo->pNext;
 	}