diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index 5a98b6a..730542c 100644 --- a/CHANGELOG.adoc +++ b/CHANGELOG.adoc @@ -10,6 +10,8 @@ A release with an intentional breaking changes is marked with: * https://github.com/clj-commons/etaoin/pull/552[#552]: Add support for wide characters to input fill functions (https://github.com/tupini07[@tupini07]) * https://github.com/clj-commons/etaoin/issues/566[#566]: Recognize `:driver-log-level` for Edge +* https://github.com/clj-commons/etaoin/issues/563[#563]: Support `"debug"` `:driver-log-level` for Safari +* https://github.com/clj-commons/etaoin/issues/517[#517]: Properly cleanup after failed webdriver launch * https://github.com/clj-commons/etaoin/issues/604[#604]: Add support for shadow DOM (https://github.com/dgr[@dgr]) * https://github.com/clj-commons/etaoin/issues/603[#603]: Add :fn/index as alias for :index in map syntax diff --git a/bb.edn b/bb.edn index 5fb8482..7de5152 100644 --- a/bb.edn +++ b/bb.edn @@ -22,13 +22,12 @@ :default "localhost"}} :restrict true}] (cli/parse-opts args cli-spec)))) - :enter (let [{:keys [name]} (current-task)] - (when-not (string/starts-with? name "-") - (status/line :head "TASK %s %s" name (string/join " " *command-line-args*)))) - :leave (let [{:keys [name]} (current-task)] - (when-not (string/starts-with? name "-") + :enter (let [{:keys [name task-decoration] :as f} (current-task)] + (when-not (= :none task-decoration) + (status/line :head "TASK %s" name))) + :leave (let [{:keys [name task-decoration] :as f} (current-task)] + (when-not (= :none task-decoration) (status/line :detail "\nTASK %s done." name))) - ;; commands dev:jvm {:doc "start a Clojure nrepl server/prompt" :task (let [opts (parse-repl-args *command-line-args*) @@ -47,6 +46,7 @@ test:jvm {:doc "Runs tests under JVM Clojure [--help]" :task test/test-jvm} -test:bb {:doc "bb test runner, invoked within script/test.clj" + :task-decoration :none :requires ([taoensso.timbre :as timbre]) ;; repeat :test paths from deps.edn :extra-paths ["test" "env/test/resources"] @@ -98,6 +98,7 @@ docker-build {:doc "build etaoin docker image" :task (shell/command "docker build --no-cache -t etaoin:latest .")} -docker-install {:doc "helper to setup docker image" + :task-decoration :none :task docker-install/-main} docker-run {:doc "run etaoin docker image (specify no commmands for interactive)" :task (let [{:keys [exit]} (apply shell/command {:continue true} @@ -106,5 +107,8 @@ "etaoin:latest" *command-line-args*)] (System/exit exit))} + fake-driver {:doc "Fake driver to support testing" + :task-decoration :none + :task fake-driver/-main} ci-release {:doc "release tasks, use --help for args" :task ci-release/-main}}} diff --git a/doc/01-user-guide.adoc b/doc/01-user-guide.adoc index f448f4d..fd9c126 100644 --- a/doc/01-user-guide.adoc +++ b/doc/01-user-guide.adoc @@ -2338,6 +2338,11 @@ values vary by browser driver vendor: * chrome & edge `"OFF"` `"SEVERE"` `"WARNING"` `"INFO"` or `"DEBUG"` * firefox `"fatal"` `"error"` `"warn"` `"info"` `"config"` `"debug"` or `"trace"` +* safari `"debug"` - safaridriver +** has only one detailed log level which we enable via its `--diagnose` option and abstract via `"debug"` +** only logs to a log file which Etaion automatically discovers and populates as <> in the `driver` map +** see <> for one way to dump this log file +* phantomjs "ERROR"` `"WARN"` `"INFO"` `"DEBUG"` [id=opt-log-stdout,reftext=`:log-stdout`] [id=opt-log-stderr,reftext=`:log-sterr`] @@ -2354,6 +2359,36 @@ _Example:_ Specify `:inherit` to have WebDriver process output destination inherit from its calling process (for example, the console or some existing redirection to a file). +[id=opt-driver-log-file,reftext=`:driver-log-file`] +=== `:driver-log-file` for discovered WebDriver log file + +_Default:_ `` Etaoin will set this value for you + +_Example:_ `` Not set by user + +Only populated for safaridriver when <> set to `"debug"`. + +[id=opt-post-stop-fns,reftext=`:post-stop-fns`] +=== `:post-stop-fns` to hook in behaviour at driver stop + +_Default:_ `` + +_Example:_ +One usage is to dump safaridriver <>. + +//:test-doc-blocks/skip +[source,clojure] +---- +:post-stop-fns [(fn dump-discovered-log [driver] + (if-let [log (:driver-log-file driver)] + (do + (println "-[start]-safaridriver log file" log) + (with-open [in (io/input-stream log)] + (io/copy in *out*)) + (println "-[end]-safaridriver log file" log)) + (println "-no safaridriver log file discovered-")))] +---- + [id=opt-profile,reftext=`:profile`] === `:profile` path to web browser profile diff --git a/script/fake_driver.clj b/script/fake_driver.clj new file mode 100644 index 0000000..b020dd4 --- /dev/null +++ b/script/fake_driver.clj @@ -0,0 +1,51 @@ +(ns fake-driver + "A fake WebDriver to support testing, adapt as necessary for tests" + (:require [babashka.cli :as cli] + [cheshire.core :as json] + [lread.status-line :as status] + [org.httpkit.server :as server])) + +(def cli-spec {:help {:desc "This usage help" :alias :h} + :port {:ref "" + :desc "Expose server on this port" + :coerce :int + :default 8888 + :alias :p} + :start-server {:ref "" + :desc "Start a fake webdriver request handler" + :default true}}) + +(defn- usage-help [] + (status/line :head "Usage help") + (status/line :detail (cli/format-opts {:spec cli-spec :order [:port :sigterm-filename :start-server :help]})) ) + +(defn- usage-fail [msg] + (status/line :error msg) + (usage-help) + (System/exit 1)) + +(defn make-handler [_opts] + (fn handle-request [{:keys [request-method uri] :as _req}] + (cond + (and (= :post request-method) (= "/session" uri)) + {:status 200 + :headers {"Content-Type" "application/json"} + :body (json/generate-string {:sessionId (random-uuid)})} + (and (= :get request-method) (= "/status" uri)) + {:status 200 + :headers {"Content-Type" "application/json"} + :body (json/generate-string {:ready true})} + :else + {:status 404}))) + +(defn -main [& args] + (let [opts (cli/parse-opts args {:spec cli-spec + :restrict true + :error-fn (fn [{:keys [msg]}] + (usage-fail msg))})] + (if (:help opts) + (usage-help) + (when (:start-server opts) + (server/run-server (make-handler opts) opts)))) + + @(promise)) diff --git a/src/etaoin/api.clj b/src/etaoin/api.clj index 102bd4a..205e891 100644 --- a/src/etaoin/api.clj +++ b/src/etaoin/api.clj @@ -147,6 +147,7 @@ " (:require [babashka.fs :as fs] + [babashka.process :as p] [cheshire.core :as json] [clojure.java.io :as io] [clojure.string :as str] @@ -2593,7 +2594,7 @@ (defn wait-predicate "Wakes up every `:interval` seconds to call `pred`. - Keeps this up until either `pred` returns true or `:timeout` has elapsed. + Keeps this up until either `pred` returns truthy or `:timeout` has elapsed. When `:timeout` has elapsed a slingshot exception is throws with `:message`. Arguments: @@ -2619,13 +2620,15 @@ :interval interval :times times :predicate pred})) - (when-not (with-http-error - (pred)) - (wait interval) - (recur pred (assoc - opts - :time-rest (- time-rest interval) - :times (inc times))))))) + (let [res (with-http-error + (pred))] + (or res + (do + (wait interval) + (recur pred (assoc + opts + :time-rest (- time-rest interval) + :times (inc times))))))))) (defn wait-exists "Waits until `driver` finds element [[exists?]] via `q`. @@ -3558,6 +3561,54 @@ http (assoc :http http) ssl (assoc :ssl ssl)))) +(defn- discover-safari-webdriver-log-pid [port] + ;; The safaridriver docs mislead, the pid in the filename is not the pid of safaridriver, + ;; it is of com.apple.WebDriver.HTTPService get the pid of whatever is listening to + ;; specified safaridriver port, this is macOS specific, but so is safari + (let [{:keys [exit out]} (p/shell {:out :string} "lsof -ti" (str ":" port))] + (when (zero? exit) + (str/trim out)))) + +(defn- discover-safari-webdriver-log [{:keys [port created-epoch-ms] :as driver}] + (let [pid (wait-predicate #(discover-safari-webdriver-log-pid port) + {:timeout 0 + :interval 0.2 + :message (format "Cannot discover safaridriver log file pid for port %s" port)})] + ;; force some output so that log file is created + (get-status driver) + (let [dir (fs/file (fs/home) "Library/Logs/com.apple.WebDriver") + glob (format "safaridriver.%s.*.txt" pid) + log-files (->> (fs/glob dir glob) + ;; use last modified instead of fs/creation-time it is more reliable + ;; creation-time was returning time in second resolution, not millisecond resolution + (filter #(>= (-> % fs/last-modified-time fs/file-time->millis) + created-epoch-ms)) + (sort-by #(fs/last-modified-time %)) + (mapv str))] + (cond + (zero? (count log-files)) + (log/warnf "Safaridriver log file not found for pid %s." pid) + + (not= 1 (count log-files)) + (let [candidates (->> log-files + (mapv #(format " %s %s" + (-> % fs/last-modified-time fs/file-time->instant) + %)))] + (log/warnf "Found multiple matching safaridriver log file candidates, assuming latest from:\n%s" + (str/join "\n" candidates)))) + (if-let [log-file (last log-files)] + (do (log/infof "Safaridriver log file discovered %s" log-file) + (assoc driver :driver-log-file log-file)) + driver)))) + +(defn stop-driver + "Returns new `driver` after killing its WebDriver process." + [driver] + (proc/kill (:process driver)) + (doseq [f (:post-stop-fns driver)] + (f driver)) + (dissoc driver :process :args :env :capabilities :pre-stop-fns)) + (defn- -run-driver* [driver & [{:keys [dev env @@ -3568,7 +3619,8 @@ path-driver download-dir path-browser - driver-log-level]}]] + driver-log-level + post-stop-fns]}]] (let [{:keys [port host]} driver _ (when (util/connectable? host port) @@ -3590,7 +3642,16 @@ process (proc/run proc-args {:log-stdout log-stdout :log-stderr log-stderr :env env})] - (util/assoc-some driver :env env :process process))) + (util/assoc-some driver + :env env + :process process + :post-stop-fns post-stop-fns + :created-epoch-ms (System/currentTimeMillis)))) + +(defn- driver-action [driver action] + (case action + :discover-safari-webdriver-log (discover-safari-webdriver-log driver) + (throw (ex-info (str "Internal error: unrecognized action " action) {})))) (defn- -run-driver "Runs a driver process locally. @@ -3646,12 +3707,15 @@ res (try (wait-running driver) (catch Exception e + (stop-driver driver) {:exception e}))] (if (not (:exception res)) - driver + (reduce (fn [driver action] + (driver-action driver action)) + driver + (:post-run-actions driver)) (recur (inc try-num) (:exception res))))))))) - (defn- -connect-driver "Connects to a running Webdriver server. @@ -3756,12 +3820,6 @@ (dissoc driver :session)) -(defn stop-driver - "Returns new `driver` after killing its WebDriver process." - [driver] - (proc/kill (:process driver)) - (dissoc driver :process :args :env :capabilities)) - (defn quit "Have `driver` close the current session, then, if Etaoin launched it, kill the WebDriver process." [driver] diff --git a/src/etaoin/impl/driver.clj b/src/etaoin/impl/driver.clj index 85537dd..14edb2c 100644 --- a/src/etaoin/impl/driver.clj +++ b/src/etaoin/impl/driver.clj @@ -485,12 +485,19 @@ [driver log-level] (set-args driver ["--log" log-level])) +(defmethod set-driver-log-level + :safari + [driver log-level] + (when-not (= "debug" (string/lower-case log-level)) + (throw (ex-info "Safari Driver only supports debug level logging" {}))) + (-> (set-args driver ["--diagnose"]) + (update :post-run-actions (fnil conj []) :discover-safari-webdriver-log))) + (defmethod set-driver-log-level :phantom [driver log-level] (set-args driver [(format "--webdriver-loglevel=%s" log-level)])) - ;; ;; User-Agent ;; https://stackoverflow.com/questions/29916054/ diff --git a/test/etaoin/api_test.clj b/test/etaoin/api_test.clj index 1847f93..a5299df 100644 --- a/test/etaoin/api_test.clj +++ b/test/etaoin/api_test.clj @@ -50,11 +50,19 @@ :log-stderr :inherit :driver-log-level "info"})) :safari (cond-> {} - ;; add logging for kind flaky CI scenario (maybe we'll answer why we need + ;; add logging for kind of flaky CI scenario (maybe we'll answer why we need ;; to retry launching safaridriver automatically) - ;; safaridriver only logs details to a somewhat obscure file, will follow up - ;; with some technique to discover/dump this file - (ci?) (merge {:log-stdout :inherit :log-stderr :inherit})) + (ci?) (merge {:log-stdout :inherit + :log-stderr :inherit + :driver-log-level "debug" + :post-stop-fns [(fn dump-discovered-log [driver] + (if-let [log (:driver-log-file driver)] + (do + (println "-[start]-safaridriver log file" log) + (with-open [in (io/input-stream log)] + (io/copy in *out*)) + (println "-[end]-safaridriver log file" log)) + (println "-no safaridriver log file discovered-")))]})) :edge {:args ["--headless"]}}) (def drivers diff --git a/test/etaoin/api_with_driver_test.clj b/test/etaoin/api_with_driver_test.clj index 09a0ed6..d47b937 100644 --- a/test/etaoin/api_with_driver_test.clj +++ b/test/etaoin/api_with_driver_test.clj @@ -5,13 +5,26 @@ These tests are separate etaoin.api-test because it uses a fixture as part of its strategy. We do reuse the driver selection mechanism from etaoin.api-test tho." - (:require [clojure.test :refer [deftest is testing use-fixtures]] + (:require [babashka.fs :as fs] + [babashka.process :as p] + [clojure.tools.logging :as log] + [clojure.test :refer [deftest is testing use-fixtures]] [etaoin.api :as e] [etaoin.api2 :as e2] [etaoin.api-test :as api-test] [etaoin.test-report] [etaoin.impl.util :as util])) +(defn- match-count [re s] + (let [matcher (re-matcher re s)] + (loop [n 0] + (if (re-find matcher) + (recur (inc n)) + n)))) + +(defn- fake-driver-path [] + (str (fs/which "bb") " fake-driver")) + (defn testing-driver? [type] (some #{type} api-test/drivers)) @@ -244,6 +257,8 @@ (e/get-title driver)))))))) (deftest driver-log-test + ;; these tests check for patterns we expect to see in webdriver implementations, + ;; these implementations might change, adjust as necessary (let [test-page (api-test/test-server-url "test.html")] (when (testing-driver? :chrome) (testing "chrome" @@ -261,11 +276,127 @@ (e/with-edge {:driver-log-level "DEBUG" :log-stderr path} driver (e/go driver test-page) (is (re-find #"\[DEBUG\]:" (slurp path))))))) - (when (testing-driver? :firefox) + (when (testing-driver? :firefox) (testing "firefox" (println "testing firefox") (util/with-tmp-file "firefoxdriver" ".log" path ;; geckodriver logs to stdout (e/with-firefox {:driver-log-level "debug" :log-stdout path} driver (e/go driver test-page) - (is (re-find #"\tDEBUG\t" (slurp path))))))))) + (is (re-find #"\tDEBUG\t" (slurp path))))))) + (when (testing-driver? :safari) + (testing "safari log is disovered" + ;; safari only logs to a log file + (e/with-safari {:driver-log-level "debug"} driver + (is (fs/exists? (:driver-log-file driver))) + (e/go driver test-page) + (is (re-find #"HTTPServer:" (slurp (:driver-log-file driver)))))) + (testing "safari log can be dumped (or whatever) on driver stop" + (let [dlf (atom nil)] + (e/with-safari {:driver-log-level "debug" + :post-stop-fns [(fn [driver] + (reset! dlf (:driver-log-file driver)))]} _driver) + (is (fs/exists? @dlf)) + (is (re-find #"HTTPServer:" (slurp @dlf)))))))) + +(deftest driver-usage-error-test + (when (testing-driver? :safari) + (testing "safari - usage error" + ;; because the safaridriver log is discovered by the port, we won't have a safaridriver log + ;; to discover on usage error, no server webdriver server will have been started. + (util/with-tmp-file "safaridriver-out" ".log" out-path + (util/with-tmp-file "safaridriver-err" ".log" err-path + (let [{:keys [exception ]} + (try + (with-redefs [log/log* (fn [& _whatever])] ;; suppress retry logging that happens automatically for safari + (e/with-safari {:driver-log-level "debug" + :log-stderr err-path + :log-stdout out-path + :stream-driver-log-file true + :args-driver ["--invalidarg"]} _driver)) + ;; on usage error safaridriver currently writes to both stderr and stdout, let's check that we can capture this output + (catch Throwable ex + {:exception ex}))] + ;; we retry launching the driver 4 times for safari by default, but when capturing to a file, we only capture the last failure + (is (some? exception)) + (is (= 1 (match-count #"Usage:.*safaridriver" (slurp out-path)))) + (is (= 1 (match-count #"unrecognized.*invalidarg" (slurp err-path)))))))))) + +(deftest safari-log-discovered-on-exception-test + ;; some exception (maybe a timeout, whatever) has been thrown while the driver is running + (when (testing-driver? :safari) + (testing "safari log can be dumped (or whatever) on driver stop" + (let [dlf (atom nil) + driver-process (atom nil) + {:keys [exception]} + (try + (e/with-safari {:driver-log-level "debug" + :post-stop-fns [(fn [driver] + (reset! dlf (:driver-log-file driver)))]} driver + (reset! driver-process (:process driver)) + (throw (ex-info "something unexpected happened" {}))) + (catch Throwable ex + {:exception ex}))] + (is (some? exception)) + (is (fs/exists? @dlf)) + (is (re-find #"HTTPServer:" (slurp @dlf))) + (is (not (p/alive? @driver-process))))))) + +(deftest safari-log-discovered-after-driver-exits-unexpectedly + ;; the driver exited unexpectedly resulting in an exception + (when (testing-driver? :safari) + (testing "safaridriver log is can be dumped (or whatever) driver exits unexpectedly" + (let [dlf (atom nil) + {:keys [exception]} + (try + (e/with-safari {:driver-log-level "debug" + :post-stop-fns [(fn [driver] + (reset! dlf (:driver-log-file driver)))]} driver + (p/destroy (:process driver))) + (catch Throwable ex + {:exception ex}))] + (is (some? exception)) + (is (fs/exists? @dlf)) + (is (re-find #"HTTPServer:" (slurp @dlf))))))) + +(deftest driver-killed-on-failure-to-run + (doseq [retries [0 4]] + (testing (format "every failed run should kill driver - %d retries" retries) + (let [stop-cnt (atom 0) + {:keys [^Throwable exception]} + (with-redefs [log/log* (fn [& _whatever])] ;; suppress any retry logging + (try + (e/with-wait-timeout 0.25 ;; timeout quickly + (e/with-driver :chrome + {:path-driver (fake-driver-path) + :log-stdout :inherit + :webdriver-failed-launch-retries retries + :args-driver ["--start-server" false] ;; driver process starts but server does not + :post-stop-fns [(fn [driver] + (is (not (-> driver :process p/alive?))) + (swap! stop-cnt inc))]} _driver)) + (catch Throwable ex + {:exception ex})))] + (is (= :etaoin/timeout (some-> exception .getCause ex-data :type))) + (is (some? exception)) + (is (= (inc retries) @stop-cnt)))))) + +(deftest driver-killed-on-exception + (doseq [retries [0 4]] + (testing (format "every failed run should kill driver - %d retries" retries) + (let [stop-cnt (atom 0) + {:keys [exception]} + (with-redefs [log/log* (fn [& _whatever])] ;; there should be no retries + (try + (e/with-driver :chrome + {:path-driver (fake-driver-path) + :webdriver-failed-launch-retries retries + :post-stop-fns [(fn [driver] + (is (not (-> driver :process p/alive?))) + (swap! stop-cnt inc))]} _driver + (throw (ex-info "Something bad happened" {:type ::badness}))) + (catch Throwable ex + {:exception ex})))] + (is (= ::badness (some-> exception ex-data :type))) + ;; driver started fine, so no retries should have occurred + (is (= 1 @stop-cnt)))))) diff --git a/test/etaoin/unit/unit_test.clj b/test/etaoin/unit/unit_test.clj index 1f32840..4659c18 100644 --- a/test/etaoin/unit/unit_test.clj +++ b/test/etaoin/unit/unit_test.clj @@ -30,7 +30,7 @@ :process {:some :process} :session "session-key" :type :firefox - :url "http://127.0.0.1:12345"} driver)))) + :url "http://127.0.0.1:12345"} (dissoc driver :created-epoch-ms))))) (testing "port" (e/with-firefox {:port 1234} driver (is (= ["geckodriver" "--port" 1234] @@ -71,6 +71,7 @@ :desired-capabilities {:specified-desired :val3 :some {:deeper {:thing3 3000 :thing6 6000}}}} driver + (is (>= (System/currentTimeMillis) (:created-epoch-ms driver))) (is (= {:args ["geckodriver" "--port" 12345], :capabilities {:default-firefox :val1 @@ -91,7 +92,7 @@ :process {:some :process} :session "session-key" :type :firefox - :url "http://127.0.0.1:12345"} driver))))))) + :url "http://127.0.0.1:12345"} (dissoc driver :created-epoch-ms)))))))) (deftest test-chrome-profile (fs/with-temp-dir [chrome-dir {:prefix "chrome-dir"}] @@ -111,20 +112,24 @@ (deftest test-retry-launch (testing "give up after max tries" (let [run-calls (atom 0) + kill-calls (atom 0) warnings-logged (atom []) ex (ex-info "firefox badness" {})] (with-redefs [etaoin.impl.proc/run (fn [_ _] (swap! run-calls inc) {:some :process}) + etaoin.impl.proc/kill (fn [_] + (swap! kill-calls inc)) e/running? (fn [_] (throw ex )) log/log* (fn [_logger level _throwable message] - (swap! warnings-logged conj [level message]))] + (swap! warnings-logged conj [level message]))] (is (thrown-with-msg? ExceptionInfo #"gave up trying to launch :firefox after 8 tries" (e/with-firefox {:webdriver-failed-launch-retries 7} driver driver))) + (is (= 8 @kill-calls) "kill calls") (is (= 8 @run-calls) "run calls") (is (= [[:warn "unexpected exception occurred launching :firefox, try 1 (of a max of 8)"] [:warn "unexpected exception occurred launching :firefox, try 2 (of a max of 8)"] @@ -136,6 +141,7 @@ @warnings-logged) "warnings logged")))) (testing "succeed before max tries" (let [run-calls (atom 0) + kill-calls (atom 0) succeed-when-calls 3 warnings-logged (atom []) ex (ex-info "safari badness" {})] @@ -144,7 +150,8 @@ (swap! run-calls inc) {:some :process}) e/create-session (fn [_ _] "session-key") - proc/kill identity + proc/kill (fn [_] + (swap! kill-calls inc)) e/delete-session identity e/running? (fn [_] (if (< @run-calls succeed-when-calls) @@ -163,7 +170,9 @@ :process {:some :process} :session "session-key" :type :safari, - :url "http://127.0.0.1:12345"} driver))) + :url "http://127.0.0.1:12345"} (dissoc driver :created-epoch-ms))) + (is (= (dec succeed-when-calls) @kill-calls))) + (is (= succeed-when-calls @kill-calls)) (is (= succeed-when-calls @run-calls)) (is (= [[:warn "unexpected exception occurred launching :safari, try 1 (of a max of 5)"] [:warn "unexpected exception occurred launching :safari, try 2 (of a max of 5)"]]