diff --git a/ChangeLog b/ChangeLog index dfb53b8..7a02d48 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,6 +1,10 @@ ChangeLog --------- +2011-01-08 02:27 Juan José Gutiérrez de Quevedo + +* revamped logging system. hopefully, messages will be more informative now + 2011-01-06 23:53 Juan José Gutiérrez de Quevedo * development restarted diff --git a/src/Configfile.cpp.in b/src/Configfile.cpp.in index e29a0e6..ad3da37 100644 --- a/src/Configfile.cpp.in +++ b/src/Configfile.cpp.in @@ -36,7 +36,7 @@ void Configfile::parse(string file) char line[255]; 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); while(!f.eof()) { @@ -47,10 +47,9 @@ void Configfile::parse(string file) equalpos=l.find("="); string option=Utils::trim(l.substr(0,equalpos)); string value=Utils::trim(l.substr(equalpos+1)); - #ifdef REALLY_VERBOSE_DEBUG - cout << l << endl; - cout << option << "->" << value << endl; - #endif //REALLY_VERBOSE_DEBUG + //if(false==cfg.getBackground()) + // cout << option << " -> " << value << endl; + //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_BOOL(x,y) if(x==option) y=Configfile::parseAsBool(value); else diff --git a/src/Database.cpp b/src/Database.cpp index 2d3590f..6af1444 100644 --- a/src/Database.cpp +++ b/src/Database.cpp @@ -19,6 +19,8 @@ */ #include "Database.h" +extern LOGGER_CLASS hermes_log; + void Database::setDatabaseFile(string p_dbfile) { dbfile=p_dbfile; @@ -33,6 +35,8 @@ void Database::setDatabaseFile(string p_dbfile) void Database::doQuery(string p_sql) { int retval; + bool was_busy=false; + do { 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) { sleep(1+rand()%2); - #ifdef REALLY_VERBOSE_DEBUG - cout << pthread_self() << " doquery() sql failed with busy state, retrying" << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR("doquery() sql failed with busy state, retrying"); + was_busy=true; } } while(SQLITE_BUSY==retval); + if(was_busy) + LERR("doquery() executed correctly after failing initially"); } 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 ncolumn=0; bool retval=true; + bool was_busy=false; int sqlite_retval; int now=time(NULL); 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) { sleep(1+rand()%2); - #ifdef REALLY_VERBOSE_DEBUG - cout << pthread_self() << " greylisted() sql busy" << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR("greylisted() sql failed with busy state, retrying"); + was_busy=true; } } while(sqlite_retval==SQLITE_BUSY); + if(was_busy) + LERR("greylisted() executed correctly after failing initially"); sql=""; @@ -203,6 +210,7 @@ int Database::countRows(string p_sql) int nrow=0; int ncolumn=0; int sqlite_retval; + bool was_busy=false; do { @@ -216,12 +224,13 @@ int Database::countRows(string p_sql) if(SQLITE_BUSY==sqlite_retval) { sleep(1+rand()%2); - #ifdef REALLY_VERBOSE_DEBUG - cout << pthread_self() << " countRows() retrying" << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR("countRows() sql failed with busy state, retrying"); + was_busy=true; } } while(SQLITE_BUSY==sqlite_retval); + if(was_busy) + LERR("countRows() executed correctly after failing initially"); if(NULL!=result) sqlite3_free_table(result); @@ -357,6 +366,7 @@ unsigned long Database::getIntValue(string& p_sql) int nrow=0; int ncolumn=0; int sqlite_retval; + bool was_busy=false; unsigned long value; do @@ -371,12 +381,13 @@ unsigned long Database::getIntValue(string& p_sql) if(SQLITE_BUSY==sqlite_retval) { sleep(1+rand()%2); - #ifdef REALLY_VERBOSE_DEBUG - cout << pthread_self() << " getIntValue() retrying" << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR("getIntValue() sql failed with busy state, retrying"); + was_busy=true; } } while(SQLITE_BUSY==sqlite_retval); + if(was_busy) + LERR("getIntValue() executed correctly after failing initially"); if(NULL==result) 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 sql="SELECT SUM(blocked) FROM greylist WHERE expires10&&"mail from:"==Utils::strtolower(strtemp.substr(0,10))) @@ -147,9 +137,7 @@ void Proxy::run(string &peer_address) code="421"; mechanism="greylist"; message=code+" Greylisted!! Please try again in a few minutes."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } #ifdef HAVE_SPF 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"; mechanism="spf"; message=code+" You do not seem to be allowed to send email for that particular domain."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } #endif //HAVE_SPF //check blacklist @@ -168,9 +154,7 @@ void Proxy::run(string &peer_address) code=cfg.getReturnTempErrorOnReject()?"421":"550"; mechanism="allowed-domain-per-ip"; message=code+" You do not seem to be allowed to send email to that particular domain from that address."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } //check rbl 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"; mechanism="dnsbl"; message=code+" You are listed on some DNS blacklists. Get delisted before trying to send us email."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } else if(cfg.getRejectNoReverseResolution()&&!authenticated&&""==resolvedname) { code=cfg.getReturnTempErrorOnReject()?"421":"550"; mechanism="no reverse resolution"; message=code+" Your IP address does not resolve to a hostname."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } else if(cfg.getCheckHeloAgainstReverse()&&!authenticated&&ehlostr!=resolvedname) { code=cfg.getReturnTempErrorOnReject()?"421":"550"; mechanism="helo differs from resolved name"; message=code+" Your IP hostname doesn't match your envelope hostname."; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Checking " << mechanism << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("checking " + mechanism); } else code="250"; @@ -208,10 +186,7 @@ void Proxy::run(string &peer_address) strlog.insert(0,code+" "); //log the connection - #ifdef REALLY_VERBOSE_DEBUG - cout << strlog << endl; - #endif //REALLY_VERBOSE_DEBUG - hermes_log.addMessage(LOG_INFO,strlog); + LINF(strlog); //if we didn't accept the email, punish spammers if("250"!=code) @@ -231,21 +206,17 @@ void Proxy::run(string &peer_address) #ifdef HAVE_SSL try { - #ifdef REALLY_VERBOSE_DEBUG - cout << peer_address << " enabled starttls, using secure comunications!!!" << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("STARTTLS issued by remote, TLS enabled"); outside.writeLine("220 You can speak now, line is secure!!"); outside.enableSSL(true); } catch(Exception &e) { - #ifdef REALLY_VERBOSE_DEBUG - cout << string(e) << endl; - #endif //REALLY_VERBOSE_DEBUG - hermes_log.addMessage(LOG_DEBUG,string(e)); + LERR(e); } #else 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 strtemp=""; } @@ -257,9 +228,6 @@ void Proxy::run(string &peer_address) if(inside.canRead(0.2)) //server wants to send something to client { strtemp=inside.readLine(); - #ifdef REALLY_VERBOSE_DEBUG - debugLog+="s> "+strtemp+"\r\n"; - #endif //REALLY_VERBOSE_DEBUG if(inside.isClosed()) return; 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 { - #ifdef REALLY_VERBOSE_DEBUG - cout << e << endl; - try - { - throw Exception(string(e)+debugLog+"\r\n",__FILE__,__LINE__); - } - catch(Exception &ex){} - #endif //REALLY_VERBOSE_DEBUG + LERR(e); if(last_state 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; } } diff --git a/src/Socket.cpp b/src/Socket.cpp index d768116..8e9e7dd 100644 --- a/src/Socket.cpp +++ b/src/Socket.cpp @@ -27,6 +27,7 @@ SSL_CTX *Socket::ssl_ctx_client=NULL; #endif //HAVE_SSL extern Configfile cfg; +extern LOGGER_CLASS hermes_log; Socket::Socket():fd(-1) #ifdef HAVE_SSL @@ -254,6 +255,9 @@ string Socket::readLine() s<" + s.str()); + return s.str(); } @@ -298,6 +302,7 @@ void Socket::writeLine(string s) s+="\r\n"; + LDEB("w>"+s); writeBytes((void *)s.c_str(),s.length()); } diff --git a/src/UnixLogger.cpp b/src/UnixLogger.cpp index c6c8a86..a2d90fa 100644 --- a/src/UnixLogger.cpp +++ b/src/UnixLogger.cpp @@ -19,6 +19,9 @@ */ #include "UnixLogger.h" +extern __thread unsigned long connection_id; +extern Configfile cfg; + UnixLogger::UnixLogger() { openlog("hermes",LOG_NDELAY,LOG_MAIL); @@ -29,7 +32,12 @@ UnixLogger::~UnixLogger() 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()); } diff --git a/src/UnixLogger.h b/src/UnixLogger.h index 07ca02e..5f4898b 100644 --- a/src/UnixLogger.h +++ b/src/UnixLogger.h @@ -37,7 +37,7 @@ class UnixLogger: public Logger public: UnixLogger(); ~UnixLogger(); - void addMessage(int,string); + void addMessage(string,int,int,string); }; #endif //UNIXLOGGER_H diff --git a/src/Utils.cpp b/src/Utils.cpp index 74cc889..5cf9d2a 100644 --- a/src/Utils.cpp +++ b/src/Utils.cpp @@ -20,6 +20,7 @@ #include "Utils.h" extern Configfile cfg; +extern LOGGER_CLASS hermes_log; //-------------------- // string functions: @@ -40,6 +41,21 @@ string Utils::inttostr(int integer) 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 * @@ -445,27 +461,30 @@ bool Utils::listed_on_dns_lists(list& dns_domains,unsigned char percenta { Socket::resolve(reversedip+dns_domain); times_listed++; - #ifdef REALLY_VERBOSE_DEBUG - cout << ip << " listed on " << dns_domain << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF(ip + " listed on " + dns_domain); } catch(Exception &e) { - #ifdef REALLY_VERBOSE_DEBUG - cout << ip << " NOT listed on " << dns_domain << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF(ip + " NOT listed on " + dns_domain); } checked_lists++; 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; + } //if we have checked a number of lists that make it impossible for this function //to return true, then return false 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; + } } + 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; } @@ -589,3 +608,16 @@ string Utils::gethostname() 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); +} + diff --git a/src/Utils.h b/src/Utils.h index 2e3e55a..42190d5 100644 --- a/src/Utils.h +++ b/src/Utils.h @@ -55,6 +55,7 @@ class Utils static string strtolower(string); static string trim(string); static string inttostr(int); + static string ulongtostr(unsigned long); //email-related utilities static string getmail(string&); @@ -80,6 +81,7 @@ class Utils static string errnotostrerror(int); static string rfc2821_date(time_t *timestamp=NULL); static string gethostname(); + static void write_pid(string,pid_t); }; #endif //UTILS_H diff --git a/src/hermes.cpp b/src/hermes.cpp index 21a4f05..cfce035 100644 --- a/src/hermes.cpp +++ b/src/hermes.cpp @@ -42,7 +42,6 @@ using namespace std; void *thread_main(void *); void *cleaner_thread_run(void *); void exit_requested(int); -void write_pid(string,pid_t); //global var to know when we have to exit bool quit=false; @@ -57,6 +56,10 @@ Configfile cfg; //our logger 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 children; #ifdef HAVE_SSL @@ -106,13 +109,11 @@ main } catch(Exception &e) { - cout << string(e) << endl; + LERR(e); return -1; } - #ifdef REALLY_VERBOSE_DEBUG - unsigned long nconns=0; - #endif //REALLY_VERBOSE_DEBUG + unsigned long nconns=0; signal(SIGTERM,exit_requested); signal(SIGINT,exit_requested); @@ -134,7 +135,7 @@ main if(retval<0) { - cout << _("Error forking into the background") << Utils::errnotostrerror(errno) << endl; + LERR(_("Error forking into the background") + Utils::errnotostrerror(errno)); return -1; } } @@ -143,11 +144,11 @@ main { try { - write_pid(cfg.getPidFile(),getpid()); + Utils::write_pid(cfg.getPidFile(),getpid()); } catch(Exception &e) { - hermes_log.addMessage(LOG_ERR,e); + LERR(e); } } @@ -158,13 +159,14 @@ main chdir(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; } chdir("/"); } #endif //WIN32 + LINF("Starting hermes"); try { server.init(); @@ -173,7 +175,7 @@ main } catch(Exception &e) { - cout << e << endl; + LERR(e); return -1; //couldn't bind, exit } @@ -207,22 +209,19 @@ main int fd=server.accept(&peer_address); info.new_fd=fd; info.peer_address=peer_address; + info.connection_id=++nconns; pthread_mutex_lock(&info_stack_mutex); info_stack.push(info); pthread_mutex_unlock(&info_stack_mutex); retval=pthread_create(&thread,&thread_attr,thread_main,(void *)&info_stack); if(retval) { - #ifdef REALLY_VERBOSE_DEBUG - cout << _("Error creating thread: ") << Utils::errnotostrerror(retval) << _(". Sleeping 5 seconds before continuing...") << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR(_("Error creating thread: ") + Utils::errnotostrerror(retval) + _(". Sleeping 5 seconds before continuing...")); sleep(5); } else { - #ifdef REALLY_VERBOSE_DEBUG - cout << "[ " << ++nconns << " ] " << endl; - #endif //REALLY_VERBOSE_DEBUG + LDEB("New thread created [" + Utils::ulongtostr(nconns) + "] thread_id: " + Utils::ulongtostr(thread)); pthread_mutex_lock(&childrenlist_mutex); children.push_back(thread); pthread_mutex_unlock(&childrenlist_mutex); @@ -234,22 +233,21 @@ main server.close(); // wait for all threads to finish - #ifdef REALLY_VERBOSE_DEBUG - cout << "Waiting for all threads to finish" << endl; - #endif //REALLY_VERBOSE_DEBUG + LINF("Waiting for threads to finish"); while(children.size()) { - #ifdef REALLY_VERBOSE_DEBUG - cout << "Threads active:" << children.size() << (char)13; - fflush(stdout); - #endif //REALLY_VERBOSE_DEBUG + if(false==cfg.getBackground()) + { + cout << "Threads active:" << children.size() << (char)13; + fflush(stdout); + } sleep(1); } if(cfg.getCleanDb()) pthread_join(cleaner_thread,NULL); - #ifdef REALLY_VERBOSE_DEBUG - cout << endl; - #endif //REALLY_VERBOSE_DEBUG + + if(false==cfg.getBackground()) + cout << endl; #ifdef HAVE_SPF Spf::deinitialize(); @@ -281,7 +279,7 @@ void *cleaner_thread_run(void *) unsigned long spamcount; 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()) { try @@ -310,12 +308,13 @@ void *cleaner_thread_run(void *) } catch(Exception &e) { - hermes_log.addMessage(LOG_DEBUG,"Exception sending stats: "+string(e)); + LDEB("Exception sending stats: "+string(e)); } } next_run+=3600; } - #ifdef REALLY_VERBOSE_DEBUG + if(false==cfg.getBackground()) + { if(!(now%10)) //echo info each 10 seconds { stringstream ss; @@ -328,16 +327,14 @@ void *cleaner_thread_run(void *) ss << endl; cout << ss.str(); } - #endif //REALLY_VERBOSE_DEBUG + } sleep(1); } db.close(); } catch(Exception &e) { - #ifdef REALLY_VERBOSE_DEBUG - cout << e << endl; - #endif //REALLY_VERBOSE_DEBUG + LERR(e); } return NULL; } @@ -363,6 +360,7 @@ void *thread_main(void *info_stack) ((stack*)info_stack)->pop(); pthread_mutex_unlock(&info_stack_mutex); + connection_id=peerinfo.connection_id; client.setFD(peerinfo.new_fd); p.setOutside(client); p.run(peerinfo.peer_address); @@ -370,10 +368,8 @@ void *thread_main(void *info_stack) } catch(Exception &e) { - #ifdef REALLY_VERBOSE_DEBUG - cout << e << endl; - #endif //REALLY_VERBOSE_DEBUG - hermes_log.addMessage(LOG_DEBUG,e); + if(false==cfg.getBackground()) + LDEB(e); } return NULL; } @@ -383,26 +379,13 @@ void exit_requested(int) if(!quit) { quit=true; - #ifdef REALLY_VERBOSE_DEBUG - cout << "Hit control+c again to force-quit" << endl; - #endif //REALLY_VERBOSE_DEBUG + if(false==cfg.getBackground()) + cout << "Hit control+c again to force-quit" << endl; } else 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 //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 diff --git a/src/hermes.h b/src/hermes.h index 5578b68..58b669b 100644 --- a/src/hermes.h +++ b/src/hermes.h @@ -26,11 +26,17 @@ #include #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 { int new_fd; std::string peer_address; + unsigned long connection_id; }new_conn_info; #endif //SMTPPROXY_H