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@testemail.domain.com pop3c:
And these are some interesting lines from the output of the above command:
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Looking up IP address Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Connecting to 10.0.0.104:110 Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Authenticating as 'test2@testemail.domain.com' (with USER+PASS) Aug 04 14:54:14 dsync(test2@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@testemail.domain.com): Debug: Mailbox INBOX: UID 1: Opened mail because: virtual size (Cache file is unusable) Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: quota: quota_over_flag check: STORAGE ret=3value=3 limit=104857600 Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: quota: quota_over_flag check: MESSAGE ret=4value=1 limit=0 Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: quota: quota_over_flag=0((null)) vs currently overquota=0 Aug 04 14:54:14 dsync(test2@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@testemail.domain.com): Debug: brain S: Namespace has location pop3c:
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Looking up IP address Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Connecting to 10.0.0.104:110 Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Authenticating as 'test2@testemail.domain.com' (with USER+PASS) Aug 04 14:54:14 dsync(test2@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@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@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@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@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@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@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@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@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@testemail.domain.com): Debug:
pop3c(10.0.0.104): Looking up IP address
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug:
pop3c(10.0.0.104): Connecting to 10.0.0.104:110
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug:
pop3c(10.0.0.104): Authenticating as 'test2@testemail.domain.com'
(with USER+PASS)
Aug 04 14:54:14 dsync(test2@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@testemail.domain.com): Debug:
doveadm-sieve: Iterating Sieve mailbox attributes
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: sieve:
Pigeonhole version 0.5.15 (e6a84e31) initializing
Aug 04 14:54:14 dsync(test2@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@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@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@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@testemail.domain.com): Debug: sieve: file
storage: Using permissions from defaults: mode=0700 gid=-1
Aug 04 14:54:14 dsync(test2@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@testemail.domain.com): Debug: sieve: file
storage: Relative path to sieve storage in active link: sieve/
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: sieve: file
storage: sync: Synchronization active
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: brain M:
Import INBOX: Last common UID=0. Delayed expunges=
Aug 04 14:54:14 dsync(test2@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@testemail.domain.com): Debug: Mailbox
INBOX: UID 1: Opened mail because: mail stream
Aug 04 14:54:14 dsync(test2@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@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@testemail.domain.com): Debug: Mailbox
POP3-MIGRATION-NS/INBOX: Mailbox opened because: pop3_migration
Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Looking up IP address Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Connecting to 10.0.0.104:110 Aug 04 14:54:14 dsync(test2@testemail.domain.com): Debug: pop3c(10.0.0.104): Authenticating as 'test2@testemail.domain.com' (with USER+PASS) Aug 04 14:54:22 dsync(test2@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@testemail.domain.com' with mysql; uid 30018, gid 8
Aug 4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[6]test2@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@testemail.domain.com(10.0.0.105):
closed connection
Aug 4 14:54:14 lmail1 tpop3d[2270]: authcontext_delete: finished
session for test2@testemail.domain.com' with mysql Aug 4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began session for test2@testemail.domain.com' with mysql; uid 30018, gid 8
Aug 4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[5]test2@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@testemail.domain.com(10.0.0.105):
closed connection
Aug 4 14:54:14 lmail1 tpop3d[2272]: authcontext_delete: finished
session for test2@testemail.domain.com' with mysql Aug 4 14:54:14 lmail1 tpop3d[1887]: authcontext_new_user_pass: began session for test2@testemail.domain.com' with mysql; uid 30018, gid 8
Aug 4 14:54:14 lmail1 tpop3d[1887]: fork_child:
[5]test2@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@testemail.domain.com' with mysql; uid 30018, gid 8 Aug 4 14:54:14 lmail1 tpop3d[1887]: fork_child: [5]test2@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@testemail.domain.com' with mysql
Aug 4 14:54:22 lmail1 tpop3d[2273]: connections_post_select:
connection_read: client [5]test2@testemail.domain.com(10.0.0.105):
closed connection
Aug 4 14:54:22 lmail1 tpop3d[2273]: authcontext_delete: finished
session for `test2@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,