Redmine Internal error at saviong wiki pages, due to faulty e-mail sending
Added by Zs Vizi about 2 years ago
Hi everybody,
I'm facing some issues with my redmine application. The problem is that whenever a wiki page is edited, after a few seconds of waiting after clicking on Save, all I get is the default Internal error page. The interesting part is that the wiki page gets edited, also the e-mails to the subscribed members are sent, only the web server gives error. If I disable e-mail sending for editing wiki pages, I don't get any error message, the page is still saved...etc. Though this is not a real solution to the problem. Also, e-mail sending in general works. If I send a test e-mail on config/e-mail notifications, I get the test e-mail without any error.
I'm using the dockerhub version of redmine and mysql as well. The interfaces of the host are passed to the docker container, and the redmine app (running on port 3000) is hosted by nginx on port 443. Here's the contents of the redmine info bar:
Environment: Redmine version 5.0.2.stable Ruby version 3.1.2-p20 (2022-04-12) [x86_64-linux] Rails version 6.1.6 Environment production Database adapter Mysql2 Mailer queue ActiveJob::QueueAdapters::AsyncAdapter Mailer delivery smtp Redmine settings: Redmine theme Default SCM: Subversion 1.14.1 Mercurial 5.6.1 Bazaar 3.1.0 Git 2.30.2 Filesystem Redmine plugins: no plugin installed
I know I should check the production.log, which would help...if there was any. I'm using log rotation, at least that works for a very basic level, but it only contains info messages, somehow it doesn't even show errors.
I read in some very old topics that in production level there are no more verbose logs, but still I don't see why error messages don't show up. I tried to look for solutions here as well as in other forums, all I got were some unanswered, 10-13 year old threads from here.
I could really use some help what can be the problem.
Replies (1)
RE: Redmine Internal error at saviong wiki pages, due to faulty e-mail sending - Added by Zs Vizi about 2 years ago
I could finally alter the config to log email errors in production environment, so at least I have some info about this error. So, after editing the wiki page, I get a bunch of
I, [2022-11-10T10:25:33.458202 #1] INFO -- : Enqueued ActionMailer::MailDeliveryJob (Job ID: 48d16c5e-bfd9-4892-8d2c-c421640a9be0) to Async(mailers) with arguments: "Mailer", "wiki_content_updated", "deliver_now", {:args=>[#<GlobalID:0x00007fc818a26510 @uri=#<URI::GID gid://redmine-app/User/6>>, #<GlobalID:0x00007fc818b50f80 @uri=#<URI::GID gid://redmine-app/WikiContent/33>>]}
... then tries to redirect to the page, and also tries to send e-mails:
I, [2022-11-10T10:25:33.498935 #1] INFO -- : Performing ActionMailer::MailDeliveryJob (Job ID: a87f6d83-046b-4866-b77e-40147c9b0104) from Async(mailers) enqueued at 2022-11-10T10:25:33Z with arguments: "Mailer", "wiki_content_updated", "deliver_now", {:args=>[#<GlobalID:0x00007fc817ae8e18 @uri=#<URI::GID gid://redmine-app/User/4>>, #<GlobalID:0x00007fc817aef5d8 @uri=#<URI::GID gid://redmine-app/WikiContent/33>>]} (...) I, [2022-11-10T10:25:33.507578 #1] INFO -- : Processing by WikiController#show as HTML I, [2022-11-10T10:25:33.507655 #1] INFO -- : Parameters: {"project_id"=>"PROJECT_NAME", "id"=>"PAGE_NAME"} I, [2022-11-10T10:25:33.527146 #1] INFO -- : Rendered mailer/wiki_content_updated.text.erb within layouts/mailer (Duration: 2.7ms | Allocations: 759) I, [2022-11-10T10:25:33.547900 #1] INFO -- : Rendered mailer/wiki_content_updated.text.erb within layouts/mailer (Duration: 0.2ms | Allocations: 76) I, [2022-11-10T10:25:33.548918 #1] INFO -- : Rendered layout layouts/mailer.text.erb (Duration: 24.5ms | Allocations: 7235)
But it fails, so it gives me the error page. Which is funny, because just after it can send the damn e-mails...
F, [2022-11-10T10:25:38.510155 #1] FATAL -- : ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use): app/models/user.rb:474:in `verify_session_token' app/controllers/application_controller.rb:86:in `session_expired?' app/controllers/application_controller.rb:76:in `session_expiration' I, [2022-11-10T10:25:39.220150 #1] INFO -- : Delivered mail redmine.wiki_content-33.20221110102533.6@DOMAIN (5651.4ms) I, [2022-11-10T10:25:39.220468 #1] INFO -- : Performed ActionMailer::MailDeliveryJob (Job ID: 48d16c5e-bfd9-4892-8d2c-c421640a9be0) from Async(mailers) in 5717.18ms
What I don't really understand is why "async" mail sending is even mentioned in the logs, if it was removed years ago? I migrated the redmine database from an older setup which indeed is long enough to have async mail sending still in it. Does that mean that those (now faulty) settings are somehow migrated too? In my config/configuration.yml I only set up the smtp email sending, and otherwise (eg. test notification mail) it works fine.
Is there any setting in config files to remove this async sending or make it work with the new modules, or should I increase the timeout period for maybe 10-15 sec, and if so, where can I change it? All I found are 10+ year old threads with not working links and even if I view those with web archieve, none of them has any useful info for me.