SSL Connection gets disconneded

maedball

Hiho,
i have a problem with the SSL connection. Z-Push is connecting fine to the Dovecot Mailserver but after a few seconds it gets disconnected. In outlook this ends than in a login window which i can just confirm with ok. After that it works for another 2 minutes until i get the same error message again.

Maybe someone has another idea ;-)

Z-Push Log

29/09/2021 20:22:47 [ 1446] [WARN] [michael.klein] /usr/share/z-push/backend/imap/imap.php:2377 imap_open(): Couldn't open stream {mailserver:993/imap/ssl/novalidate-cert} (2)
29/09/2021 20:22:47 [ 1446] [WARN] [michael.klein] /usr/share/z-push/backend/imap/imap.php:2810 imap_getmailboxes() expects parameter 1 to be resource, bool given (2)
29/09/2021 20:22:47 [ 1446] [WARN] [michael.klein] Unknown:0 Unknown: Can not authenticate to IMAP server: [CLOSED] IMAP connection broken (authenticate) (errflg=2) (8)
2

NGINX Config snip

	location /Microsoft-Server-ActiveSync {
                alias       /usr/share/z-push/index.php;

        	access_log  /var/log/nginx/z-push/access.log;
	        error_log   /var/log/nginx/z-push/error.log;

                include         fastcgi_params;
                fastcgi_index   index.php;
    
                fastcgi_param   SCRIPT_FILENAME $document_root$fastcgi_script_name;
                fastcgi_param   REQUEST_URI $1;
                fastcgi_param   PHP_FLAG "magic_quotes_gpc=off \n register_globals=off \n magic_quotes_runtime=off \n short_open_tag=on";
                fastcgi_param   PHP_VALUE "post_max_size=20M \n upload_max_filesize=20M \n max_execution_time=3660";
                fastcgi_param   HTTP_PROXY ""; # Mitigate https://httpoxy.org/ vulnerabilities
                fastcgi_read_timeout 3660; # Z-Push Ping might run 3600s, but to be safe
		
		# Attachments ca 15MB max (since binary data needs to be base64 encoded in mine, which results in in about 33% overhead)
        	client_max_body_size 20m;
        	client_body_buffer_size 128k;
		
		include snippets/z-push-php.conf;
	}
	
	location /AutoDiscover/AutoDiscover.xml {
		include snippets/z-push-autodiscover.conf;
		include snippets/z-push-php.conf;
	}
    
	location /Autodiscover/Autodiscover.xml {
		include snippets/z-push-autodiscover.conf;
		include snippets/z-push-php.conf;
	}
    
	location /autodiscover/autodiscover.xml {
		include snippets/z-push-autodiscover.conf;
		include snippets/z-push-php.conf;
    	}

bob4os

Did you change anything with session timeout in the dovecot config?
Can you export your dovecot settings with “dovecot -n” and post them here?

You are not proxying IMAP through NGINX, are you?

If you are comfortable with changing some code, you could change the function imap_reconnect() in /usr/share/z-push/backend/imap/imap.php to try again, if the connection fails, as there is currently no retry and no check if the reconnect succeeds.

Something like:

private function imap_reconnect() {
	if ($this->mbox) {
		if(imap_ping($this->mbox)) {
			return;
		}
	}

	for ($i = 0; $i < IMAP_CONNECTION_RETRY_LIMIT; $i++) {
		$this->mbox = @imap_open($this->server, $this->username, $this->password, OP_HALFOPEN, 0, $this->imapParams);
		if(imap_ping($this->mbox)) {
			$this->mboxFolder = "";
			return;
		}
		else {
			sleep(IMAP_CONNECTION_RETRY_DELAY);
		}
	}
	ZLog::Write(LOGLEVEL_ERROR, sprintf("BackendIMAP->Logon(): can't connect as user '%s' on '%s': %s", $username, $this->server, imap_last_error()));

	// TODO throw the matching exception
}

and define both constants in /usr/share/z-push/backend/imap/config.php:

// IMAP connection retry limit
define('IMAP_CONNECTION_RETRY_LIMIT', 3);

// IMAP connection retry delay in seconds
define('IMAP_CONNECTION_RETRY_DELAY', 1);

maedball

@bob4os said in SSL Connection gets disconneded:

dovecot -n

Here is the config
Just to note: mail_max_userip_connections = 100 was done as a test, but did not fix the issue
IMAP is not proxied

# 2.3.7.2 (3c910f64b): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.7.2 ()
# OS: Linux 5.4.0-88-generic x86_64 Ubuntu 20.04.3 LTS
auth_username_format = %Ln
first_valid_uid = 32
imap_idle_notify_interval = 29 mins
info_log_path = /var/log/dovecot.log
mail_location = mdbox:~/mdbox
mail_privileged_group = mail
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character vacati                                                                                   on subaddress comparator-i;ascii-numeric relational regex imap4flags copy includ                                                                                   e variables body enotify environment mailbox date index ihave duplicate mime for                                                                                   everypart extracttext imapsieve vnd.dovecot.imapsieve
namespace inbox {
  inbox = yes
  location =
  mailbox Drafts {
    auto = subscribe
    special_use = \Drafts
  }
  mailbox Junk-E-Mail {
    auto = subscribe
    special_use = \Junk
  }
  mailbox Junk {
    auto = subscribe
    special_use = \Junk
  }
  mailbox Sent {
    auto = subscribe
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    auto = subscribe
    special_use = \Trash
  }
  prefix =
  separator = /
}
passdb {
  driver = pam
}
plugin {
  imapsieve_mailbox1_before = file:/var/mail/sieve/learn-spam.sieve
  imapsieve_mailbox1_causes = COPY
  imapsieve_mailbox1_name = Junk
  imapsieve_mailbox2_before = file:/var/mail/sieve/learn-ham.sieve
  imapsieve_mailbox2_causes = COPY
  imapsieve_mailbox2_from = Junk
  imapsieve_mailbox2_name = *
  sieve = file:/var/mail/sieve/%d/%n/scripts;active=/var/mail/sieve/%d/%n/active                                                                                   -script.sieve
  sieve_before = /var/mail/sieve/spam-global.sieve
  sieve_global_extensions = +vnd.dovecot.pipe
  sieve_pipe_bin_dir = /usr/bin
  sieve_plugins = sieve_imapsieve sieve_extprograms
}
protocols = " imap lmtp sieve pop3 sieve"
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0666
    user = postfix
  }
}
service imap-login {
  inet_listener imap {
    port = 143
  }
  inet_listener imaps {
    port = 993
  }
}
service lmtp {
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    mode = 0600
    user = postfix
  }
}
service managesieve-login {
  inet_listener sieve {
    port = 4190
  }
}
ssl = required
ssl_cert = </etc/letsencrypt/live/mailserver/fullchain.pem
ssl_cipher_list = ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDH                                                                                   E-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1                                                                                   305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA                                                                                   384
ssl_client_ca_dir = /etc/ssl/certs
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
ssl_min_protocol = TLSv1.2
userdb {
  driver = passwd
}
protocol lmtp {
  mail_plugins = " quota  sieve notify push_notification"
  postmaster_address = postmaster@mailserver
}
protocol imap {
  mail_max_userip_connections = 100
  mail_plugins = " quota imap_quota imap_sieve"
}

After the code change the issue still occurs. (on the other side it still works) ;-)

bob4os

How many clients do you have?
Some clients like Thunderbird use multiple simultaneous connections.
Are you reaching the client_limit or process_limit?

maedball

@bob4os In total 4. My guess is that this has nothing todo with any limits. The clients are reconnecting regularly around once per minute to dovecot.

Thunderbird or outlook just connect fine via IMAP.

This is what i found in dovecot, but it just looks like a normal timout due to no activity.

nfo: Connection closed (No commands sent) in=0 out=400 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0

maedball

Or this one as it always happens right before the disconnect

 /usr/share/z-push/backend/imap/imap.php:2382 imap_ping() expects parameter 1 to be resource, bool given (2)

thctlo

@maedball said in SSL Connection gets disconneded:

imap_ping

i suggest report it as bug.
Thats a good find.

bob4os

imap_ping() is only performing a check, if the resource “$this->mbox” is still connected.
Your error message

 /usr/share/z-push/backend/imap/imap.php:2382 imap_ping() expects parameter 1 to be resource, bool given (2)

indicates that things went south already.

Z-Push’s IMAP backend tries to reconnect before performing IMAP actions, so this is to be expected.

Clients usually send an “IDLE” command, which keeps the IMAP connection alive and the server is sending pings back to the clients, checking if the client is still active.
The PHP IMAP extension does not support “IDLE” as far as I know -> we have to reconnect…

bob4os

@maedball I just noticed “imap_idle_notify_interval = 29 mins” in your config - this is a really long time.
Every client that sends an “IDLE” command will have to wait 29 minutes, before Dovecot sends a ping if the client is still there - that is a really long time.
I suggest you set it back to default - there is no reason to wait that long.

telecom2k3

@maedball Make sure the SSL Cert is OK. Just thinking of the LetsEncrypt CA Cert expiration Friday. Maybe PHP needs an updated openssl.cafile? Got nothing else, sorry.

maedball

@telecom2k3 said in SSL Connection gets disconneded:

openssl.cafile

What i am struggling with, is that it is working (so all mails get synced, still the log is full of errors + outlook throws a password request which can be simply confirmed with the ok button)

Is there any logging which i can enable to do some further investigation?

boospy

I have the same problem here, but only with the Kopano Enterprise Updateservers.

maedball

I have opened a ticket: In addition i took a bath in the massive log and found this, not sure if this adds some clues:

04/10/2021 00:40:29 [ 1418] [DEBUG] [michael.klein] [7usfm7ugbd1tb3toklq5c8k3e8] BackendCombined->ChangesSink(30)
04/10/2021 00:40:29 [ 1418] [DEBUG] [michael.klein] [7usfm7ugbd1tb3toklq5c8k3e8] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 10
04/10/2021 00:40:29 [ 1418] [DEBUG] [michael.klein] [7usfm7ugbd1tb3toklq5c8k3e8] BackendIMAP->close_connection(): disconnected from IMAP server

bob4os

No, “Calling in BackendIMAP with 10” is just a message indicating that you are using the combined backend and the BackendIMAP is supposed to take at least 10s to return a result.
And close_connection() is used in the ChangesSink() function to reduce concurrent connections to your IMAP server.

I have no idea of what is going on in your setup…

bob4os

What is your hardware?

maedball

@bob4os : First again thank you for all the efforts you are putting in helping!:

Processor information: Intel® Xeon® W-1270P CPU @ 3.80GHz, 16 cores
Real memory: 62.64 GiB total
Operating system: Ubuntu Linux 20.04.3
Local disk space: Local disk space

bob4os

Well, this hardware should be more than sufficient.

maedball

Another day, another log search.

Once i use a non SSL connection to the Mailserver i get some more log errors from z-push.

Mainly 3 different error messages on first sync

06/10/2021 21:40:35 [87856] [WARN] [daliane.klein] /usr/share/z-push/include/mimeDecode.php:352 Undefined offset: 1 (8)

06/10/2021 21:40:35 [87856] [WARN] [daliane.klein] /usr/share/z-push/backend/imap/imap.php:1449 Undefined offset: 0 (8)

06/10/2021 21:41:01 [2160847] [WARN] [daliane.klein] /usr/share/z-push/backend/caldav/caldav.php:841 A non-numeric value encountered (2)

the obvious error message that this is now a plain connection even thou it is going via localhost ;-)

06/10/2021 21:40:28 [2213332] [WARN] [daliane.klein] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8)

Sometimes i see the following

06/10/2021 21:47:56 [197748] [ERROR] [daliane.klein] ImportChangesCombined->Config() icc not configured

06/10/2021 21:47:56 [197748] [WARN] [daliane.klein] /usr/share/z-push/lib/default/diffbackend/diffstate.php:230 count(): Parameter must be an array or an object that implements Countable (2)

06/10/2021 21:47:58 [ 1416] [WARN] [daliane.klein] /usr/share/z-push/backend/imap/imap.php:1128 implode(): Invalid arguments passed (2)
06
06/10/2021 22:04:05 [2773723] [FATAL] [daliane.klein] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command

06/10/2021 22:26:38 [3924469] [ERROR] [michael.klein] TimezoneUtil::guessTZNameFromPHPName() no compatible timezone found for 'UTC+01:00'. Returning 'GMT Standard Time'. Please contact the Z-Push dev team.

bob4os

mimeDecode.php:352 hints to a message which has an “multipart/signed” part, but there seems to be an issue with the handling - I have seen this before, but it has not been relevant for me.
imap.php:1449 is a result of the error above.
caldav.php:841 replace the line with:

$message->reminder = $interval->format("%i") + $interval->format("%h") * 60 + $interval->format("%d") * 60 * 24;

(There is a fix in the PR for ZP-1571 but it has not been merged yet.)

“icc not configured” and diffstate.php:230 might be the result of renaming a folder, this is not implemented. I tried implementing this, but I still have some issues with the devices states.

imap.php:1128 there is a check missing, I will try to get a PR through…
I have to look into the timezone error message…

maedball

@bob4os As usual, thanks for your help already. The fix -> fixed the issue ;-).

I think my main issue is the issue related to the multipart /signed (sounds like SMIME to me). I just did a full sync and found several thousand error messages related to this.