You are viewing a plain text version of this content. The canonical link for it is here.
Posted to server-user@james.apache.org by Nathan Cheng <na...@yahoo.com> on 2006/03/27 03:58:43 UTC
smtp hung and took 10 hours to start back up again
Hi all,
My last problem (with emails getting delivered multiple times) seemed
to have resolved itself (for the most part) after adjusting db
connection and smtp/pop connection limits.
But now I'd like help addressing a different problem, one that we've
had for a while--even before the previous problem--but it doesn't seem
to happen all the time--only on some days. Today was one of those days.
This morning we got a call from our data center that smtp was not
responding. I logged in, and found the "connection" log growing at
about 10mb per 5 minutes with this complaint:
"WARN connections: Maximum number of open connections exceeded -
refusing connection. Current number of connections is 40"
This would be fine, believable--ok, I've got too much incoming smtp
traffic--except for the fact that when this warning prints, it also
prints all 40 supposedly active connections--and they are the SAME 40
connections over and over again. I.e. James is stuck on the same 40
connections and won't get over the fact that it's out of connections
and get on with its life.
I tried to restart, and james came online for a few seconds ("smtp"
log was normal for a few seconds), but then it returned to the
situation where the "connection" log was growing 10mb/5 min and the
"smtp" log stopped growing. I tried restarting several times, but
always the same result.
This continued for 10 hours, during which time I set all log levels to
DEBUG, and the "connection" log at times grew at 5MB per minute,
repeating the EXACT SAME 42 LINES over and over and over again without
so much as a pause.
In the past, this same thing would happen every time we restarted
James, but it was ALWAYS the case that after some minutes (20?),
everything would resolve itself and start behaving normally; today, no
such luck.
About an hour ago, after 10 hours of frustration, all of a sudden
everything just started working again--as if someone somewhere said,
"Ok, Nathan, you've suffered enough for one day, let there be James!"
and flipped a switch.
I dread the day when this will happen again, but I know it will, and I
dread the day.
I've got plenty of DEBUG-level log files if someone wants to look at them.
Thanks,
Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
I think we finally found the solution to the problem described on this
thread, and apparently it was not James' fault.
Because of a custom mailet that was creating filesystem copies of
certain types of email messages, our james/temp directory had about
500,000 files in it. For a particular (good) reason, these files were
being created and forgotten about.
As soon as we emptied this directory out, our problem stopped.
As a reminder, the problem was that after starting up James, after
several minutes of normal operation, James would hang for an
ever-increasing period of time -- at last count, about 80 minutes. In
hindsight, it all makes sense now; here is my theory:
The period of normal operation was the time it took to reach this line
(in our custom mailet) for the first time:
email_file = File.createTempFile( "james-email-", ".tmp" );
With an ever increasing number of files in the temp directory,
apparently this line was what was taking 10, 30, 60, 80 minutes to
complete the FIRST time it ran, with subsequent executions happening
without delay. This is my theory--I do not actually know if (or why)
File.createTempFile(...) was the hanging culprit...But it would need
to take some time to figure out how to give the file a unique name,
and that time would increase as the number of existing files
increased. But 80 minutes is an awful long time, even for 500,000 files.
In any case, we no longer suffer from the hanging on restart, and
emptying the temp directory is the only thing we've changed.
Nathan
Nathan Cheng wrote:
> Thanks for the url. That's going to take some time to go through.
>
> For the time being we blocked all non-US ips since all of the "attacker"
> ips seemed to be outside the US.
>
> James still didn't wake up.
>
> So we restarted James. James began working immediately.
>
> YAY! We rejoiced. But it was shortlived.
>
> We got exactly 10 minutes and 5 seconds of happiness. Then, with netstat
> still showing very normal results, we went back to the old 40-minute
> wait "restart" pattern, which is the connections log starts scrolling at
> 10mb/3 min and the smtpserver does this for every "Watchdog default
> Worker" (and then hangs):
>
> --------------------------------
> 25/04/06 12:37:38 DEBUG smtpserver: Watchdog default Worker #30 has time
> to sleep 300000
> ...
> 25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 has time
> to sleep -75
> 25/04/06 12:42:38 ERROR smtpserver: SMTP Connection has idled out.
> 25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 is
> exiting run().
> --------------------------------
>
> From this point it's about 30 minutes of hang time before we'll get a
> whole string of errors in the smtp log, and then James'll start back up
> again.
>
> What does it mean to sleep -71 milliseconds?
>
> Nathan
>
> Stefano Bagnara wrote:
>
>> If you use Linux read this:
>> http://www.linuxsecurity.com/content/view/121960/49/
>>
>> Otherwise you should look for a firewall with similar features that
>> allow you to automatically block IPs that are part of a DDoS attack.
>>
>> Btw, unfortunately DDoS are hard to block.
>>
>> Stefano
>>
>> Nathan Cheng wrote:
>>
>>> We have blocked over 20 ip addresses so far, they are all non-US ips
>>> (all our legit customers are in the US right now and would have
>>> almost no occasion to communicate outside the US), and as soon as we
>>> block 1, another pops up.
>>>
>>> James is reacting in just about the same manner as it does when we
>>> try to restart. So it is true: a restart and a DDoS look very similar
>>> to us. Last night we had a restart, and this morning we're having a
>>> DDoS and they look the same.
>>>
>>> How are we supposed to deal with this? We don't have fancy hardware,
>>> so what's the software solution?
>>>
>>> Thanks,
>>>
>>> Nathan
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
>> For additional commands, e-mail: server-user-help@james.apache.org
>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Stefano Bagnara <ap...@bago.org>.
I checked the code that write the "Watchdog default Worker ### has time
to sleep -###" and it seems unchanged since 2002.
The code explicitly handle times less than 0 milliseconds, so it should
not be a problem.
This probably only happens because your server is on 100% cpu and the
watchdog thread is mostly late. The watchdog code is to handle the
connection timeouts and when it writes a negative value it simply
suddenly run the "watchdog target" (idleClose).
The log snippet confirm that the "SMTP Connection has idled out".
Stefano
Nathan Cheng wrote:
> [...]
> --------------------------------
> 25/04/06 12:37:38 DEBUG smtpserver: Watchdog default Worker #30 has time
> to sleep 300000
> ...
> 25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 has time
> to sleep -75
> 25/04/06 12:42:38 ERROR smtpserver: SMTP Connection has idled out.
> 25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 is
> exiting run().
> --------------------------------
>
> From this point it's about 30 minutes of hang time before we'll get a
> whole string of errors in the smtp log, and then James'll start back up
> again.
>
> What does it mean to sleep -71 milliseconds?
>
> Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
Thanks for the url. That's going to take some time to go through.
For the time being we blocked all non-US ips since all of the
"attacker" ips seemed to be outside the US.
James still didn't wake up.
So we restarted James. James began working immediately.
YAY! We rejoiced. But it was shortlived.
We got exactly 10 minutes and 5 seconds of happiness. Then, with
netstat still showing very normal results, we went back to the old
40-minute wait "restart" pattern, which is the connections log starts
scrolling at 10mb/3 min and the smtpserver does this for every
"Watchdog default Worker" (and then hangs):
--------------------------------
25/04/06 12:37:38 DEBUG smtpserver: Watchdog default Worker #30 has
time to sleep 300000
...
25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 has
time to sleep -75
25/04/06 12:42:38 ERROR smtpserver: SMTP Connection has idled out.
25/04/06 12:42:38 DEBUG smtpserver: Watchdog default Worker #30 is
exiting run().
--------------------------------
From this point it's about 30 minutes of hang time before we'll get a
whole string of errors in the smtp log, and then James'll start back
up again.
What does it mean to sleep -71 milliseconds?
Nathan
Stefano Bagnara wrote:
> If you use Linux read this:
> http://www.linuxsecurity.com/content/view/121960/49/
>
> Otherwise you should look for a firewall with similar features that
> allow you to automatically block IPs that are part of a DDoS attack.
>
> Btw, unfortunately DDoS are hard to block.
>
> Stefano
>
> Nathan Cheng wrote:
>
>> We have blocked over 20 ip addresses so far, they are all non-US ips
>> (all our legit customers are in the US right now and would have almost
>> no occasion to communicate outside the US), and as soon as we block 1,
>> another pops up.
>>
>> James is reacting in just about the same manner as it does when we try
>> to restart. So it is true: a restart and a DDoS look very similar to
>> us. Last night we had a restart, and this morning we're having a DDoS
>> and they look the same.
>>
>> How are we supposed to deal with this? We don't have fancy hardware,
>> so what's the software solution?
>>
>> Thanks,
>>
>> Nathan
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Stefano Bagnara <ap...@bago.org>.
If you use Linux read this:
http://www.linuxsecurity.com/content/view/121960/49/
Otherwise you should look for a firewall with similar features that
allow you to automatically block IPs that are part of a DDoS attack.
Btw, unfortunately DDoS are hard to block.
Stefano
Nathan Cheng wrote:
> We have blocked over 20 ip addresses so far, they are all non-US ips
> (all our legit customers are in the US right now and would have almost
> no occasion to communicate outside the US), and as soon as we block 1,
> another pops up.
>
> James is reacting in just about the same manner as it does when we try
> to restart. So it is true: a restart and a DDoS look very similar to us.
> Last night we had a restart, and this morning we're having a DDoS and
> they look the same.
>
> How are we supposed to deal with this? We don't have fancy hardware, so
> what's the software solution?
>
> Thanks,
>
> Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
We have blocked over 20 ip addresses so far, they are all non-US ips
(all our legit customers are in the US right now and would have almost
no occasion to communicate outside the US), and as soon as we block 1,
another pops up.
James is reacting in just about the same manner as it does when we try
to restart. So it is true: a restart and a DDoS look very similar to
us. Last night we had a restart, and this morning we're having a DDoS
and they look the same.
How are we supposed to deal with this? We don't have fancy hardware,
so what's the software solution?
Thanks,
Nathan
Nathan Cheng wrote:
> > If it's a DoS, how do the attackers know the exact moment we decide to
> > restart our server? Could they really be polling us to find out? And why
> > do they stop after 40 mins every time (lately)? And are they really
> > using a network of computers to attack us? This just doesn't make sense
> > to me.
>
> This morning at exactly 7:00 AM PST a definite DDoS started against us.
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
> If it's a DoS, how do the attackers know the exact moment we decide to
> restart our server? Could they really be polling us to find out?
And why
> do they stop after 40 mins every time (lately)? And are they really
> using a network of computers to attack us? This just doesn't make
sense
> to me.
This morning at exactly 7:00 AM PST a definite DDoS started against us.
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
That's what it seems like, and I do watch netstat, but there does not
seem to be a single attacker ip, just whenever we restart james,
within a few minutes we've got 10, 20, 30, 50, 100, 200, 300 smtp
connections coming from 50 different ips, and they're different ips
every time. And it only happens when we restart james (which on
average has been about once every two weeks)! Like right now at 12:40
AM, we just restarted james and are patiently waiting the prescribed
30-50 mins. Before we restarted james, everything was just fine and
dandy, handling about 200 legit user emails per hour (and
spam-blocking about 50 trillion), no connection problems, nice and
speedy... Then the second we restart, we get things like this:
[root@pjemail1 root]# netstat -a | grep smtp | grep dhcp-66-244-127-6
| wc -l
189
[root@pjemail1 root]# netstat -a | grep smtp | grep 210.211.172.27 | wc -l
34
etc.
We just used iptables to block all smtp. That stopped the connection
log from growing at 10mb/3 mins, but now what? So we unblocked smtp
again, and the connection log went back to its phenomenal growth. And
so we just have to wait another 20 mins for our email sever to come
back up.
If it's a DoS, how do the attackers know the exact moment we decide to
restart our server? Could they really be polling us to find out? And
why do they stop after 40 mins every time (lately)? And are they
really using a network of computers to attack us? This just doesn't
make sense to me.
What does make sense to me is that we deadletter about 10,000 spam
emails a day and they usually come from about 9,000 different ip
addresses. So it does make sense to me that at all hours of the day
we're getting flooded with email. But apparently there is something
that james does during its start-up process that makes it unable to
properly cope with this kind of "faucet on" flood of emails, but once
it completes some serindipitous series of timeouts, it finds its
groove and gets to work. But it's taking 40 minutes for it to find its
groove and that's killing us.
If there is any super james developer with magical powers who would
like to restart our email server some night and observe this
phenomenon for themselves, please let me know and I will arrange it.
Thanks,
Nathan
Stefano Bagnara wrote:
> May it be you are under attack (Denial of Service)?
>
> You should check your network statistics (netstat) and eventually filter
> the attacker ip from your firewall.
>
> Stefano
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Stefano Bagnara <ap...@bago.org>.
May it be you are under attack (Denial of Service)?
You should check your network statistics (netstat) and eventually filter
the attacker ip from your firewall.
Stefano
Nathan Cheng wrote:
> Meanwhile, the "connections" log is going nuts, writing the same set of
> "Maximum number of open connections exceeded - refusing connection"
> messages over and over at a rate of 10MB per 3 minutes or so:
>
> -rw-r--r-- 1 root root 10485738 Apr 22 12:38
> connections-2006-04-22-12-28.log
> -rw-r--r-- 1 root root 10485901 Apr 22 12:42
> connections-2006-04-22-12-38.log
> -rw-r--r-- 1 root root 10485974 Apr 22 12:46
> connections-2006-04-22-12-42.log
> -rw-r--r-- 1 root root 10485856 Apr 22 12:49
> connections-2006-04-22-12-46.log
> -rw-r--r-- 1 root root 10485895 Apr 22 12:53
> connections-2006-04-22-12-49.log
> -rw-r--r-- 1 root root 10485957 Apr 22 12:56
> connections-2006-04-22-12-53.log
> -rw-r--r-- 1 root root 10485832 Apr 22 12:58
> connections-2006-04-22-12-56.log
> -rw-r--r-- 1 root root 10485985 Apr 22 13:01
> connections-2006-04-22-12-58.log
> -rw-r--r-- 1 root root 10485979 Apr 22 13:03
> connections-2006-04-22-13-01.log
> -rw-r--r-- 1 root root 10485818 Apr 22 13:04
> connections-2006-04-22-13-03.log
> -rw-r--r-- 1 root root 10485955 Apr 22 13:06
> connections-2006-04-22-13-04.log
> -rw-r--r-- 1 root root 10485911 Apr 22 13:08
> connections-2006-04-22-13-06.log
> -rw-r--r-- 1 root root 10485815 Apr 22 13:11
> connections-2006-04-22-13-08.log
> -rw-r--r-- 1 root root 8468986 Apr 22 13:13
> connections-2006-04-22-13-11.log
>
> Time now is Apr 22 13:13.
>
> I've got netstat dumps if anyone wants to take a look.
>
> I was right about it taking 10 more minuts or so, as I type, James just
> woke up.
>
> Anybody got any clue?
>
> Thanks,
>
> Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: Wrong email deleted with concurrent delete and receive operations
Posted by Danny Angus <da...@gmail.com>.
I think this may be a defect in James, but would need to re-read the
POP3 spec before I can be sure. Please raise this as an issue in the
JIRA issue tracker.
http://issues.apache.org/jira/secure/Dashboard.jspa
d.
On 24/04/06, Al Caponi <do...@yahoo.com.sg> wrote:
> Hi All,
>
> I have a scenario where the wrong emails are being deleted from the user's
> inbox. Has anyone encountered such problem and/or resolved it? Any help or
> pointers for further troubleshooting or fix is most welcome.
>
> VERSION:
> ========
> Server: Apache James 2.2
> Client: Chilkat 7.5 .NET Components
> ========
>
> SCENARIO:
> =========
> 1. The scenario starts with 100 messages (1st batch) in user A's inbox.
>
> 2. User A starts up his client (using Chilkat .NET components v.7.5) and
> begins downloading and deleting (using the API's deleteByUIDL) each of these
> 100 messages one by one.
> Almost simultaneously, from another client (this one using JavaMail), I send
> another 100 email (2nd batch) to user A inbox.
>
> 3. User A successfully downloads all 100 from 1st batch.
>
> 4. On inspection of his inbox folder, I found
> 3 messages from 1st batch and (Expected 0)
> 97 messages from 2nd batch! (Expected 100)
> ===>> It seems that at some point the 'delete' operations have
> targetted the wrong messages.
> =========
>
> JAMES LOG:
> ==========
> Here are the 100 DELE commands I extracted from the pop log (and there's
> only 100). The numbering (order num?) is not consistent(?).
> This is a test server and all the DELE commands are for this scenario.
>
> Does the DELE command come directly from the client or is there some kind of
> mapping (Between UIDL and message order num) being maintained and resolved
> by James?:
> 24/04/06 10:54:14 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:18 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:22 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:27 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:31 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:35 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:39 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:44 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:48 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:52 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:54:56 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:00 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:04 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:08 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:13 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:17 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:21 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:25 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:29 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:33 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:37 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:43 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:49 DEBUG pop3server: Command received: DELE 9
> 24/04/06 10:55:55 DEBUG pop3server: Command received: DELE 23
> 24/04/06 10:56:00 DEBUG pop3server: Command received: DELE 31
> 24/04/06 10:56:06 DEBUG pop3server: Command received: DELE 31
> 24/04/06 10:56:11 DEBUG pop3server: Command received: DELE 31
> 24/04/06 10:56:15 DEBUG pop3server: Command received: DELE 31
> 24/04/06 10:56:20 DEBUG pop3server: Command received: DELE 31
> 24/04/06 10:56:24 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:29 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:33 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:37 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:41 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:46 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:50 DEBUG pop3server: Command received: DELE 32
> 24/04/06 10:56:54 DEBUG pop3server: Command received: DELE 33
> 24/04/06 10:56:59 DEBUG pop3server: Command received: DELE 33
> 24/04/06 10:57:03 DEBUG pop3server: Command received: DELE 37
> 24/04/06 10:57:09 DEBUG pop3server: Command received: DELE 37
> 24/04/06 10:57:13 DEBUG pop3server: Command received: DELE 37
> 24/04/06 10:57:17 DEBUG pop3server: Command received: DELE 39
> 24/04/06 10:57:22 DEBUG pop3server: Command received: DELE 40
> 24/04/06 10:57:26 DEBUG pop3server: Command received: DELE 40
> 24/04/06 10:57:30 DEBUG pop3server: Command received: DELE 40
> 24/04/06 10:57:35 DEBUG pop3server: Command received: DELE 40
> 24/04/06 10:57:39 DEBUG pop3server: Command received: DELE 41
> 24/04/06 10:57:43 DEBUG pop3server: Command received: DELE 42
> 24/04/06 10:57:48 DEBUG pop3server: Command received: DELE 43
> 24/04/06 10:57:52 DEBUG pop3server: Command received: DELE 43
> 24/04/06 10:57:56 DEBUG pop3server: Command received: DELE 43
> 24/04/06 10:58:00 DEBUG pop3server: Command received: DELE 46
> 24/04/06 10:58:04 DEBUG pop3server: Command received: DELE 48
> 24/04/06 10:58:09 DEBUG pop3server: Command received: DELE 49
> 24/04/06 10:58:14 DEBUG pop3server: Command received: DELE 49
> 24/04/06 10:58:18 DEBUG pop3server: Command received: DELE 49
> 24/04/06 10:58:23 DEBUG pop3server: Command received: DELE 56
> 24/04/06 10:58:27 DEBUG pop3server: Command received: DELE 57
> 24/04/06 10:58:32 DEBUG pop3server: Command received: DELE 63
> 24/04/06 10:58:36 DEBUG pop3server: Command received: DELE 63
> 24/04/06 10:58:40 DEBUG pop3server: Command received: DELE 67
> 24/04/06 10:58:44 DEBUG pop3server: Command received: DELE 67
> 24/04/06 10:58:48 DEBUG pop3server: Command received: DELE 68
> 24/04/06 10:58:52 DEBUG pop3server: Command received: DELE 69
> 24/04/06 10:58:56 DEBUG pop3server: Command received: DELE 69
> 24/04/06 10:59:00 DEBUG pop3server: Command received: DELE 70
> 24/04/06 10:59:05 DEBUG pop3server: Command received: DELE 70
> 24/04/06 10:59:09 DEBUG pop3server: Command received: DELE 70
> 24/04/06 10:59:14 DEBUG pop3server: Command received: DELE 70
> 24/04/06 10:59:18 DEBUG pop3server: Command received: DELE 70
> 24/04/06 10:59:22 DEBUG pop3server: Command received: DELE 78
> 24/04/06 10:59:26 DEBUG pop3server: Command received: DELE 78
> 24/04/06 10:59:30 DEBUG pop3server: Command received: DELE 78
> 24/04/06 10:59:34 DEBUG pop3server: Command received: DELE 80
> 24/04/06 10:59:38 DEBUG pop3server: Command received: DELE 80
> 24/04/06 10:59:43 DEBUG pop3server: Command received: DELE 80
> 24/04/06 10:59:47 DEBUG pop3server: Command received: DELE 80
> 24/04/06 10:59:51 DEBUG pop3server: Command received: DELE 81
> 24/04/06 10:59:55 DEBUG pop3server: Command received: DELE 81
> 24/04/06 10:59:59 DEBUG pop3server: Command received: DELE 81
> 24/04/06 11:00:03 DEBUG pop3server: Command received: DELE 81
> 24/04/06 11:00:07 DEBUG pop3server: Command received: DELE 82
> 24/04/06 11:00:11 DEBUG pop3server: Command received: DELE 83
> 24/04/06 11:00:17 DEBUG pop3server: Command received: DELE 84
> 24/04/06 11:00:22 DEBUG pop3server: Command received: DELE 84
> 24/04/06 11:00:26 DEBUG pop3server: Command received: DELE 87
> 24/04/06 11:00:30 DEBUG pop3server: Command received: DELE 87
> 24/04/06 11:00:34 DEBUG pop3server: Command received: DELE 87
> 24/04/06 11:00:38 DEBUG pop3server: Command received: DELE 88
> 24/04/06 11:00:42 DEBUG pop3server: Command received: DELE 88
> 24/04/06 11:00:47 DEBUG pop3server: Command received: DELE 88
> 24/04/06 11:00:51 DEBUG pop3server: Command received: DELE 92
> 24/04/06 11:00:55 DEBUG pop3server: Command received: DELE 94
> 24/04/06 11:00:59 DEBUG pop3server: Command received: DELE 96
> 24/04/06 11:01:04 DEBUG pop3server: Command received: DELE 100
> 24/04/06 11:01:08 DEBUG pop3server: Command received: DELE 100
> 24/04/06 11:01:13 DEBUG pop3server: Command received: DELE 100
> 24/04/06 11:01:18 DEBUG pop3server: Command received: DELE 100
> 24/04/06 11:01:24 DEBUG pop3server: Command received: DELE 101
> 24/04/06 11:01:28 DEBUG pop3server: Command received: DELE 101
> ==========
>
> Regards,
> Al
>
> Send instant messages to your online friends http://asia.messenger.yahoo.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: Wrong email deleted with concurrent delete and receive operations
Posted by Danny Angus <Da...@slc.co.uk>.
Guys, remember the significant difference between UIDL and the number from
normal list operations, UIDL provides unique ID's which should be
consistent *across* sessions, normal numbers only apply duing one session.
d.
Stefano Bagnara <ap...@bago.org> wrote on 26/04/2006 09:13:59:
> Al Caponi wrote:
> > Hi again,
> > What is the reasoning behind assigning a random number to new messages
such
> > that the latter would come and disrupt the sequence (but not the
ordering)
> > of existing emails?
>
> There is no such thing "number assignment" in James.
> We simply put messages in repositories, read messages from repositories.
> Repositories don't have a "positional" information.
>
> > It seems more intuitive to me to add new messages at the end of a list
-
> > even though the POP3 protocol does not apparently require it.
>
> That's right POP3 protocol does not require it. It neither suggest it,
> if I remember correctly.
>
> > [..]
> > Any thoughts or clarifications?
> > I have some apprehensions due to James behaving in such an 'odd way' -
which
> > I hope you can help to rationalize.
>
> It is not odd if you read the POP3 rfc.
> imho it's odd the way Chilkat delete messages in different sessions.
>
> If this is critical to you, you can change the way the repository
> returns the message list adding a time condition.
>
> Look at the AvalonMailRepository (if using file repositories) or
> JDBCMailRepository (if using db).
> You can even implement your own CustomMailRepository extending the
> bundled one and changing only the list method.
>
> Stefano
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>
***************************************************************************
The information in this e-mail is confidential and for use by the addressee(s) only. If you are not the intended recipient (or responsible for delivery of the message to the intended recipient) please notify us immediately on 0141 306 2050 and delete the message from your computer. You may not copy or forward it or use or disclose its contents to any other person. As Internet communications are capable of data corruption Student Loans Company Limited does not accept any responsibility for changes made to this message after it was sent. For this reason it may be inappropriate to rely on advice or opinions contained in an e-mail without obtaining written confirmation of it. Neither Student Loans Company Limited or the sender accepts any liability or responsibility for viruses as it is your responsibility to scan attachments (if any). Opinions and views expressed in this e-mail are those of the sender and may not reflect the opinions and views of The Student Loans Company Limit
ed.
This footnote also confirms that this email message has been swept for the presence of computer viruses.
**************************************************************************
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: Wrong email deleted with concurrent delete and receive operations
Posted by Stefano Bagnara <ap...@bago.org>.
Al Caponi wrote:
> Hi again,
> What is the reasoning behind assigning a random number to new messages such
> that the latter would come and disrupt the sequence (but not the ordering)
> of existing emails?
There is no such thing "number assignment" in James.
We simply put messages in repositories, read messages from repositories.
Repositories don't have a "positional" information.
> It seems more intuitive to me to add new messages at the end of a list -
> even though the POP3 protocol does not apparently require it.
That's right POP3 protocol does not require it. It neither suggest it,
if I remember correctly.
> [..]
> Any thoughts or clarifications?
> I have some apprehensions due to James behaving in such an 'odd way' - which
> I hope you can help to rationalize.
It is not odd if you read the POP3 rfc.
imho it's odd the way Chilkat delete messages in different sessions.
If this is critical to you, you can change the way the repository
returns the message list adding a time condition.
Look at the AvalonMailRepository (if using file repositories) or
JDBCMailRepository (if using db).
You can even implement your own CustomMailRepository extending the
bundled one and changing only the list method.
Stefano
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
RE: Wrong email deleted with concurrent delete and receive operations
Posted by Al Caponi <do...@yahoo.com.sg>.
Hi again,
What is the reasoning behind assigning a random number to new messages such
that the latter would come and disrupt the sequence (but not the ordering)
of existing emails?
It seems more intuitive to me to add new messages at the end of a list -
even though the POP3 protocol does not apparently require it.
I guess that Cyrus is adding new msgs at the end of the list thus explaining
our inability to reproduce the problem there then.
After looking at the UIDL listing for a James mailbox before and after
inserting new emails, I realized that the messages actually preserve their
_ordering_ across sessions but new messages will come and offset parts of
the existing list at different random points.
The UIDL responses below show how two new messages disrupted the _sequence_
but NOT the _ordering_.
_BEFORE_NEW_MESSAGES_ _AFTER_NEW_MESSAGES_
# UID # UID
(Prev #)
1 Mail1145932157811-2379 1 Mail1145987288808-2619 <<-- (NEW)
2 Mail1145932156155-2367 2 Mail1145932157811-2379 <<-- (1)
3 Mail1145932175686-2489 3 Mail1145932156155-2367 <<-- (2)
4 Mail1145932065343-2273 4 Mail1145932175686-2489 <<-- (3)
5 Mail1145932158077-2381 5 Mail1145932065343-2273 <<-- (4)
6 Mail1145932149920-2323 6 Mail1145932158077-2381 <<-- (5)
7 Mail1145932167420-2445 7 Mail1145932149920-2323 <<-- (6)
8 Mail1145932165405-2431 8 Mail1145987289230-2623 <<-- (NEW)
9 Mail1145932172389-2469 9 Mail1145932167420-2445 <<-- (7)
10 Mail1145932169483-2459 10 Mail1145932165405-2431 <<-- (8)
11 Mail1145932163514-2417 11 Mail1145932172389-2469 <<-- (9)
12 Mail1145932160795-2401 12 Mail1145932169483-2459 <<-- (10)
13 Mail1145932175530-2487 13 Mail1145932163514-2417 <<-- (11)
14 Mail1145932160795-2401 <<--
(12)
15 Mail1145932175530-2487 <<--
(13)
Any thoughts or clarifications?
I have some apprehensions due to James behaving in such an 'odd way' - which
I hope you can help to rationalize.
Cheers,
Al.
> -----Original Message-----
> From: Al Caponi [mailto:don_alcaponi@yahoo.com.sg]
> Sent: Tuesday, April 25, 2006 11:52 AM
> To: 'James Users List'
> Subject: RE: Wrong email deleted with concurrent delete and
> receive operations
>
> From today's test - Chilkat sent the DELE commands without
> any UIDL within a
> totally new session.
> So this is not accurate as there is no guarantee of the
> msg_num (the param
> passed to DELE) for a message to remain the same across
> different sessions.
> And this would be the reason for the deletion operations
> possibly going
> haywire, specially when new messages are coming in concurrently.
>
> Log command extracts for one of the messages downloaded by Chilkat -
> (UIDL,RETR) and (DELE) cmds are in different sessions:
> -----------------------------------------------------
> 25/04/06 10:29:43 DEBUG pop3sserver: [default Worker #19]
> Command received:
> USER chilkat
> 25/04/06 10:29:43 DEBUG pop3sserver: [default Worker #19]
> Command received:
> PASS <password omitted>
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19]
> Command received:
> STAT
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19]
> Command received:
> UIDL
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19]
> Command received:
> RETR 27
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19]
> Command received:
> QUIT
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15]
> Command received:
> USER chilkat
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15]
> Command received:
> PASS <password omitted>
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15]
> Command received:
> STAT
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15]
> Command received:
> DELE 27
> 25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15]
> Command received:
> QUIT
> -----------------------------------------------------
>
> Log command extracts from a JavaMail test client - all
> operations are done
> within the same session:
> -----------------------------------------------------
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> USER javaclient
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> PASS <password omitted>
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> STAT
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> NOOP
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> UIDL 1
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> TOP 1 0
> 24/04/06 21:10:45 DEBUG pop3server: [default Worker #13]
> Command received:
> RETR 1
> ...
> 24/04/06 21:10:51 DEBUG pop3server: [default Worker #13]
> Command received:
> DELE 1
> ...
> 24/04/06 21:10:51 DEBUG pop3server: [default Worker #13]
> Command received:
> QUIT
> -----------------------------------------------------
>
>
> Also, I omitted to reply about DELE9 without DELE2-7. You
> might have figured
> out that we were doing selective 'download and delete'. That
> would explain
> the non-consecutive msg nums.
>
> I'll leave the JIRA alone for the time being as it's not an issue with
> James.
>
> Thanks for the help.
> Cheers,
> Al.
>
> > -----Original Message-----
> > From: Al Caponi [mailto:don_alcaponi@yahoo.com.sg]
> > Sent: Monday, April 24, 2006 8:34 PM
> > To: 'James Users List'
> > Subject: RE: Wrong email deleted with concurrent delete and
> > receive operations
> >
> >
> > > >
> > > > 2. "DELE 1" commands
> > > > As for the 'DELE 1' cmds being from different connections,
> > > I can't confirm
> > > > that as I didn't log the thread name.
> > > > I'll need some time to re-simulate that as the client code
> > > has changed.
> > >
> > > What about the DELE9 with no previous DELE2-7 ?
> > >
> > > Are the connections made concurrently?
> > >
> > > James does not lock the pop3 inbox, so multiple concurrent
> > > connections
> > > for the same user may ends to unknown behaviours.
> > >
> > > You said that you have 100 messages and you start reading them.
> > > Then you send to the same inbox more messages.
> > >
> > > If the client close and reopen connections then it will
> see the new
> > > messages too.
> > >
> >
> > > No one ensure that the messages in pop3 are shown in
> arrival order.
> > >
> >
> > Each 'download and delete' was made sequentially from a
> > single client. The
> > latter does the following:
> > 1. Start a session.
> > 2. Grab the list of messages in the inbox.
> > 3. For each message on that list,
> > i. Scan header for some proprietary meta-info to
> > determine if
> > download is required.
> > ii. Download the message and then issue the deleteByUIDL
> > command.
> >
> > We're processing all the messages in a single thread but we
> > don't know yet
> > whether Chilkat handles each download and/or delete with a
> > new session or
> > not.
> > We'll run the original code and add the thread name logging
> > in James. Until
> > the Chilkat folks get back to us, that'll be the only
> > guideline that we
> > have.
> > Will keep you updated.
> >
>
> Send instant messages to your online friends
> http://asia.messenger.yahoo.com
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>
Send instant messages to your online friends http://asia.messenger.yahoo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
RE: Wrong email deleted with concurrent delete and receive operations
Posted by Al Caponi <do...@yahoo.com.sg>.
>From today's test - Chilkat sent the DELE commands without any UIDL within a
totally new session.
So this is not accurate as there is no guarantee of the msg_num (the param
passed to DELE) for a message to remain the same across different sessions.
And this would be the reason for the deletion operations possibly going
haywire, specially when new messages are coming in concurrently.
Log command extracts for one of the messages downloaded by Chilkat -
(UIDL,RETR) and (DELE) cmds are in different sessions:
-----------------------------------------------------
25/04/06 10:29:43 DEBUG pop3sserver: [default Worker #19] Command received:
USER chilkat
25/04/06 10:29:43 DEBUG pop3sserver: [default Worker #19] Command received:
PASS <password omitted>
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19] Command received:
STAT
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19] Command received:
UIDL
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19] Command received:
RETR 27
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #19] Command received:
QUIT
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15] Command received:
USER chilkat
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15] Command received:
PASS <password omitted>
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15] Command received:
STAT
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15] Command received:
DELE 27
25/04/06 10:29:44 DEBUG pop3sserver: [default Worker #15] Command received:
QUIT
-----------------------------------------------------
Log command extracts from a JavaMail test client - all operations are done
within the same session:
-----------------------------------------------------
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
USER javaclient
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
PASS <password omitted>
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
STAT
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
NOOP
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
UIDL 1
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
TOP 1 0
24/04/06 21:10:45 DEBUG pop3server: [default Worker #13] Command received:
RETR 1
...
24/04/06 21:10:51 DEBUG pop3server: [default Worker #13] Command received:
DELE 1
...
24/04/06 21:10:51 DEBUG pop3server: [default Worker #13] Command received:
QUIT
-----------------------------------------------------
Also, I omitted to reply about DELE9 without DELE2-7. You might have figured
out that we were doing selective 'download and delete'. That would explain
the non-consecutive msg nums.
I'll leave the JIRA alone for the time being as it's not an issue with
James.
Thanks for the help.
Cheers,
Al.
> -----Original Message-----
> From: Al Caponi [mailto:don_alcaponi@yahoo.com.sg]
> Sent: Monday, April 24, 2006 8:34 PM
> To: 'James Users List'
> Subject: RE: Wrong email deleted with concurrent delete and
> receive operations
>
>
> > >
> > > 2. "DELE 1" commands
> > > As for the 'DELE 1' cmds being from different connections,
> > I can't confirm
> > > that as I didn't log the thread name.
> > > I'll need some time to re-simulate that as the client code
> > has changed.
> >
> > What about the DELE9 with no previous DELE2-7 ?
> >
> > Are the connections made concurrently?
> >
> > James does not lock the pop3 inbox, so multiple concurrent
> > connections
> > for the same user may ends to unknown behaviours.
> >
> > You said that you have 100 messages and you start reading them.
> > Then you send to the same inbox more messages.
> >
> > If the client close and reopen connections then it will see the new
> > messages too.
> >
>
> > No one ensure that the messages in pop3 are shown in arrival order.
> >
>
> Each 'download and delete' was made sequentially from a
> single client. The
> latter does the following:
> 1. Start a session.
> 2. Grab the list of messages in the inbox.
> 3. For each message on that list,
> i. Scan header for some proprietary meta-info to
> determine if
> download is required.
> ii. Download the message and then issue the deleteByUIDL
> command.
>
> We're processing all the messages in a single thread but we
> don't know yet
> whether Chilkat handles each download and/or delete with a
> new session or
> not.
> We'll run the original code and add the thread name logging
> in James. Until
> the Chilkat folks get back to us, that'll be the only
> guideline that we
> have.
> Will keep you updated.
>
Send instant messages to your online friends http://asia.messenger.yahoo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
RE: Wrong email deleted with concurrent delete and receive operations
Posted by Al Caponi <do...@yahoo.com.sg>.
> >
> > 2. "DELE 1" commands
> > As for the 'DELE 1' cmds being from different connections,
> I can't confirm
> > that as I didn't log the thread name.
> > I'll need some time to re-simulate that as the client code
> has changed.
>
> What about the DELE9 with no previous DELE2-7 ?
>
> Are the connections made concurrently?
>
> James does not lock the pop3 inbox, so multiple concurrent
> connections
> for the same user may ends to unknown behaviours.
>
> You said that you have 100 messages and you start reading them.
> Then you send to the same inbox more messages.
>
> If the client close and reopen connections then it will see the new
> messages too.
>
> No one ensure that the messages in pop3 are shown in arrival order.
>
Each 'download and delete' was made sequentially from a single client. The
latter does the following:
1. Start a session.
2. Grab the list of messages in the inbox.
3. For each message on that list,
i. Scan header for some proprietary meta-info to determine if
download is required.
ii. Download the message and then issue the deleteByUIDL
command.
We're processing all the messages in a single thread but we don't know yet
whether Chilkat handles each download and/or delete with a new session or
not.
We'll run the original code and add the thread name logging in James. Until
the Chilkat folks get back to us, that'll be the only guideline that we
have.
Will keep you updated.
> > 4. Mail repository
> > We're using the file repository. Any special recommendation
> for or against
> > it?
>
> No, I just wanted to gather more informations.
Well, we went with the file repository because it was the default setting. I
hope to have the time to explore the other options.
Hi Danny,
Thanks for the response, will raise it in JIRA
Send instant messages to your online friends http://asia.messenger.yahoo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: Wrong email deleted with concurrent delete and receive operations
Posted by Stefano Bagnara <ap...@bago.org>.
Al Caponi wrote:
> Hi Stefano and All,
> Thanks for the quick reply.
>
> 2. "DELE 1" commands
> As for the 'DELE 1' cmds being from different connections, I can't confirm
> that as I didn't log the thread name.
> I'll need some time to re-simulate that as the client code has changed.
What about the DELE9 with no previous DELE2-7 ?
Are the connections made concurrently?
James does not lock the pop3 inbox, so multiple concurrent connections
for the same user may ends to unknown behaviours.
You said that you have 100 messages and you start reading them.
Then you send to the same inbox more messages.
If the client close and reopen connections then it will see the new
messages too.
No one ensure that the messages in pop3 are shown in arrival order.
> 3. UIDL support
> I do see UIDLs being generated by James and I also see James responding to
> UIDL commands. I telnet in and issued the commmand and it responded.
> Do you mean 'does not fully support'? Where could we have more details?
Sorry, I was wrong. I was remembering that James pop3server was not
supporting the UIDL command, but I just checked that it does.
> 4. Mail repository
> We're using the file repository. Any special recommendation for or against
> it?
No, I just wanted to gather more informations.
Stefano
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
RE: Wrong email deleted with concurrent delete and receive operations
Posted by Al Caponi <do...@yahoo.com.sg>.
Hi Stefano and All,
Thanks for the quick reply.
1. Bug in Chilkat
In order to narrow down our troubleshooting scope, we ran the same tests
_repeatedly_ against a Cyrus POP3 v2.0.17 email server and there was no
problem w.r.t to the message deletion.
This seemed to tell me that the problem might lie elsewhere. But I wouldn't
say that it cleared any one of Chilkat or James.
Similarly, I've been unable to reproduce the error with my test JavaMail
client and James in the same scenario.
2. "DELE 1" commands
As for the 'DELE 1' cmds being from different connections, I can't confirm
that as I didn't log the thread name.
I'll need some time to re-simulate that as the client code has changed.
3. UIDL support
I do see UIDLs being generated by James and I also see James responding to
UIDL commands. I telnet in and issued the commmand and it responded.
Do you mean 'does not fully support'? Where could we have more details?
4. Mail repository
We're using the file repository. Any special recommendation for or against
it?
Thanks again,
Al
-----Original Message-----
From: Stefano Bagnara [mailto:apache@bago.org]
Sent: Monday, April 24, 2006 3:26 PM
To: James Users List
Subject: Re: Wrong email deleted with concurrent delete and receive
operations
I think this is a bug in "Chilkat .NET components".
You receive a bunch of "DELE 1" while it should never delete the same
message again and again.
If the "DELE 1" are from different connections then I can't explain the
DELE 9 with no previous DELE 1 to DELE 7.
James pop3 server does not support UIDL. It is not mandatory for POP3
protocol.
James pop3 server does keep track of message numbers and deletes the
correct message (based on the order returned to the LIST command).
What mail repository do you use? db / dbfile / file ?
Stefano
Al Caponi wrote:
> Hi All,
>
> I have a scenario where the wrong emails are being deleted from the user's
> inbox. Has anyone encountered such problem and/or resolved it? Any help or
> pointers for further troubleshooting or fix is most welcome.
>
> VERSION:
> ========
> Server: Apache James 2.2
> Client: Chilkat 7.5 .NET Components
> ========
> 24/04/06 10:55:17 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:21 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:25 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:29 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:33 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:37 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:43 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:49 DEBUG pop3server: Command received: DELE 9
> 24/04/06 10:55:55 DEBUG pop3server: Command received: DELE 23
> 24/04/06 10:56:00 DEBUG pop3server: Command received: DELE 31
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Send instant messages to your online friends http://asia.messenger.yahoo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: Wrong email deleted with concurrent delete and receive operations
Posted by Stefano Bagnara <ap...@bago.org>.
I think this is a bug in "Chilkat .NET components".
You receive a bunch of "DELE 1" while it should never delete the same
message again and again.
If the "DELE 1" are from different connections then I can't explain the
DELE 9 with no previous DELE 1 to DELE 7.
James pop3 server does not support UIDL. It is not mandatory for POP3
protocol.
James pop3 server does keep track of message numbers and deletes the
correct message (based on the order returned to the LIST command).
What mail repository do you use? db / dbfile / file ?
Stefano
Al Caponi wrote:
> Hi All,
>
> I have a scenario where the wrong emails are being deleted from the user's
> inbox. Has anyone encountered such problem and/or resolved it? Any help or
> pointers for further troubleshooting or fix is most welcome.
>
> VERSION:
> ========
> Server: Apache James 2.2
> Client: Chilkat 7.5 .NET Components
> ========
> 24/04/06 10:55:17 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:21 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:25 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:29 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:33 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:37 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:43 DEBUG pop3server: Command received: DELE 1
> 24/04/06 10:55:49 DEBUG pop3server: Command received: DELE 9
> 24/04/06 10:55:55 DEBUG pop3server: Command received: DELE 23
> 24/04/06 10:56:00 DEBUG pop3server: Command received: DELE 31
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Wrong email deleted with concurrent delete and receive operations
Posted by Al Caponi <do...@yahoo.com.sg>.
Hi All,
I have a scenario where the wrong emails are being deleted from the user's
inbox. Has anyone encountered such problem and/or resolved it? Any help or
pointers for further troubleshooting or fix is most welcome.
VERSION:
========
Server: Apache James 2.2
Client: Chilkat 7.5 .NET Components
========
SCENARIO:
=========
1. The scenario starts with 100 messages (1st batch) in user A's inbox.
2. User A starts up his client (using Chilkat .NET components v.7.5) and
begins downloading and deleting (using the API's deleteByUIDL) each of these
100 messages one by one.
Almost simultaneously, from another client (this one using JavaMail), I send
another 100 email (2nd batch) to user A inbox.
3. User A successfully downloads all 100 from 1st batch.
4. On inspection of his inbox folder, I found
3 messages from 1st batch and (Expected 0)
97 messages from 2nd batch! (Expected 100)
===>> It seems that at some point the 'delete' operations have
targetted the wrong messages.
=========
JAMES LOG:
==========
Here are the 100 DELE commands I extracted from the pop log (and there's
only 100). The numbering (order num?) is not consistent(?).
This is a test server and all the DELE commands are for this scenario.
Does the DELE command come directly from the client or is there some kind of
mapping (Between UIDL and message order num) being maintained and resolved
by James?:
24/04/06 10:54:14 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:18 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:22 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:27 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:31 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:35 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:39 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:44 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:48 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:52 DEBUG pop3server: Command received: DELE 1
24/04/06 10:54:56 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:00 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:04 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:08 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:13 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:17 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:21 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:25 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:29 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:33 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:37 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:43 DEBUG pop3server: Command received: DELE 1
24/04/06 10:55:49 DEBUG pop3server: Command received: DELE 9
24/04/06 10:55:55 DEBUG pop3server: Command received: DELE 23
24/04/06 10:56:00 DEBUG pop3server: Command received: DELE 31
24/04/06 10:56:06 DEBUG pop3server: Command received: DELE 31
24/04/06 10:56:11 DEBUG pop3server: Command received: DELE 31
24/04/06 10:56:15 DEBUG pop3server: Command received: DELE 31
24/04/06 10:56:20 DEBUG pop3server: Command received: DELE 31
24/04/06 10:56:24 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:29 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:33 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:37 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:41 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:46 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:50 DEBUG pop3server: Command received: DELE 32
24/04/06 10:56:54 DEBUG pop3server: Command received: DELE 33
24/04/06 10:56:59 DEBUG pop3server: Command received: DELE 33
24/04/06 10:57:03 DEBUG pop3server: Command received: DELE 37
24/04/06 10:57:09 DEBUG pop3server: Command received: DELE 37
24/04/06 10:57:13 DEBUG pop3server: Command received: DELE 37
24/04/06 10:57:17 DEBUG pop3server: Command received: DELE 39
24/04/06 10:57:22 DEBUG pop3server: Command received: DELE 40
24/04/06 10:57:26 DEBUG pop3server: Command received: DELE 40
24/04/06 10:57:30 DEBUG pop3server: Command received: DELE 40
24/04/06 10:57:35 DEBUG pop3server: Command received: DELE 40
24/04/06 10:57:39 DEBUG pop3server: Command received: DELE 41
24/04/06 10:57:43 DEBUG pop3server: Command received: DELE 42
24/04/06 10:57:48 DEBUG pop3server: Command received: DELE 43
24/04/06 10:57:52 DEBUG pop3server: Command received: DELE 43
24/04/06 10:57:56 DEBUG pop3server: Command received: DELE 43
24/04/06 10:58:00 DEBUG pop3server: Command received: DELE 46
24/04/06 10:58:04 DEBUG pop3server: Command received: DELE 48
24/04/06 10:58:09 DEBUG pop3server: Command received: DELE 49
24/04/06 10:58:14 DEBUG pop3server: Command received: DELE 49
24/04/06 10:58:18 DEBUG pop3server: Command received: DELE 49
24/04/06 10:58:23 DEBUG pop3server: Command received: DELE 56
24/04/06 10:58:27 DEBUG pop3server: Command received: DELE 57
24/04/06 10:58:32 DEBUG pop3server: Command received: DELE 63
24/04/06 10:58:36 DEBUG pop3server: Command received: DELE 63
24/04/06 10:58:40 DEBUG pop3server: Command received: DELE 67
24/04/06 10:58:44 DEBUG pop3server: Command received: DELE 67
24/04/06 10:58:48 DEBUG pop3server: Command received: DELE 68
24/04/06 10:58:52 DEBUG pop3server: Command received: DELE 69
24/04/06 10:58:56 DEBUG pop3server: Command received: DELE 69
24/04/06 10:59:00 DEBUG pop3server: Command received: DELE 70
24/04/06 10:59:05 DEBUG pop3server: Command received: DELE 70
24/04/06 10:59:09 DEBUG pop3server: Command received: DELE 70
24/04/06 10:59:14 DEBUG pop3server: Command received: DELE 70
24/04/06 10:59:18 DEBUG pop3server: Command received: DELE 70
24/04/06 10:59:22 DEBUG pop3server: Command received: DELE 78
24/04/06 10:59:26 DEBUG pop3server: Command received: DELE 78
24/04/06 10:59:30 DEBUG pop3server: Command received: DELE 78
24/04/06 10:59:34 DEBUG pop3server: Command received: DELE 80
24/04/06 10:59:38 DEBUG pop3server: Command received: DELE 80
24/04/06 10:59:43 DEBUG pop3server: Command received: DELE 80
24/04/06 10:59:47 DEBUG pop3server: Command received: DELE 80
24/04/06 10:59:51 DEBUG pop3server: Command received: DELE 81
24/04/06 10:59:55 DEBUG pop3server: Command received: DELE 81
24/04/06 10:59:59 DEBUG pop3server: Command received: DELE 81
24/04/06 11:00:03 DEBUG pop3server: Command received: DELE 81
24/04/06 11:00:07 DEBUG pop3server: Command received: DELE 82
24/04/06 11:00:11 DEBUG pop3server: Command received: DELE 83
24/04/06 11:00:17 DEBUG pop3server: Command received: DELE 84
24/04/06 11:00:22 DEBUG pop3server: Command received: DELE 84
24/04/06 11:00:26 DEBUG pop3server: Command received: DELE 87
24/04/06 11:00:30 DEBUG pop3server: Command received: DELE 87
24/04/06 11:00:34 DEBUG pop3server: Command received: DELE 87
24/04/06 11:00:38 DEBUG pop3server: Command received: DELE 88
24/04/06 11:00:42 DEBUG pop3server: Command received: DELE 88
24/04/06 11:00:47 DEBUG pop3server: Command received: DELE 88
24/04/06 11:00:51 DEBUG pop3server: Command received: DELE 92
24/04/06 11:00:55 DEBUG pop3server: Command received: DELE 94
24/04/06 11:00:59 DEBUG pop3server: Command received: DELE 96
24/04/06 11:01:04 DEBUG pop3server: Command received: DELE 100
24/04/06 11:01:08 DEBUG pop3server: Command received: DELE 100
24/04/06 11:01:13 DEBUG pop3server: Command received: DELE 100
24/04/06 11:01:18 DEBUG pop3server: Command received: DELE 100
24/04/06 11:01:24 DEBUG pop3server: Command received: DELE 101
24/04/06 11:01:28 DEBUG pop3server: Command received: DELE 101
==========
Regards,
Al
Send instant messages to your online friends http://asia.messenger.yahoo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
This problem has still not gone away for us, though recently it has
only been taking 30-45 to restart James. We try not to restart James
at all, but this morning we had to for an emergency server/network
reconfiguration. As I write this I am still waiting for James to wake
up. I have DEBUG on, and here is the tail of the smtpserver log:
----------------------- line 1118 -----------------------
22/04/06 12:40:15 DEBUG smtpserver: Watchdog default Worker #84 has
time to sleep -147
22/04/06 12:40:15 ERROR smtpserver: SMTP Connection has idled out.
22/04/06 12:40:15 DEBUG smtpserver: Watchdog default Worker #84 is
exiting run().
22/04/06 12:40:15 DEBUG smtpserver: Watchdog default Worker #85 has
time to sleep -71
22/04/06 12:40:15 ERROR smtpserver: SMTP Connection has idled out.
22/04/06 12:40:15 DEBUG smtpserver: Watchdog default Worker #85 is
exiting run().
22/04/06 12:40:17 DEBUG smtpserver: Watchdog default Worker #87 has
time to sleep -78
22/04/06 12:40:17 ERROR smtpserver: SMTP Connection has idled out.
22/04/06 12:40:17 DEBUG smtpserver: Watchdog default Worker #87 is
exiting run().
22/04/06 12:40:29 DEBUG smtpserver: Watchdog default Worker #88 has
time to sleep -75
22/04/06 12:40:29 ERROR smtpserver: SMTP Connection has idled out.
22/04/06 12:40:29 DEBUG smtpserver: Watchdog default Worker #88 is
exiting run().
------------------------ EOF -----------------------
Note that we restarted James at 22/04/06 12:28:39, and now the time is
22/04/06 13:05:08. So I'm guessing we have another 10 minutes or so to
wait before James spits out a string of these errors and starts
handling smtp/pop again (from a previous restart):
----------------------- line 1816 -----------------------
18/04/06 04:15:01 DEBUG smtpserver: Watchdog default Worker #66 has
time to sleep -83
18/04/06 04:15:01 ERROR smtpserver: SMTP Connection has idled out.
18/04/06 04:15:01 DEBUG smtpserver: Watchdog default Worker #66 is
exiting run().
18/04/06 04:48:27 ERROR smtpserver: Unknown error occurred while
processing DATA.
javax.mail.MessagingException: Unable to retrieve the data: Socket closed;
nested exception is:
java.net.SocketException: Socket closed
at
org.apache.james.core.MimeMessageInputStreamSource.<init>(MimeMessageInputStreamSource.java:76)
at org.apache.james.core.MailImpl.<init>(MailImpl.java:142)
at
org.apache.james.smtpserver.SMTPHandler.processMail(SMTPHandler.java:1437)
at
org.apache.james.smtpserver.SMTPHandler.doDATA(SMTPHandler.java:1289)
at
org.apache.james.smtpserver.SMTPHandler.parseCommand(SMTPHandler.java:589)
at
org.apache.james.smtpserver.SMTPHandler.handleConnection(SMTPHandler.java:358)
at
org.apache.james.util.connection.ServerConnection$ClientConnectionRunner.run(ServerConnection.java:417)
at
org.apache.james.util.thread.ExecutableRunnable.execute(ExecutableRunnable.java:55)
at
org.apache.james.util.thread.WorkerThread.run(WorkerThread.java:90)
18/04/06 04:48:27 DEBUG smtpserver: Sent: 451 Error processing
message: Unable to retrieve the data: Socket closed;
nested exception is:
java.net.SocketException: Socket closed
18/04/06 04:48:27 DEBUG smtpserver: Calling reset() for inactive watchdog
18/04/06 04:48:27 ERROR smtpserver: Socket to
bb220-255-153-237.singnet.com.sg (220.255.153.237) closed remotely.
java.net.SocketException: Socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at
java.io.BufferedInputStream.read1(BufferedInputStream.java:220)
at java.io.BufferedInputStream.read(BufferedInputStream.java:277)
at
sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:408)
at
sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:450)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:182)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.read(BufferedReader.java:157)
at
org.apache.james.util.CRLFTerminatedReader.readLine(CRLFTerminatedReader.java:98)
at
org.apache.james.smtpserver.SMTPHandler.readCommandLine(SMTPHandler.java:505)
at
org.apache.james.smtpserver.SMTPHandler.handleConnection(SMTPHandler.java:358)
at
org.apache.james.util.connection.ServerConnection$ClientConnectionRunner.run(ServerConnection.java:417)
at
org.apache.james.util.thread.ExecutableRunnable.execute(ExecutableRunnable.java:55)
at
org.apache.james.util.thread.WorkerThread.run(WorkerThread.java:90)
18/04/06 04:48:27 DEBUG smtpserver: Calling disposeWatchdog() for
inactive watchdog
18/04/06 04:48:27 DEBUG smtpserver: Returning SMTPHandler to pool.
18/04/06 04:48:27 DEBUG smtpserver: Returning a
org.apache.james.smtpserver.SMTPHandler to the pool
----------------------- etc -----------------------
Meanwhile, the "connections" log is going nuts, writing the same set
of "Maximum number of open connections exceeded - refusing connection"
messages over and over at a rate of 10MB per 3 minutes or so:
-rw-r--r-- 1 root root 10485738 Apr 22 12:38
connections-2006-04-22-12-28.log
-rw-r--r-- 1 root root 10485901 Apr 22 12:42
connections-2006-04-22-12-38.log
-rw-r--r-- 1 root root 10485974 Apr 22 12:46
connections-2006-04-22-12-42.log
-rw-r--r-- 1 root root 10485856 Apr 22 12:49
connections-2006-04-22-12-46.log
-rw-r--r-- 1 root root 10485895 Apr 22 12:53
connections-2006-04-22-12-49.log
-rw-r--r-- 1 root root 10485957 Apr 22 12:56
connections-2006-04-22-12-53.log
-rw-r--r-- 1 root root 10485832 Apr 22 12:58
connections-2006-04-22-12-56.log
-rw-r--r-- 1 root root 10485985 Apr 22 13:01
connections-2006-04-22-12-58.log
-rw-r--r-- 1 root root 10485979 Apr 22 13:03
connections-2006-04-22-13-01.log
-rw-r--r-- 1 root root 10485818 Apr 22 13:04
connections-2006-04-22-13-03.log
-rw-r--r-- 1 root root 10485955 Apr 22 13:06
connections-2006-04-22-13-04.log
-rw-r--r-- 1 root root 10485911 Apr 22 13:08
connections-2006-04-22-13-06.log
-rw-r--r-- 1 root root 10485815 Apr 22 13:11
connections-2006-04-22-13-08.log
-rw-r--r-- 1 root root 8468986 Apr 22 13:13
connections-2006-04-22-13-11.log
Time now is Apr 22 13:13.
I've got netstat dumps if anyone wants to take a look.
I was right about it taking 10 more minuts or so, as I type, James
just woke up.
Anybody got any clue?
Thanks,
Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
Re: smtp hung and took 10 hours to start back up again
Posted by Nathan Cheng <na...@yahoo.com>.
Noel J. Bergman wrote:
> Have you used netstat to confirm the IP stack's view of things and comapare
> it with what JAMES thinks is going on? I have seen a problems with spammers
> who run massively parallel attacks, and then leave without saying goodbye.
> There are some things that can be done to tune TCP/IP to help, depending
> upon your OS. And you can consider blocking attackers at the firewall.
I was watching netstat, but sorry, I didn't save my buffer. I didn't
try to match them up, but I didn't see a whole lot coming from one
source. Is there a system log file that would show any useful info? OS is:
Red Hat Enterprise Linux ES release 3 (Taroon Update 7)
Are you suggesting a DDoS? What troubles me is that James just keeps
complaining about max connections reached, but doesn't do anything
with the ones it does have. Is it reasonable for James to respond in
this way even under a DDoS?
Thanks,
Nathan
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org
RE: smtp hung and took 10 hours to start back up again
Posted by "Noel J. Bergman" <no...@devtech.com>.
Nathan Cheng wrote:
> the "connection" log at times grew at 5MB per minute, repeating
> the EXACT SAME 42 LINES over and over and over again without so
> much as a pause.
Unless there is a weird bug that needs to get fixed ASAP, JAMES will only
print out that message upon receiving an attempted connection.
Have you used netstat to confirm the IP stack's view of things and comapare
it with what JAMES thinks is going on? I have seen a problems with spammers
who run massively parallel attacks, and then leave without saying goodbye.
There are some things that can be done to tune TCP/IP to help, depending
upon your OS. And you can consider blocking attackers at the firewall.
--- Noel
---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org