mirror of
https://github.com/modoboa/modoboa.git
synced 2026-04-25 00:46:03 +03:00
[GH-ISSUE #3116] Amavis error after clean setup modoboa #1768
Labels
No labels
bug
bug
dependencies
design
documentation
duplicate
enhancement
enhancement
enhancement
feedback-needed
help-needed
help-needed
installer
invalid
looking-for-sponsors
modoboa-contacts
new-ui
new-ui
pr
pull-request
pyconfr
python
question
security
stale
webmail
wontfix
No milestone
No project
No assignees
1 participant
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
starred/modoboa-modoboa#1768
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Originally created by @doker445 on GitHub (Nov 8, 2023).
Original GitHub issue: https://github.com/modoboa/modoboa/issues/3116
Impacted versions
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 commented on GitHub (Nov 9, 2023):
@doker445 Do you have more logs to show?
@doker445 commented on GitHub (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 commented on GitHub (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 commented on GitHub (Nov 10, 2023):
Or it might also be an issue with the content amavis is trying to store in the database...
@doker445 commented on GitHub (Nov 13, 2023):
Password look like ok.
@lookup_sql_dsn = ( [ 'DBI:Pg:database=amavis;host=127.0.0.1;port=5432', 'amavis', 'B3tKDwJcfeqqLWUE' ]);
@stale[bot] commented on GitHub (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.
@layer3-fl commented on GitHub (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.
@layer3-fl commented on GitHub (Mar 19, 2024):
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 commented on GitHub (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 commented on GitHub (Mar 19, 2024):
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 commented on GitHub (Mar 20, 2024):
It won't corrupt the installation.
@layer3-fl commented on GitHub (Mar 20, 2024):
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
@theitmachine commented on GitHub (Aug 14, 2024):
Updating from 203 to 2.2.3 and ubuntu 20.04 to 22.04
This error has cropped up and killing amavis every few minutes.
Is there a way to purge the amavis table and recreate it from the latest schema?
@stale[bot] commented on GitHub (Jan 31, 2025):
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.