Logging: add timestamps for eventdriven IO
[citadel.git] / citadel / modules / c-ares-dns / serv_c-ares-dns.c
index 6c56fd6335e4e6cfc273174be7a6145803b35123..d1b1a027e5f86d2ac33acdad19115058585d4b69 100644 (file)
@@ -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 ;-)
  */
@@ -64,13 +64,14 @@ void SockStateCb(void *data, int sock, int read, int write);
 
 
 static void HostByAddrCb(void *data,
-                         int status,
-                         int timeouts,
-                         struct hostent *hostent) 
+                        int status,
+                        int timeouts,
+                        struct hostent *hostent)
 {
        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);
 
@@ -80,12 +81,11 @@ static void HostByAddrCb(void *data,
                return;
        }
        IO->DNS.Query->Data = hostent;
-/// TODO: howto free this??
 }
 
-static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen) 
+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
@@ -94,9 +94,16 @@ static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
                IO->DNS.Query->DNSReplyFree(IO->DNS.Query->VParsedDNSReply);
        IO->DNS.Query->VParsedDNSReply = NULL;
 
-       IO->DNS.Query->DNSStatus = ares_parse_a_reply(abuf, alen, &host, NULL, NULL);
+       IO->DNS.Query->DNSStatus = ares_parse_a_reply(abuf,
+                                                     alen,
+                                                     &host,
+                                                     NULL,
+                                                     NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (host != NULL)
+                       ares_free_hostent(host);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
        IO->DNS.Query->VParsedDNSReply = host;
@@ -104,9 +111,9 @@ static void ParseAnswerA(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerAAAA(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
@@ -115,9 +122,16 @@ static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen)
                IO->DNS.Query->DNSReplyFree(IO->DNS.Query->VParsedDNSReply);
        IO->DNS.Query->VParsedDNSReply = NULL;
 
-       IO->DNS.Query->DNSStatus = ares_parse_aaaa_reply(abuf, alen, &host, NULL, NULL);
+       IO->DNS.Query->DNSStatus = ares_parse_aaaa_reply(abuf,
+                                                        alen,
+                                                        &host,
+                                                        NULL,
+                                                        NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (host != NULL)
+                       ares_free_hostent(host);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
        IO->DNS.Query->VParsedDNSReply = host;
@@ -125,9 +139,9 @@ static void ParseAnswerAAAA(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerCNAME(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__);
@@ -137,9 +151,16 @@ static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
                IO->DNS.Query->DNSReplyFree(IO->DNS.Query->VParsedDNSReply);
        IO->DNS.Query->VParsedDNSReply = NULL;
 
-       IO->DNS.Query->DNSStatus = ares_parse_a_reply(abuf, alen, &host, NULL, NULL);
+       IO->DNS.Query->DNSStatus = ares_parse_a_reply(abuf,
+                                                     alen,
+                                                     &host,
+                                                     NULL,
+                                                     NULL);
        if (IO->DNS.Query->DNSStatus != ARES_SUCCESS) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (host != NULL)
+                       ares_free_hostent(host);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
 
@@ -149,9 +170,9 @@ static void ParseAnswerCNAME(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerMX(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
@@ -162,7 +183,10 @@ 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) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (mx_out != NULL)
+                       ares_free_data(mx_out);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
 
@@ -171,9 +195,9 @@ static void ParseAnswerMX(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerNS(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
@@ -184,7 +208,10 @@ 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) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (host != NULL)
+                       ares_free_hostent(host);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
        IO->DNS.Query->VParsedDNSReply = host;
@@ -192,9 +219,9 @@ static void ParseAnswerNS(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerSRV(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
@@ -205,7 +232,10 @@ 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) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (srv_out != NULL)
+                       ares_free_data(srv_out);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
 
@@ -214,7 +244,7 @@ static void ParseAnswerSRV(AsyncIO *IO, unsigned char* abuf, int alen)
 }
 
 
-static void ParseAnswerTXT(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
@@ -227,7 +257,10 @@ 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) {
-               StrBufPlain(IO->ErrMsg, ares_strerror(IO->DNS.Query->DNSStatus), -1);
+               if (txt_out != NULL)
+                       ares_free_data(txt_out);
+               StrBufPlain(IO->ErrMsg,
+                           ares_strerror(IO->DNS.Query->DNSStatus), -1);
                return;
        }
        IO->DNS.Query->VParsedDNSReply = txt_out;
@@ -238,11 +271,12 @@ void QueryCb(void *arg,
             int status,
             int timeouts,
             unsigned char* abuf,
-            int alen) 
+            int alen)
 {
        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);
 
@@ -256,10 +290,12 @@ void QueryCb(void *arg,
                StrBufPlain(IO->ErrMsg, ares_strerror(status), -1);
                IO->DNS.Query->DNSStatus = status;
        }
-       
+
        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);
 }
 
@@ -267,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);
@@ -274,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);
 }
 
@@ -320,7 +367,7 @@ DNStimeouttrigger_callback(struct ev_loop *loop, ev_timer *watcher, int revents)
        }
 }
 
-void QueueGetHostByNameDone(void *Ctx, 
+void QueueGetHostByNameDone(void *Ctx,
                            int status,
                            int timeouts,
                            struct hostent *hostent)
@@ -337,10 +384,16 @@ 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, const char *Hostname, DNSQueryParts *QueryParts, IO_CallBack PostDNS)
+void QueueGetHostByName(AsyncIO *IO,
+                       const char *Hostname,
+                       DNSQueryParts *QueryParts,
+                       IO_CallBack PostDNS)
 {
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
@@ -353,16 +406,23 @@ void QueueGetHostByName(AsyncIO *IO, const char *Hostname, DNSQueryParts *QueryP
        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,   
+                          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);
 
 }
-int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *QueryParts, IO_CallBack PostDNS)
+
+int QueueQuery(ns_type Type,
+              const char *name,
+              AsyncIO *IO,
+              DNSQueryParts *QueryParts,
+              IO_CallBack PostDNS)
 {
        int length, family;
        char address_b[sizeof(struct in6_addr)];
@@ -373,11 +433,13 @@ int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *Query
 
        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:
@@ -421,7 +483,13 @@ int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *Query
                        return -1;
                }
 
-               ares_gethostbyaddr(IO->DNS.Channel, address_b, length, family, HostByAddrCb, IO);
+               ares_gethostbyaddr(IO->DNS.Channel,
+                                  address_b,
+                                  length,
+                                  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__);
@@ -438,6 +506,7 @@ int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *Query
        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;
 }
@@ -452,25 +521,32 @@ int QueueQuery(ns_type Type, const char *name, AsyncIO *IO, DNSQueryParts *Query
 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
 
-       ares_process_fd(IO->DNS.Channel, ARES_SOCKET_BAD, IO->DNS.send_event.fd);
+       ares_process_fd(IO->DNS.Channel,
+                       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;
-       
+
+       IO->Now = ev_now(event_base);
+
 #ifdef DEBUG_CARES
        EV_syslog(LOG_DEBUG, "C-ARES: %s\n", __FUNCTION__);
 #endif
 
-       ares_process_fd(IO->DNS.Channel, IO->DNS.recv_event.fd, ARES_SOCKET_BAD);
+       ares_process_fd(IO->DNS.Channel,
+                       IO->DNS.recv_event.fd,
+                       ARES_SOCKET_BAD);
 }
 
-void SockStateCb(void *data, int sock, int read, int write) 
+void SockStateCb(void *data, int sock, int read, int write)
 {
        AsyncIO *IO = data;
 /* already inside of the event queue. */
@@ -478,8 +554,8 @@ void SockStateCb(void *data, int sock, int read, int write)
 {
        struct sockaddr_in sin = {};
        socklen_t slen;
-       slen = sizeof(sin);     
-       if ((IO->DNS.SourcePort == 0) && 
+       slen = sizeof(sin);
+       if ((IO->DNS.SourcePort == 0) &&
            (getsockname(sock, &sin, &slen) == 0))
        {
                IO->DNS.SourcePort = ntohs(sin.sin_port);
@@ -492,28 +568,43 @@ 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;
-               ev_io_init(&IO->DNS.recv_event, DNS_recv_callback, IO->DNS.recv_event.fd, EV_READ);
+               ev_io_init(&IO->DNS.recv_event,
+                          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;
-               ev_io_init(&IO->DNS.send_event, DNS_send_callback, IO->DNS.send_event.fd, EV_WRITE);
+               ev_io_init(&IO->DNS.send_event,
+                          DNS_send_callback,
+                          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);
        }
@@ -525,9 +616,7 @@ CTDL_MODULE_INIT(c_ares_client)
        {
                int r = ares_library_init(ARES_LIB_INIT_ALL);
                if (0 != r) {
-                       // TODO
-                       // ThrowException(Exception::Error(String::New(ares_strerror(r))));
-////                   assert(r == 0);
+                       
                }
        }
        return "c-ares";