xref: /third_party/libwebsockets/lib/core/logs.c (revision d4afb5ce) 
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)
32void lwsl_emit_optee(int level, const char *line);
33#endif
34
35lws_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)
45static const char * log_level_names ="EWNIDPHXCLUT??";
46#endif
47
48/*
49 * Name an instance tag and attach to a group
50 */
51
52void
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
141void
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
162void
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
196const char *
197lws_lc_tag(lws_lifecycle_t *lc)
198{
199	return lc->gutag;
200}
201
202
203int
204lwsl_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
246#if defined(LWS_PLAT_FREERTOS)
247		n += lws_snprintf(p + n, len - n, "%6u: ",
248#if defined(LWS_AMAZON_RTOS)
249				  (unsigned int)xPortGetFreeHeapSize());
250#else
251				  (unsigned int)esp_get_free_heap_size());
252#endif
253#endif
254
255		return n;
256	}
257#else
258	p[0] = '\0';
259#endif
260
261	return 0;
262}
263
264#ifndef LWS_PLAT_OPTEE
265static const char * const colours[] = {
266	"[31;1m", /* LLL_ERR */
267	"[36;1m", /* LLL_WARN */
268	"[35;1m", /* LLL_NOTICE */
269	"[32;1m", /* LLL_INFO */
270	"[34;1m", /* LLL_DEBUG */
271	"[33;1m", /* LLL_PARSER */
272	"[33m", /* LLL_HEADER */
273	"[33m", /* LLL_EXT */
274	"[33m", /* LLL_CLIENT */
275	"[33;1m", /* LLL_LATENCY */
276        "[0;1m", /* LLL_USER */
277	"[31m", /* LLL_THREAD */
278};
279
280static char tty;
281
282static void
283_lwsl_emit_stderr(int level, const char *line)
284{
285	int n, m = LWS_ARRAY_SIZE(colours) - 1;
286
287	if (!tty)
288		tty = (char)(isatty(2) | 2);
289
290	if (tty == 3) {
291		n = 1 << (LWS_ARRAY_SIZE(colours) - 1);
292		while (n) {
293			if (level & n)
294				break;
295			m--;
296			n >>= 1;
297		}
298		fprintf(stderr, "%c%s%s%c[0m", 27, colours[m], line, 27);
299	} else
300		fprintf(stderr, "%s", line);
301}
302
303void
304lwsl_emit_stderr(int level, const char *line)
305{
306	_lwsl_emit_stderr(level, line);
307}
308
309void
310lwsl_emit_stderr_notimestamp(int level, const char *line)
311{
312	_lwsl_emit_stderr(level, line);
313}
314
315#if !defined(LWS_PLAT_FREERTOS) && !defined(LWS_PLAT_OPTEE)
316
317/*
318 * Helper to emit to a file
319 */
320
321void
322lws_log_emit_cx_file(struct lws_log_cx *cx, int level, const char *line,
323			size_t len)
324{
325	int fd = (int)(intptr_t)cx->stg;
326
327	if (fd >= 0)
328		if (write(fd, line, (unsigned int)len) != (ssize_t)len)
329			fprintf(stderr, "Unable to write log to file\n");
330}
331
332/*
333 * Helper to use a .refcount_cb to store logs in a file
334 */
335
336void
337lws_log_use_cx_file(struct lws_log_cx *cx, int _new)
338{
339	int fd;
340
341	if (_new > 0 && cx->refcount == 1) {
342		fd = open((const char *)cx->opaque,
343				LWS_O_CREAT | LWS_O_TRUNC | LWS_O_WRONLY, 0600);
344		if (fd < 0)
345			fprintf(stderr, "Unable to open log %s: errno %d\n",
346				(const char *)cx->opaque, errno);
347		cx->stg = (void *)(intptr_t)fd;
348
349		return;
350	}
351
352	fd = (int)(intptr_t)cx->stg;
353
354	if (_new <= 0 && cx->refcount == 0 && fd >= 0) {
355		close(fd);
356		cx->stg = (void *)(intptr_t)-1;
357	}
358}
359
360#endif
361
362#endif
363
364#if !(defined(LWS_PLAT_OPTEE) && !defined(LWS_WITH_NETWORK))
365void
366__lws_logv(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
367	   int filter, const char *_fun, const char *format, va_list vl)
368{
369#if LWS_MAX_SMP == 1 && !defined(LWS_WITH_THREADPOOL)
370	/* this is incompatible with multithreaded logging */
371	static char buf[256];
372#else
373	char buf[1024];
374#endif
375	char *p = buf, *end = p + sizeof(buf) - 1;
376	lws_log_cx_t *cxp;
377	int n, back = 0;
378
379	/*
380	 * We need to handle NULL wsi etc at the wrappers as gracefully as
381	 * possible
382	 */
383
384	if (!cx) {
385		lws_strncpy(p, "NULL log cx: ", sizeof(buf) - 1);
386		p += 13;
387		/* use the processwide one for lack of anything better */
388		cx = &log_cx;
389	}
390
391	cxp = cx;
392
393	if (!(cx->lll_flags & (uint32_t)filter))
394		/*
395		 * logs may be produced and built in to the code but disabled
396		 * at runtime
397		 */
398		return;
399
400#if !defined(LWS_LOGS_TIMESTAMP)
401	if (cx->lll_flags & LLLF_LOG_TIMESTAMP)
402#endif
403	{
404		buf[0] = '\0';
405		lwsl_timestamp(filter, buf, sizeof(buf));
406		p += strlen(buf);
407	}
408
409	/*
410	 * prepend parent log ctx content first
411	 * top level cx also gets an opportunity to prepend
412	 */
413
414	while (cxp->parent) {
415		cxp = cxp->parent;
416		back++;
417	}
418
419	do {
420		int b = back;
421
422		cxp = cx;
423		while (b--)
424			cxp = cxp->parent;
425		if (cxp->prepend)
426			cxp->prepend(cxp, NULL, &p, end);
427
428		back--;
429	} while (back > 0);
430
431	if (prep)
432		prep(cxp, obj, &p, end);
433
434	if (_fun)
435		p += lws_snprintf(p, lws_ptr_diff_size_t(end, p), "%s: ", _fun);
436
437	/*
438	 * The actual log content
439	 */
440
441	n = vsnprintf(p, lws_ptr_diff_size_t(end, p), format, vl);
442
443	/* vnsprintf returns what it would have written, even if truncated */
444	if (p + n > end - 2) {
445		p = end - 5;
446		*p++ = '.';
447		*p++ = '.';
448		*p++ = '.';
449		*p++ = '\n';
450		*p++ = '\0';
451	} else
452		if (n > 0) {
453			p += n;
454			if (p[-1] != '\n')
455				*p++ = '\n';
456			*p = '\0';
457		}
458
459	/*
460	 * The actual emit
461	 */
462
463	if (cx->lll_flags & LLLF_LOG_CONTEXT_AWARE)
464		cx->u.emit_cx(cx, filter, buf, lws_ptr_diff_size_t(p, buf));
465	else
466		cx->u.emit(filter, buf);
467}
468
469void _lws_logv(int filter, const char *format, va_list vl)
470{
471	__lws_logv(&log_cx, NULL, NULL, filter, NULL, format, vl);
472}
473
474void _lws_log(int filter, const char *format, ...)
475{
476	va_list ap;
477
478	va_start(ap, format);
479	__lws_logv(&log_cx, NULL, NULL, filter, NULL, format, ap);
480	va_end(ap);
481}
482
483void _lws_log_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
484		 int filter, const char *_fun, const char *format, ...)
485{
486	va_list ap;
487
488	if (!cx)
489		cx = &log_cx;
490
491	va_start(ap, format);
492	__lws_logv(cx, prep, obj, filter, _fun, format, ap);
493	va_end(ap);
494}
495#endif
496
497void
498lws_set_log_level(int flags, lws_log_emit_t func)
499{
500	log_cx.lll_flags = (uint32_t)(flags & (~LLLF_LOG_CONTEXT_AWARE));
501
502	if (func)
503		log_cx.u.emit = func;
504}
505
506int lwsl_visible(int level)
507{
508	return !!(log_cx.lll_flags & (uint32_t)level);
509}
510
511int lwsl_visible_cx(lws_log_cx_t *cx, int level)
512{
513	return !!(cx->lll_flags & (uint32_t)level);
514}
515
516void
517lwsl_refcount_cx(lws_log_cx_t *cx, int _new)
518{
519#if LWS_MAX_SMP > 1
520	volatile lws_log_cx_t *vcx = (volatile lws_log_cx_t *)cx;
521#endif
522
523	if (!cx)
524		return;
525
526#if LWS_MAX_SMP > 1
527	if (!vcx->inited) {
528		vcx->inited = 1;
529		lws_pthread_mutex_init(&cx->refcount_lock);
530		vcx->inited = 2;
531	}
532	while (vcx->inited != 2)
533		;
534	lws_pthread_mutex_lock(&cx->refcount_lock);
535#endif
536
537	if (_new > 0)
538		cx->refcount++;
539	else {
540		assert(cx->refcount);
541		cx->refcount--;
542	}
543
544	if (cx->refcount_cb)
545		cx->refcount_cb(cx, _new);
546
547#if LWS_MAX_SMP > 1
548	lws_pthread_mutex_unlock(&cx->refcount_lock);
549#endif
550}
551
552void
553lwsl_hexdump_level_cx(lws_log_cx_t *cx, lws_log_prepend_cx_t prep, void *obj,
554		      int hexdump_level, const void *vbuf, size_t len)
555{
556	unsigned char *buf = (unsigned char *)vbuf;
557	unsigned int n;
558
559	if (!lwsl_visible_cx(cx, hexdump_level))
560		return;
561
562	if (!len) {
563		_lws_log_cx(cx, prep, obj, hexdump_level, NULL,
564					"(hexdump: zero length)\n");
565		return;
566	}
567
568	if (!vbuf) {
569		_lws_log_cx(cx, prep, obj, hexdump_level, NULL,
570					"(hexdump: NULL ptr)\n");
571		return;
572	}
573
574	_lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n");
575
576	for (n = 0; n < len;) {
577		unsigned int start = n, m;
578		char line[80], *p = line;
579
580		p += lws_snprintf(p, 10, "%04X: ", start);
581
582		for (m = 0; m < 16 && n < len; m++)
583			p += lws_snprintf(p, 5, "%02X ", buf[n++]);
584		while (m++ < 16)
585			p += lws_snprintf(p, 5, "   ");
586
587		p += lws_snprintf(p, 6, "   ");
588
589		for (m = 0; m < 16 && (start + m) < len; m++) {
590			if (buf[start + m] >= ' ' && buf[start + m] < 127)
591				*p++ = (char)buf[start + m];
592			else
593				*p++ = '.';
594		}
595		while (m++ < 16)
596			*p++ = ' ';
597
598		*p++ = '\n';
599		*p = '\0';
600		_lws_log_cx(cx, prep, obj, hexdump_level, NULL, "%s", line);
601		(void)line;
602	}
603
604	_lws_log_cx(cx, prep, obj, hexdump_level, NULL, "\n");
605}
606
607void
608lwsl_hexdump_level(int hexdump_level, const void *vbuf, size_t len)
609{
610	lwsl_hexdump_level_cx(&log_cx, NULL, NULL, hexdump_level, vbuf, len);
611}
612
613void
614lwsl_hexdump(const void *vbuf, size_t len)
615{
616#if defined(_DEBUG)
617	lwsl_hexdump_level(LLL_DEBUG, vbuf, len);
618#endif
619}
620