log.c 33.3 KB
Newer Older
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
/*******************************************************************************

  Eurecom OpenAirInterface
  Copyright(c) 1999 - 2010 Eurecom

  This program is free software; you can redistribute it and/or modify it
  under the terms and conditions of the GNU General Public License,
  version 2, as published by the Free Software Foundation.

  This program is distributed in the hope it will be useful, but WITHOUT
  ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
  more details.

  You should have received a copy of the GNU General Public License along with
  this program; if not, write to the Free Software Foundation, Inc.,
  51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.

  The full GNU General Public License is included in this distribution in
  the file called "COPYING".

  Contact Information
  Openair Admin: openair_admin@eurecom.fr
  Openair Tech : openair_tech@eurecom.fr
  Forums       : http://forums.eurecom.fsr/openairinterface
  Address      : Eurecom, 2229, route des crêtes, 06560 Valbonne Sophia Antipolis, France

*******************************************************************************/
/*! \file log.c
* \brief log implementaion
* \author Navid Nikaein
* \date 2011
* \version 0.5
* @ingroup util

*/

//#define LOG_TEST 1

#define COMPONENT_LOG
#define COMPONENT_LOG_IF

#include "log.h"
#include "vcd_signal_dumper.h"
45
#include "assertions.h"
46

47
48
49
50
#if defined(ENABLE_ITTI)
# include "intertask_interface.h"
#endif

51
#ifdef USER_MODE
Cedric Roux's avatar
Cedric Roux committed
52
53
# include <pthread.h>
# include <string.h>
54
55
#endif
#ifdef RTAI
56
57
58
# include <rtai.h>
# include <rtai_fifos.h>
#    define FIFO_PRINTF_MAX_STRING_SIZE 1000
59
60
61
62
#    define FIFO_PRINTF_NO              62
#    define FIFO_PRINTF_SIZE            65536
#endif

63
64
// main log variables
log_t *g_log;
65

66
67
68
69
// vars for the log thread
LOG_params log_list[2000];
int log_list_tail = 0;
int log_list_nb_elements = 0;
70

71
72
pthread_mutex_t log_lock;
pthread_cond_t log_notify;
73

74
75
76
77
#if !defined(LOG_NO_THREAD)
int log_list_head = 0;
int log_shutdown;
#endif
78

winckel's avatar
winckel committed
79
#ifndef RTAI
80
static int gfd;
winckel's avatar
winckel committed
81
#endif
82

83
84
static char *log_level_highlight_start[] = {LOG_RED, LOG_RED, LOG_RED, LOG_RED, LOG_ORANGE, LOG_BLUE, "", ""};  /*!< \brief Optional start-format strings for highlighting */
static char *log_level_highlight_end[]   = {LOG_RESET, LOG_RESET, LOG_RESET, LOG_RESET, LOG_RESET,LOG_RESET,  "",""};   /*!< \brief Optional end-format strings for highlighting */
85

86
87
88
89
#if defined(ENABLE_ITTI)
static log_instance_type_t log_instance_type;
#endif

90
91
int logInit (void)
{
92
#ifdef USER_MODE
winckel's avatar
winckel committed
93
#ifndef RTAI
94
    int i;
winckel's avatar
winckel committed
95
#endif
96
    g_log = calloc(1, sizeof(log_t));
Cedric Roux's avatar
Cedric Roux committed
97

98
#else
99
    g_log = kmalloc(sizeof(log_t), GFP_KERNEL);
100
#endif
101
    if (g_log == NULL) {
102
#ifdef USER_MODE
103
104
        perror ("cannot allocated memory for log generation module \n");
        exit(EXIT_FAILURE);
105
#else
106
107
        printk("cannot allocated memory for log generation module \n");
        return(-1);
108
#endif
109
110
    }

Cedric Roux's avatar
Cedric Roux committed
111
    g_log->log_component[PHY].name = "PHY";
112
    g_log->log_component[PHY].level = LOG_EMERG;
113
114
115
116
117
    g_log->log_component[PHY].flag =  LOG_MED;
    g_log->log_component[PHY].interval =  1;
    g_log->log_component[PHY].fd = 0;
    g_log->log_component[PHY].filelog = 0;
    g_log->log_component[PHY].filelog_name = "/tmp/phy.log";
118

119
    g_log->log_component[MAC].name = "MAC";
120
    g_log->log_component[MAC].level = LOG_EMERG;
121
122
123
124
125
    g_log->log_component[MAC].flag =  LOG_MED;
    g_log->log_component[MAC].interval =  1;
    g_log->log_component[MAC].fd = 0;
    g_log->log_component[MAC].filelog = 0;
    g_log->log_component[MAC].filelog_name = "/tmp/mac.log";
126

127
    g_log->log_component[OPT].name = "OPT";
128
    g_log->log_component[OPT].level = LOG_EMERG;
129
130
131
132
133
134
135
136
137
138
139
140
141
    g_log->log_component[OPT].flag = LOG_MED;
    g_log->log_component[OPT].interval =  1;
    g_log->log_component[OPT].fd = 0;
    g_log->log_component[OPT].filelog = 0;
    g_log->log_component[OPT].filelog_name = "";

    g_log->log_component[RLC].name = "RLC";
    g_log->log_component[RLC].level = LOG_INFO;
    g_log->log_component[RLC].flag = LOG_MED;
    g_log->log_component[RLC].interval =  1;
    g_log->log_component[RLC].fd = 0;
    g_log->log_component[RLC].filelog = 0;
    g_log->log_component[RLC].filelog_name = "/tmp/rlc.log";
142

143
144
145
146
147
148
149
    g_log->log_component[PDCP].name = "PDCP";
    g_log->log_component[PDCP].level = LOG_INFO;
    g_log->log_component[PDCP].flag = LOG_MED;
    g_log->log_component[PDCP].interval =  1;
    g_log->log_component[PDCP].fd = 0;
    g_log->log_component[PDCP].filelog = 0;
    g_log->log_component[PDCP].filelog_name = "/tmp/pdcp.log";
150

151
152
153
154
155
156
157
158
    g_log->log_component[RRC].name = "RRC";
    g_log->log_component[RRC].level = LOG_TRACE;
    g_log->log_component[RRC].flag = LOG_MED;
    g_log->log_component[RRC].interval =  1;
    g_log->log_component[RRC].fd = 0;
    g_log->log_component[RRC].filelog = 0;
    g_log->log_component[RRC].filelog_name = "/tmp/rrc.log";

winckel's avatar
winckel committed
159
160
161
162
163
164
165
166
    g_log->log_component[NAS].name = "NAS";
    g_log->log_component[NAS].level = LOG_TRACE;
    g_log->log_component[NAS].flag = LOG_MED;
    g_log->log_component[NAS].interval =  1;
    g_log->log_component[NAS].fd = 0;
    g_log->log_component[NAS].filelog = 0;
    g_log->log_component[NAS].filelog_name = "/tmp/nas.log";

167
    g_log->log_component[EMU].name = "EMU";
168
    g_log->log_component[EMU].level = LOG_EMERG;
169
    g_log->log_component[EMU].flag =  LOG_MED;
170
171
172
173
    g_log->log_component[EMU].interval =  1;
    g_log->log_component[EMU].fd = 0;
    g_log->log_component[EMU].filelog = 0;
    g_log->log_component[EMU].filelog_name = "";
174

175
    g_log->log_component[OMG].name = "OMG";
176
    g_log->log_component[OMG].level = LOG_EMERG;
177
178
179
180
181
    g_log->log_component[OMG].flag =  LOG_MED;
    g_log->log_component[OMG].interval =  1;
    g_log->log_component[OMG].fd = 0;
    g_log->log_component[OMG].filelog = 0;
    g_log->log_component[OMG].filelog_name = "";
182

183
    g_log->log_component[OTG].name = "OTG";
184
    g_log->log_component[OTG].level = LOG_EMERG;
185
186
187
188
189
190
191
    g_log->log_component[OTG].flag =  LOG_MED;
    g_log->log_component[OTG].interval =  1;
    g_log->log_component[OTG].fd = 0;
    g_log->log_component[OTG].filelog = 0;
    g_log->log_component[OTG].filelog_name = "/tmp/otg.log";

    g_log->log_component[OTG_LATENCY].name = "OTG_LATENCY";
192
    g_log->log_component[OTG_LATENCY].level = LOG_EMERG;
193
194
195
196
197
198
199
    g_log->log_component[OTG_LATENCY].flag =  LOG_MED;
    g_log->log_component[OTG_LATENCY].interval =  1;
    g_log->log_component[OTG_LATENCY].fd = 0;
    g_log->log_component[OTG_LATENCY].filelog = 0;
    g_log->log_component[OTG_LATENCY].filelog_name = "/tmp/otg_latency.dat";

    g_log->log_component[OTG_LATENCY_BG].name = "OTG_LATENCY_BG";
200
    g_log->log_component[OTG_LATENCY_BG].level = LOG_EMERG;
201
202
203
204
205
206
207
    g_log->log_component[OTG_LATENCY_BG].flag =  LOG_MED;
    g_log->log_component[OTG_LATENCY_BG].interval =  1;
    g_log->log_component[OTG_LATENCY_BG].fd = 0;
    g_log->log_component[OTG_LATENCY_BG].filelog = 0;
    g_log->log_component[OTG_LATENCY_BG].filelog_name = "/tmp/otg_latency_bg.dat";

    g_log->log_component[OTG_GP].name = "OTG_GP";
208
    g_log->log_component[OTG_GP].level = LOG_EMERG;
209
210
211
212
213
214
215
    g_log->log_component[OTG_GP].flag =  LOG_MED;
    g_log->log_component[OTG_GP].interval =  1;
    g_log->log_component[OTG_GP].fd = 0;
    g_log->log_component[OTG_GP].filelog = 0;
    g_log->log_component[OTG_GP].filelog_name = "/tmp/otg_GP.dat";

    g_log->log_component[OTG_GP_BG].name = "OTG_GP_BG";
216
    g_log->log_component[OTG_GP_BG].level = LOG_EMERG;
217
218
219
220
221
222
223
    g_log->log_component[OTG_GP_BG].flag =  LOG_MED;
    g_log->log_component[OTG_GP_BG].interval =  1;
    g_log->log_component[OTG_GP_BG].fd = 0;
    g_log->log_component[OTG_GP_BG].filelog = 0;
    g_log->log_component[OTG_GP_BG].filelog_name = "/tmp/otg_GP_bg.dat";

    g_log->log_component[OTG_JITTER].name = "OTG_JITTER";
224
    g_log->log_component[OTG_JITTER].level = LOG_EMERG;
225
226
227
228
229
    g_log->log_component[OTG_JITTER].flag =  LOG_MED;
    g_log->log_component[OTG_JITTER].interval =  1;
    g_log->log_component[OTG_JITTER].fd = 0;
    g_log->log_component[OTG_JITTER].filelog = 0;
    g_log->log_component[OTG_JITTER].filelog_name = "/tmp/otg_jitter.dat";
230

231
    g_log->log_component[OCG].name = "OCG";
232
    g_log->log_component[OCG].level = LOG_EMERG;
233
234
235
236
237
    g_log->log_component[OCG].flag =  LOG_MED;
    g_log->log_component[OCG].interval =  1;
    g_log->log_component[OCG].fd = 0;
    g_log->log_component[OCG].filelog = 0;
    g_log->log_component[OCG].filelog_name = "";
238

239
    g_log->log_component[PERF].name = "PERF";
240
    g_log->log_component[PERF].level = LOG_EMERG;
241
242
243
244
245
    g_log->log_component[PERF].flag =  LOG_MED;
    g_log->log_component[PERF].interval =  1;
    g_log->log_component[PERF].fd = 0;
    g_log->log_component[PERF].filelog = 0;
    g_log->log_component[PERF].filelog_name = "";
246

247
    g_log->log_component[OIP].name = "OIP";
248
    g_log->log_component[OIP].level = LOG_EMERG;
249
250
251
252
253
    g_log->log_component[OIP].flag =  LOG_MED;
    g_log->log_component[OIP].interval =  1;
    g_log->log_component[OIP].fd = 0;
    g_log->log_component[OIP].filelog = 0;
    g_log->log_component[OIP].filelog_name = "";
254

255
    g_log->log_component[CLI].name = "CLI";
256
    g_log->log_component[CLI].level = LOG_EMERG;
257
258
259
260
261
    g_log->log_component[CLI].flag =  LOG_MED;
    g_log->log_component[CLI].interval =  1;
    g_log->log_component[CLI].fd = 0;
    g_log->log_component[CLI].filelog =  0;
    g_log->log_component[CLI].filelog_name = "";
262

263
    g_log->log_component[MSC].name = "MSC";
264
    g_log->log_component[MSC].level = LOG_EMERG;
265
266
267
268
269
    g_log->log_component[MSC].flag =  LOG_MED;
    g_log->log_component[MSC].interval =  1;
    g_log->log_component[MSC].fd = 0;
    g_log->log_component[MSC].filelog =  0;
    g_log->log_component[MSC].filelog_name = "/tmp/msc.log";
270

271
    g_log->log_component[OCM].name = "OCM";
272
    g_log->log_component[OCM].level = LOG_EMERG;
273
274
275
276
277
278
279
    g_log->log_component[OCM].flag =  LOG_MED;
    g_log->log_component[OCM].interval =  1;
    g_log->log_component[OCM].fd = 0;
    g_log->log_component[OCM].filelog =  0;
    g_log->log_component[OCM].filelog_name = "/tmp/ocm.log";

    g_log->log_component[S1AP].name = "S1AP";
280
    g_log->log_component[S1AP].level = LOG_EMERG;
281
    g_log->log_component[S1AP].flag = LOG_FULL;
282
283
284
    g_log->log_component[S1AP].interval = 1;
    g_log->log_component[S1AP].fd = 0;
    g_log->log_component[S1AP].filelog = 0;
285
    g_log->log_component[S1AP].filelog_name = "";
286
287

    g_log->log_component[SCTP].name = "SCTP";
288
    g_log->log_component[SCTP].level = LOG_EMERG;
289
290
291
292
293
294
295
    g_log->log_component[SCTP].flag = LOG_MED;
    g_log->log_component[SCTP].interval = 1;
    g_log->log_component[SCTP].fd = 0;
    g_log->log_component[SCTP].filelog = 0;
    g_log->log_component[SCTP].filelog_name = "";

    g_log->log_component[HW].name = "HW";
296
    g_log->log_component[HW].level = LOG_EMERG;
297
298
299
300
301
302
    g_log->log_component[HW].flag = LOG_MED;
    g_log->log_component[HW].interval = 1;
    g_log->log_component[HW].fd = 0;
    g_log->log_component[HW].filelog = 0;
    g_log->log_component[HW].filelog_name = "";

303
304
305
306
307
308
309
310
    g_log->log_component[OSA].name = "OSA";
    g_log->log_component[OSA].level = LOG_EMERG;
    g_log->log_component[OSA].flag = LOG_MED;
    g_log->log_component[OSA].interval = 1;
    g_log->log_component[OSA].fd = 0;
    g_log->log_component[OSA].filelog = 0;
    g_log->log_component[OSA].filelog_name = "";

311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
    g_log->log_component[RAL_ENB].name = "eRAL";
    g_log->log_component[RAL_ENB].level = LOG_EMERG;
    g_log->log_component[RAL_ENB].flag = LOG_MED;
    g_log->log_component[RAL_ENB].interval = 1;
    g_log->log_component[RAL_ENB].fd = 0;
    g_log->log_component[RAL_ENB].filelog = 0;
    g_log->log_component[RAL_ENB].filelog_name = "";

    g_log->log_component[RAL_UE].name = "mRAL";
    g_log->log_component[RAL_UE].level = LOG_EMERG;
    g_log->log_component[RAL_UE].flag = LOG_MED;
    g_log->log_component[RAL_UE].interval = 1;
    g_log->log_component[RAL_UE].fd = 0;
    g_log->log_component[RAL_UE].filelog = 0;
    g_log->log_component[RAL_UE].filelog_name = "";

327
328
329
330
331
332
333
334
    g_log->log_component[ENB_APP].name = "ENB_APP";
    g_log->log_component[ENB_APP].level = LOG_EMERG;
    g_log->log_component[ENB_APP].flag = LOG_MED;
    g_log->log_component[ENB_APP].interval = 1;
    g_log->log_component[ENB_APP].fd = 0;
    g_log->log_component[ENB_APP].filelog = 0;
    g_log->log_component[ENB_APP].filelog_name = "";

335
336
337
338
339
340
341
342
    g_log->log_component[TMR].name = "TMR";
    g_log->log_component[TMR].level = LOG_EMERG;
    g_log->log_component[TMR].flag = LOG_MED;
    g_log->log_component[TMR].interval = 1;
    g_log->log_component[TMR].fd = 0;
    g_log->log_component[TMR].filelog = 0;
    g_log->log_component[TMR].filelog_name = "";

343
344
345
346
347
348
349
350
351
352
    g_log->level2string[LOG_EMERG]         = "G"; //EMERG
    g_log->level2string[LOG_ALERT]         = "A"; // ALERT
    g_log->level2string[LOG_CRIT]          = "C"; // CRITIC
    g_log->level2string[LOG_ERR]           = "E"; // ERROR
    g_log->level2string[LOG_WARNING]       = "W"; // WARNING
    g_log->level2string[LOG_NOTICE]        = "N"; // NOTICE
    g_log->level2string[LOG_INFO]          = "I"; //INFO
    g_log->level2string[LOG_DEBUG]         = "D"; // DEBUG
    g_log->level2string[LOG_FILE]          = "F"; // file
    g_log->level2string[LOG_TRACE]         = "T"; // TRACE
353

354
    g_log->onlinelog = 1; //online log file
355
    g_log->syslog = 0;
356
357
358
    g_log->filelog   = 0;
    g_log->level  = LOG_TRACE;
    g_log->flag   = LOG_LOW;
359

360
#ifndef RTAI
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
    g_log->config.remote_ip      = 0;
    g_log->config.remote_level   = LOG_EMERG;
    g_log->config.facility       = LOG_LOCAL7;
    g_log->config.audit_ip       = 0;
    g_log->config.audit_facility = LOG_LOCAL6;
    g_log->config.format         = 0x00; // online debug inactive

    g_log->filelog_name = "/tmp/openair.log";

    if (g_log->syslog) {
        openlog(g_log->log_component[EMU].name, LOG_PID, g_log->config.facility);
    }
    if (g_log->filelog) {
        gfd = open(g_log->filelog_name, O_WRONLY | O_CREAT, 0666);
    }
    // could put a loop here to check for all comps
    for (i=MIN_LOG_COMPONENTS; i < MAX_LOG_COMPONENTS; i++) {
        if (g_log->log_component[i].filelog == 1 ) {
            g_log->log_component[i].fd = open(g_log->log_component[i].filelog_name,
                                              O_WRONLY | O_CREAT | O_APPEND, 0666);
        }
    }
383
#else
384
385
386
    g_log->syslog = 0;
    g_log->filelog   = 0;
    rtf_create (FIFO_PRINTF_NO, FIFO_PRINTF_SIZE);
387
388
#endif

389
390
#ifdef USER_MODE
    printf("log init done\n");
391
#else
392
    printk("log init done\n");
393
394
#endif

395
    return 0;
396
397
}

398
399
400
401
402
403
404
405
406
407
408
409
410
//log record: add to a list
void logRecord(const char *file, const char *func, int line,  int comp,
               int level, char *format, ...)
{
    va_list    args;
    LOG_params log_params;
    int        len;

    va_start(args, format);
    len = vsnprintf(log_params.l_buff_info, MAX_LOG_INFO-1, format, args);
    va_end(args);

    //2 first parameters must be passed as 'const' to the thread function
411
412
    log_params.file = strdup(file);
    log_params.func = strdup(func);
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
    log_params.line = line;
    log_params.comp = comp;
    log_params.level = level;
    log_params.format = format;
    log_params.len = len;

    if (pthread_mutex_lock(&log_lock) != 0) {
        return;
    }

    log_list_tail++;
    log_list[log_list_tail - 1] = log_params;
    if (log_list_tail >= 1000) {
        log_list_tail = 0;
    }
    if (log_list_nb_elements < 1000) {
        log_list_nb_elements++;
    }
    if(pthread_cond_signal(&log_notify) != 0) {
        return;
    }

    if(pthread_mutex_unlock(&log_lock) != 0) {
        return;
    }

    //log = malloc(sizeof(LOG_elt));
    //log->next = NULL;
    //log->log_params = log_params;
    /* Add log task to queue */
    //log_list_add_tail_eurecom(log, &log_list);
444
445
446
447
448

}

void logRecord_thread_safe(const char *file, const char *func,
                           int line,  int comp, int level,
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
                           int len, const char *params_string)
{
    log_component_t *c;
    int total_len = 0;
    char log_buffer[MAX_LOG_TOTAL];

    c = &g_log->log_component[comp];

    // do not apply filtering for LOG_F
    // only log messages which are enabled and are below the global log level and component's level threshold
    if ((level != LOG_FILE) && ((c->level > g_log->level) ||
        (level > c->level) || (level > g_log->level)))
    {
        return;
    }
464

465
466
    vcd_signal_dumper_dump_function_by_name(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD,
                                            VCD_FUNCTION_IN);
467

468
469
470
471
472
473
    // adjust syslog level for TRACE messages
    if (g_log->syslog) {
        if (g_log->level > LOG_DEBUG) {
            g_log->level = LOG_DEBUG;
        }
    }
474

475
476
477
478
479
480
481
482
483
    // make sure that for log trace the extra info is only printed once, reset when the level changes
    if ((level == LOG_FILE) ||  (c->flag == LOG_NONE)  || (level ==LOG_TRACE )) {
        total_len = snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - 1, "%s",
                             params_string);
    } else {
        if ((g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR)) {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "%s",
                                  log_level_highlight_start[level]);
        }
484

485
486
487
488
        if ((g_log->flag & FLAG_COMP) || (c->flag & FLAG_COMP) ) {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s]",
                                  g_log->log_component[comp].name);
        }
489

490
491
492
493
        if ((g_log->flag & FLAG_LEVEL) || (c->flag & FLAG_LEVEL)) {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s]",
                                  g_log->level2string[level]);
        }
494

495
496
497
498
        if ((g_log->flag & FLAG_FUNCT) || (c->flag & FLAG_FUNCT)) {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s] ",
                                  func);
        }
499

500
501
502
503
        if ((g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) )  {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s:%d]",
                                  file, line);
        }
504

505
506
        len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - len, "%s",
                        params_string);
507

508
509
510
511
        if ((g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR)) {
            total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "%s",
                                  log_level_highlight_end[level]);
        }
512
513
    }

514
515
516
517
518
519
520
521
522
523
524
525
    // OAI printf compatibility
    if ((g_log->onlinelog == 1) && (level != LOG_FILE)) {
#ifdef RTAI
        if (len > MAX_LOG_TOTAL) {
            rt_printk ("[OPENAIR] FIFO_PRINTF WROTE OUTSIDE ITS MEMORY BOUNDARY : ERRORS WILL OCCUR\n");
        }
        if (len > 0) {
            rtf_put (FIFO_PRINTF_NO, log_buffer, len);
        }
#else
        fprintf(stdout, "%s", log_buffer);
#endif
526
527
    }

528
529
530
#ifndef RTAI
    if (g_log->syslog) {
        syslog(g_log->level, "%s", log_buffer);
531
    }
532
    if (g_log->filelog) {
winckel's avatar
winckel committed
533
534
535
      if (write(gfd, log_buffer, total_len) < total_len) {
        // TODO assert ?
      }
536
537
    }
    if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) {
winckel's avatar
winckel committed
538
539
540
      if (write(g_log->log_component[comp].fd, log_buffer, total_len) < total_len) {
        // TODO assert ?
      }
541
    }
542
#endif
543

544
545
    vcd_signal_dumper_dump_function_by_name(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD,
                                            VCD_FUNCTION_OUT);
546
547
}

548
549
550
#if !defined(LOG_NO_THREAD)
void *log_thread_function(void *list)
{
551

552
    LOG_params log_params;
553

554
    for(;;) {
555

556
        //log_elt = NULL;
557

558
559
        /* Lock must be taken to wait on conditional variable */
        pthread_mutex_lock(&log_lock);
560

561
562
        /* Wait on condition variable, check for spurious wakeups.
           When returning from pthread_cond_wait(), we own the lock. */
563

564
565
566
567
568
569
570
571
        // sleep
        while((log_list_nb_elements == 0) && (log_shutdown == 0)) {
            pthread_cond_wait(&log_notify, &log_lock);
        }
        // exit
        if ((log_shutdown==1) && (log_list_nb_elements == 0)) {
            break;
        }
572

573
574
575
576
577
578
579
580
        /* Grab our task */
        //log_elt = log_list_remove_head(&log_list);
        log_params = log_list[log_list_head];
        log_list_head++;
        log_list_nb_elements--;
        if (log_list_head >= 1000) {
            log_list_head = 0;
        }
581
582


583
584
        /* Unlock */
        pthread_mutex_unlock(&log_lock);
585

586
587
588
589
590
591
592
593
        /* Get to work */
        logRecord_thread_safe(log_params.file,
                              log_params.func,
                              log_params.line,
                              log_params.comp,
                              log_params.level,
                              log_params.len,
                              log_params.l_buff_info);
594

595
596
597
598
        //free(log_elt);
    }
}
#endif
599

600
601
602
603
604
605
606
//log record, format, and print:  executed in the main thread (mt)
void logRecord_mt(const char *file, const char *func, int line, int comp,
                  int level, char *format, ...)
{
    int len = 0;
    va_list args;
    log_component_t *c;
607
608
    char *log_start;
    char *log_end;
609
610
611
612
613

    c = &g_log->log_component[comp];

    // do not apply filtering for LOG_F
    // only log messages which are enabled and are below the global log level and component's level threshold
614
    if ((level != LOG_FILE) && ((level > c->level) && (level > g_log->level))) {
615
        return;
616
    }
617
618
619
620
621
622
623
624
625
626
627

    vcd_signal_dumper_dump_function_by_name(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD,
                                            VCD_FUNCTION_IN);

    va_start(args, format);

    // adjust syslog level for TRACE messages
    if (g_log->syslog) {
        if (g_log->level > LOG_DEBUG) {
            g_log->level = LOG_DEBUG;
        }
628
629
    }

630
631
    // make sure that for log trace the extra info is only printed once, reset when the level changes
    if ((level == LOG_FILE) || (c->flag == LOG_NONE) || (level == LOG_TRACE)) {
632
        log_start = c->log_buffer;
633
        len = vsnprintf(c->log_buffer, MAX_LOG_TOTAL-1, format, args);
634
635
        log_end = c->log_buffer + len;
   } else {
636
637
638
639
        if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "%s",
                            log_level_highlight_start[level]);
        }
640
        log_start = c->log_buffer + len;
641
642
643
644
645

        if ( (g_log->flag & FLAG_COMP) || (c->flag & FLAG_COMP) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s]",
                            g_log->log_component[comp].name);
        }
646

647
648
649
650
        if ( (g_log->flag & FLAG_LEVEL) || (c->flag & FLAG_LEVEL) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s]",
                            g_log->level2string[level]);
        }
651

652
653
654
655
        if ( (g_log->flag & FLAG_FUNCT) || (c->flag & FLAG_FUNCT) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s] ",
                            func);
        }
656

657
658
659
660
        if ( (g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "[%s:%d]",
                            file, line);
        }
661

662
        len += vsnprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, format, args);
663
        log_end = c->log_buffer + len;
664

665
666
667
668
669
670
671
672
673
674
        if ( (g_log->flag & FLAG_COLOR) || (c->flag & FLAG_COLOR) ) {
            len += snprintf(&c->log_buffer[len], MAX_LOG_TOTAL - len, "%s",
                            log_level_highlight_end[level]);
        }
    }

    va_end(args);

    // OAI printf compatibility
    if ((g_log->onlinelog == 1) && (level != LOG_FILE))
675
#ifdef RTAI
676
677
678
679
680
681
        if (len > MAX_LOG_TOTAL) {
            rt_printk ("[OPENAIR] FIFO_PRINTF WROTE OUTSIDE ITS MEMORY BOUNDARY : ERRORS WILL OCCUR\n");
        }
    if (len > 0) {
        rtf_put (FIFO_PRINTF_NO, c->log_buffer, len);
    }
682
#else
winckel's avatar
winckel committed
683
        fwrite(c->log_buffer, len, 1, stdout);
684
685
686
#endif

#ifndef RTAI
687
688
689
690
    if (g_log->syslog) {
        syslog(g_log->level, "%s", c->log_buffer);
    }
    if (g_log->filelog) {
winckel's avatar
winckel committed
691
692
693
      if (write(gfd, c->log_buffer, len) < len){
        // TODO assert ?
      }
694
695
    }
    if ((g_log->log_component[comp].filelog) && (level == LOG_FILE)) {
winckel's avatar
winckel committed
696
697
698
      if (write(g_log->log_component[comp].fd, c->log_buffer, len) < len) {
        // TODO assert ?
      }
699
    }
700
701
#endif

702
#if defined(ENABLE_ITTI)
703
    if (level <= LOG_DEBUG)
704
    {
705
        task_id_t origin_task_id = TASK_UNKNOWN;
706
707
708
709
710
711
712
        MessagesIds messages_id;
        MessageDef *message_p;
        size_t      message_string_size;
        char       *message_msg_p;

        message_string_size = log_end - log_start;

713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
#if !defined(DISABLE_ITTI_DETECT_SUB_TASK_ID)
        /* Try to identify sub task ID from log information (comp, log_instance_type) */
        switch (comp)
        {
          case PHY:
            switch (log_instance_type)
            {
              case LOG_INSTANCE_ENB:
                origin_task_id = TASK_PHY_ENB;
                break;

              case LOG_INSTANCE_UE:
                origin_task_id = TASK_PHY_UE;
                break;

              default:
                break;
            }
            break;

          case MAC:
            switch (log_instance_type)
            {
              case LOG_INSTANCE_ENB:
                origin_task_id = TASK_MAC_ENB;
                break;

              case LOG_INSTANCE_UE:
                origin_task_id = TASK_MAC_UE;

              default:
                break;
            }
           break;

          case RLC:
            switch (log_instance_type)
            {
              case LOG_INSTANCE_ENB:
                origin_task_id = TASK_RLC_ENB;
                break;

              case LOG_INSTANCE_UE:
                origin_task_id = TASK_RLC_UE;

              default:
                break;
            }
            break;

          case PDCP:
            switch (log_instance_type)
            {
              case LOG_INSTANCE_ENB:
                origin_task_id = TASK_PDCP_ENB;
                break;

              case LOG_INSTANCE_UE:
                origin_task_id = TASK_PDCP_UE;

              default:
                break;
            }
            break;

          default:
            break;
        }
#endif

783
        switch (level)
784
        {
785
786
787
788
          case LOG_EMERG:
          case LOG_ALERT:
          case LOG_CRIT:
          case LOG_ERR:
789
            messages_id = ERROR_LOG;
790
791
792
            break;

          case LOG_WARNING:
793
            messages_id = WARNING_LOG;
794
795
796
797
798
799
800
801
802
803
804
805
806
            break;

          case LOG_NOTICE:
            messages_id = NOTICE_LOG;
            break;

          case LOG_INFO:
            messages_id = INFO_LOG;
            break;

          default:
            messages_id = DEBUG_LOG;
            break;
807
        }
808
        message_p = itti_alloc_new_message_sized(origin_task_id, messages_id, message_string_size);
809
        switch (level)
810
        {
811
812
813
814
          case LOG_EMERG:
          case LOG_ALERT:
          case LOG_CRIT:
          case LOG_ERR:
815
            message_msg_p = (char *) &message_p->ittiMsg.error_log;
816
817
818
            break;

          case LOG_WARNING:
819
            message_msg_p = (char *) &message_p->ittiMsg.warning_log;
820
821
822
            break;

          case LOG_NOTICE:
823
            message_msg_p = (char *) &message_p->ittiMsg.notice_log;
824
825
826
            break;

          case LOG_INFO:
827
            message_msg_p = (char *) &message_p->ittiMsg.info_log;
828
829
830
            break;

          default:
831
            message_msg_p = (char *) &message_p->ittiMsg.debug_log;
832
            break;
833
834
835
836
837
838
839
        }
        memcpy(message_msg_p, log_start, message_string_size);

        itti_send_msg_to_task(TASK_UNKNOWN, INSTANCE_DEFAULT, message_p);
    }
#endif

840
841
    vcd_signal_dumper_dump_function_by_name(VCD_SIGNAL_DUMPER_FUNCTIONS_LOG_RECORD,
                                            VCD_FUNCTION_OUT);
842
}
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867

int set_log(int component, int level, int interval)
{
    /* Checking parameters */
    DevCheck((component >= MIN_LOG_COMPONENTS) && (component < MAX_LOG_COMPONENTS),
             component, MIN_LOG_COMPONENTS, MAX_LOG_COMPONENTS);
    DevCheck((level <= LOG_TRACE) && (level >= LOG_EMERG), level, LOG_TRACE,
             LOG_EMERG);
    DevCheck((interval > 0) && (interval <= 0xFF), interval, 0, 0xFF);

    g_log->log_component[component].level = level;

    switch (level) {
        case LOG_TRACE:
            g_log->log_component[component].flag = LOG_MED ;
            break;
        case LOG_DEBUG:
            g_log->log_component[component].flag = LOG_MED ;
            break;
        case LOG_INFO:
            g_log->log_component[component].flag = LOG_LOW ;
            break;
        default:
            g_log->log_component[component].flag = LOG_NONE ;
            break;
868
    }
869
870
871

    g_log->log_component[component].interval = interval;

872
873
874
    return 0;
}

875
876
877
878
879
880
881
882
883
884
885
886
887
int set_comp_log(int component, int level, int verbosity, int interval)
{
    /* Checking parameters */
    DevCheck((component >= MIN_LOG_COMPONENTS) && (component < MAX_LOG_COMPONENTS),
             component, MIN_LOG_COMPONENTS, MAX_LOG_COMPONENTS);
    DevCheck((level <= LOG_TRACE) && (level >= LOG_EMERG), level, LOG_TRACE,
             LOG_EMERG);
    DevCheck((interval > 0) && (interval <= 0xFF), interval, 0, 0xFF);

    if ((verbosity == LOG_NONE) || (verbosity == LOG_LOW) ||
            (verbosity == LOG_MED) || (verbosity == LOG_FULL) ||
            (verbosity == LOG_HIGH)) {
        g_log->log_component[component].flag = verbosity;
888
    }
889
890
891
892

    g_log->log_component[component].level = level;
    g_log->log_component[component].interval = interval;

893
894
895
    return 0;
}

896
897
898
899
void set_glog(int level, int verbosity)
{
    g_log->level = level;
    g_log->flag = verbosity;
900
}
901
902
903
void set_glog_syslog(int enable)
{
    g_log->syslog = enable;
904
}
905
906
907
void set_glog_onlinelog(int enable)
{
    g_log->onlinelog = enable;
908
}
909
910
911
void set_glog_filelog(int enable)
{
    g_log->filelog = enable;
912
913
}

914
915
916
917
918
919
920
921
922
923
void set_component_filelog(int comp)
{

    if (g_log->log_component[comp].filelog ==  0) {
        g_log->log_component[comp].filelog =  1;
        if (g_log->log_component[comp].fd == 0) {
            g_log->log_component[comp].fd = open(g_log->log_component[comp].filelog_name,
                                                 O_WRONLY | O_CREAT | O_TRUNC, 0666);
        }
    }
924
925
926
927
928
929
930
}

/*
 * for the two functions below, the passed array must have a final entry
 * with string value NULL
 */
/* map a string to an int. Takes a mapping array and a string as arg */
931
932
int map_str_to_int(mapping *map, const char *str)
{
933
934
935
936
937
938
939
940
941
942
943
944
    while (1) {
        if (map->name == NULL) {
            return(-1);
        }
        if (!strcmp(map->name, str)) {
            return(map->value);
        }
        map++;
    }
}

/* map an int to a string. Takes a mapping array and a value */
945
946
char *map_int_to_str(mapping *map, int val)
{
947
948
949
950
951
952
953
954
955
956
    while (1) {
        if (map->name == NULL) {
            return NULL;
        }
        if (map->value == val) {
            return map->name;
        }
        map++;
    }
}
957
958
959

int is_newline( char *str, int size)
{
960
961
    int i;
    for (  i = 0; i < size; i++ ) {
962
963
964
        if ( str[i] == '\n' ) {
            return 1;
        }
965
966
967
968
    }
    /* if we get all the way to here, there must not have been a newline! */
    return 0;
}
969
970
971

void logClean (void)
{
972
#ifdef RTAI
973
    rtf_destroy (FIFO_PRINTF_NO);
974
#else
winckel's avatar
winckel committed
975
976
    int i;

977
978
979
980
981
982
983
984
985
986
987
    if (g_log->syslog) {
        closelog();
    }
    if (g_log->filelog) {
        close(gfd);
    }
    for (i=MIN_LOG_COMPONENTS; i < MAX_LOG_COMPONENTS; i++) {
        if (g_log->log_component[i].filelog) {
            close(g_log->log_component[i].fd);
        }
    }
988
989
990
991
#endif

}

992
993
994
995
996
997
998
#if defined(ENABLE_ITTI)
void log_set_instance_type (log_instance_type_t instance)
{
    log_instance_type = instance;
}
#endif

999
1000
#ifdef LOG_TEST

1001
1002
int main(int argc, char *argv[])
{
1003

1004
    logInit();
1005

1006
1007
1008
1009
    //set_log_syslog(1);
    test_log();

    return 1;
1010
1011
}

1012
1013
1014
1015
1016
1017
1018
1019
1020
1021
1022
1023
1024
1025
1026
1027
1028
1029
1030
1031
1032
1033
1034
1035
1036
1037
1038
1039
1040
1041
1042
1043
1044
1045
1046
1047
1048
1049
1050
1051
1052
1053
1054
1055
1056
1057
1058
1059
1060
1061
1062
1063
1064
1065
1066
1067
1068
1069
1070
1071
1072
1073
1074
1075
1076
int test_log(void)
{
    LOG_ENTER(MAC); // because the default level is DEBUG
    LOG_I(EMU, "1 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_D(MAC, "1 debug  MAC \n");
    LOG_N(MAC, "1 notice MAC \n");
    LOG_W(MAC, "1 warning MAC \n");

    set_comp_log(EMU, LOG_INFO, FLAG_ONLINE);
    set_comp_log(MAC, LOG_WARNING, 0);

    LOG_I(EMU, "2 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_E(MAC, "2 emerge MAC\n");
    LOG_D(MAC, "2 debug  MAC \n");
    LOG_N(MAC, "2 notice MAC \n");
    LOG_W(MAC, "2 warning MAC \n");
    LOG_I(MAC, "2 info MAC \n");


    set_comp_log(MAC, LOG_NOTICE, 1);

    LOG_ENTER(MAC);
    LOG_I(EMU, "3 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_D(MAC, "3 debug  MAC \n");
    LOG_N(MAC, "3 notice MAC \n");
    LOG_W(MAC, "3 warning MAC \n");
    LOG_I(MAC, "3 info MAC \n");

    set_comp_log(MAC, LOG_DEBUG,1);
    set_comp_log(EMU, LOG_DEBUG,1);

    LOG_ENTER(MAC);
    LOG_I(EMU, "4 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_D(MAC, "4 debug  MAC \n");
    LOG_N(MAC, "4 notice MAC \n");
    LOG_W(MAC, "4 warning MAC \n");
    LOG_I(MAC, "4 info MAC \n");


    set_comp_log(MAC, LOG_DEBUG,0);
    set_comp_log(EMU, LOG_DEBUG,0);

    LOG_I(LOG, "5 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_D(MAC, "5 debug  MAC \n");
    LOG_N(MAC, "5 notice MAC \n");
    LOG_W(MAC, "5 warning MAC \n");
    LOG_I(MAC, "5 info MAC \n");


    set_comp_log(MAC, LOG_TRACE,0X07F);
    set_comp_log(EMU, LOG_TRACE,0X07F);

    LOG_ENTER(MAC);
    LOG_I(LOG, "6 Starting OAI logs version %s Build date: %s on %s\n",
          BUILD_VERSION, BUILD_DATE, BUILD_HOST);
    LOG_D(MAC, "6 debug  MAC \n");
    LOG_N(MAC, "6 notice MAC \n");
    LOG_W(MAC, "6 warning MAC \n");
    LOG_I(MAC, "6 info MAC \n");
    LOG_EXIT(MAC);
1077

1078
    return 0;
1079
1080
}
#endif