NullPointerException in com.sun.mail.iap.Response.parse
Hey all. I am accessing an IMAP mail server from Solaris 8 using java 1.5.0-08, but I intermittently get the following exception:
java.lang.NullPointerException
at com.sun.mail.iap.Response.parse(Response.java:130)
at com.sun.mail.iap.Response.<init>(Response.java:87)
at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:48)
at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:122)
at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:230)
at com.sun.mail.iap.Protocol.command(Protocol.java:263)
at com.sun.mail.iap.Protocol.simpleCommand(Protocol.java:310)
at com.sun.mail.imap.protocol.IMAPProtocol.close(IMAPProtocol.java:926)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:1000)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:935)
Any thoughts of what I am doing wrong?
Turn on debugging and get a protocol trace (and post it here if the issue isn't 100% apparent when you see it).
See the FAQ if you need info on how to do this.
Basically, this means that Javamail is having problems parsing the message from the server (I've seen a malformed virus email cause a very similar situation), altho this could be something else.
Thanks for the information. I turned it on, now I get all sorts of output.
One thing I forgot to mention in my original post is that this is a multithreaded application. I create one IMAP connection per thread and start downloading mail. After a while of that, the errors start happening. Because I have 20 or so threads, the debugging output of each thread is interleaved with every other thread. Is there a anything in particular I should be looking for?
Thanks!
For debugging purposes, you might want to try creating a separate JavaMail
Session for each thread, and using Session.setDebugOut to direct the
debug output for each session into a different file.
If you existing debug output includes the entire protocol trace, along with
an error message of some sort from your application when it gets the
exception, it might be possible to find a nearby protocol response that is
causing the problem. Feel free to post the protocol trace or send it to
javamail@sun.com and we'll help you sort through it.
BTW, what server (what vendor) are you using?
I might have a line on figuring this out. I am transferring a message with large attachments (25876kB total). I also have a connection timeout of 600 seconds set (as well as a monitor thread that sends an interrupt if the thread goes too long). I consistently get the error when trying to download this file. Would some strange thing happen in the response if the connection is cut?
Thanks for all your help!
Good call on separate debug files, much easier!
I got this from one of the files. It looks like it is transferring the body of an email, then stops in the middle. Then both close and exists will throw a NullPointerException.
Peter, please let me know if you are available this Monday or Tuesday.
My suggestioA430 CLOSE
DEBUG: added an Authenticated connection -- size: 1
java.lang.NullPointerException
at com.sun.mail.iap.Response.parse(Response.java:130)
at com.sun.mail.iap.Response.<init>(Response.java:87)
at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:48)
at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:122)
at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:230)
at com.sun.mail.iap.Protocol.command(Protocol.java:263)
at com.sun.mail.iap.Protocol.simpleCommand(Protocol.java:310)
at com.sun.mail.imap.protocol.IMAPProtocol.close(IMAPProtocol.java:926)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:1000)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:935)
A431 LIST "" shared
java.lang.NullPointerException
at com.sun.mail.iap.Response.parse(Response.java:130)
at com.sun.mail.iap.Response.<init>(Response.java:87)
at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:48)
at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:122)
at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:230)
at com.sun.mail.iap.Protocol.command(Protocol.java:263)
at com.sun.mail.imap.protocol.IMAPProtocol.doList(IMAPProtocol.java:799)
at com.sun.mail.imap.protocol.IMAPProtocol.list(IMAPProtocol.java:776)
at com.sun.mail.imap.IMAPFolder$1.doCommand(IMAPFolder.java:429)
at com.sun.mail.imap.IMAPFolder.doProtocolCommand(IMAPFolder.java:2387)
at com.sun.mail.imap.IMAPFolder.doCommand(IMAPFolder.java:2332)
at com.sun.mail.imap.IMAPFolder.exists(IMAPFolder.java:427)
I don't understand what's going on at the beginning of the debug output
you posted. I'd like to see a few of the IMAP commands before that
point. It also looks like two debug messages are interleaved. Are you
sure each thead is using a separate debug output file, and nothing else
is writing to those files?
The connection timeout shouldn't be triggering during such an operation.
Your monitor thread could be interrupting the operation. Changing the
timeout for that would be a good debugging step. It's hard to say what
all could go wrong if you interrupt a thread in the middle of an I/O operation.
In general, I would expect the I/O operation to throw an exception, which
would make its way up the chain of method calls without causing anything
to try to parse an incomplete message. But of course it's always possible
that there's a bug in this error handling!
Sure thing. More information is inline below. Hope it is OK if I snip any personal information.
Yes, each thread seems to be correctly writing to its own file (I have a class-static counter that each thread pulls from when it is instantiated, and I create a file of the form debug-file-X).
A421 CLOSE
A421 OK Completed
DEBUG: added an Authenticated connection -- size: 1
A422 LIST "" shared
* LIST (\Noselect \HasChildren) "." "shared"
A422 OK Completed (0.000 secs 2 calls)
A423 LIST "" shared.support
* LIST (\HasNoChildren) "." "shared.support"
A423 OK Completed (0.000 secs 2 calls)
A424 LIST "" shared.support.956
A424 OK Completed (0.000 secs 1 calls)
DEBUG: connection available -- size: 1
A425 EXAMINE shared.support
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen $Forwarded $NotJunk JunkRecorded $Junk $MDNSent NotJunk NonJunk $Label5 $Label1 $Label2 $Label3 $Label4 Junk)
* OK [PERMANENTFLAGS ()]
* 9975 EXISTS
* 9975 RECENT
* OK [UNSEEN 1]
* OK [UIDVALIDITY 1126903962]
* OK [UIDNEXT 11932]
A425 OK [READ-ONLY] Completed
A426 UID FETCH 956 (UID)
* 861 FETCH (UID 956)
A426 OK Completed (0.000 sec)
A427 GETACL shared.support
* ACL shared.support ...snipped...
A427 OK Completed
A428 FETCH 861 (FLAGS)
* 861 FETCH (FLAGS (\Recent $NotJunk JunkRecorded NotJunk $Label5))
A428 OK Completed (0.000 sec)
A429 FETCH 861 (BODY[])
* 861 FETCH (BODY[] {15069313}
Return-Path: <xxxxx@vivisimo.com>
...snipped body...
Peter, please let me know if you are available this Monday or Tuesday.
My suggestioA430 CLOSE
> In general, I would expect the I/O operation to throw
> an exception, which
> would make its way up the chain of method calls
> without causing anything
> to try to parse an incomplete message.
That is what I would expect as well. I also check the Thread.isInterrupted() status, and it does not report that it is interrupted. The timeout is currently set at 600 seconds, and I don't think that this particular email is reaching 10 minutes.
I still don't really understand what's happening with that debug output...
Again, what IMAP server are you using?
What operating system and JDK version are you using?
From the debug output it appears that you're fetching a message
that's 15069313 bytes, i.e., 15MB. How many bytes appear in
the debug output counting from the line after that FETCH response
up to the "A430 CLOSE"?
One theory is that the server is sending more data than the client
is expecting, which casuses all subsequent reads looking for
responses to commands to be "out of sync".
I can easily fix JavaMail to avoid the NPE (and I will), but that alone
won't solve your problem. Something is still going very wrong with the
protocol between the client and the server and I can't tell what.
I'd love to get a copy of the entire 15MB response to the FETCH command
so that I could examine it in more detail. You can obfuscate as much content
as you want, as long as you don't change the number of characters in the
response. You could send it to javamail@sun.com. I'm not sure that will
tell me what's wrong, but I'm running out of ideas.
> Again, what IMAP server are you using?
Cyrus IMAP4 v2.2.12-Invoca-RPM-2.2.12-3.RHEL4.1 server ready
> What operating system and JDK version are you using?
This appears to happen over a few different platforms, 64-bit linux 2.6.9 , 32-bit solaris 8, some version of Windows (don't remember at the moment ;-)). All using JDK and JRE 1.5.0-08.
> From the debug output it appears that you're fetching
> a message
> that's 15069313 bytes, i.e., 15MB.
Yep, it is a message with 3 attachments.
> How many bytes
> appear in
> the debug output counting from the line after that
> FETCH response
> up to the "A430 CLOSE"?
I'll get this for you first thing in the morning.
> One theory is that the server is sending more data
> than the client
> is expecting, which casuses all subsequent reads
> looking for
> responses to commands to be "out of sync".
>
> I can easily fix JavaMail to avoid the NPE (and I
> will), but that alone
> won't solve your problem. Something is still going
> very wrong with the
> protocol between the client and the server and I
> can't tell what.
>
> I'd love to get a copy of the entire 15MB response to
> the FETCH command
> so that I could examine it in more detail. You can
> obfuscate as much content
> as you want, as long as you don't change the number
> of characters in the
> response. You could send it to javamail@sun.com.
> I'm not sure that will
> ell me what's wrong, but I'm running out of ideas.
Do you think that the particular data for this message will be useful? It doesn't always happen with this particular message, this is just the one I caught on the last run.
> Do you think that the particular data for this
> message will be useful? It doesn't always happen with
> this particular message, this is just the one I
> caught on the last run.
I don't know.
If you have another test message that shows the problem,
that would be fine too. I'm just looking for more data to get
a handle on the problem.
> I'm just looking for more data to get
> a handle on the problem.
I ran my program again, and got a NPE on another email. It is also big...
A479 FETCH 856 (BODY[])
* 856 FETCH (BODY[] {26497359}
Return-Path: <xxx@nsc.com>
... some of the body ...
BTW, the ebinder subcollection is not in the select list. Do I have to configure
or create another foA480 CLOSE
DEBUG: added an Authenticated connection -- size: 1
java.lang.NullPointerException
at com.sun.mail.iap.Response.parse(Response.java:130)
at com.sun.mail.iap.Response.<init>(Response.java:87)
at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:48)
at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:122)
at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:230)
at com.sun.mail.iap.Protocol.command(Protocol.java:263)
at com.sun.mail.iap.Protocol.simpleCommand(Protocol.java:310)
at com.sun.mail.imap.protocol.IMAPProtocol.close(IMAPProtocol.java:926)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:1000)
at com.sun.mail.imap.IMAPFolder.close(IMAPFolder.java:935)
A481 LIST "" shared
java.lang.NullPointerException
at com.sun.mail.iap.Response.parse(Response.java:130)
at com.sun.mail.iap.Response.<init>(Response.java:87)
at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:48)
at com.sun.mail.imap.protocol.IMAPResponse.readResponse(IMAPResponse.java:122)
at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:230)
at com.sun.mail.iap.Protocol.command(Protocol.java:263)
at com.sun.mail.imap.protocol.IMAPProtocol.doList(IMAPProtocol.java:799)
at com.sun.mail.imap.protocol.IMAPProtocol.list(IMAPProtocol.java:776)
at com.sun.mail.imap.IMAPFolder$1.doCommand(IMAPFolder.java:429)
at com.sun.mail.imap.IMAPFolder.doProtocolCommand(IMAPFolder.java:2387)
at com.sun.mail.imap.IMAPFolder.doCommand(IMAPFolder.java:2332)
at com.sun.mail.imap.IMAPFolder.exists(IMAPFolder.java:427)
... lots of these ...
A490 LIST "" shared
rm or resource or something to solve this problem? please
advice.
(See attached file: private-xml.rtf)(See attached file: private-html.rtf)(See
... more body from the first email ...
And this process of getting little chunks of data seems to continue on, interspersed with NPEs. It looks like some connection is not being closed.
I just got word from our IT guy that there are no errors in the mail server logs that indicate anything probative.
> Changing the timeout for that would be a good debugging step.I have removed both my interrupt code and the setting of the mail.imap.connectiontimeout & mail.imap.timeout properties. I still get the same style of errors.
I get the same error on a Windows machine, but when I ran it on my AMD64 box, everything seemed peachy.
The interspersed debug output suggests to me that more than one
thread is writing to the same output file. If you believe you're creating
a new Session for each thread, here's a debugging technique you
could use to prove that only a single thread is using each file...
Subclass FileOutputStream. In the constructor save the current Thread
handle. Override the write methods. In each method, check that the
current Thread matches the saved Thread. If it doesn't, there's likely
a threading error in your application.
Still, all of this is about getting a clean debugging output so that I can
figure out why the parse is failing and throwing NPE. I'd still like to
see one of those complete debug logs...
> Subclass FileOutputStream. In the constructor save the
> current Thread handle. Override the write methods. In
> each method, check that the current Thread matches the
> saved Thread. If it doesn't, there's likely a threading error
> in your application.
Here is the debugging stream class, as suggested. I create this object when the constructor is called (which is called from a different thread, explaining why I do not set the owner thread in the constructor). The setOwnerThread method is called each time a message is processed, but should only ever be set the first time. Seems reasonable? There are no messages in the stderr log regarding the wrong owner.
private class DebugStream extends FileOutputStream
{
private Thread owner;
public DebugStream(File a)
throws FileNotFoundException
{
super(a);
}
public void setOwnerThread()
{
if (owner == null) {
owner = Thread.currentThread();
}
}
public void write(byte[] b)
throws IOException
{
if (Thread.currentThread() != owner) {
System.err.println("Wrong owner thread!");
} else {
super.write(b);
}
}
public void write(byte[] b, int off, int len)
throws IOException
{
if (Thread.currentThread() != owner) {
System.err.println("Wrong owner thread!");
} else {
super.write(b, off, len);
}
}
public void write(int b)
throws IOException
{
if (Thread.currentThread() != owner) {
System.err.println("Wrong owner thread!");
} else {
super.write(b);
}
}
}
> Still, all of this is about getting a clean debugging output
> so that I can figure out why the parse is failing and throwing
> NPE. I'd still like to see one of those complete debug logs...
I have reproduced the problem with non-sensitive information. I used `yes` to create a 24 MB text file. I then send that to myself as an attachment. I then sent myself ~7000 smaller emails (my signature, without any real text). I have 10 threads, the first one lists the directory and puts a (made-up) URL into a BlockingQueue. The other threads pull off a URL and list the email. You may be able to reproduce such a setup there. I believe that having a slower computer may be key. (Our Solaris 8 and Windows boxes are no speed champs, whereas our Linux boxes are noticeably faster).
I am emailing you a bzip of the stderr and each threads log files.
