Logging: add timestamps for eventdriven IO
[citadel.git] / citadel / modules / smtp / serv_smtpeventclient.c
index fba5e6e462a01a5c36ebb9cb4116e818a7b033ab..3037b0c0c65e39cb7f7a7fecb4c843365f2800a2 100644 (file)
  * The VRFY and EXPN commands have been removed from this implementation
  * because nobody uses these commands anymore, except for spammers.
  *
- * Copyright (c) 1998-2009 by the citadel.org team
+ * Copyright (c) 1998-2012 by the citadel.org team
  *
- *  This program is free software; you can redistribute it and/or modify
- *  it under the terms of the GNU General Public License as published by
- *  the Free Software Foundation; either version 3 of the License, or
- *  (at your option) any later version.
+ *  This program is open source software; you can redistribute it and/or modify
+ *  it under the terms of the GNU General Public License version 3.
+ *  
+ *  
  *
  *  This program is distributed in the hope that it will be useful,
  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  *  GNU General Public License for more details.
  *
- *  You should have received a copy of the GNU General Public License
- *  along with this program; if not, write to the Free Software
- *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+ *  
+ *  
+ *  
  */
 
 #include "sysdep.h"
@@ -106,7 +106,7 @@ void DeleteSmtpOutMsg(void *v)
        FreeURL(&Msg->Relay);
        FreeStrBuf(&Msg->msgtext);
        FreeAsyncIOContents(&Msg->IO);
-///    memset (Msg, 0, sizeof(SmtpOutMsg)); /* just to be shure... */
+       memset (Msg, 0, sizeof(SmtpOutMsg)); /* just to be shure... */
        free(Msg);
 }
 
@@ -117,10 +117,16 @@ eNextState SMTP_C_DispatchReadDone(AsyncIO *IO);
 eNextState SMTP_C_DispatchWriteDone(AsyncIO *IO);
 eNextState SMTP_C_DNSFail(AsyncIO *IO);
 eNextState SMTP_C_Terminate(AsyncIO *IO);
+eNextState SMTP_C_TerminateDB(AsyncIO *IO);
 eReadState SMTP_C_ReadServerStatus(AsyncIO *IO);
 
 eNextState mx_connect_ip(AsyncIO *IO);
 eNextState get_one_mx_host_ip(AsyncIO *IO);
+eNextState FinalizeMessageSendDB(AsyncIO *IO);
+eNextState FinalizeMessageSend_DB1(AsyncIO *IO);
+eNextState FinalizeMessageSend_DB2(AsyncIO *IO);
+eNextState FinalizeMessageSend_DB3(AsyncIO *IO);
+eNextState FinalizeMessageSend_DB4(AsyncIO *IO);
 
 /******************************************************************************
  * So, we're finished with sending (regardless of success or failure)         *
@@ -128,21 +134,52 @@ eNextState get_one_mx_host_ip(AsyncIO *IO);
  * we need to free the memory and send bounce messages (on terminal failure)  *
  * else we just free our SMTP-Message struct.                                 *
  ******************************************************************************/
-void FinalizeMessageSend(SmtpOutMsg *Msg)
+inline void FinalizeMessageSend_1(AsyncIO *IO)
 {
-       int IDestructQueItem;
-       int nRemain;
-       StrBuf *MsgData;
-       AsyncIO *IO = &Msg->IO;
+       const char *Status;
+       SmtpOutMsg *Msg = IO->Data;
+       
+       if (Msg->MyQEntry->Status == 2) 
+               Status = "Delivery Successfull.";
+       else if (Msg->MyQEntry->Status == 5) 
+               Status = "Delivery failed permanently; giving up.";
+       else
+               Status = "Delivery failed temporarily; will retry later.";
+                       
+       EVS_syslog(LOG_INFO,
+                  "SMTP: %s Time[%fs] Recipient <%s> @ <%s> (%s) Statusmessage: %s\n",
+                  Status,
+                  Msg->IO.Now - Msg->IO.StartIO,
+                  Msg->user,
+                  Msg->node,
+                  Msg->name,
+                  ChrPtr(Msg->MyQEntry->StatusMessage));
 
-       IDestructQueItem = DecreaseQReference(Msg->MyQItem);
 
-       nRemain = CountActiveQueueEntries(Msg->MyQItem);
+       Msg->IDestructQueItem = DecreaseQReference(Msg->MyQItem);
 
-       if ((nRemain > 0) || IDestructQueItem)
-               MsgData = SerializeQueueItem(Msg->MyQItem);
+       Msg->nRemain = CountActiveQueueEntries(Msg->MyQItem);
+
+       if (Msg->MyQEntry->Active && 
+           CheckQEntryIsBounce(Msg->MyQEntry))
+       {
+               /* are we casue for a bounce mail? */
+               Msg->MyQItem->SendBounceMail |= (1<<Msg->MyQEntry->Status);
+       }
+
+       if ((Msg->nRemain > 0) || Msg->IDestructQueItem)
+               Msg->QMsgData = SerializeQueueItem(Msg->MyQItem);
        else
-               MsgData = NULL;
+               Msg->QMsgData = NULL;
+}
+eNextState FinalizeMessageSend(SmtpOutMsg *Msg)
+{
+       return QueueDBOperation(&Msg->IO, FinalizeMessageSend_DB1);
+}
+
+inline void FinalizeMessageSend_DB_1(AsyncIO *IO)
+{
+       SmtpOutMsg *Msg = IO->Data;
 
        /*
         * Uncompleted delivery instructions remain, so delete the old
@@ -150,11 +187,35 @@ void FinalizeMessageSend(SmtpOutMsg *Msg)
         */
        EVS_syslog(LOG_DEBUG, "SMTPQD: %ld", Msg->MyQItem->QueMsgID);
        CtdlDeleteMessages(SMTP_SPOOLOUT_ROOM, &Msg->MyQItem->QueMsgID, 1, "");
+}
+eNextState FinalizeMessageSend_DB1(AsyncIO *IO)
+{
+       FinalizeMessageSend_1(IO);
+       FinalizeMessageSend_DB_1(IO);
+       return NextDBOperation(IO, FinalizeMessageSend_DB2);
+}
 
-       if (IDestructQueItem)
-               smtpq_do_bounce(Msg->MyQItem,Msg->msgtext);
 
-       if (nRemain > 0)
+inline void FinalizeMessageSend_DB_2(AsyncIO *IO)
+{
+       SmtpOutMsg *Msg = IO->Data;
+
+       if (Msg->IDestructQueItem)
+               smtpq_do_bounce(Msg->MyQItem, Msg->msgtext);
+}
+eNextState FinalizeMessageSend_DB2(AsyncIO *IO)
+{
+       FinalizeMessageSend_DB_2(IO);
+
+       return NextDBOperation(IO, FinalizeMessageSend_DB3);
+}
+
+
+inline void FinalizeMessageSend_DB_3(AsyncIO *IO)
+{
+       SmtpOutMsg *Msg = IO->Data;
+
+       if (Msg->nRemain > 0)
        {
                struct CtdlMessage *msg;
                msg = malloc(sizeof(struct CtdlMessage));
@@ -162,7 +223,8 @@ void FinalizeMessageSend(SmtpOutMsg *Msg)
                msg->cm_magic = CTDLMESSAGE_MAGIC;
                msg->cm_anon_type = MES_NORMAL;
                msg->cm_format_type = FMT_RFC822;
-               msg->cm_fields['M'] = SmashStrBuf(&MsgData);
+               msg->cm_fields['M'] = SmashStrBuf(&Msg->QMsgData);
+               msg->cm_fields['U'] = strdup("QMSG");
                Msg->MyQItem->QueMsgID =
                        CtdlSubmitMsg(msg, NULL, SMTP_SPOOLOUT_ROOM, QP_EADDR);
                EVS_syslog(LOG_DEBUG, "SMTPQ: %ld", Msg->MyQItem->QueMsgID);
@@ -173,12 +235,40 @@ void FinalizeMessageSend(SmtpOutMsg *Msg)
                                   &Msg->MyQItem->MessageID,
                                   1,
                                   "");
-               FreeStrBuf(&MsgData);
+               FreeStrBuf(&Msg->QMsgData);
        }
+       DecreaseShutdownDeliveries(Msg->MyQItem);
+}
+eNextState FinalizeMessageSend_DB3(AsyncIO *IO)
+{
+       SmtpOutMsg *Msg = IO->Data;
+       FinalizeMessageSend_DB_3(IO);
+       if (!Msg->IDestructQueItem)
+               return eAbort;
+       return NextDBOperation(IO, FinalizeMessageSend_DB4);
+}
+
+eNextState FinalizeMessageSend_DB4(AsyncIO *IO)
+{
+       int Done;
+       SmtpOutMsg *Msg = IO->Data;
+
+       Done = GetShutdownDeliveries(Msg->MyQItem);
+       if (!Done) 
+               return NextDBOperation(IO, FinalizeMessageSend_DB4);
+       else
+               return eAbort;
+}
+
+eNextState FinalizeMessageSend_DB(AsyncIO *IO)
+{
+       SmtpOutMsg *Msg = IO->Data;
+
        RemoveContext(Msg->IO.CitContext);
-       if (IDestructQueItem)
+       if (Msg->IDestructQueItem)
                RemoveQItem(Msg->MyQItem);
        DeleteSmtpOutMsg(Msg);
+       return eAbort;
 }
 
 eNextState FailOneAttempt(AsyncIO *IO)
@@ -283,6 +373,9 @@ eNextState get_one_mx_host_ip_done(AsyncIO *IO)
        struct hostent *hostent;
 
        QueryCbDone(IO);
+       EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n",
+                  __FUNCTION__,
+                  IO->Now - IO->DNS.Start);
 
        hostent = Msg->HostLookup.VParsedDNSReply;
        if ((Msg->HostLookup.DNSStatus == ARES_SUCCESS) &&
@@ -317,10 +410,19 @@ eNextState get_one_mx_host_ip_done(AsyncIO *IO)
                        addr->sin_port   = htons(DefaultMXPort);
                }
                Msg->mx_host = Msg->pCurrRelay->Host;
+               if (Msg->HostLookup.VParsedDNSReply != NULL) {
+                       Msg->HostLookup.DNSReplyFree(Msg->HostLookup.VParsedDNSReply);
+                       Msg->HostLookup.VParsedDNSReply = NULL;
+               }
                return mx_connect_ip(IO);
        }
-       else
+       else {
+               if (Msg->HostLookup.VParsedDNSReply != NULL) {
+                       Msg->HostLookup.DNSReplyFree(Msg->HostLookup.VParsedDNSReply);
+                       Msg->HostLookup.VParsedDNSReply = NULL;
+               }
                return FailOneAttempt(IO);
+       }
 }
 
 eNextState get_one_mx_host_ip(AsyncIO *IO)
@@ -333,8 +435,6 @@ eNextState get_one_mx_host_ip(AsyncIO *IO)
         * - one of the mx'es
         */
 
-       InitC_ares_dns(IO);
-
        EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
 
        EVS_syslog(LOG_DEBUG,
@@ -371,7 +471,10 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO)
 
        QueryCbDone(IO);
 
-       EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
+       EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n",
+                  __FUNCTION__,
+               IO->Now - IO->DNS.Start);
+
        pp = &Msg->Relay;
        while ((pp != NULL) && (*pp != NULL) && ((*pp)->Next != NULL))
                pp = &(*pp)->Next;
@@ -379,7 +482,6 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO)
        if ((IO->DNS.Query->DNSStatus == ARES_SUCCESS) &&
            (IO->DNS.Query->VParsedDNSReply != NULL))
        { /* ok, we found mx records. */
-               Msg->IO.ErrMsg = Msg->MyQEntry->StatusMessage;
 
                Msg->CurrMX
                        = Msg->AllMX
@@ -391,13 +493,29 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO)
 
                                p = (ParsedURL*) malloc(sizeof(ParsedURL));
                                memset(p, 0, sizeof(ParsedURL));
+                               p->Priority = Msg->CurrMX->priority;
                                p->IsIP = 0;
                                p->Port = DefaultMXPort;
                                p->IPv6 = i == 1;
                                p->Host = Msg->CurrMX->host;
-
-                               *pp = p;
-                               pp = &p->Next;
+                               if (*pp == NULL)
+                                       *pp = p;
+                               else {
+                                       ParsedURL *ppp = *pp;
+
+                                       while ((ppp->Next != NULL) &&
+                                              (ppp->Next->Priority <= p->Priority))
+                                              ppp = ppp->Next;
+                                       if ((ppp == *pp) &&
+                                           (ppp->Priority > p->Priority)) {
+                                               p->Next = *pp;
+                                               *pp = p;
+                                       }
+                                       else {
+                                               p->Next = ppp->Next;
+                                               ppp->Next = p;
+                                       }
+                               }
                        }
                        Msg->CurrMX    = Msg->CurrMX->next;
                }
@@ -420,7 +538,11 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO)
                }
                Msg->CXFlags   = Msg->CXFlags & F_DIRECT;
        }
-       *pp = Msg->MyQItem->FallBackHost;
+       if (Msg->MyQItem->FallBackHost != NULL)
+       {
+               Msg->MyQItem->FallBackHost->Next = *pp;
+               *pp = Msg->MyQItem->FallBackHost;
+       }
        Msg->pCurrRelay = Msg->Relay;
        return get_one_mx_host_ip(IO);
 }
@@ -474,10 +596,13 @@ SmtpOutMsg *new_smtp_outmsg(OneQueItem *MyQItem,
                     SMTP_C_DispatchWriteDone,
                     SMTP_C_DispatchReadDone,
                     SMTP_C_Terminate,
+                    SMTP_C_TerminateDB,
                     SMTP_C_ConnFail,
                     SMTP_C_Timeout,
                     SMTP_C_Shutdown);
 
+       Msg->IO.ErrMsg = Msg->MyQEntry->StatusMessage;
+
        return Msg;
 }
 
@@ -532,7 +657,11 @@ void smtp_try_one_queue_entry(OneQueItem *MyQItem,
                        StrBufPlain(Msg->MyQEntry->StatusMessage,
                                    HKEY("Invalid Recipient!"));
                }
-               FinalizeMessageSend(Msg);
+               FinalizeMessageSend_1(&Msg->IO);
+               FinalizeMessageSend_DB_1(&Msg->IO);
+               FinalizeMessageSend_DB_2(&Msg->IO);
+               FinalizeMessageSend_DB_3(&Msg->IO);
+               FinalizeMessageSend_DB(&Msg->IO);
        }
 }
 
@@ -561,7 +690,7 @@ void SMTPSetTimeout(eNextState NextTCPState, SmtpOutMsg *Msg)
                        /* if we're sending a huge message,
                         * we need more time.
                         */
-                       Timeout += StrLength(Msg->msgtext) / 1024;
+                       Timeout += StrLength(Msg->msgtext) / 512;
                }
                break;
        case eReadMessage:
@@ -571,7 +700,7 @@ void SMTPSetTimeout(eNextState NextTCPState, SmtpOutMsg *Msg)
                         * some mailservers take a nap before accepting
                         * the message content inspection and such.
                         */
-                       Timeout += StrLength(Msg->msgtext) / 1024;
+                       Timeout += StrLength(Msg->msgtext) / 512;
                }
                break;
        case eSendDNSQuery:
@@ -621,8 +750,12 @@ eNextState SMTP_C_Terminate(AsyncIO *IO)
        SmtpOutMsg *Msg = IO->Data;
 
        EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
-       FinalizeMessageSend(Msg);
-       return eAbort;
+       return FinalizeMessageSend(Msg);
+}
+eNextState SMTP_C_TerminateDB(AsyncIO *IO)
+{
+       EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
+       return FinalizeMessageSend_DB(IO);
 }
 eNextState SMTP_C_Timeout(AsyncIO *IO)
 {
@@ -631,7 +764,10 @@ eNextState SMTP_C_Timeout(AsyncIO *IO)
        Msg->MyQEntry->Status = 4;
        EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
        StrBufPlain(IO->ErrMsg, CKEY(ReadErrors[Msg->State]));
-       return FailOneAttempt(IO);
+       if (Msg->State > eRCPT)
+               return eAbort;
+       else
+               return FailOneAttempt(IO);
 }
 eNextState SMTP_C_ConnFail(AsyncIO *IO)
 {
@@ -657,8 +793,7 @@ eNextState SMTP_C_Shutdown(AsyncIO *IO)
        Msg->MyQEntry->Status = 3;
        StrBufPlain(Msg->MyQEntry->StatusMessage,
                    HKEY("server shutdown during message submit."));
-       FinalizeMessageSend(Msg);
-       return eAbort;
+       return FinalizeMessageSend(Msg);
 }