@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).
Okay, will have a look at that today.
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?
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 "<https://github.com/polyfy/polylith>"
: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"}}}
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).
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?
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?)…
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?
No. Kinda hard to explain without me having a better understanding of exactly how poly executes tests.
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.
But I don’t know how poly
runs tests, so I don’t know what execution context it sets up for them.
Is it in process or via a shelled-out process?
It uses the https://github.com/polyfy/polylith/tree/issue-66/components/test-runner/src/polylith/clj/core/test_runner.
Right, I haven’t had time to dig into that yet.
I understand.
At a quick glance, it looks like it runs tests in-process using a new classloader, yes?
Yes
So I would expect any JVM options set for poly
’s execution to be available in the tests…
I guess you are right!
@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.
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.
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 $@%
Yeah, you probably ought to insert a $JVM_OPTS
var between /usr/bin/java
and -jar
.
That way folks can do JVM_OPTS=... poly ...
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.
BTW, we're up to 16 components at work now 🙂
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 🙂
Did you attend clojureD, BTW?
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.
No, didn’t attend clojureD unfortunately. Nice that you liked the first episode! Yes, good idea to insert JVM_OPTS
to the poly
script. I will discuss these problem with @furkan3ayraktar tonight and see if he has any good ideas.
I and Joakim have discussed the following changes to improve the testing behaviour. We wanted to double check if it sounds good to you @seancorfield.
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?
#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).
#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).
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! 🙂 )
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.
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
)?
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.
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?
"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?
(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).
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.
(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
)
Perhaps having a debug/verbose option on poly test
that explains more about what it is doing as it is building classloaders would help?
(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)
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))
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.
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.
What about the :test
alias in the workspace level deps.edn
file? That's included into each test context?
And the :dev
alias is used (only) for the poly test :dev
context where the :dev
alias is used as a "project context", right?
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.
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).
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 🙂
It feels like you got it now! 🙂
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?
Yes, that’s correct.
And if everything works as expected, things should work this way in the issue-66
branch already.
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.
(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)
So the question is: does the poly
tool configure logging somewhere and how can I override that to get the behavior I want?
I looks like you (@seancorfield) 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 @furkan3ayraktar on how to best solve this, but if you have any suggestions, you are welcome.
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?
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.
That would be great! I added the log4j
library to get rid of warnings, but missed that it could be useful to configure it!
@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.
If I remove the log4j
library, I get a warning when I run the test command.
Just add org.slf4j/slf4j-nop {:mvn/version "1.7.25"}
instead (no need for log4j2 or the slf4 bridge).
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).
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.
(this is kind of like projects
including final sets of deps but components allowing for some flexibility)
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)))