Created 03-22-2017 12:22 PM
Hi all,
Our cluster just got rebooted by a remote user, all is back to normality but the solr instance cant start it complaining for missing xml.
Here is the log can someone help out I am stuck for 3 hours now
root@nuveb:/var/log/solr# cat solr_log_20170322_1046 2017-01-23 16:08:34,915 [main] INFO [ ] org.eclipse.jetty.util.log.Log (Log.java:186) - Logging initialized @359ms 2017-01-23 16:08:35,064 [main] INFO [ ] org.eclipse.jetty.server.Server (Server.java:327) - jetty-9.2.13.v20150730 2017-01-23 16:08:35,093 [main] WARN [ ] org.eclipse.jetty.server.handler.RequestLogHandler (RequestLogHandler.java:137) - !RequestLog 2017-01-23 16:08:35,097 [main] INFO [ ] org.eclipse.jetty.deploy.providers.ScanningAppProvider (ScanningAppProvider.java:133) - Deployment monitor [file:/opt/lucidworks-hdpsearch/solr/server/contexts/] at interval 0 2017-01-23 16:08:35,312 [main] INFO [ ] org.eclipse.jetty.webapp.StandardDescriptorProcessor (StandardDescriptorProcessor.java:297) - NO JSP Support for /banana, did not find org.eclipse.jetty.jsp.JettyJspServlet 2017-01-23 16:08:35,353 [main] INFO [ ] org.eclipse.jetty.server.handler.ContextHandler (ContextHandler.java:744) - Started o.e.j.w.WebAppContext@50eac852{/banana,file:/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp-banana-1.6.0/banana-webapp/webapp/,AVAILABLE}{/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp-banana-1.6.0/banana-1.6.0.war} 2017-01-23 16:08:35,609 [main] INFO [ ] org.eclipse.jetty.webapp.StandardDescriptorProcessor (StandardDescriptorProcessor.java:297) - NO JSP Support for /solr, did not find org.apache.jasper.servlet.JspServlet 2017-01-23 16:08:35,613 [main] WARN [ ] org.eclipse.jetty.security.ConstraintSecurityHandler (ConstraintSecurityHandler.java:807) - ServletContext@o.e.j.w.WebAppContext@198b6731{/solr,file:/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp/,STARTING}{/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp} has uncovered http methods for path: / 2017-01-23 16:08:35,626 [main] INFO [ ] org.apache.solr.servlet.SolrDispatchFilter (SolrDispatchFilter.java:91) - SolrDispatchFilter.init(): WebAppClassLoader=2087258327@7c6908d7 2017-01-23 16:08:35,650 [main] INFO [ ] org.apache.solr.core.SolrResourceLoader (SolrResourceLoader.java:781) - JNDI not configured for solr (NoInitialContextEx) 2017-01-23 16:08:35,650 [main] INFO [ ] org.apache.solr.core.SolrResourceLoader (SolrResourceLoader.java:793) - using system property solr.solr.home: /etc/solr/data_dir 2017-01-23 16:08:35,651 [main] INFO [ ] org.apache.solr.core.SolrResourceLoader (SolrResourceLoader.java:170) - new SolrResourceLoader for directory: '/etc/solr/data_dir' 2017-01-23 16:08:35,652 [main] INFO [ ] org.apache.solr.core.SolrResourceLoader (SolrResourceLoader.java:781) - JNDI not configured for solr (NoInitialContextEx) 2017-01-23 16:08:35,652 [main] INFO [ ] org.apache.solr.core.SolrResourceLoader (SolrResourceLoader.java:793) - using system property solr.solr.home: /etc/solr/data_dir 2017-01-23 16:08:35,670 [main] INFO [ ] org.apache.solr.common.cloud.SolrZkClient (SolrZkClient.java:211) - Using default ZkCredentialsProvider 2017-01-23 16:08:35,701 [main] INFO [ ] org.apache.solr.common.cloud.ConnectionManager (ConnectionManager.java:192) - Waiting for client to connect to ZooKeeper 2017-01-23 16:08:36,080 [zkCallback-1-thread-1] INFO [ ] org.apache.solr.common.cloud.ConnectionManager (ConnectionManager.java:102) - Watcher org.apache.solr.common.cloud.ConnectionManager@4668cbcb name:ZooKeeperConnection Watcher:10.176.69.1:2181,10.176.69.9:2181 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None 2017-01-23 16:08:36,080 [main] INFO [ ] org.apache.solr.common.cloud.ConnectionManager (ConnectionManager.java:210) - Client is connected to ZooKeeper 2017-01-23 16:08:36,081 [main] INFO [ ] org.apache.solr.common.cloud.SolrZkClient (SolrZkClient.java:227) - Using default ZkACLProvider 2017-01-23 16:08:36,087 [main-SendThread(10.176.69.1:2181)] ERROR [ ] org.apache.zookeeper.client.ZooKeeperSaslClient (ZooKeeperSaslClient.java:384) - An error: (java.security.PrivilegedActionException: javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Server not found in Kerberos database (7) - LOOKING_UP_SERVER)]) occurred when evaluating Zookeeper Quorum Member's received SASL token. Zookeeper Client will go to AUTH_FAILED state. 2017-01-23 16:08:36,087 [main-SendThread(10.176.69.1:2181)] ERROR [ ] org.apache.zookeeper.ClientCnxn$SendThread (ClientCnxn.java:1015) - SASL authentication with Zookeeper Quorum member failed: javax.security.sasl.SaslException: An error: (java.security.PrivilegedActionException: javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Server not found in Kerberos database (7) - LOOKING_UP_SERVER)]) occurred when evaluating Zookeeper Quorum Member's received SASL token. Zookeeper Client will go to AUTH_FAILED state. 2017-01-23 16:08:36,088 [zkCallback-1-thread-1] INFO [ ] org.apache.solr.common.cloud.ConnectionManager (ConnectionManager.java:102) - Watcher org.apache.solr.common.cloud.ConnectionManager@4668cbcb name:ZooKeeperConnection Watcher:10.176.69.1:2181,10.176.69.9:2181 got event WatchedEvent state:AuthFailed type:None path:null path:null type:None 2017-01-23 16:08:36,088 [zkCallback-1-thread-1] WARN [ ] org.apache.solr.common.cloud.ConnectionManager (ConnectionManager.java:171) - zkClient received AuthFailed 2017-01-23 16:08:36,197 [main] ERROR [ ] org.apache.solr.servlet.SolrDispatchFilter (SolrDispatchFilter.java:116) - Could not start Solr. Check solr/home property and the logs 2017-01-23 16:08:36,225 [main] ERROR [ ] org.apache.solr.common.SolrException (SolrException.java:159) - null:org.apache.solr.common.SolrException: Error occurred while loading solr.xml from zookeeper at org.apache.solr.servlet.SolrDispatchFilter.loadNodeConfig(SolrDispatchFilter.java:159) at org.apache.solr.servlet.SolrDispatchFilter.createCoreContainer(SolrDispatchFilter.java:131) at org.apache.solr.servlet.SolrDispatchFilter.init(SolrDispatchFilter.java:109) at org.eclipse.jetty.servlet.FilterHolder.initialize(FilterHolder.java:138) at org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:852) at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:298) at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1349) at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1342) at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:741) at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:505) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.deploy.bindings.StandardStarter.processBinding(StandardStarter.java:41) at org.eclipse.jetty.deploy.AppLifeCycle.runBindings(AppLifeCycle.java:186) at org.eclipse.jetty.deploy.DeploymentManager.requestAppGoal(DeploymentManager.java:498) at org.eclipse.jetty.deploy.DeploymentManager.addApp(DeploymentManager.java:146) at org.eclipse.jetty.deploy.providers.ScanningAppProvider.fileAdded(ScanningAppProvider.java:180) at org.eclipse.jetty.deploy.providers.WebAppProvider.fileAdded(WebAppProvider.java:461) at org.eclipse.jetty.deploy.providers.ScanningAppProvider$1.fileAdded(ScanningAppProvider.java:64) at org.eclipse.jetty.util.Scanner.reportAddition(Scanner.java:609) at org.eclipse.jetty.util.Scanner.reportDifferences(Scanner.java:528) at org.eclipse.jetty.util.Scanner.scan(Scanner.java:391) at org.eclipse.jetty.util.Scanner.doStart(Scanner.java:313) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.deploy.providers.ScanningAppProvider.doStart(ScanningAppProvider.java:150) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.deploy.DeploymentManager.startAppProvider(DeploymentManager.java:560) at org.eclipse.jetty.deploy.DeploymentManager.doStart(DeploymentManager.java:235) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132) at org.eclipse.jetty.server.Server.start(Server.java:387) at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61) at org.eclipse.jetty.server.Server.doStart(Server.java:354) at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) at org.eclipse.jetty.xml.XmlConfiguration$1.run(XmlConfiguration.java:1255) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.jetty.xml.XmlConfiguration.main(XmlConfiguration.java:1174) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.eclipse.jetty.start.Main.invokeMain(Main.java:321) at org.eclipse.jetty.start.Main.start(Main.java:817) at org.eclipse.jetty.start.Main.main(Main.java:112) Caused by: org.apache.zookeeper.KeeperException$AuthFailedException: KeeperErrorCode = AuthFailed for /solr.xml at org.apache.zookeeper.KeeperException.create(KeeperException.java:123) at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:1045) at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:311) at org.apache.solr.common.cloud.SolrZkClient$5.execute(SolrZkClient.java:308) at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60) at org.apache.solr.common.cloud.SolrZkClient.exists(SolrZkClient.java:308) at org.apache.solr.servlet.SolrDispatchFilter.loadNodeConfig(SolrDispatchFilter.java:153) ... 43 more 2017-01-23 16:08:36,225 [main] INFO [ ] org.apache.solr.servlet.SolrDispatchFilter (SolrDispatchFilter.java:123) - SolrDispatchFilter.init() done 2017-01-23 16:08:36,228 [main] INFO [ ] org.eclipse.jetty.server.handler.ContextHandler (ContextHandler.java:744) - Started o.e.j.w.WebAppContext@198b6731{/solr,file:/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp/,AVAILABLE}{/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp} 2017-01-23 16:08:36,236 [main] INFO [ ] org.eclipse.jetty.server.AbstractConnector (AbstractConnector.java:266) - Started ServerConnector@6caf0677{HTTP/1.1}{0.0.0.0:8983} 2017-01-23 16:08:36,237 [main] INFO [ ] org.eclipse.jetty.server.Server (Server.java:379) - Started @1683ms 2017-03-22 10:42:09,937 [ShutdownMonitor] INFO [ ] org.eclipse.jetty.server.AbstractConnector (AbstractConnector.java:306) - Stopped ServerConnector@6caf0677{HTTP/1.1}{0.0.0.0:8983} 2017-03-22 10:42:09,947 [ShutdownMonitor] INFO [ ] org.eclipse.jetty.server.handler.ContextHandler (ContextHandler.java:865) - Stopped o.e.j.w.WebAppContext@198b6731{/solr,file:/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp/,UNAVAILABLE}{/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp} 2017-03-22 10:42:09,949 [ShutdownMonitor] INFO [ ] org.eclipse.jetty.server.handler.ContextHandler (ContextHandler.java:865) - Stopped o.e.j.w.WebAppContext@50eac852{/banana,file:/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp-banana-1.6.0/banana-webapp/webapp/,UNAVAILABLE}{/opt/lucidworks-hdpsearch/solr/server/solr-webapp/webapp-banana-1.6.0/banana-1.6.0.war}
Created 03-22-2017 12:30 PM
As per the "SolrDispatchFilter.java" code following is the logic which it uses to load the "solr.xml" file (from zookeeper)
public static NodeConfig loadNodeConfig(Path solrHome, Properties nodeProperties) { SolrResourceLoader loader = new SolrResourceLoader(solrHome, null, nodeProperties); if (!StringUtils.isEmpty(System.getProperty("solr.solrxml.location"))) { log.warn("Solr property solr.solrxml.location is no longer supported. " + "Will automatically load solr.xml from ZooKeeper if it exists"); }
.
But in your mentioned log it looks like zookeeper is having some Kerberos issues "GSS initiate failed" and "Server not found in Kerberos database (7)"
. Can you check if you see valid kerberos tickets or if you are able to list the tickets or do a "kinit" ?
2017-01-23 16:08:36,087 [main-SendThread(10.176.69.1:2181)] ERROR [ ] org.apache.zookeeper.client.ZooKeeperSaslClient (ZooKeeperSaslClient.java:384) - An error: (java.security.PrivilegedActionException: javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Server not found in Kerberos database (7) - LOOKING_UP_SERVER)]) occurred when evaluating Zookeeper Quorum Member's received SASL token. Zookeeper Client will go to AUTH_FAILED state.
.
Created 03-22-2017 12:30 PM
As per the "SolrDispatchFilter.java" code following is the logic which it uses to load the "solr.xml" file (from zookeeper)
public static NodeConfig loadNodeConfig(Path solrHome, Properties nodeProperties) { SolrResourceLoader loader = new SolrResourceLoader(solrHome, null, nodeProperties); if (!StringUtils.isEmpty(System.getProperty("solr.solrxml.location"))) { log.warn("Solr property solr.solrxml.location is no longer supported. " + "Will automatically load solr.xml from ZooKeeper if it exists"); }
.
But in your mentioned log it looks like zookeeper is having some Kerberos issues "GSS initiate failed" and "Server not found in Kerberos database (7)"
. Can you check if you see valid kerberos tickets or if you are able to list the tickets or do a "kinit" ?
2017-01-23 16:08:36,087 [main-SendThread(10.176.69.1:2181)] ERROR [ ] org.apache.zookeeper.client.ZooKeeperSaslClient (ZooKeeperSaslClient.java:384) - An error: (java.security.PrivilegedActionException: javax.security.sasl.SaslException: GSS initiate failed [Caused by GSSException: No valid credentials provided (Mechanism level: Server not found in Kerberos database (7) - LOOKING_UP_SERVER)]) occurred when evaluating Zookeeper Quorum Member's received SASL token. Zookeeper Client will go to AUTH_FAILED state.
.
Created 03-22-2017 12:41 PM
We got the solution at the same time but I will give you the points it isn't fare to give myself 🙂
Created 03-22-2017 12:38 PM
Hi all,
Problem resolved I grabbed a new kerberos ticket and started solr
root@nuveb:/opt/lucidworks-hdpsearch/solr# bin/solr start Waiting up to 30 seconds to see Solr running on port 8983 [/] Started Solr server on port 8983 (pid=5214). Happy searching!
Thanks