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’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Multiple logs per \n - HUGE issue when printing Exceptions! #4

Closed
feinstein opened this Issue Jan 19, 2018 · 15 comments

Comments

Projects
None yet
4 participants
@feinstein
Copy link

feinstein commented Jan 19, 2018

The same error reported here is happening on this library as well. The aws-lambda-java-log4j2 team fixed it, so you can copy their code I guess.

The problem is, since you are simply printing the log to the console, strings with \n will be printed as new lines in CloudWatch, this becomes REALLY troublesome when we try to log Exceptions, since it will be print as 1 log entry per line of stack trace, which makes our logs in CloudWatch a complete mess.

This is my test code:

Exception exception = new IllegalArgumentException(new NullPointerException("test exception"));
LOGGER.info("test 1\n test 2 \n test 3");
LOGGER.info("test 4");
LOGGER.error("new error test", exception);

And this is the result:

image

@feinstein

This comment has been minimized.

Copy link

feinstein commented Jan 19, 2018

I believe the solution is in here:

logger.log(super.getLayout().toByteArray(event));
@feinstein

This comment has been minimized.

Copy link

feinstein commented Jan 24, 2018

@johnchapin have you seen this?
It's the only thing preventing me from adopting your library and is such an easy fix.

@johnchapin

This comment has been minimized.

Copy link
Member

johnchapin commented Jan 24, 2018

Hi @feinstein - nice catch. I'll take a look when I have a chance, and of course I'd welcome a PR if you're inclined to fix it yourself.

@feinstein

This comment has been minimized.

Copy link

feinstein commented Jan 26, 2018

@johnchapin I tried to take a look on your code, but I am nor very much experienced on logging frameworks to know where to properly make the change that fixes this. Unfortunately I will have to stick with aws-lambda-java-log4j2 for now.

@johnchapin

This comment has been minimized.

Copy link
Member

johnchapin commented Jan 26, 2018

So, a little playing around with the configuration netted a positive result:

If you follow the instructions for using your own logback.xml file, here: https://github.com/symphoniacloud/lambda-monitoring/tree/master/lambda-logging#how-can-i-change-what-the-output-looks-like

And use a pattern that looks like this "[%d{yyyy-MM-dd HH:mm:ss.SSS}] %X{AWSRequestId:-" + NO_REQUEST_ID + "} %.-6level %logger{5} - %msg \r%replace(%ex){'\n','\r'}%nopex", you should end up with better exception output in the CloudWatch console.

screen shot 2018-01-26 at 12 13 48 am

H/t to this blog post: https://medium.com/@martatatiana/aws-lambda-in-java-8-log4j2-and-scattered-stacktrace-in-cloudwatch-a4aea2e7bf2a

I'll update the default config and release a new version of lambda-logging shortly.

@johnchapin

This comment has been minimized.

Copy link
Member

johnchapin commented Jan 26, 2018

This is fixed by version 1.0.1.

@johnchapin johnchapin closed this Jan 26, 2018

@feinstein

This comment has been minimized.

Copy link

feinstein commented Jan 26, 2018

Am I wrong or will this only correct the exceptions, but not the messages?

Can't you use the same solution that AWS used? It's pretty transparent to the user and we don't have to carry this hack to our configuration file.

@feinstein

This comment has been minimized.

Copy link

feinstein commented Feb 1, 2018

@johnchapin I can confirm your fix only works with exceptions. Logs suchs as:

LOGGER.info("test 1\n test 2 \n test 3");

will produce many lines of logs in CloudWatch:
image

(the lines are not sequential because the END log of the Lambda Function was emitted at the same time).

@johnchapin

This comment has been minimized.

Copy link
Member

johnchapin commented Feb 1, 2018

So the reason I didn't do that is because it'll break the metric filters functionality in lambda-metrics. I think we can come up with another solution (maybe a custom PatternLayout).

The solution that AWS used unfortunately isn't available to us without a lot more work.

@feinstein

This comment has been minimized.

Copy link

feinstein commented Feb 1, 2018

@johnchapin, I understand, but are there any reasons not to use Log4j2 then and use the same solution as AWS?

On your Medium article you point out that you chose Logback because of another article about loggers performance, but if I remember correctly, they both performed almost identical. Is Logback essential to the Metrics library and Log4j2 won't do?

@johnchapin

This comment has been minimized.

Copy link
Member

johnchapin commented Feb 1, 2018

The article mentions performance as a possible benefit, but not a main driver. It's also worth noting that the article and these libraries were written long before Log4J2 was an AWS-provided option.

I'm not switching anything over to Log4J2 because both lambda-logging and lambda-metrics are written to logback.

The issue you're interested in can be solved by configuration (you can use your own logback.xml with whatever newline replacement strategy you like), and I'll take a look at a more comprehensive solution that doesn't break lambda-metrics. And if none of that works for you, use Log4J2, or whatever else you find useful.

@feinstein

This comment has been minimized.

Copy link

feinstein commented Feb 1, 2018

@johnchapin, thanks for taking the time to look at this.

@feinstein

This comment has been minimized.

Copy link

feinstein commented Aug 26, 2018

I was looking again to logging and metrics on AWS and wanted to know If this is not throughly fixed, I believe it should remain an open issue if it isn't.

@Noisyfox

This comment has been minimized.

Copy link

Noisyfox commented Dec 3, 2018

BTW if someone is looking for configuring the line breaker in logback.xml, remember to use 
 since \r doesn't work in replacement part according to https://jira.qos.ch/browse/LOGBACK-1261
e.g.:

<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] %X{AWSRequestId:-" + NO_REQUEST_ID + "} %.-6level %logger{5} - %msg &#xd;%replace(%ex){'\n','&#xd;'}%nopex</pattern>

\r works in Java code because Java compiler escapes this for you but it doesn't work in xml.
You could use \n as the first arg here because replace treats its first arg as a regex and not for the second arg so it won't do the escaping for you. See code here and here. The javadoc of java.util.regex.Matcher#replaceAll says:

backslashes are used to escape literal characters in the replacement string.

which means a \r in replacement string will become r in the result instead of a line breaker as expected. The source code of appendReplacement explains this more clearly:

char nextChar = replacement.charAt(cursor);
if (nextChar == '\\') {
  cursor++;
  if (cursor == replacement.length())
    throw new IllegalArgumentException(
      "character to be escaped is missing");
  nextChar = replacement.charAt(cursor);
  result.append(nextChar);
  cursor++;
}
@FritzOscarBerngruber1701

This comment has been minimized.

Copy link

FritzOscarBerngruber1701 commented Dec 28, 2018

Found a way to also deal with the new line problem in the log messages, thanks to this conversation. Solved it using a corresponding pattern. Described it at stackoverflow for others to find.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment