Лог письма уже после разрыва соединения

[vkuzmin]

Добрый день, как посмотреть или начать собирать лог сохранения письма на диск: в какую именно папку оно попало, под каким названием?

Столкнулся со странной проблемой: письмо получено, о чём в логах есть запись, но у человека его нет. Восстановление удалённых из корзины писем настроено, в удалённых письма так же нет. И такое происходило минимум 2 раза с письмами одного и того же клиента. Как можно узнать, что происходило с письмом после разрыва соединения?

Окончание передачи письма:

Code: Select all

Jun 11 17:03:16 domain amavis[550]: (00550-03) tyS3L6WIczkX FWD from <prvs=1065c7575c=client@client.com> -> <manager@our.domain>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as BCA62E5199

Лог проблемного письма из zimbra.log:

Code: Select all

Jun 11 17:03:08 domain postfix/postscreen[17100]: CONNECT from [clients.ip.v4.address]:50636 to [internal.ip.v4.address]:25
Jun 11 17:03:09 domain postfix/smtp[15230]: connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out
Jun 11 17:03:09 domain postfix/smtp[15231]: connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out
Jun 11 17:03:09 domain postfix/smtp[16970]: connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out
Jun 11 17:03:09 domain postfix/smtp[16969]: connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out
Jun 11 17:03:09 domain postfix/smtp[15230]: 2D461E503F: to=<root@mail.our.domain>, relay=none, delay=34058, delays=34028/0.01/30/0, dsn=4.4.1, status=deferred (connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out)
Jun 11 17:03:09 domain postfix/smtp[15231]: 4925AE5181: to=<zimbra@mail.our.domain>, relay=none, delay=56700, delays=56670/0/30/0, dsn=4.4.1, status=deferred (connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out)
Jun 11 17:03:09 domain postfix/smtp[16969]: 80D46E5111: to=<zimbra@mail.our.domain>, relay=none, delay=233101, delays=233071/0/30/0, dsn=4.4.1, status=deferred (connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out)
Jun 11 17:03:09 domain postfix/smtp[16970]: 54258E514B: to=<zimbra@mail.our.domain>, relay=none, delay=144901, delays=144871/0.01/30/0, dsn=4.4.1, status=deferred (connect to mail.our.domain[our.ip.v4.address]:25: Connection timed out)
Jun 11 17:03:14 domain postfix/postscreen[17100]: PASS OLD [clients.ip.v4.address]:50636
Jun 11 17:03:14 domain postfix/smtpd[17121]: connect from mail.client.com[clients.ip.v4.address]
Jun 11 17:03:14 domain postfix/smtpd[17121]: Anonymous TLS connection established from mail.client.com[clients.ip.v4.address]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Jun 11 17:03:14 domain postfix/smtpd[17121]: NOQUEUE: filter: RCPT from mail.client.com[clients.ip.v4.address]: <prvs=1065c7575c=client@client.com>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026; from=<prvs=1065c7575c=client@client.com> to=<manager@our.domain> proto=ESMTP helo=<mail.client.com>
Jun 11 17:03:14 domain postfix/smtpd[17121]: NOQUEUE: filter: RCPT from mail.client.com[clients.ip.v4.address]: <prvs=1065c7575c=client@client.com>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10024; from=<prvs=1065c7575c=client@client.com> to=<manager@our.domain> proto=ESMTP helo=<mail.client.com>
Jun 11 17:03:14 domain postfix/smtpd[17121]: DA7A3E5151: client=mail.client.com[clients.ip.v4.address]
Jun 11 17:03:14 domain postfix/cleanup[17124]: DA7A3E5151: message-id=""
Jun 11 17:03:14 domain postfix/qmgr[5387]: DA7A3E5151: from=<prvs=1065c7575c=client@client.com>, size=57829, nrcpt=1 (queue active)
Jun 11 17:03:14 domain amavis[550]: (00550-03) ESMTP [127.0.0.1]:10024 /opt/zimbra/data/amavisd/tmp/amavis-20190611T165005-00550-o11oL10a: <prvs=1065c7575c=client@client.com> -> <manager@our.domain> SIZE=57829 Received: from
 mail.our.domain ([127.0.0.1]) by localhost (domain.local [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <manager@our.domain>; Tue, 11 Jun 2019 17:03:14 +0300 (MSK)
Jun 11 17:03:14 domain amavis[550]: (00550-03) Checking: tyS3L6WIczkX [clients.ip.v4.address] <prvs=1065c7575c=client@client.com> -> <manager@our.domain>
Jun 11 17:03:15 domain postfix/smtpd[17121]: disconnect from mail.client.com[clients.ip.v4.address] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jun 11 17:03:16 domain postfix/amavisd/smtpd[17136]: connect from localhost[127.0.0.1]
Jun 11 17:03:16 domain postfix/amavisd/smtpd[17136]: BCA62E5199: client=localhost[127.0.0.1]
Jun 11 17:03:16 domain postfix/cleanup[17124]: BCA62E5199: message-id=""
Jun 11 17:03:16 domain amavis[550]: (00550-03) tyS3L6WIczkX FWD from <prvs=1065c7575c=client@client.com> -> <manager@our.domain>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as BCA62E5199
Jun 11 17:03:16 domain postfix/amavisd/smtpd[17136]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jun 11 17:03:16 domain postfix/qmgr[5387]: BCA62E5199: from=<prvs=1065c7575c=client@client.com>, size=58513, nrcpt=1 (queue active)
Jun 11 17:03:16 domain amavis[550]: (00550-03) Passed CLEAN {RelayedInbound}, [clients.ip.v4.address]:50636 [clients.ip.v4.address] <prvs=1065c7575c=client@client.com> -> <manager@our.domain>, Queue-ID: DA7A3E5151, Message-ID: <"">, mail_id: tyS3
L6WIczkX, Hits: -52.757, size: 57792, queued_as: BCA62E5199, 1911 ms
Jun 11 17:03:16 domain postfix/smtp[17126]: DA7A3E5151: to=<manager@our.domain>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.9, delays=0.03/0/0/1.9, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: que
ued as BCA62E5199)
Jun 11 17:03:16 domain postfix/qmgr[5387]: DA7A3E5151: removed
Jun 11 17:03:16 domain postfix/lmtp[17137]: BCA62E5199: to=<manager@our.domain>, relay=domain.local[internal.ip.v4.address]:7025, delay=0.22, delays=0.05/0.01/0.05/0.12, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)
Jun 11 17:03:16 domain postfix/qmgr[5387]: BCA62E5199: removed
Jun 11 17:03:17 domain zmconfigd[30763]: Fetching All configs
Jun 11 17:03:17 domain zmconfigd[30763]: All configs fetched in 0.02 seconds
Jun 11 17:03:18 domain zmconfigd[30763]: Command not defined for imapd
Jun 11 17:03:19 domain zmconfigd[30763]: Watchdog: service antivirus status is OK.
Jun 11 17:03:19 domain zmconfigd[30763]: All rewrite threads completed in 0.00 sec
Jun 11 17:03:19 domain zmconfigd[30763]: All restarts completed in 0.00 sec
Jun 11 17:03:20 domain slapd[1662]: slap_queue_csn: queueing 0xa70e880 20190611140320.350014Z#000000#000#000000
Jun 11 17:03:20 domain slapd[1662]: slap_graduate_commit_csn: removing 0xa70e880 20190611140320.350014Z#000000#000#000000
Jun 11 17:04:19 domain zmconfigd[30763]: Fetching All configs
Jun 11 17:04:19 domain zmconfigd[30763]: All configs fetched in 0.02 seconds
Jun 11 17:04:20 domain slapd[1662]: slap_queue_csn: queueing 0x684d680 20190611140420.358339Z#000000#000#000000
Jun 11 17:04:20 domain slapd[1662]: slap_graduate_commit_csn: removing 0x684d680 20190611140420.358339Z#000000#000#000000
Jun 11 17:04:21 domain zmconfigd[30763]: Command not defined for imapd
Jun 11 17:04:22 domain zmconfigd[30763]: Watchdog: service antivirus status is OK.
Jun 11 17:04:22 domain zmconfigd[30763]: All rewrite threads completed in 0.00 sec
Jun 11 17:04:22 domain zmconfigd[30763]: All restarts completed in 0.00 sec
Jun 11 17:05:20 domain slapd[1662]: slap_queue_csn: queueing 0x684f9c0 20190611140520.392057Z#000000#000#000000
Jun 11 17:05:20 domain slapd[1662]: slap_graduate_commit_csn: removing 0x684f9c0 20190611140520.392057Z#000000#000#000000
Jun 11 17:05:22 domain zmconfigd[30763]: Fetching All configs
Jun 11 17:05:22 domain zmconfigd[30763]: All configs fetched in 0.02 seconds
Jun 11 17:05:23 domain zmconfigd[30763]: Command not defined for imapd
Jun 11 17:05:24 domain zmconfigd[30763]: Watchdog: service antivirus status is OK.
Jun 11 17:05:24 domain zmconfigd[30763]: All rewrite threads completed in 0.00 sec
Jun 11 17:05:24 domain zmconfigd[30763]: All restarts completed in 0.00 sec
Jun 11 17:06:07 domain postfix/amavisd/smtpd[13015]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
Jun 11 17:06:07 domain postfix/amavisd/smtpd[13015]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=6 data=2 commands=11

[vkuzmin]

От этого клиента письма так и не доходят, прошу помощи в разрешении проблемы

[vkuzmin]

С логами разобрался, надо в log4j.proterites (по желанию) понизить уровень сообщений до debug, (так же по желанию, я добавил DBG) создать новый Appender и дописать что-то вроде:

Code: Select all

log4j.logger.zimbra.lmtp=DEBUG,DBG
log4j.logger.zimbra.smtp=DEBUG,DBG
log4j.logger.zimbra.io=DEBUG,DBG
log4j.logger.zimbra.store=DEBUG,DBG

Заменяя DBG на удобное Вам значение. Можно оставит только log4j.logger.zimbra.store.

Пример, как будет выглядеть лог:

Code: Select all

2019-06-27 17:53:31,930 DEBUG [LmtpServer-10] [name=manager1@ourdomain.com;mid=5;ip=our.internal.ip.v4;] store - Linking /opt/zimbra/store/incoming/1561645975183-125.msg (size=29108, raw size=29108) to /opt/zimbra/store/0/xx/msg/xx/236705-334005.msg for mailbox 5, id 236705.
2019-06-27 17:53:31,941 DEBUG [LmtpServer-9] [name=manager2@ourdomain.com;mid=13;ip=our.internal.ip.v4;] store - Linking /opt/zimbra/store/incoming/1561645975183-126.msg (size=29092, raw size=29092) to /opt/zimbra/store/0/xx/msg/xx/18322-35306.msg for mailbox 13, id 18322.

[vkuzmin]

В общем, сервер клиента в сообщениях вставлял заголовок Message-ID: "" (да, не просто пустой, а именно две двойных кавычки), а Zimbra удаляла почти все письма от клиента, как дубликаты. Со своей стороны решил отключением кэша:

Code: Select all

Zmprov mcf zimbraMessageIdDedupeCacheSize 0