Suppress "INFO: Unable to fetch credentials"

[grzm]

The aws-api pod is quite noisy, logging INFO messges to STDERR.

$ cat ex.clj 
(ns com.grzm.ex.pod-aws
  (:require
   [babashka.pods :as pods]))

(when-let [jul-config (System/getProperty "java.util.logging.config.file")]
  (println "java.util.logging.config.file:" jul-config))

(pods/load-pod "./pod-babashka-aws")
(require '[pod.babashka.aws :as aws])

(defn ex [_]
  (let [s3 (aws/client {:api :s3})]
    (prn (keys (aws/invoke s3 {:op :ListBuckets}))))
  (let [sts (aws/client {:api :sts})]
    (prn (keys (aws/invoke sts {:op :GetCallerIdentity})))))

(ex nil)

$ bb ex.clj 
Oct 30, 2021 9:47:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 30, 2021 9:47:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from system properties.
(:Buckets :Owner)
Oct 30, 2021 9:47:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 30, 2021 9:47:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from system properties.
(:UserId :Account :Arn)

This is because the aws-api client logs at INFO level when it tries to find valid credentials:

https://github.com/cognitect-labs/aws-api/blob/fb41cdad69bd04ff5ba36890e1f667fc1f955ebc/src/cognitect/aws/credentials.clj#L130

This can be really noisy when using multiple AWS services (as shown above). One solution would be to redirect stderr to /dev/null, but that would also mean suppressing all other uses of stderr, including more serious messages.

The aws-api client uses clojure.tools.logging, and falls back to java.util.logging as there is no other logging implementation.

https://github.com/clojure/tools.logging/blob/2472b6f84853075cb58082753ec39f49d1716dc2/src/main/clojure/clojure/tools/logging/impl.clj#L245-L256

As expected, the aws-api client exhibits the same behavior using JVM Clojure:

$ cat src/com/grzm/ex/pod_aws.clj 
(ns com.grzm.ex.pod-aws
  (:require
   [cognitect.aws.client.api :as aws]))

(defn ex [_]
  (let [s3 (aws/client {:api :s3})]
    (prn (keys (aws/invoke s3 {:op :ListBuckets}))))
  (let [sts (aws/client {:api :sts})]
    (prn (keys (aws/invoke sts {:op :GetCallerIdentity})))))

$ clj -X com.grzm.ex.pod-aws/ex 
2021-10-30 10:14:32.587:INFO::main: Logging initialized @5251ms to org.eclipse.jetty.util.log.StdErrLog
Oct 30, 2021 10:14:32 AM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 30, 2021 10:14:32 AM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from system properties.
(:Buckets :Owner)
(:UserId :Account :Arn)

(Though, it's only half as noisy: the bb equivalent echoes twice as much. I haven't dug into why that might be.)

I'm able to set the log level for using a logging.properties file using JVM Clojure. See https://github.com/grzm/aws-api-logging-ex for a running example.

$ cat resources/jul/logging.properties
java.util.logging.ConsoleHandler.level = WARNING

$ clj -A:REALLY:quiet -X com.grzm.ex.pod-aws/ex
(:Buckets :Owner)
(:UserId :Account :Arn)

I added resources/logging.properties to the aws-api pod, updated deps to include the additional JVM property, and recompiled. However, it doesn't have the desired effect: the Unable to fetch credentials log messages are still echoed.

Is there a way to get the aws-api pod to pick up the logging.properties file? Is this something that needs to be compiled with the pod or does it need to be specified when the bb script is called? If the latter, it doesn't seem to have the desired effect, either.

bb -cp resources -Djava.util.logging.config.file=logging.properties ex.clj 
java.util.logging.config.file: logging.properties
Oct 30, 2021 10:31:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 30, 2021 10:31:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from system properties.
(:Buckets :Owner)
Oct 30, 2021 10:31:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 30, 2021 10:31:52 AM clojure.tools.logging$eval136$fn__139 invoke
INFO: Unable to fetch credentials from system properties.
(:UserId :Account :Arn)

Maybe it's not getting passed to the pod somehow? I'd be happy just having it compiled in and applied to the pod itself, if that's an easier option.

[borkdude]

I'll take a look.

[borkdude]

@grzm I don't think adding a fixed logging config in resources is flexible enough since this gets baked into the binary and is hard to override by users. Also passing Java properties at pod compile time doesn't affect the runtime. The property has to be set at runtime.

On the pod side I added a function:

(defn set-logging-config! [s]
  (let [s (.readConfiguration (java.util.logging.LogManager/getLogManager) (string->stream s))]
    (.println System/err (str s))))

So in a script you can do:

(require '[babashka.pods :as pods])

(pods/load-pod ["clojure" "-M" "-m" "pod.babashka.aws"])

(require '[pod.babashka.aws :as aws])

(aws/set-logging-config! "java.util.logging.ConsoleHandler.level = TRACE")

(defn ex [_]
  (let [s3 (aws/client {:api :s3})]
    (prn (aws/invoke s3 {:op :ListBuckets})))
  (let [sts (aws/client {:api :sts})]
    (prn (aws/invoke sts {:op :GetCallerIdentity}))))

(ex nil)

This has an effect on the logging, although with TRACE I would expect to see more, not less logs and now I see less logs. Do you have any idea how this works? And do you think the above would be a good way to support setting logging stuff at runtime?

I added the above in a branch called logging and the script is in scratch.clj.

[grzm]

@borkdudeset-logging-config! definitely does something :) I'll try to dig into why we're seeing what looks like no logs at all if that's set. That's curious.

I agree on the flexibility point: I don't know the ins and outs of how pods work to know what the options are.

What prevents the pod from picking up the -Djava.util.logging.config.file=logging.properties passed to bb and reading that configuration file? Did I not have the file properly on the class path where the pod could pick it up? One of the reasons I ask is that while the Unable to fetch lines, if the pod could pick up the files on the class path, it could also potentially read the jetty-logging.properties file and quiet the jetty log line I'm seeing.

2021-10-31 10:15:21.786:INFO::main: Logging initialized @5803ms to org.eclipse.jetty.util.log.StdErrLog

[borkdude]

Pods run in their own operating system process, so any properties passed to bb are not automatically passed to the pod.

[borkdude]

Also the bb classpath has no effect on pods, since they run in their own process.

[borkdude]

We could make other functions like: read the config from this property file etc, but we'll have to do this using bespoke functions I think. But we already have some code that automatically picks up on some properties when you create a client. So we might also do it like that.

[grzm]

Would it make sense to have something like clojure.tools.deps' :extra-paths that would be added to the pod's classpath? Maybe something like :jvm-opts could get around the need to have per-pod bespoke functions?

I suppose this might only make sense for a pod to opt into this: it's not clear what :extra-paths would mean for a Rust-based pod for example (if that makes sense).

[grzm]

One note is that TRACE is not a valid java.util.logging.Level value: https://docs.oracle.com/javase/9/docs/api/java/util/logging/Level.html

SEVERE (highest value)
WARNING
INFO
CONFIG
FINE
FINER
FINEST (lowest value)

In addition there is a level OFF that can be used to turn off logging, and a level ALL that can be used to enable logging of all messages.

However, that's not the issue as using a valid enum doesn't change the no-logging behavior.

[borkdude]

@grzm Perhaps you could try the similar thing in a regular clj script and see what the behavior there is?

[grzm]

Believe me, I have been :) The success I've had so far is showing what it's not:

(defn logger-levels []
  (let [log-manager  (LogManager/getLogManager)]
    (->> (.getLoggerNames log-manager)
         (enumeration-seq)
         (map (juxt identity #(-> (.getLevel (.getLogger log-manager %)))))
         (into (sorted-map)))))

(defn log-manager-prop-vals [prop-names]
  (let [log-manager (LogManager/getLogManager)]
    (->> prop-names
         (map (juxt identity #(.getProperty log-manager %)))
         (into (sorted-map)))))

(set-logging-config! "java.util.logging.ConsoleHandler.level = ALL")
(pprint/pprint {:top-level (log-manager-prop-vals ["java.util.logging.ConsoleHandler.level"])})

(defn ex [_]
  (pprint/pprint {:ex (log-manager-prop-vals ["java.util.logging.ConsoleHandler.level"])})
  (pprint/pprint {:before (logger-levels)})
  (let [sts (aws/client {:api :sts})]
    (prn (keys (aws/invoke sts {:op :GetCallerIdentity}))))
  (pprint/pprint {:after (logger-levels)}))

Calling as-is, with (set-logging-config! "java.util.logging.ConsoleHandler.level = ALL")

{:top-level {"java.util.logging.ConsoleHandler.level" "ALL"}}
{:ex {"java.util.logging.ConsoleHandler.level" "ALL"}}
{:before
 {"" #object[java.util.logging.Level 0x3eacf08e "INFO"],
  "clojure.data.xml" nil,
  "global" nil}}
2021-10-31 14:05:47.558:INFO::main: Logging initialized @5149ms to org.eclipse.jetty.util.log.StdErrLog
(:UserId :Account :Arn)
{:after
 {"" #object[java.util.logging.Level 0x3eacf08e "INFO"],
  "clojure.data.xml" nil,
  "cognitect.aws.credentials" nil,
  "global" nil,
  "jdk.event.security" nil}}

And with commenting it out:

{:top-level {"java.util.logging.ConsoleHandler.level" "INFO"}}
{:ex {"java.util.logging.ConsoleHandler.level" "INFO"}}
{:before
 {"" #object[java.util.logging.Level 0x2e1a8c1a "INFO"],
  "clojure.data.xml" nil,
  "global" nil}}
2021-10-31 14:07:54.480:INFO::main: Logging initialized @5154ms to org.eclipse.jetty.util.log.StdErrLog
Oct 31, 2021 2:07:54 PM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from environment variables.
Oct 31, 2021 2:07:54 PM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from system properties.
(:UserId :Account :Arn)
{:after
 {"" #object[java.util.logging.Level 0x2e1a8c1a "INFO"],
  "clojure.data.xml" nil,
  "cognitect.aws.credentials" nil,
  "global" nil,
  "jdk.event.security" nil}}

Riddles, mysteries, and enigmas. And on a Sunday!

[grzm]

Well, I'm not sure what's going on. Short answer, this works:

(defn set-logging-level!
  "Sets the log level of a java.util.logging Logger. With no logger-name, the global logger is updated."
  ([lvl]
   (set-logging-level! "" lvl))
  ([logger-name lvl]
   (some-> (.getLogger (java.util.logging.LogManager/getLogManager) logger-name)
           (.setLevel (java.util.logging.Level/parse lvl)))))

(pprint/pprint {:before-set (logger-levels)})
(set-logging-level! (System/getenv "X_LOGGER_LEVEL"))
(pprint/pprint {:top-level (log-manager-prop-vals ["java.util.logging.ConsoleHandler.level"])})
(pprint/pprint {:after-set (logger-levels)})

(defn ex [_]
  (let [sts (aws/client {:api :sts})]
    (prn (keys (aws/invoke sts {:op :GetCallerIdentity}))))
  (pprint/pprint {:after-invoke (logger-levels)}))

Setting level to ALL, we still print out everything:

% X_LOGGER_LEVEL=ALL clj -X com.grzm.ex.pod-aws/ex
{:before-set {"" "INFO", "clojure.data.xml" nil, "global" nil}}
{:top-level {"java.util.logging.ConsoleHandler.level" "INFO"}}
{:after-set {"" "ALL", "clojure.data.xml" nil, "global" nil}}
2021-11-02 01:07:02.108:INFO::main: Logging initialized @5009ms to org.eclipse.jetty.util.log.StdErrLog
Nov 02, 2021 1:07:02 AM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from environment variables.
Nov 02, 2021 1:07:02 AM clojure.tools.logging$eval9763$fn__9766 invoke
INFO: Unable to fetch credentials from system properties.
(:UserId :Account :Arn)
{:after-invoke
 {"" "ALL",
  "clojure.data.xml" nil,
  "cognitect.aws.credentials" nil,
  "global" nil,
  "jdk.event.security" nil}}

Setting level to WARNING, we no longer print out the clojure.tools.logging INFO lines:

% X_LOGGER_LEVEL=WARNING clj -X com.grzm.ex.pod-aws/ex
{:before-set {"" "INFO", "clojure.data.xml" nil, "global" nil}}
{:top-level {"java.util.logging.ConsoleHandler.level" "INFO"}}
{:after-set {"" "WARNING", "clojure.data.xml" nil, "global" nil}}
2021-11-02 01:07:15.128:INFO::main: Logging initialized @4996ms to org.eclipse.jetty.util.log.StdErrLog
(:UserId :Account :Arn)
{:after-invoke
 {"" "WARNING",
  "clojure.data.xml" nil,
  "cognitect.aws.credentials" nil,
  "global" nil,
  "jdk.event.security" nil}}

The global logger is the logger with only an empty string for a name.

Works in the pod, too. It's not as flexible as passing in the entire logging configuration, but I haven't been able to get that to work. I came across some notes saying readConfiguration(is) has problems and to use updateConfigurationWith instead, which I tried, with the same results we've seen with readConfiguration

• https://stackoverflow.com/a/49406953
• https://stackoverflow.com/questions/16441467/use-of-readconfiguration-method-in-logging-activities/36069135#36069135

(defn update-logging-configuration [s]
  (let [lm (LogManager/getLogManager)]
    (.updateConfiguration lm (string->stream s)
                          (reify java.util.function.Function
                            (apply [_ _k]
                              (reify java.util.function.BiFunction
                                (apply [_ _o n] n)))))))

I know I'd find set-logging-level! useful, but it's pretty specific.

[grzm]

Maybe set-jul-level! would be a better name?

[borkdude]

@grzm OK, let's proceed with just a function to tweak the log level like you proposed, with a sane default. PR welcome. The name is ok, perhaps -log- instead of -logging- works too. Should we put this in a separate namespace pod.babashka.aws.logging? Then we can use pod.babashka.aws.logging/set-level!.

[borkdude]

Some more context from Slack:

• The logging comes from the default credential provider which is a chain of credential providers.
• You can work around this by setting a :credentials-provider manually
• This isn't always desirable since different environments use different providers

So it's still useful to tweak the log level or other logging settings.

More info here: https://github.com/grzm/aws-api-logging-ex

Response from @grzm:

Re: aws-api. I’m going to work on porting it to babashka this weekend. If you want to bump aws versions or other changes to the aws-pod, feel free to leave out the set-jul-level stuff. I’m probably the only person that’s barking about it, and I can put up with it for a while longer, and the port might be a better fix.