stalwartlabs / mail-server

Secure & Modern All-in-One Mail Server (IMAP, JMAP, POP3, SMTP)
https://stalw.art
4.8k stars 194 forks source link

[bug]: discourse pop3 polling doesn't work #567

Closed programmerjake closed 3 months ago

programmerjake commented 3 months ago

What happened?

I'm trying to setup a discourse server that uses pop3 polling for a stalwart mail instance on the same host, discourse fails when trying to verify it can connect to the pop3 server. I can connect to the pop3 server and login using the credentials successfully using python.

Apparently someone else also has this problem, but I couldn't find where they reported it to stalwart: https://meta.discourse.org/t/stalwart-mail-discourse-pop3-eof-reached-again/312287

How can we reproduce the problem?

installing discourse and stalwart-mail, try to set up pop3 polling on discourse pointing to an account on the mail server by adding the following code to discourse's app.yml and run ./launcher bootstrap app:

## Any custom commands to run after building
run:
  - exec: echo "Beginning of custom commands"
  - exec: rails r "SiteSetting.notification_email='forum-noreply@site.test'"
  - exec: rails r "SiteSetting.title='Site.test Forum'"
  - exec: rails r "SiteSetting.reply_by_email_address='forum+%{reply_key}@site.test'"
  - exec: rails r "SiteSetting.pop3_polling_username='forum'"
  - exec: rails r "SiteSetting.pop3_polling_password='<secret>'"
  - exec: rails r "SiteSetting.pop3_polling_host='site.test'"
  # using a test domain that I can't get ssl certificates for, so I'm using pebble to generate untrusted certificates
  - exec: rails r "SiteSetting.pop3_polling_openssl_verify = false"
  - exec: rails r "SiteSetting.pop3_polling_enabled = true"
  - exec: rails r "SiteSetting.reply_by_email_enabled = true"

Version

v0.8.x

What database are you using?

SQLite

What blob storage are you using?

RocksDB

Where is your directory located?

None

What operating system are you using?

Docker

Relevant log output

Stalwart's Log:

2024-06-28T00:25:01.516798Z  INFO common::manager::boot: Starting Stalwart Mail Server v0.8.2...
2024-06-28T00:25:01.850632Z  INFO common::manager::boot: Imported spam filter rules context="config" event="import" version="1.1"
2024-06-28T00:25:02.736805Z  INFO common::manager::boot: Downloaded webadmin bundle context="webadmin" event="download"
2024-06-28T00:25:02.960704Z DEBUG common::manager::webadmin: WebAdmin successfully unpacked path="/tmp/STALWART_WEBADMIN"
2024-06-28T00:25:02.960750Z  INFO common::listener::listen: Starting listener id="http" protocol=Http bind.ip="::" bind.port=80 tls=false
2024-06-28T00:25:02.960767Z  INFO common::listener::listen: Starting listener id="imaptls" protocol=Imap bind.ip="::" bind.port=993 tls=true
2024-06-28T00:25:02.960774Z  INFO common::listener::listen: Starting listener id="pop3s" protocol=Pop3 bind.ip="::" bind.port=995 tls=true
2024-06-28T00:25:02.960778Z  INFO common::listener::listen: Starting listener id="smtp" protocol=Smtp bind.ip="::" bind.port=25 tls=false
2024-06-28T00:25:02.960783Z  INFO common::listener::listen: Starting listener id="submission" protocol=Smtp bind.ip="::" bind.port=587 tls=false
2024-06-28T00:25:02.960786Z  INFO common::listener::listen: Starting listener id="submissions" protocol=Smtp bind.ip="::" bind.port=465 tls=true
2024-06-28T00:25:02.960791Z DEBUG jmap::services::housekeeper: Housekeeper task started.
2024-06-28T00:25:02.960833Z DEBUG jmap::services::housekeeper: Scheduling housekeeper event. due_in=2997 event=Session
2024-06-28T00:25:02.960837Z DEBUG jmap::services::housekeeper: Scheduling housekeeper event. due_in=84897 event=Account
2024-06-28T00:25:02.960839Z DEBUG jmap::services::housekeeper: Scheduling housekeeper event. due_in=9297 event=Store(0)
2024-06-28T00:25:02.960845Z DEBUG jmap::services::housekeeper: Scheduling housekeeper event. due_in=12897 event=Store(1)
2024-06-28T00:25:02.960846Z DEBUG jmap::services::housekeeper: Scheduling housekeeper event. due_in=16497 event=Store(2)
2024-06-28T00:25:03.335287Z DEBUG session{instance="http" protocol=Http remote.ip="127.0.0.1" remote.port=35526}: jmap::api::http: event="request" uri="/api/domain/site.test"
2024-06-28T00:25:03.335303Z  WARN jmap::api::http: Warning: No remote address found in request, using remote ip.
2024-06-28T00:25:03.556299Z DEBUG session{instance="http" protocol=Http remote.ip="127.0.0.1" remote.port=35534}: jmap::api::http: event="request" uri="/api/principal"
2024-06-28T00:25:03.556312Z  WARN jmap::api::http: Warning: No remote address found in request, using remote ip.
2024-06-28T00:25:03.783341Z DEBUG session{instance="http" protocol=Http remote.ip="127.0.0.1" remote.port=35544}: jmap::api::http: event="request" uri="/api/principal"
2024-06-28T00:25:03.783354Z  WARN jmap::api::http: Warning: No remote address found in request, using remote ip.
2024-06-28T00:25:06.255699Z DEBUG session{instance="http" protocol=Http remote.ip="127.0.0.1" remote.port=55058}: jmap::api::http: event="request" uri="/api/principal"
2024-06-28T00:25:06.255708Z  WARN jmap::api::http: Warning: No remote address found in request, using remote ip.
2024-06-28T00:25:06.464293Z DEBUG session{instance="http" protocol=Http remote.ip="127.0.0.1" remote.port=55062}: jmap::api::http: event="request" uri="/api/principal"
2024-06-28T00:25:06.464307Z  WARN jmap::api::http: Warning: No remote address found in request, using remote ip.
2024-06-28T00:28:15.548547Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=55684}: pop3::session: event="write" data="+OK Stalwart POP3 at your service.\r\n" size=36
2024-06-28T00:28:15.548785Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=55684}: pop3::session: event="write" data="+OK forum is a valid mailbox\r\n" size=30
2024-06-28T00:28:15.554972Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=55684}: pop3::session: event="write" data="+OK Authentication successful\r\n" size=31
2024-06-28T00:28:15.555053Z DEBUG session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=55684}: pop3::session: Disconnecting client. event="disconnect"

Discourse Log:

I, [2024-06-27T04:52:07.020063 #1]  INFO -- : > rails r "SiteSetting.reply_by_email_address='forum+%{reply_key}@site.test'"
I, [2024-06-27T04:52:08.821052 #1]  INFO -- : 
I, [2024-06-27T04:52:08.821249 #1]  INFO -- : > rails r "SiteSetting.pop3_polling_username='forum'"
I, [2024-06-27T04:52:10.626233 #1]  INFO -- : 
I, [2024-06-27T04:52:10.626412 #1]  INFO -- : > rails r "SiteSetting.pop3_polling_password='<secret>'"
I, [2024-06-27T04:52:12.443751 #1]  INFO -- : 
I, [2024-06-27T04:52:12.444003 #1]  INFO -- : > rails r "SiteSetting.pop3_polling_host='site.test'"
I, [2024-06-27T04:52:14.281101 #1]  INFO -- : 
I, [2024-06-27T04:52:14.281346 #1]  INFO -- : > rails r "SiteSetting.pop3_polling_openssl_verify = false"
I, [2024-06-27T04:52:16.106502 #1]  INFO -- : 
I, [2024-06-27T04:52:16.106720 #1]  INFO -- : > rails r "SiteSetting.pop3_polling_enabled = true"
bundler: failed to load command: script/rails (script/rails)
/usr/local/lib/ruby/3.3.0/net/protocol.rb:237:in `rbuf_fill': end of file reached (EOFError)
        from /usr/local/lib/ruby/3.3.0/net/protocol.rb:199:in `readuntil'
        from /usr/local/lib/ruby/3.3.0/net/protocol.rb:209:in `readline'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:1000:in `recv_response'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:996:in `get_response'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:984:in `block in quit'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:1016:in `critical'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:984:in `quit'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:603:in `do_finish'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:533:in `start'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/net-pop-0.1.2/lib/net/pop.rb:316:in `auth_only'
        from /var/www/discourse/app/services/email_settings_validator.rb:55:in `validate_pop3'
        from /var/www/discourse/lib/validators/pop3_polling_enabled_setting_validator.rb:35:in `authentication_works?'
        from /var/www/discourse/lib/validators/pop3_polling_enabled_setting_validator.rb:15:in `valid_value?'
        from /var/www/discourse/lib/site_settings/type_supervisor.rb:287:in `validate_value'
        from /var/www/discourse/lib/site_settings/type_supervisor.rb:168:in `to_db_value'
        from /var/www/discourse/lib/site_setting_extension.rb:381:in `add_override!'
        from /var/www/discourse/lib/site_setting_extension.rb:622:in `block in setup_methods'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/commands/runner/runner_command.rb:46:in `<main>'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/commands/runner/runner_command.rb:46:in `eval'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/commands/runner/runner_command.rb:46:in `perform'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/thor-1.3.1/lib/thor/command.rb:28:in `run'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/thor-1.3.1/lib/thor/invocation.rb:127:in `invoke_command'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/thor-1.3.1/lib/thor.rb:527:in `dispatch'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/command/base.rb:87:in `perform'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/command.rb:48:in `invoke'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/railties-7.0.8.4/lib/rails/commands.rb:18:in `<main>'
        from /usr/local/lib/ruby/3.3.0/bundled_gems.rb:74:in `require'
        from /usr/local/lib/ruby/3.3.0/bundled_gems.rb:74:in `block (2 levels) in replace_require'
        from /var/www/discourse/vendor/bundle/ruby/3.3.0/gems/bootsnap-1.18.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
        from script/rails:8:in `<top (required)>'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli/exec.rb:58:in `load'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli/exec.rb:58:in `kernel_load'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli/exec.rb:23:in `run'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli.rb:451:in `exec'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/command.rb:28:in `run'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor.rb:527:in `dispatch'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli.rb:34:in `dispatch'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/vendor/thor/lib/thor/base.rb:584:in `start'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/cli.rb:28:in `start'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/exe/bundle:28:in `block in <top (required)>'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
        from /usr/local/lib/ruby/gems/3.3.0/gems/bundler-2.5.3/exe/bundle:20:in `<top (required)>'
        from /usr/local/bin/bundle:25:in `load'
        from /usr/local/bin/bundle:25:in `<main>'

Code of Conduct

mdecimus commented 3 months ago

Try setting the log level to trace and provide the Stalwart logs after a POP3 connection attempt.

programmerjake commented 3 months ago

Try setting the log level to trace and provide the Stalwart logs after a POP3 connection attempt.

ok, done. I added the log.

programmerjake commented 3 months ago

I would guess you forgot to flush the TlsStream before dropping it, so it doesn't write the final TLS stuff and openssl on the other end complains that the TLS stuff was truncated.

programmerjake commented 3 months ago

I'm able to reproduce the eof error from python, which likely makes debugging it much easier:

SSLKEYLOGFILE=sslkey.log python3 -c $'import poplib\nc=poplib.POP3_SSL("localhost")\nc.user("forum")\nc.pass_("<password>")\nc.quit()'

Output:

Traceback (most recent call last):
  File "<string>", line 5, in <module>
  File "/usr/lib/python3.11/poplib.py", line 279, in quit
    resp = self._shortcmd('QUIT')
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/poplib.py", line 181, in _shortcmd
    return self._getresp()
           ^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/poplib.py", line 154, in _getresp
    resp, o = self._getline()
              ^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/poplib.py", line 138, in _getline
    if not line: raise error_proto('-ERR EOF')
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
poplib.error_proto: -ERR EOF

Stalwart Logs:

2024-06-28T01:56:53.549554Z DEBUG common::listener::tls: No SNI certificate found by name, using default. context="tls" event="not-found" client_name="localhost"
2024-06-28T01:56:53.550555Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=58656}: pop3::session: event="write" data="+OK Stalwart POP3 at your service.\r\n" size=36
2024-06-28T01:56:53.550733Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=58656}: pop3::session: event="write" data="+OK forum is a valid mailbox\r\n" size=30
2024-06-28T01:56:53.552998Z TRACE session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=58656}: pop3::session: event="write" data="+OK Authentication successful\r\n" size=31
2024-06-28T01:56:53.553087Z DEBUG session{instance="pop3s" protocol=Pop3 remote.ip="172.18.0.1" remote.port=58656}: pop3::session: Disconnecting client. event="disconnect"
programmerjake commented 3 months ago

looks like you need to call TlsStream::shutdown (calls poll_shutdown) which is what sends the TLS close messages. Just dropping the TlsStream doesn't work since it can't run any async work in drop.

programmerjake commented 3 months ago

also, the QUIT command is supposed to have a response, but Stalwart doesn't send anything: https://www.ietf.org/rfc/rfc1939.html#section-6