【前情提要】快一年前,我處理了一件Email異常延遲傳送的案件,原本計劃分兩篇說明,第一篇談Mail Client端的偵察,第二篇談Exchange Log的追蹤。結果,事多人忙心頹手懶,Post完上集,第二篇就被我遺留在火星上...

前幾天驚聞網友Leo詢問下集,心頭一驚,這這這... 趕緊登陸火星,挖出塵封的KB...


細看過IMS主機案發當時的Log,最後的推斷傾向SMTP Mail Server並沒有問題,純粹只是Queue太長導致。我的分析如下:

這是我第一次看Message Tracking Log,被它龐大的資料量及瑣碎的記錄搞到頭暈,找到一份重要的參考資料: KB-821905 Message tracking event IDs in Exchange Server 2003。由這份文件的指引,理出了一些頭緒。

當Exchange送出一份Mail時(下例為由phoenix.com.tw寄到foocorp.com.tw的正常記錄),會在Message Tracking Log中寫入如下的Log記錄(Log每一列很長,重點在前面,所以後方省略)

2007-4-21  2:3:55 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1019           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:3:55 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1025           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:3:55 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1024           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:3:55 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1033           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:3:55 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1034           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:4:19 GMT           192.168.9.113  ims03.phoenix.com.tw      -         IMS01          192.168.9.111   amy@foocorp.com.tw     1020           001301c78397$b3bd0c80$06d19934@rincon
2007-4-21  2:4:19 GMT           192.168.9.113  ims03.phoenix.com.tw      s1mail.foocorp.com.tw   IMS01          192.168.9.111           amy@foocorp.com.tw     1031 001301c78397$b3bd0c80$06d19934@rincon

amy@foocorp.com.tw後方的那個數字欄位叫做Event-ID,參照MS的官方文件,我們可以整理出以下的順序:

1019(SMTP submit message to AG) -> 1025(SMTP begin submit message) -> 1024(SMTP submit message to cat) -> 1033(SMTP message categorized and queued for routing) -> 1034(SMTP message routed and queued for remote delivery) -> 1020(SMTP begin outbound transfer) -> 1031(SMTP end outbound transfer)

值得注意的是1034(排入Qeue)到1020(開始送信)這段會拖得比較久一點,上面的例子是花了24秒。而在1031時,會Show對方Mail Server的名稱(Partner Name,但是似乎可以由Mail Server自行命名,有時會亂取),如上例為s1mail.foocorp.com.tw

回頭看4-19有問題的Mail,我們可以由Log追出它的完整寄出過程: (收信人為mary@ coolcorp.com及katherine@ boocorp.net兩人)

2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1019
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1019
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1025
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1025
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1024
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1024
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1033
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1033
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1034
2007-4-19  3:33:27 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1034
2007-4-19  3:33:36 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1020
2007-4-19  3:33:36 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1020
2007-4-19 3:33:38 GMT         192.168.8.30          nmail07.phoenix.com.tw  mh4pdmz3b.boocorp.net  IMS01          192.168.9.111           mary@coolcorp.com    1031
2007-4-19  3:33:38 GMT         192.168.8.30          nmail07.phoenix.com.tw  mh4pdmz3b.boocorp.net  IMS01          192.168.9.111           katherine@boocorp.net         1031
2007-4-19  4:19:29 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   mary@coolcorp.com           1020
2007-4-19  4:19:29 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   katherine@boocorp.net           1020
2007-4-19  4:19:30 GMT         192.168.8.30          nmail07.phoenix.com.tw  ************************   IMS01          192.168.9.111           mary@coolcorp.com    1031
2007-4-19  4:19:30 GMT         192.168.8.30          nmail07.phoenix.com.tw  ************************   IMS01          192.168.9.111           katherine@boocorp.net         1031

在11:33:38(Log中的時間是UTC,要+8才是台北時間),兩封出去的信已走完一次完整的1019->1025->1024->1033->1034->1020->1031的流程,但是到了12:19:30,1020->1031的流程又跑了一次。這兩次有點不同,第一次IMS01前方出現的字是mh4pdmz3b.boocorp.net,表示寄到BooCorp公司,而12:19:30出現的則是************************,對照收方的記錄,應該就是寄給CoolCorp的。於是我找了另一封寄給兩個收信人(jennifer@ mail.woocorp.com.tw及john@ ms3.coocorp.com.tw)的Log做比對。

2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1019
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1019
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1025
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1025
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1024
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1024
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1033
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1033
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1034
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1034
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1020
2007-4-21  4:38:40 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1020
2007-4-21  4:38:42 GMT         192.168.8.30          nmail07.phoenix.com.tw  [st3.coocorp.com.tw    IMS01          192.168.9.111           jennifer@mail.woocorp.com.tw      1031
2007-4-21  4:38:42 GMT         192.168.8.30          nmail07.phoenix.com.tw  [st3.coocorp.com.tw    IMS01          192.168.9.111           john@ms3.coocorp.com.tw          1031 2007-4-21  4:38:46 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   jennifer@mail.woocorp.com.tw           1020
2007-4-21  4:38:46 GMT         192.168.8.30          nmail07.phoenix.com.tw  -         IMS01          192.168.9.111   john@ms3.coocorp.com.tw           1020
2007-4-21  4:38:54 GMT         192.168.8.30          nmail07.phoenix.com.tw  mail.woocorp.com.tw   IMS01          192.168.9.111           jennifer@mail.woocorp.com.tw      1031
2007-4-21  4:38:54 GMT         192.168.8.30          nmail07.phoenix.com.tw  mail.woocorp.com.tw   IMS01          192.168.9.111           john@ms3.coocorp.com.tw          1031

兩相比較,二者的Pattern相同,都有兩組1020->1031的Log,寄給收信人甲的Mail Server時,收信人乙的Mail Address也會出現在Log中,所以共有4筆1020, 4筆1031。但最重要的差別,在於正常案例中兩組1020->1031的間隔時間只差了12秒,而4/19的異常Mail則差了近45分鐘。

看來關鍵出在1034(SMTP message queued for remote delivery,丟到Queue中排隊)到1020(SMTP begin outbound transfer,真正開始傳遞)的時間,由於信得乖乖在Queue裡等待寄出,如果Queue很長,那麼等上45分鐘並非不可能的事。

重點是,要怎麼證明它是在Queue中等待,而不是出了狀況? 我不是很清楚IMS Queue的結構及原理,但試圖找來相關證明:

2007-4-19  4:22:23 GMT         192.168.8.30          nmail07.phoenix.com.tw  port.sing.net  IMS01          192.168.9.111           rd@koocorp.com.tw           1031 B3C781785A2914458D97ABD324E5E97A3A662D@nmail07.phoenix.com.tw           1        0           227436       434    2007-4-19 2:44:48 GMT          0        Version: 5.0.2195.6713 -         The Next-Generation AI Engine-Secret Report (Phoenix Foundation)     research@phoenix.com.tw       --

以上這封信是10:44:48寄出的,是風凰城基金會(XD)寄給434個散佈在不同Mail Server收信人的研究報告信件。寄到port.sing.net時,已經過了1小時又37分。

  • 大轟炸信件(434個收件者)Delay時間為10:44:48 -> 12:22:23 = 約97分鐘
  • 另一封CoolCorp異常延遲信件的Delay時間為11:38:36 -> 12:19:30 = 約45分鐘

兩封信差了53分鐘發出,卻差不多同時送達,我大膽推論這是Queue差不多在12:20左右消化完畢的象徵。

由以上的分析,我研判有可能IMS01的傳送延遲,有可能來自於Queue大爆滿。不過,要明確指出這個推論是否正確,有待很了解Exchange SMTP Queue行為的專家依原理面加以證實。


Comments

Be the first to post a comment

Post a comment


40 + 10 =