[BUG] *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100)

[djgalloway]

Tag/version of Container Images: maxking/mailman-web:0.2.2

This is a follow-up to https://github.com/maxking/docker-mailman/issues/327.

I guess we theorized that running "minutely" jobs "hourly" instead would help this issue (https://github.com/maxking/docker-mailman/pull/346) but as my archives get larger, hyperkitty keeps becoming unresponsive every night.

Tue Jan 14 10:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs minutely" (pid 3439)
Tue Jan 14 10:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 3440)
Tue Jan 14 10:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs hourly" (pid 3441)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 3440 exited after 3 second(s)
[uwsgi-cron] command "./manage.py runjobs hourly" running with pid 3441 exited after 3 second(s)
Tue Jan 14 10:15:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 3445)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 3445 exited after 3 second(s)
Tue Jan 14 10:30:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 3447)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 3447 exited after 3 second(s)
Tue Jan 14 10:34:11 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 10:34:12 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 10:34:13 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***

<later>

Tue Jan 14 13:10:47 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100) ***
Tue Jan 14 13:10:48 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100) ***
DAMN ! worker 1 (pid: 1948) died, killed by signal 9 :( trying respawn ...
Respawned uWSGI worker 1 (new pid: 3479)
Tue Jan 14 13:10:49 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:50 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:51 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:52 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:53 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:54 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:55 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:56 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Tue Jan 14 13:10:58 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?thread=NIVVTSR2YW22VELM4BW4S6NQUCS3T4XW (ip 172.19.199.1) !!!
Tue Jan 14 13:10:58 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?thread=NIVVTSR2YW22VELM4BW4S6NQUCS3T4XW (172.19.199.1)
OSError: write error
Tue Jan 14 13:10:59 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/thread/EX7WEVSL62TZ5UJ2ZHJQYBMQYHPF23PS/ (ip 172.19.199.1) !!!
Tue Jan 14 13:10:59 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 341] during GET /hyperkitty/list/[email protected]/thread/EX7WEVSL62TZ5UJ2ZHJQYBMQYHPF23PS/ (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:00 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/thread/EX7WEVSL62TZ5UJ2ZHJQYBMQYHPF23PS/ (ip 172.19.199.1) !!!
Tue Jan 14 13:11:00 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 341] during GET /hyperkitty/list/[email protected]/thread/EX7WEVSL62TZ5UJ2ZHJQYBMQYHPF23PS/ (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:00 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=NQNK2FICV2IETWWOYDM5E3B6L6Q7E6ZZ (ip 172.19.199.1) !!!
Tue Jan 14 13:11:00 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=NQNK2FICV2IETWWOYDM5E3B6L6Q7E6ZZ (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:00 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=AGPGOMJTC3YKCHZ7SYBH7YGBNMWSZ4GJ (ip 172.19.199.1) !!!
Tue Jan 14 13:11:00 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=AGPGOMJTC3YKCHZ7SYBH7YGBNMWSZ4GJ (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:05 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=56XUO7SVDY4CZEU2UMEEET5M4T7V44VG (ip 172.19.199.1) !!!
Tue Jan 14 13:11:05 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=56XUO7SVDY4CZEU2UMEEET5M4T7V44VG (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:06 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=JVAYKROJT2YEHH5K5ZPIBRVNHKY4DXJY (ip 172.19.199.1) !!!
Tue Jan 14 13:11:06 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=JVAYKROJT2YEHH5K5ZPIBRVNHKY4DXJY (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:06 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=6WWS6G52C35IQXCRBKMTK3TCTSYLBSOG (ip 172.19.199.1) !!!
Tue Jan 14 13:11:06 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=6WWS6G52C35IQXCRBKMTK3TCTSYLBSOG (172.19.199.1)
OSError: write error
Tue Jan 14 13:11:07 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?thread=ZJBLM5YAO7U3AATHHQITCBUG6YRSBDNZ (ip 172.19.199.1) !!!
Tue Jan 14 13:11:07 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?thread=ZJBLM5YAO7U3AATHHQITCBUG6YRSBDNZ (172.19.199.1)
OSError: write error
13:11:10 [Q] INFO Enqueued 5941

I can sometimes force hyperkitty offline by doing a search as well.

I'm not super familiar with tuning containers but is there a way we can use more of the host's cores for certain processes? I've noticed a single core gets pegged when I do a hyperkitty search while 6 of the 8 are idle.

[issue-label-bot[bot]]

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.94. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

[maxking]

So, the current search engine that is default in these images aren't very good for production workloads. I have had several reports about it's poor performance.

What we need to do now is to migrate to using Xapian in these images. I am planning to do this soon-ish if something else doesn't come up. But please ping me if this isn't fixed in ~2weeks :)

[maxking]

So, the fix has already been added to master branch through https://github.com/maxking/docker-mailman/pull/364. I'll make a release soon, but if you want to do this in your running instance, you can easily do it by just adding

#
HAYSTACK_CONNECTIONS = {
    'default': {
        'PATH': "/opt/mailman-web-data/fulltext_index",
        'ENGINE': 'xapian_backend.XapianEngine'
    },
}

to your settings_local.py. As it turns out, the Xapian indexing library was already installed in the images, contributed by one of the users.

[djgalloway]

Once I make that change, do I just need to restart the mailman-web container?

Can/should we revert https://github.com/maxking/docker-mailman/pull/346?

[maxking]

You need to restart and also index all your existing emails with the new Xapian Engine. You'd have to do that with the next release anyway.

One you have re-started the mailman-web container, you can run:

docker exec -it mailman-web ./manage.py rebuild_index

It can take a long time depending on how many emails you have. The site although, would continue to function and you can keep the indexing running in the background.

[maxking]

About #346 , I think it's okay. It will only add a little bit of latency in the search. Maybe later we can switch to 15mins.

[djgalloway]

So far so good I think! I did this on Monday. Yesterday I saw this:

[ERROR/MainProcess] Failed indexing 1 - 25 (retry 5/5): Unable to get write lock on /opt/mailman-web-data/fulltext_index: Couldn't open lockfile: Permission denied (pid 256): Unable to get write lock on /opt/mailman-web-data/fulltext_index: Couldn't open lockfile: Permiss
ion denied
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/haystack/management/commands/update_index.py", line 97, in do_update
    backend.update(index, current_qs, commit=commit)
  File "/usr/lib/python3.6/site-packages/xapian_backend.py", line 282, in update
    database = self._database(writable=True)
  File "/usr/lib/python3.6/site-packages/xapian_backend.py", line 1156, in _database
    database = xapian.WritableDatabase(self.path, xapian.DB_CREATE_OR_OPEN)
  File "/usr/lib/python3.6/site-packages/xapian/__init__.py", line 9205, in __init__
    _xapian.WritableDatabase_swiginit(self, _xapian.new_WritableDatabase(*args))
xapian.DatabaseLockError: Unable to get write lock on /opt/mailman-web-data/fulltext_index: Couldn't open lockfile: Permission denied

I touched /opt/mailman-web-data/fulltext_index, chowned it to mailman and haven't seen any issues with the queue being full or hyperkitty going offline.

[djgalloway]

Spoke too soon. I'm still seeing this roughly every day.

Sat Jan 25 13:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs minutely" (pid 1146)
Sat Jan 25 13:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 1147)
Sat Jan 25 13:00:00 2020 - [uwsgi-cron] running "./manage.py runjobs hourly" (pid 1148)
[uwsgi-cron] command "./manage.py runjobs minutely" running with pid 1146 exited after 3 second(s)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 1147 exited after 3 second(s)
[uwsgi-cron] command "./manage.py runjobs hourly" running with pid 1148 exited after 3 second(s)
Sat Jan 25 13:15:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 1152)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 1152 exited after 3 second(s)
Sat Jan 25 13:30:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 1154)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 1154 exited after 3 second(s)
Sat Jan 25 13:45:00 2020 - [uwsgi-cron] running "./manage.py runjobs quarter_hourly" (pid 1156)
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 1156 exited after 3 second(s)
Sat Jan 25 13:46:00 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Sat Jan 25 13:46:01 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***


.......


Sat Jan 25 16:52:31 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100) ***
Sat Jan 25 16:52:32 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100) ***
Sat Jan 25 16:52:33 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (101/100) ***
DAMN ! worker 1 (pid: 981) died, killed by signal 9 :( trying respawn ...
Respawned uWSGI worker 1 (new pid: 1193)
Sat Jan 25 16:52:34 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Sat Jan 25 16:52:35 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Sat Jan 25 16:52:36 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Sat Jan 25 16:52:37 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
[uwsgi-cron] command "./manage.py runjobs quarter_hourly" running with pid 1192 exited after 456 second(s)
Sat Jan 25 16:52:38 2020 - *** uWSGI listen queue of socket "0.0.0.0:8000" (fd: 9) full !!! (100/100) ***
Sat Jan 25 16:52:41 2020 - SIGPIPE: writing to a closed pipe/socket/fd (probably the client disconnected) on request /hyperkitty/list/[email protected]/export/[email protected]?message=QHKOQFP56NDK3YLFA6VX3NUFEY6BGOEJ (ip 172.19.199.1) !!!
Sat Jan 25 16:52:41 2020 - uwsgi_response_write_body_do(): Broken pipe [core/writer.c line 429] during GET /hyperkitty/list/[email protected]/export/[email protected]?message=QHKOQFP56NDK3YLFA6VX3NUFEY6BGOEJ (172.19.199.1)
OSError: write error

[djgalloway]

@maxking Any ideas?

[github-actions[bot]]

This issue has not been updated for more than 1year