Add logging when catching unknown errors.

[shibboleth/sp.git] / shibsp / remoting / impl / SocketListener.cpp

diff --git a/shibsp/remoting/impl/SocketListener.cpp b/shibsp/remoting/impl/SocketListener.cpp
index 8d94983..d302b5d 100644 (file)
--- a/shibsp/remoting/impl/SocketListener.cpp
+++ b/shibsp/remoting/impl/SocketListener.cpp
@@ -22,6 +22,7 @@
 
 #include "internal.h"
 #include "exceptions.h"
+#include "ServiceProvider.h"
 #include "remoting/impl/SocketListener.h"
 
 #include <errno.h>
@@ -30,13 +31,12 @@
 #include <shibsp/SPConfig.h>
 #include <xmltooling/util/NDC.h>
 
-#ifdef HAVE_UNISTD_H
-# include <unistd.h>
+#ifndef WIN32
+# include <netinet/in.h>
 #endif
 
 using namespace shibsp;
 using namespace xmltooling;
-using namespace log4cpp;
 using namespace std;
 using xercesc::DOMElement;
 
@@ -54,9 +54,9 @@ namespace shibsp {
   
     private:
         SocketListener::ShibSocket connect();
-        
+       
+        Category& m_log; 
         const SocketListener* m_listener;
-        Category& m_log;
         auto_ptr<Mutex> m_lock;
         stack<SocketListener::ShibSocket> m_pool;
     };
@@ -67,7 +67,7 @@ namespace shibsp {
         ServerThread(SocketListener::ShibSocket& s, SocketListener* listener, unsigned long id);
         ~ServerThread();
         void run();
-        bool job();
+        int job();  // Return -1 on error, 1 for closed, 0 for success
 
     private:
         SocketListener::ShibSocket m_sock;
@@ -154,8 +154,8 @@ void SocketPool::put(SocketListener::ShibSocket s)
     m_lock->unlock();
 }
 
-SocketListener::SocketListener(const DOMElement* e) : log(&Category::getInstance(SHIBSP_LOGCAT".Listener")),
-    m_shutdown(NULL), m_child_lock(NULL), m_child_wait(NULL), m_socketpool(NULL), m_socket((ShibSocket)0)
+SocketListener::SocketListener(const DOMElement* e) : m_catchAll(false), log(&Category::getInstance(SHIBSP_LOGCAT".Listener")),
+    m_socketpool(NULL), m_shutdown(NULL), m_child_lock(NULL), m_child_wait(NULL), m_socket((ShibSocket)0)
 {
     // Are we a client?
     if (SPConfig::getConfig().isEnabled(SPConfig::InProcess)) {
@@ -180,7 +180,17 @@ bool SocketListener::run(bool* shutdown)
 #ifdef _DEBUG
     NDC ndc("run");
 #endif
-
+    log->info("listener service starting");
+
+    ServiceProvider* sp = SPConfig::getConfig().getServiceProvider();
+    sp->lock();
+    const PropertySet* props = sp->getPropertySet("OutOfProcess");
+    if (props) {
+        pair<bool,bool> flag = props->getBool("catchAll");
+        m_catchAll = flag.first && flag.second;
+    }
+    sp->unlock();
+    
     // Save flag to monitor for shutdown request.
     m_shutdown=shutdown;
     unsigned long count = 0;
@@ -229,6 +239,8 @@ bool SocketListener::run(bool* shutdown)
                 }
                 catch (...) {
                     log->crit("error starting new server thread to service incoming request");
+                    if (!m_catchAll)
+                        *m_shutdown = true;
                 }
             }
         }
@@ -252,7 +264,7 @@ DDF SocketListener::send(const DDF& in)
     NDC ndc("send");
 #endif
 
-    log->debug("sending message: %s", in.name());
+    log->debug("sending message (%s)", in.name() ? in.name() : "unnamed");
 
     // Serialize data for transmission.
     ostringstream os;
@@ -323,6 +335,7 @@ DDF SocketListener::send(const DDF& in)
         XMLToolingException* except=NULL;
         try { 
             except=XMLToolingException::fromString(out.string());
+            log->error("remoted message returned an error: %s", except->what());
         }
         catch (XMLToolingException& e) {
             log->error("caught XMLToolingException while building the XMLToolingException: %s", e.what());
@@ -409,6 +422,7 @@ void ServerThread::run()
     m_listener->m_children[m_sock] = m_child;
     m_listener->m_child_lock->unlock();
     
+    int result;
     fd_set readfds;
     struct timeval tv = { 0, 0 };
 
@@ -432,9 +446,12 @@ void ServerThread::run()
             break;
 
         default:
-            if (!job()) {
-                m_listener->log_error();
-                m_listener->log->error("I/O failure processing request on socket (%u)", m_sock);
+            result = job();
+            if (result) {
+                if (result < 0) {
+                    m_listener->log_error();
+                    m_listener->log->error("I/O failure processing request on socket (%u)", m_sock);
+                }
                 m_listener->close(m_sock);
                 return;
             }
@@ -442,10 +459,11 @@ void ServerThread::run()
     }
 }
 
-bool ServerThread::job()
+int ServerThread::job()
 {
     Category& log = Category::getInstance("shibd.Listener");
 
+    bool incomingError = true;  // set false once incoming message is received
     ostringstream sink;
 #ifdef WIN32
     u_long len;
@@ -455,9 +473,14 @@ bool ServerThread::job()
 
     try {
         // Read the message.
-        if (m_listener->recv(m_sock,(char*)&len,sizeof(len)) != sizeof(len)) {
+        int readlength = m_listener->recv(m_sock,(char*)&len,sizeof(len));
+        if (readlength == 0) {
+            log.info("detected socket closure, shutting down worker thread");
+            return 1;
+        }
+        else if (readlength != sizeof(len)) {
             log.error("error reading size of input message");
-            return false;
+            return -1;
         }
         len = ntohl(len);
         
@@ -470,7 +493,7 @@ bool ServerThread::job()
         
         if (len) {
             log.error("error reading input message from socket");
-            return false;
+            return -1;
         }
         
         // Unmarshall the message.
@@ -478,31 +501,38 @@ bool ServerThread::job()
         DDFJanitor jin(in);
         is >> in;
 
+        log.debug("dispatching message (%s)", in.name() ? in.name() : "unnamed");
+
+        incomingError = false;
+
         // Dispatch the message.
         m_listener->receive(in, sink);
     }
     catch (XMLToolingException& e) {
-        log.error("error processing incoming message: %s", e.what());
+        if (incomingError)
+            log.error("error processing incoming message: %s", e.what());
         DDF out=DDF("exception").string(e.toString().c_str());
         DDFJanitor jout(out);
         sink << out;
     }
     catch (exception& e) {
-        log.error("error processing incoming message: %s", e.what());
+        if (incomingError)
+            log.error("error processing incoming message: %s", e.what());
         ListenerException ex(e.what());
         DDF out=DDF("exception").string(ex.toString().c_str());
         DDFJanitor jout(out);
         sink << out;
     }
-#ifndef _DEBUG
     catch (...) {
-        log.error("unexpected error processing incoming message");
+        if (incomingError)
+            log.error("unexpected error processing incoming message");
+        if (!m_listener->m_catchAll)
+            throw;
         ListenerException ex("An unexpected error occurred while processing an incoming message.");
         DDF out=DDF("exception").string(ex.toString().c_str());
         DDFJanitor jout(out);
         sink << out;
     }
-#endif
     
     // Return whatever's available.
     string response(sink.str());
@@ -510,12 +540,12 @@ bool ServerThread::job()
     len = htonl(outlen);
     if (m_listener->send(m_sock,(char*)&len,sizeof(len)) != sizeof(len)) {
         log.error("error sending output message size");
-        return false;
+        return -1;
     }
     if (m_listener->send(m_sock,response.c_str(),outlen) != outlen) {
         log.error("error sending output message");
-        return false;
+        return -1;
     }
     
-    return true;
+    return 0;
 }