[PATCH weston v5 03/14] libweston: add weston_debug API and implementation

[Pekka Paalanen]

On Thu, 23 Aug 2018 17:53:07 +0100
Daniel Stone <daniel at fooishbar.org> wrote:

> Hi Pekka,
> 
> On Mon, 6 Aug 2018 at 12:16, Pekka Paalanen <ppaalanen at gmail.com> wrote:
> > On Fri, 20 Jul 2018 20:03:24 +0100 Daniel Stone <daniels at collabora.com> wrote:  
> > > +/** Format current time as a string
> > > + * and append the debug scope name to it
> > > + *
> > > + * \param scope[in] debug scope.
> > > + * \param buf[out] Buffer to store the string.
> > > + * \param len Available size in the buffer in bytes.
> > > + * \return \c buf
> > > + *
> > > + * Reads the current local wall-clock time and formats it into a string.
> > > + * and append the debug scope name to it.
> > > + * The string is nul-terminated, even if truncated.
> > > + */
> > > +WL_EXPORT char *
> > > +weston_debug_scope_timestamp(struct weston_debug_scope *scope,
> > > +                          char *buf, size_t len)
> > > +{
> > > +     struct timeval tv;
> > > +     struct tm *bdt;
> > > +     char string[128];
> > > +     size_t ret = 0;
> > > +
> > > +     gettimeofday(&tv, NULL);
> > > +
> > > +     bdt = localtime(&tv.tv_sec);
> > > +     if (bdt)
> > > +             ret = strftime(string, sizeof string,
> > > +                            "%Y-%m-%d %H:%M:%S", bdt);
> > > +
> > > +     if (ret > 0)
> > > +             snprintf(buf, len, "[%s.%03ld][%s]", string,
> > > +                      tv.tv_usec / 1000, scope->name);
> > > +     else
> > > +             snprintf(buf, len, "[?][%s]", scope->name);
> > > +
> > > +     return buf;
> > > +}  
> >
> > realized something when looking at the "log" debug scope patch:
> > weston_debug_scope_timestamp() should probably be resilient against
> > scope == NULL, all the other functions already are.
> >
> > weston_log gets initialized early, but the log debug scope gets
> > initialized after the compositor. If something logs something between
> > those two...  
> 
> The users introduced in this patchset already check if the scope is
> enabled, which bails out if the scope is NULL. Given that, and that I
> can't see a sensible behaviour if the scope is NULL, I'm inclined to
> add an assert(scope) at the top of the function as well as
> documentation. Does that seem reasonable? Would assert(scope) be
> better or assert(weston_debug_scope_is_enabled(scope))?

Hi Daniel,

after "compositor: offer logs via weston-debug",
main.c:custom_handler() will call weston_debug_scope_timestamp()
unchecked.

Relying on libwayland not logging anything until the debug scope has
been set up seems a bit too fragile to me.

We could forbid calling weston_debug_scope_timestamp() with NULL scope,
but I think it would be easier if it just accepted NULL by doing
whatever non-crashy. That would be easier for developers. It could
simply replace the scope name with "unknown" for instance. The
resulting string will probably never be used, so it might just make an
empty string too.



On another matter, I've been wondering if storing the debug scopes in
weston_compositor is a good thing. We have the logger initialized
earlier, and quite a lot might happen before weston_compositor is
created. Also the idea of a circular buffer for after-the-fact
reporting might benefit from having debug scopes set up early, and the
command line argument to enable debug scopes from launch.


Thanks,
pq
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 833 bytes
Desc: OpenPGP digital signature
URL: <https://lists.freedesktop.org/archives/wayland-devel/attachments/20180824/4293aa9e/attachment.sig>