Timeout error on anonymous subscribe
Hi,
I am running a mailman 3.3.9 server (pip installation). It's working fine so far. However, I have problems setting a template. I set a '[list:user:action:subscribe]' template for a list with some simple text like "test1234".
When someone wants to subscribe on the list page without creating an account, it takes five seconds until "HTTPSConnectionPool(host='lists.example.org', port=443): Read timed out. (read timeout=5)" appears on the page. The mail address has been added pending confirmation but no mail gets send.
mailman.log shows just exceptions about the timeout itself:
Sep 09 15:01:45 2024 (2070549) deque: do_confirm_verify Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.11/site-packages/urllib3/connectionpool.py", line 536, in _make_request response = conn.getresponse() ^^^^^^^^^^^^^^^^^^ ... requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='lists.dkrz.de', port=443): Read timed out. (read timeout=5) [09/Sep/2024:15:01:45 +0200] "POST /3.1/members HTTP/1.1" 400 132 "-" "GNU Mailman REST client v3.3.5"
The access log suggests that getting the template took 5s:
==> /opt/mailman/mm/var/logs/access.log <== 127.0.0.1 - - [09/Sep/2024:13:01:45 +0000] "GET /mailman3/api/templates/list/community.lists.example.org/list:user:action:subscribe HTTP/1.1" 200 8 "-" "python-requests/2.32.3"
Running curl on that url returns immediately $ curl -v 'http://localhost:8000/mailman3/api/templates/list/community.lists.example.or...'
I have captured the network traffic on localhost interface lo and I can see that the request is sent through the tcp connection and acknowledged. Then 5 seconds later the server (port 8000) sends a push data with the response and closes the connection with FIN.
The data exchanged on the connection looks like this:
GET /mailman3/api/templates/list/community.lists.example.org/list:user:action:subscribe HTTP/1.1 Host: lists.example.org User-Agent: python-requests/2.32.3 Accept-Encoding: gzip, deflate Accept: */* X-Forwarded-Proto: https X-Forwarded-For: 2001:638:1234:1224::111 X-Forwarded-Host: lists.example.org X-Forwarded-Server: lists.example.org Connection: Keep-Alive
HTTP/1.1 200 OK Server: gunicorn Date: Mon, 09 Sep 2024 13:01:45 GMT Connection: close Content-Type: text/plain; charset=utf-8 X-Content-Type-Options: nosniff Referrer-Policy: same-origin Cross-Origin-Opener-Policy: same-origin X-Frame-Options: DENY Vary: Accept-Language, Cookie Content-Language: en Content-Length: 8
test1234
The timestamp 13:01:45 is the time of the timeout. The request started five seconds before that. It looks to me as if the connection/keepalive handling is not working properly or the server isn't pushing the response immediately, but it gets buffered until the 5s timeout.
Occassionally, I have capture a requests, where the client side would send a FIN to the server and only then the server would send the http response with the final packets.
Does anyone have an idea how I can fix this?
Thanks,
Gerald
Hi,
sorry to bother, but does anyone have an idea why this doesn't work? I am on mailman 3.3.10 by now but still not difference. I wonder why nobody else has the same problem. I didn't think my setup would be so special...
Thanks,
Gerald
vogt@spamcop.net wrote:
Hi,
I am running a mailman 3.3.9 server (pip installation). It's working fine so far. However, I have problems setting a template. I set a '[list:user:action:subscribe]' template for a list with some simple text like "test1234".
When someone wants to subscribe on the list page without creating an account, it takes five seconds until "HTTPSConnectionPool(host='lists.example.org', port=443): Read timed out. (read timeout=5)" appears on the page. The mail address has been added pending confirmation but no mail gets send.
mailman.log shows just exceptions about the timeout itself:
Sep 09 15:01:45 2024 (2070549) deque: do_confirm_verify Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.11/site-packages/urllib3/connectionpool.py", line 536, in _make_request response = conn.getresponse() ^^^^^^^^^^^^^^^^^^ ... requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='lists.dkrz.de', port=443): Read timed out. (read timeout=5) [09/Sep/2024:15:01:45 +0200] "POST /3.1/members HTTP/1.1" 400 132 "-" "GNU Mailman REST client v3.3.5"
The access log suggests that getting the template took 5s:
==> /opt/mailman/mm/var/logs/access.log <== 127.0.0.1 - - [09/Sep/2024:13:01:45 +0000] "GET /mailman3/api/templates/list/community.lists.example.org/list:user:action:subscribe HTTP/1.1" 200 8 "-" "python-requests/2.32.3"
Running curl on that url returns immediately $ curl -v 'http://localhost:8000/mailman3/api/templates/list/community.lists.example.or...'
I have captured the network traffic on localhost interface lo and I can see that the request is sent through the tcp connection and acknowledged. Then 5 seconds later the server (port 8000) sends a push data with the response and closes the connection with FIN.
The data exchanged on the connection looks like this:
GET /mailman3/api/templates/list/community.lists.example.org/list:user:action:subscribe HTTP/1.1 Host: lists.example.org User-Agent: python-requests/2.32.3 Accept-Encoding: gzip, deflate Accept: */* X-Forwarded-Proto: https X-Forwarded-For: 2001:638:1234:1224::111 X-Forwarded-Host: lists.example.org X-Forwarded-Server: lists.example.org Connection: Keep-Alive
HTTP/1.1 200 OK Server: gunicorn Date: Mon, 09 Sep 2024 13:01:45 GMT Connection: close Content-Type: text/plain; charset=utf-8 X-Content-Type-Options: nosniff Referrer-Policy: same-origin Cross-Origin-Opener-Policy: same-origin X-Frame-Options: DENY Vary: Accept-Language, Cookie Content-Language: en Content-Length: 8
test1234
The timestamp 13:01:45 is the time of the timeout. The request started five seconds before that. It looks to me as if the connection/keepalive handling is not working properly or the server isn't pushing the response immediately, but it gets buffered until the 5s timeout.
Occassionally, I have capture a requests, where the client side would send a FIN to the server and only then the server would send the http response with the final packets.
Does anyone have an idea how I can fix this?
Thanks,
Gerald
On 10/14/24 06:13, Gerald Vogt wrote:
Hi,
sorry to bother, but does anyone have an idea why this doesn't work? I am on mailman 3.3.10 by now but still not difference. I wonder why nobody else has the same problem. I didn't think my setup would be so special...
Thanks,
Gerald
vogt@spamcop.net wrote:
Hi,
I am running a mailman 3.3.9 server (pip installation). It's working fine so far. However, I have problems setting a template. I set a '[list:user:action:subscribe]' template for a list with some simple text like "test1234".
How are you creating the template? If you are creating it via Postorius, what is your setting for POSTORIUS_TEMPLATE_BASE_URL and what does the entry in the template table in the database look like?
POSTORIUS_TEMPLATE_BASE_URL should be the same URL you use to access
Postorius up to but not including the /postorius/
or /mailman3/
part. I.e, for this list whose info page is at
https://lists.mailman3.org/mailman3/lists/mailman-users.mailman3.org/,
the setting is
POSTORIUS_TEMPLATE_BASE_URL = 'https://lists.mailman3.org'
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
On 23.10.24 00:09, Mark Sapiro wrote:
How are you creating the template? If you are creating it via Postorius,
Yes, via Postorius created using the url
https://lists.example.org/mailman3/lists/community.lists.example.com/templat...
what is your setting for POSTORIUS_TEMPLATE_BASE_URL and what does the
I did not set POSTORIUS_TEMPLATE_BASE_URL in settings.py.
entry in the template table in the database look like?
in mailman.template:
mailman=# select * from template where id = 6; 6|list:user:action:subscribe|community.lists.example.com|http://localhost:8000/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe||
in mailmanweb.template:
mailmanweb=# select * from postorius_emailtemplate where id = 6; 6|list:user:action:subscribe|test1234||2024-09-09 13:52:22.377792+02|2024-10-14 15:11:43.029873+02|list|community.lists.example.com
POSTORIUS_TEMPLATE_BASE_URL should be the same URL you use to access Postorius up to but not including the
/postorius/
or/mailman3/
part. I.e, for this list whose info page is at https:// lists.mailman3.org/mailman3/lists/mailman-users.mailman3.org/, the setting isPOSTORIUS_TEMPLATE_BASE_URL = 'https://lists.mailman3.org'
For testing I have set
POSTORIUS_TEMPLATE_BASE_URL = 'https://lists.example.org'
to the URL of our main domain, however, if I test an anonymous subscribe through the list info page I still get the timeout error
HTTPConnectionPool(host='localhost', port=8000): Read timed out. (read
timeout=5)
Logs still show the same behaviour: the request for the template comes into the server but is finished and logged after 5 seconds:
127.0.0.1 - - [23/Oct/2024:05:51:38 +0000] "GET /mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe HTTP/1.1" 200 8 "-" "python-requests/2.32.3"
The tcpdump of the tcp conection also looks the same: the response is pushed with the termination of the connection.
I can access http://localhost:8000/mailman3/api/templates/list/community.lists.example.co... with curl and immediately get the response.
So it still looks to me as if the response is stuck in the tcp buffers of the connection and not pushed immediately, but only once the requestor times out after 5 seconds and closes the connection.
Thanks,
Gerald
On 10/22/24 23:07, Gerald Vogt wrote:
For testing I have set
POSTORIUS_TEMPLATE_BASE_URL = 'https://lists.example.org'
to the URL of our main domain, however, if I test an anonymous subscribe through the list info page I still get the timeout error
This will have no effect unless you delete and recreate the template in
Postorius because simple changing the setting won't change the uri
in
the template table.
I can access http://localhost:8000/mailman3/api/templates/list/community.lists.example.co... with curl and immediately get the response.
Can you do that as the Mailman user?, e.g.
sudo -u mailman curl
http://localhost:8000/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
assuming the Mailman user is mailman
.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
On 23.10.24 21:35, Mark Sapiro wrote:
On 10/22/24 23:07, Gerald Vogt wrote:
For testing I have set
POSTORIUS_TEMPLATE_BASE_URL = 'https://lists.example.org'
to the URL of our main domain, however, if I test an anonymous subscribe through the list info page I still get the timeout error
This will have no effect unless you delete and recreate the template in Postorius because simple changing the setting won't change the
uri
in the template table.
O.K. Did that. Now the uri in mailman.template is https://lists.example.org/mailman3/api/templates/list/community.lists.exampl...
However, it doesn't change the timeout issue, except now the error is
HTTPSConnectionPool(host='lists.example.org', port=443): Read timed out. (read timeout=5)
instead of localhost:8000.
I can access http://localhost:8000/mailman3/api/templates/list/ community.lists.example.com/list:user:action:subscribe with curl and immediately get the response.
Can you do that as the Mailman user?, e.g.
sudo -u mailman curl http://localhost:8000/mailman3/api/templates/list/ community.lists.example.com/list:user:action:subscribe
assuming the Mailman user is
mailman
.
I don't quite understand the relevance of the user accessing the localhost tcp port. Any local user can do that.
I can access the template content with
curl http://localhost:8000/mailman3/api/templates/list/community.lists.example.co...
as well as
curl http://lists.example.org/mailman3/api/templates/list/community.lists.example...
as any user on the mailman server.
And I can use the latter to access the template from anywhere as it's a public server.
In any case, curl immediately returns the content. There is no delay.
Thanks,
Gerald
On 10/23/24 13:23, Gerald Vogt wrote:
I don't quite understand the relevance of the user accessing the localhost tcp port. Any local user can do that.
I am trying to duplicate what Mailman does in an attempt to find the issue.
I can access the template content with
curl http://localhost:8000/mailman3/api/templates/list/community.lists.example.co...
as well as
curl http://lists.example.org/mailman3/api/templates/list/community.lists.example...
as any user on the mailman server.
How about
curl -A 'python-requests/2.32.3'
http://lists.example.org/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
as the Mailman user?
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
Mark Sapiro wrote:
On 10/23/24 13:23, Gerald Vogt wrote:
I don't quite understand the relevance of the user accessing the localhost tcp port. Any local user can do that. I am trying to duplicate what Mailman does in an attempt to find the issue. I can access the template content with curl http://localhost:8000/mailman3/api/templates/list/community.lists.example.co... as well as curl http://lists.example.org/mailman3/api/templates/list/community.lists.example... as any user on the mailman server. How about curl -A 'python-requests/2.32.3' http://lists.example.org/mailman3/api/templates/list/community.lists.example...
as the Mailman user?
I have tried anything I could think of but I cannot reproduce the issue using curl as user mailman (or any other for that matter)
Going directly for localhost:8000, using some or all of the headers I can capture with tcpdump:
$ curl -v -H 'Accept-Encoding: gzip, deflate' -H 'Connection: Keep-Alive' -H 'Host: lists.example.org' -A 'python-requests/2.32.3' http://localhost:8000/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
as well as going through the local httpd:
$ curl -v --http1.1 -H 'Accept-Encoding: gzip, deflate' -H 'Connection: Keep-Alive' -H 'Host: lists.example.org' -A 'python-requests/2.32.3' https://lists.example.org/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
Running tcpdump during those runs shows me it's sending the same headers as mailman does. Thus on http protocol level it's the same, but still the server returns immediately.
What I have just noticed is that the Date header in the delayed response is the "late" time. I have even compared tcp headers from either capture. They look identical down to the frame sizes.
The only difference the last times is that with curl, the server side sends the ACK for the request and milliseconds later a PSH,ACK with the response headers. When it comes internally from mailman it sends the ACK for the request and then 5 seconds later it sends the PSH,ACK with the response headers.
Thanks,
Gerald
On 10/23/24 23:36, vogt@spamcop.net wrote:
I have tried anything I could think of but I cannot reproduce the issue using curl as user mailman (or any other for that matter)
Going directly for localhost:8000, using some or all of the headers I can capture with tcpdump:
$ curl -v -H 'Accept-Encoding: gzip, deflate' -H 'Connection: Keep-Alive' -H 'Host: lists.example.org' -A 'python-requests/2.32.3' http://localhost:8000/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
as well as going through the local httpd:
$ curl -v --http1.1 -H 'Accept-Encoding: gzip, deflate' -H 'Connection: Keep-Alive' -H 'Host: lists.example.org' -A 'python-requests/2.32.3' https://lists.example.org/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
Running tcpdump during those runs shows me it's sending the same headers as mailman does. Thus on http protocol level it's the same, but still the server returns immediately.
What I have just noticed is that the Date header in the delayed response is the "late" time. I have even compared tcp headers from either capture. They look identical down to the frame sizes.
The only difference the last times is that with curl, the server side sends the ACK for the request and milliseconds later a PSH,ACK with the response headers. When it comes internally from mailman it sends the ACK for the request and then 5 seconds later it sends the PSH,ACK with the response headers.
I'm unable to explain what's going on. You could try one more thing in an attempt to duplicate this outside of Mailman. Invoke the same python3 that Mailman does - this may be in a venv or the system python3. If in a venv, you don't need to activate the venv, just run venv/bin/python.
Then in response to Python's prompts do
>>> import requests
>>> res =
requests.get('https://lists.example.org/mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe',
timeout=5)
and see what that does? I think it should time out because this is exactly what Mailman core is doing tho get the template, and if it does, perhaps you can determine why from this simple example.
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
On 24.10.24 22:09, Mark Sapiro wrote:
On 10/23/24 23:36, vogt@spamcop.net wrote:
The only difference the last times is that with curl, the server side sends the ACK for the request and milliseconds later a PSH,ACK with the response headers. When it comes internally from mailman it sends the ACK for the request and then 5 seconds later it sends the PSH,ACK with the response headers.
I'm unable to explain what's going on. You could try one more thing in an attempt to duplicate this outside of Mailman. Invoke the same python3 that Mailman does - this may be in a venv or the system python3. If in a venv, you don't need to activate the venv, just run venv/bin/python.
Then in response to Python's prompts do
>>> import requests >>> res = requests.get('https://lists.example.org/mailman3/api/ templates/list/community.lists.example.com/list:user:action:subscribe', timeout=5)
and see what that does? I think it should time out because this is exactly what Mailman core is doing tho get the template, and if it does, perhaps you can determine why from this simple example.
I have tried it using the fqdn url as well as the localhost:8000 url but in both cases requests.get immediately returns the response. The server side pushes the response within milliseconds.
But that made me looking another time at the localhost tcpdump: I have noticed two connections to localhost:8000 where gunicorn with mailman_web.wsgi:application is running.
The first one is
POST /mailman3/lists/community.lists.example.com/anonymous_subscribe
the second one is
GET /mailman3/api/templates/list/community.lists.example.com/list:user:action:subscribe
Both take 5 seconds. First the first one responds then shortly after the second one. I have noticed that only two gunicorn processes are running which looked like only one is a worker.
Thus I have added workers=9 (2xncore+1) to /etc/mailman3/gunicorn.conf and restarted mailmanweb.service. Now it's working. So it must have been some kind of deadlock situation because it only had a single worker running.
I have just followed the docs from
https://docs.mailman3.org/en/latest/install/virtualenv.html#setting-up-gunic...
which doesn't mention anything about workers and I seriously don't have a clue about gunicorn. Maybe that could be added to the docs?
Thanks for the help!
Cheers,
Gerald
participants (3)
-
Gerald Vogt
-
Mark Sapiro
-
vogt@spamcop.net