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.

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

Amavis error after clean setup modoboa #3116

Open
doker445 opened this issue Nov 8, 2023 · 12 comments
Open

Amavis error after clean setup modoboa #3116

doker445 opened this issue Nov 8, 2023 · 12 comments

Comments

@doker445
Copy link

doker445 commented Nov 8, 2023

Impacted versions

  • OS Type: Ubuntu
  • OS Version: 22.04 LTS
  • Database Type: PostgreSQL
  • Database version: 14.9
  • Modoboa: 2.2.2
  • installer used: Yes
  • Webserver: Nginx

Steps to reproduce

Clear setup and try to get email.

Current behavior

Get following error in mail.log:
Nov 8 16:41:05 mail2 amavis[11816]: (11816-04) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169.
Nov 8 16:41:08 mail2 amavis[11816]: (11816-04) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169.
Nov 8 16:41:11 mail2 amavis[11816]: (11816-04) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169.
Nov 8 16:41:14 mail2 amavis[11816]: (11816-04) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169.
Nov 8 16:41:14 mail2 amavis[11816]: (11816-04) (!!)ERROR sql_storage: too many retries on storing final, info not saved

Expected behavior

Video/Screenshot link (optional)

@tonioo
Copy link
Member

tonioo commented Nov 9, 2023

@doker445 Do you have more logs to show?

@doker445
Copy link
Author

doker445 commented Nov 9, 2023

In error log always get next event:
Nov 9 17:07:28 mail2 amavis[519067]: (519067-18) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:13:11 mail2 amavis[519069]: (519069-20) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:23:12 mail2 amavis[526395]: (526395-01) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:25:22 mail2 amavis[526624]: (526624-01) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:26:30 mail2 amavis[526395]: (526395-02) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:27:13 mail2 amavis[526624]: (526624-02) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:29:59 mail2 amavis[526395]: (526395-03) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:30:36 mail2 amavis[526624]: (526624-03) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:41:03 mail2 amavis[526395]: (526395-04) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:43:36 mail2 amavis[526624]: (526624-04) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:44:12 mail2 amavis[526395]: (526395-05) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:49:08 mail2 amavis[526395]: (526395-06) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:51:17 mail2 amavis[526624]: (526624-06) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:54:16 mail2 amavis[526395]: (526395-07) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:55:13 mail2 amavis[526624]: (526624-07) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:56:39 mail2 amavis[526395]: (526395-08) (!!)ERROR sql_storage: too many retries on storing final, info not saved

In mail.log:
Nov 9 17:48:57 mail2 postfix/smtpd[531147]: connect from localhost[127.0.0.1]
Nov 9 17:48:57 mail2 postfix/smtpd[531147]: B2AF483D1D: client=localhost[127.0.0.1], orig_client=mail.senderdomain.com[sender_ip]
Nov 9 17:48:57 mail2 postfix/cleanup[531148]: B2AF483D1D: message-id=89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com
Nov 9 17:48:57 mail2 opendkim[17273]: B2AF483D1D: no signing table match for 'mail@senderdomain.com'
Nov 9 17:48:57 mail2 opendkim[17273]: B2AF483D1D: signature=CQyMUN4I domain=senderdomain.com selector=mail result="no signature error"
Nov 9 17:48:57 mail2 opendkim[17273]: B2AF483D1D: DKIM verification successful
Nov 9 17:48:57 mail2 opendkim[17273]: B2AF483D1D: s=mail d=senderdomain.com a=rsa-sha256 SSL
Nov 9 17:48:57 mail2 postfix/qmgr[452343]: B2AF483D1D: from=mail@senderdomain.com, size=540434, nrcpt=4 (queue active)
Nov 9 17:48:57 mail2 postfix/smtpd[531147]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 quit=1 commands=6
Nov 9 17:48:57 mail2 amavis[526395]: (526395-06) Passed CLEAN {RelayedInbound}, [sender_ip]:42491 [sender_ip] mail@senderdomain.com -> myalias@mydomain.com, Message-ID: 89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com, mail_id: EpSoNMTMZyL8, Hits: -2.797, size: 539799, queued_as: B2AF483D1D, dkim_sd=mail:senderdomain.com, 2312 ms
Nov 9 17:48:57 mail2 amavis[526395]: (526395-06) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169, line 7035.
Nov 9 17:48:57 mail2 dovecot: lmtp(531150): Connect from local
Nov 9 17:48:57 mail2 dovecot: lmtp(user3@mydomain.com)<531150><DDvuOGn/TGXOGggAF04bsg>: msgid=89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com: saved mail to INBOX
Nov 9 17:48:58 mail2 dovecot: lmtp(user2@mydomain.com)<531150><DDvuOGn/TGXOGggAF04bsg:2>: msgid=89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com: saved mail to INBOX
Nov 9 17:48:58 mail2 dovecot: lmtp(user1@mydomain.com)<531150><DDvuOGn/TGXOGggAF04bsg:3>: msgid=89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com: saved mail to INBOX
Nov 9 17:48:58 mail2 dovecot: lmtp(user4@mydomain.com)<531150><DDvuOGn/TGXOGggAF04bsg:4>: msgid=89776e96d35c6463d960a18764033b5d2023119174854@senderdomain.com: saved mail to INBOX
Nov 9 17:48:58 mail2 postfix/lmtp[531149]: B2AF483D1D: to=user3@mydomain.com, orig_to=myalias@mydomain.com, relay=mail.mydomain.com[private/dovecot-lmtp], delay=0.38, delays=0.18/0.03/0.02/0.15, dsn=2.0.0, status=sent (250 2.0.0 user3@mydomain.com DDvuOGn/TGXOGggAF04bsg Saved)
Nov 9 17:48:58 mail2 dovecot: lmtp(531150): Disconnect from local: Logged out (state=READY)
Nov 9 17:48:58 mail2 postfix/lmtp[531149]: B2AF483D1D: to=user2@mydomain.com, orig_to=myalias@mydomain.com, relay=mail.mydomain.com[private/dovecot-lmtp], delay=0.38, delays=0.18/0.03/0.02/0.15, dsn=2.0.0, status=sent (250 2.0.0 user2@mydomain.com DDvuOGn/TGXOGggAF04bsg:2 Saved)
Nov 9 17:48:58 mail2 postfix/lmtp[531149]: B2AF483D1D: to=user1@mydomain.com, orig_to=myalias@mydomain.com, relay=mail.mydomain.com[private/dovecot-lmtp], delay=0.38, delays=0.18/0.03/0.02/0.15, dsn=2.0.0, status=sent (250 2.0.0 user1@mydomain.com DDvuOGn/TGXOGggAF04bsg:3 Saved)
Nov 9 17:48:58 mail2 postfix/lmtp[531149]: B2AF483D1D: to=user4@mydomain.com, orig_to=myalias@mydomain.com, relay=mail.mydomain.com[private/dovecot-lmtp], delay=0.38, delays=0.18/0.03/0.02/0.15, dsn=2.0.0, status=sent (250 2.0.0 user4@mydomain.com DDvuOGn/TGXOGggAF04bsg:4 Saved)
Nov 9 17:48:58 mail2 postfix/qmgr[452343]: B2AF483D1D: removed
Nov 9 17:49:00 mail2 amavis[526395]: (526395-06) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169, line 7035.
Nov 9 17:49:03 mail2 amavis[526395]: (526395-06) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169, line 7035.
Nov 9 17:49:06 mail2 amavis[526395]: (526395-06) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169, line 7035.
Nov 9 17:49:08 mail2 amavis[526395]: (526395-06) (!)WARN save_info_final: sql exec: err=, , Wide character in subroutine entry at (eval 123) line 169, line 7035.
Nov 9 17:49:08 mail2 amavis[526395]: (526395-06) (!!)ERROR sql_storage: too many retries on storing final, info not saved
Nov 9 17:49:08 mail2 postfix/smtpd[531120]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as B2AF3D1D; from=mail@senderdomain.com to=myalias@mydomain.com proto=ESMTP helo=<senderdomain.com>
Nov 9 17:49:08 mail2 postfix/smtpd[531120]: disconnect from mail.senderdomain.com[sender_ip] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7

@tonioo
Copy link
Member

tonioo commented Nov 10, 2023

@doker445 My guess is that the generated password contains strange characters... Can you check amavis configuration file? (/etc/amavis/conf.d/50-user)

@tonioo
Copy link
Member

tonioo commented Nov 10, 2023

Or it might also be an issue with the content amavis is trying to store in the database...

@doker445
Copy link
Author

/etc/amavis/conf.d/50-user

Password look like ok.
@lookup_sql_dsn = ( [ 'DBI:Pg:database=amavis;host=127.0.0.1;port=5432', 'amavis', 'B3tKDwJcfeqqLWUE' ]);

Copy link

stale bot commented Mar 17, 2024

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the stale stale status label Mar 17, 2024
@layer3-fl
Copy link

layer3-fl commented Mar 18, 2024

This is present in my logs today after fresh install on top of fresh Debian 12 OS install Saturday evening. No strange characters in my password either.

@stale stale bot removed the stale stale status label Mar 18, 2024
@layer3-fl
Copy link

Good morning,

I have confirmed in my logs that this is happening anytime there is an email with emojis in the subject.

I found this which is same error but in the iRed mail forums:
https://forum.iredmail.org/topic16612-amavis-error-sqlstorage-too-many-retries-on-storing-final.html

With the answer being:


Re: AMAVIS: ERROR sql_storage: too many retries on storing final

ok, it's clear caused by emojis.
Converting to column "msgs.subject" to VARBINARY type should fix this issue:

USE amavisd;
ALTER TABLE msgs MODIFY COLUMN subject VARBINARY(255) NOT NULL DEFAULT '';

Let me know how it works.


Of course the database for Modoboa is amavis, not amavisd so don't copy and paste that command as it will fail as written.
Me being the careful person I am have not run the command to alter the database.

Can anyone from Modoboa chime in on this and confirm its safe to apply to Modoboa and that it will fix the issue?

Regards,
Matt

@tonioo
Copy link
Member

tonioo commented Mar 19, 2024

@layer3-fl That's something you can try but I can't guarantee it will fix your issue since the error in your logs is not exactly the same

@layer3-fl
Copy link

Thank you and understood,
Can you at least guarantee that this modification to the database will not damage/corrupt installation of Modoboa? I would not perform any DB modification that you can not define as safe.

@tonioo
Copy link
Member

tonioo commented Mar 20, 2024

It won't corrupt the installation.

@layer3-fl
Copy link

Thanks for the response.

As written above I get syntax error near MODIFY.

After a little googling specifying Postgres, I tried:
ALTER TABLE msgs ALTER COLUMN subject VARBINARY(255) NOT NULL DEFAULT '';
and get syntax error near VARBINARY

After more googling I found references to not being able to perform this modification in Postgres if there is existing data in the column. A new column has to be created as type VARBINARY(255), use UPDATE statement to add data to new column, drop VARCHAR(MAX) column and rename VARBINARY(255) column to the name the VARCHAR(MAX) column had been.

Not being a DB admin this has gotten past my "pay grade" so to speak. My mail is working and I receive the emails with emoji's in the subject, there are just errors in the logs. Not knowing what the actual repercussions of the errors are if any, I am going to let it be unless someone more knowledgeable in SQL than I am can provide syntax to perform the conversion. Perhaps this can be addressed in a later version if it is actually causing any harm or preventing a function from being properly performed.

Thanks again!
-Matt

@Spitfireap Spitfireap modified the milestone: 3.0.0 May 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants