search

postalserver / postal

📮 A fully featured open source mail delivery platform for incoming & outgoing e-mail
https://postalserver.io
MIT License
14.4k stars 1.02k forks source link

Database connection not re-astablished #3023

Open notz opened 3 days ago

notz commented 3 days ago

We use postal on kubernetes with a managed database from OVH. After OVH applied a security update on the database servers, the smtp server wasn't working anymore.

On smtp client we received: can't modify frozen String: "end of file reached"

Here is a log from one smtp session:

2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/message.rb:278:in `save_raw_message' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/message.rb:208:in `save' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/client.rb:506:in `block in finished' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/client.rb:490:in `each' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/client.rb:490:in `finished' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/client.rb:429:in `block in data' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/client.rb:72:in `handle' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:204:in `block (2 levels) in run_event_loop' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:106:in `select' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:106:in `block in run_event_loop' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:104:in `loop' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:104:in `run_event_loop' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:39:in `block in run' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /usr/local/bundle/gems/klogger-logger-1.4.0/lib/klogger/group_set.rb:18:in `call_without_id' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /usr/local/bundle/gems/klogger-logger-1.4.0/lib/klogger/logger.rb:72:in `tagged' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/app/lib/smtp_server/server.rb:37:in `run' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.805 2024-07-01 07:36:01 +0000 ERROR  script/smtp_server.rb:13:in `<main>' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:311:in `block in escape' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/connection_pool.rb:20:in `use' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:345:in `with_mysql' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:303:in `escape' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:232:in `block in insert' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:232:in `map' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:232:in `insert' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.804 2024-07-01 07:36:01 +0000 ERROR  /opt/postal/app/lib/postal/message_db/database.rb:125:in `insert_raw_message' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.803 2024-07-01 07:36:01 +0000 ERROR  An error occurred while processing data from a client. trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.803 2024-07-01 07:36:01 +0000 ERROR  NoMethodError: undefined method `escape' for nil:NilClass trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.756 2024-07-01 07:36:01 +0000 DEBUG  <= Date: Mon, 01 Jul 2024 07:36:01 +0000 trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.756 2024-07-01 07:36:01 +0000 DEBUG  Not logging further message data. trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.755 2024-07-01 07:36:01 +0000 DEBUG  => 354 Go ahead trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.754 2024-07-01 07:36:01 +0000 DEBUG  Added external address 'xxx.xxxr@test.me' trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.754 2024-07-01 07:36:01 +0000 DEBUG  => 250 OK trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.754 2024-07-01 07:36:01 +0000 DEBUG  <= DATA trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.753 2024-07-01 07:36:01 +0000 DEBUG  <= MAIL FROM:<noreply@test.me> trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.753 2024-07-01 07:36:01 +0000 DEBUG  => 250 OK trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.753 2024-07-01 07:36:01 +0000 DEBUG  <= RCPT TO:<xxx.xxx@test.me> trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.749 2024-07-01 07:36:01 +0000 DEBUG  => 235 Granted for service/psy-discourse trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.742 2024-07-01 07:36:01 +0000 DEBUG  <= xxx trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.742 2024-07-01 07:36:01 +0000 DEBUG  => 334 UGFzc3dvcmQ6 trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.742 2024-07-01 07:36:01 +0000 DEBUG  <= [redacted] trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.741 2024-07-01 07:36:01 +0000 DEBUG  <= AUTH LOGIN trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.741 2024-07-01 07:36:01 +0000 DEBUG  => 334 VXNlcm5hbWU6 trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.694 2024-07-01 07:36:01 +0000 DEBUG  <= EHLO localhost.localdomain trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.694 2024-07-01 07:36:01 +0000 DEBUG  => 250-My capabilities are trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.694 2024-07-01 07:36:01 +0000 DEBUG  => 250 AUTH CRAM-MD5 PLAIN LOGIN trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.689 2024-07-01 07:36:01 +0000 DEBUG  <= STARTTLS trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.689 2024-07-01 07:36:01 +0000 DEBUG  => 220 Ready to start TLS trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.645 2024-07-01 07:36:01 +0000 DEBUG  <= EHLO localhost.localdomain trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.645 2024-07-01 07:36:01 +0000 DEBUG  => 250-My capabilities are trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.645 2024-07-01 07:36:01 +0000 DEBUG  => 250-STARTTLS trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.645 2024-07-01 07:36:01 +0000 DEBUG  => 250 AUTH CRAM-MD5 PLAIN LOGIN trace_id=E0LLJEZE component=smtp-server
2024-07-01 09:36:01.644 2024-07-01 07:36:01 +0000 DEBUG  Client identified as 10.2.4.69 trace_id=E0LLJEZE component=smtp-server

Here is the evidence for the database change: image

The other pods for web & worker pods have restarted after the database change. So there was no problem.

Expected behaviour

Database connection should be restored.

Environment details

willpower232 commented 3 days ago

So everything is working now it has been restarted and there was only a failure whilst the change was applied and the connection was broken?

notz commented 3 days ago

@willpower232 yes, after pod restart everything was working fine.