improve logging output of event clients & opnional DNS lookup

  - when compiling -DDEBUG_CARES a verbose trace of nameserver lookup is done
  - the log-line 'C-ARES: %s %d|%d Sock %d port %hu' can be used to identify requests in tcpdump pcap files: tcpdump -r out.pcap -w /tmp/filtered.pcap port <%hu output>
  - we log the session context, so outputs of rwho can be connected to loglines

diff --git a/citadel/event_client.h b/citadel/event_client.h
index dd334f9633311fd50c70435f7eb0eee1630843f4..6d4f50dedcb47167d48e6491ce83035cd3b8ab91 100644 (file)
--- a/citadel/event_client.h
+++ b/citadel/event_client.h
@@ -120,6 +120,9 @@ struct AsyncIO {
        /* DNS Related */
        ev_io dns_recv_event, 
                dns_send_event;
+#ifdef DEBUG_CARES
+       short int DnsSourcePort;
+#endif
        struct ares_options DNSOptions;
        ares_channel DNSChannel;
        DNSQueryParts *DNSQuery;
@@ -140,8 +143,12 @@ typedef struct _IOAddHandler {
        IO_CallBack EvAttch;
 }IOAddHandler; 
 
-#define EV_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID, __VA_ARGS__)
-#define EVM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID)
+#define CCID ((CitContext*)IO->CitContext)->cs_pid
+#define EV_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]CC[%d]" FORMAT, IO->ID, CCID, __VA_ARGS__)
+#define EVM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]CC[%d]" FORMAT, IO->ID, CCID)
+
+#define EVNC_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID, __VA_ARGS__)
+#define EVNCM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID)
 
 void FreeAsyncIOContents(AsyncIO *IO);
 

diff --git a/citadel/modules/c-ares-dns/serv_c-ares-dns.c b/citadel/modules/c-ares-dns/serv_c-ares-dns.c
index 4b00d727712bd6c1ff5c4d2b0832959ca94e99f2..a97f5368d6cbbc15efe6684bbb952ab62d8cfa7a 100644 (file)
--- a/citadel/modules/c-ares-dns/serv_c-ares-dns.c
+++ b/citadel/modules/c-ares-dns/serv_c-ares-dns.c
@@ -69,6 +69,9 @@ static void HostByAddrCb(void *data,
                          struct hostent *hostent) 
 {
        AsyncIO *IO = data;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
        IO->DNSQuery->DNSStatus = status;
        if  (status != ARES_SUCCESS) {
 //             ResolveError(*cb, status);
@@ -81,6 +84,9 @@ static void HostByAddrCb(void *data,
 static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct hostent* host;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -99,6 +105,9 @@ static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
 static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct hostent* host;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -118,6 +127,10 @@ static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
 {
        struct hostent* host;
 
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
        IO->DNSQuery->VParsedDNSReply = NULL;
@@ -137,6 +150,9 @@ static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
 static void ParseAnswerMX(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct ares_mx_reply *mx_out;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -156,6 +172,9 @@ static void ParseAnswerMX(AsyncIO *IO, unsigned char* abuf, int alen)
 static void ParseAnswerNS(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct hostent* host;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -174,6 +193,9 @@ static void ParseAnswerNS(AsyncIO *IO, unsigned char* abuf, int alen)
 static void ParseAnswerSRV(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct ares_srv_reply *srv_out;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -193,6 +215,9 @@ static void ParseAnswerSRV(AsyncIO *IO, unsigned char* abuf, int alen)
 static void ParseAnswerTXT(AsyncIO *IO, unsigned char* abuf, int alen) 
 {
        struct ares_txt_reply *txt_out;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        if (IO->DNSQuery->VParsedDNSReply != NULL)
                IO->DNSQuery->DNSReplyFree(IO->DNSQuery->VParsedDNSReply);
@@ -214,6 +239,9 @@ void QueryCb(void *arg,
             int alen) 
 {
        AsyncIO *IO = arg;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        IO->DNSQuery->DNSStatus = status;
        if (status == ARES_SUCCESS)
@@ -226,11 +254,14 @@ void QueryCb(void *arg,
                     IO_postdns_callback);
        IO->unwind_stack.data = IO;
        ev_idle_start(event_base, &IO->unwind_stack);
-       syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 }
 
 void QueryCbDone(AsyncIO *IO)
 {
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        ev_idle_stop(event_base, &IO->unwind_stack);
 }
 
@@ -238,6 +269,10 @@ void QueryCbDone(AsyncIO *IO)
 void InitC_ares_dns(AsyncIO *IO)
 {
        int optmask = 0;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        if (IO->DNSChannel == NULL) {
                optmask |= ARES_OPT_SOCK_STATE_CB;
                IO->DNSOptions.sock_state_cb = SockStateCb;
@@ -252,6 +287,9 @@ void QueueGetHostByNameDone(void *Ctx,
                            struct hostent *hostent)
 {
        AsyncIO *IO = (AsyncIO *) Ctx;
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
 
        IO->DNSQuery->DNSStatus = status;
        IO->DNSQuery->VParsedDNSReply = hostent;
@@ -261,11 +299,14 @@ void QueueGetHostByNameDone(void *Ctx,
                     IO_postdns_callback);
        IO->unwind_stack.data = IO;
        ev_idle_start(event_base, &IO->unwind_stack);
-       syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 }
 
 void QueueGetHostByName(AsyncIO *IO, const char *Hostname, DNSQueryParts *QueryParts, IO_CallBack PostDNS)
 {
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        IO->DNSQuery = QueryParts;
        IO->DNSQuery->PostDNS = PostDNS;
 
@@ -332,11 +373,20 @@ int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *Query
 
                ares_gethostbyaddr(IO->DNSChannel, address_b, length, family, HostByAddrCb, IO);
 
+#ifdef DEBUG_CARES
+               EV_syslog(LOG_DEBUG, "C-ARES: %s X1\n", __FUNCTION__);
+#endif
                return 1;
 
        default:
+#ifdef DEBUG_CARES
+               EV_syslog(LOG_DEBUG, "C-ARES: %sX2\n", __FUNCTION__);
+#endif
                return 0;
        }
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
        ares_query(IO->DNSChannel, name, ns_c_in, Type, QueryCb, IO);
        return 1;
 }
@@ -352,24 +402,50 @@ static void DNS_send_callback(struct ev_loop *loop, ev_io *watcher, int revents)
 {
        AsyncIO *IO = watcher->data;
        
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        ares_process_fd(IO->DNSChannel, ARES_SOCKET_BAD, IO->dns_send_event.fd);
 }
 static void DNS_recv_callback(struct ev_loop *loop, ev_io *watcher, int revents)
 {
        AsyncIO *IO = watcher->data;
        
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+#endif
+
        ares_process_fd(IO->DNSChannel, IO->dns_recv_event.fd, ARES_SOCKET_BAD);
 }
 
 void SockStateCb(void *data, int sock, int read, int write) 
 {
-/*
+       /*
        struct timeval tvbuf, maxtv, *ret;
        
        int64_t time = 10;
 */
        AsyncIO *IO = data;
-/* already inside of the event queue. */       
+/* already inside of the event queue. */
+#ifdef DEBUG_CARES
+{
+       struct sockaddr_in sin = {};
+       socklen_t slen;
+       slen = sizeof(sin);     
+       if ((IO->DnsSourcePort == 0) && 
+           (getsockname(sock, &sin, &slen) == 0))
+       {
+               IO->DnsSourcePort = ntohs(sin.sin_port);
+       }
+       EV_syslog(LOG_DEBUG, "C-ARES: %s %d|%d Sock %d port %hu\n",
+                 __FUNCTION__,
+                 read,
+                 write,
+                 sock,
+                 IO->DnsSourcePort);
+}
+#endif
 
        if (read) {
                if ((IO->dns_recv_event.fd != sock) &&

diff --git a/citadel/modules/smtp/serv_smtpeventclient.c b/citadel/modules/smtp/serv_smtpeventclient.c
index f6a4116492b4fb662543e3e8a3921be585f78fad..6325ff8736e3c2c4bf2ac5cad154af10a96d70da 100644 (file)
--- a/citadel/modules/smtp/serv_smtpeventclient.c
+++ b/citadel/modules/smtp/serv_smtpeventclient.c
@@ -129,7 +129,6 @@ void FinalizeMessageSend(SmtpOutMsg *Msg)
        int nRemain;
        StrBuf *MsgData;
        AsyncIO *IO = &Msg->IO;
-       EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
 
        IDestructQueItem = DecreaseQReference(Msg->MyQItem);
 
@@ -171,10 +170,9 @@ void FinalizeMessageSend(SmtpOutMsg *Msg)
                                   "");
                FreeStrBuf(&MsgData);
        }
+       RemoveContext(Msg->IO.CitContext);
        if (IDestructQueItem)
                RemoveQItem(Msg->MyQItem);
-
-       RemoveContext(Msg->IO.CitContext);
        DeleteSmtpOutMsg(Msg);
 }
 
@@ -462,7 +460,7 @@ SmtpOutMsg *new_smtp_outmsg(OneQueItem *MyQItem,
        SendMsg->IO.IOBuf         = NewStrBuf();
 
        SendMsg->IO.NextState     = eReadMessage;
-       
+
        return SendMsg;
 }
 
@@ -472,11 +470,13 @@ void smtp_try_one_queue_entry(OneQueItem *MyQItem,
                              int KeepMsgText,  /* KeepMsgText allows us to use MsgText as ours. */
                              int MsgCount)
 {
+       AsyncIO *IO;
        SmtpOutMsg *SendMsg;
 
        syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
 
        SendMsg = new_smtp_outmsg(MyQItem, MyQEntry, MsgCount);
+       IO = &SendMsg->IO;
        if (KeepMsgText) SendMsg->msgtext = MsgText;
        else             SendMsg->msgtext = NewStrBufDup(MsgText);
        
@@ -485,10 +485,15 @@ void smtp_try_one_queue_entry(OneQueItem *MyQItem,
                SubC = CloneContext (CC);
                SubC->session_specific_data = (char*) SendMsg;
                SendMsg->IO.CitContext = SubC;
-
-               syslog(LOG_DEBUG, "SMTP Starting: [%ld] <%s> \n",
+               
+               EVS_syslog(LOG_DEBUG, 
+                          "SMTP: %s new context %s - %p\n", __FUNCTION__, 
+                          ChrPtr(SendMsg->MyQEntry->Recipient),
+                          SendMsg);
+               syslog(LOG_DEBUG, "SMTP Starting: [%ld] <%s> CC <%d> \n",
                       SendMsg->MyQItem->MessageID, 
-                      ChrPtr(SendMsg->MyQEntry->Recipient));
+                      ChrPtr(SendMsg->MyQEntry->Recipient),
+                      ((CitContext*)SendMsg->IO.CitContext)->cs_pid);
                if (SendMsg->pCurrRelay == NULL)
                        QueueEventContext(&SendMsg->IO,
                                          resolve_mx_records);

diff --git a/citadel/modules/smtp/smtp_clienthandlers.c b/citadel/modules/smtp/smtp_clienthandlers.c
index 81b79bb64691d9f95b58c743698bf7ea37dfea66..677d9afa51af95edb6a3f42fcd93a4f94032e821 100644 (file)
--- a/citadel/modules/smtp/smtp_clienthandlers.c
+++ b/citadel/modules/smtp/smtp_clienthandlers.c
@@ -465,7 +465,7 @@ int smtp_resolve_recipients(SmtpOutMsg *SendMsg)
        int lp, rp;
        int i;
 
-       EVS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
+       EVNCS_syslog(LOG_DEBUG, "SMTP: %s\n", __FUNCTION__);
 
        if ((SendMsg==NULL) || 
            (SendMsg->MyQEntry == NULL) || 
@@ -479,7 +479,7 @@ int smtp_resolve_recipients(SmtpOutMsg *SendMsg)
                            SendMsg->node, 
                            SendMsg->name);
 
-       EVS_syslog(LOG_DEBUG, "SMTP client[%ld]: Attempting delivery to <%s> @ <%s> (%s)\n",
+       EVNCS_syslog(LOG_DEBUG, "SMTP client[%ld]: Attempting delivery to <%s> @ <%s> (%s)\n",
                  SendMsg->n, SendMsg->user, SendMsg->node, SendMsg->name);
        /* If no envelope_from is supplied, extract one from the message */
        SendMsg->envelope_from = ChrPtr(SendMsg->MyQItem->EnvelopeFrom);

diff --git a/citadel/modules/smtp/smtp_clienthandlers.h b/citadel/modules/smtp/smtp_clienthandlers.h
index 02120784ac306f86f0d0ce02de4e256b10576b94..ba51001af6882d6b621808a15459688b2a2ecc83 100644 (file)
--- a/citadel/modules/smtp/smtp_clienthandlers.h
+++ b/citadel/modules/smtp/smtp_clienthandlers.h
@@ -68,5 +68,7 @@ int smtp_resolve_recipients(SmtpOutMsg *SendMsg);
 
 #define QID ((SmtpOutMsg*)IO->Data)->MyQItem->MessageID
 #define N ((SmtpOutMsg*)IO->Data)->n
-#define EVS_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, IO->ID, QID, N, __VA_ARGS__)
-#define EVSM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, IO->ID, QID, N)
+#define EVS_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]CC[%d]S[%ld][%ld]" FORMAT, IO->ID, CCID, QID, N, __VA_ARGS__)
+#define EVSM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]CC[%d]S[%ld][%ld]" FORMAT, IO->ID, CCID, QID, N)
+#define EVNCS_syslog(LEVEL, FORMAT, ...) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, IO->ID, QID, N, __VA_ARGS__)
+#define EVNCSM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]S[%ld][%ld]" FORMAT, IO->ID, QID, N)