Windowsコンソールに付随するstdout/stderrの不可解な動き

遭遇した事象

以下のようなバッチファイルとVBScriptファイルがある。

parentBatch.cmd

@echo off
cd /d %~dp0
set LOGFILE=example.log
echo =開始= %DATE% %TIME% > %LOGFILE% 2>&1
cscript.exe //nologo childScript.vbs >> %LOGFILE% 2>&1
echo =終了= %DATE% %TIME% >> %LOGFILE% 2>&1

childScript.vbs

WScript.Echo " -呼出先- " & Now
WScript.Sleep 10000

出力されるログファイル example.log の内容は、以下のようになる、はず。

example.log (expected)

=開始= 2023/09/22  0:49:16.34 
 -呼出先- 2023/09/22 0:49:16
=終了= 2023/09/22  0:49:26.44 

ところが、なぜかVBScriptの処理部分だけ取りこぼす現象が発生した。

example.log (actual)

=開始= 2023/09/22  0:49:16.34 
=終了= 2023/09/22  0:49:26.44 

なんで、こんなことが発生するんだ？という話。

起動元パラメータの影響を受ける

実は起動元は、とあるミドルウエア製品である。
製品のコードは提示できないので、代わりに再現のためのPowerShellコードを以下に提示する。

caller.ps1

Start-ProcessEx -CommandLine 'cmd.exe /c parentBatch.cmd' `
   -CreationFlags DetachedProcess `
   -StartupInfo (New-StartupInfo -Flags UseStdHandles )

Start-ProcessEx
サンプルは本コマンドレットを使ってますのでご紹介。
Win32APIの CreateProcessA を呼べます。

gistにもあります

CreateProcessAの起動時パラメータで明示的にDETACH_PROCESSしておらず、STARTUPINFOのフラグ設定STARTF_USESTDHANDLESがない場合は再現しない。
たとえば以下のようにWSH経由で起動された場合は、期待した通りの出力がされる。

callerWsh.vbs

Dim wsh: Set wsh = CreateObject("WScript.Shell")
rv = wsh.Run("cmd.exe /c parentBatch.cmd", 0, True)

caller.ps1 を実行すると、cscriptの起動時に、新たなコンソールウィンドウが開いてしまうことが分かる。

これはcscript以外のプログラム、たとえばpowershellで処理させた場合でも、同様にコンソールウィンドウが開いてしまう。

プロセスツリーを見ると、 cscript.exe の配下に conhost.exe がいることが分かる。

WSHからの起動では、こうはならずに cmd.exe の配下に conhost.exe がいる。 cscript.exe とは並列になる。

stdin/stdout/stderrについて、自プロセスがどこから起動されたかによってふるまいが変わるというのは、直感的に受け入れ難い。。。
にわかに信じがたいが、目の前で起こっていることをみると受け入れざるを得ない。。。

回避策

現象は理解できたので、回避策。

呼出元を改修すると、すべての起動パターンが変わってしまうのでリスクが高く、できれば回避したい。
あくまで呼び出された側、本プログラムだけの改修で済ませたい。

標準出力の制御を取り戻すために、とりあえず自前で保持するコンソールを持てればいいんじゃないか。
ということで、以下のようなVBScriptを追加作成。

wshRun.vbs

Dim wsh: Set wsh = CreateObject("WScript.Shell")
rv = wsh.Run(WScript.Arguments(0), 0, True)

元の parentBatch.cmd を以下のように改修する。

parentBatch(modified).cmd

@echo off
cd /d %~dp0
set LOGFILE=example.log
echo =開始= %DATE% %TIME% > %LOGFILE% 2>&1
cscript.exe //nologo wshRun.vbs "cmd.exe /c cscript.exe //nologo childScript.vbs >> %LOGFILE% 2>&1"
echo =終了= %DATE% %TIME% >> %LOGFILE% 2>&1

サンプルだと「別窓が開く」という残念な状況は変わらないが、別窓の中でexample.logに出力するという処理結果を得られる。

ミドルウエアはデスクトップセッションを持たないので、別窓の心配は無用。

Windows「コンソールの作成」

ところで、そもそも、なんでこんな事象が起きるのか。

Microsoft Learn 内に掲載されている「Windowsコンソール」の文書を読むと、少しは推し量る余地があるかもしれない。

その記述を見れば、少しは推し量る余地があるかもしれない。

• キャラクター モード アプリケーションについて

• コンソールの作成

要は、Windowsにおいてはstdin/stdout/stderrは単なるファイルハンドルではなくって、コンソールに紐づいている入出力なのだということらしい。
これは知らないと分からないな。。

なにかの参考になれば幸いです。