Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

    Kopano-dagent and Autoresponder failed

    Kopano Groupware Core
    4
    6
    2019
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • robertwbrandt
      robertwbrandt last edited by robertwbrandt

      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

      1 Reply Last reply Reply Quote 0
      • robertwbrandt
        robertwbrandt last edited by

        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

        1 Reply Last reply Reply Quote 0
        • robertwbrandt
          robertwbrandt last edited by

          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
          
          MarcS 1 Reply Last reply Reply Quote 0
          • MarcS
            MarcS @robertwbrandt last edited by

            This is a known issue Bob;

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

            1 Reply Last reply Reply Quote 1
            • Gerald
              Gerald last edited by Gerald

              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!

              1 Reply Last reply Reply Quote 0
              • micro
                micro last edited by micro

                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.

                1 Reply Last reply Reply Quote 0
                • First post
                  Last post