Skip to content

feat: Allow changing the Dovecot vmail UID/GID via ENV#3550

Merged
polarathene merged 13 commits intodocker-mailserver:masterfrom
vincentDcmps:UID
Sep 30, 2023
Merged

feat: Allow changing the Dovecot vmail UID/GID via ENV#3550
polarathene merged 13 commits intodocker-mailserver:masterfrom
vincentDcmps:UID

Conversation

@vincentDcmps
Copy link
Copy Markdown
Contributor

@vincentDcmps vincentDcmps commented Sep 27, 2023

Description

There is a deployment scenario with remote storage (NFS / NAS) where the appliance restricts what UID / GID values are allowed on the file system.

This causes a problem when using a volume bind mount for persisting the DMS /var/mail onto the host, where the UID/GID of 5000:5000 (internally mapped to docker:docker) that is used by Dovecot in DMS is not permitted.

Unlike a similar issue with LDAP supporting per-user UID/GID (where chown -R during startup and change detection adjusts ownership over /var/mail), this PR only needs to adjust the static vmail user configured for Dovecot. This can be supported easily with ENV.

Resolves: #3548 #405 #1611

Resolves discussion: https://github.com/orgs/docker-mailserver/discussions/3407#discussioncomment-6299183

Type of change

Fixes a bug by introducing a new feature.

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • This change requires a documentation update

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

@vincentDcmps vincentDcmps changed the title UI d add UID and GID Variable Sep 27, 2023
@polarathene
Copy link
Copy Markdown
Member

I ran the test suite locally with a clone of your branch, but with a slight modification to the test/helper/setup.bash method _common_container_create():

--env UID_DOCKER=9042 \
--env GID_DOCKER=9042 \

This gave a variety of errors though.


LDAP (non-concern)

This one is just due to the .ldif configuration still being 5000:5000, so can be ignored.

# test/tests/serial/mail_with_ldap.bats

 ✗ [LDAP] dovecot: ldap mail delivery works [120578]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `_should_successfully_deliver_mail_to' in file test/tests/serial/mail_with_ldap.bats, line 397,
    in test file test/tests/serial/mail_with_ldap.bats, line 257)
     `_should_successfully_deliver_mail_to "some.user@${FQDN_LOCALHOST_A}" "/var/mail/${FQDN_LOCALHOST_A}/some.user/new/"' failed
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
# test/tests/serial/test.bats

 ✗ [General] system: /var/log/mail/mail.log is error free [576]
   (from function `assert_failure' in file test/test_helper/bats-assert/src/assert_failure.bash, line 66,
    in test file test/tests/serial/tests.bats, line 194)
     `assert_failure' failed

   -- command succeeded, but it was expected to fail --
   output (4 lines):
     Sep 27 23:25:14 mail dovecot: imap([email protected])<1034><toDtgF8GvNp/AAAB>: Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
     Sep 27 23:25:14 mail dovecot: imap([email protected])<1034><toDtgF8GvNp/AAAB>: Error: Couldn't create mailbox list lock /var/mail/localhost.localdomain/user1/mailboxes.lock: file_create_locked(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: safe_mkstemp(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: Permission denied
     Sep 27 23:25:15 mail dovecot: imap([email protected])<1046><GV/vgF8Gytp/AAAB>: Error: file_dotlock_open(/var/mail/localhost.localdomain/added/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/added, dir owned by 0:9042 mode=0755)
     Sep 27 23:25:15 mail dovecot: imap([email protected])<1046><GV/vgF8Gytp/AAAB>: Error: Couldn't create mailbox list lock /var/mail/localhost.localdomain/added/mailboxes.lock: file_create_locked(/var/mail/localhost.localdomain/added/mailboxes.lock) failed: safe_mkstemp(/var/mail/localhost.localdomain/added/mailboxes.lock) failed: Permission denied
   --


 ✗ [General] pflogsum delivery [10340]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/tests/serial/tests.bats, line 502)
     `assert_success' failed

   -- command failed --
   status : 2
   output : grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   --
# test/tests/parallel/set1/dovecot/dovecot_sieve.bats

 ✗ setup_file failed []
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `setup_file' in test file test/tests/parallel/set1/dovecot/dovecot_sieve.bats, line 33)
     `_wait_for_empty_mail_queue_in_container' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_dovecot-sieve
# test/tests/parallel/set1/dovecot/mailbox_format_dbox.bats

 ✗ [Dovecot] (ENV DOVECOT_MAILBOX_FORMAT=sdbox) should store received mail at expected location [126589]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    in test file test/tests/parallel/set1/dovecot/mailbox_format_dbox.bats, line 30)
     `_wait_for_empty_mail_queue_in_container' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_dovecot-dbox_sdbox
 ✗ [Dovecot] (ENV DOVECOT_MAILBOX_FORMAT=mdbox) should store received mail at expected location [126785]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    in test file test/tests/parallel/set1/dovecot/mailbox_format_dbox.bats, line 51)
     `_wait_for_empty_mail_queue_in_container' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_dovecot-dbox_mdbox
# test/tests/parallel/set1/dovecot/special_use_folders.bats

 ✗ [Special Use Folders] normal delivery works [818]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    from function `_should_have_content_in_directory' in file test/helper/common.bash, line 413,
    from function `_count_files_in_directory_in_container' in file test/helper/common.bash, line 400,
    in test file test/tests/parallel/set1/dovecot/special_use_folders.bats, line 18)
     `_count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new 1' failed

   -- command failed --
   status : 1
   output :
   --
# test/tests/parallel/set1/spam_virus/clamav.bats

 ✗ setup_file failed []
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `setup_file' in test file test/tests/parallel/set1/spam_virus/clamav.bats, line 29)
     `_wait_for_empty_mail_queue_in_container' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_clamav
rspamd_full.bats (big failure logs)
# test/tests/parallel/set1/spam_virus/rspamd_full.bats

 ✗ [Rspamd] (full) normal mail passes fine [323]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 186,
    in test file test/tests/parallel/set1/spam_virus/rspamd_full.bats, line 111)
     `assert_output --partial "stored mail into mailbox 'INBOX'"' failed

   -- output does not contain substring --
   substring (1 lines):
     stored mail into mailbox 'INBOX'
   output (56 lines):
     Sep 27 23:42:06 mail postfix/smtpd[980]: 87D03B0E8: client=localhost[127.0.0.1]
     Sep 27 23:42:06 mail postfix/cleanup[1001]: 87D03B0E8: message-id=<[email protected]>
     Sep 27 23:42:06 mail postfix/qmgr[838]: 87D03B0E8: from=<[email protected]>, size=518, nrcpt=1 (queue active)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=no)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (no commit, status=ok, keep=yes)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=yes)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute implicit keep (status=ok)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Start storing into mailbox INBOX
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing implicit keep action
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute storing into mailbox 'INBOX'
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Failed to open mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06]
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing implicit keep action (status=temporary_failure)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalizing actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished finalizing actions (status=ok, keep=implicit, committed=no)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep (status=ok)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep action(status=temporary_failure, action_status=temporary_failure, commit_status=ok)
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back implicit keep action
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back storing into mailbox 'INBOX'
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Error: sieve: msgid=<[email protected]>: failed to store into mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06]
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finish implicit keep action
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finishing actions
     Sep 27 23:42:06 mail dovecot: lmtp([email protected])<1004><kM7nKc69FGXsAwAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)
     Sep 27 23:42:06 mail postfix/lmtp[1003]: 87D03B0E8: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=0.16, delays=0.14/0/0.01/0.01, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06] (in reply to end of DATA command))
     Sep 27 23:51:54 mail postfix/qmgr[838]: 87D03B0E8: from=<[email protected]>, size=518, nrcpt=1 (queue active)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=no)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (no commit, status=ok, keep=yes)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=yes)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute implicit keep (status=ok)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Start storing into mailbox INBOX
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing implicit keep action
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute storing into mailbox 'INBOX'
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Failed to open mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing implicit keep action (status=temporary_failure)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalizing actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished finalizing actions (status=ok, keep=implicit, committed=no)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep (status=ok)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep action(status=temporary_failure, action_status=temporary_failure, commit_status=ok)
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back implicit keep action
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back storing into mailbox 'INBOX'
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: sieve: msgid=<[email protected]>: failed to store into mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finish implicit keep action
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finishing actions
     Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)
     Sep 27 23:51:54 mail postfix/lmtp[5396]: 87D03B0E8: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=588, delays=588/0/0.01/0.01, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54] (in reply to end of DATA command))
   --
# test/tests/parallel/set1/spam_virus/rspamd_full.bats
 ✗ [Rspamd] (full) detects and rejects spam [481]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    from function `_should_have_content_in_directory' in file test/helper/common.bash, line 413,
    from function `_count_files_in_directory_in_container' in file test/helper/common.bash, line 400,
    in test file test/tests/parallel/set1/spam_virus/rspamd_full.bats, line 124)
     `_count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1' failed

   -- command failed --
   status : 1
   output :
   --

 ✗ [Rspamd] (full) detects and rejects virus [435]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    from function `_should_have_content_in_directory' in file test/helper/common.bash, line 413,
    from function `_count_files_in_directory_in_container' in file test/helper/common.bash, line 400,
    in test file test/tests/parallel/set1/spam_virus/rspamd_full.bats, line 136)
     `_count_files_in_directory_in_container /var/mail/localhost.localdomain/user1/new/ 1' failed

   -- command failed --
   status : 1
   output :
   --
# test/tests/parallel/set1/spam_virus/rspamd_full.bats

 ✗ [Rspamd] (full) MOVE_SPAM_TO_JUNK works for Rspamd [545]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 186,
    in test file test/tests/parallel/set1/spam_virus/rspamd_full.bats, line 221)
     `assert_output --partial "fileinto action: stored mail into mailbox 'Junk'"' failed

   -- output does not contain substring --
   substring (1 lines):
     fileinto action: stored mail into mailbox 'Junk'
   output (26 lines):
     Sep 27 23:54:13 mail postfix/smtpd[6436]: 37E88AF7B: client=localhost[127.0.0.1]
     Sep 27 23:54:13 mail postfix/cleanup[6439]: 37E88AF7B: message-id=<[email protected]>
     Sep 27 23:54:13 mail postfix/qmgr[838]: 37E88AF7B: from=<[email protected]>, size=548, nrcpt=1 (queue active)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=no)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: fileinto action: Start storing into mailbox Junk
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing fileinto action
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: fileinto action: Execute storing into mailbox 'Junk'
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: fileinto action: Failed to open mailbox 'Junk': Mailbox Junk: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13]
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing fileinto action (status=temporary_failure, keep=implicit)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=temporary_failure, keep=implicit, executed=no)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (no commit, status=temporary_failure, keep=yes)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=temporary_failure, commit=yes)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Skip implicit keep for temporary failure (state=execute, status=temporary_failure)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalizing actions
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize fileinto action (status=temporary_failure, action_status=temporary_failure, commit_status=temporary_failure, pre-commit=no)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back fileinto action
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: fileinto action: Roll back storing into mailbox 'Junk'
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Error: sieve: msgid=<[email protected]>: fileinto action: failed to store into mailbox 'Junk': Mailbox Junk: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13]
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished finalizing actions (status=temporary_failure, keep=implicit, committed=no)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Skip implicit keep for temporary failure (state=commit, status=temporary_failure)
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finishing actions
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finish fileinto action
     Sep 27 23:54:13 mail dovecot: lmtp([email protected])<6441><uQylEaXAFGUpGQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)
     Sep 27 23:54:13 mail postfix/lmtp[6440]: 37E88AF7B: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=0.07, delays=0.06/0.01/0.01/0, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13] (in reply to end of DATA command))
   --
# test/tests/parallel/set1/spam_virus/rspamd_full.bats

 ✗ [Rspamd] (full) RSPAMD_LEARN works [2305]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 186,
    in test file test/tests/parallel/set1/spam_virus/rspamd_full.bats, line 267)
     `assert_output --partial 'imapsieve: Matched static mailbox rule [1]'' failed

   -- output does not contain substring --
   substring (1 lines):
     imapsieve: Matched static mailbox rule [1]
   output (310 lines):


# Massive output, repeating failure log:
Sep 27 23:46:08 mail postfix/postscreen[2804]: CONNECT from [127.0.0.1]:47804 to [127.0.0.1]:25
Sep 27 23:46:08 mail postfix/postscreen[2804]: WHITELISTED [127.0.0.1]:47804
Sep 27 23:46:08 mail postfix/smtpd[2805]: connect from localhost[127.0.0.1]
Sep 27 23:46:08 mail postfix/smtpd[2805]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <spa
Sep 27 23:46:08 mail postfix/smtpd[2805]: 58F7CAF7B: client=localhost[127.0.0.1]
Sep 27 23:46:08 mail postfix/cleanup[2808]: 58F7CAF7B: message-id=<[email protected]>
Sep 27 23:46:08 mail postfix/cleanup[2808]: 58F7CAF7B: milter-reject: END-OF-MESSAGE from localhost[127.0.0.1]: 5.7.1 Gtube pattern; from=<[email protected]> to=<[email protected]> proto=SMTP helo=<mail.example.test>
Sep 27 23:46:08 mail postfix/smtpd[2805]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=0/1 quit=1 commands=4/5
Sep 27 23:50:10 mail postfix/postscreen[4616]: CONNECT from [127.0.0.1]:38492 to [127.0.0.1]:25
Sep 27 23:50:10 mail postfix/postscreen[4616]: WHITELISTED [127.0.0.1]:38492
Sep 27 23:50:10 mail postfix/smtpd[4617]: connect from localhost[127.0.0.1]
Sep 27 23:50:10 mail postfix/smtpd[4617]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <vi
Sep 27 23:50:10 mail postfix/smtpd[4617]: 90935AF7B: client=localhost[127.0.0.1]
Sep 27 23:50:10 mail postfix/cleanup[4620]: 90935AF7B: message-id=<[email protected]>
Sep 27 23:50:10 mail postfix/cleanup[4620]: 90935AF7B: milter-reject: END-OF-MESSAGE from localhost[127.0.0.1]: 5.7.1 ClamAV FOUND VIRUS "Eicar-Signature"; from=<[email protected]> to=<[email protected]> proto=SMTP helo=<mail.example.test>
Sep 27 23:50:10 mail postfix/smtpd[4617]: disconnect from localhost[127.0.0.1] helo=1 mail=1 rcpt=1 data=0/1 quit=1 commands=4/5
Sep 27 23:51:54 mail postfix/qmgr[838]: 87D03B0E8: from=<[email protected]>, size=518, nrcpt=1 (queue active)
Sep 27 23:51:54 mail dovecot: lmtp(5397): Connect from local
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: auth-master: userdb lookup([email protected]): Started userdb lookup
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb: Connecting
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=710,uid=0): Client connected (fd=13)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: auth-master: userdb lookup([email protected]): auth USER input: [email protected] uid=5000 gid=5000 home=/var/mail/localhost.localdomain/user1/home
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: auth-master: userdb lookup([email protected]): Finished userdb lookup ([email protected] uid=5000 gid=5000 home=/var/mail/localhost.localdomain/user1/home)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Effective uid=5000, gid=5000, home=/var/mail/localhost.localdomain/user1/home
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota root: name=User quota backend=count args=
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota rule: root=User quota mailbox=* bytes=0 messages=0
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota rule: root=User quota mailbox=Trash bytes=+52428800 messages=0
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 [email protected] localhost.localdomain
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota warning: bytes=0 (80%) messages=0 reverse=no command=quota-warning 80 [email protected] localhost.localdomain
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota warning: bytes=0 (100%) messages=0 reverse=yes command=quota-warning below [email protected] localhost.localdomain
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Quota grace: root=User quota bytes=0 (10%)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/var/mail/localhost.localdomain/user1
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: maildir++: root=/var/mail/localhost.localdomain/user1, index=, indexpvt=, control=, inbox=/var/mail/localhost.localdomain/user1, alt=
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: duplicate db: Initialize
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Pigeonhole version 0.5.21 (f6cd4b8e) initializing
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts.
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Sieve imapsieve plugin for Pigeonhole version 0.5.21 (f6cd4b8e) loaded
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Sieve Extprograms plugin for Pigeonhole version 0.5.21 (f6cd4b8e) loaded
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: Storage path `/var/mail/localhost.localdomain/user1/home/sieve' not found
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: Using Sieve script path: /var/mail/localhost.localdomain/user1/home/.dovecot.sieve
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: Storage path `/var/mail/localhost.localdomain/user1/home/.dovecot.sieve' not found
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: storage: No default script location configured
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: User has no personal script
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: Using script storage path: /usr/lib/dovecot/sieve-global/before/
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: Using script storage path: /usr/lib/dovecot/sieve-global/after/
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: file storage: script: Opened script `spam_to_junk' from `/usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: executed after user's Sieve script(1): /usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Start execute sequence
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Opening script 1 of 1 from `/usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Loading script /usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Script binary /usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin successfully loaded
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: binary /usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin: save: not saving binary, because it is already stored
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Executing script from `/usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Run script `/usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Started running script `/usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: Finished running script `/usr/lib/dovecot/sieve-global/after/spam_to_junk.svbin' (status=ok, resource usage: no usage recorded)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Execute result
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=no)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (no commit, status=ok, keep=yes)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Sequence active
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Finishing sequence (status=ok)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing result (status=ok, commit=yes)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Starting execution of actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=ok, keep=implicit, executed=no)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute implicit keep (status=ok)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Start storing into mailbox INBOX
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Executing implicit keep action
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Execute storing into mailbox 'INBOX'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Mailbox INBOX: Mailbox opened
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Mailbox INBOX: Couldn't open mailbox in list index: Mailbox not found
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: Namespace : Using permissions from /var/mail/localhost.localdomain/user1: mode=0755 gid=default
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: Couldn't create mailbox list lock /var/mail/localhost.localdomain/user1/mailboxes.lock: file_create_locked(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: safe_mkstemp(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: Permission denied
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Failed to open mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing implicit keep action (status=temporary_failure)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalizing actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished finalizing actions (status=ok, keep=implicit, committed=no)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep (status=ok)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finalize implicit keep action(status=temporary_failure, action_status=temporary_failure, commit_status=ok)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back implicit keep action
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Roll back storing into mailbox 'INBOX'
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: sieve: msgid=<[email protected]>: failed to store into mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finish implicit keep action
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finishing actions
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Sequence finished (status=temporary_failure, keep=yes)
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: sieve: multi-script: Destroy
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Error: sieve: Execution of script /usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve was aborted due to temporary failure
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: duplicate db: Cleanup
Sep 27 23:51:54 mail dovecot: lmtp([email protected])<5397><SzGmBBrAFGUVFQAAUi6ngw>: Debug: User session is finished
Sep 27 23:51:54 mail dovecot: lmtp(5397): Disconnect from local: Logged out (state=READY)
Sep 27 23:51:54 mail postfix/lmtp[5396]: 87D03B0E8: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=588, delays=588/0/0.01/0.01, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54] (in reply to end of DATA command))
Sep 27 23:53:54 mail dovecot: lmtp(5397): Debug: auth-master: conn unix:/run/dovecot/auth-userdb (pid=710,uid=0): Disconnected: Connection closed (fd=13)
# test/tests/parallel/set1/spam_virus/spam_junk_folder.bats

 ✗ [Spam - Amavis] ENV SPAMASSASSIN_SPAM_TO_INBOX (enabled + MOVE_SPAM_TO_JUNK=0) should deliver spam message into INBOX [30098]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_should_receive_spam_at' in file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 113,
    in test file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 49)
     `_should_receive_spam_at '/var/mail/localhost.localdomain/user1/new/'' failed
   [   INF   ]  mail.example.test is up and running
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   Timed out on command: _exec_in_container grep -R Subject: SPAM:  /var/mail/localhost.localdomain/user1/new/
   dms-test_spam-amavis_env-move-spam-to-junk-0


 ✗ [Spam - Amavis] ENV SPAMASSASSIN_SPAM_TO_INBOX (enabled + MOVE_SPAM_TO_JUNK=1) should deliver spam message into Junk folder [30093]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_should_receive_spam_at' in file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 113,
    in test file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 70)
     `_should_receive_spam_at '/var/mail/localhost.localdomain/user1/.Junk/new/'' failed
   [   INF   ]  mail.example.test is up and running
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/new/: No such file or directory
   Timed out on command: _exec_in_container grep -R Subject: SPAM:  /var/mail/localhost.localdomain/user1/.Junk/new/
   dms-test_spam-amavis_env-move-spam-to-junk-1


 ✗ [Spam - Amavis] ENV SPAMASSASSIN_SPAM_TO_INBOX (enabled + MARK_SPAM_AS_READ=1) should mark spam message as read [31308]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_should_receive_spam_at' in file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 113,
    in test file test/tests/parallel/set1/spam_virus/spam_junk_folder.bats, line 92)
     `_should_receive_spam_at '/var/mail/localhost.localdomain/user1/.Junk/cur/'' failed
   [   INF   ]  mail.example.test is up and running
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   grep: /var/mail/localhost.localdomain/user1/.Junk/cur/: No such file or directory
   Timed out on command: _exec_in_container grep -R Subject: SPAM:  /var/mail/localhost.localdomain/user1/.Junk/cur/
   dms-test_spam-amavis_env-mark-spam-as-read-1
# test/tests/parallel/set3/hostname.bats

 ✗ [Network - Hostname] should update configuration correctly (Standard FQDN setup) [128211]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `_should_have_correct_mail_headers' in file test/tests/parallel/set3/container_configuration/hostname.bats, line 211,
    in test file test/tests/parallel/set3/container_configuration/hostname.bats, line 36)
     `_should_have_correct_mail_headers 'mail.example.test' 'example.test'' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_hostname_fqdn-with-subdomain


 ✗ [Network - Hostname] should update configuration correctly (Bare Domain) [128113]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `_should_have_correct_mail_headers' in file test/tests/parallel/set3/container_configuration/hostname.bats, line 211,
    in test file test/tests/parallel/set3/container_configuration/hostname.bats, line 59)
     `_should_have_correct_mail_headers 'bare-domain.test'' failed
   [   INF   ]  bare-domain.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_hostname_bare-domain


 ✗ [Network - Hostname] should update configuration correctly (ENV OVERRIDE_HOSTNAME) [128185]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `_should_have_correct_mail_headers' in file test/tests/parallel/set3/container_configuration/hostname.bats, line 211,
    in test file test/tests/parallel/set3/container_configuration/hostname.bats, line 83)
     `_should_have_correct_mail_headers 'mail.override.test' 'override.test' 'original.example.test'' failed
   [   INF   ]  mail.override.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_hostname_env-override-hostname


 ✗ [Network - Hostname] should update configuration correctly (--hostname + --domainname) [128091]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    from function `_should_have_correct_mail_headers' in file test/tests/parallel/set3/container_configuration/hostname.bats, line 211,
    in test file test/tests/parallel/set3/container_configuration/hostname.bats, line 111)
     `_should_have_correct_mail_headers 'mail.example.test' 'example.test' 'mail'' failed
   [   INF   ]  mail.example.test is up and running
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]
   dms-test_hostname_with-nis-domain
# test/tests/parallel/set3/mta/account_management.bats

 ✗ [Mail Accounts] (ENV ENABLE_QUOTAS=1) 'setup email list' should display quota information [291]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 194,
    in test file test/tests/parallel/set3/mta/account_management.bats, line 129)
     `assert_output '* [email protected] ( 0 / ~ ) [0%]'' failed

   -- output differs --
   expected (1 lines):
     * [email protected] ( 0 / ~ ) [0%]
   actual (3 lines):
     doveadm([email protected]): Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
     * [email protected] ( 0 / ~ ) [0%]
     doveadm([email protected]): Error: file_dotlock_open(/var/mail/otherdomain.tld/user2/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/otherdomain.tld/user2, dir owned by 9042:9042 mode=0755)
   --

This one is just due to how the test command was written a bit differently (I've raised a PR to address that). Instead of 124 (signifies timeout) it should fail with 1 (failure) like the others. The failure is like the other test cases, mail was not marked as status=sent as it could not be delivered successfully.

# test/tests/parallel/set3/mta/lmtp_ip.bats

 ✗ [ENV] (POSTFIX_DAGENT) delivers mail to existing account [60327]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/tests/parallel/set3/mta/lmtp_ip.bats, line 47)
     `assert_success' failed

   -- command failed --
   status : 124
   output :
   --
# test/tests/parallel/set3/mta/privacy.bats

 ✗ [Privacy] (Postfix) remove privacy details of the sender [120946]
   (from function `_run_until_success_or_timeout' in file test/helper/common.bash, line 222,
    in test file test/tests/parallel/set3/mta/privacy.bats, line 31)
     `_run_until_success_or_timeout 120 _exec_in_container_bash '[[ -d /var/mail/localhost.localdomain/user1/new ]]'' failed
   Timed out on command: _exec_in_container_bash [[ -d /var/mail/localhost.localdomain/user1/new ]]

The 2nd failure is like lmtp_ip.bats. We filter the log for successfully sent log entries only.

# test/tests/parallel/set3/mta/smtp_delivery.bats

 ✗ [SMTP] (delivery) should succeed at emptying mail queue [121029]
   (from function `_repeat_until_success_or_timeout' in file test/helper/common.bash, line 195,
    from function `_repeat_in_container_until_success_or_timeout' in file test/helper/common.bash, line 157,
    from function `_wait_for_empty_mail_queue_in_container' in file test/helper/common.bash, line 325,
    in test file test/tests/parallel/set3/mta/smtp_delivery.bats, line 102)
     `_wait_for_empty_mail_queue_in_container' failed
   Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]]


 ✗ [SMTP] (delivery) delivers mail to existing account [183]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 186,
    in test file test/tests/parallel/set3/mta/smtp_delivery.bats, line 155)
     `assert_output --partial '1 <[email protected]>'' failed

   -- output does not contain substring --
   substring : 1 <[email protected]>
   output    :
   --


 ✗ [SMTP] (delivery) user1 should have received 8 mails [83]
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert_output.bash, line 186,
    in test file test/tests/parallel/set3/mta/smtp_delivery.bats, line 204)
     `assert_output --partial 'Root Test Message'' failed

   -- output does not contain substring --
   substring : Root Test Message
   output    : grep: /var/mail/localhost.localdomain/user1/new/*: No such file or directory
   --


 ✗ [SMTP] (delivery) SA - All registered domains should receive mail with spam headers (X-Spam) [83]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/tests/parallel/set3/mta/smtp_delivery.bats, line 252)
     `assert_success' failed

   -- command failed --
   status : 2
   output : grep: /var/mail/localhost.localdomain/user1/new: No such file or directory
   --


 ✗ [SMTP] (delivery) mail for root was delivered [75]
   (from function `assert_success' in file test/test_helper/bats-assert/src/assert_success.bash, line 42,
    in test file test/tests/parallel/set3/mta/smtp_delivery.bats, line 267)
     `assert_success' failed

   -- command failed --
   status : 2
   output : grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory
   --

@polarathene
Copy link
Copy Markdown
Member

Failure keywords observed by log type (from prior comments test failures):

  • Dovecot:
    • Debug: => Internal error occurred, Failed, temporary failure, temporary_failure, not found
    • Error: => Internal error occurred, Failed, failed
  • Postfix:
    • postfix/lmtp => Internal error occurred

The bulk of test failures are due to either:

  • Expecting the mailbox for an account to have been created (eg: grep: /var/mail/localhost.localdomain/user1/new/: No such file or directory).
  • Mail queue not emptying (eg: Timed out on command: _exec_in_container /bin/bash -c [[ $(mailq) == "Mail queue is empty" ]])
    • Technically this is for the same reason. Since delivery fails, Postfix keeps the mail queued to try again.

Notably, several tests log failures with explicit UID/GID errors were caught. In the tests.bats failures, we can see that Dovecot is running as 5000:5000 (euid + egid for docker user + group), but /var/mail ownership differs by user:

  • 9042:9042 (1st dir owned by fail, default postfix-accounts.cf for user1)
  • 0:9042 (2nd dir owned by fail, non-default added account in setup_file())
All logs with the `5000` or `9042` values
# All from dovecot service logs:

# test/tests/serial/test.bats
# [General] system: /var/log/mail/mail.log is error free
Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
Error: file_dotlock_open(/var/mail/localhost.localdomain/added/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/added, dir owned by 0:9042 mode=0755)

# test/tests/parallel/set1/spam_virus/rspamd_full.bats
# [Rspamd] (full) RSPAMD_LEARN works
Debug: auth-master: userdb lookup([email protected]): auth USER input: [email protected] uid=5000 gid=5000 home=/var/mail/localhost.localdomain/user1/home`
Debug: auth-master: userdb lookup([email protected]): Finished userdb lookup ([email protected] uid=5000 gid=5000 home=/var/mail/localhost.localdomain/user1/home)
Debug: Effective uid=5000, gid=5000, home=/var/mail/localhost.localdomain/user1/home
Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)

# test/tests/parallel/set3/mta/account_management.bats
# [Mail Accounts] (ENV ENABLE_QUOTAS=1) 'setup email list' should display quota information
doveadm([email protected]): Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
doveadm([email protected]): Error: file_dotlock_open(/var/mail/otherdomain.tld/user2/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/otherdomain.tld/user2, dir owned by 9042:9042 mode=0755)
Logs filtered by failure keywords
# test/tests/parallel/set1/spam_virus/rspamd_full.bats
# ✗ [Rspamd] (full) normal mail passes fine

# Dovecot logs:
Debug: sieve: msgid=<[email protected]>: Failed to open mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06]
Debug: sieve: msgid=<[email protected]>: Finished executing implicit keep action (status=temporary_failure)
Debug: sieve: msgid=<[email protected]>: Finalize implicit keep action(status=temporary_failure, action_status=temporary_failure, commit_status=ok)
Error: sieve: msgid=<[email protected]>: failed to store into mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06]
Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)

# Postfix log then reports the Dovecot failure:
mail postfix/lmtp[1003]: 87D03B0E8: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=0.16, delays=0.14/0/0.01/0.01, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:42:06] (in reply to end of DATA command))
# test/tests/parallel/set1/spam_virus/rspamd_full.bats
# ✗ [Rspamd] (full) MOVE_SPAM_TO_JUNK works for Rspamd

# Dovecot logs:
Debug: sieve: msgid=<[email protected]>: fileinto action: Failed to open mailbox 'Junk': Mailbox Junk: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13]
Debug: sieve: msgid=<[email protected]>: Finished executing fileinto action (status=temporary_failure, keep=implicit)
Debug: sieve: msgid=<[email protected]>: Finished executing actions (status=temporary_failure, keep=implicit, executed=no)
Debug: sieve: msgid=<[email protected]>: Finished executing result (no commit, status=temporary_failure, keep=yes)
Debug: sieve: msgid=<[email protected]>: Executing result (status=temporary_failure, commit=yes)
Debug: sieve: msgid=<[email protected]>: Skip implicit keep for temporary failure (state=execute, status=temporary_failure)
Debug: sieve: msgid=<[email protected]>: Finalize fileinto action (status=temporary_failure, action_status=temporary_failure, commit_status=temporary_failure, pre-commit=no)
Error: sieve: msgid=<[email protected]>: fileinto action: failed to store into mailbox 'Junk': Mailbox Junk: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13]
Debug: sieve: msgid=<[email protected]>: Finished finalizing actions (status=temporary_failure, keep=implicit, committed=no)
Debug: sieve: msgid=<[email protected]>: Skip implicit keep for temporary failure (state=commit, status=temporary_failure)
Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)

# Postfix log then reports the Dovecot failure:
mail postfix/lmtp[6440]: 37E88AF7B: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=0.07, delays=0.06/0.01/0.01/0, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:54:13] (in reply to end of DATA command))
# test/tests/parallel/set1/spam_virus/rspamd_full.bats
# ✗ [Rspamd] (full) RSPAMD_LEARN works

# Postfix - Can ignore this:
# `īmproper command pipelining` is currently expected due to naive approach to
# send mail via netcat / openssl instead of a proper mail client that respects SMTP
mail postfix/smtpd[2805]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <spa
mail postfix/smtpd[4617]: improper command pipelining after HELO from localhost[127.0.0.1]: MAIL FROM: [email protected]\nRCPT TO: [email protected]\nDATA\nFrom: Docker Mail Server <vi

# Dovecot - Sieve `not found` failures should be ok:
Debug: sieve: file storage: Storage path `/var/mail/localhost.localdomain/user1/home/sieve' not found
Debug: sieve: file storage: Using Sieve script path: /var/mail/localhost.localdomain/user1/home/.dovecot.sieve
Debug: sieve: file storage: Storage path `/var/mail/localhost.localdomain/user1/home/.dovecot.sieve' not found

# Dovecot - A sieve script is trying to store mail but fails (note the `gid=default` fallback):
Debug: sieve: msgid=<[email protected]>: Execute storing into mailbox 'INBOX'
Debug: Mailbox INBOX: Mailbox opened
Error: file_dotlock_open(/var/mail/localhost.localdomain/user1/dovecot.list.index.log) failed: Permission denied (euid=5000(docker) egid=5000(docker) missing +w perm: /var/mail/localhost.localdomain/user1, dir owned by 9042:9042 mode=0755)
Debug: Mailbox INBOX: Couldn't open mailbox in list index: Mailbox not found
Debug: Namespace : Using permissions from /var/mail/localhost.localdomain/user1: mode=0755 gid=default
Error: Couldn't create mailbox list lock /var/mail/localhost.localdomain/user1/mailboxes.lock: file_create_locked(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: safe_mkstemp(/var/mail/localhost.localdomain/user1/mailboxes.lock) failed: Permission denied
Error: Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Debug: sieve: msgid=<[email protected]>: Failed to open mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Debug: sieve: msgid=<[email protected]>: Finished executing implicit keep action (status=temporary_failure)
Debug: sieve: msgid=<[email protected]>: Finalize implicit keep action(status=temporary_failure, action_status=temporary_failure, commit_status=ok)
Error: sieve: msgid=<[email protected]>: failed to store into mailbox 'INBOX': Mailbox INBOX: Failed to autocreate mailbox: Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54]
Debug: sieve: msgid=<[email protected]>: Finished executing result (final, status=temporary_failure, keep=yes)
Debug: sieve: multi-script: Sequence finished (status=temporary_failure, keep=yes)
Error: sieve: Execution of script /usr/lib/dovecot/sieve-global/after/spam_to_junk.sieve was aborted due to temporary failure

# Postfix log then reports the Dovecot failure:
mail postfix/lmtp[5396]: 87D03B0E8: to=<[email protected]>, relay=mail.example.test[/var/run/dovecot/lmtp], delay=588, delays=588/0/0.01/0.01, dsn=4.2.0, status=deferred (host mail.example.test[/var/run/dovecot/lmtp] said: 451 4.2.0 <[email protected]> Internal error occurred. Refer to server log for more information. [2023-09-27 23:51:54] (in reply to end of DATA command))

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.

There is quite a few mistakes to be corrected. Thanks for tackling this though!

  • It's great to see you were comfortable enough to try setup a test (which we're definitely lacking proper guidance / docs for).
  • You can go into the "Files changed" tab of this PR view and "Add suggestion to batch" everything I've suggested if you agree with the changes, and commit that via the web UI.

git pull your branch locally afterwards and continue resolving the failure ūser.bats will cause (you may want to comment out the wait for empty queue helper for now, substitute with a little bit of sleep for faster failures).


I've rewritten your PR description. Once all the review feedback is addressed, we'll deal with moving/renaming the test file and ENV. Docs will need to be improved a little bit to better clarify the feature (I'll assist with that).

Comment thread target/scripts/helpers/utils.sh Outdated
Comment thread target/scripts/startup/variables-stack.sh Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment on lines +36 to +41
@test '/var/log/mail/mail.log is error-free' {
_run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log
assert_failure
_run_in_container grep ': error:' /var/log/mail/mail.log
assert_failure
}
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

You didn't mention any reasoning for this in your PR description or commit messages.

I know this is taken from tests.bats, but I don't know why you've skimped on it with only a subset of error checks?

@test "system: /var/log/mail/mail.log is error free" {
_run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log
assert_failure
_run_in_container grep 'mail system configuration error' /var/log/mail/mail.log
assert_failure
_run_in_container grep ': error:' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i 'is not writable' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i 'permission denied' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i '(!)connect' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i 'using backwards-compatible default setting' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i 'connect to 127.0.0.1:10023: Connection refused' /var/log/mail/mail.log
assert_failure
}

Some can be ignored (but they're harmless so adding all for now is fine), here's a proper snippet instead to use:

Suggested change
@test '/var/log/mail/mail.log is error-free' {
_run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log
assert_failure
_run_in_container grep ': error:' /var/log/mail/mail.log
assert_failure
}
# TODO: Migrate to test/helper/common.bash
# This test case is shared with tests.bats, but provides context on errors + some minor edits
# TODO: Could improve in future with keywords from https://github.com/docker-mailserver/docker-mailserver/pull/3550#issuecomment-1738509088
# Potentially via a helper that allows an optional fixed number of errors to be present if they were intentional
@test '/var/log/mail/mail.log is error free' {
# Postfix: https://serverfault.com/questions/934703/postfix-451-4-3-0-temporary-lookup-failure
_run_in_container grep 'non-null host address bits in' /var/log/mail/mail.log
assert_failure
# Postfix delivery failure: https://github.com/docker-mailserver/docker-mailserver/issues/230
_run_in_container grep 'mail system configuration error' /var/log/mail/mail.log
assert_failure
# Unknown error source: https://github.com/docker-mailserver/docker-mailserver/pull/85
_run_in_container grep -i ': error:' /var/log/mail/mail.log
assert_failure
# Unknown error source: https://github.com/docker-mailserver/docker-mailserver/pull/320
_run_in_container grep -i 'not writable' /var/log/mail/mail.log
assert_failure
_run_in_container grep -i 'permission denied' /var/log/mail/mail.log
assert_failure
# Amavis: https://forum.howtoforge.com/threads/postfix-smtp-error-caused-by-clamav-cant-connect-to-a-unix-socket-var-run-clamav-clamd-ctl.81002/
_run_in_container grep -i '(!)connect' /var/log/mail/mail.log
assert_failure
# Postfix: https://github.com/docker-mailserver/docker-mailserver/pull/2597
_run_in_container grep -i 'using backwards-compatible default setting' /var/log/mail/mail.log
assert_failure
# Postgrey: https://github.com/docker-mailserver/docker-mailserver/pull/612#discussion_r117635774
_run_in_container grep -i 'connect to 127.0.0.1:10023: Connection refused' /var/log/mail/mail.log
assert_failure
}
  • Dovecot logs with : Error: (so grep -i ': error:)
  • Dovecot failure failed: Permission denied (already covered by grep -i 'permission denied', but failed: may still be applicable elsewhere 🤷‍♂️ )

Additional keywords have been identified from failures I've caught running this PR: #3550 (comment)

Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
@polarathene polarathene added kind/new feature A new feature is requested in this issue or implemeted with this PR service/dovecot area/scripts area/features kind/improvement Improve an existing feature, configuration file or the documentation kind/bug/fix A fix (PR) for a confirmed bug labels Sep 28, 2023
@polarathene polarathene added this to the v13.0.0 milestone Sep 28, 2023
Comment thread test/tests/serial/user.bats Outdated
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've decided to just apply the feedback myself. You're welcome to read the review feedback if you're interested, or raise any concerns if you disagree with those changes.

Just focus on making ūser.bats pass correctly now by having user.sh apply whatever other configuration changes are required 👍

@polarathene polarathene changed the title add UID and GID Variable feat: Allow changing the Dovecot vmail UID/GID via ENV Sep 28, 2023
Copy link
Copy Markdown
Contributor Author

@vincentDcmps vincentDcmps left a comment

Choose a reason for hiding this comment

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

ok

@vincentDcmps
Copy link
Copy Markdown
Contributor Author

vincentDcmps commented Sep 28, 2023

@polarathene Test pass correctly now thanks for your modification and advice!!! 💥

I have just searched 30 min how access to container log before to understand, I need to comment teardown function 😂

note: maybe a part of solution for other LDAP issue will be to add an UID parameter in the account creation script to custom with the LDAP UID dovecot userDB and modify chown for only chown /var/mail and not all folder hierarchy

Comment thread target/scripts/startup/setup.d/user.sh Outdated
Comment thread target/scripts/helpers/accounts.sh Outdated
Comment thread test/tests/serial/user.bats Outdated
Comment thread test/tests/serial/user.bats Outdated
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.

Please update the remaining:

  • UID_DOCKER => DMS_VMAIL_UID
  • GID_DOCKER => DMS_VMAIL_GID
  • user.sh => vmail-id.sh
  • user.bats => vmail-id.bats
  • accounts.sh needs to update one more line with 5000:500 => ${DMS_VMAIL_UID}:${DMS_VMAIL_GID}

Afterwards this looks all good to go 👍


If your test fails regarding sieve, this is an unrelated bug to this PR (the failure is just actually caught now).

Comment thread docs/content/config/environment.md Outdated
Comment thread mailserver.env Outdated
Comment thread target/scripts/start-mailserver.sh Outdated
Comment thread target/scripts/startup/setup.d/user.sh Outdated
@vincentDcmps
Copy link
Copy Markdown
Contributor Author

vincentDcmps commented Sep 30, 2023

I think we are ready to merge?

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.

These suggestions were missed.

Comment thread target/scripts/startup/setup.d/vmail-id.sh Outdated
Comment thread mailserver.env Outdated
Comment thread docs/content/config/environment.md
polarathene
polarathene previously approved these changes Sep 30, 2023
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.

LGTM 👍

Thanks for the contribution! I won't merge it immediately, the other maintainers may be interested in blocking it for a review of their own first.

It's a small enough and harmless change to review though, and a useful feature for some users. I think you'll get another approval :)

Copy link
Copy Markdown
Member

@georglauterbach georglauterbach left a comment

Choose a reason for hiding this comment

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

Only one minor detail, but I won't block on it. LGTM 👍🏼

Comment thread target/scripts/startup/setup.d/vmail-id.sh
Co-authored-by: Georg Lauterbach <[email protected]>
@github-actions
Copy link
Copy Markdown
Contributor

Documentation preview for this PR is ready! 🎉

Built with commit: e18e9a6

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area/features area/scripts kind/bug/fix A fix (PR) for a confirmed bug kind/improvement Improve an existing feature, configuration file or the documentation kind/new feature A new feature is requested in this issue or implemeted with this PR service/dovecot

Projects

None yet

Development

Successfully merging this pull request may close these issues.

feature request: UID variable

3 participants