When closing a session, log why. (#1044)

src/java/org/jivesoftware/openfire/Channel.java

@@ -16,16 +16,16 @@
 
 package org.jivesoftware.openfire;
 
-import java.util.concurrent.LinkedBlockingQueue;
-import java.util.concurrent.ThreadPoolExecutor;
-import java.util.concurrent.TimeUnit;
-
 import org.jivesoftware.openfire.session.Session;
 import org.jivesoftware.util.LocaleUtils;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.xmpp.packet.Packet;
 
+import java.util.concurrent.LinkedBlockingQueue;
+import java.util.concurrent.ThreadPoolExecutor;
+import java.util.concurrent.TimeUnit;
+
 /**
  * A channel provides a mechanism to queue work units for processing. Each work unit is
  * encapsulated as a ChannelMessage, and processing of each message is performed by a
@@ -83,22 +83,33 @@ public class Channel<T extends Packet> {
      *
      * @param packet an XMPP packet to add to the channel for processing.
      */
-    public void add(final T packet) {
-        Runnable r = new Runnable() {
+    public void add( final T packet )
+    {
+        Runnable r = new Runnable()
+        {
             @Override
-            public void run() {
-                try {
-                    channelHandler.process(packet);
-                }
-                catch (Exception e) {
-                    Log.error(LocaleUtils.getLocalizedString("admin.error"), e);
-                   
-                        try {
-                            Session session = SessionManager.getInstance().getSession(packet.getFrom());
+            public void run()
+            {
+                try
+                {
+                    channelHandler.process( packet );
+                }
+                catch ( Exception e )
+                {
+                    Log.error( LocaleUtils.getLocalizedString( "admin.error" ), e );
+
+                    try
+                    {
+                        Session session = SessionManager.getInstance().getSession( packet.getFrom() );
+                        if ( session != null )
+                        {
+                            Log.debug( "Closing session of '{}': {}", packet.getFrom(), session );
                             session.close();
                         }
-                        catch (Exception e1) {
-                           Log.error(e1.getMessage(), e1);
+                    }
+                    catch ( Exception e1 )
+                    {
+                        Log.error( "Unexpected exception while trying to close session of '{}'.", packet.getFrom(), e1 );
                     }
                 }
             }

src/java/org/jivesoftware/openfire/LocalSessionManager.java

@@ -175,6 +175,7 @@ class LocalSessionManager {
             for (LocalIncomingServerSession session : incomingServerSessions.values()) {
                 try {
                     if (session.getLastActiveDate().getTime() < deadline) {
+                        Log.debug( "ServerCleanupTask is closing an incoming server session that has been idle for a long time. Last active: {}. Session to be closed: {}", session.getLastActiveDate(), session );
                         session.close();
                     }
                 }

src/java/org/jivesoftware/openfire/PresenceRouter.java

@@ -192,6 +192,7 @@ public class PresenceRouter extends BasicModule {
             Log.error(LocaleUtils.getLocalizedString("admin.error.routing"), e);
             Session session = sessionManager.getSession(packet.getFrom());
             if (session != null) {
+                Log.debug( "Closing session of '{}': {}", packet.getFrom(), session );
                 session.close();
             }
         }

src/java/org/jivesoftware/openfire/component/ExternalComponentManager.java

@@ -149,6 +149,7 @@ public class ExternalComponentManager {
         String domain = subdomain + "." + XMPPServer.getInstance().getServerInfo().getXMPPDomain();
         Session session = SessionManager.getInstance().getComponentSession(domain);
         if (session != null) {
+            Log.debug( "Closing session for external component '{}' as the domain is being blocked. Affected session: {}", domain, session );
             session.close();
         }
     }
@@ -486,6 +487,7 @@ public class ExternalComponentManager {
         for (ComponentSession session : SessionManager.getInstance().getComponentSessions()) {
             for (String domain : session.getExternalComponent().getSubdomains()) {
                 if (!canAccess(domain)) {
+                    Log.debug( "Closing session for external component '{}' as a changed permission policy is taken into effect. Affected session: {}", domain, session );
                     session.close();
                     break;
                 }

src/java/org/jivesoftware/openfire/handler/IQBindHandler.java

@@ -129,7 +129,7 @@ public class IQBindHandler extends IQHandler {
 
                     int conflictCount = oldSession.incrementConflictCount();
                     if (conflictCount > conflictLimit) {
-                        // Kick out the old connection that is conflicting with the new one
+                        Log.debug( "Kick out an old connection that is conflicting with a new one. Old session: {}", oldSession );
                         StreamError error = new StreamError(StreamError.Condition.conflict);
                         oldSession.deliverRawText(error.toXML());
                         oldSession.close();

src/java/org/jivesoftware/openfire/http/HttpBindServlet.java

@@ -327,6 +327,7 @@ public class HttpBindServlet extends HttpServlet {
         }
         finally {
             if (bindingError.getErrorType() == BoshBindingError.Type.terminate) {
+                Log.debug( "Closing session due to error: {}. Affected session: {}", bindingError, session );
                 session.close();
             }
         }

src/java/org/jivesoftware/openfire/http/HttpSessionManager.java

@@ -128,6 +128,7 @@ public class HttpSessionManager {
         Log.info( "Stopping instance" );
         inactivityTask.cancel();
         for (HttpSession session : sessionMap.values()) {
+            Log.debug( "Closing as session manager instance is being stopped: {}", session );
             session.close();
         }
         sessionMap.clear();
@@ -350,14 +351,14 @@ public class HttpSessionManager {
                 try {
                     long lastActive = currentTime - session.getLastActivity();
                     if (Log.isDebugEnabled()) {
-                        Log.debug("Session was last active " + lastActive + " ms ago: " + session.getAddress());
+                        Log.debug("Session was last active {} ms ago: {}", lastActive, session );
                     }
                     if (lastActive > session.getInactivityTimeout() * JiveConstants.SECOND) {
-                        Log.info("Closing idle session: " + session.getAddress());
+                        Log.info("Closing idle session: {}", session);
                         session.close();
                     }
                 } catch (Exception e) {
-                    Log.error("Failed to determine idle state for session: " + session, e);
+                    Log.error("Failed to determine idle state for session: {}", session, e);
                 }
             }
         }

src/java/org/jivesoftware/openfire/multiplex/ConnectionMultiplexerManager.java

@@ -184,7 +184,7 @@ public class ConnectionMultiplexerManager implements SessionEventListener {
         if (sessions != null) {
             Session session = sessions.remove(streamID);
             if (session != null) {
-                // Close the session
+                Log.debug( "Closing session: {}", session );
                 session.close();
             }
         }

src/java/org/jivesoftware/openfire/net/BlockingReadingMode.java

@@ -101,6 +101,7 @@ class BlockingReadingMode extends SocketReadingMode {
                     Log.debug("Logging off " + socketReader.session.getAddress() + " on " + socketReader.connection);
                 }
                 try {
+                    Log.debug( "Closing session: {}", socketReader.session );
                     socketReader.session.close();
                 }
                 catch (Exception e) {

src/java/org/jivesoftware/openfire/net/ComponentStanzaHandler.java

@@ -64,10 +64,12 @@ public class ComponentStanzaHandler extends StanzaHandler {
         if ("handshake".equals(tag)) {
             // External component is trying to authenticate
             if (!((LocalComponentSession) session).authenticate(doc.getStringValue())) {
+                Log.debug( "Closing session that failed to authenticate: {}", session );
                 session.close();
             }
             return true;
         } else if ("error".equals(tag) && "stream".equals(doc.getNamespacePrefix())) {
+            Log.debug( "Closing session because of received stream error {}. Affected session: {}", doc.asXML(), session );
             session.close();
             return true;
         } else if ("bind".equals(tag)) {

src/java/org/jivesoftware/openfire/net/MultiplexerStanzaHandler.java

@@ -24,6 +24,8 @@ import org.jivesoftware.openfire.multiplex.MultiplexerPacketHandler;
 import org.jivesoftware.openfire.multiplex.Route;
 import org.jivesoftware.openfire.session.LocalConnectionMultiplexerSession;
 import org.jivesoftware.openfire.session.Session;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.xmlpull.v1.XmlPullParser;
 import org.xmlpull.v1.XmlPullParserException;
 import org.xmpp.packet.IQ;
@@ -38,6 +40,8 @@ import org.xmpp.packet.Presence;
  */
 public class MultiplexerStanzaHandler extends StanzaHandler {
 
+    private static final Logger Log = LoggerFactory.getLogger( MultiplexerStanzaHandler.class );
+
     /**
      * Handler of IQ packets sent from the Connection Manager to the server.
      */
@@ -112,10 +116,12 @@ public class MultiplexerStanzaHandler extends StanzaHandler {
             return true;
         } else if ("handshake".equals(tag)) {
             if (!((LocalConnectionMultiplexerSession) session).authenticate(doc.getStringValue())) {
+                Log.debug( "Closing session that failed to authenticate: {}", session );
                 session.close();
             }
             return true;
         } else if ("error".equals(tag) && "stream".equals(doc.getNamespacePrefix())) {
+            Log.debug( "Closing session because of received stream error {}. Affected session: {}", doc.asXML(), session );
             session.close();
             return true;
         }

src/java/org/jivesoftware/openfire/net/SASLAuthentication.java

@@ -475,6 +475,7 @@ public class SASLAuthentication {
         session.setSessionData("authRetries", retries);
         if (retries >= JiveGlobals.getIntProperty("xmpp.auth.retries", 3) ) {
             // Close the connection
+            Log.debug( "Closing session that failed to authenticate {} times: {}", retries, session );
             session.close();
         }
     }

src/java/org/jivesoftware/openfire/net/StanzaHandler.java

@@ -152,6 +152,7 @@ public abstract class StanzaHandler {
         if (stanza.equals("</stream:stream>")) {
             if (session != null) {
                 session.getStreamManager().formalClose();
+                Log.debug( "Closing session as an end-of-stream was received: {}", session );
                 session.close();
             }
             return;
@@ -304,6 +305,7 @@ public abstract class StanzaHandler {
             }
             if (packet.getID() == null && JiveGlobals.getBooleanProperty("xmpp.server.validation.enabled", false)) {
                 // IQ packets MUST have an 'id' attribute so close the connection
+                Log.debug( "Closing session, as it sent us an IQ packet that has no ID attribute: {}. Affected session: {}", packet.toXML(), session );
                 StreamError error = new StreamError(StreamError.Condition.invalid_xml);
                 session.deliverRawText(error.toXML());
                 session.close();
@@ -313,8 +315,7 @@ public abstract class StanzaHandler {
         }
         else {
             if (!processUnknowPacket(doc)) {
-                Log.warn(LocaleUtils.getLocalizedString("admin.error.packet.tag") +
-                        doc.asXML());
+                Log.warn(LocaleUtils.getLocalizedString("admin.error.packet.tag") + doc.asXML() + ". Closing session: " + session);
                 session.close();
             }
         }

src/java/org/jivesoftware/openfire/server/RemoteServerManager.java

@@ -89,12 +89,14 @@ public class RemoteServerManager {
         addConfiguration(config);
         // Check if the remote server was connected and proceed to close the connection
         for (Session session : SessionManager.getInstance().getIncomingServerSessions(domain)) {
+            Log.debug( "Closing session for domain '{}' as the domain is being blocked. Affected session: {}", domain, session );
             session.close();
         }
         // Can't just lookup a single remote server anymore, so check them all.
         for (DomainPair domainPair : SessionManager.getInstance().getOutgoingDomainPairs()) {
             if (domainPair.getRemote().equals(domain)) {
                 Session session = SessionManager.getInstance().getOutgoingServerSession(domainPair);
+                Log.debug( "Closing (domain-pair) session for domain '{}' as the domain is being blocked. Affected session: {}", domain, session );
                 session.close();
             }
         }
@@ -348,6 +350,7 @@ public class RemoteServerManager {
         for (String hostname : SessionManager.getInstance().getIncomingServers()) {
             if (!canAccess(hostname)) {
                 for (Session session : SessionManager.getInstance().getIncomingServerSessions(hostname)) {
+                    Log.debug( "Closing session for hostname '{}' as a changed permission policy is taken into effect. Affected session: {}", hostname, session );
                     session.close();
                 }
             }
@@ -355,6 +358,7 @@ public class RemoteServerManager {
         for (DomainPair domainPair : SessionManager.getInstance().getOutgoingDomainPairs()) {
             if (!canAccess(domainPair.getRemote())) {
                 Session session = SessionManager.getInstance().getOutgoingServerSession(domainPair);
+                Log.debug( "Closing session as a changed permission policy is taken into effect. Affected session: {}", session );
                 session.close();
             }
         }

src/java/org/jivesoftware/openfire/spi/LocalRoutingTable.java

@@ -181,6 +181,7 @@ class LocalRoutingTable {
                     Session session = (Session) route;
                     try {
                         if (session.getLastActiveDate().getTime() < deadline) {
+                            Log.debug( "ServerCleanupTask is closing an outgoing server session that has been idle for a long time. Last active: {}. Session to be closed: {}", session.getLastActiveDate(), session );
                             session.close();
                         }
                     }

src/java/org/jivesoftware/openfire/streammanagement/StreamManager.java

@@ -280,7 +280,7 @@ public class StreamManager {
         session.setDetached();
         // Connect new session.
         otherSession.reattach(conn, h);
-        // Perform resumption on new session.
+        Log.debug( "Perform resumption on session {}. Closing session {}", otherSession, session );
         session.close();
     }
 
@@ -405,7 +405,7 @@ public class StreamManager {
                 Log.debug( "Received acknowledgement from client: h={}", h );
 
                 if (!validateClientAcknowledgement(h)) {
-                    Log.warn( "Closing client session. Client acknowledges stanzas that we didn't send! Client Ack h: {}, our last stanza: {}", h, unacknowledgedServerStanzas.getLast().x );
+                    Log.warn( "Closing client session. Client acknowledges stanzas that we didn't send! Client Ack h: {}, our last stanza: {}, affected session: {}", h, unacknowledgedServerStanzas.getLast().x, session );
                     final StreamError error = new StreamError( StreamError.Condition.undefined_condition, "You acknowledged stanzas that we didn't send. Your Ack h: " + h + ", our last stanza: " + unacknowledgedServerStanzas.getLast().x );
                     session.deliverRawText( error.toXML() );
                     session.close();

src/java/org/jivesoftware/openfire/websocket/OpenfireWebSocketServlet.java

@@ -53,6 +53,7 @@ public class OpenfireWebSocketServlet extends WebSocketServlet {
             if (session instanceof LocalSession) {
                 Object ws = ((LocalSession) session).getSessionData("ws");
                 if (ws != null && (Boolean) ws) {
+                    Log.debug( "Closing session as websocket servlet is being destroyed: {}", session );
                     session.close();
                 }
             }

src/java/org/jivesoftware/openfire/websocket/XmppWebSocket.java

@@ -162,6 +162,7 @@ public class XmppWebSocket {
         }
         if (xmppSession != null) {
             if (!xmppSession.getStreamManager().getResume()) {
+                Log.debug( "Closing session {}", xmppSession );
                 xmppSession.close();
                 SessionManager.getInstance().removeSession(xmppSession);
             }