From 5af30ef9d8928efab7c77eb30d9946e3416d0f0c Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Wed, 23 Sep 2026 18:44:35 +0200 Subject: [PATCH 1/7] Log EC console to the Windows Event Log Poll the EC console buffer and write each line to the Framework-CrosEcBus/Console event log channel, so it persists across boots. The Event Log service caps it at 10 MB. --- README.md | 41 ++++ crosecbus/consolelog.c | 373 ++++++++++++++++++++++++++++++++++++ crosecbus/consolelog.h | 35 ++++ crosecbus/crosecbus.c | 22 +++ crosecbus/crosecbus.inf | 24 ++- crosecbus/crosecbus.man | 94 +++++++++ crosecbus/crosecbus.rc | 3 + crosecbus/crosecbus.vcxproj | 26 +++ crosecbus/driver.h | 3 + crosecbus/ec_commands.h | 33 ++++ crosecbus/trace.h | 1 + 11 files changed, 653 insertions(+), 2 deletions(-) create mode 100644 crosecbus/consolelog.c create mode 100644 crosecbus/consolelog.h create mode 100644 crosecbus/crosecbus.man diff --git a/README.md b/README.md index 830d526..b2b7fb8 100644 --- a/README.md +++ b/README.md @@ -30,3 +30,44 @@ Protocols Implemented: Note: Framework laptop does not implement GOOG0004 ACPI device. Override DSDT/SSDT with testsigning or with OpenCore to add it. (See https://github.com/coreboot/coreboot/blob/master/src/ec/google/chromeec/acpi/cros_ec.asl for an example) Tested on HP Chromebook 14b (Ryzen 3 3250C) + +## EC console log + +The EC keeps its console output in a small ring buffer, so older output gets overwritten. +The driver copies it into the Windows Event Log so it survives reboots. + +* Channel: `Framework-CrosEcBus/Console` (Event Viewer: Applications and Services Logs > Framework-CrosEcBus > Console) +* One event per console line (event ID 1). Every time the driver loads, typically once per boot, it writes a + marker with the EC firmware version (event ID 2), then the whole current EC buffer, which includes output + from before Windows started and from the end of the previous boot. +* The log is capped at 10 MB; the oldest events are overwritten. Change the size with + `wevtutil sl Framework-CrosEcBus/Console /ms:` +* Requires Windows 10 1809 or later + +Read it as text (PowerShell): + +```powershell +# Whole log, oldest first +Get-WinEvent -LogName Framework-CrosEcBus/Console -Oldest | + ForEach-Object { "{0:yyyy-MM-dd HH:mm:ss} {1}" -f $_.TimeCreated, $_.Message } + +# Current boot only +$start = Get-WinEvent -LogName Framework-CrosEcBus/Console -FilterXPath "*[System[EventID=2]]" -MaxEvents 1 +Get-WinEvent -LogName Framework-CrosEcBus/Console -Oldest | + Where-Object TimeCreated -ge $start.TimeCreated | ForEach-Object Message + +# Save to a file +Get-WinEvent -LogName Framework-CrosEcBus/Console -Oldest | ForEach-Object Message | Set-Content ec-console.txt +``` + +Or from cmd: `wevtutil qe Framework-CrosEcBus/Console /f:text` + +Settings (DWORD values under the device's hardware key, `HKLM\SYSTEM\CurrentControlSet\Enum\\Device Parameters\Settings`, +take effect after the device is restarted): + +* `ConsoleLogEnabled`: 1 (default) to log, 0 to disable +* `ConsoleLogPollMs`: how often to read the EC console, in milliseconds (default 15000, minimum 1000) + +Note: the driver and tools such as `framework_tool --console` or `ectool console` share the same EC read +position. If you use them while logging is enabled, each side will miss some of the output. +Set `ConsoleLogEnabled` to 0 if you need those tools to see everything. diff --git a/crosecbus/consolelog.c b/crosecbus/consolelog.c new file mode 100644 index 0000000..2dc981a --- /dev/null +++ b/crosecbus/consolelog.c @@ -0,0 +1,373 @@ +#include "driver.h" +#include "comm-host.h" + +// +// Called by the mc.exe generated ETW enable callback, after the provider's +// enable bits have been updated. Must be declared before the generated header. +// +static VOID CrosEcConsoleLogEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG ControlCode, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _Inout_opt_ PVOID CallbackContext); +#define MCGEN_PRIVATE_ENABLE_CALLBACK_V2 CrosEcConsoleLogEnableCallback + +#include "crosecbusEvents.h" +#include "consolelog.tmh" + +#define CROSEC_CONSOLE_POLL_MS_DEFAULT 15000 +#define CROSEC_CONSOLE_POLL_MS_MIN 1000 +// Upper bound on read commands per poll, in case the EC keeps producing output +#define CROSEC_CONSOLE_MAX_CHUNKS 256 + +// Device to kick when a consumer (the event log service) enables the provider +static KSPIN_LOCK g_ConsoleLogDeviceLock; +static PCROSECBUS_CONTEXT g_ConsoleLogDevice; + +static EXT_CALLBACK CrosEcConsoleLogTimerCallback; +static KSTART_ROUTINE CrosEcConsoleLogThread; + +VOID CrosEcConsoleLogRegisterProvider(VOID) +{ + KeInitializeSpinLock(&g_ConsoleLogDeviceLock); + EventRegisterFramework_CrosEcBus(); +} + +VOID CrosEcConsoleLogUnregisterProvider(VOID) +{ + EventUnregisterFramework_CrosEcBus(); +} + +static VOID CrosEcConsoleLogSetDevice(_In_opt_ PCROSECBUS_CONTEXT pDevice) +{ + KIRQL oldIrql; + KeAcquireSpinLock(&g_ConsoleLogDeviceLock, &oldIrql); + g_ConsoleLogDevice = pDevice; + KeReleaseSpinLock(&g_ConsoleLogDeviceLock, oldIrql); +} + +static VOID CrosEcConsoleLogEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG ControlCode, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _Inout_opt_ PVOID CallbackContext) +{ + UNREFERENCED_PARAMETER(SourceId); + UNREFERENCED_PARAMETER(Level); + UNREFERENCED_PARAMETER(MatchAnyKeyword); + UNREFERENCED_PARAMETER(MatchAllKeyword); + UNREFERENCED_PARAMETER(FilterData); + UNREFERENCED_PARAMETER(CallbackContext); + + if (ControlCode != EVENT_CONTROL_CODE_ENABLE_PROVIDER) + return; + + // Poll right away instead of waiting for the next timer tick + KIRQL oldIrql; + KeAcquireSpinLock(&g_ConsoleLogDeviceLock, &oldIrql); + if (g_ConsoleLogDevice) { + KeSetEvent(&g_ConsoleLogDevice->ConsoleLog.PollEvent, IO_NO_INCREMENT, FALSE); + } + KeReleaseSpinLock(&g_ConsoleLogDeviceLock, oldIrql); +} + +static VOID CrosEcConsoleLogTimerCallback( + _In_ PEX_TIMER Timer, + _In_opt_ PVOID Context) +{ + UNREFERENCED_PARAMETER(Timer); + + PCROSECBUS_CONTEXT pDevice = (PCROSECBUS_CONTEXT)Context; + if (pDevice) { + KeSetEvent(&pDevice->ConsoleLog.PollEvent, IO_NO_INCREMENT, FALSE); + } +} + +// +// Like CrosEcCmdXferStatus, but returns the raw result (response size or +// negative error). Doesn't bump KernelAccessesWaiting: console logging is +// low priority and shouldn't make userspace IOCTLs return STATUS_RETRY. +// +_IRQL_requires_(PASSIVE_LEVEL) +static int CrosEcConsoleLogCommand( + _In_ PCROSECBUS_CONTEXT pDevice, + UINT16 command, + UINT8 version, + _In_reads_bytes_opt_(outsize) const void* outdata, + int outsize, + _Out_writes_bytes_opt_(insize) void* indata, + int insize) +{ + if (!ec_command_proto) { + return -EC_RES_UNAVAILABLE; + } + + WdfWaitLockAcquire(pDevice->EcLock, NULL); + int rv = ec_command_proto(command, version, outdata, outsize, indata, insize); + WdfWaitLockRelease(pDevice->EcLock); + + return rv; +} + +static VOID CrosEcConsoleLogEmitLine(_Inout_ PCROSEC_CONSOLE_LOG log) +{ + log->Line[log->LineLen] = '\0'; + EventWriteConsoleLine(NULL, log->Line); + log->LineLen = 0; +} + +// Split console output into lines. A trailing partial line is kept for later. +static VOID CrosEcConsoleLogAppend( + _Inout_ PCROSEC_CONSOLE_LOG log, + _In_reads_(len) const CHAR* data, + int len) +{ + for (int i = 0; i < len; i++) { + CHAR c = data[i]; + if (c == '\0') + break; + if (c == '\r') + continue; + if (c == '\n') { + CrosEcConsoleLogEmitLine(log); + continue; + } + + if (log->LineLen >= CROSEC_CONSOLE_LINE_MAX - 1) + CrosEcConsoleLogEmitLine(log); + log->Line[log->LineLen++] = c; + } +} + +_IRQL_requires_(PASSIVE_LEVEL) +static VOID CrosEcConsoleLogWriteStarted(_In_ PCROSECBUS_CONTEXT pDevice) +{ + struct ec_response_get_version r = { 0 }; + + int rv = CrosEcConsoleLogCommand(pDevice, EC_CMD_GET_VERSION, 0, NULL, 0, &r, sizeof(r)); + if (rv < 0) { + RtlZeroMemory(&r, sizeof(r)); + } + r.version_string_ro[sizeof(r.version_string_ro) - 1] = '\0'; + r.version_string_rw[sizeof(r.version_string_rw) - 1] = '\0'; + + EventWriteConsoleLogStarted(NULL, r.version_string_ro, r.version_string_rw); +} + +_IRQL_requires_(PASSIVE_LEVEL) +static VOID CrosEcConsoleLogPoll(_In_ PCROSECBUS_CONTEXT pDevice, BOOLEAN Final) +{ + PCROSEC_CONSOLE_LOG log = &pDevice->ConsoleLog; + + // Leave the data in the EC until someone is listening + if (!EventEnabledConsoleLine()) + return; + + int rv = CrosEcConsoleLogCommand(pDevice, EC_CMD_CONSOLE_SNAPSHOT, 0, NULL, 0, NULL, 0); + if (rv < 0) { + TraceEvents(TRACE_LEVEL_ERROR, TRACE_CONSOLELOG, "Console snapshot failed: %d\n", rv); + return; + } + + struct ec_params_console_read_v1 params = { 0 }; + if (!log->DumpedInitial) { + // First poll after load: dump the whole EC buffer, including + // output from before the OS (or before the last reboot) + CrosEcConsoleLogWriteStarted(pDevice); + params.subcmd = CONSOLE_READ_NEXT; + log->DumpedInitial = TRUE; + } + else { + params.subcmd = CONSOLE_READ_RECENT; + } + + BOOLEAN gotData = FALSE; + for (int i = 0; i < CROSEC_CONSOLE_MAX_CHUNKS; i++) { + RtlZeroMemory(log->ReadBuf, log->ReadBufSize); + rv = CrosEcConsoleLogCommand(pDevice, EC_CMD_CONSOLE_READ, 1, ¶ms, sizeof(params), + log->ReadBuf, (int)log->ReadBufSize); + if (rv < 0) { + TraceEvents(TRACE_LEVEL_ERROR, TRACE_CONSOLELOG, "Console read failed: %d\n", rv); + break; + } + // Empty string means no more output + if (rv == 0 || log->ReadBuf[0] == '\0') + break; + + gotData = TRUE; + CrosEcConsoleLogAppend(log, log->ReadBuf, min(rv, (int)log->ReadBufSize)); + } + + // Don't hold back a partial line (e.g. a prompt) for more than one poll + if (log->LineLen > 0 && (Final || !gotData)) + CrosEcConsoleLogEmitLine(log); +} + +static VOID CrosEcConsoleLogThread(_In_ PVOID Context) +{ + PCROSECBUS_CONTEXT pDevice = (PCROSECBUS_CONTEXT)Context; + PCROSEC_CONSOLE_LOG log = &pDevice->ConsoleLog; + PVOID waitObjects[2] = { &log->StopEvent, &log->PollEvent }; + + for (;;) { + NTSTATUS status = KeWaitForMultipleObjects(ARRAYSIZE(waitObjects), waitObjects, WaitAny, + Executive, KernelMode, FALSE, NULL, NULL); + BOOLEAN stop = (status == STATUS_WAIT_0); + + // Read one last time when stopping + CrosEcConsoleLogPoll(pDevice, stop); + + if (stop) + break; + } + + PsTerminateSystemThread(STATUS_SUCCESS); +} + +_IRQL_requires_(PASSIVE_LEVEL) +static ULONG CrosEcConsoleLogQuerySetting(_In_opt_ WDFKEY key, _In_ PCWSTR name, ULONG defaultValue) +{ + if (!key) + return defaultValue; + + UNICODE_STRING valueName; + RtlInitUnicodeString(&valueName, name); + + ULONG value; + if (NT_SUCCESS(WdfRegistryQueryULong(key, &valueName, &value))) + return value; + return defaultValue; +} + +_IRQL_requires_(PASSIVE_LEVEL) +NTSTATUS CrosEcConsoleLogStart(_In_ PCROSECBUS_CONTEXT pDevice) +{ + PCROSEC_CONSOLE_LOG log = &pDevice->ConsoleLog; + NTSTATUS status; + + PAGED_CODE(); + + // Settings live in HKR\Settings of the device's hardware key + WDFKEY deviceKey = NULL; + WDFKEY settingsKey = NULL; + status = WdfDeviceOpenRegistryKey(pDevice->FxDevice, PLUGPLAY_REGKEY_DEVICE, KEY_READ, + WDF_NO_OBJECT_ATTRIBUTES, &deviceKey); + if (NT_SUCCESS(status)) { + DECLARE_CONST_UNICODE_STRING(settingsName, L"Settings"); + status = WdfRegistryOpenKey(deviceKey, &settingsName, KEY_READ, WDF_NO_OBJECT_ATTRIBUTES, &settingsKey); + if (!NT_SUCCESS(status)) + settingsKey = NULL; + } + + ULONG enabled = CrosEcConsoleLogQuerySetting(settingsKey, L"ConsoleLogEnabled", 1); + log->PollMs = CrosEcConsoleLogQuerySetting(settingsKey, L"ConsoleLogPollMs", CROSEC_CONSOLE_POLL_MS_DEFAULT); + if (log->PollMs < CROSEC_CONSOLE_POLL_MS_MIN) + log->PollMs = CROSEC_CONSOLE_POLL_MS_MIN; + + if (settingsKey) + WdfRegistryClose(settingsKey); + if (deviceKey) + WdfRegistryClose(deviceKey); + + if (!enabled) { + TraceEvents(TRACE_LEVEL_INFORMATION, TRACE_CONSOLELOG, "EC console logging disabled\n"); + return STATUS_SUCCESS; + } + + if (!ec_command_proto || ec_max_insize == 0) + return STATUS_NOINTERFACE; + + log->ReadBufSize = ec_max_insize; + log->ReadBuf = (PCHAR)ExAllocatePool2(POOL_FLAG_NON_PAGED, log->ReadBufSize, CROSECBUS_POOL_TAG); + if (!log->ReadBuf) + return STATUS_NO_MEMORY; + + log->DumpedInitial = FALSE; + log->LineLen = 0; + KeInitializeEvent(&log->StopEvent, NotificationEvent, FALSE); + // Start signaled so the thread polls once right away + KeInitializeEvent(&log->PollEvent, SynchronizationEvent, TRUE); + + OBJECT_ATTRIBUTES threadAttributes; + InitializeObjectAttributes(&threadAttributes, NULL, OBJ_KERNEL_HANDLE, NULL, NULL); + + HANDLE threadHandle; + status = PsCreateSystemThread(&threadHandle, THREAD_ALL_ACCESS, &threadAttributes, NULL, NULL, + CrosEcConsoleLogThread, pDevice); + if (!NT_SUCCESS(status)) { + TraceEvents(TRACE_LEVEL_ERROR, TRACE_CONSOLELOG, "PsCreateSystemThread failed %!STATUS!", status); + ExFreePoolWithTag(log->ReadBuf, CROSECBUS_POOL_TAG); + log->ReadBuf = NULL; + return status; + } + + status = ObReferenceObjectByHandle(threadHandle, THREAD_ALL_ACCESS, *PsThreadType, KernelMode, + (PVOID*)&log->Thread, NULL); + if (!NT_SUCCESS(status)) { + // Can't track the thread; stop it and wait for it before giving up + KeSetEvent(&log->StopEvent, IO_NO_INCREMENT, FALSE); + ZwWaitForSingleObject(threadHandle, FALSE, NULL); + ZwClose(threadHandle); + log->Thread = NULL; + ExFreePoolWithTag(log->ReadBuf, CROSECBUS_POOL_TAG); + log->ReadBuf = NULL; + return status; + } + ZwClose(threadHandle); + + // No-wake timer: doesn't wake the system from Modern Standby, fires on + // the next wake instead + log->Timer = ExAllocateTimer(CrosEcConsoleLogTimerCallback, pDevice, EX_TIMER_NO_WAKE); + if (log->Timer) { + EXT_SET_PARAMETERS timerParams; + ExInitializeSetTimerParameters(&timerParams); + timerParams.NoWakeTolerance = EX_TIMER_UNLIMITED_TOLERANCE; + + LONGLONG period = (LONGLONG)log->PollMs * 10000; // 100ns units + ExSetTimer(log->Timer, -period, period, &timerParams); + } + else { + TraceEvents(TRACE_LEVEL_ERROR, TRACE_CONSOLELOG, "ExAllocateTimer failed, not polling periodically\n"); + } + + CrosEcConsoleLogSetDevice(pDevice); + + TraceEvents(TRACE_LEVEL_INFORMATION, TRACE_CONSOLELOG, "EC console logging started, polling every %u ms\n", + log->PollMs); + + return STATUS_SUCCESS; +} + +_IRQL_requires_(PASSIVE_LEVEL) +VOID CrosEcConsoleLogStop(_In_ PCROSECBUS_CONTEXT pDevice) +{ + PCROSEC_CONSOLE_LOG log = &pDevice->ConsoleLog; + + PAGED_CODE(); + + CrosEcConsoleLogSetDevice(NULL); + + if (log->Timer) { + // Cancel and wait for a running callback to finish + ExDeleteTimer(log->Timer, TRUE, TRUE, NULL); + log->Timer = NULL; + } + + if (log->Thread) { + KeSetEvent(&log->StopEvent, IO_NO_INCREMENT, FALSE); + KeWaitForSingleObject(log->Thread, Executive, KernelMode, FALSE, NULL); + ObDereferenceObject(log->Thread); + log->Thread = NULL; + } + + if (log->ReadBuf) { + ExFreePoolWithTag(log->ReadBuf, CROSECBUS_POOL_TAG); + log->ReadBuf = NULL; + } +} diff --git a/crosecbus/consolelog.h b/crosecbus/consolelog.h new file mode 100644 index 0000000..fbd00a3 --- /dev/null +++ b/crosecbus/consolelog.h @@ -0,0 +1,35 @@ +#pragma once + +// +// EC console logger: periodically reads the EC console ring buffer and writes +// each line as an event to the Framework-CrosEcBus/Console event log channel. +// + +#define CROSEC_CONSOLE_LINE_MAX 512 + +typedef struct _CROSEC_CONSOLE_LOG { + PETHREAD Thread; + KEVENT StopEvent; + KEVENT PollEvent; + PEX_TIMER Timer; + ULONG PollMs; + + BOOLEAN DumpedInitial; + + PCHAR ReadBuf; + ULONG ReadBufSize; + + CHAR Line[CROSEC_CONSOLE_LINE_MAX]; + ULONG LineLen; +} CROSEC_CONSOLE_LOG, *PCROSEC_CONSOLE_LOG; + +struct _CROSECBUS_CONTEXT; + +VOID CrosEcConsoleLogRegisterProvider(VOID); +VOID CrosEcConsoleLogUnregisterProvider(VOID); + +_IRQL_requires_(PASSIVE_LEVEL) +NTSTATUS CrosEcConsoleLogStart(_In_ struct _CROSECBUS_CONTEXT* pDevice); + +_IRQL_requires_(PASSIVE_LEVEL) +VOID CrosEcConsoleLogStop(_In_ struct _CROSECBUS_CONTEXT* pDevice); diff --git a/crosecbus/crosecbus.c b/crosecbus/crosecbus.c index b203836..e999704 100644 --- a/crosecbus/crosecbus.c +++ b/crosecbus/crosecbus.c @@ -35,7 +35,10 @@ __in PUNICODE_STRING RegistryPath WPP_INIT_TRACING(DriverObject, RegistryPath); TraceEvents(TRACE_LEVEL_INFORMATION, TRACE_CROSECBUS, "DriverEntry: Entry"); + CrosEcConsoleLogRegisterProvider(); + WDF_DRIVER_CONFIG_INIT(&config, CrosEcBusEvtDeviceAdd); + config.EvtDriverUnload = CrosEcBusDriverUnload; WDF_OBJECT_ATTRIBUTES_INIT(&attributes); @@ -53,12 +56,22 @@ __in PUNICODE_STRING RegistryPath if (!NT_SUCCESS(status)) { TraceEvents(TRACE_LEVEL_ERROR, TRACE_CROSECBUS, "WdfDriverCreate failed %!STATUS!", status); + CrosEcConsoleLogUnregisterProvider(); WPP_CLEANUP(DriverObject); } return status; } +VOID +CrosEcBusDriverUnload( + _In_ WDFDRIVER Driver +) +{ + CrosEcConsoleLogUnregisterProvider(); + WPP_CLEANUP(WdfDriverWdmGetDriverObject(Driver)); +} + static NTSTATUS CrosEcCmdXferStatus( IN PCROSECBUS_CONTEXT pDevice, OUT PCROSEC_COMMAND Msg @@ -286,6 +299,12 @@ Status // TraceEvents(TRACE_LEVEL_INFORMATION, TRACE_CROSECBUS, "Warning: Failed to get ACPI device\n"); // } + // Failure to start console logging is not fatal + NTSTATUS consoleLogStatus = CrosEcConsoleLogStart(pDevice); + if (!NT_SUCCESS(consoleLogStatus)) { + TraceEvents(TRACE_LEVEL_ERROR, TRACE_CROSECBUS, "Failed to start EC console logging %!STATUS!", consoleLogStatus); + } + TraceEvents(TRACE_LEVEL_INFORMATION, TRACE_CROSECBUS, "OnPrepareHardware finished %!STATUS!", status); return status; @@ -349,6 +368,9 @@ Status PCROSECBUS_CONTEXT pDevice = GetDeviceContext(FxDevice); UNREFERENCED_PARAMETER(FxResourcesTranslated); + // Stop (and do a final read) before the EC lock goes away + CrosEcConsoleLogStop(pDevice); + if (pDevice->S0ixNotifyAcpiInterface.Context) { //Used for S0ix notifications pDevice->S0ixNotifyAcpiInterface.UnregisterForDeviceNotifications(pDevice->S0ixNotifyAcpiInterface.Context); } diff --git a/crosecbus/crosecbus.inf b/crosecbus/crosecbus.inf index e16de6b..bdc573c 100644 --- a/crosecbus/crosecbus.inf +++ b/crosecbus/crosecbus.inf @@ -36,9 +36,9 @@ crosecbus.sys = 1,, ;***************************************** [Manufacturer] -%StdMfg%=Standard,NT$ARCH$.10.0...16299 +%StdMfg%=Standard,NT$ARCH$.10.0...17763 -[Standard.NT$ARCH$.10.0...16299] +[Standard.NT$ARCH$.10.0...17763] %CrosEcBus.DeviceDesc%=CrosEcBus_Device, ACPI\FRMWC004 [CrosEcBus_Device.NT] @@ -53,12 +53,32 @@ crosecbus.sys [CrosEcBus_AddReg] ; Set to 1 to connect the first interrupt resource found, 0 to leave disconnected HKR,Settings,"ConnectInterrupt",0x00010001,0 +; EC console log to the Framework-CrosEcBus/Console event log channel +HKR,Settings,"ConsoleLogEnabled",0x00010001,1 +HKR,Settings,"ConsoleLogPollMs",0x00010001,15000 HKR,,Security,,"D:P(A;;GA;;;SY)(A;;GA;;;BA)(A;;GA;;;UD)" ;System, Admin, and UMDF drivers ;-------------- Service installation [CrosEcBus_Device.NT.Services] AddService = CrosEcBus,%SPSVCINST_ASSOCSERVICE%, CrosEcBus_Service_Inst +; -------------- Event log provider and channel +; Must match the provider GUID, channel name and channel value in crosecbus.man +[CrosEcBus_Device.NT.Events] +AddEventProvider = {265d94cd-c9ff-4cac-8f4f-28f037e32f68}, CrosEcBus_EventProvider + +[CrosEcBus_EventProvider] +ProviderName = Framework-CrosEcBus +ResourceFile = %13%\crosecbus.sys +MessageFile = %13%\crosecbus.sys +AddChannel = Framework-CrosEcBus/Console, 0x2, CrosEcBus_ConsoleChannel ; Operational + +[CrosEcBus_ConsoleChannel] +Enabled = 1 +Value = 16 +LoggingMaxSize = 10485760 ; 10 MB +LoggingRetention = 1 ; Circular, overwrite oldest events + ; -------------- WDF install section [CrosEcBus_Device.NT.Wdf] KmdfService = CrosEcBus, CrosEcBus_wdfsect diff --git a/crosecbus/crosecbus.man b/crosecbus/crosecbus.man new file mode 100644 index 0000000..3ffff3f --- /dev/null +++ b/crosecbus/crosecbus.man @@ -0,0 +1,94 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/crosecbus/crosecbus.rc b/crosecbus/crosecbus.rc index bc5b690..4116114 100644 --- a/crosecbus/crosecbus.rc +++ b/crosecbus/crosecbus.rc @@ -39,3 +39,6 @@ Abstract: #define VER_PRODUCTNAME_STR "Framework EC" #include "common.ver" + +// Event manifest resources, generated by mc.exe from crosecbus.man +#include "crosecbusEvents.rc" diff --git a/crosecbus/crosecbus.vcxproj b/crosecbus/crosecbus.vcxproj index 32f8880..960341a 100644 --- a/crosecbus/crosecbus.vcxproj +++ b/crosecbus/crosecbus.vcxproj @@ -87,6 +87,9 @@ true true + + %(AdditionalIncludeDirectories);$(IntDir) + 0.0.8.0 @@ -102,6 +105,9 @@ true true + + %(AdditionalIncludeDirectories);$(IntDir) + 0.0.8.0 @@ -117,6 +123,9 @@ true true + + %(AdditionalIncludeDirectories);$(IntDir) + 0.0.8.0 @@ -132,6 +141,9 @@ true true + + %(AdditionalIncludeDirectories);$(IntDir) + 0.0.8.0 @@ -148,6 +160,7 @@ + @@ -158,12 +171,25 @@ + + + + true + .\$(IntDir) + true + "$(SDK_INC_PATH)\winmeta.xml" + .\$(IntDir) + true + crosecbusEvents + true + + diff --git a/crosecbus/driver.h b/crosecbus/driver.h index e479dbe..f441509 100644 --- a/crosecbus/driver.h +++ b/crosecbus/driver.h @@ -20,6 +20,7 @@ #include #include "trace.h" +#include "consolelog.h" // // String definitions @@ -131,6 +132,8 @@ typedef struct _CROSECBUS_CONTEXT BOOLEAN isInS0ix; BOOLEAN hostSleepV1; + CROSEC_CONSOLE_LOG ConsoleLog; + } CROSECBUS_CONTEXT, *PCROSECBUS_CONTEXT; WDF_DECLARE_CONTEXT_TYPE_WITH_NAME(CROSECBUS_CONTEXT, GetDeviceContext) diff --git a/crosecbus/ec_commands.h b/crosecbus/ec_commands.h index 03f09c0..32ff1ce 100644 --- a/crosecbus/ec_commands.h +++ b/crosecbus/ec_commands.h @@ -2243,4 +2243,37 @@ enum ec_host_event_mask_type { #define EC_CMD_HOST_EVENT 0x00A4 +/*****************************************************************************/ +/* EC console commands */ + +/* Save a snapshot of the EC console output buffer (no params, no response) */ +#define EC_CMD_CONSOLE_SNAPSHOT 0x0097 + +/* + * Read data from the saved snapshot. If the subcmd parameter is + * CONSOLE_READ_NEXT, this will return data starting from the beginning of + * the latest snapshot. If it is CONSOLE_READ_RECENT, it will start from the + * end of the previous snapshot. + * + * The params are only looked at in version >= 1 of this command. Prior + * versions will just default to CONSOLE_READ_NEXT behavior. + * + * Response is null-terminated string. Empty string, if there is no more + * remaining output. + */ +#define EC_CMD_CONSOLE_READ 0x0098 + +enum ec_console_read_subcmd { + CONSOLE_READ_NEXT = 0, + CONSOLE_READ_RECENT +}; + +#include + +struct ec_params_console_read_v1 { + UINT8 subcmd; /* enum ec_console_read_subcmd */ +}; + +#include + #endif /* __CROS_EC_COMMANDS_H */ diff --git a/crosecbus/trace.h b/crosecbus/trace.h index 89643a7..8dfb7b1 100644 --- a/crosecbus/trace.h +++ b/crosecbus/trace.h @@ -18,6 +18,7 @@ WPP_DEFINE_BIT(TRACE_COMM_LPC) \ WPP_DEFINE_BIT(TRACE_COMM_MEC_LPC) \ WPP_DEFINE_BIT(TRACE_USERSPACEQUEUE) \ + WPP_DEFINE_BIT(TRACE_CONSOLELOG) \ ) #define WPP_FLAG_LEVEL_LOGGER(flag, level) WPP_LEVEL_LOGGER(flag) From ac60a86e2570d7df842a28a924bf7ffab985eade Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Wed, 23 Sep 2026 18:49:23 +0200 Subject: [PATCH 2/7] msbuild: define architecture x64 Newer WDKs only ship x64 InfVerif.dll, which 32-bit MSBuild can't load > INF verification exception: Unable to load DLL 'x86\InfVerif.dll': > The specified module could not be found Signed-off-by: Daniel Schaefer --- .github/workflows/ci.yml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ba3bd67..76a2c8f 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -15,6 +15,8 @@ jobs: - name: Add MSBuild to PATH uses: microsoft/setup-msbuild@v2 + with: + msbuild-architecture: x64 - name: Build solution run: | From ebb248070222f4395ae40bad4a4af17189238f5d Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Wed, 23 Sep 2026 18:50:18 +0200 Subject: [PATCH 3/7] Declare ZwWaitForSingleObject Signed-off-by: Daniel Schaefer --- crosecbus/consolelog.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/crosecbus/consolelog.c b/crosecbus/consolelog.c index 2dc981a..8662e95 100644 --- a/crosecbus/consolelog.c +++ b/crosecbus/consolelog.c @@ -18,6 +18,12 @@ static VOID CrosEcConsoleLogEnableCallback( #include "crosecbusEvents.h" #include "consolelog.tmh" +// Declared in ntifs.h, which can't be included alongside wdm.h +NTSYSAPI NTSTATUS NTAPI ZwWaitForSingleObject( + _In_ HANDLE Handle, + _In_ BOOLEAN Alertable, + _In_opt_ PLARGE_INTEGER Timeout); + #define CROSEC_CONSOLE_POLL_MS_DEFAULT 15000 #define CROSEC_CONSOLE_POLL_MS_MIN 1000 // Upper bound on read commands per poll, in case the EC keeps producing output From 80f88e1bb70a98e6488391443b52647b5bd606a8 Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Fri, 2 Oct 2026 15:59:08 -0700 Subject: [PATCH 4/7] Use System isolation for the EC console channel The channel defaulted to Application isolation, which is served by the EventLog-Application session. That session never received events from the kernel-mode provider, so the driver saw the provider as disabled, never read the EC console, and the log stayed empty. Kernel-mode providers need System isolation (EventLog-System session), like the in-box kernel driver channels. Signed-off-by: Daniel Schaefer --- crosecbus/crosecbus.inf | 3 +++ crosecbus/crosecbus.man | 1 + 2 files changed, 4 insertions(+) diff --git a/crosecbus/crosecbus.inf b/crosecbus/crosecbus.inf index bdc573c..b679a73 100644 --- a/crosecbus/crosecbus.inf +++ b/crosecbus/crosecbus.inf @@ -74,6 +74,9 @@ MessageFile = %13%\crosecbus.sys AddChannel = Framework-CrosEcBus/Console, 0x2, CrosEcBus_ConsoleChannel ; Operational [CrosEcBus_ConsoleChannel] +; Kernel-mode providers need System isolation (EventLog-System session). +; With the default Application isolation no events reach the log. +Isolation = 2 ; System Enabled = 1 Value = 16 LoggingMaxSize = 10485760 ; 10 MB diff --git a/crosecbus/crosecbus.man b/crosecbus/crosecbus.man index 3ffff3f..3b873da 100644 --- a/crosecbus/crosecbus.man +++ b/crosecbus/crosecbus.man @@ -30,6 +30,7 @@ Date: Fri, 2 Oct 2026 15:59:28 -0700 Subject: [PATCH 5/7] README: Add EC console log troubleshooting Document how to check that the right driver build is installed, that the event provider and channel are registered and enabled, and that the Event Log service is listening. Also how to capture and decode the WPP trace (with or without the WDK), and how to record the provider's events in a private session to rule out the channel configuration. Co-Authored-By: Claude Opus 5.5 Signed-off-by: Daniel Schaefer --- README.md | 82 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 82 insertions(+) diff --git a/README.md b/README.md index b2b7fb8..d1d61b4 100644 --- a/README.md +++ b/README.md @@ -71,3 +71,85 @@ take effect after the device is restarted): Note: the driver and tools such as `framework_tool --console` or `ectool console` share the same EC read position. If you use them while logging is enabled, each side will miss some of the output. Set `ConsoleLogEnabled` to 0 if you need those tools to see everything. + +### Troubleshooting the EC console log + +The version number alone doesn't tell builds apart. To check that the installed driver is the one you built, +compare hashes: + +```powershell +$dev = Get-PnpDevice -InstanceId 'ACPI\FRMWC004*' +Get-PnpDeviceProperty -InstanceId $dev.InstanceId -KeyName DEVPKEY_Device_DriverInfPath, DEVPKEY_Device_DriverVersion, DEVPKEY_Device_DriverDate +(Get-CimInstance Win32_SystemDriver -Filter "Name='CrosEcBus'").PathName # the .sys that is running +Get-FileHash , \crosecbus.sys # should match +``` + +Check each link in the chain: + +```powershell +# 1. Provider registered (only exists if the INF's Events section was installed) +wevtutil gp Framework-CrosEcBus + +# 2. Channel exists, is enabled ("enabled: true") and has "isolation: System" +wevtutil gl Framework-CrosEcBus/Console +# If it says false: wevtutil sl Framework-CrosEcBus/Console /e:true +# If it says "isolation: Application" (installed by an older build of this branch), events from +# the driver never reach the log. Fix it without reinstalling: +# Set-ItemProperty 'HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\WINEVT\Channels\Framework-CrosEcBus/Console' Isolation 1 +# wevtutil sl Framework-CrosEcBus/Console /e:false; wevtutil sl Framework-CrosEcBus/Console /e:true +# (The registry uses 1 for System; the INF's Isolation directive uses 2.) + +# 3. Number of events in the log ("numberOfLogRecords") +wevtutil gli Framework-CrosEcBus/Console + +# 4. The Event Log service is listening to the driver. The driver only reads the +# EC console while this is true, so the data isn't consumed when nobody records it. +# Expect "Framework-CrosEcBus" with KeywordsAny 0x8000000000000000. +logman query EventLog-System -ets | Select-String -Context 0,4 CrosEcBus + +# 5. The driver has the provider registered (a row with PID 0x00000000 = kernel) +logman query providers Framework-CrosEcBus + +# 6. Settings: ConsoleLogEnabled should be 1 +Get-ItemProperty "HKLM:\SYSTEM\CurrentControlSet\Enum\$((Get-PnpDevice -InstanceId 'ACPI\FRMWC004*').InstanceId)\Device Parameters\Settings" +``` + +The driver writes event ID 2 on the first poll after it starts, even if the EC buffer is empty. If the log +stays empty for more than one poll interval, capture the driver's WPP trace (as admin) while restarting the device: + +```powershell +logman create trace CrosEcBusWpp -p '{73e3b785-f5fb-423e-94a9-56627fea9053}' 0xFFFFFFFF 0xFF -o crosecbus.etl -ets +pnputil /restart-device "ACPI\FRMWC004\1" +# wait at least one poll interval +logman stop CrosEcBusWpp -ets +``` + +Decoding needs the TMF format strings from the matching `crosecbus.pdb` (CI uploads it next to the `.sys`). +With the WDK: `tracepdb -f crosecbus.pdb -p tmf`, then `tracefmt crosecbus.etl -p tmf -o crosecbus.txt`. +Without the WDK, pull them out of the PDB and decode with the built-in `tracerpt`: + +```powershell +New-Item -ItemType Directory -Force tmf | Out-Null +$s = [Text.Encoding]::ASCII.GetString([IO.File]::ReadAllBytes("$PWD\crosecbus.pdb")) +foreach ($r in [regex]::Matches($s, 'TMF:\x00((?:[^\x00]+\x00)+?)\x00')) { + $lines = $r.Groups[1].Value.TrimEnd([char]0).Split([char]0) + Add-Content -Path "tmf\$($lines[0].Split(' ')[0]).tmf" -Value ($lines -join "`r`n") -Encoding ASCII +} +tracerpt crosecbus.etl -o crosecbus.csv -of CSV -tp tmf -y +``` + +To tell whether the driver writes events at all, independent of the Event Log service, record the provider +in a session of your own. Starting it also makes the driver poll right away: + +```powershell +logman create trace CrosEcBusEvents -p Framework-CrosEcBus 0xFFFFFFFFFFFFFFFF 0xFF -o events.etl -ets +# wait a few seconds +logman stop CrosEcBusEvents -ets +Get-WinEvent -Path events.etl -Oldest | Select-Object TimeCreated, Id, Message +``` + +If events show up here but not in the channel, the problem is the channel configuration (see step 2). + +Messages from the console logger to look for: `EC console logging started, polling every N ms`, +`EC console logging disabled`, `Failed to start EC console logging`, `Console snapshot failed` and +`Console read failed`. From 7fc1e77db918aaa6630d34d80007d3c2ec887baf Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Fri, 2 Oct 2026 16:00:05 -0700 Subject: [PATCH 6/7] bump version to 0.0.9.0 Signed-off-by: Daniel Schaefer --- crosecbus/crosecbus.inf | 2 +- crosecbus/crosecbus.rc | 8 ++++---- crosecbus/crosecbus.vcxproj | 8 ++++---- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/crosecbus/crosecbus.inf b/crosecbus/crosecbus.inf index b679a73..5691dec 100644 --- a/crosecbus/crosecbus.inf +++ b/crosecbus/crosecbus.inf @@ -16,7 +16,7 @@ Signature = "$WINDOWS NT$" Class = System ClassGuid = {4d36e97d-e325-11ce-bfc1-08002be10318} Provider = Framework Computer -DriverVer = 10/24/2024,0.0.8.0 +DriverVer = 10/24/2024,0.0.9.0 CatalogFile = crosecbus.cat PnpLockdown = 1 diff --git a/crosecbus/crosecbus.rc b/crosecbus/crosecbus.rc index 4116114..a5c3e09 100644 --- a/crosecbus/crosecbus.rc +++ b/crosecbus/crosecbus.rc @@ -21,10 +21,10 @@ Abstract: #define VER_LEGALCOPYRIGHT_YEARS "2023-2025" #define VER_LEGALCOPYRIGHT_STR "Copyright (C) " VER_LEGALCOPYRIGHT_YEARS " CoolStar, Framework Computer Inc." -#define VER_FILEVERSION 0,0,8,0 -#define VER_PRODUCTVERSION_STR "0.0.8.0" -#define VER_PRODUCTVERSION 0,0,8,0 -#define LVER_PRODUCTVERSION_STR L"0.0.8.0" +#define VER_FILEVERSION 0,0,9,0 +#define VER_PRODUCTVERSION_STR "0.0.9.0" +#define VER_PRODUCTVERSION 0,0,9,0 +#define LVER_PRODUCTVERSION_STR L"0.0.9.0" #define VER_FILEFLAGSMASK (VS_FF_DEBUG | VS_FF_PRERELEASE) #ifdef DEBUG diff --git a/crosecbus/crosecbus.vcxproj b/crosecbus/crosecbus.vcxproj index 960341a..df0ed6f 100644 --- a/crosecbus/crosecbus.vcxproj +++ b/crosecbus/crosecbus.vcxproj @@ -91,7 +91,7 @@ %(AdditionalIncludeDirectories);$(IntDir) - 0.0.8.0 + 0.0.9.0 SHA256 @@ -109,7 +109,7 @@ %(AdditionalIncludeDirectories);$(IntDir) - 0.0.8.0 + 0.0.9.0 SHA256 @@ -127,7 +127,7 @@ %(AdditionalIncludeDirectories);$(IntDir) - 0.0.8.0 + 0.0.9.0 SHA256 @@ -145,7 +145,7 @@ %(AdditionalIncludeDirectories);$(IntDir) - 0.0.8.0 + 0.0.9.0 SHA256 From 2a7c2239d0c53f4a029d957f7e8701f552baaeb9 Mon Sep 17 00:00:00 2001 From: Daniel Schaefer Date: Fri, 2 Oct 2026 16:07:10 -0700 Subject: [PATCH 7/7] include commit hash in upload file Signed-off-by: Daniel Schaefer --- .github/workflows/ci.yml | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 76a2c8f..85db807 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -44,8 +44,13 @@ jobs: Configuration: ${{ matrix.configuration }} Platform: ${{ matrix.platform }} + - name: Get short commit hash + id: commit + run: | + "short_sha=$(git rev-parse --short HEAD)" >> $env:GITHUB_OUTPUT + - name: Upload bundle uses: actions/upload-artifact@v4 with: - name: crosecbus_${{ matrix.configuration }} + name: crosecbus_${{ matrix.configuration }}_${{ steps.commit.outputs.short_sha }} path: bundle