From 496f41df6f4159ad132534bad4202bf2a881eae3 Mon Sep 17 00:00:00 2001 From: Wilfried Goesgens Date: Tue, 20 Dec 2011 19:47:33 +0100 Subject: [PATCH] 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 --- citadel/event_client.h | 11 ++- citadel/modules/c-ares-dns/serv_c-ares-dns.c | 84 +++++++++++++++++++- citadel/modules/smtp/serv_smtpeventclient.c | 19 +++-- citadel/modules/smtp/smtp_clienthandlers.c | 4 +- citadel/modules/smtp/smtp_clienthandlers.h | 6 +- 5 files changed, 107 insertions(+), 17 deletions(-) diff --git a/citadel/event_client.h b/citadel/event_client.h index dd334f963..6d4f50ded 100644 --- 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 4b00d7277..a97f5368d 100644 --- 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 f6a411649..6325ff873 100644 --- 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 81b79bb64..677d9afa5 100644 --- 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 02120784a..ba51001af 100644 --- 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) -- 2.30.2