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.

Sign up for GitHub

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

Jump to bottom

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

Open
liurui-1 opened this issue Aug 23, 2023 · 13 comments
Open

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

liurui-1 opened this issue Aug 23, 2023 · 13 comments
Labels
bug Something isn't working

Comments

@liurui-1
Copy link

liurui-1 commented Aug 23, 2023 •
edited
Loading

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

  • OS: Ubuntu 20.04.6 LTS
  • Go Version: go1.20.7 linux/amd64
  • Version: N/A
# uname -r
5.4.0-156-generic

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.
@liurui-1 liurui-1 added the bug Something isn't working label Aug 23, 2023
@liurui-1 liurui-1 mentioned this issue Aug 24, 2023
Closed
@RonFed
Copy link
Contributor

RonFed commented Aug 27, 2023 •
edited
Loading

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

@liurui-1
Copy link
Author

liurui-1 commented Aug 28, 2023 •
edited
Loading

@RonFed
Yes it is the latest main branch

# uname -r
5.4.0-156-generic

@liurui-1
Copy link
Author

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
Copy link
Contributor

RonFed commented Sep 27, 2023

@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
Copy link
Author

liurui-1 commented Sep 27, 2023 •
edited
Loading

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
Copy link
Contributor

RonFed commented Sep 27, 2023

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
Copy link
Author

liurui-1 commented Sep 28, 2023 •
edited
Loading

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
Copy link
Contributor

RonFed commented Sep 28, 2023

@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:
- OTEL_GO_AUTO_TARGET_EXE=/app/main
I'm not sure how the error you got is possible if the docker-compose file didn't change

@liurui-1
Copy link
Author

liurui-1 commented Sep 29, 2023 •
edited
Loading

@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":"[email protected]/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":"[email protected]/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
Copy link
Contributor

RonFed commented Sep 30, 2023

@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
Copy link
Contributor

RonFed commented Sep 30, 2023

@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
Copy link
Author

liurui-1 commented Sep 30, 2023 •
edited
Loading

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":"[email protected]/clientconn.go:489","msg":"[core][Channel #1] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.8592908,"caller":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/server.go:667","msg":"[core][Server #5] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9154232,"caller":"[email protected]/otlp.go:83","msg":"Starting GRPC server","endpoint":"0.0.0.0:4317"}
rolldice-jaeger-1    | {"level":"warn","ts":1696090072.9161615,"caller":"[email protected]/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":"[email protected]/otlp.go:101","msg":"Starting HTTP server","endpoint":"0.0.0.0:4318"}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9162135,"caller":"[email protected]/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":"[email protected]/clientconn.go:489","msg":"[core][Channel #7] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9170392,"caller":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/server.go:667","msg":"[core][Server #9] Server created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9212728,"caller":"[email protected]/clientconn.go:489","msg":"[core][Channel #10] Channel created","system":"grpc","grpc_log":true}
rolldice-jaeger-1    | {"level":"info","ts":1696090072.9213538,"caller":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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":"[email protected]/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
Copy link
Author

@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.

@RonFed RonFed mentioned this issue Oct 11, 2023
Closed
6 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@liurui-1 @RonFed