Merge pull request #54 from Moocar/appender-should-recover-from-io-ex…

…ception

Appender should recover from io exception

src/main/java/me/moocar/logbackgelf/GelfUDPAppender.java

@@ -92,8 +92,12 @@ public void start() {
     }
 
     @Override
-    protected void writeOut(E event) throws IOException {
-        super.writeOut(event);
+    protected void writeOut(E event) {
+        try {
+            super.writeOut(event);
+        } catch (IOException e) {
+            addError("IO Exception in UDP output stream", e);
+        }
     }
 
     /**

src/test/clojure/me/moocar/logbackgelf/appender_test.clj

@@ -0,0 +1,65 @@
+(ns me.moocar.logbackgelf.appender-test
+  (:require [clojure.core.async :as async :refer [<!!]]
+            [clojure.test :refer [run-tests deftest is testing]]
+            [me.moocar.logbackgelf.system :as system])
+  (:import (ch.qos.logback.core.encoder LayoutWrappingEncoder)
+           (java.io OutputStream IOException)
+           (me.moocar.logbackgelf GelfUDPAppender GelfLayout)
+           (org.slf4j LoggerFactory)))
+
+(defn- new-throwing-output-stream []
+  (proxy [OutputStream] []
+    (write [b]
+      (throw (IOException. "Excepted exception")))))
+
+(defn- new-udp-appender [context config encoder]
+  (doto (GelfUDPAppender.)
+    (.setContext context)
+    (.setPort (:port (:appender config)))
+    (.setEncoder encoder)
+    (.start)))
+
+(defn- new-layout [context]
+  (doto (GelfLayout.)
+    (.setContext context)
+    (.start)))
+
+(defn- new-layout-encoder [context layout]
+  (doto (LayoutWrappingEncoder.)
+    (.setContext context)
+    (.setLayout layout)
+    (.start)))
+
+(defn- build-appender [config]
+  (let [context (doto (LoggerFactory/getILoggerFactory)
+                  (.reset))
+        gelf-layout (new-layout context)
+        encoder (new-layout-encoder context gelf-layout)]
+    (new-udp-appender context config encoder)))
+
+(deftest t-io-exception-not-fatal
+  (testing "when an IO exception is thrown in the output stream
+  append, make sure that future appends still complete. I.e it should recover"
+    (system/fixture
+     [system (system/make-config)]
+     (let [{:keys [config server]} system
+           appender (build-appender config)
+           gelf-output-stream (.getOutputStream appender)
+           throwing-output-stream (new-throwing-output-stream)
+           logger (doto (LoggerFactory/getLogger "this_logger")
+                    (.addAppender appender))
+           msg-ch (:msg-ch server)]
+
+       (.debug logger "msg 1")
+       (.setOutputStream appender throwing-output-stream)
+       (.debug logger "msg 2")
+       (.setOutputStream appender gelf-output-stream)
+       (.debug logger "msg 3")
+
+       (is (= ["msg 1" "msg 3"]
+              (->> msg-ch
+                   (async/take 2)
+                   (async/into [])
+                   <!!
+                   (map :full_message)))
+           "msg 2 should not succeed, but msg 3 should work again")))))

src/test/clojure/me/moocar/logbackgelf/end_to_end_test.clj

@@ -12,7 +12,8 @@
             [clojure.test.check.properties :as prop]
             [clojure.test.check.clojure-test :refer [defspec]]
             [com.stuartsierra.component :as component]
-            [me.moocar.logbackgelf.servers :as servers])
+            [me.moocar.logbackgelf.servers :as servers]
+            [me.moocar.logbackgelf.system :as system])
   (:import (ch.qos.logback.classic.joran JoranConfigurator)
            (ch.qos.logback.classic Level)
            (ch.qos.logback.classic.spi LoggingEvent)
@@ -27,42 +28,13 @@
                (async/timeout 1000)
                ([_] (throw (ex-info "Timed out waiting for request" {})))))
 
-(defn new-test-system
-  [config]
-  (component/system-map
-   :server (servers/new-test-server config (async/chan 100))
-   :config config))
-
-(defmacro with-test-system
-  "Starts a new system"
-  [[binding-form system-map] & body]
-  `(let [system# (component/start ~system-map)
-         ~binding-form system#]
-     (try ~@body
-          (finally
-            (component/stop system#)))))
-
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; xml configuration
 
 (def appender-classes
   {:udp "me.moocar.logbackgelf.GelfUDPAppender"
    :tcp "me.moocar.logback.net.SocketEncoderAppender"})
 
-(defn make-config
-  []
-  {:full-message-pattern "%rEx%m"
-   :short-message-pattern "%rEx%m"
-   :use-logger-name? true
-   :use-marker? true
-   :host "Test"
-   :version "1.1"
-   :debug? false
-   :appender {:type :udp
-              :port 12202}
-   :static-additional-fields {"_facility" "logback-gelf-test"}
-   :include-full-mdc? true})
-
 (defn logback-xml-sexp
   "Converts a configuration map into an sexpression representation of
   a logback.xml"
@@ -198,15 +170,6 @@
 ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
 ;; Tests
 
-(defmacro fixture [[binding-form config] & body]
-  `(let [config# ~config]
-     (with-test-system [system# (new-test-system config#)]
-       (let [~binding-form system#]
-         (try
-           ~@body
-           (finally
-             (.stop (LoggerFactory/getILoggerFactory))))))))
-
 (defn log->expected-json
   "Converts a test.check generated log into the same format it should
   be received in by the server"
@@ -301,21 +264,23 @@
                  (get json (keyword (str "_" field-name))))))))))
 
 (defn t-all []
-  (fixture [system (make-config)]
-           (t-substitute system)
-           (t-exception system)
-           (t-static-additional-field system)
-           (t-undefined-hostname-string system)
-           (is (= true (:result (tc/quick-check 100 (t-field-types system)))))
-           (is (= true (:result (tc/quick-check 100 (t-test system)))))))
+  (system/fixture
+   [system (system/make-config)]
+
+   (t-substitute system)
+   (t-exception system)
+   (t-static-additional-field system)
+   (t-undefined-hostname-string system)
+   (is (= true (:result (tc/quick-check 100 (t-field-types system)))))
+   (is (= true (:result (tc/quick-check 100 (t-test system)))))))
 
 (deftest t
   (t-all))
 
 (defn send-request
   "For dev purposes"
   []
-  (let [config (make-config)]
+  (let [config (system/make-config)]
     (configure-logback-xml (xml-input-stream (logback-xml-sexp config)))
     (let [logger (LoggerFactory/getLogger "this_logger")]
       (dotimes [_ 10]

src/test/clojure/me/moocar/logbackgelf/servers.clj

@@ -119,10 +119,16 @@
                 {:keys [length offset data]} packet]
             (if (chunked? packet)
               (let [[chunks full-packet] (process-chunk chunks (dechunk packet))]
-                (when full-packet
-                  (>!! msg-ch (packet->json full-packet)))
+                (try
+                  (when full-packet
+                    (>!! msg-ch (packet->json full-packet)))
+                  (catch Throwable t
+                    (.printStackTrace t)))
                 (recur chunks))
-              (do (>!! msg-ch (packet->json packet))
+              (do (try
+                    (>!! msg-ch (packet->json packet))
+                    (catch Throwable t
+                      (.printStackTrace t)))
                   (recur chunks)))))))))
 
 (defn new-datagram-socket-reader

src/test/clojure/me/moocar/logbackgelf/system.clj

@@ -0,0 +1,44 @@
+(ns me.moocar.logbackgelf.system
+  (:require [clojure.core.async :as async]
+            [com.stuartsierra.component :as component]
+            [me.moocar.logbackgelf.servers :as servers])
+  (:import (org.slf4j LoggerFactory)))
+
+(defn make-config
+  []
+  {:full-message-pattern "%rEx%m"
+   :short-message-pattern "%rEx%m"
+   :use-logger-name? true
+   :use-marker? true
+   :host "Test"
+   :version "1.1"
+   :debug? false
+   :appender {:type :udp
+              :port 12202}
+   :static-additional-fields {"_facility" "logback-gelf-test"}
+   :include-full-mdc? true})
+
+(defn new-test-system
+  [config]
+  (component/system-map
+   :server (servers/new-test-server config (async/chan 100))
+   :config config))
+
+(defmacro with-test-system
+  "Starts a new system"
+  [[binding-form system-map] & body]
+  `(let [system# (component/start ~system-map)
+         ~binding-form system#]
+     (try ~@body
+          (finally
+            (component/stop system#)))))
+
+(defmacro fixture [[binding-form config] & body]
+  `(let [config# ~config]
+     (with-test-system [system# (new-test-system config#)]
+       (let [~binding-form system#]
+         (try
+           ~@body
+           (finally
+             (.stop (LoggerFactory/getILoggerFactory))))))))
+