|
| 1 | +package datadog.smoketest; |
| 2 | + |
| 3 | +import static org.junit.jupiter.api.Assertions.assertEquals; |
| 4 | + |
| 5 | +import java.io.ByteArrayInputStream; |
| 6 | +import java.io.File; |
| 7 | +import java.io.InputStream; |
| 8 | +import java.nio.file.Path; |
| 9 | +import java.util.ArrayList; |
| 10 | +import java.util.List; |
| 11 | +import org.junit.jupiter.api.Test; |
| 12 | +import org.junit.jupiter.api.io.TempDir; |
| 13 | + |
| 14 | +/** |
| 15 | + * Deterministic reproduction for the dominant flake of "check raw file injection" in |
| 16 | + * LogInjectionSmokeTest (31 of 41 reports in CI Visibility): |
| 17 | + * |
| 18 | + * <pre> |
| 19 | + * java.lang.IndexOutOfBoundsException: toIndex = 3 |
| 20 | + * at java.util.AbstractList.subListRangeCheck(...) |
| 21 | + * at datadog.smoketest.LogInjectionSmokeTest.parseTraceFromStdOut(LogInjectionSmokeTest.groovy:416) |
| 22 | + * </pre> |
| 23 | + * |
| 24 | + * <p>Root cause lives in {@link OutputThreads.ProcessOutputRunnable#run()}: when {@code |
| 25 | + * rc.read(buffer)} returns a chunk with no newline AND the inner loop has consumed no lines yet, |
| 26 | + * the fall-through branch decodes the partial buffer and adds it to {@code testLogMessages} as if |
| 27 | + * it were a complete line. The next read delivers the remainder of the same logical line, which is |
| 28 | + * then added as another "line". |
| 29 | + * |
| 30 | + * <p>In the smoke test this turns a single child-process println of {@code "THIRDTRACEID <traceId> |
| 31 | + * <spanId>\n"} into two captured "lines" — {@code "THIRDTRACEID 12345"} and {@code " 67890"} — when |
| 32 | + * the OS pipe splits the write under CI load. The smoke test's {@code stdOutLines.find { |
| 33 | + * it.contains("THIRDTRACEID") }} then returns the truncated first chunk, and {@code split(" |
| 34 | + * ")[1..2]} throws IOOBE. |
| 35 | + * |
| 36 | + * <p>The tests below assert the buggy behavior and pass today. When {@link OutputThreads} is fixed |
| 37 | + * to buffer partial lines until a newline arrives, {@link |
| 38 | + * #partialFirstReadIsIncorrectlyTreatedAsCompleteLine} will start failing — turning this into a |
| 39 | + * regression test for the fix. |
| 40 | + */ |
| 41 | +class OutputThreadsTest { |
| 42 | + |
| 43 | + @Test |
| 44 | + void singleCompleteLineIsCapturedAsOneMessage(@TempDir Path tempDir) throws Exception { |
| 45 | + List<String> msgs = |
| 46 | + capture(new ByteArrayInputStream("THIRDTRACEID 12345 67890\n".getBytes()), tempDir); |
| 47 | + |
| 48 | + assertEquals(1, msgs.size(), "messages: " + msgs); |
| 49 | + assertEquals("THIRDTRACEID 12345 67890", msgs.get(0)); |
| 50 | + } |
| 51 | + |
| 52 | + @Test |
| 53 | + void partialFirstReadIsIncorrectlyTreatedAsCompleteLine(@TempDir Path tempDir) throws Exception { |
| 54 | + // First chunk has no newline; second chunk completes the line. A correct implementation |
| 55 | + // would emit "THIRDTRACEID 12345 67890" as a single message. |
| 56 | + List<String> msgs = capture(new ChunkedInputStream("THIRDTRACEID 12345", " 67890\n"), tempDir); |
| 57 | + |
| 58 | + assertEquals( |
| 59 | + 2, |
| 60 | + msgs.size(), |
| 61 | + "expected the buggy behavior to split one line into two; messages: " + msgs); |
| 62 | + assertEquals("THIRDTRACEID 12345", msgs.get(0)); |
| 63 | + assertEquals("67890", msgs.get(1)); |
| 64 | + } |
| 65 | + |
| 66 | + private static List<String> capture(InputStream is, Path tempDir) throws Exception { |
| 67 | + File outFile = tempDir.resolve("out.log").toFile(); |
| 68 | + OutputThreads threads = new OutputThreads(); |
| 69 | + OutputThreads.ProcessOutputRunnable r = threads.new ProcessOutputRunnable(is, outFile); |
| 70 | + try { |
| 71 | + r.run(); |
| 72 | + return new ArrayList<>(threads.testLogMessages); |
| 73 | + } finally { |
| 74 | + // ProcessOutputRunnable holds a FileOutputStream-backed channel that production code |
| 75 | + // never closes (the JVM closes it at process exit). Closing here keeps Windows |
| 76 | + // @TempDir cleanup from emitting IOException noise. |
| 77 | + r.rc.close(); |
| 78 | + r.wc.close(); |
| 79 | + threads.close(); |
| 80 | + } |
| 81 | + } |
| 82 | + |
| 83 | + /** |
| 84 | + * Returns each pre-supplied chunk on a separate read() call, so the consumer observes the exact |
| 85 | + * byte boundaries that cause the partial-line bug. |
| 86 | + */ |
| 87 | + private static final class ChunkedInputStream extends InputStream { |
| 88 | + private final String[] chunks; |
| 89 | + private int chunkIdx = 0; |
| 90 | + private int offset = 0; |
| 91 | + |
| 92 | + ChunkedInputStream(String... chunks) { |
| 93 | + this.chunks = chunks; |
| 94 | + } |
| 95 | + |
| 96 | + @Override |
| 97 | + public int read() { |
| 98 | + while (chunkIdx < chunks.length) { |
| 99 | + String c = chunks[chunkIdx]; |
| 100 | + if (offset < c.length()) { |
| 101 | + return c.charAt(offset++) & 0xff; |
| 102 | + } |
| 103 | + chunkIdx++; |
| 104 | + offset = 0; |
| 105 | + } |
| 106 | + return -1; |
| 107 | + } |
| 108 | + |
| 109 | + // read(byte[], int, int) returns ONLY the bytes from the current chunk, even if the buffer |
| 110 | + // has room for more. This is what the OS pipe does under load. |
| 111 | + @Override |
| 112 | + public int read(byte[] b, int off, int len) { |
| 113 | + if (chunkIdx >= chunks.length) { |
| 114 | + return -1; |
| 115 | + } |
| 116 | + String c = chunks[chunkIdx]; |
| 117 | + int remaining = c.length() - offset; |
| 118 | + int n = Math.min(len, remaining); |
| 119 | + for (int i = 0; i < n; i++) { |
| 120 | + b[off + i] = (byte) c.charAt(offset + i); |
| 121 | + } |
| 122 | + offset += n; |
| 123 | + if (offset >= c.length()) { |
| 124 | + chunkIdx++; |
| 125 | + offset = 0; |
| 126 | + } |
| 127 | + return n; |
| 128 | + } |
| 129 | + } |
| 130 | +} |
0 commit comments