[PATCH v1 seastar] core/reactor: Log backtrace from report_failed_future()

[Tomasz Grabiec]

Example:

WARN 2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future ignored: seastar::gate_closed_exception (gate closed)
0x498629
0x4f927a
0x6e2bc4
0x48c1c8
0x4d2bda
0x5416e3
0x41dcda
0x7ff41eb8757f
0x487648


---
core/reactor.cc | 11 ++++++++++-
1 file changed, 10 insertions(+), 1 deletion(-)

diff --git a/core/reactor.cc b/core/reactor.cc
index 9246d12..9017db9 100644
--- a/core/reactor.cc
+++ b/core/reactor.cc
@@ -3488,8 +3488,17 @@ void engine_exit(std::exception_ptr eptr) {
engine().exit(1);
}

+static sstring backtrace_as_string(const char* indent = " ") {
+ sstring s;
+ backtrace([&] (uintptr_t addr) {
+ s += indent;
+ s += sprint("0x%x\n", addr - 1);
+ });
+ return s;
+}
+
void report_failed_future(std::exception_ptr eptr) {
- seastar_logger.warn("Exceptional future ignored: {}", eptr);
+ seastar_logger.warn("Exceptional future ignored: {}\n{}", eptr, backtrace_as_string());
}

future<> check_direct_io_support(sstring path) {
--
2.5.5

[Nadav Har'El]

On Wed, Sep 28, 2016 at 5:59 PM, Tomasz Grabiec <tgra...@scylladb.com> wrote:

Example:

WARN  2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future ignored: seastar::gate_closed_exception (gate closed)
  0x498629
  0x4f927a
  0x6e2bc4
  0x48c1c8
  0x4d2bda
  0x5416e3
  0x41dcda
  0x7ff41eb8757f
  0x487648

 

Looks good. But just curious: Is it convenient for you that all these addresses are on separate lines? Wouldn't it be more convenient if they are on the same line, and it will be clearer where the backtrace starts and where it ends, and which warning it relates to?

---
 core/reactor.cc | 11 ++++++++++-
 1 file changed, 10 insertions(+), 1 deletion(-)

diff --git a/core/reactor.cc b/core/reactor.cc
index 9246d12..9017db9 100644
--- a/core/reactor.cc
+++ b/core/reactor.cc
@@ -3488,8 +3488,17 @@ void engine_exit(std::exception_ptr eptr) {
     engine().exit(1);
 }

+static sstring backtrace_as_string(const char* indent = "  ") {
+    sstring s;
+    backtrace([&] (uintptr_t addr) {
+        s += indent;
+        s += sprint("0x%x\n", addr - 1);
+    });
+    return s;
+}
+
 void report_failed_future(std::exception_ptr eptr) {
-    seastar_logger.warn("Exceptional future ignored: {}", eptr);
+    seastar_logger.warn("Exceptional future ignored: {}\n{}", eptr, backtrace_as_string());
 }

 future<> check_direct_io_support(sstring path) {

--
2.5.5

--
You received this message because you are subscribed to the Google Groups "seastar-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to seastar-dev+unsubscribe@googlegroups.com.
To post to this group, send email to seast...@googlegroups.com.
Visit this group at https://groups.google.com/group/seastar-dev.
To view this discussion on the web visit https://groups.google.com/d/msgid/seastar-dev/1475074762-13356-1-git-send-email-tgrabiec%40scylladb.com.
For more options, visit https://groups.google.com/d/optout.

[Gleb Natapov]

On Wed, Sep 28, 2016 at 06:53:18PM +0300, Nadav Har'El wrote:
> On Wed, Sep 28, 2016 at 5:59 PM, Tomasz Grabiec <tgra...@scylladb.com>
> wrote:
>
> > Example:
> >
> > WARN 2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future
> > ignored: seastar::gate_closed_exception (gate closed)
> > 0x498629
> > 0x4f927a
> > 0x6e2bc4
> > 0x48c1c8
> > 0x4d2bda
> > 0x5416e3
> > 0x41dcda
> > 0x7ff41eb8757f
> > 0x487648
> >
>
> Looks good. But just curious: Is it convenient for you that all these
> addresses are on separate lines? Wouldn't it be more convenient if they are
> on the same line, and it will be clearer where the backtrace starts and
> where it ends, and which warning it relates to?
>

+1. The bonus is that "same line" is how you pass them to addr2line
anyway.

> > email to seastar-dev...@googlegroups.com.

> > To post to this group, send email to seast...@googlegroups.com.
> > Visit this group at https://groups.google.com/group/seastar-dev.
> > To view this discussion on the web visit https://groups.google.com/d/
> > msgid/seastar-dev/1475074762-13356-1-git-send-email-
> > tgrabiec%40scylladb.com.
> > For more options, visit https://groups.google.com/d/optout.
> >
>

> --
> You received this message because you are subscribed to the Google Groups "seastar-dev" group.

> To unsubscribe from this group and stop receiving emails from it, send an email to seastar-dev...@googlegroups.com.

> To post to this group, send email to seast...@googlegroups.com.
> Visit this group at https://groups.google.com/group/seastar-dev.

> To view this discussion on the web visit https://groups.google.com/d/msgid/seastar-dev/CANEVyjtHAo39dK78%3Dy2r%3DzM3Z0RjHzGgDaJXBp4VQN%2BBDkALWA%40mail.gmail.com.

> For more options, visit https://groups.google.com/d/optout.

--
Gleb.

[Tomasz Grabiec]

On Wed, Sep 28, 2016 at 6:30 PM, Gleb Natapov <gl...@scylladb.com> wrote:

On Wed, Sep 28, 2016 at 06:53:18PM +0300, Nadav Har'El wrote:
> On Wed, Sep 28, 2016 at 5:59 PM, Tomasz Grabiec <tgra...@scylladb.com>
> wrote:
>
> > Example:
> >
> > WARN  2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future
> > ignored: seastar::gate_closed_exception (gate closed)
> >   0x498629
> >   0x4f927a
> >   0x6e2bc4
> >   0x48c1c8
> >   0x4d2bda
> >   0x5416e3
> >   0x41dcda
> >   0x7ff41eb8757f
> >   0x487648
> >
>
> Looks good. But just curious: Is it convenient for you that all these
> addresses are on separate lines? Wouldn't it be more convenient if they are
> on the same line, and it will be clearer where the backtrace starts and
> where it ends, and which warning it relates to?
>
+1. The bonus is that "same line" is how you pass them to addr2line
anyway.

addr2line doesn't seem to be able to deal with addresses in the same line, it expects each address in a different line:

$ addr2line -Cfpi -e ../build/release/scylla

0x498629 0x4f927a 0x6e2bc4 0x48c1c8 0x4d2bda 0x5416e3 0x41dcda 0x7ff41eb8757f 0x487648 

?? ??:0

$ addr2line -Cfpi -e ../build/release/scylla

0x498629, 0x4f927a, 0x6e2bc4, 0x48c1c8, 0x4d2bda, 0x5416e3, 0x41dcda, 0x7ff41eb8757f, 0x487648

backtrace_as_string at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:3529

 (inlined by) report_failed_future(std::__exception_ptr::exception_ptr) at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:3534

 

$ addr2line -Cfpi -e ../build/release/scylla

0x498629

0x4f927a

0x6e2bc4

0x48c1c8

0x4d2bda

0x5416e3

0x41dcda

0x7ff41eb8757f

0x487648

backtrace_as_string at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:3529

 (inlined by) report_failed_future(std::__exception_ptr::exception_ptr) at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:3534

promise<>::abandoned() at /home/tgrabiec/src/scylla/seastar/core/future.hh:1126

promise<>::~promise() at /home/tgrabiec/src/scylla/seastar/core/future.hh:427

 (inlined by) ~<lambda> at /home/tgrabiec/src/scylla/seastar/core/future.hh:886

 (inlined by) ~continuation at /home/tgrabiec/src/scylla/seastar/core/future.hh:386

 (inlined by) ~continuation at /home/tgrabiec/src/scylla/seastar/core/future.hh:386

std::default_delete<task>::operator()(task*) const at /usr/include/c++/5.3.1/bits/unique_ptr.h:76

 (inlined by) std::unique_ptr<task, std::default_delete<task> >::reset(task*) at /usr/include/c++/5.3.1/bits/unique_ptr.h:344

 (inlined by) reactor::run_tasks(circular_buffer<std::unique_ptr<task, std::default_delete<task> >, std::allocator<std::unique_ptr<task, std::default_delete<task> > > >&) at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:1925

reactor::run() at /home/tgrabiec/src/scylla/seastar/core/reactor.cc:2356

app_template::run_deprecated(int, char**, std::function<void ()>&&) at /home/tgrabiec/src/scylla/seastar/core/app-template.cc:131

main at /home/tgrabiec/src/scylla/main.cc:663

So it's a bit easier if addresses are already in different lines.

[Gleb Natapov]

That's very strange because it works here:

$ addr2line -Cfpi -e build/release/scylla 0x4665f0 0x4266d0 0x426880 0x426010 0x430cf0

_GLOBAL__sub_I__ZN3api17set_storage_proxyERNS_12http_contextERN5httpd6routesE at /home/gleb/work/seastar/api/storage_proxy.cc:408
_GLOBAL__sub_I__ZN4cql310statements15grant_statement7executeERN7seastar7shardedIN7service13storage_proxyEEERNS4_11query_stateERKNS_13query_optionsE at /home/gleb/work/seastar/cql3/statements/grant_statement.cc:50
_GLOBAL__sub_I__ZN4cql310statements16revoke_statement7executeERN7seastar7shardedIN7service13storage_proxyEEERNS4_11query_stateERKNS_13query_optionsE at /home/gleb/work/seastar/cql3/statements/revoke_statement.cc:50
_GLOBAL__sub_I__ZN4cql310statements20list_users_statement8validateERN7seastar7shardedIN7service13storage_proxyEEERKNS4_12client_stateE at /home/gleb/work/seastar/cql3/statements/list_users_statement.cc:63
_GLOBAL__sub_I__ZN7service14migration_task13run_may_throwERN7seastar7shardedINS_13storage_proxyEEERKN3gms12inet_addressE at /home/gleb/work/seastar/service/migration_task.cc:70

--
Gleb.

[Tomasz Grabiec]

Ok, so it works if you pass the addresses as arguments (I was passing via stdin).

[Nadav Har'El]

On Wed, Sep 28, 2016 at 7:46 PM, Gleb Natapov <gl...@scylladb.com> wrote:

That's very strange because it works here:

$ addr2line -Cfpi -e  build/release/scylla 0x4665f0 0x4266d0 0x426880 0x426010 0x430cf0

By the way, if we invent some format for making the appearances of such a stack trace easy to recognize, e.g., 

WARN  2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future ignored: seastar::gate_closed_exception (gate closed) <stack>0x498629  0x4f927a  0x6e2bc4 0x48c1c8 0x4d2bda 0x5416e3 0x41dcda 0x7ff41eb8757f 0x487648</stack>

(just a silly xml-like format, anything else could work)

It will be easy to write a script to transform the stack traces in the log to readable functions names and line numbers.

[Gleb Natapov]

Ah, I did not even know this is a possibility.

--
Gleb.

[Avi Kivity]

On 09/28/2016 07:30 PM, Gleb Natapov wrote:
> On Wed, Sep 28, 2016 at 06:53:18PM +0300, Nadav Har'El wrote:
>> On Wed, Sep 28, 2016 at 5:59 PM, Tomasz Grabiec <tgra...@scylladb.com>
>> wrote:
>>
>>> Example:
>>>
>>> WARN 2016-09-28 16:49:26,990 [shard 0] seastar - Exceptional future
>>> ignored: seastar::gate_closed_exception (gate closed)
>>> 0x498629
>>> 0x4f927a
>>> 0x6e2bc4
>>> 0x48c1c8
>>> 0x4d2bda
>>> 0x5416e3
>>> 0x41dcda
>>> 0x7ff41eb8757f
>>> 0x487648
>>>
>> Looks good. But just curious: Is it convenient for you that all these
>> addresses are on separate lines? Wouldn't it be more convenient if they are
>> on the same line, and it will be clearer where the backtrace starts and
>> where it ends, and which warning it relates to?
>>
> +1. The bonus is that "same line" is how you pass them to addr2line
> anyway.

+0x0000000000000001. Greater probability of getting the whole thing from
a user.

[Tomasz Grabiec]

Something like this?

2016-09-28 16:49:26,991 [shard 0] seastar - Exceptional future ignored: seastar::gate_closed_exception (gate closed): 0x498629 0x4f927a 0x6e2bc4 0x48c1c8 0x4d2bda 0x5416e3 0x41dcda 0x7ff41eb8757f 0x487648 

The reason why I did it the way I did is for consistency with how backtrace is usually presented in the logs - stacked. If we add symbol resolution, printing each symbols in separate line would be much more readable. But perhaps you think that's a weak reason?

[Avi Kivity]

Maybe with a marker like Nadav suggested.

The reason why I did it the way I did is for consistency with how backtrace is usually presented in the logs - stacked. If we add symbol resolution, printing each symbols in separate line would be much more readable. But perhaps you think that's a weak reason?

I was more thinking about a user giving us a truncated log, particularly with  a long stacktrace.  Not everyone will scroll to capture the whole thing.  I agree that one-per-line is a lot nicer if we resolve, but we're not likely to.  Maybe as a separate pass (easy to do if we write it as a journald field, perhaps one day).

[Tomasz Grabiec]

I don't like using xml-style tags (<stack></stack>). The rest of the line doesn't have to be a valid xml, so it looks awkward. How about with a simple "backtrace:" prefix:

WARN  2016-09-28 16:49:26,991 [shard 0] seastar - Exceptional future ignored: seastar::gate_closed_exception (gate closed), backtrace: 0x498629 0x4f927a 0x6e2bc4 0x48c1c8 0x4d2bda 0x5416e3 0x41dcda 0x7ff41eb8757f 0x487648

It would still be easy for tools to pick up, using a regex like this: "backtrace:(\s+0x[0-9a-f]+)+$"

[Pekka Enberg]

IIRC, "journalctl" doesn't wrap lines so that just increases the
likelihood of us getting truncated stack traces. :-)

- Pekka

[Avi Kivity]

Maybe: (backtrace: ...) or backtrace: [...] to prevent possible ambiguity.  I don't like the XML annotation either.

[Tomasz Grabiec]

Avi, what about Pekka's point? Stacking the backtrace makes it more likely for it to fit on the screen when viewing in journalctl.

[Tomasz Grabiec]

ping 

[Gleb Natapov]

Why is it useful for it to fit on the screen? It is not useful for human
consumption. It should be easier for scripts to find and cut them which
is much harder with multiline output.

--
Gleb.

[Avi Kivity]

That's true, but it's true for all our log messages. Thanks systemd [1]
for choosing a bad default (the less default is to wrap, systemd
overrides it).

We can be obnoxious and drop a file that overrides SYSTEMD_PAGER in
/etc/profile.d/, but that's going a bit too far. We can try it and see
if we get truncated backtraces (and we should provide scripts to capture
system information including the logs).

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1153747

>>>
>> ping
> Why is it useful for it to fit on the screen? It is not useful for human
> consumption. It should be easier for scripts to find and cut them which
> is much harder with multiline output.
>

Right. And for humans, a long backtrace can fill up a screenfull with
meaningless hex numbers, making it harder to see what's going on.

[Tomasz Grabiec]

Our logs are designed primarily for humans. A human will look at them first when something bad happens. If there is an error with backtrace, a human will select it and paste to an issue report or addr2line's stdin. It is easier to select it if it fits on the screen. It's also a bit easier to spot it in logs.

It may be easier to script extraction if the backtrace is not stacked, but it's not impossible to do so. As long as the logs are read by humans, their convenience should take priority in my opinion.

[Pekka Enberg]

On Tue, Jan 3, 2017 at 6:02 PM, Gleb Natapov <gl...@scylladb.com> wrote:
> Why is it useful for it to fit on the screen? It is not useful for human
> consumption. It should be easier for scripts to find and cut them which
> is much harder with multiline output.

Which scripts are are you talking about? Most people who report bugs
will simply run "systemctl -xe" (like we ask them to) and blindly
copy-paste the truncated backtrace. Having the backtrace on a single
line only makes debugging harder for us, not easier.

- Pekka

[Pekka Enberg]

On Tue, Jan 3, 2017 at 6:15 PM, Avi Kivity <a...@scylladb.com> wrote:
>> Why is it useful for it to fit on the screen? It is not useful for human
>> consumption. It should be easier for scripts to find and cut them which
>> is much harder with multiline output.
>
> Right. And for humans, a long backtrace can fill up a screenfull with
> meaningless hex numbers, making it harder to see what's going on.

It won't make it any harder than reading regular logs which also fill
up with lot of stuff. The wrapping thing is an issue because most
people will not even notice that the backtrace is truncated. It's also
very hard to manually copy-paste the non-wrapped line correctly. It's
less of a problem when the backtrace is on multiple lines because the
whole thing usually fits on one terminal window.

- Pekka

[Gleb Natapov]

On Tue, Jan 03, 2017 at 06:30:34PM +0200, Pekka Enberg wrote:
> On Tue, Jan 3, 2017 at 6:02 PM, Gleb Natapov <gl...@scylladb.com> wrote:
> > Why is it useful for it to fit on the screen? It is not useful for human
> > consumption. It should be easier for scripts to find and cut them which
> > is much harder with multiline output.
>
> Which scripts are are you talking about? Most people who report bugs

Script that we will write to decode backtraces from a log.

> will simply run "systemctl -xe" (like we ask them to) and blindly

We will ask them to run the script instead.

> copy-paste the truncated backtrace. Having the backtrace on a single
> line only makes debugging harder for us, not easier.
>
> - Pekka

--
Gleb.

[Gleb Natapov]

What is convenient about seeing a lot of lines of hex data? If they
happen to not fit on a screen horizontally there is no even argument about
easy cut and paste, as opposite to one marked line that can be extracted
with simple grep.

--
Gleb.

[Avi Kivity]

How about we tell them to journalctl -x > /tmp/log instead, so we see
everything instead of the 8 lines they copy/pasted for us, as well as
avoid the systemd no-wrap-of-death.

We could also do something clever like pack the backtrace in a journal
field.

[Gleb Natapov]

And there is also a high chances of other logs to be inserted between
multiple lines, so c&p becomes c&p into editor, edit, pass to addr2line.

--
Gleb.

[Tomasz Grabiec]

It's more convenient to select it because it's more likely to fit on the screen. Assuming 80x25 term, you can fit 25 frames horizontally, and (assuming scylla addresses) about 8 frames vertically, without considering the preceding message.

[Pekka Enberg]

If we teach them to do that and have a special script, it's trivial to
parse the current logs and produce a fancy report for us.

What I'm saying is that we should optimize for the (very common) case
where user saw something scary in the logs and reported it back to us.
We cannot assume that they still have the full logs available or that
they will be able to run a fancy script. IMO, the current format is
optimal for that scenario because the backtraces are _less likely_ to
be truncated than the proposed one-line format.

And btw, if we *really* want to make the reports better, we should add
symbol resolution to the backtraces so that they appear automatically
in the logs with no need for any external script...

- Pekka

[Pekka Enberg]

On Tue, Jan 3, 2017 at 6:45 PM, Tomasz Grabiec <tgra...@scylladb.com> wrote:
> It's more convenient to select it because it's more likely to fit on the
> screen. Assuming 80x25 term, you can fit 25 frames horizontally, and
> (assuming scylla addresses) about 8 frames vertically, without considering
> the preceding message.

Yes. So in practice vertically formatted backtraces are almost always
truncated...

- Pekka

[Gleb Natapov]

Why select? grep | cut | xargs addr2line. The advantage is that when you
interested in it it is easy to find, if you are not interested the
format is much less noisy.


--
Gleb.

[Tomasz Grabiec]

There could be many backtraces in the logs. I may be interested in resolving only the one I am currently looking at in the logs.

[Tomasz Grabiec]

Even if the message is logged using a single syslog() call? That sounds like a bug, and it would be indeed unfortunate.

 

[Gleb Natapov]

No, single syslog() call should be atomic, but then I am not sure how \n
in the middle of a message will be handled by all log programs out there.

--
Gleb.

[Gleb Natapov]

Grep it by timestamp or just view log with non truncating pager and c&p
if you prefer.

--
Gleb.

[Tomasz Grabiec]

Yes, it's possible to deal with that. It's still easier if I don't have to do that. If I'd have to choose between more effort to write a script vs more effort when working with the log manually, I think we should choose the former. You write the script once, but extra manual work you do every time.

[Gleb Natapov]

Working with a log that has multiline hex splashes all over it when you
do not care about them at all is more effort. Asking user to search for
a hex and explain exactly what he should c&p is more effort. Running
journalctl -ex | less (which will wrap lines), or providing user a cmd
that will find and translate backtraces is less effort.

--
Gleb.

[Hải Nguyễn]

How about translating address directly to function name in backtrace using unw_get_proc_name and abi::__cxa_demangle. It should make reading log less painful and look more like Java-style exception.