SMTP 로그 분석 방법

인터넷 메일은 SMTP라는 규약을 통해 전송이 이루어집니다. 메일 클라이언트(아웃룩)와 메일 서버 사이, 메일 서버와 다른 메일 서버 사이에서 메시지를 전달하기 위해 SMTP 통신이 발생하게 됩니다. 메일캐리어에서는 이 SMTP 통신의 모든 내용을 로그 파일에 기록하며 이 기록은 향후 발생할 수 있는 여러 문제를 해결하기 위한 기초 자료가 됩니다. 특히, 송수신 장애가 있을 경우 정확한 원인 분석을 위한 데이터가 되므로 SMTP에 대한 이해는 필수적인 사항입니다.

SMTP 로그 파일

메일캐리어 SMTP 서비스는 메일을 수신하는 수신부와 발송하는 발신부로 나뉘어져 있으며 각 부분별로 따로 로그 파일을 기록합니다.

메일캐리어 수신부 로그 파일은 [설치폴더/LogFiles/SMTPR] 폴더에 저장되고 발신부 로그 파일은 [설치폴더/LogFiles/SMTPS] 폴더에 저장됩니다. 로그 파일은 일 단위로 생성되며 텍스트 파일이므로 메모장과 같은 텍스트 편집기로 확인해 볼 수 있습니다.

메일캐리어 관리 도구의 로그 항목에서 보여지는 로그는 요약 로그로 SMTP 수준이 아닌 세션 기준으로 요약된 정보만을 보여줍니다. 따라서 정확한 통신 내역을 분석하고자 한다면 요약 로그가 아닌 로그 파일에 기록된 SMTP 통신 내용을 직접 분석해야 합니다.

보다 편리하게 SMTP 수신 로그를 분석할 수 있도록 도움을 주는 LogFinder 프로그램도 포함되어 있습니다. [설치폴더/Tools/logfinder.exe] 파일을 실행시킨 후 분석하기를 원하는 로그 파일을 선택하면 됩니다.

아웃룩에서 내부 도메인으로 메일을 보내는 경우

아웃룩에서 메일을 작성한 후 보내기 버튼을 눌렀을 경우 SMTP 통신을 사용해 아웃룩에서 작성한 메시지를 메일캐리어 서버로 보내게 됩니다. 이 경우 SMTPR 로그 파일을 보면 아래와 같은 로그가 기록됩니다.

log

Copy

14:43:07 2,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,Connected from 39.118.201.45/25.
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,EHLO command successful(AQUA7).
14:43:07 99,99,9db2c974-b114-4e46-a3bc-48a06f3ce426,Processing AUTH NTLM 
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,Authentication successful(help@tabslab.com, NTLM).
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,MAIL command successful( <help@tabslab.com>).
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,RCPT command successful(khkim2@tabslab.com).
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,RCPT command successful(khkim3@tabslab.com).
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,DATA command successful.
14:43:07 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,DATA received(4207 bytes, 0.01MB).
14:43:08 3,99,9db2c974-b114-4e46-a3bc-48a06f3ce426,FLT:black list
14:43:08 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,Saved in the mailbox(khkim2@tabslab.com:mcInbox:a1b528c2-c90c-48ee-8ed6-91fc8334b8f8).
14:43:08 3,99,9db2c974-b114-4e46-a3bc-48a06f3ce426,FLT:black list
14:43:08 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,Saved in the mailbox(khkim3@tabslab.com:mcInbox:6979ebff-ef4e-40b3-847c-70ac9a66b98c).
14:43:09 3,1,9db2c974-b114-4e46-a3bc-48a06f3ce426,QUIT command successful.

로그에 대한 상세 설명은 아래와 같습니다.

로그 내용	설명
Connected from 39.118.201.45/25	아웃룩이 실행되고 있는 PC의 IP(39.118.201.45)로부터 25번 포트를 통해 연결되었습니다.
EHLO command successful(AQUA7)	SMTP 통신 시작을 알리는 EHLO 명령이 전달되었고 올바르게 처리되었습니다.
Authentication successful(help@tabslab.com, NTLM)	메일을 보내기 위해 인증(로그인)을 진행하였고 성공적으로 인증되었습니다. 인증에 사용된 방법은 NTLM 입니다.
MAIL command successful( <help@tabslab.com>)	메일 발송자 메일 주소를 help@tabslab.com로 지정합니다.
RCPT command successful(khkim2@tabslab.com)	메일 수신자 주소를 khkim2@tabslab.com로 지정합니다. 다수의 수신자를 지정하기 위해서는 RCPT 명령을 반복해서 사용합니다. 수신자가 잘못 지정되었다면 RCPT command failed(khkim4@tabslab.com not local)와 같은 로그가 기록됩니다.
DATA command successful	송수신자가 올바르게 지정되었다면 메시지 내용을 전송하겠다는 신호를 보냅니다.
DATA received(4207 bytes, 0.01MB)	아웃룩으로부터 실질적인 메시지 데이터(eml)를 받았습니다.
QUIT command successful	메일 전송이 끝났으므로 종료 명령을 보냅니다.
Saved in the mailbox(khkim2@tabslab.com:mcInbox)	메일캐리어는 수신한 메일의 수신자가 내부 도메인이므로 해당 메일함을 찾아 저장하였습니다.

로그에 있는 9db2c974-b114-4e46-a3bc-48a06f3ce426와 같은 UUID는 세션을 의미합니다. 세션은 아웃룩과 메일 서버간에 맺어진 TCP 연결을 의미합니다. SMTP 통신이 많을 경우 세션 ID 값이 겹쳐서 출력되므로 텍스트 편집기에서 로그를 확인하는 작업이 다소 불편할 수 있습니다. 이 경우 LogFinder 프로그램을 사용하면 세션 별로 정렬해서 보여주므로 쉽게 SMTP 로그를 탐색할 수 있습니다.

아웃룩에서 외부 도메인으로 메일을 보내는 경우

메일캐리어가 운영하는 도메인이 아닌 외부 도메인으로 메일을 보내는 경우입니다. 내부 도메인으로 메일을 보내는 경우와 거의 유사하지만 메일 수신자가 외부 도메인에 존재하므로 메일함에 저장하는 Saved in the mailbox 로그 대신 Mail relayed(help@tabslab.com,ddusxs97@hotmail.com)와 같은 로그가 기록됩니다. 전체 로그는 아래와 같습니다.

log

Copy

15:02:48 2,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,Connected from 39.118.201.45/25.
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,EHLO command successful(AQUA7).
15:02:48 99,99,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,Processing AUTH NTLM 
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,Authentication successful(help@tabslab.com, NTLM).
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,MAIL command successful( <help@tabslab.com>).
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,RCPT command successful(ddusxs97@hotmail.com).
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,DATA command successful.
15:02:48 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,DATA received(4184 bytes, 0.00MB).
15:02:50 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,Mail relayed(help@tabslab.com,ddusxs97@hotmail.com).
15:02:51 3,1,fabf385d-e5d2-4ab0-966b-97ec1eaa5645,QUIT command successful.

Mail relayed는 메일을 메일함에 저장하지 않고 메일 발송부로 전달했다는 의미입니다. 따라서 실 수신자(ddusxs97@hotmail.com)에게 메일이 올바르게 전달되었는지를 확인하기 위해서는 SMTPS에 저장되어 있는 발신 로그 파일을 추가로 확인해야 합니다. 다음은 [LogFiles/SMTPS]에 저장되어 있는 발신 로그입니다.

log

Copy

15:03:00 {84457317-1CC8-4281-96B5-68A7333AAD7D},0,0,help@tabslab.com,ddusxs97@hotmail.com,4381,65.55.37.104
15:07:00 {63ED0448-DCC0-4C50-8214-453994A9119D},3,550,help@tabslab.com,ddusxs123@hotmail.com,4381,65.55.37.104,RCPT: 550 5.1.1 User unknown

발신도 수신과 마찬가지로 SMTP를 사용하므로 유사한 로그가 만들어지지만 수신에 비해 그 내용이 간략하므로 상세 내용 대신 요약 로그가 기록됩니다. 발송 로그에 대한 상세 설명은 다음과 같습니다.

로그 내용	설명
0,0	오류 형식과 상세 오류 코드를 기록합니다. 0,0은 성공을 의미하고 3,550은 SMTP 오류/코드 550을 의미합니다. 오류 발생시 로그의 마지막 부분에 상세 설명이 기록되므로 참고합니다.
help@tabslab.com,ddusxs97@hotmail.com	발송자와 수신자를 기록합니다.
4381	전송한 메시지 량(바이트)을 기록합니다.
65.55.37.104	연결한 상대편 서버 IP를 기록합니다.
RCPT: 550 5.1.1 User unknown	SMTP 통신 중 RCPT 명령에서 수신자를 잘못 지정해서 User unknown 오류가 발생하였습니다. SMTP 상에서 오류 코드는 큰 의미를 가지지 않습니다. 상대편 서버가 반환한 오류 텍스트 문구가 의미를 가지므로 해당 내용을 읽어서 전송 실패 이유를 판별해야 합니다.

외부에서 메일을 수신하는 경우

외부의 다른 메일 서버로부터 메일이 전달되는 경우는 이전에 설명한 아웃룩에서 내부 도메인으로 메일을 보내는 경우와 유사합니다. 차이점은 인증을 거치지 않는 다는 것과 인증하지 않으므로 여러 가지 스팸 필터가 동작한다는 것입니다. 인증을 하지 않으므로 또 다른 곳으로 메일을 보낼 수 없으며 메일캐리어에서 운영 중인 로컬 도메인 메일함으로만 받을 수 있습니다. 아래는 외부 도메인(hotmail.com)에서 전송된 메일을 수신하는 로그입니다.

log

Copy

15:32:58 2,1,292005fb-9789-4363-92a0-93d8270743ed,Connected from 65.55.111.170/25.
15:32:59 3,1,292005fb-9789-4363-92a0-93d8270743ed,EHLO command successful(BLU004-OMC4S31.hotmail.com).
15:32:59 3,1,292005fb-9789-4363-92a0-93d8270743ed,MAIL command successful(<ddusxs97@hotmail.com> SIZE=4279).
15:33:00 3,1,292005fb-9789-4363-92a0-93d8270743ed,RCPT command successful(help@tabslab.com).
15:33:00 3,1,292005fb-9789-4363-92a0-93d8270743ed,DATA command successful.
15:33:04 3,1,292005fb-9789-4363-92a0-93d8270743ed,DATA received(4433 bytes, 0.00MB).
15:33:04 3,1,292005fb-9789-4363-92a0-93d8270743ed,QUIT command successful.
15:33:05 3,99,292005fb-9789-4363-92a0-93d8270743ed,FLT:black list
15:33:05 3,99,292005fb-9789-4363-92a0-93d8270743ed,FLT:language
15:33:05 3,99,292005fb-9789-4363-92a0-93d8270743ed,FLT:contents
15:33:05 3,99,292005fb-9789-4363-92a0-93d8270743ed,FLT:spamout
15:33:05 3,1,292005fb-9789-4363-92a0-93d8270743ed,Saved in the mailbox(help@tabslab.com:mcInbox:cd8cb093-b722-4ccc-934e-67a52dd97832).

FLT:black list는 여러 내용 필터 중 black list 필터를 통과했다는 의미입니다. 내용 필터가 동작하는 시점은 메시지 데이터를 수신한 이후이므로 메시지 헤더, 본문, 첨부 파일 등을 분석 가능합니다. 정상적인 메일함에 저장할 지 스팸 메일함에 저장할 지 여부가 결정됩니다. 만약 내용 필터에 의해 차단되거나 스팸 메일로 스팸함에 저장되는 경우라면 아래와 같은 내용이 추가적으로 기록됩니다.

log

Copy

Filtered by black list(thkim@tabslab.com, noreply@etnews.com).
Filtered by spamas(thkim@tabslab.com,11.4/6.5).

메일 메시지를 받기 전 수신자가 지정되는 단계에서는 메일을 발송한 IP 주소가 올바른 IP 인지 여부를 검사합니다. 도메인을 속이고 발송한 경우를 차단하는 SPF 검사와 스팸 서버로 등록된 IP인지 여부를 검사하는 RBL 검사를 수행합니다. 이와 같은 검사에 걸릴 경우 SMTP 통신은 더 이상 진행되지 않고 종료되고 아래와 같은 내용이 로그에 기록됩니다.

log

Copy

RCPT command failed(rdcomputer.com(59.26.125.152) cannot pass SPF).                
RCPT command failed(The IP 119.165.25.40 exists in the RBL server(cbl.abuseat.org)).