Анализ доставки сообщения с использованием Log-файлов

Для поиска сообщений, прошедших через почтовые сервера, обычно используется программа FmStat, но иногда требуется более детальный анализ. Его варианты мы и рассмотрим в этой статье.

Маршрут «АРМ1 — АРМ2»

Анализ Log-файлов АРМ1. Отправка сообщения

Рассмотрим схему, когда сообщение передается от автоматизированного рабочего места 1 (АРМ1) на АРМ2, которые обслуживаются разными серверами. Эти АРМ-ы имеют соответственно адреса

C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:OFFICE/PN:ARM1

и

 C:UA/ADMD:NBU/PRMD:U1H0/ORG:CRP/OU:ЦЕНТРАЛЬНА-РОЗРАХУНКОВА-ПАЛА/PN:ARM2

Log_ARM

 

Наше сообщение формируется скриптом script.bas посредством упаковки файлов, которые помещены в каталог    OutDir   := «..\Out», и отправляется программой TcpFoss. В результате работы скрипта в каталог FpkOutDir := «.\FPkOut» помещен файл почтовой корреспонденции (ФПК) с именем Nf59ba4.fpk и появилась следующая запись в Log-файле 150610Xp.log обработчика скрипта.

---[ Packed ]----------------------------------[ 10/06/2015 12:01:25 ]-
  FPK : G~20150610120125AARFSCFHE3QT0ED	29696	10/06/2015 12:01:25
  TYPE: Message  
  FROM: C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:OFFICE/PN:ARM1
  TO  : C:UA/ADMD:NBU/PRMD:U1H0/ORG:CRP/OU:ЦЕНТРАЛЬНА-РОЗРАХУНКОВА-ПАЛА/PN:ARM2
  RT  : 3	"deliver & read"
  Subj: Speed test
  File: "Письмо.doc"	7288	22/05/2015 09:40:24
  FPK Name:"Nf59ba4.fpk"

где:

  • FPK : идентификатор ФПК
  • TYPE: тип-сообщение
  • FROM: адрес отправителя сообщения
  • TO : адрес получателя сообщения
  • RT : тип запрашиваемого отчета — запрошен отчет о доставке и о прочтении
  • Subj: тема сообщения
  • File: имя файла,  упакованного в сообщение
  • FPK Name: имя файла непосредственно самого ФПК

Далее наш ФПК c именем Nf59ba4.fpk был передан программой TcpFoss на почтовый сервер UCIH (имя указывается в строке CONNECT), о чем была сделана запись в ее Log-файле 150610t0.log_

10/06/15 12:01:28 CONNECT 1 UCIH 10.0.1.77 V4.6.5
 S0|Nf59ba4.fpk |            |10/06/15|12:01:25|7817     |12:01:28|12:01:28|7817
END CONNECTION 10.0.1.77 10/06/15 12:01:31 (S/R=7817 bytes Cps=2605 cps)

Анализ Log-файлов почтового сервера UCIH. Прием и отправка сообщения

Проведем анализ значимых Log-файлов сервера UCIH. В файле 150610T1_SNTPC_1.LOG есть запись о приеме файла Nf59ba4.fpk на почтовый сервер от клиента с именем ARM1.

10/06/15 12:01:28 CONNECT 1 ARM1 10.0.1.77 V4.6.4
 R0|Nf59ba4.fpk |            |10/06/15|12:01:25|7817     |12:01:28|12:01:28|7817

 

Учитывая алгоритм работы почтового сервера  далее проанализируем  Log-файл маршрутизатора почтового сервера 150610t0.log. В нем существует следующая запись.

12:01:28  0........   (FROM: Dir: ARM1, Apf: T1_SNTPC_1)
 G~20150610120125AARFSCFHE3QT0ED  M  NF59BA4.FPK
       U1H0                       0  C:UA/ADMD:NBU/PRMD:U1H0/ORG:CRP/OU:ЦЕНТРАЛЬНА-РОЗРАХУНКОВА-ПАЛА/PN:ARM2

 

Данная запись означает, что был принят ФПК с именем  Nf59ba4.fpk. Это сообщение «М«.  ФПК принят с направления ARM1, АПФ-ом T1_SNTPC_1 (FROM: Dir: ARM1, Apf: T1_SNTPC_1). Указан адрес получателя, и почтовый ящик U1H0, в который и помещен файл с именем Nf59ba4.fpk. Кроме этого записывается идентификатор сообщения  G~20150610120125AARFSCFHE3QT0ED, который не меняется в процессе движения сообщения по системе. Он совпадает с идентификатором, который был присвоен сообщению в момент его создания.

Учитывая, что наше сообщение должно быть передано на почтовый сервер с именем U1H0 при помощи АПФ-а TcpFoss найдем об этом запись. Запись о передаче этого сообщения находится в файле 150610T1_SNTPC_0.LOG

10/06/15 12:01:37 CONNECT 6 U1H0 10.0.1.186 V4.6.5
 S0|NF59BA4.FPK |            |10/06/15|12:01:28|7861     |12:01:38|12:01:38|7861
END CONNECTION U1H0 10/06/15 12:01:39 (S/R=7861 bytes Cps=7861 cps)

 

Следовательно наш ФПК успешно передан на почтовый сервер U1H0.

Примечание: Задача TcpFoss одновременно ведет работу несколькими потоками и каждый из потоков ведет свой  Log-файл. Следовательно запись о  приеме/передаче файлов может быть в любом из ее Log-файлов.

Анализ прохождения отчета на почтовом сервере

Как было сказано выше, в момент упаковки ФПК были запрошены отчеты о доставке и прочтении. Проверим, проходили ли такие отчеты. Для этого откроем Log-файл маршрутизатора 150610rt.log и по идентификатору нашего сообщения G~20150610120125AARFSCFHE3QT0ED найдем запись о том, что проходил отчет «R»  и этот отчет отправлен в почтовый ящик ARM1. Отчет находится в файле с именем 0L295ER.REP

12:01:47  0........   (FROM: Dir: U1H0, Apf: T1_SNTPC_0)
 G~20150610120125AARFSCFHE3QT0ED  R  G~20150610120125AARFSCFHE3QT0EDRR_0L295ER.REP
       ARM1                       0  C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:OFFICE/PN:ARM1

 

и далее, этот отчет передан программой TcpFoss на рабочее место ARM1.

10/06/15 12:01:49 CONNECT 10 ARM1 10.0.1.77 V4.6.4
 S0|0L295ER.REP |            |10/06/15|12:01:47|663      |12:01:49|12:01:49|663
END CONNECTION ARM1 10/06/15 12:01:50 (S/R=663 bytes Cps=663 cps)

Анализ прохождения отчета на рабочем месте ARM1

Посмотрим, что реально находиться в этом отчете. Запись об этом содержит Log-файл обработчика скрипта 150610Xp.log

---[ Unpacked ]----------------------------------[ 10/06/2015 12:01:49 ]-
  FPK : G~20150610120125AARFSCFHE3QT0ED	0	10/06/2015 12:02:03
  TYPE: Report
  CODE: 3 	"unroute"	C:UA/ADMD:NBU/PRMD:U1H0/ORG:CRP/OU:ЦЕНТРАЛЬНА-РОЗРАХУНКОВА-ПАЛА/PN:ARM2	10/06/2015 12:02:02
  FROM: HOST:U1H0
  TO  : C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:OFFICE/PN:ARM1
  RT  : 1	"deliver"
  Subj: Speed test
  FPK Name:"G~20150610120125AARFSCFHE3QT0EDRR_0L295ER.REP"

 

Эта запись значит следующее. Был распакован отчет «TYPE: Report» на сообщение с идентификатором «FPK : G~20150610120125AARFSCFHE3QT0ED«. Отчет был о недоставке сообщения, «CODE: 3 «unroute» C:UA/ADMD:NBU/PRMD:U1H0/ORG:CRP/OU:ЦЕНТРАЛЬНА-РОЗРАХУНКОВА-ПАЛА/PN:ARM2«. Т.е. нет маршрута для сообщение с таким адресом получателя. Этот отчет сформировал почтовый сервер U1H0 «FROM: HOST:U1H0«

Маршрут «интерактивный клиент -интерактивный клиент»

Для простоты рассмотрим обслуживание двух клиентов одним почтовым сервером.

Log_client

 

В отличии от работы с АРМ-ами в процессе передачи сообщения программа TcpFoss не участвует. И запись о таком сообщении и о прохождении отчетов на него будет только в Log-файле маршрутизатора 150610rt.log.

14:56:27  0........   (FROM: Dir: СТЕПАНОВ, Apf: FossDoc transport)
 F~20150610145627AARFMR2IFWIJDIM  M  L03OP636.UUH
       СИДОРОВ                    0  C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:ПРИВАТБАНК/PN:СИДОРОВ
 
14:56:27  0........
 F~20150610145627AARFMR2IFWIJDIM  R  F~20150610145627AARFMR2IFWIJDIMRR_0un87OK.rep
       СТЕПАНОВ                   0  C:UA/ADMD:PRIVATBANK/PRMD:UCIH/ORG:CENTER/OU:ПРИВАТБАНК/PN:СТЕПАНОВ
 
14:56:58  0........   (FROM: Dir: СИДОРОВ, Apf: FossDoc transport)
 F~20150610145627AARFMR2IFWIJDIM  R  0B92RS2M.U9C
       СТЕПАНОВ         

 

Из записей в Log-файле видно что АПФ FossDoc transport от имени пользователя СТЕПАНОВ передал сообщение на почтовый сервер (FROM: Dir: СТЕПАНОВ, Apf: FossDoc transport) и это сообщение было помещено в почтовый ящик СИДОРОВ. Далее почтовым сервером был сформирован отчет о доставке сообщения (вторая запись) и от имени СИДОРОВ (FROM: Dir: СИДОРОВ, Apf: FossDoc transport) получен отчет о прочтении (третья запись). Идентификаторы сообщения и отчетов совпадают.