Skip to content
Snippets Groups Projects
Commit c8240a74 authored by Ryan Senior's avatar Ryan Senior
Browse files

Fix NPE from sync operations logging 

This looks to have been introduced by 96b77169. Not all sync steps have
extra metadata (and thus a `log-metadata-fn` function. Unfortunately
this wasn't covered by tests as it was in the body of a `log/debug`
call. This commit fixes the problem and also pulls the logic to verify
it out of that `log/debug` call and into a separate function so that
it can be tested separately.
parent a27a4360
Branches
Tags
No related merge requests found
Hide whitespace changes
Inline Side-by-side
src/metabase/sync/util.clj
+ 36
− 28
View file @ c8240a74
......@@ -309,7 +309,7 @@
"Map with metadata about the step. Contains both generic information like `start-time` and `end-time` and step
specific information"
(merge TimedSyncMetadata
{:log-summary-fn (s/maybe (s/=> s/Str StepRunMetadata) #_(s/pred ifn?))}
{:log-summary-fn (s/maybe (s/=> s/Str StepRunMetadata))}
StepSpecificMetadata))
(def StepNameWithMetadata
......@@ -338,7 +338,8 @@
([step-name sync-fn log-summary-fn]
{:sync-fn sync-fn
:step-name step-name
:log-summary-fn (comp str log-summary-fn)}))
:log-summary-fn (when log-summary-fn
(comp str log-summary-fn))}))
(defn- datetime->str [datetime]
(du/->iso-8601-datetime datetime "UTC"))
......@@ -358,38 +359,45 @@
:end-time end-time
:log-summary-fn log-summary-fn)]))
(s/defn ^:private make-log-sync-summary-str
"The logging logic from `log-sync-summary`. Separated for testing purposes as the `log/debug` macro won't invoke
this function unless the logging level is at debug (or higher)."
[operation :- s/Str
database :- i/DatabaseInstance
{:keys [start-time end-time steps log-summary-fn]} :- SyncOperationMetadata]
(str
(apply format
(str "\n#################################################################\n"
"# %s\n"
"# %s\n"
"# %s\n"
"# %s\n")
(map str [(trs "Completed {0} on {1}" operation (:name database))
(trs "Start: {0}" (datetime->str start-time))
(trs "End: {0}" (datetime->str end-time))
(trs "Duration: {0}" (calculate-duration-str start-time end-time))]))
(apply str (for [[step-name {:keys [start-time end-time log-summary-fn] :as step-info}] steps]
(apply format (str "# ---------------------------------------------------------------\n"
"# %s\n"
"# %s\n"
"# %s\n"
"# %s\n"
(when log-summary-fn
(format "# %s\n" (log-summary-fn step-info))))
(map str [(trs "Completed step ''{0}''" step-name)
(trs "Start: {0}" (datetime->str start-time))
(trs "End: {0}" (datetime->str end-time))
(trs "Duration: {0}" (calculate-duration-str start-time end-time))]))))
"#################################################################\n"))
(s/defn ^:private log-sync-summary
"Log a sync/analyze summary message with info from each step"
[operation :- s/Str
database :- i/DatabaseInstance
{:keys [start-time end-time steps log-summary-fn]} :- SyncOperationMetadata]
sync-metadata :- SyncOperationMetadata]
;; Note this needs to either stay nested in the `debug` macro call or be guarded by an log/enabled?
;; call. Constructing the log below requires some work, no need to incur that cost debug logging isn't enabled
(log/debug
(str
(apply format
(str "\n#################################################################\n"
"# %s\n"
"# %s\n"
"# %s\n"
"# %s\n")
(map str [(trs "Completed {0} on {1}" operation (:name database))
(trs "Start: {0}" (datetime->str start-time))
(trs "End: {0}" (datetime->str end-time))
(trs "Duration: {0}" (calculate-duration-str start-time end-time))]))
(apply str (for [[step-name {:keys [start-time end-time duration log-summary-fn] :as step-info}] steps]
(apply format (str "# ---------------------------------------------------------------\n"
"# %s\n"
"# %s\n"
"# %s\n"
"# %s\n"
(when log-summary-fn
(format "# %s\n" (log-summary-fn step-info))))
(map str [(trs "Completed step ''{0}''" step-name)
(trs "Start: {0}" (datetime->str start-time))
(trs "End: {0}" (datetime->str end-time))
(trs "Duration: {0}" (calculate-duration-str start-time end-time))]))))
"#################################################################\n")))
(log/debug (make-log-sync-summary-str operation database sync-metadata)))
(def ^:private SyncOperationOrStepRunMetadata
(s/conditional
......
test/metabase/sync/util_test.clj
+ 57
− 2
View file @ c8240a74
(ns metabase.sync.util-test
"Tests for the utility functions shared by all parts of sync, such as the duplicate ops guard."
(:require [expectations :refer :all]
(:require [clj-time.core :as time]
[clojure.string :as str]
[expectations :refer :all]
[metabase
[driver :as driver]
[sync :as sync]]
[metabase.models
[database :as mdb :refer [Database]]
[task-history :refer [TaskHistory]]]
[metabase.sync.util :refer :all]
[metabase.sync.util :as sync-util :refer :all]
[metabase.test.util :as tu]
[metabase.util.date :as du]
[toucan.db :as db]
......@@ -137,3 +139,56 @@
:operation-history (fetch-task-history-row process-name)
:step-1-history (fetch-task-history-row step-1-name)
:step-2-history (fetch-task-history-row step-2-name)})))
(defn- create-test-sync-summary [step-name log-summary-fn]
(let [start (time/now)]
{:start-time start
:end-time (time/plus start (time/seconds 5))
:steps [[step-name {:start-time start
:end-time (time/plus start (time/seconds 4))
:log-summary-fn log-summary-fn}]]}))
;; Test that we can create the log summary message. This is a big string blob, so validate that it contains the
;; important parts and it doesn't throw an exception
(expect
{:has-operation? true
:has-db-name? true
:has-operation-duration? true
:has-step-name? true
:has-step-duration? true
:has-log-summary-text? true}
(let [operation (tu/random-name)
db-name (tu/random-name)
step-name (tu/random-name)
step-log-text (tu/random-name)
results (#'sync-util/make-log-sync-summary-str operation
(mdb/map->DatabaseInstance {:name db-name})
(create-test-sync-summary step-name
(fn [step-info]
step-log-text)))]
{:has-operation? (str/includes? results operation)
:has-db-name? (str/includes? results db-name)
:has-operation-duration? (str/includes? results "5 s")
:has-step-name? (str/includes? results step-name)
:has-step-duration? (str/includes? results "4 s")
:has-log-summary-text? (str/includes? results step-log-text)}))
;; The `log-summary-fn` part of step info is optional as not all steps have it. Validate that we properly handle that
;; case
(expect
{:has-operation? true
:has-db-name? true
:has-operation-duration? true
:has-step-name? true
:has-step-duration? true}
(let [operation (tu/random-name)
db-name (tu/random-name)
step-name (tu/random-name)
results (#'sync-util/make-log-sync-summary-str operation
(mdb/map->DatabaseInstance {:name db-name})
(create-test-sync-summary step-name nil))]
{:has-operation? (str/includes? results operation)
:has-db-name? (str/includes? results db-name)
:has-operation-duration? (str/includes? results "5 s")
:has-step-name? (str/includes? results step-name)
:has-step-duration? (str/includes? results "4 s")}))
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Please register or to comment