LTTng » LTTng-tools

I am trying to reproduce the scenario 2 of https://github.com/jgalar/PyConCanada2017/

The commands used to start the session are:

# Create a live session
lttng create py_syscalls --live

# Enable all Python agent (logger) events
lttng track --userspace --pid $1
lttng enable-event --python --all

# Enable all syscalls invoked by python
lttng track --kernel --pid $1
lttng enable-event --kernel --syscall --all

lttng start

where $1 is normally the pid of a Python http server, but I was able to reproduce using the pid of a dummy /bin/sleep process.

After running the commands above, I connect with babeltrace or babeltrace2:

[root@simark PyConCanada2017]# babeltrace -i lttng-live net://localhost/host/simark/py_syscalls
[error] Remote side has closed connection
[warning] [Context] Cannot open_trace of format lttng-live at path net://localhost/host/simark/py_syscalls.
[warning] [Context] cannot open trace "net://localhost/host/simark/py_syscalls" for reading.
[error] opening trace "net://localhost/host/simark/py_syscalls" for reading.

[error] none of the specified trace paths could be opened.

[root@simark PyConCanada2017]# babeltrace2 net://localhost/host/simark/py_syscalls                                                                           
11-29 22:56:32.275 719277 719277 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_recv@viewer-connection.c:197 [auto-disc-source-ctf-lttng-live] Remote side has closed connection
11-29 22:56:32.275 719277 719277 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_session_attach@viewer-connection.c:1106 [auto-disc-source-ctf-lttng-live] Error receiving attach session reply
11-29 22:56:32.275 719277 719277 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_get_session@lttng-live.c:477 [auto-disc-source-ctf-lttng-live] Error attaching to LTTng live session
11-29 22:56:32.275 719277 719277 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1662 [auto-disc-source-ctf-lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR11-29 22:56:32.275 719277 719277 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x56536acf7250, iter-upstream-comp-name="auto-disc-source-ctf-lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
11-29 22:56:32.275 719277 719277 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:452 [muxer] Upstream iterator's next method returned an error: status=ERROR
11-29 22:56:32.275 719277 719277 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:986 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x56536acf6da0, muxer-upstream-msg-iter-wrap-addr=0x56536acf9f10
11-29 22:56:32.275 719277 719277 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1411 [muxer] Cannot get next message: comp-addr=0x56536acfa680, muxer-comp-addr=0x56536acfc260, muxer-msg-iter-addr=0x56536acf6da0, msg-iter-addr=0x56536acf7510, status=ERROR
11-29 22:56:32.275 719277 719277 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x56536acf7510, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
11-29 22:56:32.275 719277 719277 W LIB/GRAPH consume_graph_sink@graph.c:469 Component's "consume" method failed: status=ERROR, comp-addr=0x56536ad2a6f0, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x56536ad2c4d0, comp-class-so-handle-path="/usr/lib/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
11-29 22:56:32.275 719277 719277 E CLI cmd_run@babeltrace2.c:2547 Graph failed to complete successfully

ERROR:    [Babeltrace CLI] (babeltrace2.c:2547)
  Graph failed to complete successfully
CAUSED BY [libbabeltrace2] (graph.c:469)
  Component's "consume" method failed: status=ERROR, comp-addr=0x56536ad2a6f0, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK,
  comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x56536ad2c4d0,
  comp-class-so-handle-path="/usr/lib/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
CAUSED BY [libbabeltrace2] (iterator.c:861)
  Component input port message iterator's "next" method failed: iter-addr=0x56536acf7510, iter-upstream-comp-name="muxer",
  iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer",
  iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:986)
  Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x56536acf6da0, muxer-upstream-msg-iter-wrap-addr=0x56536acf9f10
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:452)
  Upstream iterator's next method returned an error: status=ERROR
CAUSED BY [libbabeltrace2] (iterator.c:861)
  Component input port message iterator's "next" method failed: iter-addr=0x56536acf7250, iter-upstream-comp-name="auto-disc-source-ctf-lttng-live",
  iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live",
  iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
CAUSED BY [auto-disc-source-ctf-lttng-live: 'source.ctf.lttng-live'] (lttng-live.c:1662)
  Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
CAUSED BY [auto-disc-source-ctf-lttng-live: 'source.ctf.lttng-live'] (lttng-live.c:477)
  Error attaching to LTTng live session
CAUSED BY [auto-disc-source-ctf-lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:1106)
  Error receiving attach session reply
CAUSED BY [auto-disc-source-ctf-lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:197)
  Remote side has closed connection

In both cases, lttng-relay shows:

[root@simark ~]# lttng-relayd 
Warning: No tracing group detected
lttng-relayd: /home/simark/src/lttng-tools/src/bin/lttng-relayd/viewer-session.c:80: viewer_session_attach: Assertion `!vsession->current_trace_chunk' failed.
Aborted (core dumped)

I don't know much about lttng-relayd, so I wasn't able to debug much, but I saw that the relayd received the command LTTNG_VIEWER_ATTACH_SESSION twice, and the second time around, current_trace_chunk was not NULL (it was set the first time).