Log recent network activities when IMAP parser crashes.

Added DiscourseLogger, which stores last N (currently 64) lines of IMAP
commands sent to the server and responses received from the server.

We dump it to logcat when the IMAP parser crashes, that is, a) getting a
RuntimeException in ImapFolder.fetch() or b) getting a Runtime/IOException
in ImapResponseParser.

Bug 2480227

Change-Id: I6b5a728a7df106627ec29bb3c7c04a97a99b444b
This commit is contained in:
Makoto Onuki 2010-03-08 11:59:14 -08:00
parent a5e2aa4057
commit 69ade70f2d
6 changed files with 376 additions and 37 deletions

View File

@ -20,6 +20,7 @@ import com.android.email.Email;
import com.android.email.FixedLengthInputStream;
import com.android.email.PeekableInputStream;
import com.android.email.mail.MessagingException;
import com.android.email.mail.transport.DiscourseLogger;
import com.android.email.mail.transport.LoggingInputStream;
import android.util.Config;
@ -40,49 +41,98 @@ public class ImapResponseParser {
// mDateTimeFormat is used only for parsing IMAP's FETCH ENVELOPE command, in which
// en_US-like date format is used like "01-Jan-2009 11:20:39 -0800", so this should be
// handled by Locale.US
SimpleDateFormat mDateTimeFormat = new SimpleDateFormat("dd-MMM-yyyy HH:mm:ss Z", Locale.US);
PeekableInputStream mIn;
InputStream mActiveLiteral;
private final SimpleDateFormat mDateTimeFormat =
new SimpleDateFormat("dd-MMM-yyyy HH:mm:ss Z", Locale.US);
private final PeekableInputStream mIn;
private InputStream mActiveLiteral;
public ImapResponseParser(InputStream in) {
/**
* To log network activities when the parser crashes.
*
* <p>We log all bytes received from the server, except for the part sent as literals.
*/
private final DiscourseLogger mDiscourseLogger;
public ImapResponseParser(InputStream in, DiscourseLogger discourseLogger) {
if (DEBUG_LOG_RAW_STREAM && Config.LOGD && Email.DEBUG) {
in = new LoggingInputStream(in);
}
this.mIn = new PeekableInputStream(in);
mDiscourseLogger = discourseLogger;
}
/**
* Read and return one byte from {@link #mIn}, and put it in {@link #mDiscourseLogger}.
* Return -1 when EOF.
*/
private int readByte() throws IOException {
int ret = mIn.read();
if (ret != -1) {
mDiscourseLogger.addReceivedByte(ret);
}
return ret;
}
/**
* Reads the next response available on the stream and returns an
* ImapResponse object that represents it.
*
* @return
* @throws IOException
* @return the parsed {@link ImapResponse} object.
*/
public ImapResponse readResponse() throws IOException {
ImapResponse response = new ImapResponse();
if (mActiveLiteral != null) {
while (mActiveLiteral.read() != -1)
;
mActiveLiteral = null;
}
int ch = mIn.peek();
if (ch == '*') {
parseUntaggedResponse();
readTokens(response);
} else if (ch == '+') {
response.mCommandContinuationRequested =
parseCommandContinuationRequest();
readTokens(response);
} else {
response.mTag = parseTaggedResponse();
readTokens(response);
}
if (Config.LOGD) {
if (Email.DEBUG) {
Log.d(Email.LOG_TAG, "<<< " + response.toString());
try {
ImapResponse response = new ImapResponse();
if (mActiveLiteral != null) {
while (mActiveLiteral.read() != -1)
;
mActiveLiteral = null;
}
int ch = mIn.peek();
if (ch == '*') {
parseUntaggedResponse();
readTokens(response);
} else if (ch == '+') {
response.mCommandContinuationRequested =
parseCommandContinuationRequest();
readTokens(response);
} else {
response.mTag = parseTaggedResponse();
readTokens(response);
}
if (Config.LOGD) {
if (Email.DEBUG) {
Log.d(Email.LOG_TAG, "<<< " + response.toString());
}
}
return response;
} catch (RuntimeException e) {
// Parser crash -- log network activities.
onParseError(e);
throw e;
} catch (IOException e) {
// Network error, or received an unexpected char.
onParseError(e);
throw e;
}
return response;
}
private void onParseError(Exception e) {
// Read a few more bytes, so that the log will contain some more context, even if the parser
// crashes in the middle of a response.
// This also makes sure the byte in question will be logged, no matter where it crashes.
// e.g. when parseAtom() peeks and finds at an unexpected char, it throws an exception
// before actually reading it.
// However, we don't want to read too much, because then it may get into an email message.
try {
for (int i = 0; i < 4; i++) {
int b = readByte();
if (b == -1 || b == '\n') {
break;
}
}
} catch (IOException ignore) {
}
Log.w(Email.LOG_TAG, "Exception detected: " + e.getMessage());
mDiscourseLogger.logLastDiscourse();
}
private void readTokens(ImapResponse response) throws IOException {
@ -215,7 +265,7 @@ public class ImapResponseParser {
}
return sb.toString();
} else {
sb.append((char)mIn.read());
sb.append((char)readByte());
}
}
}
@ -251,7 +301,7 @@ public class ImapResponseParser {
private String readStringUntil(char end) throws IOException {
StringBuffer sb = new StringBuffer();
int ch;
while ((ch = mIn.read()) != -1) {
while ((ch = readByte()) != -1) {
if (ch == end) {
return sb.toString();
} else {
@ -266,7 +316,7 @@ public class ImapResponseParser {
private int expect(char ch) throws IOException {
int d;
if ((d = mIn.read()) != ch) {
if ((d = readByte()) != ch) {
if (d == -1 && Config.LOGD && Email.DEBUG) {
Log.d(Email.LOG_TAG, "expect(): end of stream reached");
}

View File

@ -39,6 +39,7 @@ import com.android.email.mail.internet.MimeUtility;
import com.android.email.mail.store.ImapResponseParser.ImapList;
import com.android.email.mail.store.ImapResponseParser.ImapResponse;
import com.android.email.mail.transport.CountingOutputStream;
import com.android.email.mail.transport.DiscourseLogger;
import com.android.email.mail.transport.EOLConvertingOutputStream;
import com.android.email.mail.transport.MailTransport;
import com.beetstra.jutf7.CharsetProvider;
@ -791,8 +792,20 @@ public class ImapStore extends Store {
return messages.toArray(new Message[] {});
}
@Override
public void fetch(Message[] messages, FetchProfile fp, MessageRetrievalListener listener)
throws MessagingException {
try {
fetchInternal(messages, fp, listener);
} catch (RuntimeException e) { // Probably a parser error.
Log.w(Email.LOG_TAG, "Exception detected: " + e.getMessage());
mConnection.logLastDiscourse();
throw e;
}
}
public void fetchInternal(Message[] messages, FetchProfile fp,
MessageRetrievalListener listener) throws MessagingException {
if (messages == null || messages.length == 0) {
return;
}
@ -1292,9 +1305,13 @@ public class ImapStore extends Store {
* A cacheable class that stores the details for a single IMAP connection.
*/
class ImapConnection {
private static final String IMAP_DEDACTED_LOG = "[IMAP command redacted]";
private Transport mTransport;
private ImapResponseParser mParser;
private int mNextCommandTag;
/** # of command/response lines to log upon crash. */
private static final int DISCOURSE_LOGGER_SIZE = 64;
private final DiscourseLogger mDiscourse = new DiscourseLogger(DISCOURSE_LOGGER_SIZE);
public void open() throws IOException, MessagingException {
if (mTransport != null && mTransport.isOpen()) {
@ -1312,7 +1329,7 @@ public class ImapStore extends Store {
mTransport.open();
mTransport.setSoTimeout(MailTransport.SOCKET_READ_TIMEOUT);
mParser = new ImapResponseParser(mTransport.getInputStream());
mParser = new ImapResponseParser(mTransport.getInputStream(), mDiscourse);
// BANNER
mParser.readResponse();
@ -1331,7 +1348,8 @@ public class ImapStore extends Store {
mTransport.reopenTls();
mTransport.setSoTimeout(MailTransport.SOCKET_READ_TIMEOUT);
mParser = new ImapResponseParser(mTransport.getInputStream());
mParser = new ImapResponseParser(mTransport.getInputStream(),
mDiscourse);
} else {
if (Config.LOGD && Email.DEBUG) {
Log.d(Email.LOG_TAG, "TLS not supported but required");
@ -1425,7 +1443,8 @@ public class ImapStore extends Store {
open();
String tag = Integer.toString(mNextCommandTag++);
String commandToSend = tag + " " + command;
mTransport.writeLine(commandToSend, sensitive ? "[IMAP command redacted]" : null);
mTransport.writeLine(commandToSend, sensitive ? IMAP_DEDACTED_LOG : null);
mDiscourse.addSentCommand(sensitive ? IMAP_DEDACTED_LOG : commandToSend);
return tag;
}
@ -1464,6 +1483,11 @@ public class ImapStore extends Store {
}
return responses;
}
/** @see ImapResponseParser#logLastDiscourse() */
public void logLastDiscourse() {
mDiscourse.logLastDiscourse();
}
}
class ImapMessage extends MimeMessage {

View File

@ -0,0 +1,120 @@
/*
* Copyright (C) 2010 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.android.email.mail.transport;
import com.android.email.Email;
import android.util.Log;
import java.util.ArrayList;
/**
* A class to keep last N of lines sent to the server and responses received from the server.
* They are sent to logcat when {@link #logLastDiscourse} is called.
*
* <p>This class is used to log the recent network activities when a response parser crashes.
*/
public class DiscourseLogger {
private final int mBufferSize;
private String[] mBuffer;
private int mPos;
private final StringBuilder mReceivingLine = new StringBuilder(100);
public DiscourseLogger(int bufferSize) {
mBufferSize = bufferSize;
initBuffer();
}
private void initBuffer() {
mBuffer = new String[mBufferSize];
}
/** Add a single line to {@link #mBuffer}. */
private void addLine(String s) {
mBuffer[mPos] = s;
mPos++;
if (mPos >= mBufferSize) {
mPos = 0;
}
}
private void addReceivingLineToBuffer() {
if (mReceivingLine.length() > 0) {
addLine(mReceivingLine.toString());
mReceivingLine.delete(0, Integer.MAX_VALUE);
}
}
/**
* Store a single byte received from the server in {@link #mReceivingLine}. When LF is
* received, the content of {@link #mReceivingLine} is added to {@link #mBuffer}.
*/
public void addReceivedByte(int b) {
if (0x20 <= b && b <= 0x7e) { // Append only printable ASCII chars.
mReceivingLine.append((char) b);
} else if (b == '\n') { // LF
addReceivingLineToBuffer();
} else if (b == '\r') { // CR
} else {
final String hex = "00" + Integer.toHexString(b);
mReceivingLine.append("\\x" + hex.substring(hex.length() - 2, hex.length()));
}
}
/** Add a line sent to the server to {@link #mBuffer}. */
public void addSentCommand(String command) {
addLine(command);
}
/** @return the contents of {@link #mBuffer} as a String array. */
/* package for testing */ String[] getLines() {
addReceivingLineToBuffer();
ArrayList<String> list = new ArrayList<String>();
final int start = mPos;
int pos = mPos;
do {
String s = mBuffer[pos];
if (s != null) {
list.add(s);
}
pos = (pos + 1) % mBufferSize;
} while (pos != start);
String[] ret = new String[list.size()];
list.toArray(ret);
return ret;
}
/**
* Log the contents of the {@link mBuffer}, and clears it out. (So it's okay to call this
* method successively more than once. There will be no duplicate log.)
*/
public void logLastDiscourse() {
String[] lines = getLines();
if (lines.length == 0) {
return;
}
Log.w(Email.LOG_TAG, "Last network activities:");
for (String r : getLines()) {
Log.w(Email.LOG_TAG, r);
}
initBuffer();
}
}

View File

@ -19,6 +19,7 @@ package com.android.email.mail.store;
import com.android.email.FixedLengthInputStream;
import com.android.email.mail.store.ImapResponseParser.ImapList;
import com.android.email.mail.store.ImapResponseParser.ImapResponse;
import com.android.email.mail.transport.DiscourseLogger;
import android.test.AndroidTestCase;
import android.test.suitebuilder.annotation.SmallTest;
@ -45,7 +46,7 @@ public class ImapResponseParserUnitTests extends AndroidTestCase {
+ "INBOX (UNSEEN 10)\r\n"
+ "101 OK STATUS completed\r\n")
.getBytes());
ImapResponseParser parser = new ImapResponseParser(is);
ImapResponseParser parser = new ImapResponseParser(is, new DiscourseLogger(4));
ImapResponse line1 = parser.readResponse();
assertNull("Line 1 tag", line1.mTag);

View File

@ -27,6 +27,7 @@ import com.android.email.mail.Folder.FolderType;
import com.android.email.mail.Folder.OpenMode;
import com.android.email.mail.internet.BinaryTempFileBody;
import com.android.email.mail.internet.MimeUtility;
import com.android.email.mail.transport.DiscourseLogger;
import com.android.email.mail.transport.MockTransport;
import android.test.AndroidTestCase;
@ -272,7 +273,7 @@ public class ImapStoreUnitTests extends AndroidTestCase {
}
private void doTestImapList() throws MessagingException {
ImapResponseParser parser = new ImapResponseParser(null);
ImapResponseParser parser = new ImapResponseParser(null, new DiscourseLogger(4));
ImapResponseParser.ImapList list = parser.new ImapList();
String key = "key";
String date = "01-Jan-2009 01:00:00 -0800";

View File

@ -0,0 +1,143 @@
/*
* Copyright (C) 2010 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
package com.android.email.mail.transport;
import android.test.MoreAsserts;
import junit.framework.TestCase;
public class DiscourseLoggerTest extends TestCase {
/** Shortcut to create a byte array */
private static byte[] b(String chars) {
byte[] ret = new byte[chars.length()];
for (int i = 0; i < chars.length(); i++) {
ret[i] = (byte) chars.charAt(i);
}
return ret;
}
/** Shortcut to create a String array */
private static String[] s(String... strings) {
return strings;
}
/** Shortcut to create an Object array */
private static Object[] o(Object... objects) {
return objects;
}
public void testDiscourseLogger() {
checkDiscourseStore(4, o(), s());
checkDiscourseStore(4,
o(
"command"
),
s(
"command"
));
checkDiscourseStore(4,
o(
"1a",
"2b",
"3",
"4dd"
),
s(
"1a",
"2b",
"3",
"4dd"
));
checkDiscourseStore(4,
o(
"1",
"2",
"3",
"4",
"5"
),
s(
"2",
"3",
"4",
"5"
));
checkDiscourseStore(4,
o(
b("A")
),
s(
"A"
));
checkDiscourseStore(4,
o(
b("A\nB\nC")
),
s(
"A",
"B",
"C"
));
checkDiscourseStore(4,
o(
b("A\nBCD\nC\nDEF\u0080\u0001G\r\n")
),
s(
"A",
"BCD",
"C",
"DEF\\x80\\x01G"
));
checkDiscourseStore(4,
o(
"1",
b("2"),
"3",
b("4\n5\n"),
"6 7 8",
"7 a bbb ccc",
b("* aaa8\n* bbb9\n7 ccc 10")
),
s(
"7 a bbb ccc",
"* aaa8",
"* bbb9",
"7 ccc 10"
));
}
private void checkDiscourseStore(int storeSize, Object[] discource, String[] expected) {
DiscourseLogger store = new DiscourseLogger(storeSize);
for (Object o : discource) {
if (o instanceof String) {
store.addSentCommand((String) o);
} else if (o instanceof byte[]) {
for (byte b : (byte[]) o) {
store.addReceivedByte(b);
}
} else {
fail("Invalid argument. Test broken.");
}
}
MoreAsserts.assertEquals(expected, store.getLines());
// logLastDiscourse should empty the buffer.
store.logLastDiscourse();
assertEquals(0, store.getLines().length);
}
}