{"id":97536,"date":"2017-12-07T07:00:00","date_gmt":"2017-12-07T22:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/?p=97536"},"modified":"2019-03-13T01:20:54","modified_gmt":"2019-03-13T08:20:54","slug":"20171207-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20171207-00\/?p=97536","title":{"rendered":"Knowing just enough about debugging IRPs to chase the problem out of the I\/O stack"},"content":{"rendered":"<p>One of my colleagues was running a tool that wound up stuck on <code>Flush&shy;File&shy;Buffers<\/code>. Since this was a hang in the I\/O stack, a kernel dump is more useful. <\/p>\n<p>I used the <code>!irp<\/code> debugger command to look at the I\/O request that got stuck: <\/p>\n<pre>\n0: kd&gt; !irp 0xffffab0c`fced9340 1\n\nIrp is active with 2 stacks 2 is current (= 0xffffab0cfced9458)\n No Mdl: No System Buffer: Thread ffffab0d15731080:  Irp stack trace.\n     cmd  flg cl Device   File     Completion-Context\n [N\/A(0), N\/A(0)]\n            0  0 00000000 00000000 00000000-00000000\n\n                        Args: 00000000 00000000 00000000 00000000\n&gt;[IRP_<a HREF=\"https:\/\/en.wikipedia.org\/wiki\/MJ#People\">MJ<\/a>_FLUSH_BUFFERS(9), N\/A(0)]\n            0  1 ffffab0cdf855060 ffffab0ce2c6eef0 00000000-00000000    pending\n               \\FileSystem\\Npfs\n                        Args: 00000000 00000000 00000000 00000000\n<\/pre>\n<p>I don&#8217;t know what any of this means, but somebody else did. <\/p>\n<p>The file system is <code>Npfs<\/code>, which is the &#8220;named pipe&#8221; file system. This means that the code is trying to flush a named pipe, and the process on the other end of the pipe is not responding. <\/p>\n<p>With the help of <a HREF=\"https:\/\/docs.microsoft.com\/en-us\/windows-hardware\/drivers\/debugger\/-fileobj\">debugger documentation<\/a> I dumped the file object: <\/p>\n<pre>\n0: kd&gt; !fileobj ffffab0ce2c6eef0\n\n\\contoso44268\n\nDevice Object: 0xffffab0cdf855060   \\FileSystem\\Npfs\nVpb is NULL\n\nFlags:  0x40082\n        Synchronous IO\n        Named Pipe\n        Handle Created\n\nFile Object is currently busy and has 1 waiters.\n\nFsContext: 0xffffe30b60eefe70   FsContext2: 0xffffe30b23b593d3\nPrivate Cache Map: 0x00000001\nCurrentByteOffset: 0\n<\/pre>\n<p>I don&#8217;t know what any of this means either, but the name of the named pipe is apparently <code>contoso44268<\/code>. <\/p>\n<p>We provided this information to the owner of the tool, and they recognized it as a named pipe they use to communicate between the tool and a helper process, and the helper process in turn satisfies the pipe request by contacting a Web service. <\/p>\n<p>The owner of the tool requested some diagnostic logs to figure out why the named pipe got stuck. But that&#8217;s not the point of the story today. The point here is just being able to chase the stuck I\/O out of kernel mode back into an application so the forward progress can be made. <\/p>\n<p><b>Bonus reading<\/b>: More on debugging the I\/O system: <\/p>\n<ul>\n<li>    <a HREF=\"https:\/\/blogs.msdn.microsoft.com\/ntdebugging\/2009\/04\/13\/search-to-the-rescue\/\">    !Search to the Rescue!<\/a> <\/li>\n<li>    <a HREF=\"https:\/\/blogs.msdn.microsoft.com\/ntdebugging\/2012\/10\/29\/breaking-down-the-cl-in-irp\/\">    Breaking down the &#8220;CI&#8221; in !irp<\/a> <\/li>\n<li>    <a HREF=\"https:\/\/blogs.msdn.microsoft.com\/ntdebugging\/tag\/io\/\">    All I\/O-tagged topics on the NT debugging blog<\/a> <\/li>\n<\/ul>\n","protected":false},"excerpt":{"rendered":"<p>Fumbling around and stumbling into a diagnosis.<\/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":[104],"class_list":["post-97536","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-tipssupport"],"acf":[],"blog_post_summary":"<p>Fumbling around and stumbling into a diagnosis.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/97536","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=97536"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/97536\/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=97536"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=97536"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=97536"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}