【茶包射手專欄】追查電子郵件傳送歷程(下)
 |  | 0 |  |  |
【前情提要】快一年前，我處理了一件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 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 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 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的結構及原理，但試圖找來相關證明:
以上這封信是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