Explore ERROR log lines from Apache Commons JCS

[lread]

Recently

We enabled console logging (it was previously entirely suppressed) and then we suppressed the noisy INFO level errors for Apache Commons JCS by setting its min log level to warn.

But

On after clj-watson completes a dependency-check scan I see the following error log lines from JCS on termination:

2024-08-03 10:34:43,183 ERROR IndexedDiskCache - Region [NODEAUDIT] : Not alive and dispose was called, filename: NODEAUDIT
2024-08-03 10:34:43,185 ERROR IndexedDiskCache - Region [CENTRAL] : Not alive and dispose was called, filename: CENTRAL
2024-08-03 10:34:43,185 ERROR IndexedDiskCache - Region [POM] : Not alive and dispose was called, filename: POM

So...

I'll explore. Maybe dependency-check is doing something JCS finds objectionable, or maybe clj-watson is.

[seancorfield]

Or set its level to FATAL 😄

[lread]

Ok, I looked at the clj-watson code. It is not closing the dependency-check Engine, and it probably should be. If I close the Engine, the error appears sooner.

But I also googled and the opinion over at dependency-check is that this error should be debug level. jeremylong/DependencyCheck#6073

Looking at the JCS code, I agree, it doesn't seem worthy to wail so loudly about this.

So, I'll:

• ensure clj-watson closes the dependency check engine
• suppress this particular error noise

[seancorfield]

Sounds good. Thanks for doing all that digging!

[lread]

Options for log message suppression:

1. [rejected] Suppress all ERROR level from IndexedDiskCache

   • con: there are other meaningful errors that IndexDiskCache emits

2. Suppress specific messages via logback janino evaluator

   • con: requires optional janino dep be brought in.

3. Suppress via custom logback filter written in Java

   • con: requires precompile of Java

4. Suppress via custom logback filter written in Clojure

   1. expressed in logback config
      • con: requires precompile for logback to see it
   2. expressed config programmatically
      • con: programmatically ties clj-watson to logback

Thoughts and Proposal

If we already had a precompile requirement, options 3 and 4.1 would not seem terrible, but we don't, so I'd rather not suggest introducing such a requirement.

A security tool should avoid bringing in deps if it can, so I'm not crazy about option 2.
But maybe I should not be overly concerned here, thoughts?

Re option 4.2: Since clj-watson is a tool and not a lib, I don't see a big issue with the coupling to logback for logging.

If you agree with my analysis above, we have a choice between options 2 and 4.2.
Because it is simpler, I'll explore option 2 first.

[lread]

I should address closing the Engine as a separate issue. I'll create one.

[seancorfield]

Option 5: Leave it as-is, just like DependencyCheck does, and document that this is a spurious/harmless error.

I think 4.2 (or 5) are both fine. I think 2 is overkill just to get rid of a spurious error in the logs. Either way, I consider this low priority so I'd lean to option 5 for now.

[lread]

Seeing three ERROR lines output every time I run clj-watson is pretty bad. I'll try to make my case:

• Users having to wonder what these ERRORs mean is a burden on the users (just look at the amount of work I did to understand them)
• Having to tell users to ignore ERRORs is a burden on clj-watson support and does not inspire trust
• Telling users to just ignore these ERRORs sets the tone of ERRORs emitted by clj-watson can be ignored, which is not great for a security-related tool.
• Because DependencyCheck is also a lib and not just a tool, it doesn't have the luxury of suppressing these errors, but clj-watson is a tool, and therefore, it does.

Whatcha think? Are you ok with me trying out 4.2?

[seancorfield]

Yup, I said 4.2 was okay by me. Create a chore issue as a placeholder for that error message having its severity lowered at some point, and then we could take out the programmatic suppression.

[lread]

Cool, you were leaning toward 5 so I felt sharing my rationale had merit.
Did it sway you more toward 4.2?

[lread]

Here's the Apache Commons JCS issue tracker: https://issues.apache.org/jira/projects/JCS/issues/?filter=allissues
I'm gonna guess that they are not open to changing their logging, but maybe nobody ever asked them to. I'm not JIRA-smart and have yet to figure out how to efficiently search their issues.

[seancorfield]

There's at least one issue in there discussing the log level of another component, but I couldn't find anything about this IndexedDiskCache logging.

I just offered up 5 as a do-nothing option. If 4.2 is straightforward, that's fine. The other options, not so keen...

[seancorfield]

I just tried the latest SHA from the main branch and ran into a problem: I had excluded slf4j-nop and added all the log4j2 bridging stuff and this code failed because:

Execution error (IllegalArgumentException) at clj-watson.logging-config/init (logging_config.clj:37).
No matching method addTurboFilter found taking 1 args for class org.apache.logging.slf4j.Log4jLoggerFactory

We might want to either wrap that in a try/catch (fallback: the jcs logging won't be suppressed) and/or add a note to the documentation about expected usage around logging?

Here's what I had initially:

  :watson
  {:replace-deps {io.github.clj-holmes/clj-watson
                  {:git/tag "v5.1.3" :git/sha "5812615"
                   :exclusions [org.slf4j/slf4j-nop]}
                  org.owasp/dependency-check-core {:mvn/version "RELEASE"}
                  ;; use log4j 2.x:
                  org.apache.logging.log4j/log4j-api {:mvn/version "2.23.1"}
                  ;; bridge into log4j:
                  org.apache.logging.log4j/log4j-1.2-api {:mvn/version "2.23.1"}
                  org.apache.logging.log4j/log4j-jcl {:mvn/version "2.23.1"}
                  org.apache.logging.log4j/log4j-jul {:mvn/version "2.23.1"}
                  org.apache.logging.log4j/log4j-slf4j-impl {:mvn/version "2.23.1"}
                  org.apache.logging.log4j/log4j-slf4j2-impl {:mvn/version "2.23.1"}}

and here's what I have now:

  :watson
  {:replace-deps {io.github.clj-holmes/clj-watson
                  {;; :git/tag "v5.1.3" :git/sha "5812615"
                   ;; unreleased next version:
                   :git/sha "20b42599320fc30491a7b9a6ef1dc69b75a19799"}
                  org.owasp/dependency-check-core {:mvn/version "RELEASE"}}

[lread]

Ah OK, interesting @seancorfield, you were excluding slf4j-nop and adding your own deps so that you could see the missing suppressed logs? The con I listed for option 4.2 was:

con: programmatically ties clj-watson to logback

But also slf4j...
I'll add a note to the README about the current logging behaviour.

[seancorfield]

Thanks. Yeah, I don't suppose many users had gone down my path :)

[lread]

It's the path I would have taken too, @seancorfield. It was way too quiet!

[lread]

Actually @seancorfield your logging failure drove home that we did favour complecting over bringing the new dep on Janino.
Option 2 is always available should you change your mind in the future.