From b5d9a5debc8a174d269a5bb5d2e63df836ef397a Mon Sep 17 00:00:00 2001 From: Wilfried Goesgens Date: Sun, 29 Apr 2012 12:13:34 +0200 Subject: [PATCH] SMTP-Client: streamline logging; make look more uniq --- citadel/modules/smtp/serv_smtpeventclient.c | 62 ++++++++++----------- citadel/modules/smtp/serv_smtpqueue.c | 15 +++-- citadel/modules/smtp/smtp_clienthandlers.c | 13 ++--- citadel/modules/smtp/smtp_clienthandlers.h | 17 ++++-- 4 files changed, 57 insertions(+), 50 deletions(-) diff --git a/citadel/modules/smtp/serv_smtpeventclient.c b/citadel/modules/smtp/serv_smtpeventclient.c index f15a18564..d98a2181b 100644 --- a/citadel/modules/smtp/serv_smtpeventclient.c +++ b/citadel/modules/smtp/serv_smtpeventclient.c @@ -96,7 +96,7 @@ void DeleteSmtpOutMsg(void *v) { SmtpOutMsg *Msg = v; AsyncIO *IO = &Msg->IO; - EV_syslog(LOG_DEBUG, "SMTP: %s Aborting\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s Exit\n", __FUNCTION__); /* these are kept in our own space and free'd below */ Msg->IO.ConnectMe = NULL; @@ -148,7 +148,7 @@ inline void FinalizeMessageSend_1(AsyncIO *IO) Status = "Delivery failed temporarily; will retry later."; EVS_syslog(LOG_INFO, - "SMTP: %s Time[%fs] Recipient <%s> @ <%s> (%s) Status message: %s\n", + "%s Time[%fs] Recipient <%s> @ <%s> (%s) Status message: %s\n", Status, Msg->IO.Now - Msg->IO.StartIO, Msg->user, @@ -186,7 +186,7 @@ inline void FinalizeMessageSend_DB_1(AsyncIO *IO) * Uncompleted delivery instructions remain, so delete the old * instructions and replace with the updated ones. */ - EVS_syslog(LOG_DEBUG, "SMTPQD: %ld", Msg->MyQItem->QueMsgID); + EVS_syslog(LOG_DEBUG, "%ld", Msg->MyQItem->QueMsgID); CtdlDeleteMessages(SMTP_SPOOLOUT_ROOM, &Msg->MyQItem->QueMsgID, 1, ""); } eNextState FinalizeMessageSend_DB1(AsyncIO *IO) @@ -228,7 +228,7 @@ inline void FinalizeMessageSend_DB_3(AsyncIO *IO) 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); + EVS_syslog(LOG_DEBUG, "%ld", Msg->MyQItem->QueMsgID); CtdlFreeMessage(msg); } else { @@ -290,16 +290,16 @@ eNextState FailOneAttempt(AsyncIO *IO) Msg->pCurrRelay = Msg->pCurrRelay->Next; if (Msg->pCurrRelay == NULL) { - EVS_syslog(LOG_DEBUG, "SMTP: %s Aborting\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s Aborting\n", __FUNCTION__); return eAbort; } if (Msg->pCurrRelay->IsIP) { - EVS_syslog(LOG_DEBUG, "SMTP: %s connecting IP\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s connecting IP\n", __FUNCTION__); return mx_connect_ip(IO); } else { EVS_syslog(LOG_DEBUG, - "SMTP: %s resolving next MX Record\n", + "%s resolving next MX Record\n", __FUNCTION__); return get_one_mx_host_ip(IO); } @@ -332,9 +332,8 @@ void SetConnectStatus(AsyncIO *IO) if (Msg->mx_host == NULL) Msg->mx_host = ""; - EVS_syslog(LOG_DEBUG, - "SMTP client[%ld]: connecting to %s [%s]:%d ...\n", - Msg->n, + EVS_syslog(LOG_INFO, + "connecting to %s [%s]:%d ...\n", Msg->mx_host, buf, Msg->IO.ConnectMe->Port); @@ -355,7 +354,7 @@ eNextState mx_connect_ip(AsyncIO *IO) { SmtpOutMsg *Msg = IO->Data; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); IO->ConnectMe = Msg->pCurrRelay; Msg->State = eConnectMX; @@ -374,7 +373,7 @@ eNextState get_one_mx_host_ip_done(AsyncIO *IO) struct hostent *hostent; QueryCbDone(IO); - EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n", + EVS_syslog(LOG_DEBUG, "%s Time[%fs]\n", __FUNCTION__, IO->Now - IO->DNS.Start); @@ -436,11 +435,10 @@ eNextState get_one_mx_host_ip(AsyncIO *IO) * - one of the mx'es */ - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); EVS_syslog(LOG_DEBUG, - "SMTP client[%ld]: looking up %s-Record %s : %d ...\n", - Msg->n, + "looking up %s-Record %s : %d ...\n", (Msg->pCurrRelay->IPv6)? "aaaa": "a", Msg->pCurrRelay->Host, Msg->pCurrRelay->Port); @@ -472,9 +470,9 @@ eNextState smtp_resolve_mx_record_done(AsyncIO *IO) QueryCbDone(IO); - EVS_syslog(LOG_DEBUG, "SMTP: %s Time[%fs]\n", + EVS_syslog(LOG_DEBUG, "%s Time[%fs]\n", __FUNCTION__, - IO->Now - IO->DNS.Start); + IO->Now - IO->DNS.Start); pp = &Msg->Relay; while ((pp != NULL) && (*pp != NULL) && ((*pp)->Next != NULL)) @@ -552,7 +550,7 @@ eNextState resolve_mx_records(AsyncIO *IO) { SmtpOutMsg * Msg = IO->Data; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); /* start resolving MX records here. */ if (!QueueQuery(ns_t_mx, Msg->node, @@ -616,7 +614,7 @@ void smtp_try_one_queue_entry(OneQueItem *MyQItem, { SmtpOutMsg *Msg; - syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + SMTPC_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); Msg = new_smtp_outmsg(MyQItem, MyQEntry, MsgCount); if (KeepMsgText) Msg->msgtext = MsgText; @@ -630,10 +628,10 @@ void smtp_try_one_queue_entry(OneQueItem *MyQItem, sizeof(((CitContext *) Msg->IO.CitContext)->cs_host)); - syslog(LOG_DEBUG, "SMTP Starting: [%ld] <%s> CC <%d> \n", - Msg->MyQItem->MessageID, - ChrPtr(Msg->MyQEntry->Recipient), - ((CitContext*)Msg->IO.CitContext)->cs_pid); + SMTPC_syslog(LOG_DEBUG, "Starting: [%ld] <%s> CC <%d> \n", + Msg->MyQItem->MessageID, + ChrPtr(Msg->MyQEntry->Recipient), + ((CitContext*)Msg->IO.CitContext)->cs_pid); if (Msg->pCurrRelay == NULL) QueueEventContext(&Msg->IO, resolve_mx_records); @@ -680,7 +678,7 @@ void SMTPSetTimeout(eNextState NextTCPState, SmtpOutMsg *Msg) double Timeout = 0.0; AsyncIO *IO = &Msg->IO; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); switch (NextTCPState) { case eSendFile: @@ -719,7 +717,7 @@ void SMTPSetTimeout(eNextState NextTCPState, SmtpOutMsg *Msg) } eNextState SMTP_C_DispatchReadDone(AsyncIO *IO) { - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); SmtpOutMsg *Msg = IO->Data; eNextState rc; @@ -733,7 +731,7 @@ eNextState SMTP_C_DispatchReadDone(AsyncIO *IO) } eNextState SMTP_C_DispatchWriteDone(AsyncIO *IO) { - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); SmtpOutMsg *Msg = IO->Data; eNextState rc; @@ -750,12 +748,12 @@ eNextState SMTP_C_Terminate(AsyncIO *IO) { SmtpOutMsg *Msg = IO->Data; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); return FinalizeMessageSend(Msg); } eNextState SMTP_C_TerminateDB(AsyncIO *IO) { - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); return FinalizeMessageSend_DB(IO); } eNextState SMTP_C_Timeout(AsyncIO *IO) @@ -763,7 +761,7 @@ eNextState SMTP_C_Timeout(AsyncIO *IO) SmtpOutMsg *Msg = IO->Data; Msg->MyQEntry->Status = 4; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); StrBufPlain(IO->ErrMsg, CKEY(ReadErrors[Msg->State])); if (Msg->State > eRCPT) return eAbort; @@ -775,7 +773,7 @@ eNextState SMTP_C_ConnFail(AsyncIO *IO) SmtpOutMsg *Msg = IO->Data; Msg->MyQEntry->Status = 4; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); StrBufPlain(IO->ErrMsg, CKEY(ReadErrors[Msg->State])); return FailOneAttempt(IO); } @@ -783,12 +781,12 @@ eNextState SMTP_C_DNSFail(AsyncIO *IO) { SmtpOutMsg *Msg = IO->Data; Msg->MyQEntry->Status = 4; - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); return FailOneAttempt(IO); } eNextState SMTP_C_Shutdown(AsyncIO *IO) { - EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); SmtpOutMsg *Msg = IO->Data; Msg->MyQEntry->Status = 3; diff --git a/citadel/modules/smtp/serv_smtpqueue.c b/citadel/modules/smtp/serv_smtpqueue.c index 92bc9d625..a3626c8a7 100644 --- a/citadel/modules/smtp/serv_smtpqueue.c +++ b/citadel/modules/smtp/serv_smtpqueue.c @@ -86,6 +86,7 @@ #include "ctdl_module.h" #include "smtpqueue.h" +#include "smtp_clienthandlers.h" #include "event_client.h" @@ -926,6 +927,7 @@ void smtp_do_procmsg(long msgnum, void *userdata) { ChrPtr(ThisItem->Recipient), i, m); + (*((int*) userdata)) ++; smtp_try_one_queue_entry(MyQItem, ThisItem, Msg, @@ -997,16 +999,17 @@ void smtp_do_procmsg(long msgnum, void *userdata) { void smtp_do_queue(void) { static int is_running = 0; int num_processed = 0; + int num_activated = 0; if (is_running) return; /* Concurrency check - only one can run */ is_running = 1; pthread_setspecific(MyConKey, (void *)&smtp_queue_CC); - syslog(LOG_INFO, "SMTP client: processing outbound queue"); + SMTPCM_syslog(LOG_INFO, "processing outbound queue"); if (CtdlGetRoom(&CC->room, SMTP_SPOOLOUT_ROOM) != 0) { - syslog(LOG_ERR, "Cannot find room <%s>", SMTP_SPOOLOUT_ROOM); + SMTPC_syslog(LOG_ERR, "Cannot find room <%s>", SMTP_SPOOLOUT_ROOM); } else { num_processed = CtdlForEachMessage(MSGS_ALL, @@ -1015,11 +1018,11 @@ void smtp_do_queue(void) { SPOOLMIME, NULL, smtp_do_procmsg, - NULL); + &num_activated); } - syslog(LOG_INFO, - "SMTP client: queue run completed; %d messages processed", - num_processed); + SMTPC_syslog(LOG_INFO, + "queue run completed; %d messages processed %d activated", + num_processed, num_activated); run_queue_now = 0; is_running = 0; diff --git a/citadel/modules/smtp/smtp_clienthandlers.c b/citadel/modules/smtp/smtp_clienthandlers.c index 0a01805c6..c974e822b 100644 --- a/citadel/modules/smtp/smtp_clienthandlers.c +++ b/citadel/modules/smtp/smtp_clienthandlers.c @@ -106,10 +106,10 @@ #define SMTP_IS_STATE(WHICH_STATE) (ChrPtr(Msg->IO.IOBuf)[0] == WHICH_STATE) #define SMTP_DBG_SEND() \ - EVS_syslog(LOG_DEBUG, "SMTP: > %s\n", ChrPtr(Msg->IO.SendBuf.Buf)) + EVS_syslog(LOG_DEBUG, "> %s\n", ChrPtr(Msg->IO.SendBuf.Buf)) #define SMTP_DBG_READ() \ - EVS_syslog(LOG_DEBUG, "SMTP: < %s\n", ChrPtr(Msg->IO.IOBuf)) + EVS_syslog(LOG_DEBUG, "< %s\n", ChrPtr(Msg->IO.IOBuf)) /*****************************************************************************/ @@ -374,8 +374,7 @@ eNextState SMTPC_read_QUIT_reply(SmtpOutMsg *Msg) SMTP_DBG_READ(); EVS_syslog(LOG_DEBUG, - "SMTP client[%ld]: delivery to <%s> @ <%s> (%s) succeeded\n", - Msg->n, + "delivery to <%s> @ <%s> (%s) succeeded\n", Msg->user, Msg->node, Msg->name); @@ -475,7 +474,7 @@ int smtp_resolve_recipients(SmtpOutMsg *Msg) int lp, rp; int i; - EVNCS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__); + EVNCS_syslog(LOG_DEBUG, "%s\n", __FUNCTION__); if ((Msg==NULL) || (Msg->MyQEntry == NULL) || @@ -490,9 +489,7 @@ int smtp_resolve_recipients(SmtpOutMsg *Msg) Msg->name); EVNCS_syslog(LOG_DEBUG, - "SMTP client[%ld]: Attempting delivery to " - "<%s> @ <%s> (%s)\n", - Msg->n, + "Attempting delivery to <%s> @ <%s> (%s)\n", Msg->user, Msg->node, Msg->name); diff --git a/citadel/modules/smtp/smtp_clienthandlers.h b/citadel/modules/smtp/smtp_clienthandlers.h index 46532c032..149c3ddc5 100644 --- a/citadel/modules/smtp/smtp_clienthandlers.h +++ b/citadel/modules/smtp/smtp_clienthandlers.h @@ -97,18 +97,27 @@ int smtp_resolve_recipients(SmtpOutMsg *SendMsg); #define EVS_syslog(LEVEL, FORMAT, ...) \ DBGLOG(LEVEL) syslog(LEVEL, \ - "IO[%ld]CC[%d]S[%ld][%ld]" FORMAT, \ + "SMTPC:IO[%ld]CC[%d]S[%ld][%ld] " FORMAT, \ IO->ID, CCID, QID, N, __VA_ARGS__) #define EVSM_syslog(LEVEL, FORMAT) \ DBGLOG(LEVEL) syslog(LEVEL, \ - "IO[%ld]CC[%d]S[%ld][%ld]" FORMAT, \ + "SMTPC:IO[%ld]CC[%d]S[%ld][%ld] " FORMAT, \ IO->ID, CCID, QID, N) #define EVNCS_syslog(LEVEL, FORMAT, ...) \ - DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, \ + DBGLOG(LEVEL) syslog(LEVEL, "SMTPC:IO[%ld]S[%ld][%ld] " FORMAT, \ IO->ID, QID, N, __VA_ARGS__) #define EVNCSM_syslog(LEVEL, FORMAT) \ - DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, \ + DBGLOG(LEVEL) syslog(LEVEL, "SMTPC:IO[%ld]S[%ld][%ld] " FORMAT, \ IO->ID, QID, N) + +#define SMTPC_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "SMTPCQ: " FORMAT, \ + __VA_ARGS__) + +#define SMTPCM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "SMTPCQ: " FORMAT) -- 2.30.2