Kopano-dagent and Autoresponder failed
-
Since the last upgrade, our out-of-office’s are not being sent.
A look at the dagent.log shows a load of errors:
root@kopano-core:~# grep fail /var/log/kopano/dagent.log Sun Nov 19 06:37:52 2017: [error ] [12955] Autoresponder failed Sun Nov 19 07:00:02 2017: [error ] [30591] Autoresponder failed Sun Nov 19 07:01:42 2017: [error ] [31457] Autoresponder failed Sun Nov 19 07:01:43 2017: [error ] [31485] Autoresponder failed Sun Nov 19 07:01:43 2017: [error ] [31494] Autoresponder failed Sun Nov 19 07:01:43 2017: [error ] [31491] Autoresponder failed Sun Nov 19 07:01:44 2017: [error ] [31486] Autoresponder failed Sun Nov 19 07:01:44 2017: [error ] [31573] Autoresponder failed Sun Nov 19 07:01:44 2017: [error ] [31592] Autoresponder failed Sun Nov 19 07:01:47 2017: [error ] [31571] Autoresponder failed Sun Nov 19 07:01:47 2017: [error ] [31583] Autoresponder failed Sun Nov 19 07:01:47 2017: [error ] [31494] Autoresponder failedIf I look specifically at a single messsage:
root@kopano-core:~# grep 17286 /var/log/kopano/dagent.log Wed Nov 22 09:21:12 2017: [info ] [17286] Starting worker for LMTP request pid 17286 Wed Nov 22 09:21:12 2017: [notice ] [17286] Resolved recipient email.user@domain.name as user EmailUser Wed Nov 22 09:21:12 2017: [info ] [17286] * Loading plugins started Wed Nov 22 09:21:12 2017: [info ] [17286] ** Checking plugins in /var/lib/kopano/dagent/plugins Wed Nov 22 09:21:12 2017: [info ] [17286] * Loading plugins done Wed Nov 22 09:21:12 2017: [info ] [17286] Mail will be delivered in Inbox Wed Nov 22 09:21:12 2017: [info ] [17286] * PostConverting processing started Wed Nov 22 09:21:12 2017: [info ] [17286] * PostConverting processing done Wed Nov 22 09:21:12 2017: [info ] [17286] * PreDelivery processing started Wed Nov 22 09:21:12 2017: [info ] [17286] * PreDelivery processing done Wed Nov 22 09:21:12 2017: [info ] [17286] * PreRuleProcess processing started Wed Nov 22 09:21:12 2017: [info ] [17286] * PreRuleProcess processing done Wed Nov 22 09:21:12 2017: [info ] [17286] Starting autoresponder for out-of-office message Wed Nov 22 09:21:12 2017: [error ] [17286] Autoresponder failed Wed Nov 22 09:21:13 2017: [info ] [17286] * PostDelivery processing started Wed Nov 22 09:21:13 2017: [info ] [17286] * PostDelivery processing done Wed Nov 22 09:21:13 2017: [info ] [17286] * SendNewMailNotify processing started Wed Nov 22 09:21:13 2017: [info ] [17286] * SendNewMailNotify processing done Wed Nov 22 09:21:13 2017: [info ] [17286] Delivered message to "EmailUser", Subject: "Some Subject", Message-Id: <20171122092109.8A6F8200D8@sdbahcorepdb1.mail.pssc.gov.ie>, size 2641 Wed Nov 22 09:21:13 2017: [info ] [17286] Finished processing message Wed Nov 22 09:21:13 2017: [info ] [17286] LMTP thread exitingI verified that the version of kopano-dagent we have installed is: kopano-dagent/stable,now 8.4.3.4-0+12.1 amd64 [installed]
Anyone see this after their upgrade?
Thanks
Bob Brandt -
Although this thread didn’t show up when I searched originally, I found this.
However I checked the /var/lib/kopano/autorespond directory and everything looks fine…
root@kopano-core:/var/lib/kopano# ls -l autorespond/ total 6132 -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME1.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME2.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME3.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME4.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME5.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME6.db -rw------- 1 kopano kopano 1395 Nov 14 15:43 vacation-USERNAME7.db . . . -rw------- 1 kopano kopano 4518 May 20 2017 zarafa-vacation-USERNAME1.db -rw------- 1 kopano kopano 4518 May 20 2017 zarafa-vacation-USERNAME2.db -rw------- 1 kopano kopano 4518 May 20 2017 zarafa-vacation-USERNAME3.db -rw------- 1 kopano kopano 4518 May 20 2017 zarafa-vacation-USERNAME4.db -rw------- 1 kopano kopano 4518 May 20 2017 zarafa-vacation-USERNAME5.dbHowever I do see what I assume are holdovers from when it was a Zarafa system.
Everything looks good to me, permission-wise. I’m wondering if deleting the zarafa-* files will help?
Bob -
So I’m getting further…
I found the error after I enabled debugging in kopano-dagent:Wed Nov 22 10:41:48 2017: [info ] [31525] Starting worker for LMTP request pid 31525 Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Kopano Directory Service" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Private Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Public Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] < 220 2.1.5 LMTP server is ready Wed Nov 22 10:41:48 2017: [debug ] [31525] > LHLO kopano.domain.name Wed Nov 22 10:41:48 2017: [debug ] [31525] LHLO ID: kopano.domain.name Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250-SERVER ready Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250-PIPELINING Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250-ENHANCEDSTATUSCODE Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250 RSET Wed Nov 22 10:41:48 2017: [debug ] [31525] > MAIL FROM:<other.user@domain.name> Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250 2.1.0 Ok Wed Nov 22 10:41:48 2017: [debug ] [31525] > RCPT TO:<email.user@domain.name> Wed Nov 22 10:41:48 2017: [debug ] [31525] Resolved command "RCPT TO:<email.user@domain.name>" to recipient address "email.user@domain.name" Wed Nov 22 10:41:48 2017: [notice ] [31525] Resolved recipient izabel.pennec@opw.ie as user EMAILUSER Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250 2.1.5 Ok Wed Nov 22 10:41:48 2017: [debug ] [31525] > DATA Wed Nov 22 10:41:48 2017: [debug ] [31525] < 354 2.1.5 Start mail input; end with <CRLF>.<CRLF> Wed Nov 22 10:41:48 2017: [debug ] [31525] PYTHONPATH = /usr/share/kopano-dagent/python Wed Nov 22 10:41:48 2017: [info ] [31525] * Loading plugins started Wed Nov 22 10:41:48 2017: [info ] [31525] ** Checking plugins in /var/lib/kopano/dagent/plugins Wed Nov 22 10:41:48 2017: [info ] [31525] * Loading plugins done Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Kopano Directory Service" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Private Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Public Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Kopano Directory Service" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Private Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Public Folders" Wed Nov 22 10:41:48 2017: [info ] [31525] Mail will be delivered in Inbox Wed Nov 22 10:41:48 2017: [debug ] [31525] Trying to parse alternative multipart 1 of mail body Wed Nov 22 10:41:48 2017: [debug ] [31525] HTML4 meta tag found: charset="text/html; charset=utf-8" Wed Nov 22 10:41:48 2017: [debug ] [31525] HTML charset adjusted to "utf-8" Wed Nov 22 10:41:48 2017: [debug ] [31525] renovate_encoding: reading data using charset "utf-8" succeeded. Wed Nov 22 10:41:48 2017: [info ] [31525] * PostConverting processing started Wed Nov 22 10:41:48 2017: [info ] [31525] * PostConverting processing done Wed Nov 22 10:41:48 2017: [info ] [31525] * PreDelivery processing started Wed Nov 22 10:41:48 2017: [info ] [31525] * PreDelivery processing done Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Kopano Directory Service" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Private Folders" Wed Nov 22 10:41:48 2017: [debug ] [31525] Initializing provider "Public Folders" Wed Nov 22 10:41:48 2017: [info ] [31525] * PreRuleProcess processing started Wed Nov 22 10:41:48 2017: [info ] [31525] * PreRuleProcess processing done Wed Nov 22 10:41:48 2017: [debug ] [31525] Processing rule Credit Cards for EMAILUSER Wed Nov 22 10:41:48 2017: [info ] [31525] Rule Credit Cards doesn't match: 0x8004010f Wed Nov 22 10:41:48 2017: [debug ] [31525] Processing rule SagePay for EMAILUSER Wed Nov 22 10:41:48 2017: [info ] [31525] Rule SagePay doesn't match: 0x8004010f Wed Nov 22 10:41:48 2017: [debug ] [31525] Processing rule FB for EMAILUSER Wed Nov 22 10:41:48 2017: [info ] [31525] Rule FB doesn't match: 0x8004010f Wed Nov 22 10:41:48 2017: [debug ] [31525] Processing rule G4S for EMAILUSER Wed Nov 22 10:41:48 2017: [info ] [31525] Rule G4S doesn't match: 0x8004010f Wed Nov 22 10:41:48 2017: [debug ] [31525] Target user has OOF active Wed Nov 22 10:41:48 2017: [info ] [31525] Starting autoresponder for out-of-office message Wed Nov 22 10:41:48 2017: [debug ] [31525] /usr/sbin/kopano-autorespond[31529]: /usr/sbin/kopano-autorespond: 83: /usr/sbin/kopano-autorespond: arithmetic expression: expecting primary: "1508928848+$[24*60*60]" Wed Nov 22 10:41:48 2017: [error ] [31525] Autoresponder failed Wed Nov 22 10:41:48 2017: [info ] [31525] * PostDelivery processing started Wed Nov 22 10:41:48 2017: [info ] [31525] * PostDelivery processing done Wed Nov 22 10:41:48 2017: [info ] [31525] * SendNewMailNotify processing started Wed Nov 22 10:41:48 2017: [info ] [31525] * SendNewMailNotify processing done Wed Nov 22 10:41:48 2017: [debug ] [31525] Send 'New Mail' notification Wed Nov 22 10:41:48 2017: [info ] [31525] Delivered message to "penneci", Subject: "Some Subject", Message-Id: <5A15546B.8040607@domain.name>, size 19450 Wed Nov 22 10:41:48 2017: [info ] [31525] Finished processing message Wed Nov 22 10:41:48 2017: [debug ] [31525] < 250 2.1.5 email.user@domain.name Ok Wed Nov 22 10:41:50 2017: [error ] [31525] Client disconnected Wed Nov 22 10:41:50 2017: [info ] [31525] LMTP thread exitingThe bit arithmetic expression: expecting primary: “1508928848+$[24*60*60]” comes about because of my autorespond config file
root@kopano-core:/usr/lib/kopano# cat /etc/kopano/autorespond # -*- Mode: sh -*- ########################################### # Autoresponder settings ########################################### # Autorespond if the recipient is in the Cc field AUTORESPOND_CC=0 # Autorespond if the recipient is in the Bcc field AUTORESPOND_BCC=0 # Autorespond if the recipient is not in any of To, Cc or Bcc # (i.e. received the message through a distribution list) AUTORESPOND_NORECIP=0 # Only send reply to same e-mail address once per 24 hours TIMELIMIT=$[24*60*60] BASE_PATH=/var/lib/kopano/autorespond # File which contains where vacation message was sent SENDDB=$BASE_PATH/vacation-$USER.db # Tempfile containing message that will be send SENDDBTMP=$BASE_PATH/vacation-$USER-$$.tmp # Customize your actual mail command, normally sendmail # Input to this command is the message to send SENDMAILCMD=/usr/sbin/sendmail # Additional parameters for the $SENDMAILCMD # The last parameter added to the $SENDMAILCMD is $FROM, # so take that into account for the $SENDMAILPARAMS SENDMAILPARAMS="-t -f"Interestingly enough, this config file has been in use since forever!!
So I changed the file a bit:
# Only send reply to same e-mail address once per 24 hours #TIMELIMIT=$[24*60*60] = 86400 TIMELIMIT=86400And this stopped the arithmetic error from coming up!
Also, out-of-office messages are now being delivered once again, but… I’m still seeing these errors in the dagent.log file:Wed Nov 22 11:21:30 2017: [debug ] [ 3194] Target user has OOF active Wed Nov 22 11:21:30 2017: [info ] [ 3194] Starting autoresponder for out-of-office message Wed Nov 22 11:21:30 2017: [error ] [ 3194] Autoresponder failed -
This is a known issue Bob;
-
Also happens on my system (Ubuntu 16.04) with kopano-dagent/now 8.4.90.1463-0+167.1 amd64
I noticed it because autoresponses were not working. Then fixed the line
TIMELIMIT=$((24*60*60)) in /etc/kopano/autorespond (had [] before, which now seems to be no longer supported)And now autoresponder seems to work fine again. But it still says “Autoresponder failed” in dagent.log even though it works!
-
Hello all,
I also have lots of [error] Autoresponder failed lines regularly appear in dagent.log
In my signature at the bottom you can see the versions I am running. But in my case it doesn’t seem to be related to the mentioned bug because it was already fixed. To ensure: when I run the command:
grep -R -i arithemtic /var/log/kopano
I get no results.Then I raised the log level to debug in dagent.cfg and restarted that service. The error in detail:
Tue May 29 09:30:41 2018: [debug ] [ 9495] > RCPT TO:<kathy.long@mydoma.in> Tue May 29 09:30:41 2018: [debug ] [ 9495] Resolved command "RCPT TO:<kathy.long@mydoma.in>" to recipient address "kathy.long@mydoma.in" Tue May 29 09:30:41 2018: [notice ] [ 9495] Resolved recipient kathy.long@mydoma.in as user kathy Tue May 29 09:30:41 2018: [debug ] [ 9495] < 250 2.1.5 Ok Tue May 29 09:30:41 2018: [debug ] [ 9495] > DATA Tue May 29 09:30:41 2018: [debug ] [ 9495] < 354 2.1.5 Start mail input; end with <CRLF>.<CRLF> Tue May 29 09:30:41 2018: [debug ] [ 9495] PYTHONPATH = /usr/share/kopano-dagent/python Tue May 29 09:30:41 2018: [info ] [ 9495] * Loading plugins started Tue May 29 09:30:41 2018: [info ] [ 9495] ** Checking plugins in /var/lib/kopano/dagent/plugins Tue May 29 09:30:41 2018: [info ] [ 9495] * Loading plugins done Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Kopano Directory Service" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Private Folders" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Public Folders" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Kopano Directory Service" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Private Folders" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Public Folders" Tue May 29 09:30:41 2018: [info ] [ 9495] Mail will be delivered in Inbox Tue May 29 09:30:41 2018: [debug ] [ 9495] Trying to parse alternative multipart 1 of mail body Tue May 29 09:30:41 2018: [debug ] [ 9495] HTML4 meta tag found: charset="text/html; charset=iso-8859-1" Tue May 29 09:30:41 2018: [debug ] [ 9495] HTML charset adjusted to "iso-8859-1" Tue May 29 09:30:41 2018: [debug ] [ 9495] renovate_encoding: reading data using charset "iso-8859-1" succeeded. Tue May 29 09:30:41 2018: [info ] [ 9495] * PostConverting processing started Tue May 29 09:30:41 2018: [info ] [ 9495] * PostConverting processing done Tue May 29 09:30:41 2018: [info ] [ 9495] * PreDelivery processing started Tue May 29 09:30:41 2018: [info ] [ 9495] * PreDelivery processing done Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Kopano Directory Service" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Private Folders" Tue May 29 09:30:41 2018: [debug ] [ 9495] Initializing provider "Public Folders" Tue May 29 09:30:41 2018: [info ] [ 9495] * PreRuleProcess processing started Tue May 29 09:30:41 2018: [info ] [ 9495] * PreRuleProcess processing done Tue May 29 09:30:41 2018: [debug ] [ 9495] Processing rule Delegate Meetingrequest service for kathy Tue May 29 09:30:41 2018: [info ] [ 9495] Rule Delegate Meetingrequest service doesn't match: 0x8004010f Tue May 29 09:30:41 2018: [debug ] [ 9495] Processing rule Kategorien der E-Mails löschen (empfohlen) for kathy Tue May 29 09:30:41 2018: [info ] [ 9495] Rule Kategorien der E-Mails löschen (empfohlen) doesn't match: 0x8004010f Tue May 29 09:30:41 2018: [debug ] [ 9495] Target user has OOF active Tue May 29 09:30:41 2018: [info ] [ 9495] Starting autoresponder for out-of-office message Tue May 29 09:30:41 2018: [debug ] [ 9495] Running command: "/usr/sbin/kopano-autorespond" "kathy.long@mydoma.in" "peter.gens@partn.er" "Abwesend" "kathy" "/tmp/autorespond.qaQX2Q" Tue May 29 09:30:41 2018: [error ] [ 9495] Autoresponder failed Tue May 29 09:30:41 2018: [info ] [ 9495] * PostDelivery processing started Tue May 29 09:30:41 2018: [info ] [ 9495] * PostDelivery processing done Tue May 29 09:30:41 2018: [info ] [ 9495] * SendNewMailNotify processing started Tue May 29 09:30:41 2018: [info ] [ 9495] * SendNewMailNotify processing done Tue May 29 09:30:41 2018: [debug ] [ 9495] Send 'New Mail' notification Tue May 29 09:30:41 2018: [info ] [ 9495] Delivered message to "kathy", Subject: "Something", Message-Id: <08c01920b4244633aabb8a73ffa63b14@mx1-mta.partn.er>, size 47457 Tue May 29 09:30:41 2018: [info ] [ 9495] Finished processing message Tue May 29 09:30:41 2018: [debug ] [ 9495] < 250 2.1.5 kathy.long@mydoma.in Ok Tue May 29 09:30:41 2018: [debug ] [ 9495] > QUIT Tue May 29 09:30:41 2018: [debug ] [ 9495] < 221 2.0.0 Bye Tue May 29 09:30:41 2018: [info ] [ 9495] LMTP thread exitingwhy do each processed message generate such an error message? any clues where to look at and how to fix it? In the debug log I posted you also see the status code … doesn’t match: 0x8004010f appear often. Is that anything to worry about?
thanks to everyone in advance.
