source: trunk/oscam-log.c @ 5375

Last change on this file since 5375 was 5361, checked in by Admin, 8 years ago

Some internal restructuring regarding globals.h file to make it a bit more structured.

File size: 13.9 KB
Line 
1#include "globals.h"
2#include <syslog.h>
3#include <stdlib.h>
4
5static FILE *fp=(FILE *)0;
6static FILE *fps=(FILE *)0;
7static int16_t logStarted = 0;
8
9pthread_mutex_t switching_log;
10pthread_mutex_t loghistory_lock;
11
12#ifdef CS_ANTICASC
13FILE *fpa=(FILE *)0;
14#endif
15
16#define LOG_BUF_SIZE (520+11) // should be aligned with s_client.dump from globals.h
17
18static void switch_log(char* file, FILE **f, int32_t (*pfinit)(void))
19{
20    if( cfg.max_log_size)   //only 1 thread needs to switch the log; even if anticasc, statistics and normal log are running
21                    //at the same time, it is ok to have the other logs switching 1 entry later
22    {
23        struct stat stlog;
24
25        if( stat(file, &stlog)!=0 )
26        {
27            fprintf(stderr, "stat('%s',..) failed (errno=%d %s)\n", file, errno, strerror(errno));
28            return;
29        }
30
31        if( stlog.st_size >= cfg.max_log_size*1024 && *f != NULL) {
32            int32_t rc;
33            char prev_log[strlen(file) + 6];
34            snprintf(prev_log, sizeof(prev_log), "%s-prev", file);
35            if ( cs_trylock(&switching_log) == 0) { //I got the lock so I am the first thread detecting a switchlog is needed
36                FILE *tmp = *f;
37                *f = (FILE *)0;
38                fprintf(tmp, "switch log file\n");
39                cs_sleepms(1);
40                fflush(tmp);
41                fclose(tmp);
42                rc = rename(file, prev_log);
43                if( rc!=0 ) {
44                    fprintf(stderr, "rename(%s, %s) failed (errno=%d %s)\n", file, prev_log, errno, strerror(errno));
45                }
46                else
47                    if( pfinit()){
48                        fprintf(stderr, "Initialisation of log file failed, continuing without logging thread %8X. Log will be output to stdout!", (unsigned int)pthread_self());
49                        cfg.logtostdout = 1;
50                    }
51            }
52            else //I am not the first to detect a switchlog is needed, so I need to wait for the first thread to complete
53                cs_lock(&switching_log); //wait on 1st thread
54            cs_unlock(&switching_log); //release after processing or after waiting
55        }
56    }
57}
58
59void cs_write_log(char *txt)
60{
61#ifdef CS_ANTICASC
62    struct s_client *cl = cur_client();
63    if( cl && cl->typ == 'a' && fpa ) {
64        switch_log(cfg.ac_logfile, &fpa, ac_init_log);
65        if (fpa) {
66                fputs(txt, fpa);
67                fflush(fpa);
68        }
69    }
70    else
71#endif
72        // filter out entries with leading 's' and forward to statistics
73        if(txt[0] == 's') {
74            if (fps) {
75                switch_log(cfg.usrfile, &fps, cs_init_statistics);
76                if (fps) {
77                        fputs(txt + 1, fps); // remove the leading 's' and write to file
78                        fflush(fps);
79                }
80            }
81        } else {
82            if(!cfg.disablelog){
83                if (fp){
84                    switch_log(cfg.logfile, &fp, cs_open_logfiles);
85                    if (fp) {
86                            fputs(txt, fp);
87                            fflush(fp);
88                    }       
89                }
90                if(cfg.logtostdout){
91                    fputs(txt, stdout);
92                    fflush(stdout);
93                }
94            }
95        }
96}
97
98int32_t cs_open_logfiles()
99{
100    char *starttext;
101    if(logStarted) starttext = "log switched";
102    else starttext = "started";
103    if (!fp && cfg.logfile != NULL) {   //log to file
104        if ((fp = fopen(cfg.logfile, "a+")) <= (FILE *)0) {
105            fp = (FILE *)0;
106            fprintf(stderr, "couldn't open logfile: %s (errno %d %s)\n", cfg.logfile, errno, strerror(errno));
107        } else {
108            time_t t;
109            char line[80];
110            memset(line, '-', sizeof(line));
111            line[(sizeof(line)/sizeof(char)) - 1] = '\0';
112            time(&t);
113            if (!cfg.disablelog)
114                fprintf(fp, "\n%s\n>> OSCam <<  cardserver %s at %s%s\n", line, starttext, ctime(&t), line);
115        }
116    }
117    // according to syslog docu: calling closelog is not necessary and calling openlog multiple times is safe
118    // We use openlog to set the default syslog settings so that it's possible to allow switching syslog on and off
119    openlog("oscam", LOG_NDELAY, LOG_DAEMON);
120   
121    cs_log(">> OSCam <<  cardserver %s, version " CS_VERSION ", build #" CS_SVN_VERSION " (" CS_OSTYPE ")", starttext);
122    cs_log_config();
123    return(fp <= (FILE *)0);
124}
125
126int32_t cs_init_log(void)
127{
128    if(logStarted == 0){
129        pthread_mutex_init(&switching_log, NULL);
130        pthread_mutex_init(&loghistory_lock, NULL);
131    }
132    int32_t rc = cs_open_logfiles();
133    logStarted = 1;
134    return rc;
135}
136
137/*
138 This function allows to reinit the in-memory loghistory with a new size.
139*/
140void cs_reinit_loghist(uint32_t size)
141{
142    char *tmp, *tmp2;
143    if(size != cfg.loghistorysize){
144        if(cs_malloc(&tmp, size, -1)){
145            cs_lock(&loghistory_lock);
146            tmp2 = loghist;
147            // On shrinking, the log is not copied and the order is reversed
148            if(size < cfg.loghistorysize){
149                cfg.loghistorysize = size;
150                cs_sleepms(20); // Monitor or webif may be currently outputting the loghistory but don't use locking so we sleep a bit...
151                loghistptr = tmp;
152                loghist = tmp;
153            } else {
154                if(loghist){
155                    memcpy(tmp, loghist, cfg.loghistorysize);
156                    loghistptr = tmp + (loghistptr - loghist);
157                } else loghistptr = tmp;
158                loghist = tmp;
159                cs_sleepms(20); // Monitor or webif may be currently outputting the loghistory but don't use locking so we sleep a bit...
160                cfg.loghistorysize = size;                     
161            }
162            cs_unlock(&loghistory_lock);
163            if(tmp2 != NULL) add_garbage(tmp2);         
164        }
165    }
166}
167
168static void get_log_header(int32_t m, char *txt)
169{
170    struct s_client *cl = cur_client(); 
171    pthread_t thread = cl?cl->thread:0;
172    if(m)
173        snprintf(txt, LOG_BUF_SIZE, "%8X %c ",(unsigned int) thread, cl?cl->typ:' ');
174    else
175        snprintf(txt, LOG_BUF_SIZE, "%8X%-3.3s",(unsigned int) thread, "");
176}
177
178static void write_to_log(char *txt)
179{
180    //flag = -1 is old behaviour, before implementation of debug_nolf (=debug no line feed)
181    //
182    time_t t;
183    struct tm lt;
184    char sbuf[16];
185    char log_buf[700];
186    struct s_client *cur_cl = cur_client();
187
188    //  get_log_header(flag, sbuf);
189    //  memcpy(txt, sbuf, 11);
190
191#ifdef CS_ANTICASC
192    if (cfg.logtosyslog && cur_cl && cur_cl->typ != 'a') // system-logfile
193#else
194    if (cfg.logtosyslog) // system-logfile
195#endif
196        syslog(LOG_INFO, "%s", txt);
197
198    time(&t);
199    localtime_r(&t, &lt);
200
201    snprintf(log_buf, sizeof(log_buf),  "[LOG000]%4d/%02d/%02d %2d:%02d:%02d %s\n",
202        lt.tm_year+1900, lt.tm_mon+1, lt.tm_mday, lt.tm_hour, lt.tm_min, lt.tm_sec, txt);
203
204    cs_write_log(log_buf + 8);
205
206    if (loghist) {
207        char *usrtxt = NULL;
208
209        if (!cur_cl)
210            usrtxt = "undef";
211        else {
212            switch(cur_cl->typ) {
213                case 'c':
214                case 'm':
215                    usrtxt = cur_cl->account ? cur_cl->account->usr : "";
216                    break;
217                case 'p':
218                case 'r':
219                    usrtxt = cur_cl->reader ? cur_cl->reader->label : "";
220                    break;
221                default:
222                    usrtxt = "server";
223                    break;
224            }
225        }
226
227        char *target_ptr = NULL;
228        int32_t target_len = strlen(usrtxt) + (strlen(log_buf) - 8) + 1;
229       
230        cs_lock(&loghistory_lock);
231        char *lastpos = loghist + (cfg.loghistorysize) - 1;     
232        if (!loghistptr)
233            loghistptr = loghist;
234
235        if (loghistptr+target_len > lastpos - 1) {
236            *loghistptr='\0';
237            loghistptr=loghist + target_len + 1;
238            *loghistptr='\0';
239            target_ptr=loghist;
240        } else {
241            target_ptr = loghistptr;
242            loghistptr=loghistptr + target_len + 1;
243            *loghistptr='\0';
244        }
245        cs_unlock(&loghistory_lock);
246
247        snprintf(target_ptr, target_len + 1, "%s\t%s", usrtxt, log_buf + 8);
248    }
249
250    struct s_client *cl;
251    for (cl=first_client; cl ; cl=cl->next) {
252        if ((cl->typ == 'm') && (cl->monlvl>0) && cl->log) //this variable is only initialized for cl->typ = 'm'
253        {
254            if (cl->monlvl<2) {
255                if (cur_cl && (cur_cl->typ != 'c') && (cur_cl->typ != 'm'))
256                    continue;
257                if (cur_cl && cur_cl->account && cl->account && strcmp(cur_cl->account->usr, cl->account->usr))
258                    continue;
259            }
260            snprintf(sbuf, sizeof(sbuf), "%03d", cl->logcounter);
261            cl->logcounter = (cl->logcounter+1) % 1000;
262            memcpy(log_buf + 4, sbuf, 3);
263            monitor_send_idx(cl, log_buf);
264        }
265    }
266}
267
268void cs_log(const char *fmt,...)
269{
270    char log_txt[LOG_BUF_SIZE];
271    get_log_header(1, log_txt);
272    va_list params;
273    va_start(params, fmt);
274    vsnprintf(log_txt+11, sizeof(log_txt) - 11, fmt, params);
275    va_end(params);
276    write_to_log(log_txt);
277}
278
279void cs_close_log(void)
280{
281    if (!fp) return;
282    fclose(fp);
283    fp=(FILE *)0;
284}
285#ifdef WITH_DEBUG
286void cs_debug_mask(uint16_t mask, const char *fmt,...)
287{
288    char log_txt[LOG_BUF_SIZE];
289    if (cs_dblevel & mask)
290    {
291        get_log_header(1, log_txt);
292        va_list params;
293        va_start(params, fmt);
294        vsnprintf(log_txt+11, sizeof(log_txt) - 11, fmt, params);
295        va_end(params);
296        write_to_log(log_txt);
297    }
298}
299#endif
300void cs_dump(const uchar *buf, int32_t n, char *fmt, ...)
301{
302    char log_txt[LOG_BUF_SIZE];
303    int32_t i;
304
305    if( fmt )
306    {
307        get_log_header(1, log_txt);
308        va_list params;
309        va_start(params, fmt);
310        vsnprintf(log_txt+11, sizeof(log_txt) - 11, fmt, params);
311        va_end(params);
312        write_to_log(log_txt);
313        //printf("LOG: %s\n", txt); fflush(stdout);
314    }
315
316    for( i=0; i<n; i+=16 )
317    {
318        get_log_header(0, log_txt);
319        snprintf(log_txt+11, sizeof(log_txt) - 11, "%s", cs_hexdump(1, buf+i, (n-i>16) ? 16 : n-i));
320        write_to_log(log_txt);
321    }
322}
323#ifdef WITH_DEBUG
324void cs_ddump_mask(uint16_t mask, const uchar *buf, int32_t n, char *fmt, ...)
325{
326
327    char log_txt[LOG_BUF_SIZE];
328    int32_t i;
329    if ((mask & cs_dblevel) && (fmt))
330    {
331        get_log_header(1, log_txt);
332        va_list params;
333        va_start(params, fmt);
334        vsnprintf(log_txt+11, sizeof(log_txt) - 11, fmt, params);
335        va_end(params);
336        write_to_log(log_txt);
337        //printf("LOG: %s\n", txt); fflush(stdout);
338    }
339    if (mask & cs_dblevel)
340    {
341        for (i=0; i<n; i+=16)
342        {
343            get_log_header(0, log_txt);
344            snprintf(log_txt+11, sizeof(log_txt) - 11, "%s", cs_hexdump(1, buf+i, (n-i>16) ? 16 : n-i));
345            write_to_log(log_txt);
346        }
347    }
348}
349#endif
350
351void log_emm_request(struct s_reader *rdr){
352    cs_log("%s emm-request sent (reader=%s, caid=%04X, auprovid=%06lX)",
353            username(cur_client()), rdr->label, rdr->caid,
354            rdr->auprovid ? rdr->auprovid : b2i(4, rdr->prid[0]));
355}
356
357/*
358 * This function writes the current CW from ECM struct to a cwl file.
359 * The filename is re-calculated and file re-opened every time.
360 * This will consume a bit cpu time, but nothing has to be stored between
361 * each call. If not file exists, a header is prepended
362 */
363void logCWtoFile(ECM_REQUEST *er){
364    FILE *pfCWL;
365    char srvname[128];
366    /* %s / %s   _I  %04X  _  %s  .cwl  */
367    char buf[256 + sizeof(srvname)];
368    char date[7];
369    unsigned char  i, parity, writeheader = 0;
370    time_t t;
371    struct tm timeinfo;
372
373    /*
374    * search service name for that id and change characters
375    * causing problems in file name
376    */
377
378    get_servicename(cur_client(), er->srvid, er->caid, srvname);
379
380    for (i = 0; srvname[i]; i++)
381        if (srvname[i] == ' ') srvname[i] = '_';
382
383    /* calc log file name */
384    time(&t);
385    localtime_r(&t, &timeinfo);
386    strftime(date, sizeof(date), "%Y%m%d", &timeinfo);
387    snprintf(buf, sizeof(buf), "%s/%s_I%04X_%s.cwl", cfg.cwlogdir, date, er->srvid, srvname);
388
389    /* open failed, assuming file does not exist, yet */
390    if((pfCWL = fopen(buf, "r")) == NULL) {
391        writeheader = 1;
392    } else {
393    /* we need to close the file if it was opened correctly */
394        fclose(pfCWL);
395    }
396
397    if ((pfCWL = fopen(buf, "a+")) == NULL) {
398        /* maybe this fails because the subdir does not exist. Is there a common function to create it?
399            for the moment do not print32_t to log on every ecm
400            cs_log(""error opening cw logfile for writing: %s (errno=%d %s)", buf, errno, strerror(errno)); */
401        return;
402    }
403    if (writeheader) {
404        /* no global macro for cardserver name :( */
405        fprintf(pfCWL, "# OSCam cardserver v%s - http://streamboard.gmc.to/oscam/\n", CS_VERSION);
406        fprintf(pfCWL, "# control word log file for use with tsdec offline decrypter\n");
407        strftime(buf, sizeof(buf),"DATE %Y-%m-%d, TIME %H:%M:%S, TZ %Z\n", &timeinfo);
408        fprintf(pfCWL, "# %s", buf);
409        fprintf(pfCWL, "# CAID 0x%04X, SID 0x%04X, SERVICE \"%s\"\n", er->caid, er->srvid, srvname);
410    }
411
412    parity = er->ecm[0]&1;
413    fprintf(pfCWL, "%d ", parity);
414    for (i = parity * 8; i < 8 + parity * 8; i++)
415        fprintf(pfCWL, "%02X ", er->cw[i]);
416    /* better use incoming time er->tps rather than current time? */
417    strftime(buf,sizeof(buf),"%H:%M:%S\n", &timeinfo);
418    fprintf(pfCWL, "# %s", buf);
419    fflush(pfCWL);
420    fclose(pfCWL);
421}
422
423void cs_log_config()
424{
425  uchar buf[20];
426
427  if (cfg.nice!=99)
428    snprintf((char *)buf, sizeof(buf), ", nice=%d", cfg.nice);
429  else
430    buf[0]='\0';
431  cs_log("version=%s, build #%s, system=%s-%s-%s%s", CS_VERSION, CS_SVN_VERSION, CS_OS_CPU, CS_OS_HW, CS_OS_SYS, buf);
432  cs_log("client max. idle=%d sec, debug level=%d", cfg.cmaxidle, cs_dblevel);
433
434  if( cfg.max_log_size )
435    snprintf((char *)buf, sizeof(buf), "%d Kb", cfg.max_log_size);
436  else
437    cs_strncpy((char *)buf, "unlimited", sizeof(buf));
438  cs_log("max. logsize=%s, loghistorysize=%d bytes", buf, cfg.loghistorysize);
439  cs_log("client timeout=%lu ms, fallback timeout=%lu ms, cache delay=%d ms",
440         cfg.ctimeout, cfg.ftimeout, cfg.delay);
441}
442
443int32_t cs_init_statistics(void) 
444{
445    if ((!fps) && (cfg.usrfile != NULL))
446    {
447        if ((fps=fopen(cfg.usrfile, "a+"))<=(FILE *)0)
448        {
449            fps=(FILE *)0;
450            cs_log("couldn't open statistics file: %s", cfg.usrfile);
451        }
452    }
453    return(fps<=(FILE *)0);
454}
455
456void cs_statistics(struct s_client * client)
457{
458    if (!cfg.disableuserfile){
459        time_t t;
460        struct tm lt;
461        char buf[LOG_BUF_SIZE];
462
463        float cwps;
464
465        time(&t);
466        localtime_r(&t, &lt);
467        if (client->cwfound+client->cwnot>0)
468        {
469            cwps=client->last-client->login;
470            cwps/=client->cwfound+client->cwnot;
471        }
472        else
473            cwps=0;
474
475        char channame[32];
476        if(cfg.mon_appendchaninfo)
477            get_servicename(client, client->last_srvid,client->last_caid, channame);
478        else
479            channame[0] = '\0';
480
481        int32_t lsec;
482        if ((client->last_caid == 0xFFFF) && (client->last_srvid == 0xFFFF))
483            lsec = client->last - client->login; //client leave calc total duration
484        else
485            lsec = client->last - client->lastswitch;
486
487        int32_t secs = 0, fullmins = 0, mins = 0, fullhours = 0;
488
489        if((lsec > 0) && (lsec < 1000000)) {
490            secs = lsec % 60;
491            if (lsec > 60) {
492                fullmins = lsec / 60;
493                mins = fullmins % 60;
494                if(fullmins > 60) {
495                    fullhours = fullmins / 60;
496                }
497            }
498        }
499
500        /* statistics entry start with 's' to filter it out on other end of pipe
501         * so we can use the same Pipe as Log
502         */
503        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",
504                lt.tm_mday, lt.tm_mon+1, lt.tm_year%100,
505                lt.tm_hour, lt.tm_min, lt.tm_sec, cwps,
506                client->account->usr,
507                cs_inet_ntoa(client->ip),
508                client->port,
509                client->cwfound,
510                client->cwcache,
511                client->cwnot,
512                client->cwignored,
513                client->cwtout,
514                client->cwtun,
515                client->login,
516                client->last,
517                fullhours, mins, secs,
518                ph[client->ctyp].desc,
519                client->last_caid,
520                client->last_srvid,
521                channame);
522
523        cs_write_log(buf);
524    }
525}
Note: See TracBrowser for help on using the repository browser.