X-Git-Url: https://code.citadel.org/?a=blobdiff_plain;f=citadel%2Fmodules%2Fpop3client%2Fserv_pop3client.c;h=433309f38895ed0d9e6877f510ad40848e985d3c;hb=3e3d387a634d0d82ed22a8db85f4cc036b60df17;hp=2f6e69c0cd6962ec862cf287116e0c6b54b7a485;hpb=c42eb07cca6871697b3c6be3fa486754c871fdf3;p=citadel.git

diff --git a/citadel/modules/pop3client/serv_pop3client.c b/citadel/modules/pop3client/serv_pop3client.c
index 2f6e69c0c..433309f38 100644
--- a/citadel/modules/pop3client/serv_pop3client.c
+++ b/citadel/modules/pop3client/serv_pop3client.c
@@ -63,30 +63,42 @@ int POP3ClientDebugEnabled = 0;
 
 #define EVP3C_syslog(LEVEL, FORMAT, ...)				\
 	DBGLOG(LEVEL) syslog(LEVEL,					\
-			     "IO[%ld]CC[%d][%ld]" FORMAT,		\
+			     "IO[%ld]CC[%d][%ld]POP3: " FORMAT,		\
 			     IO->ID, CCID, N, __VA_ARGS__)
 
 #define EVP3CM_syslog(LEVEL, FORMAT)					\
 	DBGLOG(LEVEL) syslog(LEVEL,					\
-			     "IO[%ld]CC[%d][%ld]" FORMAT,		\
+			     "IO[%ld]CC[%d][%ld]POP3: " FORMAT,		\
 			     IO->ID, CCID, N)
 
+#define EVP3CQ_syslog(LEVEL, FORMAT, ...)				\
+	DBGLOG(LEVEL) syslog(LEVEL,					\
+			     "P3Q:" FORMAT,				\
+			     __VA_ARGS__)
+
+#define EVP3CQM_syslog(LEVEL, FORMAT)					\
+	DBGLOG(LEVEL) syslog(LEVEL,					\
+			     "P3Q" FORMAT				\
+		)
+
 #define EVP3CCS_syslog(LEVEL, FORMAT, ...)				\
-	DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]" FORMAT,		\
+	DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]POP3: " FORMAT,	\
 			     IO->ID, N, __VA_ARGS__)
 
-#define EVP3CCSM_syslog(LEVEL, FORMAT)				\
-	DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]" FORMAT,	\
+#define EVP3CCSM_syslog(LEVEL, FORMAT)					\
+	DBGLOG(LEVEL) syslog(LEVEL, "IO[%ld][%ld]POP3: " FORMAT,	\
 			     IO->ID, N)
 
 #define POP3C_DBG_SEND()						\
 	EVP3C_syslog(LOG_DEBUG,						\
-		     "POP3: > %s\n",					\
+		     "IO[%ld]CC[%d][%ld]POP3: > %s\n",			\
+		     IO->ID, CCID, N,					\
 		     ChrPtr(RecvMsg->IO.SendBuf.Buf))
 
-#define POP3C_DBG_READ()				\
-	EVP3C_syslog(LOG_DEBUG,				\
-		     "POP3: < %s\n",			\
+#define POP3C_DBG_READ()						\
+	EVP3C_syslog(LOG_DEBUG,						\
+		     "IO[%ld]CC[%d][%ld]POP3: < %s\n",			\
+		     IO->ID, CCID, N,					\
 		     ChrPtr(RecvMsg->IO.IOBuf))
 
 
@@ -150,6 +162,8 @@ struct pop3aggr {
 	AsyncIO	 IO;
 
 	long n;
+	double IOStart;
+	long count;
 	long RefCount;
 	DNSQueryParts HostLookup;
 
@@ -159,6 +173,7 @@ struct pop3aggr {
 	StrBuf		*Url;
 	StrBuf *pop3user;
 	StrBuf *pop3pass;
+	StrBuf *Host;
 	StrBuf *RoomName; // TODO: fill me
 	int keep;
 	time_t interval;
@@ -176,6 +191,7 @@ void DeletePOP3Aggregator(void *vptr)
 //	FreeStrBuf(&ptr->rooms);
 	FreeStrBuf(&ptr->pop3user);
 	FreeStrBuf(&ptr->pop3pass);
+	FreeStrBuf(&ptr->Host);
 	FreeStrBuf(&ptr->RoomName);
 	FreeURL(&ptr->IO.ConnectMe);
 	FreeStrBuf(&ptr->Url);
@@ -192,14 +208,21 @@ void DeletePOP3Aggregator(void *vptr)
 eNextState FinalizePOP3AggrRun(AsyncIO *IO)
 {
 	HashPos  *It;
-	pop3aggr *cptr = (pop3aggr *)IO->Data;
+	pop3aggr *cpptr = (pop3aggr *)IO->Data;
 
-	EVP3CM_syslog(LOG_DEBUG, "Terminating Aggregator; bye.\n");
+	EVP3C_syslog(LOG_INFO,
+		     "%s@%s: fetched %ld new of %d messages in %fs. bye.",
+		     ChrPtr(cpptr->pop3user),
+		     ChrPtr(cpptr->Host),
+		     cpptr->count,
+		     GetCount(cpptr->MsgNumbers), 
+		     IO->Now - cpptr->IOStart 
+		);
 
 	It = GetNewHashPos(POP3FetchUrls, 0);
 	pthread_mutex_lock(&POP3QueueMutex);
 	{
-		if (GetHashPosFromKey(POP3FetchUrls, SKEY(cptr->Url), It))
+		if (GetHashPosFromKey(POP3FetchUrls, SKEY(cpptr->Url), It))
 			DeleteEntryFromHash(POP3FetchUrls, It);
 	}
 	pthread_mutex_unlock(&POP3QueueMutex);
@@ -319,14 +342,14 @@ eNextState POP3C_GetListOneLine(pop3aggr *RecvMsg)
 #if 0
 	rc = TestValidateHash(RecvMsg->MsgNumbers);
 	if (rc != 0)
-		syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
+		EVP3CCS_syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
 #endif
 
 	Put(RecvMsg->MsgNumbers, LKEY(OneMsg->MSGID), OneMsg, HfreeFetchItem);
 #if 0
 	rc = TestValidateHash(RecvMsg->MsgNumbers);
 	if (rc != 0)
-		syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
+		EVP3CCS_syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
 #endif
 	//RecvMsg->State --; /* read next Line */
 	return eReadMore;
@@ -340,7 +363,8 @@ eNextState POP3_FetchNetworkUsetableEntry(AsyncIO *IO)
 	struct cdbdata *cdbut;
 	pop3aggr *RecvMsg = (pop3aggr *) IO->Data;
 
-	if(GetNextHashPos(RecvMsg->MsgNumbers,
+	if((RecvMsg->Pos != NULL) &&
+	   GetNextHashPos(RecvMsg->MsgNumbers,
 			  RecvMsg->Pos,
 			  &HKLen,
 			  &HKey,
@@ -351,9 +375,9 @@ eNextState POP3_FetchNetworkUsetableEntry(AsyncIO *IO)
 			return eAbort;
 
 		RecvMsg->CurrMsg = (FetchItem*) vData;
-		syslog(LOG_DEBUG,
-		       "CHECKING: whether %s has already been seen: ",
-		       ChrPtr(RecvMsg->CurrMsg->MsgUID));
+		EVP3CCS_syslog(LOG_DEBUG,
+			       "CHECKING: whether %s has already been seen: ",
+			       ChrPtr(RecvMsg->CurrMsg->MsgUID));
 
 		/* Find out if we've already seen this item */
 		safestrncpy(ut.ut_msgid,
@@ -364,7 +388,7 @@ eNextState POP3_FetchNetworkUsetableEntry(AsyncIO *IO)
 		cdbut = cdb_fetch(CDB_USETABLE, SKEY(RecvMsg->CurrMsg->MsgUID));
 		if (cdbut != NULL) {
 			/* Item has already been seen */
-			syslog(LOG_DEBUG, "YES\n");
+			EVP3CCSM_syslog(LOG_DEBUG, "YES\n");
 			cdb_free(cdbut);
 
 			/* rewrite the record anyway, to update the timestamp */
@@ -375,7 +399,7 @@ eNextState POP3_FetchNetworkUsetableEntry(AsyncIO *IO)
 		}
 		else
 		{
-			syslog(LOG_DEBUG, "NO\n");
+			EVP3CCSM_syslog(LOG_DEBUG, "NO\n");
 			RecvMsg->CurrMsg->NeedFetch = 1;
 		}
 		return NextDBOperation(&RecvMsg->IO,
@@ -402,9 +426,10 @@ eNextState POP3C_GetOneMessagID(pop3aggr *RecvMsg)
 	int rc;
 	rc = TestValidateHash(RecvMsg->MsgNumbers);
 	if (rc != 0)
-		syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
+		EVP3CCS_syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
 #endif
-	if(GetNextHashPos(RecvMsg->MsgNumbers,
+	if((RecvMsg->Pos != NULL) &&
+	   GetNextHashPos(RecvMsg->MsgNumbers,
 			  RecvMsg->Pos,
 			  &HKLen, &HKey,
 			  &vData))
@@ -418,7 +443,7 @@ eNextState POP3C_GetOneMessagID(pop3aggr *RecvMsg)
 	}
 	else
 	{
-	    RecvMsg->State++;
+		RecvMsg->State++;
 		DeleteHashPos(&RecvMsg->Pos);
 		/// done receiving uidls.. start looking them up now.
 		RecvMsg->Pos = GetNewHashPos(RecvMsg->MsgNumbers, 0);
@@ -435,7 +460,7 @@ eNextState POP3C_GetOneMessageIDState(pop3aggr *RecvMsg)
 	int rc;
 	rc = TestValidateHash(RecvMsg->MsgNumbers);
 	if (rc != 0)
-		syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
+		EVP3CCS_syslog(LOG_DEBUG, "Hash Invalid: %d\n", rc);
 #endif
 
 	POP3C_DBG_READ();
@@ -467,7 +492,8 @@ eNextState POP3C_SendGetOneMsg(pop3aggr *RecvMsg)
 	void *vData;
 
 	RecvMsg->CurrMsg = NULL;
-	while (GetNextHashPos(RecvMsg->MsgNumbers,
+	while ((RecvMsg->Pos != NULL) && 
+	       GetNextHashPos(RecvMsg->MsgNumbers,
 			      RecvMsg->Pos,
 			      &HKLen, &HKey,
 			      &vData) &&
@@ -511,9 +537,9 @@ eNextState POP3C_StoreMsgRead(AsyncIO *IO)
 	pop3aggr *RecvMsg = (pop3aggr *) IO->Data;
 	struct UseTable ut;
 
-	syslog(LOG_DEBUG,
-	       "MARKING: %s as seen: ",
-	       ChrPtr(RecvMsg->CurrMsg->MsgUID));
+	EVP3CCS_syslog(LOG_DEBUG,
+		       "MARKING: %s as seen: ",
+		       ChrPtr(RecvMsg->CurrMsg->MsgUID));
 
 	safestrncpy(ut.ut_msgid,
 		    ChrPtr(RecvMsg->CurrMsg->MsgUID),
@@ -546,6 +572,7 @@ eNextState POP3C_SaveMsg(AsyncIO *IO)
 	}
 	CtdlFreeMessage(RecvMsg->CurrMsg->Msg);
 
+	RecvMsg->count ++;
 	return NextDBOperation(&RecvMsg->IO, POP3C_StoreMsgRead);
 }
 
@@ -555,7 +582,7 @@ eNextState POP3C_ReadMessageBody(pop3aggr *RecvMsg)
 	EVP3CM_syslog(LOG_DEBUG, "Converting message...");
 	RecvMsg->CurrMsg->Msg =
 		convert_internet_message_buf(&RecvMsg->IO.ReadMsg->MsgBuf);
-	StopClientWatchers(IO);
+	StopClientWatchers(IO, 0);
 	return QueueDBOperation(&RecvMsg->IO, POP3C_SaveMsg);
 }
 
@@ -714,7 +741,7 @@ void POP3SetTimeout(eNextState NextTCPState, pop3aggr *pMsg)
 }
 eNextState POP3_C_DispatchReadDone(AsyncIO *IO)
 {
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+/*	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__); to noisy anyways. */
 	pop3aggr *pMsg = IO->Data;
 	eNextState rc;
 
@@ -726,10 +753,10 @@ eNextState POP3_C_DispatchReadDone(AsyncIO *IO)
 }
 eNextState POP3_C_DispatchWriteDone(AsyncIO *IO)
 {
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	pop3aggr *pMsg = IO->Data;
 	eNextState rc;
 
+/*	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__); to noisy anyways. */
 	rc = POP3C_SendHandlers[pMsg->State](pMsg);
 	POP3SetTimeout(rc, pMsg);
 	return rc;
@@ -743,7 +770,7 @@ eNextState POP3_C_Terminate(AsyncIO *IO)
 {
 ///	pop3aggr *pMsg = (pop3aggr *)IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	FinalizePOP3AggrRun(IO);
 	return eAbort;
 }
@@ -751,7 +778,7 @@ eNextState POP3_C_TerminateDB(AsyncIO *IO)
 {
 ///	pop3aggr *pMsg = (pop3aggr *)IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	FinalizePOP3AggrRun(IO);
 	return eAbort;
 }
@@ -759,7 +786,7 @@ eNextState POP3_C_Timeout(AsyncIO *IO)
 {
 	pop3aggr *pMsg = IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	StrBufPlain(IO->ErrMsg, CKEY(POP3C_ReadErrors[pMsg->State]));
 	return FailAggregationRun(IO);
 }
@@ -767,7 +794,7 @@ eNextState POP3_C_ConnFail(AsyncIO *IO)
 {
 	pop3aggr *pMsg = (pop3aggr *)IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	StrBufPlain(IO->ErrMsg, CKEY(POP3C_ReadErrors[pMsg->State]));
 	return FailAggregationRun(IO);
 }
@@ -775,13 +802,13 @@ eNextState POP3_C_DNSFail(AsyncIO *IO)
 {
 	pop3aggr *pMsg = (pop3aggr *)IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 	StrBufPlain(IO->ErrMsg, CKEY(POP3C_ReadErrors[pMsg->State]));
 	return FailAggregationRun(IO);
 }
 eNextState POP3_C_Shutdown(AsyncIO *IO)
 {
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 ////	pop3aggr *pMsg = IO->Data;
 
 ////pMsg->MyQEntry->Status = 3;
@@ -830,7 +857,7 @@ eNextState POP3_C_ReAttachToFetchMessages(AsyncIO *IO)
 {
 	pop3aggr *cpptr = IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 ////???	cpptr->State ++;
 	if (cpptr->Pos == NULL)
 		cpptr->Pos = GetNewHashPos(cpptr->MsgNumbers, 0);
@@ -843,7 +870,12 @@ eNextState POP3_C_ReAttachToFetchMessages(AsyncIO *IO)
 
 eNextState pop3_connect_ip(AsyncIO *IO)
 {
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	pop3aggr *cpptr = IO->Data;
+
+	if (cpptr->IOStart == 0.0) /* whith or without DNS? */
+		cpptr->IOStart = IO->Now;
+
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
 
 	return EvConnectSock(IO,
 			     POP3_C_ConnTimeout,
@@ -894,14 +926,16 @@ eNextState pop3_get_one_host_ip(AsyncIO *IO)
 {
 	pop3aggr *cpptr = IO->Data;
 
-	syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+	cpptr->IOStart = IO->Now;
 
-	syslog(LOG_DEBUG, 
-		      "POP3 client[%ld]: looking up %s-Record %s : %d ...\n",
-		      cpptr->n,
-		      (cpptr->IO.ConnectMe->IPv6)? "aaaa": "a",
-		      cpptr->IO.ConnectMe->Host,
-		      cpptr->IO.ConnectMe->Port);
+	EVP3CCS_syslog(LOG_DEBUG, "POP3: %s\n", __FUNCTION__);
+
+	EVP3CCS_syslog(LOG_DEBUG, 
+		       "POP3 client[%ld]: looking up %s-Record %s : %d ...\n",
+		       cpptr->n,
+		       (cpptr->IO.ConnectMe->IPv6)? "aaaa": "a",
+		       cpptr->IO.ConnectMe->Host,
+		       cpptr->IO.ConnectMe->Port);
 
 	QueueQuery((cpptr->IO.ConnectMe->IPv6)? ns_t_aaaa : ns_t_a,
 		   cpptr->IO.ConnectMe->Host,
@@ -969,11 +1003,12 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data)
 	pthread_mutex_lock(&POP3QueueMutex);
 	if (GetHash(POP3QueueRooms, LKEY(qrbuf->QRnumber), &vptr))
 	{
-		syslog(LOG_DEBUG,
-			      "pop3client: [%ld] %s already in progress.\n",
+		pthread_mutex_unlock(&POP3QueueMutex);
+		EVP3CQ_syslog(LOG_DEBUG,
+			      "pop3client: [%ld] %s already in progress.",
 			      qrbuf->QRnumber,
 			      qrbuf->QRname);
-		pthread_mutex_unlock(&POP3QueueMutex);
+		return;
 	}
 	pthread_mutex_unlock(&POP3QueueMutex);
 
@@ -992,10 +1027,10 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data)
 	if (server_shutting_down)
 		return;
 	if (fstat(fd, &statbuf) == -1) {
-		syslog(LOG_DEBUG,
-		       "ERROR: could not stat configfile '%s' - %s\n",
-		       filename,
-		       strerror(errno));
+		EVP3CQ_syslog(LOG_INFO,
+			      "ERROR: could not stat configfile '%s' - %s",
+			      filename,
+			      strerror(errno));
 		return;
 	}
 	if (server_shutting_down)
@@ -1004,7 +1039,8 @@ void pop3client_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<br>\n",
+		EVP3CQ_syslog(LOG_INFO,
+			      "ERROR: reading config '%s' - %s",
 			      filename, strerror(errno));
 		return;
 	}
@@ -1027,7 +1063,6 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data)
 			if (!strcasecmp("pop3client", ChrPtr(CfgType)))
 			{
 				pop3aggr *cptr;
-				StrBuf *Tmp;
 /*
 				if (Count == NULL)
 				{
@@ -1046,9 +1081,10 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data)
 				cptr->pop3pass =
 					NewStrBufPlain(NULL, StrLength(Line));
 				cptr->Url = NewStrBuf();
-				Tmp = NewStrBuf();
+				cptr->Host =
+					NewStrBufPlain(NULL, StrLength(Line));
 
-				StrBufExtract_NextToken(Tmp, Line, &lPtr, '|');
+				StrBufExtract_NextToken(cptr->Host, Line, &lPtr, '|');
 				StrBufExtract_NextToken(cptr->pop3user,
 							Line,
 							&lPtr,
@@ -1072,11 +1108,10 @@ void pop3client_scan_room(struct ctdlroom *qrbuf, void *data)
 				StrBufAppendBufPlain(cptr->Url, HKEY(":"), 0);
 				StrBufUrlescUPAppend(cptr->Url, cptr->pop3pass, NULL);
 				StrBufAppendBufPlain(cptr->Url, HKEY("@"), 0);
-				StrBufAppendBuf(cptr->Url, Tmp, 0);
+				StrBufAppendBuf(cptr->Url, cptr->Host, 0);
 				StrBufAppendBufPlain(cptr->Url, HKEY("/"), 0);
 				StrBufUrlescAppend(cptr->Url, cptr->RoomName, NULL);
 
-				FreeStrBuf(&Tmp);
 				ParseURL(&cptr->IO.ConnectMe, cptr->Url, 110);
 
 
@@ -1176,7 +1211,7 @@ void pop3client_scan(void) {
 	if (doing_pop3client) return;
 	doing_pop3client = 1;
 
-	syslog(LOG_DEBUG, "pop3client started");
+	EVP3CQM_syslog(LOG_DEBUG, "pop3client started");
 	CtdlForEachRoom(pop3client_scan_room, NULL);
 
 	pthread_mutex_lock(&POP3QueueMutex);
@@ -1202,7 +1237,7 @@ void pop3client_scan(void) {
 	DeleteHashPos(&it);
 	pthread_mutex_unlock(&POP3QueueMutex);
 
-	syslog(LOG_DEBUG, "pop3client ended");
+	EVP3CQM_syslog(LOG_DEBUG, "pop3client ended");
 	last_run = time(NULL);
 	doing_pop3client = 0;
 }
@@ -1231,7 +1266,7 @@ CTDL_MODULE_INIT(pop3client)
 		pthread_mutex_init(&POP3QueueMutex, NULL);
 		POP3QueueRooms = NewHash(1, lFlathash);
 		POP3FetchUrls = NewHash(1, NULL);
-		CtdlRegisterSessionHook(pop3client_scan, EVT_TIMER);
+		CtdlRegisterSessionHook(pop3client_scan, EVT_TIMER, PRIO_AGGR + 50);
 		CtdlRegisterEVCleanupHook(pop3_cleanup);
 		CtdlRegisterDebugFlagHook(HKEY("pop3client"), LogDebugEnablePOP3Client, &POP3ClientDebugEnabled);
 	}