search

mailcow / mailcow-dockerized

mailcow: dockerized - 🐮 + 🐋 = 💕
https://mailcow.email
GNU General Public License v3.0
8.94k stars 1.17k forks source link

After restore emails not showing up (resync fails) #2516

Closed MB-Jan closed 5 years ago

MB-Jan commented 5 years ago

Yesterday the MySQL database appeared to have crashed and I was unable to restore it. As I was having a lot of issues, I set up a new VPS and installed MailCow from scratch. I then used the restore script to restore everything from a backup when the database was still intact (last week) and only used the latest backup for restoring the vmail backup. Everything appeared to have worked fine until this point: Force a resync now? [y|N] y Error: userdb lookup: connect(/usr/local/var/run/dovecot/auth-userdb) failed: Connection refused doveadm: Error: Failed to iterate through some users

After this error the SOGo and MailCow appear to work fine. Except of one issue. Issue SOGo and other email clients do not show the imported emails. SOGo does however show the number of emails in the account below the email address, but only newly received emails are showing up. Here is a link to a screenshot: https://imgur.com/Yr4kDrC

What I tried to fix the issue

  1. Double-checked that mailcow.conf is identical to the configuration on the previous system.
  2. Followed this advice in another thread:

    Run inside the mailcow-dockerized folder docker-compose down, run systemctl stop dovecot followed by systemctl disable dovecot and restart the stack with docker-compose up -d (and did the same with Postfix)

  3. Checked the Dovecot Log: 
    WARNING: The WATCHDOG_NOTIFY_EMAIL variable is not set. Defaulting to a blank string.
Attaching to mailcowdockerized_dovecot-mailcow_1
dovecot-mailcow_1    | Waiting for database to come up...
dovecot-mailcow_1    | Waiting for database to come up...
dovecot-mailcow_1    | Waiting for database to come up...
dovecot-mailcow_1    | Uptime: 4  Threads: 9  Questions: 6  Slow queries: 0  Opens: 18  Flush tables: 1  Open tables: 12  Queries per second avg: 1.500
dovecot-mailcow_1    | Adding user `vmail' to group `tty' ...
dovecot-mailcow_1    | Adding user vmail to group tty
dovecot-mailcow_1    | Done.
dovecot-mailcow_1    |   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
dovecot-mailcow_1    |                                  Dload  Upload   Total   Spent    Left  Speed
100 97484  100 97484    0     0  59449      0  0:00:01  0:00:01 --:--:-- 59477
dovecot-mailcow_1    | 20_blatspammer.cf
dovecot-mailcow_1    | 70_HS_body.cf
dovecot-mailcow_1    | 70_HS_header.cf
dovecot-mailcow_1    | 2019-04-10 15:27:48,679 CRIT Set uid to user 0
dovecot-mailcow_1    | 2019-04-10 15:27:48,740 INFO supervisord started with pid 1
dovecot-mailcow_1    | 2019-04-10 15:27:49,755 INFO spawned: 'processes' with pid 97
dovecot-mailcow_1    | 2019-04-10 15:27:49,804 INFO spawned: 'cron' with pid 98
dovecot-mailcow_1    | 2019-04-10 15:27:49,856 INFO spawned: 'dovecot' with pid 99
dovecot-mailcow_1    | 2019-04-10 15:27:49,891 INFO spawned: 'syslog-ng' with pid 100
dovecot-mailcow_1    | Apr 10 15:27:50 service syslog-ng[100]: syslog-ng starting up; version='3.8.1'
dovecot-mailcow_1    | 2019-04-10 15:27:51,665 INFO success: processes entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-04-10 15:27:51,666 INFO success: cron entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-04-10 15:27:51,666 INFO success: dovecot entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | 2019-04-10 15:27:51,666 INFO success: syslog-ng entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
dovecot-mailcow_1    | Apr 10 15:27:56 service dovecot: imap(jan@mydomain.com)<115><skAeAiiGMr6sFgH4>: Logged out in=146 out=1780 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
dovecot-mailcow_1    | Apr 10 15:27:57 service dovecot: imap(jan@mydomain.com)<119><cn4tAiiGPL6sFgH4>: Logged out in=154 out=2141 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
dovecot-mailcow_1    | Apr 10 15:27:58 service dovecot: imap(jan@mydomain.com)<122><PTQ0AiiGRr6sFgH4>: Logged out in=818 out=151760 deleted=0 expunged=0 trashed=0 hdr_count=100 hdr_bytes=230 body_count=0 body_bytes=0
dovecot-mailcow_1    | Apr 10 15:27:58 service dovecot: imap(jan@mydomain.com)<125><03VHAiiGUL6sFgH4>: Logged out in=145 out=1762 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[128]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[127]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[130]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[129]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[127]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Apr 10 15:28:01 service CRON[128]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Apr 10 15:28:09 service dovecot: imap-login: Login: user=<jiraporn@mydomain.com>, method=PLAIN, rip=110.77.192.92, lip=172.22.1.250, mpid=143, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:01 service CRON[145]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Apr 10 15:29:01 service CRON[147]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Apr 10 15:29:01 service CRON[146]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Apr 10 15:29:01 service CRON[149]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Apr 10 15:29:02 service CRON[145]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service CRON[146]: pam_unix(cron:session): session closed for user root
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:02 service dovecot: imap-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=110.77.192.92, lip=172.22.1.250, TLS: Connection closed, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:03 service dovecot: imap-login: Login: user=<jan@mydomain.com>, method=PLAIN, rip=110.77.192.92, lip=172.22.1.250, mpid=174, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:03 service dovecot: imap-login: Login: user=<jan@mydomain.com>, method=PLAIN, rip=110.77.192.92, lip=172.22.1.250, mpid=176, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:03 service dovecot: imap-login: Login: user=<jan@mydomain.com>, method=PLAIN, rip=110.77.192.92, lip=172.22.1.250, mpid=178, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:29:03 service dovecot: imap-login: Login: user=<jan@mydomain.com>, method=PLAIN, rip=110.77.192.92, lip=172.22.1.250, mpid=180, TLS, TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
dovecot-mailcow_1    | Apr 10 15:30:02 service CRON[183]: pam_unix(cron:session): session opened for user root by (uid=0)
dovecot-mailcow_1    | Apr 10 15:30:02 service CRON[182]: pam_unix(cron:session): session opened for user vmail by (uid=0)
dovecot-mailcow_1    | Apr 10 15:30:04 service CRON[185]: (root) CMD ( /usr/local/bin/imapsync_cron.pl 2>&1 | /usr/bin/logger)
dovecot-mailcow_1    | Apr 10 15:30:04 service CRON[186]: (vmail) CMD (/usr/local/bin/trim_logs.sh >> /dev/console 2>&1)
dovecot-mailcow_1    | Apr 10 15:30:07 service CRON[182]: pam_unix(cron:session): session closed for user vmail
dovecot-mailcow_1    | Apr 10 15:30:08 service CRON[183]: pam_unix(cron:session): session closed for user root

    But it does not really help me.

For reference, here is the postfix log:

postfix-mailcow_1    | 2019-04-10 15:27:34,939 CRIT Set uid to user 0
postfix-mailcow_1    | 2019-04-10 15:27:34,964 INFO supervisord started with pid 1
postfix-mailcow_1    | 2019-04-10 15:27:35,974 INFO spawned: 'processes' with pid 8
postfix-mailcow_1    | 2019-04-10 15:27:35,983 INFO spawned: 'postfix' with pid 9
postfix-mailcow_1    | 2019-04-10 15:27:36,045 INFO spawned: 'syslog-ng' with pid 10
postfix-mailcow_1    | Apr 10 15:27:36 service syslog-ng[10]: syslog-ng starting up; version='3.13.2'
postfix-mailcow_1    | 2019-04-10 15:27:37,015 INFO success: processes entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | 2019-04-10 15:27:37,015 INFO success: postfix entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | 2019-04-10 15:27:37,015 INFO success: syslog-ng entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
postfix-mailcow_1    | Apr 10 15:27:42 service postfix[258]: Postfix is running with backwards-compatible default settings
postfix-mailcow_1    | Apr 10 15:27:42 service postfix[258]: See http://www.postfix.org/COMPATIBILITY_README.html for details
postfix-mailcow_1    | Apr 10 15:27:42 service postfix[258]: To disable backwards compatibility use "postconf compatibility_level=2" and "postfix reload"
postfix-mailcow_1    | Apr 10 15:27:43 service postfix/postfix-script[342]: starting the Postfix mail system
postfix-mailcow_1    | Apr 10 15:27:43 service postfix/master[344]: daemon started -- version 3.3.0, configuration /opt/postfix/conf
postfix-mailcow_1    | Apr 10 15:32:08 service postfix/postscreen[351]: cache proxy:btree:/var/lib/postfix/postscreen_cache full cleanup: retained=0 dropped=0 entries
postfix-mailcow_1    | Apr 10 15:32:08 service postfix/postscreen[351]: CONNECT from [209.85.166.68]:44511 to [172.22.1.7]:25
postfix-mailcow_1    | Apr 10 15:32:08 service postfix/postscreen[351]: WHITELISTED [209.85.166.68]:44511
postfix-mailcow_1    | Apr 10 15:32:10 service postfix/smtpd[354]: connect from mail-io1-f68.google.com[209.85.166.68]
postfix-mailcow_1    | Apr 10 15:32:11 service postfix/smtpd[354]: Anonymous TLS connection established from mail-io1-f68.google.com[209.85.166.68]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Apr 10 15:32:12 service postfix/smtpd[354]: 3B0DD419E8: client=mail-io1-f68.google.com[209.85.166.68]
postfix-mailcow_1    | Apr 10 15:32:12 service postfix/cleanup[359]: 3B0DD419E8: message-id=<CADjN1jzu+9WV_qzs+f86Rv8AxT46LiqZ0FtVdDP2-Tgnuh-AQQ@mail.gmail.com>
postfix-mailcow_1    | Apr 10 15:32:17 service postfix/qmgr[346]: 3B0DD419E8: from=<uniquetraining2016@gmail.com>, size=2815854, nrcpt=2 (queue active)
postfix-mailcow_1    | Apr 10 15:32:17 service postfix/smtpd[354]: disconnect from mail-io1-f68.google.com[209.85.166.68] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
postfix-mailcow_1    | Apr 10 15:32:18 service postfix/lmtp[360]: 3B0DD419E8: to=<jan@mydomain.com>, orig_to=<hr@mydomain.com>, relay=dovecot[fd4d:6169:6c63:6f77::4]:24, delay=6, delays=5.7/0.03/0.05/0.29, dsn=2.0.0, status=sent (250 2.0.0 <jan@mydomain.com> MOYSLQGcrVzoAAAAbUpgNw Saved)
postfix-mailcow_1    | Apr 10 15:32:18 service postfix/lmtp[360]: 3B0DD419E8: to=<penny@mydomain.com>, orig_to=<hr@mydomain.com>, relay=dovecot[fd4d:6169:6c63:6f77::4]:24, delay=6, delays=5.7/0.03/0.05/0.29, dsn=2.0.0, status=sent (250 2.0.0 <penny@mydomain.com> MOYSLQGcrVzoAAAAbUpgNw:2 Saved)
postfix-mailcow_1    | Apr 10 15:32:18 service postfix/qmgr[346]: 3B0DD419E8: removed
postfix-mailcow_1    | Apr 10 15:33:41 service postfix/postscreen[351]: CONNECT from [204.62.115.54]:7073 to [172.22.1.7]:25
postfix-mailcow_1    | Apr 10 15:33:41 service whitelist_forwardinghosts: Look up 204.62.115.54 on whitelist, result 200 DUNNO
postfix-mailcow_1    | Apr 10 15:33:42 service postfix/dnsblog[372]: addr 204.62.115.54 listed by domain hostkarma.junkemailfilter.com as 127.0.0.1
postfix-mailcow_1    | Apr 10 15:33:42 service postfix/dnsblog[372]: addr 204.62.115.54 listed by domain hostkarma.junkemailfilter.com as 127.0.1.1
postfix-mailcow_1    | Apr 10 15:33:44 service postfix/postscreen[351]: PASS NEW [204.62.115.54]:7073
postfix-mailcow_1    | Apr 10 15:33:45 service postfix/smtpd[354]: connect from mail-relay-104.3.basecamp.com[204.62.115.54]
postfix-mailcow_1    | Apr 10 15:33:46 service postfix/smtpd[354]: Anonymous TLS connection established from mail-relay-104.3.basecamp.com[204.62.115.54]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
postfix-mailcow_1    | Apr 10 15:33:47 service postfix/smtpd[354]: 316D541445: client=mail-relay-104.3.basecamp.com[204.62.115.54]
postfix-mailcow_1    | Apr 10 15:33:47 service postfix/cleanup[359]: 316D541445: message-id=<comments/1721263256@3.basecamp.com>

If there is another way to import the old emails from the backup it maybe works as a workaround. Please let me know if I can provide anything else to solve the issue.

Thank you very much for your help!

MB-Jan commented 5 years ago

This issue can be closed. It turned out that it just took time until all emails were synced up in SOGo.

pierre-le commented 5 years ago

Hi @MB-Jan,

I've been in quite the same situation as you, and I've also set up a new instance from scratch and restored data from a previous backup. However, it's been hours since the restore process has completed, and I'm still not seeing any mail in my inbox...

Did you have to wait for that much time?

andryyy commented 5 years ago

Did you restore the mail_crypt key?

pierre-le commented 5 years ago

@andryyy Actually I used the backup_and_restore.sh restore script and restored each item in order, so that would include the Crypt data. Is that what you meant?

deba10106 commented 1 year ago

I'm facing the same issue. Could someone help? used backup_and_restore.sh restore all command to restore....