{"id":101034,"date":"2019-02-06T23:00:00","date_gmt":"2019-02-07T14:00:00","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/oldnewthing\/?p=101034"},"modified":"2019-03-18T11:17:43","modified_gmt":"2019-03-18T18:17:43","slug":"20190207-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20190206-00\/?p=101034","title":{"rendered":"The Intel 80386, part 14: Rescuing a stack trace after the debugger gave up when it reached an FPO function"},"content":{"rendered":"<p>So here you go, minding your own business, taking a stack trace, and then the world stops. <\/p>\n<pre>\nChildEBP RetAddr\n0019ec98 5654ef4e combase!CoInitializeEx+0x35\n0019ecf8 5654e70b WINSPOOL!GetCurrentNetworkId+0x36\n0019ed28 5654e58a WINSPOOL!InternalGetDefaultPrinter+0x8b\n0019ed58 75953b77 WINSPOOL!GetDefaultPrinterW+0x5a\n0019ed70 7594e6b8 comdlg32!PrintGetDefaultPrinterName+0x17\n0019f1b8 7594e520 comdlg32!PrintBuildDevNames+0x60\n0019f1d0 75951340 comdlg32!PrintReturnDefault+0x30\n0019f628 759a03ab comdlg32!PrintDlgX+0x132\n0019fae0 01804a8e comdlg32!PrintDlgA+0x5b\n0019fd50 7686196c contoso+0x4a8e\n<\/pre>\n<p>The stack trace just gives up. The function in the Cnotoso DLL was compiled with frame pointer omission (FPO), which means that the <var>ebp<\/var> register is being used as a general-purpose register and does not point to the next frame deeper in the stack. And since we don&#8217;t have symbols for Contoso, the debugger cannot consult the symbol table to get help with unwinding the stack one more level. <\/p>\n<p>We&#8217;ll have to build the stack trace manually. This is basically the same exercise on every architecture: You look at the code you&#8217;re returning to, find its function prologue or epilogue, and use that information to unwind another frame. <\/p>\n<p>The last known good stack frame was <code>0019fae0<\/code> from <code>Print&shy;DlgA<\/code>. Let&#8217;s see what we have there: <\/p>\n<pre>\n0:000&gt; dps 0019fae0\n0019fae0  0019fd50                &larr; saved ebp\n0019fae4  01804a8e contoso+0x4a8e &larr; return address\n0019fae8  018083b0 contoso+0x83b0 &larr; argument to PrintDlgA\n0019faec  0000000e\n0019faf0  01803b8c contoso+0x3b8c\n0019faf4  0019fd50\n0019faf8  0000000e\n0019fafc  0000000e\n0019fb00  00200cce\n0019fb04  00000112\n0019fb08  0000f095\n0019fb0c  0078006b\n<\/pre>\n<p>The <code>Print&shy;DlgA<\/code> function takes a single parameter, and it uses the <code>__stdcall<\/code> calling convention, so we know that when <code>Print&shy;DlgA<\/code> returns, the stack pointer will be at <code>0019faec<\/code>, and we will have returned to the code at <code>01804a8e<\/code>. We also see that the <var>ebp<\/var> register will have the value <code>0019fd50<\/code>. <\/p>\n<p>To unwind a level, we need to disassemble at <code>01804a8e<\/code> and look for the code that cleans up the stack and returns to the previous function. <\/p>\n<pre>\ncontoso+0x4a8e:\n01804a8e 833dbc83800100  cmp     dword ptr [contoso+0x83bc (018083bc)],0\n01804a95 7509            jne     contoso+0x4aa0 (01804aa0)\n01804a97 b8ffffffff      mov     eax,0FFFFFFFFh\n01804a9c 5e              pop     esi\n01804a9d c3              ret\n<\/pre>\n<p>For the purpose of this exercise, we are just looking for any code path that leads to a <code>ret<\/code> instruction. We can assume conditional jumps are taken, or not taken, based on whichever case will get us to a <code>ret<\/code> instruction faster. Along the way to the <code>ret<\/code>, we watch for instructions that affect the <var>esp<\/var> register, because we&#8217;ll have to simulate them in our head. <\/p>\n<p>In this case, we can pretend that the conditional jump is not taken, and that leads us quickly to a <code>pop esi<\/code> and a <code>ret<\/code>. <\/p>\n<p>So let&#8217;s simulate those two operations. Since our simulated <var>esp<\/var> register is at <code>0019faec<\/code>, the <code>pop esi<\/code> pops the value <code>0000000e<\/code> into <var>esi<\/var>, and the <code>ret<\/code> returns to <code>01803b8c<\/code>. Since this was a simple <code>ret<\/code> with no parameters, there is no extra cleanup, and the stack pointer is left pointing to <code>0019faf4<\/code>. <\/p>\n<pre>\n0019faec  0000000e                &larr; saved esi\n0019faf0  01803b8c contoso+0x3b8c &larr; return address\n0019faf4  0019fd50                &larr; esp points here after ret\n0019faf8  0000000e\n<\/pre>\n<p>Disassemble at the return address to see how to pop out another level. <\/p>\n<pre>\ncontoso+0x3b8c:\n01803b8c 8bd8            mov     ebx,eax\n01803b8e 0bdb            or      ebx,ebx\n01803b90 7510            jne     contoso+0x3ba2 (01803ba2)\n01803b92 b8fbffffff      mov     eax,0FFFFFFFBh\n01803b97 5d              pop     ebp        &larr; saved ebp\n01803b98 5f              pop     edi        &larr; saved edi\n01803b99 5e              pop     esi        &larr; saved esi\n01803b9a 5b              pop     ebx        &larr; saved ebx\n01803b9b 81c4e8000000    add     esp,0E8h  &larr; adjust esp\n01803ba1 c3              ret               &larr; return, no extra cleanup\n<\/pre>\n<p>Again, we pretend that the conditional jump is not taken, and that leads us quickly to the function epilogue. We pop four values off the stack, then add <code>0e8h<\/code> to the <var>esp<\/var> register before executing the <code>ret<\/code>. Let&#8217;s simulate those operations on our stack. <\/p>\n<pre>\n0019faf4  0019fd50       &larr; saved ebp\n0019faf8  0000000e       &larr; saved edi\n0019fafc  0000000e       &larr; saved esi\n0019fb00  00200cce       &larr; saved ebx\n0019fb04  00000112       &larr; esp points here after pop ebx\n<\/pre>\n<p>After popping <var>ebx<\/var>, the code adds <code>0E8h<\/code> to <var>esp<\/var>, so let&#8217;s ask the debugger to skip ahead <code>0xe8<\/code> bytes. <\/p>\n<pre>\n0:000&gt; dps 0019fb04+e8\n0019fbec  01801325 contoso+0x1325 &larr; return address\n0019fbf0  0000000e                &larr; esp points here after ret\n<\/pre>\n<p><a HREF=\"https:\/\/www.youtube.com\/watch?v=0Hkn-LSh7es\">Just keep swimming<\/a>. <\/p>\n<pre>\n01801325 0bc0            or      eax,eax\n01801327 0f8d74040000    jge     contoso+0x17a1 (018017a1)\n0180132d 83f8fd          cmp     eax,0FFFFFFFDh\n01801330 0f846b040000    je      contoso+0x17a1 (018017a1)\n01801336 83f8fb          cmp     eax,0FFFFFFFBh\n01801339 740d            je      contoso+0x1348 (01801348)\n0180133b 83f8fc          cmp     eax,0FFFFFFFCh\n0180133e 7410            je      contoso+0x1350 (01801350)\n<\/pre>\n<p>Okay, we&#8217;re not so lucky this time. We don&#8217;t see the end of the function right away. The code does a bunch of stuff with the value returned by this function, but if the return value is nonnegative, it jumps ahead to <code>018017a1<\/code>. I&#8217;m guessing that that jump forward will take us closer to the end of the function, so let&#8217;s continue disassembling there. <\/p>\n<pre>\n018017a1 b801000000      mov     eax,1\n018017a6 5f              pop     edi\n018017a7 5e              pop     esi\n018017a8 81c404010000    add     esp,104h\n018017ae c20c00          ret     0Ch\n<\/pre>\n<p>My hunch paid off. We pop two registers, adjust <var>esp<\/var>, and then return with 12 bytes of extra cleanup. <\/p>\n<pre>\n0019fbf0  0000000e            &larr; pop edi\n0019fbf4  00000111            &larr; pop esi\n0019fbf8  00000000            &larr; esp points here after pop esi\n0:000&gt; dps 0019fbf8+0x104  &larr; simulate \"add esp, 104h\"\n0019fcfc  01801fea contoso+0x1fea &larr; return address\n0019fd00  00200cce            &larr; first four bytes of stack arguments\n0019fd04  0000000e            &larr; next four bytes of stack arguments\n0019fd08  00000000            &larr; last four bytes of stack arguments\n0019fd0c  00000111            &larr; esp points here after ret 0Ch\n<\/pre>\n<p>Okay, that was a little trickier because the <code>ret 0Ch<\/code> means that after popping the return address, we also have to add <code>0Ch<\/code> to the <var>esp<\/var> register, leaving it at <code>0019fd0c<\/code>. <\/p>\n<p>On to the next function. <\/p>\n<pre>\ncontoso+0x1fea:\n01801fea 0bc0            or      eax,eax\n01801fec 0f85d6010000    jne     contoso+0x21c8 (018021c8)\n01801ff2 8b44242c        mov     eax,dword ptr [esp+2Ch]\n01801ff6 50              push    eax\n01801ff7 57              push    edi\n01801ff8 56              push    esi\n01801ff9 53              push    ebx\n01801ffa e831060000      call    contoso+0x2630 (01802630)\n01801fff 5f              pop     edi\n01802000 5e              pop     esi\n01802001 5b              pop     ebx\n01802002 83c410          add     esp,10h\n01802005 c21000          ret     10h\n<\/pre>\n<p>This one is a little trickier, for even though the <code>ret<\/code> is in sight, there&#8217;s another function call in between. <\/p>\n<p>I&#8217;m going to assume that the function at <code>01802630<\/code> ends with a <code>ret 10h<\/code>, matching the 16 bytes of parameters pushed immediately prior to the <code>call<\/code>. This is generally a safe bet with the Microsoft C compiler, which prefers to create its entire stack frame at function entry and leave it alone until the function epilogue. <\/p>\n<p>That means that the epilogue starts with the <code>pop edi<\/code>, and we can simulate those instructions as well. <\/p>\n<pre>\n0019fd0c  00000111                &larr; saved edi\n0019fd10  00000000                &larr; saved esi\n0019fd14  01801b90 contoso+0x1b90 &larr; saved ebx\n0019fd18  00000070                                      \\\n0019fd1c  ffffffff                                       \\ skipped by\n0019fd20  ffffffff                                       \/ add esp, 10h\n0019fd24  768617bb USER32!UserCallWinProcCheckWow+0x1fb \/\n0019fd28  7688311b USER32!_InternalCallWinProc+0x2b &larr; return address\n0019fd2c  00200cce\n0019fd30  00000111\n0019fd34  0000000e\n0019fd38  00000000\n0019fd3c  00000000                &larr; esp points here after return\n<\/pre>\n<p>Hooray, we finally returned to a function we have symbols for! That means we can use the <code>k=<\/code> command to resume our stack trace. <\/p>\n<p>The parameters to the <code>k=<\/code> command are <\/p>\n<ul>\n<li>The value to pretend is in <var>ebp<\/var>.<\/li>\n<li>The value to pretend is in <var>esp<\/var>.<\/li>\n<li>The value to pretend is in <var>eip<\/var>.<\/li>\n<\/ul>\n<p>We will pretend that we are just about to execute the <code>ret 10h<\/code> instruction. From our calculations, therefore, immediately after the <code>ret 10h<\/code> instruction, the stack pointer is at <code>0019fd3c<\/code>, the instruction pointer is at <code>7688311b<\/code>, and the <var>ebp<\/var> register has the value&hellip; um, what&#8217;s the value? <\/p>\n<p>Look back through our notes for the most recent simulated <code>pop ebp<\/code>. <\/p>\n<pre>\n0019faf4  0019fd50       &larr; saved ebp\n<\/pre>\n<p>Ah, there it is. Okay, let&#8217;s go for it. <\/p>\n<pre>\n0:000&gt; k=0019fd50 0019fd28 768617bb\nChildEBP RetAddr\n0019fd50 7686196c USER32!_InternalCallWinProc+0x2b\n0019fe34 76860abe USER32!UserCallWinProcCheckWow+0x3ac\n0019fea8 7687d750 USER32!DispatchMessageWorker+0x20e\n0019feb0 018022d1 USER32!DispatchMessageA+0x10\n0019ff70 765b60c9 contoso+0x22d1 &larr; UH-OH\n0019ff80 77d43814 KERNEL32!BaseThreadInitThunk+0x19\n0019ffdc 77d437e4 ntdll!__RtlUserThreadStart+0x2f\n0019ffec 00000000 ntdll!_RtlUserThreadStart+0x1b\n<\/pre>\n<p>Okay, this seems to look good, but there&#8217;s that <code>contoso<\/code> on the stack again. However, this time, the debugger was able to walk the stack past that function. It could mean that the function was compiled with frame pointers enabled, in which case we have a valid stack trace. Or it could mean that the function was compiled with frame pointers omitted, but the value in the <var>ebp<\/var> register happened to point to another frame, which is probably the next <var>ebp<\/var>-based frame. <\/p>\n<p>Since debugging is an exercise in optimism, we&#8217;ll assume that the stack trace is &#8220;good enough&#8221;. It certainly looks reasonable. The <var>ebp<\/var> chain looks reasonable. The next frame is only slightly deeper on the stack. And even if there were some FPO functions in there, we can defer trying to tease them out until our investigation tells us that we need to do so. <\/p>\n<p>So here&#8217;s the stack trace we ended up with at the point we decided we had something &#8220;good enough&#8221;: <\/p>\n<pre>\nChildEBP RetAddr\n0019ec98 5654ef4e combase!CoInitializeEx+0x35\n0019ecf8 5654e70b WINSPOOL!GetCurrentNetworkId+0x36\n0019ed28 5654e58a WINSPOOL!InternalGetDefaultPrinter+0x8b\n0019ed58 75953b77 WINSPOOL!GetDefaultPrinterW+0x5a\n0019ed70 7594e6b8 comdlg32!PrintGetDefaultPrinterName+0x17\n0019f1b8 7594e520 comdlg32!PrintBuildDevNames+0x60\n0019f1d0 75951340 comdlg32!PrintReturnDefault+0x30\n0019f628 759a03ab comdlg32!PrintDlgX+0x132\n0019fae0 01804a8e comdlg32!PrintDlgA+0x5b\n0019fd50 7686196c contoso+0x4a8e\n0019faf0 01803b8c contoso+0x3b8c \\ we reconstructed these\n0019fbec 01801325 contoso+0x1325  &gt; three stack\n0019fcfc 01801fea contoso+0x1fea \/ frames\n0019fd50 7686196c USER32!_InternalCallWinProc+0x2b\n0019fe34 76860abe USER32!UserCallWinProcCheckWow+0x3ac\n0019fea8 7687d750 USER32!DispatchMessageWorker+0x20e\n0019feb0 018022d1 USER32!DispatchMessageA+0x10\n0019ff70 765b60c9 contoso+0x22d1 &larr; UH-OH\n0019ff80 77d43814 KERNEL32!BaseThreadInitThunk+0x19\n0019ffdc 77d437e4 ntdll!__RtlUserThreadStart+0x2f\n0019ffec 00000000 ntdll!_RtlUserThreadStart+0x1b\n<\/pre>\n<p>Now, sure, digging out those three stack frames doesn&#8217;t look that useful because we don&#8217;t have any symbols for Contoso at all, but you may be in a case where you do have symbols for Contoso, but those symbols lack FPO information. In that case, reconstructing stack frames gives you a proper stack trace as if you had FPO information all along. <\/p>\n<p>And those extra stack frames may be the difference between a &#8220;How did we get here?&#8221; and a &#8220;Oh, this is how we got here.&#8221; <\/p>\n<p><a HREF=\"http:\/\/devblogs.microsoft.com\/oldnewthing\/20190208-00\/?p=101036\">Next time<\/a>, we&#8217;ll look at some compiler code generation idioms. <\/p>\n","protected":false},"excerpt":{"rendered":"<p>Pretend to be the computer.<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[2],"class_list":["post-101034","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-history"],"acf":[],"blog_post_summary":"<p>Pretend to be the computer.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/101034","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=101034"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/101034\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=101034"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=101034"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=101034"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}