Who is writing "Event ID 0" events to the application log?, Venkatesh blogging here again. Recently I had a collaboration request to determine which mystery component was writing to the application event log. This was the event- Event Type: ErrorEvent Source: ODBCEvent Category: NoneEvent ID: 0Date: 5/12/2009Time: 2:13:19 PMUser: N/AComputer: TX163611Description:The description for Event ID ( 0 ) in Source ( ODBC ) cannot be found. The local computer may not have the necessary registry information or message DLL files to display messages from a remote computer. You may be able to use the /AUXSOURCE= flag to retrieve this description; see Help and Support for details. The following information is part of the event: Failed to enlist in DTC: SQL state 42000, native error 8509, error message [Microsoft][ODBC SQL Server Driver][SQL Server]Import of Microsoft Distributed Transaction Coordinator (MS DTC) transaction failed: 0x8004d00e(XACT_E_NOTRANSACTION)..The external partner's machine was flooded with this event in the event log. To reproduce the problem in-house, our Developer Support team wrote a small test app to repro the issue locally. Unfortunately the issue reproduced only when we single stepped through the test app in Visual Studio, but it would work in a pinch. The test application was not writing this event but we suspected one of the background services from the application talked to MSDTC.exe or SQLServer.exe, and it may be writing this event. We know that applications use Win32 API ReportEvent (part of Advapi32.dll) to write events into event logs. Advapi32 makes a Local RPC call to the Event Log Service running in Services.exe process. It’s the Event Log service that actually writes events to the log files. We can verify this using procmon which should show services.exe writing into the event log files. So I setup the machine for the kernel debug. Since I didn’t know who was writing to the application log, I needed to set a break point at the server side. I set a break point on EventLog!ElfReportEventW in the Services.exe process using "!bpid < PID>" (more info on !bpid can be found in debugger help). EventLog!ElfReportEventW is the server side of the RPC to Advapi32!ReportEventW call.First I got the PID of services.exe process: kd> !process 0 0 services.exePROCESS 8d9aa020 SessionId: 0 Cid: 01ac Peb: 7ffde000 ParentCid: 017c DirBase: 3549e080 ObjectTable: e151e698 HandleCount: 355. Image: services.exeNext I used !bpid <PID> to set the context of the breakpoint in services.exe process: kd> !bpid 01ac Finding winlogon.exe (0)...Waiting for winlogon.exe to break. This can take a couple of minutes...Break instruction exception - code 80000003 (first chance)Stepping to g_BreakinProcessId check...Break into process 1ac set. The next break should be in the desired process.Break instruction exception - code 80000003 (first chance)ntdll!DbgBreakPoint
7c81a3e1 cc int 3 Then I verified the current process was services.exe by using the -1 flag. Since we see Services.exe in the output below, we know the !bpid command broke into the correct process.kd> !process -1 0PROCESS 8d9aa020 SessionId: 0 Cid: 01ac Peb: 7ffde000 ParentCid: 017c DirBase: 3549e080 ObjectTable: e151e698 HandleCount: 355. Image: services.exeThis is how I loaded the user mode symbols to set the break point in Eventlog.dll kd> .process /p /r 8d9aa020 Implicit process is now 8d9aa020.cache forcedecodeuser doneLoading User Symbols......................Here I'm setting the eventlog!ElfrReportEventW break point: kd> x eventlog!*Reportevent*7575b18f eventlog!ElfrReportEventAndSourceW = <no type information>75753324 eventlog!ElfIntReportEvent = <no type information>7575372e eventlog!ElfrReportEventW = <no type information>75753a07 eventlog!ElfrReportEventA = <no type information>kd> bp 7575372ekd>With the debugger ready, I single stepped through the test app in Visual Studio to repro the problem. The break point EventLog!ElfReportEventW hit in the services.exe process. Using the LPC message I was able to determine the client of the RPC call which turned out to be the test app. kd> gBreakpoint 0 hiteventlog!ElfrReportEventW
7575372e 8bff mov edi,ediHere I looked at the current thread to see the call stack:kd> !threadTHREAD 8e0413d0 Cid 01ac.0694 Teb: 7ffa6000 Win32Thread: 00000000 RUNNING on processor 0Not impersonatingDeviceMap e1000128Owning Process 8d9aa020 Image: services.exeAttached Process N/A Image: N/AWait Start TickCount 75870 Ticks: 0Context Switch Count 2754 UserTime 00:00:00.281KernelTime 00:00:01.968Win32 Start Address 0x0006e72dLPC Server thread working on message Id 6e72dStart Address kernel32!BaseThreadStartThunk (0x77e617ec)Stack Init f5d87000 Current f5d86c24 Base f5d87000 Limit f5d84000 Call 0Priority 10 BasePriority 9 PriorityDecrement 0ChildEBP RetAddr Args to Child 0129f8ac 77c80193 01021fe8 4a09ca4f 00000001 eventlog!ElfrReportEventW (FPO: [14,0,0])0129f8f8 77ce33e1 7575372e 0129fae0 0000000e RPCRT4!Invoke+0x300129fcf8 77ce35c4 00000000 00000000 000d7c2c RPCRT4!NdrStubCall2+0x299 (FPO: [SEH])0129fd14 77c7ff7a 000d7c2c 000b6e78 000d7c2c RPCRT4!NdrServerCall2+0x19 (FPO: [1,1,0])0129fd48 77c8042d 75751b51 000d7c2c 0129fdec RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [SEH])0129fd9c 77c80353 0000000b 00000000 75760050 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x11f (FPO: [4,13,4])0129fdc0 77c811dc 000d7c2c 00000000 75760050 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [4,0,4])0129fdfc 77c812f0 000d79c0 000a1028 000ce2c0 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0x42c (FPO: [0,6,4])0129fe20 77c88678 000a1060 0129fe38 000d79c0 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0x127 (FPO: [4,4,4])0129ff84 77c88792 0129ffac 77c8872d 000a1028 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x430 (FPO: [0,14,0])0129ff8c 77c8872d 000a1028 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd (FPO: [1,0,0])0129ffac 77c7b110 0009f4c0 0129ffec 77e6482f RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [1,2,4])0129ffb8 77e6482f 000ccb58 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [1,0,0])0129ffec 00000000 77c7b0f5 000ccb58 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH]) From the !thread output, we know the thread above is working on LPC message 6e72d. We can use !lpc command to get the client thread: kd> !lpc message 6e72dSearching message 6e72d in threads ... Server thread 8e0413d0 is working on message 6e72d Client thread 8da33220 waiting a reply from 6e72d Searching thread 8da33220 in port rundown queues ... Server communication port 0xe2875380 Handles: 1 References: 1 The LpcDataInfoChainHead queue is empty Connected port: 0xe23cedd0 Server connection port: 0xe1ceb2b0 Client communication port 0xe23cedd0 Handles: 1 References: 2 The LpcDataInfoChainHead queue is empty Server connection port e1ceb2b0 Name: ntsvcs Handles: 1 References: 129 Server process : 8d9aa020 (services.exe) Queue semaphore : 8db981a0 Semaphore state 0 (0x0) The message queue is empty Messages in LpcDataInfoChainHead: 0000 e22aa008 - Busy Id=0006e72d From: 0f60.0db4 Context=80680017 [e1ceb330 . e1ceb330] Length=0044002c Type=00380001 (LPC_REQUEST) Data: 00000001 000b0242 8092d465 8dad78d0 8dad78e8 8e34a720 The LpcDataInfoChainHead queue contains 1 messages Threads in RunDown queue : 0xe22a9e48Done. From the output above, we know the client thread is 8da33220. No we can use the !thread command to get the process it belongs to: kd> !thread 8da33220THREAD 8da33220 Cid 0f60.0db4 Teb: 7ffdd000 Win32Thread: e2890c20 WAIT: (Unknown) UserMode Non-Alertable 8da3340c Semaphore Limit 0x1Waiting for reply to LPC MessageId 0006e72d:Current LPC port e23cedd0Not impersonatingDeviceMap e2295b28Owning Process 8d1f95d8 Image: ODBCLoggingTest.exeAttached Process N/A Image: N/AWait Start TickCount 75870 Ticks: 0Context Switch Count 2049 LargeStackUserTime 00:00:00.343KernelTime 00:00:00.203Win32 Start Address 0x79007bf0Start Address kernel32!BaseProcessStartThunk (0x77e617f8)Stack Init f54ee000 Current f54edc20 Base f54ee000 Limit f54ea000 Call 0Priority 10 BasePriority 8 PriorityDecrement 0ChildEBP RetAddr Args to Child f54edc38 8082ffd7 8da33220 8da332c8 000007c1 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])f54edc50 808287d4 8da3340c 8da333e0 8da33220 nt!KiSwapThread+0x83 (FPO: [0,2,0])f54edc94 80916b4c 8da3340c 00000011 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])f54edd50 80883938 00000478 00209058 00209058 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])f54edd50 7c82860c 00000478 00209058 00209058 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f54edd64)0012b80c 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0]) Currently we are in services process context. We need to change to the LPC client thread process context to get the complete call stack. We do this by using the .thread command (instead of !thread): kd> .process /p /r 8d1f95d8 Implicit process is now 8d1f95d8.cache forcedecodeuser doneLoading User Symbols............................................................................ kd> !thread 8da33220THREAD 8da33220 Cid 0f60.0db4 Teb: 7ffdd000 Win32Thread: e2890c20 WAIT: (Unknown) UserMode Non-Alertable 8da3340c Semaphore Limit 0x1Waiting for reply to LPC MessageId 0006e72d:Current LPC port e23cedd0Not impersonatingDeviceMap e2295b28Owning Process 8d1f95d8 Image: ODBCLoggingTest.exeAttached Process N/A Image: N/AWait Start TickCount 75870 Ticks: 0Context Switch Count 2049 LargeStackUserTime 00:00:00.343KernelTime 00:00:00.203Win32 Start Address mscoree!_CorExeMain (0x79007bf0)Start Address KERNEL32!BaseProcessStartThunk (0x77e617f8)Stack Init f54ee000 Current f54edc20 Base f54ee000 Limit f54ea000 Call 0Priority 10 BasePriority 8 PriorityDecrement 0*** WARNING: Unable to verify checksum for System.Data.ni.dll*** ERROR: Module load completed but symbols could not be loaded for System.Data.ni.dllChildEBP RetAddr Args to Child f54edc38 8082ffd7 8da33220 8da332c8 000007c1 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])f54edc50 808287d4 8da3340c 8da333e0 8da33220 nt!KiSwapThread+0x83 (FPO: [0,2,0])f54edc94 80916b4c 8da3340c 00000011 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])f54edd50 80883938 00000478 00209058 00209058 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])f54edd50 7c82860c 00000478 00209058 00209058 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f54edd64)0012b7bc 7c827899 77c80a6e 00000478 00209058 ntdll!KiFastSystemCallRet (FPO: [0,0,0])0012b7c0 77c80a6e 00000478 00209058 00209058 ntdll!ZwRequestWaitReplyPort+0xc (FPO: [3,0,0])0012b80c 77c7fcf0 0012b848 0012b82c 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])0012b818 77c80673 0012b848 7d1f73e8 0012bc34 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])0012b82c 77ce315a 0012b874 00223340 00222b90 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])0012bc14 7d1fc005 7d1f73e8 7d1fba3c 0012bc34 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])0012bc2c 7d1fbfc6 00222ad0 4a09ca4f 00000001 ADVAPI32!ElfrReportEventW+0x1c (FPO: [14,1,0])0012bca4 7d1fbf08 00222ad0 00000001 00000000 ADVAPI32!ElfReportEventW+0x5a (FPO: [SEH])0012bd0c 488c4e16 00222ad0 00000001 00000000 ADVAPI32!ReportEventW+0xcb (FPO: [SEH])0012dd4c 488c2bf1 0012e1c8 0012e9c8 0000213d ODBC32!Log+0xa9 (FPO: [1,2051,0])0012e184 488c32c2 00000000 0012e1c8 0000213d ODBC32!HashForTrace+0xb7 (FPO: [4,262,0])0012e9d8 4a757523 03f71ac0 03f72f30 04310128 ODBC32!CDispenser::EnlistResource+0x22d (FPO: [3,524,4])0012ea10 4a7580f4 0020cff4 03f72f30 04310128 comsvcs!CHolder::SafeDispenserDriver::EnlistResource+0x22 (FPO: [SEH])0012ea48 4a75892a 03f72f30 00000000 00000001 comsvcs!CHolder::AddRes+0xdb (FPO: [6,6,4])0012eaac 488c3551 04310128 03f71b48 0012eb10 comsvcs!CHolder::AllocResource+0x346 (FPO: [3,14,4])0012eacc 488c36b4 03f71ac0 03f71b48 0012eb10 ODBC32!CDispenser::TryAllocResource+0x49 (FPO: [4,0,4])0012eb04 488c45c0 03f71ac0 03f72f30 00000000 ODBC32!CDispenser::GetActiveConnection+0x31 (FPO: [2,5,4])0012eb20 488a29d3 03f71ab8 00000000 0012f69c ODBC32!GetActiveConn+0x7e (FPO: [2,0,4])0012f260 0090ba00 03f71b48 00000000 012a3620 ODBC32!SQLDriverConnectW+0x9df (FPO: [8,457,4])WARNING: Frame IP not in any known module. Following frames may be wrong.0012f2a4 655ca10c 0012f308 013049e8 012e025c 0x90ba000012f318 655ca612 012e2db4 013049e8 0130495c System_Data_ni+0x47a10c0012f32c 655cde8a 012e2db4 012e025c 00000000 System_Data_ni+0x47a6120012f348 655cdb78 012e025c 012c3df0 0130495c System_Data_ni+0x47de8a0012f378 656c681d 012e05b8 00000000 012c3df0 System_Data_ni+0x47db780012f39c 65223831 0130495c 012e0160 00000000 System_Data_ni+0x57681d0012f3cc 655c07e1 012c3df0 0012f410 0012f428 System_Data_ni+0xd38310012f480 79e71b4c 0012f4cc 00000000 0012f510 System_Data_ni+0x4707e10012f490 79e821b1 0012f560 00000000 0012f530 mscorwks!CallDescrWorker+0x330012f510 79e96501 0012f560 00000000 0012f530 mscorwks!CallDescrWorkerWithHandler+0xa3 (FPO: [SEH])0012f648 79e96534 0091c010 0012f714 0012f6e0 mscorwks!MethodDesc::CallDescr+0x19c (FPO: [5,12,4])0012f664 79e96552 0091c010 0012f714 0012f6e0 mscorwks!MethodDesc::CallTargetWorker+0x1f (FPO: [4,0,0])0012f67c 79eefa45 0012f6e0 38a6f4e1 00000000 mscorwks!MethodDescCallSite::CallWithValueTypes+0x1a (FPO: [1,0,0])0012f7e0 79eef965 00912ff0 00000001 0012f81c mscorwks!ClassLoader::RunMain+0x223 (FPO: [SEH])0012fa48 79eefeb5 00000000 38a6fc19 00000001 mscorwks!Assembly::ExecuteMainMethod+0xa6 (FPO: [1,144,4])0012ff18 79ef009f 00400000 00000000 38a6fc69 mscorwks!SystemDomain::ExecuteMainMethod+0x456 (FPO: [2,301,4]) From the test app call we can clearly see that ODBC32.dll is writing the event to the event log using Advapi32!ReportEventW. With this information I engaged our internal ODBC32.dll development team to continue the investigation.If we had known the test app was writing to the event log, we could have avoided the kernel debugging and set a breakpoint on Advapi32!ReportEventW in the Visual Studio itself. Since I use windbg, I didn’t even know you could set break points in OS modules while debugging in Visual Studio.For other debuggers in the same boat, this is how you set breakpoint in Visual Studio on OS APIs.1. First setup the OS symbol path by either using the _NT_SYMBOL_PATH environment variable, or by using the UI (Tools->Options->Debugging->Symbols) window.2. From the Debug->New Breakpoint menu, select "Break at Function..."3. In the "New Breakpoint" window, enter {,,advapi32.dll}ReportEventW in the Function: box and click OK. More information about the syntax can be found at the below link:
http://msdn.microsoft.com/en-us/library ... 80).aspxIn conclusion, if you don’t know who is writing a particular event to the event log, set a breakpoint on eventlog!ElfrReportEventW in the services.exe process, and use the !lpc command to find the module\thread (Call stack)\process writing the event in the event log. Feel free to "dialog" about the post on our Twitter page -
http://twitter.com/ntdebugging Quelle
7c81a3e1 cc int 3 Then I verified the current process was services.exe by using the -1 flag. Since we see Services.exe in the output below, we know the !bpid command broke into the correct process.kd> !process -1 0PROCESS 8d9aa020 SessionId: 0 Cid: 01ac Peb: 7ffde000 ParentCid: 017c DirBase: 3549e080 ObjectTable: e151e698 HandleCount: 355. Image: services.exeThis is how I loaded the user mode symbols to set the break point in Eventlog.dll kd> .process /p /r 8d9aa020 Implicit process is now 8d9aa020.cache forcedecodeuser doneLoading User Symbols......................Here I'm setting the eventlog!ElfrReportEventW break point: kd> x eventlog!*Reportevent*7575b18f eventlog!ElfrReportEventAndSourceW = <no type information>75753324 eventlog!ElfIntReportEvent = <no type information>7575372e eventlog!ElfrReportEventW = <no type information>75753a07 eventlog!ElfrReportEventA = <no type information>kd> bp 7575372ekd>With the debugger ready, I single stepped through the test app in Visual Studio to repro the problem. The break point EventLog!ElfReportEventW hit in the services.exe process. Using the LPC message I was able to determine the client of the RPC call which turned out to be the test app. kd> gBreakpoint 0 hiteventlog!ElfrReportEventW
der samu is wieder da jüpi
