{"id":94355,"date":"2016-09-21T07:00:00","date_gmt":"2016-09-21T21:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/?p=94355"},"modified":"2019-03-13T11:07:01","modified_gmt":"2019-03-13T18:07:01","slug":"20160921-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20160921-00\/?p=94355","title":{"rendered":"The case of the system() call that returned before finishing"},"content":{"rendered":"<p>A customer was having trouble with some code that copies a bunch of files and then processes the copy. Here&#8217;s the code they shared (suitably redacted): <\/p>\n<p><pre>\n\/\/ copy the files\nchar command[512] = {NULL};\nsprintf_s(command, 512, \"copy \/Y %s %s &gt;nul 2&gt;&amp;1\",\n          sourcePath, destPath);\nprintf(\"The command is %s\\n\", command);\nLog(\"The command is %s\", command);\nsystem(command);\n\n\/\/ process the files\nchar searchPattern[256] = {NULL};\nsprintf_s(searchPattern, 256, \"%s\\\\*\", destPath);\nprintf(\"The directory is %s.\\n\", searchPattern);\nLog(\"The directory is %s\", searchPattern);\n\nhFile = FindFirstFileA(searchPattern, &amp;FindFileData);\n\n\/\/ error when searching files\nif (hFile == INVALID_HANDLE_VALUE) {\n  DWORD lastError = GetLastError();\n\n  if (lastError == ERROR_FILE_NOT_FOUND) {\n    printf(\"No files under directory %s.\\n\", searchPattern);\n    Log(\"No files under directory %s\", searchPattern);\n    return S_OK;\n  } else {\n    printf(\"FindFirstFile failed in directory %s with error: %d.\\n\",\n           searchPattern, lastError);\n    Log(\"FindFirstFile failed under directory %s with error: %d\",\n        searchPattern, lastError);\n    return E_FAIL;\n  }\n}\n\ndo { \n  printf(\"The file is %s.\\n\", FindFileData.cFileName);\n  Log(\"The file is %s\", FindFileData.cFileName);\n  ...\n<\/pre>\n<p>The customer reported that &#8220;It appears that <code>Find&shy;First&shy;FileA<\/code> does not wait for <code>system()<\/code> to finish copying the files. Here&#8217;s a sample log file: <\/p>\n<pre>\nThe command is copy \/Y \\\\server\\path\\to\\data\\* D:\\data &gt;nul 2&gt;&amp;1\nThe directory is D:\\data\\*\nThe file is .\n<\/pre>\n<p>&#8220;Observe that <code>Find&shy;First&shy;FileA<\/code> did not find the files we copied. How can we wait for the <code>system()<\/code> function to finish copying the files before the program proceeds to the <code>Find&shy;First&shy;FileA<\/code>?&#8221; <\/p>\n<p>In the ensuing discussion, people suggested using <code>Copy&shy;File<\/code> or <code>SHFile&shy;Operation<\/code> instead of shelling out to <code>cmd.exe<\/code>. Issues with spaces and other characters in the directory names. But can you find the reason why <code>Find&shy;First&shy;FileA<\/code> couldn&#8217;t find the files? <\/p>\n<p>Look carefully at the last line of the log: &#8220;The file is&nbsp;.&#8221; Part of this is confusing because the program both prints its output to the screen as well as to the log file, but prints them differently. The output to the screen includes a period at the end; the output to the log file does not. <\/p>\n<p>And that&#8217;s the key. Since the output to the log file does not include a period at the end, it means that the period in the output is the actual contents of <code>FindFileData.cFileName<\/code>. <\/p>\n<p>The customer misread their log file. The issue isn&#8217;t that the <code>Find&shy;First&shy;FileA<\/code> ran before the files were copied. The issue is that the first thing found by <code>Find&shy;First&shy;FileA<\/code> was the file whose name consists of a single period. <\/p>\n<p>Recall that every directory has two artificial entries, one for the directory itself (<code>.<\/code>), and one for the directory&#8217;s parent (<code>..<\/code>). What you found was the first artificial entry, the one that represents the directory itself. Instead of giving up right away, keep looking, and the files you copied will show up later. <\/p>\n<p>(Assuming they were all successfully copied. The program doesn&#8217;t actually check.) <\/p>\n","protected":false},"excerpt":{"rendered":"<p>Study the output more carefully.<\/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-94355","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"<p>Study the output more carefully.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/94355","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=94355"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/94355\/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=94355"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=94355"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=94355"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}