filterlog.txtにログとして記載されないこNo.36261
緒方聡 さん 09/05/24 22:05
 
お世話になってます。

マクロのユーザ様から問い合わせがあり、ここ2ヶ月ぐらいいろいろと試していて、
一度だけ目撃した現象があります。

「全般的な設定」「上級者向け」「動作の記録」「振り分け結果をfilterlog.txtフ
ァイルに記録する」にチェックをしていても、ものすごく低い確率で記録されないこ
とがある、ということはないでしょうか。

やっていることは、

・自動起動マクロの送受信開始直前でこのオプションを有効にする
・自動起動マクロの受信が一段落した時にfilterlog.txtをチェックする

というものですが、受信したメールがfilterlog.txtに記載されていないことを一度
だけ確認しました。その際エラーなどは特に出ていません。

もしかするとfilterlog.txtにログが残らない条件というのがあるのでしょうか?

秀丸メールのバージョンは5.15betaか5.16です。

一度しか確認していないので、あまり自信がありませんが、確認していただければ幸
いです。

[ ]
RE:36261 filterlog.txtにログとして記載No.36265
秀まるお2 さん 09/05/25 10:29
 
 こちらのソースコードを確認した限りでは、振り分けの処理の中で、
filterlog.txtに何も出力しようとせずに振り分けの処理を終わるということは
ありませんでした。

 具体的には、振り分けの処理というのは

BOOL CFilter::ProcessFilter( .... );

 という唯一の関数でのみ実行出来る仕組みになっていて、その関数の中の処理
として、実際の振り分けを行う処理の一番最後にログを出力する処理があって、
その「ログを出力する処理」の前にはreturn文は存在せず、唯一存在している
goto文は、ログを出力する処理よりも後ろへジャンプすることはありません。

 ということで仕組み上は、ログを出さずに振り分けだけ実行することは無いは
ずですが…。1つログを出さない可能性があります。それは、filterlog.txtフ
ァイルのオープン(CreateFile)に失敗したケースです。この場合は何もエラー
メッセージを出すことも無く、ログも出さずにreturnしてしまいます。

    if( config.fFilterLog ) {
        if( *pAction == 0 && config.fFilterLog == 1 ) {
            // 振り分けしなかった場合はログに残さない。
        } else {
            if( hfileLog == INVALID_HANDLE_VALUE ) {
                char    szFileName[MAX_PATH * 2];
                strcpy( szFileName, config.szHomeDir );
                strcat( szFileName, global_fNoSec ? szFilterLogTxtNoSec : sz
FilterLogTxt );
                hfileLog = CreateFile( szFileName, GENERIC_WRITE, global_dwS
hare
                                , NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_ARCHIVE,
 NULL );
            }
            if( hfileLog == INVALID_HANDLE_VALUE ) {        // 書き込みエラー?
                return fFound;
            }
            SetFilePointer( hfileLog, 0, NULL, FILE_END );
            ...
            ...
            ...
            WriteFile( hfileLog, strLog.Direct(), strLog.GetLength(), &cbWri
tten, NULL );
        }
    }
    return fFound;

   global_dwShareには、FILE_SHARE_READ | FILE_SHARE_WRITE が入ってます。

 もしも外部のプロセスがfilterlog.txtファイルを

       FILE_SHARE_READ | FILE_SHAER_WRITE

 無しでオープンしっぱなしにしてると、秀丸メールがログを出力出来ない、と
いうことはありえると思います。それ以外はちょっと分かりません。

 もし必要でしたら、ログの出力に失敗した場合はdump.txtに何か情報を出すよ
うにする、っていう対応なら出来ますけども…。念のためそういう処理を入れて
みます。というか、たしかにログを出した場合もdump.txtに何か出すようにして
みます。

[ ]
RE:36265 filterlog.txtにログとして記載No.36268
緒方聡 さん 09/05/25 18:54
 
お手数をおかけしてすみません。

> もしも外部のプロセスがfilterlog.txtファイルを
>
>       FILE_SHARE_READ | FILE_SHAER_WRITE
>
> 無しでオープンしっぱなしにしてると、秀丸メールがログを出力出来ない、と
>いうことはありえると思います。それ以外はちょっと分かりません。


僕のプログラムでは、filterlog.txt を以下のようにオープンしています。

    file1 = CreateFile(filename, GENERIC_READ, 0, NULL, OPEN_EXISTING, 0, 0);

もしかするとこれが原因なのかもしれません。

自分のプログラムの処理を追ってみると、filterlog.txt を読み込んでいるタイミン
グはふたつで、ひとつは「受信直前」に 1 回、もうひとつは「受信が一段落した
時」に受信したメールの数だけ。

問題なのは「受信が一段落した時」にあるべきログがないので、受信直前の処理が問
題なのかなぁ、という気がしました。

プログラムとマクロの双方を見ると、なんとマクロが run でプログラムを呼び出し
ているため、僕のプログラムと秀丸メールの処理が同時に走り、filterlog.txt に書
き込まれないことが起こりうる、ということがわかりました。

ものすごく低い確率で発生する問題は run と runsync の使い分けの間違いでした。

ありがとうございました。

[ ]
RE:36268 filterlog.txtにログとして記載No.36269
秀まるお2 さん 09/05/25 21:58
 
 どっちにしてもマクロを使わずにDLL化してもらえればいいと思うんですが、
やっぱりマクロでやられますかね。だとしたら、せめてEnvChanged関数呼び出し
の問題だけでも解決すると、いわゆるマクロ実行のバッティング問題が多少改善
可能なんですけども…

 hidebiffさんがやられているのは、単純にfilterlog.txtの作成に関するオプ
ション変更なので、これの変更だけをするのであれば、EnvChanged関数内での面
倒な排他制御は必要ありません。なので、こういう場合用の、無理矢理に排他制
御を無視しててEnvChagnedする、

     EnvChangedDanger

 って関数を追加しようと思います。それを呼ぶ用に直してもらおうかなぁと…。

 今日アップロードしたV5.18β1には追加してません。次回のβ版に追加します。

 DLL化していただけるならそっちの方がいいですけど。どっちにしても念のた
め追加させていただきます。

[ ]
RE:36269 filterlog.txtにログとして記載No.36271
緒方聡 さん 09/05/26 00:03
 
こんばんは。

DLL化はするつもりです。
ただ、今出てるトラブルを解決してからでないと後々トラブるので質問させてもらい
ました。

とりあえず報告してくれたユーザさんに差分を提供してから、こつこつやろうかなと
思います。

[ ]
RE:36265 filterlog.txtにログとして記載No.37101
緒方聡 さん 09/10/09 18:24
 
> もし必要でしたら、ログの出力に失敗した場合はdump.txtに何か情報を出すよ
>うにする、っていう対応なら出来ますけども…。念のためそういう処理を入れて
>みます。というか、たしかにログを出した場合もdump.txtに何か出すようにして
>みます。

その後も極まれに filterlog.txt に振り分け条件がかかれない
ことが発生しています。

filterlog.txt nolog

というのが振り分け条件書き込みに失敗したログだと思います。
dump.txt を取り出し始めて初めて発生しました。


filterlog.txt のアクセスは以下のような感じだと思います。

 送受信の開始直前に hidebiff でアクセス。
 受信処理中に秀丸メールでアクセス。
 受信がひと段落した時に hidebiff でアクセス。

送受信の開始直前に DLL から EXE を CreateProcess で起動して
filterlog.txt をオープン(行数を数えている)しています。
DLL では EXE の終了を待っています。
その後、秀丸メール本体で振り分けログが追記されます。
受信がひと段落した時に DLL から EXE を CreateProcess で起動して
filterlog.txt をオープン(数えた行数以降を検索)しています。
DLL では EXE の終了を待っています。

filterlog.txt が秀丸メール本体で開けないのは、
- 送受信の開始直前の処理中に秀丸メールの処理が行われている
- 送受信の開始直前の処理でファイルが正しく閉じられていない
だと思いますが、前者も後者も考えにくいなぁ、と思っています。

以下が、実際に使用しているファイル内容を取得するための関数です。

/**
 * 指定されたファイルの内容を取得する。
 *
 * 呼び出し元で戻り値のポインタを開放しなければならない。
 * size が NULL の場合は、当然ファイルサイズはポインタに出力されない。
 *
 * この関数は [ファイル内容] + ['\0'] という形式でポインタを返す。
 * ただし出力される size は最後の \0 を含まない。
 *
 * ファイルが存在しない場合、処理に失敗した場合は NULL を返す。
 *
 * @param [in] filename ファイルパス
 * @param [out] size ファイルサイズ
 * @return ファイルの内容
 */
static char *getFileContents(const char *filename, DWORD *size) {
 HANDLE file1;
 HANDLE map1;
 DWORD hsize1, lsize1;
 char *view1;
 char *result = NULL;
 static int count = 0;
 string map("filemapping");
 char buf[6] = {0};
 _itoa(count++, buf, 10);
 map += buf;

 // ファイルの生成
 file1 = CreateFile(filename, GENERIC_READ, 0, NULL, OPEN_EXISTING, 0, 0);
 if (file1 == INVALID_HANDLE_VALUE) {
  // ファイルが存在しない
  return result;
 }

 // サイズの取得
 lsize1 = GetFileSize(file1, &hsize1);
 if (hsize1 != 0) {
  // ファイルが大きすぎる場合はエラーにしちゃう
  return result;
 }
 
 // メモリマップドファイルの生成
 map1 = CreateFileMapping(file1, NULL, PAGE_READONLY, hsize1, lsize1, map.c_
str());
 if (map1 == NULL) {
  // エラー処理
  msgbox("error 32");
  CloseHandle(file1);
  return result;
 }
 
 // マップビューの生成
 view1 = (char *)MapViewOfFile(map1, FILE_MAP_READ, 0, 0, 0);
 if (view1 == NULL) {
  // エラー処理
  msgbox("error 42");
  CloseHandle(map1);
  CloseHandle(file1);
  return result;
 }
 
 result = (char *)malloc(lsize1 + 1);
 if (result) {
  memcpy(result, view1, lsize1);
  result[lsize1] = '\0';
 }
 
 // アンマップ
 if (!UnmapViewOfFile(view1)) {
  // エラー処理
  msgbox("error 5s");
 }

 CloseHandle(map1);
 CloseHandle(file1);

 if (size != NULL) {
  *size = lsize1;
 }

 return result;
}

何かアドバイスいただければ幸いです。

[ ]
RE:37101 filterlog.txtにログとして記載No.37102
秀まるお2 さん 09/10/09 18:55
 
 「filterlog.txt nolog」という記録が出るのは、filterlog.txtへの書き込み
に失敗したのじゃなくて、ログを取る設定がOFFである時に出している記録とい
うことになります。

 ソースコードを書くと、

    if( config.fFilterLog ) {
        if( *pAction == 0 && config.fFilterLog == 1 ) {
            // 振り分けしなかった場合はログに残さない。
            DumpSmall( "filterlog.txt no output" );
        } else {
            if( hfileLog == INVALID_HANDLE_VALUE ) {
                char    szFileName[MAX_PATH * 2];
                strcpy( szFileName, config.szHomeDir );
                strcat( szFileName, global_fNoSec ? szFilterLogTxtNoSec : sz
FilterLogTxt );
                hfileLog = CreateFile( szFileName, GENERIC_WRITE, FILE_SHARE
_READ | FILE_SHARE_WRITE
                                , NULL, OPEN_ALWAYS, FILE_ATTRIBUTE_ARCHIVE,
 NULL );
            }
            if( hfileLog == INVALID_HANDLE_VALUE ) {        // 書き込みエラー?
                int nError = GetLastError();
                wsprintf( szDump, "filterlog.txt access failed, code=%u", nE
rror );
                DumpSmall( szDump );
                return fFound;
            }
            ...
            ... 書き込み処理
        }
    } else {
        DumpSmall( "filterlog.txt nolog" );
    }


 のようになってます。config.fFilterLogというのは、レジストリの
"FilterLog"の値を読み込んでる物です。


 ということで、何かマクロでそこの設定を書き換える関係がおかしいのかなぁ
と思いますけども…。

 filterlog.txtは常に作成する設定のままにするというか、マクロの動作条件
としてそういう風にしたらいいんじゃないかと思います。

-------------------------------------------------------------

 それと、今回の件とは関係ないですが、排他制御でエラーになることを防ぐた
めには、hidebiffさんの方で、CreateFileする時の第3パラメータに

 FILE_SHARE_READ | FILE_SHARE_WRITE

 を指定してくれた方がいいです。こうしておけば、仮にファイルをオープンし
っぱなしにしてても他の人がアクセス拒否されることは無いです。

[ ]
RE:37102 filterlog.txtにログとして記載No.37103
緒方聡 さん 09/10/09 19:30
 
なるほど、理解できました。
以下は秀丸メール本体の自動起動マクロの「送受信の開始直前」に
登録している関数です。


extern "C" void _cdecl AtSendReceive() {
 int n = GetTransmitCommandCode();
 if (n == 40003 ||   // 受信
   n == 40216 ||  // 送受信
   n == 40024 ||  // すべて送受信
   n == 40143 ||  // すべて受信
   n == 40074 ||  // リモートメール
   n == 40209 ||  // リモートメール - 現在メールの再受信
   n == 1) {   // 定期受信
  int i = 0;
  while (true) {
   std::string account(Account(i));
   if (account == "") {
    break;
   }
   LoadAccountProp(account.c_str());
   SetAccountProp("fRecvLog", 1);
   SaveAccountProp();
   i++;
  }
  DWORD filterLog = 2;
  set_reg_value(FILTER_LOG_KEY, REG_DWORD, (CONST BYTE *)&filterLog, sizeof
DWORD);
  EnvChanged(0);

  std::string path;
  path.append("\"").append(macrodir).append("\\hidebiff.exe\" -i");

  PROCESS_INFORMATION pi;
  STARTUPINFO si;
  memset(&si, 0, sizeof(STARTUPINFO));
  si.cb = sizeof(STARTUPINFO);
  CreateProcess(NULL, (LPSTR)path.c_str(), NULL, NULL, FALSE, HIGH_PRIORITY_
CLASS, NULL, NULL, &si, &pi);
  WaitForSingleObject(pi.hProcess, INFINITE);
  CloseHandle(pi.hThread);
  CloseHandle(pi.hProcess);
 }
}


考えられる可能性として
- GetTransmitCommandCode() の返す値で if 文に入っていない??
- EnvChanged(0) に失敗している??
という気がします。なんだかすみません。


動作条件に filterlog.txt の生成を入れてしまう、というのは
簡単でよさそうですが、これは最後の手段にしたいと思います。

[ ]
RE:37103 filterlog.txtにログとして記載No.37110
秀まるお2 さん 09/10/10 21:21
 
 dump.txtの中での、その「filter.txt nolog」の出ている箇所の直前の所でた
しかにDLLが呼び出されているかどうか、あと、そのDLLからEnvChanged関数が呼
び出されてるかどうかなんかはdump.txtに出てるんじゃないかと思います。

 EnvChagned関数が呼び出された場合は、「tkinfo 70」という記録が出てると
思います。

 EnvChanged関数呼び出しがたしかになされてるとしたら、あとは秀丸メールで
のそのEnvChanged関数の中から、fFilterLogの値をdump.txtに毎回出力するよう
な処理を入れてみるって作戦はありかもしれません。

 dump.txtに出てくる「tkinfo XX」の所の番号と関数の対応は、聞いていただ
ければお返事出来ます。(というか、その対応表を書いてもいいです)

[ ]
RE:37110 filterlog.txtにログとして記載No.37113
緒方聡 さん 09/10/12 10:52
 
filterlog.txt nolog の前後のログです(個人情報的な部分はxxxなどに変更してあ
ります)。
直前に TKINFO 70 は見当たりませんでした。



14:33:32.390 (   0) ExecCommandMacroSub HidemaruMailSearch.mac
14:33:42.171 (2318) TKINFO 160
14:33:42.171 (4982) tkinfo 160
14:33:42.171 (19840) MuteOther()
14:33:42.171 (19903) MuteOther: OBJECT_0
14:33:42.171 ( 656) ProcessExecEvent
14:33:42.171 (2318) TKINFO 6
14:33:42.171 (1254) ProcessExecEvent exit
14:33:42.171 (19990) ReleaseMuteOther()
14:33:42.171 (2318) TKINFO 7
14:33:42.171 (2318) TKINFO 82
14:33:42.171 (8650) cPack=1 FindPackAnd=1 Charset=0 TotalTaget=4 FindIn=0 Fi
ndFlagEnable=1 FindFlagMask=10000 FindFlag=10000
14:33:42.171 (8658) wEmail=0 dwMessageId=0 PersonTarget=1F FindTermSize=0 Fi
ndTermTransmit=0 FindTermDate=0
14:33:42.171 (8660) Account= Folder=0 SubFolder=
14:33:42.171 (8664) str=xxx
14:33:42.171 (8667) NoCase=xxx
14:33:42.171 (8677) cch=7 CaseSense=0 WordOnly=0 Regular=0 Fuzzy=0 NoReturn=
0 Not=0 Target=3
14:33:42.171 (2318) TKINFO 199
14:33:42.171 (2318) TKINFO 85
14:33:42.171 (7910) leave
14:33:42.171 (14700) 42010 ret 1
14:33:42.281 (2318) TKINFO 204
14:33:42.281 (1272) GetTimeZoneInformation return=0 bias=-480 stdbias=0 dayl
ightbias=0
14:33:42.296 (1584) HmCreate
14:33:42.296 (   0) call WinMainSub
14:33:42.296 (   0) FrameWndProc: WM_CREATE
14:33:42.296 (   0) ClientWndProc: WM_CREATE
14:33:42.312 (   0) return WinMainSub
14:33:42.312 (1588) HmCreate return
14:33:42.312 (2335) SetNull at pHidemaruSmall
14:33:42.625 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\091009_00\xxx.eml
14:33:42.625 (2087) SetText at pHidemaruSmall
14:33:42.625 (2116) cmdReasonCreated=open
14:33:50.765 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\091008_01\xxx.1.jpg
14:33:50.765 (1028) will SHGetFileInfo
14:33:50.781 (1031) done
14:33:50.781 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\091008_01\xxx.2.jpg
14:33:50.796 (1028) will SHGetFileInfo
14:33:50.812 (1031) done
14:33:50.812 (2087) SetText at pHidemaruSmall
14:33:50.812 (2116) cmdReasonCreated=open
14:33:51.015 (7378) FrameWndProc() IDTIMER_AUTODOWN
14:33:51.015 (1517) IsProcessExitable: ShowFrame
14:33:51.015 (1520) IsProcessExitable: IconInTaskbar
14:33:51.015 (1523) IsProcessExitable: editor > 1
14:33:51.015 (15057) StopAutoDownTimer()
14:33:51.015 (8266) CTrans::AutoDown()
14:33:51.015 (4982) tkinfo 182
14:33:51.015 (8012) InitPatrol
14:33:51.015 (8659) EnterTrans
14:33:51.015 ( 739) InitializeFilter
14:33:51.015 (8687) Trans mutex
14:33:51.015 (8737) Trans mutex release
14:33:51.015 (8739) EnterTrans() entered
14:33:51.015 (6675) ProcessTransmitSub()
14:33:51.015 (6698) fSetReceivedIcon = 0
14:33:51.015 (6772) will SetTransmitTaskbarIcon
14:33:51.015 (1955) will Shell_NotifyIcon
14:33:51.031 (1959) done
14:33:51.031 (1965) will WM_SETICON
14:33:51.031 (1969) done
14:33:51.046 (1983) will SetTimer
14:33:51.046 (6774) done
14:33:51.046 (6776) will dialup
14:33:51.046 ( 732) RASSUB::EnsureOnline()
14:33:51.046 ( 741) RASSUB: GetConnectedState
14:33:51.046 ( 756) RASSUB: already connected
14:33:51.046 (6810) will apSock init
14:33:51.046 (6838) will CheckNN2MIncluding
14:33:51.046 (6840) done
14:33:51.046 (6843) will EnterTransDockTwin
14:33:51.046 (6846) ProcessTransmitSub() new pSock
14:33:51.046 (8269) 準備中
14:33:51.046 (6867) ProcessTransmitSub() ModelessDialog, TransDlgProc
14:33:51.046 (  62) SilentDialogBox()
14:33:51.046 (5705) TransDlgProc() WM_INITDIALOG
14:33:51.046 (5736) IDTIMER_TRANS_START set
14:33:51.062 (5875) IDTIMER_TRANS_START kill
14:33:51.062 (8269) 受信 - xxx@example.com  ...  サーバーを検索中 - imap.gma
il.com
14:33:51.062 (8269) 接続中 - 74.125.127.109 (port=993)
14:33:51.281 (3663) Send ThreadCreated 2580
14:33:51.281 (8269) 完了
14:33:51.281 (8269) SSL初期化中
14:33:51.734 (8269) 暗号化開始 (TLS1.0/RC4/128bit)
R * OK Gimap ready for requests from 114.241.174.118 39if3163519pzk.85
14:33:51.734 (8269) アカウント/パスワードを送信
S ****
R C1 OK xxx@example.com authenticated (Success)
14:33:52.031 S C2 LIST "" *
14:33:52.031 (8269) IMAPフォルダ一覧を取得中
R * LIST (\HasNoChildren) "/" "Drafts"
  * LIST (\HasNoChildren) "/" "INBOX"
  * LIST (\HasNoChildren) "/" "Sent"
  * LIST (\HasNoChildren) "/" "Trash"
  * LIST (\Noselect \HasChildren) "/" "[Gmail]"
  * LIST (\HasNoChildren) "/" "[Gmail]/All Mail"
  * LIST (\HasNoChildren) "/" "[Gmail]/Drafts"
  * LIST (\HasNoChildren) "/" "[Gmail]/Sent Mail"
  * LIST (\HasNoChildren) "/" "[Gmail]/Spam"
  * LIST (\HasNoChildren) "/" "[Gmail]/Starred"
  * LIST (\HasNoChildren) "/" "[Gmail]/Trash"
  C2 OK Success
S C3 SELECT "INBOX"
14:33:52.296 (8269) メール一覧を取得中(1/2)
R * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
  * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
  * OK [UIDVALIDITY 612562459]
  * 4869 EXISTS
  * 0 RECENT
  * OK [UNSEEN 2689]
  * OK [UIDNEXT 5212]
  C3 OK [READ-WRITE] INBOX selected. (Success)
14:33:52.750 S C4 UID SEARCH UNSEEN
14:33:53.765 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090930_03\xxx.png
14:33:53.765 (1028) will SHGetFileInfo
14:33:53.796 (1031) done
14:33:53.796 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090930_03\xxx.log.png
14:33:53.796 (1028) will SHGetFileInfo
14:33:53.828 (1031) done
14:33:53.828 (2087) SetText at pHidemaruSmall
14:33:53.828 (2116) cmdReasonCreated=open
14:33:54.703 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090918_00\xxx.xls
14:33:54.734 (1028) will SHGetFileInfo
14:33:54.734 (1031) done
14:33:54.734 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090918_00\xxx.png
14:33:54.734 (1028) will SHGetFileInfo
14:33:54.750 (1031) done
14:33:54.750 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090918_00\xxx.txt
14:33:54.750 (1028) will SHGetFileInfo
14:33:54.765 (1031) done
14:33:54.765 (2087) SetText at pHidemaruSmall
14:33:54.765 (2116) cmdReasonCreated=open
R ...(13455バイト)
  C4 OK SEARCH completed (Success)
14:33:55.140 (8269) 2/2)
S C5 SELECT "[Gmail]/Sent Mail"
14:33:55.484 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090917_00\xxx.png
14:33:55.515 (1028) will SHGetFileInfo
14:33:55.546 (1031) done
14:33:55.562 (2087) SetText at pHidemaruSmall
14:33:55.562 (2116) cmdReasonCreated=open
R * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
  * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
  * OK [UIDVALIDITY 612562464]
  * 2017 EXISTS
  * 0 RECENT
  * OK [UNSEEN 37]
  * OK [UIDNEXT 2029]
  C5 OK [READ-WRITE] [Gmail]/Sent Mail selected. (Success)
14:33:55.703 S C6 UID SEARCH UNSEEN
R ...(191バイト)
  C6 OK SEARCH completed (Success)
14:33:56.093 (8269) 0 / 1 済み (0.0K / 1Kバイト)
S C7 SELECT "INBOX"
R * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
  * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
  * OK [UIDVALIDITY 612562459]
  * 4869 EXISTS
  * 0 RECENT
  * OK [UNSEEN 2689]
  * OK [UIDNEXT 5212]
  C7 OK [READ-WRITE] INBOX selected. (Success)
14:33:56.375 S C8 UID FETCH 5211 (RFC822)
R ...(4561バイト)
  C8 OK Success
14:33:56.671 (3841) filter action=00000001
14:33:56.671 (3978) filterlog.txt nolog
14:33:56.703 (4874) Appended xxx@example.com/6/ file=受信ログ200910_05.txt o
ffset1=142558 offset2=142556 size=4635
14:33:56.703 (4891) xxx@example.com,6 cEach=0
14:33:56.703 (4916) GrepResult not realtime
14:33:56.703 (4874) Appended xxx@example.com/0/yyy file=yyy200910.txt offset
1=7763 offset2=7761 size=4410
14:33:56.703 (4916) GrepResult not realtime
14:33:56.718 (4874) Appended xxx@example.com/11/ file=Remote20091009.txt off
set1=44239 offset2=44237 size=3072
14:33:56.718 (8269) 1 / 1 済み (1.0K / 1Kバイト)
14:33:56.718 S C9 LOGOUT
14:33:56.718 (8589) Updating Remotemail 0, 0
14:33:56.890 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090915_02\zzz.xls
14:33:56.953 (2087) SetText at pHidemaruSmall
14:33:56.953 (2116) cmdReasonCreated=open
R * BYE LOGOUT Requested
  C9 OK 73 good day (Success)
14:33:56.968 (8475) tid=2580 ThreadExit 2580
14:33:56.984 (1307) Peek socket
14:33:56.984 (6108) IDTIMER_SOCKET_END received
14:33:56.984 (6170) IDTIMER_TRANS_START post
14:33:56.984 (5875) IDTIMER_TRANS_START kill
14:33:56.984 (8269) 終了
14:33:56.984 (8271) -
14:33:56.984 (6021) IDTIMER_TRANS_END set
14:33:56.984 (6104) IDTIMER_TRANS_END kill
14:33:56.984 ( 164) EndSilentDialog()
14:33:56.984 (6262) TransDlgProc() WM_DESTROY
14:33:56.984 ( 158) SilentDialogBox() exit
14:33:56.984 (6875) ProcessTransmitSub() ModelessDialog, TransDlgProc exit
14:33:56.984 (1989) RestoreTransmitTaskbarIcon()
14:33:56.984 (1832) SetReceivedTaskbarIcon 0
14:33:56.984 (1882) 常駐アイコンを戻します。
14:33:56.984 (1893) 本体アイコンを戻します。
14:33:57.000 (6950) fSetReceivedIcon != 0
14:33:57.015 (1832) SetReceivedTaskbarIcon 1
14:33:57.031 (8269)  1通のメールを受信しました。
14:33:57.031 (6997) ProcessTransmitSub() exit
14:33:57.031 (8043) FreePatrol
14:33:57.031 (8762) LeaveTrans()
14:33:57.062 (8422) AutoDown exit
14:33:57.062 (15037) StartAutoDownTimer()
14:33:57.062 (15045) StartAutoDownTimer() set
14:33:57.062 (2318) TKINFO 70
14:33:57.062 (8659) EnterTrans
14:33:57.062 (8687) Trans mutex
14:33:57.171 (19840) MuteOther()
14:33:57.171 (19903) MuteOther: OBJECT_0
14:33:57.171 (19990) ReleaseMuteOther()
14:33:57.171 (19840) tid=3572 MuteOther()
14:33:57.171 (19903) tid=3572 MuteOther: OBJECT_0
14:33:57.187 (19990) tid=3572 ReleaseMuteOther()
14:33:57.187 (19840) MuteOther()
14:33:57.187 (19903) MuteOther: OBJECT_0
14:33:57.187 (19990) ReleaseMuteOther()
14:33:57.187 (19840) tid=848 MuteOther()
14:33:57.187 (19903) tid=848 MuteOther: OBJECT_0
14:33:57.203 (19990) tid=848 ReleaseMuteOther()
14:33:57.203 (19840) MuteOther()
14:33:57.203 (19903) MuteOther: OBJECT_0
14:33:57.218 ( 945) C:\Program Files\HidemaruMail\MailData\xxx@example.com\
送信添付\090915_02\zzz.xls
14:33:57.218 (1028) will SHGetFileInfo
14:33:57.218 (1031) done
14:33:57.234 (19990) ReleaseMuteOther()
14:33:57.234 (8269) メール総数=2022 / 最近の分=110 / マーク=0
14:33:57.234 (8762) LeaveTrans()
14:33:57.250 (2318) TKINFO 103
14:33:58.234 (8269)  1通のメールを受信しました。

[ ]
RE:37113 filterlog.txtにログとして記載No.37115
秀まるお2 さん 09/10/13 08:58
 
 大文字/小文字の区別が間違ってましたが、大文字のがありました。

> 14:33:57.062 (2318) TKINFO 70

 あとはそのタイミングでたしかにfFilterLogの値が正しく書き換わってるかど
うかという話になりますけども。

 とりあえず次のβ版でdump.txtに、EnvChanged関数呼び出しの度にfFilterLog
の値を出力するように直してみます。

[ ]
RE:37115 filterlog.txtにログとして記載No.37116
秀まるお2 さん 09/10/13 09:12
 
 ちょっと理解不足の所があるような気がします。受信を開始する前に
fFilterLogを書き換えてるつもりのような気がしますが、受信の前には
TKINFO 70は無いようです。

 そもそも受信の前に実行してるのが「tkinfo 182」ということで、これは
GetTransmitCommandCodeという関数です。それを呼び出しただけで他は何もして
ないようです。

 あと、マクロ代替DLLを呼び出してる記録も無いようなので、その辺のログも
出すようにしてみます。

[ ]
RE:37116 filterlog.txtにログとして記載No.37117
秀まるお2 さん 09/10/13 09:41
 
 矢継ぎ早ですみません。もっと詳しく調べていますのでその途中経過を説明さ
せていただきますと…

 hidebiffさんの方では、たしかにGetTransmitCommandCode呼び出しの後に
EnvChanged(0)って関数呼び出しをしているようです。でもdump.txtにはその形
跡が無いです。

 これはなぜだか、今のところ分かりません。

 1つテストをしてみたんですけども、例えばエディタ上で、「message "A";」
みたいなマクロを実行してメッセージを出したまま、裏で送受信を実行して、そ
のときの自動実行マクロ代替DLLにて、EnvChanged(0);呼び出しをするテストを
してみました。

 そうしたら、5秒くらい経過した後に、

 「他のエディタウィンドウがマクロ実行中なので、このウィンドウ上での処理
が続行出来ません。マクロが終了するのを待ってからOKボタンを押すか…」

 のようなメッセージが出てきて先に進まない、という状況になりました。

 ということで、EnvChanged関数の中で排他制御をやっていて、結果として、エ
ディタウィンドウ上でマクロ実行中に裏でEnvChangedするというのは出来ない仕
組みになっているようです。

 ということで、まずはこの辺の処理から見直すというか、排他制御をかけずに
無理矢理EnvChangedが通るように直してみます。

 まぁ、そんな無理矢理なことをすると、それはそれでまたバグの元になるかも
しれませんが…

[ ]
RE:37117 filterlog.txtにログとして記載No.37120
緒方聡 さん 09/10/13 15:29
 
お世話になっています。

> ちょっと理解不足の所があるような気がします。受信を開始する前に
> fFilterLogを書き換えてるつもりのような気がしますが、受信の前には
> TKINFO 70は無いようです。

そうなんです。
それで「見当たらない」と報告させてもらいました。


>  1つテストをしてみたんですけども、例えばエディタ上で、「message "A";」
> みたいなマクロを実行してメッセージを出したまま、裏で送受信を実行して、そ
> のときの自動実行マクロ代替DLLにて、EnvChanged(0);呼び出しをするテストを
> してみました。

そうですね。これは確かによく起こります。
ですが、今回のケースは、これには当てはまりません。

流れは以下のような感じです。

- 定期受信でメール着信音が鳴り、メールが来たことがわかった
- トーストが出る場所を注目
- 出ない
- 本体でメールがあることを確認
- filterlog.txt を見て振り分けがないことが判明
- dump.txt を確認

いろいろとお手数をおかけします。

[ ]
RE:37120 filterlog.txtにログとして記載No.37121
秀まるお2 さん 09/10/13 16:55
 
 とりあえず次のβ版で、EnvChanged関数がたしかに呼び出しされれば必ずdump.
txtに記録を出すようにします。
 (現状では、tkinfo.dllのEnvChanged関数呼び出しされても、何らかの理由で
秀丸メール本体ウィンドウとの通信に失敗すると、dump.txtに何も出ないという
可能性がありました)

 その他、DLL|xxxx.macでマクロ実行した記録とかも出すようにします。あと、
EnvChangedの後のfFilterLogの値も出します。

 それでまた様子見していただくしか無いかなぁと思います。

 次のβ版で対応させていただきます。


[ ]