Log a warning when extraneous parameters are passed into a request (#28032)

* Log a warning when extraneous parameters are passed into a request

* Massive Metabase logging performance improvement: use configured log levels in logs API endpoint

---------

Co-authored-by: Cam Saul <github@camsaul.com>

dev/src/dev.clj

@@ -87,6 +87,7 @@
   `(require [(symbol (str "metabase.models." (quote ~model-sym))) :as (quote ~model-sym)]))
 
 (defmacro with-permissions
+  "Execute the body with the given permissions."
   [permissions & body]
   `(binding [api/*current-user-permissions-set* (delay ~permissions)]
      ~@body))

dev/src/user.clj

 (ns user
   (:require
    [hawk.assert-exprs]
+   [metabase.bootstrap]
    [metabase.test-runner.assert-exprs]))
 
-;; make sure stuff like `schema=` and what not are loaded
-(comment hawk.assert-exprs/keep-me
+(comment metabase.bootstrap/keep-me
+         ;; make sure stuff like `schema=` and what not are loaded
+         hawk.assert-exprs/keep-me
          metabase.test-runner.assert-exprs/keep-me)
 
 (defn dev
   "Load and switch to the 'dev' namespace."
   []
-  (require 'metabase.bootstrap)
   (require 'dev)
   (in-ns 'dev)
   :loaded)

src/metabase/api/common.clj

 (ns metabase.api.common
   "Dynamic variables and utility functions/macros for writing API functions."
   (:require
+   [clojure.set :as set]
    [clojure.spec.alpha :as s]
    [clojure.string :as str]
    [clojure.tools.logging :as log]
@@ -16,6 +17,7 @@
             route-fn-name
             validate-params
             wrap-response-if-needed]]
+   [metabase.config :as config]
    [metabase.models.interface :as mi]
    [metabase.util :as u]
    [metabase.util.i18n :as i18n :refer [deferred-tru tru]]
@@ -261,16 +263,50 @@
                                   (ns-name *ns*) fn-name)))
       (assoc parsed :fn-name fn-name, :route route, :docstr docstr))))
 
+(defn validate-param-values
+  "Log a warning if the request body contains any parameters not included in `expected-params` (which is presumably
+  populated by the defendpoint schema)"
+  [{route :compojure/route body :body} expected-params]
+  (when (and (not config/is-prod?)
+             (map? body))
+    (let [extraneous-params (set/difference (set (keys body))
+                                            (set expected-params))]
+      (when (seq extraneous-params)
+        (log/warnf "Unexpected parameters at %s: %s\nPlease add them to the schema or remove them from the API client"
+                   route (vec extraneous-params))))))
+
+
+(defn method-symbol->keyword
+  "Convert Compojure-style HTTP method symbols (PUT, POST, etc.) to the keywords used internally by
+  Compojure (:put, :post, ...)"
+  [method-symbol]
+  (-> method-symbol
+      name
+      u/lower-case-en
+      keyword))
+
 (defmacro defendpoint*
   "Impl macro for [[defendpoint]]; don't use this directly."
-  [{:keys [method route fn-name docstr args body]}]
+  [{:keys [method route fn-name docstr args body arg->schema]}]
   {:pre [(or (string? route) (vector? route))]}
-  `(def ~(vary-meta fn-name
-                    assoc
-                    :doc          docstr
-                    :is-endpoint? true)
-     (~(symbol "compojure.core" (name method)) ~route ~args
-      ~@body)))
+  (let [method-kw      (method-symbol->keyword method)
+        allowed-params (keys arg->schema)
+        prep-route     #'compojure/prepare-route]
+    `(def ~(vary-meta fn-name
+                      assoc
+                      :doc          docstr
+                      :is-endpoint? true)
+       ;; The next form is a copy of `compojure/compile-route`, with the sole addition of the call to
+       ;; `validate-param-values`. This is because to validate the request body we need to intercept the request
+       ;; before the destructuring takes place. I.e., we need to validate the value of `(:body request#)`, and that's
+       ;; not available if we called `compile-route` ourselves.
+       (compojure/make-route
+        ~method-kw
+        ~(prep-route route)
+        (fn [request#]
+          (validate-param-values request# (quote ~allowed-params))
+          (compojure/let-request [~args request#]
+            ~@body))))))
 
 ;; TODO - several of the things `defendpoint` does could and should just be done by custom Ring middleware instead
 ;; e.g. `auto-parse`

src/metabase/logger.clj

@@ -6,13 +6,16 @@
    [amalloy.ring-buffer :refer [ring-buffer]]
    [clj-time.coerce :as time.coerce]
    [clj-time.format :as time.format]
-   [metabase.config :as config])
+   [metabase.config :as config]
+   [metabase.plugins.classloader :as classloader])
   (:import
    (org.apache.commons.lang3.exception ExceptionUtils)
    (org.apache.logging.log4j LogManager)
    (org.apache.logging.log4j.core Appender LogEvent LoggerContext)
    (org.apache.logging.log4j.core.config LoggerConfig)))
 
+(set! *warn-on-reflection* true)
+
 (def ^:private ^:const max-log-entries 2500)
 
 (defonce ^:private messages* (atom (ring-buffer max-log-entries)))
@@ -47,13 +50,11 @@
 (when-not *compile-files*
   (when-not @has-added-appender?
     (reset! has-added-appender? true)
-    (let [^LoggerContext ctx                           (LogManager/getContext false)
-          config                                       (.getConfiguration ctx)
-          appender                                     (metabase-appender)
-          ^org.apache.logging.log4j.Level level        nil
-          ^org.apache.logging.log4j.core.Filter filter nil]
+    (let [^LoggerContext ctx (LogManager/getContext (classloader/the-classloader) false)
+          config             (.getConfiguration ctx)
+          appender           (metabase-appender)]
       (.start appender)
       (.addAppender config appender)
       (doseq [[_ ^LoggerConfig logger-config] (.getLoggers config)]
-        (.addAppender logger-config appender level filter))
-      (.updateLoggers ctx))))
+        (.addAppender logger-config appender (.getLevel logger-config) (.getFilter logger-config))
+        (.updateLoggers ctx)))))

test/metabase/api/common/internal_test.clj

@@ -2,6 +2,7 @@
   (:require
    [cheshire.core :as json]
    [clj-http.client :as http]
+   [clojure.string :as str]
    [clojure.test :refer :all]
    [compojure.core :refer [POST]]
    [malli.util :as mut]
@@ -9,7 +10,9 @@
    [metabase.api.common :as api]
    [metabase.api.common.internal :as internal]
    [metabase.config :as config]
+   [metabase.logger :as mb.logger]
    [metabase.server.middleware.exceptions :as mw.exceptions]
+   [metabase.test :as mt]
    [metabase.util :as u]
    [ring.adapter.jetty :as jetty]))
 
@@ -68,59 +71,64 @@
 
 (deftest defendpoint-test
   (let [server (jetty/run-jetty (json-mw (exception-mw #'routes)) {:port 0 :join? false})
-        port (.. server getURI getPort)
-        post! (fn [route body]
-                (http/post (str "http://localhost:" port route)
-                           {:throw-exceptions false
-                            :accept :json
-                            :as :json
-                            :coerce :always
-                            :body (json/generate-string body)}))]
+        port   (.. server getURI getPort)
+        post!  (fn [route body]
+                 (http/post (str "http://localhost:" port route)
+                            {:throw-exceptions false
+                             :accept           :json
+                             :as               :json
+                             :coerce           :always
+                             :body             (json/generate-string body)}))]
     (is (= {:a 1 :b 2} (:body (post! "/post/any" {:a 1 :b 2}))))
 
     (is (= {:id 1} (:body (post! "/post/id-int" {:id 1}))))
-    (is (= {:errors {:id "integer"},
+    (is (= {:errors          {:id "integer"},
             :specific-errors {:id ["should be an int"]}}
            (:body (post! "/post/id-int" {:id "1"}))))
 
-    (is (= {:id "myid"
-            :tags ["abc"]
-            :address {:street "abc" :city "sdasd" :zip 2999 :lonlat [0.0 0.0]}}
-           (:body (post! "/post/test-address"
-                         {:id "myid"
-                          :tags ["abc"]
-                          :address {:street "abc"
-                                    :city "sdasd"
-                                    :zip 2999
-                                    :lonlat [0.0 0.0]}}))))
+    (mt/with-log-level [metabase.api.common :warn]
+      (is (= {:id      "myid"
+              :tags    ["abc"]
+              :address {:street "abc" :city "sdasd" :zip 2999 :lonlat [0.0 0.0]}}
+             (:body (post! "/post/test-address"
+                           {:id      "myid"
+                            :tags    ["abc"]
+                            :address {:street "abc"
+                                      :city   "sdasd"
+                                      :zip    2999
+                                      :lonlat [0.0 0.0]}}))))
+      (is (some (fn [{message :msg, :as entry}]
+                  (when (str/includes? (str message) "Unexpected parameters")
+                    entry))
+                (mb.logger/messages))))
 
     (is (= {:errors
             {:address "map (titled: ‘Address’) where {:id -> <string>, :tags -> <vector of string>, :address -> <map where {:street -> <string>, :city -> <string>, :zip -> <integer>, :lonlat -> <vector with exactly 2 items of type: double, double>}>}"},
-             :specific-errors {:address {:id ["missing required key"],
-                                        :tags ["missing required key"],
+            :specific-errors {:address {:id      ["missing required key"],
+                                        :tags    ["missing required key"],
                                         :address ["missing required key"]}}}
            (:body (post! "/post/test-address" {:x "1"}))))
 
     (is (= {:errors
             {:address "map (titled: ‘Address’) where {:id -> <string>, :tags -> <vector of string>, :address -> <map where {:street -> <string>, :city -> <string>, :zip -> <integer>, :lonlat -> <vector with exactly 2 items of type: double, double>}>}"},
             :specific-errors {:address
-                              {:id ["should be a string"]
-                               :tags ["invalid type"]
+                              {:id      ["should be a string"]
+                               :tags    ["invalid type"]
                                :address {:street ["missing required key"]
-                                         :zip ["should be an int"]}}}}
-           (:body (post! "/post/test-address" {:id 1288
-                                               :tags "a,b,c"
+                                         :zip    ["should be an int"]}}}}
+           (:body (post! "/post/test-address" {:id      1288
+                                               :tags    "a,b,c"
                                                :address {:streeqt "abc"
-                                                         :city "sdasd"
-                                                         :zip "12342"
-                                                         :lonlat [0.0 0.0]}}))))
+                                                         :city    "sdasd"
+                                                         :zip     "12342"
+                                                         :lonlat  [0.0 0.0]}}))))
 
     (is (= {:errors
             {:address "map (titled: ‘Address’) where {:id -> <string>, :tags -> <vector of string>, :address -> <map where {:street -> <string>, :city -> <string>, :zip -> <integer>, :lonlat -> <vector with exactly 2 items of type: double, double>} with no other keys>} with no other keys"},
             :specific-errors {:address
                               {:address ["missing required key"],
-                               :a ["disallowed key"],
-                               :b ["disallowed key"]}}}
+                               :a       ["disallowed key"],
+                               :b       ["disallowed key"]}}}
            (:body (post! "/post/closed-test-address" {:id "1" :tags [] :a 1 :b 2}))))))
 
 (deftest route-fn-name-test

test/metabase/api/common_test.clj

 (ns metabase.api.common-test
   (:require
    [clojure.test :refer :all]
+   [hawk.assert-exprs.approximately-equal :as hawk.approx]
    [metabase.api.common :as api]
    [metabase.api.common.internal :as api.internal]
    [metabase.server.middleware.exceptions :as mw.exceptions]
    [metabase.server.middleware.misc :as mw.misc]
-   [metabase.server.middleware.security :as mw.security]))
+   [metabase.server.middleware.security :as mw.security]
+   [methodical.core :as methodical]))
 
 ;;; TESTS FOR CHECK (ETC)
 
@@ -92,18 +94,27 @@
              ;; compare easily.
              (update-in [:route 2] str)))))
 
+(methodical/defmethod hawk.approx/=?-diff [java.util.regex.Pattern clojure.lang.Symbol]
+  [expected-re sym]
+  (hawk.approx/=?-diff expected-re (name sym)))
+
 (deftest ^:parallel defendpoint-test
   ;; replace regex `#"[0-9]+"` with str `"#[0-9]+" so expectations doesn't barf
   (binding [api.internal/*auto-parse-types* (update-in api.internal/*auto-parse-types* [:int :route-param-regex] (partial str "#"))]
-    (is (= '(def GET_:id
-              (compojure.core/GET
-               ["/:id" :id "#[0-9]+"]
-               [id]
-               (metabase.api.common.internal/auto-parse [id]
-                 (metabase.api.common.internal/validate-param 'id id metabase.util.schema/IntGreaterThanZero)
-                 (metabase.api.common.internal/wrap-response-if-needed
-                  (do
-                    (select-one Card :id id))))))
-           (macroexpand '(metabase.api.common/defendpoint-schema compojure.core/GET "/:id" [id]
-                           {id metabase.util.schema/IntGreaterThanZero}
-                           (select-one Card :id id)))))))
+    (is (=? '(def
+               GET_:id
+               (compojure.core/make-route
+                :get
+                {:source "/:id", :re #"/(#[0-9]+)", :keys [:id], :absolute? false}
+                (clojure.core/fn
+                  [#"request__\d+__auto__"]
+                  (metabase.api.common/validate-param-values #"request__\d+__auto__" '(id))
+                  (compojure.core/let-request
+                   [[id] #"request__\d+__auto__"]
+                   (metabase.api.common.internal/auto-parse
+                       [id]
+                       (metabase.api.common.internal/validate-param 'id id metabase.util.schema/IntGreaterThanZero)
+                       (metabase.api.common.internal/wrap-response-if-needed (do (select-one Card :id id))))))))
+            (macroexpand '(metabase.api.common/defendpoint-schema compojure.core/GET "/:id" [id]
+                            {id metabase.util.schema/IntGreaterThanZero}
+                            (select-one Card :id id)))))))

test/metabase/api/table_test.clj

@@ -829,7 +829,7 @@
                                           {:field_order :database})
                     :fields
                     (map :name)))))
-      (testing "Cane we set custom field ordering?"
+      (testing "Can we set custom field ordering?"
         (let [custom-field-order [(mt/id :venues :price) (mt/id :venues :longitude) (mt/id :venues :id)
                                   (mt/id :venues :category_id) (mt/id :venues :name) (mt/id :venues :latitude)]]
           (mt/user-http-request :crowberto :put 200 (format "table/%s/fields/order" (mt/id :venues))

test/metabase/logger_test.clj

 (ns metabase.logger-test
   (:require
+   [clojure.string :as str]
    [clojure.test :refer :all]
    [clojure.tools.logging :as log]
    [clojure.tools.logging.impl :as log.impl]
    [metabase.logger :as mb.logger]
-   [metabase.test :as mt]))
+   [metabase.test :as mt])
+  (:import
+   (org.apache.logging.log4j.core Logger)))
+
+(set! *warn-on-reflection* true)
+
+(defn logger
+  (^Logger []
+   (logger 'metabase.logger-test))
+  (^Logger [ns-symb]
+   (log.impl/get-logger log/*logger-factory* ns-symb)))
 
 (deftest added-appender-tests
   (testing "appender is added to the logger"
-    (let [logger (log.impl/get-logger log/*logger-factory* *ns*)]
-      (is (contains? (.getAppenders logger) "metabase-appender")
-          "Logger does not contain `metabase-appender` logger")))
+    (is (contains? (.getAppenders (logger)) "metabase-appender")
+        "Logger does not contain `metabase-appender` logger"))
   (testing "logging adds to in-memory ringbuffer"
-    (mt/with-log-level :warn
-      (let [before (count (mb.logger/messages))]
-        (log/warn "testing in-memory logger")
-        (let [after (count (mb.logger/messages))]
-          ;; it either increases (could have many logs from other tests) or it is the max capacity of the ring buffer
-          (is (or (> after before)
-                  (= before (var-get #'mb.logger/max-log-entries)))
-              "In memory ring buffer did not receive log message")))))
+    (mt/with-log-level :debug
+      (log/debug "testing in-memory logger")
+      (is (some (fn [{message :msg, :as entry}]
+                  (when (str/includes? (str message) "testing in-memory logger")
+                    entry))
+                (mb.logger/messages))
+          "In memory ring buffer did not receive log message")))
 
   (testing "set isAdditive = false if parent logger is root to prevent logging to console (#26468)"
     (testing "make sure it's true to starts with"
-      (is (true? (.isAdditive (log.impl/get-logger log/*logger-factory* 'metabase)))))
+      (is (.isAdditive (logger 'metabase))))
 
     (testing "set to false if parent logger is root"
       (mt/with-log-level :warn
-        (is (false? (.isAdditive (log.impl/get-logger log/*logger-factory* 'metabase))))))
+        (is (not (.isAdditive (logger 'metabase))))))
 
     (testing "still true if the parent logger is not root"
       (mt/with-log-level [metabase.logger :warn]
-        (is (true? (.isAdditive (log.impl/get-logger log/*logger-factory* 'metabase.logger))))))))
+        (is (.isAdditive (logger 'metabase.logger)))))))
 
-(deftest logger-test
+(deftest ^:parallel logger-test
   (testing "Using log4j2 logger"
-    (is (= (log.impl/name log/*logger-factory*)
-           "org.apache.logging.log4j")
+    (is (= "org.apache.logging.log4j"
+           (log.impl/name log/*logger-factory*))
         "Not using log4j2 logger factory. This could add two orders of magnitude of time to logging calls")))
+
+(deftest logger-respect-configured-log-level-test
+  (testing "The appender that we programmatically added should respect the log levels in the config file"
+    ;; whether we're in the REPL or in test mode this should not show up
+    (log/debug "THIS SHOULD NOT SHOW UP")
+    (is (not (some (fn [{message :msg, :as entry}]
+                     (when (str/includes? (str message) "THIS SHOULD NOT SHOW UP")
+                       entry))
+                   (mb.logger/messages))))))

test/metabase/test/util/log.clj

@@ -5,11 +5,15 @@
    [clojure.tools.logging :as log]
    [clojure.tools.logging.impl :as log.impl]
    [hawk.parallel]
+   [metabase.plugins.classloader :as classloader]
    [potemkin :as p]
    [schema.core :as s])
-  (:import [org.apache.logging.log4j Level LogManager]
-           [org.apache.logging.log4j.core Appender LifeCycle LogEvent Logger LoggerContext]
-           [org.apache.logging.log4j.core.config Configuration LoggerConfig]))
+  (:import
+   (org.apache.logging.log4j Level LogManager)
+   (org.apache.logging.log4j.core Appender LifeCycle LogEvent Logger LoggerContext)
+   (org.apache.logging.log4j.core.config Configuration LoggerConfig)))
+
+(set! *warn-on-reflection* true)
 
 (def ^:private keyword->Level
   {:off   Level/OFF
@@ -45,7 +49,7 @@
     (name a-namespace)))
 
 (defn- logger-context ^LoggerContext []
-  (LogManager/getContext false))
+  (LogManager/getContext (classloader/the-classloader) false))
 
 (defn- configuration ^Configuration []
   (.getConfiguration (logger-context)))
@@ -90,6 +94,9 @@
                          (into-array org.apache.logging.log4j.core.config.Property (.getPropertyList parent-logger))
                          (configuration)
                          (.getFilter parent-logger))]
+      ;; copy the appenders from the parent logger, e.g. the [[metabase.logger/metabase-appender]]
+      (doseq [[_name ^Appender appender] (.getAppenders parent-logger)]
+        (.addAppender new-logger appender (.getLevel new-logger) (.getFilter new-logger)))
       (.addLogger (configuration) (logger-name a-namespace) new-logger)
       (.updateLoggers (logger-context))
       #_{:clj-kondo/ignore [:discouraged-var]}
@@ -110,6 +117,14 @@
    (let [logger    (exact-ns-logger a-namespace)
          new-level (->Level new-level)]
      (.setLevel logger new-level)
+     ;; it seems like changing the level doesn't update the level for the appenders
+     ;; e.g. [[metabase.logger/metabase-appender]], so if we want the new level to be reflected there the only way I can
+     ;; figure out to make it work is to remove the appender and then add it back with the updated level. See JavaDoc
+     ;; https://logging.apache.org/log4j/2.x/log4j-core/apidocs/org/apache/logging/log4j/core/config/LoggerConfig.html
+     ;; for more info. There's probably a better way to do this, but I don't know what it is. -- Cam
+     (doseq [[^String appender-name ^Appender appender] (.getAppenders logger)]
+       (.removeAppender logger appender-name)
+       (.addAppender logger appender new-level (.getFilter logger)))
      (.updateLoggers (logger-context)))))
 
 (defn do-with-log-level [a-namespace level thunk]

test/metabase/test_runner/assert_exprs.clj

 (ns metabase.test-runner.assert-exprs
-  "Custom implementations of [[clojure.test/is]] expressions (i.e., implementations of [[clojure.test/assert-expr]]).
-  `re=`, `schema=`, `query=`, `sql=`, `=?`, and more."
+  "Custom implementations of a few [[clojure.test/is]] expressions (i.e., implementations of [[clojure.test/assert-expr]]):
+  `query=` and `sql=`.
+
+  Other expressions (`re=`, `schema=`, `=?`, and so forth) are implemented with the Hawk test-runner."
   (:require
    [clojure.data :as data]
    [clojure.test :as t]