diff --git a/docs/content/configuration/index.md b/docs/content/configuration/index.md index aa033c4416d..c53deb63af1 100644 --- a/docs/content/configuration/index.md +++ b/docs/content/configuration/index.md @@ -91,7 +91,7 @@ All nodes that can serve queries can also log the query requests they see. |Property|Description|Default| |--------|-----------|-------| -|`druid.request.logging.type`|Choices: noop, file, emitter. How to log every query request.|noop| +|`druid.request.logging.type`|Choices: noop, file, emitter, slf4j. How to log every query request.|noop| Note that, you can enable sending all the HTTP requests to log by setting "io.druid.jetty.RequestLog" to DEBUG level. See [Logging](../configuration/logging.html) @@ -111,6 +111,28 @@ Every request is emitted to some external location. |--------|-----------|-------| |`druid.request.logging.feed`|Feed name for requests.|none| +#### SLF4J Request Logging + +Every request is logged via SLF4J. Queries are serialized into JSON in the log message regardless of the SJF4J format specification. They will be logged under the class `io.druid.server.log.LoggingRequestLogger`. + +|Property|Description|Default| +|--------|-----------|-------| +|`druid.request.logging.setMDC`|If MDC entries should be set in the log entry. Your logging setup still has to be configured to handle MDC to format this data|false| +|`druid.request.logging.setContextMDC`|If the druid query `context` should be added to the MDC entries. Has no effect unless `setMDC` is `true`|false| + +MDC fields populated with `setMDC`: + +|MDC field|Description| +|---------|-----------| +|`queryId` |The query ID| +|`dataSource`|The datasource the query was against| +|`queryType` |The type of the query| +|`hasFilters`|If the query has any filters| +|`remoteAddr`|The remote address of the requesting client| +|`duration` |The duration of the query interval| +|`resultOrdering`|The ordering of results| +|`descending`|If the query is a descending query| + ### Enabling Metrics Druid nodes periodically emit metrics and different metrics monitors can be included. Each node can overwrite the default list of monitors. diff --git a/server/src/main/java/io/druid/guice/QueryableModule.java b/server/src/main/java/io/druid/guice/QueryableModule.java index 3da8e691d44..5a0a84ae193 100644 --- a/server/src/main/java/io/druid/guice/QueryableModule.java +++ b/server/src/main/java/io/druid/guice/QueryableModule.java @@ -27,6 +27,7 @@ import io.druid.initialization.DruidModule; import io.druid.query.QuerySegmentWalker; import io.druid.server.log.EmittingRequestLoggerProvider; import io.druid.server.log.FileRequestLoggerProvider; +import io.druid.server.log.LoggingRequestLoggerProvider; import io.druid.server.log.RequestLogger; import io.druid.server.log.RequestLoggerProvider; @@ -50,7 +51,11 @@ public class QueryableModule implements DruidModule { return Arrays.asList( new SimpleModule("QueryableModule") - .registerSubtypes(EmittingRequestLoggerProvider.class, FileRequestLoggerProvider.class) + .registerSubtypes( + EmittingRequestLoggerProvider.class, + FileRequestLoggerProvider.class, + LoggingRequestLoggerProvider.class + ) ); } } diff --git a/server/src/main/java/io/druid/server/log/LoggingRequestLogger.java b/server/src/main/java/io/druid/server/log/LoggingRequestLogger.java new file mode 100644 index 00000000000..6d2db82b2df --- /dev/null +++ b/server/src/main/java/io/druid/server/log/LoggingRequestLogger.java @@ -0,0 +1,105 @@ +/* + * Licensed to Metamarkets Group Inc. (Metamarkets) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. Metamarkets licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package io.druid.server.log; + +import com.fasterxml.jackson.databind.ObjectMapper; +import com.google.common.collect.ImmutableList; +import com.metamx.common.logger.Logger; +import io.druid.query.Query; +import io.druid.server.RequestLogLine; +import org.slf4j.MDC; + +import java.io.IOException; +import java.util.Map; + +public class LoggingRequestLogger implements RequestLogger +{ + private static final Logger LOG = new Logger(LoggingRequestLogger.class); + + private final ObjectMapper mapper; + private final boolean setMDC; + private final boolean setContextMDC; + + public LoggingRequestLogger( + ObjectMapper mapper, + boolean setMDC, + boolean setContextMDC + ) + { + this.mapper = mapper; + this.setMDC = setMDC; + this.setContextMDC = setContextMDC; + } + + @Override + public void log(RequestLogLine requestLogLine) throws IOException + { + final Map mdc = MDC.getCopyOfContextMap(); + // MDC must be set during the `LOG.info` call at the end of the try block. + try { + if (setMDC) { + try { + final Query query = requestLogLine.getQuery(); + MDC.put("queryId", query.getId()); + MDC.put("dataSource", query.getDataSource().toString()); + MDC.put("queryType", query.getType()); + MDC.put("hasFilters", Boolean.toString(query.hasFilters())); + MDC.put("remoteAddr", requestLogLine.getRemoteAddr()); + MDC.put("duration", query.getDuration().toString()); + MDC.put("descending", Boolean.toString(query.isDescending())); + if (setContextMDC) { + final Iterable> entries = query.getContext() == null + ? ImmutableList.>of() + : query.getContext().entrySet(); + for (Map.Entry entry : entries) { + MDC.put(entry.getKey(), entry.getValue() == null ? "NULL" : entry.getValue().toString()); + } + } + } + catch (RuntimeException re) { + LOG.error(re, "Error preparing MDC"); + } + } + final String line = requestLogLine.getLine(mapper); + + // MDC must be set here + LOG.info("%s", line); + } + finally { + if (setMDC) { + if (mdc != null) { + MDC.setContextMap(mdc); + } else { + MDC.clear(); + } + } + } + } + + public boolean isSetMDC() + { + return setMDC; + } + + public boolean isSetContextMDC() + { + return setContextMDC; + } +} diff --git a/server/src/main/java/io/druid/server/log/LoggingRequestLoggerProvider.java b/server/src/main/java/io/druid/server/log/LoggingRequestLoggerProvider.java new file mode 100644 index 00000000000..478795057f6 --- /dev/null +++ b/server/src/main/java/io/druid/server/log/LoggingRequestLoggerProvider.java @@ -0,0 +1,46 @@ +/* + * Licensed to Metamarkets Group Inc. (Metamarkets) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. Metamarkets licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package io.druid.server.log; + +import com.fasterxml.jackson.annotation.JacksonInject; +import com.fasterxml.jackson.annotation.JsonProperty; +import com.fasterxml.jackson.annotation.JsonTypeName; +import com.fasterxml.jackson.databind.ObjectMapper; +import io.druid.guice.annotations.Json; + +@JsonTypeName("slf4j") +public class LoggingRequestLoggerProvider implements RequestLoggerProvider +{ + @JacksonInject + @Json + public ObjectMapper mapper; + + @JsonProperty + public boolean setMDC = false; + + @JsonProperty + public boolean setContextMDC = false; + + @Override + public RequestLogger get() + { + return new LoggingRequestLogger(mapper, setMDC, setContextMDC); + } +} diff --git a/server/src/test/java/io/druid/server/log/LoggingRequestLoggerProviderTest.java b/server/src/test/java/io/druid/server/log/LoggingRequestLoggerProviderTest.java new file mode 100644 index 00000000000..ece090f5e6d --- /dev/null +++ b/server/src/test/java/io/druid/server/log/LoggingRequestLoggerProviderTest.java @@ -0,0 +1,89 @@ +/* + * Licensed to Metamarkets Group Inc. (Metamarkets) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. Metamarkets licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package io.druid.server.log; + +import com.google.common.collect.ImmutableList; +import com.google.inject.Binder; +import com.google.inject.Injector; +import com.google.inject.Key; +import com.google.inject.Module; +import com.google.inject.name.Names; +import io.druid.guice.GuiceInjectors; +import io.druid.guice.JsonConfigProvider; +import io.druid.guice.JsonConfigurator; +import io.druid.initialization.Initialization; +import org.junit.Assert; +import org.junit.Test; + +import java.util.Properties; +import java.util.UUID; + +public class LoggingRequestLoggerProviderTest +{ + private final String propertyPrefix = UUID.randomUUID().toString().replace('-', '_'); + private final JsonConfigProvider provider = JsonConfigProvider.of( + propertyPrefix, + RequestLoggerProvider.class + ); + private final Injector injector = makeInjector(); + + @Test + public void testDefaultConfigParsing() + { + final Properties properties = new Properties(); + properties.put(propertyPrefix + ".type", "slf4j"); + provider.inject(properties, injector.getInstance(JsonConfigurator.class)); + final LoggingRequestLogger requestLogger = (LoggingRequestLogger) provider.get().get().get(); + Assert.assertFalse(requestLogger.isSetContextMDC()); + Assert.assertFalse(requestLogger.isSetMDC()); + } + + @Test + public void testConfigParsingFull() + { + final Properties properties = new Properties(); + properties.put(propertyPrefix + ".type", "slf4j"); + properties.put(propertyPrefix + ".setMDC", "true"); + properties.put(propertyPrefix + ".setContextMDC", "true"); + provider.inject(properties, injector.getInstance(JsonConfigurator.class)); + final LoggingRequestLogger requestLogger = (LoggingRequestLogger) provider.get().get().get(); + Assert.assertTrue(requestLogger.isSetContextMDC()); + Assert.assertTrue(requestLogger.isSetMDC()); + } + + private Injector makeInjector() + { + return Initialization.makeInjectorWithModules( + GuiceInjectors.makeStartupInjector(), + ImmutableList.of( + new Module() + { + @Override + public void configure(Binder binder) + { + binder.bind(Key.get(String.class, Names.named("serviceName"))).toInstance("some service"); + binder.bind(Key.get(Integer.class, Names.named("servicePort"))).toInstance(0); + JsonConfigProvider.bind(binder, propertyPrefix, RequestLoggerProvider.class); + } + } + ) + ); + } +} diff --git a/server/src/test/java/io/druid/server/log/LoggingRequestLoggerTest.java b/server/src/test/java/io/druid/server/log/LoggingRequestLoggerTest.java new file mode 100644 index 00000000000..b11dae47777 --- /dev/null +++ b/server/src/test/java/io/druid/server/log/LoggingRequestLoggerTest.java @@ -0,0 +1,224 @@ +/* + * Licensed to Metamarkets Group Inc. (Metamarkets) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. Metamarkets licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package io.druid.server.log; + +import com.fasterxml.jackson.annotation.JsonTypeName; +import com.fasterxml.jackson.core.type.TypeReference; +import com.fasterxml.jackson.databind.ObjectMapper; +import com.google.common.base.Charsets; +import com.google.common.collect.ImmutableMap; +import io.druid.jackson.DefaultObjectMapper; +import io.druid.query.BaseQuery; +import io.druid.query.DataSource; +import io.druid.query.LegacyDataSource; +import io.druid.query.Query; +import io.druid.query.QueryRunner; +import io.druid.query.QuerySegmentWalker; +import io.druid.query.filter.DimFilter; +import io.druid.query.spec.QuerySegmentSpec; +import io.druid.server.QueryStats; +import io.druid.server.RequestLogLine; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.appender.OutputStreamAppender; +import org.apache.logging.log4j.core.layout.JsonLayout; +import org.joda.time.DateTime; +import org.joda.time.Interval; +import org.junit.After; +import org.junit.AfterClass; +import org.junit.Assert; +import org.junit.BeforeClass; +import org.junit.Test; + +import java.io.ByteArrayOutputStream; +import java.util.Collection; +import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Map; + +// Mostly just test that it doesn't crash +public class LoggingRequestLoggerTest +{ + private static final ObjectMapper mapper = new DefaultObjectMapper(); + private static final ByteArrayOutputStream baos = new ByteArrayOutputStream(); + private static Appender appender; + + final DateTime timestamp = DateTime.parse("2016-01-01T00:00:00Z"); + final String remoteAddr = "some.host.tld"; + final Map queryContext = ImmutableMap.of("foo", "bar"); + final Query query = new FakeQuery( + new LegacyDataSource("datasource"), + new QuerySegmentSpec() + { + @Override + public List getIntervals() + { + return Collections.singletonList(Interval.parse("2016-01-01T00Z/2016-01-02T00Z")); + } + + @Override + public QueryRunner lookup(Query query, QuerySegmentWalker walker) + { + return null; + } + }, false, queryContext + ); + final QueryStats queryStats = new QueryStats(ImmutableMap.of()); + final RequestLogLine logLine = new RequestLogLine( + timestamp, + remoteAddr, + query, + queryStats + ); + + @BeforeClass + public static void setUpStatic() throws Exception + { + appender = OutputStreamAppender + .newBuilder() + .setName("test stream") + .setTarget(baos) + .setLayout(JsonLayout.createLayout(false, true, false, true, true, Charsets.UTF_8)) + .build(); + final org.apache.logging.log4j.core.Logger logger = (org.apache.logging.log4j.core.Logger) + LogManager.getLogger(LoggingRequestLogger.class); + appender.start(); + logger.addAppender(appender); + } + + @After + public void tearDown() + { + baos.reset(); + } + + @AfterClass + public static void tearDownStatic() + { + final org.apache.logging.log4j.core.Logger logger = (org.apache.logging.log4j.core.Logger) LogManager.getLogger( + LoggingRequestLogger.class); + logger.removeAppender(appender); + appender.stop(); + } + + @Test + public void testSimpleLogging() throws Exception + { + final LoggingRequestLogger requestLogger = new LoggingRequestLogger(new DefaultObjectMapper(), false, false); + requestLogger.log(logLine); + } + + @Test + public void testLoggingMDC() throws Exception + { + final LoggingRequestLogger requestLogger = new LoggingRequestLogger(new DefaultObjectMapper(), true, false); + requestLogger.log(logLine); + final Map map = readContextMap(baos.toByteArray()); + Assert.assertEquals("datasource", map.get("dataSource")); + Assert.assertEquals("PT86400S", map.get("duration")); + Assert.assertEquals("false", map.get("hasFilters")); + Assert.assertEquals("fake", map.get("queryType")); + Assert.assertEquals("some.host.tld", map.get("remoteAddr")); + Assert.assertEquals("false", map.get("descending")); + Assert.assertNull(map.get("foo")); + } + + @Test + public void testLoggingMDCContext() throws Exception + { + final LoggingRequestLogger requestLogger = new LoggingRequestLogger(new DefaultObjectMapper(), true, true); + requestLogger.log(logLine); + final Map map = readContextMap(baos.toByteArray()); + Assert.assertEquals("datasource", map.get("dataSource")); + Assert.assertEquals("PT86400S", map.get("duration")); + Assert.assertEquals("false", map.get("hasFilters")); + Assert.assertEquals("fake", map.get("queryType")); + Assert.assertEquals("some.host.tld", map.get("remoteAddr")); + Assert.assertEquals("false", map.get("descending")); + Assert.assertEquals("bar", map.get("foo")); + } + + private static Map readContextMap(byte[] bytes) throws Exception + { + final Map rawMap = mapper.readValue(bytes, new TypeReference>() + { + }); + final Object contextMap = rawMap.get("contextMap"); + if (contextMap == null) { + return null; + } + final Collection> contextList = (Collection>) contextMap; + final Map context = new HashMap<>(); + for (Map microContext : contextList) { + final String key = microContext.get("key").toString(); + final Object value = microContext.get("value"); + if (key != null && value != null) { + context.put(key, value); + } + } + return ImmutableMap.copyOf(context); + } +} + +@JsonTypeName("fake") +class FakeQuery extends BaseQuery +{ + public FakeQuery(DataSource dataSource, QuerySegmentSpec querySegmentSpec, boolean descending, Map context) + { + super(dataSource, querySegmentSpec, descending, context); + } + + @Override + public boolean hasFilters() + { + return false; + } + + @Override + public DimFilter getFilter() + { + throw new UnsupportedOperationException("shouldn't be here"); + } + + @Override + public String getType() + { + return "fake"; + } + + @Override + public Query withQuerySegmentSpec(QuerySegmentSpec spec) + { + throw new UnsupportedOperationException("shouldn't be here"); + } + + @Override + public Query withDataSource(DataSource dataSource) + { + throw new UnsupportedOperationException("shouldn't be here"); + } + + @Override + public Query withOverriddenContext(Map contextOverride) + { + throw new UnsupportedOperationException("shouldn't be here"); + } +}