LP#1268619: websocket gateway safer logging

Avoid using ap_log_rerror, in particular referencing server->request
from the responder thread, since the request_rec will be invalid after
on_disconnect is called.

diff --git a/src/gateway/osrf_websocket_translator.c b/src/gateway/osrf_websocket_translator.c
index 2e74fa1..b6205d8 100644 (file)
--- a/src/gateway/osrf_websocket_translator.c
+++ b/src/gateway/osrf_websocket_translator.c
@@ -54,12 +54,11 @@
  */
 
 #include "httpd.h"
-#include "http_log.h"
-#include "http_log.h"
 #include "apr_strings.h"
 #include "apr_thread_proc.h"
 #include "apr_hash.h"
 #include "websocket_plugin.h"
+#include "opensrf/log.h"
 #include "opensrf/osrf_json.h"
 #include "opensrf/transport_client.h"
 #include "opensrf/transport_message.h"
@@ -92,7 +91,6 @@ static char recipient_buf[RECIP_BUF_SIZE]; // reusable recipient buffer
  */
 void* APR_THREAD_FUNC osrf_responder_thread_main(apr_thread_t *thread, void *data) {
 
-    request_rec *r = trans->server->request(trans->server);
     transport_message *tmsg;
     jsonObject *msg_wrapper;
     char *msg_string;
@@ -100,18 +98,20 @@ void* APR_THREAD_FUNC osrf_responder_thread_main(apr_thread_t *thread, void *dat
     while (1) {
 
         tmsg = client_recv(osrf_handle, -1);
+
         if (!tmsg) continue; // early exit on interrupt
         
         // discard responses received after client disconnect
         if (!trans->client_connected) {
-            ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+            osrfLogDebug(OSRF_LOG_MARK, 
                 "WS discarding response for thread=%s, xid=%s", 
-                    tmsg->thread, tmsg->osrf_xid);
+                tmsg->thread, tmsg->osrf_xid);
             message_free(tmsg);                                                         
             continue; 
         }
 
-        ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+
+        osrfLogDebug(OSRF_LOG_MARK, 
             "WS received opensrf response for thread=%s, xid=%s", 
                 tmsg->thread, tmsg->osrf_xid);
 
@@ -122,9 +122,10 @@ void* APR_THREAD_FUNC osrf_responder_thread_main(apr_thread_t *thread, void *dat
         jsonObjectSetKey(msg_wrapper, "osrf_msg", jsonParseRaw(tmsg->body));
 
         if (tmsg->is_error) {
-            ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, 
+            fprintf(stderr,  
                 "WS received jabber error message in response to thread=%s and xid=%s", 
-                    tmsg->thread, tmsg->osrf_xid);
+                tmsg->thread, tmsg->osrf_xid);
+            fflush(stderr);
             jsonObjectSetKey(msg_wrapper, "transport_error", jsonNewBoolObject(1));
         }
 
@@ -140,7 +141,7 @@ void* APR_THREAD_FUNC osrf_responder_thread_main(apr_thread_t *thread, void *dat
         // a last-touched timeout mechanism to periodically remove old  entries
         if (!apr_hash_get(trans->session_cache, tmsg->thread, APR_HASH_KEY_STRING)) {
 
-            ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+            osrfLogDebug(OSRF_LOG_MARK, 
                 "WS caching sender thread=%s, sender=%s", tmsg->thread, tmsg->sender);
 
             apr_hash_set(trans->session_cache, 
@@ -167,7 +168,7 @@ int child_init(const WebSocketServer *server) {
     apr_threadattr_t *thread_attr = NULL;
     request_rec *r = server->request(server);
         
-    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "WS child_init");
+    osrfLogDebug(OSRF_LOG_MARK, "WS child_init");
 
     // osrf_handle will already be connected if this is not the first request
     // served by this process.
@@ -175,7 +176,7 @@ int child_init(const WebSocketServer *server) {
         char* config_file = "/openils/conf/opensrf_core.xml";
         char* config_ctx = "gateway"; //TODO config
         if (!osrfSystemBootstrapClientResc(config_file, config_ctx, "websocket")) {   
-            ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r,                              
+            osrfLogError(OSRF_LOG_MARK, 
                 "WS unable to bootstrap OpenSRF client with config %s", config_file); 
             return 1;
         }
@@ -185,7 +186,7 @@ int child_init(const WebSocketServer *server) {
 
     // create a standalone pool for our translator data
     if (apr_pool_create(&pool, NULL) != APR_SUCCESS) {
-        ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, "WS Unable to create apr_pool");
+        osrfLogError(OSRF_LOG_MARK, "WS Unable to create apr_pool");
         return 1;
     }
 
@@ -195,7 +196,7 @@ int child_init(const WebSocketServer *server) {
         apr_palloc(pool, sizeof(osrfWebsocketTranslator));
 
     if (trans == NULL) {
-        ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, "WS Unable to create translator");
+        osrfLogError(OSRF_LOG_MARK, "WS Unable to create translator");
         return 1;
     }
 
@@ -214,8 +215,7 @@ int child_init(const WebSocketServer *server) {
         trans->responder_thread = thread;
         
     } else {
-        ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, 
-            "WS unable to create responder thread");
+        osrfLogError(OSRF_LOG_MARK, "WS unable to create responder thread");
         return 1;
     }
 
@@ -229,7 +229,7 @@ void* CALLBACK on_connect_handler(const WebSocketServer *server) {
     request_rec *r = server->request(server);
     apr_pool_t *pool;
 
-    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+    osrfLogDebug(OSRF_LOG_MARK, 
         "WS connect from %s", r->connection->remote_ip); 
         //"WS connect from %s", r->connection->client_ip); // apache 2.4
 
@@ -242,8 +242,7 @@ void* CALLBACK on_connect_handler(const WebSocketServer *server) {
     // create a standalone pool for the session cache values, which will be
     // destroyed on client disconnect.
     if (apr_pool_create(&pool, trans->main_pool) != APR_SUCCESS) {
-        ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, 
-            "WS Unable to create apr_pool");
+        osrfLogError(OSRF_LOG_MARK, "WS Unable to create apr_pool");
         return NULL;
     }
 
@@ -251,8 +250,7 @@ void* CALLBACK on_connect_handler(const WebSocketServer *server) {
     trans->session_cache = apr_hash_make(trans->session_pool);
 
     if (trans->session_cache == NULL) {
-        ap_log_rerror(APLOG_MARK, APLOG_ERR, 0, r, 
-            "WS unable to create session cache");
+        osrfLogError(OSRF_LOG_MARK, "WS unable to create session cache");
         return NULL;
     }
 
@@ -282,8 +280,7 @@ static size_t CALLBACK on_message_handler(void *data,
 
     if (buffer_size <= 0) return OK;
 
-    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
-        "WS received message size=%d", buffer_size);
+    osrfLogDebug(OSRF_LOG_MARK, "WS received message size=%d", buffer_size);
 
     // buffer may not be \0-terminated, which jsonParse requires
     char buf[buffer_size + 1];
@@ -293,8 +290,7 @@ static size_t CALLBACK on_message_handler(void *data,
     msg_wrapper = jsonParseRaw(buf);
 
     if (msg_wrapper == NULL) {
-        ap_log_rerror(APLOG_MARK, 
-            APLOG_NOTICE, 0, r, "WS Invalid JSON: %s", buf);
+        osrfLogWarning(OSRF_LOG_MARK, "WS Invalid JSON: %s", buf);
         return HTTP_BAD_REQUEST;
     }
 
@@ -313,8 +309,7 @@ static size_t CALLBACK on_message_handler(void *data,
 
         // use the caller-provide log trace id
         if (strlen(log_xid) > MAX_THREAD_SIZE) {
-            ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 
-                0, r, "WS log_xid exceeds max length");
+            osrfLogWarning(OSRF_LOG_MARK, "WS log_xid exceeds max length");
             return HTTP_BAD_REQUEST;
         }
 
@@ -330,8 +325,7 @@ static size_t CALLBACK on_message_handler(void *data,
     if (thread) {
 
         if (strlen(thread) > MAX_THREAD_SIZE) {
-            ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 
-                0, r, "WS thread exceeds max length");
+            osrfLogWarning(OSRF_LOG_MARK, "WS thread exceeds max length");
             return HTTP_BAD_REQUEST;
         }
 
@@ -341,8 +335,7 @@ static size_t CALLBACK on_message_handler(void *data,
             trans->session_cache, thread, APR_HASH_KEY_STRING);
 
         if (recipient) {
-            ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
-                "WS found cached recipient %s", recipient);
+            osrfLogDebug(OSRF_LOG_MARK, "WS found cached recipient %s", recipient);
         }
     }
 
@@ -355,14 +348,13 @@ static size_t CALLBACK on_message_handler(void *data,
             recipient = recipient_buf;
 
         } else {
-            ap_log_rerror(APLOG_MARK, APLOG_NOTICE, 
-                0, r, "WS Unable to determine recipient");
+            osrfLogWarning(OSRF_LOG_MARK, "WS Unable to determine recipient");
             return HTTP_BAD_REQUEST;
         }
     }
 
     // TODO: activity log entry? -- requires message analysis
-    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+    osrfLogDebug(OSRF_LOG_MARK, 
         "WS relaying message thread=%s, xid=%s, recipient=%s", 
             thread, osrfLogGetXid(), recipient);
 
@@ -398,7 +390,7 @@ void CALLBACK on_disconnect_handler(
     trans->session_cache = NULL;
 
     request_rec *r = server->request(server);
-    ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, 
+    osrfLogDebug(OSRF_LOG_MARK, 
         "WS disconnect from %s", r->connection->remote_ip); 
         //"WS disconnect from %s", r->connection->client_ip); // apache 2.4
 }