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!



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

    why 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.


Log in to reply