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
    

  • Kopano

    This is a known issue Bob;

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


Log in to reply
 

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