Jesús Ángel del Pozo Domínguez
2021-Aug-04 13:15 UTC
Problem migrating POP accounts into dovecot
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 expungesAug 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>
> On 04/08/2021 16:15 Jes?s ?ngel del Pozo Dom?nguez <jesusangel.delpozo at gmail.com> wrote: > > > 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.Is it possible to migrate the POP3 accounts over IMAP, and use https://doc.dovecot.org/settings/plugin/pop3-migration-plugin/? Aki