Support Questions

Find answers, ask questions, and share your expertise

Solr health check is ok but logs show errors

avatar
Contributor

CDH version 5.7 deployed using Cloudera Manager.

 

Environment is Kerberized with TLS/SSL where applicable.

 

Solr logs have this as INFO every minute or so:

 

Could not consume full client request
java.io.IOException: Stream closed
	at org.apache.catalina.connector.InputBuffer.readByte(InputBuffer.java:315)
	at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:105)
	at org.apache.solr.servlet.SolrDispatchFilter.consumeInput(SolrDispatchFilter.java:916)
	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:223)
	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:216)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.solr.servlet.SolrHadoopAuthenticationFilter$2.doFilter(SolrHadoopAuthenticationFilter.java:394)
	at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:622)
	at org.apache.hadoop.security.token.delegation.web.DelegationTokenAuthenticationFilter.doFilter(DelegationTokenAuthenticationFilter.java:291)
	at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:574)
	at org.apache.solr.servlet.SolrHadoopAuthenticationFilter.doFilter(SolrHadoopAuthenticationFilter.java:399)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.solr.servlet.HostnameFilter.doFilter(HostnameFilter.java:86)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:620)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
	at java.lang.Thread.run(Thread.java:745)

 

[admin] webapp=null path=/admin/cores params={action=STATUS&wt=json} status=0 QTime=0 

 

1 ACCEPTED SOLUTION

avatar
This is actually a logging regression issue, that was introduced in CDH5.7.0, but fixed in CDH5.7.1, and the messages are benign, but can fill up the logs quickly. The recommendation would be to upgrade to CDH5.7.1 or higher where this logging regression was fixed.

Alternatively, you can suppress these INFO messages by adding the following to the"Solr Server Logging Advanced Configuration Snippet (Safety Valve)
":
log4j.logger.org.apache.solr.servlet.SolrDispatchFilter=WARN

-pd

View solution in original post

2 REPLIES 2

avatar

I am seeing a similar issue. I have also confirmed it only appears on CDH 5.7.0 clusters ( I have another CDH 5.4.8 cluster that is not seeing any issues, only clusters that were upgraded to 5.7.0--have this issue. I am not using Kerberos, or KIS, etc. We are using standard Unix security, and am  seeing a simmilar issue as per the log snippet posted below:

 

	
[admin] webapp=null path=/admin/cores params={action=STATUS&wt=json} status=0 QTime=0 
May 1, 6:56:15.914 AM	INFO	org.apache.solr.servlet.SolrDispatchFilter	
Could not consume full client request
java.io.IOException: Stream closed
	at org.apache.catalina.connector.InputBuffer.readByte(InputBuffer.java:315)
	at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:105)
	at org.apache.solr.servlet.SolrDispatchFilter.consumeInput(SolrDispatchFilter.java:916)
	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:223)
	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:216)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.solr.servlet.SolrHadoopAuthenticationFilter$2.doFilter(SolrHadoopAuthenticationFilter.java:394)
	at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:622)
	at org.apache.hadoop.security.token.delegation.web.DelegationTokenAuthenticationFilter.doFilter(DelegationTokenAuthenticationFilter.java:291)
	at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:574)
	at org.apache.solr.servlet.SolrHadoopAuthenticationFilter.doFilter(SolrHadoopAuthenticationFilter.java:399)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.solr.servlet.HostnameFilter.doFilter(HostnameFilter.java:86)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
	at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
	at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:620)
	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
	at java.lang.Thread.run(Thread.java:745)
May 1, 6:56:16.093 AM	INFO	org.apache.solr.servlet.SolrDispatchFilter	
[admin] webapp=null path=/admin/cores params={action=STATUS&wt=json} status=0 QTime=0 
May 1, 6:56:55.797 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 25)
May 1, 6:56:56.119 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 23)
May 1, 6:56:56.416 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 18)
May 1, 6:56:56.541 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 17)
May 1, 6:56:56.695 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 16)
May 1, 6:56:56.935 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 14)
May 1, 6:56:57.094 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 12)
May 1, 6:56:57.513 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 9)
May 1, 6:56:57.675 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 7)
May 1, 6:56:57.814 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
May 1, 6:56:57.817 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
May 1, 6:56:57.923 AM	INFO	org.apache.solr.common.cloud.ZkStateReader	
A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 6)
May 1, 6:56:58.010 AM	INFO	org.apache.zookeeper.ZooKeeper	
Session: 0x4546493a57d0107 closed
May 1, 6:56:58.010 AM	INFO	org.apache.zookeeper.ClientCnxn	
EventThread shut down
May 1, 6:56:58.011 AM	ERROR	org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager	
ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted
May 1, 6:56:58.015 AM	INFO	org.apache.solr.core.CoreContainer	
Shutting down CoreContainer instance=402797011
May 1, 6:56:58.015 AM	INFO	org.apache.solr.cloud.ZkController	
Publish node=chsnmphbase87.usdc2.oraclecloud.com:8970_solr as DOWN
May 1, 6:56:58.022 AM	INFO	org.apache.zookeeper.ClientCnxn	
EventThread shut down
May 1, 6:56:58.022 AM	INFO	org.apache.zookeeper.ZooKeeper	
Session: 0x5546493a7a5014b closed
May 1, 6:56:58.024 AM	WARN	org.apache.solr.common.cloud.ZkStateReader	
ZooKeeper watch triggered, but Solr cannot talk to ZK

 

avatar
This is actually a logging regression issue, that was introduced in CDH5.7.0, but fixed in CDH5.7.1, and the messages are benign, but can fill up the logs quickly. The recommendation would be to upgrade to CDH5.7.1 or higher where this logging regression was fixed.

Alternatively, you can suppress these INFO messages by adding the following to the"Solr Server Logging Advanced Configuration Snippet (Safety Valve)
":
log4j.logger.org.apache.solr.servlet.SolrDispatchFilter=WARN

-pd