Somewhat confusing bugs during live indexing

[ashprice]

v-2025-03-24.0-dirty

This reports dirty because of only three changes:

1. I modified the default cron instead of the one under local.
2. I tried to set SOLR_ULIMIT_CHECKS to 65000 in docker-compose.yml during troubleshooting this issue.
3. MUSICBRAINZ_SERVER_PROCESSES=${MUSICBRAINZ_SERVER_PROCESSES:-24} I don't know if this actually improves performance in any way.

Docker compose version: 2.34.0
Docker Client/Server: 28.0.4/28.0.4

Issue

During live indexing/replication I receive the following errors:

Died at ./admin/replication/LoadReplicationChanges line 228.
Sat Mar 29 15:30:01 2025 : Downloading https://metabrainz.org/api/musicbrainz/replication-175725-v2.tar.bz2 to /tmp/replication-175725-v2.tar.bz2
500 Can't connect to metabrainz.org:443 (Temporary failure in name resolution)
Content-Type: text/plain
Client-Date: Sat, 29 Mar 2025 15:30:01 GMT
Client-Warning: Internal response

Can't connect to metabrainz.org:443 (Temporary failure in name resolution)

Temporary failure in name resolution at /musicbrainz-server/local/lib/perl5/LWP/Protocol/http.pm line 49.

These issues started on Wednesday. Here is what I have done to troubleshoot:

1. Checked I can poll most recent packages and download them from the server with my API key using curl.
2. Starting and stopping services, recreating them.
3. Full database and search index rebuild. This worked! Replication proceeded as expected. Until I restarted my machine - then the issue has started to recur. The replication packet mentioned (175725) is completely different!

Indexer refuses to run:

indexer-1      | 2025-03-29 15:40:26,977: HTTP Error 500: Server Error
indexer-1      | Traceback (most recent call last):
indexer-1      |   File "/usr/local/lib/python2.7/site-packages/retrying.py", line 200, in call
indexer-1      |     attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
indexer-1      |   File "sir/amqp/handler.py", line 444, in _watch_impl
indexer-1      |     handler = Handler(entities)
indexer-1      |   File "sir/amqp/handler.py", line 148, in __init__
indexer-1      |     self.cores[core_name] = solr_connection(core_name)
indexer-1      |   File "sir/util.py", line 88, in solr_connection
indexer-1      |     urllib2.urlopen(ping_uri)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 154, in urlopen
indexer-1      |     return opener.open(url, data, timeout)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 435, in open
indexer-1      |     response = meth(req, response)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 548, in http_response
indexer-1      |     'http', request, response, code, msg, hdrs)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 473, in error
indexer-1      |     return self._call_chain(*args)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 407, in _call_chain
indexer-1      |     result = func(*args)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 556, in http_error_default
indexer-1      |     raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
indexer-1      | HTTPError: HTTP Error 500: Server Error
indexer-1      | 2025-03-29 15:40:26,978: Connecting to Solr failed: HTTP Error 500: Server Error
indexer-1      | 2025-03-29 16:09:11,449: Retrying...
indexer-1      | 2025-03-29 16:09:11,450: HTTP Error 500: Server Error
indexer-1      | Traceback (most recent call last):
indexer-1      |   File "/usr/local/lib/python2.7/site-packages/retrying.py", line 200, in call
indexer-1      |     attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
indexer-1      |   File "sir/amqp/handler.py", line 444, in _watch_impl
indexer-1      |     handler = Handler(entities)
indexer-1      |   File "sir/amqp/handler.py", line 148, in __init__
indexer-1      |     self.cores[core_name] = solr_connection(core_name)
indexer-1      |   File "sir/util.py", line 88, in solr_connection
indexer-1      |     urllib2.urlopen(ping_uri)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 154, in urlopen
indexer-1      |     return opener.open(url, data, timeout)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 435, in open
indexer-1      |     response = meth(req, response)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 548, in http_response
indexer-1      |     'http', request, response, code, msg, hdrs)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 473, in error
indexer-1      |     return self._call_chain(*args)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 407, in _call_chain
indexer-1      |     result = func(*args)
indexer-1      |   File "/usr/local/lib/python2.7/urllib2.py", line 556, in http_error_default
indexer-1      |     raise HTTPError(req.get_full_url(), code, msg, hdrs, fp)
indexer-1      | HTTPError: HTTP Error 500: Server Error
indexer-1      | 2025-03-29 16:09:11,451: Connecting to Solr failed: HTTP Error 500: Server Error

Search is running into what looks to me like read/write issues:

search-1  | 2025-03-29 16:09:11.449 ERROR (qtp802600647-56) [   ] o.a.s.s.HttpSolrCall null:org.apache.solr.core.SolrCoreInitializationException: SolrCore 'recording' is not available due to init failure: Error opening new searcher
search-1  | 	at org.apache.solr.core.CoreContainer.getCore(CoreContainer.java:1653)
search-1  | 	at org.apache.solr.servlet.HttpSolrCall.init(HttpSolrCall.java:249)
search-1  | 	at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:469)
search-1  | 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:395)
search-1  | 	at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:341)
search-1  | 	at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)
search-1  | 	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
search-1  | 	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
search-1  | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
search-1  | 	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
search-1  | 	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
search-1  | 	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
search-1  | 	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
search-1  | 	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
search-1  | 	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
search-1  | 	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220)
search-1  | 	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
search-1  | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
search-1  | 	at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)
search-1  | 	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
search-1  | 	at org.eclipse.jetty.server.Server.handle(Server.java:502)
search-1  | 	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
search-1  | 	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
search-1  | 	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
search-1  | 	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
search-1  | 	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
search-1  | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
search-1  | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
search-1  | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
search-1  | 	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
search-1  | 	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
search-1  | 	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
search-1  | 	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
search-1  | 	at java.lang.Thread.run(Thread.java:748)
search-1  | Caused by: org.apache.solr.common.SolrException: Error opening new searcher
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:1048)
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:874)
search-1  | 	at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1187)
search-1  | 	at org.apache.solr.core.CoreContainer.getCore(CoreContainer.java:1673)
search-1  | 	... 38 more
search-1  | Caused by: org.apache.solr.common.SolrException: Error opening new searcher
search-1  | 	at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:2137)
search-1  | 	at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2257)
search-1  | 	at org.apache.solr.core.SolrCore.initSearcher(SolrCore.java:1106)
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:993)
search-1  | 	... 41 more
search-1  | Caused by: org.apache.lucene.index.CorruptIndexException: Unexpected file read error while reading index. (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/opt/solr/server/solr/data/recording/index/segments_lh4x")))
search-1  | 	at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:293)
search-1  | 	at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:845)
search-1  | 	at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:124)
search-1  | 	at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:97)
search-1  | 	at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:257)
search-1  | 	at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:131)
search-1  | 	at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:2098)
search-1  | 	... 44 more
search-1  | Caused by: java.nio.file.NoSuchFileException: /opt/solr/server/solr/data/recording/index/_22auo.si
search-1  | 	at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
search-1  | 	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
search-1  | 	at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
search-1  | 	at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:177)
search-1  | 	at java.nio.channels.FileChannel.open(FileChannel.java:287)
search-1  | 	at java.nio.channels.FileChannel.open(FileChannel.java:335)
search-1  | 	at org.apache.lucene.store.MMapDirectory.openInput(MMapDirectory.java:238)
search-1  | 	at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:157)
search-1  | 	at org.apache.lucene.codecs.lucene70.Lucene70SegmentInfoFormat.read(Lucene70SegmentInfoFormat.java:91)
search-1  | 	at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:361)
search-1  | 	at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:291)

and

search-1  | 2025-03-29 15:40:25.723 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
search-1  | 2025-03-29 15:40:25.724 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=/opt/solr/server/solr/data/recording defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
search-1  | 2025-03-29 15:40:25.724 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.u.CommitTracker Hard AutoCommit: if uncommitted for 60000ms; 
search-1  | 2025-03-29 15:40:25.724 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.u.CommitTracker Soft AutoCommit: if uncommitted for 10000ms; 
search-1  | 2025-03-29 15:40:25.725 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.c.SolrCore [recording]  CLOSING SolrCore org.apache.solr.core.SolrCore@25309e2d
search-1  | 2025-03-29 15:40:25.725 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.recording, tag=25309e2d
search-1  | 2025-03-29 15:40:25.726 INFO  (coreLoadExecutor-9-thread-1) [   ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@68279487: rootName = null, domain = solr.core.recording, service url = null, agent id = null] for registry solr.core.recording / com.codahale.metrics.MetricRegistry@67f02055
search-1  | 2025-03-29 15:40:25.736 ERROR (coreContainerWorkExecutor-2-thread-1) [   ] o.a.s.c.CoreContainer Error waiting for SolrCore to be loaded on startup
search-1  | org.apache.solr.common.SolrException: Unable to create core [recording]

This is the first output of an error I see after a session is started:

search-1  | 2025-03-29 16:20:49.889 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=/opt/solr/server/solr/data/recording defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
search-1  | 2025-03-29 16:20:49.890 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.u.CommitTracker Hard AutoCommit: if uncommitted for 60000ms; 
search-1  | 2025-03-29 16:20:49.890 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.u.CommitTracker Soft AutoCommit: if uncommitted for 10000ms; 
search-1  | 2025-03-29 16:20:49.891 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.c.SolrCore [recording]  CLOSING SolrCore org.apache.solr.core.SolrCore@3c5c8d1f
search-1  | 2025-03-29 16:20:49.892 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.recording, tag=3c5c8d1f
search-1  | 2025-03-29 16:20:49.892 INFO  (coreLoadExecutor-9-thread-2) [   ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@3a7ec5d0: rootName = null, domain = solr.core.recording, service url = null, agent id = null] for registry solr.core.recording / com.codahale.metrics.MetricRegistry@12345f93
search-1  | 2025-03-29 16:20:49.900 ERROR (coreContainerWorkExecutor-2-thread-1) [   ] o.a.s.c.CoreContainer Error waiting for SolrCore to be loaded on startup
search-1  | org.apache.solr.common.SolrException: Unable to create core [recording]
search-1  | 	at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1208) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.CoreContainer.lambda$load$13(CoreContainer.java:699) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197) ~[metrics-core-3.2.6.jar:3.2.6]
search-1  | 	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_212]
search-1  | 	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:209) ~[solr-solrj-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:52]
search-1  | 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
search-1  | 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
search-1  | 	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
search-1  | Caused by: org.apache.solr.common.SolrException: Error opening new searcher
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:1048) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:874) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1187) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	... 7 more
search-1  | Caused by: org.apache.solr.common.SolrException: Error opening new searcher
search-1  | 	at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:2137) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2257) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.SolrCore.initSearcher(SolrCore.java:1106) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:993) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.SolrCore.<init>(SolrCore.java:874) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1187) ~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
search-1  | 	... 7 more
search-1  | Caused by: org.apache.lucene.index.CorruptIndexException: Unexpected file read error while reading index. (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/opt/solr/server/solr/data/recording/index/segments_lh4x")))

It does complain about SOLR_ULIMIT_CHECKS though, presumably I have declared it in the wrong place.

Any guidance on further troubleshooting would be much appreciated!

[ashprice]

The issue in the original title has been resolved. That is, replication now works, following another rebuild of the database. Initially I got the same errors. However, for some reason, they went away, and now the connection is to musicbrainz api is opened without issue.

I have another issue, however, and I'm hesitant to close this and open another one, because it seems it may be related.

First of all, the packets are now successfully downloaded and processed. docker-compose exec musicbrainz /usr/bin/tail -f mirror.log:

un Apr 13 06:14:53 2025 : load dbmirror2.pending_keys
dbmirror2.pending_keys                75 100%    140449 0.00 sec
Sun Apr 13 06:14:53 2025 : load dbmirror2.pending_ts
dbmirror2.pending_ts                1037 100%    335164 0.00 sec
Sun Apr 13 06:14:53 2025 : import finished
Loaded 3 tables (8956 rows) in 0 seconds
Sun Apr 13 06:14:53 2025 : Removing /tmp/loadrep-Vuh0Q9
Sun Apr 13 06:14:53 2025 : Processing replication changes
     XIDs     Stmts est%  XIDs/sec  Stmt/sec
      610      4148  52%        32       224WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4
      802      5421  69%        31       212WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4
     1037      7844 100%        30       232 33.77 sec
Sun Apr 13 06:15:27 2025 : Summary of changes applied:
Inserts  Updates  Deletes  Table
     69      173        1  cover_art_archive.cover_art
     73        0        1  cover_art_archive.cover_art_type
      0        2        0  event_art_archive.event_art
     21        0        0  musicbrainz.annotation

However, as you can see, there are a number of warnings relating to amqp:

WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4

These seem to be similar as in issue #142 . Looking at the mq logs:

mq-1  | =WARNING REPORT==== 13-Apr-2025::06:16:23 ===
mq-1  | closing AMQP connection <0.1859.0> (172.18.0.5:33868 -> 172.18.0.3:5672, vhost: '/search-index-rebuilder', user: 'sir'):
mq-1  | client unexpectedly closed TCP connection
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:24 ===
mq-1  | accepting AMQP connection <0.1878.0> (172.18.0.5:54266 -> 172.18.0.3:5672)
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:24 ===
mq-1  | connection <0.1878.0> (172.18.0.5:54266 -> 172.18.0.3:5672): user 'sir' authenticated and granted access to vhost '/search-index-rebuilder'
mq-1  | 
mq-1  | =WARNING REPORT==== 13-Apr-2025::06:16:45 ===
mq-1  | closing AMQP connection <0.1878.0> (172.18.0.5:54266 -> 172.18.0.3:5672, vhost: '/search-index-rebuilder', user: 'sir'):
mq-1  | client unexpectedly closed TCP connection
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:46 ===
mq-1  | accepting AMQP connection <0.1895.0> (172.18.0.5:53898 -> 172.18.0.3:5672)
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:46 ===
mq-1  | connection <0.1895.0> (172.18.0.5:53898 -> 172.18.0.3:5672): user 'sir' authenticated and granted access to vhost '/search-index-rebuilder'
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:56 ===
mq-1  | closing AMQP connection <0.1895.0> (172.18.0.5:53898 -> 172.18.0.3:5672, vhost: '/search-index-rebuilder', user: 'sir')
mq-1  | 
mq-1  | =INFO REPORT==== 13-Apr-2025::06:16:56 ===
mq-1  | accepting AMQP connection <0.1912.0> (172.18.0.5:40260 -> 172.18.0.3:5672)
mq-1  | 

As mentioned in the linked issue, the problem is the indexer is not running. But the question on my mind is why - they all start on an invocation of sudo docker-compose up -d. But it seems that the first time this is invoked (ie. all containers going from cold to up), then the indexer will fail to start. The indexer log will report:

indexer-1  | 2025-04-13 05:52:17,843: Couldn't connect to RabbitMQ, check your settings. [Errno 111] Connection refused

But if I run it after some time has passed, it starts as expected:

indexer-1  | 2025-04-13 06:21:36,337: Batch size is set to 100
indexer-1  | 2025-04-13 06:21:36,338: Process delay is set to 15 seconds
indexer-1  | 2025-04-13 06:21:36,338: Index limit is set to 200000 rows
indexer-1  | 2025-04-13 06:21:36,341: AMQP timeout is set to 30 seconds
indexer-1  | 2025-04-13 06:21:37,365: Connection to RabbitMQ established
indexer-1  | 2025-04-13 06:21:38,833: Successfully processed 270 messages

---

So I have a few thoughts here. First, in the initial issue I raised there was a connection error reported in mirror.log - and this reoccured during the current database build (the one where replication now works), but there is a difference in that the errors reported by the search and indexer containers reported in my initial issue have been wholly absent (despite the replication running into the same conncetion errors) - there's no trace of them from anywhere in the logs of the current build during the periods where replication was failing.

Second, it's that these two may in some way be related despite the difference in errors. But I really don't know, so I will share some of the logs, maybe someone can spot something.

Here is the point in the logs where that issue resolved itself:

Fri Apr 11 04:00:02 2025 : Downloading https://metabrainz.org/api/musicbrainz/replication-175973-v2.tar.bz2 to /tmp/replication-175973-v2.tar.bz2
500 Can't connect to metabrainz.org:443 (Temporary failure in name resolution)
Content-Type: text/plain
Client-Date: Fri, 11 Apr 2025 04:00:02 GMT
Client-Warning: Internal response

Can't connect to metabrainz.org:443 (Temporary failure in name resolution)

Temporary failure in name resolution at /musicbrainz-server/local/lib/perl5/LWP/Protocol/http.pm line 49.
Fri Apr 11 16:00:01 2025 : Downloading https://metabrainz.org/api/musicbrainz/replication-175973-v2.tar.bz2 to /tmp/replication-175973-v2.tar.bz2
Fri Apr 11 16:00:02 2025 : Decompressing /tmp/replication-175973-v2.tar.bz2 to /tmp/loadrep-b_bsTx

DB logs from that time:

db-1  | 2025-04-11 04:14:29.949 UTC [1] LOG:  database system is shut down
db-1  | 
db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
db-1  | 
db-1  | 2025-04-11 15:39:18.630 UTC [1] LOG:  starting PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
db-1  | 2025-04-11 15:39:18.630 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db-1  | 2025-04-11 15:39:18.630 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db-1  | 2025-04-11 15:39:18.633 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db-1  | 2025-04-11 15:39:18.638 UTC [29] LOG:  database system was shut down at 2025-04-11 04:14:29 UTC
db-1  | 2025-04-11 15:39:18.645 UTC [1] LOG:  database system is ready to accept connections
db-1  | 2025-04-11 15:44:18.660 UTC [27] LOG:  checkpoint starting: time
db-1  | 2025-04-11 15:44:18.668 UTC [27] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.002 s, total=0.008 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB; lsn=7A/F0BBB770, redo lsn=7A/F0BBB738
db-1  | 2025-04-11 15:54:59.078 UTC [1] LOG:  received fast shutdown request
db-1  | 2025-04-11 15:54:59.079 UTC [1] LOG:  aborting any active transactions
db-1  | 2025-04-11 15:54:59.080 UTC [1] LOG:  background worker "logical replication launcher" (PID 32) exited with exit code 1
db-1  | 2025-04-11 15:54:59.081 UTC [27] LOG:  shutting down
db-1  | 2025-04-11 15:54:59.081 UTC [27] LOG:  checkpoint starting: shutdown immediate
db-1  | 2025-04-11 15:54:59.088 UTC [27] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.008 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=7A/F0BBB820, redo lsn=7A/F0BBB820
db-1  | 2025-04-11 15:54:59.098 UTC [1] LOG:  database system is shut down
db-1  | 
db-1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
db-1  | 
db-1  | 2025-04-11 15:54:59.359 UTC [1] LOG:  starting PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit
db-1  | 2025-04-11 15:54:59.359 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
db-1  | 2025-04-11 15:54:59.359 UTC [1] LOG:  listening on IPv6 address "::", port 5432
db-1  | 2025-04-11 15:54:59.360 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
db-1  | 2025-04-11 15:54:59.364 UTC [29] LOG:  database system was shut down at 2025-04-11 15:54:59 UTC
db-1  | 2025-04-11 15:54:59.368 UTC [1] LOG:  database system is ready to accept connections
db-1  | 2025-04-11 15:59:59.404 UTC [27] LOG:  checkpoint starting: time
db-1  | 2025-04-11 15:59:59.412 UTC [27] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.002 s, total=0.008 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB; lsn=7A/F0BBB908, redo lsn=7A/F0BBB8D0
db-1  | 2025-04-11 16:00:12.775 UTC [42] WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4
db-1  | 2025-04-11 16:00:31.221 UTC [42] WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4
db-1  | 2025-04-11 16:01:24.213 UTC [53] WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4
db-1  | 2025-04-11 16:01:43.525 UTC [58] WARNING:  amqp could not commit tx mode on broker 1, reply_type=2, library_errno=4

Musicbrainz logs:

musicbrainz-1  | 2025/04/11 15:55:14 Waiting for: tcp://db:5432
musicbrainz-1  | 2025/04/11 15:55:14 Waiting for: tcp://mq:5672
musicbrainz-1  | 2025/04/11 15:55:14 Waiting for: tcp://redis:6379
musicbrainz-1  | 2025/04/11 15:55:14 Connected to tcp://mq:5672
musicbrainz-1  | 2025/04/11 15:55:14 Connected to tcp://redis:6379
musicbrainz-1  | 2025/04/11 15:55:14 Connected to tcp://db:5432
musicbrainz-1  | forking 92
musicbrainz-1  | 2025/04/11 15:55:14 Command finished successfully.
musicbrainz-1  | start_server (pid:95) starting now...
musicbrainz-1  | starting new worker 109

MQ logs:

mq-1  | =INFO REPORT==== 11-Apr-2025::15:55:01 ===
mq-1  | Server startup complete; 6 plugins started.
mq-1  |  * rabbitmq_management
mq-1  |  * rabbitmq_web_dispatch
mq-1  |  * rabbitmq_management_agent
mq-1  |  * amqp_client
mq-1  |  * cowboy
mq-1  |  * cowlib
mq-1  | 
mq-1  | =INFO REPORT==== 11-Apr-2025::16:00:02 ===
mq-1  | accepting AMQP connection <0.535.0> (172.18.0.5:37566 -> 172.18.0.3:5672)

The messages from the period where replication was failing were no different:

mq-1  | =INFO REPORT==== 10-Apr-2025::08:41:28 ===
mq-1  | Server startup complete; 6 plugins started.
mq-1  |  * rabbitmq_management
mq-1  |  * rabbitmq_web_dispatch
mq-1  |  * rabbitmq_management_agent
mq-1  |  * amqp_client
mq-1  |  * cowboy
mq-1  |  * cowlib
mq-1  | 
mq-1  | =INFO REPORT==== 10-Apr-2025::08:45:56 ===
mq-1  | accepting AMQP connection <0.535.0> (172.18.0.7:37478 -> 172.18.0.4:5672)
mq-1  | 
mq-1  | =INFO REPORT==== 10-Apr-2025::08:45:56 ===
mq-1  | connection <0.535.0> (172.18.0.7:37478 -> 172.18.0.4:5672): user 'sir' authenticated and granted access to vhost '/search-index-rebuilder'

And the same for the indexer:

indexer-1  | 2025-04-08 09:49:54,343: Connection to RabbitMQ established
indexer-1  | 2025-04-09 02:51:15,760: Terminating SIR
indexer-1  | 2025-04-09 09:26:47,988: Batch size is set to 100
indexer-1  | 2025-04-09 09:26:47,988: Process delay is set to 15 seconds
indexer-1  | 2025-04-09 09:26:47,989: Index limit is set to 200000 rows
indexer-1  | 2025-04-09 09:26:47,991: AMQP timeout is set to 30 seconds
indexer-1  | 2025-04-09 09:26:47,997: Connection to RabbitMQ established
indexer-1  | 2025-04-10 01:51:00,146: Terminating SIR
indexer-1  | 2025-04-10 08:45:59,360: Batch size is set to 100
indexer-1  | 2025-04-10 08:45:59,360: Process delay is set to 15 seconds
indexer-1  | 2025-04-10 08:45:59,360: Index limit is set to 200000 rows
indexer-1  | 2025-04-10 08:45:59,363: AMQP timeout is set to 30 seconds
indexer-1  | 2025-04-10 08:45:59,368: Connection to RabbitMQ established
indexer-1  | 2025-04-11 04:14:29,897: Terminating SIR
indexer-1  | 2025-04-11 15:54:46,115: Batch size is set to 100
indexer-1  | 2025-04-11 15:54:46,115: Process delay is set to 15 seconds
indexer-1  | 2025-04-11 15:54:46,115: Index limit is set to 200000 rows
indexer-1  | 2025-04-11 15:54:46,118: AMQP timeout is set to 30 seconds
indexer-1  | 2025-04-11 15:54:46,123: Connection to RabbitMQ established
indexer-1  | 2025-04-11 15:54:59,077: Terminating SIR
indexer-1  | 2025-04-11 15:55:00,928: Couldn't connect to RabbitMQ, check your settings. [Errno 111] Connection refused
indexer-1  | 2025-04-11 17:06:48,588: Batch size is set to 100
indexer-1  | 2025-04-11 17:06:48,589: Process delay is set to 15 seconds
indexer-1  | 2025-04-11 17:06:48,589: Index limit is set to 200000 rows
indexer-1  | 2025-04-11 17:06:48,591: AMQP timeout is set to 30 seconds
indexer-1  | 2025-04-11 17:06:49,394: Connection to RabbitMQ established
indexer-1  | 2025-04-11 17:06:55,274: Successfully processed 204 messages

The only difference I see is... SIR was not terminated when replication started to work again.

I am assuming that musicbrainz hasn't suffered blackouts or overloads during the periods, given I have always been able to pull the packets using my API key with curl. I am not sure what the error output would look like in that case (and maybe the latter cases can be explained by that but not the initial issue raised).

Third, I wonder if the fact that I run musicbrainz on a machine that is powered off regularly overnight and the fact that I also occasionally have sudden reboots (a lower level issue I am working on fixing) caused the initial issue. Maybe a file got corrupted. But I am not sure what it could have to do with the replication/connection failures after a rebuild.

[yvanzo]

Hi @ashprice, thank you for the detailed feedback. Sorry for the hassle and for not having responded earlier. Today’s release v-2025-05-29.0-solr9 features a new version of SIR with updated dependencies, that might improve its stability. I’m not sure about the connection failures either, sudden reboots may cause issues with initialization of the Docker network, please try running curl from inside the musicbrainz service the next time.

[ashprice]

Hmm, I rebuilt against the most recent release and I have the same pattern of behaviour - it worked at first, and now I am back to the same errors about failures to resolve the host.

Weirdly, it works sometimes, but seemingly at random, maybe 10% of the time, on the same build where it previously failed.

I've fiddled a lot with firewalls and such trying to fix it but no dice - I don't even see any messages relating to blocked input/output in my firewall logs. Currently, with my firewall disabled, I'm unable to access the external internet from inside the container - ie. ping, curl, etc. do not work.

As we speak I am observing something else that is odd - invoking the replication script returns an error in mirror.log but... given a few attempts at running the replication script, I notice in my system monitor that there are ~3 instances of the replication script running, and which are eating up some CPU cycles; there's no reported network bandwidth, and the docker-compose logs don't report anything. I wonder if this is related to the broken pipe reported before...?

And now... killing all the containers and restarting them has it working again (regardless of firewall status). But when I tried that not 30 minutes ago, it did not work!

Edit:

Also - no worries about the slow reply! Thank you for working on and providing this at all.