FastCopyのログ出力を把握する

どうも、Tです。

今までrobocopyばかりだったのですが、robocopyの代替としてFastCopyを検証しています。ログ出力がヘルプを読んでいてもイマイチわからんかたので、忘れぬように備忘録です。

スポンサーリンク
アドセンス1

ログの読み方まとめ

はい。思ったより検証の内容が長くなってしまったので、当初目的の基本ログの読み方だけまとめておきます。詳細が知りたい方は、続きの記事をよんでください。

基本ログの項目の意味

項目意味備考
Sourceコピー元パス
DestDirコピー先パス
Exclude除外ファイル名
Command動作モード、ACL、ベリファイの設定有無
FileLog詳細ログのファイルパス
TotalReadコピー元にあるコピー対象ファイルの容量(単位:MB)
TotalWriteコピー先に書き込んだファイル容量(単位:MB)コピー強制停止をした場合は停止するまでの容量
TotalFilesコピー先に書き込んだファイル数。()内はフォルダ数コピー強制停止をした場合は停止するまでの数。
ショートカットは1ファイルとしてカウント。
詳細ログで+がついているもの。
TotalSkipスキップファイルの総容量(単位:MB)TotalFiles+TotalSkipがコピー処理終了時の総数になる。
SkipFilesコピー元と先で同じのためスキップされたファイル数。
DelFilesされたファイル数は、含まれない。
フォルダはスキップされてもカウントされない
TotalDel削除ファイルの総容量(単位:MB)
DelFiles削除ファイルの数。()内はフォルダ数ショートカットは1ファイルとしてカウント。
詳細ログで-がついているもの。
TotalTimeコピー処理した時間
TransRateTotalWrite / TotalTime (単位:MB/s)左記の割り算で算出している模様
FileRateTotalFiles / TotalTime(単位:files/s)左記の割り算で算出している模様
VerifyReadベリファイ処理を行ったファイル総容量(単位:MB)コピー強制停止をした場合は0MBで表記
VerifyFilesベリファイ処理を行ったファイル数コピー強制停止をした場合は0で表記
ErrFilesエラー処理になったファイル数
ErrDirsエラー処理になったフォルダ数

コピーを強制停止する際の注意点

  • コピーを強制停止する場合は、「taskkill /IM FastCopy.exe」コマンドを使う
  • 強制停止すると詳細ログにファイルは出力されない(フォルダは出力される)
  • 強制停止すると基本ログのVerifyReadとVerifyFilesは0になる(ベリファイされない)

FastCopyとは

FastCopy
FastCopyのオフィシャルサイトです。

Windowsのファイルコピーやバックアップに利用できるツールです。

歴史は古く2004年にリリースされて、窓の杜の2015年大賞にも輝くなど有名なソフトです。

フリーウェアですが、細かいライセンスはこちらをご確認ください。日本の白水啓章さんが開発されています。

やりたいこと&環境

やりたいこと

やりたいことは、FastCopyがどのようなログを出力するか把握することです。

FastCopyバージョン

検証時点(2020年11月)最新のFastCopy ver 3.92を使用します。

コピー環境

上記のように異なるsambaサーバー間をFastCopy(Windows10)を経由してコピー行いログを取得します。

コピー対象

初期状態として、用意したのは下記です。フルコピー後、差分コピーとの異なりを比較していきます。

項目備考
フォルダ数111
ファイル数10001
容量88.3MB

コピー元のフォルダ配下には、下記のように複数フォルダを作成しました。

テストフォルダ01~10には、ぞれぞれ10個のフォルダと1000個のファイルを作成しています。(いずれも0KB)

テストフォルダーOtherには、容量があるファイル(88.3MB)を配置しました。

検証時のルール

検証を行う上で、下記のルールを決めて行っています。

  • FastCopyは、GUIではなくCUI(スクリプト)で行う(冪等性確保)
  • FastCopyのログは都度削除する(ログを見やすくするため)
  • FastCopyの動作は、同期モードで行う

FastCopyスクリプト

スクリプト内容

下記のbatファイルを「fastcopy.bat」ファイル作成して管理者権限で実行します。FastCopy.exeファイルは、C:\FastCopy392_x64フォルダに配置した前提で記述しています。

REM @echo off

REM =========================================================================================================
REM 用途:FastCopy ver 3.92ツールを用いたWindowsOSが利用するファイルコピー
REM ファイル名:fastcopy.bat
REM 実行方法:本ファイルを管理者権限で実行
REM =========================================================================================================

REM =========================================================================================================
REM   定義-START
REM =========================================================================================================
REM //コピー情報////////////////////////////////////////////////////////////////////////////////////////////
REM //コピー元パス
set COPY_SRC_PATH=<コピー元のパス>

REM //コピー先パス
set COPY_DEST_PATH=<コピー先のパス>


REM //FastCopyコマンド////////////////////////////////////////////////////////////////////////////////////////////

REM //FastCopyコマンドファイル指定
set CMD=C:\FastCopy392_x64\FastCopy.exe

REM //FastCopyコマンドオプション指定
set CMD_OPTS=/cmd=sync /no_ui /estimate=FALSE /balloon=FALSE /error_stop=FALSE /bufsize=1024 /log /filelog /utf8 /skip_empty_dir=FALSE /force_start=3 /speed=full /exclude="Thumbs.db" /time_allow=2000 /acl /reparse /verify

REM //FastCopyコマンドオプション説明
REM /cmd=sync				動作モードをSync(同期)に設定
REM /no_ui					バックグラウンド動作。/no_confirm_del(削除時に問合せしない)、/no_confirm_stop(エラー出力しない)、/force_close(コピー終了後に強制終了)も暗黙的に付与。
REM /estimate=FALSE			コピー完了時間予測を行わない※コピー処理高速化の対応。
REM /balloon=FALSE			バルーンの表示を行わない
REM /error_stop=FALSE		エラー発生時にもダイアログを出力しない
REM /bufsize=1024			バッファサイズの指定(単位:MB)
REM /log					基本ログ(fastcopy.log)を出力有効化
REM /filelog				詳細ログ(ファイルコピー単位のログ)を出力有効化
REM /utf8					ログファイルの文字コードをUTF-8に指定
REM /skip_empty_dir=FALSE	空ディレクトリもコピー対象とする
REM /force_start=3			FastCopy同実行数上限数
REM /speed=full				速度制限を無しに設定
REM /exclude="Thumbs.db"	コピー除外ファイル指定
REM /time_allow=2000		タイムスタンプの許容差異時間(単位:ms)
REM /acl					アクセス許可情報(ACL)をコピー対象に含める
REM /reparse				ジャンクション・マウントポイント・シンボリックリンク自体をコピー
REM /verify					ベリファイ(書き込み時の正確性確認)を有効
REM =========================================================================================================
REM   定義-END
REM =========================================================================================================



REM =========================================================================================================
REM   メイン処理-START
REM =========================================================================================================

REM //FastCopy実行
%CMD% %CMD_OPTS% %COPY_SRC_PATH% /to=%COPY_DEST_PATH%

REM =========================================================================================================
REM   メイン処理-END
REM =========================================================================================================

exit /b

実行時の状態

fastcopy.batが正常に動作すると、下記のようにコマンドプロンプトが表示され、fastcopyのコマンドが表示されます。FastCopyが終了すると自動的に閉じます。

Windowsタスクマネージャーを見るとFastCopyのプロセスが動いていることが分かります。

デスクトップ右下のインジケーターを見るとFastCopyのアイコンが表示されます。

FastCopyログの種類

FastCopyが出力する際は、基本ログと詳細ログ(またはファイルログ)と呼ばれる2種類のログが存在します。

基本ログ

基本ログは、FastCopy.exeと同階層に「FastCopy.log」ファイルとして作成されます。

中身は非常なシンプルな構成になっています。

詳細ログ(ファイルログ)

詳細ログは、FastCopy.exeと同階層にある「Logs」フォルダの中に「FastCopy実行時の時間」のファイル名で作成されます。

こちらはファイル単位で詳細なログが表示されます。

ログの末端にはサマリが表示されます。

また、詳細ログの行の先頭に記号がついていますが、下記の意味になります。

記号意味
ファイル/ディレクトリの作成
ファイル/ディレクトリの削除
->シンボリックリンク/ジャンクションの作成
=>ハードリンクの作成
!!ベリファイエラー(ハッシュ値の不一致)

フルコピー(初回)

まずは、コピー先に何もない状態でコピーした状態のログを確認してみます。

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 12:47:13

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-124713-0.log
-------------------------------------------------

TotalRead  = 88 MiB
TotalWrite = 88 MiB
TotalFiles = 10,001 (111)
TotalTime  = 01:43
TransRate  = 0.86 MiB/s
FileRate   = 97.1 files/s
VerifyRead = 88 MiB
VerifyFiles= 10,001

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 12:48:56

一通りのログが出力されています。TotalFilesがファイル数で()の中はフォルダ数になっています。設定したオプション(ExcludeやACL、同期モード)も記載されています。

詳細ログ

詳細ログは全部記載すると大変なので、確認する部分を抜粋します。

コピーされたフォルダとファイルの一覧が表示されています。

フォルダやファイル名の後ろに出力している<YYYYMMDD-HHMMSSss>は、更新日時が記録されているようです。

ファイルに関しては、更新日時以外にもファイル容量(Byte表記)とベリファイのハッシュ値が付与されます。

最後にでてくるサマリーは基本ログと同じものです。

差分コピー(差分なし)

フルコピーが完了している状態でfastcopy.batを実行してみます。

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 14:00:49

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-140049-0.log
-------------------------------------------------

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 0 (0)
TotalSkip  = 88 MiB
SkipFiles  = 10,001 (0)
TotalTime  = 1.5 sec
TransRate  = 0.00 MiB/s
FileRate   = 0.00 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 0

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 14:00:50

新しい項目として、「TotalSkip」「SkipFiles」が表示されました。スキップした容量とファイル数が見えるようです。SkipFilesの(0)を見るとフォルダはスキップ対象としてカウントされていないようです・・・フォルダもカウントしてほしいところ・・・・。

詳細ログ

ファイルがないときは、基本ログと同じ出力内容です。

差分コピー(コピー元に新規フォルダ・ファイルあり)

次にコピー元に差分があった際にどのような動きになるか確認します。

コピー元に下記の変更を行いました。

  • 新規フォルダ:「NewFolder」を作成
  • 新規ファイル:「NewFolder」の中に「NewText.txt」を作成

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 15:02:42

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-150242-0.log
-------------------------------------------------

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 1 (1)
TotalSkip  = 88 MiB
SkipFiles  = 10,001 (0)
TotalTime  = 1.7 sec
TransRate  = 0.00 MiB/s
FileRate   = 0.60 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 1

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 15:02:44

TotalFilesに1つのファイルと1つのフォルダがコピーされたことがわかります。

詳細ログ

詳細ログからファイル単位で記録が行えます。

差分コピー(コピー元に変更フォルダ・ファイルあり)

コピー元に変更フォルダと変更ファイルがあった場合です。

  • 変更フォルダ:「テストフォルダー01」を「テストフォルダー01_Modify」に変更
  • 変更ファイル:「NewText.txt」に文章を書き込み

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 15:06:46

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-150646-0.log
-------------------------------------------------

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 1,001 (11)
TotalSkip  = 88 MiB
SkipFiles  = 9,001 (0)
TotalDel   = 0.0 MiB
DelFiles   = 1,000 (11)
TotalTime  = 16.0 sec
TransRate  = 0.00 MiB/s
FileRate   = 62.6 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 1,001

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 15:07:02

TotalFilesが1001(11)でDelFilesが1000(11)になっています。フォルダを変更した配下のファイルが一旦削除されて、再コピーされていることが確認できます。

詳細ログ

詳細ログを見ると、名称変更のあったフォルダ配下のファイルが一度削除されました。

ファイルの中身だけ変更したNewText.txtの削除履歴はなく、+(作成)の扱いになっていました。

差分コピー(コピー元に削除フォルダ・ファイルあり)

次は、コピー元からファイルが削除された場合です。

  • 削除フォルダ:先ほど作成した「NewFolder」
  • 削除ファイル:「NewFolder」配下の「NewText.txt」

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 15:29:01

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-152901-0.log
-------------------------------------------------

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 0 (0)
TotalSkip  = 88 MiB
SkipFiles  = 10,001 (0)
TotalDel   = 0.0 MiB
DelFiles   = 1 (1)
TotalTime  = 1.5 sec
TransRate  = 0.00 MiB/s
FileRate   = 0.00 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 0

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 15:29:02

DelFilesの項目が表示されました。削除されているのがわかります。

詳細ログ

削除されているのがわかります。

差分コピー(コピー先に新規ファイル、フォルダあり)

余りないことですが、コピー先にだけ新規ファイルとフォルダがある場合です。同期モードで動かしているのでコピー先から削除されるのが正しい状態です。

コピー先に下記を作成しました。

  • 新規フォルダ:「NewFolder」を作成
  • 新規ファイル:「NewFolder」配下に「NewText.txt」を作成

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 15:44:20

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-154420-0.log
-------------------------------------------------

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 0 (0)
TotalSkip  = 1,060 MiB
SkipFiles  = 10,012 (0)
TotalDel   = 0.0 MiB
DelFiles   = 1 (1)
TotalTime  = 1.4 sec
TransRate  = 0.00 MiB/s
FileRate   = 0.00 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 0

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 15:44:21

DelFilesでファイルとフォルダが1つずつ削除されているのがわかります。

詳細ログ

削除されているファイルとフォルダが確認できます。

差分コピー(コピー元にエラーファイル)

コピー元にエラーがファイルあった場合です。今回は、明示的にロックファイルを作成しました。

※FastCopyでロックファイルをコピーするときに、0KBのテキストファイルだとエラーはでるが、コピーされる現象がありました。サイズが0ではないファイルをロックしてください。

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 17:15:18

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-171518-0.log
-------------------------------------------------
OpenFile(プロセスはファイルにアクセスできません。別のプロセスが使用中です。32) : \\devisilon\test_src\test.zip

TotalRead  = 0.0 MiB
TotalWrite = 0.0 MiB
TotalFiles = 0 (0)
TotalSkip  = 88 MiB
SkipFiles  = 10,001 (0)
TotalTime  = 1.4 sec
TransRate  = 0.00 MiB/s
FileRate   = 0.00 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 0

Result : (ErrFiles : 1 / ErrDirs : 0) at 2020/11/02 17:15:19

ErrFilesとして記録されています。エラーに関するファイル名は、基本ログにも出力されます。

詳細ログ

詳細ログも同じですね。エラーとして記録されます。

フルコピー(途中で強制停止)

コピー中に強制的に終了した場合、どのようにログが出力されるか確認します。コピー先のファイルをすべて削除してもう一度フルコピーを実施します。コマンドプロンプトを閉じてもFastCopy自体はバックグラウンドプロセスとして処理し続けられるため、別のコマンドプロンプトから「taskkill /IM FastCopy.exe」を実行して終了させます。フォルダの半分程度がコピーされたあたりで強制停止しました。

※タスクマネージャーから手動でFastCopyを終了しないでください。KILLシグナルの関係かと思いますが、タスクマネージャーから手動で停止するとログが出力されません。

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 17:43:20

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-174320-0.log
-------------------------------------------------
CancelCopy (aborted by system or etc.)

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 17:43:20

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-174320-0.log
-------------------------------------------------
 Aborted by User

TotalRead  = 88 MiB
TotalWrite = 0.0 MiB
TotalFiles = 5,371 (56)
TotalTime  = 59.6 sec
TransRate  = 0.00 MiB/s
FileRate   = 90.1 files/s
VerifyRead = 0.0 MiB
VerifyFiles= 0

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 17:44:19

Aborted by Userが出力されて強制停止したことがわかります。少し気持ち悪いなと思ったのは強制停止するとログのヘッダ部分が二重に出力されます。

TotalFilesは強制停止した部分までのコピーが行えたファイルとフォルダ数です。VerifyFilesが0なのは、完了する前だと値を保持していないのかな・・・ファイル単位でベリファイしていると思っているのですが・・・不明です。

詳細ログ

ここが一番困ったのですが、強制停止をするとフォルダのログはでてもファイルのログは出力されません。ファイルのリストは処理の最後に出力する仕様のようです。

ログ末尾付近にAborted by Userで強制停止されたことがわかります。

もう1つ注意点としては、最後にコピーしていたトップフォルダの更新日時は、更新されません。テストフォルダー6が開始された当たりで停止したのですが、更新日時がコピー開始時間のままになります。

※配下の更新日時は反映されていました。

差分コピー(強制停止から続き)

フルコピー(途中で強制停止)したところから、再度FastCopyを最後まで流してみます。

基本ログ

=================================================
FastCopy(ver3.92 (Admin)) start at 2020/11/02 17:54:54

<Source>  \\devisilon\test_src
<DestDir> \\devunity-temp\test_dest
<Exclude> Thumbs.db
<Command> 同期(サイズ・日付) (with Verify ACL)
<FileLog> C:\FastCopy392_x64\Log\20201102-175454-0.log
-------------------------------------------------

TotalRead  = 88 MiB
TotalWrite = 88 MiB
TotalFiles = 4,630 (55)
TotalSkip  = 0.0 MiB
SkipFiles  = 5,371 (0)
TotalTime  = 52.5 sec
TransRate  = 1.68 MiB/s
FileRate   = 88.3 files/s
VerifyRead = 88 MiB
VerifyFiles= 4,630

Result : (ErrFiles : 0 / ErrDirs : 0) at 2020/11/02 17:55:46

フルコピーした差分からコピーが行われています。最後のコピー中のフォルダの更新日時がずれたため、削除→コピーの流れを危惧しましたが正常にコピーされました。

詳細ログ

ファイルのログも(差分から)正常に出力されています。

コピー途中から開始した場合も、エラー記載などはありませんでした。

参考

FastCopy Help

まとめ

強制停止したときの詳細ログにファイルログが記録されないのだけが残念・・・・知らないと結構焦りそう・・・。

スポンサーリンク
アドセンス1
アドセンス1
ブログランキング・にほんブログ村へ

シェアする

フォローする