commits@javamail.java.net

[javamail~mercurial:474] MailHandler detect and prevent logging loops by the current thread.

From: <shannon_at_kenai.com>
Date: Sat, 10 Nov 2012 01:25:22 +0000

Project: javamail
Repository: mercurial
Revision: 474
Author: shannon
Date: 2012-11-10 01:24:48 UTC
Link:

Log Message:
------------
MailHandler detect and prevent logging loops by the current thread.
MailHandlerTest added tests for various logging loops.

(Updates from Jason)


Revisions:
----------
474


Modified Paths:
---------------
mail/src/main/java/com/sun/mail/util/logging/MailHandler.java
mail/src/test/java/com/sun/mail/util/logging/MailHandlerTest.java


Diffs:
------
diff -r 88b44267a301 -r d72dfc286bdc mail/src/main/java/com/sun/mail/util/logging/MailHandler.java
--- a/mail/src/main/java/com/sun/mail/util/logging/MailHandler.java Mon Nov 05 16:28:24 2012 -0800
+++ b/mail/src/main/java/com/sun/mail/util/logging/MailHandler.java Fri Nov 09 17:24:48 2012 -0800
@@ -327,6 +327,39 @@
      */
     private static final int offValue = Level.OFF.intValue();
     /**
+ * A thread local mutex used to prevent logging loops.
+ * The MUTEX has 3 states:
+ * 1. MUTEX_RESET which is the null state.
+ * 2. MUTEX_PUBLISH on first entry of a push or publish.
+ * 3. MUTEX_REPORT when cycle of records is detected.
+ */
+ private static final ThreadLocal MUTEX = new ThreadLocal();
+ /**
+ * The marker object used to report a publishing state.
+ */
+ private static final Object MUTEX_PUBLISH = Level.ALL;
+ /**
+ * The marker object used to report a error reporting state.
+ */
+ private static final Object MUTEX_REPORT = Level.OFF;
+ /**
+ * Java 1.4 does not have a ThreadLocal remove method.
+ * Try reflection to access it on newer platforms.
+ */
+ private static final Method REMOVE;
+
+ static {
+ Method m;
+ try {
+ m = ThreadLocal.class.getMethod("remove", (Class[]) null);
+ } catch (final RuntimeException noAccess) {
+ m = null;
+ } catch (final Exception javaOnePointFour) {
+ m = null;
+ }
+ REMOVE = m;
+ }
+ /**
      * Used to turn off security checks.
      */
     private volatile boolean sealed;
@@ -501,9 +534,17 @@
          * will push to ensure that all published records are sent.
          * See close().
          */
- if (isLoggable(record)) {
- record.getSourceMethodName(); //Infer caller, outside of lock.
- publish0(record);
+ if (tryMutex()) {
+ try {
+ if (isLoggable(record)) {
+ record.getSourceMethodName(); //Infer caller.
+ publish0(record);
+ }
+ } finally {
+ releaseMutex();
+ }
+ } else {
+ reportUnPublishedError(record);
         }
     }
 
@@ -529,9 +570,9 @@
                 } else {
                     ctx = null;
                 }
- } else { //Drain the buffer and try again.
+ } else {
                 priority = false;
- ctx = flushAndRePublish(record);
+ ctx = null;
             }
         }
 
@@ -541,37 +582,69 @@
     }
 
     /**
- * Flushes the buffer into a MessageContext and then tries to store
- * the given record. This method will only be called in cases of
- * reentrant filters, formatters, or comparators. The push filter is
- * the only filter allowed to be reentrant. This is because the push filter
- * is never used during formatting and only called after a record is stored.
- * @param record the log record still needed to publish.
- * @return the MessageContext containing the previous push or null.
- * @since JavaMail 1.4.5
+ * Report to the error manager that a logging loop was detected and
+ * we are going to break the cycle of messages. It is possible that
+ * a custom error manager could continue the cycle in which case
+ * we will stop trying to report errors.
+ * @param record the record or null.
+ * @since JavaMail 1.4.6
      */
- private MessageContext flushAndRePublish(final LogRecord record) {
- MessageContext ctx = writeLogRecords(ErrorManager.WRITE_FAILURE);
- if (ctx != null) { //Try again with an empty buffer.
- /**
- * The common case should be a simple store, no push.
- * Rarely should we be pushing while holding a lock.
- */
- publish0(record);
+ private void reportUnPublishedError(LogRecord record) {
+ if (MUTEX_PUBLISH.equals(MUTEX.get())) {
+ MUTEX.set(MUTEX_REPORT);
+ try {
+ final String msg;
+ if (record != null) {
+ final SimpleFormatter f = new SimpleFormatter();
+ msg = "Log record " + record.getSequenceNumber()
+ + " was not published. "
+ + head(f) + format(f, record) + tail(f, "");
+ } else {
+ msg = null;
+ }
+ Exception e = new IllegalStateException(
+ "Recursive publish detected by thread "
+ + Thread.currentThread());
+ reportError(msg, e, ErrorManager.WRITE_FAILURE);
+ } finally {
+ MUTEX.set(MUTEX_PUBLISH);
+ }
+ }
+ }
+
+ /**
+ * Used to detect reentrance by the current thread to the publish method.
+ * This mutex is thread local scope and will not block other threads.
+ * The state is advanced on if the current thread is in a reset state.
+ * @return true if the mutex was acquired.
+ * @since JavaMail 1.4.6
+ */
+ private boolean tryMutex() {
+ if (MUTEX.get() == null) {
+ MUTEX.set(MUTEX_PUBLISH);
+ return true;
         } else {
- /**
- * This record is lost, report this to the error manager.
- * Use ISE because this is a push inside of a push.
- */
- final SimpleFormatter f = new SimpleFormatter();
- final String msg = "Log record " + record.getSequenceNumber()
- + " was not published. "
- + head(f) + format(f, record) + tail(f, "");
- reportError(msg,
- new IllegalStateException("Unable to drain buffer."),
- ErrorManager.WRITE_FAILURE);
+ return false;
         }
- return ctx;
+ }
+
+ /**
+ * Releases the mutex held by the current thread.
+ * This mutex is thread local scope and will not block other threads.
+ * @since JavaMail 1.4.6
+ */
+ private void releaseMutex() {
+ if (REMOVE != null) {
+ try {
+ REMOVE.invoke(MUTEX, (Object[]) null);
+ } catch (RuntimeException ignore) {
+ MUTEX.set(null);
+ } catch (Exception ignore) {
+ MUTEX.set(null);
+ }
+ } else {
+ MUTEX.set(null);
+ }
     }
 
     /**
@@ -1266,7 +1339,7 @@
             final ContentType ct = new ContentType(type);
             ct.setParameter("charset", MimeUtility.mimeCharset(encoding));
             encoding = ct.toString(); //See javax.mail.internet.ContentType.
- if (encoding != null) { //Value is null if the conversion failed.
+ if (!isEmpty(encoding)) { //Value is null if the conversion failed.
                 type = encoding;
             }
         } catch (final MessagingException ME) {
@@ -1857,9 +1930,17 @@
      * @param code the error manager code.
      */
     private void push(final boolean priority, final int code) {
- final MessageContext ctx = writeLogRecords(code);
- if (ctx != null) {
- send(ctx, priority, code);
+ if (tryMutex()) {
+ try {
+ final MessageContext ctx = writeLogRecords(code);
+ if (ctx != null) {
+ send(ctx, priority, code);
+ }
+ } finally {
+ releaseMutex();
+ }
+ } else {
+ reportUnPublishedError(null);
         }
     }
 
@@ -2496,7 +2577,7 @@
     private String toString(final Formatter f) {
         //Should never be null but, guard against formatter bugs.
         final String name = f.toString();
- if (name != null && name.length() > 0) {
+ if (!isEmpty(name)) {
             return name;
         } else {
             return getClassId(f);
@@ -2764,7 +2845,7 @@
             reportError(ME.getMessage(), ME, ErrorManager.FORMAT_FAILURE);
         }
     }
-
+
     /**
      * Signals that this message was generated by automatic process.
      * This header is defined in RFC 3834 section 5.
@@ -2952,7 +3033,7 @@
             this.pass = pass;
         }
 
- protected PasswordAuthentication getPasswordAuthentication() {
+ protected final PasswordAuthentication getPasswordAuthentication() {
             return new PasswordAuthentication(getDefaultUserName(), pass);
         }
     }

diff -r 88b44267a301 -r d72dfc286bdc mail/src/test/java/com/sun/mail/util/logging/MailHandlerTest.java
--- a/mail/src/test/java/com/sun/mail/util/logging/MailHandlerTest.java Mon Nov 05 16:28:24 2012 -0800
+++ b/mail/src/test/java/com/sun/mail/util/logging/MailHandlerTest.java Fri Nov 09 17:24:48 2012 -0800
@@ -1238,8 +1238,14 @@
         instance.flush();
 
         for (int i = 0; i < em.exceptions.size(); i++) {
- assertEquals(false, em.exceptions.get(i) instanceof RuntimeException);
- }
+ Throwable t = em.exceptions.get(i);
+ if ((t instanceof MessagingException == false)
+ && (t instanceof IllegalStateException == false)) {
+ dump(t);
+ fail(String.valueOf(t));
+ }
+ }
+ assertFalse(em.exceptions.isEmpty());
     }
 
     @Test
@@ -3123,8 +3129,11 @@
             instance.close();
 
             for (int i = 0; i < em.exceptions.size(); i++) {
- if (em.exceptions.get(i) instanceof MessagingException == false) {
- fail(String.valueOf(em.exceptions.get(i)));
+ Throwable t = em.exceptions.get(i);
+ if ((t instanceof MessagingException == false)
+ && (t instanceof IllegalStateException == false)) {
+ dump(t);
+ fail(String.valueOf(t));
                 }
             }
             assertFalse(em.exceptions.isEmpty());
@@ -3137,6 +3146,142 @@
     }
 
     @Test
+ public void testMailDebugLowCap() throws Exception {
+ MailHandler instance = new MailHandler(1);
+ try {
+ testMailDebug(instance, 2);
+ } finally {
+ instance.close();
+ }
+ }
+
+ @Test
+ public void testMailDebugPushLevel() throws Exception {
+ MailHandler instance = new MailHandler(1000);
+ try {
+ instance.setPushLevel(Level.ALL);
+ testMailDebug(instance, 2);
+ } finally {
+ instance.close();
+ }
+ }
+
+ @Test
+ public void testMailDebugPush() throws Exception {
+ MailHandler instance = new MailHandler(4);
+ try {
+ testMailDebug(instance, -3);
+ } finally {
+ instance.close();
+ }
+ }
+
+ @Test
+ public void testMailDebugFlush() throws Exception {
+ MailHandler instance = new MailHandler(3);
+ try {
+ testMailDebug(instance, -2);
+ } finally {
+ instance.close();
+ }
+ }
+
+ @Test
+ public void testMailDebugClose() throws Exception {
+ MailHandler instance = new MailHandler(1000);
+ try {
+ testMailDebug(instance, -1);
+ } finally {
+ instance.close();
+ }
+ }
+
+ @Test
+ public void testMailDebugErrorManager() throws Exception {
+ MailHandler instance = new MailHandler(1);
+ try {
+ instance.setErrorManager(new MailDebugErrorManager());
+ testMailDebug(instance, 2);
+ } finally {
+ instance.close();
+ }
+ }
+
+ private void testMailDebug(MailHandler instance, int records) throws Exception {
+ final Properties props = createInitProperties("");
+ props.put("mail.debug", "true");
+ props.put("verify", "local");
+
+ instance.setLevel(Level.ALL);
+ testMailDebugQuietLog(instance, props, records);
+ }
+
+ private void testMailDebugQuietLog(MailHandler instance, Properties props, int records) throws Exception {
+ final Logger root = Logger.getLogger("");
+ hardRef = root;
+ try {
+ final Handler[] handlers = root.getHandlers();
+ for(Handler h : handlers) {
+ root.removeHandler(h);
+ }
+ try {
+ root.setLevel(Level.ALL);
+ root.addHandler(instance);
+ try {
+ testMailDebugQuietStreams(instance, props, records);
+ } finally {
+ root.setLevel(null);
+ root.removeHandler(instance);
+ }
+ } finally {
+ for (Handler h : handlers) {
+ root.addHandler(h);
+ }
+ }
+ } finally {
+ hardRef = null;
+ }
+ }
+
+ private void testMailDebugQuietStreams(MailHandler instance, Properties props, int records) throws Exception {
+ final PrintStream out = System.out;
+ try {
+ ByteArrayOutputStream baos = new ByteArrayOutputStream();
+ System.setOut(new PrintStream(baos, true, "ISO-8859-1"));
+ final PrintStream err = System.err;
+ try {
+ System.setErr(new PrintStream(baos, true, "ISO-8859-1"));
+ instance.setMailProperties(props);
+
+ if(records > 0) {
+ for (int i = 0; i < records; i++) {
+ baos.reset();
+ instance.publish(new LogRecord(Level.SEVERE, ""));
+ }
+ } else {
+ records = -records;
+ for (int i = 0; i < records; i++) {
+ baos.reset();
+ instance.publish(new LogRecord(Level.SEVERE, ""));
+ }
+
+ if (records == 1) {
+ instance.close();
+ } else if (records == 2) {
+ instance.flush();
+ } else if (records == 3) {
+ instance.push();
+ }
+ }
+ } finally {
+ System.setErr(err);
+ }
+ } finally {
+ System.setOut(out);
+ }
+ }
+
+ @Test
     public void testReportError() {
         MailHandler instance = new MailHandler();
         instance.setErrorManager(new ErrorManager() {
@@ -4175,7 +4320,7 @@
     public void testInitErrorManagerException() throws Exception {
         final String encoding = System.getProperty("file.encoding", "8859_1");
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String key;
 
         setPending(new RuntimeException());
@@ -4225,7 +4370,7 @@
     public void testInitErrorManagerError() throws Exception {
         final String encoding = System.getProperty("file.encoding", "8859_1");
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String key;
 
         setPending(new Error());
@@ -4274,7 +4419,7 @@
     @Test
     public void testInitError() throws Exception {
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String filter;
         String name;
         String key;
@@ -4341,7 +4486,7 @@
     @Test
     public void testInitException() throws Exception {
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String filter;
         String name;
         String key;
@@ -4433,7 +4578,7 @@
         final String encoding = System.getProperty("file.encoding", "8859_1");
         final String test = MailHandlerTest.class.getName();
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String key;
 
         setPending(new RuntimeException());
@@ -4493,7 +4638,7 @@
     public void testStaticInitException() throws Exception {
         final String test = MailHandlerTest.class.getName();
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String filter;
         String name;
         String key;
@@ -4561,7 +4706,7 @@
     public void testStaticInitError() throws Exception {
         final String test = MailHandlerTest.class.getName();
         final String p = MailHandler.class.getName();
- final Properties props = this.createInitProperties(p);
+ final Properties props = createInitProperties(p);
         String filter;
         String name;
         String key;
@@ -4656,7 +4801,7 @@
         manager.readConfiguration(new ByteArrayInputStream(out.toByteArray()));
     }
 
- private Properties createInitProperties(String p) {
+ static Properties createInitProperties(String p) {
         final Properties props = new Properties();
         if (p.length() != 0) {
             p = p.concat(".");
@@ -5740,6 +5885,25 @@
         }
     }
 
+ public static class MailDebugErrorManager extends ErrorManager {
+
+ @Override
+ public void error(String msg, Exception ex, int code) {
+ try {
+ Session session = Session.getInstance(createInitProperties(""));
+ session.setDebug(true);
+ Message m = new MimeMessage(session);
+ m.setFrom();
+ m.setRecipient(Message.RecipientType.TO, m.getFrom()[0]);
+ m.setText(MailDebugErrorManager.class.getName());
+ Transport.send(m);
+ } catch (Exception e) {
+ super.error(msg, e, code);
+ }
+ }
+
+ }
+
     public final static class MailHandlerExt extends MailHandler {
 
         public MailHandlerExt() {