Quickstart: instrument a Node.js service with Beyla not tracing logs on HTTP call #1093
Comments
|
Hi @sandeepkoseai, everything looks correct from your steps. We need to enable a bit more logging to see what's happening. Can you please add the following two environment options and send us the Beyla output: Run one or two curl commands like you did before. This will print a lot more and we should be able to tell what's not working or what's misconfigured. |
|
Hi Nikola,
Thanks for the quick response, here is the complete logs as requested:
***@***.***:~# echo $BEYLA_LOG_LEVEL && echo $BEYLA_BPF_DEBUG
debug
1
***@***.***:~# sudo -E beyla
time=2024-08-15T16:13:48.846Z level=INFO msg="Grafana Beyla" Version=v1.7.0
Revision=9d07bfb "OpenTelemetry SDK Version"=1.28.0
time=2024-08-15T16:13:48.847Z level=DEBUG msg="not reporting internal
metrics"
time=2024-08-15T16:13:48.847Z level=DEBUG msg="trying to fetch host ID"
component=ContextInfo func=fetchHostID fetcher=AWS
time=2024-08-15T16:13:48.849Z level=INFO msg="got host ID"
component=ContextInfo func=fetchHostID fetcher=AWS
hostID=i-0ea5b51aa1675a5c6
time=2024-08-15T16:13:48.849Z level=INFO msg="starting Beyla in Application
Observability mode"
time=2024-08-15T16:13:48.849Z level=DEBUG msg="Linux kernel version"
component=nethttp.Tracer major=6 minor=8
time=2024-08-15T16:13:48.849Z level=DEBUG msg="checking kernel lockdown
mode, [none] allows us to propagate trace context"
component=ebpf.ProcessTracer
time=2024-08-15T16:13:48.849Z level=DEBUG msg="Kernel not in lockdown mode,
trace context propagation is supported." component=nethttp.Tracer
time=2024-08-15T16:13:48.849Z level=DEBUG msg="Linux kernel version"
component=grpc.Tracer major=6 minor=8
time=2024-08-15T16:13:48.849Z level=DEBUG msg="checking kernel lockdown
mode, [none] allows us to propagate trace context"
component=ebpf.ProcessTracer
time=2024-08-15T16:13:48.849Z level=DEBUG msg="Kernel not in lockdown mode,
trace context propagation is supported." component=grpc.Tracer
time=2024-08-15T16:13:48.849Z level=DEBUG msg="mounting BPF map pinning"
component=discover.TraceAttacher path=/var/run/beyla/beyla-958378
time=2024-08-15T16:13:48.849Z level=DEBUG msg="BPF map pinning path does
not exist. Creating before mounting" component=discover.TraceAttacher
time=2024-08-15T16:13:48.851Z level=DEBUG msg="creating instrumentation
pipeline" component=beyla.Instrumenter
time=2024-08-15T16:13:48.851Z level=DEBUG msg="starting criteria matcher
node" component=discover.CriteriaMatcher
time=2024-08-15T16:13:48.852Z level=DEBUG msg="loading independent eBPF
program" component=ebpf.ProcessTracer
time=2024-08-15T16:13:48.855Z level=DEBUG msg="found FQDN hosts"
component=HostnameResolver
hosts=[ip-172-31-43-47.us-east-2.compute.internal.]
time=2024-08-15T16:13:48.855Z level=DEBUG msg="Notifying observers"
component=HostnameResolver change=2
time=2024-08-15T16:13:48.855Z level=INFO msg="using hostname"
component=traces.ReadDecorator function=instance_ID_hostNamePIDDecorator
hostname=ip-172-31-43-47.us-east-2.compute.internal
time=2024-08-15T16:13:48.856Z level=INFO msg="Starting main node"
component=beyla.Instrumenter
time=2024-08-15T16:13:48.958Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_bind
probes="{Required:true Start:Kprobe(kprobe_sys_bind)#3 End:<nil>}"
time=2024-08-15T16:13:48.961Z level=DEBUG msg="loading independent eBPF
program" component=ebpf.ProcessTracer
time=2024-08-15T16:13:48.961Z level=DEBUG msg="start reading and
forwarding" component=watcher.Tracer
time=2024-08-15T16:13:48.961Z level=DEBUG msg="start reading and
forwarding" component=BPFLogger
time=2024-08-15T16:13:48.961Z level=DEBUG msg="starting to read ring
buffer" component=watcher.Tracer
time=2024-08-15T16:13:48.961Z level=DEBUG msg="starting to read ring
buffer" component=BPFLogger
time=2024-08-15T16:13:49.024Z level=DEBUG msg="new process watching events"
component=discover.ProcessWatcher interval=5s events="[{Type:0 Obj:{pid:19
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:37
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:100
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958148
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:957900
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958323
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:46
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:47
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:754
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:1
openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:7
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:25
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:42
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:45
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:718988
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:956797
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958010
openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958034
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958366
openPorts:[8080] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:863749
openPorts:[3000] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:863825
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:863856
openPorts:[3000] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:18
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:62
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:65190
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:65216
openPorts:[68] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:718877
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:957997
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:21
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:70
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:71
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:957975
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:14
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:182
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:958293
openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:41
openPorts:[] metadata:map[] podLabels:map[]}} {Type:0 Obj:{pid:65201
openPorts:[53 53 53 53] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:863681 openPorts:[9090] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:5 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:23 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:35 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:667 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:878 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:48 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:51 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:68 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:2 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:183 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:863639 openPorts:[9090] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:957858 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:26 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:53 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:56 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:957782 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:33 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958365 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:321 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:863770 openPorts:[3000] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:906948 openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958028 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958138 openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:817 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:855875 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958029 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:804 openPorts:[323 323] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958220 openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958377 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:65215 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:957947 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958221 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:15 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:67 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:73 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:84 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:273 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:28 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:65 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:674 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:1045 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958322 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:44 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:50 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:69 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:97 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:3022 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:668 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:1028 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:9 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:27 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:29 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:64 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:129 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958150 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:38 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:74 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:99 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:863633 openPorts:[9090] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:957961 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:863661 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:59 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:66 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:1049 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:65206 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:20037 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:855896 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958158 openPorts:[22] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:4 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:22 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:57 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:58 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:61 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958316 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958350 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958378 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:17 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:204 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:663 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:65193 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958000 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:12 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958294 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958348 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:82 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:98 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:274 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:3 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:13 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:39 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:49 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:63 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958004 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958149 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958349 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958376 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:32 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:34 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:60 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958321 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958139 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:6 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:16 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:20 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:75 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:19860 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:320 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:957551 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:31 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:678 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:855900 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958230 openPorts:[22] metadata:map[] podLabels:map[]}}]"
time=2024-08-15T16:13:49.025Z level=DEBUG msg="filtering processes"
component=discover.CriteriaMatcher len=150
time=2024-08-15T16:13:49.027Z level=DEBUG msg="found process"
component=discover.CriteriaMatcher pid=958366 comm=/usr/bin/node
metadata=map[] podLabels=map[]
time=2024-08-15T16:13:49.044Z level=DEBUG msg="processes matching selection
criteria" component=discover.CriteriaMatcher len=1
time=2024-08-15T16:13:49.044Z level=DEBUG msg="Found namespace"
component=httpfltr.Tracer nsPid=pid:[4026531836]
time=2024-08-15T16:13:49.044Z level=DEBUG msg="getting instrumentable
information" component=discover.ExecTyper pid=958366 comm=/usr/bin/node
time=2024-08-15T16:13:49.044Z level=DEBUG msg=inspecting
component=discover.ExecTyper pid=958366 comm=/usr/bin/node
time=2024-08-15T16:13:49.044Z level=DEBUG msg="searching for
instrumentation points" component=goexec.instructions functions="[
golang.org/x/net/http2.(*ClientConn).RoundTrip net.(*netFD).Read
net/http.(*response).WriteHeader net/http.(*conn).serve
net/http.(*persistConn).roundTrip database/sql.(*DB).queryDC
net/http.serverHandler.ServeHTTP
golang.org/x/net/http2.(*ClientConn).roundTrip
net/http.(*http2ClientConn).RoundTrip
net/http.(*http2responseWriterState).writeHeader database/sql.(*DB).execDC
net/http.(*http2Framer).WriteHeaders net/http.(*conn).readRequest
golang.org/x/net/http2.(*responseWriterState).writeHeader
net/http.(*http2serverConn).runHandler
golang.org/x/net/http2.(*Framer).WriteHeaders
net/http.(*Transport).roundTrip
golang.org/x/net/http2.(*serverConn).runHandler net/http.Header.writeSubset
google.golang.org/grpc.(*ClientConn).NewStream
google.golang.org/grpc.(*ClientConn).Close
google.golang.org/grpc/internal/transport.(*http2Client).NewStream
google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders
google.golang.org/grpc.(*ClientConn).Invoke
google.golang.org/grpc/internal/transport.(*http2Server).WriteStatus
google.golang.org/grpc.(*clientStream).RecvMsg
google.golang.org/grpc.(*clientStream).CloseSend
google.golang.org/grpc/internal/transport.(*serverHandlerTransport).HandleStreams
google.golang.org/grpc.(*Server).handleStream runtime.newproc1
runtime.goexit1 github.com/IBM/sarama.(*responsePromise).handle
github.com/IBM/sarama.(*Broker).sendInternal
github.com/IBM/sarama.(*Broker).write
github.com/Shopify/sarama.(*Broker).write
github.com/Shopify/sarama.(*responsePromise).handle
github.com/Shopify/sarama.(*Broker).sendInternal
github.com/redis/go-redis/v9/internal/pool.(*Conn).WithWriter
github.com/redis/go-redis/v9.(*baseClient)._process
github.com/redis/go-redis/v9.(*baseClient).pipelineProcessCmds
github.com/redis/go-redis/v9.(*baseClient).txPipelineProcessCmds
github.com/segmentio/kafka-go.(*Writer).WriteMessages
github.com/segmentio/kafka-go.(*Writer).produce
github.com/segmentio/kafka-go.(*Client).roundTrip
github.com/segmentio/kafka-go/protocol.RoundTrip
github.com/segmentio/kafka-go.(*reader).read
github.com/segmentio/kafka-go.(*reader).sendMessage]"
time=2024-08-15T16:13:49.044Z level=DEBUG msg="couldn't find go specific
tracers" component=discover.ExecTyper error="couldn't find any
instrumentation point in /usr/bin/node"
time=2024-08-15T16:13:49.044Z level=DEBUG msg="identified as a generic,
non-Go executable" component=discover.ExecTyper pid=958366
comm=/usr/bin/node
time=2024-08-15T16:13:49.045Z level=DEBUG msg=instrumented
component=discover.ExecTyper pid=958366 comm=/usr/bin/node
comm=/usr/bin/node pid=958366 child=[] language=nodejs
time=2024-08-15T16:13:49.045Z level=DEBUG msg="found an instrumentable
process" component=discover.ExecTyper type=nodejs exec=/usr/bin/node
pid=958366
time=2024-08-15T16:13:49.045Z level=DEBUG msg=Instrumentable
component=discover.TraceAttacher len=1 inst="{Type:0 Obj:{Type:nodejs
InstrumentationError:couldn't find any instrumentation point in
/usr/bin/node ChildPids:[] FileInfo:0xc0015eb340 Offsets:<nil>}}"
time=2024-08-15T16:13:49.045Z level=INFO msg="instrumenting process"
component=discover.TraceAttacher cmd=/usr/bin/node pid=958366
time=2024-08-15T16:13:49.045Z level=DEBUG msg="new executable for
discovered process" component=discover.TraceAttacher pid=958366 child=[]
exec=/usr/bin/node
time=2024-08-15T16:13:49.045Z level=DEBUG msg=.done
component=discover.TraceAttacher
time=2024-08-15T16:13:49.045Z level=DEBUG msg="running tracer for new
process" component=beyla.Instrumenter inode=72985 pid=958366
exec=/usr/bin/node
time=2024-08-15T16:13:49.045Z level=DEBUG msg="starting process tracer"
component=ebpf.ProcessTracer path=/usr/bin/node pid=958366
time=2024-08-15T16:13:49.045Z level=DEBUG msg="loading eBPF program"
component=ebpf.ProcessTracer program=*httpfltr.Tracer
PinPath=/var/run/beyla/beyla-958378 pid=958366 cmd=/usr/bin/node
time=2024-08-15T16:13:49.232Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_clone3
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sys_clone)#49}"
time=2024-08-15T16:13:49.234Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_exit
probes="{Required:true Start:Kprobe(kprobe_sys_exit)#27 End:<nil>}"
time=2024-08-15T16:13:49.237Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_accept4
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sys_accept4)#48}"
time=2024-08-15T16:13:49.241Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes
function=tcp_rcv_established probes="{Required:true
Start:Kprobe(kprobe_tcp_rcv_established)#34 End:<nil>}"
time=2024-08-15T16:13:49.244Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=tcp_close
probes="{Required:true Start:Kprobe(kprobe_tcp_close)#30 End:<nil>}"
time=2024-08-15T16:13:49.247Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=tcp_sendmsg
probes="{Required:true Start:Kprobe(kprobe_tcp_sendmsg)#45
End:Kprobe(kretprobe_tcp_sendmsg)#52}"
time=2024-08-15T16:13:49.251Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=tcp_recvmsg
probes="{Required:true Start:Kprobe(kprobe_tcp_recvmsg)#36
End:Kprobe(kretprobe_tcp_recvmsg)#51}"
time=2024-08-15T16:13:49.255Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_clone
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sys_clone)#49}"
time=2024-08-15T16:13:49.258Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_accept
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sys_accept4)#48}"
time=2024-08-15T16:13:49.262Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sock_alloc
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sock_alloc)#47}"
time=2024-08-15T16:13:49.265Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=sys_connect
probes="{Required:true Start:<nil> End:Kprobe(kretprobe_sys_connect)#50}"
time=2024-08-15T16:13:49.269Z level=DEBUG msg="going to add kprobe to
function" component=ebpf.Instrumenter probes=kprobes function=tcp_connect
probes="{Required:true Start:Kprobe(kprobe_tcp_connect)#32 End:<nil>}"
time=2024-08-15T16:13:49.273Z level=DEBUG msg="loading eBPF program"
component=ebpf.ProcessTracer program=*httpssl.Tracer
PinPath=/var/run/beyla/beyla-958378 pid=958366 cmd=/usr/bin/node
time=2024-08-15T16:13:49.347Z level=DEBUG msg="finding library"
component=ebpf.Instrumenter probes=uprobes lib=libssl.so
time=2024-08-15T16:13:49.347Z level=DEBUG msg="instrumenting library"
component=ebpf.Instrumenter probes=uprobes lib=libssl.so
path=/usr/lib/x86_64-linux-gnu/libssl.so.3
time=2024-08-15T16:13:49.347Z level=DEBUG msg="found inode number,
recording this instrumentation if successful" component=ebpf.Instrumenter
probes=uprobes lib=libssl.so path=/usr/lib/x86_64-linux-gnu/libssl.so.3
ino=31415
time=2024-08-15T16:13:49.347Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes function=SSL_read
programs="{Required:false Start:Kprobe(uprobe_ssl_read)#126
End:Kprobe(uretprobe_ssl_read)#136}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes function=SSL_write
programs="{Required:false Start:Kprobe(uprobe_ssl_write)#133
End:Kprobe(uretprobe_ssl_write)#138}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes function=SSL_read_ex
programs="{Required:false Start:Kprobe(uprobe_ssl_read_ex)#127
End:Kprobe(uretprobe_ssl_read_ex)#137}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes function=SSL_write_ex
programs="{Required:false Start:Kprobe(uprobe_ssl_write_ex)#134
End:Kprobe(uretprobe_ssl_write_ex)#139}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=SSL_do_handshake programs="{Required:false
Start:Kprobe(uprobe_ssl_do_handshake)#123
End:Kprobe(uretprobe_ssl_do_handshake)#135}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes function=SSL_shutdown
programs="{Required:false Start:Kprobe(uprobe_ssl_shutdown)#129 End:<nil>}"
time=2024-08-15T16:13:49.355Z level=DEBUG msg="loading eBPF program"
component=ebpf.ProcessTracer program=*nodejs.Tracer
PinPath=/var/run/beyla/beyla-958378 pid=958366 cmd=/usr/bin/node
time=2024-08-15T16:13:49.359Z level=DEBUG msg="finding library"
component=ebpf.Instrumenter probes=uprobes lib=node
time=2024-08-15T16:13:49.359Z level=DEBUG msg="instrumenting library"
component=ebpf.Instrumenter probes=uprobes lib=node path=/usr/bin/node
time=2024-08-15T16:13:49.359Z level=DEBUG msg="found inode number,
recording this instrumentation if successful" component=ebpf.Instrumenter
probes=uprobes lib=node path=/usr/bin/node ino=72985
time=2024-08-15T16:13:49.359Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap13EmitAsyncInitEPNS_11EnvironmentEN2v85LocalINS3_6ObjectEEENS4_INS3_6StringEEEdd
programs="{Required:false Start:Kprobe(emit_async_init)#171 End:<nil>}"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="error instrumenting uprobe"
component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap13EmitAsyncInitEPNS_11EnvironmentEN2v85LocalINS3_6ObjectEEENS4_INS3_6StringEEEdd
error="setting uprobe: symbol
_ZN4node9AsyncWrap13EmitAsyncInitEPNS_11EnvironmentEN2v85LocalINS3_6ObjectEEENS4_INS3_6StringEEEdd:
not found"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEENS3_INS0_6StringEEEd
programs="{Required:false Start:Kprobe(emit_async_init)#171 End:<nil>}"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="error instrumenting uprobe"
component=ebpf.Instrumenter probes=uprobes
function=_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEENS3_INS0_6StringEEEd
error="setting uprobe: symbol
_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEENS3_INS0_6StringEEEd:
not found"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEEPKcd
programs="{Required:false Start:Kprobe(emit_async_init)#171 End:<nil>}"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="error instrumenting uprobe"
component=ebpf.Instrumenter probes=uprobes
function=_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEEPKcd
error="setting uprobe: symbol
_ZN4node13EmitAsyncInitEPN2v87IsolateENS0_5LocalINS0_6ObjectEEEPKcd: not
found"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap10AsyncResetEN2v85LocalINS1_6ObjectEEEdb
programs="{Required:false Start:Kprobe(async_reset)#167
End:Kprobe(async_reset_ret)#168}"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="error instrumenting uprobe"
component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap10AsyncResetEN2v85LocalINS1_6ObjectEEEdb
error="setting uprobe: symbol
_ZN4node9AsyncWrap10AsyncResetEN2v85LocalINS1_6ObjectEEEdb: not found"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="going to instrument
function" component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap10AsyncResetERKN2v820FunctionCallbackInfoINS1_5ValueEEE
programs="{Required:false Start:Kprobe(async_reset)#167
End:Kprobe(async_reset_ret)#168}"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="error instrumenting uprobe"
component=ebpf.Instrumenter probes=uprobes
function=_ZN4node9AsyncWrap10AsyncResetERKN2v820FunctionCallbackInfoINS1_5ValueEEE
error="setting uprobe: symbol
_ZN4node9AsyncWrap10AsyncResetERKN2v820FunctionCallbackInfoINS1_5ValueEEE:
not found"
time=2024-08-15T16:13:49.359Z level=DEBUG msg="Reallowing pid"
component=httpfltr.Tracer pid=958366 namespace=4026531836
time=2024-08-15T16:13:49.359Z level=DEBUG msg="number of segments in pid
filter cache" component=httpfltr.Tracer len=3001
time=2024-08-15T16:13:49.359Z level=DEBUG msg="start reading and
forwarding" component=ringbuf.Tracer
time=2024-08-15T16:13:49.360Z level=DEBUG msg="starting to read ring
buffer" component=ringbuf.Tracer
time=2024-08-15T16:13:59.079Z level=DEBUG msg="new process watching events"
component=discover.ProcessWatcher interval=5s events="[{Type:0
Obj:{pid:958390 openPorts:[] metadata:map[] podLabels:map[]}} {Type:0
Obj:{pid:958391 openPorts:[] metadata:map[] podLabels:map[]}}]"
time=2024-08-15T16:13:59.079Z level=DEBUG msg="filtering processes"
component=discover.CriteriaMatcher len=2
time=2024-08-15T16:13:59.080Z level=DEBUG msg="processes matching selection
criteria" component=discover.CriteriaMatcher len=0
time=2024-08-15T16:14:04.081Z level=DEBUG msg="new process watching events"
component=discover.ProcessWatcher interval=5s events="[{Type:0
Obj:{pid:958461 openPorts:[] metadata:map[] podLabels:map[]}} {Type:1
Obj:{pid:958391 openPorts:[] metadata:map[] podLabels:map[]}}]"
time=2024-08-15T16:14:04.081Z level=DEBUG msg="filtering processes"
component=discover.CriteriaMatcher len=2
time=2024-08-15T16:14:04.081Z level=DEBUG msg="deleted untracked process.
Ignoring" component=discover.CriteriaMatcher pid=958391
time=2024-08-15T16:14:04.081Z level=DEBUG msg="processes matching selection
criteria" component=discover.CriteriaMatcher len=0
time=2024-08-15T16:14:09.082Z level=DEBUG msg="new process watching events"
component=discover.ProcessWatcher interval=5s events="[{Type:0
Obj:{pid:958462 openPorts:[] metadata:map[] podLabels:map[]}}]"
time=2024-08-15T16:14:09.082Z level=DEBUG msg="filtering processes"
component=discover.CriteriaMatcher len=1
time=2024-08-15T16:14:09.082Z level=DEBUG msg="processes matching selection
criteria" component=discover.CriteriaMatcher len=0
time=2024-08-15T16:14:21.160Z level=DEBUG msg="=== sock alloc e9f9e000e9f9e
===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.160Z level=DEBUG msg="=== accept 4 ret id=958366,
sock=ffff92ea566b16c0, fd=27 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb53c04600 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="=== tcp_recvmsg ret
id=958366 sock=ffff92eb53c04600 copied_len 77 ===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="msg iter type exists, read
value 0" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="iter type 0"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="standard iov 62818dfcb2b0
base 5448202f20544547 len 825184340" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:21.162Z level=DEBUG msg="buf=[], pid=958366, len=77"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="=== kprobe
tcp_sendmsg=958366 sock=ffff92eb53c04600 size 241===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="msg iter type exists, read
value 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="iter type 1"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 3" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="standard iov
ffff9ea7ecadfd80 base 62818e05de40 len 233" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="buf=[HTTP/1.1 200
OK\r\nX-Power\xe0|\x8f\xbf\xa7\xbe\xff\xff\xf1], pid=958366, len=241"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="No info, pid =958366?,
looking for fallback..." component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="=== http_buffer_event
len=241 pid=958366 still_reading=1 ===" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="Delaying finish http for
large request, orig_len 241" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.169Z level=DEBUG msg="=== kretprobe
tcp_sendmsg=958366 sent 241===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.171Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb53c04600 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.171Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.171Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.173Z level=DEBUG msg="=== kprobe tcp_close 958366
sock ffff92eb53c04600 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.173Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:21.173Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.919Z level=DEBUG msg="=== sock alloc e9f9e000e9f9e
===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="=== accept 4 ret id=958366,
sock=ffff92ea566b1d40, fd=27 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb4cdba800 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="=== tcp_recvmsg ret
id=958366 sock=ffff92eb4cdba800 copied_len 80 ===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="msg iter type exists, read
value 0" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="iter type 0"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="standard iov 62818dfcb2b0
base 6f6f662f20544547 len 1414809632" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:36.920Z level=DEBUG msg="buf=[], pid=958366, len=80"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== kprobe
tcp_sendmsg=958366 sock=ffff92eb4cdba800 size 241===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="msg iter type exists, read
value 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="iter type 1"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 3" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="standard iov
ffff9ea7ecadfd80 base 62818e05de40 len 233" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="buf=[HTTP/1.1 200
OK\r\nX-Power\xe0|\x8f\xbf\xa7\xbe\xff\xff\xf1], pid=958366, len=241"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="No info, pid =958366?,
looking for fallback..." component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== http_buffer_event
len=241 pid=958366 still_reading=1 ===" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="Delaying finish http for
large request, orig_len 241" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== kretprobe
tcp_sendmsg=958366 sent 241===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb4cdba800 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.921Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.922Z level=DEBUG msg="=== kprobe tcp_close 958366
sock ffff92eb4cdba800 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.922Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:36.922Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.214Z level=DEBUG msg="=== sock alloc e9f9e000e9f9e
===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.214Z level=DEBUG msg="=== accept 4 ret id=958366,
sock=ffff92ea566b1380, fd=27 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb4cdb8a00 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="=== tcp_recvmsg ret
id=958366 sock=ffff92eb4cdb8a00 copied_len 80 ===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="msg iter type exists, read
value 0" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="iter type 0"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="standard iov 62818dfcb2b0
base 6f6f662f20544547 len 1414809632" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:54.215Z level=DEBUG msg="buf=[], pid=958366, len=80"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== kprobe
tcp_sendmsg=958366 sock=ffff92eb4cdb8a00 size 241===" component=BPFLogger
pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="msg iter type exists, read
value 1" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="iter type 1"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="new kernel, iov doesn't
exist, nr_segs 3" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="standard iov
ffff9ea7ecadfd70 base 62818e05de40 len 233" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="buf=[HTTP/1.1 200
OK\r\nX-Power\xe0|\x8f\xbf\xa7\xbe\xff\xff\xf1], pid=958366, len=241"
component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="No info, pid =958366?,
looking for fallback..." component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== http_buffer_event
len=241 pid=958366 still_reading=1 ===" component=BPFLogger pid=958366
comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="Delaying finish http for
large request, orig_len 241" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== tcp_rcv_established
id=958366 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== kretprobe
tcp_sendmsg=958366 sent 241===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="=== tcp_recvmsg id=958366
sock=ffff92eb4cdb8a00 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.216Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.217Z level=DEBUG msg="=== kprobe tcp_close 958366
sock ffff92eb4cdb8a00 ===" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.217Z level=DEBUG msg="Checking if we need to
finish the request per thread id" component=BPFLogger pid=958366 comm=node
time=2024-08-15T16:14:54.217Z level=DEBUG msg="Checking if we need to
finish the request per socket" component=BPFLogger pid=958366 comm=node
Best & Regards,
Sandeep
…On Thu, Aug 15, 2024 at 6:37 PM Nikola Grcevski ***@***.***> wrote:
Hi @sandeepkoseai <https://github.com/sandeepkoseai>, everything looks
correct from your steps. We need to enable a bit more logging to see what's
happening.
Can you please add the following two environment options and send us the
Beyla output:
export BEYLA_LOG_LEVEL=debug
export BEYLA_BPF_DEBUG=1
Run one or two curl commands like you did before.
This will print a lot more and we should be able to tell what's not
working or what's misconfigured.
—
Reply to this email directly, view it on GitHub
<#1093 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/BKRSU5ANZR2R2HSRYIB4AVLZRSR2HAVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJRGIZTKNZZHE>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
|
Ah this is the issue we just fixed few days ago with kernel versions 6.7 and newer. Are you able to try our main branch? The PR that resolved the problem is this one #1086. CC @rafaelroquetto |
|
Hi Nikola,
Here is the branch details I am currently using:
***@***.***:/home/ubuntu/belya# git remote -v
origin https://github.com/grafana/beyla.git (fetch)
origin https://github.com/grafana/beyla.git (push)
***@***.***:/home/ubuntu/belya# git status
On branch *main*
Your branch is up to date with 'origin/main'.
nothing to commit, working tree clean
Please let me know if any additional information is required.
Best & regards,
Sandeep
…On Thu, Aug 15, 2024 at 11:12 PM Nikola Grcevski ***@***.***> wrote:
Ah this is the issue we just fixed few days ago with kernel versions 6.7
and newer. Are you able to try our main branch?
The PR that resolved the problem is this one #1086
<#1086>. CC @rafaelroquetto
<https://github.com/rafaelroquetto>
—
Reply to this email directly, view it on GitHub
<#1093 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/BKRSU5HOPSVSRT5FCL2W56TZRTSB7AVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJRHAZTSMJXGE>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
|
Hi @sandeepkoseai, are you able to post the SHA1 of the branch HEAD commit just so that we can be sure about what we are dealing with? |
|
He Fafael,
Please find suggested commands output below:
$ git rev-parse HEAD
ef14616
Please let me know if any additional information is required.
Best & regards,
Sandeep Kose
…On Fri, Aug 16, 2024 at 7:00 PM Rafael Roquetto ***@***.***> wrote:
Hi @sandeepkoseai <https://github.com/sandeepkoseai>, are you able to
post the SHA1 of the branch HEAD commit just so that we can be sure about
what we are dealing with?
You can do it with git rev-parse HEAD.
Thanks!
—
Reply to this email directly, view it on GitHub
<#1093 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/BKRSU5EFQRHBGFLLCQB6NCTZRX5IRAVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJTGUYTKOBWGM>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
|
Hi @sandeepkoseai, Based on what Beyla showed in the log, the build revision that's running is "9d07bfb". When you downloaded the "main" branch, if you built it with When you run Beyla we print the git hash as the first line in the version, e.g.: |
|
Hi Nikola, I performed a fresh clone on the main branch and ran the 1. Initial Error:
2. Subsequent Error:
3. Current Issue: Test Failures
Could you please assist with resolving the test failures (#3) or provide the Best regards, |
|
Hi @sandeepkoseai, you can ignore the test failures, if you'd like you can also just run We've also made a pre-release with the fixes here, so you can instead pull the binaries directly https://github.com/grafana/beyla/releases |
|
Hello Team, Thank you for your help! The issue has been resolved with the release of version v1.7.1-alpha.1. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Hello Team,
I am experiencing issues with Grafana Beyla when trying to trace logs for a Node.js service on Ubuntu. I followed the Node.js Quickstart guide but am not seeing any traces in Beyla despite performing all steps as instructed.
Here are the specifics of my environment and the steps I’ve followed:
Environment:
Steps Taken:
Run an Instrumentable Node.js Service:
curl -OL https://raw.githubusercontent.com/grafana/beyla/main/examples/quickstart/nodejs/package.json curl -OL https://raw.githubusercontent.com/grafana/beyla/main/examples/quickstart/nodejs/quickstart.js npm install && npm startDownload Beyla:
Downloaded the latest Beyla executable from the Beyla releases page. Uncompressed and placed the Beyla executable in my
$PATH.Run Beyla with Minimal Configuration:
Test the Service:
With Beyla and the Node.js service running, I made an HTTP request:
Expected Output:
Beyla should output traces to the standard output, similar to:
Current Issue:
I am not receiving any trace output in the Beyla console after making the HTTP request, even waited for sometime. The Beyla console output after starting is:
Request for Assistance:
Please let me know if there are any additional steps I should take or if there is something I might be missing.
The text was updated successfully, but these errors were encountered: