Skip to content

ci: attempt to fix recent transient test failures#2811

Closed
georglauterbach wants to merge 13 commits intomasterfrom
ci/fix-more-tests
Closed

ci: attempt to fix recent transient test failures#2811
georglauterbach wants to merge 13 commits intomasterfrom
ci/fix-more-tests

Conversation

@georglauterbach
Copy link
Copy Markdown
Member

Description

This adds more waiting barriers to allow a bit more time to pass in order to prevent this.

Moreover, I added a barrier for the test of the setup email del command, which failed from time to time as well.

Type of change

  • Bug fix (non-breaking change which fixes an issue)

Checklist:

  • My code follows the style guidelines of this project
  • I have performed a self-review of my own code
  • I have commented my code, particularly in hard-to-understand areas
  • I have made corresponding changes to the documentation (README.md or the documentation under docs/)
  • If necessary I have added tests that prove my fix is effective or that my feature works
  • New and existing unit tests pass locally with my changes

casperklein
casperklein previously approved these changes Oct 2, 2022
Copy link
Copy Markdown
Member

@polarathene polarathene left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am suspecting the problem is related to ClamAV usage in this test, which I believe becomes problematic the longer it's been cached in an image layer.

If this is the case, it could be resolved by moving this part of the Dockerfile to the final stage and invalidating only that stage (BuildKit supports this), to pull the latest ClamAV update:

# Copy over latest DB updates from official ClamAV image. Better than running `freshclam` (which requires extra RAM during build)
# hadolint ignore=DL3021
COPY --link --from=docker.io/clamav/clamav:latest /var/lib/clamav /var/lib/clamav

Comment thread test/tests.bats Outdated
@georglauterbach georglauterbach mentioned this pull request Oct 2, 2022
7 tasks
last commit was done in error; now the `IMAGE_NAME` should be provided
properly to the tests. `IMAGE_NAME` should be the new ENV variable name
for new tests because `NAME` is a bit too generic. I'm just introducing
it here, we can change it step by step in the future.
@georglauterbach
Copy link
Copy Markdown
Member Author

georglauterbach commented Oct 3, 2022

Now tests show a different error: https://github.com/docker-mailserver/docker-mailserver/actions/runs/3173238458/jobs/5168636410. I have no idea why the mail system should be down:

550 5.1.1 <[email protected]>: Recipient address rejected: User unknown in virtual mailbox table
554 5.5.1 Error: no valid recipients
221 2.7.0 Error: I can break rules, too. Goodbye.
postqueue: warning: Mail system is down -- accessing queue directly
postqueue: warning: Mail system is down -- accessing queue directly
Timed out on command: docker exec mail bash -c [[ $(mailq) == *"Mail queue is empty"* ]]
mail
bats warning: Executed 222 instead of expected 320 tests

@polarathene
Copy link
Copy Markdown
Member

I have no idea why the mail system should be down

Just to confirm, you have verified the tests run fine locally, and these failures are only happening in CI?

@georglauterbach
Copy link
Copy Markdown
Member Author

I have no idea why the mail system should be down

Just to confirm, you have verified the tests run fine locally, and these failures are only happening in CI?

Not quite. I was seeing other errors locally, but I think I haven't tested the last commit locally, to be honest. I still want to know where the current errors come from though.. I do not see a place where local vs GH CI would matter right now. Do you have an idea?

@georglauterbach
Copy link
Copy Markdown
Member Author

georglauterbach commented Oct 4, 2022

I was able to reproduce the CI results locally. Here is the log for a failed run

tests.bats
 ✗ setup_file failed []
   (from function `setup_file' in test file test/tests.bats, line 74)
     `docker exec mail /bin/sh -c "nc 0.0.0.0 25 < /tmp/docker-mailserver-test/email-templates/sieve-spam-folder.txt"' failed
   f5d9559e6b265bf36b1225bc700ffe2aab9f868d28be5c57dfc88fd1f81d4c76
   [   INF   ]  mail.my-domain.com is up and running
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as A82BC38FDF2
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as DEE8E38FDF3
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 44B8F38FDF4
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 96E8438FDF5
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as D1A1538FDF9
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 1C4AC38FDFA
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 7FEBD38FDFB
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 050A638FDFC
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 50B8038FDFD
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 8FEDF38FDFE
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as CB0AA38FDFF
   221 2.0.0 Bye
   220 mail.my-domain.com ESMTP
   250 mail.my-domain.com
   250 2.1.0 Ok
   250 2.1.5 Ok
   354 End data with <CR><LF>.<CR><LF>
   250 2.0.0 Ok: queued as 15CF038FE00
   221 2.0.0 Bye
   mail
   bats warning: Executed 1 instead of expected 98 tests

98 tests, 1 failure, 97 not run in 41 seconds

make: *** [Makefile:49: test/tests] Error 1

Mail server log:

Details
[  DEBUG  ]  Handling general environment variable setup
[   INF   ]  Welcome to docker-mailserver 11.1.0
[   INF   ]  Initializing setup
[  DEBUG  ]  Registering functions
[   INF   ]  Checking configuration
[  DEBUG  ]  Checking that hostname/domainname is provided or overridden
[  DEBUG  ]  Domain has been set to my-domain.com
[  DEBUG  ]  Hostname has been set to mail.my-domain.com
[   INF   ]  Configuring mail server
[  DEBUG  ]  Setting file and directory permissions
[  DEBUG  ]  Setting up Dovecot
[  DEBUG  ]  Setting up Dovecot dhparam
[  DEBUG  ]  Setting up Dovecot quota
[  DEBUG  ]  Setting up Dovecot Local User
[  DEBUG  ]  Creating master user 'masterusername'
[  DEBUG  ]  Creating user 'user1' for domain 'localhost.localdomain'
[  DEBUG  ]  Creating user 'user2' for domain 'otherdomain.tld'
[  DEBUG  ]  Creating user 'user3' for domain 'localhost.localdomain' with attributes 'userdb_mail=mbox:~/mail:INBOX=~/inbox'
[  DEBUG  ]  Adding alias '[email protected]' for user '[email protected]' to Dovecot's userdb
[  DEBUG  ]  Alias '[email protected]' is non-local (or mapped to a non-existing account) and will not be added to Dovecot's userdb
[  DEBUG  ]  Adding alias '@localdomain2.com' for user '[email protected]' to Dovecot's userdb
[  DEBUG  ]  Disabling postfix DNS block list (zen.spamhaus.org)
[  DEBUG  ]  Disabling postscreen DNS block lists
[  DEBUG  ]  Setting up DKIM
[  DEBUG  ]  Setting up SSL
[  DEBUG  ]  TLS configured with 'modern' ciphers
[  DEBUG  ]  Setting up PERMIT_DOCKER option
[  DEBUG  ]  Setting up mailname and creating '/etc/mailname'
[  DEBUG  ]  Setting up Amavis
[  DEBUG  ]  Setting up DMARC
[  DEBUG  ]  Applying hostname and domainname to Postfix
[  DEBUG  ]  Applying hostname to Dovecot
[  DEBUG  ]  Setting up Security Stack
[  DEBUG  ]  Enabling and configuring SpamAssassin
[  DEBUG  ]  ClamAV is disabled
[  DEBUG  ]  Enabling Amavis
[  DEBUG  ]  Setting up Postfix aliases
[  DEBUG  ]  Setting up Postfix vhost
[  DEBUG  ]  Setting up Postfix dhparam
[  DEBUG  ]  Configuring Postscreen
[  DEBUG  ]  Setting up SRS
[  DEBUG  ]  Setting up Postfix Relay Hosts
[  DEBUG  ]  Overriding / adjusting Postfix configuration with user-supplied values
[  DEBUG  ]  Setting up logrotate
[  DEBUG  ]  Enabling Postfix log summary reports with recipient '[email protected]'
[  DEBUG  ]  Logwatch reports disabled.
[  DEBUG  ]  Applying user patches
Default user-patches.sh successfully executed
[  DEBUG  ]  Exporting environment variables now (creating '/etc/dms-settings')
[  DEBUG  ]  Setting up configuration checksum file
[  DEBUG  ]  Printing environment variables. Make sure no sensitive data is copied.
ACCOUNT_PROVISIONER='FILE'
AMAVIS_LOGLEVEL='2'
CLAMAV_MESSAGE_SIZE_LIMIT='25M'
DEFAULT_RELAY_HOST=''
DOVECOT_INET_PROTOCOLS='all'
DOVECOT_MAILBOX_FORMAT='maildir'
DOVECOT_TLS='no'
ENABLE_AMAVIS='1'
ENABLE_CLAMAV='0'
ENABLE_DNSBL='0'
ENABLE_FAIL2BAN='0'
ENABLE_FETCHMAIL='0'
ENABLE_MANAGESIEVE='1'
ENABLE_POP3='0'
ENABLE_POSTGREY='0'
ENABLE_QUOTAS='1'
ENABLE_SASLAUTHD='0'
ENABLE_SPAMASSASSIN='1'
ENABLE_SPAMASSASSIN_KAM='0'
ENABLE_SRS='1'
ENABLE_UPDATE_CHECK='0'
FAIL2BAN_BLOCKTYPE='drop'
FETCHMAIL_PARALLEL='0'
FETCHMAIL_POLL='300'
LOGROTATE_INTERVAL='weekly'
LOGWATCH_INTERVAL='none'
LOGWATCH_RECIPIENT='[email protected]'
LOGWATCH_SENDER='[email protected]'
LOG_LEVEL='debug'
MOVE_SPAM_TO_JUNK='1'
NETWORK_INTERFACE='eth0'
ONE_DIR='1'
OVERRIDE_HOSTNAME=''
PERMIT_DOCKER='host'
PFLOGSUMM_RECIPIENT='[email protected]'
PFLOGSUMM_SENDER='[email protected]'
PFLOGSUMM_TRIGGER='logrotate'
POSTFIX_INET_PROTOCOLS='all'
POSTFIX_MAILBOX_SIZE_LIMIT='0'
POSTFIX_MESSAGE_SIZE_LIMIT='10240000'
POSTGREY_AUTO_WHITELIST_CLIENTS='5'
POSTGREY_DELAY='300'
POSTGREY_MAX_AGE='35'
POSTGREY_TEXT='Delayed by Postgrey'
POSTMASTER_ADDRESS='[email protected]'
POSTSCREEN_ACTION='enforce'
RELAY_HOST=''
REPORT_RECIPIENT='[email protected]'
REPORT_SENDER='[email protected]'
SA_KILL='3.0'
SA_SPAM_SUBJECT='SPAM: '
SA_TAG2='2.0'
SA_TAG='-5.0'
SMTP_ONLY='0'
SPAMASSASSIN_SPAM_TO_INBOX='0'
SPOOF_PROTECTION='1'
SRS_SENDER_CLASSES='envelope_sender'
SSL_TYPE='snakeoil'
SUPERVISOR_LOGLEVEL='warn'
TLS_LEVEL='modern'
TZ=''
UPDATE_CHECK_INTERVAL='1d'
VIRUSMAILS_DELETE_DELAY='7'
[   INF   ]  Post-configuration checks
[  DEBUG  ]  Checking /var/mail permissions
[   INF   ]  Starting miscellaneous tasks
[  DEBUG  ]  Consolidating all state onto /var/mail-state
[   INF   ]  Starting daemons
[  DEBUG  ]  Starting postsrsd
[  DEBUG  ]  Starting cron
[  DEBUG  ]  Starting rsyslog
[  DEBUG  ]  Starting dovecot
[  DEBUG  ]  Starting opendkim
[  DEBUG  ]  Starting opendmarc
[  DEBUG  ]  Starting postfix
[  DEBUG  ]  Starting changedetector
[  DEBUG  ]  Starting amavis
[   INF   ]  mail.my-domain.com is up and running
Oct  4 09:16:47 mail amavis[686]: logging initialized, log level 2, syslog: amavis.mail
Oct  4 09:16:47 mail amavis[686]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Oct  4 09:16:47 mail amavis[686]: starting. /usr/sbin/amavisd-new at mail.my-domain.com amavisd-new-2.11.1 (20181009), Unicode aware, LC_CTYPE="C.UTF-8"
Oct  4 09:16:47 mail amavis[686]: perl=5.032001, user=, EUID: 110 (110);  group=, EGID: 112 112 (112 112)
Oct  4 09:16:47 mail amavis[686]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Oct  4 09:16:47 mail amavis[686]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Oct  4 09:16:48 mail amavis[686]: INFO: SA version: 3.4.6, 3.004006, no optional modules: Net::CIDR::Lite Encode::Detect Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
Oct  4 09:16:48 mail amavis[686]: SpamControl: init_pre_chroot on SpamAssassin done
Oct  4 09:16:48 mail amavis[686]: socket module IO::Socket::IP, protocol families available: INET
Oct  4 09:16:48 mail amavis[686]: will bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp
Oct  4 09:16:48 mail amavis[686]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Oct  4 09:16:48 mail amavis[686]: sd_notify (no socket): STATUS=Preparing to bind sockets.
Oct  4 09:16:48 mail amavis[686]: Net::Server: 2022/10/04-09:16:48 Amavis (type Net::Server::PreForkSimple) starting! pid(686)
Oct  4 09:16:48 mail amavis[686]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
Oct  4 09:16:48 mail amavis[686]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Oct  4 09:16:48 mail amavis[686]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.
Oct  4 09:16:48 mail amavis[686]: Net::Server: Group Not Defined.  Defaulting to EGID '112 112'
Oct  4 09:16:48 mail amavis[686]: Net::Server: User Not Defined.  Defaulting to EUID '110'
Oct  4 09:16:48 mail amavis[686]: sd_notify (no socket): STATUS=The rest of pre-fork init, finding helper programs.
Oct  4 09:16:48 mail amavis[686]: config files read: /usr/share/amavis/conf.d/10-debian_scripts, /usr/share/amavis/conf.d/20-package, /etc/amavis/conf.d/01-debian, /etc/amavis/conf.d/05-domain_id, /etc/amavis/conf.d/05-node_id, /etc/amavis/conf.d/15-av_scanners, /etc/amavis/conf.d/15-content_filter_mode, /etc/amavis/conf.d/20-debian_defaults, /etc/amavis/conf.d/25-amavis_helpers, /etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/49-docker-mailserver, /etc/amavis/conf.d/50-user, /etc/amavis/conf.d/60-dms_default_config, /etc/amavis/conf.d/61-dms_auto_generated, /etc/amavis/conf.d/62-improve_privacy_remove_headers
Oct  4 09:16:48 mail amavis[686]: Module Amavis::Conf        2.412
Oct  4 09:16:48 mail amavis[686]: Module Archive::Zip        1.68
Oct  4 09:16:48 mail amavis[686]: Module BerkeleyDB          0.64
Oct  4 09:16:48 mail amavis[686]: Module Compress::Raw::Zlib 2.093
Oct  4 09:16:48 mail amavis[686]: Module Compress::Zlib      2.093
Oct  4 09:16:48 mail amavis[686]: Module Crypt::OpenSSL::RSA 0.31
Oct  4 09:16:48 mail amavis[686]: Module DB_File             1.853
Oct  4 09:16:48 mail amavis[686]: Module Digest::MD5         2.55_01
Oct  4 09:16:48 mail amavis[686]: Module Digest::SHA         6.02
Oct  4 09:16:48 mail amavis[686]: Module Encode              3.06
Oct  4 09:16:48 mail amavis[686]: Module File::Temp          0.2309
Oct  4 09:16:48 mail amavis[686]: Module IO::Socket::IP      0.39
Oct  4 09:16:48 mail amavis[686]: Module MIME::Entity        5.509
Oct  4 09:16:48 mail amavis[686]: Module MIME::Parser        5.509
Oct  4 09:16:48 mail amavis[686]: Module MIME::Tools         5.509
Oct  4 09:16:48 mail amavis[686]: Module Mail::DKIM::Verifier 1.20200907
Oct  4 09:16:48 mail amavis[686]: Module Mail::Header        2.21
Oct  4 09:16:48 mail amavis[686]: Module Mail::Internet      2.21
Oct  4 09:16:48 mail amavis[686]: Module Mail::SPF           v2.009
Oct  4 09:16:48 mail amavis[686]: Module Mail::SpamAssassin  3.004006
Oct  4 09:16:48 mail amavis[686]: Module Net::DNS            1.29
Oct  4 09:16:48 mail amavis[686]: Module Net::LibIDN         0.12
Oct  4 09:16:48 mail amavis[686]: Module Net::Server         2.009
Oct  4 09:16:48 mail amavis[686]: Module NetAddr::IP         4.079
Oct  4 09:16:48 mail amavis[686]: Module Razor2::Client::Version 2.84
Oct  4 09:16:48 mail amavis[686]: Module Scalar::Util        1.55
Oct  4 09:16:48 mail amavis[686]: Module Socket              2.029
Oct  4 09:16:48 mail amavis[686]: Module Socket6             0.29
Oct  4 09:16:48 mail amavis[686]: Module Time::HiRes         1.9764
Oct  4 09:16:48 mail amavis[686]: Module URI                 5.08
Oct  4 09:16:48 mail amavis[686]: Module Unix::Syslog        1.1
Oct  4 09:16:48 mail amavis[686]: Amavis::ZMQ code     NOT loaded
Oct  4 09:16:48 mail amavis[686]: Amavis::DB code      loaded
Oct  4 09:16:48 mail amavis[686]: SQL base code        NOT loaded
Oct  4 09:16:48 mail amavis[686]: SQL::Log code        NOT loaded
Oct  4 09:16:48 mail amavis[686]: SQL::Quarantine      NOT loaded
Oct  4 09:16:48 mail amavis[686]: Lookup::SQL code     NOT loaded
Oct  4 09:16:48 mail amavis[686]: Lookup::LDAP code    NOT loaded
Oct  4 09:16:48 mail amavis[686]: AM.PDP-in proto code loaded
Oct  4 09:16:48 mail amavis[686]: SMTP-in proto code   loaded
Oct  4 09:16:48 mail amavis[686]: Courier proto code   NOT loaded
Oct  4 09:16:48 mail amavis[686]: SMTP-out proto code  loaded
Oct  4 09:16:48 mail amavis[686]: Pipe-out proto code  NOT loaded
Oct  4 09:16:48 mail amavis[686]: BSMTP-out proto code NOT loaded
Oct  4 09:16:48 mail amavis[686]: Local-out proto code loaded
Oct  4 09:16:48 mail amavis[686]: OS_Fingerprint code  NOT loaded
Oct  4 09:16:48 mail amavis[686]: ANTI-VIRUS code      NOT loaded
Oct  4 09:16:48 mail amavis[686]: ANTI-SPAM code       loaded
Oct  4 09:16:48 mail amavis[686]: ANTI-SPAM-EXT code   NOT loaded
Oct  4 09:16:48 mail amavis[686]: ANTI-SPAM-C code     NOT loaded
Oct  4 09:16:48 mail amavis[686]: ANTI-SPAM-SA code    loaded
Oct  4 09:16:48 mail amavis[686]: Unpackers code       loaded
Oct  4 09:16:48 mail amavis[686]: DKIM code            NOT loaded
Oct  4 09:16:48 mail amavis[686]: Tools code           NOT loaded
Oct  4 09:16:48 mail amavis[686]: Found $file            at /usr/bin/file
Oct  4 09:16:48 mail amavis[686]: Found $altermime       at /usr/bin/altermime
Oct  4 09:16:48 mail amavis[686]: Internal decoder for .mail
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .Z    at /bin/uncompress
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .gz   at /bin/gzip -d
Oct  4 09:16:48 mail amavis[686]: Internal decoder for .gz   (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .bz2  at /bin/bzip2 -d
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .xz   at /usr/bin/xz -dc
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lzma at /usr/bin/xz -dc --format=lzma
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lrz  at /usr/bin/lrzip -q -k -d -o -
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lzo  at /usr/bin/lzop -d
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lz4  at /usr/bin/lz4c -d
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .rpm  at /usr/bin/rpm2cpio
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .cpio at /bin/pax
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .tar  at /bin/pax
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .deb  at /usr/bin/ar
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .rar  at /usr/bin/unrar-free
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .arj  at /usr/bin/arj
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .arc  at /usr/bin/nomarch
Oct  4 09:16:48 mail amavis[686]: No ext program for   .zoo, tried: zoo
Oct  4 09:16:48 mail amavis[686]: No ext program for   .doc, tried: ripole
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .cab  at /usr/bin/cabextract
Oct  4 09:16:48 mail amavis[686]: Internal decoder for .tnef
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .zip  at /usr/bin/7za
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .kmz  at /usr/bin/7za
Oct  4 09:16:48 mail amavis[686]: Internal decoder for .zip  (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Internal decoder for .kmz  (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .7z   at /usr/bin/7zr
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .gz   at /usr/bin/7za (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .bz2  at /usr/bin/7za (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .Z    at /usr/bin/7za (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .tar  at /usr/bin/7za (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .xz   at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lzma at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .jar  at /usr/bin/7z
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .cpio at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .arj  at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .rar  at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .swf  at /usr/bin/7z
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .lha  at /usr/bin/7z
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .iso  at /usr/bin/7z
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .cab  at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .deb  at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .rpm  at /usr/bin/7z (backup, not used)
Oct  4 09:16:48 mail amavis[686]: Found decoder for    .exe  at /usr/bin/unrar-free; /usr/bin/arj
Oct  4 09:16:48 mail amavis[686]: No decoder for       .F   
Oct  4 09:16:48 mail amavis[686]: No decoder for       .doc 
Oct  4 09:16:48 mail amavis[686]: No decoder for       .zoo 
Oct  4 09:16:48 mail amavis[686]: Deleting db files __db.003,__db.002,nanny.db,__db.001,snmp.db in /var/lib/amavis/db
Oct  4 09:16:48 mail amavis[686]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.64, libdb 5.3
Oct  4 09:16:48 mail amavis[686]: initializing Mail::SpamAssassin (0)
Oct  4 09:16:48 mail amavis[686]: SpamAssassin debug facilities: info
Oct  4 09:16:50 mail postfix/master[1293]: daemon started -- version 3.5.13, configuration /etc/postfix
Oct  4 09:16:52 mail amavis[1319]: SA info: util: setuid: ruid=110 euid=110 rgid=112 112 egid=112 112 
Oct  4 09:16:52 mail amavis[686]: SpamAssassin loaded plugins: AskDNS, AutoLearnThreshold, Bayes, BodyEval, Check, DKIM, DNSEval, FreeMail, HTMLEval, HTTPSMismatch, HeaderEval, ImageInfo, MIMEEval, MIMEHeader, Pyzor, Razor2, RelayEval, ReplaceTags, SPF, SpamCop, URIDNSBL, URIDetail, URIEval, VBounce, WLBLEval, WhiteListSubject
Oct  4 09:16:52 mail amavis[686]: SpamControl: init_pre_fork on SpamAssassin done
Oct  4 09:16:52 mail amavis[686]: extra modules loaded after daemonizing/chrooting: /etc/perl/Net/libnet.cfg, /usr/lib/x86_64-linux-gnu/perl5/5.32/auto/Net/SSLeay/autosplit.ix, /usr/lib/x86_64-linux-gnu/perl5/5.32/auto/Net/SSLeay/randomize.al, IO/Socket/SSL.pm, IO/Socket/SSL/PublicSuffix.pm, Mail/SpamAssassin/Plugin/FreeMail.pm, Mail/SpamAssassin/Plugin/SpamCop.pm, Net/Cmd.pm, Net/Config.pm, Net/SMTP.pm, Net/SSLeay.pm
Oct  4 09:16:52 mail amavis[686]: sd_notify (no socket): READY=1\nSTATUS=Initialization done.
Oct  4 09:16:52 mail amavis[686]: sd_notify (no socket): STATUS=Starting child process(es), ready for work.

Oct 4 09:16:57 mail amavis[1508]: logging initialized, log level 2, syslog: amavis.mail
Oct 4 09:16:57 mail amavis[1508]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Oct 4 09:16:57 mail amavis[1508]: Valid PID file /var/run/amavis/amavisd.pid (younger than sys uptime 0 0:57:00)
Oct 4 09:16:57 mail amavis[1508]: Signalling a SIGHUP to a running daemon [686]

Oct 4 09:16:57 mail amavis[686]: Net::Server: Received a SIG HUP
Oct 4 09:16:57 mail amavis[686]: sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Oct 4 09:16:57 mail amavis[686]: Net::Server: 2022/10/04-09:16:57 Server closing!
Oct 4 09:16:57 mail amavis[686]: Net::Server: Sending children hup signal
Oct 4 09:16:57 mail amavis[686]: sd_notify (no socket): RELOADING=1\nSTATUS=Reloading server, about to re-exec the program.
Oct 4 09:16:57 mail amavis[686]: (!)Net::Server: 2022/10/04-09:16:57 Re-exec server during HUP
Oct 4 09:16:58 mail amavis[686]: logging initialized, log level 2, syslog: amavis.mail
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Oct 4 09:16:58 mail amavis[686]: starting. (warm) /usr/sbin/amavisd-new at mail.my-domain.com amavisd-new-2.11.1 (20181009), Unicode aware, LC_CTYPE="C.UTF-8"
Oct 4 09:16:58 mail amavis[686]: perl=5.032001, user=110, EUID: 110 (110); group=, EGID: 112 112 (112 112)
Oct 4 09:16:58 mail amavis[686]: warm restart on HUP [686]: '/usr/sbin/amavisd-new foreground', sockets: 6||/var/lib/amavis/amavisd.sock|UNIX|; 4|127.0.0.1|10024|TCP|ipv4
Oct 4 09:16:58 mail amavis[686]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Oct 4 09:16:58 mail amavis[686]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Oct 4 09:16:58 mail amavis[686]: INFO: SA version: 3.4.6, 3.004006, no optional modules: Net::CIDR::Lite Encode::Detect Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
Oct 4 09:16:58 mail amavis[686]: SpamControl: init_pre_chroot on SpamAssassin done
Oct 4 09:16:58 mail amavis[686]: socket module IO::Socket::IP, protocol families available: INET
Oct 4 09:16:58 mail amavis[686]: will bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Oct 4 09:16:58 mail amavis[686]: _WARN: Pid_file created by this same process. Doing nothing.
Oct 4 09:16:58 mail amavis[686]: _WARN: Pid_file created by this same process. Doing nothing.
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=Preparing to re-bind sockets.
Oct 4 09:16:58 mail amavis[686]: Net::Server: 2022/10/04-09:16:58 Amavis (type Net::Server::PreForkSimple) starting! pid(686)
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=Warm restart, re-binding sockets.
Oct 4 09:16:58 mail amavis[686]: Net::Server: Binding open file descriptors
Oct 4 09:16:58 mail amavis[686]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
Oct 4 09:16:58 mail amavis[686]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.
Oct 4 09:16:58 mail amavis[686]: Net::Server: Group Not Defined. Defaulting to EGID '112 112'
Oct 4 09:16:58 mail amavis[686]: Net::Server: User Not Defined. Defaulting to EUID '110'
Oct 4 09:16:58 mail amavis[686]: sd_notify (no socket): STATUS=The rest of pre-fork init, finding helper programs.
Oct 4 09:16:58 mail amavis[686]: config files read: /usr/share/amavis/conf.d/10-debian_scripts, /usr/share/amavis/conf.d/20-package, /etc/amavis/conf.d/01-debian, /etc/amavis/conf.d/05-domain_id, /etc/amavis/conf.d/05-node_id, /etc/amavis/conf.d/15-av_scanners, /etc/amavis/conf.d/15-content_filter_mode, /etc/amavis/conf.d/20-debian_defaults, /etc/amavis/conf.d/25-amavis_helpers, /etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/49-docker-mailserver, /etc/amavis/conf.d/50-user, /etc/amavis/conf.d/60-dms_default_config, /etc/amavis/conf.d/61-dms_auto_generated, /etc/amavis/conf.d/62-improve_privacy_remove_headers
Oct 4 09:16:58 mail amavis[686]: Module Amavis::Conf 2.412
Oct 4 09:16:58 mail amavis[686]: Module Archive::Zip 1.68
Oct 4 09:16:58 mail amavis[686]: Module BerkeleyDB 0.64
Oct 4 09:16:58 mail amavis[686]: Module Compress::Raw::Zlib 2.093
Oct 4 09:16:58 mail amavis[686]: Module Compress::Zlib 2.093
Oct 4 09:16:58 mail amavis[686]: Module Crypt::OpenSSL::RSA 0.31
Oct 4 09:16:58 mail amavis[686]: Module DB_File 1.853
Oct 4 09:16:58 mail amavis[686]: Module Digest::MD5 2.55_01
Oct 4 09:16:58 mail amavis[686]: Module Digest::SHA 6.02
Oct 4 09:16:58 mail amavis[686]: Module Encode 3.06
Oct 4 09:16:58 mail amavis[686]: Module File::Temp 0.2309
Oct 4 09:16:58 mail amavis[686]: Module IO::Socket::IP 0.39
Oct 4 09:16:58 mail amavis[686]: Module MIME::Entity 5.509
Oct 4 09:16:58 mail amavis[686]: Module MIME::Parser 5.509
Oct 4 09:16:58 mail amavis[686]: Module MIME::Tools 5.509
Oct 4 09:16:58 mail amavis[686]: Module Mail::DKIM::Verifier 1.20200907
Oct 4 09:16:58 mail amavis[686]: Module Mail::Header 2.21
Oct 4 09:16:58 mail amavis[686]: Module Mail::Internet 2.21
Oct 4 09:16:58 mail amavis[686]: Module Mail::SPF v2.009
Oct 4 09:16:58 mail amavis[686]: Module Mail::SpamAssassin 3.004006
Oct 4 09:16:59 mail amavis[686]: Module Net::DNS 1.29
Oct 4 09:16:59 mail amavis[686]: Module Net::LibIDN 0.12
Oct 4 09:16:59 mail amavis[686]: Module Net::Server 2.009
Oct 4 09:16:59 mail amavis[686]: Module NetAddr::IP 4.079
Oct 4 09:16:59 mail amavis[686]: Module Razor2::Client::Version 2.84
Oct 4 09:16:59 mail amavis[686]: Module Scalar::Util 1.55
Oct 4 09:16:59 mail amavis[686]: Module Socket 2.029
Oct 4 09:16:59 mail amavis[686]: Module Socket6 0.29
Oct 4 09:16:59 mail amavis[686]: Module Time::HiRes 1.9764
Oct 4 09:16:59 mail amavis[686]: Module URI 5.08
Oct 4 09:16:59 mail amavis[686]: Module Unix::Syslog 1.1
Oct 4 09:16:59 mail amavis[686]: Amavis::ZMQ code NOT loaded
Oct 4 09:16:59 mail amavis[686]: Amavis::DB code loaded
Oct 4 09:16:59 mail amavis[686]: SQL base code NOT loaded
Oct 4 09:16:59 mail amavis[686]: SQL::Log code NOT loaded
Oct 4 09:16:59 mail amavis[686]: SQL::Quarantine NOT loaded
Oct 4 09:16:59 mail amavis[686]: Lookup::SQL code NOT loaded
Oct 4 09:16:59 mail amavis[686]: Lookup::LDAP code NOT loaded
Oct 4 09:16:59 mail amavis[686]: AM.PDP-in proto code loaded
Oct 4 09:16:59 mail amavis[686]: SMTP-in proto code loaded
Oct 4 09:16:59 mail amavis[686]: Courier proto code NOT loaded
Oct 4 09:16:59 mail amavis[686]: SMTP-out proto code loaded
Oct 4 09:16:59 mail amavis[686]: Pipe-out proto code NOT loaded
Oct 4 09:16:59 mail amavis[686]: BSMTP-out proto code NOT loaded
Oct 4 09:16:59 mail amavis[686]: Local-out proto code loaded
Oct 4 09:16:59 mail amavis[686]: OS_Fingerprint code NOT loaded
Oct 4 09:16:59 mail amavis[686]: ANTI-VIRUS code NOT loaded
Oct 4 09:16:59 mail amavis[686]: ANTI-SPAM code loaded
Oct 4 09:16:59 mail amavis[686]: ANTI-SPAM-EXT code NOT loaded
Oct 4 09:16:59 mail amavis[686]: ANTI-SPAM-C code NOT loaded
Oct 4 09:16:59 mail amavis[686]: ANTI-SPAM-SA code loaded
Oct 4 09:16:59 mail amavis[686]: Unpackers code loaded
Oct 4 09:16:59 mail amavis[686]: DKIM code NOT loaded
Oct 4 09:16:59 mail amavis[686]: Tools code NOT loaded
Oct 4 09:16:59 mail amavis[686]: Found $file at /usr/bin/file
Oct 4 09:16:59 mail amavis[686]: Found $altermime at /usr/bin/altermime
Oct 4 09:16:59 mail amavis[686]: Internal decoder for .mail
Oct 4 09:16:59 mail amavis[686]: Found decoder for .Z at /bin/uncompress
Oct 4 09:16:59 mail amavis[686]: Found decoder for .gz at /bin/gzip -d
Oct 4 09:16:59 mail amavis[686]: Internal decoder for .gz (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .bz2 at /bin/bzip2 -d
Oct 4 09:16:59 mail amavis[686]: Found decoder for .xz at /usr/bin/xz -dc
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lzma at /usr/bin/xz -dc --format=lzma
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lrz at /usr/bin/lrzip -q -k -d -o -
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lzo at /usr/bin/lzop -d
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lz4 at /usr/bin/lz4c -d
Oct 4 09:16:59 mail amavis[686]: Found decoder for .rpm at /usr/bin/rpm2cpio
Oct 4 09:16:59 mail amavis[686]: Found decoder for .cpio at /bin/pax
Oct 4 09:16:59 mail amavis[686]: Found decoder for .tar at /bin/pax
Oct 4 09:16:59 mail amavis[686]: Found decoder for .deb at /usr/bin/ar
Oct 4 09:16:59 mail amavis[686]: Found decoder for .rar at /usr/bin/unrar-free
Oct 4 09:16:59 mail amavis[686]: Found decoder for .arj at /usr/bin/arj
Oct 4 09:16:59 mail amavis[686]: Found decoder for .arc at /usr/bin/nomarch
Oct 4 09:16:59 mail amavis[686]: No ext program for .zoo, tried: zoo
Oct 4 09:16:59 mail amavis[686]: No ext program for .doc, tried: ripole
Oct 4 09:16:59 mail amavis[686]: Found decoder for .cab at /usr/bin/cabextract
Oct 4 09:16:59 mail amavis[686]: Internal decoder for .tnef
Oct 4 09:16:59 mail amavis[686]: Found decoder for .zip at /usr/bin/7za
Oct 4 09:16:59 mail amavis[686]: Found decoder for .kmz at /usr/bin/7za
Oct 4 09:16:59 mail amavis[686]: Internal decoder for .zip (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Internal decoder for .kmz (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .7z at /usr/bin/7zr
Oct 4 09:16:59 mail amavis[686]: Found decoder for .gz at /usr/bin/7za (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .bz2 at /usr/bin/7za (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .Z at /usr/bin/7za (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .tar at /usr/bin/7za (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .xz at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lzma at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .jar at /usr/bin/7z
Oct 4 09:16:59 mail amavis[686]: Found decoder for .cpio at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .arj at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .rar at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .swf at /usr/bin/7z
Oct 4 09:16:59 mail amavis[686]: Found decoder for .lha at /usr/bin/7z
Oct 4 09:16:59 mail amavis[686]: Found decoder for .iso at /usr/bin/7z
Oct 4 09:16:59 mail amavis[686]: Found decoder for .cab at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .deb at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .rpm at /usr/bin/7z (backup, not used)
Oct 4 09:16:59 mail amavis[686]: Found decoder for .exe at /usr/bin/unrar-free; /usr/bin/arj
Oct 4 09:16:59 mail amavis[686]: No decoder for .F
Oct 4 09:16:59 mail amavis[686]: No decoder for .doc
Oct 4 09:16:59 mail amavis[686]: No decoder for .zoo
Oct 4 09:16:59 mail amavis[686]: Deleting db files nanny.db in /var/lib/amavis/db
Oct 4 09:16:59 mail amavis[686]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.64, libdb 5.3
Oct 4 09:16:59 mail amavis[686]: initializing Mail::SpamAssassin (0)
Oct 4 09:16:59 mail amavis[686]: SpamAssassin debug facilities: info
Oct 4 09:17:01 mail postfix/master[1293]: terminating on signal 15
Oct 4 09:17:01 mail dovecot: master: Warning: Killed with signal 15 (by pid=7 uid=0 code=kill)
Oct 4 09:17:02 mail amavis[1715]: SA info: util: setuid: ruid=110 euid=110 rgid=112 112 egid=112 112
Oct 4 09:17:02 mail amavis[686]: SpamAssassin loaded plugins: AskDNS, AutoLearnThreshold, Bayes, BodyEval, Check, DKIM, DNSEval, FreeMail, HTMLEval, HTTPSMismatch, HeaderEval, ImageInfo, MIMEEval, MIMEHeader, Pyzor, Razor2, RelayEval, ReplaceTags, SPF, SpamCop, URIDNSBL, URIDetail, URIEval, VBounce, WLBLEval, WhiteListSubject
Oct 4 09:17:02 mail amavis[686]: SpamControl: init_pre_fork on SpamAssassin done
Oct 4 09:17:02 mail amavis[686]: extra modules loaded after daemonizing/chrooting: /etc/perl/Net/libnet.cfg, /usr/lib/x86_64-linux-gnu/perl5/5.32/auto/Net/SSLeay/autosplit.ix, /usr/lib/x86_64-linux-gnu/perl5/5.32/auto/Net/SSLeay/randomize.al, IO/Socket/SSL.pm, IO/Socket/SSL/PublicSuffix.pm, Mail/SpamAssassin/Plugin/FreeMail.pm, Mail/SpamAssassin/Plugin/SpamCop.pm, Net/Cmd.pm, Net/Config.pm, Net/SMTP.pm, Net/SSLeay.pm
Oct 4 09:17:02 mail amavis[686]: sd_notify (no socket): READY=1\nSTATUS=Initialization done.
Oct 4 09:17:02 mail amavis[686]: sd_notify (no socket): STATUS=Starting child process(es), ready for work.
Oct 4 09:17:02 mail dovecot: master: Dovecot v2.3.13 (89f716dc2) starting up for imap, lmtp, sieve
Oct 4 09:17:05 mail postfix/master[2455]: daemon started -- version 3.5.13, configuration /etc/postfix
Oct 4 09:17:06 mail amavis[2343]: logging initialized, log level 2, syslog: amavis.mail
Oct 4 09:17:06 mail amavis[2343]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Oct 4 09:17:06 mail amavis[2343]: Valid PID file /var/run/amavis/amavisd.pid (younger than sys uptime 0 0:57:00)
Oct 4 09:17:06 mail amavis[2343]: Signalling a SIGHUP to a running daemon [686]
Oct 4 09:17:06 mail amavis[686]: Net::Server: Received a SIG HUP
Oct 4 09:17:06 mail amavis[686]: sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Oct 4 09:17:06 mail amavis[686]: Net::Server: 2022/10/04-09:17:06 Server closing!
Oct 4 09:17:06 mail amavis[686]: Net::Server: Sending children hup signal
Oct 4 09:17:06 mail amavis[686]: sd_notify (no socket): RELOADING=1\nSTATUS=Reloading server, about to re-exec the program.
Oct 4 09:17:06 mail amavis[686]: (!)Net::Server: 2022/10/04-09:17:06 Re-exec server during HUP
Oct 4 09:17:06 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34598 to [127.0.0.1]:25
Oct 4 09:17:06 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34598
Oct 4 09:17:06 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34614 to [127.0.0.1]:25
Oct 4 09:17:06 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34614
Oct 4 09:17:07 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:07 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:07 mail postfix/smtpd[2493]: lost connection after CONNECT from localhost[127.0.0.1]
Oct 4 09:17:07 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] commands=0/0
Oct 4 09:17:07 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:07 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:07 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <doc
Oct 4 09:17:07 mail postfix/smtpd[2493]: 6D6F638FDCE: client=localhost[127.0.0.1]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:07 mail postfix/cleanup[2513]: 6D6F638FDCE: message-id=[email protected]
Oct 4 09:17:07 mail opendkim[531]: 6D6F638FDCE: no signing table match for '[email protected]'
Oct 4 09:17:07 mail opendkim[531]: 6D6F638FDCE: no signature data
Oct 4 09:17:07 mail postfix/qmgr[2459]: 6D6F638FDCE: from=[email protected], size=574, nrcpt=1 (queue active)
Oct 4 09:17:07 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:07 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34624 to [127.0.0.1]:25
Oct 4 09:17:07 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34624
Oct 4 09:17:07 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:07 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:07 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <do
Oct 4 09:17:07 mail postfix/smtpd[2509]: A82BC38FDF2: client=localhost[127.0.0.1]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:07 mail postfix/cleanup[2513]: A82BC38FDF2: message-id=[email protected]
Oct 4 09:17:07 mail opendkim[531]: A82BC38FDF2: no signing table match for '[email protected]'
Oct 4 09:17:07 mail opendkim[531]: A82BC38FDF2: no signature data
Oct 4 09:17:07 mail postfix/qmgr[2459]: A82BC38FDF2: from=[email protected], size=1061, nrcpt=1 (queue active)
Oct 4 09:17:07 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:07 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34636 to [127.0.0.1]:25
Oct 4 09:17:07 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34636
Oct 4 09:17:07 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:07 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:07 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <do
Oct 4 09:17:07 mail postfix/smtpd[2493]: DEE8E38FDF3: client=localhost[127.0.0.1]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:07 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:07 mail postfix/cleanup[2513]: DEE8E38FDF3: message-id=[email protected]
Oct 4 09:17:07 mail opendkim[531]: DEE8E38FDF3: no signing table match for '[email protected]'
Oct 4 09:17:07 mail opendkim[531]: DEE8E38FDF3: no signature data
Oct 4 09:17:07 mail postfix/qmgr[2459]: DEE8E38FDF3: from=[email protected], size=518, nrcpt=1 (queue active)
Oct 4 09:17:07 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:07 mail amavis[686]: logging initialized, log level 2, syslog: amavis.mail
Oct 4 09:17:07 mail amavis[686]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Oct 4 09:17:07 mail amavis[686]: starting. (warm) /usr/sbin/amavisd-new at mail.my-domain.com amavisd-new-2.11.1 (20181009), Unicode aware, LC_CTYPE="C.UTF-8"
Oct 4 09:17:07 mail amavis[686]: perl=5.032001, user=110, EUID: 110 (110); group=, EGID: 112 112 (112 112)
Oct 4 09:17:07 mail amavis[686]: warm restart on HUP [686]: '/usr/sbin/amavisd-new foreground', sockets: 5||/var/lib/amavis/amavisd.sock|UNIX|; 6|127.0.0.1|10024|TCP|ipv4
Oct 4 09:17:08 mail amavis[686]: INFO: no optional modules: utf8_heavy.pl unicore::lib::Nt::De.pl unicore::Heavy.pl Unix::Getrusage
Oct 4 09:17:08 mail amavis[686]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Oct 4 09:17:08 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34638 to [127.0.0.1]:25
Oct 4 09:17:08 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34638
Oct 4 09:17:08 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:08 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:08 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <do
Oct 4 09:17:08 mail postfix/smtpd[2509]: 44B8F38FDF4: client=localhost[127.0.0.1]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:08 mail postfix/cleanup[2513]: 44B8F38FDF4: message-id=[email protected]
Oct 4 09:17:08 mail opendkim[531]: 44B8F38FDF4: no signing table match for '[email protected]'
Oct 4 09:17:08 mail opendkim[531]: 44B8F38FDF4: no signature data
Oct 4 09:17:08 mail postfix/qmgr[2459]: 44B8F38FDF4: from=[email protected], size=516, nrcpt=1 (queue active)
Oct 4 09:17:08 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:08 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:34652 to [127.0.0.1]:25
Oct 4 09:17:08 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:34652
Oct 4 09:17:08 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:08 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:08 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: alias1~[email protected]\nDATA\nFrom: Docker Mail Serve
Oct 4 09:17:08 mail postfix/smtpd[2493]: 96E8438FDF5: client=localhost[127.0.0.1]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:08 mail postfix/cleanup[2513]: 96E8438FDF5: message-id=[email protected]
Oct 4 09:17:08 mail opendkim[531]: 96E8438FDF5: no signing table match for '[email protected]'
Oct 4 09:17:08 mail opendkim[531]: 96E8438FDF5: no signature data
Oct 4 09:17:08 mail postfix/qmgr[2459]: 96E8438FDF5: from=[email protected], size=555, nrcpt=1 (queue active)
Oct 4 09:17:08 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:08 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52530 to [127.0.0.1]:25
Oct 4 09:17:08 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52530
Oct 4 09:17:08 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:08 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:08 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <doc
Oct 4 09:17:08 mail postfix/smtpd[2509]: D1A1538FDF9: client=localhost[127.0.0.1]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:08 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:08 mail postfix/cleanup[2513]: D1A1538FDF9: message-id=[email protected]
Oct 4 09:17:08 mail opendkim[531]: D1A1538FDF9: no signing table match for '[email protected]'
Oct 4 09:17:08 mail opendkim[531]: D1A1538FDF9: no signature data
Oct 4 09:17:08 mail amavis[686]: INFO: SA version: 3.4.6, 3.004006, no optional modules: Net::CIDR::Lite Encode::Detect Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
Oct 4 09:17:08 mail amavis[686]: SpamControl: init_pre_chroot on SpamAssassin done
Oct 4 09:17:08 mail amavis[686]: socket module IO::Socket::IP, protocol families available: INET
Oct 4 09:17:08 mail amavis[686]: will bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp
Oct 4 09:17:08 mail amavis[686]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Oct 4 09:17:08 mail amavis[686]: _WARN: Pid_file created by this same process. Doing nothing.
Oct 4 09:17:08 mail amavis[686]: _WARN: Pid_file created by this same process. Doing nothing.
Oct 4 09:17:08 mail amavis[686]: sd_notify (no socket): STATUS=Preparing to re-bind sockets.
Oct 4 09:17:08 mail amavis[686]: Net::Server: 2022/10/04-09:17:08 Amavis (type Net::Server::PreForkSimple) starting! pid(686)
Oct 4 09:17:08 mail postfix/qmgr[2459]: D1A1538FDF9: from=[email protected], size=507, nrcpt=1 (queue active)
Oct 4 09:17:08 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:08 mail amavis[686]: sd_notify (no socket): STATUS=Warm restart, re-binding sockets.
Oct 4 09:17:08 mail amavis[686]: Net::Server: Binding open file descriptors
Oct 4 09:17:08 mail amavis[686]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
Oct 4 09:17:08 mail amavis[686]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Oct 4 09:17:08 mail amavis[686]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.
Oct 4 09:17:08 mail amavis[686]: Net::Server: Group Not Defined. Defaulting to EGID '112 112'
Oct 4 09:17:08 mail amavis[686]: Net::Server: User Not Defined. Defaulting to EUID '110'
Oct 4 09:17:08 mail amavis[686]: sd_notify (no socket): STATUS=The rest of pre-fork init, finding helper programs.
Oct 4 09:17:08 mail amavis[686]: config files read: /usr/share/amavis/conf.d/10-debian_scripts, /usr/share/amavis/conf.d/20-package, /etc/amavis/conf.d/01-debian, /etc/amavis/conf.d/05-domain_id, /etc/amavis/conf.d/05-node_id, /etc/amavis/conf.d/15-av_scanners, /etc/amavis/conf.d/15-content_filter_mode, /etc/amavis/conf.d/20-debian_defaults, /etc/amavis/conf.d/25-amavis_helpers, /etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/49-docker-mailserver, /etc/amavis/conf.d/50-user, /etc/amavis/conf.d/60-dms_default_config, /etc/amavis/conf.d/61-dms_auto_generated, /etc/amavis/conf.d/62-improve_privacy_remove_headers
Oct 4 09:17:08 mail amavis[686]: Module Amavis::Conf 2.412
Oct 4 09:17:08 mail amavis[686]: Module Archive::Zip 1.68
Oct 4 09:17:08 mail amavis[686]: Module BerkeleyDB 0.64
Oct 4 09:17:08 mail amavis[686]: Module Compress::Raw::Zlib 2.093
Oct 4 09:17:08 mail amavis[686]: Module Compress::Zlib 2.093
Oct 4 09:17:08 mail amavis[686]: Module Crypt::OpenSSL::RSA 0.31
Oct 4 09:17:08 mail amavis[686]: Module DB_File 1.853
Oct 4 09:17:08 mail amavis[686]: Module Digest::MD5 2.55_01
Oct 4 09:17:08 mail amavis[686]: Module Digest::SHA 6.02
Oct 4 09:17:08 mail amavis[686]: Module Encode 3.06
Oct 4 09:17:08 mail amavis[686]: Module File::Temp 0.2309
Oct 4 09:17:08 mail amavis[686]: Module IO::Socket::IP 0.39
Oct 4 09:17:08 mail amavis[686]: Module MIME::Entity 5.509
Oct 4 09:17:08 mail amavis[686]: Module MIME::Parser 5.509
Oct 4 09:17:08 mail amavis[686]: Module MIME::Tools 5.509
Oct 4 09:17:08 mail amavis[686]: Module Mail::DKIM::Verifier 1.20200907
Oct 4 09:17:08 mail amavis[686]: Module Mail::Header 2.21
Oct 4 09:17:08 mail amavis[686]: Module Mail::Internet 2.21
Oct 4 09:17:08 mail amavis[686]: Module Mail::SPF v2.009
Oct 4 09:17:08 mail amavis[686]: Module Mail::SpamAssassin 3.004006
Oct 4 09:17:08 mail amavis[686]: Module Net::DNS 1.29
Oct 4 09:17:08 mail amavis[686]: Module Net::LibIDN 0.12
Oct 4 09:17:08 mail amavis[686]: Module Net::Server 2.009
Oct 4 09:17:08 mail amavis[686]: Module NetAddr::IP 4.079
Oct 4 09:17:08 mail amavis[686]: Module Razor2::Client::Version 2.84
Oct 4 09:17:08 mail amavis[686]: Module Scalar::Util 1.55
Oct 4 09:17:08 mail amavis[686]: Module Socket 2.029
Oct 4 09:17:08 mail amavis[686]: Module Socket6 0.29
Oct 4 09:17:08 mail amavis[686]: Module Time::HiRes 1.9764
Oct 4 09:17:08 mail amavis[686]: Module URI 5.08
Oct 4 09:17:08 mail amavis[686]: Module Unix::Syslog 1.1
Oct 4 09:17:08 mail amavis[686]: Amavis::ZMQ code NOT loaded
Oct 4 09:17:08 mail amavis[686]: Amavis::DB code loaded
Oct 4 09:17:08 mail amavis[686]: SQL base code NOT loaded
Oct 4 09:17:08 mail amavis[686]: SQL::Log code NOT loaded
Oct 4 09:17:08 mail amavis[686]: SQL::Quarantine NOT loaded
Oct 4 09:17:08 mail amavis[686]: Lookup::SQL code NOT loaded
Oct 4 09:17:08 mail amavis[686]: Lookup::LDAP code NOT loaded
Oct 4 09:17:08 mail amavis[686]: AM.PDP-in proto code loaded
Oct 4 09:17:08 mail amavis[686]: SMTP-in proto code loaded
Oct 4 09:17:08 mail amavis[686]: Courier proto code NOT loaded
Oct 4 09:17:08 mail amavis[686]: SMTP-out proto code loaded
Oct 4 09:17:08 mail amavis[686]: Pipe-out proto code NOT loaded
Oct 4 09:17:08 mail amavis[686]: BSMTP-out proto code NOT loaded
Oct 4 09:17:08 mail amavis[686]: Local-out proto code loaded
Oct 4 09:17:08 mail amavis[686]: OS_Fingerprint code NOT loaded
Oct 4 09:17:08 mail amavis[686]: ANTI-VIRUS code NOT loaded
Oct 4 09:17:08 mail amavis[686]: ANTI-SPAM code loaded
Oct 4 09:17:08 mail amavis[686]: ANTI-SPAM-EXT code NOT loaded
Oct 4 09:17:08 mail amavis[686]: ANTI-SPAM-C code NOT loaded
Oct 4 09:17:08 mail amavis[686]: ANTI-SPAM-SA code loaded
Oct 4 09:17:08 mail amavis[686]: Unpackers code loaded
Oct 4 09:17:08 mail amavis[686]: DKIM code NOT loaded
Oct 4 09:17:08 mail amavis[686]: Tools code NOT loaded
Oct 4 09:17:08 mail amavis[686]: Found $file at /usr/bin/file
Oct 4 09:17:08 mail amavis[686]: Found $altermime at /usr/bin/altermime
Oct 4 09:17:08 mail amavis[686]: Internal decoder for .mail
Oct 4 09:17:08 mail amavis[686]: Found decoder for .Z at /bin/uncompress
Oct 4 09:17:08 mail amavis[686]: Found decoder for .gz at /bin/gzip -d
Oct 4 09:17:08 mail amavis[686]: Internal decoder for .gz (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .bz2 at /bin/bzip2 -d
Oct 4 09:17:08 mail amavis[686]: Found decoder for .xz at /usr/bin/xz -dc
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lzma at /usr/bin/xz -dc --format=lzma
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lrz at /usr/bin/lrzip -q -k -d -o -
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lzo at /usr/bin/lzop -d
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lz4 at /usr/bin/lz4c -d
Oct 4 09:17:08 mail amavis[686]: Found decoder for .rpm at /usr/bin/rpm2cpio
Oct 4 09:17:08 mail amavis[686]: Found decoder for .cpio at /bin/pax
Oct 4 09:17:08 mail amavis[686]: Found decoder for .tar at /bin/pax
Oct 4 09:17:08 mail amavis[686]: Found decoder for .deb at /usr/bin/ar
Oct 4 09:17:08 mail amavis[686]: Found decoder for .rar at /usr/bin/unrar-free
Oct 4 09:17:08 mail amavis[686]: Found decoder for .arj at /usr/bin/arj
Oct 4 09:17:08 mail amavis[686]: Found decoder for .arc at /usr/bin/nomarch
Oct 4 09:17:08 mail amavis[686]: No ext program for .zoo, tried: zoo
Oct 4 09:17:08 mail amavis[686]: No ext program for .doc, tried: ripole
Oct 4 09:17:08 mail amavis[686]: Found decoder for .cab at /usr/bin/cabextract
Oct 4 09:17:08 mail amavis[686]: Internal decoder for .tnef
Oct 4 09:17:08 mail amavis[686]: Found decoder for .zip at /usr/bin/7za
Oct 4 09:17:08 mail amavis[686]: Found decoder for .kmz at /usr/bin/7za
Oct 4 09:17:08 mail amavis[686]: Internal decoder for .zip (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Internal decoder for .kmz (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .7z at /usr/bin/7zr
Oct 4 09:17:08 mail amavis[686]: Found decoder for .gz at /usr/bin/7za (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .bz2 at /usr/bin/7za (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .Z at /usr/bin/7za (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .tar at /usr/bin/7za (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .xz at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lzma at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .jar at /usr/bin/7z
Oct 4 09:17:08 mail amavis[686]: Found decoder for .cpio at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .arj at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .rar at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .swf at /usr/bin/7z
Oct 4 09:17:08 mail amavis[686]: Found decoder for .lha at /usr/bin/7z
Oct 4 09:17:08 mail amavis[686]: Found decoder for .iso at /usr/bin/7z
Oct 4 09:17:08 mail amavis[686]: Found decoder for .cab at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .deb at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .rpm at /usr/bin/7z (backup, not used)
Oct 4 09:17:08 mail amavis[686]: Found decoder for .exe at /usr/bin/unrar-free; /usr/bin/arj
Oct 4 09:17:08 mail amavis[686]: No decoder for .F
Oct 4 09:17:08 mail amavis[686]: No decoder for .doc
Oct 4 09:17:08 mail amavis[686]: No decoder for .zoo
Oct 4 09:17:08 mail amavis[686]: Deleting db files nanny.db in /var/lib/amavis/db
Oct 4 09:17:08 mail amavis[686]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.64, libdb 5.3
Oct 4 09:17:08 mail amavis[686]: initializing Mail::SpamAssassin (0)
Oct 4 09:17:08 mail amavis[686]: SpamAssassin debug facilities: info
Oct 4 09:17:09 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52540 to [127.0.0.1]:25
Oct 4 09:17:09 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52540
Oct 4 09:17:09 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:09 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:09 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <dockermai
Oct 4 09:17:09 mail postfix/smtpd[2493]: 1C4AC38FDFA: client=localhost[127.0.0.1]
Oct 4 09:17:09 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:09 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:09 mail postfix/cleanup[2513]: 1C4AC38FDFA: message-id=[email protected]
Oct 4 09:17:09 mail opendkim[531]: 1C4AC38FDFA: no signing table match for '[email protected]'
Oct 4 09:17:09 mail opendkim[531]: 1C4AC38FDFA: no signature data
Oct 4 09:17:09 mail postfix/qmgr[2459]: 1C4AC38FDFA: from=[email protected], size=495, nrcpt=1 (queue active)
Oct 4 09:17:09 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:09 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52554 to [127.0.0.1]:25
Oct 4 09:17:09 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52554
Oct 4 09:17:09 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:09 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:09 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <doc
Oct 4 09:17:09 mail postfix/smtpd[2509]: 7FEBD38FDFB: client=localhost[127.0.0.1]
Oct 4 09:17:09 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:09 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:09 mail postfix/cleanup[2513]: 7FEBD38FDFB: message-id=[email protected]
Oct 4 09:17:09 mail opendkim[531]: 7FEBD38FDFB: no signing table match for '[email protected]'
Oct 4 09:17:09 mail opendkim[531]: 7FEBD38FDFB: no signature data
Oct 4 09:17:09 mail postfix/qmgr[2459]: 7FEBD38FDFB: from=[email protected], size=507, nrcpt=1 (queue active)
Oct 4 09:17:09 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:10 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52566 to [127.0.0.1]:25
Oct 4 09:17:10 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52566
Oct 4 09:17:10 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:10 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:10 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <doc
Oct 4 09:17:10 mail postfix/smtpd[2493]: 050A638FDFC: client=localhost[127.0.0.1]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:10 mail postfix/cleanup[2513]: 050A638FDFC: message-id=[email protected]
Oct 4 09:17:10 mail opendkim[531]: 050A638FDFC: no signing table match for '[email protected]'
Oct 4 09:17:10 mail opendkim[531]: 050A638FDFC: no signature data
Oct 4 09:17:10 mail postfix/qmgr[2459]: 050A638FDFC: from=[email protected], size=507, nrcpt=1 (queue active)
Oct 4 09:17:10 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:10 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52578 to [127.0.0.1]:25
Oct 4 09:17:10 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52578
Oct 4 09:17:10 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:10 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:10 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <doc
Oct 4 09:17:10 mail postfix/smtpd[2509]: 50B8038FDFD: client=localhost[127.0.0.1]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:10 mail postfix/cleanup[2513]: 50B8038FDFD: message-id=[email protected]
Oct 4 09:17:10 mail opendkim[531]: 50B8038FDFD: no signing table match for '[email protected]'
Oct 4 09:17:10 mail opendkim[531]: 50B8038FDFD: no signature data
Oct 4 09:17:10 mail postfix/qmgr[2459]: 50B8038FDFD: from=[email protected], size=582, nrcpt=1 (queue active)
Oct 4 09:17:10 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:10 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52594 to [127.0.0.1]:25
Oct 4 09:17:10 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52594
Oct 4 09:17:10 mail postfix/smtpd[2493]: connect from localhost[127.0.0.1]
Oct 4 09:17:10 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:10 mail postfix/smtpd[2493]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Ser
Oct 4 09:17:10 mail postfix/smtpd[2493]: 8FEDF38FDFE: client=localhost[127.0.0.1]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:10 mail postfix/cleanup[2513]: 8FEDF38FDFE: message-id=[email protected]
Oct 4 09:17:10 mail opendkim[531]: 8FEDF38FDFE: no signing table match for '[email protected]'
Oct 4 09:17:10 mail opendkim[531]: 8FEDF38FDFE: no signature data
Oct 4 09:17:10 mail postfix/qmgr[2459]: 8FEDF38FDFE: from=[email protected], size=539, nrcpt=1 (queue active)
Oct 4 09:17:10 mail postfix/smtpd[2493]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Oct 4 09:17:10 mail postfix/postscreen[2492]: CONNECT from [127.0.0.1]:52608 to [127.0.0.1]:25
Oct 4 09:17:10 mail postfix/postscreen[2492]: WHITELISTED [127.0.0.1]:52608
Oct 4 09:17:10 mail postfix/smtpd[2509]: connect from localhost[127.0.0.1]
Oct 4 09:17:10 mail opendmarc[540]: ignoring connection from localhost
Oct 4 09:17:10 mail postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <d
Oct 4 09:17:10 mail postfix/smtpd[2509]: CB0AA38FDFF: client=localhost[127.0.0.1]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] rewritten as [email protected]
Oct 4 09:17:10 mail postsrsd[2514]: srs_forward: [email protected] not rewritten: Valid SRS address for [email protected]
Oct 4 09:17:10 mail postfix/cleanup[2513]: CB0AA38FDFF: message-id=[email protected]
Oct 4 09:17:10 mail opendkim[531]: CB0AA38FDFF: no signing table match for '[email protected]'
Oct 4 09:17:10 mail opendkim[531]: CB0AA38FDFF: no signature data
Oct 4 09:17:10 mail postfix/qmgr[2459]: CB0AA38FDFF: from=[email protected], size=524, nrcpt=1 (queue active)
Oct 4 09:17:10 mail postfix/smtpd[2509]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=1 quit=1 commands=5

Amavis seems to restart way more often than is healthy I think. Hadn't had enough time to find the reason yet, though. Not sure why Amavis receives SIGHUP all the time, but this is definitely looking like the issue that introduces more timing-related issues, and in turn, the unsteady CI.

@polarathene
Copy link
Copy Markdown
Member

polarathene commented Oct 4, 2022

I do not see a place where local vs GH CI would matter right now. Do you have an idea?

The intention was to confirm that it was a CI only issue, which I suspected was unlikely.

My approach is to just to make a copy of the test and strip it down until it works. Like we did with ClamAV, if Amavis is contributing to the issue, and the test coverage can be extracted, it may resolve the issue.

I'd first just disable anything related to Amavis to address those startup issues, and if that's not it, disable further as we do know other tests are working fine and it's something about how this container is setup differently.


I was able to reproduce the CI results locally. Here is the log for a failed run

That's a different failure than the one being discussed earlier here. Although we have been having failures in CI at this point sometimes too.

Did you do an image build without any cache to ensure latest ClamAV updates? I suppose with ClamAV disabled, that shouldn't be an issue though 🤷‍♂️


Not sure why Amavis receives SIGHUP all the time, but this is definitely looking like the issue that introduces more timing-related issues, and in turn, the unsteady CI.

If it's being killed by the OOM reaper (even if Amavis isn't the actual memory hog), that might explain it.

There was recent changes to the Dockerfile and how packages are managed, is it possible we've somehow introduced a regression there? Should be easy enough to confirm by seeing if the test reproduces on an existing release prior to those changes like 11.1.0?

There's also a chance that the check-for-changes.sh service is misbehaving, or the Amavis specific logic to restart the service there has a bug. Should be possible to verify with trace logs?


Soooo, if I was to approach it:

  1. Reproduce test failure with a released image to confirm if failure is due to unreleased changes or specific to our test suite.
  2. If reproduced with v11.1, then enable trace logging, run the test and docker exec to poll the change detector logs for activity.
  3. If change detector or supervisord is restarting Amavis frequently, investigate cause.
  4. If not, brute-force approach is to strip test container config down by 50% of options, if unable to reproduce failure, restore 50% of settings removed, otherwise, drop another 50% of container settings that were applied when the failure was reproduced, and repeat this process until hopefully identifying the cause.
  5. Alternatively, attempt to resolve by extracting out more tests into their own files, but this isn't likely any better / easier than step 4.

Oh.... probably not helpful, but I remember trying change detection with Amavis to use reload, not restart. It still shouldn't be triggered so often, but that is something that is different from postfix and dovecot services in change detection.

Another thing I noticed was the docker network config. Before this PR, somehow we had two competing lines for that, one using container, another host. Most tests don't use either of these, so I'm not sure which tests those were intended for. Perhaps it's contributing to the issue?


postfix/smtpd[2509]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM

This is due to nc not respecting proper protocol of waiting it's turn during the exchange, and can be resolved using a mail client CLI tool. For my work on relays a while back I did make a little Rust program that does this, and configured network + local DNS to perform the testing as if it was from outside the server (and optionally authenticated).

The rust code itself wasn't that complicated, leveraged crates to do the bulk of it. But I assume this isn't going to resolve the test failures here 😓

CI is not yet updated to use IMAGE_NAME as well, so we need to provide
it explictly here
georglauterbach added a commit that referenced this pull request Oct 5, 2022
@georglauterbach georglauterbach mentioned this pull request Oct 5, 2022
7 tasks
@georglauterbach
Copy link
Copy Markdown
Member Author

closing in favor of #2815

@georglauterbach georglauterbach deleted the ci/fix-more-tests branch October 5, 2022 15:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants