Skip to content

Commit a92909f

Browse files
ChristophEichhornChristophEichhorn
committed
Use longer representation of stack traces in log messages
Previously, stack traces got truncated to the first 42 lines. Now stacktraces up to a size of 55k are entirely displayed in Kibana. If the size of a stacktrace exceeds 55k, the stacktrace will be abbreviated in such a way that its first lines and its last lines (which are considered the most important ones) are still logged. Some lines in between are omitted in order to keep the overall size of the stacktrace under 55k. The reason for this is that larger log messages will not be processed successfully by the logging service. Change-Id: Idce5716bf4591bf235b852b5aa95ce854d68b66a
1 parent 0e7086d commit a92909f

File tree

26 files changed

+767
-149
lines changed

26 files changed

+767
-149
lines changed

‎LoggingStacktraces.md

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,12 @@
1+
# Logging Stack Traces
2+
3+
This library provides the possibility to log stack traces within one log
4+
message. This facilitates debugging significantly, because the complete stack
5+
trace can be read in the correct order and does not need to be retrieved from
6+
numerous single and unordered log messages. This library does also consider
7+
limitations imposed by the logging pipeline. These limitations would prevent
8+
very large stack traces from being written to Elasticsearch. If a stack trace
9+
exceeds a total size of 55kB, it will therefore not be logged entirely. Since
10+
the interesting lines of a stack trace are usually situated in its first and in
11+
its last part, we will remove as few lines as necessary from its middle part
12+
whereby the last remaining part will have twice the size of the first part.

‎cf-java-logging-support-core/pom.xml

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,13 +21,37 @@
2121
<version>${logback.version}</version>
2222
<scope>test</scope>
2323
</dependency>
24+
25+
<dependency>
26+
<groupId>org.apache.commons</groupId>
27+
<artifactId>commons-lang3</artifactId>
28+
<version>3.6</version>
29+
</dependency>
2430
</dependencies>
31+
2532
<parent>
2633
<groupId>com.sap.hcp.cf.logging</groupId>
2734
<artifactId>cf-java-logging-support-parent</artifactId>
2835
<version>2.1.0-SNAPSHOT</version>
2936
<relativePath>../pom.xml</relativePath>
3037
</parent>
38+
<build>
39+
<plugins>
40+
<plugin>
41+
<groupId>org.apache.maven.plugins</groupId>
42+
<artifactId>maven-jar-plugin</artifactId>
43+
<version>3.0.2</version>
44+
<executions>
45+
<execution>
46+
<goals>
47+
<goal>test-jar</goal>
48+
</goals>
49+
</execution>
50+
</executions>
51+
</plugin>
52+
</plugins>
53+
</build>
54+
3155
<profiles>
3256
<profile>
3357
<id>generate</id>
@@ -120,4 +144,5 @@
120144
</build>
121145
</profile>
122146
</profiles>
147+
123148
</project>

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/converter/DefaultStacktraceConverter.java

Lines changed: 36 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -1,54 +1,56 @@
11
package com.sap.hcp.cf.logging.common.converter;
22

33
import java.io.PrintWriter;
4-
import java.io.StringWriter;
4+
import java.util.List;
55

66
import org.slf4j.LoggerFactory;
77

88
import com.fasterxml.jackson.jr.ob.JSON;
99
import com.fasterxml.jackson.jr.ob.JSONComposer;
1010
import com.fasterxml.jackson.jr.ob.comp.ArrayComposer;
1111

12-
public class DefaultStacktraceConverter {
13-
14-
private static final int MAX_DEPTH = 42;
15-
private static String TAB_PATTERN = "\n";
16-
private static String TAB_SPACES = " ";
17-
private static String LS_PROPERTY = "line.separator";
18-
private static String NEWLINE = "\n";
19-
20-
private String lineSeparator;
21-
private final int depth = MAX_DEPTH;
12+
public class DefaultStacktraceConverter extends StacktraceConverter {
13+
public static final int MAX_SIZE = 55 * 1024;
14+
private int maxSize;
2215

2316
public DefaultStacktraceConverter() {
24-
try {
25-
lineSeparator = System.getProperty(LS_PROPERTY, NEWLINE);
26-
} catch (Exception ex) {
27-
lineSeparator = NEWLINE;
28-
}
17+
this(MAX_SIZE);
18+
}
19+
20+
DefaultStacktraceConverter(int maxSize) {
21+
this.maxSize = maxSize;
2922
}
3023

24+
@Override
3125
public void convert(Throwable t, StringBuilder appendTo) {
32-
if (t != null) {
33-
ArrayComposer<JSONComposer<String>> ac;
34-
try {
35-
StringWriter sw = new StringWriter();
36-
t.printStackTrace(new PrintWriter(sw));
37-
String[] lines = sw.toString().split(lineSeparator);
38-
int maxLines = getMaxLines(lines.length);
39-
ac = JSON.std.composeString().startArray();
40-
for (int i = 0; i < maxLines; i++) {
41-
ac.add(lines[i].trim().replace(TAB_PATTERN, TAB_SPACES));
26+
if (t == null) {
27+
return;
28+
}
29+
try {
30+
LineWriter lw = new LineWriter();
31+
t.printStackTrace(new PrintWriter(lw));
32+
List<String> lines = lw.getLines();
33+
StacktraceLines stacktraceLines = new StacktraceLines(lines);
34+
35+
ArrayComposer<JSONComposer<String>> ac = JSON.std.composeString().startArray();
36+
if (stacktraceLines.getTotalLineLength() <= maxSize) {
37+
for (String line: stacktraceLines.getLines()) {
38+
ac.add(line);
39+
}
40+
} else {
41+
ac.add("-------- STACK TRACE TRUNCATED --------");
42+
for (String line: stacktraceLines.getFirstLines(maxSize / 3)) {
43+
ac.add(line);
44+
}
45+
ac.add("-------- OMITTED --------");
46+
for (String line: stacktraceLines.getLastLines((maxSize / 3) * 2)) {
47+
ac.add(line);
4248
}
43-
appendTo.append(ac.end().finish());
44-
} catch (Exception ex) {
45-
/* -- avoids substitute logger warnings on startup -- */
46-
LoggerFactory.getLogger(DefaultStacktraceConverter.class).error("Conversion failed ", ex);
4749
}
50+
appendTo.append(ac.end().finish());
51+
} catch (Exception ex) {
52+
/* -- avoids substitute logger warnings on startup -- */
53+
LoggerFactory.getLogger(DefaultStacktraceConverter.class).error("Conversion failed ", ex);
4854
}
4955
}
50-
51-
private int getMaxLines(int length) {
52-
return length >= depth ? depth : length;
53-
}
5456
}

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/converter/LineWriter.java

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,53 @@
1+
package com.sap.hcp.cf.logging.common.converter;
2+
3+
import java.io.IOException;
4+
import java.io.StringWriter;
5+
import java.io.Writer;
6+
import java.util.LinkedList;
7+
import java.util.List;
8+
9+
import org.apache.commons.lang3.StringUtils;
10+
11+
public class LineWriter extends Writer {
12+
13+
StringWriter sw = new StringWriter();
14+
15+
private List<String> lines = new LinkedList<String>();
16+
17+
public List<String> getLines() {
18+
return lines;
19+
}
20+
21+
public LineWriter() {
22+
}
23+
24+
/**
25+
* We have decided for our use-case to ignore offset and length and always
26+
* write the whole String.
27+
*/
28+
@Override
29+
public void write(String str, int off, int len) {
30+
if (StringUtils.isNotBlank(str)) {
31+
lines.add(str);
32+
}
33+
}
34+
35+
/**
36+
* We have decided for our use-case to ignore offset and length and always
37+
* write the whole char array
38+
*/
39+
@Override
40+
public void write(char[] cbuf, int off, int len) throws IOException {
41+
String str = String.valueOf(cbuf);
42+
write(str, off, len);
43+
}
44+
45+
@Override
46+
public void flush() throws IOException {
47+
}
48+
49+
@Override
50+
public void close() throws IOException {
51+
}
52+
53+
}

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/converter/StacktraceConverter.java

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
package com.sap.hcp.cf.logging.common.converter;
2+
3+
public abstract class StacktraceConverter {
4+
public abstract void convert(Throwable t, StringBuilder appendTo);
5+
6+
public final static StacktraceConverter CONVERTER = new DefaultStacktraceConverter();
7+
}

‎cf-java-logging-support-core/src/main/java/com/sap/hcp/cf/logging/common/converter/StacktraceLines.java

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,56 @@
1+
package com.sap.hcp.cf.logging.common.converter;
2+
3+
import java.util.List;
4+
5+
public class StacktraceLines {
6+
7+
private List<String> lines;
8+
9+
public StacktraceLines(List<String> lines) {
10+
this.lines = lines;
11+
}
12+
13+
public List<String> getLines() {
14+
return lines;
15+
}
16+
17+
public int getTotalLineLength() {
18+
int length = 0;
19+
for (String line: lines) {
20+
length += line.length();
21+
}
22+
return length;
23+
}
24+
25+
/**
26+
*
27+
* @param firstSize
28+
* @return the first part of the stacktrace of a given size
29+
*/
30+
public List<String> getFirstLines(int firstSize) {
31+
int size = 0;
32+
int i = 0;
33+
while (size < firstSize && i < lines.size()) {
34+
size += lines.get(i).length();
35+
i++;
36+
}
37+
return lines.subList(0, i - 1);
38+
}
39+
40+
/**
41+
*
42+
* @param lastSize
43+
* @return the last part of the stacktrace of a given size
44+
*/
45+
46+
public List<String> getLastLines(int lastSize) {
47+
int size = 0;
48+
int i = lines.size() - 1;
49+
while (size < lastSize && i >= 0) {
50+
size += lines.get(i).length();
51+
i--;
52+
}
53+
return lines.subList(i + 2, lines.size());
54+
}
55+
56+
}

‎cf-java-logging-support-core/src/test/java/com/sap/hcp/cf/logging/common/converter/DefaultStacktraceConverterTest.java

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,123 @@
1+
package com.sap.hcp.cf.logging.common.converter;
2+
3+
import static org.hamcrest.CoreMatchers.containsString;
4+
import static org.hamcrest.core.Is.is;
5+
import static org.hamcrest.core.IsNot.not;
6+
import static org.junit.Assert.assertThat;
7+
8+
import org.junit.Assert;
9+
import org.junit.Test;
10+
11+
import com.sap.hcp.cf.logging.common.helper.StacktraceGenerator;
12+
13+
public class DefaultStacktraceConverterTest extends AbstractConverterTest {
14+
15+
private String expectedString;
16+
StringBuilder stringBuilder = new StringBuilder();
17+
18+
@Test
19+
public void testNull() {
20+
DefaultStacktraceConverter dstc = new DefaultStacktraceConverter();
21+
assertThat(formatStacktrace(dstc, null), is(EMPTY));
22+
}
23+
24+
@Test
25+
public void testSynthetic() throws Exception {
26+
DefaultStacktraceConverter dstc = new DefaultStacktraceConverter();
27+
String actual = formatStacktrace(dstc, new NullPointerException());
28+
assertThat(actual, not(is(EMPTY)));
29+
assertThat(arrayElem(actual, 0).toString(), is(NullPointerException.class.getName()));
30+
}
31+
32+
@Test
33+
public void testReal() throws Exception {
34+
DefaultStacktraceConverter dstc = new DefaultStacktraceConverter();
35+
36+
try {
37+
throw new ArrayIndexOutOfBoundsException();
38+
} catch (ArrayIndexOutOfBoundsException ex) {
39+
String actual = formatStacktrace(dstc, ex);
40+
assertThat(actual, not(is(EMPTY)));
41+
assertThat(arrayElem(actual, 0).toString(), containsString(ex.getClass().getName()));
42+
}
43+
}
44+
45+
@Test
46+
public void compareCompleteStacktraceWithExpectation() throws InterruptedException {
47+
Thread thread = new Thread(new Runnable() {
48+
49+
@Override
50+
public void run() {
51+
DefaultStacktraceConverter converter = new DefaultStacktraceConverter(4000);
52+
StacktraceGenerator generator = new StacktraceGenerator(5, 10, 5);
53+
converter.convert(generator.generateException(), stringBuilder);
54+
}
55+
});
56+
thread.start();
57+
thread.join();
58+
expectedString = "[\"java.lang.IllegalArgumentException: too long\"," + //
59+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
60+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
61+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
62+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
63+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
64+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
65+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
66+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
67+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
68+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
69+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
70+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
71+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
72+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
73+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
74+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
75+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
76+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
77+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
78+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
79+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
80+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
81+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
82+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.generateException(StacktraceGenerator.java:X)\"," + //
83+
"\"\\tat com.sap.hcp.cf.logging.common.converter.DefaultStacktraceConverterTest$X.run(DefaultStacktraceConverterTest.java:X)\"," + //
84+
"\"\\tat java.lang.Thread.run(Thread.java:X)\"]";
85+
Assert.assertEquals(expectedString, stringBuilder.toString().replaceAll(":\\d+\\)", ":X)").//
86+
replaceAll("\\$\\d", "\\$X"));
87+
}
88+
89+
@Test
90+
public void compareTruncatedStacktraceWithExpectation() throws InterruptedException {
91+
Thread thread = new Thread(new Runnable() {
92+
93+
@Override
94+
public void run() {
95+
DefaultStacktraceConverter converter = new DefaultStacktraceConverter(2000);
96+
StacktraceGenerator generator = new StacktraceGenerator(5, 20, 5);
97+
converter.convert(generator.generateException(), stringBuilder);
98+
}
99+
});
100+
thread.start();
101+
thread.join();
102+
expectedString = "[\"-------- STACK TRACE TRUNCATED --------\"," + //
103+
"\"java.lang.IllegalArgumentException: too long\"," + //
104+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
105+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
106+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
107+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f3IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
108+
"\"-------- OMITTED --------\"," + //
109+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f2IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
110+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
111+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
112+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
113+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
114+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
115+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.f1IsASimpleFunctionWithAnExceptionallyLongName(StacktraceGenerator.java:X)\"," + //
116+
"\"\\tat com.sap.hcp.cf.logging.common.helper.StacktraceGenerator.generateException(StacktraceGenerator.java:X)\"," + //
117+
"\"\\tat com.sap.hcp.cf.logging.common.converter.DefaultStacktraceConverterTest$X.run(DefaultStacktraceConverterTest.java:X)\"," + //
118+
"\"\\tat java.lang.Thread.run(Thread.java:X)\"]";
119+
Assert.assertEquals(expectedString, stringBuilder.toString().replaceAll(":\\d+\\)", ":X)").//
120+
replaceAll("\\$\\d", "\\$X"));
121+
}
122+
123+
}

0 commit comments

Comments
 (0)