Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

"unexpected response - expected env vars response None" #670

Closed
JasonkayZK opened this issue Oct 31, 2022 · 18 comments
Closed

"unexpected response - expected env vars response None" #670

JasonkayZK opened this issue Oct 31, 2022 · 18 comments
Assignees
Labels
bug Something isn't working user

Comments

@JasonkayZK
Copy link

Bug Description

I tried to use a binary executable file for testing.

And the pod crashed:

mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main
✓ layer initialized
✓ agent running
  ✓ agent pod created
  ✓ pod is ready
unexpected response - expected env vars response None
Terminated

Steps to Reproduce

  1. Deploy a busybox image;
  2. Use mirrord mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main;

Backtrace

No response

Relevant Logs

No response

Your operating system and version

Centos 7.9

Local process

None

Local process version

No response

Additional Info

No response

@JasonkayZK JasonkayZK added the bug Something isn't working label Oct 31, 2022
@meowjesty
Copy link
Member

Hey @JasonkayZK thanks for opening a bug report.

Could you provide a bit more info about the issue:

  • Any additional info on what ./main is doing (even better if it's open source)?
  • Could you run file ./main and post the results?
  • What language (and framework) is being used in the binary?
  • Could you run it again, and check that the mirrord-agent pod is being created (post the results of kubectl get pods)?

@JasonkayZK
Copy link
Author

While, the main program is simple:

package main

import (
   "fmt"
   "net/http"
)

func HelloHandler(w http.ResponseWriter, r *http.Request) {
   fmt.Fprintf(w, "Hello World")
}

func main () {
   http.HandleFunc("/", HelloHandler)
   fmt.Println("Start!")
   http.ListenAndServe(":8000", nil)
}

That, i wanted to start a server in the pod. So, it's simply a go binary executable file, that created by go build main.go.

The file ./main:

$ file ./main
./main: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked (uses shared libs), not stripped

Actually, the mirrord-agent does created about 2-3 seconds but soon it exited with no logs.

@aviramha
Copy link
Member

aviramha commented Nov 1, 2022

Thanks!
Can you provide your go version? using go version
Also, can you run the same with env var at start?
MIRRORD_AGENT_TTL=60 mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main
it will make the pod linger for about 60 seconds after it finished so you can collect logs using kubectl logs

@JasonkayZK
Copy link
Author

JasonkayZK commented Nov 1, 2022

The go version is go version go1.19.2 linux/amd64;

I tried the command, and it did print some logs:

$ k logs mirrord-agent-paqtt5rtlx-ps9sb
2022-11-01T07:28:53.571551Z  INFO ThreadId(01) mirrord_agent: agent ready
2022-11-01T07:28:54.691187Z ERROR ThreadId(03) mirrord_agent: ClientConnectionHandler::start -> Client 0 disconnected with error: SnifferCommand sender failed with `channel closed`
2022-11-01T07:29:24.692296Z ERROR ThreadId(01) mirrord_agent: start_agent -> sniffer task failed with error: Agent failed with `Protocol not available (os error 92)`
2022-11-01T07:29:24.692349Z  INFO ThreadId(01) mirrord_agent: main -> mirrord-agent `start` exiting successfully.

Maybe some network problem? But i can't figure it out...

@aviramha
Copy link
Member

aviramha commented Nov 1, 2022

Sorry about the troubles. I think we're close to figuring it out.
Can you re-run with the following?
MIRRORD_AGENT_RUST_LOG="mirrord=trace" MIRRORD_AGENT_TTL=60 mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main
then obtain logs?
Also, could you provide more info about the cluster? what kubernetes version, which cloud provider or local? if local, which software (minikube,k3s, etc)
Anything that might be special in your k8s environment?

@JasonkayZK
Copy link
Author

Sure, i re-run the command, and here is the log:

$ k logs mirrord-agent-wps50o6hqg-7gcws
2022-11-01T08:52:51.311452Z DEBUG ThreadId(01) mirrord_agent: main -> Initializing mirrord-agent.
2022-11-01T08:52:51.311547Z DEBUG ThreadId(01) mirrord_agent: starting with args Args { container_id: Some("5334850498a712d9a912da38b35496c916e220646b4ecad2eb45ad1a7589a201"), container_runtime: Some("containerd"), communicate_port: 47181, communication_timeout: 30, interface: "eth0", ephemeral_container: false }
2022-11-01T08:52:51.312405Z  INFO ThreadId(01) mirrord_agent: agent ready
2022-11-01T08:52:51.313503Z DEBUG ThreadId(18) mirrord_agent::runtime: set_namespace -> fd 18
2022-11-01T08:52:51.314229Z DEBUG ThreadId(19) mirrord_agent::runtime: set_namespace -> fd 19
2022-11-01T08:52:51.314244Z DEBUG ThreadId(19) mirrord_agent::sniffer: preparing sniffer
2022-11-01T08:52:51.314247Z DEBUG ThreadId(19) mirrord_agent::sniffer: prepare_sniffer -> Preparing interface.
2022-11-01T08:52:51.791816Z DEBUG ThreadId(01) mirrord_agent: start -> Connection accepted from 127.0.0.1:43026
2022-11-01T08:52:51.791897Z TRACE ThreadId(03) new: mirrord_agent::file: enter pid=Some(270887)
2022-11-01T08:52:51.791912Z DEBUG ThreadId(03) new: mirrord_agent::file: Agent root path >> "/proc/270887/root" pid=Some(270887)
2022-11-01T08:52:51.791924Z TRACE ThreadId(03) new: mirrord_agent::file: exit pid=Some(270887)
2022-11-01T08:52:51.791953Z ERROR ThreadId(03) mirrord_agent: ClientConnectionHandler::start -> Client 0 disconnected with error: SnifferCommand sender failed with `channel closed`
2022-11-01T08:53:21.792566Z DEBUG ThreadId(01) mirrord_agent: start_agent -> main thread timeout, no clients connected
2022-11-01T08:53:21.792587Z DEBUG ThreadId(01) mirrord_agent: start_agent -> shutting down start
2022-11-01T08:53:21.792593Z ERROR ThreadId(01) mirrord_agent: start_agent -> sniffer task failed with error: Agent failed with `Protocol not available (os error 92)`
2022-11-01T08:53:21.792609Z DEBUG ThreadId(01) mirrord_agent: shutdown done
2022-11-01T08:53:21.792637Z  INFO ThreadId(01) mirrord_agent: main -> mirrord-agent `start` exiting successfully.

I run the k8s(single node) as Kind which is provided by:

And here are these tools version:

k version
Client Version: version.Info{Major:"1", Minor:"21", GitVersion:"v1.21.0", GitCommit:"cb303e613a121a29364f75cc67d3d580833a7479", GitTreeState:"clean", BuildDate:"2021-04-08T16:31:21Z", GoVersion:"go1.16.1", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"23", GitVersion:"v1.23.4", GitCommit:"e6c093d87ea4cbb530a7b2ae91e54c0842d8308a", GitTreeState:"clean", BuildDate:"2022-03-06T21:32:53Z", GoVersion:"go1.17.7", Compiler:"gc", Platform:"linux/amd64"}
WARNING: version difference between client (1.21) and server (1.23) exceeds the supported minor version skew of +/-1

And by the way i firstly tried run in my k3s cluster, but it did has some network problems.
But it was not relevant with this issue. 😭

@aviramha
Copy link
Member

aviramha commented Nov 1, 2022

I have a good guess on what's the issue - can you check if you have eth0 on your machine? ifconfig / ip a

@aviramha
Copy link
Member

aviramha commented Nov 1, 2022

P.S How did you install Centos? It seems that the default libc isn't compatible with mirrord?

@JasonkayZK
Copy link
Author

No, there does not has the eth0, but there does have eth1 instead.
Maybe it's the libc's problem. Although the os is CentOS, but it's a modified version for company use.
Also, i tried the operation above in vmware and it did work!
Maybe its the os's problem. i guess.

@aviramha
Copy link
Member

aviramha commented Nov 2, 2022

No, there does not has the eth0, but there does have eth1 instead.

Maybe it's the libc's problem. Although the os is CentOS, but it's a modified version for company use.

Also, i tried the operation above in vmware and it did work!

Maybe its the os's problem. i guess.

No it's our fault. We default to use eth0 since it's the case in the vast majority. We can add interface detection in a simple manner. We will work on adding it soon and let you know once it's ready.

@JasonkayZK
Copy link
Author

Well, that's great! Thx! 👍

@aviramha
Copy link
Member

aviramha commented Nov 8, 2022

hey @JasonkayZK,
we released a patch that should fix that.
Please let us know if it's working.

@JasonkayZK
Copy link
Author

I tried with the newest version mirrord 3.8.0, still got some problems.

$ MIRRORD_AGENT_RUST_LOG="mirrord=trace" MIRRORD_AGENT_TTL=60 mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main
✓ layer initialized
✓ agent running
  ✓ agent pod created
  ✓ pod is ready

mirrord-layer received an unexpected response from the agent pod!

- Suggestions:

>> When trying to run a program with arguments in the form of `app -arg value`, run it as
   `app -- -arg value` instead.

- If you're still stuck and everything looks fine:

>> Please open a new bug report at https://github.com/metalbear-co/mirrord/issues/new/choose

>> Or join our discord https://discord.com/invite/J5YSrStDKD and request help in #mirrord-help.

Expected env vars response, but got None
Terminated

Here are the logs:

$ k logs mirrord-agent-tswkszfya3-wmccf
2022-11-11T06:28:59.294305Z DEBUG ThreadId(01) mirrord_agent: main -> Initializing mirrord-agent.
2022-11-11T06:28:59.294416Z DEBUG ThreadId(01) mirrord_agent: starting with args Args { container_id: Some("6a3c683c94067f41ba1c9b5157a85220e242efdb6a428960534b2d24b819e721"), container_runtime: Some("containerd"), communicate_port: 33886, communication_timeout: 30, network_interface: None, ephemeral_container: false }
2022-11-11T06:28:59.295284Z  INFO ThreadId(01) mirrord_agent: agent ready
2022-11-11T06:28:59.297252Z DEBUG ThreadId(18) mirrord_agent::runtime: set_namespace -> fd 18
2022-11-11T06:28:59.297304Z TRACE ThreadId(19) new: mirrord_agent::sniffer: enter receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None
2022-11-11T06:28:59.297336Z DEBUG ThreadId(19) new: mirrord_agent::runtime: set_namespace -> fd 19 receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None
2022-11-11T06:28:59.297351Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: enter receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None network_interface=None
2022-11-11T06:28:59.297357Z TRACE ThreadId(19) new:prepare_sniffer:resolve_interface: mirrord_agent::sniffer: enter receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None network_interface=None
2022-11-11T06:28:59.297462Z TRACE ThreadId(19) new:prepare_sniffer:resolve_interface: mirrord_agent::sniffer: exit receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None network_interface=None
2022-11-11T06:28:59.297473Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: Using "eth0" interface. receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None network_interface=None
2022-11-11T06:28:59.350636Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: exit receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None network_interface=None
2022-11-11T06:28:59.350661Z TRACE ThreadId(19) new: mirrord_agent::sniffer: exit receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x564c7880ef60, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(3097262) network_interface=None
2022-11-11T06:29:00.598515Z DEBUG ThreadId(01) mirrord_agent: start -> Connection accepted from 127.0.0.1:49332
2022-11-11T06:29:00.598601Z TRACE ThreadId(04) new: mirrord_agent::file: enter pid=Some(3097262)
2022-11-11T06:29:00.598615Z DEBUG ThreadId(04) new: mirrord_agent::file: Agent root path >> "/proc/3097262/root" pid=Some(3097262)
2022-11-11T06:29:00.598628Z TRACE ThreadId(04) new: mirrord_agent::file: exit pid=Some(3097262)
2022-11-11T06:29:00.598669Z ERROR ThreadId(04) mirrord_agent: ClientConnectionHandler::start -> Client 0 disconnected with error: SnifferCommand sender failed with `channel closed`

@aviramha aviramha reopened this Nov 11, 2022
@aviramha aviramha assigned aviramha and unassigned meowjesty Nov 11, 2022
@eyalb181
Copy link
Member

Hi @JasonkayZK, apologies for the delayed response. Our newest version (3.9.0) supports a configuration value for specifying which network interface to use. Could you try running it with MIRRORD_AGENT_NETWORK_INTERFACE=eth1 MIRRORD_AGENT_RUST_LOG="mirrord=trace" MIRRORD_AGENT_TTL=60 mirrord exec --target pod/<pod-name> -- ./main?

@JasonkayZK
Copy link
Author

I tried with:

$ MIRRORD_AGENT_NETWORK_INTERFACE=eth1 MIRRORD_AGENT_RUST_LOG="mirrord=trace" MIRRORD_AGENT_TTL=60 mirrord exec --target pod/busybox-58d584f97b-pbtv8 -- ./main

Still got:

✓ layer initialized
✓ agent running
  ✓ agent pod created
  ✓ pod is ready

mirrord-layer received an unexpected response from the agent pod!

- Suggestions:

>> When trying to run a program with arguments in the form of `app -arg value`, run it as
   `app -- -arg value` instead.

- If you're still stuck and everything looks fine:

>> Please open a new bug report at https://github.com/metalbear-co/mirrord/issues/new/choose

>> Or join our discord https://discord.com/invite/J5YSrStDKD and request help in #mirrord-help.

Expected env vars response, but got None
Terminated

Here's the logs:

$ k logs mirrord-agent-8clc23kllh-mfnq8
2022-11-15T04:20:46.691244Z DEBUG ThreadId(01) mirrord_agent: main -> Initializing mirrord-agent.
2022-11-15T04:20:46.691344Z DEBUG ThreadId(01) mirrord_agent: starting with args Args { container_id: Some("aaa09d787fd5f38c87971fbfba0da2b23e530b26934d4f6fdf3945c47838aaad"), container_runtime: Some("containerd"), communicate_port: 35215, communication_timeout: 30, network_interface: Some("eth1"), ephemeral_container: false }
2022-11-15T04:20:46.692217Z  INFO ThreadId(01) mirrord_agent: agent ready
2022-11-15T04:20:46.692584Z DEBUG ThreadId(18) mirrord_agent::runtime: set_namespace -> fd 14
2022-11-15T04:20:46.693385Z TRACE ThreadId(19) new: mirrord_agent::sniffer: enter receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1")
2022-11-15T04:20:46.693404Z DEBUG ThreadId(19) new: mirrord_agent::runtime: set_namespace -> fd 19 receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1")
2022-11-15T04:20:46.693410Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: enter receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1") network_interface=Some("eth1")
2022-11-15T04:20:46.693413Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: Using "eth1" interface. receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1") network_interface=Some("eth1")
2022-11-15T04:20:46.695136Z TRACE ThreadId(19) new:prepare_sniffer: mirrord_agent::sniffer: exit receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1") network_interface=Some("eth1")
2022-11-15T04:20:46.695163Z TRACE ThreadId(19) new: mirrord_agent::sniffer: exit receiver=Receiver { chan: Rx { inner: Chan { tx: Tx { block_tail: 0x55f0f60edb20, tail_position: 0 }, semaphore: (Semaphore { permits: 1000 }, 1000), rx_waker: AtomicWaker, tx_count: 1, rx_fields: "..." } } } pid=Some(1251295) network_interface=Some("eth1")
2022-11-15T04:20:47.451144Z DEBUG ThreadId(01) mirrord_agent: start -> Connection accepted from 127.0.0.1:38418
2022-11-15T04:20:47.451214Z TRACE ThreadId(17) new: mirrord_agent::file: enter pid=Some(1251295)
2022-11-15T04:20:47.451226Z DEBUG ThreadId(17) new: mirrord_agent::file: Agent root path >> "/proc/1251295/root" pid=Some(1251295)
2022-11-15T04:20:47.451244Z TRACE ThreadId(17) new: mirrord_agent::file: exit pid=Some(1251295)
2022-11-15T04:20:47.451278Z ERROR ThreadId(17) mirrord_agent: ClientConnectionHandler::start -> Client 0 disconnected with error: SnifferCommand sender failed with `channel closed`

@aviramha
Copy link
Member

@JasonkayZK sorry I don't have ideas atm, do you want to schedule a debug session using my calendly?

@JasonkayZK
Copy link
Author

Yep, next tuesday works fine with me. And here is the deployment config file, maybe you can test it?

busybox-deploy.yaml

apiVersion: apps/v1
kind: Deployment
metadata:
  name: busybox
#  namespace: test
spec:
  replicas: 1
  selector:
    matchLabels:
      app: busybox
  template:
    metadata:
      labels:
        app: busybox
    spec:
      containers:
      - name: busybox
        image: busybox 
        args:
        - /bin/sh
        - -c
        - sleep 10; touch /tmp/healthy; sleep 3600
        readinessProbe:      
          exec:
            command:
            - cat
            - /tmp/healthy
          initialDelaySeconds: 10 
          periodSeconds: 5  
        ports:
            - containerPort: 8000

@JasonkayZK
Copy link
Author

JasonkayZK commented Nov 22, 2022

I figured it out! It just my develop machine's network problem.
I tried on my Mac M1 Pro and win10 AMD machine, it worked just fine!

$ MIRRORD_AGENT_RUST_LOG="mirrord=trace" MIRRORD_AGENT_TTL=60 mirrord exec --target pod/busybox-58d584f97b-dggqz -- ./main 
✓ layer initialized
✓ agent running
  ✓ agent pod created
  ✓ pod is ready
Start!

Thanks for you guys help! ❤️

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

Successfully merging a pull request may close this issue.

4 participants