With cce33f8, I improved check-for-changes.sh a bit. I know this is not actually related to the log, but I figured the change was small enough (around 10 lines in check-for-changes.sh) to fit in here. I hope you don't mind it :) The commit as a whole does more than that (i.e. adjusting some log levels, formatting, etc.).

@polarathene I need your help:

The test mail_ssl_letsencrypt.bats does not work. The last call of _acme_wildcard in the test ssl(letsencrypt): Traefik 'acme.json' (*.example.test) does not succeed, because the message /etc/letsencrypt/acme.json' has changed - extracting certifcates now is not logged. I spent more than an hour trying to debug this. To me, it seems as if I found a false positive (in the past, we were viewing too much log ???).

This is the current log of _acme_wildcard:

[   INF   ]  (CHANGEDETECTOR) 2022-03-17 13:47:28 Change detected
[  TRACE  ]  Creating lock /tmp/docker-mailserver/check-for-changes.sh.lock
[  TRACE  ]  Checking file line endings
[  TRACE  ]  Regenerating postfix user list
[  DEBUG  ]  Creating user 'user1' for domain 'localhost.localdomain'
[  DEBUG  ]  Creating user 'user2' for domain 'otherdomain.tld'
[  DEBUG  ]  Creating user 'user3' for domain 'localhost.localdomain' with attributes 'userdb_mail=mbox:~/mail:INBOX=~/inbox'
[  DEBUG  ]  Adding alias '[email protected]' for user '[email protected]' to Dovecot's userdb
[  DEBUG  ]  Alias '[email protected]' is non-local (or mapped to a non-existing account) and will not be added to Dovecot's userdb
[  DEBUG  ]  Adding alias '@localdomain2.com' for user '[email protected]' to Dovecot's userdb
[  TRACE  ]  Adding regexp alias file postfix-regexp.cf
virtual_alias_maps = texthash:/etc/postfix/virtual pcre:/etc/postfix/regexp
[  TRACE  ]  Configuring root alias
[  DEBUG  ]  (CHANGEDETECTOR) 2022-03-17 13:47:28 Restarting services due to detected changes
postfix: stopped
postfix: started
dovecot: stopped
dovecot: started
[  TRACE  ]  Removed lock /tmp/docker-mailserver/check-for-changes.sh.lock
[  TRACE  ]  (CHANGEDETECTOR) 2022-03-17 13:47:31 Completed handling of detected change

This is the log of the call to _acme_rsa before:

[   INF   ]  (CHANGEDETECTOR) 2022-03-17 13:47:20 Change detected
[  TRACE  ]  Creating lock /tmp/docker-mailserver/check-for-changes.sh.lock
[  DEBUG  ]  (CHANGEDETECTOR) 2022-03-17 13:47:20 '/etc/letsencrypt/acme.json' has changed - extracting certifcates now
[  TRACE  ]  (CHANGEDETECTOR) 2022-03-17 13:47:20 Attempting to extract for '*.example.test'
[  TRACE  ]  _extract_certs_from_acme | Certificate successfully extracted for 'example.test'
[  TRACE  ]  Checking file line endings
[  TRACE  ]  Regenerating postfix user list
[  DEBUG  ]  Creating user 'user1' for domain 'localhost.localdomain'
[  DEBUG  ]  Creating user 'user2' for domain 'otherdomain.tld'
[  DEBUG  ]  Creating user 'user3' for domain 'localhost.localdomain' with attributes 'userdb_mail=mbox:~/mail:INBOX=~/inbox'
[  DEBUG  ]  Adding alias '[email protected]' for user '[email protected]' to Dovecot's userdb
[  DEBUG  ]  Alias '[email protected]' is non-local (or mapped to a non-existing account) and will not be added to Dovecot's userdb
[  DEBUG  ]  Adding alias '@localdomain2.com' for user '[email protected]' to Dovecot's userdb
[  TRACE  ]  Adding regexp alias file postfix-regexp.cf
virtual_alias_maps = texthash:/etc/postfix/virtual pcre:/etc/postfix/regexp
[  TRACE  ]  Configuring root alias
[  DEBUG  ]  (CHANGEDETECTOR) 2022-03-17 13:47:20 Restarting services due to detected changes
postfix: stopped
postfix: started
dovecot: stopped
dovecot: started
[  TRACE  ]  Removed lock /tmp/docker-mailserver/check-for-changes.sh.lock
[  TRACE  ]  (CHANGEDETECTOR) 2022-03-17 13:47:26 Completed handling of detected change

In the latter, the line '/etc/letsencrypt/acme.json' has changed - extracting certifcates now is properly shown. But I cannot for the life of me find out why this line is not shown in the former...

@polarathene indeed, the log of the changedetector on master for this test looks like this:

[[ TASKS ]]  2022-03-17 16:11:22 Start check-for-changes script.
[[  INF  ]]  2022-03-17 16:11:22 Using postmaster address [email protected]
[[  INF  ]]  2022-03-17 16:11:32 check-for-changes is ready
[[  INF  ]]  2022-03-17 16:11:36 Change detected
[[  INF  ]]  '/etc/letsencrypt/acme.json' has changed, extracting certs..
[[  INF  ]]  Attempting to extract for '*.example.test'
[ WARNING ]  _extract_certs_from_acme | Unable to find key and/or cert for '*.example.test' in '/etc/letsencrypt/acme.json'
[[  INF  ]]  Attempting to extract for 'mail.example.test'
[[  INF  ]]  _extract_certs_from_acme | Certificate successfully extracted for 'mail.example.test'
[[  INF  ]]  Checking file line endings
[[  INF  ]]  Regenerating postfix user list
[[  INF  ]]  Creating user 'user1' for domain 'localhost.localdomain'
[[  INF  ]]  Creating user 'user2' for domain 'otherdomain.tld'
[[  INF  ]]  Creating user 'user3' for domain 'localhost.localdomain' with attributes 'userdb_mail=mbox:~/mail:INBOX=~/inbox'
[[  INF  ]]  Adding regexp alias file postfix-regexp.cf
virtual_alias_maps = texthash:/etc/postfix/virtual pcre:/etc/postfix/regexp
[[  INF  ]]  Configuring root alias
[[  INF  ]]  Restarting services due to detected changes..
postfix: stopped
postfix: started
dovecot: stopped
dovecot: started
[[  INF  ]]  Removed lock /tmp/docker-mailserver/check-for-changes.sh.lock.
[[  INF  ]]  2022-03-17 16:11:44 Completed handling of detected change
[[  INF  ]]  2022-03-17 16:11:48 Change detected
[[  INF  ]]  '/etc/letsencrypt/acme.json' has changed, extracting certs..
[[  INF  ]]  Attempting to extract for '*.example.test'
[[  INF  ]]  _extract_certs_from_acme | Certificate successfully extracted for 'example.test'
[[  INF  ]]  Checking file line endings
[[  INF  ]]  Regenerating postfix user list
[[  INF  ]]  Creating user 'user1' for domain 'localhost.localdomain'
[[  INF  ]]  Creating user 'user2' for domain 'otherdomain.tld'
[[  INF  ]]  Creating user 'user3' for domain 'localhost.localdomain' with attributes 'userdb_mail=mbox:~/mail:INBOX=~/inbox'
[[  INF  ]]  Adding regexp alias file postfix-regexp.cf
virtual_alias_maps = texthash:/etc/postfix/virtual pcre:/etc/postfix/regexp
[[  INF  ]]  Configuring root alias
[[  INF  ]]  Restarting services due to detected changes..
postfix: stopped
postfix: started
dovecot: stopped
dovecot: started
[[  INF  ]]  Removed lock /tmp/docker-mailserver/check-for-changes.sh.lock.
[[  INF  ]]  2022-03-17 16:11:53 Completed handling of detected change

and there is a third '/etc/letsencrypt/acme.json' has changed, extracting certs.. somehow missing. It could be that there are only 2, which would indicate that actually all is well but we're not looking at enough log?? Are there overall only 2 changes with this test? Have I misunderstood it the whole time?

EDIT: Something odd is happening here. On master, only two changes are detected. On this branch (update/log), three changes are detected...

I spent more than an hour trying to debug this. To me, it seems as if I found a false positive (in the past, we were viewing too much log ???).

If we were viewing too much log, then the test should still fail, it explicitly looks for the FQDN arg the function is called with:

And after that test, I also added another to count duplicate log output for expected number of restarts by this point. Perhaps not exactly foolproof but should be reasonably reliable:

Detailed breakdown if helpful

Full flow

and there is a third '/etc/letsencrypt/acme.json' has changed, extracting certs.. somehow missing. It could be that there are only 2, which would indicate that actually all is well but we're not looking at enough log?? Are there overall only 2 changes with this test? Have I misunderstood it the whole time?

• _acme_ecdsa(): Only cares that certs were extracted at startup.
• _acme_rsa(): Certs have changed, should be detected and extracted to mail.example.test cert dir.
• _acme_wildcard(): Same as before, but this time the first check for wildcard is successful and has priority, this is not a *.example.test dir, but example.test dir (which may seem a bit odd but was to avoid *. as part of the directory name).

Priority is due to the SSL_DOMAIN=*.example.test ENV specified early in the test as additional container args/ENV beyond the defaults:

Priority logic in change detection for acme.json:

That should be calling the extract certs helper:

which should log a success or failure.. but there is two || exit 1 lines at the end there which would not log and go undetected.. I did not introduce that logic for those two lines, it was pre-existing before me. I recall briefly discussing it with casper in a review that it probably should get addressed at some point I think..?

The directory is created in advance however, and we return early with warning logged if KEY or CERT is empty. I'm not sure why that would fail to trigger || exit?

I assume there is nothing wrong with calling the python script since that is working at an earlier stage in the tests. There was a recent change to use an explicit .py extension, otherwise acme_extract.py works like so:

1. Given a filepath to acme.json (rsa example and ecdsa wildcard example) parse it and iterate through the top-level keys looking for the Certificates key:

   docker-mailserver/target/bin/acme_extract.py

   Lines 22 to 27 in 321ae74

   	def retrieve_data():
   	with open(args.filepath) as json_file:
   	acme_data = json.load(json_file)
   	for key, value in acme_data.items():
   	try:
   	certs = value['Certificates'] or []

2. The Certificates field contains an array of objects, each a certificate. Check each one for a domain field, it has the subfields main and sans, these days sans should contain the FQDN, we check that it has the FQDN we requested via args:

   docker-mailserver/target/bin/acme_extract.py

   Lines 28 to 30 in 321ae74

   	for cert in certs:
   	if has_fqdn(cert['domain'], args.fqdn):
   	return cert[args.requested]

   docker-mailserver/target/bin/acme_extract.py

   Lines 15 to 18 in 321ae74

   	def has_fqdn(domains, fqdn):
   	main = domains.get('main', '')
   	sans = domains.get('sans', [])
   	return main == fqdn or fqdn in sans

3. In the event of a failure, we return None which will print as an empty string (which will be caught/logged by the ssl helper function _extract_certs_from_acme):

   docker-mailserver/target/bin/acme_extract.py

   Lines 31 to 39 in 321ae74

   	# One of the expected keys is missing.. return an empty result
   	# Certificates: [{domain: [main, sans], key, certificate}]
   	except KeyError:
   	return None
   	# No match == 'None', we convert to empty string for
   	# existing error handling:
   	result = retrieve_data() or ''
   	print(result)

Actual flow issue

So that whole flow seems sound AFAIK. The issue with _acme_wildcard() in your current PR error logs detects a change but doesn't log anything about attempting to extract or that acme.json changed.. Referencing check-for-changes.sh master:

As we don't reach that 2nd step, what may have occurred is in _acme_rsa() this logic ran which would be intentional, but somehow prevented change detection of acme.json on the following _acme_wildcard() test:

Actually, it looks like the first | is being escaped here, but not the 2nd, I'm not sure if that's valid or not, I've probably mentioned it in the relevant PR or commit in that PR (maybe PR merge commit message):

That doesn't explain why acme.json was not part of the detected change however. Could be a timing issue with insufficient sleep? When are you retrieving the logs you shared? If that's not in sync with when the test attempts to match, you could be right that the PR tests are reading and matching old logs, change-detection for the acme.json file may occur after that.

One possible factor contributing to the observed behaviour

If file locking logic has anything to do with it, I will reference these findings I made late last year. I'd like to highlight the collapsed details block there "Switch back to flock", which points out:

The intent of locking files in the first place - flock locked the configs being interacted with, while the replacement applied locks to individual scripts instead, thus locks only blocked a specific script from being concurrently called, but not concurrent access to the actual config files being modified which was the original intent with flock being introduced.

It's possible that is part of the problem, along with sleeps and the changes to log output size affecting timing? I would look into the checksum file changes, as that should reveal more about what change is detected for _acme_wildcard() if it's not the acme.json update..

If resolving proves difficult:

I would offer to investigate this further myself, but it would presently be inconvenient. I'd be happy to try allocate some time later this month for it if needed.

Feel free to workaround or disable the test to merge this PR, then open an issue about this problem and assign me to it.

Houston, we have a problem

The Problem

So, after long and painful hours of debugging, I found some problems that are currently present with check-for-changes.sh. After I was unable to figure out why my log PR #2486 fails, I had enough and added the following lines to the script to look at the changes myself:

_changedetector_notify 'warn' 'DEBUG START'
echo -e "\nchanged: ${CHANGED}\n"
echo -e "\nnew: $(<${CHKSUM_FILE}.new)\n"
echo -e "\nold: $(<${CHKSUM_FILE})\n"
_changedetector_notify 'warn' 'DEBUG END'

For context: the current logs only show two changes being being detected in the mail_ssl_letsencrypt.bats test, while with #2486, three changes are detected... To my surprise, the last change looked like this:

changed:


new: d6825c549a553df95e3830b6a3ec3f161f320b2a600b4f1fd63540920ad33fd6b587dbdf8359ccb35dd1a17c9fd14c17f113954f73da8f19bcf83f1649fd757a  /tmp/docker-mailserver/postfix-accounts.cf
37d1a2f5cb4f99c81463b05b366f27f3877d10e83685fec1ec1f38aabf60e2d28bc32a7d4b810e66739b37912f9dd9d1424145b93c7e5969120d345c05c8f74c  /tmp/docker-mailserver/postfix-virtual.cf
cf83e1357eefb8bdf1542850d66d8007d620e4050b5715dc83f4a921d36ce9ce47d0d13c5d85f2b0ff8318d2877eec2f63b931bd47417a81a538327af927da3e  /tmp/docker-mailserver/postfix-aliases.cf
cf83e1357eefb8bdf1542850d66d8007d620e4050b5715dc83f4a921d36ce9ce47d0d13c5d85f2b0ff8318d2877eec2f63b931bd47417a81a538327af927da3e  /tmp/docker-mailserver/dovecot-quotas.cf
a0eafaf897cb7c793244fe71de32120d7b22897ffe20e5f9f295251e992104c48148e3103187a61c7d92ad773d1e00889d4790038ca4326b414439dfbd90045e  /etc/letsencrypt/acme.json
5f79d61f94f365052e7c079d1ea5d3ac8810e6e5c028d8b22b12d80f3ceeffc0c8182a4bace90cea265d357fc73bb3518214cb54247a7945152d6dbd94d23a31  /etc/letsencrypt/live/mail.example.test/fullchain.pem
4fd75dc009e4499cd72e12ace6f348bfd904ac4e816aa2a13200ec2749a0e9b86f362407bc35c945f7cd667b3da5449de771ed96d0ae6f7cb24c8f82fcd3d3b6  /etc/letsencrypt/live/mail.example.test/key.pem


old: d6825c549a553df95e3830b6a3ec3f161f320b2a600b4f1fd63540920ad33fd6b587dbdf8359ccb35dd1a17c9fd14c17f113954f73da8f19bcf83f1649fd757a  /tmp/docker-mailserver/postfix-accounts.cf
37d1a2f5cb4f99c81463b05b366f27f3877d10e83685fec1ec1f38aabf60e2d28bc32a7d4b810e66739b37912f9dd9d1424145b93c7e5969120d345c05c8f74c  /tmp/docker-mailserver/postfix-virtual.cf
cf83e1357eefb8bdf1542850d66d8007d620e4050b5715dc83f4a921d36ce9ce47d0d13c5d85f2b0ff8318d2877eec2f63b931bd47417a81a538327af927da3e  /tmp/docker-mailserver/postfix-aliases.cf
cf83e1357eefb8bdf1542850d66d8007d620e4050b5715dc83f4a921d36ce9ce47d0d13c5d85f2b0ff8318d2877eec2f63b931bd47417a81a538327af927da3e  /tmp/docker-mailserver/dovecot-quotas.cf
a0eafaf897cb7c793244fe71de32120d7b22897ffe20e5f9f295251e992104c48148e3103187a61c7d92ad773d1e00889d4790038ca4326b414439dfbd90045e  /etc/letsencrypt/acme.json
5f79d61f94f365052e7c079d1ea5d3ac8810e6e5c028d8b22b12d80f3ceeffc0c8182a4bace90cea265d357fc73bb3518214cb54247a7945152d6dbd94d23a31  /etc/letsencrypt/live/mail.example.test/fullchain.pem
4fd75dc009e4499cd72e12ace6f348bfd904ac4e816aa2a13200ec2749a0e9b86f362407bc35c945f7cd667b3da5449de771ed96d0ae6f7cb24c8f82fcd3d3b6  /etc/letsencrypt/live/mail.example.test/key.pem
f8911bc63794d532e2af7e24f71a92dea5fbef8a3f4da5249a13285fd715c958cdd265eea82721dbc5f9921613916d2b2cf21bf2012a1d6abae2a5a76c1e6faa  /etc/letsencrypt/live/example.test/fullchain.pem
760241712a2d96a6cbfe166c9fa063458c57ba869a8caf5bed1add6547f5445e1e890320f262ff04c60ecd757da15cbfc006547c5f0717af994a08edff20009b  /etc/letsencrypt/live/example.test/key.pem

After doing a manual cmp, the result was:

$ cmp old new
cmp: EOF on old after byte 1207, line 7
$ echo $?
1
$ diff old new
7a8,9
> f8911bc63794d532e2af7e24f71a92dea5fbef8a3f4da5249a13285fd715c958cdd265eea82721dbc5f9921613916d2b2cf21bf2012a1d6abae2a5a76c1e6faa  /etc/letsencrypt/live/example.test/fullchain.pem
> 760241712a2d96a6cbfe166c9fa063458c57ba869a8caf5bed1add6547f5445e1e890320f262ff04c60ecd757da15cbfc006547c5f0717af994a08edff20009b  /etc/letsencrypt/live/example.test/key.pem

So, there are two additional lines in the diff now.

f8911bc63794d532e2af7e24f71a92dea5fbef8a3f4da5249a13285fd715c958cdd265eea82721dbc5f9921613916d2b2cf21bf2012a1d6abae2a5a76c1e6faa  /etc/letsencrypt/live/example.test/fullchain.pem
760241712a2d96a6cbfe166c9fa063458c57ba869a8caf5bed1add6547f5445e1e890320f262ff04c60ecd757da15cbfc006547c5f0717af994a08edff20009b  /etc/letsencrypt/live/example.test/key.pem

Adding an ls -lhA /etc/letsencrypt/live/** to the script yields

/etc/letsencrypt/live/example.test:
total 8.0K
-rw-r--r-- 1 root root 1.2K Mar 18 09:28 fullchain.pem
-rw-r--r-- 1 root root 1.7K Mar 18 09:28 key.pem

/etc/letsencrypt/live/mail.example.test:
total 8.0K
-rw-r--r-- 1 root root 1.3K Mar 18 09:27 fullchain.pem
-rw-r--r-- 1 root root 1.7K Mar 18 09:27 key.pem

Summing up: the additional files are picked by the changedetector-run and cmp (which actually is correct behaviour, if you ask me). I don't know why this would not be the case on the master branch... The wildcard certificate does not use the mail. prefix for example.test, therefore the new files in example.test without the mail. prefix exist. The old files not cleaned up? This causes an additional run for the changedetector.

The Solution

I adjusted the tests to query an appropriate amount of log. This "solves" the issue, but in the future, a better solution could / should be found (the log should be queried in a more intelligent way). This is however not related to this PR.

@polarathene now I need your help again again (with a test failure that may actually be an expected and therefore correct failure):

Line 171 says "WARNING: This should fail...but requires resolving the above TODO. ". Or is he warning for the line below?

Documentation preview for this PR is ready! 🎉

Built with commit: 28c4842

I don't know why this would not be the case on the master branch... The wildcard certificate does not use the mail. prefix for example.test, therefore the new files in example.test without the mail. prefix exist. The old files not cleaned up? This causes an additional run for the changedetector.

You don't think this is related to more earlier investigation notes above? This is in particular:

As we don't reach that 2nd step, what may have occurred is in _acme_rsa() this logic ran which would be intentional, but somehow prevented change detection of acme.json on the following _acme_wildcard() test:

docker-mailserver/target/scripts/check-for-changes.sh

Lines 100 to 111 in 321ae74

	_notify 'inf' "Attempting to extract for '${CERT_DOMAIN}'"
	if _extract_certs_from_acme "${CERT_DOMAIN}"
	then
	# Prevent an unnecessary change detection from the newly extracted cert files by updating their hashes in advance:
	CERT_DOMAIN=$(_strip_wildcard_prefix "${CERT_DOMAIN}")
	ACME_CERT_DIR="/etc/letsencrypt/live/${CERT_DOMAIN}"
	sed -i "\|${ACME_CERT_DIR}|d" "${CHKSUM_FILE}.new"
	sha512sum "${ACME_CERT_DIR}"/*.pem >> "${CHKSUM_FILE}.new"
	break

Actually, it looks like the first | is being escaped here, but not the 2nd, I'm not sure if that's valid or not, I've probably mentioned it in the relevant PR or commit in that PR (maybe PR merge commit message):

docker-mailserver/target/scripts/check-for-changes.sh

Line 108 in 321ae74

sed -i "\|${ACME_CERT_DIR}|d" "${CHKSUM_FILE}.new"

I have not verified the sed concern, but if it's not correctly removing the lines to prevent an unnecessary change detection, then that explains why you're getting a change detection event regarding new cert files, instead of for acme.json which should be the relevant change to react to in the test - not changes that happened as a result of the cert extraction in _acme_rsa() prior, or after example.test wildcard (if that change was detected and handled, but this logic resulted in an additional change after).

I'd also have to give it some thought if that logic is testing with *.example.test or example.test, it looks like CERT_DOMAIN is originally *.example.test and then if the strip method works correctly, it should be adjusted to example.test for the remaining logic.

You say master has 2 change detections logged, and then share the third additional change log that this PR caught due to log verbosity changes.. does this mean that the first two are the correct acme.json changes as expected? And the third is an accidental event with the example.test wildcard cert files triggering detection? The failure in the letsencrypt test is now present because that 2nd change event for acme.json success with the wildcard cert got the log bumped out of the retrieved lines, with only the third change event logs that shouldn't have occurred?

Line 171 says "WARNING: This should fail...but requires resolving the above TODO. ". Or is he warning for the line below?

This should be fine to enable now (but probably best deferred to a separate PR).

It's referencing line 163 which would also be enabled along with it, and the TODO comment above it. They needed the change detection event to run the ssl startup script again to update the filepaths to the correct letsencrypt directory (changed from mail.example.test to example.test).

It's an edge case, most users won't be changing to/from a wildcard cert on a running instance I imagine, this test will ensure we catch it though if someone refactors check-for-changes.sh thinking it wasn't necessary.

Test failure:

not ok 92 ssl(letsencrypt): Traefik 'acme.json' (*.example.test) in 41322ms
# (from function `assert_output' in file test/test_helper/bats-assert/src/assert.bash, line 231,
#  from function `_negotiate_tls' in file test/test_helper/tls.bash, line 53,
#  from function `_should_succesfully_negotiate_tls' in file test/test_helper/tls.bash, line 30,
#  from function `_acme_wildcard' in file test/mail_ssl_letsencrypt.bats, line 174,
#  in test file test/mail_ssl_letsencrypt.bats, line 193)
#   `_acme_wildcard' failed
# mail.example.test is up and running
# [  TRACE  ]  (CHANGEDETECTOR) 2022-03-18 19:30:13 Changedetector is ready
# 
# -- output does not contain substring --
# substring : Verification: OK
# output    : 
# --
# 

This is the last part of the test case for _acme_wildcard(), where it calls a TLS helper method:

which is saying it should match the *.example.test registered in the cert:

Not the mail.example.test cert used in _acme_rsa() previously, which is valid for both mail.example.test and example.test:

These methods are only used in the wildcard, to ensure that mail.example.test resolves to the wildcard cert. The previous used cert covers both mail.example.test and example.test FQDN explicitly. AFAIK, *.example.test will be compatible with any subdomain used, but not example.test itself.

Here is the relevant part of the ssl helper function where failure is happening:

All certs used in the acme.json test cases are using an RSA CA root cert:

Given the changes in this PR, chances are that undesired third change event is restarting Postfix while trying to make the connection perhaps..

Failure will likely be resolved by preventing the unexpected change event from happening. Related check-for-changes.sh logic needs to be fixed which should prevent this happening.

In the meantime, introducing a reasonable sleep as a workaround would probably work.

Stay focused, refrain from extras that can wait

I want to see this PR merged, please stop adding additions not related to the feedback. This is already deviating again from the core focus that resulted in it being extracted to a separate PR.

If you feel comments could be refactored/added, unless specifically about the new log functionality being introduced, hold off on that. Create a branch and pile them up there for you to follow up with.

This PR is a good improvement, but becoming a bit frustrating to review when changes that could be deferred to another PR are thrown in (and then reverted after review when I state not to unless requested by other reviewers, sometimes with residue errors).

Under no circumstances, take the initiative to clean up this PR with a force-pushed interactive-rebase (it's unlikely, but I want to communicate that clearly).

If you feel a need to do such, wait until ready to merge, so that all feedback and discussion is resolved first, then diffing the prior state to the reworked commits won't be as much effort.

Personally, since we squash commits on merge, and this PR history is already not pleasant to wade through for traceability to a future maintainer, I rather we not complicate it further and discourage altering PR history this way.

I'm sorry, I tried to follow your advice and only added what I deemed necessary for tests run. I don't know how to proceed with this PR without annoying anyone even further - I have therefore come to the conclusion that I will close this and provide smaller updates from time to time, which should be easier to review and easier to test.

I am very sorry to have wasted your time, but I think we nevertheless got some insights - and if it's only about ditching supervisor.

I don't know how to proceed with this PR without annoying anyone even further - I have therefore come to the conclusion that I will close this and provide smaller updates from time to time, which should be easier to review and easier to test.

It's only really been me providing reviews each morning I woke up. It was getting a bit overwhelming with all the changes going on, I was checking the individual commits for diffs, reading the commit messages and referencing the master version and full diff for certain files like check-for-changes.sh.

I could have communicated a bit better, or delayed review until I got a morning coffee 😅 I know sometimes my communication can come off a bit blunt and harsh, while I don't often comment on all the good changes the PR brought and my appreciation for how responsive you have been to my feedback, there was plenty of that unsaid :)

I am very sorry to have wasted your time, but I think we nevertheless got some insights - and if it's only about ditching supervisor.

I don't think you wasted my time. I chose to review regularly and invest the time that I did to provide as thorough review as I could because I value the changes you've put together here and I think you've invested a fair amount more of your time putting all this together.

I hope you do see it through, in whatever form that is, I'll continue to be happy to review it. Reviews work both ways, I can only be a better reviewer with your feedback when I overstep or get too pushy/fussy.

If you don't have the time to keep working on this, I can understand that too. I'm happy to piecemeal it through several PRs like I've done in the past with another maintainers large PR. It looks like a lot of thought went into it, it'd be a shame to lose it.

Just adding my 2 cents^^. PRs should be as simple as possible (just doing/introducing/fixing at best only one thing). In question, some should provide multiple PRs instead of one. This makes reviewing so much easier and faster.

There were so much discussion/changes/splitting in this PR, I was not able to keep track at some point. Then my "strategy" changed to wait until this has been calm down and then try to review it 😆

An approach for bigger PRs could also be, to open an issue and discuss the planed changes beforehand (if necessary/worth). I feel sometimes guilty, if someone took a lot of time to prepare something, for starting a general discussion about it. But just because it was a lot of work, doesn't automatically mean it's a good addition or that it can't be done better/simpler.