Cannot format message if compiler output contains %

[jilen]

a java.util.UnknownFormatConversionException will be thrown

[lefou]

Can you please post the full Mill + compiler output, the full command, relevant compiler settings and a source file that causes the output (if any).

[jilen]

Something like this. Produced by mill -j 8 __.compile

[#2] 2022-06-14 10:45:42,308 pool-1-thread-4 ERROR Unable to format msg: /path/to/some/file:103:11: SELECT COUNT(*) FROM course x30 WHERE x30.store_id = $1 AND x30.status = $2 AND x30.online = true AND x30.name like ('%' || $3) || '%' java.util.UnknownFormatConversionException: Conversion = '''

[lefou]

Something like this. Produced by mill -j 8 __.compile

[#2] 2022-06-14 10:45:42,308 pool-1-thread-4 ERROR Unable to format msg: /path/to/some/file:103:11: SELECT COUNT(*) FROM course x30 WHERE x30.store_id = $1 AND x30.status = $2 AND x30.online = true AND x30.name like ('%' || $3) || '%' java.util.UnknownFormatConversionException: Conversion = '''

A file without an extension (/path/to/some/file) should not end up in the file list which is fed to the compiler. Assuming this is a scala file (file.scala), the quoted SQL expression doesn't look like valid Scala, too. Please provide all details necessary to understand your issue!

[jilen]

That is just an example, not actual file name. I'll try make a reproducable repo, if you like.
That quoted sql was produced by https://github.com/zio/zio-quill/

[jilen]

https://github.com/jilen/mill-format-prj/runs/6876008355?check_suite_focus=true#step:5:240 you can take a look at here. It seems harmless, though.

[lefou]

I can't tell whether this is supposed to work or a programming error. If you consider it correct code, you should report the issue upstream to zinc/sbt or even zio-quill, as it is unrelated to Mill code.

[jilen]

I can confirm sbt won't have this issue. Seems related to compiler reporter. I saw it was caused by log4j indeed.

Note I haven't run any code, just compile.

[jilen]

 [#3] 	at sbt.internal.inc.IncrementalCompilerImpl.compile(IncrementalCompilerImpl.scala:137)
[#3] 	at mill.scalalib.worker.ZincWorkerImpl.compileInternal(ZincWorkerImpl.scala:544)
[#3] 	at mill.scalalib.worker.ZincWorkerImpl.$anonfun$compileMixed0$1(ZincWorkerImpl.scala:317)
[#3] 	at mill.api.FixSizedCache.withCachedValue(FixSizedCache.scala:66)
[#3] 	at mill.scalalib.worker.ZincWorkerImpl.withCompilers(ZincWorkerImpl.scala:399)
[#3] 	at mill.scalalib.worker.ZincWorkerImpl.compileMixed0(ZincWorkerImpl.scala:316)
[#3] 	at mill.scalalib.worker.ZincWorkerImpl.compileMixed(ZincWorkerImpl.scala:284)
[#3] 	at mill.scalalib.ScalaModule.$anonfun$compile$2(ScalaModule.scala:195)
[#3] 	at mill.define.Task$TraverseCtx.evaluate(Task.scala:380)
[#3] 	at mill.eval.Evaluator.$anonfun$evaluateGroup$13(Evaluator.scala:627)
[#3] 	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)

@lefou not totally unrelated to mill, see the stack trace

[lefou]

I reopen to investigate further.

AFAIK, we don't use log4j explicitly. Log4j is an transitive dependency of zinc, but we control the exact version in our dependency setup to mitigate security issues.

I could imagine that sbt is using zinc differently (it has lots of internal API which we can't use) than Mill and only Mill triggers this issues. And I still think this issue should be reported upstream too.

[lefou]

A minimal repro with Mill build file and sbt build file would be ideal.

[jilen]

https://github.com/jilen/mill-format-prj

[jilen]

I could imagine that sbt is using zinc differently (it has lots of internal API which we can't use) than Mill and only Mill triggers this issues. And I still think this issue should be reported upstream too.

I think you are right. Might caused by unexpected usage of log4j. I won't mind if you'd like to close this issue.

[lefou]

Related issue, where this error message is seen, too:

• Incorrect zinc modified binary dependencies #1901

[lefou]

I just compiled your linked project with sbt (version 1.6.2), and the error message did not appear.

08:32:05 θ72° lefou:~/work/tmp/mill-format-prj main(+3/-0)* ± mkdir project
08:32:07 θ71° lefou:~/work/tmp/mill-format-prj main(+3/-0)* ± echo "sbt.version=1.6.2" > project/build.properties
08:32:22 θ74° lefou:~/work/tmp/mill-format-prj main(+3/-0)* 4s ± sbt
[info] welcome to sbt 1.6.2 (Eclipse Adoptium Java 11.0.15)
[info] loading settings for project global-plugins from eclipse.sbt,idea.sbt ...
[info] loading global plugins from /home/lefou/.sbt/1.0/plugins
[info] loading project definition from /home/lefou/work/tmp/mill-format-prj/project
[info] loading settings for project root from build.sbt ...
[info] set current project to root (in build file:/home/lefou/work/tmp/mill-format-prj/)
[info] sbt server started at local:///home/lefou/.sbt/1.0/server/b470f076afe180d6527c/sock
[info] started sbt server
sbt:root> debug
sbt:root> compile
[debug] Other repositories:
[debug] Default repositories:
[debug] Using inline dependencies specified in Scala.
[debug] not up to date. inChanged = true, force = false
[debug] Updating app...
[debug] Done updating app
[debug] not up to date. inChanged = true, force = false
[debug] Updating ...
[debug] [zinc] IncrementalCompile -----------
[debug] IncrementalCompile.incrementalCompile
[debug] previous = Stamps for: 0 products, 0 sources, 0 libraries
[debug] current source = Set(${BASE}/app/src/main/scala/App.scala, ${BASE}/app/src/main/scala/models/TestModel1.scala)
[debug] > initialChanges = InitialChanges(Changes(added = Set(${BASE}/app/src/main/scala/models/TestModel1.scala, ${BASE}/app/src/main/scala/App.scala), removed = Set(), changed = Set(), unmodified = ...),Set(),Set(),API Changes: Set())
[debug] Full compilation, no sources in previous analysis.
[debug] all 2 sources are invalidated
[debug] Created transactional ClassFileManager with tempDir = /home/lefou/work/tmp/mill-format-prj/app/target/scala-2.13/classes.bak
[debug] Initial set of included nodes: 
[debug] Recompiling all sources: number of invalidated sources > 50.0% of all sources
[debug] About to delete class files:
[debug] We backup class files:
[debug] compilation cycle 1
[info] compiling 2 Scala sources to /home/lefou/work/tmp/mill-format-prj/app/target/scala-2.13/classes ...
[debug] Getting org.scala-sbt:compiler-bridge_2.13:1.6.0:compile for Scala 2.13.8
[debug] Done updating 
[debug] Copy resource mappings: 
[debug]         
[debug] [zinc] Running cached compiler 56a43a7d for Scala compiler version 2.13.8
[debug] [zinc] The Scala compiler is invoked with:
[debug]         -bootclasspath
[debug]         /home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/org/scala-lang/scala-library/2.13.8/scala-library-2.13.8.jar
[debug]         -classpath
[debug]         /home/lefou/work/tmp/mill-format-prj/app/target/scala-2.13/classes:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/io/getquill/quill-sql_2.13/3.18.0/quill-sql_2.13-3.18.0.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/io/getquill/quill-engine_2.13/3.18.0/quill-engine_2.13-3.18.0.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/io/getquill/quill-core_2.13/3.18.0/quill-core_2.13-3.18.0.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/lihaoyi/pprint_2.13/0.6.6/pprint_2.13-0.6.6.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/org/scala-lang/modules/scala-collection-compat_2.13/2.7.0/scala-collection-compat_2.13-2.7.0.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/typesafe/config/1.4.2/config-1.4.2.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/typesafe/scala-logging/scala-logging_2.13/3.9.4/scala-logging_2.13-3.9.4.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/github/takayahilton/sql-formatter_2.13/1.2.1/sql-formatter_2.13-1.2.1.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/io/suzaku/boopickle_2.13/1.4.0/boopickle_2.13-1.4.0.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/zio-logging_2.13/0.5.14/zio-logging_2.13-0.5.14.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/lihaoyi/fansi_2.13/0.2.14/fansi_2.13-0.2.14.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/com/lihaoyi/sourcecode_2.13/0.2.7/sourcecode_2.13-0.2.7.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/org/scala-lang/scala-reflect/2.13.8/scala-reflect-2.13.8.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/org/slf4j/slf4j-api/1.7.30/slf4j-api-1.7.30.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/zio_2.13/1.0.12/zio_2.13-1.0.12.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/zio-streams_2.13/1.0.12/zio-streams_2.13-1.0.12.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/zio-stacktracer_2.13/1.0.12/zio-stacktracer_2.13-1.0.12.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/izumi-reflect_2.13/1.1.3/izumi-reflect_2.13-1.1.3.jar:/home/lefou/.cache/coursier/v1/https/repo1.maven.org/maven2/dev/zio/izumi-reflect-thirdparty-boopickle-shaded_2.13/1.1.3/izumi-reflect-thirdparty-boopickle-shaded_2.13-1.1.3.jar
[info] /home/lefou/work/tmp/mill-format-prj/app/src/main/scala/App.scala:19:12: SELECT c.name, c.age FROM person c WHERE c.name like ('% $1' || ?) || '%'
[info]     ctx.run(q)
[info]            ^
[debug] Scala compilation took 7.363770838 s
[debug] done compiling
[debug] Registering generated classes:
[debug]         App$Person.class
[debug]         App$$anon$1$$anon$2.class
[debug]         Foo$.class
[debug]         App$$anon$3.class
[debug]         App$.class
[debug]         App$$anon$3$$anon$4.class
[debug]         App$$anon$1.class
[debug]         App$Person$.class
[debug]         Foo.class
[debug]         App.class
[debug] Removing the temporary directory used for backing up class files: /home/lefou/work/tmp/mill-format-prj/app/target/scala-2.13/classes.bak
[debug] [zinc] IncrementalCompile -----------
[debug] IncrementalCompile.incrementalCompile
[debug] previous = Stamps for: 0 products, 0 sources, 0 libraries
[debug] current source = Set()
[debug] > initialChanges = InitialChanges(Changes(added = Set(), removed = Set(), changed = Set(), unmodified = ...),Set(),Set(),API Changes: Set())
[debug] Full compilation, no sources in previous analysis.
[debug] Created transactional ClassFileManager with tempDir = /home/lefou/work/tmp/mill-format-prj/target/scala-2.13/classes.bak
[debug] Removing the temporary directory used for backing up class files: /home/lefou/work/tmp/mill-format-prj/target/scala-2.13/classes.bak
[success] Total time: 8 s, completed 23.06.2022, 08:32:58
sbt:root> ^D
08:36:02 θ74° lefou:~/work/tmp/mill-format-prj main(+3/-0)* 3m38s ± cat build.sbt 
(ThisBuild / scalaVersion) := "2.13.8"
(ThisBuild / version) := "0.0.1-SNAPSHOT"

lazy val app = project.in(file("app")).settings(
  libraryDependencies ++= Seq(
    "io.getquill" %% "quill-sql" % "3.18.0"
  )
)

lazy val root = project.in(file(".")).aggregate(app).dependsOn(app)

[lefou]

Closing, as we don't have an idea where this is coming from, and it is doing no harm (besides the annoying message). Please comment, if you have any ideas, pointers or issues, then I can reopen and investigate further.

[lefou]

• probably related: Log4j formatting error sbt/zinc#1122