Uploaded image for project: 'Solr'
  1. Solr
  2. SOLR-13218

MetricsHistoryHandler failes to collect metrics in BasicAuthPlugin enabled setup

    XMLWordPrintableJSON

Details

    Description

      After Updating solr to version 7.6.0 (from 6.6.5) running the setup

      • SolrCloud with 3 Zookeepers and 2 Solr Servers
      • HTTPS enabled
      • BasicAuthentication Enabled
      {
  "authorization": {
    "user-role": {"Solr": "admin"},
    "permissions": [{
      "role": "admin",
      "name": "security-edit"
    }],
    "class": "solr.RuleBasedAuthorizationPlugin"
  },
  "authentication": {
    "credentials": {"Solr": "1XkpuFRODp3WJJeMqvyGXcu8QSeo0juRvR2g4B1pCvQ= RETXcj9xeYDQ9V+kuDSV3hF2gEUEj79e7Uo+HehPfAE="},
    "blockUnknown": true,
    "class": "solr.BasicAuthPlugin"
  }
}

      the following errors started showing up in the logs at regular intervals

      11:22:35 [MetricsHistoryHandler-12-thread-1] WARN o.a.s.c.s.i.SolrClientNodeStateProvider - could not get tags from node localhost:8011_solr
org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://localhost:8011/solr: Expected mime type application/octet-stream but got text/html. <html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8"/>
<title>Error 401 require authentication</title>
</head>
<body><h2>HTTP ERROR 401</h2>
<p>Problem accessing /solr/admin/metrics. Reason:
<pre> require authentication</pre></p>
</body>
</html>

at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:607)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244)
at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1260)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$ClientSnitchCtx.invoke(SolrClientNodeStateProvider.java:349)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.fetchReplicaMetrics(SolrClientNodeStateProvider.java:195)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$AutoScalingSnitch.getRemoteInfo(SolrClientNodeStateProvider.java:242)
at org.apache.solr.common.cloud.rule.ImplicitSnitch.getTags(ImplicitSnitch.java:76)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.fetchTagValues(SolrClientNodeStateProvider.java:138)
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.getNodeValues(SolrClientNodeStateProvider.java:127)
at org.apache.solr.handler.admin.MetricsHistoryHandler.collectGlobalMetrics(MetricsHistoryHandler.java:498)
at org.apache.solr.handler.admin.MetricsHistoryHandler.collectMetrics(MetricsHistoryHandler.java:371)
at org.apache.solr.handler.admin.MetricsHistoryHandler.lambda$new$0(MetricsHistoryHandler.java:231)

      After some debugging it showed that the error only shows up during the (seemingly) periodic metrics collection on the leader node. The following stack is seen in this cases

       

      While trying to debug it a bit if this can be resolved by some additional settings - for which no solution was found - this method was also called from another location during collection creation where the authentication seems to work just fine

      So something in this chain must enable the correct authentication settings it seems.

      Appart from periodic error logs generally functionality seems to work but most likely something related to the cluster metrics is not fully working.

      Disabling basic authentication or setting ""blockUnknown": false" makes the issue disappear as expected.

       

      Edit how to reproduce:

       

      Hi, already thanks for the fast response. Just tested and yes I can reproduce it even with a completely fresh download and 2 simple commands, using the following steps and files (this test was done on windows 10 with an embedded zookeeper but we observed the same for the rhel6 server installations with an external zookeeper ensemble)

      • Download solr-7.6.0.zip from http://archive.apache.org/dist/lucene/solr/7.6.0/
      • Unpack it somewhere
      • Create a "solr" directory in the unpacked directory and insert the attached solr.xml and zoo.cfg.txt files - need to remove the .txt from the zoo.cfg file wouldn't let me upload otherwise (not 100% sure this even needed but I'm used to it so I decided to stick close to the original case)
      • Finally copy the attached security.json file into the unpacked directory
      • Now open a cmd in the unpacked directory and run 
        bin\solr.cmd start -p 8010 -f -c -s solr -a "-Dhost=localhost -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=1044"
      • Open a second cmd and run 
        bin\solr.cmd zk cp file:security.json zk:/security.json -z localhost:9010

      Soon afterwards the errors happened the first time even without any collection being created. It would also appear right away again after solr server restarts. Here's the full log

      Listening for transport dt_socket at address: 1044
2019-02-05 14:01:25.203 INFO (main) [ ] o.e.j.u.log Logging initialized @677ms to org.eclipse.jetty.util.log.Slf4jLog
2019-02-05 14:01:25.329 INFO (main) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_191-b12
2019-02-05 14:01:25.354 INFO (main) [ ] o.e.j.d.p.ScanningAppProvider Deployment monitor [file:///C:/Users/xhd/Downloads/solr-7.6.0/server/contexts/] at interval 0
2019-02-05 14:01:25.727 INFO (main) [ ] o.e.j.w.StandardDescriptorProcessor NO JSP Support for /solr, did not find org.apache.jasper.servlet.JspServlet
2019-02-05 14:01:25.735 INFO (main) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
2019-02-05 14:01:25.735 INFO (main) [ ] o.e.j.s.session No SessionScavenger set, using defaults
2019-02-05 14:01:25.737 INFO (main) [ ] o.e.j.s.session node0 Scavenging every 660000ms
2019-02-05 14:01:25.769 INFO (main) [ ] o.a.s.u.c.SSLCredentialProviderFactory Processing SSL Credential Provider chain: env;sysprop
2019-02-05 14:01:25.804 INFO (main) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
2019-02-05 14:01:25.808 INFO (main) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache SolrÖ version 7.6.0
2019-02-05 14:01:25.808 INFO (main) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port 8010
2019-02-05 14:01:25.808 INFO (main) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: C:\Users\xhd\Downloads\solr-7.6.0
2019-02-05 14:01:25.809 INFO (main) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2019-02-05T14:01:25.809Z
2019-02-05 14:01:25.826 INFO (main) [ ] o.a.s.c.SolrResourceLoader Using system property solr.solr.home: C:\Users\xhd\Downloads\solr-7.6.0\solr
2019-02-05 14:01:25.831 INFO (main) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from C:\Users\xhd\Downloads\solr-7.6.0\solr\solr.xml
2019-02-05 14:01:25.872 INFO (main) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@72bc6553, but no JMX reporters were configured - adding default JMX reporter.
2019-02-05 14:01:26.533 INFO (main) [ ] o.a.s.c.SolrZkServerProps Reading configuration from: C:\Users\xhd\Downloads\solr-7.6.0\solr\zoo.cfg
2019-02-05 14:01:26.534 INFO (main) [ ] o.a.s.c.SolrZkServer STARTING EMBEDDED STANDALONE ZOOKEEPER SERVER at port 9010
2019-02-05 14:01:27.036 INFO (main) [ ] o.a.s.c.ZkContainer Zookeeper client=localhost:9010
2019-02-05 14:01:27.121 INFO (zkConnectionManagerCallback-4-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
2019-02-05 14:01:27.187 INFO (main) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
2019-02-05 14:01:42.061 INFO (zkCallback-3-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
2019-02-05 14:01:42.077 INFO (main) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader localhost:8010_solr
2019-02-05 14:01:42.083 INFO (main) [ ] o.a.s.c.Overseer Overseer (id=72119892333101056-localhost:8010_solr-n_0000000001) starting
2019-02-05 14:01:42.136 INFO (zkConnectionManagerCallback-11-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
2019-02-05 14:01:42.142 INFO (main) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at localhost:9010 ready
2019-02-05 14:01:42.179 INFO (main) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/localhost:8010_solr
2019-02-05 14:01:42.185 INFO (OverseerStateUpdate-72119892333101056-localhost:8010_solr-n_0000000001) [ ] o.a.s.c.Overseer Starting to work on the main queue : localhost:8010_solr
2019-02-05 14:01:42.194 INFO (zkCallback-10-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
2019-02-05 14:01:42.193 INFO (OverseerStateUpdate-72119892333101056-localhost:8010_solr-n_0000000001) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
2019-02-05 14:01:42.199 INFO (main) [ ] o.a.s.c.CoreContainer Initializing authorization plugin: solr.RuleBasedAuthorizationPlugin
2019-02-05 14:01:42.213 INFO (main) [ ] o.a.s.c.CoreContainer Initializing authentication plugin: solr.BasicAuthPlugin
2019-02-05 14:01:42.222 INFO (main) [ ] o.a.s.c.CoreContainer PKIAuthenticationPlugin is managing internode requests
2019-02-05 14:01:42.312 INFO (main) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
2019-02-05 14:01:42.362 INFO (main) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@72bc6553
2019-02-05 14:01:42.363 INFO (main) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@72bc6553
2019-02-05 14:01:42.369 INFO (main) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@72bc6553
2019-02-05 14:01:42.393 INFO (main) [ ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath C:\Users\xhd\Downloads\solr-7.6.0\solr
2019-02-05 14:01:42.946 INFO (main) [ ] o.e.j.s.h.ContextHandler Started o.e.j.w.WebAppContext@46268f08{/solr,file:///C:/Users/xhd/Downloads/solr-7.6.0/server/solr-webapp/webapp/,AVAILABLE}{C:\Users\xhd\Downloads\solr-7.6.0\server/solr-webapp/webapp}
2019-02-05 14:01:42.956 INFO (main) [ ] o.e.j.s.AbstractConnector Started ServerConnector@4beabeec{HTTP/1.1,[http/1.1]}{0.0.0.0:8010}
2019-02-05 14:01:42.956 INFO (main) [ ] o.e.j.s.Server Started @18432ms
2019-02-05 14:02:48.667 WARN (MetricsHistoryHandler-12-thread-1) [ ] o.a.s.c.s.i.SolrClientNodeStateProvider could not get tags from node localhost:8010_solr
org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://localhost:8010/solr: Expected mime type application/octet-stream but got text/html. <html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8"/>
<title>Error 401 require authentication</title>
</head>
<body><h2>HTTP ERROR 401</h2>
<p>Problem accessing /solr/admin/metrics. Reason:
<pre> require authentication</pre></p>
</body>
</html>

at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:607) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1260) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$ClientSnitchCtx.invoke(SolrClientNodeStateProvider.java:349) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.fetchReplicaMetrics(SolrClientNodeStateProvider.java:195) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider$AutoScalingSnitch.getRemoteInfo(SolrClientNodeStateProvider.java:242) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.common.cloud.rule.ImplicitSnitch.getTags(ImplicitSnitch.java:76) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.fetchTagValues(SolrClientNodeStateProvider.java:138) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.client.solrj.impl.SolrClientNodeStateProvider.getNodeValues(SolrClientNodeStateProvider.java:127) ~[solr-solrj-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:53]
at org.apache.solr.handler.admin.MetricsHistoryHandler.collectGlobalMetrics(MetricsHistoryHandler.java:498) ~[solr-core-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:52]
at org.apache.solr.handler.admin.MetricsHistoryHandler.collectMetrics(MetricsHistoryHandler.java:371) ~[solr-core-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:52]
at org.apache.solr.handler.admin.MetricsHistoryHandler.lambda$new$0(MetricsHistoryHandler.java:231) ~[solr-core-7.6.0.jar:7.6.0 719cde97f84640faa1e3525690d262946571245f - nknize - 2018-12-07 14:47:52]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_191]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_191]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_191]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_191]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

      Hope this helps!

      Attachments

        1. image-2019-02-05-11-29-22-569.png
          41 kB
          Daniel Hofer
        2. image-2019-02-05-11-30-33-948.png
          82 kB
          Daniel Hofer
        3. security.json
          0.4 kB
          Daniel Hofer
        4. solr.xml
          2 kB
          Daniel Hofer
        5. zoo.cfg.txt
          0.5 kB
          Daniel Hofer

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. SOLR-12860 MetricsHistoryHandler does not work with BasicAuth

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            People

              Unassigned Unassigned
              hoferd Daniel Hofer
              Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: