openlibrary
openlibrary copied to clipboard
internetarchive
trending updater throws errors in local environment
Problem
When I run docker compose up on a fully reset environment with the latest master 0e22cc94b79cf252b09427efef2f050e95fb59a9 it fails with the following error.
This seems to be a new error. I went back to master from July 1 and didn't have this issue.
It also happens if I restart just the solr updater container so probably not a race condition.
CC: @cdrini
2025-07-10 10:03:24.353 | Python 3.12.2
2025-07-10 10:03:26.858 |
2025-07-10 10:03:26.868 | total 33308
2025-07-10 10:03:26.868 | drwxr-xr-x 2 openlibrary openlibrary 4096 Jul 10 17:02 .
2025-07-10 10:03:26.868 | drwxr-xr-x 1 root root 4096 Jul 10 17:03 ..
2025-07-10 10:03:26.868 | -rw-r--r-- 1 openlibrary openlibrary 34095104 Jul 10 17:02 osp_totals.db
2025-07-10 10:03:26.868 | -rw-r--r-- 1 openlibrary openlibrary 20 Jul 10 17:02 trending-update.offset
2025-07-10 10:03:26.868 | Starting trending updater
2025-07-10 10:03:26.870 | Starting Solr updater
2025-07-10 10:03:27.705 | Couldn't find statsd_server section in config
2025-07-10 10:03:27.872 | Couldn't find statsd_server section in config
2025-07-10 10:03:28.481 | 0.0 (1): SELECT * FROM thing LIMIT 1
2025-07-10 10:03:28.482 | 0.0 (2): SELECT * FROM thing WHERE key='/type/type'
2025-07-10 10:03:28.482 | 0.0 (3): SELECT * FROM thing WHERE key='/type/type'
2025-07-10 10:03:28.487 | 2025-07-10 17:03:28 [infobase.ol] [INFO] logging initialized
2025-07-10 10:03:28.487 | 2025-07-10 17:03:28 [infobase.ol] [DEBUG] debug
2025-07-10 10:03:28.487 | 2025-07-10 17:03:28 [openlibrary.olbase] [INFO] setting up infobase events for Open Library
2025-07-10 10:03:28.488 | [TRENDING-UPDATER] Monitoring job trending_updater_hourly with crontab: 5 * * * *
2025-07-10 10:03:28.488 | [TRENDING-UPDATER] Monitoring job trending_updater_daily with crontab: 0 0 * * *
2025-07-10 10:03:28.488 | 2025-07-10 17:03:28 [openlibrary.trending-updater] [INFO] Starting trending updater init with offset 2025-07-03T00:00:00
2025-07-10 10:03:28.510 | 2025-07-10 17:03:28 [infobase] [INFO] loading plugin openlibrary.olbase
2025-07-10 10:03:28.514 | 2025-07-10 17:03:28 [infobase.ol] [INFO] logging initialized
2025-07-10 10:03:28.514 | 2025-07-10 17:03:28 [infobase.ol] [DEBUG] debug
2025-07-10 10:03:28.514 | 2025-07-10 17:03:28 [openlibrary.olbase] [INFO] setting up infobase events for Open Library
2025-07-10 10:03:28.514 | Running daily trending for 2025-07-03T00:00:00
2025-07-10 10:03:28.515 | 2025-07-10 17:03:28 [openlibrary.logger] [INFO] solr request: http://solr:8983/solr/openlibrary/export?q=trending_score_hourly_sum%3A%5B1+TO+%2A%5D+OR+trending_score_daily_3%3A%5B1+TO+%2A%5D&fl=key%2Ctrending_score_hourly_sum&sort=key+asc
2025-07-10 10:03:28.580 | 2025-07-10 17:03:28,579 INFO BEGIN solr_updater
2025-07-10 10:03:28.580 | 2025-07-10 17:03:28,579 INFO loading config from conf/openlibrary.yml
2025-07-10 10:03:28.642 | 2025-07-10 17:03:28,641 INFO loading plugin openlibrary.olbase
2025-07-10 10:03:28.651 | 0.0 (1): SELECT * FROM thing LIMIT 1
2025-07-10 10:03:28.652 | 0.0 (2): SELECT * FROM thing WHERE key='/type/type'
2025-07-10 10:03:28.652 | 0.0 (3): SELECT * FROM thing WHERE key='/type/type'
2025-07-10 10:03:28.654 | 2025-07-10 17:03:28 [infobase.ol] [INFO] logging initialized
2025-07-10 10:03:28.654 | 2025-07-10 17:03:28 [infobase.ol] [DEBUG] debug
2025-07-10 10:03:28.654 | 2025-07-10 17:03:28 [openlibrary.olbase] [INFO] setting up infobase events for Open Library
2025-07-10 10:03:28.654 | 2025-07-10 17:03:28 [openlibrary.solr-updater] [ERROR] State file /solr-updater-data/solr-update.offset is not found. Reading log from the beginning of today
2025-07-10 10:03:28.678 | 2025-07-10 17:03:28 [infobase] [INFO] loading plugin openlibrary.olbase
2025-07-10 10:03:28.683 | 2025-07-10 17:03:28 [infobase.ol] [INFO] logging initialized
2025-07-10 10:03:28.683 | 2025-07-10 17:03:28 [infobase.ol] [DEBUG] debug
2025-07-10 10:03:28.683 | 2025-07-10 17:03:28 [openlibrary.olbase] [INFO] setting up infobase events for Open Library
2025-07-10 10:03:28.854 | 2025-07-10 17:03:28 [openlibrary] [INFO] Application init
2025-07-10 10:03:28.854 | 2025-07-10 17:03:28 [openlibrary] [INFO] loading plugin openlibrary
2025-07-10 10:03:29.178 | 2025-07-10 17:03:29 [openlibrary] [INFO] Setting up requests
2025-07-10 10:03:29.178 | 2025-07-10 17:03:29 [openlibrary] [INFO] Setting up proxy
2025-07-10 10:03:29.183 | 2025-07-10 17:03:29 [openlibrary] [INFO] No proxy configuration found
2025-07-10 10:03:29.183 | 2025-07-10 17:03:29 [openlibrary] [INFO] Setting up proxy bypass
2025-07-10 10:03:29.183 | 2025-07-10 17:03:29 [openlibrary] [INFO] No proxy bypass configuration found
2025-07-10 10:03:29.183 | 2025-07-10 17:03:29 [openlibrary] [INFO] Requests set up
2025-07-10 10:03:29.184 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin worksearch
2025-07-10 10:03:29.208 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin inside
2025-07-10 10:03:29.218 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin books
2025-07-10 10:03:29.272 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin admin
2025-07-10 10:03:29.283 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin upstream
2025-07-10 10:03:29.443 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin importapi
2025-07-10 10:03:29.669 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading plugin recaptcha
2025-07-10 10:03:29.691 | 2025-07-10 17:03:29 [openlibrary] [INFO] loading complete.
2025-07-10 10:03:29.842 | 2025-07-10 17:03:29 [infobase] [INFO] loading plugin openlibrary.olbase
2025-07-10 10:03:29.860 | 2025-07-10 17:03:29 [infobase.ol] [INFO] logging initialized
2025-07-10 10:03:29.860 | 2025-07-10 17:03:29 [infobase.ol] [DEBUG] debug
2025-07-10 10:03:29.860 | 2025-07-10 17:03:29 [openlibrary.olbase] [INFO] setting up infobase events for Open Library
2025-07-10 10:03:29.865 | ######################################################################## 100.0%
2025-07-10 10:03:29.865 | ######################################################################## 100.0%
2025-07-10 10:03:30.795 | Traceback (most recent call last):
2025-07-10 10:03:30.795 | File "/openlibrary/scripts/solr_updater/trending_updater.py", line 86, in <module>
2025-07-10 10:03:30.796 | FnToCLI(main).run()
2025-07-10 10:03:30.797 | File "/openlibrary/scripts/solr_builder/solr_builder/fn_to_cli.py", line 87, in run
2025-07-10 10:03:30.800 | return asyncio.run(self.fn(**args_dicts))
2025-07-10 10:03:30.800 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-07-10 10:03:30.800 | File "/usr/local/lib/python3.12/asyncio/runners.py", line 194, in run
2025-07-10 10:03:30.800 | return runner.run(main)
2025-07-10 10:03:30.801 | ^^^^^^^^^^^^^^^^
2025-07-10 10:03:30.801 | File "/usr/local/lib/python3.12/asyncio/runners.py", line 118, in run
2025-07-10 10:03:30.801 | return self._loop.run_until_complete(task)
2025-07-10 10:03:30.801 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-07-10 10:03:30.801 | File "/usr/local/lib/python3.12/asyncio/base_events.py", line 685, in run_until_complete
2025-07-10 10:03:30.802 | return future.result()
2025-07-10 10:03:30.802 | ^^^^^^^^^^^^^^^
2025-07-10 10:03:30.802 | File "/openlibrary/scripts/solr_updater/trending_updater.py", line 71, in main
2025-07-10 10:03:30.804 | trending_updater_init_main(
2025-07-10 10:03:30.804 | File "/openlibrary/scripts/solr_updater/trending_updater_init.py", line 59, in main
2025-07-10 10:03:30.808 | run_daily_update(timestamp=day_dt.isoformat(), dry_run=dry_run)
2025-07-10 10:03:30.810 | File "/openlibrary/scripts/solr_updater/trending_updater_daily.py", line 37, in run_daily_update
2025-07-10 10:03:30.818 | work_data = fetch_works_trending_scores(current_day)
2025-07-10 10:03:30.818 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2025-07-10 10:03:30.818 | File "/openlibrary/scripts/solr_updater/trending_updater_daily.py", line 18, in fetch_works_trending_scores
2025-07-10 10:03:30.828 | assert resp
2025-07-10 10:03:30.828 | AssertionError
Reproducing the bug
- Go to ...
- Do ...
- Expected behavior:
- Actual behavior:
Context
- Browser (Chrome, Safari, Firefox, etc):
- OS (Windows, Mac, etc):
- Logged in (Y/N):
- Environment (prod, dev, local): prod
Breakdown
Requirements Checklist
- [ ]
Related files
Stakeholders
Instructions for Contributors
- Please run these commands to ensure your repository is up to date before creating a new branch to work on this issue and each time after pushing code to Github, because the pre-commit bot may add commits to your PRs upstream.
Whenever I restart solr-updater, I do not see the error.
When running docker compose up, it looks like solr-updater is calling solr before it is ready for requests:
solr-1 | 2025-07-10 18:15:00.615 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.
solr-1 | 2025-07-10 18:15:00.617 WARN (main) [c: s: r: x: t:] o.a.s.c.CoreContainer Not all security plugins configured! authentication=disabled authorization=disabled. Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external. See https://s.apache.org/solrsecurity for more info
solr-1 | 2025-07-10 18:15:00.767 INFO (main) [c: s: r: x: t:] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /var/solr/data
solr-1 | 2025-07-10 18:15:00.768 INFO (main) [c: s: r: x: t:] o.a.s.c.CorePropertiesLocator Cores are: [openlibrary]
solr-1 | 2025-07-10 18:15:00.804 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.c.SolrResourceLoader Added 3 libs to classloader, from paths: [/opt/solr-9.5.0/modules/analysis-extras/lib]
solr-1 | 2025-07-10 18:15:00.829 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.4.0
solr-1 | 2025-07-10 18:15:00.923 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.s.IndexSchema Schema name=openlibrary-config
solr-1 | 2025-07-10 18:15:00.985 WARN (main) [c: s: r: x: t:] o.g.j.m.i.MessagingBinders A class jakarta.activation.DataSource for a default provider MessageBodyWriter<jakarta.activation.DataSource> was not found. The provider is not available.
solr-1 | 2025-07-10 18:15:01.172 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.s.IndexSchema Loaded schema openlibrary-config/1.6 with uniqueid field key
solr-1 | 2025-07-10 18:15:01.172 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.c.CoreContainer Creating SolrCore 'openlibrary' using configuration from instancedir /var/solr/data/openlibrary, trusted=true
solr-1 | 2025-07-10 18:15:01.213 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.c.SolrCore Opening new SolrCore at [/var/solr/data/openlibrary], dataDir=[/var/solr/data/openlibrary/data/]
solr-1 | 2025-07-10 18:15:01.223 WARN (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.D.s.CircuitBreakerManager Solr loaded a deprecated plugin/analysis class [solr.CircuitBreakerManager]. Please consult documentation how to replace it accordingly.
solr-1 | 2025-07-10 18:15:01.224 WARN (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.c.CircuitBreakerManager CircuitBreakerManager is deprecated. Use individual Circuit Breakers instead
solr-1 | 2025-07-10 18:15:01.225 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.c.CircuitBreakerRegistry Registered circuit breaker CircuitBreakerManager for request type(s) QUERY
solr-1 | 2025-07-10 18:15:01.315 INFO (main) [c: s: r: x: t:] o.a.s.j.SolrRequestAuthorizer Creating a new SolrRequestAuthorizer
solr-1 | 2025-07-10 18:15:01.461 INFO (main) [c: s: r: x: t:] o.e.j.s.h.ContextHandler Started o.e.j.w.WebAppContext@21362712{solr-jetty-context.xml,/solr,file:///opt/solr-9.5.0/server/solr-webapp/webapp/,AVAILABLE}{/opt/solr-9.5.0/server/solr-webapp/webapp}
solr-1 | 2025-07-10 18:15:01.469 INFO (main) [c: s: r: x: t:] o.e.j.s.RequestLogWriter Opened /var/solr/logs/2025_07_10.request.log
solr-1 | 2025-07-10 18:15:01.476 INFO (main) [c: s: r: x: t:] o.e.j.s.AbstractConnector Started ServerConnector@666b83a4{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8983}
solr-1 | 2025-07-10 18:15:01.478 INFO (main) [c: s: r: x: t:] o.e.j.s.Server Started Server@3e8f7922{STARTING}[10.0.19,sto=0] @4192ms
solr-updater-1 | Traceback (most recent call last):
solr-updater-1 | File "/openlibrary/scripts/solr_updater/trending_updater.py", line 86, in <module>
solr-updater-1 | FnToCLI(main).run()
solr-updater-1 | File "/openlibrary/scripts/solr_builder/solr_builder/fn_to_cli.py", line 87, in run
solr-updater-1 | return asyncio.run(self.fn(**args_dicts))
solr-updater-1 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
solr-updater-1 | File "/usr/local/lib/python3.12/asyncio/runners.py", line 194, in run
solr-updater-1 | return runner.run(main)
solr-updater-1 | ^^^^^^^^^^^^^^^^
solr-updater-1 | File "/usr/local/lib/python3.12/asyncio/runners.py", line 118, in run
solr-updater-1 | return self._loop.run_until_complete(task)
solr-updater-1 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
solr-updater-1 | File "/usr/local/lib/python3.12/asyncio/base_events.py", line 685, in run_until_complete
solr-updater-1 | return future.result()
solr-updater-1 | ^^^^^^^^^^^^^^^
solr-updater-1 | File "/openlibrary/scripts/solr_updater/trending_updater.py", line 71, in main
solr-updater-1 | trending_updater_init_main(
solr-updater-1 | File "/openlibrary/scripts/solr_updater/trending_updater_init.py", line 59, in main
solr-updater-1 | run_daily_update(timestamp=day_dt.isoformat(), dry_run=dry_run)
solr-updater-1 | File "/openlibrary/scripts/solr_updater/trending_updater_daily.py", line 37, in run_daily_update
solr-updater-1 | work_data = fetch_works_trending_scores(current_day)
solr-updater-1 | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
solr-updater-1 | File "/openlibrary/scripts/solr_updater/trending_updater_daily.py", line 18, in fetch_works_trending_scores
solr-updater-1 | assert resp
solr-updater-1 | AssertionError
solr-1 | 2025-07-10 18:15:01.735 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.j.SolrRequestAuthorizer Creating a new SolrRequestAuthorizer
solr-1 | 2025-07-10 18:15:01.750 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
solr-1 | 2025-07-10 18:15:01.750 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
solr-1 | 2025-07-10 18:15:01.755 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.CommitTracker Hard AutoCommit: if uncommitted for 120000ms;
solr-1 | 2025-07-10 18:15:01.756 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.u.CommitTracker Soft AutoCommit: if uncommitted for 60000ms;
solr-1 | 2025-07-10 18:15:01.811 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /var/solr/data/openlibrary/conf
solr-1 | 2025-07-10 18:15:01.824 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.s.DirectSolrSpellChecker init: {accuracy=0.5, maxQueryFrequency=0.01, maxEdits=2, minPrefix=1, maxInspections=5, minQueryLength=4, name=default, field=text, classname=solr.DirectSolrSpellChecker, distanceMeasure=internal}
solr-1 | 2025-07-10 18:15:01.833 INFO (coreLoadExecutor-11-thread-1) [c: s: r: x:openlibrary t:] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
solr-1 | 2025-07-10 18:15:01.835 INFO (searcherExecutor-13-thread-1-processing-openlibrary) [c: s: r: x:openlibrary t:] o.a.s.c.QuerySenderListener QuerySenderListener done.
solr-1 | 2025-07-10 18:15:01.836 INFO (searcherExecutor-13-thread-1-processing-openlibrary) [c: s: r: x:openlibrary t:] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
solr-1 | 2025-07-10 18:15:01.841 INFO (searcherExecutor-13-thread-1-processing-openlibrary) [c: s: r: x:openlibrary t:] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
Note I verified and although this throws errors, it does not actually interfere with solr-updater, so dropping the priority.
It looks like running docker compose down -v && docker compose up multiple times didn’t reproduce the failure — likely because Solr happened to start up quickly. This supports the idea that the bug is caused by an intermittent race condition: the updater starts querying Solr before the Solr container is fully ready.
To address this, I propose adding a wait_for_solr() helper that performs retry-based polling until Solr responds successfully (e.g., hitting /solr/admin/ping). This will force the updater to wait for Solr's readiness rather than relying on container startup timing.
If this approach makes sense, I can put together a draft PR.
@cdrini
