Logging: add timestamps for eventdriven IO

[citadel.git] / citadel / modules / c-ares-dns / serv_c-ares-dns.c

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 a22d6c55794a3ce590c75b1bb396ec5a4cddde9a..d1b1a027e5f86d2ac33acdad19115058585d4b69 100644 (file)
--- a/citadel/modules/c-ares-dns/serv_c-ares-dns.c
+++ b/citadel/modules/c-ares-dns/serv_c-ares-dns.c
@@ -1,19 +1,19 @@
 /*
- * 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
+ *  
+ *  
+ *  
  *
  *  Inspired by NodeJS.org; thanks for the MX-Parser ;-)
  */
@@ -71,6 +71,7 @@ static void HostByAddrCb(void *data,
        AsyncIO *IO = data;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+       EV_DNS_LOGT_STOP(DNS.timeout);
 #endif
        ev_timer_stop (event_base, &IO->DNS.timeout);
 
@@ -84,7 +85,7 @@ static void HostByAddrCb(void *data,
 
 static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
 {
-       struct hostent* host;
+       struct hostent* host = NULL;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -99,6 +100,8 @@ static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
                                                      NULL,
                                                      NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (host != NULL)
+                       ares_free_hostent(host);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -110,7 +113,7 @@ static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
 
 static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen)
 {
-       struct hostent* host;
+       struct hostent* host = NULL;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -125,6 +128,8 @@ static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen)
                                                         NULL,
                                                         NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (host != NULL)
+                       ares_free_hostent(host);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -136,7 +141,7 @@ static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen)
 
 static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
 {
-       struct hostent* host;
+       struct hostent* host = NULL;
 
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
@@ -152,6 +157,8 @@ static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
                                                      NULL,
                                                      NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (host != NULL)
+                       ares_free_hostent(host);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -165,7 +172,7 @@ 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;
+       struct ares_mx_reply *mx_out = NULL;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -176,6 +183,8 @@ static void ParseAnswerMX(AsyncIO *IO, unsigned char* abuf, int alen)
 
        IO->DNS.Query->DNSStatus = ares_parse_mx_reply(abuf, alen, &mx_out);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (mx_out != NULL)
+                       ares_free_data(mx_out);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -188,7 +197,7 @@ static void ParseAnswerMX(AsyncIO *IO, unsigned char* abuf, int alen)
 
 static void ParseAnswerNS(AsyncIO *IO, unsigned char* abuf, int alen)
 {
-       struct hostent* host;
+       struct hostent* host = NULL;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -199,6 +208,8 @@ static void ParseAnswerNS(AsyncIO *IO, unsigned char* abuf, int alen)
 
        IO->DNS.Query->DNSStatus = ares_parse_ns_reply(abuf, alen, &host);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (host != NULL)
+                       ares_free_hostent(host);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -210,7 +221,7 @@ 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;
+       struct ares_srv_reply *srv_out = NULL;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -221,6 +232,8 @@ static void ParseAnswerSRV(AsyncIO *IO, unsigned char* abuf, int alen)
 
        IO->DNS.Query->DNSStatus = ares_parse_srv_reply(abuf, alen, &srv_out);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (srv_out != NULL)
+                       ares_free_data(srv_out);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -244,6 +257,8 @@ static void ParseAnswerTXT(AsyncIO *IO, unsigned char* abuf, int alen)
 
        IO->DNS.Query->DNSStatus = ares_parse_txt_reply(abuf, alen, &txt_out);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
+               if (txt_out != NULL)
+                       ares_free_data(txt_out);
                StrBufPlain(IO->ErrMsg,
                            ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
@@ -261,6 +276,7 @@ void QueryCb(void *arg,
        AsyncIO *IO = arg;
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+       EV_DNS_LOGT_STOP(DNS.timeout);
 #endif
        ev_timer_stop (event_base, &IO->DNS.timeout);
 
@@ -278,6 +294,8 @@ void QueryCb(void *arg,
        ev_idle_init(&IO->unwind_stack,
                     IO_postdns_callback);
        IO->unwind_stack.data = IO;
+       EV_DNS_LOGT_INIT(unwind_stack);
+       EV_DNS_LOGT_START(unwind_stack);
        ev_idle_start(event_base, &IO->unwind_stack);
 }
 
@@ -285,6 +303,7 @@ void QueryCbDone(AsyncIO *IO)
 {
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+       EV_DNS_LOGT_STOP(DNS.timeout);
 #endif
 
        ev_idle_stop(event_base, &IO->unwind_stack);
@@ -292,6 +311,16 @@ void QueryCbDone(AsyncIO *IO)
 
 void DestructCAres(AsyncIO *IO)
 {
+#ifdef DEBUG_CARES
+       EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
+       EV_DNS_LOGT_STOP(DNS.timeout);
+#endif
+       EV_DNS_LOG_STOP(DNS.recv_event);
+       ev_io_stop(event_base, &IO->DNS.recv_event);
+       EV_DNS_LOG_STOP(DNS.send_event);
+       ev_io_stop(event_base, &IO->DNS.send_event);
+       ev_timer_stop (event_base, &IO->DNS.timeout);
+       ev_idle_stop(event_base, &IO->unwind_stack);
        ares_destroy_options(&IO->DNS.Options);
 }
 
@@ -355,7 +384,10 @@ void QueueGetHostByNameDone(void *Ctx,
        ev_idle_init(&IO->unwind_stack,
                     IO_postdns_callback);
        IO->unwind_stack.data = IO;
+       EV_DNS_LOGT_INIT(unwind_stack);
+       EV_DNS_LOGT_START(unwind_stack);
        ev_idle_start(event_base, &IO->unwind_stack);
+       ev_timer_stop (event_base, &IO->DNS.timeout);
 }
 
 void QueueGetHostByName(AsyncIO *IO,
@@ -374,12 +406,14 @@ void QueueGetHostByName(AsyncIO *IO,
        InitC_ares_dns(IO);
 
        ev_timer_init(&IO->DNS.timeout, DNStimeouttrigger_callback, 10, 1);
+       EV_DNS_LOGT_INIT(DNS.timeout);
        IO->DNS.timeout.data = IO;
        ares_gethostbyname(IO->DNS.Channel,
                           Hostname,
                           AF_INET6, /* it falls back to ipv4 in doubt... */
                           QueueGetHostByNameDone,
                           IO);
+       EV_DNS_LOGT_START(DNS.timeout);
        ev_timer_start(event_base, &IO->DNS.timeout);
 
 }
@@ -399,11 +433,13 @@ int QueueQuery(ns_type Type,
 
        IO->DNS.Query = QueryParts;
        IO->DNS.Query->PostDNS = PostDNS;
+       IO->DNS.Start = IO->Now;
 
        InitC_ares_dns(IO);
 
        ev_timer_init(&IO->DNS.timeout, DNStimeouttrigger_callback, 10, 1);
        IO->DNS.timeout.data = IO;
+       EV_DNS_LOGT_INIT(DNS.timeout);
 
        switch(Type) {
        case ns_t_a:
@@ -453,6 +489,7 @@ int QueueQuery(ns_type Type,
                                   family,
                                   HostByAddrCb,
                                   IO);
+               EV_DNS_LOGT_START(DNS.timeout);
                ev_timer_start(event_base, &IO->DNS.timeout);
 #ifdef DEBUG_CARES
                EV_syslog(LOG_DEBUG, "C-ARES: %s X1\n", __FUNCTION__);
@@ -469,6 +506,7 @@ int QueueQuery(ns_type Type,
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
        ares_query(IO->DNS.Channel, name, ns_c_in, Type, QueryCb, IO);
+       EV_DNS_LOGT_START(DNS.timeout);
        ev_timer_start(event_base, &IO->DNS.timeout);
        return 1;
 }
@@ -484,6 +522,7 @@ static void DNS_send_callback(struct ev_loop *loop, ev_io *watcher, int revents)
 {
        AsyncIO *IO = watcher->data;
 
+       IO->Now = ev_now(event_base);
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -496,6 +535,8 @@ static void DNS_recv_callback(struct ev_loop *loop, ev_io *watcher, int revents)
 {
        AsyncIO *IO = watcher->data;
 
+       IO->Now = ev_now(event_base);
+
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
@@ -527,10 +568,12 @@ void SockStateCb(void *data, int sock, int read, int write)
                  IO->DNS.SourcePort);
 }
 #endif
+       IO->Now = ev_now(event_base);
 
        if (read) {
                if ((IO->DNS.recv_event.fd != sock) &&
                    (IO->DNS.recv_event.fd != 0)) {
+                       EV_DNS_LOG_STOP(DNS.recv_event);
                        ev_io_stop(event_base, &IO->DNS.recv_event);
                }
                IO->DNS.recv_event.fd = sock;
@@ -538,12 +581,15 @@ void SockStateCb(void *data, int sock, int read, int write)
                           DNS_recv_callback,
                           IO->DNS.recv_event.fd,
                           EV_READ);
+               EV_DNS_LOG_INIT(DNS.recv_event);
                IO->DNS.recv_event.data = IO;
+               EV_DNS_LOG_START(DNS.recv_event);
                ev_io_start(event_base, &IO->DNS.recv_event);
        }
        if (write) {
                if ((IO->DNS.send_event.fd != sock) &&
                    (IO->DNS.send_event.fd != 0)) {
+                       EV_DNS_LOG_STOP(DNS.send_event);
                        ev_io_stop(event_base, &IO->DNS.send_event);
                }
                IO->DNS.send_event.fd = sock;
@@ -552,9 +598,13 @@ void SockStateCb(void *data, int sock, int read, int write)
                           IO->DNS.send_event.fd,
                           EV_WRITE);
                IO->DNS.send_event.data = IO;
+               EV_DNS_LOG_INIT(DNS.send_event);
+               EV_DNS_LOG_START(DNS.send_event);
                ev_io_start(event_base, &IO->DNS.send_event);
        }
        if ((read == 0) && (write == 0)) {
+               EV_DNS_LOG_STOP(DNS.recv_event);
+               EV_DNS_LOG_STOP(DNS.send_event);
                ev_io_stop(event_base, &IO->DNS.recv_event);
                ev_io_stop(event_base, &IO->DNS.send_event);
        }