Troubleshooting inconsistencies with Solr 9 availability in Github Actions

[brockfanning]

Hi all,

I am troubleshooting some issues we're experiencing in Github Actions, and I'm very ignorant of both Docker and Solr. We're seeing some strange inconsistency in the availability of Solr, when run inside Github Actions. I was wondering if anyone may have run into this problem, and/or if anyone has any tips on where to investigate further, based on the behavior described below.

To illustrate, I added this step in our Github Actions workflow (running a sapi-c followed by a sapi-i on one of our Search API indexes -- "content" -- 10 times in a row):

      - name: Check health of Solr
        run: |
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev logs -s solr

When this runs, the first few commands work as expected, but then Solr starts giving a "code 7" response, and then later a "code 28" response:

 [success] Content was successfully cleared.
 [success] The index Content is up to date.
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 7, body: , message: Solr HTTP error: HTTP request failed, Failed to connect to solr port 8983 after 0 ms: Couldn't connect to server (7)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 7, body: , message: Solr HTTP error: HTTP request failed, Failed to connect to solr port 8983 after 0 ms: Couldn't connect to server (7)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 7, body: , message: Solr HTTP error: HTTP request failed, Failed to connect to solr port 8983 after 2 ms: Couldn't connect to server (7)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 7, body: , message: Solr HTTP error: HTTP request failed, Failed to connect to solr port 8983 after 0 ms: Couldn't connect to server (7)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 28, body: , message: Solr HTTP error: HTTP request failed, Operation timed out after 5000 milliseconds with 0 bytes received (28)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.
Error: ]  Drupal\search_api_solr\SearchApiSolrException while deleting items of index Content from server Local ddev Solr server: Solr endpoint http://solr:8983/ unreachable or returned unexpected response code (code: 28, body: , message: Solr HTTP error: HTTP request failed, Operation timed out after 5000 milliseconds with 0 bytes received (28)). in Drupal\search_api_solr\SolrConnector\SolrConnectorPluginBase->handleHttpException() (line 1152 of /var/www/html/docroot/modules/contrib/search_api_solr/src/SolrConnector/SolrConnectorPluginBase.php). 
 [success] Content was successfully cleared.
 [success] The index Content is up to date.

In case it's helpful, here are a few more files:

.ddev/config.yaml:

name: foo
type: drupal10
docroot: docroot
php_version: "8.3"
webserver_type: nginx-fpm
router_http_port: "80"
router_https_port: "443"
xdebug_enabled: false
additional_hostnames: []
additional_fqdns: []
database:
    type: mariadb
    version: "10.3"
performance_mode: none
use_dns_when_possible: true
composer_version: ""
web_environment: []
nodejs_version: "20"

.ddev/docker-compose.solr.yaml:

#ddev-generated

services:
  solr:
    image: solr:9.6
    container_name: ddev-${DDEV_SITENAME}-solr
    expose:
      - 8983
    labels:
      com.ddev.site-name: ${DDEV_SITENAME}
      com.ddev.approot: ${DDEV_APPROOT}
    environment:
      SOLR_HOST: ddev-${DDEV_SITENAME}-solr
      SOLR_PORT: 8983
      # The pre-trained OpenNLP models require a much bigger buffer.
      SOLR_OPTS: -Djute.maxbuffer=50000000
      #SOLR_HEAP: 1g
      SOLR_AUTH_TYPE: basic
      SOLR_AUTHENTICATION_OPTS: -Dbasicauth=solr:SolrRocks
      VIRTUAL_HOST: ${DDEV_HOSTNAME}
      HTTP_EXPOSE: 8983:8983
      #HTTPS_EXPOSE: 8943:8983
    volumes:
      - .:/mnt/ddev_config
      - ./solr/lib:/opt/solr/modules/ddev/lib
      - solr:/var/solr
    command: bash -c "set -eu;
      docker-entrypoint.sh solr start -c -Dlog4j.configurationFile=/opt/solr/server/resources/log4j2-console.xml;
      solr zk cp file:/mnt/ddev_config/solr/security.json zk:/security.json -z localhost:9983;
      cd /mnt/ddev_config/solr/configsets;
      for dir in */; do
        dir=$${dir%/};
        if [[ \"$$dir\" != \"*\" ]]; then
          echo \"uploading configset $$dir\";
          solr zk upconfig -n \"$$dir\" -d \"$$dir\" -z localhost:9983;
          echo \"creating collection $$dir\";
          solr create -c \"$$dir\" -n \"$$dir\" -shards 1 -replicationFactor 1 || true;
        fi;
      done;
      cd -;
      solr stop > /dev/null;
      exec solr-foreground -c -Dlog4j.configurationFile=/opt/solr/server/resources/log4j2.xml;
      "
    healthcheck:
      test: ["CMD-SHELL", "curl --fail -s localhost:8983/solr/"]

  web:
    links:
      - solr:solr

volumes:
  solr:

.github/workflows/test.yml (our Github Actions configuration):

name: Test PRs

on:
  pull_request:
    types:
      - labeled
      - opened
      - synchronize
      - reopened
jobs:
  test:
    runs-on: ubuntu-latest
    steps:
      - uses: actions/checkout@v4
      - uses: actions/setup-node@v4
        with:
          node-version: '20'
      - name: Setup PHP
        uses: shivammathur/setup-php@v2
        with:
          php-version: '8.3'
          extensions: :php-psr
      - name: Set up ddev
        uses: ddev/github-action-setup-ddev@v1
      - name: Install dependencies
        run: |
          ddev composer install
      - name: Site install
        run: ddev drush site:install --existing-config
      - name: Update Database
        run: |
          ddev drush updatedb -y
      - name: Import config
        run: |
          ddev drush cim -y
      - name: Create solr collection
        run: |
          ddev drush --numShards=1 search-api-solr:upload-configset foo
      - name: clear cache
        run: |
          ddev drush cr
      - name: Build front-end
        run: |
          ddev blt --no-interaction source:build:frontend
      - name: Check health of Solr
        run: |
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev drush sapi-c content
          ddev drush sapi-i content
          ddev logs -s solr
      - name: Run tests
        run: |
          ddev exec vendor/bin/behat --config=tests/behat/behat.yml --format=progress

For reference, here is the output of a ddev logs -s solr after the above errors have happened:

Java 17 detected. Enabled workaround for SOLR-16463
Waiting up to 180 seconds to see Solr running on port 8983 [|]  ������ [/]  ������ [-]  ������ [\]  ������ [|]  ������ [/]  ������ [-]  ������ [\]  ������ [|]  ������ [/]  ������
Started Solr server on port 8983 (pid=68). Happy searching!
WARN  - 2025-04-01 15:59:35.212; org.apache.solr.common.cloud.SolrZkClient; Using default ZkCredentialsInjector. ZkCredentialsInjector is not secure, it creates an empty list of credentials which leads to 'OPEN_ACL_UNSAFE' ACLs to Zookeeper nodes
WARN  - 2025-04-01 15:59:37.691; org.apache.solr.common.cloud.SolrZkClient; Using default ZkACLProvider. DefaultZkACLProvider is not secure, it creates 'OPEN_ACL_UNSAFE' ACLs to Zookeeper nodes
 [-]  ������    ����Copying from 'file:/mnt/ddev_config/solr/security.json' to 'zk:/security.json'. ZooKeeper at localhost:9983
/opt/solr-9.6.1
Starting Solr
Java 17 detected. Enabled workaround for SOLR-16463
Warning: [0.002s][warning][pagesize] UseLargePages disabled, no large pages configured and available on the system.
CompileCommand: exclude com/github/benmanes/caffeine/cache/BoundedLocalCache.put bool exclude = true
WARNING: A command line option has enabled the Security Manager
WARNING: The Security Manager is deprecated and will be removed in a future release
2025-04-01 16:02:53.724 INFO  (main) [c: s: r: x: t:] o.e.j.s.Server jetty-10.0.20; built: 2024-01-[29](https://github.com/foo/bar/actions/runs/...)T20:46:45.278Z; git: 3a745c71c23682146f262b99f4ddc4c1bc416[30](https://github.com/foo/bar/...)c; jvm 17.0.13+11
2025-04-01 16:02:54.462 WARN  (main) [c: s: r: x: t:] o.e.j.u.DeprecationWarning Using @Deprecated Class org.eclipse.jetty.servlet.listener.ELContextCleaner
2025-04-01 16:02:54.509 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
2025-04-01 16:02:54.521 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider  ___      _       Welcome to Apache Solr™ version 9.6.1
2025-04-01 16:02:54.522 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider / __| ___| |_ _   Starting in cloud mode on port 8983
2025-04-01 16:02:54.522 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider \__ \/ _ \ | '_|  Install dir: /opt/solr-9.6.1
2025-04-01 16:02:54.523 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider |___/\___/_|_|    Start time: 2025-04-01T16:02:54.523012526Z
2025-04-01 16:02:54.529 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider Solr started with "-XX:+CrashOnOutOfMemoryError" that will crash on any OutOfMemoryError exception. The cause of the OOME will be logged in the crash file at the following path: /var/solr/logs/jvm_crash_1544.log
2025-04-01 16:02:54.564 INFO  (main) [c: s: r: x: t:] o.a.s.s.CoreContainerProvider Solr Home: /var/solr/data (source: system property: solr.solr.home)
2025-04-01 16:02:54.590 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrXmlConfig solr.xml not found in SOLR_HOME, using built-in default
2025-04-01 16:02:54.591 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrXmlConfig Loading solr.xml from /opt/solr-9.6.1/server/solr/solr.xml
2025-04-01 16:02:54.662 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrResourceLoader Added 1 libs to classloader, from paths: [/opt/solr-9.6.1/lib]
2025-04-01 16:02:55.679 INFO  (main) [c: s: r: x: t:] o.a.s.u.t.SimplePropagator Always-on trace id generation enabled.
2025-04-01 16:02:56.108 WARN  (main) [c: s: r: x: t:] o.a.s.u.StartupLoggingUtils Jetty request logging enabled. Will retain logs for last 3 days. See chapter "Configuring Logging" in reference guide for how to configure.
2025-04-01 16:02:56.116 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrZkServer Zookeeper configuration not found in /var/solr/data, using built-in default
2025-04-01 16:02:56.116 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrZkServerProps Reading configuration from: /opt/solr-9.6.1/server/solr/zoo.cfg
2025-04-01 16:02:56.121 INFO  (main) [c: s: r: x: t:] o.a.s.c.SolrZkServer STARTING EMBEDDED ENSEMBLE ZOOKEEPER SERVER at port 9983, listening on host 0.0.0.0
2025-04-01 16:02:56.121 WARN  (main) [c: s: r: x: t:] o.a.s.c.SolrZkServer Embedded Zookeeper is not recommended in production environments. See Reference Guide for details.
2025-04-01 16:02:56.171 WARN  (embeddedZkServer) [c: s: r: x: t:] o.a.z.s.ServerCnxnFactory maxCnxns is not configured, using default value 0.
2025-04-01 16:02:56.624 INFO  (main) [c: s: r: x: t:] o.a.s.c.ZkContainer Zookeeper client=172.19.0.3:9983
2025-04-01 16:02:56.6[39](https://github.com/foo/bar/...) INFO  (main) [c: s: r: x: t:] o.a.s.c.DistributedClusterStateUpdater Creating DistributedClusterStateUpdater with useDistributedStateUpdate=false. Solr will be using Overseer based cluster state updates.
2025-04-01 16:02:56.670 INFO  (main) [c: s: r: x: t:] o.a.s.c.c.ConnectionManager Waiting up to 15000ms for client to connect to ZooKeeper
2025-04-01 16:02:56.686 INFO  (zkConnectionManagerCallback-10-thread-1) [c: s: r: x: t:] o.a.s.c.c.ConnectionManager zkClient has connected
2025-04-01 16:02:56.687 INFO  (main) [c: s: r: x: t:] o.a.s.c.c.ConnectionManager Client is connected to ZooKeeper
2025-04-01 16:02:56.757 WARN  (main) [c: s: r: x: t:] o.a.s.c.ZkController Contents of zookeeper /security.json are world-readable; consider setting up ACLs as described in https://solr.apache.org/guide/solr/latest/deployment-guide/zookeeper-access-control.html
2025-04-01 16:02:56.767 INFO  (main) [c: s: r: x: t:] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)

Also possibly relevant in case it is a problem in our application, here are some Search API overrides or our "foo" server that we have in our settings.php, specifically for the DDEV (local) environment:

  $config['search_api.server.foo']['name'] = 'Local ddev Solr server';
  $config['search_api.server.foo']['backend'] = 'search_api_solr';
  $config['search_api.server.foo']['backend_config']['connector'] = 'solr_cloud_basic_auth';
  $config['search_api.server.foo']['dependencies']['config'] = [
    'search_api_solr.solr_cache.cache_document_default_9_0_0',
    'search_api_solr.solr_cache.cache_fieldvalue_default_9_0_0',
    'search_api_solr.solr_cache.cache_filter_default_9_0_0',
    'search_api_solr.solr_cache.cache_persegfilter_default_9_0_0',
    'search_api_solr.solr_cache.cache_queryresult_default_9_0_0',
    'search_api_solr.solr_field_type.text_edge_und_7_0_0',
    'search_api_solr.solr_field_type.text_edgestring_und_6_0_0',
    'search_api_solr.solr_field_type.text_en_7_0_0',
    'search_api_solr.solr_field_type.text_ngram_und_7_0_0',
    'search_api_solr.solr_field_type.text_ngramstring_und_6_0_0',
    'search_api_solr.solr_field_type.text_phonetic_en_7_0_0',
    'search_api_solr.solr_field_type.text_phonetic_uk_7_0_0',
    'search_api_solr.solr_field_type.text_phonetic_und_7_0_0',
    'search_api_solr.solr_field_type.text_string_und_6_0_0',
    'search_api_solr.solr_field_type.text_uk_8_2_0',
    'search_api_solr.solr_field_type.text_und_7_0_0',
    'search_api_solr.solr_request_dispatcher.request_dispatcher_httpcachingnever_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_autocomplete_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_extract_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_mlt_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_select_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_spell_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_suggest_default_7_0_0',
    'search_api_solr.solr_request_handler.request_handler_tvrh_default_7_0_0',
  ];
  $config['search_api.server.foo']['backend_config']['disabled_request_handlers'] = [
    'request_handler_elevate_default_7_0_0',
    'request_handler_replicationmaster_default_7_0_0',
    'request_handler_replicationslave_default_7_0_0',
  ];
  $config['search_api.server.foo']['backend_config']['disabled_request_dispatchers'] = [
    'request_dispatcher_httpcaching_default_7_0_0',
  ];
  $config['search_api.server.foo']['backend_config']['connector_config'] = [
    'scheme' => 'http',
    'host' => 'solr',
    'port' => '8983',
    'path' => '/',
    'core' => 'drupal',
    'timeout' => 5,
    'index_timeout' => 5,
    'optimize_timeout' => 10,
    'finalize_timeout' => 30,
    'skip_schema_check' => FALSE,
    'solr_version' => '',
    'http_method' => 'AUTO',
    'commit_within' => 1000,
    'jmx' => FALSE,
    'jts' => FALSE,
    'solr_install_dir' => '',
    'checkpoints_collection' => '',
    'stats_cache' => 'org.apache.solr.search.stats.LRUStatsCache',
    'distrib' => TRUE,
    'context' => 'solr',
    'username' => 'solr',
    'password' => 'SolrRocks',
  ];

[rfay]

I think you're going to have to use tmate to sort this out with manual testing in github actions environment. https://github.com/mxschmitt/action-tmate

When you get that set up (as all add-ons have it, including this one), you can try to reproduce. It looks to me like maybe you're crashing the solr server, or over-stressing the github container.

[brockfanning]

Thanks @rfay! In trying that out, I actually stumbled across a workaround: downgrading to Solr 8 (specifically, 8.11). Given that this solves my problem, I'll just stop here.

I've updated the title of this issue accordingly, and I'll go ahead and close this. But feel free to re-open if you think this needs more discussion.