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

          Issue Links

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: