Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Database connection not re-astablished #3023

Open
notz opened this issue Jul 1, 2024 · 6 comments
Open

Database connection not re-astablished #3023

notz opened this issue Jul 1, 2024 · 6 comments
Labels
bug

Comments

@notz
Copy link

notz commented Jul 1, 2024 •
edited
Loading

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 '[email protected]' 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:<[email protected]> 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:<[email protected]> 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

  • OS: Managed Kubernetes 1.29 with pods for smtp, web & workers
  • Database: Managed MySql 8.0 by OVH
  • Version: ghcr.io/postalserver/postal:3.3.4
@willpower232
Copy link
Collaborator

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
Copy link
Author

notz commented Jul 1, 2024

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

@notz notz mentioned this issue Jul 15, 2024
Open
@notz
Copy link
Author

notz commented Jul 15, 2024

@adamcooke Any chance to implement a re-connection. Had the same problem again. All smtp & worker pods have to be restarted to get it working.

I'm no ruby developer. But perhaps i should give it a try.

@github-actions GitHub Actions
Copy link
Contributor

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@github-actions github-actions bot added the stale label Aug 15, 2024
@github-actions GitHub Actions
Copy link
Contributor

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 5 days.

@github-actions github-actions bot added the stale label Sep 15, 2024
@willpower232 willpower232 added bug and removed stale labels Sep 16, 2024
@memcorrupt
Copy link

+1 - this issue also happens to me

postal logs:

postal-web-1  | 2024-09-26 20:52:15 +0000 ERROR  POST /api/v1/send/message (500) event=request transaction=[snip] controller=LegacyAPI::SendController action=message format=html method=POST path=/api/v1/send/message request_id=[snip] ip_address=[snip] status=500 db_runtime=6.752912521362305 exception_class=Mysql2::Error::ConnectionError exception_message=MySQL server has gone away exception_backtrace=/usr/local/bundle/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `_query'\n/usr/local/bundle/gems/mysql2-0.5.6/lib/mysql2/client.rb:151:in `block in query'\n/usr/local/bundle/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `handle_interrupt'\n/usr/local/bundle/gems/mysql2-0.5.6/lib/mysql2/client.rb:150:in `query'

mariadb logs:

[Warning] Aborted connection 34409 to db: 'unconnected' user: 'x' host: 'localhost' (Got timeout reading communication packets)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@notz @willpower232 @memcorrupt