{"id":93615,"date":"2016-06-08T07:00:00","date_gmt":"2016-06-08T21:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/?p=93615"},"modified":"2019-03-13T11:50:47","modified_gmt":"2019-03-13T18:50:47","slug":"20160608-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20160608-00\/?p=93615","title":{"rendered":"Investigating an app compat problem: Part 1: The initial plunge"},"content":{"rendered":"
\n

Today we’re going to look at an application compatiblity problem. Actually, today, we’ll just look at the crash that is the reason why we have an application compatibility problem. We’ll then spend the next few days trying to figure out what went wrong. Today’s installment will be rather long because I want to go through the entire process of making the initial diagnosis, so that we won’t have to spend each day re-establishing context. <\/p>\n

I also want to point out that even though this is presented as a straightforward narrative, the actual analysis involved a good number of dead ends and sitting around thinking, “Great, what am I supposed to do now?” <\/p>\n

We start with the actual crash. <\/p>\n

\neax=00000001 ebx=31410000 ecx=00000000<\/span> edx=40000000 esi=001345a8 edi=1fee0a9c\neip=314259d3 esp=0013443c ebp=0013444c iopl=0         nv up ei pl nz na pe nc\ncs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010206\ncontoso!ContosoInitialize+0x4d73:\n314259d3 mov     eax,dword ptr [ecx<\/span>+eax*4]            ds:0023:00000004<\/span>=????????\n<\/pre>\n
(Obviously, the symbols are wrong<\/a>. Which makes sense because we don’t have symbols for contoso.dll<\/code>.) <\/p>\n
What we have here is an array index operation into an array, but the array is a null pointer. Let’s see where that null pointer came from. <\/p>\n
\ncontoso!ContosoInitialize+0x4d40:\n314259a0 push    ebp\n314259a1 mov     ebp, esp\n314259a3 sub     esp, 10h\n314259a6 mov     dword ptr [ebp-10h]<\/span>, ecx<\/span>\n314259a9 mov     eax, dword ptr [ebp+8]\n314259ac mov     dword ptr [ebp-8], eax\n314259af lea     ecx, [ebp-0Ch]\n314259b2 push    ecx\n314259b3 lea     edx, [ebp-4]\n314259b6 push    edx\n314259b7 mov     eax, dword ptr [ebp-8]\n314259ba push    eax\n314259bb call    contoso!ContosoInitialize+0x4db0 (31425a10)\n314259c0 add     esp, 0Ch\n314259c3 mov     edx, 1\n314259c8 mov     ecx, dword ptr [ebp-0Ch]\n314259cb shl     edx, cl\n314259cd mov     eax, dword ptr [ebp-4]\n314259d0 mov     ecx<\/span>, dword ptr [ebp-10h]<\/span>\n314259d3 mov     eax, dword ptr [ecx<\/span>+eax*4]\n<\/pre>\n
Ah, it came from the this<\/code> pointer. the object itself has an array as its first member, and we’re trying to index into it, but the this<\/code> pointer is null, so there is nothing to index into. Where did that null pointer come from? We’ll have to go up the stack to see what the caller is passing as this<\/code>. <\/p>\n
Here’s the stack trace, or at least part of it. <\/p>\n
\nChildEBP RetAddr\n0013444c 31426201<\/span> contoso!ContosoInitialize+0x4d73\n00134478<\/span> 31427401 contoso!ContosoInitialize+0x55a1\n00134484 3142b030 contoso!ContosoInitialize+0x67a1\n00134494 3142afdd contoso!ContosoInitialize+0xa3d0\n001344c4 314279e0 contoso!ContosoInitialize+0xa37d\n001344dc 31427e86 contoso!ContosoInitialize+0x6d80\n001344f8 31427c2f contoso!ContosoInitialize+0x7226\n00134504 31427bd3 contoso!ContosoInitialize+0x6fcf\n00134530 314332b8 contoso!ContosoInitialize+0x6f73\n00134554 31432278 contoso!ContosoInitialize+0x12658\n00134578 3142dd7a contoso!ContosoInitialize+0x11618\n001345a8 3142e326 contoso!ContosoInitialize+0xd11a\n00134668 3142e4b5 contoso!ContosoInitialize+0xd6c6\n0013468c 3142e5b6 contoso!ContosoInitialize+0xd855\n001346b0 31424766 contoso!ContosoInitialize+0xd956\n001346bc 31421c0d contoso!ContosoInitialize+0x3b06\n001346e0 314c8cba contoso!ContosoInitialize+0xfad\n00134790 314b5e08 contoso!ContosoInitialize+0xa805a\n001347b0 77c60c6e contoso!ContosoInitialize+0x951a8\n001347d0 77c12f17 ntdll!RtlAddAuditAccessAceEx+0x5e\n00134820 77c09331 ntdll!RtlActivateActivationContextUnsafeFast+0xd7\n001348a0 77c091b4 ntdll!RtlLoadString+0x3c1\n001348c4 77c07d68 ntdll!RtlLoadString+0x244\n001348e0 77c0bd21 ntdll!LdrGetDllHandleByMapping+0xe8\n00134928 77c0b941 ntdll!RtlAcquirePebLock+0x391\n00134a74 77c0b615 ntdll!LdrLoadDll+0x3a1\n00134af8 751a7f94 ntdll!LdrLoadDll+0x75\n00134b3c 751aad06 KERNELBASE!LoadLibraryExW+0x124\n00134b64 018aa533 KERNELBASE!LoadLibraryExA+0x26\n00134c18 018aa410 setup+0x3a533\n<\/pre>\n
At this point, you might choose to shudder in horror, because you can see that this DLL is running a ton of code during DLL_PROCESS_ATTACH<\/code> <\/p>\n
Once you overcome your initial shock, you can pick off the caller (highlighted in the stack trace as the return address) and take a look at the enclosing function. <\/p>\n
\ncontoso!ContosoInitialize+0x5570:\n314261d0 push    ebp\n314261d1 mov     ebp, esp\n314261d3 push    0FFFFFFFFh\n314261d5 push    offset contoso!ContosoInitialize+0xa5798 (314c63f8)\n314261da mov     eax, dword ptr fs:[00000000h]\n314261e0 push    eax\n314261e1 mov     dword ptr fs:[0], esp\n314261e8 sub     esp, 14h\n314261eb mov     dword ptr [ebp-20h]<\/span>, ecx<\/span> \/\/ \"this\"\n314261ee mov     eax, dword ptr [ebp+8]\n314261f1 push    eax\n314261f2 mov     ecx, dword ptr [ebp-20h<\/span>]<\/span> \/\/ \"this\"\n314261f5 call<\/span>    contoso!ContosoInitialize+0x5620 (31426280)\n314261fa mov     ecx<\/span> eax<\/span>\n314261fc call<\/span>    contoso!ContosoInitialize+0x4d40 (314259a0)\n<\/pre>\n
The null pointer came from the call to mystery member function 31426280<\/code>. Let’s see how that function calculated its return value. Since the function is long and contains branches, we’ll follow the code forward. This is not guaranteed to be accurate, because the contents of memory at the time of the crash may not match the contents of memory at the time the code was executed, but we’ll take that chance for now. (Remember, debugging is an exercise in optimism.) <\/p>\n
\ncontoso!ContosoInitialize+0x5620:\n31426280 push    ebp\n31426281 mov     ebp, esp\n31426283 push    0FFFFFFFFh\n31426285 push    offset contoso!ContosoInitialize+0xa57c3 (314c6423)\n3142628a mov     eax, dword ptr fs:[00000000h]\n31426290 push    eax\n31426291 mov     dword ptr fs:[0], esp\n31426298 sub     esp, 24h\n3142629b mov     dword ptr [ebp-2Ch], ecx \/\/ \"this\"\n3142629e mov     eax, dword ptr [ebp-2Ch] \/\/ \"this\"\n314262a1 mov     ecx, dword ptr [eax+400h<\/span>] \/\/ read member at offset 0x400\n314262a7 cmp     ecx, dword ptr [contoso!ContosoInitialize+0xe5d3c (3150699c<\/span>)]\n314262ad jne     contoso!ContosoInitialize+0x56c0 (31426320)\n<\/pre>\n
Was this jump taken? Let’s find out. First, extract the this<\/code> pointer passed to the mystery member function 31426280, then look at the member at offset 0x400<\/code>, then compare it to the value at 3150699c<\/code>. <\/p>\n
\n0:000> dd 00134478<\/span>-20<\/span> L1\n00134458 1fee50f8\n0:000> dd 1fee50f8+400<\/span> L1\n1fee54f8  00000041\n0:000> dd 3150699c<\/span> L1\n3150699c  00000000\n<\/pre>\n
        The values do not match, so let’s assume the jump was taken. <\/p>\n
\n31426320 mov     dword ptr [ebp-10h], 0\n31426327 lea     eax, [ebp-10h]             \/\/ bonus parameter\n3142632a push    eax\n3142632b mov     ecx, dword ptr [ebp-2Ch]   \/\/ \"this\"\n3142632e mov     edx, dword ptr [ecx+400h]  \/\/ the value is 0x41\n31426334 push    edx\n31426335 call    contoso!ContosoInitialize+0x50b0 (31425d10)\n<\/pre>\n
Let’s follow the money into mystery free function<\/a> 31425d10<\/code>. <\/p>\n
\ncontoso!ContosoInitialize+0x50b0:\n31425d10 push    ebp\n31425d11 mov     ebp, esp\n31425d13 push    0FFFFFFFFh\n31425d15 push    offset contoso!ContosoInitialize+0xa5738 (314c6398)\n31425d1a mov     eax, dword ptr fs:[00000000h]\n31425d20 push    eax\n31425d21 mov     dword ptr fs:[0], esp\n31425d28 sub     esp, 10h\n31425d2b call    contoso!ContosoInitialize+0x952f3 (314b5f53)\n31425d30 push    eax\n31425d31 lea     ecx, [ebp-14h]\n31425d34 call    contoso!ContosoInitialize+0xfe0 (31421c40)\n31425d39 mov     dword ptr [ebp-4], 0\n31425d40 mov     eax, dword ptr [ebp+8]\n31425d43 push    eax\n31425d44 call    dword ptr [contoso!ContosoInitialize+0xa8590 (314c91f0)] \/\/ TlsGetValue -> goes into the variable\n31425d4a mov     ecx, dword ptr [ebp+0Ch]\n31425d4d mov     dword ptr [ecx], eax\n31425d4f mov     edx, dword ptr [ebp+0Ch]\n31425d52 cmp     dword ptr [edx], 0\n31425d55 jne     contoso!ContosoInitialize+0x5125 (31425d85)\n31425d57 call    dword ptr [contoso!ContosoInitialize+0xa840c (314c906c)] \/\/ GetLastError\n31425d5d push    eax\n31425d5e lea     ecx, [ebp-14h]\n31425d61 call    contoso!ContosoInitialize+0x5150 (31425db0)\n31425d66 test    eax, eax\n31425d68 je      contoso!ContosoInitialize+0x5125 (31425d85)\n31425d6a mov     dword ptr [ebp-18h]<\/span>, 0FFFFFFFFh<\/span>\n31425d71 mov     dword ptr [ebp-4], 0FFFFFFFFh\n31425d78 lea     ecx, [ebp-14h]\n31425d7b call    contoso!ContosoInitialize+0xff0 (31421c50)\n31425d80 mov     eax<\/span>, dword ptr [ebp-18h]<\/span>\n31425d83 jmp     contoso!ContosoInitialize+0x513e (31425d9e)\n31425d85 mov     dword ptr [ebp-1Ch]<\/span>, 0<\/span>\n31425d8c mov     dword ptr [ebp-4], 0FFFFFFFFh\n31425d93 lea     ecx, [ebp-14h]\n31425d96 call    contoso!ContosoInitialize+0xff0 (31421c50)\n31425d9b mov     eax<\/span>, dword ptr [ebp-1Ch]<\/span>\n31425d9e mov     ecx, dword ptr [ebp-0Ch]\n31425da1 mov     dword ptr fs:[0], ecx\n31425da8 mov     esp, ebp\n31425daa pop     ebp\n31425dab ret<\/span>\n<\/pre>\n
There are two exit paths for this function; one returns -1<\/code> and the other returns 0<\/code>. Let’s see if we can figure out which path got executed. The execution is straight-line until we reach this decision: <\/p>\n
\n31425d39 mov     dword ptr [ebp-4], 0\n31425d40 mov     eax, dword ptr [ebp+8]     \/\/ Parameter 0 = 0x00000041\n31425d43 push    eax\n31425d44 call    dword ptr [contoso!ContosoInitialize+0xa8590 (314c91f0)] \/\/ TlsGetValue\n31425d4a mov     ecx, dword ptr [ebp+0Ch]   \/\/ Parameter 1 (the bonus parameter)\n31425d4d mov     dword ptr [ecx], eax       \/\/ Save the TLS value into parameter 1\n31425d4f mov     edx, dword ptr [ebp+0Ch]   \/\/ Parameter 1\n31425d52 cmp     dword ptr [edx], 0         \/\/ Was the TLS value zero?\n31425d55 jne     contoso!ContosoInitialize+0x5125 (31425d85)\n<\/pre>\n
I was able to figure out that the called function was TlsGetValue<\/code> by looking at the value in the dump file.     <\/p>\n
\n0:000> ln poi 314c91f0\nkernel32!TlsGetValue:\n7603a1f0 mov     edi,edi\n<\/pre>\n
The branch is taken if the value in the TLS slot is nonzero. So is it? Let’s manually re-execute the call to TlsGetValue<\/code>. <\/p>\n
\nKERNELBASE!TlsGetValue:\n751b6ed0 mov     edi, edi\n751b6ed2 push    ebp\n751b6ed3 mov     ebp, esp\n751b6ed5 mov     ecx, dword ptr fs:[18h] \/\/ get the TEB\n751b6edc mov     eax, dword ptr [ebp+8] \/\/ tlsIndex (0x00000041)\n751b6edf mov     dword ptr [ecx+34h], 0 \/\/ SetLastError(NOERROR);\n751b6ee6 cmp     eax, 40h\n751b6ee9 jae     KERNELBASE!TlsGetValue+0x26 (751b6ef6) \/\/ Jump taken\n...\n751b6ef6 cmp     eax,440h\n751b6efb jae     KERNELBASE!TlsGetValue+0x42 (751b6f12) \/\/ Jump not taken\n751b6efd mov     ecx,dword ptr [ecx+0F94h]\n751b6f03 test    ecx,ecx\n751b6f05 je      KERNELBASE!TlsGetValue+0x4c (751b6f1c)\n\n0:000> dd @$teb+f94 L1\n7ffdff94  05f5bf30<\/span>\n<\/pre>\n
The value is nonzero, so the jump is not taken. <\/p>\n
\n751b6f07 mov     eax,dword ptr [ecx+eax*4-100h]\n751b6f0e pop     ebp\n751b6f0f ret     4\n0:000> dd 05f5bf30<\/span>+41*4-100 L1\n05f5bf34  00000000\n<\/pre>\n
The TLS value is zero. <\/p>\n
Okay, let’s go back to the function that called TlsGetValue<\/code> and see what it does when the TLS value is zero. <\/p>\n
\n31425d52 cmp     dword ptr [edx], 0         \/\/ Was the TLS value zero?\n31425d55 jne     contoso!ContosoInitialize+0x5125 (31425d85) \/\/ Jump not taken\n31425d57 call    dword ptr [contoso!ContosoInitialize+0xa840c (314c906c)] \/\/ GetLastError\n31425d5d push    eax                        \/\/ NOERROR\n31425d5e lea     ecx,[ebp-14h]\n31425d61 call    contoso!ContosoInitialize+0x5150 (31425db0)\n31425d66 test    eax,eax\n31425d68 je      contoso!ContosoInitialize+0x5125 (31425d85)\n<\/pre>\n
We don’t pay attention to Get­Last­Error<\/code> because it doesn’t affect flow control. The thing that does affect flow control is function 31425db0<\/code>, so let’s see what it does. <\/p>\n
\ncontoso!ContosoInitialize+0x5150:\n31425db0 push    ebp\n31425db1 mov     ebp,esp\n31425db3 push    ecx\n31425db4 mov     dword ptr [ebp-4],ecx\n31425db7 mov     eax,dword ptr [ebp-4]\n31425dba mov     ecx,dword ptr [ebp+8]\n31425dbd mov     dword ptr [eax+4],ecx\n31425dc0 mov     eax<\/span>, dword ptr [ebp+8]<\/span>\n31425dc3 mov     esp, ebp\n31425dc5 pop     ebp\n31425dc6 ret     4<\/span>\n<\/pre>\n
The function returns its input parameter. (It does other stuff, but we aren’t interested in that part yet.) Therefore, since we passed NOERROR<\/code> as the error code, it also returns NOERROR<\/code>, which is zero. We also saw that the TLS value zero is stored into the bonus parameter, which was [ebp-10h]<\/code>. Armed with this information, we can continue our analysis back to the caller: <\/p>\n
\n31425d66 test    eax,eax\n31425d68 je      contoso!ContosoInitialize+0x5125 (31425d85) \/\/ jump taken\n<\/pre>\n
And we saw from the analysis earlier that once you hit the code path at 31425d85<\/code>, the function will return zero. <\/p>\n
Now we can unwind back to the caller and see what happens when function 31425d10<\/code> returns zero. <\/p>\n
\n31426335 call    contoso!ContosoInitialize+0x50b0 (31425d10) \/\/ Returns zero\n3142633a add     esp, 8\n3142633d cmp     eax, 0FFFFFFFFh\n31426340 jne     contoso!ContosoInitialize+0x56e9 (31426349) \/\/ jump not taken\n31426342 xor     eax, eax                           \/\/ return zero\n31426344 jmp     contoso!ContosoInitialize+0x5783 (314263e3)\n\n314263e3 mov     ecx, dword ptr [ebp-0Ch]\n314263e6 mov     dword ptr fs:[0], ecx\n314263ed mov     esp, ebp\n314263ef pop     ebp\n314263f0 ret\n<\/pre>\n
Okay, so now we know where the null pointer came from: The null pointer was stored in the TLS slot, and this function returns whatever is in the TLS slot. <\/p>\n
That is a superficial analysis of why the program crashed. It doesn’t really tell us what happened in the operating system that induced the crash; we’ll have to dig in deeper. <\/p>\n
The story continues next time. <\/p>\n<\/p><\/div>\n
 (function () {     var arrowAngle = Math.PI \/ 12;     var arrowLength = 10;     function vec2(x, y) {         this.x = x;         this.y = y;     }     vec2.prototype.add = function (v) {         return new vec2(this.x + v.x, this.y + v.y);     };     vec2.prototype.sub = function (v) {         return new vec2(this.x – v.x, this.y – v.y);     }     vec2.prototype.magnitude = function () {         return Math.sqrt(this.x * this.x + this.y * this.y);     };     vec2.prototype.scale = function (scale) {         return new vec2(this.x * scale, this.y * scale);     };     vec2.prototype.rotate = function (theta) {         var sth = Math.sin(theta);         var cth = Math.cos(theta);         return new vec2(this.x * cth – this.y * sth, this.x * sth + this.y * cth);     };     function directionVector(v0, v1, l) {         var d = v1.sub(v0);         return d.scale((l || 1) \/ (d.magnitude() || 1));     }     function drawArrowHead(ctx, v0, v1) {         var u = directionVector(v1, v0, arrowLength);         ctx.beginPath();         ctx.moveTo(v1.x, v1.y);         var v = v1.add(u.rotate(arrowAngle));         ctx.lineTo(v.x, v.y);         v = v1.add(u.rotate(-arrowAngle));         ctx.lineTo(v.x, v.y);         ctx.lineTo(ctx, v1.x, v1.y);         ctx.fill();     }     function getAttachment(ctx, element, attach) {         var v = new vec2(element.offsetLeft – ctx.canvas.offsetLeft, element.offsetTop – ctx.canvas.offsetTop);         var mag = parseInt(attach) * 10;         if (isNaN(mag)) mag = 10;         var dv = new vec2(-mag, -mag);         if (attach.indexOf(“S”) >= 0) {             v.y += element.offsetHeight;             dv.y = mag;         } else if (attach.indexOf(“N”) = 0) {             v.x += element.offsetWidth;             dv.x = mag;         } else if (attach.indexOf(“W”) < 0) {             v.x += element.offsetWidth \/ 2;             dv.x = 0;         }         return [v, v.add(dv)];     }     function onresize() {         var thisPost = document.getElementById("appCompatPart1");         var canvas = thisPost.getElementsByTagName("canvas")[0];         if (!canvas.getContext) return;         canvas.width = thisPost.offsetWidth;         canvas.height = thisPost.offsetHeight;         var ctx = canvas.getContext("2d");         ctx.fillStyle = "#404040";         Array.prototype.forEach.call(thisPost.querySelectorAll("[data-to]"), function (source) {             var ids = source.getAttribute("data-to");             ids.split(" ").forEach(function (id) {                 var opt = id.split(":"); \/\/ target:connector:attachStart:attachEnd                 var target = thisPost.querySelector("#" + opt[0]);                 var vStart = getAttachment(ctx, source, opt[2]);                 var vEnd = getAttachment(ctx, target, opt[3]);                 var v0 = vStart[0];                 var v1 = vStart[1];                 var v2 = vEnd[1];                 var v3 = vEnd[0];                 ctx.beginPath();                 ctx.moveTo(v0.x, v0.y);                 switch (opt[1]) {                     case "L":                         ctx.lineTo(v3.x, v3.y);                         v2 = v0;                         break;                     case "C":                         ctx.bezierCurveTo(v1.x, v1.y, v2.x, v2.y, v3.x, v3.y);                         break;                 }                 ctx.stroke();                 drawArrowHead(ctx, v2, v3);             });         });     }     if (window.addEventListener) {         window.addEventListener("resize", onresize);         onresize();     } })(); <\/p>\n","protected":false},"excerpt":{"rendered":"
Seeing the proximate cause.<\/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":[25],"class_list":["post-93615","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
Seeing the proximate cause.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/93615","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=93615"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/93615\/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=93615"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=93615"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=93615"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}