search

grafana / beyla

eBPF-based autoinstrumentation of web applications and network metrics
https://grafana.com/oss/beyla-ebpf/
Apache License 2.0
1.44k stars 102 forks source link

Quickstart: instrument a Node.js service with Beyla not tracing logs on HTTP call #1093

Closed sandeepkoseai closed 3 months ago

sandeepkoseai commented 3 months ago

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:

  1. 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 start

  2. Download Beyla: Downloaded the latest Beyla executable from the Beyla releases page. Uncompressed and placed the Beyla executable in my $PATH.

  3. Run Beyla with Minimal Configuration:

    export BEYLA_SERVICE_NAME=quickstart
export BEYLA_OPEN_PORT=8080
export BEYLA_TRACE_PRINTER=text
sudo -E beyla

  4. Test the Service: With Beyla and the Node.js service running, I made an HTTP request:

    curl http://localhost:8080/foo

Expected Output: Beyla should output traces to the standard output, similar to:

2024-01-09 10:31:33.19103133 (3.254486ms[3.254486ms]) 200 GET /foo [127.0.0.1]->[127.0.0.1:8080]
size:80B svc=[{quickstart nodejs lima-ubuntu-lts-5074}] traceparent=[00-46214bd23716280eef43cf798dbe5522-0000000000000000-01]

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:

time=2024-08-15T08:53:17.121Z level=INFO msg="Grafana Beyla" Version=v1.7.0 Revision=9d07bfb "OpenTelemetry SDK Version"=1.28.0
time=2024-08-15T08:53:17.124Z level=INFO msg="got host ID" component=ContextInfo func=fetchHostID fetcher=AWS hostID=i-0ea5b51aa1675a5c6
time=2024-08-15T08:53:17.124Z level=INFO msg="starting Beyla in Application Observability mode"
time=2024-08-15T08:53:17.130Z level=INFO msg="using hostname" component=traces.ReadDecorator function=instance_ID_hostNamePIDDecorator hostname=ip-x.x.x.x.us-east-2.compute.internal
time=2024-08-15T08:53:17.131Z level=INFO msg="Starting main node" component=beyla.Instrumenter
time=2024-08-15T08:53:17.326Z level=INFO msg="instrumenting process" component=discover.TraceAttacher cmd=/usr/bin/node pid=955982

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.

grcevski commented 3 months ago

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:

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.

sandeepkoseai commented 3 months ago

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:}" 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:}}" 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: 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:}" 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: 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:}" 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:}" 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: 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: 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: 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: 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:}" 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:}" 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:}" 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:}" 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:}" 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 https://github.com/grafana/beyla/issues/1093#issuecomment-2291235799, or unsubscribe https://github.com/notifications/unsubscribe-auth/BKRSU5ANZR2R2HSRYIB4AVLZRSR2HAVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJRGIZTKNZZHE . You are receiving this because you were mentioned.Message ID: @.***>

grcevski commented 3 months ago

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 https://github.com/grafana/beyla/pull/1086. CC @rafaelroquetto

sandeepkoseai commented 3 months ago

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 https://github.com/grafana/beyla/pull/1086. CC @rafaelroquetto https://github.com/rafaelroquetto

— Reply to this email directly, view it on GitHub https://github.com/grafana/beyla/issues/1093#issuecomment-2291839171, or unsubscribe https://github.com/notifications/unsubscribe-auth/BKRSU5HOPSVSRT5FCL2W56TZRTSB7AVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJRHAZTSMJXGE . You are receiving this because you were mentioned.Message ID: @.***>

rafaelroquetto commented 3 months ago

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? You can do it with git rev-parse HEAD. Thanks!

sandeepkoseai commented 3 months ago

He Fafael,

Please find suggested commands output below:

$ git rev-parse HEAD ef146163253d6644e3b4db861ea8eb130ca7fdb2

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 https://github.com/grafana/beyla/issues/1093#issuecomment-2293515863, or unsubscribe https://github.com/notifications/unsubscribe-auth/BKRSU5EFQRHBGFLLCQB6NCTZRX5IRAVCNFSM6AAAAABMR3I22KVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEOJTGUYTKOBWGM . You are receiving this because you were mentioned.Message ID: @.***>

grcevski commented 3 months ago

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 make, the new Beyla executable will be in bin/beyla. I wonder if it's simply an issue that you are still picking up the old 1.7.0 branch of Beyla?

When you run Beyla we print the git hash as the first line in the version, e.g.:

time=2024-08-15T16:13:48.846Z level=INFO msg="Grafana Beyla" Version=v1.7.0
Revision=9d07bfb "OpenTelemetry SDK Version"=1.28.0
sandeepkoseai commented 3 months ago

Hi Nikola,

I performed a fresh clone on the main branch and ran the make command, but I encountered several issues. Here are the details:

1. Initial Error: llvm-strip Not Found

2. Subsequent Error: clang Not Found

3. Current Issue: Test Failures

Could you please assist with resolving the test failures (#3) or provide the bin/beyla package, if possible?

Best regards,
Sandeep Kose

grcevski commented 3 months ago

Hi @sandeepkoseai, you can ignore the test failures, if you'd like you can also just run make dev which will build without the tests.

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

v1.7.1-alpha.1

sandeepkoseai commented 3 months ago

Hello Team,

Thank you for your help! The issue has been resolved with the release of version v1.7.1-alpha.1.