1 /*
2 * libwebsockets - small server side websockets and web server implementation
3 *
4 * Copyright (C) 2010 - 2021 Andy Green <andy@warmcat.com>
5 *
6 * Permission is hereby granted, free of charge, to any person obtaining a copy
7 * of this software and associated documentation files (the "Software"), to
8 * deal in the Software without restriction, including without limitation the
9 * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or
10 * sell copies of the Software, and to permit persons to whom the Software is
11 * furnished to do so, subject to the following conditions:
12 *
13 * The above copyright notice and this permission notice shall be included in
14 * all copies or substantial portions of the Software.
15 *
16 * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
17 * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
18 * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
19 * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
20 * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
21 * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS
22 * IN THE SOFTWARE.
23 */
24
25 #include "private-lib-core.h"
26
27 #ifdef LWS_HAVE_SYS_TYPES_H
28 #include <sys/types.h>
29 #endif
30
31 #if defined(LWS_PLAT_OPTEE)
32 void lwsl_emit_optee(int level, const char *line);
33 #endif
34
35 lws_log_cx_t log_cx = {
36 #if !defined(LWS_PLAT_OPTEE)
37 .u.emit = lwsl_emit_stderr,
38 #else
39 .u.emit = lwsl_emit_optee,
40 #endif
41 .lll_flags = LLL_ERR | LLL_WARN | LLL_NOTICE,
42 };
43
44 #if !defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NO_LOGS)
45 static const char * log_level_names ="EWNIDPHXCLUT??";
46 #endif
47
48 /*
49 * Name an instance tag and attach to a group
50 */
51
52 void
__lws_lc_tag(struct lws_context * context,lws_lifecycle_group_t * grp,lws_lifecycle_t * lc,const char * format,...)53 __lws_lc_tag(struct lws_context *context, lws_lifecycle_group_t *grp,
54 lws_lifecycle_t *lc, const char *format, ...)
55 {
56 va_list ap;
57 int n = 1;
58
59 if (*lc->gutag == '[') {
60 /* appending inside [] */
61
62 char *cp = strchr(lc->gutag, ']');
63 char rend[96];
64 size_t ll, k;
65 int n;
66
67 if (!cp)
68 return;
69
70 /* length of closing brace and anything else after it */
71 k = strlen(cp);
72
73 /* compute the remaining gutag unused */
74 ll = sizeof(lc->gutag) - lws_ptr_diff_size_t(cp, lc->gutag) - k - 1;
75 if (ll > sizeof(rend) - 1)
76 ll = sizeof(rend) - 1;
77 va_start(ap, format);
78 n = vsnprintf(rend, ll, format, ap);
79 va_end(ap);
80
81 if ((unsigned int)n > ll)
82 n = (int)ll;
83
84 /* shove the trailer up by what we added */
85 memmove(cp + n, cp, k);
86 assert(k + (unsigned int)n < sizeof(lc->gutag));
87 cp[k + (unsigned int)n] = '\0';
88 /* copy what we added into place */
89 memcpy(cp, rend, (unsigned int)n);
90
91 return;
92 }
93
94 assert(grp);
95 assert(grp->tag_prefix); /* lc group must have a tag prefix string */
96
97 lc->gutag[0] = '[';
98
99 #if defined(LWS_WITH_SECURE_STREAMS_PROXY_API) /* ie, will have getpid if set */
100 n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) -
101 (unsigned int)n - 1u, "%u|", getpid());
102 #endif
103 n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) -
104 (unsigned int)n - 1u, "%s|%lx|",
105 grp->tag_prefix,
106 (unsigned long)grp->ordinal++);
107
108 va_start(ap, format);
109 n += vsnprintf(&lc->gutag[n], sizeof(lc->gutag) - (unsigned int)n -
110 1u, format, ap);
111 va_end(ap);
112
113 if (n < (int)sizeof(lc->gutag) - 2) {
114 lc->gutag[n++] = ']';
115 lc->gutag[n++] = '\0';
116 } else {
117 lc->gutag[sizeof(lc->gutag) - 2] = ']';
118 lc->gutag[sizeof(lc->gutag) - 1] = '\0';
119 }
120
121 lc->us_creation = (uint64_t)lws_now_usecs();
122 lws_dll2_add_tail(&lc->list, &grp->owner);
123
124 lwsl_refcount_cx(lc->log_cx, 1);
125
126 #if defined(LWS_LOG_TAG_LIFECYCLE)
127 lwsl_cx_notice(context, " ++ %s (%d)", lc->gutag, (int)grp->owner.count);
128 #endif
129 }
130
131 /*
132 * Normally we want to set the tag one time at creation. But sometimes we
133 * don't have enough information at that point to give it a meaningful tag, eg,
134 * it's an accepted, served connection but we haven't read data from it yet
135 * to find out what it wants to be.
136 *
137 * This allows you to append some extra info to the tag in those cases, the
138 * initial tag remains the same on the lhs so it can be tracked correctly.
139 */
140
141 void
__lws_lc_tag_append(lws_lifecycle_t * lc,const char * app)142 __lws_lc_tag_append(lws_lifecycle_t *lc, const char *app)
143 {
144 int n = (int)strlen(lc->gutag);
145
146 if (n && lc->gutag[n - 1] == ']')
147 n--;
148
149 n += lws_snprintf(&lc->gutag[n], sizeof(lc->gutag) - 2u -
150 (unsigned int)n, "|%s]", app);
151
152 if ((unsigned int)n >= sizeof(lc->gutag) - 2u) {
153 lc->gutag[sizeof(lc->gutag) - 2] = ']';
154 lc->gutag[sizeof(lc->gutag) - 1] = '\0';
155 }
156 }
157
158 /*
159 * Remove instance from group
160 */
161
162 void
__lws_lc_untag(struct lws_context * context,lws_lifecycle_t * lc)163 __lws_lc_untag(struct lws_context *context, lws_lifecycle_t *lc)
164 {
165 //lws_lifecycle_group_t *grp;
166 char buf[24];
167
168 if (!lc->gutag[0]) { /* we never tagged this object... */
169 lwsl_cx_err(context, "%s never tagged", lc->gutag);
170 assert(0);
171 return;
172 }
173
174 if (!lc->list.owner) { /* we already untagged this object... */
175 lwsl_cx_err(context, "%s untagged twice", lc->gutag);
176 assert(0);
177 return;
178 }
179
180 //grp = lws_container_of(lc->list.owner, lws_lifecycle_group_t, owner);
181
182 lws_humanize(buf, sizeof(buf),
183 (uint64_t)lws_now_usecs() - lc->us_creation,
184 humanize_schema_us);
185
186 #if defined(LWS_LOG_TAG_LIFECYCLE)
187 lwsl_cx_notice(context, " -- %s (%d) %s", lc->gutag,
188 (int)lc->list.owner->count - 1, buf);
189 #endif
190
191 lws_dll2_remove(&lc->list);
192
193 lwsl_refcount_cx(lc->log_cx, -1);
194 }
195
196 const char *
lws_lc_tag(lws_lifecycle_t * lc)197 lws_lc_tag(lws_lifecycle_t *lc)
198 {
199 return lc->gutag;
200 }
201
202
203 int
lwsl_timestamp(int level,char * p,size_t len)204 lwsl_timestamp(int level, char *p, size_t len)
205 {
206 #if !defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NO_LOGS)
207 time_t o_now;
208 unsigned long long now;
209 struct timeval tv;
210 struct tm *ptm = NULL;
211 #if defined(LWS_HAVE_LOCALTIME_R)
212 struct tm tm;
213 #endif
214 int n;
215
216 gettimeofday(&tv, NULL);
217 o_now = tv.tv_sec;
218 now = ((unsigned long long)tv.tv_sec * 10000) +
219 (unsigned int)(tv.tv_usec / 100);
220
221 #if defined(LWS_HAVE_LOCALTIME_R)
222 ptm = localtime_r(&o_now, &tm);
223 #else
224 ptm = localtime(&o_now);
225 #endif
226 p[0] = '\0';
227 for (n = 0; n < LLL_COUNT; n++) {
228 if (level != (1 << n))
229 continue;
230
231 if (ptm)
232 n = lws_snprintf(p, len,
233 "[%04d/%02d/%02d %02d:%02d:%02d:%04d] %c: ",
234 ptm->tm_year + 1900,
235 ptm->tm_mon + 1,
236 ptm->tm_mday,
237 ptm->tm_hour,
238 ptm->tm_min,
239 ptm->tm_sec,
240 (int)(now % 10000), log_level_names[n]);
241 else
242 n = lws_snprintf(p, len, "[%llu:%04d] %c: ",
243 (unsigned long long) now / 10000,
244 (int)(now % 10000), log_level_names[n]);
245 return n;
246 }
247 #else
248 p[0] = '\0';
249 #endif
250
251 return 0;
252 }
253
254 #ifndef LWS_PLAT_OPTEE
255 static const char * const colours[] = {
256 "[31;1m", /* LLL_ERR */
257 "[36;1m", /* LLL_WARN */
258 "[35;1m", /* LLL_NOTICE */
259 "[32;1m", /* LLL_INFO */
260 "[34;1m", /* LLL_DEBUG */
261 "[33;1m", /* LLL_PARSER */
262 "[33m", /* LLL_HEADER */
263 "[33m", /* LLL_EXT */
264 "[33m", /* LLL_CLIENT */
265 "[33;1m", /* LLL_LATENCY */
266 "[0;1m", /* LLL_USER */
267 "[31m", /* LLL_THREAD */
268 };
269
270 static char tty;
271
272 static void
_lwsl_emit_stderr(int level,const char * line)273 _lwsl_emit_stderr(int level, const char *line)
274 {
275 int n, m = LWS_ARRAY_SIZE(colours) - 1;
276
277 if (!tty)
278 tty = (char)(isatty(2) | 2);
279
280 if (tty == 3) {
281 n = 1 << (LWS_ARRAY_SIZE(colours) - 1);
282 while (n) {
283 if (level & n)
284 break;
285 m--;
286 n >>= 1;
287 }
288 fprintf(stderr, "%c%s%s%c[0m", 27, colours[m], line, 27);
289 } else
290 fprintf(stderr, "%s", line);
291 }
292
293 void
lwsl_emit_stderr(int level,const char * line)294 lwsl_emit_stderr(int level, const char *line)
295 {
296 _lwsl_emit_stderr(level, line);
297 }
298
299 void
lwsl_emit_stderr_notimestamp(int level,const char * line)300 lwsl_emit_stderr_notimestamp(int level, const char *line)
301 {
302 _lwsl_emit_stderr(level, line);
303 }
304
305 #if !defined(LWS_PLAT_FREERTOS) && !defined(LWS_PLAT_OPTEE)
306
307 /*
308 * Helper to emit to a file
309 */
310
311 void
lws_log_emit_cx_file(struct lws_log_cx * cx,int level,const char * line,size_t len)312 lws_log_emit_cx_file(struct lws_log_cx *cx, int level, const char *line,
313 size_t len)
314 {
315 int fd = (int)(intptr_t)cx->stg;
316
317 if (fd >= 0)
318 if (write(fd, line, (unsigned int)len) != (ssize_t)len)
319 fprintf(stderr, "Unable to write log to file\n");
320 }
321
322 /*
323 * Helper to use a .refcount_cb to store logs in a file
324 */
325
326 void
lws_log_use_cx_file(struct lws_log_cx * cx,int _new)327 lws_log_use_cx_file(struct lws_log_cx *cx, int _new)
328 {
329 int fd;
330
331 if (_new > 0 && cx->refcount == 1) {
332 fd = open((const char *)cx->opaque,
333 LWS_O_CREAT | LWS_O_TRUNC | LWS_O_WRONLY, 0600);
334 if (fd < 0)
335 fprintf(stderr, "Unable to open log %s: errno %d\n",
336 (const char *)cx->opaque, errno);
337 cx->stg = (void *)(intptr_t)fd;
338
339 return;
340 }
341
342 fd = (int)(intptr_t)cx->stg;
343
344 if (_new <= 0 && cx->refcount == 0 && fd >= 0) {
345 close(fd);
346 cx->stg = (void *)(intptr_t)-1;
347 }
348 }
349
350 #endif
351
352 #endif
353
354 #if !(defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NETWORK))
355 void
__lws_logv(lws_log_cx_t * cx,lws_log_prepend_cx_t prep,void * obj,int filter,const char * _fun,const char * format,va_list vl)356 __lws_logv(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
357 int filter, const char *_fun, const char *format, va_list vl)
358 {
359 #if LWS_MAX_SMP == 1 && !defined(LWS_WITH_THREADPOOL)
360 /* this is incompatible with multithreaded logging */
361 static char buf[256];
362 #else
363 char buf[1024];
364 #endif
365 char *p = buf, *end = p + sizeof(buf) - 1;
366 lws_log_cx_t *cxp;
367 int n, back = 0;
368
369 /*
370 * We need to handle NULL wsi etc at the wrappers as gracefully as
371 * possible
372 */
373
374 if (!cx) {
375 lws_strncpy(p, "NULL log cx: ", sizeof(buf) - 1);
376 p += 13;
377 /* use the processwide one for lack of anything better */
378 cx = &log_cx;
379 }
380
381 cxp = cx;
382
383 if (!(cx->lll_flags & (uint32_t)filter))
384 /*
385 * logs may be produced and built in to the code but disabled
386 * at runtime
387 */
388 return;
389
390 #if !defined(LWS_LOGS_TIMESTAMP)
391 if (cx->lll_flags & LLLF_LOG_TIMESTAMP)
392 #endif
393 {
394 buf[0] = '\0';
395 lwsl_timestamp(filter, buf, sizeof(buf));
396 p += strlen(buf);
397 }
398
399 /*
400 * prepend parent log ctx content first
401 * top level cx also gets an opportunity to prepend
402 */
403
404 while (cxp->parent) {
405 cxp = cxp->parent;
406 back++;
407 }
408
409 do {
410 int b = back;
411
412 cxp = cx;
413 while (b--)
414 cxp = cxp->parent;
415 if (cxp->prepend)
416 cxp->prepend(cxp, NULL, &p, end);
417
418 back--;
419 } while (back > 0);
420
421 if (prep)
422 prep(cxp, obj, &p, end);
423
424 if (_fun)
425 p += lws_snprintf(p, lws_ptr_diff_size_t(end, p), "%s: ", _fun);
426
427 /*
428 * The actual log content
429 */
430
431 n = vsnprintf(p, lws_ptr_diff_size_t(end, p), format, vl);
432
433 /* vnsprintf returns what it would have written, even if truncated */
434 if (p + n > end - 2) {
435 p = end - 5;
436 *p++ = '.';
437 *p++ = '.';
438 *p++ = '.';
439 *p++ = '\n';
440 *p++ = '\0';
441 } else
442 if (n > 0) {
443 p += n;
444 if (p[-1] != '\n')
445 *p++ = '\n';
446 *p = '\0';
447 }
448
449 /*
450 * The actual emit
451 */
452
453 if (cx->lll_flags & LLLF_LOG_CONTEXT_AWARE)
454 cx->u.emit_cx(cx, filter, buf, lws_ptr_diff_size_t(p, buf));
455 else
456 cx->u.emit(filter, buf);
457 }
458
_lws_logv(int filter,const char * format,va_list vl)459 void _lws_logv(int filter, const char *format, va_list vl)
460 {
461 __lws_logv(&log_cx, NULL, NULL, filter, NULL, format, vl);
462 }
463
_lws_log(int filter,const char * format,...)464 void _lws_log(int filter, const char *format, ...)
465 {
466 va_list ap;
467
468 va_start(ap, format);
469 __lws_logv(&log_cx, NULL, NULL, filter, NULL, format, ap);
470 va_end(ap);
471 }
472
_lws_log_cx(lws_log_cx_t * cx,lws_log_prepend_cx_t prep,void * obj,int filter,const char * _fun,const char * format,...)473 void _lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
474 int filter, const char *_fun, const char *format, ...)
475 {
476 va_list ap;
477
478 if (!cx)
479 cx = &log_cx;
480
481 va_start(ap, format);
482 __lws_logv(cx, prep, obj, filter, _fun, format, ap);
483 va_end(ap);
484 }
485 #endif
486
487 void
lws_set_log_level(int flags,lws_log_emit_t func)488 lws_set_log_level(int flags, lws_log_emit_t func)
489 {
490 log_cx.lll_flags = (uint32_t)(flags & (~LLLF_LOG_CONTEXT_AWARE));
491
492 if (func)
493 log_cx.u.emit = func;
494 }
495
lwsl_visible(int level)496 int lwsl_visible(int level)
497 {
498 return !!(log_cx.lll_flags & (uint32_t)level);
499 }
500
lwsl_visible_cx(lws_log_cx_t * cx,int level)501 int lwsl_visible_cx(lws_log_cx_t *cx, int level)
502 {
503 return !!(cx->lll_flags & (uint32_t)level);
504 }
505
506 void
lwsl_refcount_cx(lws_log_cx_t * cx,int _new)507 lwsl_refcount_cx(lws_log_cx_t *cx, int _new)
508 {
509 if (!cx)
510 return;
511
512 if (_new > 0)
513 cx->refcount++;
514 else {
515 assert(cx->refcount);
516 cx->refcount--;
517 }
518
519 if (cx->refcount_cb)
520 cx->refcount_cb(cx, _new);
521 }
522
523 void
lwsl_hexdump_level_cx(lws_log_cx_t * cx,lws_log_prepend_cx_t prep,void * obj,int hexdump_level,const void * vbuf,size_t len)524 lwsl_hexdump_level_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
525 int hexdump_level, const void *vbuf, size_t len)
526 {
527 unsigned char *buf = (unsigned char *)vbuf;
528 unsigned int n;
529
530 if (!lwsl_visible_cx(cx, hexdump_level))
531 return;
532
533 if (!len) {
534 _lws_log_cx(cx, prep, obj, hexdump_level, NULL,
535 "(hexdump: zero length)\n");
536 return;
537 }
538
539 if (!vbuf) {
540 _lws_log_cx(cx, prep, obj, hexdump_level, NULL,
541 "(hexdump: NULL ptr)\n");
542 return;
543 }
544
545 _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n");
546
547 for (n = 0; n < len;) {
548 unsigned int start = n, m;
549 char line[80], *p = line;
550
551 p += lws_snprintf(p, 10, "%04X: ", start);
552
553 for (m = 0; m < 16 && n < len; m++)
554 p += lws_snprintf(p, 5, "%02X ", buf[n++]);
555 while (m++ < 16)
556 p += lws_snprintf(p, 5, " ");
557
558 p += lws_snprintf(p, 6, " ");
559
560 for (m = 0; m < 16 && (start + m) < len; m++) {
561 if (buf[start + m] >= ' ' && buf[start + m] < 127)
562 *p++ = (char)buf[start + m];
563 else
564 *p++ = '.';
565 }
566 while (m++ < 16)
567 *p++ = ' ';
568
569 *p++ = '\n';
570 *p = '\0';
571 _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "%s", line);
572 (void)line;
573 }
574
575 _lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n");
576 }
577
578 void
lwsl_hexdump_level(int hexdump_level,const void * vbuf,size_t len)579 lwsl_hexdump_level(int hexdump_level, const void *vbuf, size_t len)
580 {
581 lwsl_hexdump_level_cx(&log_cx, NULL, NULL, hexdump_level, vbuf, len);
582 }
583
584 void
lwsl_hexdump(const void * vbuf,size_t len)585 lwsl_hexdump(const void *vbuf, size_t len)
586 {
587 #if defined(_DEBUG)
588 lwsl_hexdump_level(LLL_DEBUG, vbuf, len);
589 #endif
590 }
591