source: trunk/oscam-log.c@ 8360

Last change on this file since 8360 was 8360, checked in by gf, 9 years ago

Abstract access to struct modules[] using get_module().

The goal is to make "struct s_module modules[]" static and prevent
random modules from knowing about it.

  • Property svn:eol-style set to LF
File size: 16.7 KB
Line 
1#include "globals.h"
2#include <syslog.h>
3#include "module-monitor.h"
4#include "oscam-client.h"
5#include "oscam-garbage.h"
6#include "oscam-lock.h"
7#include "oscam-log.h"
8#include "oscam-net.h"
9#include "oscam-string.h"
10#include "oscam-time.h"
11
12extern char *syslog_ident;
13extern int32_t exit_oscam;
14
15char *LOG_LIST = "log_list";
16
17static FILE *fp=(FILE *)0;
18static FILE *fps=(FILE *)0;
19static int8_t logStarted = 0;
20static LLIST *log_list;
21
22struct s_log {
23 char *txt;
24 int8_t header_len;
25 int8_t direct_log;
26 int8_t cl_typ;
27 char *cl_usr;
28 char *cl_text;
29};
30
31#if defined(WEBIF) || defined(MODULE_MONITOR)
32static CS_MUTEX_LOCK loghistory_lock;
33char *loghist = NULL; // ptr of log-history
34char *loghistptr = NULL;
35#endif
36
37#define LOG_BUF_SIZE 512
38
39static void switch_log(char* file, FILE **f, int32_t (*pfinit)(void))
40{
41 if(cfg.max_log_size && file) //only 1 thread needs to switch the log; even if anticasc, statistics and normal log are running
42 //at the same time, it is ok to have the other logs switching 1 entry later
43 {
44 if(*f != NULL && ftell(*f) >= cfg.max_log_size*1024) {
45 int32_t rc;
46 char prev_log[strlen(file) + 6];
47 snprintf(prev_log, sizeof(prev_log), "%s-prev", file);
48 fprintf(*f, "switch log file\n");
49 fflush(*f);
50 fclose(*f);
51 *f = (FILE *)0;
52 rc = rename(file, prev_log);
53 if( rc!=0 ) {
54 fprintf(stderr, "rename(%s, %s) failed (errno=%d %s)\n", file, prev_log, errno, strerror(errno));
55 }
56 else
57 if( pfinit()){
58 fprintf(stderr, "Initialisation of log file failed, continuing without logging thread %8lX. Log will be output to stdout!", (unsigned long)pthread_self());
59 cfg.logtostdout = 1;
60 }
61 }
62 }
63}
64
65static void cs_write_log(char *txt, int8_t do_flush)
66{
67 // filter out entries with leading 's' and forward to statistics
68 if(txt[0] == 's') {
69 if (fps) {
70 switch_log(cfg.usrfile, &fps, cs_init_statistics);
71 if (fps) {
72 fputs(txt + 1, fps); // remove the leading 's' and write to file
73 if (do_flush) fflush(fps);
74 }
75 }
76 } else {
77 if(!cfg.disablelog){
78 if (fp){
79 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
80 if (fp) {
81 fputs(txt, fp);
82 if (do_flush) fflush(fp);
83 }
84 }
85 if(cfg.logtostdout){
86 fputs(txt+11, stdout);
87 if (do_flush) fflush(stdout);
88 }
89 }
90 }
91}
92
93static void cs_write_log_int(char *txt)
94{
95 if(exit_oscam == 1) {
96 cs_write_log(txt, 1);
97 } else {
98 char *newtxt = cs_strdup(txt);
99 if (!newtxt)
100 return;
101 struct s_log *log;
102 if (!cs_malloc(&log, sizeof(struct s_log))) {
103 free(newtxt);
104 return;
105 }
106 log->txt = newtxt;
107 log->header_len = 0;
108 log->direct_log = 1;
109 ll_append(log_list, log);
110 }
111}
112
113int32_t cs_open_logfiles(void)
114{
115 char *starttext;
116 if(logStarted) starttext = "log switched";
117 else starttext = "started";
118 if (!fp && cfg.logfile) { //log to file
119 if ((fp = fopen(cfg.logfile, "a+")) <= (FILE *)0) {
120 fp = (FILE *)0;
121 fprintf(stderr, "couldn't open logfile: %s (errno %d %s)\n", cfg.logfile, errno, strerror(errno));
122 } else {
123 setvbuf(fp, NULL, _IOFBF, 8*1024);
124 time_t t;
125 char line[80];
126 memset(line, '-', sizeof(line));
127 line[(sizeof(line)/sizeof(char)) - 1] = '\0';
128 time(&t);
129 if (!cfg.disablelog){
130 char buf[28];
131 cs_ctime_r(&t, buf);
132 fprintf(fp, "\n%s\n>> OSCam << cardserver %s at %s%s\n", line, starttext, buf, line);
133 }
134 }
135 }
136 // according to syslog docu: calling closelog is not necessary and calling openlog multiple times is safe
137 // We use openlog to set the default syslog settings so that it's possible to allow switching syslog on and off
138 openlog(syslog_ident, LOG_NDELAY | LOG_PID, LOG_DAEMON);
139
140 cs_log_nolock(">> OSCam << cardserver %s, version " CS_VERSION ", build r" CS_SVN_VERSION " (" CS_TARGET ")", starttext);
141 return(fp <= (FILE *)0);
142}
143
144#if defined(WEBIF) || defined(MODULE_MONITOR)
145/*
146 This function allows to reinit the in-memory loghistory with a new size.
147*/
148void cs_reinit_loghist(uint32_t size)
149{
150 char *tmp = NULL, *tmp2;
151 if(size != cfg.loghistorysize){
152 if (size == 0 || cs_malloc(&tmp, size)) {
153 cs_writelock(&loghistory_lock);
154 tmp2 = loghist;
155 // On shrinking, the log is not copied and the order is reversed
156 if(size < cfg.loghistorysize){
157 cfg.loghistorysize = size;
158 cs_sleepms(20); // Monitor or webif may be currently outputting the loghistory but don't use locking so we sleep a bit...
159 loghistptr = tmp;
160 loghist = tmp;
161 } else {
162 if(loghist){
163 memcpy(tmp, loghist, cfg.loghistorysize);
164 loghistptr = tmp + (loghistptr - loghist);
165 } else loghistptr = tmp;
166 loghist = tmp;
167 cs_sleepms(20); // Monitor or webif may be currently outputting the loghistory but don't use locking so we sleep a bit...
168 cfg.loghistorysize = size;
169 }
170 cs_writeunlock(&loghistory_lock);
171 if(tmp2 != NULL) add_garbage(tmp2);
172 }
173 }
174}
175#endif
176
177static time_t log_ts = 0;
178
179static int32_t get_log_header(int32_t m, char *txt)
180{
181 struct s_client *cl = cur_client();
182 struct tm lt;
183 int32_t pos;
184
185 time(&log_ts);
186 localtime_r(&log_ts, &lt);
187
188 pos = snprintf(txt, LOG_BUF_SIZE, "[LOG000]%4d/%02d/%02d %02d:%02d:%02d ", lt.tm_year+1900, lt.tm_mon+1, lt.tm_mday, lt.tm_hour, lt.tm_min, lt.tm_sec);
189
190 switch (m) {
191 case 1: // Add thread id and reader type
192 return pos + snprintf(txt+pos, LOG_BUF_SIZE-pos, "%8X %c ", cl?cl->tid:0, cl?cl->typ:' ');
193 case 0: // Add thread id
194 return pos + snprintf(txt+pos, LOG_BUF_SIZE-pos, "%8X%-3.3s ", cl?cl->tid:0, "");
195 default: // Add empty thread id
196 return pos + snprintf(txt+pos, LOG_BUF_SIZE-pos, "%8X%-3.3s ", 0, "");
197 }
198}
199
200static void write_to_log(char *txt, struct s_log *log, int8_t do_flush)
201{
202 (void)log; // Prevent warning when WEBIF, MODULE_MONITOR and CS_ANTICASC are disabled
203
204#ifdef CS_ANTICASC
205 extern FILE *ac_log;
206 if (!strncmp(txt + log->header_len, "acasc:", 6) && ac_log) {
207 strcat(txt, "\n");
208 fputs(txt + 8, ac_log);
209 fflush(ac_log);
210 } else
211#endif
212 {
213 if (cfg.logtosyslog)
214 syslog(LOG_INFO, "%s", txt+24);
215 strcat(txt, "\n");
216 }
217 cs_write_log(txt + 8, do_flush);
218
219#if defined(WEBIF) || defined(MODULE_MONITOR)
220 if (loghist && exit_oscam != 1) {
221 char *usrtxt = log->cl_text;
222 char *target_ptr = NULL;
223 int32_t target_len = strlen(usrtxt) + (strlen(txt) - 8) + 1;
224
225 cs_writelock(&loghistory_lock);
226 char *lastpos = loghist + (cfg.loghistorysize) - 1;
227 if(loghist + target_len + 1 >= lastpos){
228 strncpy(txt + 39, "Log entry too long!", strlen(txt) - 39); // we can assume that the min loghistorysize is always 1024 so we don't need to check if this new string fits into it!
229 target_len = strlen(usrtxt) + (strlen(txt) - 8) + 1;
230 }
231 if (!loghistptr)
232 loghistptr = loghist;
233
234 if (loghistptr + target_len + 1 > lastpos) {
235 *loghistptr='\0';
236 loghistptr=loghist + target_len + 1;
237 *loghistptr='\0';
238 target_ptr=loghist;
239 } else {
240 target_ptr = loghistptr;
241 loghistptr=loghistptr + target_len + 1;
242 *loghistptr='\0';
243 }
244 cs_writeunlock(&loghistory_lock);
245
246 snprintf(target_ptr, target_len + 1, "%s\t%s", usrtxt, txt + 8);
247 }
248#endif
249
250#if defined(MODULE_MONITOR)
251 char sbuf[16];
252 struct s_client *cl;
253 for (cl=first_client; cl ; cl=cl->next) {
254 if ((cl->typ == 'm') && (cl->monlvl>0) && cl->log) //this variable is only initialized for cl->typ = 'm'
255 {
256 if (cl->monlvl<2) {
257 if (log->cl_typ != 'c' && log->cl_typ != 'm')
258 continue;
259 if (log->cl_usr && cl->account && strcmp(log->cl_usr, cl->account->usr))
260 continue;
261 }
262 snprintf(sbuf, sizeof(sbuf), "%03d", cl->logcounter);
263 cl->logcounter = (cl->logcounter+1) % 1000;
264 memcpy(txt + 4, sbuf, 3);
265 monitor_send_idx(cl, txt);
266 }
267 }
268#endif
269}
270
271static void write_to_log_int(char *txt, int8_t header_len)
272{
273#if !defined(WEBIF) && !defined(MODULE_MONITOR)
274 if (cfg.disablelog) return;
275#endif
276 char *newtxt = cs_strdup(txt);
277 if (!newtxt)
278 return;
279 struct s_log *log;
280 if (!cs_malloc(&log, sizeof(struct s_log))) {
281 free(newtxt);
282 return;
283 }
284 log->txt = newtxt;
285 log->header_len = header_len;
286 log->direct_log = 0;
287 struct s_client *cl = cur_client();
288 log->cl_usr = "";
289 if (!cl){
290 log->cl_text = "undef";
291 log->cl_typ = ' ';
292 } else {
293 switch(cl->typ) {
294 case 'c':
295 case 'm':
296 if(cl->account) {
297 log->cl_text = cl->account->usr;
298 log->cl_usr = cl->account->usr;
299 } else log->cl_text = "";
300 break;
301 case 'p':
302 case 'r':
303 log->cl_text = cl->reader ? cl->reader->label : "";
304 break;
305 default:
306 log->cl_text = "server";
307 break;
308 }
309 log->cl_typ = cl->typ;
310 }
311
312 if(exit_oscam == 1 || cfg.disablelog){ //Exit or log disabled. if disabled, just display on webif/monitor
313 char buf[LOG_BUF_SIZE];
314 cs_strncpy(buf, log->txt, LOG_BUF_SIZE);
315 write_to_log(buf, log, 1);
316 free(log->txt);
317 free(log);
318 } else
319 ll_append(log_list, log);
320}
321
322static pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER;
323static char last_log_txt[LOG_BUF_SIZE] = { 0 };
324static time_t last_log_ts = 0;
325static unsigned int last_log_duplicates = 0;
326
327void cs_log_int(uint16_t mask, int8_t lock __attribute__((unused)), const uchar *buf, int32_t n, const char *fmt, ...)
328{
329 if ((mask & cs_dblevel) || !mask ) {
330 va_list params;
331
332 static char log_txt[LOG_BUF_SIZE], dupl[LOG_BUF_SIZE/4];
333 int32_t dupl_header_len, repeated_line, i, len = 0;
334 pthread_mutex_lock(&log_mutex);
335 if (fmt)
336 {
337 va_start(params, fmt);
338 len = get_log_header(1, log_txt);
339 vsnprintf(log_txt + len, sizeof(log_txt) - len, fmt, params);
340 va_end(params);
341 if (cfg.logduplicatelines) {
342 memcpy(last_log_txt, log_txt + len, LOG_BUF_SIZE);
343 write_to_log_int(log_txt, len);
344 } else {
345 repeated_line = strcmp(last_log_txt, log_txt + len) == 0;
346 if (last_log_duplicates > 0) {
347 if (!last_log_ts) // Must be initialized once
348 last_log_ts = log_ts;
349 // Report duplicated lines when the new log line is different
350 // than the old or 60 seconds have passed.
351 if (!repeated_line || log_ts - last_log_ts >= 60) {
352 dupl_header_len = get_log_header(2, dupl);
353 snprintf(dupl + dupl_header_len - 1, sizeof(dupl) - dupl_header_len, "--- Skipped %u duplicated log lines ---", last_log_duplicates);
354 write_to_log_int(dupl, 0);
355 last_log_duplicates = 0;
356 last_log_ts = log_ts;
357 }
358 }
359 if (!repeated_line) {
360 memcpy(last_log_txt, log_txt + len, LOG_BUF_SIZE);
361 write_to_log_int(log_txt, len);
362 } else {
363 last_log_duplicates++;
364 }
365 }
366 }
367 if (buf)
368 {
369 for (i=0; i<n; i+=16)
370 {
371 len = get_log_header(0, log_txt);
372 cs_hexdump(1, buf+i, (n-i>16) ? 16 : n-i, log_txt + len, sizeof(log_txt) - len);
373 write_to_log_int(log_txt, len);
374 }
375 }
376 pthread_mutex_unlock(&log_mutex);
377 }
378}
379
380void cs_close_log(void)
381{
382 //Wait for log close:
383 int32_t i = 0;
384 while (ll_count(log_list) > 0 && i < 1000) {
385 cs_sleepms(1);
386 ++i;
387 }
388 if(fp){
389 fclose(fp);
390 fp=(FILE *)0;
391 }
392}
393
394/*
395 * This function writes the current CW from ECM struct to a cwl file.
396 * The filename is re-calculated and file re-opened every time.
397 * This will consume a bit cpu time, but nothing has to be stored between
398 * each call. If not file exists, a header is prepended
399 */
400void logCWtoFile(ECM_REQUEST *er, uchar *cw){
401 FILE *pfCWL;
402 char srvname[128];
403 /* %s / %s _I %04X _ %s .cwl */
404 char buf[256 + sizeof(srvname)];
405 char date[9];
406 unsigned char i, parity, writeheader = 0;
407 time_t t;
408 struct tm timeinfo;
409
410 /*
411 * search service name for that id and change characters
412 * causing problems in file name
413 */
414
415 get_servicename(cur_client(), er->srvid, er->caid, srvname);
416
417 for (i = 0; srvname[i]; i++)
418 if (srvname[i] == ' ') srvname[i] = '_';
419
420 /* calc log file name */
421 time(&t);
422 localtime_r(&t, &timeinfo);
423 strftime(date, sizeof(date), "%Y%m%d", &timeinfo);
424 snprintf(buf, sizeof(buf), "%s/%s_I%04X_%s.cwl", cfg.cwlogdir, date, er->srvid, srvname);
425
426 /* open failed, assuming file does not exist, yet */
427 if((pfCWL = fopen(buf, "r")) == NULL) {
428 writeheader = 1;
429 } else {
430 /* we need to close the file if it was opened correctly */
431 fclose(pfCWL);
432 }
433
434 if ((pfCWL = fopen(buf, "a+")) == NULL) {
435 /* maybe this fails because the subdir does not exist. Is there a common function to create it?
436 for the moment do not print32_t to log on every ecm
437 cs_log(""error opening cw logfile for writing: %s (errno=%d %s)", buf, errno, strerror(errno)); */
438 return;
439 }
440 if (writeheader) {
441 /* no global macro for cardserver name :( */
442 fprintf(pfCWL, "# OSCam cardserver v%s - http://www.streamboard.tv/oscam/\n", CS_VERSION);
443 fprintf(pfCWL, "# control word log file for use with tsdec offline decrypter\n");
444 strftime(buf, sizeof(buf),"DATE %Y-%m-%d, TIME %H:%M:%S, TZ %Z\n", &timeinfo);
445 fprintf(pfCWL, "# %s", buf);
446 fprintf(pfCWL, "# CAID 0x%04X, SID 0x%04X, SERVICE \"%s\"\n", er->caid, er->srvid, srvname);
447 }
448
449 parity = er->ecm[0]&1;
450 fprintf(pfCWL, "%d ", parity);
451 for (i = parity * 8; i < 8 + parity * 8; i++)
452 fprintf(pfCWL, "%02X ", cw[i]);
453 /* better use incoming time er->tps rather than current time? */
454 strftime(buf,sizeof(buf),"%H:%M:%S\n", &timeinfo);
455 fprintf(pfCWL, "# %s", buf);
456 fflush(pfCWL);
457 fclose(pfCWL);
458}
459
460int32_t cs_init_statistics(void)
461{
462 if ((!fps) && (cfg.usrfile != NULL))
463 {
464 if ((fps=fopen(cfg.usrfile, "a+"))<=(FILE *)0)
465 {
466 fps=(FILE *)0;
467 cs_log("couldn't open statistics file: %s", cfg.usrfile);
468 }
469 }
470 return(fps<=(FILE *)0);
471}
472
473void cs_statistics(struct s_client * client)
474{
475 if (!cfg.disableuserfile){
476 time_t t;
477 struct tm lt;
478 char buf[LOG_BUF_SIZE];
479
480 float cwps;
481
482 time(&t);
483 localtime_r(&t, &lt);
484 if (client->cwfound+client->cwnot>0)
485 {
486 cwps=client->last-client->login;
487 cwps/=client->cwfound+client->cwnot;
488 }
489 else
490 cwps=0;
491
492 char channame[32];
493 if (cfg.appendchaninfo)
494 get_servicename(client, client->last_srvid,client->last_caid, channame);
495 else
496 channame[0] = '\0';
497
498 int32_t lsec;
499 if ((client->last_caid == 0xFFFF) && (client->last_srvid == 0xFFFF))
500 lsec = client->last - client->login; //client leave calc total duration
501 else
502 lsec = client->last - client->lastswitch;
503
504 int32_t secs = 0, fullmins = 0, mins = 0, fullhours = 0;
505
506 if((lsec > 0) && (lsec < 1000000)) {
507 secs = lsec % 60;
508 if (lsec > 60) {
509 fullmins = lsec / 60;
510 mins = fullmins % 60;
511 if(fullmins > 60) {
512 fullhours = fullmins / 60;
513 }
514 }
515 }
516
517 /* statistics entry start with 's' to filter it out on other end of pipe
518 * so we can use the same Pipe as Log
519 */
520 snprintf(buf, sizeof(buf), "s%02d.%02d.%02d %02d:%02d:%02d %3.1f %s %s %d %d %d %d %d %d %d %ld %ld %02d:%02d:%02d %s %04X:%04X %s\n",
521 lt.tm_mday, lt.tm_mon+1, lt.tm_year%100,
522 lt.tm_hour, lt.tm_min, lt.tm_sec, cwps,
523 client->account->usr,
524 cs_inet_ntoa(client->ip),
525 client->port,
526 client->cwfound,
527 client->cwcache,
528 client->cwnot,
529 client->cwignored,
530 client->cwtout,
531 client->cwtun,
532 client->login,
533 client->last,
534 fullhours, mins, secs,
535 get_module(client)->desc,
536 client->last_caid,
537 client->last_srvid,
538 channame);
539
540 cs_write_log_int(buf);
541 }
542}
543
544void log_list_thread(void)
545{
546 char buf[LOG_BUF_SIZE];
547 set_thread_name(__func__);
548 int last_count=ll_count(log_list), count, grow_count=0, write_count;
549 do {
550 LL_ITER it = ll_iter_create(log_list);
551 struct s_log *log;
552 write_count = 0;
553 while ((log=ll_iter_next_remove(&it))) {
554 int8_t do_flush = ll_count(log_list) == 0; //flush on writing last element
555
556 cs_strncpy(buf, log->txt, LOG_BUF_SIZE);
557 if (log->direct_log)
558 cs_write_log(buf, do_flush);
559 else
560 write_to_log(buf, log, do_flush);
561 free(log->txt);
562 free(log);
563
564 //If list is faster growing than we could write to file, drop list:
565 write_count++;
566 if (write_count%10000 == 0) { //check every 10000 writes:
567 count = ll_count(log_list);
568 if (count > last_count) {
569 grow_count++;
570 if (grow_count > 5) { //5 times still growing
571 cs_write_log("------------->logging temporary disabled (30s) - too much data!\n", 1);
572 cfg.disablelog = 1;
573 ll_iter_reset(&it);
574 while ((log=ll_iter_next_remove(&it))) { //clear log
575 free(log->txt);
576 free(log);
577 }
578 cs_sleepms(30*1000);
579 cfg.disablelog = 0;
580
581 grow_count = 0;
582 last_count = 0;
583 break;
584 }
585 }
586 else
587 grow_count = 0;
588 last_count = count;
589 }
590 }
591 cs_sleepms(250);
592 } while(1);
593}
594
595int32_t cs_init_log(void)
596{
597 if(logStarted == 0){
598#if defined(WEBIF) || defined(MODULE_MONITOR)
599 cs_lock_create(&loghistory_lock, 5, "loghistory_lock");
600#endif
601
602 log_list = ll_create(LOG_LIST);
603 start_thread((void*)&log_list_thread, "log_list_thread");
604 }
605 int32_t rc = 0;
606 if(!cfg.disablelog) rc = cs_open_logfiles();
607 logStarted = 1;
608 return rc;
609}
610
611void cs_disable_log(int8_t disabled)
612{
613 if (cfg.disablelog != disabled) {
614 if(disabled && logStarted) {
615 cs_log("Stopping log...");
616 int32_t i = 0;
617 while(ll_count(log_list) > 0 && i < 200){
618 cs_sleepms(5);
619 ++i;
620 }
621 }
622 cfg.disablelog = disabled;
623 if (disabled){
624 if(logStarted) {
625 cs_sleepms(20);
626 cs_close_log();
627 }
628 } else {
629 cs_open_logfiles();
630 }
631 }
632}
633
Note: See TracBrowser for help on using the repository browser.