fb-contrib icon indicating copy to clipboard operation
fb-contrib copied to clipboard

Detect improper args for SLF4J Logger::error

Open efenderbosch opened this issue 7 years ago • 10 comments

There are two method signatures for SLF4J Logger::error

1st is what you'd expect given the rest of the API: public void error(String format, Object... arguments);

2nd is different: public void error(String msg, Throwable t);

We've found multiple instances in our code where we are calling the 2nd method when we are expecting to call the 1st. What happens is that the log just looks like "some message {}" without any substitution and the context of the Throwable is completely lost.

Can fb-contrib trigger if Logger::error is called and the String contains "{}" and the last parameter is a Throwable?

efenderbosch avatar Dec 20 '17 16:12 efenderbosch

so you are doing LOGGER.error("Lookie an error->{}", e); and it is mapping to the second method.

yeah, makes sense, i can do that. altho it's kind of odd that you want to pass an exception to a {} marker. But ok, yeah problem.

mebigfatguy avatar Dec 21 '17 03:12 mebigfatguy

ah, i get it, it's not that you wanted to pass the exception to the marker, it's that you forgot to add the parm, and so the method resolution was to the wrong method. got it.

mebigfatguy avatar Dec 21 '17 04:12 mebigfatguy

thanks for the report. See how that works for you. Feel free to reopen if need be.

mebigfatguy avatar Dec 21 '17 04:12 mebigfatguy

Hmmm... was there a regression on this? I'm seeing it in our code.

LOG.error("Exception saving webhook: '{}'", webhook, e);

That's resolving to this method: public void error(String format, Object arg1, Object arg2);

When really we want to call public void error(String msg, Throwable t);

efenderbosch avatar Mar 20 '19 21:03 efenderbosch

When really we want to call public void error(String msg, Throwable t);

But you've provided three arguments.

ThrawnCA avatar Mar 20 '19 23:03 ThrawnCA

Right, which is why I want fb-contrib to flag this.

efenderbosch avatar Mar 21 '19 14:03 efenderbosch

I'm not sure what you want me to do here. You're saying if the last parameter is an exception, you want to make sure that the call is to a method who's signature ends with Throwable? I'm sure i'm missing something. How would a three parm call, invoke a two parm signature?

mebigfatguy avatar Mar 22 '19 23:03 mebigfatguy

If the last parameter of a call to any of the error methods is a Throwable make sure the method signature is String msg, Throwable t

We have developers treating error logs like all other log levels in that they try to pass arguments to a format string with {} and then the last parameter is a Throwable. It is a somewhat reasonable expectation given how the rest of the SLF4J API is written (debug/info/warn), but the log message that's generated isn't what's expected.

this is correct: LOG.info("my message with para1 {} and para2 {}", para1, para2);

this is incorrect: LOG.error("an exception happened with para1 {} and para2 {}", para1, para2, someThrowable);

this is correct:

String message = "an exception happened with para1 " + para1 + " and para2 " + para2;
LOG.error(message, someThrowable);

efenderbosch avatar Mar 24 '19 14:03 efenderbosch

"the log message that's generated isn't what's expected."

Can you provide the expected vs actual log messages? I'm still confused about exactly what the problem is.

What is incorrect about your second example? As I understand it, SLF4J will understand all of the parameters.

ThrawnCA avatar Mar 25 '19 22:03 ThrawnCA

Hi all, I hope you don't mind me jumping in here. I think I understand the misunderstanding here..

LOG.error("an exception happened with para1 {} and para2 {}", para1, para2, someThrowable);

What is incorrect about your second example? As I understand it, SLF4J will understand all of the parameters.

The problem here is that there are two {} and three varargs parameters. So someThrowable will be silently ignored by the logger.

LOGGER.error("my message", throwable); // good
LOGGER.error("my message {}", para1); // good
LOGGER.error("my message {}", throwable); // bad - stacktrace is ignored
LOGGER.error("my message {}", para1, para2); // bad - para2 is ignored
LOGGER.error("my message {}", para1, throwable); // bad - throwable is ignored
LOGGER.error("my message {} {}", para1); // bad - should have two vararg parameters
LOGGER.error("my message {} {}", para1, para2); // good
LOGGER.error("my message {} {}", para1, throwable); // bad - stacktrace is ignored

So the error conditions would be:

  1. String contains {} and the number of remaining parameters doesn't match the number of {} in the string
  2. String contains {} and any remaining parameter is assignable to Throwable

mattj256 avatar Mar 01 '20 07:03 mattj256