|
| 1 | +package net.snowflake.client.internal.jdbc; |
| 2 | + |
| 3 | +import static org.junit.jupiter.api.Assertions.assertFalse; |
| 4 | +import static org.junit.jupiter.api.Assertions.assertTrue; |
| 5 | + |
| 6 | +import java.util.ArrayList; |
| 7 | +import java.util.List; |
| 8 | +import java.util.concurrent.atomic.AtomicBoolean; |
| 9 | +import java.util.logging.Handler; |
| 10 | +import java.util.logging.Level; |
| 11 | +import java.util.logging.LogRecord; |
| 12 | +import java.util.logging.Logger; |
| 13 | +import net.snowflake.client.category.TestTags; |
| 14 | +import net.snowflake.client.internal.jdbc.telemetry.ExecTimeTelemetryData; |
| 15 | +import org.apache.http.client.methods.HttpGet; |
| 16 | +import org.apache.http.impl.client.CloseableHttpClient; |
| 17 | +import org.apache.http.impl.client.HttpClientBuilder; |
| 18 | +import org.junit.jupiter.api.AfterEach; |
| 19 | +import org.junit.jupiter.api.BeforeEach; |
| 20 | +import org.junit.jupiter.api.Tag; |
| 21 | +import org.junit.jupiter.api.Test; |
| 22 | + |
| 23 | +/** |
| 24 | + * Verifies that response bodies for non-retryable HTTP 400 responses are logged through {@link |
| 25 | + * SnowflakeUtil#logResponseDetails(org.apache.http.HttpResponse, |
| 26 | + * net.snowflake.client.internal.log.SFLogger)} instead of being silently consumed by {@code |
| 27 | + * RestRequest#checkForDPoPNonceError}. |
| 28 | + * |
| 29 | + * <p>See SNOW-3388174 / GitHub issue #2584. |
| 30 | + */ |
| 31 | +@Tag(TestTags.OTHERS) |
| 32 | +public class RestRequest400BodyLoggingWiremockLatestIT extends BaseWiremockTest { |
| 33 | + |
| 34 | + private static final String LOGGER_NAME = "net.snowflake.client.internal.jdbc.RestRequest"; |
| 35 | + |
| 36 | + /** |
| 37 | + * Distinctive marker string baked into the stubbed 400 body. The test asserts this exact string |
| 38 | + * shows up in the captured log records, proving the body was actually read and logged. |
| 39 | + */ |
| 40 | + private static final String BODY_MARKER = "snow-3388174-marker"; |
| 41 | + |
| 42 | + private static final String BAD_REQUEST_SCENARIO = |
| 43 | + "{\n" |
| 44 | + + " \"mappings\": [\n" |
| 45 | + + " {\n" |
| 46 | + + " \"request\": {\n" |
| 47 | + + " \"method\": \"GET\",\n" |
| 48 | + + " \"url\": \"/some-endpoint-returning-400\"\n" |
| 49 | + + " },\n" |
| 50 | + + " \"response\": {\n" |
| 51 | + + " \"status\": 400,\n" |
| 52 | + + " \"headers\": { \"Content-Type\": \"application/json\" },\n" |
| 53 | + + " \"body\": \"{\\\"error\\\":\\\"invalid_resource\\\",\\\"error_description\\\":\\\"" |
| 54 | + + BODY_MARKER |
| 55 | + + "\\\"}\"\n" |
| 56 | + + " }\n" |
| 57 | + + " }\n" |
| 58 | + + " ],\n" |
| 59 | + + " \"importOptions\": {\n" |
| 60 | + + " \"duplicatePolicy\": \"IGNORE\",\n" |
| 61 | + + " \"deleteAllNotInImport\": true\n" |
| 62 | + + " }\n" |
| 63 | + + "}"; |
| 64 | + |
| 65 | + private CapturingLogHandler handler; |
| 66 | + private Logger internalLogger; |
| 67 | + private Level previousLevel; |
| 68 | + private boolean previousUseParentHandlers; |
| 69 | + |
| 70 | + @BeforeEach |
| 71 | + public void attachLogCapture() { |
| 72 | + internalLogger = Logger.getLogger(LOGGER_NAME); |
| 73 | + previousLevel = internalLogger.getLevel(); |
| 74 | + previousUseParentHandlers = internalLogger.getUseParentHandlers(); |
| 75 | + |
| 76 | + internalLogger.setLevel(Level.ALL); |
| 77 | + internalLogger.setUseParentHandlers(false); |
| 78 | + |
| 79 | + handler = new CapturingLogHandler(); |
| 80 | + handler.setLevel(Level.ALL); |
| 81 | + internalLogger.addHandler(handler); |
| 82 | + } |
| 83 | + |
| 84 | + @AfterEach |
| 85 | + public void detachLogCapture() { |
| 86 | + if (internalLogger != null && handler != null) { |
| 87 | + internalLogger.removeHandler(handler); |
| 88 | + internalLogger.setLevel(previousLevel); |
| 89 | + internalLogger.setUseParentHandlers(previousUseParentHandlers); |
| 90 | + } |
| 91 | + } |
| 92 | + |
| 93 | + @Test |
| 94 | + public void logs400ResponseBodyInsteadOfClosedStreamError() throws Exception { |
| 95 | + importMapping(BAD_REQUEST_SCENARIO); |
| 96 | + |
| 97 | + HttpClientBuilder httpClientBuilder = HttpClientBuilder.create().disableAutomaticRetries(); |
| 98 | + try (CloseableHttpClient httpClient = httpClientBuilder.build()) { |
| 99 | + HttpGet request = |
| 100 | + new HttpGet( |
| 101 | + String.format( |
| 102 | + "http://%s:%d/some-endpoint-returning-400", WIREMOCK_HOST, wiremockHttpPort)); |
| 103 | + |
| 104 | + // We don't care about the return value - we only care about what got logged while |
| 105 | + // RestRequest processed the 400 response. |
| 106 | + try { |
| 107 | + RestRequest.executeWithRetries( |
| 108 | + httpClient, |
| 109 | + request, |
| 110 | + 0, |
| 111 | + 0, |
| 112 | + 0, |
| 113 | + 0, |
| 114 | + 0, |
| 115 | + new AtomicBoolean(false), |
| 116 | + false, |
| 117 | + false, |
| 118 | + false, |
| 119 | + false, |
| 120 | + false, |
| 121 | + new ExecTimeTelemetryData(), |
| 122 | + null, |
| 123 | + null, |
| 124 | + null, |
| 125 | + false); |
| 126 | + } catch (Exception ignored) { |
| 127 | + // executeWithRetries may surface the 400 as a SnowflakeSQLException; that's fine. |
| 128 | + } |
| 129 | + } |
| 130 | + |
| 131 | + List<String> messages = handler.getFormattedMessages(); |
| 132 | + |
| 133 | + assertTrue( |
| 134 | + messages.stream().anyMatch(m -> m.contains(BODY_MARKER)), |
| 135 | + "Expected the 400 response body to be logged (looking for marker '" |
| 136 | + + BODY_MARKER |
| 137 | + + "'); captured messages:\n" |
| 138 | + + String.join("\n----\n", messages)); |
| 139 | + |
| 140 | + assertFalse( |
| 141 | + messages.stream().anyMatch(m -> m.contains("Attempted read from closed stream")), |
| 142 | + "Response body must not have been consumed before logResponseDetails(..) could " |
| 143 | + + "read it. Captured messages:\n" |
| 144 | + + String.join("\n----\n", messages)); |
| 145 | + } |
| 146 | + |
| 147 | + /** Minimal {@link Handler} that records every {@link LogRecord} it receives. */ |
| 148 | + private static class CapturingLogHandler extends Handler { |
| 149 | + private final List<LogRecord> records = new ArrayList<>(); |
| 150 | + |
| 151 | + @Override |
| 152 | + public synchronized void publish(LogRecord record) { |
| 153 | + records.add(record); |
| 154 | + } |
| 155 | + |
| 156 | + @Override |
| 157 | + public void flush() {} |
| 158 | + |
| 159 | + @Override |
| 160 | + public void close() {} |
| 161 | + |
| 162 | + synchronized List<String> getFormattedMessages() { |
| 163 | + List<String> out = new ArrayList<>(records.size()); |
| 164 | + for (LogRecord r : records) { |
| 165 | + out.add(formatMessage(r)); |
| 166 | + } |
| 167 | + return out; |
| 168 | + } |
| 169 | + |
| 170 | + /** |
| 171 | + * Best-effort substitution of SLF4J-style {@code {}} placeholders with the record's parameters, |
| 172 | + * so the captured message string contains the resolved body content even though the underlying |
| 173 | + * SFLogger formats lazily. |
| 174 | + */ |
| 175 | + private static String formatMessage(LogRecord r) { |
| 176 | + String msg = r.getMessage() == null ? "" : r.getMessage(); |
| 177 | + Object[] params = r.getParameters(); |
| 178 | + if (params != null) { |
| 179 | + for (Object p : params) { |
| 180 | + int idx = msg.indexOf("{}"); |
| 181 | + if (idx < 0) { |
| 182 | + break; |
| 183 | + } |
| 184 | + msg = msg.substring(0, idx) + String.valueOf(p) + msg.substring(idx + 2); |
| 185 | + } |
| 186 | + } |
| 187 | + return msg; |
| 188 | + } |
| 189 | + } |
| 190 | +} |
0 commit comments