OpenLMI tracing facility

[Jan Synacek]

I've been trying trying to implement the SELinux provider for a while
now. It is written in C and it uses the new job manager. So far, I've
only had to implement jobs in storage, which is python, and that was
relatively easy compared to all the detail that has to be taken care of
in C.

This complexity, and the fact that debugging it is pretty hard, led me
to an idea...

I suggest that all the providers (I'm now mainly concerned about
openlmi-providers) have a common, unified tracing facility. We should be
able to turn it on as the lowest logging level and it should trace
entrance/exit of all functions. This would make debugging and
pinpointing failures much easier.

#define lmi_trace_in lmi_debug("==> %s", __PRETTY_FUNCTION__);
#define lmi_trace_out lmi_debug("<== %s", __PRETTY_FUNCTION__);
#define lmi_trace_out_rc(rc) lmi_debug("<== %s (rc=%d)", __PRETTY_FUNCTION__,
rc);

Every function would look like:

void function()
{
        lmi_trace_in

        stuff();

        lmi_trace_out /* or lmi_trace_out_rc(rc) where relevant */
}

Note that "lmi_debug" could be replaced with something like
"lmi_trace",
which would be defined via CMPI bindings to be even lower level than
"lmi_debug".

Suggestions and constructive criticism welcome.

-- 
Jan Synacek
Software Engineer, Red Hat

[Michal Minář]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 07/11/2014 01:54 PM, Jan Synacek wrote:
I like this idea. See my notes embedded below.
>  
>  I've been trying trying to implement the SELinux provider for a
>  while now. It is written in C and it uses the new job manager. So
>  far, I've only had to implement jobs in storage, which is python,
>  and that was relatively easy compared to all the detail that has to
>  be taken care of in C.
>  
>  This complexity, and the fact that debugging it is pretty hard, led
>  me to an idea...
>  
>  I suggest that all the providers (I'm now mainly concerned about 
>  openlmi-providers) have a common, unified tracing facility. We
>  should be able to turn it on as the lowest logging level and it
>  should trace entrance/exit of all functions. This would make
>  debugging and pinpointing failures much easier.
>  
>  #define lmi_trace_in lmi_debug("==> %s", __PRETTY_FUNCTION__); 
>  #define lmi_trace_out lmi_debug("<== %s", __PRETTY_FUNCTION__); 
>  #define lmi_trace_out_rc(rc) lmi_debug("<== %s (rc=%d)",
>  __PRETTY_FUNCTION__, rc); 
Plain RC is a little bit misleading when used in
functions returning
anything else than CMStatus. Boolean return value is such a case (1
usually means success and 0 failure). Quite the contrary to CMStatus.rc.
Perhaps above tracing functions could be extended with:

  #define lmi_trace_out_bool(val) lmi_debug("<== %s (res=%s)", \
        __PRETTY_FUNCTION__, val ? "true" : "false");
  #define lmi_trace_out_status(status) lmi_debug("<== %s (rc=%d (%s),
msg=%s)", \
        __PRETTY_FUNCTION__, status.rc, _rc_names[status.rc], status.msg);

I also find very useful having information about executing thread
embedded in tracing message. Dbus providers tend to be multithreaded and
sometimes it is hard to deduce the flow of execution when outputs of
multiple threads are mixed together.

>  
>  Every function would look like:
>  
>  void function() { lmi_trace_in
>  
>  stuff();
>  
>  lmi_trace_out /* or lmi_trace_out_rc(rc) where relevant */ }
>  
>  Note that "lmi_debug" could be replaced with something like
>  "lmi_trace", which would be defined via CMPI bindings to be even
>  lower level than "lmi_debug". 
I vote for lmi_trace() method. Tracing
methods shouldn't be mixed with
debug ones. Let's have another logging levels for them. We could also
reuse tracing levels from our python providers:

    INFO > DEBUG > TRACE_WARNING > TRACE_INFO > TRACE_VERBOSE

Commonly used levels (ERROR, WARNING, INFO, DEBUG) are handled with
CMLogMessage(), while the tracing ones with CMTraceMessage(). Broker
then allows for fine-grained logging setup to filter out uninteresting
messages.

I'm in favor of following our python logging pattern. We could use the
same configuration templates for our C and python providers and thus
avoid a risk of confusing our users.
>  
>  Suggestions and constructive criticism welcome.
>   
Michal M.
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1
> Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
>
> iQEcBAEBAgAGBQJTv+CmAAoJEPezUylxRFUD4woH/iEQIXkhZywb0Pf+fs49Vc9l
> UqY8kxtU+CGQHzz/LdnRPlVBmdAP6IAYtT70JL3R6IN/fRC2XVsEHCS5cscaBW9Q
> O/6XHA2s6i195dqJlPe74LIRNGXDFPJCaKupNbXedWge92sN7yw2buaiPw//vhLt
> MSaRecHySm5/I7MbgeeUyebqfUKygEpxpzWTIP5tXPIxD1Tfp4YeKpSMnbGMm1mu
> RTtT8o2kncwiPj2vOX/W/gA+CDdGlHWD8mUHm6PLBkYj7engsuOu88fZ8+pOaIKv
> a97L+16pvmcpn65XsIqop+LVN1TPGDtZYKEEAW1JiZAyxn1cqK4fBZIKdOgieW0=
> =zD0p
> -----END PGP SIGNATURE-----

[Jan Synacek]

Michal Minář <miminar(a)redhat.com&gt; writes:
>  -----BEGIN PGP SIGNED MESSAGE-----
>  Hash: SHA1
>
>  On 07/11/2014 01:54 PM, Jan Synacek wrote:
>  I like this idea. See my notes embedded below.
> > 
> > I've been trying trying to implement the SELinux provider for a
> > while now. It is written in C and it uses the new job manager. So
> > far, I've only had to implement jobs in storage, which is python,
> > and that was relatively easy compared to all the detail that has to
> > be taken care of in C.
> > 
> > This complexity, and the fact that debugging it is pretty hard, led
> > me to an idea...
> > 
> > I suggest that all the providers (I'm now mainly concerned about 
> > openlmi-providers) have a common, unified tracing facility. We
> > should be able to turn it on as the lowest logging level and it
> > should trace entrance/exit of all functions. This would make
> > debugging and pinpointing failures much easier.
> > 
> > #define lmi_trace_in lmi_debug("==> %s", __PRETTY_FUNCTION__); 
> > #define lmi_trace_out lmi_debug("<== %s", __PRETTY_FUNCTION__); 
> > #define lmi_trace_out_rc(rc) lmi_debug("<== %s (rc=%d)",
> > __PRETTY_FUNCTION__, rc);
>  Plain RC is a little bit misleading when used in functions returning
>  anything else than CMStatus. Boolean return value is such a case (1
>  usually means success and 0 failure). Quite the contrary to CMStatus.rc.
>  Perhaps above tracing functions could be extended with:
>
>    #define lmi_trace_out_bool(val) lmi_debug("<== %s (res=%s)", \
>          __PRETTY_FUNCTION__, val ? "true" : "false");
>    #define lmi_trace_out_status(status) lmi_debug("<== %s (rc=%d (%s),
>  msg=%s)", \
>          __PRETTY_FUNCTION__, status.rc, _rc_names[status.rc], status.msg);
>  
Even better, we could treat the plain rc as the plain rc and have
CMPIStatus.rc displayed as its symbolic name. That would remove the
confusion and provide more useful piece of information.

>  I also find very useful having information about executing thread
>  embedded in tracing message. Dbus providers tend to be multithreaded and
>  sometimes it is hard to deduce the flow of execution when outputs of
>  multiple threads are mixed together. 
I agree. I don't know how to do this, though, I will have to check.

> > Every function would look like:
> > 
> > void function() { lmi_trace_in
> > 
> > stuff();
> > 
> > lmi_trace_out /* or lmi_trace_out_rc(rc) where relevant */ }
> > 
> > Note that "lmi_debug" could be replaced with something like
> > "lmi_trace", which would be defined via CMPI bindings to be even
> > lower level than "lmi_debug".
>  I vote for lmi_trace() method. Tracing methods shouldn't be mixed with
>  debug ones. Let's have another logging levels for them. We could also
>  reuse tracing levels from our python providers:
>
>      INFO > DEBUG > TRACE_WARNING > TRACE_INFO > TRACE_VERBOSE
>
>  Commonly used levels (ERROR, WARNING, INFO, DEBUG) are handled with
>  CMLogMessage(), while the tracing ones with CMTraceMessage(). Broker
>  then allows for fine-grained logging setup to filter out uninteresting
>  messages. 
After thinking about it for the second time, tracing is a subset of
debugging (at least that's how I see it), so lmi_trace may not be
needed. If we agreed on using it nonetheless, I suggest only one level
of tracing, because I don't see any reason to use three distinct tracing
levels. That's just confusing and overkill.

>  I'm in favor of following our python logging pattern. We could
> use the
>  same configuration templates for our C and python providers and thus
>  avoid a risk of confusing our users. 
I'm for unifying logging as well. However, I disagree with three trace
levels as written above.

> > Suggestions and constructive criticism welcome.
>
>  Michal M.
> >  -----BEGIN PGP SIGNATURE-----
> >  Version: GnuPG v1
> >  Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
> >
> >  iQEcBAEBAgAGBQJTv+CmAAoJEPezUylxRFUD4woH/iEQIXkhZywb0Pf+fs49Vc9l
> >  UqY8kxtU+CGQHzz/LdnRPlVBmdAP6IAYtT70JL3R6IN/fRC2XVsEHCS5cscaBW9Q
> >  O/6XHA2s6i195dqJlPe74LIRNGXDFPJCaKupNbXedWge92sN7yw2buaiPw//vhLt
> >  MSaRecHySm5/I7MbgeeUyebqfUKygEpxpzWTIP5tXPIxD1Tfp4YeKpSMnbGMm1mu
> >  RTtT8o2kncwiPj2vOX/W/gA+CDdGlHWD8mUHm6PLBkYj7engsuOu88fZ8+pOaIKv
> >  a97L+16pvmcpn65XsIqop+LVN1TPGDtZYKEEAW1JiZAyxn1cqK4fBZIKdOgieW0=
> >  =zD0p
> >  -----END PGP SIGNATURE----- 
>  
-- 
Jan Synacek
Software Engineer, Red Hat

[Frank Ch. Eigler]

jsynacek wrote:

>  [...]  I suggest that all the providers (I'm now mainly
> concerned
>  about openlmi-providers) have a common, unified tracing facility. We
>  should be able to turn it on as the lowest logging level and it
>  should trace entrance/exit of all functions. This would make
>  debugging and pinpointing failures much easier. [...] 
You might find on-demand dynamic tracing with a tool such as perf or
systemtap can do this particular job, without manual instrumentation.
(If you do wish to compile in tracing code, I'd recommend KISS; maybe
consider systemtap <sys/sdt.h> markers that gdb can trace too.)

- FChE

[Jan Synacek]

"Frank Ch. Eigler" <fche(a)redhat.com&gt; writes:

>  jsynacek wrote:
>
> > [...]  I suggest that all the providers (I'm now mainly concerned
> > about openlmi-providers) have a common, unified tracing facility. We
> > should be able to turn it on as the lowest logging level and it
> > should trace entrance/exit of all functions. This would make
> > debugging and pinpointing failures much easier. [...]
>
>  You might find on-demand dynamic tracing with a tool such as perf or
>  systemtap can do this particular job, without manual instrumentation.
>  (If you do wish to compile in tracing code, I'd recommend KISS; maybe
>  consider systemtap <sys/sdt.h> markers that gdb can trace too.)
>
>  - FChE 
I'll try those locally, thanks!

In my original post, I should have also mentioned that the goal should
also be to provide a trace in production -- in my opinion, it's good to
see the trace in logs together with everything else if need be.

-- 
Jan Synacek
Software Engineer, Red Hat

[Robin Hack]

Hi Jan.

I just dug around in samba source codes (I saw lot of backtrace output
in logs) and I found this:

http://www.gnu.org/software/libc/manual/html_node/Backtraces.html

Also:
http://www.nongnu.org/libunwind/man/libunwind(3).html
I'm not sure if libunwind is right for you.

Have nice day.
Robin Hack

On Mon, Jul 14, 2014 at 09:49:48AM +0200, Jan Synacek wrote:
>  "Frank Ch. Eigler" <fche(a)redhat.com&gt; writes:
>  
>  > jsynacek wrote:
>  >
>  >> [...]  I suggest that all the providers (I'm now mainly concerned
>  >> about openlmi-providers) have a common, unified tracing facility. We
>  >> should be able to turn it on as the lowest logging level and it
>  >> should trace entrance/exit of all functions. This would make
>  >> debugging and pinpointing failures much easier. [...]
>  >
>  > You might find on-demand dynamic tracing with a tool such as perf or
>  > systemtap can do this particular job, without manual instrumentation.
>  > (If you do wish to compile in tracing code, I'd recommend KISS; maybe
>  > consider systemtap <sys/sdt.h> markers that gdb can trace too.)
>  >
>  > - FChE
>  
>  I'll try those locally, thanks!
>  
>  In my original post, I should have also mentioned that the goal should
>  also be to provide a trace in production -- in my opinion, it's good to
>  see the trace in logs together with everything else if need be.
>  
>  -- 
>  Jan Synacek
>  Software Engineer, Red Hat
>  _______________________________________________
>  openlmi-devel mailing list
>  openlmi-devel(a)lists.fedorahosted.org
>  https://lists.fedorahosted.org/mailman/listinfo/openlmi-devel