Non-coordinator services are repeatedly logging JsonMappingException when using druid-basic-security extension with an authenticator that has no users setup #8678
Description
Affected Version
Detected in master (0.17.0), but also occurs in versions 0.12.0 and above.
Description
Issue occurs when using druid-basic-security extension and having an authenticator in the authenticator chain that has no users setup (not even the admin and druid_system internal users). We're seeing the following exception getting logged repeatedly within non-coordinator services:
WARN [main] org.apache.druid.java.util.common.RetryUtils - Retrying (1 of 9) in 901ms.
com.fasterxml.jackson.databind.JsonMappingException: No content to map due to end-of-input
-
Cluster size
Any -
Configurations in use
// Coordinator config
-server
-Xms256m
-Xmx256m
-Duser.timezone=UTC
-Dfile.encoding=UTF-8
-Djava.io.tmpdir=/tmp/druid
-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager
-XX:+UseG1GC
-Dlog4j.configurationFile=/path/to/log4j2.debug.xml
-Dorg.jboss.logging.provider=slf4j
-Ddruid.service=druid/coordinator
-Ddruid.coordinator.period=PT10S
-Ddruid.coordinator.startDelay=PT5S
-Ddruid.host=localhost
-Ddruid.extensions.directory=/path/to/apache/druid/extensions/
-Ddruid.extensions.loadList=["mysql-metadata-storage","druid-basic-security"]
-Ddruid.zk.service.host=localhost
-Ddruid.zk.paths.base=/druid
-Ddruid.metadata.storage.type=mysql
-Ddruid.metadata.storage.connector.connectURI="jdbc:mysql://localhost:3306/druid"
-Ddruid.metadata.storage.connector.user=druid1
-Ddruid.metadata.storage.connector.password=test
-Ddruid.emitter=logging
-Ddruid.emitter.logging.logLevel=debug
-Ddruid.sql.enable=true
-Ddruid.auth.authenticator.local.type=basic
-Ddruid.auth.authenticator.local.skipOnFailure=true
-Ddruid.auth.authenticator.local.initialAdminPassword=password1
-Ddruid.auth.authenticator.local.initialInternalClientPassword=password2
-Ddruid.auth.authenticator.local.credentialsValidator.type=metadata
-Ddruid.extensions.directory=/path/to/apache/druid/extensions/
-Ddruid.extensions.loadList=["mysql-metadata-storage","druid-basic-security"]
-Ddruid.auth.authenticatorChain=["local","test"]
-Ddruid.auth.authenticator.local.type=basic
-Ddruid.auth.authenticator.local.skipOnFailure=true
-Ddruid.auth.authenticator.local.initialAdminPassword=password1
-Ddruid.auth.authenticator.local.initialInternalClientPassword=password2
-Ddruid.auth.authenticator.local.credentialsValidator.type=metadata
-Ddruid.auth.authenticator.local.authorizerName=local
-Ddruid.auth.authenticator.test.type=basic
-Ddruid.auth.authenticator.test.skipOnFailure=false
-Ddruid.auth.authenticator.test.credentialsValidator.type=metadata
-Ddruid.auth.authenticator.test.authorizerName=test
-Ddruid.auth.authorizers=["local","test"]
-Ddruid.auth.authorizer.local.type=basic
-Ddruid.auth.authorizer.local.roleProvider.type=metadata
-Ddruid.auth.authorizer.test.type=basic
-Ddruid.auth.authorizer.test.roleProvider.type=metadata
-Ddruid.escalator.type=basic
-Ddruid.escalator.internalClientUsername=druid_system
-Ddruid.escalator.internalClientPassword=password2
-Ddruid.escalator.authorizerName=local
// Broker config
-server
-Xms1g
-Xmx1g
-XX:MaxDirectMemorySize=1792m
-Duser.timezone=UTC
-Dfile.encoding=UTF-8
-Djava.io.tmpdir=/tmp/druid
-Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager
-XX:+UseG1GC
-Dlog4j.configurationFile=/path/to/log4j2.debug.xml
-Dorg.jboss.logging.provider=slf4j
-Ddruid.service=druid/broker
-Ddruid.broker.http.numConnections=5
-Ddruid.broker.cache.useCache=false
-Ddruid.broker.cache.populateCache=false
-Ddruid.server.http.numThreads=9
-Ddruid.processing.buffer.sizeBytes=256000000
-Ddruid.processing.numThreads=2
-Ddruid.cache.sizeInBytes=10000000
-Ddruid.host=localhost
-Ddruid.extensions.directory=
-Ddruid.extensions.loadList=["mysql-metadata-storage","druid-basic-security"]
-Ddruid.zk.service.host=localhost
-Ddruid.zk.paths.base=/druid
-Ddruid.metadata.storage.type=mysql
-Ddruid.metadata.storage.connector.connectURI="jdbc:mysql://localhost:3306/druid"
-Ddruid.metadata.storage.connector.user=druid1
-Ddruid.metadata.storage.connector.password=test
-Ddruid.emitter=logging
-Ddruid.emitter.logging.logLevel=debug
-Ddruid.sql.enable=true
-Ddruid.auth.authenticator.local.type=basic
-Ddruid.auth.authenticator.local.skipOnFailure=true
-Ddruid.auth.authenticator.local.initialAdminPassword=password1
-Ddruid.auth.authenticator.local.initialInternalClientPassword=password2
-Ddruid.auth.authenticator.local.credentialsValidator.type=metadata
-Ddruid.extensions.directory=/path/to/apache/druid/extensions/
-Ddruid.extensions.loadList=["mysql-metadata-storage","druid-basic-security"]
-Ddruid.auth.authenticatorChain=["local","test"]
-Ddruid.auth.authenticator.local.type=basic
-Ddruid.auth.authenticator.local.skipOnFailure=true
-Ddruid.auth.authenticator.local.initialAdminPassword=password1
-Ddruid.auth.authenticator.local.initialInternalClientPassword=password2
-Ddruid.auth.authenticator.local.credentialsValidator.type=metadata
-Ddruid.auth.authenticator.local.authorizerName=local
-Ddruid.auth.authenticator.test.type=basic
-Ddruid.auth.authenticator.test.skipOnFailure=false
-Ddruid.auth.authenticator.test.credentialsValidator.type=metadata
-Ddruid.auth.authenticator.test.authorizerName=test
-Ddruid.auth.authorizers=["local","test"]
-Ddruid.auth.authorizer.local.type=basic
-Ddruid.auth.authorizer.local.roleProvider.type=metadata
-Ddruid.auth.authorizer.test.type=basic
-Ddruid.auth.authorizer.test.roleProvider.type=metadata
-Ddruid.escalator.type=basic
-Ddruid.escalator.internalClientUsername=druid_system
-Ddruid.escalator.internalClientPassword=password2
-Ddruid.escalator.authorizerName=local -
Steps to reproduce the problem
Start the coordinator service, then the broker service, and then view the broker service logs -
The error message or stack traces encountered. Providing more context, such as nearby log messages or even entire logs, can be helpful.
2019-10-15T14:39:44,673 DEBUG [HttpClient-Netty-Worker-1] org.apache.druid.java.util.http.client.NettyHttpClient - [GET http://localhost:8081/druid-ext/basic-security/authentication/db/ldap/cachedSerializedUserMap] Got response: 200 OK
2019-10-15T14:39:57,792 WARN [main] org.apache.druid.java.util.common.RetryUtils - Retrying (1 of 9) in 901ms.
com.fasterxml.jackson.databind.JsonMappingException: No content to map due to end-of-input
at [Source: [B@7109b603; line: -1, column: 0]
at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:148) ~[jackson-databind-2.6.7.jar:2.6.7]
at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3781) ~[jackson-databind-2.6.7.jar:2.6.7]
at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:3721) ~[jackson-databind-2.6.7.jar:2.6.7]
at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2836) ~[jackson-databind-2.6.7.jar:2.6.7]
at org.apache.druid.security.basic.authentication.db.cache.CoordinatorPollingBasicAuthenticatorCacheManager.tryFetchUserMapFromCoordinator(CoordinatorPollingBasicAuthenticatorCacheManager.java:262) ~[classes/:?]
at org.apache.druid.security.basic.authentication.db.cache.CoordinatorPollingBasicAuthenticatorCacheManager.lambda$fetchUserMapFromCoordinator$1(CoordinatorPollingBasicAuthenticatorCacheManager.java:192) ~[classes/:?]
at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:86) [classes/:?]
at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:114) [classes/:?]
at org.apache.druid.java.util.common.RetryUtils.retry(RetryUtils.java:104) [classes/:?]
at org.apache.druid.security.basic.authentication.db.cache.CoordinatorPollingBasicAuthenticatorCacheManager.fetchUserMapFromCoordinator(CoordinatorPollingBasicAuthenticatorCacheManager.java:190) [classes/:?]
at org.apache.druid.security.basic.authentication.db.cache.CoordinatorPollingBasicAuthenticatorCacheManager.initUserMaps(CoordinatorPollingBasicAuthenticatorCacheManager.java:289) [classes/:?]
at org.apache.druid.security.basic.authentication.db.cache.CoordinatorPollingBasicAuthenticatorCacheManager.start(CoordinatorPollingBasicAuthenticatorCacheManager.java:108) [classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_151]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_151]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_151]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_151]
at org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler.start(Lifecycle.java:442) [classes/:?]
at org.apache.druid.java.util.common.lifecycle.Lifecycle.start(Lifecycle.java:339) [classes/:?]
at org.apache.druid.guice.LifecycleModule$2.start(LifecycleModule.java:140) [classes/:?]
at org.apache.druid.cli.GuiceRunnable.initLifecycle(GuiceRunnable.java:115) [classes/:?]
at org.apache.druid.cli.ServerRunnable.run(ServerRunnable.java:57) [classes/:?]
at org.apache.druid.cli.Main.main(Main.java:113) [classes/:?] -
Any debugging that you have already done
When CoordinatorPollingBasicAuthenticatorCacheManager class' tryFetchUserMapFromCoordinator method retrieves cached serialized user map from end point /druid-ext/basic-security/authentication/db/%s/cachedSerializedUserMap and the map is null then calling getContent() method of BytesFullResponseHolder returns zero byte array which when the jackson object mapper tries to deserialize to BasicAuthUtils.AUTHENTICATOR_USER_MAP_TYPE_REFERENCE (a Map<String, BasicAuthenticatorUser> object) ends up throwing com.fasterxml.jackson.databind.JsonMappingException: No content to map due to end-of-input
To fix this issue we should add a zero byte array check to userMapBytes and log a message instead. Only attempt to deserialize if the user mao byte array is not empty.
This will also help clean up the behavior for authenticators that don't reply on the user map to authenticate, like ldap