Problem migrating POP accounts into dovecot

Wed Aug 4 16:15:48 EEST 2021

Hello,

I am trying to migrate mailboxes from an old pop/imap server to a new one
using Dovecot 2.3.15. The old server uses tpop3d and courier as POP and
IMAP servers, respectively.

Whereas I can migrate IMAP mailboxes without many problems, I am facing
difficulties while trying to do the same with POP ones. The problem is that
dsync opens simultaneous connections to the remote POP server, so the
remote mailbox gets locked and dsync can not copy the messages.

This is the command I am using to migrate POP mailboxes:

# doveadm -Dv -c dovecot-migration.conf -o pop3c_password="*******" backup
-R -u test2 at testemail.domain.com pop3c:

And these are some interesting lines from the output of the above command:

Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Looking up IP address
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Connecting to 10.0.0.104:110
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Authenticating as 'test2 at testemail.domain.com'
(with USER+PASS)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: Adding field pop3.uidl to cache for the first time (uid=1)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: UID 1: Opened mail because: virtual size (Cache file is
unusable)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: quota:
quota_over_flag check: STORAGE ret=3value=3 limit=104857600
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: quota:
quota_over_flag check: MESSAGE ret=4value=1 limit=0
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: quota:
quota_over_flag=0((null)) vs currently overquota=0
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain M:
Locking done locally in
/var/mail/testemail.domain.com/test2/.dovecot-sync.lock (local
hostname=tremedal.domain.com, remote hostname=tremedal.domain.com)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain S:
Namespace  has location pop3c:

Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Looking up IP address
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Connecting to 10.0.0.104:110
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Authenticating as 'test2 at testemail.domain.com'
(with USER+PASS)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: Adding field pop3.uidl to cache for the first time (uid=1)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain S:
Local mailbox tree: INBOX guid=c92f64f79f0d1ed01e6d5b314f04886c
uid_validity=1628081654 uid_next=2 subs=no last_change=0 last_subs=0
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain M:
Remote mailbox tree: INBOX guid=c92f64f79f0d1ed01e6d5b314f04886c
uid_validity=1628081654 uid_next=2 subs=no last_change=0 last_subs=0
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain M:
Mailbox INBOX: local=00000000000000000000000000000000/0/0,
remote=c92f64f79f0d1ed01e6d5b314f04886c/0/1: mailbox not selectable
yet
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Namespace :
/var/mail/testemail.domain.com/test2/Mailbox/inbox doesn't exist yet,
using default permissions
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Namespace :
Using permissions from /var/mail/testemail.domain.com/test2/Mailbox:
mode=0700 gid=default
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Namespace :
/var/mail/testemail.domain.com/test2/Mailbox/inbox doesn't exist yet,
using default permissions
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Namespace :
Using permissions from /var/mail/testemail.domain.com/test2/Mailbox:
mode=0700 gid=default
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain S:
Mailbox INBOX: local=c92f64f79f0d1ed01e6d5b314f04886c/0/1,
remote=00000000000000000000000000000000/0/0: mailbox not selectable
yet

Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Looking up IP address
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Connecting to 10.0.0.104:110
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Authenticating as 'test2 at testemail.domain.com'
(with USER+PASS)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: Adding field pop3.uidl to cache for the first time (uid=1)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
doveadm-sieve: Iterating Sieve mailbox attributes
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve:
Pigeonhole version 0.5.15 (e6a84e31) initializing
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve:
include: sieve_global is not set; it is currently not possible to
include `:global' scripts.
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Storage path `/var/mail/testemail.domain.com/test2/sieve' not
found
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Using active Sieve script path:
/var/mail/testemail.domain.com/test2/.dovecot.sieve
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Using script storage path:
/var/mail/testemail.domain.com/test2/sieve
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Using permissions from defaults: mode=0700 gid=-1
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Created storage directory
/var/mail/testemail.domain.com/test2/sieve/tmp
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: Relative path to sieve storage in active link: sieve/
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: sieve: file
storage: sync: Synchronization active
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain M:
Import INBOX: Last common UID=0. Delayed expunges=
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: brain M:
Import INBOX: Import change type=save
GUID=1a82a18794d50d5de2b3f0faa8a6e27c UID=1 hdr_hash= result=Mail's
UID is above local UIDNEXT - No more local mails found
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: UID 1: Opened mail because: mail stream
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: Adding field size.virtual to cache for the first time (uid=1)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
INBOX: Adding field size.physical to cache for the first time (uid=1)
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug: Mailbox
POP3-MIGRATION-NS/INBOX: Mailbox opened because: pop3_migration

Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Looking up IP address
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Connecting to 10.0.0.104:110
Aug 04 14:54:14 dsync(test2 at testemail.domain.com): Debug:
pop3c(10.0.0.104): Authenticating as 'test2 at testemail.domain.com'
(with USER+PASS)
Aug 04 14:54:22 dsync(test2 at testemail.domain.com): Error:
pop3_migration: Couldn't sync mailbox POP3-MIGRATION-NS/INBOX: Unable
to open mailbox; it may be locked by another concurrent session.

In the remote server I get these lines from the tpop3d log:

Aug  4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began
session for `test2 at testemail.domain.com' with mysql; uid 30018, gid 8

Aug  4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[6]test2 at testemail.domain.com(10.0.0.105): successfully authenticated
with mysql
Aug  4 14:54:14 lmail1 tpop3d[2270]: mailspool_new_from_file: indexed
mailspool /var/spool/mail/testemail.domain.com/test2 (2831 bytes) in
0.000s
Aug  4 14:54:14 lmail1 tpop3d[2270]: connections_post_select:
connection_read: client [6]test2 at testemail.domain.com(10.0.0.105):
closed connection
Aug  4 14:54:14 lmail1 tpop3d[2270]: authcontext_delete: finished
session for `test2 at testemail.domain.com' with mysql
Aug  4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began
session for `test2 at testemail.domain.com' with mysql; uid 30018, gid 8
Aug  4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[5]test2 at testemail.domain.com(10.0.0.105): successfully authenticated
with mysql
Aug  4 14:54:14 lmail1 tpop3d[2272]: mailspool_new_from_file: indexed
mailspool /var/spool/mail/testemail.domain.com/test2 (2831 bytes) in
0.000s
Aug  4 14:54:14 lmail1 tpop3d[2272]: connections_post_select:
connection_read: client [5]test2 at testemail.domain.com(10.0.0.105):
closed connection
Aug  4 14:54:14 lmail1 tpop3d[2272]: authcontext_delete: finished
session for `test2 at testemail.domain.com' with mysql
Aug  4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began
session for `test2 at testemail.domain.com' with mysql; uid 30018, gid 8
Aug  4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[5]test2 at testemail.domain.com(10.0.0.105): successfully authenticated
with mysql
Aug  4 14:54:14 lmail1 tpop3d[2273]: mailspool_new_from_file: indexed
mailspool /var/spool/mail/testemail.domain.com/test2 (2831 bytes) in
0.000s
Aug  4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began
session for `test2 at testemail.domain.com' with mysql; uid 30018, gid 8
Aug  4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[5]test2 at testemail.domain.com(10.0.0.105): successfully authenticated
with mysql
Aug  4 14:54:22 lmail1 tpop3d[2274]: mailspool_new_from_file: failed
to lock /var/spool/mail/testemail.domain.com/test2: Resource
temporarily unavailable
Aug  4 14:54:22 lmail1 tpop3d[2274]:
dotfile_unlock(/var/spool/mail/testemail.domain.com/test2): lockfile
does not have our PID
Aug  4 14:54:22 lmail1 tpop3d[2274]: authcontext_delete: finished
session for `test2 at testemail.domain.com' with mysql
Aug  4 14:54:22 lmail1 tpop3d[2273]: connections_post_select:
connection_read: client [5]test2 at testemail.domain.com(10.0.0.105):
closed connection
Aug  4 14:54:22 lmail1 tpop3d[2273]: authcontext_delete: finished
session for `test2 at testemail.domain.com' with mysql

As you can see, in the first five lines the first connection from dsync is
opened and closed. Then, the same sequence is repeated again (second
connection from dsync). However, on opening the third connection, it is not
closed before the fourth one is opened. On authenticating a user, the
tpop3d server locks the mailbox to prevent other clients wirting to it.
That is why the fourth connection fails as it can not get a lock for the
mailbox:

Aug  4 14:54:22 lmail1 tpop3d[2274]: mailspool_new_from_file: failed
to lock /var/spool/mail/testemail.domain.com/test2: Resource
temporarily unavailable
Aug  4 14:54:22 lmail1 tpop3d[2274]:
dotfile_unlock(/var/spool/mail/testemail.domain.com/test2): lockfile
does not have our PID

Could you please tell me how can I avoid this problem? I wonder why dsync
opens so many connections to the remote server, and why it does not close
the previous connections before opening new ones.

Regards,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20210804/c450df1e/attachment-0001.html>