バッチ処理にてcopy,xcopyが不穏な動きを見せる

Question

###前提・実現したいこと
Windows7にてファイルのバックアップをバッチ処理で行う。
バッチファイルは(fessのクロール処理に組み込んでいるため)Groovyからキックされる。
処理の流れはとしては、バッチが終わった後にfessのクロールが走る。
ファイルをコピーする際のコマンドはcopyでもxcopyでもそのほかでも可。

以下のバッチはファイルパスさえ環境に合わせてやれば動くのですが動作が不安定なため今回質問することにいたしました。

※補足情報は必ずお読みください。解決したい内容が書かれています。
**追記：**ソースコードと補足情報を更新しました 2016/09/13/ 17:22 現在

###該当のソースコード

@echo off
rem 格納パス
set MYSQLPATH="C:\Program Files\MySQL\MySQL Server 5.6\bin"

rem 接続文字列とかを環境変数で登録しとく
rem DB情報
set MYSQLDATABASE=fess_db
set MYSQLUSER=root
set PGPASSWD=mysql@dmin01

rem ファイルパス
rem 環境によって変化するもの
set BATPATH=C:\batch\bat
set BACKUPPATH=C:\backup
set SOLRPATH=C:\fess\solr

rem 環境には左右されないもの
set LOGPATH=%BATPATH%\..\log
set ERRLOGPATH=%LOGPATH%\errlog
set CORE1PATH=%SOLRPATH%\core1\data
set CORE1SGPATH=%SOLRPATH%\core1-suggest\data
set SOLRBACKUPPATH1=%BACKUPPATH%\solr\core1
set SOLRBACKUPPATH2=%BACKUPPATH%\solr\core1-suggest

rem バックアップデータ作成
mkdir %LOGPATH% > NUL 2>&1
call :getTime
echo # %LOGTIME% # "バックアップバッチ処理 start" >> %LOGPATH%\%LOGDATE%_batch.log

rem バックアップ用のフォルダ作成 
call :getTime
echo # %LOGTIME% # "フォルダ作成 start" >> %LOGPATH%\%LOGDATE%_batch.log
mkdir %BACKUPPATH%\MySQL > NUL 2>&1
mkdir %SOLRBACKUPPATH1% > NUL 2>&1
mkdir %SOLRBACKUPPATH2% > NUL 2>&1
call :getTime
echo # %LOGTIME% # "フォルダ作成 end" >> %LOGPATH%\%LOGDATE%_batch.log

rem MySQLのバックアップ
call :getTime
echo # %LOGTIME% # "mysqldump start" >> %LOGPATH%\%LOGDATE%_batch.log
cd %MYSQLPATH%
mysqldump -u %MYSQLUSER% -p%PGPASSWD% %MYSQLDATABASE% --single-transaction > %BACKUPPATH%\MySQL\%MYSQLDATABASE%.dump
if not %errorlevel%==0 type  RET:%errorlevel%  >> %ERRLOGPATH%\%LOGDATE%_mysqldump.elog
rem echo  %LOGTIME% mysqldump-end >> %LOGPATH%\%LOGDATE%_batch.log
call :getTime
echo # %LOGTIME% # "mysqldump end" >> %LOGPATH%\%LOGDATE%_batch.log

rem Indexのバックアップ
call :getTime
echo # %LOGTIME% # "index1バックアップ start" >> %LOGPATH%\%LOGDATE%_batch.log

rem %path%\*.* %path%\*.* /Y
rem copy "%CORE1PATH%\index\*.*" %SOLRBACKUPPATH1%\index\*.* /Y
rem xcopy "%CORE1PATH%\index" %SOLRBACKUPPATH1%\index /i /y /c 2>&1> %LOGPATH%\%LOGDATE%_xcopy1.log
robocopy "%CORE1PATH%\index"\ %SOLRBACKUPPATH1%\index\ /COPYALL /R:3 /W:1
rem  >> %LOGPATH%\%LOGDATE%_robocopy1.log
rem /NDL /UNILOG+:%LOGPATH%\%LOGDATE%_robocopy1.log
echo # %LOGTIME% # "index1バックアップ end" >> %LOGPATH%\%LOGDATE%_batch.log
echo # %LOGTIME% # "index2バックアップ start" >> %LOGPATH%\%LOGDATE%_batch.log
rem copy "%CORE1SGPATH%\index\*.*" %SOLRBACKUPPATH2%\index\*.* /Y
rem xcopy "%CORE1SGPATH%\index" %SOLRBACKUPPATH2%\index /i /y 2>&1> %LOGPATH%\%LOGDATE%_xcopy1.log
robocopy "%CORE1SGPATH%\index"\ %SOLRBACKUPPATH2%\index\ /COPYALL /R:3 /W:1
rem  >> %LOGPATH%\%LOGDATE%_robocopy2.log
call :getTime
echo # %LOGTIME% # "index2バックアップ end" >> %LOGPATH%\%LOGDATE%_batch.log

rem バックアップデータ作成完了
call :getTime
echo # %LOGTIME% # "バックアップバッチ処理 end" >> %LOGPATH%\%LOGDATE%_batch.log
echo. >> %LOGPATH%\%LOGDATE%_batch.log
exit /b 0

rem 時間取得
:getTime
set TIME0=%time: =0%
set LOGTIME=%TIME0%
set LOGDATE=%date:~0,4%%date:~5,2%%date:~8,2%
exit /b

###補足情報(言語/FW/ツール等のバージョンなど)
OS:windows7 64bit
アプリケーション：fess

※以下のような不穏な動作があります。
①"xcopy"コマンドや"robocopy"コマンドを実行する際に結果を別ファイルリダイレクトするようにバッチを記載すると正常に処理が終了する

rem 正常動作時のコマンド
xcopy "%CORE1PATH%\index" %SOLRBACKUPPATH1%\index /i /y /c 2>&1> %LOGPATH%\%LOGDATE%_xcopy1.log
rem 正常動作時のコマンド
robocopy "%CORE1PATH%\index"\ %SOLRBACKUPPATH1%\index\ /COPYALL /R:3 /W:1 >> %LOGPATH%\%LOGDATE%_robocopy1.log

②"xcopy"コマンドや"robocopy"コマンドを実行する際に結果を受け取らない(リダイレクトしない)場合は処理が途中で停止する。

rem 動作が途中で止まるときのコマンド
xcopy "%CORE1PATH%\index" %SOLRBACKUPPATH1%\index /i /y /c
rem 動作が途中で止まるときのコマンド
robocopy "%CORE1PATH%\index"\ %SOLRBACKUPPATH1%\index\ /COPYALL /R:3 /W:1

以上です。
ご教授の程、よろしくお願いします。

Answer 1

ファイルがロックされている、恐らくはまだ何かのプログラムが使用中なのでしょう。
まずは問題のファイルの特定からです。
二箇所あるので、どっちが原因なのか（あるいは両方なのか）、ログを仕込んで確認してみてはどうでしょうか？

xcopy "%CORE1PATH%\index" %SOLRBACKUPPATH1%\index /i /y
xcopy "%CORE1SGPATH%\index" %SOLRBACKUPPATH2%\index /i /y

次に誰が握っているのかの特定ですが、心当たりがあるならそれで問題有りません。
ない場合はProcess Explorer等で調べられますが、一瞬しかロックされてない場合はちょっとわかりません。
逆にその場合はコピー処理を数秒遅らせる事で対処するという手もあります。

参考URL
Process Explorerでロックしているファイルを探す

Comments

[.zero]

調査の結果としては以下でした。
・xcopyコマンドが実行される前にバッチが固まっている
・ファイルをロックしているプロセスは java
こちらの行いたいこととしては"ロックされていてもコピーをしたい"なのでプログラムを落とすのは無しの方向で行きたい（javaを落としたらそもそもfessが動かなくなるはずなので落とせない）です。

[ishi9]

ロック中のファイルのコピーは難しいですね・・・
一旦、ファイルを開放しない事には正常に処理できないと思います。
・コピー処理自体を切り離して別のタイミングで行う。（起動時とか終了時、あるいは毎日０時等）
・（よく知らないので恐縮ですが）fess側に一時的にファイルを開放してもらう
等を検討できませんか？

[.zero]

提案していただいた内容なのですが二つとも実現が厳しそうです。
理由としては、「fessのクロール処理がいつ終わるかわからないため開始時に割り込ませてコピーをとるようにしたかった」ていうのと、「動いているアプリを落とすのは（再度動かそうとしたときに動かなくなったりすると）面倒だから」です。
最悪の場合は、もう一度fess自体をとめる方法を検討したいと思います

[ishi9]

すいません、ちょっと調べたのですが、やっぱり停止しないといけないのでは？
http://fess.codelibs.org/ja/9.4/config/index-backup.html

[ishi9]

と思いましたが、何やら最新版だとスナップショットの機能があるらしいですよ
http://fess.codelibs.org/ja/10.1/config/index-backup.html#id2

[.zero]

本当はそうです（汗）
一応自分で調査してみてfessの全文検索時に葉データが出来ないのを確認したので、クロール(indexデータを作る処理)の前にバックアップ処理を組み込むという流れになりました。

[ishi9]

ちょっとタイミングかぶっちゃいましたね。
最新版の機能の方は検討できないでしょうか？

[.zero]

今回のバックアップに関しては厳しいかもですが、今後が楽になりそうなので相談してみます

[ishi9]

そうなるとちょっと厳しいですね。
ロック中のファイルというのは言ってしまえば、リアルタイムに書き換え中ということです。そんなファイルをコピーするのは元のプログラム（fess）側の協力がないと厳しいです。

[.zero]

そうですよねぇ・・・
こちらとしては、バッチで作ったデータをリストアして動くというのは確認できているので、そのバッチの挙動が安定すればゴールという形になってます。
それと、質問を修正しました。
よろしければ引き続き助言がいただけると幸いです。

[ishi9]

製品(fess)のサポートにはもう質問してみましたか？
まだなら是非してみてください。

Answer 2

回答にはなりませんが、xcopyはバグが多く、Microsoft推奨から外れたと記憶しています。
それにかわる "Robust File Copy"(robocopy コマンド)を使用されていは如何でしょうか?

Comments

[.zero]

robocopyコマンドを試してみたのですが①番の呼び出し方法で実行しないと正常に終了しませんでした。出来ればバッチのみを呼び出して(標準出力ログに出さなくても)処理をさせたいのですが方法をご存知でしょうか。

[over]

いや、解決するつもりは全くなかったのですが、少し内容を確認してみました。

> indexバックアップ startがログにかかれない

上記であるな、コピータスクの問題ではなく、echo している個所のリダイレクト、リダイレクト先の記載方法を疑った方が良いのではないでしょうか?

[.zero]

echo のリダイレクト先に関しては、他のログと統一(コピペ)してるので同一箇所に計れるようになっています。
呼び出し方法①の方法で実行すると最後までバッチの処理が進むのでそのときに確認もして、他のログと同一ファイルに出力されているのは確認済みです

[over]

確認ですが、②で実行すると以下ですよね。

> indexバックアップ startがログにかかれない

[.zero]

はい、そうなります。
一応補足として、ログが出ないだけではなくコピー処理自体も動きません

[over]

②の方式で、コピー処理を省いた場合は動作するということでしょうか?

[.zero]

以下の２パターンで調査しました
１．コピー処理だけをコメントアウトしての実行
２．コピー処理全体（index バックアップ start などのログも含め）をコメントアウトしての実行
結果としては、２パターンとも止まりました(バッチ処理endのログまで出力されませんでした)

[over]

であればコピータスクが原因でないとわかりますよね?

[.zero]

そうですね。
それを含めた上でわからないことがあります。
mysqlのダンプ処理が終わった段階で echo を使い endログを出力しているのですが、なぜ endログはでて その下の処理 indexのstartログは出ないのでしょうか？
echo のリダイレクト先は両方とも同じファイルなので原因がよくわかりません。

[over]

start がコマンドとして認識されているからではないでしょうか?

echoで出力する文章をダブルクォーテーションで囲ってみては如何でしょうか?

また、気になったのですが、
:getTime ディレクティブに「exit /b」が記載されていますが、問題ないですか?
get timeを呼び出すと終了する動きになるのではないでしょうか?

また、バッチ最終でも処理される意味ない作りになっています。
「exit /b」を記載するのであれば:getTime 前だと思いますが。

[.zero]

＞ :getTimeを呼び出すと終了する動きになるのではないでしょうか?
ラベル機能をつかい関数のように使いたかったので、ラベルを呼び出し何かしらの処理をさせてもとの行に戻すためにあのような書き方になっています。
＞バッチ最終でも処理される意味ない作りになっています。
その通りですね！自分が見たサイトだと呼び出し先にしか記述されていなかったのでまねしていたのですが、他のサイトを参考に見た所、バッチ処理の最後にも「exit /b」を(下に書いているラベル部分が呼ばれないように)記載していました
＞start がコマンドとして認識されているからではないでしょうか?
ファイル作成ログでもstartを使っているのでmysqlのdumpが行われている時点でstartが原因ではないとおもわれます。
＞choで出力する文章をダブルクォーテーションで囲ってみては如何でしょうか?
何も変わりませんでした。

[over]

出力されるものすべて囲いました?
mysqldump とか囲わないで出力しようとしていますよ。

[.zero]

検証しているのはローカルのバッチで行っているので記事に反映させていないだけです。
その旨を記載するのを忘れていました

[.zero]

ログの出力ができるようになりました。
１行目の @echo off のコメントを外すと出るようになったって感じです。
ですが、ログが出ることによってxcopyの一つ目で止まってることがわかりました。
現状としましては、xcopyではなくrobocopyを使うと上手く言ってるためその違いを探している所です

[.zero]

質問を修正しました。
よろしければ引き続き助言がいただけると幸いです。

[over]

echo でリダイレクトする文字はダブルクォーテーションで囲いましょう。
スペース区切りがある場合、引数やオプションとして認識してしまう可能性があります。

特別な意図がなければ以下です。

× echo # %LOGTIME% # "index2バックアップ end" >> %LOGPATH%\%LOGDATE%_batch.log

○ echo "# %LOGTIME% # index2バックアップ end" >> %LOGPATH%\%LOGDATE%_batch.log

で、追記した部分についてですが、原因を究明されたいのであれば、各タスクごとに分解して試してみては如何でしょうか?
私もrobocopyのバッチを組んだ経験がありますが、ご質問者様のような状況に陥ったことがなく、ご質問者様の環境依存の可能性もあります。

あと、これ何の意図があってダブルクォーテーションで囲っています?
xcopy "%CORE1PATH%\index"
robocopy "%CORE1PATH%\index"\

[.zero]

ダブルクォーテーションで囲うところに関しては見落としでした。
再度試してみます。
＞あと、これ何の意図があってダブルクォーテーションで囲っています?
環境によっては半角スペースがフォルダ名に入っていることがある為囲ってます