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

This is a known issue Bob;

https://jira.kopano.io/browse/KC-759

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!