revamped logging system to make it more clear

This commit is contained in:
ps 2011-01-08 01:29:17 +00:00
parent b8e6af28fe
commit 3b0c15ac6f
13 changed files with 144 additions and 138 deletions

View file

@ -1,6 +1,10 @@
ChangeLog ChangeLog
--------- ---------
2011-01-08 02:27 Juan José Gutiérrez de Quevedo <juanjo@gutierrezdequevedo.com>
* revamped logging system. hopefully, messages will be more informative now
2011-01-06 23:53 Juan José Gutiérrez de Quevedo <juanjo@gutierrezdequevedo.com> 2011-01-06 23:53 Juan José Gutiérrez de Quevedo <juanjo@gutierrezdequevedo.com>
* development restarted * development restarted

View file

@ -36,7 +36,7 @@ void Configfile::parse(string file)
char line[255]; char line[255];
int equalpos; int equalpos;
hermes_log.addMessage(LOG_INFO,"parsing "+Utils::get_canonical_filename(file)+" configuration file"); LINF("parsing "+Utils::get_canonical_filename(file)+" configuration file");
f.open(file.c_str(),ios::in); f.open(file.c_str(),ios::in);
while(!f.eof()) while(!f.eof())
{ {
@ -47,10 +47,9 @@ void Configfile::parse(string file)
equalpos=l.find("="); equalpos=l.find("=");
string option=Utils::trim(l.substr(0,equalpos)); string option=Utils::trim(l.substr(0,equalpos));
string value=Utils::trim(l.substr(equalpos+1)); string value=Utils::trim(l.substr(equalpos+1));
#ifdef REALLY_VERBOSE_DEBUG //if(false==cfg.getBackground())
cout << l << endl; // cout << option << " -> " << value << endl;
cout << option << "->" << value << endl;
#endif //REALLY_VERBOSE_DEBUG
//this is a bit of a hack, but simplifies a lot this function //this is a bit of a hack, but simplifies a lot this function
#define PARSE_INT(x,y) if(x==option) y=Configfile::parseAsInt(value); else #define PARSE_INT(x,y) if(x==option) y=Configfile::parseAsInt(value); else
#define PARSE_BOOL(x,y) if(x==option) y=Configfile::parseAsBool(value); else #define PARSE_BOOL(x,y) if(x==option) y=Configfile::parseAsBool(value); else

View file

@ -19,6 +19,8 @@
*/ */
#include "Database.h" #include "Database.h"
extern LOGGER_CLASS hermes_log;
void Database::setDatabaseFile(string p_dbfile) void Database::setDatabaseFile(string p_dbfile)
{ {
dbfile=p_dbfile; dbfile=p_dbfile;
@ -33,6 +35,8 @@ void Database::setDatabaseFile(string p_dbfile)
void Database::doQuery(string p_sql) void Database::doQuery(string p_sql)
{ {
int retval; int retval;
bool was_busy=false;
do do
{ {
retval=sqlite3_exec(dbh,p_sql.c_str(),NULL,NULL,NULL); retval=sqlite3_exec(dbh,p_sql.c_str(),NULL,NULL,NULL);
@ -41,12 +45,13 @@ void Database::doQuery(string p_sql)
if(SQLITE_BUSY==retval) if(SQLITE_BUSY==retval)
{ {
sleep(1+rand()%2); sleep(1+rand()%2);
#ifdef REALLY_VERBOSE_DEBUG LERR("doquery() sql failed with busy state, retrying");
cout << pthread_self() << " doquery() sql failed with busy state, retrying" << endl; was_busy=true;
#endif //REALLY_VERBOSE_DEBUG
} }
} }
while(SQLITE_BUSY==retval); while(SQLITE_BUSY==retval);
if(was_busy)
LERR("doquery() executed correctly after failing initially");
} }
string Database::cleanString(string s) string Database::cleanString(string s)
@ -85,6 +90,7 @@ bool Database::greylisted(string ip,string from,string to,int initial_expiry,int
int nrow=0; int nrow=0;
int ncolumn=0; int ncolumn=0;
bool retval=true; bool retval=true;
bool was_busy=false;
int sqlite_retval; int sqlite_retval;
int now=time(NULL); int now=time(NULL);
string strnow=Utils::inttostr(now); string strnow=Utils::inttostr(now);
@ -102,12 +108,13 @@ bool Database::greylisted(string ip,string from,string to,int initial_expiry,int
if(SQLITE_BUSY==sqlite_retval) if(SQLITE_BUSY==sqlite_retval)
{ {
sleep(1+rand()%2); sleep(1+rand()%2);
#ifdef REALLY_VERBOSE_DEBUG LERR("greylisted() sql failed with busy state, retrying");
cout << pthread_self() << " greylisted() sql busy" << endl; was_busy=true;
#endif //REALLY_VERBOSE_DEBUG
} }
} }
while(sqlite_retval==SQLITE_BUSY); while(sqlite_retval==SQLITE_BUSY);
if(was_busy)
LERR("greylisted() executed correctly after failing initially");
sql=""; sql="";
@ -203,6 +210,7 @@ int Database::countRows(string p_sql)
int nrow=0; int nrow=0;
int ncolumn=0; int ncolumn=0;
int sqlite_retval; int sqlite_retval;
bool was_busy=false;
do do
{ {
@ -216,12 +224,13 @@ int Database::countRows(string p_sql)
if(SQLITE_BUSY==sqlite_retval) if(SQLITE_BUSY==sqlite_retval)
{ {
sleep(1+rand()%2); sleep(1+rand()%2);
#ifdef REALLY_VERBOSE_DEBUG LERR("countRows() sql failed with busy state, retrying");
cout << pthread_self() << " countRows() retrying" << endl; was_busy=true;
#endif //REALLY_VERBOSE_DEBUG
} }
} }
while(SQLITE_BUSY==sqlite_retval); while(SQLITE_BUSY==sqlite_retval);
if(was_busy)
LERR("countRows() executed correctly after failing initially");
if(NULL!=result) if(NULL!=result)
sqlite3_free_table(result); sqlite3_free_table(result);
@ -357,6 +366,7 @@ unsigned long Database::getIntValue(string& p_sql)
int nrow=0; int nrow=0;
int ncolumn=0; int ncolumn=0;
int sqlite_retval; int sqlite_retval;
bool was_busy=false;
unsigned long value; unsigned long value;
do do
@ -371,12 +381,13 @@ unsigned long Database::getIntValue(string& p_sql)
if(SQLITE_BUSY==sqlite_retval) if(SQLITE_BUSY==sqlite_retval)
{ {
sleep(1+rand()%2); sleep(1+rand()%2);
#ifdef REALLY_VERBOSE_DEBUG LERR("getIntValue() sql failed with busy state, retrying");
cout << pthread_self() << " getIntValue() retrying" << endl; was_busy=true;
#endif //REALLY_VERBOSE_DEBUG
} }
} }
while(SQLITE_BUSY==sqlite_retval); while(SQLITE_BUSY==sqlite_retval);
if(was_busy)
LERR("getIntValue() executed correctly after failing initially");
if(NULL==result) if(NULL==result)
throw SQLException("SQL: "+p_sql+" didn't return any data, SQL query may be wrong",__FILE__,__LINE__); throw SQLException("SQL: "+p_sql+" didn't return any data, SQL query may be wrong",__FILE__,__LINE__);
@ -408,9 +419,7 @@ unsigned long Database::cleanDB()
//we do it always because if we don't submit stats it stills appears on the logs //we do it always because if we don't submit stats it stills appears on the logs
sql="SELECT SUM(blocked) FROM greylist WHERE expires<strftime('%s','now') AND passed=0;"; sql="SELECT SUM(blocked) FROM greylist WHERE expires<strftime('%s','now') AND passed=0;";
spamcount=getIntValue(sql); spamcount=getIntValue(sql);
#ifdef REALLY_VERBOSE_DEBUG LINF("We have processed " + Utils::ulongtostr(spamcount) + " spam emails in the last 4 hours");
cout << "We have processed " << spamcount << " spam emails in the last 4 hours" << endl;
#endif //REALLY_VERBOSE_DEBUG
//at last, delete them from the database //at last, delete them from the database
doQuery("DELETE FROM greylist WHERE expires<strftime('%s','now');"); doQuery("DELETE FROM greylist WHERE expires<strftime('%s','now');");

View file

@ -25,9 +25,6 @@ extern LOGGER_CLASS hermes_log;
Exception::Exception(string p_error,string p_file,unsigned p_line) Exception::Exception(string p_error,string p_file,unsigned p_line)
{ {
error=p_error; error=p_error;
#ifdef REALLY_VERBOSE_DEBUG
hermes_log.addMessage(LOG_ERR,p_error);
#endif //REALLY_VERBOSE_DEBUG
#ifdef NOTIFY_EXCEPTIONS #ifdef NOTIFY_EXCEPTIONS
if(cfg.getNotifyTo()!="") if(cfg.getNotifyTo()!="")
{ {
@ -37,7 +34,7 @@ Exception::Exception(string p_error,string p_file,unsigned p_line)
} }
catch(NotifyException &e) catch(NotifyException &e)
{ {
cout << string(e) << endl; LERR(e);
} }
} }
#endif //NOTIFY_EXCEPTIONS #endif //NOTIFY_EXCEPTIONS

View file

@ -31,7 +31,7 @@ class Logger
{ {
public: public:
virtual ~Logger(){}; //empty destructor, not creating anything virtual ~Logger(){}; //empty destructor, not creating anything
virtual void addMessage(int,string)=0; virtual void addMessage(string,int,int,string)=0;
}; };
#ifndef WIN32 #ifndef WIN32

View file

@ -36,10 +36,6 @@ void Proxy::setOutside(Socket& p_outside)
*/ */
void Proxy::run(string &peer_address) void Proxy::run(string &peer_address)
{ {
#ifdef REALLY_VERBOSE_DEBUG
string debugLog="\r\n";
#endif //REALLY_VERBOSE_DEBUG
#ifdef HAVE_SPF #ifdef HAVE_SPF
Spf spf_checker; Spf spf_checker;
#endif //HAVE_SPF #endif //HAVE_SPF
@ -76,10 +72,7 @@ void Proxy::run(string &peer_address)
sleep(cfg.getBannerDelayTime()); sleep(cfg.getBannerDelayTime());
if(outside.canRead(0)) //if we have data waiting before the server gives us a 220 then quit, it's spam if(outside.canRead(0)) //if we have data waiting before the server gives us a 220 then quit, it's spam
{ {
#ifdef REALLY_VERBOSE_DEBUG LINF("421 (data_before_banner) (ip:"+peer_address+")");
cout << peer_address << " sent data before 220, exiting..." << endl;
#endif //REALLY_VERBOSE_DEBUG
hermes_log.addMessage(LOG_INFO,"421 (data_before_banner) (ip:"+peer_address+")");
sleep(20); // but first let's annoy spammers once more sleep(20); // but first let's annoy spammers once more
outside.writeLine("421 Stop sending data before we show you the banner"); outside.writeLine("421 Stop sending data before we show you the banner");
return; return;
@ -101,9 +94,6 @@ void Proxy::run(string &peer_address)
if(outside.canRead(0.2)) //client wants to send something to server if(outside.canRead(0.2)) //client wants to send something to server
{ {
strtemp=outside.readLine(); strtemp=outside.readLine();
#ifdef REALLY_VERBOSE_DEBUG
debugLog+="c> "+strtemp+"\r\n";
#endif //REALLY_VERBOSE_DEBUG
if(outside.isClosed()) if(outside.isClosed())
return; return;
if(strtemp.length()>10&&"mail from:"==Utils::strtolower(strtemp.substr(0,10))) if(strtemp.length()>10&&"mail from:"==Utils::strtolower(strtemp.substr(0,10)))
@ -147,9 +137,7 @@ void Proxy::run(string &peer_address)
code="421"; code="421";
mechanism="greylist"; mechanism="greylist";
message=code+" Greylisted!! Please try again in a few minutes."; message=code+" Greylisted!! Please try again in a few minutes.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
#ifdef HAVE_SPF #ifdef HAVE_SPF
else if(cfg.getQuerySpf()&&!authenticated&&!spf_checker.query(peer_address,ehlostr,from)) else if(cfg.getQuerySpf()&&!authenticated&&!spf_checker.query(peer_address,ehlostr,from))
@ -157,9 +145,7 @@ void Proxy::run(string &peer_address)
code=cfg.getReturnTempErrorOnReject()?"421":"550"; code=cfg.getReturnTempErrorOnReject()?"421":"550";
mechanism="spf"; mechanism="spf";
message=code+" You do not seem to be allowed to send email for that particular domain."; message=code+" You do not seem to be allowed to send email for that particular domain.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
#endif //HAVE_SPF #endif //HAVE_SPF
//check blacklist //check blacklist
@ -168,9 +154,7 @@ void Proxy::run(string &peer_address)
code=cfg.getReturnTempErrorOnReject()?"421":"550"; code=cfg.getReturnTempErrorOnReject()?"421":"550";
mechanism="allowed-domain-per-ip"; mechanism="allowed-domain-per-ip";
message=code+" You do not seem to be allowed to send email to that particular domain from that address."; message=code+" You do not seem to be allowed to send email to that particular domain from that address.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
//check rbl //check rbl
else if(!cfg.getDnsBlacklistDomains().empty()&&!authenticated&&Utils::listed_on_dns_lists(cfg.getDnsBlacklistDomains(),cfg.getDnsBlacklistPercentage(),peer_address)) else if(!cfg.getDnsBlacklistDomains().empty()&&!authenticated&&Utils::listed_on_dns_lists(cfg.getDnsBlacklistDomains(),cfg.getDnsBlacklistPercentage(),peer_address))
@ -178,27 +162,21 @@ void Proxy::run(string &peer_address)
code=cfg.getReturnTempErrorOnReject()?"421":"550"; code=cfg.getReturnTempErrorOnReject()?"421":"550";
mechanism="dnsbl"; mechanism="dnsbl";
message=code+" You are listed on some DNS blacklists. Get delisted before trying to send us email."; message=code+" You are listed on some DNS blacklists. Get delisted before trying to send us email.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
else if(cfg.getRejectNoReverseResolution()&&!authenticated&&""==resolvedname) else if(cfg.getRejectNoReverseResolution()&&!authenticated&&""==resolvedname)
{ {
code=cfg.getReturnTempErrorOnReject()?"421":"550"; code=cfg.getReturnTempErrorOnReject()?"421":"550";
mechanism="no reverse resolution"; mechanism="no reverse resolution";
message=code+" Your IP address does not resolve to a hostname."; message=code+" Your IP address does not resolve to a hostname.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
else if(cfg.getCheckHeloAgainstReverse()&&!authenticated&&ehlostr!=resolvedname) else if(cfg.getCheckHeloAgainstReverse()&&!authenticated&&ehlostr!=resolvedname)
{ {
code=cfg.getReturnTempErrorOnReject()?"421":"550"; code=cfg.getReturnTempErrorOnReject()?"421":"550";
mechanism="helo differs from resolved name"; mechanism="helo differs from resolved name";
message=code+" Your IP hostname doesn't match your envelope hostname."; message=code+" Your IP hostname doesn't match your envelope hostname.";
#ifdef REALLY_VERBOSE_DEBUG LINF("checking " + mechanism);
cout << "Checking " << mechanism << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
else else
code="250"; code="250";
@ -208,10 +186,7 @@ void Proxy::run(string &peer_address)
strlog.insert(0,code+" "); strlog.insert(0,code+" ");
//log the connection //log the connection
#ifdef REALLY_VERBOSE_DEBUG LINF(strlog);
cout << strlog << endl;
#endif //REALLY_VERBOSE_DEBUG
hermes_log.addMessage(LOG_INFO,strlog);
//if we didn't accept the email, punish spammers //if we didn't accept the email, punish spammers
if("250"!=code) if("250"!=code)
@ -231,21 +206,17 @@ void Proxy::run(string &peer_address)
#ifdef HAVE_SSL #ifdef HAVE_SSL
try try
{ {
#ifdef REALLY_VERBOSE_DEBUG LINF("STARTTLS issued by remote, TLS enabled");
cout << peer_address << " enabled starttls, using secure comunications!!!" << endl;
#endif //REALLY_VERBOSE_DEBUG
outside.writeLine("220 You can speak now, line is secure!!"); outside.writeLine("220 You can speak now, line is secure!!");
outside.enableSSL(true); outside.enableSSL(true);
} }
catch(Exception &e) catch(Exception &e)
{ {
#ifdef REALLY_VERBOSE_DEBUG LERR(e);
cout << string(e) << endl;
#endif //REALLY_VERBOSE_DEBUG
hermes_log.addMessage(LOG_DEBUG,string(e));
} }
#else #else
outside.writeLine("454 TLS temporarily not available"); outside.writeLine("454 TLS temporarily not available");
LINF("STARTTLS issued by remote, TLS was not enabled because this build lacks SSL support");
#endif //HAVE_SSL #endif //HAVE_SSL
strtemp=""; strtemp="";
} }
@ -257,9 +228,6 @@ void Proxy::run(string &peer_address)
if(inside.canRead(0.2)) //server wants to send something to client if(inside.canRead(0.2)) //server wants to send something to client
{ {
strtemp=inside.readLine(); strtemp=inside.readLine();
#ifdef REALLY_VERBOSE_DEBUG
debugLog+="s> "+strtemp+"\r\n";
#endif //REALLY_VERBOSE_DEBUG
if(inside.isClosed()) if(inside.isClosed())
return; return;
string code=strtemp.substr(0,3); //all responses by the server start with a code string code=strtemp.substr(0,3); //all responses by the server start with a code
@ -319,16 +287,9 @@ void Proxy::run(string &peer_address)
} }
catch(Exception &e) //any exception will close both connections catch(Exception &e) //any exception will close both connections
{ {
#ifdef REALLY_VERBOSE_DEBUG LERR(e);
cout << e << endl;
try
{
throw Exception(string(e)+debugLog+"\r\n",__FILE__,__LINE__);
}
catch(Exception &ex){}
#endif //REALLY_VERBOSE_DEBUG
if(last_state<SMTP_STATE_WAIT_FOR_DATA) if(last_state<SMTP_STATE_WAIT_FOR_DATA)
hermes_log.addMessage(LOG_INFO,"421 (throttling) from "+(""==from?"no-from":from)+" (ip:"+peer_address+", hostname:"+(""==resolvedname?"not-resolved":resolvedname)+", ehlo:"+(""==ehlostr?"no-ehlo":ehlostr)+") -> to "+(""==to?"no-to":to)); LINF("421 (probably-throttling) from "+(""==from?"no-from":from)+" (ip:"+peer_address+", hostname:"+(""==resolvedname?"not-resolved":resolvedname)+", ehlo:"+(""==ehlostr?"no-ehlo":ehlostr)+") -> to "+(""==to?"no-to":to));
return; return;
} }
} }

View file

@ -27,6 +27,7 @@ SSL_CTX *Socket::ssl_ctx_client=NULL;
#endif //HAVE_SSL #endif //HAVE_SSL
extern Configfile cfg; extern Configfile cfg;
extern LOGGER_CLASS hermes_log;
Socket::Socket():fd(-1) Socket::Socket():fd(-1)
#ifdef HAVE_SSL #ifdef HAVE_SSL
@ -254,6 +255,9 @@ string Socket::readLine()
s<<c; s<<c;
} }
while(c!=10&&!isClosed()); while(c!=10&&!isClosed());
LDEB("r>" + s.str());
return s.str(); return s.str();
} }
@ -298,6 +302,7 @@ void Socket::writeLine(string s)
s+="\r\n"; s+="\r\n";
LDEB("w>"+s);
writeBytes((void *)s.c_str(),s.length()); writeBytes((void *)s.c_str(),s.length());
} }

View file

@ -19,6 +19,9 @@
*/ */
#include "UnixLogger.h" #include "UnixLogger.h"
extern __thread unsigned long connection_id;
extern Configfile cfg;
UnixLogger::UnixLogger() UnixLogger::UnixLogger()
{ {
openlog("hermes",LOG_NDELAY,LOG_MAIL); openlog("hermes",LOG_NDELAY,LOG_MAIL);
@ -29,7 +32,12 @@ UnixLogger::~UnixLogger()
closelog(); closelog();
} }
void UnixLogger::addMessage(int loglevel,string logmessage) void UnixLogger::addMessage(string file,int line,int loglevel,string logmessage)
{ {
syslog(loglevel,logmessage.c_str()); string message;
message=file+":"+Utils::inttostr(line)+" [" + Utils::inttostr(connection_id) + "] " + logmessage;
if(false==cfg.getBackground())
cout << message << endl;
syslog(loglevel,message.c_str());
} }

View file

@ -37,7 +37,7 @@ class UnixLogger: public Logger
public: public:
UnixLogger(); UnixLogger();
~UnixLogger(); ~UnixLogger();
void addMessage(int,string); void addMessage(string,int,int,string);
}; };
#endif //UNIXLOGGER_H #endif //UNIXLOGGER_H

View file

@ -20,6 +20,7 @@
#include "Utils.h" #include "Utils.h"
extern Configfile cfg; extern Configfile cfg;
extern LOGGER_CLASS hermes_log;
//-------------------- //--------------------
// string functions: // string functions:
@ -40,6 +41,21 @@ string Utils::inttostr(int integer)
return s.str(); return s.str();
} }
/**
* convert unsigned long to string
*
* @param number number to convert
*
* @return string the number converted to stringtype
*
*/
string Utils::ulongtostr(unsigned long number)
{
stringstream s;
s << number;
return s.str();
}
/** /**
* return lowercase version of s * return lowercase version of s
* *
@ -445,27 +461,30 @@ bool Utils::listed_on_dns_lists(list<string>& dns_domains,unsigned char percenta
{ {
Socket::resolve(reversedip+dns_domain); Socket::resolve(reversedip+dns_domain);
times_listed++; times_listed++;
#ifdef REALLY_VERBOSE_DEBUG LINF(ip + " listed on " + dns_domain);
cout << ip << " listed on " << dns_domain << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
catch(Exception &e) catch(Exception &e)
{ {
#ifdef REALLY_VERBOSE_DEBUG LINF(ip + " NOT listed on " + dns_domain);
cout << ip << " NOT listed on " << dns_domain << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
checked_lists++; checked_lists++;
if((times_listed*100/number_of_lists)>=percentage) if((times_listed*100/number_of_lists)>=percentage)
{
LINF("ip " + ip + " listed on " + Utils::ulongtostr(times_listed) + " out of " + Utils::ulongtostr(checked_lists) + " checked servers, out of " + Utils::ulongtostr(number_of_lists) + ". threshold is " + Utils::ulongtostr(percentage) + "% -> return true");
return true; return true;
}
//if we have checked a number of lists that make it impossible for this function //if we have checked a number of lists that make it impossible for this function
//to return true, then return false //to return true, then return false
if((checked_lists*100/number_of_lists)>100-percentage) if((checked_lists*100/number_of_lists)>100-percentage)
{
LINF("ip " + ip + " listed on " + Utils::ulongtostr(times_listed) + " out of " + Utils::ulongtostr(checked_lists) + " checked servers, out of " + Utils::ulongtostr(number_of_lists) + ". threshold is " + Utils::ulongtostr(percentage) + "% -> return false");
return false; return false;
}
} }
LINF("ip " + ip + " listed on " + Utils::ulongtostr(times_listed) + " out of " + Utils::ulongtostr(checked_lists) + " checked servers, out of " + Utils::ulongtostr(number_of_lists) + ". threshold is " + Utils::ulongtostr(percentage) + "% -> return false");
return false; return false;
} }
@ -589,3 +608,16 @@ string Utils::gethostname()
return string(buf); return string(buf);
} }
void Utils::write_pid(string file,pid_t pid)
{
FILE *f;
f=fopen(file.c_str(),"w");
if(NULL==f)
throw Exception(_("Couldn't open file ")+file+_(" to write the pidfile"),__FILE__,__LINE__);
fprintf(f,"%d\n",pid);
fclose(f);
}

View file

@ -55,6 +55,7 @@ class Utils
static string strtolower(string); static string strtolower(string);
static string trim(string); static string trim(string);
static string inttostr(int); static string inttostr(int);
static string ulongtostr(unsigned long);
//email-related utilities //email-related utilities
static string getmail(string&); static string getmail(string&);
@ -80,6 +81,7 @@ class Utils
static string errnotostrerror(int); static string errnotostrerror(int);
static string rfc2821_date(time_t *timestamp=NULL); static string rfc2821_date(time_t *timestamp=NULL);
static string gethostname(); static string gethostname();
static void write_pid(string,pid_t);
}; };
#endif //UTILS_H #endif //UTILS_H

View file

@ -42,7 +42,6 @@ using namespace std;
void *thread_main(void *); void *thread_main(void *);
void *cleaner_thread_run(void *); void *cleaner_thread_run(void *);
void exit_requested(int); void exit_requested(int);
void write_pid(string,pid_t);
//global var to know when we have to exit //global var to know when we have to exit
bool quit=false; bool quit=false;
@ -57,6 +56,10 @@ Configfile cfg;
//our logger //our logger
LOGGER_CLASS hermes_log; LOGGER_CLASS hermes_log;
//this variable is thread-local to allow having a unique id per-thread which we can
//print at the start of log messages
__thread unsigned long connection_id;
list<pthread_t> children; list<pthread_t> children;
#ifdef HAVE_SSL #ifdef HAVE_SSL
@ -106,13 +109,11 @@ main
} }
catch(Exception &e) catch(Exception &e)
{ {
cout << string(e) << endl; LERR(e);
return -1; return -1;
} }
#ifdef REALLY_VERBOSE_DEBUG unsigned long nconns=0;
unsigned long nconns=0;
#endif //REALLY_VERBOSE_DEBUG
signal(SIGTERM,exit_requested); signal(SIGTERM,exit_requested);
signal(SIGINT,exit_requested); signal(SIGINT,exit_requested);
@ -134,7 +135,7 @@ main
if(retval<0) if(retval<0)
{ {
cout << _("Error forking into the background") << Utils::errnotostrerror(errno) << endl; LERR(_("Error forking into the background") + Utils::errnotostrerror(errno));
return -1; return -1;
} }
} }
@ -143,11 +144,11 @@ main
{ {
try try
{ {
write_pid(cfg.getPidFile(),getpid()); Utils::write_pid(cfg.getPidFile(),getpid());
} }
catch(Exception &e) catch(Exception &e)
{ {
hermes_log.addMessage(LOG_ERR,e); LERR(e);
} }
} }
@ -158,13 +159,14 @@ main
chdir(cfg.getChroot().c_str()); chdir(cfg.getChroot().c_str());
if(-1==chroot(cfg.getChroot().c_str())) if(-1==chroot(cfg.getChroot().c_str()))
{ {
cout << _("Couldn't chroot ") << Utils::errnotostrerror(errno) << endl; LERR(_("Couldn't chroot ") + Utils::errnotostrerror(errno));
return -1; return -1;
} }
chdir("/"); chdir("/");
} }
#endif //WIN32 #endif //WIN32
LINF("Starting hermes");
try try
{ {
server.init(); server.init();
@ -173,7 +175,7 @@ main
} }
catch(Exception &e) catch(Exception &e)
{ {
cout << e << endl; LERR(e);
return -1; //couldn't bind, exit return -1; //couldn't bind, exit
} }
@ -207,22 +209,19 @@ main
int fd=server.accept(&peer_address); int fd=server.accept(&peer_address);
info.new_fd=fd; info.new_fd=fd;
info.peer_address=peer_address; info.peer_address=peer_address;
info.connection_id=++nconns;
pthread_mutex_lock(&info_stack_mutex); pthread_mutex_lock(&info_stack_mutex);
info_stack.push(info); info_stack.push(info);
pthread_mutex_unlock(&info_stack_mutex); pthread_mutex_unlock(&info_stack_mutex);
retval=pthread_create(&thread,&thread_attr,thread_main,(void *)&info_stack); retval=pthread_create(&thread,&thread_attr,thread_main,(void *)&info_stack);
if(retval) if(retval)
{ {
#ifdef REALLY_VERBOSE_DEBUG LERR(_("Error creating thread: ") + Utils::errnotostrerror(retval) + _(". Sleeping 5 seconds before continuing..."));
cout << _("Error creating thread: ") << Utils::errnotostrerror(retval) << _(". Sleeping 5 seconds before continuing...") << endl;
#endif //REALLY_VERBOSE_DEBUG
sleep(5); sleep(5);
} }
else else
{ {
#ifdef REALLY_VERBOSE_DEBUG LDEB("New thread created [" + Utils::ulongtostr(nconns) + "] thread_id: " + Utils::ulongtostr(thread));
cout << "[ " << ++nconns << " ] " << endl;
#endif //REALLY_VERBOSE_DEBUG
pthread_mutex_lock(&childrenlist_mutex); pthread_mutex_lock(&childrenlist_mutex);
children.push_back(thread); children.push_back(thread);
pthread_mutex_unlock(&childrenlist_mutex); pthread_mutex_unlock(&childrenlist_mutex);
@ -234,22 +233,21 @@ main
server.close(); server.close();
// wait for all threads to finish // wait for all threads to finish
#ifdef REALLY_VERBOSE_DEBUG LINF("Waiting for threads to finish");
cout << "Waiting for all threads to finish" << endl;
#endif //REALLY_VERBOSE_DEBUG
while(children.size()) while(children.size())
{ {
#ifdef REALLY_VERBOSE_DEBUG if(false==cfg.getBackground())
cout << "Threads active:" << children.size() << (char)13; {
fflush(stdout); cout << "Threads active:" << children.size() << (char)13;
#endif //REALLY_VERBOSE_DEBUG fflush(stdout);
}
sleep(1); sleep(1);
} }
if(cfg.getCleanDb()) if(cfg.getCleanDb())
pthread_join(cleaner_thread,NULL); pthread_join(cleaner_thread,NULL);
#ifdef REALLY_VERBOSE_DEBUG
cout << endl; if(false==cfg.getBackground())
#endif //REALLY_VERBOSE_DEBUG cout << endl;
#ifdef HAVE_SPF #ifdef HAVE_SPF
Spf::deinitialize(); Spf::deinitialize();
@ -281,7 +279,7 @@ void *cleaner_thread_run(void *)
unsigned long spamcount; unsigned long spamcount;
spamcount=db.cleanDB(); spamcount=db.cleanDB();
hermes_log.addMessage(LOG_DEBUG,"Cleaning database, cleaning "+Utils::inttostr(spamcount)+" blocked spams."); LDEB("Cleaning database, cleaning "+Utils::inttostr(spamcount)+" blocked spams.");
if(spamcount>0&&cfg.getSubmitStats()) if(spamcount>0&&cfg.getSubmitStats())
{ {
try try
@ -310,12 +308,13 @@ void *cleaner_thread_run(void *)
} }
catch(Exception &e) catch(Exception &e)
{ {
hermes_log.addMessage(LOG_DEBUG,"Exception sending stats: "+string(e)); LDEB("Exception sending stats: "+string(e));
} }
} }
next_run+=3600; next_run+=3600;
} }
#ifdef REALLY_VERBOSE_DEBUG if(false==cfg.getBackground())
{
if(!(now%10)) //echo info each 10 seconds if(!(now%10)) //echo info each 10 seconds
{ {
stringstream ss; stringstream ss;
@ -328,16 +327,14 @@ void *cleaner_thread_run(void *)
ss << endl; ss << endl;
cout << ss.str(); cout << ss.str();
} }
#endif //REALLY_VERBOSE_DEBUG }
sleep(1); sleep(1);
} }
db.close(); db.close();
} }
catch(Exception &e) catch(Exception &e)
{ {
#ifdef REALLY_VERBOSE_DEBUG LERR(e);
cout << e << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
return NULL; return NULL;
} }
@ -363,6 +360,7 @@ void *thread_main(void *info_stack)
((stack<new_conn_info>*)info_stack)->pop(); ((stack<new_conn_info>*)info_stack)->pop();
pthread_mutex_unlock(&info_stack_mutex); pthread_mutex_unlock(&info_stack_mutex);
connection_id=peerinfo.connection_id;
client.setFD(peerinfo.new_fd); client.setFD(peerinfo.new_fd);
p.setOutside(client); p.setOutside(client);
p.run(peerinfo.peer_address); p.run(peerinfo.peer_address);
@ -370,10 +368,8 @@ void *thread_main(void *info_stack)
} }
catch(Exception &e) catch(Exception &e)
{ {
#ifdef REALLY_VERBOSE_DEBUG if(false==cfg.getBackground())
cout << e << endl; LDEB(e);
#endif //REALLY_VERBOSE_DEBUG
hermes_log.addMessage(LOG_DEBUG,e);
} }
return NULL; return NULL;
} }
@ -383,26 +379,13 @@ void exit_requested(int)
if(!quit) if(!quit)
{ {
quit=true; quit=true;
#ifdef REALLY_VERBOSE_DEBUG if(false==cfg.getBackground())
cout << "Hit control+c again to force-quit" << endl; cout << "Hit control+c again to force-quit" << endl;
#endif //REALLY_VERBOSE_DEBUG
} }
else else
exit(-1); exit(-1);
} }
void write_pid(string file,pid_t pid)
{
FILE *f;
f=fopen(file.c_str(),"w");
if(NULL==f)
throw Exception(_("Couldn't open file ")+file+_(" to write the pidfile"),__FILE__,__LINE__);
fprintf(f,"%d\n",pid);
fclose(f);
}
#ifdef WIN32 #ifdef WIN32
//pthreads on win32 doesn't provide an operator== for pthread_t //pthreads on win32 doesn't provide an operator== for pthread_t
//and it's also an struct, not an int, so supply one operator== here //and it's also an struct, not an int, so supply one operator== here

View file

@ -26,11 +26,17 @@
#include <string> #include <string>
#define _(x) (x) #define _(x) (x)
#define LOG(x,y) hermes_log.addMessage(__FILE__,__LINE__,x,y)
#define LERR(x) LOG(LOG_ERR,x)
#define LINF(x) LOG(LOG_INFO,x)
#define LDEB(x) LOG(LOG_DEBUG,x)
typedef struct typedef struct
{ {
int new_fd; int new_fd;
std::string peer_address; std::string peer_address;
unsigned long connection_id;
}new_conn_info; }new_conn_info;
#endif //SMTPPROXY_H #endif //SMTPPROXY_H