After upgrading to Znuny 6.3.3 error: There was an error executing Execute() in Kernel::System::Console::Command::Maint…

[KaiHerlemann]

Hi,

after upgrading to Znuny 6.3.3 (from 6.2.1), we get the following error:

Code: Select all

ERROR: OTRS-otrs.Console.pl-Maint::PostMaster::MailAccountFetch-10 Perl: 5.16.3 OS: linux Time: Tue May 10 18:26:25 2022

 Message: There was an error executing Execute() in Kernel::System::Console::Command::Maint::PostMaster::MailAccountFetch: Console command 'MailAccountFetch' is failed.

 Traceback (47250): 
   Module: Kernel::System::Daemon::DaemonModules::BaseTaskWorker::_HandleError Line: 50
   Module: Kernel::System::Daemon::DaemonModules::SchedulerTaskWorker::Cron::Run Line: 175
   Module: Kernel::System::Daemon::DaemonModules::SchedulerTaskWorker::Run Line: 233
   Module: (eval) Line: 331
   Module: main::Start Line: 331
   Module: /opt/otrs/bin/otrs.Daemon.pl Line: 152

It seems like we get the error if there is a mail received (not if is fetching for mails in case there's no new mail), but not every time. As far as I see yet, all emails are properly processed.
Unfortunately, the traceback says only something about the executed Perl modules. [Maybe there should be a possibility in the sysconfig to set the --debug param for the Maint::PostMaster::MailAccountFetch command? - EDIT: already possible]

Operating system is CentOS 7, Perl modules are:

Code: Select all

  o Apache::DBI......................ok (v1.12)
  o Apache2::Reload..................ok (v0.13)
  o Archive::Tar.....................ok (v2.38)
  o Archive::Zip.....................ok (v1.68)
  o Authen::SASL.....................ok (v2.15)
  o Crypt::Eksblowfish::Bcrypt.......ok (v0.009)
  o CSS::Minifier::XS................ok (v0.13)
  o Data::UUID.......................ok (v1.226)
  o Date::Format.....................ok (v2.24)
  o DateTime.........................ok (v1.04)
    o DateTime::TimeZone.............ok (v2.38)
  o DBI..............................ok (v1.643)
  o DBD::mysql.......................ok (v4.050)
  o DBD::ODBC........................Not installed! (optional - Required to connect to a MS-SQL database.)
  o DBD::Oracle......................Not installed! (optional - Required to connect to a Oracle database.)
  o DBD::Pg..........................Not installed! To install, you can use: 'yum install "perl(DBD::Pg)"'. (optional - Required to connect to a PostgreSQL database.)
  o Digest::SHA......................ok (v5.85)
  o Encode::HanExtra.................ok (v0.23)
  o Excel::Writer::XLSX..............ok (v0.95)
  o Hash::Merge......................ok (v0.302)
  o IO::Socket::SSL..................ok (v2.068)
  o JavaScript::Minifier::XS.........ok (v0.14)
  o Jq...............................Not installed! To install, you can use: 'yum install "perl(Jq)"'. (optional - Support for extended condition checking via Jq for the generic interface.)
  o JSON::XS.........................ok (v3.01)
  o List::Util::XS...................ok (v1.54)
  o LWP::UserAgent...................ok (v6.53)
  o Mail::IMAPClient.................ok (v3.37)
    o IO::Socket::SSL................ok (v2.068)
    o Authen::NTLM...................ok (v1.09)
  o ModPerl::Util....................ok (v2.000011)
  o Moo..............................ok (v2.004000)
  o Net::DNS.........................ok (v0.72)
  o Net::LDAP........................ok (v0.56)
  o Net::SMTP........................ok (v3.13)
  o Spreadsheet::XLSX................ok (v0.17)
  o Template.........................ok (v2.24)
  o Template::Stash::XS..............ok (undef)
  o Text::Diff::FormattedHTML........ok (v0.08)
  o Text::CSV_XS.....................ok (v1.00)
  o Time::HiRes......................ok (v1.9725)
  o XML::LibXML......................ok (v2.0207)
  o XML::LibXSLT.....................ok (v1.80)
  o XML::Parser......................ok (v2.41)
  o YAML::XS.........................ok (v0.54)

We use IMAP. I tried then another then another mail server on our test system (GMail and thus IMAPS instead of IMAP), it was the same problem.

I am not absolutely certain that we did not have the problem with 6.2.1, unfortunately the logs have so far only been saved for one day. Maybe the standard setting of Daemon::Log::DaysToKeep should be changed?

Regards,
Kai

[tms]

Glad to find this here, I was just about to open the same ticket.
We encountered the same problem since we upgraded from znuny 6.2.2 to 6.3.1.
It's hard to investigate as we don't find details on the error. --debug works fine when executing the MailAccountFetch from the command line (but in my tests I got no error during those fetches), but setting --debug in the sysconfig entry for MailAccountFetch does not show more details in the stdout.
So this is just a hint that it may be indeed a problem with the 6.3 version. I would be very happy if someone has an idea how to investigate this further.
Thanks a lot in advance
and best regards,
Stefanie

[tms]

Further remark: before upgrading to 6.3.1 we sometimes got "Error: Timeout of 600 seconds reached, killing child process!".
In this cases emails indeed were not fetched. I did investigations on this about two years ago and didn't found a proper solution. But as emails were read fine in the next step and this error occured only in ~0.3% of the fetch operations, this was acceptable for us.
I just recognized now: actually I didn't saw this error anymore since upgrading to 6.3.1. Maybe something was changed in this regard which causes the new error? Now the emails are fetched fine, but the message "MailAccountFetch is failed" occurs in about ~20% of the fetches nevertheless (which makes it difficult to recognize if there are indeed fetching problems).
Just a small guess.

[KaiHerlemann]

Further remark: before upgrading to 6.3.1 we sometimes got "Error: Timeout of 600 seconds reached, killing child process!".
In this cases emails indeed were not fetched. I did investigations on this about two years ago and didn't found a proper solution. But as emails were read fine in the next step and this error occured only in ~0.3% of the fetch operations, this was acceptable for us.
I just recognized now: actually I didn't saw this error anymore since upgrading to 6.3.1. Maybe something was changed in this regard which causes the new error? Now the emails are fetched fine, but the message "MailAccountFetch is failed" occurs in about ~20% of the fetches nevertheless (which makes it difficult to recognize if there are indeed fetching problems).
Just a small guess.

It's related for me.

We had the issue before the upgrade, but really very, very seldom. – This error message which I cited above, and also that one which is stating that there're too many instances of the process parallel running, but not the "Error: Timeout of 600 seconds reached, killing child process!" one.
As it was so seldom, I'm not sure in which case we had the issue, I think it was mainly after restarting.

[tms]

Hi,
I still have no idea how to investigate this further.
I saw that version 6.3.1 was a feature release thich introduced OAuth authentication for e-mail accounts. We don't use OAuth, but obviously something was done on mailing interfaces. But also not sure if this is related..
Best regards,
Stefanie

[hkais]

I had a very similar issue in the past 3.x, 4.x and 5.x

The major issue there was, that a big e-mail could not get fetched over and over again and thus blocked the fetching.
We had the issue on POP3 and on IMAP

The easiest way to check this is to login via thunderbird or similar tool to the mail account and to verify mails there.
Ensure that you do not modify the status of the mails by configuring your mail client not to mark them read. Also here we had strange effects in the past.

A stable fix for this was to increase mailfetchsize with enough base64 overhead buffer of OTRS/Znuny so that surely all mails can be received.

Maybe this is also your issue?

[tms]

Thanks a lot for your proposal!
As a pity, this is not the case for us, we already have PostMasterMaxEmailSize configured and are monitoring if there is a mail which is still too big. There is no big email leftover on one of the connected mail accounts.
Thanks and best,
Stefanie

[hkais]

welcome

and there was also no mail left in the mailbox which could not be fetched?

[hkais]

checked the code of your issue.
https://github.com/znuny/Znuny/blob/18b ... ker.pm#L50

It looks like that your log file is failing to write. The file shall be configured here:

Code: Select all

LogModule::LogFile 

I would check file permissions and if file is writable to your znuny/otrs user
If the file is missing try to create it with your znuny/otrs user

[tms]

We have SysLog defined for LogModule, so it's not writing to a dedicated file, but using the syslog daemon. Error messages are written to /var/log/messages, and there I also find the error messages like

Code: Select all

...  OTRS-otrs.Console.pl-Maint::PostMaster::MailAccountFetch-10[72917]: [Error][Kernel::System::Daemon::DaemonModules::BaseTaskWorker::_HandleError][Line:50]: There was an error executing Execute() in Kernel::System::Console::Command::Maint::PostMaster::MailAccountFetch: Console command 'MailAccountFetch' is failed.

Same error messages are also listed in the System Log View in znuny. And in those cases we also get an email from the OTRS Scheduler Daemon Cron::MailAccountFetch.
But unfortunatly I cannot see more details why it failed or which part is failing. Indeed all emails are read fine, there are no emails left on any connected account. But of course I would like to avoid that the situations gets worse and emails are indeed not fetched. And the current situation makes it difficult to detect real problems, yesterday an email indeed get stucked and I saw it only with delay because I didn't recognized that the body in the (at the moment regular incoming) error mail of the OTRS Scheduler Daemon changed. If we can solve the problem we will not be flooded by error messages and mails anymore and I would be able to realize such a problem directly.

Do you have an idea how to use

Code: Select all

 ./bin/otrs.Console.pl Maint::PostMaster::MailAccountFetch --debug 

from sysconfig? From command line it worked (but no error at that moment), I tried to set --debug in the params section of the sysconfig entry for MailAccountFetch (Daemon::SchedulerCronTaskManager::Task###MailAccountFetch ). This was possible, but does not show more details in the stdout (and not in /var/log/messages).

Thanks,
Stefanie

[hkais]

are you able to switch temporarily from syslog to file based to test if the syslog maybe the issue?

regarding debug. Puhh need to check used it about years ago last time. Will get back to this

[tms]

are you able to switch temporarily from syslog to file based to test if the syslog maybe the issue?

I could try it during next maintenance. To be honest I don't think that this is the problem, we are running it via syslog for years now and the error occured after switch to the new znuny release, not after e.g. OS updates. And in that case I would assume the error to occur during every fetch? But this is not the case, and the error messages are successfully written to /var/log/messages. But maybe worth a try.

A good hin to look more closely into the code, maybe https://github.com/znuny/Znuny/blob/18b ... nt/IMAP.pm ? Maybe mails are fetched fine and then (for whatever reason) there occurs a re-connect which causes afterwards the "failed" message. Will have a closer look.

regarding debug. Puhh need to check used it about years ago last time. Will get back to this

Thanks!

[hkais]

are you able to switch temporarily from syslog to file based to test if the syslog maybe the issue?

I could try it during next maintenance. To be honest I don't think that this is the problem, we are running it via syslog for years now and the error occured after switch to the new znuny release, not after e.g. OS updates. And in that case I would assume the error to occur during every fetch? But this is not the case, and the error messages are successfully written to /var/log/messages. But maybe worth a try.

It is not clear from there it is coming the issue, so from the traceback it looks like the logging is the root cause.
So I would do the cross check. But see further down

A good hin to look more closely into the code, maybe https://github.com/znuny/Znuny/blob/18b ... nt/IMAP.pm ? Maybe mails are fetched fine and then (for whatever reason) there occurs a re-connect which causes afterwards the "failed" message. Will have a closer look.

you should ensure that the given files are the files like in the repository. So would do the cross check with the real sources on your machine.

Especially the
Kernel::System::Daemon::DaemonModules::SchedulerTaskWorker::Cron::Run Line: 175
looks strange to me, since on github this line is empty.
https://github.com/znuny/Znuny/blob/18b ... er.pm#L175

Can you share the code which is on your machine at the given lines? And if it differs, can you do a compare of the distribution files vs the files active on your sever?

regarding debug. Puhh need to check used it about years ago last time. Will get back to this

Thanks!

checked this
I was sure there was an option to configure log level per module. I thought I used it on upgrade from 4.x to 5.x
But could not find it anymore.

There is one central configuration for the log level. This will bloat your logging of all components, but you could narrow the issue maybe down.

in sys config look out for

Code: Select all

MinimumLogLevel

[tms]

The code differs because your link points to the dev-branch, in the branch 6.3 you find our code: https://github.com/znuny/Znuny/blob/rel ... er/Cron.pm.

I understood the traceback in the way, that there the error was handled, e.g. in Cron.pm it's just the output we get "There was an error executing $Function() in $Param{Data}->{Module}: $ErrorMessage". And BaseTaskWorker l.50 points to ../Kernel/System/Log where File.pm and SysLog.pm are specified. I just saw this: the error seems to be get from the STDERR ( l.133 in /opt/otrs/Kernel/System/Daemon/DaemonModules/SchedulerTaskWorker/Cron.pm) of the tasks. But maybe you're still right.

Thanks for the pointer to MinimumLogLevel! I will try this, I will need to schedule a maintenance for these tests after pentecost.

[hkais]

The code differs because your link points to the dev-branch, in the branch 6.3 you find our code: https://github.com/znuny/Znuny/blob/rel ... er/Cron.pm.

strange I changed to the tag rel-6-3-3...

I understood the traceback in the way, that there the error was handled, e.g. in Cron.pm it's just the output we get "There was an error executing $Function() in $Param{Data}->{Module}: $ErrorMessage". And BaseTaskWorker l.50 points to ../Kernel/System/Log where File.pm and SysLog.pm are specified. I just saw this: the error seems to be get from the STDERR ( l.133 in /opt/otrs/Kernel/System/Daemon/DaemonModules/SchedulerTaskWorker/Cron.pm) of the tasks. But maybe you're still right.

traceback is the inversed execution order causing your problem

Thanks for the pointer to MinimumLogLevel! I will try this, I will need to schedule a maintenance for these tests after pentecost.

welcome

please keep me updated, pretty interested in the root cause too (because having same path to do on upgrade, still on 6.1.x)

[shawnbeasley]

Thanks for the pointer to MinimumLogLevel! I will try this, I will need to schedule a maintenance for these tests after pentecost.

You may have to try disabling the Daemon cron task, and logging via the normal console command.

Add this to your crontab.

*/5 * * * * $HOME/bin/otrs.Console.pl Maint::PostMaster::MailAccountFetch >> $HOME/var/log/mail_fetch.log 2>&1

[Johannes]

The code differs because your link points to the dev-branch, in the branch 6.3 you find our code: https://github.com/znuny/Znuny/blob/rel ... er/Cron.pm.

I understood the traceback in the way, that there the error was handled, e.g. in Cron.pm it's just the output we get "There was an error executing $Function() in $Param{Data}->{Module}: $ErrorMessage". And BaseTaskWorker l.50 points to ../Kernel/System/Log where File.pm and SysLog.pm are specified. I just saw this: the error seems to be get from the STDERR ( l.133 in /opt/otrs/Kernel/System/Daemon/DaemonModules/SchedulerTaskWorker/Cron.pm) of the tasks. But maybe you're still right.

Thanks for the pointer to MinimumLogLevel! I will try this, I will need to schedule a maintenance for these tests after pentecost.

Hi KaiHerlemann,
hi tms,

we can not reproduce this :/
I have additional questions:
@TMS may I ask what mailserver is on the other end?
@KaiHerlemann is a "default" Gmail account or something special? Would it be possible to get access to your test instance for some debugging?

Thanks
Johannes

[tms]

@TMS may I ask what mailserver is on the other end?

It's our central campus mailserver, afaik a microsoft exchange server, we access it via imaps.

Thanks,
Stefanie

[tms]

Hi all,

I had a maintenance today, tried to switch to LogModule "File", but this did not work as expected, did not saw any messages. I had not much time to investigate that further and switched back to syslog (errors are logged correctly in /var/log/messages).

I was a little frightend that MimimumLogLevel "Debug" would cause a flood of log messages, so I followed the idea of shawnbeasley first to do the fetch via cron. That way, I can add --debug directly to the MailAccountFetch. We will see now if we get more insight in the cause of the problem. Otherwise I will try MinimumLogLevel.

Best,
Stefanie

[kivide]

Hi,

we are getting the same "error" message after upgrading from 6.2.1 to 6.3.1. We are fetching the mails from our mailserver (based on dovecot). I made a clone from our otrs production system, removed all PostMaster-MailAccounts and added a Test-MailAccount. But we also got the error message after fetching mails on this system .

Then I made a clean install of otrs with the Test-MailAccount. This time we could fetch Mails without any error messages.

I compared the files from 6.2.1 with 6.3.1 on our system and found out that some changes were made on the error report for MailAccountFetch.pm. I found the commit, which belongs to these changes:

https://github.com/znuny/Znuny/commit/3 ... 1570ac262c

After removing these lines on our Clone-Dev-System we did not get this "error" message anymore.

I hope this could help.

[Johannes]

Hi,

thats correct. The actual change is in 6.3.3. and is a regression.
We are investigating this, but are confident that the "fix" will be rolled back and modified for 6.4.

You can safely use the 6.2 Version from MailAccountFetch.pm and place it in the Custom Folder.

Regards
Johannes

[tms]

Dear kivide,
thanks for your investigations! And Johannes, thanks for the confirmation!
Just fyi, from console I didn't saw any errors.
I now copied the 6.2.2-MailAccountFetch.pm to the custom folder and switched again to letting the Deamon run the command. Works fine!
Thanks to all of you!
Stefanie

[KaiHerlemann]

Hi,

thanks to everyone for the joint efforts to solve the problem!
I'm just wondering why kivide hadn't the problem, when he made a clean test install (with (6.3.x, as far as I think)? I marked it bold in the answer below.

Regards,
Kai

Hi,

we are getting the same "error" message after upgrading from 6.2.1 to 6.3.1. We are fetching the mails from our mailserver (based on dovecot). I made a clone from our otrs production system, removed all PostMaster-MailAccounts and added a Test-MailAccount. But we also got the error message after fetching mails on this system .

Then I made a clean install of otrs with the Test-MailAccount. This time we could fetch Mails without any error messages.

I compared the files from 6.2.1 with 6.3.1 on our system and found out that some changes were made on the error report for MailAccountFetch.pm. I found the commit, which belongs to these changes:

https://github.com/znuny/Znuny/commit/3 ... 1570ac262c

After removing these lines on our Clone-Dev-System we did not get this "error" message anymore.

I hope this could help.

[hkais]

is this issue fixed in 6.4 and integrated in the released version?

[shawnbeasley]

This issue is fixed in rel-6_4