Merge pull request #12 from conormcd/logging

Add logging

Author: conormcd

.gitignore

@@ -10,3 +10,4 @@ pom.xml.asc
 .hgignore
 .hg/
 doc/api
+test/debug.log

project.clj

@@ -6,8 +6,12 @@
   :pedantic? :abort
   :java-source-paths ["src-java"]
   :dependencies [[org.clojure/clojure "1.7.0"]
-                 [net.n01se/clojure-jna "1.0.0"]]
-  :profiles {:dev {:plugins [[lein-codox "0.9.1"]]}}
+                 [org.clojure/tools.logging "0.3.1"]
+                 [digest "1.4.4"]
+                 [net.n01se/clojure-jna "1.0.0"]
+                 [robert/hooke "1.3.0"]]
+  :profiles {:dev {:plugins [[lein-codox "0.9.1"]]}
+             :test {:jvm-opts ["-Djava.util.logging.config.file=test/logging.properties"]}}
   :deploy-repositories ^:replace [["clojars" {:url "https://clojars.org/repo"
                                               :username [:gpg :env/clojars_username]
                                               :password [:gpg :env/clojars_password]

release.sh

@@ -80,6 +80,8 @@ build_jars() {
 
 save_artifacts() {
   if [ -n "${CIRCLE_ARTIFACTS:-}" ]; then
+    echo "Saving debug log..."
+    cp test/debug.log "${CIRCLE_ARTIFACTS}"
     echo "Copying JARs to CircleCI artifacts..."
     find . -name '*.jar' -exec cp {} "${CIRCLE_ARTIFACTS}" \;
   fi

src/clj_libssh2/agent.clj

@@ -2,7 +2,8 @@
   "Functions for interacting with an SSH agent. The agent is expected to be
    available on the UNIX domain socket referred to by the SSH_AUTH_SOCK
    environment variable."
-  (:require [clj-libssh2.error :as error :refer [handle-errors with-timeout]]
+  (:require [clojure.tools.logging :as log]
+            [clj-libssh2.error :as error :refer [handle-errors with-timeout]]
             [clj-libssh2.libssh2 :as libssh2]
             [clj-libssh2.libssh2.agent :as libssh2-agent])
   (:import [com.sun.jna.ptr PointerByReference]))
@@ -33,10 +34,10 @@
     (case ret
       0 (.getValue id)
       1 nil
-      (throw (ex-info "libssh2_agent_get_identity returned a bad value."
-                      {:function "libssh2_agent_get_identity"
-                       :return ret
-                       :session session})))))
+      (error/raise "libssh2_agent_get_identity returned a bad value."
+                   {:function "libssh2_agent_get_identity"
+                    :return ret
+                    :session session}))))
 
 (defn authenticate
   "Attempt to authenticate a session using the agent.
@@ -56,25 +57,25 @@
     (when (nil? ssh-agent)
       (error/maybe-throw-error session libssh2/ERROR_ALLOC))
     (try
+      (log/info "Connecting to the SSH agent...")
       (handle-errors session
         (with-timeout :agent
           (libssh2-agent/connect ssh-agent)))
-      (when-not (loop [success false
-                       previous nil]
-                  (if success
-                    success
-                    (if-let [id (get-identity session ssh-agent previous)]
-                      (recur
-                        (= 0 (with-timeout :agent
-                               (libssh2-agent/userauth ssh-agent username id)))
-                        id)
-                      false)))
-        (throw (ex-info "Failed to authenticate using the SSH agent."
-                        {:username username
-                         :session session})))
+      (when (loop [previous nil]
+              (log/info "Fetching an ID to authenticate with...")
+              (if-let [id (get-identity session ssh-agent previous)]
+                (when-not (= 0 (with-timeout :agent
+                                 (libssh2-agent/userauth ssh-agent username id)))
+                  (recur id))
+                :fail))
+        (error/raise "Failed to authenticate using the SSH agent."
+                     {:username username
+                      :session session}))
+      (log/info "Successfully authenticated using the SSH agent.")
       true
       (finally
         (handle-errors session
           (with-timeout :agent
+            (log/info "Disconnecting from the agent...")
             (libssh2-agent/disconnect ssh-agent)))
         (libssh2-agent/free ssh-agent)))))

src/clj_libssh2/authentication.clj

@@ -1,8 +1,9 @@
 (ns clj-libssh2.authentication
   "Authenticate a session."
   (:require [clojure.java.io :refer [file]]
+            [clojure.tools.logging :as log]
             [clj-libssh2.agent :as agent]
-            [clj-libssh2.error :refer [handle-errors with-timeout]]
+            [clj-libssh2.error :as error :refer [handle-errors with-timeout]]
             [clj-libssh2.libssh2.userauth :as libssh2-userauth])
   (:import [java.io FileNotFoundException]
            [clojure.lang PersistentArrayMap]))
@@ -47,13 +48,15 @@
 
 (defmethod authenticate AgentCredentials
   [session credentials]
+  (log/info "Authenticating using an SSH agent.")
   (agent/authenticate session (:username credentials)))
 
 (defmethod authenticate KeyCredentials
   [session credentials]
+  (log/info "Authenticating using a keypair.")
   (doseq [keyfile (map #(% credentials) [:private-key :public-key])]
     (when-not (.exists (file keyfile))
-      (throw (FileNotFoundException. keyfile))))
+      (error/raise (FileNotFoundException. keyfile))))
   (handle-errors session
     (with-timeout :auth
       (libssh2-userauth/publickey-fromfile (:session session)
@@ -65,6 +68,7 @@
 
 (defmethod authenticate PasswordCredentials
   [session credentials]
+  (log/info "Authenticating using a username and password.")
   (handle-errors session
     (with-timeout :auth
       (libssh2-userauth/password (:session session)
@@ -74,12 +78,13 @@
 
 (defmethod authenticate PersistentArrayMap
   [session credentials]
+  (log/info "Deriving correct credential type from a map...")
   (loop [m [map->KeyCredentials map->PasswordCredentials map->AgentCredentials]]
     (let [creds ((first m) credentials)]
       (if (valid? creds)
         (authenticate session creds)
         (if (< 1 (count m))
           (recur (rest m))
-          (throw (ex-info "Failed to determine credentials type."
-                          {:items (keys credentials)
-                           :session session})))))))
+          (error/raise "Failed to determine credentials type."
+                       {:items (keys credentials)
+                        :session session}))))))

src/clj_libssh2/channel.clj

@@ -1,8 +1,9 @@
 (ns clj-libssh2.channel
   "Functions for manipulating channels within an SSH session."
   (:refer-clojure :exclude [read])
-  (:require [net.n01se.clojure-jna :as jna]
-            [clj-libssh2.error :refer [handle-errors]]
+  (:require [clojure.tools.logging :as log]
+            [net.n01se.clojure-jna :as jna]
+            [clj-libssh2.error :as error :refer [handle-errors]]
             [clj-libssh2.libssh2 :as libssh2]
             [clj-libssh2.libssh2.channel :as libssh2-channel]
             [clj-libssh2.libssh2.scp :as libssh2-scp]
@@ -23,6 +24,7 @@
 
    0 on success. An exception will be thrown if an error occurs."
   [session channel]
+  (log/info "Closing channel.")
   (block session
     (handle-errors session (libssh2-channel/close channel))))
 
@@ -41,6 +43,7 @@
 
    0 on success. An exception will be thrown if an error occurs."
   [session channel commandline]
+  (log/info "Executing a command on the remote host.")
   (block session
     (handle-errors session (libssh2-channel/exec channel commandline))))
 
@@ -63,6 +66,7 @@
    :err-msg     The error message.
    :lang-tag    The language tag, if provided."
   [session channel]
+  (log/info "Collecting the exit signal data from the remote host.")
   (let [->str (fn [string-ref length-ref]
                 (let [string (.getValue string-ref)
                       length (.getValue length-ref)]
@@ -97,6 +101,7 @@
 
    The numeric exit code from the remote process."
   [channel]
+  (log/info "Collecting the exit code from the remote process.")
   (libssh2-channel/get-exit-status channel))
 
 (defn free
@@ -125,6 +130,7 @@
 
    A newly-allocated channel object, or throws exception on failure."
   [session]
+  (log/info "Opening a new channel.")
   (block-return session (libssh2-channel/open-session (:session session))))
 
 (defn open-scp-recv
@@ -141,6 +147,7 @@
    the file information as reported by the remote host. Throws exception on
    failure."
   [session remote-path]
+  (log/info "Opening a new channel to receive a file using SCP.")
   (let [fileinfo (Stat/newInstance)]
     {:channel (block-return session
                 (libssh2-scp/recv (:session session) remote-path fileinfo))
@@ -164,6 +171,7 @@
 
    A newly-allocated channel object for sending a file via SCP."
   [session remote-path {:keys [atime mode mtime size] :as props}]
+  (log/info "Opening a new channel to send a file using SCP.")
   (let [mode (or mode 0644)
         mtime (or mtime 0)
         atime (or atime 0)]
@@ -182,6 +190,7 @@
 
    0 on success, throws an exception on failure."
   [session channel]
+  (log/info "Notifying the remote host of EOF")
   (block session (handle-errors session (libssh2-channel/send-eof channel))))
 
 (defn setenv
@@ -204,14 +213,15 @@
 
    0 on success. Errors will result in exceptions."
   [session channel env]
+  (log/info "Setting environment variables on the remote host.")
   (let [->str (fn [v]
                 (cond (nil? v) ""
                       (keyword? v) (name v)
                       :else (str v)))
         fail-if-forbidden (fn [ret]
                             (if (= libssh2/ERROR_CHANNEL_REQUEST_DENIED ret)
-                              (throw (ex-info "Setting environment variables is not permitted."
-                                              {:session session}))
+                              (error/raise "Setting environment variables is not permitted."
+                                           {:session session})
                               ret))]
     (doseq [[k v] env]
       (block session
@@ -394,11 +404,11 @@
       (when (and (= pump-fn pull)
                  (= :eagain new-status)
                  (< (-> session :options :read-timeout) (- now last-read-time)))
-        (throw (ex-info "Read timeout on a channel."
-                        {:direction (-> stream :direction name)
-                         :id (-> stream :id)
-                         :timeout (-> session :options :read-timeout)
-                         :session session})))
+        (error/raise "Read timeout on a channel."
+                     {:direction (-> stream :direction name)
+                      :id (-> stream :id)
+                      :timeout (-> session :options :read-timeout)
+                      :session session}))
       (assoc stream :status new-status :last-read-time now))
     stream))
 
@@ -427,6 +437,7 @@
    :status          Always :eof
    :stream          The OutputStream object connected to the SSH stream."
   [session channel input-streams output-streams]
+  (log/info "Pumping all the streams on a channel.")
   (let [now (System/currentTimeMillis)
         write-size (-> session :options :write-chunk-size)
         streams (concat (->> input-streams

src/clj_libssh2/error.clj

@@ -1,7 +1,8 @@
 (ns clj-libssh2.error
   "Utility functions for making error handling easier when calling native
    functions."
-  (:require [clj-libssh2.libssh2 :as libssh2]
+  (:require [clojure.tools.logging :as log]
+            [clj-libssh2.libssh2 :as libssh2]
             [clj-libssh2.libssh2.session :as libssh2-session])
   (:import [com.sun.jna.ptr IntByReference PointerByReference]))
 
@@ -65,6 +66,31 @@
    libssh2/ERROR_BAD_SOCKET "Bad socket."
    libssh2/ERROR_KNOWN_HOSTS "Failed to parse known hosts file."})
 
+(defmacro raise
+  "Log an error and then throw an exception with the same error message and
+   optionally some additional information.
+
+   Arguments:
+
+   message          The message to be logged. This will also be the primary
+                    message of the exception. If this message is a Throwable,
+                    then the additional information will be discarded and the
+                    passed-in Throwable will be rethrown after it's logged.
+   additional-info  A map of additional information which might be useful to
+                    anyone debugging an error reported by this exception."
+  ([message]
+   `(raise ~message {}))
+  ([message additional-info]
+   `(let [message# ~message
+          additional-info# ~additional-info]
+      (try
+        (throw (if (instance? Throwable message#)
+                 message#
+                 (ex-info message# additional-info#)))
+        (catch Exception e#
+          (log/log :error e# (.getMessage e#))
+          (throw e#))))))
+
 (defn session-error-message
   "Call libssh2_session_last_error and return the error message given or nil if
    there was no error.
@@ -117,13 +143,13 @@
              (not= libssh2/ERROR_EAGAIN error-code))
     (let [session-message (session-error-message session)
           default-message (get error-messages error-code)]
-      (throw (ex-info (or session-message
-                          default-message
-                          (format "An unknown error occurred: %d" error-code))
-                      {:error default-message
-                       :error-code error-code
-                       :session session
-                       :session-error session-message})))))
+      (raise (or session-message
+                 default-message
+                 (format "An unknown error occurred: %d" error-code))
+             {:error default-message
+              :error-code error-code
+              :session session
+              :session-error session-message}))))
 
 (defmacro handle-errors
   "Run some code that might return a negative number to indicate an error.
@@ -198,9 +224,9 @@
          timeout# (get-timeout ~timeout)]
      (loop [timedout# false]
        (if timedout#
-         (throw (ex-info "Timeout exceeded."
-                         {:timeout ~timeout
-                          :timeout-length timeout#}))
+         (raise (format "Timeout of %d ms exceeded" timeout#)
+                {:timeout ~timeout
+                 :timeout-length timeout#})
          (let [r# (do ~@body)]
            (if (= r# libssh2/ERROR_EAGAIN)
              (recur (< timeout# (- (System/currentTimeMillis) start#)))