metalbear-co / mirrord

Connect your local process and your cloud environment, and run local code in cloud conditions.
https://mirrord.dev
MIT License
3.82k stars 104 forks source link

Failed to make API calls to external services #2644

Closed algobot76 closed 3 months ago

algobot76 commented 3 months ago

Bug Description

My app makes calls to external api endpoints, however the app logs showed that it failed to receive responses when i ran it with mirrored enabled.

Steps to Reproduce

  1. Run a golang app that makes api calls to external services (api.vultr.com in my case).
  2. Read the logs produced by mirrrod agent.

Backtrace

No response

Relevant Logs

[2m2024-08-09T02:43:21.425167Z DEBUG ThreadId(01) mirrord_agent::entrypoint: main -> Initializing mirrord-agent, version 3.112.1.
2024-08-09T02:43:21.425625Z DEBUG ThreadId(01) mirrord_agent::entrypoint: start_iptable_guard -> Initializing iptable-guard.
2024-08-09T02:43:21.425688Z TRACE ThreadId(01) new: mirrord_agent::container_handle: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427420Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; idle container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427451Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; connecting container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427721Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; not ready container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427758Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; connecting container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427803Z TRACE ThreadId(01) new: hyper::client::conn: client handshake Http2 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427835Z DEBUG ThreadId(01) new: h2::client: binding client connection container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427848Z DEBUG ThreadId(01) new: h2::client: client connection bound container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427905Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::codec::framed_write: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427916Z DEBUG ThreadId(01) new:FramedWrite::buffer: h2::codec::framed_write: send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427923Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::frame::settings: encoding SETTINGS; len=18 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427927Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::frame::settings: encoding setting; val=EnablePush(0) container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427930Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::frame::settings: encoding setting; val=InitialWindowSize(2097152) container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427934Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::frame::settings: encoding setting; val=MaxFrameSize(16384) container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427937Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::codec::framed_write: encoded settings rem=27 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427942Z TRACE ThreadId(01) new:FramedWrite::buffer: h2::codec::framed_write: close time.busy=25.9µs time.idle=11.5µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
2024-08-09T02:43:21.427955Z TRACE ThreadId(01) new: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427961Z TRACE ThreadId(01) new: h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427965Z TRACE ThreadId(01) new: h2::proto::streams::prioritize: Prioritize::new; flow=FlowControl { window_size: Window(65535), available: Window(65535) } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.427971Z DEBUG ThreadId(01) new:Connection: h2::proto::connection: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.427995Z TRACE ThreadId(01) new: h2::proto::streams::recv: set_target_connection_window; target=5242880; available=65535, reserved=0 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428010Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; connected container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428020Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; not ready container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428052Z TRACE ThreadId(01) new:Connection:poll: h2::proto::connection: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428059Z TRACE ThreadId(01) new:Connection:poll: h2::proto::connection: connection.state=Open container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428073Z TRACE ThreadId(01) new:Connection:poll:poll_ready: h2::proto::connection: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428079Z TRACE ThreadId(01) new:Connection:poll:poll_ready: h2::proto::connection: close time.busy=1.74µs time.idle=4.10µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428087Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428091Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: poll container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428106Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: read.bytes=15 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428112Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next:FramedRead::decode_frame: h2::codec::framed_read: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client offset=15
2024-08-09T02:43:21.428116Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next:FramedRead::decode_frame: h2::codec::framed_read: decoding frame from 15B container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client offset=15
2024-08-09T02:43:21.428120Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next:FramedRead::decode_frame: h2::codec::framed_read: frame.kind=Settings container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client offset=15
2024-08-09T02:43:21.428126Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next:FramedRead::decode_frame: h2::codec::framed_read: close time.busy=9.55µs time.idle=3.98µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client offset=15
2024-08-09T02:43:21.428131Z DEBUG ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: received frame=Settings { flags: (0x0), max_frame_size: 16384 } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428136Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: close time.busy=45.0µs time.idle=3.94µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428142Z TRACE ThreadId(01) new:Connection:poll: h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x0), max_frame_size: 16384 } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428151Z TRACE ThreadId(01) new:Connection:poll:poll_ready: h2::proto::connection: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428155Z TRACE ThreadId(01) new:Connection:poll:poll_ready:FramedWrite::buffer: h2::codec::framed_write: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=Settings { flags: (0x1: ACK) }
2024-08-09T02:43:21.428159Z DEBUG ThreadId(01) new:Connection:poll:poll_ready:FramedWrite::buffer: h2::codec::framed_write: send frame=Settings { flags: (0x1: ACK) } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=Settings { flags: (0x1: ACK) }
2024-08-09T02:43:21.428163Z TRACE ThreadId(01) new:Connection:poll:poll_ready:FramedWrite::buffer: h2::frame::settings: encoding SETTINGS; len=0 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=Settings { flags: (0x1: ACK) }
2024-08-09T02:43:21.428167Z TRACE ThreadId(01) new:Connection:poll:poll_ready:FramedWrite::buffer: h2::codec::framed_write: encoded settings rem=36 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=Settings { flags: (0x1: ACK) }
2024-08-09T02:43:21.428171Z TRACE ThreadId(01) new:Connection:poll:poll_ready:FramedWrite::buffer: h2::codec::framed_write: close time.busy=11.3µs time.idle=3.99µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=Settings { flags: (0x1: ACK) }
2024-08-09T02:43:21.428176Z TRACE ThreadId(01) new:Connection:poll:poll_ready: h2::proto::settings: ACK sent; applying settings container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428185Z TRACE ThreadId(01) new:Connection:poll:poll_ready: h2::proto::connection: close time.busy=30.6µs time.idle=3.57µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428192Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428207Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: poll container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428211Z TRACE ThreadId(01) new:Connection:poll:FramedRead::poll_next: h2::codec::framed_read: close time.busy=4.37µs time.idle=15.3µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428218Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::buffer: h2::codec::framed_write: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-08-09T02:43:21.428221Z DEBUG ThreadId(01) new:Connection:poll:FramedWrite::buffer: h2::codec::framed_write: send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 } container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-08-09T02:43:21.428226Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::buffer: h2::frame::window_update: encoding WINDOW_UPDATE; id=StreamId(0) container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-08-09T02:43:21.428230Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::buffer: h2::codec::framed_write: encoded window_update rem=49 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-08-09T02:43:21.428234Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::buffer: h2::codec::framed_write: close time.busy=12.7µs time.idle=3.67µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
2024-08-09T02:43:21.428240Z TRACE ThreadId(01) new:Connection:poll: h2::proto::streams::flow_control: inc_window; sz=5177345; old=65535; new=5242880 container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428246Z TRACE ThreadId(01) new:Connection:poll:try_reclaim_frame: h2::proto::streams::prioritize: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428250Z TRACE ThreadId(01) new:Connection:poll:try_reclaim_frame: h2::proto::streams::prioritize: close time.busy=180ns time.idle=3.86µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428258Z TRACE ThreadId(01) new:Connection:poll: h2::proto::streams::prioritize: poll_complete container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428261Z TRACE ThreadId(01) new:Connection:poll: h2::proto::streams::prioritize: schedule_pending_open container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428266Z TRACE ThreadId(01) new:Connection:poll:pop_frame: h2::proto::streams::prioritize: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428271Z TRACE ThreadId(01) new:Connection:poll:pop_frame: h2::proto::streams::prioritize: close time.busy=308ns time.idle=3.85µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428276Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::flush: h2::codec::framed_write: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428282Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::flush: h2::codec::framed_write: queued_data_frame=false container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428290Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::flush: h2::codec::framed_write: flushing buffer container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428296Z TRACE ThreadId(01) new:Connection:poll:FramedWrite::flush: h2::codec::framed_write: close time.busy=14.7µs time.idle=5.03µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428300Z TRACE ThreadId(01) new:Connection:poll:try_reclaim_frame: h2::proto::streams::prioritize: new container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428304Z TRACE ThreadId(01) new:Connection:poll:try_reclaim_frame: h2::proto::streams::prioritize: close time.busy=227ns time.idle=3.30µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428309Z TRACE ThreadId(01) new:Connection:poll: h2::proto::connection: close time.busy=250µs time.idle=6.89µs container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" }) peer=Client
2024-08-09T02:43:21.428333Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; connected container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428336Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; ready container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428389Z TRACE ThreadId(01) new: tower::buffer::service: sending request to buffer worker container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428397Z TRACE ThreadId(01) tower::buffer::worker: worker polling for next message
2024-08-09T02:43:21.428402Z TRACE ThreadId(01) tower::buffer::worker: processing new request
2024-08-09T02:43:21.428406Z TRACE ThreadId(01) new: tower::buffer::worker: resumed=false worker received request; waiting for service readiness container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428409Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; connected container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428412Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: poll_ready; ready container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428415Z DEBUG ThreadId(01) new: tower::buffer::worker: service.ready=true processing request container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428421Z TRACE ThreadId(01) new: tonic::transport::service::reconnect: Reconnect::call container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428425Z TRACE ThreadId(01) new: tower::buffer::worker: returning response future container=Containerd(ContainerdContainer { container_id: "f89b970b6fbab7d7a552814eac485cba82a610c283eb739da3f472890de7bf29" })
2024-08-09T02:43:21.428430Z TRACE ThreadId(01) tower::buffer::worker: worker polling for next message
2024-08-09T02:43:21.428447Z TRACE ThreadId(01) h2::proto::streams::flow_control: inc_window; sz=2097152; old=0; new=2097152
2024-08-09T02:43:21.428452Z TRACE ThreadId(01) h2::proto::streams::flow_control: inc_window; sz=65535; old=0; new=65535
2024-08-09T02:43:21.428463Z TRACE ThreadId(01) h2::proto::streams::send: send_headers; frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }; init_window=65535
2024-08-09T02:43:21.428471Z TRACE ThreadId(01) h2::proto::streams::store: Queue::push_back
2024-08-09T02:43:21.428474Z TRACE ThreadId(01) h2::proto::streams::store:  -> first entry
2024-08-09T02:43:21.428477Z TRACE ThreadId(01) Prioritize::queue_frame: h2::proto::streams::prioritize: new stream.id=StreamId(1)
2024-08-09T02:43:21.428487Z TRACE ThreadId(01) Prioritize::queue_frame: h2::proto::streams::prioritize: close time.busy=6.54µs time.idle=3.04µs stream.id=StreamId(1)
2024-08-09T02:43:21.428497Z TRACE ThreadId(01) reserve_capacity: h2::proto::streams::prioritize: new stream.id=StreamId(1) requested=1 effective=1 curr=0
2024-08-09T02:43:21.428502Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: new stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428505Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: requested=1 additional=1 buffered=0 window=65535 conn=65535 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428509Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: assigning capacity=1 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428513Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::stream:   assigned capacity to stream; available=1; buffered=0; id=StreamId(1); max_buffer_size=1048576 prev=0 stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428516Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::stream:   notifying task stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428520Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: available=1 requested=1 buffered=0 has_unavailable=true stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428524Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: close time.busy=19.4µs time.idle=3.39µs stream.id=StreamId(1) requested=1 effective=1 curr=0 stream.id=StreamId(1)
2024-08-09T02:43:21.428531Z TRACE ThreadId(01) reserve_capacity: h2::proto::streams::prioritize: close time.busy=31.1µs time.idle=2.90µs stream.id=StreamId(1) requested=1 effective=1 curr=0
2024-08-09T02:43:21.428538Z TRACE ThreadId(01) hyper::proto::h2: send body chunk: 71 bytes, eos=false
2024-08-09T02:43:21.428544Z TRACE ThreadId(01) send_data: h2::proto::streams::prioritize: new sz=71 requested=1
2024-08-09T02:43:21.428547Z TRACE ThreadId(01) send_data: h2::proto::streams::prioritize: buffered=71 sz=71 requested=1
2024-08-09T02:43:21.428551Z TRACE ThreadId(01) send_data: h2::proto::streams::prioritize: available=1 buffered=71 sz=71 requested=1
2024-08-09T02:43:21.428555Z TRACE ThreadId(01) send_data:Prioritize::queue_frame: h2::proto::streams::prioritize: new sz=71 requested=1 stream.id=StreamId(1)
2024-08-09T02:43:21.428559Z TRACE ThreadId(01) send_data:Prioritize::queue_frame: h2::proto::streams::prioritize: close time.busy=269ns time.idle=3.42µs sz=71 requested=1 stream.id=StreamId(1)
2024-08-09T02:43:21.428564Z TRACE ThreadId(01) send_data: h2::proto::streams::prioritize: close time.busy=16.6µs time.idle=2.90µs sz=71 requested=1
2024-08-09T02:43:21.428569Z TRACE ThreadId(01) h2::proto::streams::counts: transition_after; stream=StreamId(1); state=State { inner: Open { local: Streaming, remote: AwaitingHeaders } }; is_closed=false; pending_send_empty=false; buffered_send_data=71; num_recv=0; num_send=0
2024-08-09T02:43:21.428575Z TRACE ThreadId(01) reserve_capacity: h2::proto::streams::prioritize: new stream.id=StreamId(1) requested=1 effective=72 curr=71
2024-08-09T02:43:21.428579Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: new stream.id=StreamId(1) requested=1 effective=72 curr=71 stream.id=StreamId(1)
2024-08-09T02:43:21.428582Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: requested=72 additional=71 buffered=71 window=65535 conn=65534 stream.id=StreamId(1) requested=1 effective=72 curr=71 stream.id=StreamId(1)
2024-08-09T02:43:21.428586Z TRACE ThreadId(01) reserve_capacity:try_assign_capacity: h2::proto::streams::prioritize: assigning capacity=71 stream.id=StreamId(1) requested=1 effective=72 curr=71 stream.id=StreamId(1)

Your operating system and version

MacOS 14.2.1

Local process

cim

Local process version

No response

Additional Info

No response

algobot76 commented 3 months ago

full log: mirrord-agent.log

Razz4780 commented 3 months ago

I don't see any failure in the agent logs. Can we get local logs and maybe some code snippet we can use to reproduce the issue? You can enable local logs by:

  1. Setting RUST_LOG=mirrord=trace env for the run. This will dump layer logs to stderr of the application
  2. Enabling intproxy logs in the mirrord config:
    {
    "internal_proxy": {
    "log_level": "mirrord=trace",
    "log_destination": "where/to/dump/logs"
    }
    }

Would be great if we had all of agent/layer/intproxy logs from the same run

aviramha commented 3 months ago

Adjusted @Razz4780 json to be more correct (intproxy -> internal_proxy, added missing })

algobot76 commented 3 months ago

I don't see any failure in the agent logs. Can we get local logs and maybe some code snippet we can use to reproduce the issue? You can enable local logs by:

  1. Setting RUST_LOG=mirrord=trace env for the run. This will dump layer logs to stderr of the application
  2. Enabling intproxy logs in the mirrord config:
{
  "internal_proxy": {
    "log_level": "mirrord=trace",
    "log_destination": "where/to/dump/logs"
   }
}

Would be great if we had all of agent/layer/intproxy logs from the same run

I tried again with the latest release and it was working! It cloud have been fixed in recent releases or my poor network connection made the previous release unusable.

algobot76 commented 3 months ago

Closing the issue as it can no longer be reproduced.