もじら組フォーラム

(環境: Mac/Other)

既出かもしれませんが，探しても見つからなかったので質問させていただきます。
MacOSX Thunderbird において結構以前のバージョンから
送受信の初期段階，受信ボタンを押した直後とか，起動してメール送受信の途中に
メニューより終了，またはCommand+Qで終了すると
「ユーザー名を送信できませんでした」のメッセージの後，
「ログイン失敗」のダイアログが出て応答無しの状態になります。
間違えてThunderbirdを起動させてしまいすぐ終了させたときや，
自動受信チェック時にタイミング悪く終了したとき，
サーバーの反応待ちの間に気づかず終了したとき等と割と頻繁に起こります。

何かの設定で回避できるものなのか，どうなのでしょうか？
どなたかご教示お願いいたします。

(環境: WinXP SP3/Other)

> MacOSX Thunderbird において結構以前のバージョンから
> 送受信の初期段階，受信ボタンを押した直後とか，起動してメール送受信の途中に
> メニューより終了，またはCommand+Qで終了すると
> 「ユーザー名を送信できませんでした」のメッセージの後，
> 「ログイン失敗」のダイアログが出て応答無しの状態になります。
> 間違えてThunderbirdを起動させてしまいすぐ終了させたときや，
> 自動受信チェック時にタイミング悪く終了したとき，
> サーバーの反応待ちの間に気づかず終了したとき等と割と頻繁に起こります。

IMAPだと、max cached connections(default=5)の数だけ常にコネクションを維持していて、そのためもあってか、終了時に、(a) リトライループになる(CPU=100%)、(b) 永久ウェイトになる(CPU=0%)、という問題が、知られています。
また、IDLEコマンドの使用を許可している場合(default=許可)、(c) IDLE中にコネクションが切れた時にIDLEのタイムアウトの30分を経過しないと接続し直しにいかないという問題があり、これが終了時に起こると、終了に30分かかる、というような現象になって現れます。
これらの問題はタイミングや環境依存であり、非常に稀にしか起こり得ない問題のはずで、ほとんどの人は遭遇していないのですが、起こる人のところでは必ずしも非常に稀というわけでもなさそうです。

IMAPを使用していて定期的な新規メールチェックを行う設定ならば、IDLEコマンドの使用を停止することで、(c) による問題は回避できます。

> サーバーの反応待ちの間に気づかず終了したとき等と割と頻繁に起こります。

終了しようとした時にはほぼ必ずサーバーにアクセスしている、というくらいに、ごく短時間ごとの新規メールチェックの設定をしていて、それを数多くのサーバーについて設定しているのですか(IMAPの場合は、全てのフォルダーについて、も含む)？

あまりにも頻繁に起こるのならば、終了前に「オフライン作業」に入り(ダウンロードするかしないについては、しない、を答える)、サーバーアクセスを停止させてから終了するといいでしょう。
「オフライン作業」で終了しても、プロファイルマネージャーで、あるいはパラメーターで、「オフライン作業」を指定しないと「オフライン作業」で起動してくれなかったはずですから、次回の起動には支障をきたさないはずです。

(環境: Mac/Other)

遠州白熊様

返信ありがとうございます。
メールのアカウントは５つ使っており，Gmail,Yahoo,Hotmailのアカウントも使用していますが，全てPOPにて使用しております。
あまり専門的なことはわからないのですが，遠州白熊様の返信に近いかなと思い
mail.server.default.use_idle=false
にしてみましたが，変化ありません。

この書き込み前後にThunderbirdの初期化含めいろいろ試しており，Thunderbirdのアプリケーション，設定，プロファイル全て消去，再インストール，Gmailだけアカウント登録の状態でも試しました。
結果，やはり同じでThunderbirdのバグかと思い書き込みしたのです。
他ではない現象なのですね。

メールの受信チェック，サーバーにログインの手続き中にアプリケーションの終了(Command+Q)させるとうちの環境では１００％起こるんですよね。

(環境: WinXP SP3/Other)

> あまり専門的なことはわからないのですが，遠州白熊様の返信に近いかなと思い
> mail.server.default.use_idle=false
> にしてみましたが，変化ありません。

良くわからないならIDLEでググってみるとかできるはずですし、POP3アカウントしか使っていないにも係らず、「IMAPなら」と書いているにも係らず、闇雲に何かを変えてみるのは、止めた方が利口でしょう。

> メールのアカウントは５つ使っており，Gmail,Yahoo,Hotmailのアカウントも使用していますが，全てPOPにて使用しております。

最近の容量が大きい系統のサーバーですから、全てのメールをサーバーに残す設定かな?
一度タイムスタンプ付きでPOP3ログを採り、どのようなことがどのような頻度で行われていて、それにどのくらいの時間がかかっているのかを見ておくといいでしょう。
プロトコルログの採取について : https://bugzilla.mozilla.org/show_bug.cgi?id=402793#c28
そして、簡単に問題を引き起こせるのならば、問題が起こる時のPOP3ログを採って、POP3レベルでどのようなことが起こっているのかを見て、
その後、ソケットレベルでどのようなことが起こっているかを見てみるといいでしょう、
> NSPR_LOG_MODULES=timestamp,pop3:5,nsSocketTransport:5,nsHostResolver:5
POP3レベルでのリトライループor永久ウェイトなのか、ソケットレベルでの問題かの判別くらいはできます。
GoogleもYahoo!もSSLを使用しているから、SSL絡みでのリトライループのような現象が疑われます。

(環境: WinXP SP3/Other)

Banana さん(投稿:2012/09/13(Thu)22:25:17,環境:Mac/Other)
maji です。


> メールの受信チェック，サーバーにログインの手続き中に
> アプリケーションの終了(Command+Q)させると
> うちの環境では１００％起こるんですよね。

当方、WinXP(SP3) + Thunderbird 15.0.1、なので
Mac版とは厳密には状況は違いますが、
以下の検証をしてみましたので報告しておきます。
結論を先に書くと
当方では Banana さんがお困りの現象は再現出来ません。

-----

上述の通り WinXP(SP3) + Thunderbird 15.0.1 で
手元の環境(プロファイル含む)をバックアップ取った上で削除し
あらためて新規インストールし
常用している POPアカウント 1個(★)だけ設定し
サーバ上にメール残してる状態で 受信 させ
Thunderbirdの画面上ちゃんと受信処理しているのを目視で確認したうえで
メニューより「ファイル」→「終了」で終了させます。

上記の★の部分を
常用しているレンタルサーバのもの(サーバ上に約 4,000通のメールあり)と
同じく常用している gmail(サーバ上に約 150通のメールあり)の
それぞれ二つの設定を別々にやりました。

すると何も問題なくスルッとその場で Thunderbirdは終了します。
少なくとも渡しの環境では
　》 「ユーザー名を送信できませんでした」のメッセージの後，
　》 「ログイン失敗」のダイアログが出て> 応答無しの状態になります
は再現出来ません。

-----

Windows と Mac で環境違うと思われ参考にはならないかもしれませんが
以上の通り報告させていただきます。


では。




.

(環境: Mac/Other)

maji様

ご報告感謝いたします。

(環境: Mac/Other)

遠州白熊様

ご指導感謝いたします。
仰せの通り，取ったログとにらめっこをしています。

起動時にgmailのみを受信するようにし，正常に受信したものと，当該の現象の場合のログを比較していますが，私には手に余ります。

ログイン時の処理によるものだと思うので，ユーザー名を送信したところからのログを貼付けます。
どなたか，この状況から原因を探れる方がおりましたら，よろしくお願いいたします。

2012-09-14 23:43:05.300514 UTC - 61938016[108a6c340]: SEND: USER 伏せ字@gmail.com
2012-09-14 23:43:05.300558 UTC - 265818112[108a6c6a0]: ...returned after 8 milliseconds
2012-09-14 23:43:05.300585 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::Write [this=164c4280 count=24]
2012-09-14 23:43:05.300592 UTC - 265818112[108a6c6a0]: calling PR_Write [count=24]
2012-09-14 23:43:05.300652 UTC - 265818112[108a6c6a0]: PR_Write returned [n=24]
2012-09-14 23:43:05.300658 UTC - 265818112[108a6c6a0]: nsSocketTransport::SendStatus [this=164c4120 status=804b0005]
2012-09-14 23:43:05.300684 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::AsyncWait [this=164c4280]
2012-09-14 23:43:05.300698 UTC - 265818112[108a6c6a0]: STS poll iter [1]
2012-09-14 23:43:05.300702 UTC - 265818112[108a6c6a0]: active [0] { handler=164c4120 condition=0 pollflags=7 }
2012-09-14 23:43:05.300706 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=1 idle=0]
2012-09-14 23:43:05.300710 UTC - 265818112[108a6c6a0]: poll timeout: 100
2012-09-14 23:43:05.300714 UTC - 265818112[108a6c6a0]: timeout = 100000 milliseconds
2012-09-14 23:43:05.300726 UTC - 265818112[108a6c6a0]: ...returned after 0 milliseconds
2012-09-14 23:43:05.300731 UTC - 265818112[108a6c6a0]: nsSocketTransport::OnSocketReady [this=164c4120 outFlags=2]
2012-09-14 23:43:05.300735 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::OnSocketReady [this=164c4280 cond=0]
2012-09-14 23:43:05.300740 UTC - 265818112[108a6c6a0]: STS poll iter [1]
2012-09-14 23:43:05.300743 UTC - 265818112[108a6c6a0]: active [0] { handler=164c4120 condition=0 pollflags=5 }
2012-09-14 23:43:05.300747 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=1 idle=0]
2012-09-14 23:43:05.300751 UTC - 265818112[108a6c6a0]: poll timeout: 100
2012-09-14 23:43:05.300755 UTC - 265818112[108a6c6a0]: timeout = 100000 milliseconds
2012-09-14 23:43:05.375919 UTC - 61938016[108a6c340]: Calling ReleaseFolderLock from AbortMailDelivery
2012-09-14 23:43:05.375941 UTC - 61938016[108a6c340]: ReleaseFolderLock haveSemaphore = FALSE
2012-09-14 23:43:05.376320 UTC - 61938016[108a6c340]: Clearing running protocol in nsPop3Protocol::Abort
2012-09-14 23:43:05.376334 UTC - 61938016[108a6c340]: STS dispatch [11f5626e0]
2012-09-14 23:43:05.376356 UTC - 265818112[108a6c6a0]: ...returned after 76 milliseconds
2012-09-14 23:43:05.376373 UTC - 265818112[108a6c6a0]: nsSocketInputStream::CloseWithStatus [this=164c4250 reason=804b0002]
2012-09-14 23:43:05.376377 UTC - 265818112[108a6c6a0]: nsSocketTransport::OnMsgInputClosed [this=164c4120 reason=804b0002]
2012-09-14 23:43:05.376382 UTC - 265818112[108a6c6a0]: nsSocketInputStream::CloseWithStatus [this=164c4250 reason=80470002]
2012-09-14 23:43:05.376386 UTC - 265818112[108a6c6a0]: STS poll iter [1]
2012-09-14 23:43:05.376389 UTC - 265818112[108a6c6a0]: active [0] { handler=164c4120 condition=804b0002 pollflags=5 }
2012-09-14 23:43:05.376393 UTC - 265818112[108a6c6a0]: nsSocketTransportService::DetachSocket [handler=164c4120]
2012-09-14 23:43:05.376396 UTC - 265818112[108a6c6a0]: nsSocketTransport::OnSocketDetached [this=164c4120 cond=804b0002]
2012-09-14 23:43:05.376400 UTC - 265818112[108a6c6a0]: nsSocketTransport::RecoverFromError [this=164c4120 state=4 cond=804b0002]
2012-09-14 23:43:05.376403 UTC - 265818112[108a6c6a0]: nsSocketInputStream::OnSocketReady [this=164c4250 cond=804b0002]
2012-09-14 23:43:05.376417 UTC - 265818112[108a6c6a0]: STS dispatch [11f5626e0]
2012-09-14 23:43:05.376423 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::OnSocketReady [this=164c4280 cond=804b0002]
2012-09-14 23:43:05.376427 UTC - 265818112[108a6c6a0]: STS dispatch [11f562520]
2012-09-14 23:43:05.376433 UTC - 265818112[108a6c6a0]: nsSocketTransport: calling PR_Close [this=164c4120]
2012-09-14 23:43:05.376614 UTC - 265818112[108a6c6a0]: nsSocketTransportService::RemoveFromPollList [handler=0]
2012-09-14 23:43:05.376622 UTC - 265818112[108a6c6a0]: index=0 mActiveCount=1
2012-09-14 23:43:05.376626 UTC - 265818112[108a6c6a0]: active=0 idle=0
2012-09-14 23:43:05.376631 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=0 idle=0]
2012-09-14 23:43:05.376635 UTC - 265818112[108a6c6a0]: timeout = -1 milliseconds
2012-09-14 23:43:05.376643 UTC - 265818112[108a6c6a0]: ...returned after 0 milliseconds
2012-09-14 23:43:05.376651 UTC - 265818112[108a6c6a0]: STS poll iter [0]
2012-09-14 23:43:05.376655 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=0 idle=0]
2012-09-14 23:43:05.376659 UTC - 265818112[108a6c6a0]: timeout = 0 milliseconds
2012-09-14 23:43:05.376665 UTC - 265818112[108a6c6a0]: ...returned after 0 milliseconds
2012-09-14 23:43:05.376671 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::AsyncWait [this=164c4280]
2012-09-14 23:43:05.376680 UTC - 265818112[108a6c6a0]: STS poll iter [1]
2012-09-14 23:43:05.376684 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=0 idle=0]
2012-09-14 23:43:05.376688 UTC - 265818112[108a6c6a0]: timeout = -1 milliseconds
2012-09-14 23:43:05.376830 UTC - 61938016[108a6c340]: dropped connection before auth error
2012-09-14 23:43:05.376839 UTC - 61938016[108a6c340]: Entering NET_ProcessPop3 0
2012-09-14 23:43:05.376843 UTC - 61938016[108a6c340]: POP3: Entering state: 31
2012-09-14 23:43:05.376846 UTC - 61938016[108a6c340]: NextAuthStep()
2012-09-14 23:43:05.376850 UTC - 61938016[108a6c340]: command did not succeed
2012-09-14 23:43:05.376853 UTC - 61938016[108a6c340]: auth failure, setting password failed
2012-09-14 23:43:05.376856 UTC - 61938016[108a6c340]: ERROR: 4004
2012-09-14 23:43:05.385342 UTC - 61938016[108a6c340]: Calling ReleaseFolderLock from AbortMailDelivery
2012-09-14 23:43:05.385354 UTC - 61938016[108a6c340]: ReleaseFolderLock haveSemaphore = FALSE
2012-09-14 23:43:05.385460 UTC - 61938016[108a6c340]: Clearing running protocol in nsPop3Protocol::Abort
2012-09-14 23:43:09.092237 UTC - 61938016[108a6c340]: POP3: Entering state: 24
2012-09-14 23:43:09.092256 UTC - 61938016[108a6c340]: POP3: Entering state: 0
2012-09-14 23:43:09.092346 UTC - 61938016[108a6c340]: STS dispatch [11f562520]
2012-09-14 23:43:09.092360 UTC - 61938016[108a6c340]: Reset callbacks for secinfo=115cce670 callbacks=0
2012-09-14 23:43:09.092373 UTC - 61938016[108a6c340]: nsSocketInputStream::CloseWithStatus [this=164c4250 reason=804b0002]
2012-09-14 23:43:09.092377 UTC - 61938016[108a6c340]: nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=804b0002]
2012-09-14 23:43:09.092382 UTC - 61938016[108a6c340]: Entering NET_ProcessPop3 0
2012-09-14 23:43:09.092385 UTC - 61938016[108a6c340]: POP3: Entering state: 24
2012-09-14 23:43:09.092389 UTC - 61938016[108a6c340]: need to rerun url because connection dropped during auth
2012-09-14 23:43:09.092390 UTC - 265818112[108a6c6a0]: ...returned after 3716 milliseconds
2012-09-14 23:43:09.092415 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=0]
2012-09-14 23:43:09.092422 UTC - 265818112[108a6c6a0]: nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=80470002]
2012-09-14 23:43:09.092427 UTC - 265818112[108a6c6a0]: destroying nsSocketTransport @164c4120
2012-09-14 23:43:09.092455 UTC - 265818112[108a6c6a0]: STS poll iter [1]
2012-09-14 23:43:09.092461 UTC - 265818112[108a6c6a0]: calling PR_Poll [active=0 idle=0]
2012-09-14 23:43:09.092464 UTC - 265818112[108a6c6a0]: timeout = -1 milliseconds
2012-09-14 23:43:09.096385 UTC - 61938016[108a6c340]: OnPromptStart()
2012-09-14 23:43:09.096409 UTC - 61938016[108a6c340]: POP: ask user what to do (after password failed): new password, retry or cancel

(環境: WinXP SP3/Other)

> 起動時にgmailのみを受信するようにし，正常に受信したものと，当該の現象の場合のログを比較していますが，私には手に余ります。
> ログイン時の処理によるものだと思うので，ユーザー名を送信したところからのログを貼付けます。

ソケット関係のログもありますが、POP3だけでのログでもきちんと見ていますか?

POP3レベルでは、単に、
(1) POP3のポートに接続してSSLのハンドシェイクも無事終わりグリーティングが来て、Authenticationのステップに入り、
(2) SEND USER xxx、
(3) 応答が来る前に接続が切れ、"dropped connection before auth error"、"command did not succeed" のログ、
(4) "auth failure, setting password failed" と "ERROR: 4004" のログ。
以下で書いていて、4004は、POP3_USERNAME_FAILUREで、この場合は、単にOP3_PASSWORD_FAILUREの方ではではないというだけの話。
> http://mxr.mozilla.org/comm-central/source/mailnews/local/src/nsPop3Protocol.cpp#1871
> http://mxr.mozilla.org/comm-central/source/mailnews/local/src/nsLocalStrings.h#16
(5) それで、次にどうするかのダイアログを出した、
というだけです。

おかしな点といえば、
(A) "dropped connection before auth error"の前に、ソケットログに、
> STS poll iter [1]
> calling PR_Poll [active=0 idle=0]
> timeout = -1 milliseconds
と、正の値であるはずのtimeoutに-1が見られることだけで、
サーバーへの接続処理中に強制的にTbを終了させたことによる特殊な状況に思えるのは、
(B) "dropped connection before auth error"自体と、
(通常は、SEND USER/PASSに対し何らかの応答がサーバーから返って、ログインが失敗)
(C) "dropped connection before auth error"の後、次にどうするかのダイアログの前に、
> Reset callbacks for secinfo=115cce670 callbacks=0
> nsSocketInputStream::CloseWithStatus [this=164c4250 reason=804b0002]
> nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=804b0002]
> Entering NET_ProcessPop3 0
> POP3: Entering state: 24
> need to rerun url because connection dropped during auth
>: ...returned after 3716 milliseconds
>: nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=0]
>: nsSocketOutputStream::CloseWithStatus [this=164c4280 reason=80470002]
>: destroying nsSocketTransport @164c4120
というログのシーケンスが見られることくらいです。

ログインエラーが起こって次にどうするかのダイアログが出たあとのTbの状態はどのようなものですか?
(CPU100%とCPU0%では現象が大きく異なるし、そのあとTbの仮想メモリー使用量・実メモリー使用量が減っていくのか増えるのか変化しないのかでも現象は変わります)

完全にウェイトの状態で仮想メモリーの解放もほとんど済んでいる、という状況ならば、ダイアログが残った状態であるが、しかしTbを終了させているのでほとんどのタスクが既に終了していて、ダイアログを誰も処理してくれなくて永久にウェイト、というような現象かもしれません。
"Reset callbacks for secinfo=xxx" があるので、Tbの終了でloopbackインターフェースが閉じられたのでダイアログの処理が先に進めなくなり、しかし誰もダイアログを終了させない、というようなことかな?
Mac OSだと、プロンプトやアラートが出ているときにファイルピッカーダイアログが表示されると、ファイルピッカーダイアログが前面にでてきてプロンプトやアラートに答えられなくなり、ファイルピッカーダイアログでの応答の処理はプロンプトやアラートの処理が終わらないと先に進めず、しかしプロンプトやアラートには答えることは不可能な状態なので、そこでストップ、というような問題があります。これと似たような状況になっているのかもしれません。

(環境: Mac/Other)

遠州白熊様

幾度もご回答ありがとうございます。
私が見る画面での状況と重ねてログを見ていましたが
大まかな流れしかわからず遠州白熊様の解説で納得できます。
私から拙いログの読みと私が目で見ている動作との流れはこのような感じです。

Tb/ユーザー名送信　ー＞　User/応答前に中止　ー＞　Server/パスワード要求
ー＞　Tb/終了処理が始まるのでパスワード不送信　ー＞　Server/パスワードエラー
ー＞　Tb/【ダイアログ】ユーザー名が送信できませんでした　ー＞ User/OKボタン
ー＞　Tb/【ダイアログ】ログイン失敗　ー＞　User/ボタン押せずフリーズ状態に見える

最後の状態で，CPU20%程度〜１０秒後ぐらいに0〜2.5%で落ち着きます。
その時メモリはほぼ解放されていません。動作しているときとほとんど変わらず175MB程度です。
私ははじめにPOP3のログを取り，見てたのですが，さほどおかしなものも見当たらないのです。参考に最後に貼付けておきます。

> Mac OSだと、プロンプトやアラートが出ているときにファイルピッカーダイアログが表示されると、ファイルピッカーダイアログが前面にでてきてプロンプトやアラートに答えられなくなり、ファイルピッカーダイアログでの応答の処理はプロンプトやアラートの処理が終わらないと先に進めず、しかしプロンプトやアラートには答えることは不可能な状態なので、そこでストップ、というような問題があります。これと似たような状況になっているのかもしれません。

そうですね。似ているのかもしれませんが，その状況になったものはあまり経験がないので比較できませんが，Tbの場合は最終的にDockかアクティビティモニタで強制終了しなければなりません。
同じようなものなのでしょうか。

自分で書いた流れを見る限り
Tb/ユーザー名送信　ー＞　User/応答前に中止　ー＞　Server/パスワード要求
ー＞　Tb/終了処理が始まるのでパスワード不送信　ー＞　Server/パスワードエラー
ー＞　Tb/以降サーバーからのエラーは無視　ー＞　アプリケーション終了

となればシンプルに解決するのではないかとも思いますが，他ではあまり起こらない現象のようなので，上手くつき合って行くしか無いのでしょうか。
因にMacOSXのMail.appでは同じアカウントを登録して，同じように何度操作しても起きないので，これはTbの潜在的なバグなのかと思っていました。

61938016[108a6c340]: USER login
61938016[108a6c340]: SEND: USER ********@gmail.com
61938016[108a6c340]: Calling ReleaseFolderLock from AbortMailDelivery
61938016[108a6c340]: ReleaseFolderLock haveSemaphore = FALSE
61938016[108a6c340]: Clearing running protocol in nsPop3Protocol::Abort
61938016[108a6c340]: dropped connection before auth error
61938016[108a6c340]: Entering NET_ProcessPop3 0
61938016[108a6c340]: POP3: Entering state: 31
61938016[108a6c340]: NextAuthStep()
61938016[108a6c340]: command did not succeed
61938016[108a6c340]: auth failure, setting password failed
61938016[108a6c340]: ERROR: 4004
61938016[108a6c340]: Calling ReleaseFolderLock from AbortMailDelivery
61938016[108a6c340]: ReleaseFolderLock haveSemaphore = FALSE
61938016[108a6c340]: Clearing running protocol in nsPop3Protocol::Abort
61938016[108a6c340]: POP3: Entering state: 24
61938016[108a6c340]: POP3: Entering state: 0
61938016[108a6c340]: Entering NET_ProcessPop3 0
61938016[108a6c340]: POP3: Entering state: 24
61938016[108a6c340]: need to rerun url because connection dropped during auth
61938016[108a6c340]: OnPromptStart()
61938016[108a6c340]: POP: ask user what to do (after password failed): new password, retry or cancel

(環境: WinXP SP3/Other)

> 私から拙いログの読みと私が目で見ている動作との流れはこのような感じです。
>
> Tb/ユーザー名送信　ー＞　User/応答前に中止　ー＞　Server/パスワード要求
> ー＞　Tb/終了処理が始まるのでパスワード不送信　ー＞　Server/パスワードエラー
> ー＞　Tb/【ダイアログ】ユーザー名が送信できませんでした　ー＞ User/OKボタン
> ー＞　Tb/【ダイアログ】ログイン失敗　ー＞　User/ボタン押せずフリーズ状態に見える

以下の最後のログは、ログインが失敗したのでRetry/New Password/Cancelを問い合わせるステップに入ったことを示します。
> POP: ask user what to do (after password failed): new password, retry or cancel
これが「Tb/【ダイアログ】ログイン失敗」にあたりますか？

「Tb/【ダイアログ】ユーザー名が送信できませんでした」がどのタイミングでだされたか、"ask user what to do" のログが「Tb/【ダイアログ】ユーザー名が送信できませんでした」に対してＯＫを返した後に書かれているか返す前に書かれているか、などで、何が起こっているかが変わってきそうです。
「Tb/【ダイアログ】ユーザー名が送信できませんでした」に対してＯＫを返した後に"ask user what to do"のステップに進んでいるのならば、「Tb/【ダイアログ】ユーザー名が送信できませんでした」に対してすぐにＯＫを返した場合と、「Tb/【ダイアログ】ユーザー名が送信できませんでした」をしばらく放置してからＯＫを返した場合で、ログに書かれるものや現象が変わってくる可能性もあります。

NSPR_LOG_MODULES=timestamp,POP3:5,DOMLeak:5,DocumentLeak:5,nsDocShellLeak:5
でログを採ると、ダイアログの表示を、xxxLeak:5によるログの、about:blankページのInternalLoad、といった形で見ることができます。
どのタイミングでダイアログが表示されていますか?