From: Wilfried Goesgens Date: Sun, 29 Apr 2012 10:14:09 +0000 (+0200) Subject: Merge branch 'master' of ssh://git.citadel.org/appl/gitroot/citadel X-Git-Tag: v8.11~57 X-Git-Url: https://code.citadel.org/?a=commitdiff_plain;h=c064b240ff457c4bcdc119aaf7a6a09ff31952e2;hp=fde1737f07b2161c11d7d091dc14d8a4eada9fdb;p=citadel.git Merge branch 'master' of ssh://git.citadel.org/appl/gitroot/citadel --- diff --git a/citadel/event_client.c b/citadel/event_client.c index d0e0fd9ae..697fd7bcd 100644 --- a/citadel/event_client.c +++ b/citadel/event_client.c @@ -976,6 +976,7 @@ int InitcURLIOStruct(AsyncIO *IO, } +extern int DebugEventLoopBacktrace; void EV_backtrace(AsyncIO *IO) { #ifdef HAVE_BACKTRACE @@ -983,14 +984,17 @@ void EV_backtrace(AsyncIO *IO) size_t size, i; char **strings; - + if ((IO == NULL) || (DebugEventLoopBacktrace == 0)) + return; size = backtrace(stack_frames, sizeof(stack_frames) / sizeof(void*)); strings = backtrace_symbols(stack_frames, size); for (i = 0; i < size; i++) { - if (strings != NULL) + if (strings != NULL) { EV_syslog(LOG_ALERT, " BT %s\n", strings[i]); - else + } + else { EV_syslog(LOG_ALERT, " BT %p\n", stack_frames[i]); + } } free(strings); #endif diff --git a/citadel/event_client.h b/citadel/event_client.h index 2d5ab9861..9ed142eeb 100644 --- a/citadel/event_client.h +++ b/citadel/event_client.h @@ -179,51 +179,52 @@ typedef struct _IOAddHandler { IO_CallBack EvAttch; } IOAddHandler; + + +extern int DebugEventLoop; +extern int DebugCAres; + +#define EDBGLOG(LEVEL) if ((LEVEL != LOG_DEBUG) || (DebugEventLoop != 0)) + #define CCID ((CitContext*)IO->CitContext)->cs_pid #define EV_syslog(LEVEL, FORMAT, ...) \ - syslog(LEVEL, "IO[%ld]CC[%d]" FORMAT, IO->ID, CCID, __VA_ARGS__) + EDBGLOG (LEVEL) 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) + EDBGLOG (LEVEL) syslog(LEVEL, "IO[%ld]CC[%d]" FORMAT, IO->ID, CCID) #define EVNC_syslog(LEVEL, FORMAT, ...) \ - syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID, __VA_ARGS__) + EDBGLOG (LEVEL) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID, __VA_ARGS__) -#define EVNCM_syslog(LEVEL, FORMAT) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID) +#define EVNCM_syslog(LEVEL, FORMAT) EDBGLOG (LEVEL) syslog(LEVEL, "IO[%ld]" FORMAT, IO->ID) -#ifdef DEBUG_CARES + +#define CDBGLOG() if (DebugCAres != 0) #define EV_DNS_LOG_START(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] + Starting " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ - EV_backtrace(IO); + CDBGLOG () {syslog(LOG_DEBUG, "IO[%ld]CC[%d] + Starting " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ + EV_backtrace(IO);} #define EV_DNS_LOG_STOP(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] - Stopping " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ - EV_backtrace(IO); + CDBGLOG () { syslog(LOG_DEBUG, "IO[%ld]CC[%d] - Stopping " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ + EV_backtrace(IO);} #define EV_DNS_LOG_INIT(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] * Init " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ - EV_backtrace(IO); + CDBGLOG () { syslog(LOG_DEBUG, "IO[%ld]CC[%d] * Init " #a " %p FD %d", IO->ID, CCID, &IO->a, IO->a.fd); \ + EV_backtrace(IO);} #define EV_DNS_LOGT_START(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] + Starting " #a " %p", IO->ID, CCID, &IO->a); \ - EV_backtrace(IO); + CDBGLOG () { syslog(LOG_DEBUG, "IO[%ld]CC[%d] + Starting " #a " %p", IO->ID, CCID, &IO->a); \ + EV_backtrace(IO);} #define EV_DNS_LOGT_STOP(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] - Stopping " #a " %p", IO->ID, CCID, &IO->a); \ - EV_backtrace(IO); + CDBGLOG () { syslog(LOG_DEBUG, "IO[%ld]CC[%d] - Stopping " #a " %p", IO->ID, CCID, &IO->a); \ + EV_backtrace(IO); } #define EV_DNS_LOGT_INIT(a) \ - syslog(LOG_DEBUG, "IO[%ld]CC[%d] * Init " #a " %p", IO->ID, CCID, &IO->a); \ - EV_backtrace(IO); -#else -#define EV_DNS_LOG_START(a) -#define EV_DNS_LOG_STOP(a) -#define EV_DNS_LOG_INIT(a) -#define EV_DNS_LOGT_START(a) -#define EV_DNS_LOGT_STOP(a) -#define EV_DNS_LOGT_INIT(a) -#endif + CDBGLOG () { syslog(LOG_DEBUG, "IO[%ld]CC[%d] * Init " #a " %p", IO->ID, CCID, &IO->a); \ + EV_backtrace(IO);} + 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 d1b1a027e..13e156a80 100644 --- a/citadel/modules/c-ares-dns/serv_c-ares-dns.c +++ b/citadel/modules/c-ares-dns/serv_c-ares-dns.c @@ -57,6 +57,7 @@ #include "ctdl_module.h" #include "event_client.h" +int DebugCAres = 0; extern struct ev_loop *event_base; @@ -609,11 +610,16 @@ void SockStateCb(void *data, int sock, int read, int write) ev_io_stop(event_base, &IO->DNS.send_event); } } +void EnableDebugCAres(void) +{ + DebugCAres = 1; +} CTDL_MODULE_INIT(c_ares_client) { if (!threading) { + CtdlRegisterDebugFlagHook(HKEY("cares"), EnableDebugCAres); int r = ares_library_init(ARES_LIB_INIT_ALL); if (0 != r) { diff --git a/citadel/modules/eventclient/serv_eventclient.c b/citadel/modules/eventclient/serv_eventclient.c index ce5d7f041..a079d1232 100644 --- a/citadel/modules/eventclient/serv_eventclient.c +++ b/citadel/modules/eventclient/serv_eventclient.c @@ -60,6 +60,9 @@ #include "serv_curl.h" ev_loop *event_base; +int DebugEventLoop = 0; +int DebugEventLoopBacktrace = 0; +int DebugCurl = 0; long EvIDSource = 1; /***************************************************************************** @@ -76,6 +79,20 @@ long EvIDSource = 1; } \ } while (0) +#define DBGLOG(LEVEL) if ((LEVEL != LOG_DEBUG) || (DebugCurl != 0)) + +#define EVCURL_syslog(LEVEL, FORMAT, ...) \ + DBGLOG (LEVEL) syslog(LEVEL, "EVCURL:IO[%ld]CC[%d] " FORMAT, IO->ID, CCID, __VA_ARGS__) + +#define EVCURLM_syslog(LEVEL, FORMAT) \ + DBGLOG (LEVEL) syslog(LEVEL, "EVCURL:IO[%ld]CC[%d] " FORMAT, IO->ID, CCID) + +#define CURL_syslog(LEVEL, FORMAT, ...) \ + DBGLOG (LEVEL) syslog(LEVEL, "CURL: " FORMAT, __VA_ARGS__) + +#define CURLM_syslog(LEVEL, FORMAT) \ + DBGLOG (LEVEL) syslog(LEVEL, "CURL: " FORMAT) + typedef struct _evcurl_global_data { int magic; CURLM *mhnd; @@ -94,16 +111,16 @@ gotstatus(int nnrun) global.nrun = nnrun; - syslog(LOG_DEBUG, - "CURLEV: gotstatus(): about to call curl_multi_info_read\n"); + CURLM_syslog(LOG_DEBUG, + "gotstatus(): about to call curl_multi_info_read\n"); while ((msg = curl_multi_info_read(global.mhnd, &nmsg))) { - syslog(LOG_ERR, - "EVCURL: got curl multi_info message msg=%d\n", - msg->msg); + CURL_syslog(LOG_DEBUG, + "got curl multi_info message msg=%d\n", + msg->msg); if (CURLMSG_DONE == msg->msg) { CURL *chnd; - char *chandle; + char *chandle = NULL; CURLcode sta; CURLMcode msta; AsyncIO*IO; @@ -113,12 +130,14 @@ gotstatus(int nnrun) sta = curl_easy_getinfo(chnd, CURLINFO_PRIVATE, &chandle); - syslog(LOG_ERR, "EVCURL: request complete\n"); - if (sta) - syslog(LOG_ERR, - "EVCURL: error asking curl for private" - " cookie of curl handle: %s\n", - curl_easy_strerror(sta)); + EVCURLM_syslog(LOG_DEBUG, "request complete\n"); + if (sta) { + EVCURL_syslog(LOG_ERR, + "error asking curl for private" + " cookie of curl handle: %s\n", + curl_easy_strerror(sta)); + continue; + } IO = (AsyncIO *)chandle; IO->Now = ev_now(event_base); @@ -128,34 +147,34 @@ gotstatus(int nnrun) sta = msg->data.result; if (sta) { - EV_syslog(LOG_ERR, - "EVCURL: error description: %s\n", - IO->HttpReq.errdesc); - EV_syslog(LOG_ERR, - "EVCURL: error performing request: %s\n", - curl_easy_strerror(sta)); + EVCURL_syslog(LOG_ERR, + "error description: %s\n", + IO->HttpReq.errdesc); + EVCURL_syslog(LOG_ERR, + "error performing request: %s\n", + curl_easy_strerror(sta)); } sta = curl_easy_getinfo(chnd, CURLINFO_RESPONSE_CODE, &IO->HttpReq.httpcode); if (sta) - EV_syslog(LOG_ERR, - "EVCURL: error asking curl for " - "response code from request: %s\n", - curl_easy_strerror(sta)); - EV_syslog(LOG_ERR, - "EVCURL: http response code was %ld\n", - (long)IO->HttpReq.httpcode); + EVCURL_syslog(LOG_ERR, + "error asking curl for " + "response code from request: %s\n", + curl_easy_strerror(sta)); + EVCURL_syslog(LOG_ERR, + "http response code was %ld\n", + (long)IO->HttpReq.httpcode); curl_slist_free_all(IO->HttpReq.headers); msta = curl_multi_remove_handle(global.mhnd, chnd); if (msta) - EV_syslog(LOG_ERR, - "EVCURL: warning problem detaching " - "completed handle from curl multi: " - "%s\n", - curl_multi_strerror(msta)); + EVCURL_syslog(LOG_ERR, + "warning problem detaching " + "completed handle from curl multi: " + "%s\n", + curl_multi_strerror(msta)); ev_cleanup_stop(event_base, &IO->abort_by_shutdown); @@ -203,13 +222,13 @@ stepmulti(void *data, curl_socket_t fd, int which) which, &running_handles); - syslog(LOG_DEBUG, "EVCURL: stepmulti(): calling gotstatus()\n"); + CURLM_syslog(LOG_DEBUG, "stepmulti(): calling gotstatus()\n"); if (msta) - syslog(LOG_ERR, - "EVCURL: error in curl processing events" - "on multi handle, fd %d: %s\n", - (int)fd, - curl_multi_strerror(msta)); + CURL_syslog(LOG_ERR, + "error in curl processing events" + "on multi handle, fd %d: %s\n", + (int)fd, + curl_multi_strerror(msta)); if (global.nrun != running_handles) gotstatus(running_handles); @@ -218,16 +237,16 @@ stepmulti(void *data, curl_socket_t fd, int which) static void gottime(struct ev_loop *loop, ev_timer *timeev, int events) { - syslog(LOG_DEBUG, "EVCURL: waking up curl for timeout\n"); + CURLM_syslog(LOG_DEBUG, "EVCURL: waking up curl for timeout\n"); stepmulti(NULL, CURL_SOCKET_TIMEOUT, 0); } static void got_in(struct ev_loop *loop, ev_io *ioev, int events) { - syslog(LOG_DEBUG, - "EVCURL: waking up curl for io on fd %d\n", - (int)ioev->fd); + CURL_syslog(LOG_DEBUG, + "EVCURL: waking up curl for io on fd %d\n", + (int)ioev->fd); stepmulti(ioev->data, ioev->fd, CURL_CSELECT_IN); } @@ -235,9 +254,9 @@ got_in(struct ev_loop *loop, ev_io *ioev, int events) static void got_out(struct ev_loop *loop, ev_io *ioev, int events) { - syslog(LOG_DEBUG, - "EVCURL: waking up curl for io on fd %d\n", - (int)ioev->fd); + CURL_syslog(LOG_DEBUG, + "waking up curl for io on fd %d\n", + (int)ioev->fd); stepmulti(ioev->data, ioev->fd, CURL_CSELECT_OUT); } @@ -259,7 +278,7 @@ gotdata(void *data, size_t size, size_t nmemb, void *cglobal) { static int gotwatchtime(CURLM *multi, long tblock_ms, void *cglobal) { - syslog(LOG_DEBUG, "EVCURL: gotwatchtime called %ld ms\n", tblock_ms); + CURL_syslog(LOG_DEBUG, "EVCURL: gotwatchtime called %ld ms\n", tblock_ms); evcurl_global_data *global = cglobal; ev_timer_stop(EV_DEFAULT, &global->timeev); if (tblock_ms < 0 || 14000 < tblock_ms) @@ -287,16 +306,16 @@ gotwatchsock(CURL *easy, if (IO == NULL) { sta = curl_easy_getinfo(easy, CURLINFO_PRIVATE, &f); if (sta) { - EV_syslog(LOG_ERR, - "EVCURL: error asking curl for private " - "cookie of curl handle: %s\n", - curl_easy_strerror(sta)); + EVCURL_syslog(LOG_ERR, + "EVCURL: error asking curl for private " + "cookie of curl handle: %s\n", + curl_easy_strerror(sta)); return -1; } IO = (AsyncIO *) f; - EV_syslog(LOG_DEBUG, - "EVCURL: got socket for URL: %s\n", - IO->ConnectMe->PlainUrl); + EVCURL_syslog(LOG_DEBUG, + "EVCURL: got socket for URL: %s\n", + IO->ConnectMe->PlainUrl); if (IO->SendBuf.fd != 0) { @@ -332,21 +351,21 @@ gotwatchsock(CURL *easy, } - EV_syslog(LOG_DEBUG, - "EVCURL: gotwatchsock called fd=%d action=%s[%d]\n", - (int)fd, Action, action); + EVCURL_syslog(LOG_DEBUG, + "EVCURL: gotwatchsock called fd=%d action=%s[%d]\n", + (int)fd, Action, action); switch (action) { case CURL_POLL_NONE: - EVM_syslog(LOG_ERR, - "EVCURL: called first time " - "to register this sockwatcker\n"); + EVCURLM_syslog(LOG_ERR, + "called first time " + "to register this sockwatcker\n"); break; case CURL_POLL_REMOVE: - EVM_syslog(LOG_ERR, - "EVCURL: called last time to unregister " - "this sockwatcher\n"); + EVCURLM_syslog(LOG_ERR, + "called last time to unregister " + "this sockwatcher\n"); ev_io_stop(event_base, &IO->recv_event); ev_io_stop(event_base, &IO->send_event); break; @@ -377,17 +396,17 @@ void curl_init_connectionpool(void) if (sta) { - syslog(LOG_ERR, - "EVCURL: error initializing curl library: %s\n", - curl_easy_strerror(sta)); + CURL_syslog(LOG_ERR, + "error initializing curl library: %s\n", + curl_easy_strerror(sta)); exit(1); } mhnd = global.mhnd = curl_multi_init(); if (!mhnd) { - syslog(LOG_ERR, - "EVCURL: error initializing curl multi handle\n"); + CURLM_syslog(LOG_ERR, + "error initializing curl multi handle\n"); exit(3); } @@ -404,12 +423,12 @@ int evcurl_init(AsyncIO *IO) CURLcode sta; CURL *chnd; - EVM_syslog(LOG_DEBUG, "EVCURL: evcurl_init called ms\n"); + EVCURLM_syslog(LOG_DEBUG, "EVCURL: evcurl_init called ms\n"); IO->HttpReq.attached = 0; chnd = IO->HttpReq.chnd = curl_easy_init(); if (!chnd) { - EVM_syslog(LOG_ERR, "EVCURL: error initializing curl handle\n"); + EVCURLM_syslog(LOG_ERR, "EVCURL: error initializing curl handle\n"); return 0; } @@ -464,16 +483,16 @@ static void IOcurl_abort_shutdown_callback(struct ev_loop *loop, CURLMcode msta; AsyncIO *IO = watcher->data; IO->Now = ev_now(event_base); - EV_syslog(LOG_DEBUG, "EVENT Curl: %s\n", __FUNCTION__); + EVCURL_syslog(LOG_DEBUG, "EVENT Curl: %s\n", __FUNCTION__); curl_slist_free_all(IO->HttpReq.headers); msta = curl_multi_remove_handle(global.mhnd, IO->HttpReq.chnd); if (msta) { - EV_syslog(LOG_ERR, - "EVCURL: warning problem detaching completed handle " - "from curl multi: %s\n", - curl_multi_strerror(msta)); + EVCURL_syslog(LOG_ERR, + "EVCURL: warning problem detaching completed handle " + "from curl multi: %s\n", + curl_multi_strerror(msta)); } curl_easy_cleanup(IO->HttpReq.chnd); @@ -492,7 +511,7 @@ evcurl_handle_start(AsyncIO *IO) CURL *chnd; chnd = IO->HttpReq.chnd; - EV_syslog(LOG_DEBUG, + EVCURL_syslog(LOG_DEBUG, "EVCURL: Loading URL: %s\n", IO->ConnectMe->PlainUrl); OPT(URL, IO->ConnectMe->PlainUrl); if (StrLength(IO->ConnectMe->CurlCreds)) @@ -515,11 +534,11 @@ evcurl_handle_start(AsyncIO *IO) OPT(HTTPHEADER, IO->HttpReq.headers); IO->NextState = eConnect; - EVM_syslog(LOG_DEBUG, "EVCURL: attaching to curl multi handle\n"); + EVCURLM_syslog(LOG_DEBUG, "EVCURL: attaching to curl multi handle\n"); msta = curl_multi_add_handle(global.mhnd, IO->HttpReq.chnd); if (msta) { - EV_syslog(LOG_ERR, + EVCURL_syslog(LOG_ERR, "EVCURL: error attaching to curl multi handle: %s\n", curl_multi_strerror(msta)); } @@ -535,7 +554,7 @@ evcurl_handle_start(AsyncIO *IO) static void WakeupCurlCallback(EV_P_ ev_async *w, int revents) { - syslog(LOG_DEBUG, "EVCURL: waking up curl multi handle\n"); + CURLM_syslog(LOG_DEBUG, "waking up curl multi handle\n"); curl_multi_perform(&global, CURL_POLL_NONE); } @@ -544,7 +563,7 @@ static void evcurl_shutdown (void) { curl_global_cleanup(); curl_multi_cleanup(global.mhnd); - syslog(LOG_DEBUG, "client_event_thread() initializing\n"); + CURLM_syslog(LOG_DEBUG, "exiting\n"); } /***************************************************************************** * libevent integration * @@ -822,10 +841,27 @@ void ShutDownEventQueues(void) pthread_mutex_unlock(&EventQueueMutex); } +void DebugEventloopEnable(void) +{ + DebugEventLoop = 1; +} +void DebugEventloopBacktraceEnable(void) +{ + DebugEventLoopBacktrace = 1; +} + +void DebugCurlEnable(void) +{ + DebugCurl = 1; +} + CTDL_MODULE_INIT(event_client) { if (!threading) { + CtdlRegisterDebugFlagHook(HKEY("eventloop"), DebugEventloopEnable); + CtdlRegisterDebugFlagHook(HKEY("eventloopbacktrace"), DebugEventloopBacktraceEnable); + CtdlRegisterDebugFlagHook(HKEY("curl"), DebugCurlEnable); InitEventQueue(); DBInitEventQueue(); CtdlThreadCreate(client_event_thread); diff --git a/citadel/modules/pop3client/serv_pop3client.c b/citadel/modules/pop3client/serv_pop3client.c index e559f2824..9784798cc 100644 --- a/citadel/modules/pop3client/serv_pop3client.c +++ b/citadel/modules/pop3client/serv_pop3client.c @@ -1,15 +1,21 @@ /* * Consolidate mail from remote POP3 accounts. * - * Copyright (c) 2007-2012 by the citadel.org team + * Copyright (c) 2007-2011 by the citadel.org team * * 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. + * 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 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 */ #include @@ -46,18 +52,43 @@ #include "citadel_dirs.h" #include "event_client.h" + #define POP3C_OK (strncasecmp(ChrPtr(RecvMsg->IO.IOBuf), "+OK", 3) == 0) +int Pop3ClientID = 0; +int POP3ClientDebugEnabled = 0; + +#define N ((pop3aggr*)IO->Data)->n + +#define DBGLOG(LEVEL) if ((LEVEL != LOG_DEBUG) || (POP3ClientDebugEnabled != 0)) + +#define EVP3C_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]" FORMAT, \ + IO->ID, CCID, N, __VA_ARGS__) + +#define EVP3CM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]" FORMAT, \ + IO->ID, CCID, N) -#define POP3C_DBG_SEND() \ - syslog(LOG_DEBUG, \ - "POP3 client[%ld]: > %s\n", \ - RecvMsg->n, ChrPtr(RecvMsg->IO.SendBuf.Buf)) +#define EVP3CCS_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]" FORMAT, \ + IO->ID, N, __VA_ARGS__) + +#define EVP3CCSM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]" FORMAT, \ + IO->ID, N) + +#define POP3C_DBG_SEND() \ + EVP3C_syslog(LOG_DEBUG, \ + "POP3: > %s\n", \ + ChrPtr(RecvMsg->IO.SendBuf.Buf)) #define POP3C_DBG_READ() \ - syslog(LOG_DEBUG, \ - "POP3 client[%ld]: < %s\n", \ - RecvMsg->n, \ - ChrPtr(RecvMsg->IO.IOBuf)) + EVP3C_syslog(LOG_DEBUG, \ + "POP3: < %s\n", \ + ChrPtr(RecvMsg->IO.IOBuf)) + struct CitContext pop3_client_CC; @@ -163,7 +194,7 @@ eNextState FinalizePOP3AggrRun(AsyncIO *IO) HashPos *It; pop3aggr *cptr = (pop3aggr *)IO->Data; - syslog(LOG_DEBUG, "Terminating Aggregator; bye.\n"); + EVP3CM_syslog(LOG_DEBUG, "Terminating Aggregator; bye.\n"); It = GetNewHashPos(POP3FetchUrls, 0); pthread_mutex_lock(&POP3QueueMutex); @@ -183,6 +214,7 @@ eNextState FailAggregationRun(AsyncIO *IO) eNextState POP3C_ReadGreeting(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); /* Read the server greeting */ if (!POP3C_OK) return eTerminateConnection; @@ -191,6 +223,7 @@ eNextState POP3C_ReadGreeting(pop3aggr *RecvMsg) eNextState POP3C_SendUser(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; /* Identify ourselves. NOTE: we have to append a CR to each command. * The LF will automatically be appended by sock_puts(). Believe it * or not, leaving out the CR will cause problems if the server happens @@ -205,6 +238,7 @@ eNextState POP3C_SendUser(pop3aggr *RecvMsg) eNextState POP3C_GetUserState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); if (!POP3C_OK) return eTerminateConnection; else return eSendReply; @@ -212,16 +246,18 @@ eNextState POP3C_GetUserState(pop3aggr *RecvMsg) eNextState POP3C_SendPassword(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; /* Password */ StrBufPrintf(RecvMsg->IO.SendBuf.Buf, "PASS %s\r\n", ChrPtr(RecvMsg->pop3pass)); - syslog(LOG_DEBUG, "\n"); -// POP3C_DBG_SEND(); No, we won't write the password to syslog... + EVP3CM_syslog(LOG_DEBUG, "\n"); +// POP3C_DBG_SEND(); No, we won't write the passvoid to syslog... return eReadMessage; } eNextState POP3C_GetPassState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); if (!POP3C_OK) return eTerminateConnection; else return eSendReply; @@ -229,6 +265,7 @@ eNextState POP3C_GetPassState(pop3aggr *RecvMsg) eNextState POP3C_SendListCommand(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; /* Get the list of messages */ StrBufPlain(RecvMsg->IO.SendBuf.Buf, HKEY("LIST\r\n")); POP3C_DBG_SEND(); @@ -237,6 +274,7 @@ eNextState POP3C_SendListCommand(pop3aggr *RecvMsg) eNextState POP3C_GetListCommandState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); if (!POP3C_OK) return eTerminateConnection; RecvMsg->MsgNumbers = NewHash(1, NULL); @@ -247,6 +285,7 @@ eNextState POP3C_GetListCommandState(pop3aggr *RecvMsg) eNextState POP3C_GetListOneLine(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; #if 0 int rc; #endif @@ -354,6 +393,7 @@ eNextState POP3_FetchNetworkUsetableEntry(AsyncIO *IO) eNextState POP3C_GetOneMessagID(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; long HKLen; const char *HKey; void *vData; @@ -390,6 +430,7 @@ eNextState POP3C_GetOneMessagID(pop3aggr *RecvMsg) eNextState POP3C_GetOneMessageIDState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; #if 0 int rc; rc = TestValidateHash(RecvMsg->MsgNumbers); @@ -420,6 +461,7 @@ eNextState POP3C_GetOneMessageIDState(pop3aggr *RecvMsg) eNextState POP3C_SendGetOneMsg(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; long HKLen; const char *HKey; void *vData; @@ -451,6 +493,7 @@ eNextState POP3C_SendGetOneMsg(pop3aggr *RecvMsg) eNextState POP3C_ReadMessageBodyFollowing(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); if (!POP3C_OK) return eTerminateConnection; RecvMsg->IO.ReadMsg = NewAsyncMsg(HKEY("."), @@ -508,7 +551,8 @@ eNextState POP3C_SaveMsg(AsyncIO *IO) eNextState POP3C_ReadMessageBody(pop3aggr *RecvMsg) { - syslog(LOG_DEBUG, "Converting message...\n"); + AsyncIO *IO = &RecvMsg->IO; + EVP3CM_syslog(LOG_DEBUG, "Converting message..."); RecvMsg->CurrMsg->Msg = convert_internet_message_buf(&RecvMsg->IO.ReadMsg->MsgBuf); @@ -517,6 +561,7 @@ eNextState POP3C_ReadMessageBody(pop3aggr *RecvMsg) eNextState POP3C_SendDelete(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; if (!RecvMsg->keep) { StrBufPrintf(RecvMsg->IO.SendBuf.Buf, "DELE %ld\r\n", RecvMsg->CurrMsg->MSGID); @@ -530,6 +575,7 @@ eNextState POP3C_SendDelete(pop3aggr *RecvMsg) } eNextState POP3C_ReadDeleteState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); RecvMsg->State = GetOneMessageIDState; return eReadMessage; @@ -537,6 +583,7 @@ eNextState POP3C_ReadDeleteState(pop3aggr *RecvMsg) eNextState POP3C_SendQuit(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; /* Log out */ StrBufPlain(RecvMsg->IO.SendBuf.Buf, HKEY("QUIT\r\n3)")); @@ -547,6 +594,7 @@ eNextState POP3C_SendQuit(pop3aggr *RecvMsg) eNextState POP3C_ReadQuitState(pop3aggr *RecvMsg) { + AsyncIO *IO = &RecvMsg->IO; POP3C_DBG_READ(); return eTerminateConnection; } @@ -619,9 +667,10 @@ const long POP3_C_ReadTimeouts[] = { void POP3SetTimeout(eNextState NextTCPState, pop3aggr *pMsg) { + AsyncIO *IO = &pMsg->IO; double Timeout = 0.0; - syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__); + EVP3C_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__); switch (NextTCPState) { case eSendFile: @@ -742,9 +791,9 @@ eNextState POP3_C_Shutdown(AsyncIO *IO) } -/* - * lineread Handler; understands when to read more POP3 lines, - * and when this is a one-lined reply. +/** + * @brief lineread Handler; understands when to read more POP3 lines, + * and when this is a one-lined reply. */ eReadState POP3_C_ReadServerStatus(AsyncIO *IO) { @@ -776,8 +825,7 @@ eReadState POP3_C_ReadServerStatus(AsyncIO *IO) /***************************************************************************** * So we connect our Server IP here. * - ***************************************************************************** - */ + *****************************************************************************/ eNextState POP3_C_ReAttachToFetchMessages(AsyncIO *IO) { pop3aggr *cpptr = IO->Data; @@ -868,7 +916,9 @@ eNextState pop3_get_one_host_ip(AsyncIO *IO) int pop3_do_fetching(pop3aggr *cpptr) { - InitIOStruct(&cpptr->IO, + AsyncIO *IO = &cpptr->IO; + + InitIOStruct(IO, cpptr, eReadMessage, POP3_C_ReadServerStatus, @@ -1067,7 +1117,7 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data) } pthread_mutex_unlock(&RSSQueueMutex); #endif - + cptr->n = Pop3ClientID++; pthread_mutex_lock(&POP3QueueMutex); Put(POP3FetchUrls, SKEY(cptr->Url), @@ -1110,11 +1160,6 @@ void pop3client_scan(void) { * Run POP3 aggregation no more frequently than once every n seconds */ if ( (time(NULL) - last_run) < fastest_scan ) { - syslog(LOG_DEBUG, - "pop3client: polling interval not yet reached; last run was %ldm%lds ago", - ((time(NULL) - last_run) / 60), - ((time(NULL) - last_run) % 60) - ); return; } @@ -1124,10 +1169,7 @@ void pop3client_scan(void) { * don't really require extremely fine granularity here, we'll do it * with a static variable instead. */ - if (doing_pop3client) { - syslog(LOG_DEBUG, "pop3client: concurrency check failed; another poll is already running"); - return; - } + if (doing_pop3client) return; doing_pop3client = 1; syslog(LOG_DEBUG, "pop3client started"); @@ -1170,6 +1212,13 @@ void pop3_cleanup(void) DeleteHash(&POP3QueueRooms); } + + +void LogDebugEnablePOP3Client(void) +{ + POP3ClientDebugEnabled = 1; +} + CTDL_MODULE_INIT(pop3client) { if (!threading) @@ -1180,6 +1229,7 @@ CTDL_MODULE_INIT(pop3client) POP3FetchUrls = NewHash(1, NULL); CtdlRegisterSessionHook(pop3client_scan, EVT_TIMER); CtdlRegisterEVCleanupHook(pop3_cleanup); + CtdlRegisterDebugFlagHook(HKEY("pop3client"), LogDebugEnablePOP3Client); } /* return our module id for the log */ diff --git a/citadel/modules/rssclient/rss_atom_parser.c b/citadel/modules/rssclient/rss_atom_parser.c index 610dd2b95..0c7290b5c 100644 --- a/citadel/modules/rssclient/rss_atom_parser.c +++ b/citadel/modules/rssclient/rss_atom_parser.c @@ -60,6 +60,29 @@ void rss_save_item(rss_item *ri, rss_aggregator *Cfg); +int RSSAtomParserDebugEnabled = 0; + +#define N ((rss_aggregator*)IO->Data)->QRnumber + +#define DBGLOG(LEVEL) if ((LEVEL != LOG_DEBUG) || (RSSAtomParserDebugEnabled != 0)) + +#define EVRSSATOM_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]RSSP" FORMAT, \ + IO->ID, CCID, N, __VA_ARGS__) + +#define EVRSSATOMM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]RSSP" FORMAT, \ + IO->ID, CCID, N) + +#define EVRSSATOMCS_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]RSSP" FORMAT, \ + IO->ID, N, __VA_ARGS__) + +#define EVRSSATOMSM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]RSSP" FORMAT, \ + IO->ID, N) /* * Convert an RDF/RSS datestamp into a time_t @@ -126,35 +149,38 @@ void flush_rss_item(rss_item *ri) void RSS_item_rss_start (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { - syslog(LOG_DEBUG, "RSS: This is an RSS feed.\n"); - Cfg->ItemType = RSS_RSS; + AsyncIO *IO = &RSSAggr->IO; + EVRSSATOMM_syslog(LOG_DEBUG, "RSS: This is an RSS feed.\n"); + RSSAggr->ItemType = RSS_RSS; } void RSS_item_rdf_start(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { - syslog(LOG_DEBUG, "RSS: This is an RDF feed.\n"); - Cfg->ItemType = RSS_RSS; + AsyncIO *IO = &RSSAggr->IO; + EVRSSATOMM_syslog(LOG_DEBUG, "RSS: This is an RDF feed.\n"); + RSSAggr->ItemType = RSS_RSS; } void ATOM_item_feed_start(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { - syslog(LOG_DEBUG, "RSS: This is an ATOM feed.\n"); - Cfg->ItemType = RSS_ATOM; + AsyncIO *IO = &RSSAggr->IO; + EVRSSATOMM_syslog(LOG_DEBUG, "RSS: This is an ATOM feed.\n"); + RSSAggr->ItemType = RSS_ATOM; } void RSS_item_item_start(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { ri->item_tag_nesting ++; @@ -163,7 +189,7 @@ void RSS_item_item_start(StrBuf *CData, void ATOM_item_entry_start(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { /* Atom feed... */ @@ -173,7 +199,7 @@ void ATOM_item_entry_start(StrBuf *CData, void ATOM_item_link_start (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { int i; @@ -256,7 +282,7 @@ void ATOM_item_link_start (StrBuf *CData, void ATOMRSS_item_title_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if ((ri->item_tag_nesting == 0) && (StrLength(CData) > 0)) { @@ -267,7 +293,7 @@ void ATOMRSS_item_title_end(StrBuf *CData, void RSS_item_guid_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -276,7 +302,7 @@ void RSS_item_guid_end(StrBuf *CData, } void ATOM_item_id_end(StrBuf *CData, - rss_item *ri, rss_aggregator *Cfg, const char** Attr) + rss_item *ri, rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { NewStrBufDupAppendFlush(&ri->guid, CData, NULL, 0); @@ -286,7 +312,7 @@ void ATOM_item_id_end(StrBuf *CData, void RSS_item_link_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -296,7 +322,7 @@ void RSS_item_link_end (StrBuf *CData, } void RSS_item_relink_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -307,7 +333,7 @@ void RSS_item_relink_end(StrBuf *CData, void RSSATOM_item_title_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -318,7 +344,7 @@ void RSSATOM_item_title_end (StrBuf *CData, void ATOM_item_content_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { long olen = StrLength (ri->description); @@ -345,7 +371,7 @@ void ATOM_item_content_end (StrBuf *CData, } void ATOM_item_summary_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { /* @@ -361,7 +387,7 @@ void ATOM_item_summary_end (StrBuf *CData, void RSS_item_description_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { long olen = StrLength (ri->description); @@ -388,7 +414,7 @@ void RSS_item_description_end (StrBuf *CData, void ATOM_item_published_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -399,7 +425,7 @@ void ATOM_item_published_end (StrBuf *CData, void ATOM_item_updated_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -410,7 +436,7 @@ void ATOM_item_updated_end (StrBuf *CData, void RSS_item_pubdate_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -422,7 +448,7 @@ void RSS_item_pubdate_end (StrBuf *CData, void RSS_item_date_end (StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -435,7 +461,7 @@ void RSS_item_date_end (StrBuf *CData, void RSS_item_author_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -447,7 +473,7 @@ void RSS_item_author_end(StrBuf *CData, void ATOM_item_name_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -458,7 +484,7 @@ void ATOM_item_name_end(StrBuf *CData, void ATOM_item_email_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -469,7 +495,7 @@ void ATOM_item_email_end(StrBuf *CData, void RSS_item_creator_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if ((StrLength(CData) > 0) && @@ -483,7 +509,7 @@ void RSS_item_creator_end(StrBuf *CData, void ATOM_item_uri_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { if (StrLength(CData) > 0) { @@ -494,45 +520,47 @@ void ATOM_item_uri_end(StrBuf *CData, void RSS_item_item_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { --ri->item_tag_nesting; - rss_save_item(ri, Cfg); + rss_save_item(ri, RSSAggr); } void ATOM_item_entry_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { --ri->item_tag_nesting; - rss_save_item(ri, Cfg); + rss_save_item(ri, RSSAggr); } void RSS_item_rss_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { -// syslog(LOG_DEBUG, "End of feed detected. Closing parser.\n"); + AsyncIO *IO = &RSSAggr->IO; + EVRSSATOMM_syslog(LOG_DEBUG, "End of feed detected. Closing parser.\n"); ri->done_parsing = 1; } void RSS_item_rdf_end(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { -// syslog(LOG_DEBUG, "End of feed detected. Closing parser.\n"); + AsyncIO *IO = &RSSAggr->IO; + EVRSSATOMM_syslog(LOG_DEBUG, "End of feed detected. Closing parser.\n"); ri->done_parsing = 1; } void RSSATOM_item_ignore(StrBuf *CData, rss_item *ri, - rss_aggregator *Cfg, + rss_aggregator *RSSAggr, const char** Attr) { } @@ -604,7 +632,7 @@ void AppendLink(StrBuf *Message, /* * Commit a fetched and parsed RSS item to disk */ -void rss_save_item(rss_item *ri, rss_aggregator *Cfg) +void rss_save_item(rss_item *ri, rss_aggregator *RSSAggr) { networker_save_message *SaveMsg; struct MD5Context md5context; @@ -612,7 +640,7 @@ void rss_save_item(rss_item *ri, rss_aggregator *Cfg) int msglen = 0; StrBuf *Message; StrBuf *guid; - AsyncIO *IO = &Cfg->IO; + AsyncIO *IO = &RSSAggr->IO; int n; @@ -647,7 +675,7 @@ void rss_save_item(rss_item *ri, rss_aggregator *Cfg) } /* translate Item into message. */ - EVM_syslog(LOG_DEBUG, "RSS: translating item...\n"); + EVRSSATOMM_syslog(LOG_DEBUG, "RSS: translating item...\n"); if (ri->description == NULL) ri->description = NewStrBufPlain(HKEY("")); StrBufSpaceToBlank(ri->description); SaveMsg->Msg.cm_magic = CTDLMESSAGE_MAGIC; @@ -767,8 +795,8 @@ void rss_save_item(rss_item *ri, rss_aggregator *Cfg) SaveMsg->MsgGUID = guid; SaveMsg->Message = Message; - n = GetCount(Cfg->Messages) + 1; - Put(Cfg->Messages, IKEY(n), SaveMsg, FreeNetworkSaveMessage); + n = GetCount(RSSAggr->Messages) + 1; + Put(RSSAggr->Messages, IKEY(n), SaveMsg, FreeNetworkSaveMessage); } @@ -776,6 +804,7 @@ void rss_xml_start(void *data, const char *supplied_el, const char **attr) { rss_xml_handler *h; rss_aggregator *RSSAggr = (rss_aggregator*) data; + AsyncIO *IO = &RSSAggr->IO; rss_item *ri = RSSAggr->Item; void *pv; const char *pel; @@ -784,7 +813,7 @@ void rss_xml_start(void *data, const char *supplied_el, const char **attr) /* Axe the namespace, we don't care about it */ /* syslog(LOG_DEBUG, - "RSS: supplied el %d: %s\n", RSSAggr->Cfg->ItemType, supplied_el); + "RSS: supplied el %d: %s\n", RSSAggr->RSSAggr->ItemType, supplied_el); */ pel = supplied_el; while (sep = strchr(pel, ':'), sep) { @@ -800,12 +829,10 @@ void rss_xml_start(void *data, const char *supplied_el, const char **attr) pel - supplied_el - 1, &v)) { -#ifdef DEBUG_RSS - syslog(LOG_DEBUG, - "RSS: START ignoring " - "because of wrong namespace [%s]\n", - supplied_el); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: START ignoring " + "because of wrong namespace [%s]\n", + supplied_el); return; } } @@ -834,27 +861,24 @@ void rss_xml_start(void *data, const char *supplied_el, const char **attr) RSSAggr, attr); } -#ifdef DEBUG_RSS else - syslog(LOG_DEBUG, - "RSS: START unhandled: [%s] [%s]...\n", - pel, - supplied_el); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: START unhandled: [%s] [%s]...\n", + pel, + supplied_el); } -#ifdef DEBUG_RSS else - syslog(LOG_DEBUG, - "RSS: START unhandled: [%s] [%s]...\n", - pel, - supplied_el); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: START unhandled: [%s] [%s]...\n", + pel, + supplied_el); } void rss_xml_end(void *data, const char *supplied_el) { rss_xml_handler *h; rss_aggregator *RSSAggr = (rss_aggregator*) data; + AsyncIO *IO = &RSSAggr->IO; rss_item *ri = RSSAggr->Item; const char *pel; char *sep = NULL; @@ -865,7 +889,7 @@ void rss_xml_end(void *data, const char *supplied_el) while (sep = strchr(pel, ':'), sep) { pel = sep + 1; } -// syslog(LOG_DEBUG, "RSS: END %s...\n", el); + EVRSSATOM_syslog(LOG_DEBUG, "RSS: END %s...\n", supplied_el); if (pel != supplied_el) { void *v; @@ -875,13 +899,11 @@ void rss_xml_end(void *data, const char *supplied_el) pel - supplied_el - 1, &v)) { -#ifdef DEBUG_RSS - syslog(LOG_DEBUG, - "RSS: END ignoring because of wrong namespace" - "[%s] = [%s]\n", - supplied_el, - ChrPtr(RSSAggr->CData)); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: END ignoring because of wrong namespace" + "[%s] = [%s]\n", + supplied_el, + ChrPtr(RSSAggr->CData)); FlushStrBuf(RSSAggr->CData); return; } @@ -908,23 +930,19 @@ void rss_xml_end(void *data, const char *supplied_el) { h->Handler(RSSAggr->CData, ri, RSSAggr, NULL); } -#ifdef DEBUG_RSS else - syslog(LOG_DEBUG, - "RSS: END unhandled: [%s] [%s] = [%s]...\n", - pel, - supplied_el, - ChrPtr(RSSAggr->CData)); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: END unhandled: [%s] [%s] = [%s]...\n", + pel, + supplied_el, + ChrPtr(RSSAggr->CData)); } -#ifdef DEBUG_RSS else - syslog(LOG_DEBUG, - "RSS: END unhandled: [%s] [%s] = [%s]...\n", - pel, - supplied_el, - ChrPtr(RSSAggr->CData)); -#endif + EVRSSATOM_syslog(LOG_DEBUG, + "RSS: END unhandled: [%s] [%s] = [%s]...\n", + pel, + supplied_el, + ChrPtr(RSSAggr->CData)); FlushStrBuf(RSSAggr->CData); } @@ -952,8 +970,8 @@ eNextState RSSAggregator_ParseReply(AsyncIO *IO) if (IO->HttpReq.httpcode != 200) { - EV_syslog(LOG_DEBUG, "need a 200, got a %ld !\n", - IO->HttpReq.httpcode); + EVRSSATOM_syslog(LOG_ALERT, "need a 200, got a %ld !\n", + IO->HttpReq.httpcode); // TODO: aide error message with rate limit return eAbort; } @@ -982,11 +1000,11 @@ eNextState RSSAggregator_ParseReply(AsyncIO *IO) else ptr = "UTF-8"; - syslog(LOG_DEBUG, "RSS: Now parsing [%s] \n", ChrPtr(RSSAggr->Url)); + EVRSSATOM_syslog(LOG_DEBUG, "RSS: Now parsing [%s] \n", ChrPtr(RSSAggr->Url)); RSSAggr->xp = XML_ParserCreateNS(ptr, ':'); if (!RSSAggr->xp) { - syslog(LOG_DEBUG, "Cannot create XML parser!\n"); + EVRSSATOMM_syslog(LOG_ALERT, "Cannot create XML parser!\n"); return eAbort; } FlushStrBuf(RSSAggr->Key); @@ -1008,8 +1026,8 @@ eNextState RSSAggregator_ParseReply(AsyncIO *IO) XML_Parse(RSSAggr->xp, "", 0, 1); - syslog(LOG_DEBUG, "RSS: XML Status [%s] \n", - XML_ErrorString(XML_GetErrorCode(RSSAggr->xp))); + EVRSSATOM_syslog(LOG_DEBUG, "RSS: XML Status [%s] \n", + XML_ErrorString(XML_GetErrorCode(RSSAggr->xp))); XML_ParserFree(RSSAggr->xp); flush_rss_item(ri); @@ -1021,7 +1039,7 @@ eNextState RSSAggregator_ParseReply(AsyncIO *IO) RSSAggr->Pos = GetNewHashPos(RSSAggr->Messages, 1); -//Cfg->next_poll = time(NULL) + config.c_net_freq; +//RSSAggr->next_poll = time(NULL) + config.c_net_freq; if (GetNextHashPos(RSSAggr->Messages, RSSAggr->Pos, &len, @@ -1068,6 +1086,10 @@ void rss_parser_cleanup(void) DeleteHash(&KnownNameSpaces); } +void LogDebugEnableRSSATOMParser(void) +{ + RSSAtomParserDebugEnabled = 1; +} CTDL_MODULE_INIT(rssparser) { @@ -1155,6 +1177,7 @@ CTDL_MODULE_INIT(rssparser) /* we don't like these namespaces because of they shadow our usefull parameters. */ Put(KnownNameSpaces, HKEY("http://search.yahoo.com/mrss/"), NULL, reference_free_handler); #endif + CtdlRegisterDebugFlagHook(HKEY("RSSAtomParser"), LogDebugEnableRSSATOMParser); CtdlRegisterCleanupHook(rss_parser_cleanup); } return "rssparser"; diff --git a/citadel/modules/rssclient/serv_rssclient.c b/citadel/modules/rssclient/serv_rssclient.c index 68f04ab75..638300feb 100644 --- a/citadel/modules/rssclient/serv_rssclient.c +++ b/citadel/modules/rssclient/serv_rssclient.c @@ -68,7 +68,30 @@ eNextState RSSAggregator_ShutdownAbort(AsyncIO *IO); struct CitContext rss_CC; struct rssnetcfg *rnclist = NULL; +int RSSClientDebugEnabled = 0; +#define N ((rss_aggregator*)IO->Data)->QRnumber +#define DBGLOG(LEVEL) if ((LEVEL != LOG_DEBUG) || (RSSClientDebugEnabled != 0)) + +#define EVRSSC_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]RSS" FORMAT, \ + IO->ID, CCID, N, __VA_ARGS__) + +#define EVRSSCM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, \ + "IO[%ld]CC[%d][%ld]RSS" FORMAT, \ + IO->ID, CCID, N) + +#define EVRSSQ_syslog(LEVEL, FORMAT, ...) \ + DBGLOG(LEVEL) syslog(LEVEL, "RSS" FORMAT, \ + __VA_ARGS__) +#define EVRSSQM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, "RSS" FORMAT) + +#define EVRSSCSM_syslog(LEVEL, FORMAT) \ + DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]RSS" FORMAT, \ + IO->ID, N) void DeleteRoomReference(long QRnumber) { @@ -94,19 +117,19 @@ void DeleteRoomReference(long QRnumber) DeleteHashPos(&At); } -void UnlinkRooms(rss_aggregator *Cfg) +void UnlinkRooms(rss_aggregator *RSSAggr) { - DeleteRoomReference(Cfg->QRnumber); - if (Cfg->OtherQRnumbers != NULL) + DeleteRoomReference(RSSAggr->QRnumber); + if (RSSAggr->OtherQRnumbers != NULL) { long HKLen; const char *HK; HashPos *At; void *vData; - At = GetNewHashPos(Cfg->OtherQRnumbers, 0); + At = GetNewHashPos(RSSAggr->OtherQRnumbers, 0); while (! server_shutting_down && - GetNextHashPos(Cfg->OtherQRnumbers, + GetNextHashPos(RSSAggr->OtherQRnumbers, At, &HKLen, &HK, &vData) && @@ -120,15 +143,15 @@ void UnlinkRooms(rss_aggregator *Cfg) } } -void UnlinkRSSAggregator(rss_aggregator *Cfg) +void UnlinkRSSAggregator(rss_aggregator *RSSAggr) { HashPos *At; pthread_mutex_lock(&RSSQueueMutex); - UnlinkRooms(Cfg); + UnlinkRooms(RSSAggr); At = GetNewHashPos(RSSFetchUrls, 0); - if (GetHashPosFromKey(RSSFetchUrls, SKEY(Cfg->Url), At)) + if (GetHashPosFromKey(RSSFetchUrls, SKEY(RSSAggr->Url), At)) { DeleteEntryFromHash(RSSFetchUrls, At); } @@ -141,7 +164,7 @@ void DeleteRssCfg(void *vptr) { rss_aggregator *RSSAggr = (rss_aggregator *)vptr; AsyncIO *IO = &RSSAggr->IO; - EVM_syslog(LOG_DEBUG, "RSS: destroying\n"); + EVRSSCM_syslog(LOG_DEBUG, "RSS: destroying\n"); FreeStrBuf(&RSSAggr->Url); FreeStrBuf(&RSSAggr->rooms); @@ -170,7 +193,7 @@ eNextState RSSAggregator_Terminate(AsyncIO *IO) { rss_aggregator *RSSAggr = (rss_aggregator *)IO->Data; - EVM_syslog(LOG_DEBUG, "RSS: Terminating.\n"); + EVRSSCM_syslog(LOG_DEBUG, "RSS: Terminating.\n"); UnlinkRSSAggregator(RSSAggr); @@ -181,7 +204,7 @@ eNextState RSSAggregator_TerminateDB(AsyncIO *IO) { rss_aggregator *RSSAggr = (rss_aggregator *)IO->Data; - EVM_syslog(LOG_DEBUG, "RSS: Terminating.\n"); + EVRSSCM_syslog(LOG_DEBUG, "RSS: Terminating.\n"); UnlinkRSSAggregator(RSSAggr); @@ -197,7 +220,7 @@ eNextState RSSAggregator_ShutdownAbort(AsyncIO *IO) if (pUrl == NULL) pUrl = ""; - EV_syslog(LOG_DEBUG, "RSS: Aborting by shutdown: %s.\n", pUrl); + EVRSSC_syslog(LOG_DEBUG, "RSS: Aborting by shutdown: %s.\n", pUrl); UnlinkRSSAggregator(RSSAggr); @@ -252,7 +275,7 @@ eNextState RSS_FetchNetworkUsetableEntry(AsyncIO *IO) #ifndef DEBUG_RSS if (cdbut != NULL) { /* Item has already been seen */ - EV_syslog(LOG_DEBUG, + EVRSSC_syslog(LOG_DEBUG, "%s has already been seen\n", ChrPtr(Ctx->ThisMsg->MsgGUID)); cdb_free(cdbut); @@ -283,41 +306,42 @@ eNextState RSS_FetchNetworkUsetableEntry(AsyncIO *IO) /* * Begin a feed parse */ -int rss_do_fetching(rss_aggregator *Cfg) +int rss_do_fetching(rss_aggregator *RSSAggr) { + AsyncIO *IO = &RSSAggr->IO; rss_item *ri; time_t now; now = time(NULL); - if ((Cfg->next_poll != 0) && (now < Cfg->next_poll)) + if ((RSSAggr->next_poll != 0) && (now < RSSAggr->next_poll)) return 0; ri = (rss_item*) malloc(sizeof(rss_item)); memset(ri, 0, sizeof(rss_item)); - Cfg->Item = ri; + RSSAggr->Item = ri; - if (! InitcURLIOStruct(&Cfg->IO, - Cfg, + if (! InitcURLIOStruct(&RSSAggr->IO, + RSSAggr, "Citadel RSS Client", RSSAggregator_ParseReply, RSSAggregator_Terminate, RSSAggregator_TerminateDB, RSSAggregator_ShutdownAbort)) { - syslog(LOG_ALERT, "Unable to initialize libcurl.\n"); + EVRSSCM_syslog(LOG_ALERT, "Unable to initialize libcurl.\n"); return 0; } - safestrncpy(((CitContext*)Cfg->IO.CitContext)->cs_host, - ChrPtr(Cfg->Url), - sizeof(((CitContext*)Cfg->IO.CitContext)->cs_host)); + safestrncpy(((CitContext*)RSSAggr->IO.CitContext)->cs_host, + ChrPtr(RSSAggr->Url), + sizeof(((CitContext*)RSSAggr->IO.CitContext)->cs_host)); - syslog(LOG_DEBUG, "Fetching RSS feed <%s>\n", ChrPtr(Cfg->Url)); - ParseURL(&Cfg->IO.ConnectMe, Cfg->Url, 80); - CurlPrepareURL(Cfg->IO.ConnectMe); + EVRSSC_syslog(LOG_DEBUG, "Fetching RSS feed <%s>\n", ChrPtr(RSSAggr->Url)); + ParseURL(&RSSAggr->IO.ConnectMe, RSSAggr->Url, 80); + CurlPrepareURL(RSSAggr->IO.ConnectMe); - QueueCurlContext(&Cfg->IO); + QueueCurlContext(&RSSAggr->IO); return 1; } @@ -343,10 +367,10 @@ void rssclient_scan_room(struct ctdlroom *qrbuf, void *data) pthread_mutex_lock(&RSSQueueMutex); if (GetHash(RSSQueueRooms, LKEY(qrbuf->QRnumber), &vptr)) { - syslog(LOG_DEBUG, - "rssclient: [%ld] %s already in progress.\n", - qrbuf->QRnumber, - qrbuf->QRname); + EVRSSQ_syslog(LOG_DEBUG, + "rssclient: [%ld] %s already in progress.\n", + qrbuf->QRnumber, + qrbuf->QRname); pthread_mutex_unlock(&RSSQueueMutex); return; } @@ -370,10 +394,10 @@ void rssclient_scan_room(struct ctdlroom *qrbuf, void *data) return; if (fstat(fd, &statbuf) == -1) { - syslog(LOG_DEBUG, - "ERROR: could not stat configfile '%s' - %s\n", - filename, - strerror(errno)); + EVRSSQ_syslog(LOG_DEBUG, + "ERROR: could not stat configfile '%s' - %s\n", + filename, + strerror(errno)); return; } @@ -385,8 +409,8 @@ void rssclient_scan_room(struct ctdlroom *qrbuf, void *data) if (StrBufReadBLOB(CfgData, &fd, 1, statbuf.st_size, &Err) < 0) { close(fd); FreeStrBuf(&CfgData); - syslog(LOG_DEBUG, "ERROR: reading config '%s' - %s
\n", - filename, strerror(errno)); + EVRSSQ_syslog(LOG_ERR, "ERROR: reading config '%s' - %s
\n", + filename, strerror(errno)); return; } close(fd); @@ -481,8 +505,8 @@ void rssclient_scan_room(struct ctdlroom *qrbuf, void *data) { Count->QRnumber = qrbuf->QRnumber; pthread_mutex_lock(&RSSQueueMutex); - syslog(LOG_DEBUG, "rssclient: [%ld] %s now starting.\n", - qrbuf->QRnumber, qrbuf->QRname); + EVRSSQ_syslog(LOG_DEBUG, "client: [%ld] %s now starting.\n", + qrbuf->QRnumber, qrbuf->QRname); Put(RSSQueueRooms, LKEY(qrbuf->QRnumber), Count, NULL); pthread_mutex_unlock(&RSSQueueMutex); } @@ -505,10 +529,10 @@ void rssclient_scan(void) { /* Run no more than once every 15 minutes. */ if ((now - last_run) < 900) { - syslog(LOG_DEBUG, - "rssclient: polling interval not yet reached; last run was %ldm%lds ago", - ((now - last_run) / 60), - ((now - last_run) % 60) + EVRSSQ_syslog(LOG_DEBUG, + "Client: polling interval not yet reached; last run was %ldm%lds ago", + ((now - last_run) / 60), + ((now - last_run) % 60) ); return; } @@ -523,15 +547,15 @@ void rssclient_scan(void) { pthread_mutex_unlock(&RSSQueueMutex); if ((RSSRoomCount > 0) || (RSSCount > 0)) { - syslog(LOG_DEBUG, - "rssclient: concurrency check failed; %d rooms and %d url's are queued", - RSSRoomCount, RSSCount + EVRSSQ_syslog(LOG_DEBUG, + "rssclient: concurrency check failed; %d rooms and %d url's are queued", + RSSRoomCount, RSSCount ); return; } become_session(&rss_CC); - syslog(LOG_DEBUG, "rssclient started\n"); + EVRSSQM_syslog(LOG_DEBUG, "rssclient started\n"); CtdlForEachRoom(rssclient_scan_room, NULL); pthread_mutex_lock(&RSSQueueMutex); @@ -547,7 +571,7 @@ void rssclient_scan(void) { DeleteHashPos(&it); pthread_mutex_unlock(&RSSQueueMutex); - syslog(LOG_DEBUG, "rssclient ended\n"); + EVRSSQM_syslog(LOG_DEBUG, "rssclient ended\n"); return; } @@ -558,6 +582,10 @@ void rss_cleanup(void) DeleteHash(&RSSQueueRooms); } +void LogDebugEnableRSSClient(void) +{ + RSSClientDebugEnabled = 1; +} CTDL_MODULE_INIT(rssclient) { @@ -570,6 +598,7 @@ CTDL_MODULE_INIT(rssclient) syslog(LOG_INFO, "%s\n", curl_version()); CtdlRegisterSessionHook(rssclient_scan, EVT_TIMER); CtdlRegisterEVCleanupHook(rss_cleanup); + CtdlRegisterDebugFlagHook(HKEY("rssclient"), LogDebugEnableRSSClient); } return "rssclient"; } 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)