Debian Bug report logs - #1000195
dovecot-core: Job for dovecot.service failed because the control process exited with error code (after dist-upgrade)

Full log

Message #9 received at [email protected] (full text, mbox, reply):

Received: (at 1000191) by bugs.debian.org; 19 Nov 2021 17:46:32 +0000
From [email protected] Fri Nov 19 17:46:32 2021
X-Spam-Checker-Version: SpamAssassin 3.4.2-bugs.debian.org_2005_01_02
	(2018-09-13) on buxtehude.debian.org
X-Spam-Level: 
X-Spam-Status: No, score=-16.2 required=4.0 tests=BAYES_00,DIGITS_LETTERS,
	DKIM_SIGNED,DKIM_VALID,DKIM_VALID_EF,FOURLA,FROMDEVELOPER,
	HAS_BUG_NUMBER,HEADER_FROM_DIFFERENT_DOMAINS,JOBS,SHIP_ID_INT,
	SPF_HELO_NONE,SPF_PASS,TXREP autolearn=ham autolearn_force=no
	version=3.4.2-bugs.debian.org_2005_01_02
X-Spam-Bayes: score:0.0000 Tokens: new, 56; hammy, 150; neutral, 268; spammy,
	0. spammytokens: hammytokens:0.000-+--systemctl, 0.000-+--distupgrade,
	0.000-+--dfsg12, 0.000-+--dist-upgrade, 0.000-+--UD:socket
Return-path: <[email protected]>
Received: from minas.morgul.net ([2603:400a:ffff:bb8::801f:30]:33794)
	by buxtehude.debian.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256)
	(Exim 4.92)
	(envelope-from <[email protected]>)
	id 1mo7y3-0000Jv-9c
	for [email protected]; Fri, 19 Nov 2021 17:46:32 +0000
DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=morgul.net;
	s=20210611; h=In-Reply-To:Content-Transfer-Encoding:Content-Type:MIME-Version
	:References:Message-ID:Subject:To:From:Date:Sender:Reply-To:Cc:Content-ID:
	Content-Description:Resent-Date:Resent-From:Resent-Sender:Resent-To:Resent-Cc
	:Resent-Message-ID:List-Id:List-Help:List-Unsubscribe:List-Subscribe:
	List-Post:List-Owner:List-Archive;
	bh=zY0q+ZyRFkRGMxiBWVznYV6zQXMKWIWSlVrg1ZMqIxg=; b=MgIxq84XizRYFHlASD2QTEw5uz
	yJQH8Mpj2ULnaEJCO/vEX7LJ3vyDmJbW08hAk+PIOjSzm5cMGCm+AAPk1tq9MdbIG5SLqI7qGYQLF
	aX/iknL0hNbROjBopkGJuWVSNTrbZPtEhWSW/smgFK3ZUbE9QU6PehZjvxB4AwwHV/KWSRVeX/32R
	dmJABQQVwU2DdeuVPDl3YAjqIZmzydxYxb6S14kaniHHn4rZpygOiNqAICugzyVySKEbcjahkM0xE
	SuwTFMLYYmZDLc6KMyB8CgD8tbzKE+aAz8mMOONrsT1Id0Tt1coAFHkpHOeWG4ZZ6dfwc0/8BfadI
	UKHig2dQ==;
Received: from [2601:602:9400:9b61::ec1] (helo=doom)
	by minas.morgul.net with esmtpsa  (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
	(Exim 4.94.2)
	(envelope-from <[email protected]>)
	id 1mo7xz-008br5-1q; Fri, 19 Nov 2021 12:46:27 -0500
Received: from noahm by doom with local (Exim 4.94.2)
	(envelope-from <[email protected]>)
	id 1mo7xw-0001s1-EC; Fri, 19 Nov 2021 09:46:24 -0800
Date: Fri, 19 Nov 2021 09:46:24 -0800
From: Noah Meyerhans <[email protected]>
To: Michael Hatzold <[email protected]>, [email protected]
Subject: Re: Bug#1000191: dovecot-core: Job for dovecot.service failed
 because the control process exited with error code (after dist-upgrade)
Message-ID: <[email protected]>
References: <163732650921.94166.5611604054664478720.reportbug@localhost>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <163732650921.94166.5611604054664478720.reportbug@localhost>

Control: tags -1 + moreinfo

On Fri, Nov 19, 2021 at 01:55:09PM +0100, Michael Hatzold wrote:
> 
>    * What led up to the situation?
> apt dist-upgrade
>    * What exactly did you do (or not do) that was effective (or
>      ineffective)?
> apt dist-upgrade
>    * What was the outcome of this action?
> distupgrade went through, but when restaring the necceccary systemd.services
> all went wel except fpr dovecot.service.
> This is a long-standing bug. imap wont work after dist-upgrade unless you
> reboot  or you manually execute:

I am not able to reproduce this on an upgrade from a basic bullseye
installation to bookworm.  Prior to the upgrade I have:

admin@ip-10-0-0-111:~$ systemctl status dovecot.service
● dovecot.service - Dovecot IMAP/POP3 email server
     Loaded: loaded (/lib/systemd/system/dovecot.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2021-11-19 17:20:00 UTC; 1min 12s ago
       Docs: man:dovecot(1)
             http://wiki2.dovecot.org/
   Main PID: 593 (dovecot)
      Tasks: 4 (limit: 4444)
     Memory: 5.0M
        CPU: 32ms
     CGroup: /system.slice/dovecot.service
             ├─593 /usr/sbin/dovecot -F
             ├─606 dovecot/anvil
             ├─607 dovecot/log
             └─609 dovecot/config

Nov 19 17:20:00 ip-10-0-0-111 systemd[1]: Starting Dovecot IMAP/POP3 email server...
Nov 19 17:20:00 ip-10-0-0-111 dovecot[593]: master: Dovecot v2.3.13 (89f716dc2) starting up for imap (core dumps disabled)
Nov 19 17:20:00 ip-10-0-0-111 systemd[1]: Started Dovecot IMAP/POP3 email server.
admin@ip-10-0-0-111:~$ dpkg -l | grep dovecot
ii  dovecot-core                     1:2.3.13+dfsg1-2               amd64        secure POP3/IMAP server - core files
ii  dovecot-imapd                    1:2.3.13+dfsg1-2               amd64        secure POP3/IMAP server - IMAP daemon
ii  dovecot-sieve                    1:2.3.13+dfsg1-2               amd64        secure POP3/IMAP server - Sieve filters support

admin@ip-10-0-0-111:~$ sudo sed -i 's,bullseye,bookworm,' /etc/apt/sources.list
admin@ip-10-0-0-111:~$ sudo apt update
admin@ip-10-0-0-111:~$ sudo apt -y dist-upgrade
...
Setting up dovecot-core (1:2.3.16+dfsg1-3) ...
Replacing config file /etc/dovecot/dovecot.conf with new version
Replacing config file /etc/dovecot/dovecot-dict-sql.conf.ext with new version
Replacing config file /etc/dovecot/conf.d/10-logging.conf with new version
Replacing config file /etc/dovecot/conf.d/10-ssl.conf with new version
dovecot.socket is a disabled or a static unit not running, not starting it.
...
Setting up dovecot-imapd (1:2.3.16+dfsg1-3) ...
...
Setting up dovecot-sieve (1:2.3.16+dfsg1-3) ...
...
Processing triggers for dovecot-core (1:2.3.16+dfsg1-3) ...

During this process, I had an IMAP (mutt) client connected, and it
received a disconnect due to the server shutting down for restart during
the trigger processing.  After that the client was able to reconnect
with no additional work on the server to make this possible.

systemctl on the server showed the following after the upgrade and
client reconnect:

admin@ip-10-0-0-111:~$ systemctl status dovecot.service
● dovecot.service - Dovecot IMAP/POP3 email server
     Loaded: loaded (/lib/systemd/system/dovecot.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2021-11-19 17:27:03 UTC; 5min ago
       Docs: man:dovecot(1)
             https://doc.dovecot.org/
   Main PID: 24660 (dovecot)
     Status: "v2.3.16 (7e2e900c1a) running"
      Tasks: 7 (limit: 4444)
     Memory: 5.3M
        CPU: 43ms
     CGroup: /system.slice/dovecot.service
             ├─24660 /usr/sbin/dovecot -F
             ├─24661 dovecot/anvil
             ├─24662 dovecot/log
             ├─24663 dovecot/config
             ├─24667 dovecot/imap-login
             ├─24668 dovecot/stats
             └─24670 dovecot/imap

Nov 19 17:27:03 ip-10-0-0-111 systemd[1]: Starting Dovecot IMAP/POP3 email server...
Nov 19 17:27:03 ip-10-0-0-111 dovecot[24660]: master: Dovecot v2.3.16 (7e2e900c1a) starting up for imap (core dumps disabled)
Nov 19 17:27:03 ip-10-0-0-111 systemd[1]: Started Dovecot IMAP/POP3 email server.
Nov 19 17:27:35 ip-10-0-0-111 dovecot[24662]: imap-login: Login: user=<admin>, method=PLAIN, rip=73.140.205.249, lip=10.0.0.> 
> # journalctl -xeu dovecot.service
> ░░ Subject: Resources consumed by unit runtime
> ░░ Defined-By: systemd
> ░░ Support: https://www.debian.org/support
> ░░
> ░░ The unit dovecot.service completed and consumed the indicated resources.
> Nov 15 01:15:31 neutower systemd[1]: Starting Dovecot IMAP/POP3 email server...
> ░░ Subject: A start job for unit dovecot.service has begun execution
> ░░ Defined-By: systemd
> ░░ Support: https://www.debian.org/support
> ░░
> ░░ A start job for unit dovecot.service has begun execution.
> ░░
> ░░ The job identifier is 4759.
> Nov 15 01:15:31 neutower dovecot[162036]: Error: bind(192.168.2.13, 143)
> failed: Cannot assign requested address
> Nov 15 01:15:31 neutower dovecot[162036]: Error: service(imap-login):
> listen(192.168.2.13, 143) failed: Cannot assign request>
> Nov 15 01:15:31 neutower dovecot[162036]: master: Error: bind(192.168.2.13,
> 143) failed: Cannot assign requested address
> Nov 15 01:15:31 neutower dovecot[162036]: master: Error: service(imap-login):
> listen(192.168.2.13, 143) failed: Cannot assign>
> Nov 15 01:15:31 neutower dovecot[162036]: master: Fatal: Failed to start
> listeners
> Nov 15 01:15:31 neutower dovecot[162036]: Fatal: Failed to start listeners
> Nov 15 01:15:31 neutower systemd[1]: dovecot.service: Main process exited,
> code=exited, status=89/n/a
> ░░ Subject: Unit process exited

This indicates that we did try to restart dovecot on your system, but
that it didn't start because something else was bound to port 143.  It
would be interesting to know what that is.  Wsa it the old dovecot
process that didn't shut down for some reason?  Was it systemd? (Can you
show the output of `systemctl status dovecot.socket`?)

Those logs only show what happened when dovecot tried to start. It would
be interesting to see earlier logs corresponding with dovecot attempting
to shut down during the 'restart' operation.

Does `systemctl restart dovecot.service` work for you generally (outside
the context of an apt operation)?

noah

Send a report that this bug log contains spam.