Search reindex doesn't work

Using Mayan EDMS Bugs or errors
1

Tried with both Tools → Reindex search backend and

sudo docker compose run frontend run_command search_initialize
sudo docker compose run frontend run_command search_reindex

2.5 GB RAM used, 5.5 GB RAM remain free. 4 CPU cores, with the CPU load near zero the entire time.

RabbitMQ logs show no relevant errors, neither do the app container logs. The “search” queue remains idle most of the time:

image_2023-05-14_130203335
image_2023-05-14_1302033351406×35 2.71 KB

The reindexing happens at an ultra-slow pace, eventually petering out with the “search” queue becoming empty. At the same time, the number of indexed document pages is vanishingly small, i.e., I’m experiencing the same problem as the guy from

https://forum.mayan-edms.com/t/search-not-working-anymore/

This appears to be a related problem:

https://forum.mayan-edms.com/t/documents-dont-get-send-to-tesseract/

PS RabbitMQ logs do show errors occasionally, not sure if related:

2023-05-14 11:05:56.376991+00:00 [warning] <0.2874.0> closing AMQP connection <0.2874.0> (172.30.0.5:55202 -> 172.30.0.4:5672, vhost: 'mayan', user: 'mayan'):
2023-05-14 11:05:56.376991+00:00 [warning] <0.2874.0> client unexpectedly closed TCP connection
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>     supervisor: {<0.2878.0>,rabbit_channel_sup}
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>     errorContext: shutdown_error
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>     reason: noproc
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>     offender: [{pid,<0.2881.0>},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                {id,channel},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                {mfargs,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                    {rabbit_channel,start_link,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                        [1,<0.2874.0>,<0.2879.0>,<0.2874.0>,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         <<"172.30.0.5:55202 -> 172.30.0.4:5672">>,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         rabbit_framing_amqp_0_9_1,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         {user,<<"mayan">>,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                             [administrator],
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                             [{rabbit_auth_backend_internal,none}]},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         <<"mayan">>,
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         [{<<"consumer_cancel_notify">>,bool,true},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                          {<<"connection.blocked">>,bool,true},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                          {<<"authentication_failure_close">>,bool,true}],
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                         <0.2875.0>,<0.2880.0>]}},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                {restart_type,intrinsic},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                {shutdown,70000},
2023-05-14 11:05:56.377652+00:00 [error] <0.2878.0>                {child_type,worker}]

The same warning pops up quite often:

2023-05-14 11:09:02.178962+00:00 [warning] <0.3372.0> closing AMQP connection <0.3372.0> (172.30.0.5:58246 -> 172.30.0.4:5672, vhost: 'mayan', user: 'mayan'):
2023-05-14 11:09:02.178962+00:00 [warning] <0.3372.0> client unexpectedly closed TCP connection
1 Like
2

I have the same problem from the very beginning when I started using mayan edms.
The logs keep showing:

client unexpectedly closed TCP connection

At first I ignored it because everything seemed to be working properly.
When the number of documents added increased significantly, a search problem appeared. Newly added documents are never indexed in the search engine. Only docker compose down/up triggers re-indexing and the search works correctly. After some time, the problem returns.

mayan-rabbitmq-1    | 2023-11-08 07:31:17.861518+00:00 [warning] <0.15041.0> closing AMQP connection <0.15041.0> (172.28.0.4:52096 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'):
mayan-rabbitmq-1    | 2023-11-08 07:31:17.861518+00:00 [warning] <0.15041.0> client unexpectedly closed TCP connection
mayan-rabbitmq-1    | 2023-11-08 07:31:17.862591+00:00 [warning] <0.15030.0> closing AMQP connection <0.15030.0> (172.28.0.4:52086 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'):
mayan-rabbitmq-1    | 2023-11-08 07:31:17.862591+00:00 [warning] <0.15030.0> client unexpectedly closed TCP connection
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>     supervisor: {<0.15034.0>,rabbit_channel_sup}
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>     errorContext: shutdown_error
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>     reason: noproc
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>     offender: [{pid,<0.15037.0>},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                {id,channel},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                {mfargs,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                    {rabbit_channel,start_link,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                        [1,<0.15030.0>,<0.15035.0>,<0.15030.0>,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         <<"172.28.0.4:52086 -> 172.28.0.3:5672">>,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         rabbit_framing_amqp_0_9_1,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         {user,<<"user">>,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                             [administrator],
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                             [{rabbit_auth_backend_internal,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                                  #Fun<rabbit_auth_backend_internal.3.131409679>}]},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         <<"mayan">>,
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         [{<<"consumer_cancel_notify">>,bool,true},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                          {<<"connection.blocked">>,bool,true},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                          {<<"authentication_failure_close">>,bool,true}],
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                         <0.15031.0>,<0.15036.0>]}},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                {restart_type,intrinsic},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                {shutdown,70000},
mayan-rabbitmq-1    | 2023-11-08 07:31:17.864126+00:00 [error] <0.15034.0>                {child_type,worker}]
mayan-rabbitmq-1    | 2023-11-08 07:31:17.869492+00:00 [warning] <0.15054.0> closing AMQP connection <0.15054.0> (172.28.0.4:52102 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'):
mayan-rabbitmq-1    | 2023-11-08 07:31:17.869492+00:00 [warning] <0.15054.0> client unexpectedly closed TCP connection

mayan-rabbitmq-1    | 2023-11-08 07:31:15.945492+00:00 [info] <0.14998.0> accepting AMQP connection <0.14998.0> (172.28.0.4:52076 -> 172.28.0.3:5672)
mayan-rabbitmq-1    | 2023-11-08 07:31:15.947166+00:00 [info] <0.14998.0> connection <0.14998.0> (172.28.0.4:52076 -> 172.28.0.3:5672): user 'user' authenticated and granted access to vhost 'mayan'
mayan-rabbitmq-1    | 2023-11-08 07:31:15.951042+00:00 [info] <0.15010.0> accepting AMQP connection <0.15010.0> (172.28.0.4:52080 -> 172.28.0.3:5672)
mayan-rabbitmq-1    | 2023-11-08 07:31:15.952960+00:00 [info] <0.15010.0> connection <0.15010.0> (172.28.0.4:52080 -> 172.28.0.3:5672): user 'user' authenticated and granted access to vhost 'mayan'
mayan-rabbitmq-1    | 2023-11-08 07:31:16.243389+00:00 [warning] <0.14998.0> closing AMQP connection <0.14998.0> (172.28.0.4:52076 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'):
mayan-rabbitmq-1    | 2023-11-08 07:31:16.243389+00:00 [warning] <0.14998.0> client unexpectedly closed TCP connection
mayan-rabbitmq-1    | 2023-11-08 07:31:16.541911+00:00 [warning] <0.15010.0> closing AMQP connection <0.15010.0> (172.28.0.4:52080 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'):
mayan-rabbitmq-1    | 2023-11-08 07:31:16.541911+00:00 [warning] <0.15010.0> client unexpectedly closed TCP connection

mayan-rabbitmq-1    | 2023-11-08 07:53:33.749015+00:00 [warning] <0.971.0> Consumer 25143 on channel 1 has timed out waiting for delivery acknowledgement. Timeout used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more
mayan-rabbitmq-1    | 2023-11-08 07:53:33.805435+00:00 [error] <0.971.0> Channel error on connection <0.962.0> (172.28.0.4:43030 -> 172.28.0.3:5672, vhost: 'mayan', user: 'user'), channel 1:
mayan-rabbitmq-1    | 2023-11-08 07:53:33.805435+00:00 [error] <0.971.0> operation none caused a channel exception precondition_failed: delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more
mayan-app-1         | [2023-11-08 07:53:33,807: CRITICAL/MainProcess] Unrecoverable error: PreconditionFailed(406, 'PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more', (0, 0), '')
mayan-app-1         | Traceback (most recent call last):
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/worker/worker.py", line 202, in start
mayan-app-1         |     self.blueprint.start(self)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/bootsteps.py", line 116, in start
mayan-app-1         |     step.start(parent)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/bootsteps.py", line 365, in start
mayan-app-1         |     return self.obj.start()
mayan-app-1         |            ^^^^^^^^^^^^^^^^
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/worker/consumer/consumer.py", line 336, in start
mayan-app-1         |     blueprint.start(self)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/bootsteps.py", line 116, in start
mayan-app-1         |     step.start(parent)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/worker/consumer/consumer.py", line 726, in start
mayan-app-1         |     c.loop(*c.loop_args())
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/celery/worker/loops.py", line 97, in asynloop
mayan-app-1         |     next(loop)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/kombu/asynchronous/hub.py", line 373, in create_loop
mayan-app-1         |     cb(*cbargs)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/kombu/transport/base.py", line 248, in on_readable
mayan-app-1         |     reader(loop)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/kombu/transport/base.py", line 230, in _read
mayan-app-1         |     drain_events(timeout=0)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/connection.py", line 525, in drain_events
mayan-app-1         |     while not self.blocking_read(timeout):
mayan-app-1         |               ^^^^^^^^^^^^^^^^^^^^^^^^^^^
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/connection.py", line 531, in blocking_read
mayan-app-1         |     return self.on_inbound_frame(frame)
mayan-app-1         |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/method_framing.py", line 53, in on_frame
mayan-app-1         |     callback(channel, method_sig, buf, None)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/connection.py", line 537, in on_inbound_method
mayan-app-1         |     return self.channels[channel_id].dispatch_method(
mayan-app-1         |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/abstract_channel.py", line 156, in dispatch_method
mayan-app-1         |     listener(*args)
mayan-app-1         |   File "/opt/mayan-edms/lib/python3.11/site-packages/amqp/channel.py", line 293, in _on_close
mayan-app-1         |     raise error_for_code(
mayan-app-1         | amqp.exceptions.PreconditionFailed: (0, 0): (406) PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more

EDIT:
I did the test on clean Ubuntu 22.04.3LTS and ran mayan edms via docker compose. I didn’t change anything in the env configuration. Without SSL on port 80. I added 5 files, after some time I see a repeating message in the console:
client unexpectedly closed TCP connection
According to sentry, the problem first appeared in version 4.5.7, but this may be a coincidence.