Case of Excel Conditional Formatting Hang

Previously we saw network traffic causing a hang http://chentiangemalc.wordpress.com/2014/08/21/case-of-the-excel-hang-on-worksheet-open/

This time no network traffic was occurring when launching a customer’s payroll Excel Application (XLS file). The application hang occurred in Excel 2010 and 2013, but not in Excel 2003. As before Office File Validation had been confirmed off, and issue occurred with no add-ons…

During the hang Process Monitor (http://live.sysinternals.com/ProcMon.exe ) detected no registry/file/network activity from Excel.exe

image

 

The progress bar opening document stuck for over 60 seconds at the same position…

image

From Process Explorer we notice for the duration of hang, Excel is consuming high CPU.

image

 

Using XPerf + Windows Performance Analyzer with the –stackWalk option we can see this see on a graph. We can also on see in the “Images – Transient Lifetime By Process, Image” that several modules loaded at the same time the high CPU started. In some cases we might get a clue just from this, but not today.

image

 

image

Running under Visual Studio Profiler…

image

From the per-module view, we can see almost all time is spent in one function in MSO.dll

image

Using Rohitab Monitor we add external DLL MSO.dll and monitor Excel launching document

image

Almost all the time is spent in function @8879 which is called non-stop during the hang, followed up by _MsoFreePv@4. This lined up with what I had captured in WinDbg when attaching to Excel. With Microsoft’s internal symbols we can probably easily figure out what is causing this hang from this information, as we can get the actual API name at least.

image

We could spend some time reversing the function and trying to figure out how it’s being used but instead went back to a more basic troubleshooting method:

1) Saved document as XLSM – issue doesn’t occur, document opens instantly

2) Saved XLSM to XLS again – issue is back

3) Saved XLSM to XLSX (No Macros – there is an open document macro) – issue still occurs

4) Deleted 1st workheet – issue doesn’t occur

OK so we have found the culprit is the 1st worksheet. In fact when we are saving the document in XLS format we are given a clue to this problem.

We see two warnings about conditional formatting:

image

So in the worksheet I clear all conditional formatting (This required unprotecting the sheet, which required a password, which happened to be the department’s name, and was throughout the macros as .Unprotect <password>) Keep in mind password protected macros are not protected! ( http://chentiangemalc.wordpress.com/2012/01/17/powershell-script-to-remove-office-macro-protection/ )

image

 

Sure enough this fixed the issue, document loaded instantly. But what conditional formatting actually caused the issue…

Looking at the rows most rows had a set of rules like this:

image

However there were two rows in the worksheet that had 250 conditional formatting rules applied to an individual cell – 500 total.

image

Recreating these two rows, fixed the performance issue.

This issue didn’t occur in Excel 2003 due to the issue being cause by Excel 2007 and later functionality that would be ignored in Excel 2003. The XLS vs XLSM are significantly different file formats – XLS being a binary OLE Object Document, XLSX/XLSM being essentially a ZIP file of XML files, so the processing of these files will be different.

Posted in API Monitor, Debugging, Office | Tagged | Leave a comment

Windows Performance Analysis Field Guide–Book Review

As someone who spends most of his time providing “IT support for IT support” one area I notice many IT people struggle with is performance diagnostics. Tools like Performance Monitor,  XPerf often aren’t utilized at all in the diagnostics process, or there is a lack of understanding how to best make use of them.

Windows Performance Analysis Field Guide is one of the best general-purpose books I’ve seen to-date covering the topic of Microsoft Windows Performance Diagnostics. (http://blogs.technet.com/b/clinth/archive/2014/07/10/available-for-pre-order-windows-performance-analysis-field-guide.aspx)

This book covers essentials for those new to performance diagnostics, and has a selection of useful reference material, even more experienced engineers will gain value from.

Importantly this book starts with the basics:

  • Boot or shutdown problem?
  • Hardware or software hang?
  • Hardware diagnostics
  • High Processor or Disk Usage
  • Lack of Kernel Pool Memory
  • High Process Interrupts or DPCs
  • Processes terminating unexpectedly

The book then moves onto topics such as

  • General Slow System Performance
  • Common Environment / Hardware Induced Performance Issues
  • Power Usage Analysis
  • Hard Drive / Optical Drive Performance
  • Overheating
  • Windows Performance Analysis Industry Experts and Their Contact Information

The book continues with an excellent Performance Monitor Reference, covering all essential details and many tips to optimize both monitoring and processing of logs.

The 3rd chapter covers storage, covering

  • Initial indicators of poor disk performance
  • Storage & Hardware Industry Terminology
  • I/O Operations Per Second
  • Disk Capacity
  • Understanding and Measuring Disk Performance
  • Covers common misconceptions on disk queue length
  • Read/Write Ratios
  • The effects of I/O sizes
  • I/O Response Times
  • List of Disk Performance Analysis Tools
  • Disk Performance Analysis Experts and their Contact Information

In the fourth chapter we are looking at Process Memory. For those who have not read the Windows Internals Series, or lack an understanding of how Windows handles memory, this gives a good rapid intro on the most critical aspects relating to performance.

We see covered

  • Process Virtual Address Space
  • Identifying Applications That Run out of Virtual Address Space
  • Using the PAL Tool
  • Using VMMap
  • Using DebugDiag
  • How to collect information for a Microsoft Support Call
  • Identifying/adding Large Address Aware
  • 32-bit/64-bit Virtual Address Space
  • Virtual Memory and Paging Files
  • System.OutOfMemory Exception Errors
  • Guidance on using /3GB or increased user VA
  • Identify Leaking Process

Chapter 5 moves into Kernel Memory space, covering topics such as

  • Pool Paged
  • Pool Non Paged
  • System Page Table Entries (PTEs)
  • Troubleshooting Lack of PTEs
  • Monitoring Kernel Memory with ProcExp
  • Analyzing Kernel Memory with WPA
  • Analyzing Kernel Memory with PoolMon
  • Analyzing Kernel Memory with Kernel Debugger
  • Page Frame Number Databage/Physical Memory/Virtual Address Space
  • Kernel Memory Analysis Experts Twitter Handles

Chapter 6 covers System Committed Memory

  • How much is enough / too much
  • Using Performance Monitor
  • USing Process Explorer
  • Using WMI
  • Where did all System Committed Memory Go?
  • Treating Systems of High System Committed Memory
  • Case Study of High System Committed Memory

Chapter 7 talks about Page Files

  • Page File Sizing
  • Impact on Crash Dumps
  • Page File Related Performance Counters
  • Running without a page file
  • Tracking Page file with Resource Monitor / WPA / ProcMon
  • Pagefile Security

Chapter 8 covers physical memory:

  • Free Is Different Than Available Memory
  • Using Performance Monitor
  • Working Sets
  • Driver Locked Memory
  • Address Windowing Extensions (AWE)
  • How Physical Memory is Managed
  • Detected Bad Physical Memory
  • ReadyBoost
  • Prefetch
  • Superfetch
  • System Cache
  • Too much Physical Memory

In chapter 9 network is covered in a basic detail. This covers network utilization, NIC duplex settings, chattiness and latency. Unfortunately this section while covering network as a bottleneck, does not cover a very common scenario – identifying client application hangs related to poor server performance.

Chapter 10 – Processor

  • Using Task Manager / Performance Monitor / Resource Monitor / Process Explorer / Windows Performance Analyzer / Xperf
  • Processor Interrupts and DPC Events
  • Virtual Machine Considerations

Chapter 11 – Boot Performance

  • Common causes of poor boot performance
  • Using AutoRuns
  • Boot Trace with WPA
  • Analyzing Boot Trace with WPA
  • Boot Phases in WPA
  • Example of Bad Boot Trace with WPA

 

Chapter 12 – Performance Analysis of Logs (PAL Tool)

  • Using PAL wizard
  • Interpreting the report
  • Creating Threshold

In the appendix there is a brief overview of the tools used through the book, and a guide on collecting Process Memory Dumps.

This book in general provides a very good overview on the essentials of Windows diagnostics, in a concise manner and I’m glad to have it in my collection.

Posted in Book Review | Tagged | Leave a comment

Case of the Excel Hang on Worksheet Open

Excel was hanging for a long time on a very simple spreadsheet, with no macros, no Office File Validation, and no crazy add-ons, whenever the “Header” worksheet was first activated.

image

 

Launching excel with ProcDump http://live.sysinternals.com/ProcDumpe.exe in hang mode, we captured a dump file.

image

In WinDbg looking at the stack trace we can see hang is occurring in module OART, which is OfficeArt module. This hints our image might be linked to the issue, we also see urlmon and winhttp waiting which hints at network traffic.

0:000> ~*k

.  0  Id: 23b8.1b94 Suspend: 0 Teb: 7ee2d000 Unfrozen
ChildEBP RetAddr 
00c6de64 75a91211 ntdll!NtDelayExecution+0xc
00c6decc 75a91176 KERNELBASE!SleepEx+0x8a
00c6dedc 0fd387f2 KERNELBASE!Sleep+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
00c6def4 0f9338a7 OART!Ordinal7761+0x6b9bd
00c6df50 0f933881 OART!Ordinal8884+0x4a
00c6df60 10140b40 OART!Ordinal8884+0x24
00c6dfa8 0fd371e6 OART!Ordinal4307+0x396
00c6dfd8 0f93d0aa OART!Ordinal7761+0x6a3b1
00c6e00c 0f93d067 OART!Ordinal8060+0x53
00c6e01c 0faac57e OART!Ordinal8060+0x10
00c6e064 0f9234f8 OART!Ordinal5748+0x92
00c6e0b4 0f923bb9 OART!Ordinal5496+0x280
00c6e170 0f9308d8 OART!Ordinal3146+0x254
00c6e27c 0f934d43 OART!Ordinal9814+0x4be
00c6e2d4 00ef138e OART!Ordinal1525+0x690
00c6e618 00ef4751 EXCEL!Ordinal43+0x24138e
00c6e6bc 00d2f295 EXCEL!Ordinal43+0x244751
00c6e86c 00d2ef4a EXCEL!Ordinal43+0x7f295
00c6e960 00d2e9cc EXCEL!Ordinal43+0x7ef4a
00c6eab0 00d2e58c EXCEL!Ordinal43+0x7e9cc
00c6ebe4 00d2de92 EXCEL!Ordinal43+0x7e58c
00c6ec68 69770c62 EXCEL!Ordinal43+0x7de92
00c6ed0c 696561ac MSO!Ordinal3226+0xa6f
00c6ed44 6965589b MSO!Ordinal3894+0x372
00c6ed88 6965573d MSO!Ordinal9043+0xcfb
00c6edb0 695ac834 MSO!Ordinal9043+0xb9d
00c6edb8 75417834 MSO!MsoGetHmodPTLServices+0x3b9
00c6ede4 75417a9a user32!_InternalCallWinProc+0x23
00c6ee74 7541988e user32!UserCallWinProcCheckWow+0x184
00c6eee0 754198f1 user32!DispatchMessageWorker+0x208
00c6eeec 00ce4ba2 user32!DispatchMessageW+0x10
00c6ef20 0185c48d EXCEL!Ordinal43+0x34ba2
00c6ef88 0175a45c EXCEL!LinkASPPModelTable+0x1fe9f3
00c6f31c 0175b81e EXCEL!LinkASPPModelTable+0xfc9c2
00c6f414 017339b1 EXCEL!LinkASPPModelTable+0xfdd84
00c6f69c 01734d46 EXCEL!LinkASPPModelTable+0xd5f17
00c6f714 01084c96 EXCEL!LinkASPPModelTable+0xd72ac
00c6f840 00cd1eee EXCEL!Ordinal43+0x3d4c96
00c6f940 75417834 EXCEL!Ordinal43+0x21eee
00c6f96c 75417a9a user32!_InternalCallWinProc+0x23
00c6f9fc 7541988e user32!UserCallWinProcCheckWow+0x184
00c6fa68 754198f1 user32!DispatchMessageWorker+0x208
00c6fa74 00ce4ba2 user32!DispatchMessageW+0x10
00c6fb74 00cb4d5f EXCEL!Ordinal43+0x34ba2
00c6fbfc 00cb4a68 EXCEL!Ordinal43+0x4d5f
00c6fc90 7717919f EXCEL!Ordinal43+0x4a68
00c6fc9c 7747a8cb kernel32!BaseThreadInitThunk+0xe
00c6fce0 7747a8a1 ntdll!__RtlUserThreadStart+0x20
00c6fcf0 00000000 ntdll!_RtlUserThreadStart+0x1b

   1  Id: 23b8.23d0 Suspend: 0 Teb: 7ee27000 Unfrozen
ChildEBP RetAddr 
04d0fc80 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
04d0fe04 77179188 KERNELBASE!WaitForMultipleObjectsEx+0xdc
04d0fe20 695b8db1 kernel32!WaitForMultipleObjects+0x19
WARNING: Stack unwind information not available. Following frames may be wrong.
04d0fe64 695b8c43 MSO!Ordinal970+0xb63
04d0fedc 695a7e43 MSO!Ordinal970+0x9f5
04d0fef0 7747a8cb MSO!Ordinal7766+0x72f
04d0ff34 7747a8a1 ntdll!__RtlUserThreadStart+0x20
04d0ff44 00000000 ntdll!_RtlUserThreadStart+0x1b

   2  Id: 23b8.27ac Suspend: 0 Teb: 7ecff000 Unfrozen
ChildEBP RetAddr 
04e6f6d0 774527d3 ntdll!NtWaitForWorkViaWorkerFactory+0xc
04e6f874 7717919f ntdll!TppWorkerThread+0x259
04e6f880 7747a8cb kernel32!BaseThreadInitThunk+0xe
04e6f8c4 7747a8a1 ntdll!__RtlUserThreadStart+0x20
04e6f8d4 00000000 ntdll!_RtlUserThreadStart+0x1b

   3  Id: 23b8.1fa8 Suspend: 0 Teb: 7ecfc000 Unfrozen
ChildEBP RetAddr 
04fafcc0 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
04fafe44 77179188 KERNELBASE!WaitForMultipleObjectsEx+0xdc
04fafe60 695bb446 kernel32!WaitForMultipleObjects+0x19
WARNING: Stack unwind information not available. Following frames may be wrong.
04faff74 695b7349 MSO!Ordinal7961+0xbc0
04faff88 7747a8cb MSO!Ordinal6778+0x301
04faffcc 7747a8a1 ntdll!__RtlUserThreadStart+0x20
04faffdc 00000000 ntdll!_RtlUserThreadStart+0x1b

   4  Id: 23b8.12a8 Suspend: 0 Teb: 7ecf9000 Unfrozen
ChildEBP RetAddr 
050efab0 774527d3 ntdll!NtWaitForWorkViaWorkerFactory+0xc
050efc54 7717919f ntdll!TppWorkerThread+0x259
050efc60 7747a8cb kernel32!BaseThreadInitThunk+0xe
050efca4 7747a8a1 ntdll!__RtlUserThreadStart+0x20
050efcb4 00000000 ntdll!_RtlUserThreadStart+0x1b

   5  Id: 23b8.b98 Suspend: 0 Teb: 7ecf6000 Unfrozen
ChildEBP RetAddr 
0523fbf0 75a910fd ntdll!NtWaitForSingleObject+0xc
0523fc60 695a52f5 KERNELBASE!WaitForSingleObjectEx+0x99
WARNING: Stack unwind information not available. Following frames may be wrong.
0523fc74 69c6cbb0 MSO!Ordinal3901+0x343
0523fc8c 00cc7c5a MSO!Ordinal7377+0x2c
0523fcac 00cc7034 EXCEL!Ordinal43+0x17c5a
0523fcb8 7717919f EXCEL!Ordinal43+0x17034
0523fcc4 7747a8cb kernel32!BaseThreadInitThunk+0xe
0523fd08 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0523fd18 00000000 ntdll!_RtlUserThreadStart+0x1b

   6  Id: 23b8.1ce8 Suspend: 0 Teb: 7ecf3000 Unfrozen
ChildEBP RetAddr 
0537f9dc 75a910fd ntdll!NtWaitForSingleObject+0xc
0537fa4c 695a52f5 KERNELBASE!WaitForSingleObjectEx+0x99
WARNING: Stack unwind information not available. Following frames may be wrong.
0537fa60 69c6cbb0 MSO!Ordinal3901+0x343
0537fa78 00cc7c5a MSO!Ordinal7377+0x2c
0537fa98 00cc7034 EXCEL!Ordinal43+0x17c5a
0537faa4 7717919f EXCEL!Ordinal43+0x17034
0537fab0 7747a8cb kernel32!BaseThreadInitThunk+0xe
0537faf4 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0537fb04 00000000 ntdll!_RtlUserThreadStart+0x1b

   7  Id: 23b8.848 Suspend: 0 Teb: 7ecf0000 Unfrozen
ChildEBP RetAddr 
05f3f4c4 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
05f3f648 695dc998 KERNELBASE!WaitForMultipleObjectsEx+0xdc
WARNING: Stack unwind information not available. Following frames may be wrong.
05f3f664 69648bf8 MSO!Ordinal2376+0x125
05f3f790 69648a2b MSO!Ordinal208+0x1c6
05f3f7b0 6963fa6b MSO!Ordinal2847+0x3db
05f3f93c 6963f5e7 MSO!Ordinal1557+0x8fe
05f3f98c 6963f07f MSO!Ordinal1557+0x47a
05f3f9c0 6963ef9b MSO!Ordinal2260+0x433
05f3f9cc 6959981f MSO!Ordinal2260+0x34f
05f3f9fc 6958b5f8 MSO!Ordinal1788+0x1ee
05f3fa14 695881b1 MSO!Ordinal4578+0xf6
05f3fa48 695868f1 MSO!Ordinal9805+0x2a0
05f3fa9c 7717919f MSO!Ordinal1981+0xb7b
05f3faa8 7747a8cb kernel32!BaseThreadInitThunk+0xe
05f3faec 7747a8a1 ntdll!__RtlUserThreadStart+0x20
05f3fafc 00000000 ntdll!_RtlUserThreadStart+0x1b

   8  Id: 23b8.124c Suspend: 0 Teb: 7eced000 Unfrozen
ChildEBP RetAddr 
0693f4cc 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
0693f650 77035fd0 KERNELBASE!WaitForMultipleObjectsEx+0xdc
0693f784 7703603e combase!WaitCoalesced+0x73 [d:\blue_gdr\com\published\comutils\coalescedwait.cxx @ 70]
0693f7ac 77036101 combase!CROIDTable::WorkerThreadLoop+0x4b [d:\blue_gdr\com\combase\dcomrem\refcache.cxx @ 1480]
0693f8d4 77036257 combase!CRpcThread::WorkerLoop+0x2e [d:\blue_gdr\com\combase\dcomrem\threads.cxx @ 264]
0693f8e4 7717919f combase!CRpcThreadCache::RpcWorkerThreadEntry+0x16 [d:\blue_gdr\com\combase\dcomrem\threads.cxx @ 67]
0693f8f0 7747a8cb kernel32!BaseThreadInitThunk+0xe
0693f934 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0693f944 00000000 ntdll!_RtlUserThreadStart+0x1b

   9  Id: 23b8.17d0 Suspend: 0 Teb: 7ecea000 Unfrozen
ChildEBP RetAddr 
06a3a658 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
06a3a7dc 7541c2a0 KERNELBASE!WaitForMultipleObjectsEx+0xdc
06a3a834 7541be18 user32!MsgWaitForMultipleObjectsEx+0x159
06a3a850 70a16ba2 user32!MsgWaitForMultipleObjects+0x1f
06a3a89c 70a16b26 urlmon!CTransaction::CompleteOperation+0x6f [d:\blue_gdr\inetcore\urlmon\trans\transact.cxx @ 2496]
06a3ad40 70a028ff urlmon!CTransaction::StartEx+0xffb [d:\blue_gdr\inetcore\urlmon\trans\transact.cxx @ 4453]
06a3ae20 70a01f3b urlmon!CBinding::StartBinding+0x92b [d:\blue_gdr\inetcore\urlmon\trans\cbinding.cxx @ 2289]
06a3ae64 70a0299e urlmon!CUrlMon::StartBinding+0x314 [d:\blue_gdr\inetcore\urlmon\trans\urlmon.cxx @ 1056]
06a3ae88 14415040 urlmon!CUrlMon::BindToStorage+0x4d [d:\blue_gdr\inetcore\urlmon\trans\urlmon.cxx @ 921]
06a3aeb8 14414f86 hlink!HrUrlmonBindToStorage+0x73
06a3aef4 14419eb7 hlink!HrResolveMonikerForData+0x172
06a3af0c 69bb217f hlink!HlinkResolveMonikerForData+0x29
WARNING: Stack unwind information not available. Following frames may be wrong.
06a3af48 69eb7620 MSO!Ordinal3677+0xc7c
06a3af90 69bb18fd MSO!Ordinal4502+0x1ae2a5
06a3afbc 69da3fb2 MSO!Ordinal3677+0x3fa
06a3c084 6a583550 MSO!Ordinal4502+0x9ac37
06a3c0c8 6a087fa4 MSO!Ordinal458+0x2bcd
06a3c344 1014af44 MSO!Ordinal670+0x13a
06a3c374 1014b975 OART!Ordinal6481+0xa0
06a3d3f4 1014ba40 OART!Ordinal11273+0xda
06a3f4e0 1014b7d3 OART!Ordinal3684+0x66
06a3f52c 0fd385de OART!Ordinal709+0x44
06a3f580 0fb1d456 OART!Ordinal7761+0x6b7a9
06a3f674 0fb1d349 OART!Ordinal9957+0xbd
06a3f6c4 0fc4f159 OART!Ordinal2726+0x1ff
06a3f728 1014bdad OART!Ordinal4876+0x1be1
06a3f744 1018e7d3 OART!Ordinal2361+0x31
06a3f784 1018edf4 OART!Ordinal10358+0x1b45
06a3f794 695f9cf4 OART!Ordinal10358+0x2166
06a3f7ac 6959981f MSO!Ordinal4294+0x24b
06a3f7dc 6958b5f8 MSO!Ordinal1788+0x1ee
06a3f7f4 695881b1 MSO!Ordinal4578+0xf6
06a3f828 695868f1 MSO!Ordinal9805+0x2a0
06a3f880 7717919f MSO!Ordinal1981+0xb7b
06a3f88c 7747a8cb kernel32!BaseThreadInitThunk+0xe
06a3f8d0 7747a8a1 ntdll!__RtlUserThreadStart+0x20
06a3f8e0 00000000 ntdll!_RtlUserThreadStart+0x1b

  10  Id: 23b8.25a8 Suspend: 0 Teb: 7ece7000 Unfrozen
ChildEBP RetAddr 
06b3fb30 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
06b3fcb4 7541c2a0 KERNELBASE!WaitForMultipleObjectsEx+0xdc
06b3fd0c 7541be18 user32!MsgWaitForMultipleObjectsEx+0x159
06b3fd28 6958683d user32!MsgWaitForMultipleObjects+0x1f
WARNING: Stack unwind information not available. Following frames may be wrong.
06b3fdc8 7717919f MSO!Ordinal1981+0xac7
06b3fdd4 7747a8cb kernel32!BaseThreadInitThunk+0xe
06b3fe18 7747a8a1 ntdll!__RtlUserThreadStart+0x20
06b3fe28 00000000 ntdll!_RtlUserThreadStart+0x1b

  11  Id: 23b8.10a4 Suspend: 0 Teb: 7ece4000 Unfrozen
ChildEBP RetAddr 
06c3fd40 75ad0dc0 ntdll!NtRemoveIoCompletion+0xc
06c3fd74 69588135 KERNELBASE!GetQueuedCompletionStatus+0x44
WARNING: Stack unwind information not available. Following frames may be wrong.
06c3fdb8 695868f1 MSO!Ordinal9805+0x224
06c3fe10 7717919f MSO!Ordinal1981+0xb7b
06c3fe1c 7747a8cb kernel32!BaseThreadInitThunk+0xe
06c3fe60 7747a8a1 ntdll!__RtlUserThreadStart+0x20
06c3fe70 00000000 ntdll!_RtlUserThreadStart+0x1b

  12  Id: 23b8.2438 Suspend: 0 Teb: 7ece1000 Unfrozen
ChildEBP RetAddr 
0bb8f850 75ad0dc0 ntdll!NtRemoveIoCompletion+0xc
0bb8f884 69588135 KERNELBASE!GetQueuedCompletionStatus+0x44
WARNING: Stack unwind information not available. Following frames may be wrong.
0bb8f8c8 695868f1 MSO!Ordinal9805+0x224
0bb8f920 7717919f MSO!Ordinal1981+0xb7b
0bb8f92c 7747a8cb kernel32!BaseThreadInitThunk+0xe
0bb8f970 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0bb8f980 00000000 ntdll!_RtlUserThreadStart+0x1b

  13  Id: 23b8.e08 Suspend: 0 Teb: 7ecde000 Unfrozen
ChildEBP RetAddr 
0bccfbf8 75ad0dc0 ntdll!NtRemoveIoCompletion+0xc
0bccfc2c 69588135 KERNELBASE!GetQueuedCompletionStatus+0x44
WARNING: Stack unwind information not available. Following frames may be wrong.
0bccfc70 695868f1 MSO!Ordinal9805+0x224
0bccfcc8 7717919f MSO!Ordinal1981+0xb7b
0bccfcd4 7747a8cb kernel32!BaseThreadInitThunk+0xe
0bccfd18 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0bccfd28 00000000 ntdll!_RtlUserThreadStart+0x1b

  14  Id: 23b8.2258 Suspend: 0 Teb: 7ecd8000 Unfrozen
ChildEBP RetAddr 
0e34fd44 774527d3 ntdll!NtWaitForWorkViaWorkerFactory+0xc
0e34fee8 7717919f ntdll!TppWorkerThread+0x259
0e34fef4 7747a8cb kernel32!BaseThreadInitThunk+0xe
0e34ff38 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0e34ff48 00000000 ntdll!_RtlUserThreadStart+0x1b

  15  Id: 23b8.25a4 Suspend: 0 Teb: 7ecd5000 Unfrozen
ChildEBP RetAddr 
0eccfc10 75ad0dc0 ntdll!NtRemoveIoCompletion+0xc
0eccfc44 69588135 KERNELBASE!GetQueuedCompletionStatus+0x44
WARNING: Stack unwind information not available. Following frames may be wrong.
0eccfc88 695868f1 MSO!Ordinal9805+0x224
0eccfce0 7717919f MSO!Ordinal1981+0xb7b
0eccfcec 7747a8cb kernel32!BaseThreadInitThunk+0xe
0eccfd30 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0eccfd40 00000000 ntdll!_RtlUserThreadStart+0x1b

  16  Id: 23b8.2220 Suspend: 0 Teb: 7ecd2000 Unfrozen
ChildEBP RetAddr 
11d8fbf8 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
11d8fd7c 7541c2a0 KERNELBASE!WaitForMultipleObjectsEx+0xdc
11d8fdd4 695da6dd user32!MsgWaitForMultipleObjectsEx+0x159
WARNING: Stack unwind information not available. Following frames may be wrong.
11d8fdf4 695da363 MSO!Ordinal1520+0x2d
11d8fe1c 6a4723c1 MSO!Ordinal2954+0x2c
11d8feb8 7717919f MSO!Ordinal3863+0x573a
11d8fec4 7747a8cb kernel32!BaseThreadInitThunk+0xe
11d8ff08 7747a8a1 ntdll!__RtlUserThreadStart+0x20
11d8ff18 00000000 ntdll!_RtlUserThreadStart+0x1b

  17  Id: 23b8.2648 Suspend: 0 Teb: 7ecbf000 Unfrozen
ChildEBP RetAddr 
128cf560 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
128cf6e4 7541c2a0 KERNELBASE!WaitForMultipleObjectsEx+0xdc
128cf73c 7541be18 user32!MsgWaitForMultipleObjectsEx+0x159
128cf758 711c812c user32!MsgWaitForMultipleObjects+0x1f
128cf7c8 711c82c5 uxtheme!CManagerImpl::_RunDelegateThread+0xb4
128cf7d4 711c8251 uxtheme!CManagerImpl::_DelegateThreadProc+0x6b
128cf7dc 7717919f uxtheme!CManagerImpl::s_ThreadProc+0xd
128cf7e8 7747a8cb kernel32!BaseThreadInitThunk+0xe
128cf82c 7747a8a1 ntdll!__RtlUserThreadStart+0x20
128cf83c 00000000 ntdll!_RtlUserThreadStart+0x1b

  18  Id: 23b8.16ac Suspend: 0 Teb: 7ecbc000 Unfrozen
ChildEBP RetAddr 
13cdfa44 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
13cdfbc8 736869b5 KERNELBASE!WaitForMultipleObjectsEx+0xdc
13cdfc2c 7368690b clr!DebuggerRCThread::MainLoop+0x98
13cdfc5c 7368683a clr!DebuggerRCThread::ThreadProc+0xcb
13cdfc8c 7717919f clr!DebuggerRCThread::ThreadProcStatic+0xb9
13cdfc98 7747a8cb kernel32!BaseThreadInitThunk+0xe
13cdfcdc 7747a8a1 ntdll!__RtlUserThreadStart+0x20
13cdfcec 00000000 ntdll!_RtlUserThreadStart+0x1b

  19  Id: 23b8.25a0 Suspend: 0 Teb: 7ecb9000 Unfrozen
ChildEBP RetAddr 
143ff69c 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
143ff820 7361df8f KERNELBASE!WaitForMultipleObjectsEx+0xdc
143ff86c 73627db8 clr!WKS::WaitForFinalizerEvent+0xbe
143ff8b4 736657a1 clr!WKS::GCHeap::FinalizerThreadWorker+0x6e
143ff8c8 7366580f clr!ManagedThreadBase_DispatchInner+0x67
143ff96c 736658dc clr!ManagedThreadBase_DispatchMiddle+0x82
143ff9c8 7367990a clr!ManagedThreadBase_DispatchOuter+0x5b
143ffa44 7361814d clr!WKS::GCHeap::FinalizerThreadStart+0x198
143ffae0 7717919f clr!Thread::intermediateThreadProc+0x4d
143ffaec 7747a8cb kernel32!BaseThreadInitThunk+0xe
143ffb30 7747a8a1 ntdll!__RtlUserThreadStart+0x20
143ffb40 00000000 ntdll!_RtlUserThreadStart+0x1b

  20  Id: 23b8.258c Suspend: 0 Teb: 7ecb6000 Unfrozen
ChildEBP RetAddr 
1331f554 75a910fd ntdll!NtWaitForSingleObject+0xc
1331f5c4 7352202c KERNELBASE!WaitForSingleObjectEx+0x99
1331f5f4 73522073 clr!CLREventWaitHelper2+0x31
1331f644 73521fd7 clr!CLREventWaitHelper+0x2a
1331f67c 735a8861 clr!CLREventBase::WaitEx+0x152
1331f694 7369de7e clr!CLREventBase::Wait+0x1a
1331f744 7361814d clr!AppDomain::ADUnloadThreadStart+0x2a4
1331f860 7717919f clr!Thread::intermediateThreadProc+0x4d
1331f86c 7747a8cb kernel32!BaseThreadInitThunk+0xe
1331f8b0 7747a8a1 ntdll!__RtlUserThreadStart+0x20
1331f8c0 00000000 ntdll!_RtlUserThreadStart+0x1b

  21  Id: 23b8.2790 Suspend: 0 Teb: 7ecb3000 Unfrozen
ChildEBP RetAddr 
1676fcb8 774527d3 ntdll!NtWaitForWorkViaWorkerFactory+0xc
1676fe5c 7717919f ntdll!TppWorkerThread+0x259
1676fe68 7747a8cb kernel32!BaseThreadInitThunk+0xe
1676feac 7747a8a1 ntdll!__RtlUserThreadStart+0x20
1676febc 00000000 ntdll!_RtlUserThreadStart+0x1b

  22  Id: 23b8.25c4 Suspend: 0 Teb: 7ecdb000 Unfrozen
ChildEBP RetAddr 
16cafa74 75a91211 ntdll!NtDelayExecution+0xc
16cafadc 75a91176 KERNELBASE!SleepEx+0x8a
16cafaec 708c15e6 KERNELBASE!Sleep+0xf
16cafb0c 708c1620 winhttp!SafeTerminateDll+0xba
16cafb50 77455e0a winhttp!FailFastThreadpoolWaitCallback<&SafeTerminateDll>+0x2a
16cafb78 77455d96 ntdll!TppExecuteWaitCallback+0x63
16cafb94 77455ccc ntdll!TppWaitCompletion+0x76
16cafd34 7717919f ntdll!TppWorkerThread+0x4bf
16cafd40 7747a8cb kernel32!BaseThreadInitThunk+0xe
16cafd84 7747a8a1 ntdll!__RtlUserThreadStart+0x20
16cafd94 00000000 ntdll!_RtlUserThreadStart+0x1b

  23  Id: 23b8.1c04 Suspend: 0 Teb: 7ec3f000 Unfrozen
ChildEBP RetAddr 
16dafa64 774527d3 ntdll!NtWaitForWorkViaWorkerFactory+0xc
16dafc08 7717919f ntdll!TppWorkerThread+0x259
16dafc14 7747a8cb kernel32!BaseThreadInitThunk+0xe
16dafc58 7747a8a1 ntdll!__RtlUserThreadStart+0x20
16dafc68 00000000 ntdll!_RtlUserThreadStart+0x1b

  24  Id: 23b8.2298 Suspend: 0 Teb: 7ec3c000 Unfrozen
ChildEBP RetAddr 
0c86f688 75aa0ca9 ntdll!NtWaitForMultipleObjects+0xc
0c86f80c 752918a4 KERNELBASE!WaitForMultipleObjectsEx+0xdc
0c86f834 7717919f crypt32!ILS_WaitForThreadProc+0x26
0c86f840 7747a8cb kernel32!BaseThreadInitThunk+0xe
0c86f884 7747a8a1 ntdll!__RtlUserThreadStart+0x20
0c86f894 00000000 ntdll!_RtlUserThreadStart+0x1b
0:000> lmv m OART
start    end        module name
0f890000 10639000   OART       (export symbols)       OART.DLL
    Loaded symbol image file: OART.DLL
    Image path: C:\program files (X86)\microsoft office\Office15\OART.DLL
    Image name: OART.DLL
    Timestamp:        Tue May 06 15:41:15 2014 (536875FB)
    CheckSum:         00DB5B99
    ImageSize:        00DA9000
    File version:     15.0.4621.1000
    Product version:  15.0.4621.0
    File flags:       0 (Mask 3F)
    File OS:          40004 NT Win32
    File type:        1.0 App
    File date:        00000000.00000000
    Translations:     0000.04e4
    CompanyName:      Microsoft Corporation
    ProductName:      Microsoft Office 2013
    InternalName:     OART
    OriginalFilename: OART.DLL
    ProductVersion:   15.0.4621.1000
    FileVersion:      15.0.4621.1000
    FileDescription:  Microsoft OfficeArt

 

Using Fiddler ( http://www.telerik.com/fiddler ) and launching the Excel document, sure enough we see HTTP traffic at time of the hang, to a non-existent web server.

image

Note, from Excel there is no obvious way to see that the image is attempting to come from a URL, except we do see the same URL in the image description

image

Renaming the .XLSX to a ZIP file we extract the contents

Using a file content search utility, like SearchMyFiles (http://www.nirsoft.net/utils/search_my_files.html), we find the offending components

image

The external target is located here. We can also see why we still see the image despite the fact this URL no longer exists, once the HTTP request fails, it reverts to the ../media/image1.png file.

image

Just like the classic way to remove formatting with a copy/paste into/from notepad, we can copy/paste image into MSPaint, copy it from MSPaint paste it back into Excel

No more hangs…

Posted in Office, Excel, WinDbg | Tagged | Leave a comment

Case of the “Server Returned a Referral”

From the development team that brought us such great bugs such as “Invalid Base Key Error” (http://chentiangemalc.wordpress.com/2014/05/22/case-of-the-invalid-base-key-error/) and “Continuing Case Of ByRef Corruption” (http://chentiangemalc.wordpress.com/2014/07/07/continuing-case-of-byref-corruption-net-patching/) on the latest update to the application we got a new error:

image

Of course if you were expecting a helpful error message, you’ve come to the wrong place. Using Process Explorer ( http://live.sysinternals.com/procexp.exe ) we used the target icon:

image

And dragged it over the message box so we knew exactly what process was throwing the error. We then right clicked the process in Process Explorer and selected Create Full Dump File

image

Loading the dmp file in WinDbg from a simple stack trace we see we are dealing with .NET app thanks to presence of mscorwks and mscoree

0:000> k
Child-SP          RetAddr           Call Site
00000000`002fcad8 00000000`77484bc4 user32!NtUserWaitMessage+0xa
00000000`002fcae0 00000000`77484edd user32!DialogBox2+0x274
00000000`002fcb70 00000000`774d2920 user32!InternalDialogBox+0x135
00000000`002fcbd0 00000000`774d1c15 user32!SoftModalMessageBox+0x9b4
00000000`002fcd00 00000000`774d146b user32!MessageBoxWorker+0x31d
00000000`002fcec0 00000000`774d1362 user32!MessageBoxTimeoutW+0xb3
00000000`002fcf90 000007fe`eb87cd37 user32!MessageBoxW+0x4e
*** WARNING: Unable to verify checksum for System.Windows.Forms.ni.dll
00000000`002fcfd0 000007fe`e8ec8269 mscorwks!DoNDirectCall__PatchGetThreadCall+0x7b
00000000`002fd070 000007fe`e8febeae System_Windows_Forms_ni+0x9a8269
00000000`002fd150 000007fe`e8feb78d System_Windows_Forms_ni+0xacbeae
*** WARNING: Unable to verify checksum for Microsoft.VisualBasic.ni.dll
00000000`002fd2e0 000007fe`f161ff24 System_Windows_Forms_ni+0xacb78d
00000000`002fd330 000007ff`00181455 Microsoft_VisualBasic_ni+0x11ff24
00000000`002fd3f0 000007ff`0017140a 0x000007ff`00181455
00000000`002fd4a0 000007ff`001710b8 0x000007ff`0017140a
00000000`002fd570 000007fe`e8eb8cbb 0x000007ff`001710b8
00000000`002fd720 000007fe`e8ebafbe System_Windows_Forms_ni+0x998cbb
00000000`002fd7e0 000007fe`e94135ba System_Windows_Forms_ni+0x99afbe
00000000`002fd820 000007fe`e8863d26 System_Windows_Forms_ni+0xef35ba
00000000`002fd9d0 000007fe`e8863bc5 System_Windows_Forms_ni+0x343d26
00000000`002fda20 000007fe`e88624c4 System_Windows_Forms_ni+0x343bc5
00000000`002fdad0 000007fe`eb87b08a System_Windows_Forms_ni+0x3424c4
00000000`002fdb10 00000000`77479bd1 mscorwks!UMThunkStubAMD64+0x7a
00000000`002fdba0 00000000`77473bfc user32!UserCallWinProcCheckWow+0x1ad
00000000`002fdc60 00000000`77473b78 user32!CallWindowProcAorW+0xdc
00000000`002fdcb0 000007fe`fc5a6215 user32!CallWindowProcW+0x18
00000000`002fdcf0 000007fe`fc5a69a0 comctl32_7fefc580000!CallOriginalWndProc+0x1d
00000000`002fdd30 000007fe`fc5a6768 comctl32_7fefc580000!CallNextSubclassProc+0x8c
00000000`002fddb0 000007fe`fc5a69a0 comctl32_7fefc580000!DefSubclassProc+0x7c
00000000`002fde00 000007fe`fc5a6877 comctl32_7fefc580000!CallNextSubclassProc+0x8c
00000000`002fde80 00000000`77479bd1 comctl32_7fefc580000!MasterSubclassProc+0xe7
00000000`002fdf20 00000000`774798da user32!UserCallWinProcCheckWow+0x1ad
00000000`002fdfe0 000007fe`eb87cd37 user32!DispatchMessageWorker+0x3b5
00000000`002fe060 000007fe`e887fa57 mscorwks!DoNDirectCall__PatchGetThreadCall+0x7b
00000000`002fe100 000007fe`e887ea03 System_Windows_Forms_ni+0x35fa57
00000000`002fe280 000007fe`e887e278 System_Windows_Forms_ni+0x35ea03
00000000`002fe4d0 000007fe`e887dce5 System_Windows_Forms_ni+0x35e278
00000000`002fe620 000007fe`f16531c7 System_Windows_Forms_ni+0x35dce5
00000000`002fe680 000007fe`f165487c Microsoft_VisualBasic_ni+0x1531c7
00000000`002fe6e0 000007fe`f16528cd Microsoft_VisualBasic_ni+0x15487c
00000000`002fe750 000007ff`001601ff Microsoft_VisualBasic_ni+0x1528cd
00000000`002fe800 000007fe`eb87d512 0x000007ff`001601ff
00000000`002fe850 000007fe`eb76b693 mscorwks!CallDescrWorker+0x82
00000000`002fe8a0 000007fe`ebc5aac1 mscorwks!CallDescrWorkerWithHandler+0xd3
00000000`002fe940 000007fe`eb7c848b mscorwks!MethodDesc::CallDescr+0x2b1
00000000`002feb80 000007fe`eb7ebbb0 mscorwks!ClassLoader::RunMain+0x22b
00000000`002fede0 000007fe`ebd4743d mscorwks!Assembly::ExecuteMainMethod+0xbc
00000000`002ff0d0 000007fe`eb7f90d7 mscorwks!SystemDomain::ExecuteMainMethod+0x47d
00000000`002ff6a0 000007fe`eb7dbdf4 mscorwks!ExecuteEXE+0x47
00000000`002ff6f0 000007fe`f2ac74e5 mscorwks!CorExeMain+0xac
00000000`002ff750 000007fe`f2b65b21 mscoreei!CorExeMain+0xe0
00000000`002ff7a0 00000000`77a359ed mscoree!CorExeMain_Exported+0x57
00000000`002ff7d0 00000000`77b6ba01 kernel32!BaseThreadInitThunk+0xd
00000000`002ff800 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

So we load SOS.dll debugging extension and print CLR stack

0:000> .load c:\windows\microsoft.net\framework64\v2.0.50727\sos.dll
0:000> !clrstack
OS Thread Id: 0x9c8 (0)
Child-SP         RetAddr          Call Site
00000000002fd070 000007fee8febeae DomainBoundILStubClass.IL_STUB(System.Runtime.InteropServices.HandleRef, System.String, System.String, Int32)
00000000002fd150 000007fee8feb78d System.Windows.Forms.MessageBox.ShowCore(System.Windows.Forms.IWin32Window, System.String, System.String, System.Windows.Forms.MessageBoxButtons, System.Windows.Forms.MessageBoxIcon, System.Windows.Forms.MessageBoxDefaultButton, System.Windows.Forms.MessageBoxOptions, Boolean)
00000000002fd2e0 000007fef161ff24 System.Windows.Forms.MessageBox.Show(System.Windows.Forms.IWin32Window, System.String, System.String, System.Windows.Forms.MessageBoxButtons, System.Windows.Forms.MessageBoxIcon, System.Windows.Forms.MessageBoxDefaultButton, System.Windows.Forms.MessageBoxOptions)
00000000002fd330 000007ff00181455 Microsoft.VisualBasic.Interaction.MsgBox(System.Object, Microsoft.VisualBasic.MsgBoxStyle, System.Object)
00000000002fd3f0 000007ff0017140a QFBox2.modQIK.StartQIK()
00000000002fd4a0 000007ff001710b8 QFBox2.modQIK.FunctionSelection(Int16 ByRef)
00000000002fd570 000007fee8eb8cbb QFBox2.frmMain.txtQIKFunction_KeyUp(System.Object, System.Windows.Forms.KeyEventArgs)
00000000002fd720 000007fee8ebafbe System.Windows.Forms.Control.ProcessKeyEventArgs(System.Windows.Forms.Message ByRef)
00000000002fd7e0 000007fee94135ba System.Windows.Forms.Control.WmKeyChar(System.Windows.Forms.Message ByRef)
00000000002fd820 000007fee8863d26 System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
00000000002fd9d0 000007fee8863bc5 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
00000000002fda20 000007fee88624c4 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
00000000002fdad0 000007feeb87b08a DomainBoundILStubClass.IL_STUB(Int64, Int32, Int64, Int64)
00000000002fe100 000007fee887ea03 DomainBoundILStubClass.IL_STUB(MSG ByRef)
00000000002fe280 000007fee887e278 System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(Int32, Int32, Int32)
00000000002fe4d0 000007fee887dce5 System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)
00000000002fe620 000007fef16531c7 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
00000000002fe680 000007fef165487c Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.OnRun()
00000000002fe6e0 000007fef16528cd Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.DoApplicationModel()
00000000002fe750 000007ff001601ff Microsoft.VisualBasic.ApplicationServices.WindowsFormsApplicationBase.Run(System.String[])
00000000002fe800 000007feeb87d512 QFBox2.My.MyApplication.Main(System.String[])

From this we can determine that the issue is occurring in QFBox2.modQIK.StartQIK() function

Now we look for the exception that was generated, which our programmers unfortunately had not been kind enough to show us:

0:000> !pe
Exception object: 00000000030f3100
Exception type: System.ComponentModel.Win32Exception
Message: A referral was returned from the server
InnerException: <none>
StackTrace (generated):
    SP               IP               Function
    00000000002FD2B0 000007FEEA40BF74 System_ni!System.Diagnostics.Process.StartWithShellExecuteEx(System.Diagnostics.ProcessStartInfo)+0x444
    00000000002FD3B0 000007FEEA40C3CD System_ni!System.Diagnostics.Process.Start(System.Diagnostics.ProcessStartInfo)+0x3d
    00000000002FD3F0 000007FF00181411 QFBox2!QFBox2.modQIK.StartQIK()+0xe1

StackTraceString: <none>
HResult: 80004005

Ok so we know attempting to start a process failed with error “A referral was returned from the server”

What was it trying to start? We can figure this by checking objects on the stack:

0:000> !dumpstackobjects
OS Thread Id: 0x9c8 (0)
RSP/REG          Object           Name
00000000002fcf80 00000000030f2d10 System.String
00000000002fcf90 00000000030f2dc0 System.String
00000000002fcff8 00000000030f3758 System.Windows.Forms.Application+ThreadWindows
00000000002fd008 0000000002e549a8 System.Windows.Forms.Application+ThreadContext
00000000002fd050 00000000030f2d10 System.String
00000000002fd0c0 00000000030f2d10 System.String
00000000002fd0d0 00000000030f2dc0 System.String
00000000002fd110 00000000030f2dc0 System.String
00000000002fd118 00000000030f2d10 System.String
00000000002fd158 00000000030f2d10 System.String
00000000002fd160 00000000030f2dc0 System.String
00000000002fd250 00000000030f2dc0 System.String
00000000002fd258 00000000030f2d10 System.String
00000000002fd2b0 0000000002f543d8 System.Windows.Forms.KeyEventArgs
00000000002fd2b8 00000000030f2d10 System.String
00000000002fd330 0000000002ea4bd0 System.Windows.Forms.TextBox
00000000002fd378 00000000030f2dc0 System.String
00000000002fd3b8 00000000030f2d10 System.String
00000000002fd3d0 0000000002ea4bd0 System.Windows.Forms.TextBox
00000000002fd3f0 00000000030f2d10 System.String
00000000002fd400 00000000030f2dc0 System.String
00000000002fd420 00000000030f2ed0 System.Diagnostics.ProcessStartInfo <—ProcessStartInfo was passed to StartWithShellExecuteEx
00000000002fd438 00000000030f2e00 System.String
00000000002fd440 00000000030f2e70 System.String

We can then dump that object to extract the filename:

0:000> !do 00000000030f2ed0
Name: System.Diagnostics.ProcessStartInfo
MethodTable: 000007feea50a730
EEClass: 000007fee9d5e7e0
Size: 128(0x80) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feeab17d90  40033f0        8        System.String  0 instance 00000000030f2e00 fileName
000007feeab17d90  40033f1       10        System.String  0 instance 00000000030f2e70 arguments
000007feeab17d90  40033f2       18        System.String  0 instance 0000000000000000 directory
000007feeab17d90  40033f3       20        System.String  0 instance 0000000000000000 verb
000007feea4d7c00  40033f4       68         System.Int32  1 instance                0 windowStyle
000007feeab16f60  40033f5       6c       System.Boolean  1 instance                0 errorDialog
000007feeab1a798  40033f6       60        System.IntPtr  1 instance                0 errorDialogParentHandle
000007feeab16f60  40033f7       6d       System.Boolean  1 instance                1 useShellExecute
000007feeab17d90  40033f8       28        System.String  0 instance 0000000000000000 userName
000007feeab17d90  40033f9       30        System.String  0 instance 0000000000000000 domain
000007feeb30ad60  40033fa       38 …rity.SecureString  0 instance 0000000000000000 password
000007feeab16f60  40033fb       6e       System.Boolean  1 instance                0 loadUserProfile
000007feeab16f60  40033fc       6f       System.Boolean  1 instance                0 redirectStandardInput
000007feeab16f60  40033fd       70       System.Boolean  1 instance                0 redirectStandardOutput
000007feeab16f60  40033fe       71       System.Boolean  1 instance                0 redirectStandardError
000007feeab1fbe0  40033ff       40 System.Text.Encoding  0 instance 0000000000000000 standardOutputEncoding
000007feeab1fbe0  4003400       48 System.Text.Encoding  0 instance 0000000000000000 standardErrorEncoding
000007feeab16f60  4003401       72       System.Boolean  1 instance                0 createNoWindow
000007feeab0f2a8  4003402       50 System.WeakReference  0 instance 0000000000000000 weakParentProcess
000007fee9f9a0a8  4003403       58 ….StringDictionary  0 instance 0000000000000000 environmentVariables

Finally we dump the filename value…
0:000> !do 00000000030f2e00
Name: System.String
MethodTable: 000007feeab17d90
EEClass: 000007feea71e560
Size: 112(0x70) bytes
(C:\WINDOWS\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: “C:\QIK-QUBE2\QARUN\ARECURRENT\AQIRE32.EXE”
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007feeab1f000  4000096        8         System.Int32  1 instance               44 m_arrayLength
000007feeab1f000  4000097        c         System.Int32  1 instance               43 m_stringLength
000007feeab197d8  4000098       10          System.Char  1 instance               22 m_firstChar
000007feeab17d90  4000099       20        System.String  0   shared           static Empty
                                 >> Domain:Value  0000000000123340:0000000002e51308 <<
000007feeab19688  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                 >> Domain:Value  0000000000123340:0000000002e51a58 <<

So what if I launched the process from a cmd prompt or Windows Explorer?

image

We also noticed:

  • the EXE had a recent “Last Modified Date”
  • Copying the EXE to a “clean install Windows 7 machine” the exe failed with same error message
  • The previous version of EXE did not fail with this error message

So why was the new one broken…launching from WinDbg we got a different error:

The requested operation requires elevation.

image

So I looked for a manifest file requesting elevation. There was an Aqire32.exe.Manifest file in the same folder as the EXE but it didn’t refer to elevation:

<?xml version=’1.0′ encoding=’UTF-8′ standalone=’yes’?>
<assembly xmlns=’urn:schemas-microsoft-com:asm.v1′ manifestVersion=’1.0′>
<dependency>
    <dependentAssembly>
      <assemblyIdentity name=”QikComHlp2″ version=”2.0.0.7″ processorArchitecture=”MSIL” />
    </dependentAssembly>
  </dependency>
<dependency>
   <dependentAssembly>
     <assemblyIdentity
       type=”win32″
       name=”Microsoft.Windows.Common-Controls”
       version=”6.0.0.0″
       processorArchitecture=”X86″
       publicKeyToken=”6595b64144ccf1df”
       language=”*”
     />
   </dependentAssembly>
</dependency>
</assembly>

So opened the EXE in Resource Hacker http://angusj.com/resourcehacker/

Here we can see the embedded manifest file:

image

 

Most interesting here is the uiAccess=”true” component.

<assembly xmlns=”urn:schemas-microsoft-com:asm.v1″ manifestVersion=”1.0″>
  <trustInfo xmlns=”urn:schemas-microsoft-com:asm.v3″>
    <security>
      <requestedPrivileges>
        <requestedExecutionLevel level=”requireAdministrator” uiAccess=”true”></requestedExecutionLevel>
      </requestedPrivileges>
    </security>
  </trustInfo>
</assembly>

There are several requirements on Windows Vista and later if you want to use uiAccess=”true”

Firstly because this program is outside a “secure location” the following group policy must be set: User Account Control: Only elevate UIAccess applications that are installed in secure locations

We confirmed this policy was applied on the machine using gpresult.

This security setting will enforce the requirement that applications that request execution with a UIAccess integrity level (via a marking of UIAccess=true in their application manifest), must reside in a secure location on the file system.  Secure locations are limited to the following directories:

- \Program Files\, including subdirectories
- \Windows\system32\
- \Program Files (x86)\, including subdirectories for 64 bit versions of Windows

In addition Windows enforces a PKI signature check on any interactive application that requests execution with UIAccess integrity level regardless of the state of this security setting.

Refer:
http://technet.microsoft.com/en-us/library/dd834830.aspx
 http://technet.microsoft.com/en-us/library/jj852244.aspx
 

Using Resource hacker when we deleted the manifest, the application launched fine. However the component requiring UIAccess=true would now fail to work correctly.

image

Using SignTool.exe from Windows SDK we can check if EXE is signed correctly:

image

Ok it is not….

image

So I run…

MakeCert /n CN=Test /r /h 0 /eku “1.3.6.1.5.5.7.3.3,1.3.6.1.4.1.311.10.3.13” /sv test.pvk test.cer

Pvk2Pfx /pvk test.pvk /pi password /spc Test.cer /pfx Test.pfx

signtool sign /f test.pfx /p password c:\qik-qube2\QARUN\ARECURRENT\aqire32.exe

 

However attempting to sign EXE I received error

image

SignTool Error: SignedCode::Sign returned error: 0x800700C1
        Either the file being signed or one of the DLL specified by /j switch is
not a valid Win32 application.
SignTool Error: An error occurred while attempting to sign: c:\qik-qube2\QARUN\A
RECURRENT\AQIRE32.exe

Now 0x800700C1 is a “bad image format” error. Typically thrown when the file image of a dynamic link library (DLL) or an executable program is invalid – or the wrong format i.e. 64-bit loading 32-bit DLL.

However in the case of signtool.exe it is usually the fact that the EXE has some remnant of signature…

So I used delcert.exe to remove the signature from EXE – source code included here:

http://forum.xda-developers.com/showthread.php?p=2508061

image

Then we signed it…

image

As a final step I imported it into root cert

certmgr.exe -add test.cer -s -r localMachine root

image

We can see now it is signed:

image

 

image

And application launches fine now…with the manifest in place.

Now to try to run it in WinDbg we could have tried this to launch it under debugger:

image

Unfortunately we don’t get enough information on what is going on from the stack trace…

0:007> !uniqstack
Processing 6 threads, please wait

.  0  Id: 1b24.2340 Suspend: 1 Teb: 00007ff6`3915e000 Unfrozen
      Start: cmd!mainCRTStartup (00007ff6`39dd65b4)
      Priority: 0  Priority class: 32  Affinity: 3
Child-SP          RetAddr           Call Site
00000001`9b83dfc8 00007ffd`0f5f13ad ntdll!NtWaitForMultipleObjects+0xa
00000001`9b83dfd0 00007ffd`10493b10 KERNELBASE!WaitForMultipleObjectsEx+0xe1
00000001`9b83e2b0 00007ffd`0d96396b USER32!RealMsgWaitForMultipleObjectsEx+0x100
00000001`9b83e360 00007ffd`0d9638be DUser!CoreSC::Wait+0x7f
00000001`9b83e3b0 00007ffd`0d96e825 DUser!CoreSC::WaitMessage+0xa6
00000001`9b83e410 00007ffd`104bff92 DUser!MphWaitMessageEx+0x31
00000001`9b83e440 00007ffd`121ac99f USER32!_ClientWaitMessageExMPH+0x1a
00000001`9b83e490 00007ffd`1049102a ntdll!KiUserCallbackDispatcherContinue
00000001`9b83e4f8 00007ffd`104c07e3 USER32!NtUserWaitMessage+0xa
00000001`9b83e500 00007ffd`104c219a USER32!DialogBox2+0x133
00000001`9b83e590 00007ffd`104c2212 USER32!InternalDialogBox+0x132
00000001`9b83e5f0 00007ffd`104c2248 USER32!DialogBoxIndirectParamAorW+0x56
00000001`9b83e630 00007ffd`0db1a596 USER32!DialogBoxIndirectParamW+0x18
00000001`9b83e670 00007ffd`0daba783 comctl32!SHFusionDialogBoxIndirectParam+0x5a
00000001`9b83e6b0 00007ffd`106bca0a comctl32!CTaskDialog::Show+0x163
00000001`9b83e740 00007ffd`106a7e4c SHLWAPI!TaskDialogIndirect+0x52
00000001`9b83e770 00007ffd`10c3136a SHLWAPI!ShellMessageBoxW+0x164
00000001`9b83e940 00007ffd`10c65350 SHELL32!SHSysErrorMessageBox+0xf6
00000001`9b83ede0 00007ffd`10c65ef0 SHELL32!_ExecErrorMsgBox+0x204
00000001`9b83ee30 00007ffd`10b43ded SHELL32!SHExecuteErrorMessageBox+0x80
00000001`9b83ee60 00007ffd`10908734 SHELL32!`Microsoft::WRL::Module<1,Microsoft::WRL::Details::DefaultModule<5> >::Create'::`2′::`dynamic atexit destructor for ‘module”+0x40993
00000001`9b83eec0 00007ffd`10908674 SHELL32!CShellExecute::ExecuteNormal+0x94
00000001`9b83eef0 00007ffd`109085e9 SHELL32!ShellExecuteNormal+0x4c
00000001`9b83ef20 00007ffd`03b41226 SHELL32!ShellExecuteExW+0x35
00000001`9b83ef50 00007ff6`39dd1bed cmdext!ShellExecuteWorker+0x7e
00000001`9b83f000 00007ff6`39dd1607 cmd!ExecPgm+0x3d1
00000001`9b83f230 00007ff6`39dd1697 cmd!ECWork+0xa3
00000001`9b83f4a0 00007ff6`39dd1379 cmd!FindFixAndRun+0x2ec
00000001`9b83f930 00007ff6`39dd5e89 cmd!Dispatch+0xa1
00000001`9b83f9c0 00007ff6`39dd66c8 cmd!main+0x191
00000001`9b83fa50 00007ffd`11fd168d cmd!eErrorLevel+0x299
00000001`9b83fa90 00007ffd`12184629 KERNEL32!BaseThreadInitThunk+0xd
00000001`9b83fac0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

.  3  Id: 1b24.1ccc Suspend: 1 Teb: 00007ff6`3915c000 Unfrozen
      Start: ntdll!TppWorkerThread (00007ffd`12138e30)
      Priority: 0  Priority class: 32  Affinity: 3
Child-SP          RetAddr           Call Site
00000001`9dc2f748 00007ffd`121390b6 ntdll!NtWaitForWorkViaWorkerFactory+0xa
00000001`9dc2f750 00007ffd`11fd168d ntdll!TppWorkerThread+0x286
00000001`9dc2fb40 00007ffd`12184629 KERNEL32!BaseThreadInitThunk+0xd
00000001`9dc2fb70 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

.  5  Id: 1b24.1d04 Suspend: 1 Teb: 00007ff6`39158000 Unfrozen
      Start: combase!CRpcThreadCache::RpcWorkerThreadEntry (00007ffd`0f9b0310)
      Priority: 0  Priority class: 32  Affinity: 3
Child-SP          RetAddr           Call Site
00000001`9de2f618 00007ffd`0f5f13ad ntdll!NtWaitForMultipleObjects+0xa
00000001`9de2f620 00007ffd`0f9924fa KERNELBASE!WaitForMultipleObjectsEx+0xe1
00000001`9de2f900 00007ffd`0f9925a8 combase!WaitCoalesced+0x96 [d:\blue_gdr\com\published\comutils\coalescedwait.cxx @ 72]
00000001`9de2fb50 00007ffd`0f9ba5e1 combase!CROIDTable::WorkerThreadLoop+0x78 [d:\blue_gdr\com\combase\dcomrem\refcache.cxx @ 1480]
00000001`9de2fba0 00007ffd`0f9ba781 combase!CRpcThread::WorkerLoop+0x31 [d:\blue_gdr\com\combase\dcomrem\threads.cxx @ 264]
00000001`9de2fe10 00007ffd`11fd168d combase!CRpcThreadCache::RpcWorkerThreadEntry+0x46 [d:\blue_gdr\com\combase\dcomrem\threads.cxx @ 67]
00000001`9de2fe40 00007ffd`12184629 KERNEL32!BaseThreadInitThunk+0xd
00000001`9de2fe70 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

.  6  Id: 1b24.9f4 Suspend: 1 Teb: 00007ff6`39155000 Unfrozen
      Start: msvcrt!endthreadex+0x30 (00007ffd`103399b0)
      Priority: 0  Priority class: 32  Affinity: 3
Child-SP          RetAddr           Call Site
00000001`9df4f818 00007ffd`0f5f13ad ntdll!NtWaitForMultipleObjects+0xa
00000001`9df4f820 00007ffd`10493b10 KERNELBASE!WaitForMultipleObjectsEx+0xe1
00000001`9df4fb00 00007ffd`0d9311d2 USER32!RealMsgWaitForMultipleObjectsEx+0x100
00000001`9df4fbb0 00007ffd`0d94e887 DUser!CoreSC::xwProcessNL+0x142
00000001`9df4fc50 00007ffd`0d94e7d3 DUser!GetMessageExA+0x67
00000001`9df4fca0 00007ffd`10339967 DUser!ResourceManager::SharedThreadProc+0xf3
00000001`9df4fd30 00007ffd`10339a0d msvcrt!beginthreadex+0x123
00000001`9df4fd60 00007ffd`11fd168d msvcrt!endthreadex+0xac
00000001`9df4fd90 00007ffd`12184629 KERNEL32!BaseThreadInitThunk+0xd
00000001`9df4fdc0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

.  7  Id: 1b24.232c Suspend: 1 Teb: 00007ff6`39153000 Unfrozen
      Start: ntdll!DbgUiRemoteBreakin (00007ffd`121db930)
      Priority: 0  Priority class: 32  Affinity: 3
Child-SP          RetAddr           Call Site
00000001`a248f958 00007ffd`121db964 ntdll!DbgBreakPoint
00000001`a248f960 00007ffd`11fd168d ntdll!DbgUiRemoteBreakin+0x34
00000001`a248f990 00007ffd`12184629 KERNEL32!BaseThreadInitThunk+0xd
00000001`a248f9c0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

Total threads: 6
Duplicate callstacks: 1 (windbg thread #s follow):
4

Using ProcMon and filtering on path contains Aqire32.exe and operation is CreateFile we can see the following process open the EXE before it fails when launched from a command prompt:

  • MsMpEng.exe (Antimalware Service Executable)
  • csrss.exe (Client Server Runtime Process)
  • svchost.exe (Host Process for Windows Services)
  • consent.exe (Consent UI for administrative applications)

image

We can check what service svchost.exe contains by looking for the service DLL in stack trace properties. Here we find it is Application Information Service 

image

You can see from ProcExp quite a few services are hosted in this process:

image

Looking at consent.exe stack in ProcMon we can see a cert check is occurring before failure:

image

Using Rohitab API Monitor (http://www.rohitab.com/apimonitor)

I enabled monitoring of Security and Identity along with System Administration, System Services, and String Manipulation under Visual C++ Library

image

I ensured “Monitor child process” was ticked

image

So we start monitoring this process:

image

From this we can see the Application Information service calls function CheckElevation

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
31312    8:12:50.132 AM    9    appinfo.dll    CheckElevation ( “C:\qik-qube2\QARUN\ARECURRENT\AQIRE32.exe”, 0x00000068dc2eeb3c, NULL, 0x00000068dc2eeb04, 0x00000068dc2eeb10 )    ERROR_SUCCESS        0.0006713

Then application information launches consent.exe

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
31365    8:12:50.147 AM    9    KERNEL32.DLL    CreateProcessAsUserW ( 0x0000000000000a54, NULL, “consent.exe 2736 364 00000068DC8DD760″, NULL, NULL, FALSE, CREATE_SUSPENDED | CREATE_UNICODE_ENVIRONMENT | EXTENDED_STARTUPINFO_PRESENT, NULL, NULL, 0x00000068dc2ee300, 0x00000068dc2ee290 )    TRUE        0.0013189

Then consent.exe performs:

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
1827    8:12:50.365 AM    1    WINTRUST.dll    CryptSIPRetrieveSubjectGuid ( “C:\qik-qube2\QARUN\ARECURRENT\AQIRE32.exe”, 0x0000000000000158, IID_NULL )    TRUE        0.0000770

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
1834    8:12:50.365 AM    1    WINTRUST.dll    CryptSIPLoad ( {c689aab8-8e78-11d0-8c47-00c04fc295ee}, 0, 0x0000005187ca72f0 )    TRUE        0.0010002

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
1965    8:12:50.381 AM    1    WINTRUST.dll    CryptSIPGetCaps ( 0x0000005187ca7240, 0x00000051879ef010 )    TRUE        0.0001413

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
2166    8:12:50.397 AM    1    WINTRUST.dll    CryptSIPRetrieveSubjectGuidForCatalogFile ( “CATADMIN”, 0x0000000000000158, {00000014-0000-0000-0800-000000000000} )    TRUE        0.0000360

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
2168    8:12:50.397 AM    1    WINTRUST.dll    CryptSIPLoad ( {c689aab8-8e78-11d0-8c47-00c04fc295ee}, 0, 0x00000051879ef1f0 )    TRUE        0.0000090

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
2292    8:12:50.397 AM    1    WINTRUST.dll    CryptEncodeObject ( PKCS_7_ASN_ENCODING | X509_ASN_ENCODING, 2004, 0x0000005187ca7938, NULL, 0x00000051879eefd8 )    TRUE        0.0009945

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
2616    8:12:50.413 AM    1    WINTRUST.dll    CryptFindOIDInfo ( CRYPT_OID_INFO_OID_KEY, 0x00007ffd0f5b8838, 1 )    0x00007ffd0f75e920        0.0031781

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
3155    8:12:50.475 AM    1    WINTRUST.dll    CryptFindOIDInfo ( CRYPT_OID_INFO_OID_KEY, 0x00007ffd0f5b8838, 1 )    0x00007ffd0f75e920        0.0000004

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
3155    8:12:50.475 AM    1    WINTRUST.dll    CryptFindOIDInfo ( CRYPT_OID_INFO_OID_KEY, 0x00007ffd0f5b8838, 1 )    0x00007ffd0f75e920        0.0000004
3162    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “AlgorithmName” )    1        0.0000000
3163    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “HashDigestLength” )    -1        0.0000000
3164    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “ObjectLength” )    -1        0.0000004
3165    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “MultiObjectLength” )    -1        0.0000000
3166    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “HashOIDList” )    -1        0.0000004
3167    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashBlockLength”, “HashBlockLength” )    0        0.0000000
3168    8:12:50.475 AM    1    bcrypt.dll    wcscmp ( “HashDigestLength”, “ProviderHandle” )    -1        0.0000000
3169    8:12:50.475 AM    1    bcrypt.dll    wcscmp ( “HashDigestLength”, “PrimitiveType” )    -1        0.0000004
3170    8:12:50.475 AM    1    bcrypt.dll    wcscmp ( “HashDigestLength”, “IsKeyedHash” )    -1        0.0000004
3171    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashDigestLength”, “AlgorithmName” )    1        0.0000000
3172    8:12:50.475 AM    1    bcryptPrimitives.dll    wcscmp ( “HashDigestLength”, “HashDigestLength” )    0        0.0000000
3173    8:12:50.475 AM    1    bcrypt.dll    wcscmp ( “HashDigestLength”, “ObjectLength” )    -1        0.0000000
3174    8:12:50.475 AM    1    bcrypt.dll    wcscmp ( “HashDigestLength”, “MultiObjectLength” )    -1        0.0000000

After this we see an error is displayed:

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
3214    8:12:50.475 AM    1    WINTRUST.dll    _vsnprintf ( 0x00000051879eef50, 511, “CatalogDB: %s: %s at line #%u encountered error 0x%.8lx
“, 0x00000051879eee18 )    89        0.0000041

In comparison with the fixed EXE when consent.exe runs instead of the error we see:

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
2833    8:21:13.531 AM    1    WINTRUST.dll    CryptMsgGetParam ( 0x000000e4c813ac90, CMSG_SIGNER_AUTH_ATTR_PARAM, 0, NULL, 0x000000e4c80bec80 )    TRUE        0.0000414
2879    8:21:13.531 AM    1    WINTRUST.dll    CryptMsgGetParam ( 0x000000e4c813ac90, CMSG_SIGNER_AUTH_ATTR_PARAM, 0, 0x000000e4c8143610, 0x000000e4c80bec80 )    TRUE        0.0002662
2997    8:21:13.563 AM    1    WINTRUST.dll    CertFindAttribute ( “1.3.6.1.4.1.311.2.4.2”, 4, 0x000000e4c8143620 )    NULL    0 = The operation completed successfully.     0.0000008
2998    8:21:13.563 AM    1    WINTRUST.dll    CryptMsgGetParam ( 0x000000e4c813ac90, CMSG_SIGNER_UNAUTH_ATTR_PARAM, 0, NULL, 0x000000e4c80bec80 )    FALSE    -2146889713 = The cryptographic message does not contain all of the requested attributes.     0.0000213
3010    8:21:13.563 AM    1    WINTRUST.dll    CertOpenStore ( CERT_STORE_PROV_MSG, PKCS_7_ASN_ENCODING | X509_ASN_ENCODING, 0x000000e4c8136470, CERT_STORE_NO_CRYPT_RELEASE_FLAG, 0x000000e4c813ac90 )    0x000000e4c8127fb0        0.0004768

#    Time of Day    Thread    Module    API    Return Value    Error    Duration
3953    8:21:13.750 AM    1    WINTRUST.dll    CertFindAttribute ( “1.2.840.113549.1.9.6”, 0, NULL )    NULL    0 = The operation completed successfully.     0.0000000
3954    8:21:13.750 AM    1    WINTRUST.dll    CertFindAttribute ( “1.3.6.1.4.1.311.3.3.1”, 0, NULL )    NULL    0 = The operation completed successfully.     0.0000000
3956    8:21:13.750 AM    1    WINTRUST.dll    CryptMsgControl ( 0x000000e4c813ac90, 0, CMSG_CTRL_VERIFY_SIGNATURE_EX, 0x000000e4c80becc0 )    TRUE        0.0006312

 

 

 

 

 

 

 

 

 

 

 


 

Posted in .NET, API Monitor, Debugging, ProcMon, WinDbg | Tagged | Leave a comment

Debugging A PowerShell String

A friend had asked for some assistance with a script that was adding objects into Active Directory. It was failing to create Active Directory groups – “Invalid DN Syntax” was the descriptive message we received.

However the DN syntax appeared to be valid:

image

And when we copied and pasted the text from $groupname it worked fine…

image

So what was the difference?

To find if the strings were different we did a compare:

image

OK, trimmed they match. But when we surrounded $groupname with exclamation points there weren’t any spaces or tabs…

To find out why we check the string at byte level. To do this we used:

[System.Text.Encoding]::Unicode.GetBytes($groupname)

Broken Working

77
0
121
0
65
0
68
0
71
0
114
0
111
0
117
0
112
0
13
0

77
0
121
0
65
0
68
0
71
0
114
0
111
0
117
0
112
0

We can see the broken one has a carriage return at the end ( In PowerShell “`r” )

The problem was a file had been retrieved split by line feed ( In PowerShell “`n”) But Windows text files usually end in Carriage Return + Line Feed (“`r`n”) It is the line feed that moves text onto the next line, so that is why we didn’t see any spaces when printing string in PowerShell. PowerShell just doesn’t display the unprintable characters.

In the days of VBScript I found similar issues with tabs in the text file. In the case of VBScript the Trim function doesn’t remove these.

Posted in Debugging, PowerShell | Tagged | Leave a comment

When Windows 8.1 VM Host Runs Out of Disk Space…

When copying a large file in Windows 8.1 Parallels Virtual Machine, the host ran out of disk space…

image

We can see from the stack trace explorer was copying file at time of crash…

0: kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

IRQL_NOT_LESS_OR_EQUAL (a)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high.  This is usually
caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arguments:
Arg1: 0000000000000000, memory referenced
Arg2: 0000000000000002, IRQLw
Arg3: 0000000000000000, bitfield :
    bit 0 : value 0 = read operation, 1 = write operation
    bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)
Arg4: fffff8007689692a, address which referenced memory

Debugging Details:
——————

READ_ADDRESS: unable to get nt!MmNonPagedPoolStart
unable to get nt!MmSizeOfNonPagedPoolInBytes
0000000000000000

CURRENT_IRQL:  2

FAULTING_IP:
nt!MiAddViewsForSection+22
fffff800`7689692a 488b01          mov     rax,qword ptr [rcx]

DEFAULT_BUCKET_ID:  WIN8_DRIVER_FAULT

BUGCHECK_STR:  AV

PROCESS_NAME:  explorer.exe

ANALYSIS_VERSION: 6.3.9600.17029 (debuggers(dbg).140219-1702) amd64fre

TRAP_FRAME:  ffffd00021a6cd90 — (.trap 0xffffd00021a6cd90)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=ffffd00021a6cf88 rbx=0000000000000000 rcx=0000000000000000
rdx=000000000005b500 rsi=0000000000000000 rdi=0000000000000000
rip=fffff8007689692a rsp=ffffd00021a6cf20 rbp=ffffe001f0f943d0
r8=fffff6d80022b000  r9=ffffd00021a6cfd0 r10=fffff6c000000000
r11=ffffd00021a6cf60 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei ng nz na pe nc
nt!MiAddViewsForSection+0x22:
fffff800`7689692a 488b01          mov     rax,qword ptr [rcx] ds:00000000`00000000=????????????????
Resetting default scope

LAST_CONTROL_TRANSFER:  from fffff8007697dae9 to fffff80076971fa0

STACK_TEXT: 
ffffd000`21a6cc48 fffff800`7697dae9 : 00000000`0000000a 00000000`00000000 00000000`00000002 00000000`00000000 : nt!KeBugCheckEx
ffffd000`21a6cc50 fffff800`7697c33a : 00000000`00000000 00000000`00000000 fffff800`76b6b000 ffffd000`21a6cd90 : nt!KiBugCheckDispatch+0x69
ffffd000`21a6cd90 fffff800`7689692a : 00000000`00000200 00000000`00000004 00000000`0000002f ffffe001`f08a8770 : nt!KiPageFault+0x23a
ffffd000`21a6cf20 fffff800`768aff8f : 00000000`00000000 00000000`0005b500 00000000`00000000 ffffd000`21a6cfd0 : nt!MiAddViewsForSection+0x22
ffffd000`21a6cf90 fffff800`768ae0d7 : fffff800`7681e000 00000000`00000001 00000000`00000001 fffff800`76b04830 : nt!MmMapViewInSystemCache+0x113
ffffd000`21a6d100 fffff800`7689f6ff : 00000000`00000001 ffffe001`eeae2010 00000000`00000000 00000000`00000000 : nt!CcGetVacbMiss+0xef
ffffd000`21a6d190 fffff800`7689bd13 : 00000000`00000000 00000000`5b500000 ffffd000`21a6d298 ffffd000`21a6d26c : nt!CcGetVirtualAddress+0x36f
ffffd000`21a6d230 fffff800`7689b313 : ffffe001`eeae2010 00000000`37782040 ffffd000`21a6d388 00000000`00100000 : nt!CcMapAndCopyInToCache+0x157
ffffd000`21a6d320 fffff800`769e07e9 : ffffe001`f14705c0 ffffe001`f14705c0 00000000`5b500000 00000000`5b500000 : nt!CcCopyWriteEx+0x1bb
ffffd000`21a6d3c0 fffff800`8922d393 : ffffc000`805b3480 ffffe001`f14705c0 fffff800`89230500 00000000`5b500000 : nt!CcCopyWrite+0x19
ffffd000`21a6d400 fffff800`8920a841 : ffffe001`f148ea80 ffffe001`f14705c0 ffffe001`ef2ec000 00000000`00000000 : prl_fs+0x2d393
ffffd000`21a6d5d0 fffff800`8921ebb1 : fffff800`892112e0 ffffe001`f0659600 ffffe001`f14705c0 ffffe001`ef2ec040 : prl_fs+0xa841
ffffd000`21a6d6c0 fffff800`89204b77 : ffffe001`f14705c0 ffffe001`f14705c0 ffffe001`f0659680 ffffe001`f0659680 : prl_fs+0x1ebb1
ffffd000`21a6d6f0 fffff800`88c083cd : ffffe001`f14705c0 00000000`00000000 fffff800`88c05010 ffffe001`ee36b8a0 : prl_fs+0x4b77
ffffd000`21a6d720 fffff800`8861ccf8 : ffffd000`21a6d860 00000000`00000000 ffffc000`78ab6770 00000000`00000000 : mup!MupFsdIrpPassThrough+0x1ee
ffffd000`21a6d7a0 fffff800`8861b0b6 : ffffe001`eeea7df0 ffffe001`f0659680 ffffe001`f14705c0 fffff800`8861fcdf : fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x258
ffffd000`21a6d840 fffff800`76c238ec : 00000000`00000001 ffffd000`21a6d921 ffffe001`f0659680 fffff800`88645ac1 : fltmgr!FltpDispatch+0xb6
ffffd000`21a6d8a0 fffff800`76c23298 : ffffe001`f0659604 ffffe001`f0659680 ffffe001`f0d4afe0 ffffe001`f0659680 : nt!IopSynchronousServiceTail+0x16c
ffffd000`21a6d970 fffff800`7697d7b3 : ffffe001`f1ad5801 00000000`00003918 00000000`00000000 00000000`224ffd90 : nt!NtWriteFile+0x750
ffffd000`21a6da90 00007ff8`68f6ac0a : 00007ff8`66363979 00000000`224ffd90 00000000`00000001 00000000`ffffffff : nt!KiSystemServiceCopyEnd+0x13
00000000`3700cfc8 00007ff8`66363979 : 00000000`224ffd90 00000000`00000001 00000000`ffffffff 00000000`224ffd60 : ntdll!NtWriteFile+0xa
00000000`3700cfd0 00007ff8`66387e0e : 00000000`5b500000 00000000`5b500000 00000000`00000008 00000000`00000000 : KERNELBASE!WriteFile+0x10c
00000000`3700d050 00007ff8`663861eb : 00000000`00004001 00000000`00000002 00000000`48200000 00000000`00000000 : KERNELBASE!BaseCopyStream+0x9c8
00000000`3700df00 00007ff8`663df751 : 00000000`229ad198 00000000`3700e508 00000000`000002a8 00007ff8`66e42c2d : KERNELBASE!BasepCopyFileExW+0x74f
00000000`3700e4e0 00007ff8`66c99a8e : 00000000`2feb8b50 00000000`80070bea 00000000`00000000 ffffffff`ffffffff : KERNELBASE!CopyFile2+0xd9
00000000`3700e5a0 00007ff8`6706e2be : 00000000`00000000 00000000`00000000 00000000`00000000 00007ff8`66c84ac9 : SHELL32!CFSTransfer::_PerformCopyFileWithRetry+0xde
00000000`3700e650 00007ff8`66c84317 : 00000000`3700e9e0 00000000`00000000 00000000`2fe61228 00000000`229ae000 : SHELL32!CFSTransfer::CopyItem+0x23a
00000000`3700e6c0 00007ff8`66c840f8 : 00000000`223116c0 00000000`226f26f0 00000000`226f26f0 00000000`3700e860 : SHELL32!CCopyOperation::_CreateDestinationOrCopyItemWithRetry+0x9b
00000000`3700e760 00007ff8`66a66bf9 : 00000000`22256680 00000000`12ca0c40 00000000`226f26f0 00000000`12ca0c40 : SHELL32!CCopyOperation::Do+0x134
00000000`3700ea40 00007ff8`66a67806 : 00000000`12ca0c40 00000000`12ca0c40 00000000`3700eb40 00000000`226f26f0 : SHELL32!CCopyWorkItem::_DoOperation+0x49
00000000`3700eab0 00007ff8`66a697db : 00000000`12ca0c40 00000000`12ca0c40 00000000`3700eef0 00000000`00000000 : SHELL32!CCopyWorkItem::_SetupAndPerformOp+0x23a
00000000`3700edf0 00007ff8`66a69645 : 00000000`14a2e780 00000000`14a2e780 00000000`14a2e780 00000000`14a2e780 : SHELL32!CCopyWorkItem::ProcessWorkItem+0x14b
00000000`3700f0b0 00007ff8`66a67d6f : 00000000`2fe61228 00000000`2fe61228 00000000`00000000 00000000`14a2e780 : SHELL32!CRecursiveFolderOperation::Do+0x195
00000000`3700f150 00007ff8`66a6919c : 00000000`3022e9f0 00000000`3700f259 00000000`3022eb28 00000000`00000000 : SHELL32!CFileOperation::_EnumRootDo+0x23b
00000000`3700f1f0 00007ff8`66a6f212 : 00000000`00000000 00000000`00000000 00000000`3022e9f0 00000000`3022ea00 : SHELL32!CFileOperation::PrepareAndDoOperations+0x19c
00000000`3700f2c0 00007ff8`6707f37e : 00000000`222e2f28 00000000`00000001 00000000`00000000 00000000`144f7430 : SHELL32!CFileOperation::PerformOperations+0xd2
00000000`3700f310 00007ff8`6707d96e : 00000000`226f03f0 00000000`226f03f0 00000000`00000000 00000000`144f7430 : SHELL32!CFSDropTargetHelper::_MoveCopyHIDA+0x232
00000000`3700f3c0 00007ff8`6707ff2a : 00000000`00000052 00000000`144f7430 00000000`00000000 00000000`00000048 : SHELL32!CFSDropTargetHelper::_Drop+0x2be
00000000`3700f690 00007ff8`64bd8023 : 00000000`00000001 00000000`00000001 00000000`00000000 00000000`00000000 : SHELL32!CFSDropTargetHelper::s_DoDropThreadProc+0x3e
00000000`3700f6c0 00007ff8`68c9168d : 00000000`24a3c480 00000000`00000000 00000000`00000000 00000000`00000000 : SHCORE!Microsoft::WRL::FtmBase::MarshalInterface+0x17b
00000000`3700f7e0 00007ff8`68f44629 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : KERNEL32!BaseThreadInitThunk+0xd
00000000`3700f810 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

Posted in WinDbg | Tagged | Leave a comment

Continuing Case of ByRef Corruption–.NET Patching

A new revision of app we previously met here http://chentiangemalc.wordpress.com/2014/05/22/case-of-the-invalid-base-key-error/ was out…

The “Invalid Base Key” error had been patched, but now we had another. It looked like another case of variables being unexpectedly modified due to liberal and incorrect use of By Reference.

I also noticed the recommendation to change ByRef into ByVal hadn’t been followed. Instead…

if (szBaseKey.ToString() == “”)
{
  Information.Err().Raise(-2147220989, “RegIni Class”, “Invalid Base Key”, null, null);
}

had been replaced with

if (szBaseKey.ToString() == “”)
{
}

Certainly eliminated the error message though.

In this new case however it seemed multiple API calls may be impacted. Majority of them were called by a function called QueryValue. So I wanted to change that function to use it’s parameters “by value” instead of “by reference”

Using ILDasm from Windows SDK I decompiled the EXE, and it was easy enough to patch the function definition to use “by value” I just had to remove the ampersands:

From

.method public instance object  QueryValue(int32& lhKey,
                                             string& szKeyName,
                                             string& szValueName,
                                             [opt] bool& bSupressErrorMessage) cil managed noinlining nooptimization
 

to

.method public instance object  QueryValue(int32 lhKey,
                                             string szKeyName,
                                             string szValueName,
                                             [opt] bool bSupressErrorMessage) cil managed noinlining nooptimization
 


However this also requires updating all the calls to the method. To easily do this you want a text editor that supports multi-line search & replace. In this case I used UltraEdit (http://www.ultraedit.com/downloads/ultraedit_download.html)

image

I had to do this twice as calls to this function had been formatted in two different ways. To ensure none were let I searched for QueryValue(int32&

With that we recompiled our IL file. This was .NET 2.0 app so I used .NET 2.0 version of ilasm:

c:\windows\microsoft.net\framework\v2.0.50727\ilasm.exe qfbox2.il /resource=qfbox2.res

However the fresh EXE didn’t work:

image

Using Visual Studio I set Debug –> Exceptions and ticked all boxes

image

Then launched EXE with Visual Studio .NET Reflector add-in “Debug an Executable”

image

then

image

Looking at this we can see our bSupressErrorMessage had been turned into an array. This is because accessing the “by reference” value different code gets generated.

For example this C# code:

public object QueryValue(ref int lhKey,ref string szKeyName, ref string szValueName,ref bool bSupressErrorMessage) { if (!bSupressErrorMessage) { Console.WriteLine("by reference: bSupressErrorMessage NOT true"); } return null; } public object QueryValue(int lhKey, string szKeyName, string szValueName, bool bSupressErrorMessage) { if (!bSupressErrorMessage) { Console.WriteLine("by value: bSupressErrorMessage NOT true"); } return null; }

Generates the following IL code:

.method public hidebysig instance object QueryValue(int32& lhKey, string& szKeyName, string& szValueName, bool& bSupressErrorMessage) cil managed { .maxstack 1 .locals init ( [0] object obj2, [1] bool flag) L_0000: nop L_0001: ldarg.s bSupressErrorMessage L_0003: ldind.i1 L_0004: stloc.1 L_0005: ldloc.1 L_0006: brtrue.s L_0015 L_0008: nop L_0009: ldstr "by reference: bSupressErrorMessage NOT true" L_000e: call void [mscorlib]System.Console::WriteLine(string) L_0013: nop L_0014: nop L_0015: ldnull L_0016: stloc.0 L_0017: br.s L_0019 L_0019: ldloc.0 L_001a: ret } .method public hidebysig instance object QueryValue(int32 lhKey, string szKeyName, string szValueName, bool bSupressErrorMessage) cil managed { .maxstack 1 .locals init ( [0] object obj2, [1] bool flag) L_0000: nop L_0001: ldarg.s bSupressErrorMessage L_0003: stloc.1 L_0004: ldloc.1 L_0005: brtrue.s L_0014 L_0007: nop L_0008: ldstr "by value: bSupressErrorMessage NOT true" L_000d: call void [mscorlib]System.Console::WriteLine(string) L_0012: nop L_0013: nop L_0014: ldnull L_0015: stloc.0 L_0016: br.s L_0018 L_0018: ldloc.0 L_0019: ret }

In both cases we can see a local variable is created

[1] bool flag

Then bSupressErrorMessage argument is loaded onto the stack:

ldarg.s bSupressErrorMessage

Now only the “by reference” version performs:

ldind.i1 (Loads a value of type int8 as an int32 onto the evaluation stack indirectly.)

Then both versions continue the same:

Pops the current value from the top of the evaluation stack and stores it in a the local variable list at index 1. (This saving our argument into the bool flag)

stloc.1

Loads the local variable at index 1 onto the evaluation stack.

ldloc.1

Transfers control to a target instruction (short form) if value is true, not null, or non-zero.

brtrue.s <target>

In our crashing code we found:

IL_012c:  ldarg.s    bSupressErrorMessage
    IL_012e:  ldind.i1
    IL_012f:  ldc.i4.0
    IL_0130:  ceq
    IL_0132:  stloc.s    V_10
    IL_0134:  ldloc.s    V_10
 

We removed the

ldind.i1

We can double check our patch with .NET reflector, we can see the [0] is gone…

image

And the app no longer crashes…

Posted in .NET, Hacking, MSIL, Patching | Tagged | Leave a comment