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

Trace logs returns "Error: unable to hijack connection" #17749

Closed
hsnoil opened this issue Mar 13, 2023 · 3 comments · Fixed by #17781
Closed

Trace logs returns "Error: unable to hijack connection" #17749

hsnoil opened this issue Mar 13, 2023 · 3 comments · Fixed by #17781
Assignees
@Luap99
Labels
In Progress This issue is actively being worked by the assignee, please do not work on this at this time. kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.

Comments

@hsnoil
Copy link

hsnoil commented Mar 13, 2023

Issue Description

Adding --log-level=trace gives an error on podman 4.4.2 while --log-level=debug works fine.

This seems to be a continuing of issue #17332

Steps to reproduce the issue

Steps to reproduce the issue

  1. Run
$ podman system service --time=0 --log-level=trace

$ CONTAINER_HOST=unix://$XDG_RUNTIME_DIR/podman/podman.sock podman run --rm -ti busybox

Describe the results you received

Error: unable to hijack connection

Describe the results you expected

Same as below but with added trace info:

 $ podman system service --time=0 --log-level=debug

podman info output

host:
  arch: amd64
  buildahVersion: 1.29.0
  cgroupControllers:
  - memory
  - pids
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.5-2.1.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.5, commit: unknown'
  cpuUtilization:
    idlePercent: 94.16
    systemPercent: 1.16
    userPercent: 4.69
  cpus: 8
  distribution:
    distribution: '"opensuse-tumbleweed"'
    version: "20230308"
  eventLogger: journald
  hostname: localhost.localdomain
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 6.2.1-1-default
  linkmode: dynamic
  logDriver: journald
  memFree: 3546005504
  memTotal: 12294696960
  networkBackend: netavark
  ociRuntime:
    name: crun
    package: crun-1.8.1-1.1.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 1.8.1
      commit: f8a096be060b22ccd3d5f3ebe44108517fbf6c30
      rundir: /run/user/1000/crun
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +LIBKRUN +YAJL
  os: linux
  remoteSocket:
    path: /run/user/1000/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: true
    seccompEnabled: true
    seccompProfilePath: /etc/containers/seccomp.json
    selinuxEnabled: false
  serviceIsRemote: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.2.0-1.1.x86_64
    version: |-
      slirp4netns version 1.2.0
      commit: unknown
      libslirp: 4.7.0
      SLIRP_CONFIG_VERSION_MAX: 5
      libseccomp: 2.5.4
  swapFree: 0
  swapTotal: 0
  uptime: 26h 38m 17.00s (Approximately 1.08 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  volume:
  - local
registries:
  localhost:44273:
    Blocked: false
    Insecure: true
    Location: localhost:44273
    MirrorByDigestOnly: false
    Mirrors: null
    Prefix: localhost:44273
    PullFromMirror: ""
  search:
  - registry.opensuse.org
  - registry.suse.com
  - docker.io
store:
  configFile: /home/test1/.config/containers/storage.conf
  containerStore:
    number: 3
    paused: 0
    running: 3
    stopped: 0
  graphDriverName: overlay
  graphOptions: {}
  graphRoot: /home/test1/.local/share/containers/storage
  graphRootAllocated: 25732034560
  graphRootUsed: 4838006784
  graphStatus:
    Backing Filesystem: btrfs
    Native Overlay Diff: "true"
    Supports d_type: "true"
    Using metacopy: "false"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 79
  runRoot: /run/user/1000/containers
  transientStore: false
  volumePath: /home/test1/.local/share/containers/storage/volumes
version:
  APIVersion: 4.4.2
  Built: 1677456000
  BuiltTime: Sun Feb 26 19:00:00 2023
  GitCommit: ""
  GoVersion: go1.18.10
  Os: linux
  OsArch: linux/amd64
  Version: 4.4.2

Podman in a container

No

Privileged Or Rootless

Rootless

Upstream Latest Release

Yes

Additional environment details

No response

Additional information

Here is my entire log

 
DEBU[0023] IdleTracker:new 0m+0h/0t connection(s)        X-Reference-Id=0xc00059e028
DEBU[0023] IdleTracker:active 0m+0h/1t connection(s)     X-Reference-Id=0xc00059e028
time="2023-03-12T03:32:11-04:00" level=trace msg=OK API=response X-Reference-Id=0xc00059e028
@ - - [12/Mar/2023:03:32:11 -0400] "GET /v4.4.2/libpod/_ping HTTP/1.1" 200 2 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 1m+0h/1t connection(s)       X-Reference-Id=0xc00059e028
DEBU[0023] IdleTracker:closed 1m+0h/1t connection(s)     X-Reference-Id=0xc00059e028
DEBU[0023] IdleTracker:new 0m+0h/1t connection(s)        X-Reference-Id=0xc00059e048
DEBU[0023] IdleTracker:active 0m+0h/2t connection(s)     X-Reference-Id=0xc00059e048
time="2023-03-12T03:32:11-04:00" level=trace msg=OK API=response X-Reference-Id=0xc00059e048
@ - - [12/Mar/2023:03:32:11 -0400] "GET /v4.4.2/libpod/_ping HTTP/1.1" 200 2 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 1m+0h/2t connection(s)       X-Reference-Id=0xc00059e048
DEBU[0023] IdleTracker:closed 1m+0h/2t connection(s)     X-Reference-Id=0xc00059e048
DEBU[0023] IdleTracker:new 0m+0h/2t connection(s)        X-Reference-Id=0xc000144008
DEBU[0023] IdleTracker:active 0m+0h/3t connection(s)     X-Reference-Id=0xc000144008
DEBU[0023] Successfully loaded network k3d-k3s-default: &{k3d-k3s-default cff136757ee9e10caec945f805e260bd5cd28202777024cca6236c9bdeef3751 bridge podman1 2023-03-11 02:42:35.11372516 -0500 EST [{{{10.89.0.0 ffffff00}} 10.89.0.1 <nil>}] false false true [] map[app:k3d] map[isolate:true] map[driver:host-local]} 
DEBU[0023] Successfully loaded 2 networks               
INFO[0023] Request Failed(Not Found): network not found 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"cause\":\"network not found\",\"message\":\"network not found\",\"response\":404}\n" API=response X-Reference-Id=0xc000144008
@ - - [12/Mar/2023:03:32:11 -0400] "GET /v4.4.2/libpod/networks/pasta/exists HTTP/1.1" 404 75 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 1m+0h/3t connection(s)       X-Reference-Id=0xc000144008
DEBU[0023] IdleTracker:closed 1m+0h/3t connection(s)     X-Reference-Id=0xc000144008
DEBU[0023] IdleTracker:new 0m+0h/3t connection(s)        X-Reference-Id=0xc000144018
DEBU[0023] IdleTracker:active 0m+0h/4t connection(s)     X-Reference-Id=0xc000144018
DEBU[0023] Pulling image busybox (policy: missing)      
DEBU[0023] Looking up image "busybox" in local containers storage 
DEBU[0023] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0023] Loading registries configuration "/etc/containers/registries.conf" 
DEBU[0023] Loading registries configuration "/etc/containers/registries.conf.d/000-shortnames.conf" 
DEBU[0023] Loading registries configuration "/etc/containers/registries.conf.d/myregistry.conf" 
DEBU[0023] Trying "docker.io/library/busybox:latest" ... 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage ([overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c) 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Looking up image "docker.io/library/busybox:latest" in local containers storage 
DEBU[0023] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0023] Trying "docker.io/library/busybox:latest" ... 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Found image "docker.io/library/busybox:latest" as "docker.io/library/busybox:latest" in local containers storage 
DEBU[0023] Found image "docker.io/library/busybox:latest" as "docker.io/library/busybox:latest" in local containers storage ([overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c) 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"images\":[\"bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c\"],\"id\":\"bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c\"}\n" API=response X-Reference-Id=0xc000144018
@ - - [12/Mar/2023:03:32:11 -0400] "POST /v4.4.2/libpod/images/pull?alltags=false&arch=&authfile=&os=&password=&policy=missing&quiet=false&reference=busybox&username=&variant= HTTP/1.1" 200 152 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 1m+0h/4t connection(s)       X-Reference-Id=0xc000144018
DEBU[0023] IdleTracker:new 1m+0h/4t connection(s)        X-Reference-Id=0xc000144a08
DEBU[0023] IdleTracker:active 1m+0h/5t connection(s)     X-Reference-Id=0xc000144a08
DEBU[0023] Looking up image "busybox" in local containers storage 
DEBU[0023] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0023] Trying "docker.io/library/busybox:latest" ... 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage ([overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c) 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Inspecting image bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@ff9ced6cc0710b9560493044c17e3edd01c9039f29c46d547270cb942cc72bfd" 
DEBU[0023] exporting opaque data as blob "sha256:ff9ced6cc0710b9560493044c17e3edd01c9039f29c46d547270cb942cc72bfd" 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"Id\":\"bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c\",\"Digest\":\"sha256:c118f538365369207c12e5794c3cbfb7b042d950af590ae6c287ede74f29b7d4\",\"RepoTags\":[\"docker.io/library/busybox:latest\"],\"RepoDigests\":[\"docker.io/library/busybox@sha256:2c8ed5408179ff4f53242a4bdd2706110ce000be239fe37a61be9c52f704c437\",\"docker.io/library/busybox@sha256:c118f538365369207c12e5794c3cbfb7b042d950af590ae6c287ede74f29b7d4\"],\"Parent\":\"\",\"Comment\":\"\",\"Created\":\"2023-03-06T23:19:25.955224807Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"Config\":{\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\"],\"Cmd\":[\"sh\"]},\"Version\":\"20.10.23\",\"Author\":\"\",\"Architecture\":\"amd64\",\"Os\":\"linux\",\"Size\":5097160,\"VirtualSize\":5097160,\"GraphDriver\":{\"Name\":\"overlay\",\"Data\":{\"UpperDir\":\"/home/test1/.local/share/containers/storage/overlay/427701cb9c9623cab51dcec9cfd66d7a88d189a14961120f4b2c62ce2e439b9d/diff\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"WorkDir\":\"/home/test1/.local/share/containers/storage/overlay/427701cb9c9623cab51dcec9cfd66d7a88d189a14961120f4b2c62ce2e439b9d/work\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg="}},\"RootFS\":{\"Type\":\"layers\",\"Layers\":[\"sha256:427701cb9c9623cab51dcec9cfd66d7a88d189a14961120f4b2c62ce2e439b9d\"]},\"Labels\":null,\"Annotations\":{},\"ManifestType\":\"application/vnd.docker.distribution.manifest.v2+json\",\"User\":\"\",\"History\":[{\"created\":\"2023-03-06T23:19:25.827755207Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"created_by\":\"/bin/sh -c #(nop) ADD file:10c68f24723166c5dca276ce56a44db80a195a11377deeb04d816902b23608c2 in / \"},{\"created\":\"2023-03-06T23:19:25.955224807Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"created_by\":\"/bin/sh -c #(nop)  CMD [\\\"sh\\\"]\",\"empty_layer\":true}],\"NamesHistory\":[\"docker.io/library/busybox:latest\"]}\n" API=response X-Reference-Id=0xc000144a08
@ - - [12/Mar/2023:03:32:11 -0400] "GET /v4.4.2/libpod/images/busybox/json?size=false HTTP/1.1" 200 1562 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 2m+0h/5t connection(s)       X-Reference-Id=0xc000144a08
DEBU[0023] IdleTracker:active 2m+0h/5t connection(s)     X-Reference-Id=0xc000144a08
DEBU[0023] Looking up image "busybox" in local containers storage 
DEBU[0023] Normalized platform linux/amd64 to {amd64 linux  [] } 
DEBU[0023] Trying "docker.io/library/busybox:latest" ... 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage 
DEBU[0023] Found image "busybox" as "docker.io/library/busybox:latest" in local containers storage ([overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c) 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Inspecting image bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Inspecting image bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c 
DEBU[0023] Inspecting image bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c 
DEBU[0023] Inspecting image bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c 
DEBU[0023] using systemd mode: false                    
DEBU[0023] No hostname set; container's hostname will default to runtime default 
DEBU[0023] Loading seccomp profile from "/etc/containers/seccomp.json" 
DEBU[0023] Allocated lock 2 for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] exporting opaque data as blob "sha256:bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Cached value indicated that idmapped mounts for overlay are not supported 
DEBU[0023] Check for idmapped mounts support            
DEBU[0023] Created container "e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6" 
DEBU[0023] Container "e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6" has work directory "/home/test1/.local/share/containers/storage/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata" 
DEBU[0023] Container "e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6" has run directory "/run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata" 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"Id\":\"e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6\",\"Warnings\":[]}\n" API=response X-Reference-Id=0xc000144a08
@ - - [12/Mar/2023:03:32:11 -0400] "POST /v4.4.2/libpod/containers/create HTTP/1.1" 201 88 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 2m+0h/5t connection(s)       X-Reference-Id=0xc000144a08
DEBU[0023] IdleTracker:active 2m+0h/5t connection(s)     X-Reference-Id=0xc000144a08
DEBU[0023] Looking up image "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" in local containers storage 
DEBU[0023] Trying "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" ... 
DEBU[0023] parsed reference into "[overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" 
DEBU[0023] Found image "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" as "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" in local containers storage 
DEBU[0023] Found image "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" as "bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c" in local containers storage ([overlay@/home/test1/.local/share/containers/storage+/run/user/1000/containers]@bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c) 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"Id\":\"e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6\",\"Created\":\"2023-03-12T03:32:11.241267612-04:00\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"Path\":\"sh\",\"Args\":[\"sh\"],\"State\":{\"OciVersion\":\"1.0.2-dev\",\"Status\":\"created\",\"Running\":false,\"Paused\":false,\"Restarting\":false,\"OOMKilled\":false,\"Dead\":false,\"Pid\":0,\"ExitCode\":0,\"Error\":\"\",\"StartedAt\":\"0001-01-01T00:00:00Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"FinishedAt\":\"0001-01-01T00:00:00Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"Health\":{\"Status\":\"\",\"FailingStreak\":0,\"Log\":null},\"CheckpointedAt\":\"0001-01-01T00:00:00Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"RestoredAt\":\"0001-01-01T00:00:00Z\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg="},\"Image\":\"bab98d58e29e4eb5744a69057a7b3d6ce99b19363a0e52c40301a5db43abf83c\",\"ImageDigest\":\"sha256:c118f538365369207c12e5794c3cbfb7b042d950af590ae6c287ede74f29b7d4\",\"ImageName\":\"docker.io/library/busybox:latest\",\"Rootfs\":\"\",\"Pod\":\"\",\"ResolvConfPath\":\"\",\"HostnamePath\":\"\",\"HostsPath\":\"\",\"StaticDir\":\"/home/test1/.local/share/containers/storage/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata\",\"OCIRuntime\":\"crun\",\"ConmonPidFile\":\"/run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/conmon.pid\",\"PidFile\":\"/run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/pidfile\",\"Name\":\"festive_shannon\",\"RestartCount\":0,\"Driver\":\"overlay\",\"MountLabel\":\"\",\"ProcessLabel\":\"\",\"AppArmorProfile\":\"\",\"EffectiveCaps\":[\"CAP_CHOWN\",\"CAP_DAC_OVERRIDE\",\"CAP_FOWNER\",\"CAP_FSETID\",\"CAP_KILL\",\"CAP_NET_BIND_SERVICE\",\"CAP_SETFCAP\",\"CAP_SETGID\",\"CAP_SETPCAP\",\"CAP_SETUID\",\"CAP_SYS_CHROOT\"],\"BoundingCaps\":[\"CAP_CHOWN\",\"CAP_DAC_OVERRIDE\",\"CAP_FOWNER\",\"CAP_FSETID\",\"CAP_KILL\",\"CAP_NET_BIND_SERVICE\",\"CAP_SETFCAP\",\"CAP_SETGID\",\"CAP_SETPCAP\",\"CAP_SETUID\",\"CAP_SYS_CHROOT\"],\"ExecIDs\":[],\"GraphDriver\":{\"Name\":\"overlay\",\"Data\":{\"LowerDir\":\"/home/test1/.local/share/containers/storage/overlay/427701cb9c9623cab51dcec9cfd66d7a88d189a14961120f4b2c62ce2e439b9d/diff\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"UpperDir\":\"/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/diff\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg=",\"WorkDir\":\"/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/work\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg="}},\"Mounts\":[],\"Dependencies\":[],\"NetworkSettings\":{\"EndpointID\":\"\",\"Gateway\":\"\",\"IPAddress\":\"\",\"IPPrefixLen\":0,\"IPv6Gateway\":\"\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"MacAddress\":\"\",\"Bridge\":\"\",\"SandboxID\":\"\",\"HairpinMode\":false,\"LinkLocalIPv6Address\":\"\",\"LinkLocalIPv6PrefixLen\":0,\"Ports\":{},\"SandboxKey\":\"\"},\"Namespace\":\"\",\"IsInfra\":false,\"IsService\":false,\"Config\":{\"Hostname\":\"e42de8476903\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":true,\"OpenStdin\":true,\"StdinOnce\":false,\"Env\":[\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\",\"TERM=xterm\",\"container=podman\"],\"Cmd\":[\"sh\"],\"Image\":\"docker.io/library/busybox:latest\",\"Volumes\":null,\"WorkingDir\":\"/\",\"Entrypoint\":\"\",\"OnBuild\":null,\"Labels\":null,\"Annotations\":{\"io.podman.annotations.autoremove\":\"TRUE\"" API=response X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:11-04:00" level=trace msg="},\"StopSignal\":15,\"HealthcheckOnFailureAction\":\"none\",\"CreateCommand\":[\"podman\",\"run\",\"--rm\",\"-ti\",\"busybox\"],\"Umask\":\"0022\",\"Timeout\":0,\"StopTimeout\":10,\"Passwd\":true,\"sdNotifyMode\":\"container\"},\"HostConfig\":{\"Binds\":[],\"CgroupManager\":\"systemd\",\"CgroupMode\":\"private\",\"ContainerIDFile\":\"\",\"LogConfig\":{\"Type\":\"journald\",\"Config\":null,\"Path\":\"\",\"Tag\":\"\",\"Size\":\"0B\"},\"NetworkMode\":\"slirp4netns\",\"PortBindings\":{},\"RestartPolicy\":{\"Name\":\"\",\"MaximumRetryCount\":0},\"AutoRemove\":true,\"VolumeDriver\":\"\",\"VolumesFrom\":null,\"CapAdd\":[],\"CapDrop\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":[],\"GroupAdd\":[],\"IpcMode\":\"shareable\",\"Cgroup\":\"\",\"Cgroups\":\"default\",\"Links\":null,\"OomScoreAdj\":0,\"PidMode\":\"private\",\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyRootfs\":false,\"SecurityOpt\":[],\"Tmpfs\":{},\"UTSMode\":\"private\",\"UsernsMode\":\"\",\"ShmSize\":65536000,\"Runtime\":\"oci\",\"ConsoleSize\":[0,0],\"Isolation\":\"\",\"CpuShares\":0,\"Memory\":0,\"NanoCpus\":0,\"CgroupParent\":\"user.slice\",\"BlkioWeight\":0,\"BlkioWeightDevice\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteIOps\":null,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"Devices\":[],\"DiskQuota\":0,\"KernelMemory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":0,\"OomKillDisable\":false,\"PidsLimit\":2048,\"Ulimits\":[],\"CpuCount\":0,\"CpuPercent\":0,\"IOMaximumIOps\":0,\"IOMaximumBandwidth\":0,\"CgroupConf\":null}}\n" API=response X-Reference-Id=0xc000144a08
@ - - [12/Mar/2023:03:32:11 -0400] "GET /v4.4.2/libpod/containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/json?size=false HTTP/1.1" 200 4502 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 2m+0h/5t connection(s)       X-Reference-Id=0xc000144a08
DEBU[0023] IdleTracker:new 2m+0h/5t connection(s)        X-Reference-Id=0xc0000113d0
DEBU[0023] IdleTracker:active 2m+0h/6t connection(s)     X-Reference-Id=0xc0000113d0
DEBU[0023] Cached value indicated that volatile is being used 
DEBU[0023] overlay: mount_data=lowerdir=/home/test1/.local/share/containers/storage/overlay/l/ENXBDQN66S4FY64OOSJODFZ2ER,upperdir=/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/diff,workdir=/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/work,,userxattr,volatile 
DEBU[0023] Made network namespace at /run/user/1000/netns/netns-4cd3c76d-f917-34a1-18b1-35f69e91f7c1 for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Mounted container "e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6" at "/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/merged" 
DEBU[0023] Created root filesystem for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 at /home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/merged 
DEBU[0023] slirp4netns command: /usr/bin/slirp4netns --disable-host-loopback --mtu=65520 --enable-sandbox --enable-seccomp --enable-ipv6 -c -e 3 -r 4 --netns-type=path /run/user/1000/netns/netns-4cd3c76d-f917-34a1-18b1-35f69e91f7c1 tap0 
DEBU[0023] Skipping unrecognized mount in /etc/containers/mounts.conf: "# This configuration file specifies the default mounts for each container of the" 
DEBU[0023] Skipping unrecognized mount in /etc/containers/mounts.conf: "# tools adhering to this file (e.g., CRI-O, Podman, Buildah).  The format of the" 
DEBU[0023] Skipping unrecognized mount in /etc/containers/mounts.conf: "# config is /SRC:/DST, one mount per line." 
DEBU[0023] /etc/system-fips does not exist on host, not mounting FIPS mode subscription 
DEBU[0023] Setting Cgroups for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 to user.slice:libpod:e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] reading hooks from /usr/share/containers/oci/hooks.d 
DEBU[0023] Workdir "/" resolved to host path "/home/test1/.local/share/containers/storage/overlay/800778dfb21281bc290aa85af5c9e69b1015eea3584b6f8105c420ee0497d1cf/merged" 
DEBU[0023] Created OCI spec for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 at /home/test1/.local/share/containers/storage/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/config.json 
DEBU[0023] running conmon: /usr/bin/conmon               args="[--api-version 1 -c e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 -u e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 -r /usr/bin/crun -b /home/test1/.local/share/containers/storage/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata -p /run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/pidfile -n festive_shannon --exit-dir /run/user/1000/libpod/tmp/exits --full-attach -s -l journald --log-level trace --runtime-arg --log-format=json --runtime-arg --log --runtime-arg=/run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/oci-log -t --conmon-pidfile /run/user/1000/containers/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /home/test1/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg trace --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --network-config-dir --exit-command-arg  --exit-command-arg --network-backend --exit-command-arg netavark --exit-command-arg --volumepath --exit-command-arg /home/test1/.local/share/containers/storage/volumes --exit-command-arg --transient-store=false --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6]"
INFO[0023] Running conmon under slice user.slice and unitName libpod-conmon-e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6.scope 
DEBU[0023] Received: 17572                              
INFO[0023] Got Conmon PID as 17566                      
DEBU[0023] Created container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 in OCI runtime 
INFO[0023] Performing HTTP Hijack attach to container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Successfully connected to container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 attach socket /home/test1/.local/share/containers/storage/overlay-containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/userdata/attach 
DEBU[0023] Going to hijack container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 attach connection 
INFO[0023] Request Failed(Internal Server Error): unable to hijack connection 
time="2023-03-12T03:32:11-04:00" level=trace msg="{\"cause\":\"unable to hijack connection\",\"message\":\"unable to hijack connection\",\"response\":500}\n" API=response X-Reference-Id=0xc0000113d0
ERRO[0023] Error attaching to container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6: unable to hijack connection 
DEBU[0023] Attach for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 completed successfully 
@ - - [12/Mar/2023:03:32:11 -0400] "POST /v4.4.2/libpod/containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6/attach?detachKeys=ctrl-p%2Cctrl-q&detachkeys=ctrl-p%2Cctrl-q&stderr=true&stdin=true&stdout=true&stream=true HTTP/1.1" 500 95 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 3m+0h/6t connection(s)       X-Reference-Id=0xc0000113d0
DEBU[0023] IdleTracker:active 3m+0h/6t connection(s)     X-Reference-Id=0xc0000113d0
DEBU[0023] Starting parallel job on container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Removing container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Cleaning up container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Tearing down network namespace at /run/user/1000/netns/netns-4cd3c76d-f917-34a1-18b1-35f69e91f7c1 for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Successfully cleaned up container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Unmounted container "e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6" 
DEBU[0023] Removing all exec sessions for container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 
DEBU[0023] Container e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6 storage is already unmounted, skipping... 
time="2023-03-12T03:32:11-04:00" level=trace msg="[{\"Id\":\"e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6\"}]\n" API=response X-Reference-Id=0xc0000113d0
@ - - [12/Mar/2023:03:32:11 -0400] "DELETE /v4.4.2/libpod/containers/e42de8476903a2dd884d4a9c143c7b57080380e989e28173d52a900f13dfe4e6?force=false&volumes=true HTTP/1.1" 200 76 "" "Go-http-client/1.1"
DEBU[0023] IdleTracker:idle 3m+0h/6t connection(s)       X-Reference-Id=0xc0000113d0
DEBU[0023] IdleTracker:closed 3m+0h/6t connection(s)     X-Reference-Id=0xc0000113d0
DEBU[0023] IdleTracker:closed 2m+0h/6t connection(s)     X-Reference-Id=0xc000144018
DEBU[0023] IdleTracker:closed 1m+0h/6t connection(s)     X-Reference-Id=0xc000144a08
time="2023-03-12T03:32:47-04:00" level=trace msg="{\"httpproxy\":true,\"terminal\":true,\"stdin\":true,\"stop_timeout\":10,\"log_configuration\":{},\"raw_image_name\":\"busybox\",\"systemd\":\"true\",\"sdnotifyMode\":\"container\",\"pidns\":{},\"utsns\":{},\"remove\":true,\"containerCreateCommand\":[\"podman\",\"run\",\"--rm\",\"-ti\",\"busybox\"],\"init_container_type\":\"\",\"manage_password\":true,\"image\":\"busybox\",\"image_volume_mode\":\"anonymous\",\"ipcns\":{},\"volatile\":true,\"seccomp_policy\":\"default\",\"userns\":{},\"idmappings\":{\"HostUIDMapping\":true,\"HostGIDMapping\":true,\"UIDMap\":null,\"GIDMap\":null,\"AutoUserNs\":false,\"AutoUserNsOpts\":{\"Size\":0,\"InitialSize\":0,\"PasswdFile\":\"\",\"GroupFile\":\"\",\"AdditionalUIDMappings\":null,\"AdditionalGIDMappings\":null}},\"umask\":\"0022\",\"cgroupns\":{},\"cgroups_mode\":\"enabled\",\"netns\":{},\"Networks\":null,\"use_image_hosts\":false}" API=request X-Reference-Id=0xc000144a08
@hsnoil hsnoil added the kind/bug Categorizes issue or PR as related to a bug. label Mar 13, 2023
@Luap99 Luap99 self-assigned this Mar 14, 2023
@Luap99 Luap99 added the In Progress This issue is actively being worked by the assignee, please do not work on this at this time. label Mar 14, 2023
Luap99 added a commit to Luap99/libpod that referenced this issue Mar 14, 2023
@Luap99
system service --log-level=trace: support hijack
7d8d3e8 
When the service is running with trace log level it wraps the
`http.ResponseWriter` to log extra information. The problem is that the
new type does not keep all the functions from the embedded type.
Instead we have to implement them ourselves, however only Write() was
implemented. Thus `Hijack()`could not be called on the writer. To
prevent these issues we would implement all the interfaces that the
inner type supports (Header, WriteHeader, Flush, Hijack).

Fixes containers#17749

Signed-off-by: Paul Holzinger <pholzing@redhat.com>
@Luap99 Luap99 mentioned this issue Mar 14, 2023
Merged
@Luap99
Copy link
Member

Luap99 commented Mar 14, 2023

Thanks for the report, PR #17781 to fix it

@hsnoil
Copy link
Author

hsnoil commented Mar 14, 2023 •
edited
Loading

Thanks for the report, PR #17781 to fix it

Thanks, it works!

Just to confirm a minor detail I noticed, the trace logs are in this format:

time="2023-03-14T14:33:48-04:00" level=trace msg=","dev.tilt.gc":"true"" API=response X-Reference-Id=0xc0008be820

while other logs have a different identifier in front:

DEBU[0433] IdleTracker:active 7m+0h/43t connection(s) X-Reference-Id=0xc0003f2da8

I do see TRAC[0000] logs on startup though like so:

TRAC[0000] Methods: POST Path: /volumes/prune

If that is fine, then all is good :)

@Luap99
Copy link
Member

Luap99 commented Mar 15, 2023

I think this is because we use a separate logger instance for it, feel free to file a new issue if you want to get this fixed.

Luap99 added a commit to Luap99/libpod that referenced this issue Mar 16, 2023
@Luap99
system service --log-level=trace: support hijack
bd65bf2 
When the service is running with trace log level it wraps the
`http.ResponseWriter` to log extra information. The problem is that the
new type does not keep all the functions from the embedded type.
Instead we have to implement them ourselves, however only Write() was
implemented. Thus `Hijack()`could not be called on the writer. To
prevent these issues we would implement all the interfaces that the
inner type supports (Header, WriteHeader, Flush, Hijack).

Fixes containers#17749

Signed-off-by: Paul Holzinger <pholzing@redhat.com>
@github-actions github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Aug 30, 2023
@github-actions github-actions bot locked as resolved and limited conversation to collaborators Aug 30, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@Luap99 Luap99

Labels
In Progress This issue is actively being worked by the assignee, please do not work on this at this time. kind/bug Categorizes issue or PR as related to a bug. locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

system service --log-level=trace: support hijack Luap99/libpod
2 participants
@Luap99 @hsnoil