Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Baffling IOException in :duct/compiler #37

Closed
dpiliouras opened this issue Jan 13, 2021 · 8 comments
Closed

Baffling IOException in :duct/compiler #37

dpiliouras opened this issue Jan 13, 2021 · 8 comments

Comments

@dpiliouras
Copy link

Hi there and thanks once again for your work on the various Clojure libs - hugely appreciated 馃憤

Now, I'm trying to debug a rather baffling IOException in a duct-based project, and the reason I am asking here is because I tried to reproduce the error in a bare project and it doesn't show up. I should warn you this is confusing stuff, so be prepared.

I have a library full of utilities at hand - let's call it foo-tools. In there one can find a foo.tools.logging.structured.clj, which integrates clojure.tools.logging with log4j2, and in particular leveraging MapMessage (for structured logging). So basically you will find the usual suspects - a couple of (System/setProperty ... ) expressions, a couple of alter-var-root expressions (for #'ctl/*force* and #'ctl/log*), and logging-macro variants (infom, debugm, errorm etc). All good so far, this library compiles just fine and logging works as expected. The same is true when I depend on this library from a bare project - no issues whatsoever.

However, when I depend on this library from a duct-based project, confusion begins...I will first paste the DEBUG output of lein check, and then I will paste the actual stack-trace which is not actually very helpful because it points to namespace loading issues.

DEBUG=true lein check        
Leiningen's classpath: /Users/dimitriospiliouras/.lein/self-installs/leiningen-2.9.1-standalone.jar
OpenJDK 64-Bit Server VM warning: Options -Xverify:none and -noverify were deprecated in JDK 13 and will likely be removed in a future release.
Applying task check to []
Applying task javac to nil
Running javac with [@/var/folders/zw/c3k5myj97z740h4sqdmnvwsr0000gq/T/.leiningen-cmdline5659625979363096591.tmp]
Applying task compile to nil
All namespaces already AOT compiled.
Applying task run to (:duct/compiler)
Syntax error (IOException) compiling at (com/foo/tools/logging/structured.clj:124:1).
Stream closed

Full report at:
/var/folders/zw/c3k5myj97z740h4sqdmnvwsr0000gq/T/clojure-15911932431814012512.edn

I can see that something went wrong in :duct/compiler task. but I'm not sure where that code is :(. Here are the contents of the clojure-15911932431814012512.edn file:

{:clojure.main/message
 "Syntax error (IOException) compiling at (com/foo/tools/logging/structured.clj:124:1).\nStream closed\n",
 :clojure.main/triage
 {:clojure.error/phase :compile-syntax-check,
  :clojure.error/line 124,
  :clojure.error/column 1,
  :clojure.error/source "structured.clj",
  :clojure.error/path "com/foo/tools/logging/structured.clj",
  :clojure.error/class java.io.IOException,
  :clojure.error/cause "Stream closed"},
 :clojure.main/trace
 {:via
  [{:type clojure.lang.Compiler$CompilerException,
    :message
    "Syntax error compiling at (com/foo/tools/logging/structured.clj:124:1).",
    :data
    {:clojure.error/phase :compile-syntax-check,
     :clojure.error/line 124,
     :clojure.error/column 1,
     :clojure.error/source "com/foo/tools/logging/structured.clj"},
    :at [clojure.lang.Compiler load "Compiler.java" 7652]}
   {:type java.io.IOException,
    :message "Stream closed",
    :at
    [java.util.zip.InflaterInputStream
     ensureOpen
     "InflaterInputStream.java"
     67]}],
  :trace
  [[java.util.zip.InflaterInputStream
    ensureOpen
    "InflaterInputStream.java"
    67]
   [java.util.zip.InflaterInputStream
    read
    "InflaterInputStream.java"
    142]
   [java.io.FilterInputStream read "FilterInputStream.java" 132]
   [sun.nio.cs.StreamDecoder readBytes "StreamDecoder.java" 297]
   [sun.nio.cs.StreamDecoder implRead "StreamDecoder.java" 339]
   [sun.nio.cs.StreamDecoder read "StreamDecoder.java" 188]
   [java.io.InputStreamReader read "InputStreamReader.java" 181]
   [java.io.BufferedReader fill "BufferedReader.java" 161]
   [java.io.BufferedReader read "BufferedReader.java" 182]
   [java.io.LineNumberReader read "LineNumberReader.java" 126]
   [java.io.FilterReader read "FilterReader.java" 65]
   [java.io.PushbackReader read "PushbackReader.java" 90]
   [clojure.lang.LineNumberingPushbackReader
    read
    "LineNumberingPushbackReader.java"
    66]
   [clojure.lang.LispReader read1 "LispReader.java" 170]
   [clojure.lang.Compiler consumeWhitespaces "Compiler.java" 7593]
   [clojure.lang.Compiler load "Compiler.java" 7637]
   [clojure.lang.RT loadResourceScript "RT.java" 381]
   [clojure.lang.RT loadResourceScript "RT.java" 372]
   [clojure.lang.RT load "RT.java" 459]
   [clojure.lang.RT load "RT.java" 424]
   [clojure.core$load$fn__6857 invoke "core.clj" 6115]
   [clojure.core$load invokeStatic "core.clj" 6114]
   [clojure.core$load doInvoke "core.clj" 6098]
   [clojure.lang.RestFn invoke "RestFn.java" 408]
   [clojure.core$load_one invokeStatic "core.clj" 5897]
   [clojure.core$load_one invoke "core.clj" 5892]
   [clojure.core$load_lib$fn__6797 invoke "core.clj" 5937]
   [clojure.core$load_lib invokeStatic "core.clj" 5936]
   [clojure.core$load_lib doInvoke "core.clj" 5917]
   [clojure.lang.RestFn applyTo "RestFn.java" 142]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$load_libs invokeStatic "core.clj" 5974]
   [clojure.core$load_libs doInvoke "core.clj" 5958]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$require invokeStatic "core.clj" 5996]
   [clojure.core$require doInvoke "core.clj" 5996]
   [clojure.lang.RestFn invoke "RestFn.java" 551]
   [com.foo.auth.api.impl.authentication$eval5055$loading__6738__auto____5056
    invoke
    "authentication.clj"
    1]
   [com.foo.auth.api.impl.authentication$eval5055
    invokeStatic
    "authentication.clj"
    1]
   [com.foo.auth.api.impl.authentication$eval5055
    invoke
    "authentication.clj"
    1]
   [clojure.lang.Compiler eval "Compiler.java" 7181]
   [clojure.lang.Compiler eval "Compiler.java" 7170]
   [clojure.lang.Compiler load "Compiler.java" 7640]
   [clojure.lang.RT loadResourceScript "RT.java" 381]
   [clojure.lang.RT loadResourceScript "RT.java" 372]
   [clojure.lang.RT load "RT.java" 459]
   [clojure.lang.RT load "RT.java" 424]
   [clojure.core$load$fn__6857 invoke "core.clj" 6115]
   [clojure.core$load invokeStatic "core.clj" 6114]
   [clojure.core$load doInvoke "core.clj" 6098]
   [clojure.lang.RestFn invoke "RestFn.java" 408]
   [clojure.core$load_one invokeStatic "core.clj" 5897]
   [clojure.core$load_one invoke "core.clj" 5892]
   [clojure.core$load_lib$fn__6797 invoke "core.clj" 5937]
   [clojure.core$load_lib invokeStatic "core.clj" 5936]
   [clojure.core$load_lib doInvoke "core.clj" 5917]
   [clojure.lang.RestFn applyTo "RestFn.java" 142]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$load_libs invokeStatic "core.clj" 5978]
   [clojure.core$load_libs doInvoke "core.clj" 5958]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$require invokeStatic "core.clj" 5996]
   [clojure.core$require doInvoke "core.clj" 5996]
   [clojure.lang.RestFn invoke "RestFn.java" 3204]
   [com.foo.auth.api.endpoints$eval5049$loading__6738__auto____5050
    invoke
    "endpoints.clj"
    1]
   [com.foo.auth.api.endpoints$eval5049
    invokeStatic
    "endpoints.clj"
    1]
   [com.foo.auth.api.endpoints$eval5049 invoke "endpoints.clj" 1]
   [clojure.lang.Compiler eval "Compiler.java" 7181]
   [clojure.lang.Compiler eval "Compiler.java" 7170]
   [clojure.lang.Compiler load "Compiler.java" 7640]
   [clojure.lang.RT loadResourceScript "RT.java" 381]
   [clojure.lang.RT loadResourceScript "RT.java" 372]
   [clojure.lang.RT load "RT.java" 459]
   [clojure.lang.RT load "RT.java" 424]
   [clojure.core$load$fn__6857 invoke "core.clj" 6115]
   [clojure.core$load invokeStatic "core.clj" 6114]
   [clojure.core$load doInvoke "core.clj" 6098]
   [clojure.lang.RestFn invoke "RestFn.java" 408]
   [clojure.core$load_one invokeStatic "core.clj" 5897]
   [clojure.core$load_one invoke "core.clj" 5892]
   [clojure.core$load_lib$fn__6797 invoke "core.clj" 5937]
   [clojure.core$load_lib invokeStatic "core.clj" 5936]
   [clojure.core$load_lib doInvoke "core.clj" 5917]
   [clojure.lang.RestFn applyTo "RestFn.java" 142]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$load_libs invokeStatic "core.clj" 5974]
   [clojure.core$load_libs doInvoke "core.clj" 5958]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.core$apply invokeStatic "core.clj" 669]
   [clojure.core$require invokeStatic "core.clj" 5996]
   [clojure.core$require doInvoke "core.clj" 5996]
   [clojure.lang.RestFn invoke "RestFn.java" 408]
   [integrant.core$try_require invokeStatic "core.cljc" 171]
   [integrant.core$try_require invoke "core.cljc" 170]
   [clojure.core$keep$fn__8584 invoke "core.clj" 7346]
   [clojure.lang.LazySeq sval "LazySeq.java" 42]
   [clojure.lang.LazySeq seq "LazySeq.java" 58]
   [clojure.lang.Cons next "Cons.java" 39]
   [clojure.lang.RT next "RT.java" 713]
   [clojure.core$next__5404 invokeStatic "core.clj" 64]
   [clojure.core$dorun invokeStatic "core.clj" 3130]
   [clojure.core$doall invokeStatic "core.clj" 3136]
   [clojure.core$doall invoke "core.clj" 3136]
   [integrant.core$load_namespaces invokeStatic "core.cljc" 184]
   [integrant.core$load_namespaces invoke "core.cljc" 175]
   [integrant.core$load_namespaces invokeStatic "core.cljc" 182]
   [integrant.core$load_namespaces invoke "core.cljc" 175]
   [duct.core$prep_config invokeStatic "core.clj" 202]
   [duct.core$prep_config invoke "core.clj" 192]
   [duct.core$exec_config invokeStatic "core.clj" 233]
   [duct.core$exec_config invoke "core.clj" 221]
   [com.elcom.auth.main$_main invokeStatic "main.clj" 12]
   [com.elcom.auth.main$_main doInvoke "main.clj" 7]
   [clojure.lang.RestFn invoke "RestFn.java" 408]
   [clojure.lang.Var invoke "Var.java" 384]
   [user$eval151 invokeStatic "form-init6731054948017491289.clj" 1]
   [user$eval151 invoke "form-init6731054948017491289.clj" 1]
   [clojure.lang.Compiler eval "Compiler.java" 7181]
   [clojure.lang.Compiler eval "Compiler.java" 7171]
   [clojure.lang.Compiler load "Compiler.java" 7640]
   [clojure.lang.Compiler loadFile "Compiler.java" 7578]
   [clojure.main$load_script invokeStatic "main.clj" 475]
   [clojure.main$init_opt invokeStatic "main.clj" 477]
   [clojure.main$init_opt invoke "main.clj" 477]
   [clojure.main$initialize invokeStatic "main.clj" 508]
   [clojure.main$null_opt invokeStatic "main.clj" 542]
   [clojure.main$null_opt invoke "main.clj" 539]
   [clojure.main$main invokeStatic "main.clj" 664]
   [clojure.main$main doInvoke "main.clj" 616]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.lang.Var applyTo "Var.java" 705]
   [clojure.main main "main.java" 40]],
  :cause "Stream closed",
  :phase :compile-syntax-check}}

As you can see, the stack-trace is kind of misleading...it points the finger at structured.clj , but I know for a fact that there is nothing syntactically wrong with that namespace - I can AOT compile it and everything.

To make matters even more confusing, the duct-based project that throws the above on lein check, works just fine through the regular REPL workflow (dev, go etc), including logging! Do you have any idea or clues about what could happening here? Many thanks in advance...

As always, keep up the good work (and stay healthy) 馃憤

@weavejester
Copy link
Contributor

I can't diagnose issues in custom code without being able to see that code.

@dpiliouras
Copy link
Author

There is no particular piece of code that I can isolate in order to show you. That is why I tried to explain the problem at a high-level. I would have to create two dummy projects, and you would have to install one of them locally, in order to reproduce the issue. I'll try to do that this morning and get back to you...

Out of curiosity, where does the code for the :duct/compiler live?

@dpiliouras
Copy link
Author

dpiliouras commented Jan 14, 2021

After spending a few hours on this, I have officially hit a dead-end :(. The new (duct-based) dummy project doesn't exhibit the same issue, regardless of whether it depends on the original library, or a (newly installed) stripped down version, so i have nothing to share with you (at this point).

Would you be able to explain to me the order in which the namespaces are loaded? On the new dummy project I can see the following (notice the Compiling namespace dev right after Applying task run to (:duct/compiler)):

Applying task check to []
Applying task javac to nil
Running javac with [@/var/folders/zw/c3k5myj97z740h4sqdmnvwsr0000gq/T/.leiningen-cmdline15650892232635446166.tmp]
Applying task compile to nil
All namespaces already AOT compiled.
Applying task run to (:duct/compiler)
Compiling namespace dev
Performance warning, duct/core/env.clj:20:3 - hash collision of some case test constants; if selected, those entries will be tested sequentially.
Reflection warning, hawk/core.clj:16:30 - reference to field isFile can't be resolved.
Reflection warning, hawk/core.clj:21:18 - reference to field toPath can't be resolved.
Reflection warning, hawk/core.clj:22:18 - reference to field getParentFile can't be resolved.
Reflection warning, hawk/core.clj:22:18 - reference to field toPath can't be resolved.
Reflection warning, hawk/core.clj:33:25 - reference to field toPath on java.lang.Object can't be resolved.
Reflection warning, hawk/core.clj:35:29 - call to method startsWith can't be resolved (target class is unknown).
Reflection warning, hawk/core.clj:47:22 - call to method compareTo can't be resolved (target class is unknown).
Reflection warning, hawk/core.clj:55:27 - call to method startsWith can't be resolved (target class is unknown).
Reflection warning, hawk/core.clj:95:3 - reference to field interrupt can't be resolved.
Reflection warning, hawk/core.clj:95:3 - reference to field join can't be resolved.
Reflection warning, hawk/core.clj:100:3 - reference to field isFile on java.lang.Object can't be resolved.
Reflection warning, hawk/core.clj:103:3 - reference to field isDirectory on java.lang.Object can't be resolved.
Reflection warning, duct/core/repl.clj:24:39 - reference to field getName on java.lang.Object can't be resolved.
Reflection warning, eftest/report.clj:30:11 - reference to field close can't be resolved.
Reflection warning, eftest/output_capture.clj:8:25 - reference to field toByteArray can't be resolved.
Reflection warning, eftest/output_capture.clj:8:40 - call to java.lang.String ctor can't be resolved.
Reflection warning, eftest/output_capture.clj:30:32 - call to method write can't be resolved (target class is unknown).
Reflection warning, eftest/output_capture.clj:31:32 - call to method write can't be resolved (target class is unknown).
Reflection warning, eftest/output_capture.clj:33:30 - call to method write can't be resolved (target class is unknown).
Reflection warning, eftest/runner.clj:61:14 - reference to field get can't be resolved.
Reflection warning, eftest/runner.clj:59:14 - call to method submit can't be resolved (target class is unknown).
Compiling namespace user
Compiling namespace duct-foo.main
Compiling namespace duct-foo.bar.api
Compiling namespace duct-foo.bar.macros

On my original project that I'm trying to debug, I don't see the Compiling namespace dev line, and judging from the stack-trace, it seems to jump straight to the main one. Is that a helpful clue at all? The two projects have virtually identical project.clj files.

Many thanks in advance...

@weavejester
Copy link
Contributor

weavejester commented Jan 14, 2021

Out of curiosity, where does the code for the :duct/compiler live?

The :duct/compiler key doesn't do anything itself. It's the parent from which keys that need to do some compilation derive.

You can see in your project.clj file this line:

:prep-tasks ["javac" "compile" ["run" ":duct/compiler"]]

This will initiate all keys deriving from :duct/compiler before packaging everything into an uberjar. This might be useful for doing one-time jobs, such as minimising CSS.

The prep tasks are the same as doing:

lein javac
lein compile
lein run :duct/compiler

However, note that the Leiningen profile may be different. I believe that it may just use the base and uberjar profiles, but I haven't checked. When you run a REPL, you usually have the base, dev, user and repl profiles.

You can find the keys that are used in this step by using Integrant's find-derived function after you've prepped the config:

user=> (dev)
:loaded
dev=> (prep)
:prepped
dev=> (ig/find-derived config :duct/compiler)

@dpiliouras
Copy link
Author

dpiliouras commented Jan 15, 2021

Hi again, and thanks for the prompt response yesterday. There are no keys deriving from :duct/compiler in my config so I guess that's the wrong tree to bark at.

I am attaching two zip files below. The elcom-tools has actual code in, but by no means secret (some low level utils). You can confirm that it fully compiles via lein check. In fact, you can jump into com.elcom.tools.clients.http and try the comment at the end of the file, to confirm that logging works. If you're happy with it, do a lein install.

Now open the second one called elcom-auth. This has practically no code in, and so its duct config is pretty bare. You can again try lein-check and it should finish just fine. Now, jump into dev.clj and uncomment the very last :require clause. Try lein-check again and you should witness the error I was talking about.

I've been doing Clojure for close to 10 years now, and this is probably the most bizarre issue I've ever encountered. I am beyond baffled at this point :(.

Many thanks in advance...

elcom-tools.zip
elcom-auth.zip

ps: I should also say that a bare (non-duct) project requiring elcom-tools doesn't exhibit the issue:

(ns sanity-check.core
  (:require  [com.elcom.tools.logging.structured :as l]))

(defn foo
  "I don't do a whole lot."
  [x]
  (l/infom "hi" :a "1" :b "2"))

produces

$ lein check
OpenJDK 64-Bit Server VM warning: Options -Xverify:none and -noverify were deprecated in JDK 13 and will likely be removed in a future release.
Compiling namespace sanity-check.core
$

@weavejester
Copy link
Contributor

This is an interesting problem. I cleaned up the two project zips you provided, cutting out anything that wasn't related to the error:

The cause appears to be an interaction between your log4j setup and the Clojure class loader. I can't be sure, but my guess is that something like this happens:

  1. The Clojure classloader opens a stream to read com.elcom.tools.logging.structured from the jar.
  2. The clojure.tools.logging namespace is then required and loaded.
  3. Log4j is triggered from clojure.tools.logging, which then tries to read from the elcom-tools jar again, probably to load in your custom logging class or properties file.
  4. This second read appears to close the first stream to com.elcom.tools.logging.structured, causing an IO error from the still-open reader.

Note that this only occurs when the classloader is trying to load from a jar. The moment the files are cached in the target directory, everything is works fine.

Feel free to post those files up to the Clojure Google group or somewhere like that. They may have more insight as to the interactions between log4j and the Clojure classloader, as they relate to loading from jars in particular.

As a workaround, you can force a load of clojure.tools.logging before you load up com.elcom.tools.logging.structured:

(ns dev
  (:refer-clojure :exclude [test])
  (:require [clojure.repl :refer :all]
            ...
            [clojure.tools.logging]
            [com.elcom.tools.logging.structured]))

This ensures that the elcom-tools jar isn't being hit twice at the same time.

@dpiliouras
Copy link
Author

WOW - first of all, the workaround does work, and for that I'm very grateful. I will post a message to the Clojure mailing list (first thing Monday morning), with a link back here, if that's ok.

Thanks again - have a great weekend 馃憤

@weavejester
Copy link
Contributor

That's fine. Have a good weekend!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants