• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 
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
265 static 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 
280 static char tty;
281 
282 static void
_lwsl_emit_stderr(int level,const char * line)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 
303 void
lwsl_emit_stderr(int level,const char * line)304 lwsl_emit_stderr(int level, const char *line)
305 {
306 	_lwsl_emit_stderr(level, line);
307 }
308 
309 void
lwsl_emit_stderr_notimestamp(int level,const char * line)310 lwsl_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 
321 void
lws_log_emit_cx_file(struct lws_log_cx * cx,int level,const char * line,size_t len)322 lws_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 
336 void
lws_log_use_cx_file(struct lws_log_cx * cx,int _new)337 lws_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))
365 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)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 
_lws_logv(int filter,const char * format,va_list vl)469 void _lws_logv(int filter, const char *format, va_list vl)
470 {
471 	__lws_logv(&log_cx, NULL, NULL, filter, NULL, format, vl);
472 }
473 
_lws_log(int filter,const char * format,...)474 void _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 
_lws_log_cx(lws_log_cx_t * cx,lws_log_prepend_cx_t prep,void * obj,int filter,const char * _fun,const char * format,...)483 void _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 
497 void
lws_set_log_level(int flags,lws_log_emit_t func)498 lws_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 
lwsl_visible(int level)506 int lwsl_visible(int level)
507 {
508 	return !!(log_cx.lll_flags & (uint32_t)level);
509 }
510 
lwsl_visible_cx(lws_log_cx_t * cx,int level)511 int lwsl_visible_cx(lws_log_cx_t *cx, int level)
512 {
513 	return !!(cx->lll_flags & (uint32_t)level);
514 }
515 
516 void
lwsl_refcount_cx(lws_log_cx_t * cx,int _new)517 lwsl_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 
552 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)553 lwsl_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 
607 void
lwsl_hexdump_level(int hexdump_level,const void * vbuf,size_t len)608 lwsl_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 
613 void
lwsl_hexdump(const void * vbuf,size_t len)614 lwsl_hexdump(const void *vbuf, size_t len)
615 {
616 #if defined(_DEBUG)
617 	lwsl_hexdump_level(LLL_DEBUG, vbuf, len);
618 #endif
619 }
620