Mails Not Deleting in first POP3 Session

Mon Feb 9 23:19:44 UTC 2015

The dovecot -n output is attached to this email.  Filename dovecot-n_filtered.conf.
Dovecot Version: 2.2.10
OS: CentOS 6.6
MTA: Postfix version 2.6.6
The system is using dsync between two mailbox servers.
Problem:  When a pop3 session deletes a new message and the pop3 session ends, the message is not deleted.  On a subsequent pop3 session, the same messages is deleted again and when the session ends, this time the messages is removed.  This results in automated scripts getting duplicate messages.  Previous mail server utilized postfix and dbmail.  The problem did not exist.

All of our replication settings are located in the file /etc/dovecot/conf.d/12-replicator.conf.
When I move the above file out of /etc/dovecot/conf.d/ on both mailbox servers and restart dovecot, the pop3 deletion problem goes away and the system behaves as expected i.e. when a messages is deleted, it's removed when the session ends (of course its not replicated to the secondary server).

Numerous tests using IMAP and deleted messages behaved as expected.with or without replication
Here is some additional information that I hope helps:
Below I'm running watch 'pwd; ls -l; echo "../cur"; ls -l ../cur | tail -2'
On the primary mailbox server:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur | t...  Mon Feb  9 22:42:04 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.nasc
om.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,

On the backup mailbox server:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur...  Mon Feb  9 22:44:12 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.
nascom.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,

After I connect to the primary mailbox server using openssl s_client -connect mail1.example.com:995 tls1_2
user test_u
pass 123456

output below from the same watch command from above:
Primary
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur | t...  Mon Feb  9 22:47:50 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 0
../cur
-rw------- 1 vmail mail  3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.nasco
m.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.nasc
om.nasa.gov,S=46223,W=46902:2,

Secondary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur...  Mon Feb  9 22:48:14 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.
nascom.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,

So far,  on the primary, the new message is moved to the cur directory while on the backup the new messages is still in new.

I perform a list command to get the message I want to delete.  In this case the message number is 2402 so it looks like this...
list
.
.
.
2401
2402
dele 2402
+OK Marked to be deleted
quit
Here's the primary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur | t...  Mon Feb  9 22:53:16 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.nasc
om.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,

Here's the secondary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur...  Mon Feb  9 22:53:38 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423522362.M879542P21023.mbox-open-2.
nascom.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,

See we see the message on the primary is moved back to new while the message on the secindary has a name change.

Now for the second session (again using openssl):
+OK Dovecot ready.
user test_u
+OK
pass ---------------
+OK Logged in.

Here's the output on the primary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur | t...  Mon Feb  9 22:56:27 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 0
../cur
-rw------- 1 vmail mail  3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.nasco
m.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423521693.M193283P20903.mbox-open-1.nasc
om.nasa.gov,S=46223,W=46902:2,

Here's the output on the secondary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur...  Mon Feb  9 22:57:22 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 48
-rw------- 1 vmail mail 46223 Feb  9 22:41 1423522362.M879542P21023.mbox-open-2.
nascom.nasa.gov,S=46223,W=46902
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,

Now a list and delete...

list
.
.
.
2401
2402
dele 2402
+OK Marked to be deleted
quit

Here's the output of the primary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur | t...  Mon Feb  9 22:59:17 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 0
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.nascom
.nasa.gov,S=3269,W=3980:2,

Now the scondary:
Every 2.0s: pwd; ls -l; echo "../cur"; ls -l ../cur...  Mon Feb  9 22:59:37 2015

/home/vmail/nascom.nasa.gov/test_u/new
total 0
../cur
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191796.M570666P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,
-rw------- 1 vmail mail 3269 Nov 28 16:23 1417191797.M813970P7291.mbox-open-1.na
scom.nasa.gov,S=3269,W=3980:2,

The message is deleted now.

Multiple new messages that are all deleted in the same session behave the same way..  However, if the new messages aren't deleted in the first session, they move to the cur directory.  On a subsequent session, the messages can be deleted and they are removed.  The new messages remain in the new directory after the first session (as previously stated) on the secondary mailbox server until the dele.  So second session deletes appear to work fine

Any assistance would be greatly appreciated.

--Mike

-------------- next part --------------
A non-text attachment was scrubbed...
Name: dovecot-n_filtered.conf
Type: application/octet-stream
Size: 2935 bytes
Desc: dovecot-n_filtered.conf
URL: <http://dovecot.org/pipermail/dovecot/attachments/20150209/1564d825/attachment.obj>