[weston,v5,06/14] compositor: offer logs via weston-debug

Submitted by Daniel Stone on July 20, 2018, 7:03 p.m.

Details

Message ID 20180720190335.23880-7-daniels@collabora.com
State Superseded
Headers show
Series "weston-debug API and tool" ( rev: 2 1 ) in Wayland

Not browsing as part of any series.

Commit Message

Daniel Stone July 20, 2018, 7:03 p.m.
From: Pekka Paalanen <pq@iki.fi>

This registers a new weston-debug scope "log" through which one can get
live log output interspersed with possible other debugging prints.

Signed-off-by: Pekka Paalanen <pq@iki.fi>

pass the log_scope to weston_debug_scope_timestamp API to append
the scope name to the timestamp

Signed-off-by: Maniraj Devadoss <Maniraj.Devadoss@in.bosch.com>
Reviewed-by: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
Reviewed-by: Daniel Stone <daniels@collabora.com>
---
 compositor/main.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

Patch hide | download patch | download mbox

diff --git a/compositor/main.c b/compositor/main.c
index 2f34e1115..eaf4cf381 100644
--- a/compositor/main.c
+++ b/compositor/main.c
@@ -119,6 +119,7 @@  struct wet_compositor {
 };
 
 static FILE *weston_logfile = NULL;
+static struct weston_debug_scope *log_scope;
 
 static int cached_tm_mday = -1;
 
@@ -149,9 +150,16 @@  static int weston_log_timestamp(void)
 static void
 custom_handler(const char *fmt, va_list arg)
 {
+	char timestr[128];
+
 	weston_log_timestamp();
 	fprintf(weston_logfile, "libwayland: ");
 	vfprintf(weston_logfile, fmt, arg);
+
+	weston_debug_scope_printf(log_scope, "%s libwayland: ",
+			weston_debug_scope_timestamp(log_scope,
+			timestr, sizeof timestr));
+	weston_debug_scope_vprintf(log_scope, fmt, arg);
 }
 
 static void
@@ -183,6 +191,14 @@  static int
 vlog(const char *fmt, va_list ap)
 {
 	int l;
+	char timestr[128];
+
+	if (weston_debug_scope_is_enabled(log_scope)) {
+		weston_debug_scope_printf(log_scope, "%s ",
+				weston_debug_scope_timestamp(log_scope,
+				timestr, sizeof timestr));
+		weston_debug_scope_vprintf(log_scope, fmt, ap);
+	}
 
 	l = weston_log_timestamp();
 	l += vfprintf(weston_logfile, fmt, ap);
@@ -193,6 +209,8 @@  vlog(const char *fmt, va_list ap)
 static int
 vlog_continue(const char *fmt, va_list argp)
 {
+	weston_debug_scope_vprintf(log_scope, fmt, argp);
+
 	return vfprintf(weston_logfile, fmt, argp);
 }
 
@@ -2490,6 +2508,9 @@  int main(int argc, char *argv[])
 	}
 	segv_compositor = wet.compositor;
 
+	log_scope = weston_compositor_add_debug_scope(wet.compositor, "log",
+			"Weston and Wayland log\n", NULL, NULL);
+
 	if (debug_protocol)
 		weston_compositor_enable_debug_protocol(wet.compositor);
 
@@ -2602,6 +2623,7 @@  out:
 	/* free(NULL) is valid, and it won't be NULL if it's used */
 	free(wet.parsed_options);
 
+	weston_debug_scope_destroy(log_scope);
 	weston_compositor_destroy(wet.compositor);
 
 out_signals:

Comments

On Fri, 20 Jul 2018 20:03:27 +0100
Daniel Stone <daniels@collabora.com> wrote:

> From: Pekka Paalanen <pq@iki.fi>
> 
> This registers a new weston-debug scope "log" through which one can get
> live log output interspersed with possible other debugging prints.
> 
> Signed-off-by: Pekka Paalanen <pq@iki.fi>
> 
> pass the log_scope to weston_debug_scope_timestamp API to append
> the scope name to the timestamp
> 
> Signed-off-by: Maniraj Devadoss <Maniraj.Devadoss@in.bosch.com>
> Reviewed-by: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
> Reviewed-by: Daniel Stone <daniels@collabora.com>
> ---
>  compositor/main.c | 22 ++++++++++++++++++++++
>  1 file changed, 22 insertions(+)
> 
> diff --git a/compositor/main.c b/compositor/main.c
> index 2f34e1115..eaf4cf381 100644
> --- a/compositor/main.c
> +++ b/compositor/main.c

> @@ -2490,6 +2508,9 @@ int main(int argc, char *argv[])
>  	}
>  	segv_compositor = wet.compositor;
>  
> +	log_scope = weston_compositor_add_debug_scope(wet.compositor, "log",
> +			"Weston and Wayland log\n", NULL, NULL);
> +
>  	if (debug_protocol)
>  		weston_compositor_enable_debug_protocol(wet.compositor);
>  
> @@ -2602,6 +2623,7 @@ out:
>  	/* free(NULL) is valid, and it won't be NULL if it's used */
>  	free(wet.parsed_options);
>  
> +	weston_debug_scope_destroy(log_scope);

Maybe log_scope should be set to NULL again, in case
weston_compositor_destroy() logs something.

>  	weston_compositor_destroy(wet.compositor);
>  
>  out_signals:

Otherwise still good.


Thanks,
pq
On Mon, 6 Aug 2018 14:20:51 +0300
Pekka Paalanen <ppaalanen@gmail.com> wrote:

> On Fri, 20 Jul 2018 20:03:27 +0100
> Daniel Stone <daniels@collabora.com> wrote:
> 
> > From: Pekka Paalanen <pq@iki.fi>
> > 
> > This registers a new weston-debug scope "log" through which one can get
> > live log output interspersed with possible other debugging prints.
> > 
> > Signed-off-by: Pekka Paalanen <pq@iki.fi>
> > 
> > pass the log_scope to weston_debug_scope_timestamp API to append
> > the scope name to the timestamp
> > 
> > Signed-off-by: Maniraj Devadoss <Maniraj.Devadoss@in.bosch.com>
> > Reviewed-by: Pekka Paalanen <pekka.paalanen@collabora.co.uk>
> > Reviewed-by: Daniel Stone <daniels@collabora.com>
> > ---
> >  compositor/main.c | 22 ++++++++++++++++++++++
> >  1 file changed, 22 insertions(+)
> > 
> > diff --git a/compositor/main.c b/compositor/main.c
> > index 2f34e1115..eaf4cf381 100644
> > --- a/compositor/main.c
> > +++ b/compositor/main.c  
> 
> > @@ -2490,6 +2508,9 @@ int main(int argc, char *argv[])
> >  	}
> >  	segv_compositor = wet.compositor;
> >  
> > +	log_scope = weston_compositor_add_debug_scope(wet.compositor, "log",
> > +			"Weston and Wayland log\n", NULL, NULL);
> > +
> >  	if (debug_protocol)
> >  		weston_compositor_enable_debug_protocol(wet.compositor);
> >  
> > @@ -2602,6 +2623,7 @@ out:
> >  	/* free(NULL) is valid, and it won't be NULL if it's used */
> >  	free(wet.parsed_options);
> >  
> > +	weston_debug_scope_destroy(log_scope);  
> 
> Maybe log_scope should be set to NULL again, in case
> weston_compositor_destroy() logs something.

Hi,

I may have hit that, here's a backtrace from drm-backend:

Core was generated by `weston --debug'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007fb517596657 in __strlen_avx2 () from /lib64/libc.so.6
(gdb) bt
#0  0x00007fb517596657 in __strlen_avx2 () from /lib64/libc.so.6
#1  0x00007fb51748339b in vfprintf () from /lib64/libc.so.6
#2  0x00007fb517543be9 in __vsnprintf_chk () from /lib64/libc.so.6
#3  0x00007fb517543b1d in __snprintf_chk () from /lib64/libc.so.6
#4  0x00007fb518cd5a08 in snprintf (__fmt=0x7fb518cdb6db "[%s.%03ld][%s]", __n=128, 
    __s=0x7ffe718ca4e0 "[2018-08-07 15:03:25.484][(\026\265\177") at /usr/include/bits/stdio2.h:64
#5  weston_debug_scope_timestamp (scope=0x558d51518770, buf=0x7ffe718ca4e0 "[2018-08-07 15:03:25.484][(\026\265\177", 
    len=128) at /home/pq/git/weston/libweston/weston-debug.c:717
#6  0x0000558d504f5788 in vlog (fmt=0x7ffe718ca5e0 "event2  - Video Bus: device removed\n", ap=0x7ffe718caa30)
    at /home/pq/git/weston/compositor/main.c:198
#7  0x00007fb517d5fbb6 in log_msg_va (libinput=0x558d51680600, priority=LIBINPUT_LOG_PRIORITY_INFO, 
    format=0x7ffe718ca5e0 "event2  - Video Bus: device removed\n", args=0x7ffe718caa30) at ../src/libinput.c:266
#8  0x00007fb517d67b47 in evdev_log_msg_va (device=0x558d516ad1b0, priority=LIBINPUT_LOG_PRIORITY_INFO, 
    format=0x7fb517d91789 "device removed\n", args=0x7ffe718caa30) at ../src/evdev.h:680
#9  0x00007fb517d67c1f in evdev_log_msg (device=0x558d516ad1b0, priority=LIBINPUT_LOG_PRIORITY_INFO, 
    format=0x7fb517d91789 "device removed\n") at ../src/evdev.h:693
#10 0x00007fb517d6ce45 in evdev_device_remove (device=0x558d516ad1b0) at ../src/evdev.c:2489
#11 0x00007fb517d8ce3c in udev_input_remove_devices (input=0x558d51680600) at ../src/udev-seat.c:203
#12 0x00007fb517d8cf24 in udev_input_disable (libinput=0x558d51680600) at ../src/udev-seat.c:222
#13 0x00007fb517d65241 in libinput_suspend (libinput=0x558d51680600) at ../src/libinput.c:2821
#14 0x00007fb517d63023 in libinput_unref (libinput=0x558d51680600) at ../src/libinput.c:1752
#15 0x00007fb51652f340 in udev_input_destroy (input=input@entry=0x558d5151faf8)
    at /home/pq/git/weston/libweston/libinput-seat.c:373
#16 0x00007fb516529607 in drm_destroy (ec=0x558d51517f30) at /home/pq/git/weston/libweston/compositor-drm.c:6429
#17 0x00007fb518cc4a59 in weston_compositor_destroy (compositor=0x558d51517f30)
    at /home/pq/git/weston/libweston/compositor.c:6925
#18 0x0000558d504f3c55 in main (argc=<optimized out>, argv=<optimized out>)
    at /home/pq/git/weston/compositor/main.c:2752


#5  weston_debug_scope_timestamp (scope=0x558d51518770, buf=0x7ffe718ca4e0 "[2018-08-07 15:03:25.484][(\026\265\177", 
    len=128) at /home/pq/git/weston/libweston/weston-debug.c:717
717			snprintf(buf, len, "[%s.%03ld][%s]", string,
(gdb) print *scope
$1 = {
  name = 0x80100016c <error: Cannot access memory at address 0x80100016c>, 
  desc = 0x980000001d <error: Cannot access memory at address 0x980000001d>, 
  begin_cb = 0x21006f0101, 
  user_data = 0x6572662f67726f2f, 
  stream_list = {
    prev = 0x706f746b73656465, 
    next = 0x2f316e69676f6c2f
  }, 
  compositor_link = {
    prev = 0x2f6e6f6973736573, 
    next = 0x32
  }
}

That looks like it might be the scope already destroyed and dangling.


> >  	weston_compositor_destroy(wet.compositor);
> >  
> >  out_signals:  
> 
> Otherwise still good.


Thanks,
pq