Re: Mail spooled but not processed

[Eric Charles]

On the broken server, you can launch a jmx console, go to MBeans tab, 
open the org.apache.activemq.james.Queue.spool/outgoing tree.

There are attributes and operations such as browseMessages, getMessage...
I never did that, but I can imagine you could invoke the copyMessage to 
the spool queue, so it will be successfully respooled #hack.

Thx.

On 16/09/11 16:23, Simon A wrote:
Raju's stack dump indicated that he was running HotSpot 14.0 Client
mode. If possible try running on a more recent Oracle JDK VM in Server
mode.

If that's not an option try adding -XX:+UseMembar to your startup.sh
and restart James.
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6822370

Cheers,
Simon

On Sat, Sep 17, 2011 at 8:40 AM, Zach Cox<zcox...@gmail.com>  wrote:
After restarting James several times, 1) all mails continued to be
spooled, and 2) not all mails previously spooled were actually sent
out after restart.  Thus, I had to run a new James server and point
DNS to it.

But I did not terminate the broken server, so it is still there for
debugging purposes.

Please let me know what information I can pull off of that broken
James server to help find a resolution to this severe problem.

Thanks,
Zach



On Fri, Sep 16, 2011 at 4:56 PM, Zach Cox<zcox...@gmail.com>  wrote:
James is currently spooling all of our incoming email and not
processing it.  I took 4 jstack dumps. Anything else I can look at
quickly before I have to restart James?



On Fri, Sep 16, 2011 at 6:58 AM, Zach Cox<zcox...@gmail.com>  wrote:
mailetcontainer.xml has:

  <spooler>
    <threads>  20</threads>
  </spooler>

After running all night, there are still only 4 blocked Camel threads,
and for the most part James appears to be processing all emails
properly. I will do some more testing this morning, and try to force a
bunch of these HTTP requests and see if I can lock it up.

Just taking another look at our stack trace. In this mailet, we use
DefaultHttpClient with ThreadSafeClientConnManager. I know this is not
the Apache HttpClient mailing list, but does this mean it's not
blocking on a request with no response, but it's blocking just trying
to get a connection from the connection pool?

  java.lang.Thread.State: WAITING (parking)
       at sun.misc.Unsafe.park(Native Method)
       - parking to wait for<0x7aff2ee0>  (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
       at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
       at 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
       at 
org.apache.http.impl.conn.tsccm.WaitingThread.await(WaitingThread.java:158)
       at 
org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking(ConnPoolByRoute.java:403)
       at 
org.apache.http.impl.conn.tsccm.ConnPoolByRoute$1.getPoolEntry(ConnPoolByRoute.java:300)
       at 
org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection(ThreadSafeClientConnManager.java:224)
       at 
org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:401)
       at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
       at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
       at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)

That stack trace looks almost identical up towards the top as all of
the other "normal" Camel threads like this one:

"Camel Thread 72 - Split" prio=10 tid=0x0a1ebc00 nid=0x10b5 waiting on
condition [0xb0e7a000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for<0x7a6a2ca0>  (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
        at 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
        at 
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)
        at 
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
        at 
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
        at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:679)

I just want to make sure I understand how exactly this mailet is blocking.

Thanks,
Zach






On Fri, Sep 16, 2011 at 12:16 AM, Norman Maurer
<norman.mau...@googlemail.com>  wrote:
Hi there,

how many spooling threads did you specifiy in mailetcontainer.xml ?

About the split threads... If a Matcher "split" and email into parts
Camel will process this new parts in seperate threads. And no, 4
blocked threads should not block all the others.

Bye,
Norman


2011/9/16 Zach Cox<zcox...@gmail.com>:
I just noticed James starting to spool some emails and did some
jstacks. I found several threads like this:

"Camel Thread 65 - Split" prio=10 tid=0x0a1c1400 nid=0x10ae waiting on
condition [0xb105f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for<0x7aff2ee0>  (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
        at 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
        at 
org.apache.http.impl.conn.tsccm.WaitingThread.await(WaitingThread.java:158)
        at 
org.apache.http.impl.conn.tsccm.ConnPoolByRoute.getEntryBlocking(ConnPoolByRoute.java:403)
        at 
org.apache.http.impl.conn.tsccm.ConnPoolByRoute$1.getPoolEntry(ConnPoolByRoute.java:300)
        at 
org.apache.http.impl.conn.tsccm.ThreadSafeClientConnManager$1.getConnection(ThreadSafeClientConnManager.java:224)
        at 
org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:401)
        at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:820)
        at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:754)
        at 
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:732)
<rest is redacted>


One of our custom mailets makes an HTTP request to a 3rd party site.
Usually this works fine, but apparently sometimes this other site does
not send back an HTTP response, keeps the request open forever, and
the Apache HttpClient is not doing any kind of timeouts, so this
request stays open and seems to block a thread forever.

What exactly do these 200 Camel Threads do?  Currently we have 4 Camel
threads blocked like this.  But I wouldn't think 4 out of 200 would
cause James to stop processing all incoming emails? James is still
processing some emails, but stuck on others. We will let James run all
night, and see if eventually all 200 get blocked.

Anyways, wanted to share this.  In the morning we will add timeouts to
these HTTP requests (as well as any others we do) and see if that
helps things.

Thanks,
Zach





On Thu, Sep 15, 2011 at 6:27 PM, Raju Buchi<raju.bu...@contentpilot.net>  wrote:
I guess the attachment was sent over. I have created a Bug report.

https://issues.apache.org/jira/browse/JAMES-1317

- Raju

On Thu, Sep 15, 2011 at 6:12 PM, Raju Buchi<raju.bu...@contentpilot.net>  wrote:
Hi

I have got the issue again today where the mails are stuck in spool
and all the mails sent to the server will just say
INFO  19:02:25,581 | james.smtpserver | ID=17053510 Successfully
spooled mail Mail1316127745577-3dd610ec-2f53-4dcd-ad87-fa9b8401d84b
from ...............


But those mails will never be sent out.

I tried to run jstack as Norman mentioned and exported the output
(Attached File).

Please let me know if we can figure out what the issue is.

Thanks

- Raju



On Thu, Sep 15, 2011 at 3:17 PM, Zach Cox<zcox...@gmail.com>  wrote:
jstack requires a JDK to be installed, not just a JRE (as I discovered
earlier today).


On Thu, Sep 15, 2011 at 2:59 PM, Raju Buchi<raju.bu...@contentpilot.net>  wrote:
The mails are now stuck up in spool on my server. Can any one tell me how to
debug. I tried to use jstack, but it says jstack: command not found.

- Raju

On Thu, Sep 15, 2011 at 1:16 PM, Zach Cox<zcox...@gmail.com>  wrote:

OK so the cause of this shutdown problem was setting jmx.address=
public IP address of the server in conf/jmx.properties.  Just had the
exact same problem on a fresh install of James. I changed jmx.address
back to 127.0.0.1 and James now starts up properly.

There is also no mention of anything related to jmx in the logs when
James is unable to start up because of using the public IP address for
jmx.address.




On Thu, Sep 15, 2011 at 1:02 PM, Zach Cox<zcox...@gmail.com>  wrote:
Sorry, had to replace that EC2 instance with a new one, need to keep
emails flowing...

So that server is gone, but we still have all of the logs.

If this happens again I will try moving activemq dir.

Thanks,
Zach


On Thu, Sep 15, 2011 at 1:00 PM, Norman Maurer
<norman.mau...@googlemail.com>  wrote:
Hmm..

never saw this problem. But could you try to move the activemq dir out
of the way.

# mv /path/to/james/var/store/activemq
/path/to/james/var/store/activemq.crc

After that try to start again..

Bye,
Norman


2011/9/15 Zach Cox<zcox...@gmail.com>:
And now every time I start James, after it completes startup, it just
shuts down:


2011-09-15 17:56:26  INFO smtpserver:? - Init SMTP Service done
2011-09-15 17:56:26 DEBUG ConfigurationUtils:? -
ConfigurationUtils.locate(): base is null, name is null
2011-09-15 17:56:26  INFO lmtpserver:? - LMTP Service disabled by
configuration
2011-09-15 17:56:26 DEBUG ConfigurationUtils:? -
ConfigurationUtils.locate(): base is null, name is null
2011-09-15 17:56:26  INFO pop3server:? - POP3 Service disabled by
configuration
2011-09-15 17:56:27 DEBUG ConfigurationUtils:? -
ConfigurationUtils.locate(): base is null, name is null
2011-09-15 17:56:27  INFO imapserver:? - IMAP Service disabled by
configuration
2011-09-15 17:56:27 DEBUG ConfigurationUtils:? -
ConfigurationUtils.locate(): base is null, name is null
2011-09-15 17:56:27  INFO usersrepository23:? - Init
org.apache.james.repository.file.FilePersistentObjectRepository Store
2011-09-15 17:56:27  INFO usersrepository23:? -
org.apache.james.repository.file.FilePersistentObjectRepository opened
in ../var/users
2011-09-15 17:56:27 DEBUG usersrepository23:? -
org.apache.james.user.file.UsersFileRepository created in
file://var/users/
2011-09-15 17:56:27  INFO imapserver:? - Dispose IMAP Service
2011-09-15 17:56:27  INFO imapserver:? - Dispose IMAP Service done
2011-09-15 17:56:27  INFO pop3server:? - Dispose POP3 Service
2011-09-15 17:56:27  INFO pop3server:? - Dispose POP3 Service done
2011-09-15 17:56:27  INFO lmtpserver:? - Dispose LMTP Service
2011-09-15 17:56:27  INFO lmtpserver:? - Dispose LMTP Service done
2011-09-15 17:56:27  INFO smtpserver:? - Dispose SMTP Service
2011-09-15 17:56:27  INFO smtpserver:? - Dispose SMTP Service done
2011-09-15 17:56:27  INFO mailspooler:? -
org.apache.james.mailetcontainer.impl.JamesMailSpooler dispose...
2011-09-15 17:56:27  INFO mailspooler:? - Stop
org.apache.james.mailetcontainer.impl.JamesMailSpooler: dequeuer-1
2011-09-15 17:56:27  INFO mailspooler:? - Stop
org.apache.james.mailetcontainer.impl.JamesMailSpooler: dequeuer-2
2011-09-15 17:56:27  INFO mailspooler:? -
org.apache.james.mailetcontainer.impl.JamesMailSpooler thread shutdown
completed.
2011-09-15 17:56:30  INFO SocketNode:94 - Caught java.io.EOFException
closing conneciton.


Any advice would be greatly appreciated.



On Thu, Sep 15, 2011 at 12:54 PM, Zach Cox<zcox...@gmail.com>  wrote:
OK now several minutes after I restarted James, everything was working
fine, then all of a sudden I see this while tailing james-server.log:

2011-09-15 17:51:24  WARN DefaultShutdownStrategy:? - Timeout
occurred. Now forcing the routes to be shutdown now.
2011-09-15 17:51:24  WARN DefaultShutdownStrategy:? - Interrupted
while waiting during graceful shutdown, will force shutdown now.
2011-09-15 17:51:24  WARN DefaultInflightRepository:? - Shutting down
while there are still 8 in flight exchanges.
2011-09-15 17:51:26  INFO SocketNode:94 - Caught java.io.EOFException
closing conneciton.


And James just shuts down.  This is incredibly bad to have a mail
server just shut down out of the blue...



On Thu, Sep 15, 2011 at 12:46 PM, Zach Cox<zcox...@gmail.com>  wrote:
Also when James is starting up I see this in logs:

2011-09-15 17:45:05  WARN AMQPersistenceAdapter:? - The
ReferenceStore
is not valid - recovering ...


I'm guessing that's not a good thing?


On Thu, Sep 15, 2011 at 11:54 AM, Zach Cox<zcox...@gmail.com>
wrote:
I don't think we're seeing the problem again yet, but I just had to
restart James and noticed this on shutdown:

2011-09-15 16:48:31  INFO JamesServerApplicationContext:? - Closing

org.apache.james.container.spring.context.JamesServerApplicationContext@86fe26
:
startup date [Thu Sep 15 12:20:21 UTC 2011]; root of context
hierarchy
2011-09-15 16:48:31  INFO imapserver:? - Dispose IMAP Service
2011-09-15 16:48:31  INFO imapserver:? - Dispose IMAP Service done
2011-09-15 16:48:31  INFO pop3server:? - Dispose POP3 Service
2011-09-15 16:48:31  INFO pop3server:? - Dispose POP3 Service done
2011-09-15 16:48:31  INFO lmtpserver:? - Dispose LMTP Service
2011-09-15 16:48:31  INFO lmtpserver:? - Dispose LMTP Service done
2011-09-15 16:48:31  INFO smtpserver:? - Dispose SMTP Service
2011-09-15 16:48:31  INFO smtpserver:? - Dispose SMTP Service done
2011-09-15 16:48:31  INFO mailspooler:? -
org.apache.james.mailetcontainer.impl.JamesMailSpooler dispose...
2011-09-15 16:48:32  INFO mailspooler:? - Stop
org.apache.james.mailetcontainer.impl.JamesMailSpooler: dequeuer-2
2011-09-15 16:48:32  INFO mailspooler:? - Stop
org.apache.james.mailetcontainer.impl.JamesMailSpooler: dequeuer-1
2011-09-15 16:48:51  INFO SocketNode:94 - Caught
java.io.EOFException
closing conneciton.


Is that java.io.EOFException normal and expected? Or is it a sign of
some problems?

Thanks,
Zach





On Thu, Sep 15, 2011 at 8:35 AM, Norman Maurer
<norman.mau...@googlemail.com>  wrote:
Using:

# jstack<pid>


Please take 3 within on minute ...

Bye,
Norman

2011/9/15 Zach Cox<zcox...@gmail.com>:
I had to restart James several times this morning so nothing is
blocked at the moment.

There is nothing indicated in the log files. Things look normal,
and
then they look like this:

2011-09-15 01:25:26  INFO smtpserver:? - ID=8443803 Connection
established from x
2011-09-15 01:25:31  INFO smtpserver:? - ID=8443803 Successfully
spooled mail
Mail1316049931087-05b8199e-e01f-4d14-84d5-3d7ac2443bb3
from x on x for [x]
2011-09-15 01:25:36  INFO smtpserver:? - ID=8443803 Connection
closed for x
2011-09-15 01:25:47  INFO smtpserver:? - ID=11521429 Connection
established from x
2011-09-15 01:25:48  INFO smtpserver:? - ID=11521429 Successfully
spooled mail
Mail1316049948254-abd67e8f-bafe-41ab-8eef-c551420fd56e
from x on x for [x]
2011-09-15 01:25:48  INFO smtpserver:? - ID=11521429 Connection
closed for x
2011-09-15 01:26:41  INFO smtpserver:? - ID=5675333 Connection
established from x
2011-09-15 01:26:52  INFO smtpserver:? - ID=5675333 Successfully
spooled mail
Mail1316050012621-522b1f2a-2851-46fb-940c-711591f637cc
from x on x for [x]
2011-09-15 01:26:57  INFO smtpserver:? - ID=5675333 Connection
closed for x
2011-09-15 01:27:52  INFO smtpserver:? - ID=33404412 Connection
established from localhost (127.0.0.1)
2011-09-15 01:27:52  INFO smtpserver:? - ID=33404412 Connection
closed
for localhost (127.0.0.1)
2011-09-15 01:28:12  INFO smtpserver:? - ID=11673762 Connection
established from x
2011-09-15 01:28:22  INFO smtpserver:? - ID=11673762 Successfully
spooled mail
Mail1316050102393-6fcc21aa-8f32-4935-b0eb-df892d54a5e8
from x on x for [x]
2011-09-15 01:28:27  INFO smtpserver:? - ID=11673762 Connection
closed for x

So every mail that comes in just gets spooled and not processed.

When this starts happening again, what's the best way to take a
thread
dump from James?

Thanks,
Zach


On Thu, Sep 15, 2011 at 8:13 AM, Norman Maurer
<norman.mau...@googlemail.com>  wrote:
Hi there,

please take a thread-dump to see why its blocked...

Anything in the logs ?

Bye,
Norman


2011/9/15 Zach Cox<zcox...@gmail.com>:
We upgraded to James 3.0-beta3 on Tuesday night. Things worked
fine
until around 9pm last night, where exactly the same problem
started
occurring: mail would get spooled, but not processed.  After
restarting James, some of the mail was then processed
successfully,
but most was lost.

We consider this an emergency situation for our company and need
to
find a resolution ASAP. What kind of information can we provide
to
help find a resolution? If financial resources need to be
involved to
find a resolution or move things along, that is an option.

Any help is most greatly appreciated.

Thanks,
Zach


On Tue, Sep 13, 2011 at 12:41 PM, Norman Maurer
<norman.mau...@googlemail.com>  wrote:
No problems...

If you still can replicate then please open a issue with a
stack trace
attached..

Bye,
Norman


2011/9/13 Raju Buchi<raju.bu...@contentpilot.net>:
James 3.0-M2. I will try to stand up a new server with beta3
and see if I
can replicate the issue.

Thanks

- Raju

On Tue, Sep 13, 2011 at 12:37 PM, Norman Maurer<
norman.mau...@googlemail.com>  wrote:

Do you use beta3 ?

Bye,
Norman


2011/9/13 Raju Buchi<raju.bu...@contentpilot.net>:
Hello

We are also facing exactly the same issues. Tried to debug
my custom
mailets
and seems to be everything is working fine. Logs did not
show any
exception
messages except it will always spool a mail and will never
attempt to
send
it. i.e. all mails are stuck in the spool.

- Raju

On Tue, Sep 13, 2011 at 12:20 PM, Zach Cox<
zcox...@gmail.com>  wrote:

We are having a severe problem with James 3.0-M2 where it
will operate
correctly for hours or days, and then all of a sudden it
will not
process a lot of the mail it spools.  Sometimes it will
not process
*any* mail that it spools, and other times it will spool a
bunch of
mail, and then process others seemingly at random.  I have
to restart
James to get that spooled mail to be processed.  But even
then,
sometimes the spooled mail is completely lost after a
restart.  I have
seen several other threads lately with similar problems,
but they
haven't helped our situation.

We do not store mail in James for personal accounts and we
have IMAP&
POP3 disabled.  Every inbound email has one of two things
done to it:
  - it is processed locally by custom mailets&  matchers
  - or it is relayed to our corporate Google Apps account

A previous thread recommended checking all custom mailets
and
matchers.  As far as I can tell, they are all working
properly.  There
are no exceptions or errors in log/james-server.log, and
in the
scenario where James spools some mail&  processes others,
the mail
that is processed is handled properly by our custom
mailets&
matchers.

I've tried connecting to James JMX remotely via JConsole
but have not
been able to connect.  Which port does James run JMX on?
  Any help
with JMX would be appreciated.

Does anyone have any other ideas about what we should look
for?  I
noticed 3.0-beta3 is out now, were there fixes in beta3
related to
mail being spooled but not processed?

Thanks,
Zach


---------------------------------------------------------------------
To unsubscribe, e-mail:
server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org





---------------------------------------------------------------------
To unsubscribe, e-mail:
server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org





---------------------------------------------------------------------
To unsubscribe, e-mail:
server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail:
server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail:
server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org






---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org




---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org





--

Raju Buchi
Web Developer | Content Pilot LLC
Mobile: 817.313.2578
Email: raju...@gmail.com | raju.bu...@contentpilot.net
Website: http://www.rajubuchi.com




--

Raju Buchi
Web Developer | Content Pilot LLC
Mobile: 817.313.2578
Email: raju...@gmail.com | raju.bu...@contentpilot.net
Website: http://www.rajubuchi.com

---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org





---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org


--
Eric
http://about.echarles.net

---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscr...@james.apache.org
For additional commands, e-mail: server-user-h...@james.apache.org