Fork me on GitHub
#polylith
<
2021-06-03
>
seancorfield17:06:36

@tengstrand I’ve run into some “interesting” issues with logging in tests when using the poly tool. The tool uses log4j2 and the slf4j bridge — but I don’t see any use of tools.logging in the tool and I haven’t found anywhere that it modifies the logging levels etc. We use tools.logging and we also use log4j2 -- and we bridge all of the logging libs into log4j2 and we use a JVM property to tell tools.logging to use log4j2 no matter what else is on the classpath. I’ve figured out that I can add development/resources (containing our log4j2-test.properties file) and the :jvm-opts when running the poly tool via :git/url (that took me a while — I expected it to pick that up from either the :dev alias or from a :test alias inside the component for which this is relevant).

tengstrand18:06:44

I looks like you (@U04V70XH6) have found a problem in the test runner. This should be configurable, and you are the first person to points this out. I have to look into this and also discuss it with @U2BDZ9JG3 on how to best solve this, but if you have any suggestions, you are welcome.

seancorfield18:06:00

I was a bit surprised that poly depends on log4j2/slf4j because I couldn’t find any logging code in it. What should I be looking for in the source code?

seancorfield18:06:26

We’ve done a huge amount of work with various logging solutions over the years, going back and forth between Java logging and Timbre and back to Java logging, and even recently I’ve been reorganizing how we customize logging for dev/test. Happy to take a deep look at whatever poly is doing and offer suggestions.

tengstrand18:06:58

That would be great! I added the log4jlibrary to get rid of warnings, but missed that it could be useful to configure it!

seancorfield18:06:24

@tengstrand Do you remember, specifically, what the warnings were and do you know what caused them? Java logging is, unfortunately, a “hot mess” so there are a lot of conflicting things.

tengstrand18:06:58

If I remove the log4j library, I get a warning when I run the test command.

seancorfield19:06:39

Just add org.slf4j/slf4j-nop {:mvn/version "1.7.25"} instead (no need for log4j2 or the slf4 bridge).

seancorfield19:06:43

This is needed because tools.deps used to include it but then stopped including it (so clients of t.d.a started to get warnings and needed to add this explicitly themselves).

seancorfield19:06:17

I would say, only include it when you actually build the poly tool executable and in the example :poly alias — do not make it a hard dependency of the repo itself — otherwise folks trying to use poly with other logging setups will be broken.

seancorfield19:06:43

(this is kind of like projects including final sets of deps but components allowing for some flexibility)

tengstrand00:06:36

@U04V70XH6 I replaced with org.slf4j/slf4j-nop {:mvn/version "1.7.25"} + some other changes that I was working on. You can find them in the latest commit (version issue-66.09 ).

3
seancorfield00:06:32

This is why I said it should not be a direct dependency of poly — only when you build the executable:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/sean/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.3/log4j-slf4j-impl-2.13.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/sean/.m2/repository/org/slf4j/slf4j-nop/1.7.25/slf4j-nop-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See  for an explanation.
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]

seancorfield00:06:24

So you are still “breaking” other logging in people’s codebases.

seancorfield00:06:27

There’s still something else interfering with my test’s logging though. I’ll keep digging and let you know. But you definitely need to remove that slf4j lib as a direct dep of poly — and add it in the contexts where you run the tool.

tengstrand04:06:26

Okay, will have a look at that today.

tengstrand05:06:45

But for the AOT compiled poly tool, if I don’t include slf4j how can I get rid of the SLF4J warning when I run the test command? Or maybe I should exclude slf4j altogether and always include it as a dependency in all polylith projects that allow people to configure the logging per project?

seancorfield05:06:19

Hi @tengstrand! Yes, for the AOT-compiled poly tool, you’ll want to include it as part of the project. For the alias :poly in generated workspaces etc, and in docs about that alias, you’ll want to include it. Just not in the main :deps of the polylith project itself. And in the docs around the :poly alias, you can add a note that it is present to stop warnings from clojure.tools.deps but users could swap it out for a different set of logging libraries if that’s what they would prefer to use. An example is:

:poly {:main-opts ["-m" "polylith.clj.core.poly-cli.core"]
         :extra-deps {polyfy/polylith
                      {:git/url   ""
                       :sha       "887e4237cec8f42eaa15be3501f134732602bb41"
                       :deps/root "projects/poly"}
                      ;; use log4j 2.x:
                      org.apache.logging.log4j/log4j-api {:mvn/version "2.13.3"}
                      ;; bridge into log4j:
                      org.apache.logging.log4j/log4j-1.2-api {:mvn/version "2.13.3"}
                      org.apache.logging.log4j/log4j-jcl {:mvn/version "2.13.3"}
                      org.apache.logging.log4j/log4j-jul {:mvn/version "2.13.3"}
                      org.apache.logging.log4j/log4j-slf4j-impl {:mvn/version "2.13.3"}}}

seancorfield05:06:26

Strictly, only the first and last of those five org.apache.logging lines are needed to replace the slf4j line — I haven’t quite figured out how the test code is being loaded and executed (which is why I can’t yet figure out how to get the test code to respect the logging context I need for it).

seancorfield05:06:39

Do you have any detailed docs — or code I can look at — that makes it clear exactly what context is constructed by poly test for running source/test code? Or some debug mode that prints out exactly what ends up on the classpath etc?

seancorfield05:06:12

Some of this may be because poly doesn’t yet respect things like :jvm-opts from the :test aliases or projects (and somehow tests are not run in a context that inherits properties from the poly tool’s execution context?)…

tengstrand05:06:00

It definitively feels like this is an undeveloped area of the poly tool at the moment, that needs to be improved! When you say “… from the `poly` tool’s execution context?” do you refer to the AOT compiled poly command?

seancorfield06:06:40

No. Kinda hard to explain without me having a better understanding of exactly how poly executes tests.

seancorfield06:06:27

Example: I run poly from source, via the alias, using :git/url. So I can set :jvm-opts as part of that alias and they affect how poly itself executes.

seancorfield06:06:46

But I don’t know how poly runs tests, so I don’t know what execution context it sets up for them.

seancorfield06:06:59

Is it in process or via a shelled-out process?

seancorfield06:06:30

Right, I haven’t had time to dig into that yet.

tengstrand06:06:35

I understand.

seancorfield06:06:05

At a quick glance, it looks like it runs tests in-process using a new classloader, yes?

seancorfield06:06:34

So I would expect any JVM options set for poly’s execution to be available in the tests…

tengstrand06:06:58

I guess you are right!

seancorfield01:06:38

@tengstrand I’ve done some more digging into this and I’ve come to the following conclusions/positions: 1. You can have that org.slf4j/slf4j-nop dep in the poly project deps.edn directly. Now that I understand how tests are run, I have managed to confirm that I can override the logging deps however I want in my components — regardless of the no-op logging in poly itself. Sorry for the runaround on that but my testing scenarios were based on a faulty assumption! 2. Any JVM properties a user needs for running tests has to be specified in the :poly alias, as far as I can tell — so that probably ought to be documented, but it also begs the question of how JVM options can be provided for the (AOT-compiled) poly command itself? 3. I can provide log4j2 configuration via environment variables or JVM properties but I must specify a full file path because components don’t necessarily have the property files on the classpath: because those would normally be provided in projects deps.edn files (i.e., project-specific resources). There’s still a slight quirk for my setup that if I fail to explicitly specify the log4j2 configuration file (via the environment, for example), I get failures in the test. I haven’t worked out what I need to tweak to make that work.

tengstrand04:06:51

Thanks for digging into this. Unfortunately, this is not my expert area (even though every programmer needs to deal with these things now and then) but now is maybe the time to become one 😉 I need to make some research to see if I can figure out how JVM options can be provided for the AOT-compiled poly command. About the component property files, maybe they can be explicitly included by the test runner. If you want, you can also create an issue and a branch in the usermanager project where you manage to reproduce these problems.

tengstrand04:06:27

I guess you could pass in the JVM options in the poly batch script. I commented out one line in my script, so it looks like this right now:

#!/usr/bin/env bash
# JAVA_HOME="${JAVA_HOME:-/usr/local/opt/openjdk/libexec/openjdk.jdk/Contents/Home}" exec "/usr/local/Cellar/poly/0.1.0-alpha9/libexec/bin/poly"  "$@"

exec /usr/bin/java -jar /usr/local/polylith/poly.jar $@%

seancorfield04:06:39

Yeah, you probably ought to insert a $JVM_OPTS var between /usr/bin/java and -jar.

seancorfield04:06:03

That way folks can do JVM_OPTS=... poly ...

seancorfield04:06:52

I haven't figured out a good way, yet, of setting up test-only resources that can still easily be overridden when running the poly tool -- especially since the way you do it for the alias and for the AOT/shell-script version are essentially different. Hard problems.

seancorfield04:06:39

BTW, we're up to 16 components at work now 🙂

👍 3
seancorfield04:06:51

It's complicated a bit by having to keep two "build systems" running side-by-side: I have to ensure all of the new components can still be tested/managed by our existing build script, as well as ensuring that poly can run all the tests properly 🙂

seancorfield04:06:47

Did you attend clojureD, BTW?

seancorfield04:06:46

Oh, and I finally listened to part 1 of the Polylith podcast on ClojureScript Podcast with Jacek. It was very good! Hope to listen to part 2 tomorrow or Monday.

tengstrand14:06:05

No, didn’t attend clojureD unfortunately. Nice that you liked the first episode! Yes, good idea to insert JVM_OPTS to the polyscript. I will discuss these problem with @U2BDZ9JG3 tonight and see if he has any good ideas.

furkan3ayraktar18:06:25

I and Joakim have discussed the following changes to improve the testing behaviour. We wanted to double check if it sounds good to you @U04V70XH6. 1. We can add $JVM_OPTS to the AOT compiled poly CLI shell script as you suggested. It will look like this: exec "$JAVA_CMD" $JVM_OPTS -jar "$poly_jar" "$@". This way folks can provide $JVM_OPTS while running the poly command to override settings. 2. We can add support to include :override-deps in test alias of each project deps.edn files. Then, we can use those overridden dependencies when we create the ClassLoader for running the tests. You can https://github.com/polyfy/polylith/blob/887e4237cec8f42eaa15be3501f134732602bb41/components/deps/src/polylith/clj/core/deps/lib_deps.clj#L27 in the codebase that we resolve dependencies for tests. On this line: (tools-deps/resolve-deps config {:extra-deps deps}), we will include :override-deps. How do these changes sound?

seancorfield18:06:58

#1 sounds good. I haven’t done a poll of existing prior art to see whether JVM_OPTS or JAVA_OPTS or something else would be the best choice for the name (but I think JVM_OPTS is fine).

seancorfield18:06:33

#2 yes, definitely respect :override-deps although I don’t think it helps much in the larger picture (we’ve stopped using :override-deps at work because it just doesn’t provide enough benefit).

seancorfield18:06:10

I think the testing setup is working “correctly” as it is — now that I understand how the classloader/classpath stuff is built for each component’s test run (at least I think I understand it! 🙂 )

seancorfield18:06:53

I still have to dig into my slightly strange testing issue because that isn’t quite behaving how I would expect, based on my mental model.

seancorfield18:06:39

Documentation would probably help here. Am I correct that tests are run in a context that is basically :dev + the component’s :deps plus :test alias :extra-deps (and soon :override-deps)?

furkan3ayraktar18:06:54

Yeah, I agree, we should extend the section about testing in the documentation. When it comes to testing, there are two ways; 1) You can run the tests in your REPL as usual, Polylith does not do anything special there. 2) You can use poly test to run the tests incrementally. When it comes to option 2, first we calculate which projects are affected by the current changes. Then, we run the tests for the bricks that are included in the affected projects, and the project specific tests. When we run those tests, we use a ClassLoader to make sure we are in the correct context which is the project’s deps.edn file. This ClassLoader includes all the sources, resources, and dependencies from the project’s bricks plus the :extra-paths and :extra-deps from the :test alias of the project.

seancorfield19:06:30

I think the JVM_OPTS / :jvm-opts issue is probably the biggest "gotcha" that isn't documented at all right now. You start a REPL with the :dev alias (and the :test alias if you want to run tests interactively from your editor/REPL) so it make sense to provide :jvm-opts in :dev for things like: checking go macro expansion, disabling the optimization of stack traces, forcing tools.logging to select a logger factory(!), controlling illegal reflective access, etc. But when you run tests from the command line, you're either using the poly tool or the :poly alias and so the :jvm-opts in :dev can't take effect -- so you either need to duplicate :jvm-opts into the :poly alias or into JVM_OPTS for the poly shell wrapper. Make sense?

seancorfield19:06:11

"This ClassLoader includes all the sources, resources, and dependencies from the project’s bricks" -- what is the parent classloader for this? Is it just the poly tool / :poly alias context? Does the poly tool use the :dev or :test context from the workspace-level deps.edn file at all?

seancorfield19:06:13

(I'm trying to figure out exactly how a component that calls into other components is going to be run in tests, given that components do not specify dependencies on each other -- that only happens at the :dev or projects level).

seancorfield19:06:32

So, clarity on how poly test deals with what's in the workspace level deps.edn file -- specifically the :test alias -- and how the contexts are created for poly test via a given project and for the :dev project.

seancorfield19:06:46

(I am currently mostly doing poly test :dev because I have a lot of components that are used by our legacy code but not yet by bases or projects)

seancorfield19:06:21

Perhaps having a debug/verbose option on poly test that explains more about what it is doing as it is building classloaders would help?

seancorfield19:06:06

(so it could say which deps.edn files it is using for each set of tests and what keys/aliases from each it is using)

furkan3ayraktar19:06:04

We get the parent ClassLoader as follows:

(def base-classloader
  (or (.getClassLoader clojure.lang.RT)
      (.getContextClassLoader (Thread/currentThread))))

(def ext-classloader
  (.getParent ^ClassLoader base-classloader))

furkan3ayraktar19:06:29

When you run poly test, it does not include the :dev alias automatically. However, :dev is a special project in Polylith, you can run poly test :dev to include it.

furkan3ayraktar19:06:39

Let’s say there are two components A and B. And, project P1 only includes component B, and project P2 includes both A and B. In that case, when you run poly test it will run tests for both A and B in the context of project P2 and run tests for B in the context of project P1.

seancorfield19:06:51

What about the :test alias in the workspace level deps.edn file? That's included into each test context?

seancorfield19:06:23

And the :dev alias is used (only) for the poly test :dev context where the :dev alias is used as a "project context", right?

furkan3ayraktar19:06:53

Nope, the workspace level :test is only for the development project and REPL. So, when you run poly test :dev the :dev alias and the :test alias is used to resolve the ClassLoader context. Workspace level :dev and :test aliases are only used by the development project.

seancorfield19:06:06

Ah, OK. So there's no sense in having any overlap of stuff between :dev and :test because :test is only used in combination with :dev? I guess I missed that (and need to clean up our :test alias at work).

seancorfield19:06:17

I suspect some of my (self-inflicted) complexity and confusion is due to being in a "migration" mode at work so our :test alias is doing double duty: for our existing build-driven testing and for the new poly-based testing 🙂

tengstrand19:06:29

It feels like you got it now! 🙂

seancorfield19:06:48

This stuff is important if you're using a non-`clojure.test` library for testing (such as we do: Expectations and test.check). So it sounds like those need to go into :test for testing the :dev project and into either a component's :test alias or a project's :test alias, as needed?

tengstrand19:06:41

Yes, that’s correct.

tengstrand19:06:59

And if everything works as expected, things should work this way in the issue-66branch already.

seancorfield17:06:56

However, even though our test properties should cause logging from INFO level and above to appear during tests runs (as they do when running tests via a “regular” runner), when those tests are run via poly, only ERROR level and above are displayed, and it does not use the logging format from our test properties file.

seancorfield17:06:05

(I know that it’s picking up the test properties file because if I fail to add development/resources, log4j2 displays an error when the poly tool starts that it can’t find the specified properties file)

seancorfield17:06:50

So the question is: does the poly tool configure logging somewhere and how can I override that to get the behavior I want?

seancorfield22:06:33

Is this considered reasonable in an interface, rather than pushing the multiple arities into the implementation?

(defn from-json
  "Given a message, return a response-processing function.
  Given a message and a response, attempt to decode the
  body of the response as JSON.

  Failures are logged, using the message, and returned as
  a new `:error` key (with `:body` removed)."
  ([message] (fn [response] (impl/from-json response message)))
  ([message response]       (impl/from-json response message)))

tengstrand00:06:41

Yes, that looks reasonable to me. As long as the code we write improves the readability and changeability, I think we should feel free to put implementing code in the interface. Often the right thing to do is to put all implementing code in another namespace than the interface, but sometimes it does make more sense to put it there. We should not just follow rules and instead do what we think is best for the health of the codebase, which this probably is a good example of (and if we change our mind, it’s easy to move the code to the implementing interface).

6
👍 2