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 failed

If 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 exiting

I 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.db

However 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 exiting

The 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=86400

And 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

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!

Log in to reply

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.