Log4j formatting error

[tballard]

 s"Recompiling all sources: number of invalidated sources > ${recompileAllFraction * 100.00}% of all sources"

That line is from IncrementalCommon.scala. The "%" should be "%%" to prevent it from breaking. Or something.

Have a stacktrace:

2022-09-14 13:00:48,046 MillServerActionRunner ERROR Unable to format msg: Recompiling all sources: number of invalidated sources > 50.0% of all sources java.util.IllegalFormatConversionException: o != [Ljava.lang.Object;
	at java.base/java.util.Formatter$FormatSpecifier.failConversion(Formatter.java:4442)
	at java.base/java.util.Formatter$FormatSpecifier.printInteger(Formatter.java:2963)
	at java.base/java.util.Formatter$FormatSpecifier.print(Formatter.java:2918)
	at java.base/java.util.Formatter.format(Formatter.java:2689)
	at java.base/java.util.Formatter.format(Formatter.java:2625)
	at java.base/java.lang.String.format(String.java:4184)
	at org.apache.logging.log4j.message.StringFormattedMessage.formatMessage(StringFormattedMessage.java:120)
	at org.apache.logging.log4j.message.StringFormattedMessage.getFormattedMessage(StringFormattedMessage.java:88)
	at sbt.internal.util.Appender.$anonfun$appendMessage$1(ConsoleAppender.scala:508)
	at sbt.internal.util.Appender.appendLog(ConsoleAppender.scala:426)
	at sbt.internal.util.Appender.appendLog$(ConsoleAppender.scala:425)
	at sbt.internal.util.ConsoleAppender.appendLog(ConsoleAppender.scala:336)
	at sbt.internal.util.Appender.appendMessage(ConsoleAppender.scala:508)
	at sbt.internal.util.Appender.appendMessage$(ConsoleAppender.scala:504)
	at sbt.internal.util.ConsoleAppender.appendMessage(ConsoleAppender.scala:336)
	at sbt.internal.util.ConsoleAppender.$anonfun$toLog4J$1(ConsoleAppender.scala:350)
	at sbt.internal.util.ConsoleAppender.$anonfun$toLog4J$1$adapted(ConsoleAppender.scala:347)
	at sbt.internal.util.Log4JConsoleAppender.append(ConsoleAppender.scala:571)
	at sbt.internal.util.ConsoleAppenderFromLog4J.appendLog(ConsoleAppender.scala:584)
	at sbt.util.LoggerContext$LoggerContextImpl$Log.$anonfun$log$2(LoggerContext.scala:123)
	at sbt.util.LoggerContext$LoggerContextImpl$Log.$anonfun$log$2$adapted(LoggerContext.scala:123)
	at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:563)
	at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:561)
	at scala.collection.AbstractIterable.foreach(Iterable.scala:926)
	at sbt.util.LoggerContext$LoggerContextImpl$Log.log(LoggerContext.scala:123)
	at sbt.internal.util.ManagedLogger.log(ManagedLogger.scala:41)
	at sbt.util.Logger.debug(Logger.scala:25)
	at sbt.internal.inc.IncrementalCommon.expand$1(IncrementalCommon.scala:285)
	at sbt.internal.inc.IncrementalCommon.mapInvalidationsToSources(IncrementalCommon.scala:291)
	at sbt.internal.inc.IncrementalCommon$CycleState.next(IncrementalCommon.scala:88)
	at sbt.internal.inc.IncrementalCommon$$anon$1.next(IncrementalCommon.scala:56)
	at sbt.internal.inc.IncrementalCommon$$anon$1.next(IncrementalCommon.scala:52)
	at sbt.internal.inc.IncrementalCommon.cycle(IncrementalCommon.scala:263)
	at sbt.internal.inc.Incremental$.$anonfun$incrementalCompile$8(Incremental.scala:418)
	at sbt.internal.inc.Incremental$.withClassfileManager(Incremental.scala:506)
	at sbt.internal.inc.Incremental$.incrementalCompile(Incremental.scala:405)
	at sbt.internal.inc.Incremental$.apply(Incremental.scala:171)
	at sbt.internal.inc.IncrementalCompilerImpl.compileInternal(IncrementalCompilerImpl.scala:534)
	at sbt.internal.inc.IncrementalCompilerImpl.$anonfun$compileIncrementally$1(IncrementalCompilerImpl.scala:488)
	at sbt.internal.inc.IncrementalCompilerImpl.handleCompilationError(IncrementalCompilerImpl.scala:332)
	at sbt.internal.inc.IncrementalCompilerImpl.compileIncrementally(IncrementalCompilerImpl.scala:425)
	at sbt.internal.inc.IncrementalCompilerImpl.compile(IncrementalCompilerImpl.scala:137)
	at mill.scalalib.worker.ZincWorkerImpl.compileInternal(ZincWorkerImpl.scala:569)
	at mill.scalalib.worker.ZincWorkerImpl.$anonfun$compileMixed0$1(ZincWorkerImpl.scala:340)
	at mill.api.FixSizedCache.withCachedValue(FixSizedCache.scala:66)
	at mill.scalalib.worker.ZincWorkerImpl.withCompilers(ZincWorkerImpl.scala:422)
	at mill.scalalib.worker.ZincWorkerImpl.compileMixed0(ZincWorkerImpl.scala:339)
	at mill.scalalib.worker.ZincWorkerImpl.compileMixed(ZincWorkerImpl.scala:307)
	at mill.scalalib.ScalaModule.$anonfun$compile$2(ScalaModule.scala:198)
	at mill.define.Task$TraverseCtx.evaluate(Task.scala:380)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$13(Evaluator.scala:627)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withErr(Console.scala:193)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$12(Evaluator.scala:627)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withOut(Console.scala:164)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$11(Evaluator.scala:626)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withIn(Console.scala:227)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$8(Evaluator.scala:625)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$8$adapted(Evaluator.scala:586)
	at scala.collection.immutable.Vector.foreach(Vector.scala:1856)
	at mill.eval.Evaluator.evaluateGroup(Evaluator.scala:586)
	at mill.eval.Evaluator.$anonfun$evaluateGroupCached$21(Evaluator.scala:478)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at mill.eval.Evaluator.evaluateGroupCached(Evaluator.scala:469)
	at mill.eval.Evaluator.$anonfun$sequentialEvaluate$2(Evaluator.scala:202)
	at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:563)
	at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:561)
	at scala.collection.AbstractIterator.foreach(Iterator.scala:1293)
	at mill.eval.Evaluator.sequentialEvaluate(Evaluator.scala:177)
	at mill.eval.Evaluator.evaluate(Evaluator.scala:162)
	at mill.main.RunScript$.evaluateNamed(RunScript.scala:363)
	at mill.main.RunScript$.$anonfun$evaluateTasksNamed$1(RunScript.scala:333)
	at scala.util.Either.map(Either.scala:382)
	at mill.main.RunScript$.evaluateTasksNamed(RunScript.scala:331)
	at mill.main.MainModule$.evaluateTasksNamed(MainModule.scala:71)
	at mill.main.MainModule.$anonfun$show$1(MainModule.scala:276)
	at mill.define.Task$TraverseCtx.evaluate(Task.scala:380)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$13(Evaluator.scala:627)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withErr(Console.scala:193)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$12(Evaluator.scala:627)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withOut(Console.scala:164)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$11(Evaluator.scala:626)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at scala.Console$.withIn(Console.scala:227)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$8(Evaluator.scala:625)
	at mill.eval.Evaluator.$anonfun$evaluateGroup$8$adapted(Evaluator.scala:586)
	at scala.collection.immutable.Vector.foreach(Vector.scala:1856)
	at mill.eval.Evaluator.evaluateGroup(Evaluator.scala:586)
	at mill.eval.Evaluator.$anonfun$evaluateGroupCached$21(Evaluator.scala:478)
	at scala.util.DynamicVariable.withValue(DynamicVariable.scala:59)
	at mill.eval.Evaluator.evaluateGroupCached(Evaluator.scala:469)
	at mill.eval.Evaluator.$anonfun$sequentialEvaluate$2(Evaluator.scala:202)
	at scala.collection.IterableOnceOps.foreach(IterableOnce.scala:563)
	at scala.collection.IterableOnceOps.foreach$(IterableOnce.scala:561)
	at scala.collection.AbstractIterator.foreach(Iterator.scala:1293)
	at mill.eval.Evaluator.sequentialEvaluate(Evaluator.scala:177)
	at mill.eval.Evaluator.evaluate(Evaluator.scala:162)
	at mill.main.RunScript$.evaluateNamed(RunScript.scala:363)
	at mill.main.RunScript$.evaluate(RunScript.scala:349)
	at mill.main.RunScript$.$anonfun$evaluateTasks$1(RunScript.scala:314)
	at scala.util.Either.map(Either.scala:382)
	at mill.main.RunScript$.evaluateTasks(RunScript.scala:312)
	at mill.main.RunScript$.$anonfun$runScript$8(RunScript.scala:105)
	at ammonite.util.Res$Success.flatMap(Res.scala:62)
	at mill.main.RunScript$.runScript(RunScript.scala:104)
	at mill.main.MainRunner.$anonfun$runScript$1(MainRunner.scala:119)
	at mill.main.MainRunner.watchLoop2(MainRunner.scala:67)
	at mill.main.MainRunner.runScript(MainRunner.scala:92)
	at mill.MillMain$.main0(MillMain.scala:310)
	at mill.main.MillServerMain$.main0(MillServerMain.scala:79)
	at mill.main.Server.$anonfun$handleRun$1(MillServerMain.scala:184)
	at java.base/java.lang.Thread.run(Thread.java:833)

[szeiger]

Should this be fixed in https://github.com/sbt/sbt/blob/78f9b318e2d13e9bdffb8661c2dc4bd451db521e/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala#L600 instead? sbt's loggers do not support formatting and ConsoleAppender always appends an empty argument list so it would make sense to make this explicit by passing the string as an argument to prevent further expansion.

[lefou]

Should this be fixed in https://github.com/sbt/sbt/blob/78f9b318e2d13e9bdffb8661c2dc4bd451db521e/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala#L600 instead? sbt's loggers do not support formatting and ConsoleAppender always appends an empty argument list so it would make sense to make this explicit by passing the string as an argument to prevent further expansion.

The idea and location looks right to me. But it would be even better to find a Message constructor which avoids any kind of formatting or template processing, maybe new SimpleMessage(String) or MessageFactory.newMessage(String)