how to discover description of error which terminated run

how to discover description of error which terminated run

[John Lumby]

Recently my system tap runs have been terminating abruptly during a run,
(long after the start of the subject workload so not initialisation-related,
 but also long before the workload itself ends)
and printing something like this at the end:

WARNING: Number of errors: 1, skipped probes: 0
WARNING: /usr/local/bin/staprun exited with status: 1
Pass 5: run completed in 20usr/30sys/55140real ms.
Pass 5: run failed.  Try again with another '--vp 00001' option.
Keeping temporary directory "/tmp/stapOlPtXe"

Prior to this it has successfully and correctly printed all the output from all probes
hit till then (they are all user probes by the way  -  I am not using the kprobe)

It has the look of hitting some resource limit but I can't be sure.
How can I get stap to tell me the description of the error which occurred?
(and also of course make it continue )

This is system tap pulled from git yesterday (4 December 2012)
compiled against elfutils-0.152 ,   running under a linux amd-64 3.6.6
 
John Lumby
 		 	   		  

Re: how to discover description of error which terminated run

[Mark Wielaard]

On Wed, Dec 05, 2012 at 12:02:32PM -0500, John Lumby wrote:
> 
> Recently my system tap runs have been terminating abruptly during a run,
> (long after the start of the subject workload so not initialisation-related,
>  but also long before the workload itself ends)
> and printing something like this at the end:
> 
> WARNING: Number of errors: 1, skipped probes: 0
> WARNING: /usr/local/bin/staprun exited with status: 1
> Pass 5: run completed in 20usr/30sys/55140real ms.
> Pass 5: run failed.  Try again with another '--vp 00001' option.
> Keeping temporary directory "/tmp/stapOlPtXe"
> 
> Prior to this it has successfully and correctly printed all the output from all probes
> hit till then (they are all user probes by the way  -  I am not using the kprobe)
> 
> It has the look of hitting some resource limit but I can't be sure.
> How can I get stap to tell me the description of the error which occurred?
> (and also of course make it continue )

It is strange there is no actualy ERROR reported.
Maybe look at dmesg or /var/log/messages output to see if there is
a hint there?
If there was an actual error message, then the following page has
a couple of hints how to get past some resource limit:
http://sourceware.org/systemtap/wiki/TipExhaustedResourceErrors

Cheers,

Mark

Re: how to discover description of error which terminated run

[Frank Ch. Eigler]

Hi -

> >>I believe errors/warnings already go to stderr as opposed to stdout.
> >>I opened PR14927 to make them even more visible.  (Want to give coding
> >>that up a try?  We'll help!)
> 
> I read the Bug Report.    Looks interesting.    I can certainly try.
> Just point me to where the error messages are written.

In the context of staprun/stapio (pass-5 error messages coming from
the running script), they are pretty localised.  

One way would be to change SRC/staprun/common.c function eprintf().
Around we could emit a \033[31m ... \033[m wrapper around the vfprintf(stderr),
but conditional on isatty(stdout-filehandle), and/or a runtime configuration
item such as a SYSTEMTAP_NOCOLOR environment variable.

- FChE

Re: how to discover description of error which terminated run

[johnlumby]

On 12/07/12 05:06, Mark Wielaard wrote:
> On Thu, 2012-12-06 at 18:29 -0500, Frank Ch. Eigler wrote:
>> johnlumby wrote:
>>
>>> [...]  What surprises me is that the run continued for a full 0.1
>>> seconds (over 4000 lines of output) after this message was logged
>>> before it shut itself down.  [...]
>> The intent is not to lose information unnecessarily; the transport of
>> that queued information is lightweight enough not to cause overload.
> That and we prioritize reporting warning/error messages. When there are
> messages from the kernel to user space then warning/errors get reported
> first, even when some other messages might still be pending to make sure
> errors are always presented to the user. Which in this case made it
> harder for the user to spot the error, because we were also able deliver
> all the normal messages after reporting the error... :{
>
>>> [...] Makes me wonder  -  is there some way of directing error
>>> messages such as this to some other channel rather than interspersing
>>> them into the run output.   Or else at least making them more distinctive.

I checked how  I was running stap and now I see I was re-directing 
stderr to stdout !
So it was my fault I missed it.      I will switch to using tee for 
stderr in future
and that should solve it.

>> I believe errors/warnings already go to stderr as opposed to stdout.
>> I opened PR14927 to make them even more visible.  (Want to give coding
>> that up a try?  We'll help!)

I read the Bug Report.    Looks interesting.    I can certainly try.
Just point me to where the error messages are written.

> O, color coded error/warnings! Nice idea.
>
> Thanks,
>
> Mark
>
>
>

Re: how to discover description of error which terminated run

[Mark Wielaard]

On Thu, 2012-12-06 at 18:29 -0500, Frank Ch. Eigler wrote:
> johnlumby wrote:
> 
> > [...]  What surprises me is that the run continued for a full 0.1
> > seconds (over 4000 lines of output) after this message was logged
> > before it shut itself down.  [...]
> 
> The intent is not to lose information unnecessarily; the transport of
> that queued information is lightweight enough not to cause overload.

That and we prioritize reporting warning/error messages. When there are
messages from the kernel to user space then warning/errors get reported
first, even when some other messages might still be pending to make sure
errors are always presented to the user. Which in this case made it
harder for the user to spot the error, because we were also able deliver
all the normal messages after reporting the error... :{

> >[...] Makes me wonder  -  is there some way of directing error
> > messages such as this to some other channel rather than interspersing
> > them into the run output.   Or else at least making them more distinctive.
> 
> I believe errors/warnings already go to stderr as opposed to stdout.
> I opened PR14927 to make them even more visible.  (Want to give coding
> that up a try?  We'll help!)

O, color coded error/warnings! Nice idea.

Thanks,

Mark

Re: how to discover description of error which terminated run

[Frank Ch. Eigler]

johnlumby wrote:

> [...]  What surprises me is that the run continued for a full 0.1
> seconds (over 4000 lines of output) after this message was logged
> before it shut itself down.  [...]

The intent is not to lose information unnecessarily; the transport of
that queued information is lightweight enough not to cause overload.

>[...] Makes me wonder  -  is there some way of directing error
> messages such as this to some other channel rather than interspersing
> them into the run output.   Or else at least making them more distinctive.

I believe errors/warnings already go to stderr as opposed to stdout.
I opened PR14927 to make them even more visible.  (Want to give coding
that up a try?  We'll help!)


- FChE

Re: how to discover description of error which terminated run

[John Lumby]

Mark Wielaard wrote:
> 
> > It has the look of hitting some resource limit but I can't be sure.
> > How can I get stap to tell me the description of the error which occurred?
> > (and also of course make it continue )
> 
> It is strange there is no actualy ERROR reported.
> Maybe look at dmesg or /var/log/messages output to see if there is
> a hint there?
> If there was an actual error message, then the following page has
> a couple of hints how to get past some resource limit:
> http://sourceware.org/systemtap/wiki/TipExhaustedResourceErrors
> 
> Cheers,
> 
> Mark
> 

Thanks Mark  -
your comments made me wonder if in fact there actually was some other error message
that was written much earlier  --   and there was!     It took some finding but after some
lengthy grep -v'ing I found this

ERROR: probe overhead exceeded threshold

And this is indeed described in the document you referenced.

What surprises me is that the run continued for a full 0.1 seconds (over 4000 lines
of output) after this message was logged before it shut itself down. 
(And it was hard to find because many of my probes emit a line with words
such as error and failed in them).

Makes me wonder  -  is there some way of directing error messages such as this to
some other channel rather than interspersing them into the run output.   Or else
at least making them more distinctive.

But thanks again  -  problem solved

John