#include "globals.h" #include #include "module-anticasc.h" #include "module-monitor.h" #include "oscam-client.h" #include "oscam-garbage.h" #include "oscam-lock.h" #include "oscam-log.h" #include "oscam-net.h" #include "oscam-string.h" #include "oscam-time.h" // Do not allow log_list to grow bigger than that many entries #define MAX_LOG_LIST_BACKLOG 10000 extern char *syslog_ident; extern int32_t exit_oscam; char *LOG_LIST = "log_list"; int8_t logStarted = 0; static FILE *fp; static FILE *fps; static LLIST *log_list; static bool log_running; static int log_list_queued; static pthread_t log_thread; static pthread_cond_t log_thread_sleep_cond; static pthread_mutex_t log_thread_sleep_cond_mutex; static int32_t syslog_socket = -1; static struct SOCKADDR syslog_addr; struct s_log { char *txt; uint8_t header_len; uint8_t header_logcount_offset; uint8_t header_date_offset; uint8_t header_time_offset; uint8_t header_info_offset; int8_t direct_log; int8_t cl_typ; char *cl_usr; char *cl_text; }; #define LOG_BUF_SIZE 512 static void switch_log(char *file, FILE **f, int32_t (*pfinit)(void)) { // only 1 thread needs to switch the log; even if anticasc, statistics and normal log are running // at the same time, it is ok to have the other logs switching 1 entry later if(cfg.max_log_size && file) { if(*f != NULL && ftell(*f) >= cfg.max_log_size * 1024) { int32_t rc; char prev_log[cs_strlen(file) + 6]; snprintf(prev_log, sizeof(prev_log), "%s-prev", file); fprintf(*f, "switch log file\n"); fflush(*f); fclose(*f); *f = (FILE *)0; rc = rename(file, prev_log); if(rc != 0) { fprintf(stderr, "rename(%s, %s) failed (errno=%d %s)\n", file, prev_log, errno, strerror(errno)); } else if(pfinit()) { fprintf(stderr, "Initialisation of log file failed, continuing without logging thread %8lX. Log will be output to stdout!", (unsigned long)pthread_self()); cfg.logtostdout = 1; } } } } void cs_reopen_log(void) { if(cfg.logfile) { if(fp) { fprintf(fp, "flush and re-open log file\n"); fflush(fp); fclose(fp); fp = NULL; } if(cs_open_logfiles()) { fprintf(stderr, "Initialisation of log file failed, continuing without logging thread %8luX. Log will be output to stdout!", (unsigned long)pthread_self()); cfg.logtostdout = 1; } } if(cfg.usrfile) { if(fps) { fprintf(fps, "flush and re-open user log file\n"); fflush(fps); fclose(fps); fps = NULL; } if(cs_init_statistics()) { fprintf(stderr, "Initialisation of user log file failed, continuing without logging thread %8luX.", (unsigned long)pthread_self()); } } } static void cs_write_log(char *txt, int8_t do_flush, uint8_t hdr_date_offset, uint8_t hdr_time_offset) { // filter out entries with leading 's' and forward to statistics if(txt[hdr_date_offset] == 's') { if(fps) { switch_log(cfg.usrfile, &fps, cs_init_statistics); if(fps) { fputs(txt + hdr_date_offset + 1, fps); // remove the leading 's' and write to file if(do_flush) { fflush(fps); } } } } else { if(!cfg.disablelog) { if(fp) { switch_log(cfg.logfile, &fp, cs_open_logfiles); // only call the switch code if lock = 1 is specified as otherwise we are calling it internally if(fp) { fputs(txt + hdr_date_offset, fp); if(do_flush) { fflush(fp); } } } if(cfg.logtostdout) { fputs(txt + hdr_time_offset, stdout); if(do_flush) { fflush(stdout); } } } } } static void log_list_flush(void) { if(logStarted == 0) { return; } SAFE_COND_SIGNAL_NOLOG(&log_thread_sleep_cond); int32_t i = 0; while(ll_count(log_list) > 0 && i < 200) { cs_sleepms(5); ++i; } } static void log_list_add(struct s_log *log) { if(logStarted == 0) { return; } int32_t count = ll_count(log_list); log_list_queued++; if(count < MAX_LOG_LIST_BACKLOG) { ll_append(log_list, log); } else // We have too much backlog { NULLFREE(log->txt); NULLFREE(log); cs_write_log("-------------> Too much data in log_list, dropping log message.\n", 1, 0, 0); } SAFE_COND_SIGNAL_NOLOG(&log_thread_sleep_cond); } static void cs_write_log_int(char *txt) { if(exit_oscam == 1) { cs_write_log(txt, 1, 0, 0); } else { char *newtxt = cs_strdup(txt); if(!newtxt) { return; } struct s_log *log; if(!cs_malloc(&log, sizeof(struct s_log))) { NULLFREE(newtxt); return; } log->txt = newtxt; log->header_len = 0; log->direct_log = 1; log_list_add(log); } } int32_t cs_open_logfiles(void) { char *starttext; if(logStarted) { starttext = "log switched"; } else { starttext = "started"; } if(!fp && cfg.logfile) // log to file { if((fp = fopen(cfg.logfile, "a+")) <= (FILE *)0) { fp = (FILE *)0; fprintf(stderr, "couldn't open logfile: %s (errno %d %s)\n", cfg.logfile, errno, strerror(errno)); } else { char line[80]; memset(line, '-', sizeof(line)); line[(sizeof(line) / sizeof(char)) - 1] = '\0'; time_t walltime = cs_time(); if(!cfg.disablelog) { char buf[28]; cs_ctime_r(&walltime, buf); fprintf(fp, "\n%s\n>> OSCam << cardserver %s at %s%s\n", line, starttext, buf, line); } } } // according to syslog docu: calling closelog is not necessary and calling openlog multiple times is safe // We use openlog to set the default syslog settings so that it's possible to allow switching syslog on and off openlog(syslog_ident, LOG_NDELAY | LOG_PID, LOG_DAEMON); cs_log(">> OSCam << cardserver %s, version " CS_VERSION "@" CS_GIT_COMMIT " (" CS_TARGET ")", starttext); return (fp <= (FILE *)0); } #if defined(WEBIF) || defined(MODULE_MONITOR) static uint64_t counter = 0; LLIST *log_history = NULL; /* This function allows to reinit the in-memory loghistory with a new size. */ void cs_reinit_loghist(uint32_t size) { cfg.loghistorylines = size; } #endif static struct timeb log_ts; static uint8_t get_log_header(char *txt, int32_t txt_size, uint8_t* hdr_logcount_offset, uint8_t* hdr_date_offset, uint8_t* hdr_time_offset, uint8_t* hdr_info_offset) { struct s_client *cl = cur_client(); struct tm lt; int32_t tmp; cs_ftime(&log_ts); time_t walltime = log_ts.time; localtime_r(&walltime, <); tmp = snprintf(txt, txt_size, "[LOG000]%04d/%02d/%02d %02d:%02d:%02d %08X %c ", lt.tm_year + 1900, lt.tm_mon + 1, lt.tm_mday, lt.tm_hour, lt.tm_min, lt.tm_sec, cl ? cl->tid : 0, cl ? cl->typ : ' ' ); if(tmp == 39) { if(hdr_logcount_offset != NULL) { // depends on snprintf(...) format (*hdr_logcount_offset) = 4; } if(hdr_date_offset != NULL) { // depends on snprintf(...) format (*hdr_date_offset) = *hdr_logcount_offset + 4; } if(hdr_time_offset != NULL) { // depends on snprintf(...) format (*hdr_time_offset) = *hdr_date_offset + 11; } if(hdr_info_offset != NULL) { // depends on snprintf(...) format (*hdr_info_offset) = *hdr_time_offset + 9; } return (uint8_t)tmp; } if(hdr_logcount_offset != NULL) { (*hdr_logcount_offset) = 0; } if(hdr_date_offset != NULL) { (*hdr_date_offset) = 0; } if(hdr_time_offset != NULL) { (*hdr_time_offset) = 0; } if(hdr_info_offset != NULL) { (*hdr_info_offset) = 0; } return 0; } static void write_to_log(char *txt, struct s_log *log, int8_t do_flush) { if(logStarted == 0) { return; } (void)log; // Prevent warning when WEBIF, MODULE_MONITOR and CS_ANTICASC are disabled // anticascading messages go to their own log if (!anticasc_logging(txt + log->header_date_offset)) { if(cfg.logtosyslog) { syslog(LOG_INFO, "%s", txt + log->header_info_offset); } if (cfg.sysloghost != NULL && syslog_socket != -1) { char tmp[128 + LOG_BUF_SIZE]; static char hostname[64]; static uint8_t have_hostname = 0; time_t walltime; struct tm lt; char timebuf[32]; if(!have_hostname) { if(gethostname(hostname, 64) != 0) { cs_strncpy(hostname, "unknown", 64); } have_hostname = 1; } walltime = cs_time(); localtime_r(&walltime, <); if(strftime(timebuf, 32, "%b %d %H:%M:%S", <) == 0) { cs_strncpy(timebuf, "unknown", 32); } snprintf(tmp, sizeof(tmp), "%s %s oscam[%u]: %s", timebuf, hostname, getpid(), txt + log->header_info_offset); sendto(syslog_socket, tmp, cs_strlen(tmp), 0, (struct sockaddr*) &syslog_addr, sizeof(syslog_addr)); } } if (!cs_strncat(txt, "\n", LOG_BUF_SIZE)) { cs_log("FIXME!"); } cs_write_log(txt, do_flush, log->header_date_offset, log->header_time_offset); #if defined(WEBIF) || defined(MODULE_MONITOR) if(!exit_oscam && cfg.loghistorylines && log_history) { struct s_log_history *hist; while((uint32_t)ll_count(log_history) >= cfg.loghistorylines) { hist = ll_remove_first(log_history); if(hist) { add_garbage(hist->txt); add_garbage(hist); hist = NULL; } } if(cs_malloc(&hist, sizeof(struct s_log_history))) { int32_t target_len = cs_strlen(log->cl_text) + cs_strlen(txt+log->header_date_offset) + 1; if(cs_malloc(&hist->txt, sizeof(char) * (target_len + 1))) { hist->counter = counter++; snprintf(hist->txt, target_len + 1, "%s\t%s", log->cl_text, txt + log->header_date_offset); ll_append(log_history, hist); } else { NULLFREE(hist); } } } #endif #if defined(MODULE_MONITOR) char sbuf[16]; struct s_client *cl; for(cl = first_client; cl ; cl = cl->next) { if((cl->typ == 'm') && (cl->monlvl > 0) && cl->log) // this variable is only initialized for cl->typ = 'm' { if(cl->monlvl < 2) { if(log->cl_typ != 'c' && log->cl_typ != 'm') { continue; } if(log->cl_usr && cl->account && strcmp(log->cl_usr, cl->account->usr)) { continue; } } if(log->header_len > 0) { snprintf(sbuf, sizeof(sbuf), "%03d", cl->logcounter); cl->logcounter = (cl->logcounter + 1) % 1000; memcpy(txt + log->header_logcount_offset, sbuf, 3); monitor_send_idx(cl, txt); } else { char tmp_log[8+LOG_BUF_SIZE]; snprintf(tmp_log, sizeof(tmp_log), "[LOG%03d]%s", cl->logcounter, txt); cl->logcounter = (cl->logcounter + 1) % 1000; monitor_send_idx(cl, tmp_log); } } } #endif } static void write_to_log_int(char *txt, uint8_t header_len, uint8_t hdr_logcount_offset, uint8_t hdr_date_offset, uint8_t hdr_time_offset, uint8_t hdr_info_offset) { #if !defined(WEBIF) && !defined(MODULE_MONITOR) if(cfg.disablelog) { return; } #endif char *newtxt = cs_strdup(txt); if(!newtxt) { return; } struct s_log *log; if(!cs_malloc(&log, sizeof(struct s_log))) { NULLFREE(newtxt); return; } log->txt = newtxt; log->header_len = header_len; log->header_logcount_offset = hdr_logcount_offset; log->header_date_offset = hdr_date_offset; log->header_time_offset = hdr_time_offset; log->header_info_offset = hdr_info_offset; log->direct_log = 0; struct s_client *cl = cur_client(); log->cl_usr = ""; if(!cl) { log->cl_text = "undef"; log->cl_typ = ' '; } else { switch(cl->typ) { case 'c': case 'm': if(cl->account) { log->cl_text = cl->account->usr; log->cl_usr = cl->account->usr; } else { log->cl_text = ""; } break; case 'p': case 'r': log->cl_text = cl->reader ? cl->reader->label : ""; break; default: log->cl_text = "server"; break; } log->cl_typ = cl->typ; } if(exit_oscam == 1 || cfg.disablelog) // Exit or log disabled. if disabled, just display on webif/monitor { char buf[LOG_BUF_SIZE]; cs_strncpy(buf, log->txt, LOG_BUF_SIZE); write_to_log(buf, log, 1); NULLFREE(log->txt); NULLFREE(log); } else { log_list_add(log); } } static pthread_mutex_t log_mutex; static char log_txt[LOG_BUF_SIZE]; static char dupl[LOG_BUF_SIZE / 4]; static char last_log_txt[LOG_BUF_SIZE]; static struct timeb last_log_ts; static unsigned int last_log_duplicates; static void __cs_log_check_duplicates(uint8_t hdr_len, uint8_t hdr_logcount_offset, uint8_t hdr_date_offset, uint8_t hdr_time_offset, uint8_t hdr_info_offset) { bool repeated_line = strcmp(last_log_txt, log_txt + hdr_len) == 0; if (last_log_duplicates > 0) { if (!cs_valid_time(&last_log_ts)) // Must be initialized once last_log_ts = log_ts; // Report duplicated lines when the new log line is different // than the old or 60 seconds have passed. int64_t gone = comp_timeb(&log_ts, &last_log_ts); if (!repeated_line || gone >= 60 * 1000) { uint8_t dupl_hdr_logcount_offset = 0, dupl_hdr_date_offset = 0, dupl_hdr_time_offset = 0, dupl_hdr_info_offset = 0; uint8_t dupl_header_len = get_log_header(dupl, sizeof(dupl), &dupl_hdr_logcount_offset, &dupl_hdr_date_offset, &dupl_hdr_time_offset, &dupl_hdr_info_offset); snprintf(dupl + dupl_header_len - 1, sizeof(dupl) - dupl_header_len, " (-) -- Skipped %u duplicated log lines --", last_log_duplicates); write_to_log_int(dupl, dupl_header_len, dupl_hdr_logcount_offset, dupl_hdr_date_offset, dupl_hdr_time_offset, dupl_hdr_info_offset); last_log_duplicates = 0; last_log_ts = log_ts; } } if (!repeated_line) { memcpy(last_log_txt, log_txt + hdr_len, LOG_BUF_SIZE - hdr_len); write_to_log_int(log_txt, hdr_len, hdr_logcount_offset, hdr_date_offset, hdr_time_offset, hdr_info_offset); } else { last_log_duplicates++; } } #define __init_log_prefix(fmt) \ uint8_t hdr_logcount_offset = 0, hdr_date_offset = 0, hdr_time_offset = 0, hdr_info_offset = 0; \ uint8_t hdr_len = get_log_header(log_txt, sizeof(log_txt), &hdr_logcount_offset, &hdr_date_offset, &hdr_time_offset, &hdr_info_offset); \ int32_t log_prefix_len = 0; \ do { \ if (log_prefix) { \ char _lp[16]; \ snprintf(_lp, sizeof(_lp), "(%s)", log_prefix); \ log_prefix_len = snprintf(log_txt + hdr_len, sizeof(log_txt) - hdr_len, fmt, _lp); \ } \ } while(0) #define __do_log() \ do { \ va_list params; \ va_start(params, fmt); \ __init_log_prefix("%10s "); \ vsnprintf(log_txt + hdr_len + log_prefix_len, sizeof(log_txt) - (hdr_len + log_prefix_len), fmt, params); \ va_end(params); \ if (cfg.logduplicatelines) \ { \ memcpy(last_log_txt, log_txt + hdr_len, LOG_BUF_SIZE - hdr_len); \ write_to_log_int(log_txt, hdr_len, hdr_logcount_offset, hdr_date_offset, hdr_time_offset, hdr_info_offset); \ } else { \ __cs_log_check_duplicates(hdr_len, hdr_logcount_offset, hdr_date_offset, hdr_time_offset, hdr_info_offset); \ } \ } while(0) void cs_log_txt(const char *log_prefix, const char *fmt, ...) { if(logStarted == 0) { return; } SAFE_MUTEX_LOCK_NOLOG(&log_mutex); __do_log(); SAFE_MUTEX_UNLOCK_NOLOG(&log_mutex); } void cs_log_hex(const char *log_prefix, const uint8_t *buf, int32_t n, const char *fmt, ...) { if(logStarted == 0) { return; } SAFE_MUTEX_LOCK_NOLOG(&log_mutex); __do_log(); if(buf) { int32_t i; __init_log_prefix("%10s "); for(i = 0; i < n; i += 16) { cs_hexdump(1, buf + i, (n - i > 16) ? 16 : n - i, log_txt + hdr_len + log_prefix_len, sizeof(log_txt) - (hdr_len + log_prefix_len)); write_to_log_int(log_txt, hdr_len, hdr_logcount_offset, hdr_date_offset, hdr_time_offset, hdr_info_offset); } } SAFE_MUTEX_UNLOCK_NOLOG(&log_mutex); } static void cs_close_log(void) { log_list_flush(); if(fp) { fclose(fp); fp = (FILE *)0; } } int32_t cs_init_statistics(void) { if((!fps) && (cfg.usrfile != NULL)) { if((fps = fopen(cfg.usrfile, "a+")) <= (FILE *)0) { fps = (FILE *)0; cs_log("couldn't open statistics file: %s", cfg.usrfile); } } return (fps <= (FILE *)0); } void cs_statistics(struct s_client *client) { if(!cfg.disableuserfile) { struct tm lt; char buf[LOG_BUF_SIZE]; float cwps; time_t walltime = cs_time(); localtime_r(&walltime, <); if(client->cwfound + client->cwnot > 0) { cwps = client->last - client->login; cwps /= client->cwfound + client->cwnot; } else { cwps = 0; } char channame[CS_SERVICENAME_SIZE]; get_servicename(client, client->last_srvid, client->last_provid, client->last_caid, channame, sizeof(channame)); int32_t lsec; if((client->last_caid == NO_CAID_VALUE) && (client->last_srvid == NO_SRVID_VALUE)) { lsec = client->last - client->login; } //client leave calc total duration else { lsec = client->last - client->lastswitch; } int32_t secs = 0, fullmins = 0, mins = 0, fullhours = 0; if((lsec > 0) && (lsec < 1000000)) { secs = lsec % 60; if(lsec > 60) { fullmins = lsec / 60; mins = fullmins % 60; if(fullmins > 60) { fullhours = fullmins / 60; } } } /* statistics entry start with 's' to filter it out on other end of pipe * so we can use the same Pipe as Log */ snprintf(buf, sizeof(buf), "s%02d.%02d.%02d %02d:%02d:%02d %3.1f %s %s %d %d %d %d %d %d %d %" PRId64 " %" PRId64 " %02d:%02d:%02d %s %04X@%06X:%04X %s\n", lt.tm_mday, lt.tm_mon + 1, lt.tm_year % 100, lt.tm_hour, lt.tm_min, lt.tm_sec, cwps, client->account->usr, cs_inet_ntoa(client->ip), client->port, client->cwfound, client->cwcache, client->cwnot, client->cwignored, client->cwtout, client->cwtun, (int64_t)client->login, (int64_t)client->last, fullhours, mins, secs, get_module(client)->desc, client->last_caid, client->last_provid, client->last_srvid, channame); cs_write_log_int(buf); } } void log_list_thread(void) { char buf[LOG_BUF_SIZE]; log_running = 1; set_thread_name(__func__); do { log_list_queued = 0; LL_ITER it = ll_iter_create(log_list); struct s_log *log; while((log = ll_iter_next_remove(&it))) { int8_t do_flush = ll_count(log_list) == 0; // flush on writing last element cs_strncpy(buf, log->txt, LOG_BUF_SIZE); if(log->direct_log) { cs_write_log(buf, do_flush, log->header_date_offset, log->header_time_offset); } else { write_to_log(buf, log, do_flush); } NULLFREE(log->txt); NULLFREE(log); } if(!log_list_queued) // The list is empty, sleep until new data comes in and we are woken up sleepms_on_cond(__func__, &log_thread_sleep_cond_mutex, &log_thread_sleep_cond, 60 * 1000); } while(log_running); ll_destroy(&log_list); } static void init_syslog_socket(void) { if(cfg.sysloghost != NULL && syslog_socket == -1) { IN_ADDR_T in_addr; if ((syslog_socket = socket(DEFAULT_AF, SOCK_DGRAM, IPPROTO_UDP)) == -1) { perror("Socket create error!"); } memset((char *) &syslog_addr, 0, sizeof(syslog_addr)); SIN_GET_FAMILY(syslog_addr) = DEFAULT_AF; SIN_GET_PORT(syslog_addr) = htons(cfg.syslogport); cs_resolve(cfg.sysloghost, &in_addr, NULL, NULL); SIN_GET_ADDR(syslog_addr) = in_addr; } } int32_t cs_init_log(void) { if(logStarted == 0) { init_syslog_socket(); SAFE_MUTEX_INIT_NOLOG(&log_mutex, NULL); cs_pthread_cond_init_nolog(__func__, &log_thread_sleep_cond_mutex, &log_thread_sleep_cond); #if defined(WEBIF) || defined(MODULE_MONITOR) log_history = ll_create("log history"); #endif log_list = ll_create(LOG_LIST); int32_t ret = start_thread_nolog("logging", (void *)&log_list_thread, NULL, &log_thread, 0, 1); if(ret) { cs_exit(1); } logStarted = 1; } int32_t rc = 0; if(!cfg.disablelog) { rc = cs_open_logfiles(); } logStarted = 1; if(cfg.initial_debuglevel > 0) { cs_dblevel = cfg.initial_debuglevel; cs_log("debug_level=%d", cs_dblevel); } return rc; } void cs_disable_log(int8_t disabled) { if(cfg.disablelog != disabled) { if(disabled && logStarted) { cs_log("Stopping log..."); log_list_flush(); } cfg.disablelog = disabled; if(disabled) { if(logStarted) { if(syslog_socket != -1) { close(syslog_socket); syslog_socket = -1; } cs_sleepms(20); cs_close_log(); } } else { init_syslog_socket(); cs_open_logfiles(); } } } void log_free(void) { if(syslog_socket != -1) { close(syslog_socket); syslog_socket = -1; } cs_close_log(); log_running = 0; SAFE_COND_SIGNAL_NOLOG(&log_thread_sleep_cond); SAFE_THREAD_JOIN_NOLOG(log_thread, NULL); }