Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

the otel-go-instrumentation not works as expected in ubuntu 22.04 #141

Closed
tanghengjian opened this issue May 4, 2023 · 2 comments · Fixed by #150
Closed

the otel-go-instrumentation not works as expected in ubuntu 22.04 #141

tanghengjian opened this issue May 4, 2023 · 2 comments · Fixed by #150
Labels
bug Something isn't working

Comments

@tanghengjian
Copy link
Contributor

Describe the bug

the otel-go-instrumentation not works as expected in ubuntu 22.04 local virtual machine from vmware.

Environment

  • OS: linux
  • Go Version: [e.g. 1.20.4]
  • Ubuntu 22.04.1,Linux version 5.19.0-41-generic

To Reproduce

Steps to reproduce the behavior:
follow the docs (https://github.com/open-telemetry/opentelemetry-go-instrumentation/tree/main/docs/getting-started)

kubectl apply -f emojivoto-instrumented.yaml -n emojivoto

the otel-go-instrumentation not works as expected.

enter kind's docker and

crictl ps -a
CONTAINER           IMAGE               CREATED             STATE               NAME                               ATTEMPT             POD ID              POD
c6ad06edfb1fc       0fc3761f3f87d       3 minutes ago       Exited              emojivoto-emoji-instrumentation    25                  b41b8e14bc802       emoji-5c59d4f5f9-8g6nq
431bdddf06d93       0fc3761f3f87d       3 minutes ago       Exited              emojivoto-web-instrumentation      25                  2bbe9a5bffdbb       web-7d9f79f7d7-gwbtt
39b22e4c6f6cf       0fc3761f3f87d       3 minutes ago       Exited              emojivoto-voting-instrumentation   25                  603e0f2e4ac92       voting-574dff6f47-wkd5l

and search first instrumentation's log:

crictl logs c6ad06edfb1fc
{"level":"info","ts":1683201490.9597812,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
{"level":"info","ts":1683201490.959896,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
{"level":"info","ts":1683201492.962331,"caller":"process/discover.go:55","msg":"found process","pid":19}
{"level":"info","ts":1683201492.963499,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":19}
{"level":"info","ts":1683201492.9638128,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":20}
{"level":"info","ts":1683201492.964077,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":21}
{"level":"info","ts":1683201492.9644198,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":22}
{"level":"info","ts":1683201492.9648137,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23}
{"level":"info","ts":1683201492.9651833,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":24}
{"level":"info","ts":1683201492.9655643,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":25}
{"level":"info","ts":1683201492.9658918,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":44}
{"level":"info","ts":1683201492.9662254,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":448}
{"level":"info","ts":1683201492.982999,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":19}
{"level":"info","ts":1683201492.9832432,"caller":"process/analyze.go:139","msg":"mmaped remote memory","start_addr":"7F7175000000","end_addr":"7F7176800000"}
{"level":"info","ts":1683201492.9944782,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2870464,"returns":[2870541]}
{"level":"info","ts":1683201492.9962378,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"google.golang.org/grpc/internal/transport.(*http2Client).createHeaderFields","start":4254816,"returns":[4260087,4266761,4266816]}
{"level":"info","ts":1683201492.9970098,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"google.golang.org/grpc/internal/transport.(*http2Server).operateHeaders","start":4296672,"returns":[4297106,4298064,4298299,4298532,4299573,4301293]}
{"level":"info","ts":1683201492.9972656,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"google.golang.org/grpc.(*ClientConn).Invoke","start":4758080,"returns":[4758386,4758556]}
{"level":"info","ts":1683201492.9977455,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"google.golang.org/grpc.(*Server).handleStream","start":4857024,"returns":[4857689,4859097,4859906,4860203,4860308]}
{"level":"info","ts":1683201492.9978814,"caller":"cli/main.go:79","msg":"target process analysis completed","pid":19,"go_version":"1.15.0","dependencies":{"contrib.go.opencensus.io/exporter/ocagent":"v0.6.0","github.com/beorn7/perks":"v1.0.1","github.com/census-instrumentation/opencensus-proto":"v0.2.1","github.com/cespare/xxhash/v2":"v2.1.1","github.com/golang/groupcache":"v0.0.0-20200121045136-8c9f03a8e57e","github.com/golang/protobuf":"v1.4.0","github.com/grpc-ecosystem/go-grpc-prometheus":"v1.2.0","github.com/grpc-ecosystem/grpc-gateway":"v1.14.4","github.com/matttproud/golang_protobuf_extensions":"v1.0.1","github.com/prometheus/client_golang":"v1.6.0","github.com/prometheus/client_model":"v0.2.0","github.com/prometheus/common":"v0.9.1","github.com/prometheus/procfs":"v0.0.11","go.opencensus.io":"v0.22.3","golang.org/x/net":"v0.0.0-20200425230154-ff2c4b7c35a0","golang.org/x/sync":"v0.0.0-20200317015054-43a5402ce75a","golang.org/x/sys":"v0.0.0-20200430082407-1f5687305801","golang.org/x/text":"v0.3.2","google.golang.org/api":"v0.22.0","google.golang.org/genproto":"v0.0.0-20200430143042-b979b6f78d84","google.golang.org/grpc":"v1.29.1","google.golang.org/protobuf":"v1.21.0"},"total_functions_found":5}
{"level":"info","ts":1683201492.9980018,"caller":"cli/main.go:85","msg":"invoking instrumentors"}
{"level":"info","ts":1683201493.012342,"logger":"allocator","caller":"allocator/allocator_linux.go:43","msg":"Loading allocator","start_addr":140125270966272,"end_addr":140125296132096}
{"level":"info","ts":1683201493.0141346,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"net/http"}
{"level":"info","ts":1683201493.0148523,"caller":"inject/injector.go:91","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"is_registers_abi":false,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
{"level":"info","ts":1683201493.037925,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"google.golang.org/grpc"}
{"level":"info","ts":1683201493.0421581,"caller":"inject/injector.go:91","msg":"Injecting variables","vars":{"clientconn_target_ptr_pos":24,"end_addr":140125296132096,"is_registers_abi":false,"start_addr":140125270966272,"total_cpus":2}}
{"level":"error","ts":1683201493.0505607,"caller":"instrumentors/runner.go:88","msg":"error while loading instrumentors, cleaning up","name":"google.golang.org/grpc","error":"field UprobeHttp2ClientCreateHeaderFields: program uprobe_Http2Client_CreateHeaderFields: load program: permission denied: 983: (bf) r2 = r0                     ; R0=scalar(id=53) R2_w=scalar(id=53): 984: (67) r2 <<= 32                   ; R2_w=scalar(smax=9223372032559808512,umax=18446744069414584320,var_off=(0x0; 0xffffffff00000000),s32_min=0,s3 (truncated, 1045 line(s) omitted)","stacktrace":"go.opentelemetry.io/auto/pkg/instrumentors.(*Manager).load\n\t/app/pkg/instrumentors/runner.go:88\ngo.opentelemetry.io/auto/pkg/instrumentors.(*Manager).Run\n\t/app/pkg/instrumentors/runner.go:36\nmain.main\n\t/app/cli/main.go:86\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
{"level":"info","ts":1683201493.050718,"caller":"server/probe.go:242","msg":"closing gRPC server instrumentor"}
{"level":"info","ts":1683201493.0507877,"caller":"server/probe.go:217","msg":"closing net/http instrumentor"}
{"level":"info","ts":1683201493.0802684,"caller":"grpc/probe.go:241","msg":"closing gRPC instrumentor"}
{"level":"error","ts":1683201493.0803745,"caller":"cli/main.go:88","msg":"error while running instrumentors","error":"field UprobeHttp2ClientCreateHeaderFields: program uprobe_Http2Client_CreateHeaderFields: load program: permission denied: 983: (bf) r2 = r0                     ; R0=scalar(id=53) R2_w=scalar(id=53): 984: (67) r2 <<= 32                   ; R2_w=scalar(smax=9223372032559808512,umax=18446744069414584320,var_off=(0x0; 0xffffffff00000000),s32_min=0,s3 (truncated, 1045 line(s) omitted)","stacktrace":"main.main\n\t/app/cli/main.go:88\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}

Expected behavior

everything works as expected

Additional context

  emojivoto-emoji-instrumentation:
    Container ID:   containerd://d90fdecaaaf9d70b0dc8b5e798a2894325d99094394eea0766e82cb519de746d
    Image:          otel-go-instrumentation
    Image ID:       docker.io/library/import-2023-05-04@sha256:e1e0a2ede7b8d3edfc5eb3735ba942d48ad60a5366f484a9ef42b38ac3fb36da
    Port:           <none>
    Host Port:      <none>
    State:          Waiting
      Reason:       CrashLoopBackOff
    Last State:     Terminated
      Reason:       Completed
      Exit Code:    0
      Started:      Thu, 04 May 2023 13:13:27 +0100
      Finished:     Thu, 04 May 2023 13:13:30 +0100
    Ready:          False
    Restart Count:  28
    Environment:
      OTEL_GO_AUTO_TARGET_EXE:      /usr/local/bin/emojivoto-emoji-svc
      OTEL_EXPORTER_OTLP_ENDPOINT:  http://jaeger:4317
      OTEL_SERVICE_NAME:            emojivoto-emoji
    Mounts:
      /var/run/secrets/kubernetes.io/serviceaccount from kube-api-access-d4rfb (ro)
Conditions:
  Type              Status
  Initialized       True 
  Ready             False 
  ContainersReady   False 
  PodScheduled      True 
Volumes:
  kube-api-access-d4rfb:
    Type:                    Projected (a volume that contains injected data from multiple sources)
    TokenExpirationSeconds:  3607
    ConfigMapName:           kube-root-ca.crt
    ConfigMapOptional:       <nil>
    DownwardAPI:             true
QoS Class:                   Burstable
Node-Selectors:              <none>
Tolerations:                 node.kubernetes.io/not-ready:NoExecute op=Exists for 300s
                             node.kubernetes.io/unreachable:NoExecute op=Exists for 300s
Events:
  Type     Reason   Age                  From     Message
  ----     ------   ----                 ----     -------
  Warning  BackOff  1s (x548 over 119m)  kubelet  Back-off restarting failed container
@tanghengjian tanghengjian added the bug Something isn't working label May 4, 2023
@t00350320
Copy link

@JamieDanielson PTAL

@JamieDanielson
Copy link
Member

Unfortunately this is a known issue with the gRPC instrumentation probe that we are working on. This is the issue reported in #78, and referenced in the emojivoto PR update #129. We're also working on e2e tests for gRPC instrumentation in #106 so once this is fixed we can monitor for regressions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants