search

open-telemetry / opentelemetry-go-instrumentation

OpenTelemetry Auto Instrumentation using eBPF
https://opentelemetry.io
Apache License 2.0
494 stars 77 forks source link

The "go-auto" container of example app "rolldice" crashes #265

Open liurui-1 opened 1 year ago

liurui-1 commented 1 year ago

Describe the bug

I am running the example name "rolldice" in this "opentelemetry-go-instrumentation". I can successfully run "docker compose up" . When I ran command "curl localhost:8080/rolldice", I can see the good responses in docker logs: rolldice-rolldice-1 | 2023-08-23T11:27:41.658Z INFO app/main.go:41 rolldice called {"dice": 5} rolldice-rolldice-1 | 2023-08-23T11:27:42.389Z INFO app/main.go:41 rolldice called {"dice": 4} rolldice-rolldice-1 | 2023-08-23T11:27:43.053Z INFO app/main.go:41 rolldice called {"dice": 4} rolldice-rolldice-1 | 2023-08-23T11:27:43.678Z INFO app/main.go:41 rolldice called {"dice": 4} But when I visit Jaeger at http://ip:16686/ , I can only see one service named "jaeger-query". It seems the spans from rolldice are not sent to Jaeger.

After checking the configuration, I found the "go-auto" container of this example failed. Here is the error message:

rolldice-go-auto-1   | {"level":"info","ts":1692789922.232622,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1692789922.2327313,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2423403,"caller":"process/discover.go:55","msg":"found process","pid":5122}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2448523,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5122}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.244986,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5202}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2450695,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5203}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2451756,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5204}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2452333,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5205}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.245288,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":5206}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2608674,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":5122}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.261032,"caller":"process/analyze.go:139","msg":"mmaped remote memory","start_addr":"7FA7A4FBD000","end_addr":"7FA7A67BD000"}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.265787,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2221504,"returns":[2221560]}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.26596,"caller":"cli/main.go:79","msg":"target process analysis completed","pid":5122,"go_version":"1.20.7","dependencies":{"go.uber.org/atomic":"v1.7.0","go.uber.org/multierr":"v1.6.0","go.uber.org/zap":"v1.24.0"},"total_functions_found":1}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.266036,"caller":"cli/main.go:85","msg":"invoking instrumentors"}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.2665777,"logger":"allocator","caller":"allocator/allocator_linux.go:39","msg":"Loading allocator","start_addr":140358004232192,"end_addr":140358029398016}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.266734,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"net/http"}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.268446,"caller":"inject/injector.go:102","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"headers_ptr_pos":56,"is_registers_abi":true,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
rolldice-go-auto-1   | {"level":"error","ts":1692789924.3645194,"caller":"instrumentors/runner.go:88","msg":"error while loading instrumentors, cleaning up","name":"net/http","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}
rolldice-go-auto-1   | {"level":"info","ts":1692789924.3646195,"caller":"server/probe.go:243","msg":"closing net/http instrumentor"}
rolldice-go-auto-1   | {"level":"error","ts":1692789924.3646574,"caller":"cli/main.go:88","msg":"error while running instrumentors","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}
rolldice-jaeger-1    | {"level":"info","ts":1692789924.3849401,"caller":"grpclog/component.go:71","msg":"[transport]transport: closing: EOF","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1692789924.385165,"caller":"grpclog/component.go:71","msg":"[transport]transport: loopyWriter exited. Closing connection. Err: transport closed by client","system":"grpc","grpc_log":true}
rolldice-go-auto-1 exited with code 0

I got some comments from Jamie Danielson to change the "docker-compose.yaml" file. Change the "go-auto" to use image directly. Here is the new configuration:

  go-auto:
    depends_on:
      - rolldice
    image: ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.2.2-alpha
    privileged: true
    pid: "host"
    environment:
      - OTEL_EXPORTER_OTLP_ENDPOINT=http://jaeger:4317
      - OTEL_GO_AUTO_TARGET_EXE=/app/main
      - OTEL_SERVICE_NAME=rolldice
      - OTEL_PROPAGATORS=tracecontext,baggage
    volumes:
      - shared-data:/app
      - /proc:/host/proc

When I run run "docker compose up" again, I can see the problem is fixed.

Environment

To Reproduce

Steps to reproduce the behavior: Simply Run following commands in above environment:

cd /opentelemetry-go-instrumentation/examples/rolldice
docker compose up

Expected behavior

The "go-auto" container does not crash.

RonFed commented 1 year ago

If I understand correctly, this happens for you on the latest main branch ? Can you please include the output of uname -r ?

liurui-1 commented 1 year ago

@RonFed Yes it is the latest main branch

# uname -r
5.4.0-156-generic
liurui-1 commented 1 year ago

Here is the error message when running this "rolldice" in my test machine with latest image: ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.3.0-alpha

rolldice-go-auto-1   | {"level":"info","ts":1695776365.8909197,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695776365.8919284,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9030948,"caller":"process/discover.go:55","msg":"found process","pid":23716}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9048617,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23716}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9050202,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23779}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9051666,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23780}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9053006,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23781}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9058182,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23782}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9059122,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":23783}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9176266,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":23716}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9181762,"caller":"process/analyze.go:139","msg":"mmaped remote memory","start_addr":"7FA894FFD000","end_addr":"7FA8967FD000"}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9276805,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2221504,"returns":[2221560]}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9280427,"caller":"cli/main.go:79","msg":"target process analysis completed","pid":23716,"go_version":"1.20.7","dependencies":{"go.uber.org/atomic":"v1.7.0","go.uber.org/multierr":"v1.6.0","go.uber.org/zap":"v1.24.0"},"total_functions_found":1}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.92816,"caller":"cli/main.go:85","msg":"invoking instrumentors"}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.92898,"logger":"allocator","caller":"allocator/allocator_linux.go:39","msg":"Loading allocator","start_addr":140362031026176,"end_addr":140362056192000}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9291828,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"net/http"}
rolldice-go-auto-1   | {"level":"info","ts":1695776367.9316201,"caller":"inject/injector.go:102","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"headers_ptr_pos":56,"is_registers_abi":true,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
rolldice-go-auto-1   | {"level":"error","ts":1695776368.0481024,"caller":"instrumentors/runner.go:88","msg":"error while loading instrumentors, cleaning up","name":"net/http","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 line(s) omitted)","stacktrace":"go.opentelemetry.io/auto/internal/pkg/instrumentors.(*Manager).load\n\t/app/internal/pkg/instrumentors/runner.go:88\ngo.opentelemetry.io/auto/internal/pkg/instrumentors.(*Manager).Run\n\t/app/internal/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"}
rolldice-go-auto-1   | {"level":"info","ts":1695776368.0695193,"caller":"server/probe.go:243","msg":"closing net/http instrumentor"}
rolldice-go-auto-1   | {"level":"error","ts":1695776368.0696433,"caller":"cli/main.go:88","msg":"error while running instrumentors","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}

I can successfully run this example app with ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.2.2-alpha

My test machine:

# uname -a
Linux dk-liurui1.fyre.ibm.com 5.4.0-156-generic #173-Ubuntu SMP Tue Jul 11 07:25:22 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
RonFed commented 1 year ago

@liurui-1 Can you please try this branch on your setup ? https://github.com/RonFed/opentelemetry-go-instrumentation_fork/tree/zero_stack_before_helper

liurui-1 commented 1 year ago

hi @RonFed , I tried zero_stack_before_helper branch. The "go-auto" container was failed with following error logs:

rolldice-go-auto-1   | {"level":"info","ts":1695826660.8530214,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695826660.8531685,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8612928,"caller":"process/discover.go:55","msg":"found process","pid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8622892,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8624837,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31407}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8626378,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31408}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.862738,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31409}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.862908,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31410}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8630064,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31411}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8748329,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8750615,"caller":"process/analyze.go:139","msg":"mmaped remote memory","start_addr":"7F53AC686000","end_addr":"7F53ADE86000"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8813076,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2221504,"returns":[2221560]}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.881497,"caller":"cli/main.go:79","msg":"target process analysis completed","pid":31339,"go_version":"1.20.7","dependencies":{"go.uber.org/atomic":"v1.7.0","go.uber.org/multierr":"v1.6.0","go.uber.org/zap":"v1.24.0"},"total_functions_found":1}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.881582,"caller":"cli/main.go:85","msg":"invoking instrumentors"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8820946,"logger":"allocator","caller":"allocator/allocator_linux.go:39","msg":"Loading allocator","start_addr":139997351534592,"end_addr":139997376700416}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8823407,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"net/http"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.883774,"caller":"inject/injector.go:102","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"headers_ptr_pos":56,"is_registers_abi":true,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
rolldice-go-auto-1   | {"level":"error","ts":1695826663.0230265,"caller":"instrumentors/runner.go:88","msg":"error while loading instrumentors, cleaning up","name":"net/http","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}
rolldice-go-auto-1   | {"level":"info","ts":1695826663.0231414,"caller":"server/probe.go:243","msg":"closing net/http instrumentor"}
rolldice-go-auto-1   | {"level":"error","ts":1695826663.0231638,"caller":"cli/main.go:88","msg":"error while running instrumentors","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}

Then I revised "docker-compose.yaml" file to replace:

     build:
       context: ../..
       dockerfile: Dockerfile

with

image: ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.3.0-alpha

Then I saw the rolldice-rolldice container failed to start with following error messages:

rolldice-rolldice-1  | {"level":"info","ts":1695827260.7911618,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-rolldice-1  | {"level":"error","ts":1695827260.7912858,"caller":"cli/main.go:40","msg":"invalid target args","error":"target binary path not specified, please specify OTEL_GO_AUTO_TARGET_EXE env variable","stacktrace":"main.main\n\t/app/cli/main.go:40\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
... ...
rolldice-rolldice-1 exited with code 0
rolldice-go-auto-1   | {"level":"info","ts":1695827261.6018295,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695827261.6019938,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
... ...
RonFed commented 1 year ago

hi @RonFed , I tried zero_stack_before_helper branch. The "go-auto" container was failed with following error logs:

rolldice-go-auto-1   | {"level":"info","ts":1695826660.8530214,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695826660.8531685,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8612928,"caller":"process/discover.go:55","msg":"found process","pid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8622892,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8624837,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31407}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8626378,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31408}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.862738,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31409}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.862908,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31410}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8630064,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":31411}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8748329,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":31339}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8750615,"caller":"process/analyze.go:139","msg":"mmaped remote memory","start_addr":"7F53AC686000","end_addr":"7F53ADE86000"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8813076,"caller":"process/analyze.go:168","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2221504,"returns":[2221560]}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.881497,"caller":"cli/main.go:79","msg":"target process analysis completed","pid":31339,"go_version":"1.20.7","dependencies":{"go.uber.org/atomic":"v1.7.0","go.uber.org/multierr":"v1.6.0","go.uber.org/zap":"v1.24.0"},"total_functions_found":1}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.881582,"caller":"cli/main.go:85","msg":"invoking instrumentors"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8820946,"logger":"allocator","caller":"allocator/allocator_linux.go:39","msg":"Loading allocator","start_addr":139997351534592,"end_addr":139997376700416}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.8823407,"caller":"instrumentors/runner.go:85","msg":"loading instrumentor","name":"net/http"}
rolldice-go-auto-1   | {"level":"info","ts":1695826662.883774,"caller":"inject/injector.go:102","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"headers_ptr_pos":56,"is_registers_abi":true,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
rolldice-go-auto-1   | {"level":"error","ts":1695826663.0230265,"caller":"instrumentors/runner.go:88","msg":"error while loading instrumentors, cleaning up","name":"net/http","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}
rolldice-go-auto-1   | {"level":"info","ts":1695826663.0231414,"caller":"server/probe.go:243","msg":"closing net/http instrumentor"}
rolldice-go-auto-1   | {"level":"error","ts":1695826663.0231638,"caller":"cli/main.go:88","msg":"error while running instrumentors","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 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"}

Then I revised "docker-compose.yaml" file to replace:

     build:
       context: ../..
       dockerfile: Dockerfile

with

image: ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.3.0-alpha

Then I saw the rolldice-rolldice container failed to start with following error messages:

rolldice-rolldice-1  | {"level":"info","ts":1695827260.7911618,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-rolldice-1  | {"level":"error","ts":1695827260.7912858,"caller":"cli/main.go:40","msg":"invalid target args","error":"target binary path not specified, please specify OTEL_GO_AUTO_TARGET_EXE env variable","stacktrace":"main.main\n\t/app/cli/main.go:40\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
... ...
rolldice-rolldice-1 exited with code 0
rolldice-go-auto-1   | {"level":"info","ts":1695827261.6018295,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695827261.6019938,"caller":"opentelemetry/controller.go:119","msg":"Establishing connection to OTLP receiver ..."}
... ...

Did you ran docker compose build before re-running the example? (to make sure the new images are being built, not taking the old ones)

liurui-1 commented 1 year ago

Hi @RonFed , I forgot to run "docker compose build".

While I tested with following 2 commands in the zero_stack_before_helper branch:

docker compose build
docker compose up

Now the problem is similar. The "rolldice-rolldice" container exits.

Following are log messages of docker compose up:

rolldice-rolldice-1  | {"level":"info","ts":1695892819.6119125,"caller":"cli/main.go:37","msg":"starting Go OpenTelemetry Agent ..."}
rolldice-rolldice-1  | {"level":"error","ts":1695892819.6120028,"caller":"cli/main.go:40","msg":"invalid target args","error":"target binary path not specified, please specify OTEL_GO_AUTO_TARGET_EXE env variable","stacktrace":"main.main\n\t/app/cli/main.go:40\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-jaeger-1    | {"level":"info","ts":1695892819.964058,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to IDLE","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1695892819.9641619,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc0001b2cc0, {IDLE connection error: desc = \"transport: Error while dialing: dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1695892819.9641917,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel Connectivity change to IDLE","system":"grpc","grpc_log":true}
rolldice-rolldice-1 exited with code 0
rolldice-go-auto-1   | {"level":"info","ts":1695892820.513783,"caller":"cli/main.go:36","msg":"building OpenTelemetry Go instrumentation ..."}
rolldice-go-auto-1   | {"level":"info","ts":1695892822.5266926,"caller":"process/discover.go:59","msg":"process not found yet, trying again soon","exe_path":"/app/main"}
rolldice-go-auto-1   | {"level":"info","ts":1695892824.5236254,"caller":"process/discover.go:59","msg":"process not found yet, trying again soon","exe_path":"/app/main"}
rolldice-go-auto-1   | {"level":"info","ts":1695892826.5245879,"caller":"process/discover.go:59","msg":"process not found yet, trying again soon","exe_path":"/app/main"}
rolldice-go-auto-1   | {"level":"info","ts":1695892828.5255032,"caller":"process/discover.go:59","msg":"process not found yet, trying again soon","exe_path":"/app/main"}
rolldice-go-auto-1   | {"level":"info","ts":1695892830.5212486,"caller":"process/discover.go:59","msg":"process not found yet, trying again soon","exe_path":"/app/main"}
RonFed commented 1 year ago

@liurui-1 The error in the log you attached means the environment variable OTEL_GO_AUTO_TARGET_EXE is not defined. Considering the docker-compose.yaml file contains the following: `

liurui-1 commented 1 year ago

@RonFed In the zero_stack_before_helper branch, I can see the file docker-compose.yaml, we can see OTEL_GO_AUTO_TARGET_EXE environment variable is defined for container go-auto. The current problem is that rolldice container exits unexpectedly.

 ⠿ Container rolldice-jaeger-1    Created                                                                                                                     0.0s
 ⠿ Container rolldice-rolldice-1  Created                                                                                                                     0.0s
 ⠿ Container rolldice-go-auto-1   Created                                                                                                                     0.0s
Attaching to rolldice-go-auto-1, rolldice-jaeger-1, rolldice-rolldice-1
rolldice-jaeger-1    | 2023/09/29 17:26:13 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8276298,"caller":"flags/service.go:119","msg":"Mounting metrics handler on admin server","route":"/metrics"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8277676,"caller":"flags/service.go:125","msg":"Mounting expvar handler on admin server","route":"/debug/vars"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8408954,"caller":"flags/admin.go:129","msg":"Mounting health check on admin server","route":"/"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.84101,"caller":"flags/admin.go:143","msg":"Starting admin HTTP server","http-addr":":14269"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8410432,"caller":"flags/admin.go:121","msg":"Admin server started","http.host-port":"0.0.0.0:14269","health-status":"unavailable"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8518636,"caller":"memory/factory.go:66","msg":"Memory storage initialized","configuration":{"MaxTraces":0}}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8532298,"caller":"static/strategy_store.go:138","msg":"Loading sampling strategies","filename":"/etc/jaeger/sampling_strategies.json"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8949249,"caller":"channelz/funcs.go:340","msg":"[core][Server #1] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8951528,"caller":"server/grpc.go:104","msg":"Starting jaeger-collector gRPC server","grpc.host-port":"0.0.0.0:14250"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8951955,"caller":"server/http.go:56","msg":"Starting jaeger-collector HTTP server","http host-port":":14268"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8953664,"caller":"channelz/funcs.go:340","msg":"[core][Server #1 ListenSocket #2] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8956752,"caller":"server/zipkin.go:52","msg":"Not listening for Zipkin HTTP traffic, port not configured"}
rolldice-jaeger-1    | {"level":"warn","ts":1696008373.8957314,"caller":"internal/warning.go:51","msg":"Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks","documentation":"https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8958044,"caller":"channelz/funcs.go:340","msg":"[core][Server #3] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8958344,"caller":"otlpreceiver@v0.72.0/otlp.go:94","msg":"Starting GRPC server","endpoint":"0.0.0.0:4317"}
rolldice-jaeger-1    | {"level":"warn","ts":1696008373.8959653,"caller":"internal/warning.go:51","msg":"Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks","documentation":"https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8960094,"caller":"otlpreceiver@v0.72.0/otlp.go:112","msg":"Starting HTTP server","endpoint":"0.0.0.0:4318"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8960946,"caller":"grpc/builder.go:73","msg":"Agent requested insecure grpc connection to collector(s)"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8961372,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.896183,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] original dial target is: \":14250\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.89622,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] dial target \":14250\" parse failed: parse \":14250\": missing protocol scheme","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8962471,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8963063,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/:14250 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.896343,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Channel authority set to \"localhost:14250\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8965087,"caller":"channelz/funcs.go:340","msg":"[core][Server #3 ListenSocket #5] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.89652,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \":14250\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Type\": 0,\n      \"Metadata\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8965883,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Channel switches to new LB policy \"round_robin\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8966615,"caller":"grpclog/component.go:55","msg":"[balancer]base.baseBalancer: got new ClientConn state: {{[{\n  \"Addr\": \":14250\",\n  \"ServerName\": \"\",\n  \"Attributes\": null,\n  \"BalancerAttributes\": null,\n  \"Type\": 0,\n  \"Metadata\": null\n}] <nil> <nil>} <nil>}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8966935,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4 SubChannel #6] Subchannel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8967297,"caller":"grpclog/component.go:71","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[]}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8967507,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8968837,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4 SubChannel #6] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8969457,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4 SubChannel #6] Subchannel picks a new address \":14250\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8968928,"caller":"grpc/builder.go:113","msg":"Checking connection to collector"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.897012,"caller":"grpc/builder.go:124","msg":"Agent collector connection state change","dialTarget":":14250","status":"CONNECTING"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8970997,"caller":"grpclog/component.go:71","msg":"[balancer]base.baseBalancer: handle SubConn state change: 0xc000011cc8, CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8976948,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4 SubChannel #6] Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8977454,"caller":"grpclog/component.go:71","msg":"[balancer]base.baseBalancer: handle SubConn state change: 0xc000011cc8, READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.897805,"caller":"grpclog/component.go:71","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[0xc000011cc8:{{\n  \"Addr\": \":14250\",\n  \"ServerName\": \"\",\n  \"Attributes\": null,\n  \"BalancerAttributes\": null,\n  \"Type\": 0,\n  \"Metadata\": null\n}}]}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.897827,"caller":"channelz/funcs.go:340","msg":"[core][Channel #4] Channel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8978398,"caller":"grpc/builder.go:124","msg":"Agent collector connection state change","dialTarget":":14250","status":"READY"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8986094,"caller":"./main.go:256","msg":"Starting agent"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8989446,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8988945,"caller":"querysvc/query_service.go:135","msg":"Archive storage not created","reason":"archive storage not supported"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8991158,"caller":"app/flags.go:136","msg":"Archive storage not initialized"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.899653,"caller":"channelz/funcs.go:340","msg":"[core][Server #9] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.899731,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8997483,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] original dial target is: \":16685\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8997653,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] dial target \":16685\" parse failed: parse \":16685\": missing protocol scheme","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8997827,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.899816,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] parsed dial target is: {Scheme:passthrough Authority: URL:{Scheme:passthrough Opaque: User: Host: Path:/:16685 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.8998306,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel authority set to \"localhost:16685\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9001653,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \":16685\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Type\": 0,\n      \"Metadata\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9002278,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel switches to new LB policy \"pick_first\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9002564,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.900311,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9004664,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9004965,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel picks a new address \":16685\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9005923,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00032d890, {CONNECTING <nil>}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9008422,"caller":"grpclog/component.go:71","msg":"[core]Creating new client transport to \"{\\n  \\\"Addr\\\": \\\":16685\\\",\\n  \\\"ServerName\\\": \\\"localhost:16685\\\",\\n  \\\"Attributes\\\": null,\\n  \\\"BalancerAttributes\\\": null,\\n  \\\"Type\\\": 0,\\n  \\\"Metadata\\\": null\\n}\": connection error: desc = \"transport: Error while dialing: dial tcp :16685: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"warn","ts":1696008373.9009044,"caller":"channelz/funcs.go:342","msg":"[core][Channel #10 SubChannel #11] grpc: addrConn.createTransport failed to connect to {\n  \"Addr\": \":16685\",\n  \"ServerName\": \"localhost:16685\",\n  \"Attributes\": null,\n  \"BalancerAttributes\": null,\n  \"Type\": 0,\n  \"Metadata\": null\n}. Err: connection error: desc = \"transport: Error while dialing: dial tcp :16685: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9009464,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9009924,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00032d890, {TRANSIENT_FAILURE connection error: desc = \"transport: Error while dialing: dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.901033,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9018323,"caller":"app/static_handler.go:181","msg":"UI config path not provided, config file will not be watched"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.902492,"caller":"app/server.go:218","msg":"Query server started","http_addr":"0.0.0.0:16686","grpc_addr":"0.0.0.0:16685"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9025316,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9025595,"caller":"app/server.go:301","msg":"Starting GRPC server","port":16685,"addr":":16685"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.9025729,"caller":"app/server.go:282","msg":"Starting HTTP server","port":16686,"addr":":16686"}
rolldice-jaeger-1    | {"level":"info","ts":1696008373.902577,"caller":"channelz/funcs.go:340","msg":"[core][Server #9 ListenSocket #12] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-rolldice-1  | 2023-09-29T17:26:14.387Z INFO    app/main.go:61  starting http server    {"port": ":8080"}
rolldice-jaeger-1    | {"level":"info","ts":1696008374.9012547,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to IDLE","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008374.901369,"caller":"grpclog/component.go:71","msg":"[core]pickfirstBalancer: UpdateSubConnState: 0xc00032d890, {IDLE connection error: desc = \"transport: Error while dialing: dial tcp :16685: connect: connection refused\"}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008374.9013922,"caller":"channelz/funcs.go:340","msg":"[core][Channel #10] Channel Connectivity change to IDLE","system":"grpc","grpc_log":true}
rolldice-go-auto-1   | {"level":"info","ts":1696008375.1000192,"caller":"cli/main.go:36","msg":"building OpenTelemetry Go instrumentation ..."}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1096451,"caller":"process/discover.go:54","msg":"found process","pid":68980}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1097605,"caller":"opentelemetry/controller.go:111","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1112757,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":68980}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1113691,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":69060}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1114404,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":69061}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1114995,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":69062}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1115518,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":69063}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1116314,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":69064}
rolldice-go-auto-1   | {"level":"error","ts":1696008377.1146634,"caller":"process/analyze.go:103","msg":"Failed to mmap","pid":68980,"error":"writing data [15 5] to 403b2e: no such process","errorVerbose":"no such process\nwriting data [15 5] to 403b2e\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Syscall\n\t/app/internal/pkg/process/ptrace/ptrace_linux_amd64.go:98\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Mmap\n\t/app/internal/pkg/process/ptrace/ptrace_linux.go:211\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).remoteMmap\n\t/app/internal/pkg/process/analyze.go:101\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).Analyze\n\t/app/internal/pkg/process/analyze.go:134\ngo.opentelemetry.io/auto.NewInstrumentation\n\t/app/instrumentation.go:70\nmain.main\n\t/app/cli/main.go:37\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1598","stacktrace":"go.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).remoteMmap\n\t/app/internal/pkg/process/analyze.go:103\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).Analyze\n\t/app/internal/pkg/process/analyze.go:134\ngo.opentelemetry.io/auto.NewInstrumentation\n\t/app/instrumentation.go:70\nmain.main\n\t/app/cli/main.go:37\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-go-auto-1   | {"level":"info","ts":1696008377.1148095,"caller":"process/analyze.go:94","msg":"Detaching from process","pid":68980}
rolldice-go-auto-1   | {"level":"error","ts":1696008377.114851,"caller":"process/analyze.go:136","msg":"Failed to mmap","error":"writing data [15 5] to 403b2e: no such process","errorVerbose":"no such process\nwriting data [15 5] to 403b2e\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Syscall\n\t/app/internal/pkg/process/ptrace/ptrace_linux_amd64.go:98\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Mmap\n\t/app/internal/pkg/process/ptrace/ptrace_linux.go:211\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).remoteMmap\n\t/app/internal/pkg/process/analyze.go:101\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).Analyze\n\t/app/internal/pkg/process/analyze.go:134\ngo.opentelemetry.io/auto.NewInstrumentation\n\t/app/instrumentation.go:70\nmain.main\n\t/app/cli/main.go:37\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1598","stacktrace":"go.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).Analyze\n\t/app/internal/pkg/process/analyze.go:136\ngo.opentelemetry.io/auto.NewInstrumentation\n\t/app/instrumentation.go:70\nmain.main\n\t/app/cli/main.go:37\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-go-auto-1   | {"level":"error","ts":1696008377.1149268,"caller":"cli/main.go:39","msg":"failed to create instrumentation","error":"writing data [15 5] to 403b2e: no such process","errorVerbose":"no such process\nwriting data [15 5] to 403b2e\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Syscall\n\t/app/internal/pkg/process/ptrace/ptrace_linux_amd64.go:98\ngo.opentelemetry.io/auto/internal/pkg/process/ptrace.(*TracedProgram).Mmap\n\t/app/internal/pkg/process/ptrace/ptrace_linux.go:211\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).remoteMmap\n\t/app/internal/pkg/process/analyze.go:101\ngo.opentelemetry.io/auto/internal/pkg/process.(*Analyzer).Analyze\n\t/app/internal/pkg/process/analyze.go:134\ngo.opentelemetry.io/auto.NewInstrumentation\n\t/app/instrumentation.go:70\nmain.main\n\t/app/cli/main.go:37\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1598","stacktrace":"main.main\n\t/app/cli/main.go:39\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-jaeger-1    | {"level":"info","ts":1696008377.146185,"caller":"grpclog/component.go:71","msg":"[transport]transport: closing: connection error: desc = \"transport: http2Server.HandleStreams failed to receive the preface from client: read tcp 172.21.0.2:4317->172.21.0.4:45750: read: connection reset by peer\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696008377.14649,"caller":"channelz/funcs.go:340","msg":"[core][Server #3] grpc: Server.Serve failed to create ServerTransport: connection error: desc = \"transport: http2Server.HandleStreams failed to receive the preface from client: read tcp 172.21.0.2:4317->172.21.0.4:45750: read: connection reset by peer\"","system":"grpc","grpc_log":true}
rolldice-go-auto-1 exited with code 0
# docker ps
CONTAINER ID   IMAGE                             COMMAND                  CREATED         STATUS         PORTS                                                                                              NAMES
5ed2d92cef7e   rolldice-go-auto                  "/otel-go-instrument…"   4 minutes ago   Up 4 minutes                                                                                                      rolldice-go-auto-1
467193c15ef8   jaegertracing/all-in-one:latest   "/go/bin/all-in-one-…"   2 days ago      Up 4 minutes   5775/udp, 5778/tcp, 0.0.0.0:14268->14268/tcp, 6831-6832/udp, 14250/tcp, 0.0.0.0:16686->16686/tcp   rolldice-jaeger-1
RonFed commented 1 year ago

@liurui-1 I updated https://github.com/RonFed/opentelemetry-go-instrumentation_fork/tree/zero_stack_before_helper. Can you please pull, rebuild, and try again?

RonFed commented 1 year ago

@liurui-1 This is again the env var problem. If the yaml file is not changed this should not happen. In addition, I see that the target binary path not specified. message is printed by rolldice-rolldice-1 which is wrong, so I'm assuming somehow the files you are running are different from what I'm running.

liurui-1 commented 1 year ago

Hi @RonFed , I apologizes that withdrawn a message (10 minutes ago) because I found that I changed something in zero_stack_before_helper branch. This time all test steps are correct. I pulled with latest zero_stack_before_helper branch. Cleaned all docker compose jobs, docker containers and images. Ran following commands in the examples/rolldice directory:

docker compose build
docker compose up

Here is the error messages:

Attaching to rolldice-go-auto-1, rolldice-jaeger-1, rolldice-rolldice-1
rolldice-jaeger-1    | 2023/09/30 16:07:52 maxprocs: Leaving GOMAXPROCS=8: CPU quota undefined
rolldice-jaeger-1    | 2023/09/30 16:07:52 application version: git-commit=b876332c2248037435ca382667df5ea146967841, git-version=v1.49.0, build-date=2023-09-29T19:55:12Z
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8471782,"caller":"flags/service.go:119","msg":"Mounting metrics handler on admin server","route":"/metrics"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8472965,"caller":"flags/service.go:125","msg":"Mounting expvar handler on admin server","route":"/debug/vars"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8586216,"caller":"flags/admin.go:129","msg":"Mounting health check on admin server","route":"/"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.858801,"caller":"flags/admin.go:143","msg":"Starting admin HTTP server","http-addr":":14269"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8588643,"caller":"flags/admin.go:121","msg":"Admin server started","http.host-port":"0.0.0.0:14269","health-status":"unavailable"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8591676,"caller":"grpc@v1.58.2/clientconn.go:489","msg":"[core][Channel #1] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8592908,"caller":"grpc@v1.58.2/clientconn.go:1839","msg":"[core][Channel #1] original dial target is: \"localhost:4317\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8593504,"caller":"grpc@v1.58.2/clientconn.go:1846","msg":"[core][Channel #1] parsed dial target is: {URL:{Scheme:localhost Opaque:4317 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8593786,"caller":"grpc@v1.58.2/clientconn.go:1860","msg":"[core][Channel #1] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8594112,"caller":"grpc@v1.58.2/clientconn.go:1868","msg":"[core][Channel #1] parsed dial target is: {URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:4317 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.859434,"caller":"grpc@v1.58.2/clientconn.go:2001","msg":"[core][Channel #1] Channel authority set to \"localhost:4317\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8598032,"caller":"grpc@v1.58.2/resolver_conn_wrapper.go:246","msg":"[core][Channel #1] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \"localhost:4317\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Metadata\": null\n    }\n  ],\n  \"Endpoints\": [\n    {\n      \"Addresses\": [\n        {\n          \"Addr\": \"localhost:4317\",\n          \"ServerName\": \"\",\n          \"Attributes\": null,\n          \"BalancerAttributes\": null,\n          \"Metadata\": null\n        }\n      ],\n      \"Attributes\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8598928,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:180","msg":"[core][Channel #1] Channel switches to new LB policy \"pick_first\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8599837,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:298","msg":"[core][Channel #1 SubChannel #2] Subchannel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8600504,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #1] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8601487,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8602157,"caller":"grpc@v1.58.2/clientconn.go:1453","msg":"[core][Channel #1 SubChannel #2] Subchannel picks a new address \"localhost:4317\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8618279,"caller":"memory/factory.go:79","msg":"Memory storage initialized","configuration":{"MaxTraces":0}}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.862764,"caller":"static/strategy_store.go:138","msg":"Loading sampling strategies","filename":"/etc/jaeger/sampling_strategies.json"}
rolldice-jaeger-1    | {"level":"warn","ts":1696090072.8707004,"caller":"grpc@v1.58.2/clientconn.go:1515","msg":"[core][Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {Addr: \"localhost:4317\", ServerName: \"localhost:4317\", }. Err: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:4317: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8711126,"caller":"grpc@v1.58.2/clientconn.go:1340","msg":"[core][Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:4317: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8712773,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #1] Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.914085,"caller":"grpc@v1.58.2/server.go:667","msg":"[core][Server #3] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.914729,"caller":"server/grpc.go:104","msg":"Starting jaeger-collector gRPC server","grpc.host-port":"0.0.0.0:14250"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9147737,"caller":"server/http.go:56","msg":"Starting jaeger-collector HTTP server","http host-port":":14268"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9149528,"caller":"grpc@v1.58.2/server.go:855","msg":"[core][Server #3 ListenSocket #4] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9151707,"caller":"server/zipkin.go:52","msg":"Not listening for Zipkin HTTP traffic, port not configured"}
rolldice-jaeger-1    | {"level":"warn","ts":1696090072.9152288,"caller":"internal@v0.86.0/warning.go:40","msg":"Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks","documentation":"https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9153943,"caller":"grpc@v1.58.2/server.go:667","msg":"[core][Server #5] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9154232,"caller":"otlpreceiver@v0.86.0/otlp.go:83","msg":"Starting GRPC server","endpoint":"0.0.0.0:4317"}
rolldice-jaeger-1    | {"level":"warn","ts":1696090072.9161615,"caller":"internal@v0.86.0/warning.go:40","msg":"Using the 0.0.0.0 address exposes this server to every network interface, which may facilitate Denial of Service attacks","documentation":"https://github.com/open-telemetry/opentelemetry-collector/blob/main/docs/security-best-practices.md#safeguards-against-denial-of-service-attacks"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9162192,"caller":"otlpreceiver@v0.86.0/otlp.go:101","msg":"Starting HTTP server","endpoint":"0.0.0.0:4318"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9162135,"caller":"grpc@v1.58.2/server.go:855","msg":"[core][Server #5 ListenSocket #6] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9168634,"caller":"grpc/builder.go:74","msg":"Agent requested insecure grpc connection to collector(s)"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9169796,"caller":"grpc@v1.58.2/clientconn.go:489","msg":"[core][Channel #7] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9170392,"caller":"grpc@v1.58.2/clientconn.go:1839","msg":"[core][Channel #7] original dial target is: \"localhost:14250\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9171982,"caller":"grpc@v1.58.2/clientconn.go:1846","msg":"[core][Channel #7] parsed dial target is: {URL:{Scheme:localhost Opaque:14250 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.917235,"caller":"grpc@v1.58.2/clientconn.go:1860","msg":"[core][Channel #7] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9172628,"caller":"grpc@v1.58.2/clientconn.go:1868","msg":"[core][Channel #7] parsed dial target is: {URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:14250 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9176533,"caller":"grpc@v1.58.2/clientconn.go:2001","msg":"[core][Channel #7] Channel authority set to \"localhost:14250\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9179275,"caller":"grpc@v1.58.2/resolver_conn_wrapper.go:246","msg":"[core][Channel #7] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \"localhost:14250\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Metadata\": null\n    }\n  ],\n  \"Endpoints\": [\n    {\n      \"Addresses\": [\n        {\n          \"Addr\": \"localhost:14250\",\n          \"ServerName\": \"\",\n          \"Attributes\": null,\n          \"BalancerAttributes\": null,\n          \"Metadata\": null\n        }\n      ],\n      \"Attributes\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9180357,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:180","msg":"[core][Channel #7] Channel switches to new LB policy \"round_robin\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9180996,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:298","msg":"[core][Channel #7 SubChannel #8] Subchannel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9182122,"caller":"base/balancer.go:182","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[]}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.918291,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #7] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9182987,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #7 SubChannel #8] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9183462,"caller":"grpc@v1.58.2/clientconn.go:1453","msg":"[core][Channel #7 SubChannel #8] Subchannel picks a new address \"localhost:14250\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9185276,"caller":"grpc/builder.go:115","msg":"Checking connection to collector"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.918717,"caller":"grpc/builder.go:126","msg":"Agent collector connection state change","dialTarget":"localhost:14250","status":"CONNECTING"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9199693,"caller":"./main.go:259","msg":"Starting agent"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9201324,"caller":"querysvc/query_service.go:134","msg":"Archive storage not created","reason":"archive storage not supported"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9201646,"caller":"app/flags.go:144","msg":"Archive storage not initialized"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9206705,"caller":"app/agent.go:69","msg":"Starting jaeger-agent HTTP server","http-port":5778}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9210265,"caller":"grpc@v1.58.2/server.go:667","msg":"[core][Server #9] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9212728,"caller":"grpc@v1.58.2/clientconn.go:489","msg":"[core][Channel #10] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9213538,"caller":"grpc@v1.58.2/clientconn.go:1839","msg":"[core][Channel #10] original dial target is: \"localhost:16685\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9216022,"caller":"grpc@v1.58.2/clientconn.go:1846","msg":"[core][Channel #10] parsed dial target is: {URL:{Scheme:localhost Opaque:16685 User: Host: Path: RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9216387,"caller":"grpc@v1.58.2/clientconn.go:1860","msg":"[core][Channel #10] fallback to scheme \"passthrough\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9216614,"caller":"grpc@v1.58.2/clientconn.go:1868","msg":"[core][Channel #10] parsed dial target is: {URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:16685 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9216764,"caller":"grpc@v1.58.2/clientconn.go:2001","msg":"[core][Channel #10] Channel authority set to \"localhost:16685\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9217618,"caller":"grpc@v1.58.2/resolver_conn_wrapper.go:246","msg":"[core][Channel #10] Resolver state updated: {\n  \"Addresses\": [\n    {\n      \"Addr\": \"localhost:16685\",\n      \"ServerName\": \"\",\n      \"Attributes\": null,\n      \"BalancerAttributes\": null,\n      \"Metadata\": null\n    }\n  ],\n  \"Endpoints\": [\n    {\n      \"Addresses\": [\n        {\n          \"Addr\": \"localhost:16685\",\n          \"ServerName\": \"\",\n          \"Attributes\": null,\n          \"BalancerAttributes\": null,\n          \"Metadata\": null\n        }\n      ],\n      \"Attributes\": null\n    }\n  ],\n  \"ServiceConfig\": null,\n  \"Attributes\": null\n} (resolver returned new addresses)","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9219124,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:180","msg":"[core][Channel #10] Channel switches to new LB policy \"pick_first\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9220254,"caller":"grpc@v1.58.2/balancer_conn_wrappers.go:298","msg":"[core][Channel #10 SubChannel #11] Subchannel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9223025,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #10] Channel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.92246,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9225907,"caller":"grpc@v1.58.2/clientconn.go:1453","msg":"[core][Channel #10 SubChannel #11] Subchannel picks a new address \"localhost:16685\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9249446,"caller":"app/server.go:216","msg":"Query server started","http_addr":"0.0.0.0:16686","grpc_addr":"0.0.0.0:16685"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9250453,"caller":"healthcheck/handler.go:129","msg":"Health Check state change","status":"ready"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.925087,"caller":"app/server.go:299","msg":"Starting GRPC server","port":16685,"addr":":16685"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.925131,"caller":"grpc@v1.58.2/server.go:855","msg":"[core][Server #9 ListenSocket #13] ListenSocket created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9255288,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #7 SubChannel #8] Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9256508,"caller":"base/balancer.go:182","msg":"[roundrobin]roundrobinPicker: Build called with info: {map[SubConn(id:8):{{Addr: \"localhost:14250\", ServerName: \"\", }}]}","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.925711,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #7] Channel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9257314,"caller":"grpc/builder.go:126","msg":"Agent collector connection state change","dialTarget":"localhost:14250","status":"READY"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9259465,"caller":"app/server.go:280","msg":"Starting HTTP server","port":16686,"addr":":16686"}
rolldice-jaeger-1    | {"level":"warn","ts":1696090072.931621,"caller":"grpc@v1.58.2/clientconn.go:1515","msg":"[core][Channel #10 SubChannel #11] grpc: addrConn.createTransport failed to connect to {Addr: \"localhost:16685\", ServerName: \"localhost:16685\", }. Err: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:16685: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.931803,"caller":"grpc@v1.58.2/clientconn.go:1340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:16685: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.931858,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #10] Channel Connectivity change to TRANSIENT_FAILURE","system":"grpc","grpc_log":true}
rolldice-rolldice-1  | 2023-09-30T16:07:53.476Z INFO    app/main.go:61  starting http server    {"port": ":8080"}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.8714094,"caller":"grpc@v1.58.2/clientconn.go:1340","msg":"[core][Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE, last error: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:4317: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.8715112,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.8715298,"caller":"grpc@v1.58.2/clientconn.go:1453","msg":"[core][Channel #1 SubChannel #2] Subchannel picks a new address \"localhost:4317\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.8767037,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #1 SubChannel #2] Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.8767567,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #1] Channel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.932314,"caller":"grpc@v1.58.2/clientconn.go:1340","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to IDLE, last error: connection error: desc = \"transport: Error while dialing: dial tcp 127.0.0.1:16685: connect: connection refused\"","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.9324114,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to CONNECTING","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.932429,"caller":"grpc@v1.58.2/clientconn.go:1453","msg":"[core][Channel #10 SubChannel #11] Subchannel picks a new address \"localhost:16685\" to connect","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.9376075,"caller":"grpc@v1.58.2/clientconn.go:1338","msg":"[core][Channel #10 SubChannel #11] Subchannel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090073.9376674,"caller":"grpc@v1.58.2/clientconn.go:592","msg":"[core][Channel #10] Channel Connectivity change to READY","system":"grpc","grpc_log":true}
rolldice-go-auto-1   | {"level":"info","ts":1696090074.2012157,"caller":"cli/main.go:36","msg":"building OpenTelemetry Go instrumentation ..."}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2085896,"caller":"process/discover.go:55","msg":"found process","pid":92207}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2087228,"caller":"opentelemetry/controller.go:110","msg":"Establishing connection to OTLP receiver ..."}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2105541,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92207}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2108064,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92287}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2108803,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92288}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.211014,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92289}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2113376,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92290}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2114258,"caller":"ptrace/ptrace_linux.go:121","msg":"attach successfully","tid":92291}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.223819,"caller":"process/analyze.go:97","msg":"Detaching from process","pid":92207}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2240517,"caller":"process/analyze.go:142","msg":"mmaped remote memory","start_addr":"7F1FF9FFF000","end_addr":"7F1FFB7FF000"}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.230557,"caller":"process/analyze.go:171","msg":"found relevant function for instrumentation","function":"net/http.HandlerFunc.ServeHTTP","start":2150304,"returns":[2150350]}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2308707,"caller":"app/instrumentation.go:75","msg":"target process analysis completed","pid":92207,"go_version":"1.21.1","dependencies":{"go.uber.org/multierr":"v1.10.0","go.uber.org/zap":"v1.26.0"},"total_functions_found":1}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2312562,"caller":"cli/main.go:59","msg":"starting instrumentors..."}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2324765,"logger":"allocator","caller":"allocator/allocator_linux.go:39","msg":"Loading allocator","start_addr":139775315013632,"end_addr":139775340179456}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2326405,"caller":"instrumentors/runner.go:90","msg":"loading instrumentor","name":"net/http"}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.2350473,"caller":"inject/injector.go:101","msg":"Injecting variables","vars":{"ctx_ptr_pos":232,"headers_ptr_pos":56,"is_registers_abi":true,"method_ptr_pos":0,"path_ptr_pos":56,"url_ptr_pos":16}}
rolldice-go-auto-1   | {"level":"error","ts":1696090076.3068416,"caller":"instrumentors/runner.go:93","msg":"error while loading instrumentors, cleaning up","name":"net/http","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 line(s) omitted)","stacktrace":"go.opentelemetry.io/auto/internal/pkg/instrumentors.(*Manager).load\n\t/app/internal/pkg/instrumentors/runner.go:93\ngo.opentelemetry.io/auto/internal/pkg/instrumentors.(*Manager).Run\n\t/app/internal/pkg/instrumentors/runner.go:37\ngo.opentelemetry.io/auto.(*Instrumentation).Run\n\t/app/instrumentation.go:93\nmain.main\n\t/app/cli/main.go:60\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-go-auto-1   | {"level":"info","ts":1696090076.3069515,"caller":"server/probe.go:243","msg":"closing net/http instrumentor"}
rolldice-go-auto-1   | {"level":"error","ts":1696090076.306982,"caller":"cli/main.go:61","msg":"instrumentation crashed","error":"field UprobeServerMuxServeHTTP_Returns: program uprobe_ServerMux_ServeHTTP_Returns: load program: permission denied: invalid indirect read from stack off -8+0 size 8 (102 line(s) omitted)","stacktrace":"main.main\n\t/app/cli/main.go:61\nruntime.main\n\t/usr/local/go/src/runtime/proc.go:250"}
rolldice-go-auto-1 exited with code 0

Here is the container info:

# docker ps
CONTAINER ID   IMAGE                             COMMAND                  CREATED              STATUS              PORTS                                                                                              NAMES
58b0badb6c82   rolldice-rolldice                 "/app/main"              About a minute ago   Up About a minute   0.0.0.0:8080->8080/tcp                                                                             rolldice-rolldice-1
df914406783e   jaegertracing/all-in-one:latest   "/go/bin/all-in-one-…"   About a minute ago   Up About a minute   5775/udp, 5778/tcp, 0.0.0.0:14268->14268/tcp, 6831-6832/udp, 14250/tcp, 0.0.0.0:16686->16686/tcp   rolldice-jaeger-1
liurui-1 commented 1 year ago

@liurui-1 This is again the env var problem. If the yaml file is not changed this should not happen. In addition, I see that the target binary path not specified. message is printed by rolldice-rolldice-1 which is wrong, so I'm assuming somehow the files you are running are different from what I'm running.

I want to apologize that I forgot that I tested with a changed docker-compose.yaml finally yesterday. I tried to use "image: ghcr.io/open-telemetry/opentelemetry-go-instrumentation/autoinstrumentation-go:v0.3.0-alpha" directly yesterday. Today I just used "git pull" and it said it has got latest code but I was not aware that the docker-compose.yaml file was changed. Then I changed backed docker-compose.yaml file and I did "git pull" again (no new update). And the test result is in above post.