[BUG] Test 111 failing

# Bug Report

## Context

Test 111 (`can detect changes` in `mail_ssl_letsencrypt.bats`) is failing

### What is affected by this bug?

Every pipeline/test run since yesterday failed with an error on test 111 although only `workflow files` and the `README.md` + `CONTRIBUTING.md` file was changed. So no change that should affect any functionality of the server

### When does this occur?

Every time the test suite is run (no matter if on gh actions or local) 

### How do we replicate the issue?

1. Watch the [log of the current push pipeline](https://github.com/docker-mailserver/docker-mailserver/runs/1762121959?check_suite_focus=true#step:6:117)
2. Watch the [log of the current PR pipeline](https://github.com/docker-mailserver/docker-mailserver/runs/1760532802?check_suite_focus=true#step:4:117)
3. Run tests locally (`NAME=mailserver-testing:ci ./test/bats/bin/bats test/mail_ssl_letsencrypt.bats`) after building the image (or do a complete `make all`)

## Behavior

### Actual Behavior

The test fails with the following error:
```
 ✗ can detect changes
   (from function `assert_output' in file test/test_helper/bats-assert/src/assert.bash, line 231,
    in test file test/mail_ssl_letsencrypt.bats, line 123)
     `assert_output --partial "postfix: stopped"' failed with status 2
   
   -- output does not contain substring --
   substring : postfix: stopped
   output    : error: <class 'xml.parsers.expat.ExpatError'>, not well-formed (invalid token): line 13, column 2: file: /usr/lib/python2.7/xmlrpclib.py line: 558
   --
```

### Expected Behavior

Valid test run like yesterday ([last working run log](https://github.com/docker-mailserver/docker-mailserver/runs/1758577621?check_suite_focus=true#step:6:117)):
```
ok 111 can detect changes
```

## Your Environment



- version: current `master`
- available RAM: `4GB`
- Docker version: `v19.03.5`

### Environment Variables

According to test suite

### Relevant Stack Traces

I opened another console on my local machine to get the output of `docker logs -f mail_lets_acme_json` during the test 111.
In this example i even manually edited the test file that it uses `SUPERVISOR_LOGLEVEL=debug`:
<details>
<summary> Log output:</summary>

```BASH
# BEGIN
[ TASKLOG ]  Initializing setup
[ TASKLOG ]  Checking configuration
[ TASKLOG ]  Configuring mail server
[ WARNING ]  Spamassassin is disabled. You can enable it with 'ENABLE_SPAMASSASSIN=1'
[ WARNING ]  Clamav is disabled. You can enable it with 'ENABLE_CLAMAV=1'
[ TASKLOG ]  Starting mail server
cron: started
rsyslog: started
dovecot: started
opendkim: started
opendmarc: started
postfix: started
changedetector: started
amavis: started
[ TASKLOG ]  mail.my-domain.com is up and running
Jan 25 14:34:53 mail amavis[244]: logging initialized, log level 2, syslog: amavis.mail
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=Config files have been read, modules loaded.
Jan 25 14:34:53 mail amavis[244]: starting. /usr/sbin/amavisd-new at mail.my-domain.com amavisd-new-2.11.0 (20160426), Unicode aware
Jan 25 14:34:53 mail amavis[244]: perl=5.028001, user=, EUID: 112 (112);  group=, EGID: 114 114 (114 114)
Jan 25 14:34:53 mail amavis[244]: INFO: no optional modules: unicore::lib::Nt::De.pl Unix::Getrusage
Jan 25 14:34:53 mail amavis[244]: socket module IO::Socket::IP, protocol families available: INET
Jan 25 14:34:53 mail amavis[244]: will bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=Transferring control to Net::Server.
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=Preparing to bind sockets.
Jan 25 14:34:53 mail amavis[244]: Net::Server: 2021/01/25-14:34:53 Amavis (type Net::Server::PreForkSimple) starting! pid(244)
Jan 25 14:34:53 mail amavis[244]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
Jan 25 14:34:53 mail amavis[244]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=Sockets bound, checking user and group.
Jan 25 14:34:53 mail amavis[244]: Net::Server: Group Not Defined.  Defaulting to EGID '114 114'
Jan 25 14:34:53 mail amavis[244]: Net::Server: User Not Defined.  Defaulting to EUID '112'
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=The rest of pre-fork init, finding helper programs.
Jan 25 14:34:53 mail amavis[244]: 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
Jan 25 14:34:53 mail amavis[244]: Module Amavis::Conf        2.412
Jan 25 14:34:53 mail amavis[244]: Module Archive::Zip        1.64
Jan 25 14:34:53 mail amavis[244]: Module BerkeleyDB          0.55
Jan 25 14:34:53 mail amavis[244]: Module Compress::Raw::Zlib 2.076
Jan 25 14:34:53 mail amavis[244]: Module Compress::Zlib      2.074
Jan 25 14:34:53 mail amavis[244]: Module Digest::MD5         2.55
Jan 25 14:34:53 mail amavis[244]: Module Digest::SHA         6.01
Jan 25 14:34:53 mail amavis[244]: Module Encode              2.97
Jan 25 14:34:53 mail amavis[244]: Module File::Temp          0.2304
Jan 25 14:34:53 mail amavis[244]: Module IO::Socket::IP      0.39
Jan 25 14:34:53 mail amavis[244]: Module MIME::Entity        5.509
Jan 25 14:34:53 mail amavis[244]: Module MIME::Parser        5.509
Jan 25 14:34:53 mail amavis[244]: Module MIME::Tools         5.509
Jan 25 14:34:53 mail amavis[244]: Module Mail::Header        2.18
Jan 25 14:34:53 mail amavis[244]: Module Mail::Internet      2.18
Jan 25 14:34:53 mail amavis[244]: Module Net::LibIDN         0.12
Jan 25 14:34:53 mail amavis[244]: Module Net::Server         2.009
Jan 25 14:34:53 mail amavis[244]: Module Scalar::Util        1.5
Jan 25 14:34:53 mail amavis[244]: Module Socket              2.027
Jan 25 14:34:53 mail amavis[244]: Module Time::HiRes         1.9759
Jan 25 14:34:53 mail amavis[244]: Module Unix::Syslog        1.1
Jan 25 14:34:53 mail amavis[244]: Amavis::ZMQ code     NOT loaded
Jan 25 14:34:53 mail amavis[244]: Amavis::DB code      loaded
Jan 25 14:34:53 mail amavis[244]: SQL base code        NOT loaded
Jan 25 14:34:53 mail amavis[244]: SQL::Log code        NOT loaded
Jan 25 14:34:53 mail amavis[244]: SQL::Quarantine      NOT loaded
Jan 25 14:34:53 mail amavis[244]: Lookup::SQL code     NOT loaded
Jan 25 14:34:53 mail amavis[244]: Lookup::LDAP code    NOT loaded
Jan 25 14:34:53 mail amavis[244]: AM.PDP-in proto code loaded
Jan 25 14:34:53 mail amavis[244]: SMTP-in proto code   loaded
Jan 25 14:34:53 mail amavis[244]: Courier proto code   NOT loaded
Jan 25 14:34:53 mail amavis[244]: SMTP-out proto code  loaded
Jan 25 14:34:53 mail amavis[244]: Pipe-out proto code  NOT loaded
Jan 25 14:34:53 mail amavis[244]: BSMTP-out proto code NOT loaded
Jan 25 14:34:53 mail amavis[244]: Local-out proto code loaded
Jan 25 14:34:53 mail amavis[244]: OS_Fingerprint code  NOT loaded
Jan 25 14:34:53 mail amavis[244]: ANTI-VIRUS code      NOT loaded
Jan 25 14:34:53 mail amavis[244]: ANTI-SPAM code       NOT loaded
Jan 25 14:34:53 mail amavis[244]: ANTI-SPAM-EXT code   NOT loaded
Jan 25 14:34:53 mail amavis[244]: ANTI-SPAM-C code     NOT loaded
Jan 25 14:34:53 mail amavis[244]: ANTI-SPAM-SA code    NOT loaded
Jan 25 14:34:53 mail amavis[244]: Unpackers code       loaded
Jan 25 14:34:53 mail amavis[244]: DKIM code            NOT loaded
Jan 25 14:34:53 mail amavis[244]: Tools code           NOT loaded
Jan 25 14:34:53 mail amavis[244]: Found $file            at /usr/bin/file
Jan 25 14:34:53 mail amavis[244]: Found $altermime       at /usr/bin/altermime
Jan 25 14:34:53 mail amavis[244]: Internal decoder for .mail
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .Z    at /bin/uncompress
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .gz   at /bin/gzip -d
Jan 25 14:34:53 mail amavis[244]: Internal decoder for .gz   (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .bz2  at /bin/bzip2 -d
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .xz   at /usr/bin/xz -dc
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lzma at /usr/bin/xz -dc --format=lzma
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lrz  at /usr/bin/lrzip -q -k -d -o -
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lzo  at /usr/bin/lzop -d
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lz4  at /usr/bin/lz4c -d
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .rpm  at /usr/bin/rpm2cpio
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .cpio at /bin/pax
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .tar  at /bin/pax
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .deb  at /usr/bin/ar
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .rar  at /usr/bin/unrar-free
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .arj  at /usr/bin/arj
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .arc  at /usr/bin/nomarch
Jan 25 14:34:53 mail amavis[244]: No ext program for   .zoo, tried: zoo
Jan 25 14:34:53 mail amavis[244]: No ext program for   .doc, tried: ripole
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .cab  at /usr/bin/cabextract
Jan 25 14:34:53 mail amavis[244]: Internal decoder for .tnef
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .zip  at /usr/bin/7za
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .kmz  at /usr/bin/7za
Jan 25 14:34:53 mail amavis[244]: Internal decoder for .zip  (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Internal decoder for .kmz  (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .7z   at /usr/bin/7zr
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .gz   at /usr/bin/7za (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .bz2  at /usr/bin/7za (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .Z    at /usr/bin/7za (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .tar  at /usr/bin/7za (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .xz   at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lzma at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .jar  at /usr/bin/7z
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .cpio at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .arj  at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .rar  at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .swf  at /usr/bin/7z
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .lha  at /usr/bin/7z
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .iso  at /usr/bin/7z
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .cab  at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .deb  at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .rpm  at /usr/bin/7z (backup, not used)
Jan 25 14:34:53 mail amavis[244]: Found decoder for    .exe  at /usr/bin/unrar-free; /usr/bin/arj
Jan 25 14:34:53 mail amavis[244]: No decoder for       .F   
Jan 25 14:34:53 mail amavis[244]: No decoder for       .doc 
Jan 25 14:34:53 mail amavis[244]: No decoder for       .zoo 
Jan 25 14:34:53 mail amavis[244]: Deleting db files  in /var/lib/amavis/db
Jan 25 14:34:53 mail amavis[244]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.55, libdb 5.3
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): READY=1\nSTATUS=Initialization done.
Jan 25 14:34:53 mail amavis[244]: sd_notify (no socket): STATUS=Starting child process(es), ready for work.
Jan 25 14:34:56 mail postfix/master[879]: daemon started -- version 3.4.14, configuration /etc/postfix


Jan 25 14:35:06 mail postfix/master[879]: terminating on signal 15
Jan 25 14:35:06 mail dovecot: master: Warning: Killed with signal 15 (by pid=9 uid=0 code=kill)
Jan 25 14:35:07 mail dovecot: master: Dovecot v2.3.4.1 (f79e8e7e4) starting up for imap, lmtp
Jan 25 14:35:07 mail postfix/master[1642]: daemon started -- version 3.4.14, configuration /etc/postfix
Jan 25 14:35:12 mail postfix/master[1642]: terminating on signal 15
Jan 25 14:35:12 mail dovecot: master: Warning: Killed with signal 15 (by pid=9 uid=0 code=kill)
Jan 25 14:35:13 mail dovecot: master: Dovecot v2.3.4.1 (f79e8e7e4) starting up for imap, lmtp
Jan 25 14:35:13 mail postfix/master[2372]: daemon started -- version 3.4.14, configuration /etc/postfix
# END
```

</details>

Interestingly `postfix` did restart but without at least the wanted log entry: `"postfix: stopped"`

Could that be related to the changes to the logging system introduced with https://github.com/docker-mailserver/docker-mailserver/commit/324ee8eb85e0ab5e0ad810385ecdee2d42db6c7f (although the pipeline with that change went through!?)? @aendeavor Any idea on that?

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[BUG] Test 111 failing #1768

Bug Report

Context

What is affected by this bug?

When does this occur?

How do we replicate the issue?

Behavior

Actual Behavior

Expected Behavior

Your Environment

Environment Variables

Relevant Stack Traces

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Uh oh!

[BUG] Test 111 failing #1768

Description

Bug Report

Context

What is affected by this bug?

When does this occur?

How do we replicate the issue?

Behavior

Actual Behavior

Expected Behavior

Your Environment

Environment Variables

Relevant Stack Traces

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions