[flakey-test] cri-integration: TestIssue7496

[fuweid]

Description

The shim was leak during the test.

2023-12-01T00:18:12.8811516Z     default: [pid 75044] --- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=75038, si_uid=0} ---
2023-12-01T00:18:12.8922269Z     default:     issue7496_linux_test.go:94: PodSandbox 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f has been deleted and start to wait for strace exit
2023-12-01T00:18:27.8939499Z     default:     issue7496_linux_test.go:98:
2023-12-01T00:18:27.8940760Z     default:         	Error Trace:	/root/go/src/github.com/containerd/containerd/integration/issue7496_linux_test.go:98
2023-12-01T00:18:27.8942177Z     default:         	Error:      	An error is expected but got nil.
2023-12-01T00:18:27.8942921Z     default:         	Test:       	TestIssue7496
2023-12-01T00:18:27.8943905Z     default:         	Messages:   	should failed to call shim connect API
2023-12-01T00:18:27.8945421Z     default:     issue7496_linux_test.go:100: Strace doesn't exit in time
2023-12-01T00:18:27.8946437Z     default:     issue7496_linux_test.go:102: Cleanup the shim (pid: 75038)
2023-12-01T00:18:27.8951010Z     default: [pid 75049] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8952017Z     default: [pid 75046] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8953159Z     default: [pid 75045] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8956242Z     default: [pid 75043] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8957151Z     default: [pid 75042] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8957875Z     default: [pid 75039] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8961005Z     default: [pid 75119] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8961801Z     default: [pid 75047] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8962580Z     default: [pid 75040] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8963689Z     default: [pid 75041] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8965486Z     default: [pid 75044] +++ killed by SIGKILL +++
2023-12-01T00:18:27.8968289Z     default: +++ killed by SIGKILL +++
2023-12-01T00:18:27.8972998Z     default:     issue7496_linux_test.go:144: Strace has exited
2023-12-01T00:18:27.8974449Z     default: --- FAIL: TestIssue7496 (64.08s)

https://github.com/containerd/containerd/actions/runs/7053718417/job/19201394691?pr=9445
In #9445

2023-12-01T00:21:16.6609235Z     default: time="2023-12-01T00:17:24.408236333Z" level=info msg="CreateContainer within sandbox \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\" for &ContainerMetadata{Name:pausecontainer,Attempt:0,} returns container id \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\""
2023-12-01T00:21:16.6609917Z     default: time="2023-12-01T00:17:24.408668226Z" level=info msg="StartContainer for \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\""
2023-12-01T00:21:16.6611212Z     default: time="2023-12-01T00:17:24.409056526Z" level=info msg="connecting to shim 4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7" address="unix:///run/containerd/s/d55e7c20bf3c9f5535bae96d5dca8841879a861f7fde222b8100640c499e4989" protocol=ttrpc version=3
2023-12-01T00:21:16.6611839Z     default: time="2023-12-01T00:17:24.462805638Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/create type=containerd.events.TaskCreate
2023-12-01T00:21:16.6612454Z     default: time="2023-12-01T00:17:24.475220072Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/start type=containerd.events.TaskStart
2023-12-01T00:21:16.6613228Z     default: time="2023-12-01T00:17:24.477458307Z" level=info msg="StartContainer for \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" returns successfully"
2023-12-01T00:21:16.6613910Z     default: time="2023-12-01T00:17:24.477886566Z" level=info msg="StopPodSandbox for \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\""
2023-12-01T00:21:16.6614566Z     default: time="2023-12-01T00:17:24.478469038Z" level=info msg="Kill container \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\""
2023-12-01T00:21:16.6614958Z     default: time="2023-12-01T00:17:24.488503033Z" level=debug msg="garbage collected" d=1.204856ms
2023-12-01T00:21:16.6615711Z     default: time="2023-12-01T00:17:24.494912691Z" level=debug msg="Finish piping stderr of container \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\""
2023-12-01T00:21:16.6616523Z     default: time="2023-12-01T00:17:24.495220172Z" level=debug msg="Finish piping stdout of container \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\""
2023-12-01T00:21:16.6617131Z     default: time="2023-12-01T00:17:24.504652242Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
2023-12-01T00:21:16.6618660Z     default: time="2023-12-01T00:17:24.504902112Z" level=debug msg="received exit event container_id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" pid:75081 exit_status:137 exited_at:{seconds:1701389844 nanos:504395334}"
2023-12-01T00:21:16.6619170Z     default: 2023/12/01 00:17:25 traces export: Post "https://localhost:4318/v1/traces": dial tcp [::1]:4318: connect: connection refused
2023-12-01T00:21:16.6620026Z     default: time="2023-12-01T00:17:34.505697952Z" level=debug msg="failed to delete task" error="context deadline exceeded" id=4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7
2023-12-01T00:21:16.6621956Z     default: time="2023-12-01T00:17:34.505790303Z" level=error msg="failed to handle container TaskExit event container_id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" pid:75081 exit_status:137 exited_at:{seconds:1701389844 nanos:504395334}" error="failed to stop container: failed to delete task: context deadline exceeded: unknown"
2023-12-01T00:21:16.6623341Z     default: time="2023-12-01T00:17:35.652328473Z" level=info msg="TaskExit event container_id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" pid:75081 exit_status:137 exited_at:{seconds:1701389844 nanos:504395334}"
2023-12-01T00:21:16.6624225Z     default: time="2023-12-01T00:17:37.652582165Z" level=error msg="get state for 4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6624587Z     default: time="2023-12-01T00:17:37.652658888Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6625407Z     default: time="2023-12-01T00:17:39.653371812Z" level=error msg="get state for 4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6625763Z     default: time="2023-12-01T00:17:39.653414872Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6628079Z     default: time="2023-12-01T00:17:45.652782447Z" level=error msg="Failed to handle backOff event container_id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" pid:75081 exit_status:137 exited_at:{seconds:1701389844 nanos:504395334} for 4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7" error="failed to handle container TaskExit event: failed to stop container: context deadline exceeded: unknown"
2023-12-01T00:21:16.6628581Z     default: time="2023-12-01T00:17:48.532459380Z" level=error msg="ttrpc: received message on inactive stream" stream=33
2023-12-01T00:21:16.6629209Z     default: time="2023-12-01T00:17:48.533200075Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/delete type=containerd.events.TaskDelete
2023-12-01T00:21:16.6629702Z     default: time="2023-12-01T00:17:48.533764772Z" level=error msg="ttrpc: received message on inactive stream" stream=35
2023-12-01T00:21:16.6630188Z     default: time="2023-12-01T00:17:48.534192146Z" level=error msg="ttrpc: received message on inactive stream" stream=37
2023-12-01T00:21:16.6630665Z     default: time="2023-12-01T00:17:48.534446117Z" level=error msg="ttrpc: received message on inactive stream" stream=39
2023-12-01T00:21:16.6631141Z     default: time="2023-12-01T00:17:48.534572312Z" level=error msg="ttrpc: received message on inactive stream" stream=43
2023-12-01T00:21:16.6632577Z     default: time="2023-12-01T00:17:48.652272571Z" level=info msg="TaskExit event container_id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" id:\"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" pid:75081 exit_status:137 exited_at:{seconds:1701389844 nanos:504395334}"
2023-12-01T00:21:16.6633718Z     default: time="2023-12-01T00:17:48.653553999Z" level=debug msg="failed to delete task" error="rpc error: code = NotFound desc = container not created: not found" id=4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7
2023-12-01T00:21:16.6634614Z     default: time="2023-12-01T00:17:48.654022299Z" level=info msg="Ensure that container 4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7 in task-service has been cleanup successfully"
2023-12-01T00:21:16.6635255Z     default: time="2023-12-01T00:17:48.681659474Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
2023-12-01T00:21:16.6635933Z     default: time="2023-12-01T00:17:48.681859262Z" level=debug msg="received sandbox exit {code:137 exitedAt:{wall:681414316 ext:63836986668 loc:<nil>} err:<nil>}"
2023-12-01T00:21:16.6636783Z     default: time="2023-12-01T00:17:58.682984516Z" level=debug msg="failed to delete task" error="context deadline exceeded" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f
2023-12-01T00:21:16.6637919Z     default: time="2023-12-01T00:17:58.683046150Z" level=error msg="failed to handle sandbox TaskExit 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f" error="failed to stop sandbox: failed to delete task: context deadline exceeded: unknown"
2023-12-01T00:21:16.6638726Z     default: time="2023-12-01T00:17:58.683056429Z" level=error msg="failed to wait for sandbox exit" error="failed to stop sandbox: failed to delete task: context deadline exceeded: unknown"
2023-12-01T00:21:16.6639941Z     default: time="2023-12-01T00:17:58.683069193Z" level=error msg="failed to get task exit status for \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\"" error="failed to stop sandbox: failed to delete task: context deadline exceeded: unknown"
2023-12-01T00:21:16.6640963Z     default: time="2023-12-01T00:17:58.683101824Z" level=debug msg="received exit event sandbox_id:\"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\" exit_status:255 exited_at:{seconds:1701389878 nanos:683075755}"
2023-12-01T00:21:16.6641786Z     default: time="2023-12-01T00:18:00.684089943Z" level=error msg="get state for 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6642158Z     default: time="2023-12-01T00:18:00.684137562Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6642940Z     default: time="2023-12-01T00:18:01.072688356Z" level=info msg="TearDown network for sandbox \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\" successfully"
2023-12-01T00:21:16.6643848Z     default: time="2023-12-01T00:18:01.072721457Z" level=info msg="StopPodSandbox for \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\" returns successfully"
2023-12-01T00:21:16.6644709Z     default: time="2023-12-01T00:18:01.073123152Z" level=info msg="RemovePodSandbox for \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\""
2023-12-01T00:21:16.6645425Z     default: time="2023-12-01T00:18:01.073156674Z" level=info msg="Forcibly stopping sandbox \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\""
2023-12-01T00:21:16.6646434Z     default: time="2023-12-01T00:18:01.073235260Z" level=info msg="Container to stop \"4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7\" must be in running or unknown state, current state \"CONTAINER_EXITED\""
2023-12-01T00:21:16.6647283Z     default: time="2023-12-01T00:18:03.074232282Z" level=error msg="get state for 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6647764Z     default: time="2023-12-01T00:18:03.074288445Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6648542Z     default: time="2023-12-01T00:18:03.086987039Z" level=info msg="TearDown network for sandbox \"906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f\" successfully"
2023-12-01T00:21:16.6649498Z     default: time="2023-12-01T00:18:05.087178433Z" level=error msg="get state for 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6649869Z     default: time="2023-12-01T00:18:05.087221994Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6650535Z     default: time="2023-12-01T00:18:05.088824591Z" level=debug msg="event published" ns=k8s.io topic=/snapshot/remove type=containerd.events.SnapshotRemove
2023-12-01T00:21:16.6651216Z     default: time="2023-12-01T00:18:05.089813556Z" level=debug msg="event published" ns=k8s.io topic=/containers/delete type=containerd.events.ContainerDelete
2023-12-01T00:21:16.6651706Z     default: time="2023-12-01T00:18:05.190910417Z" level=debug msg="schedule snapshotter cleanup" snapshotter=overlayfs
2023-12-01T00:21:16.6652545Z     default: time="2023-12-01T00:18:05.191887621Z" level=debug msg="removed snapshot" key=k8s.io/96/4e51c7a502eecc857c488641f42c1c2c54f3f6053d640dd2ec4e6952c0644ac7 snapshotter=overlayfs
2023-12-01T00:21:16.6653092Z     default: time="2023-12-01T00:18:05.192784847Z" level=debug msg="snapshot garbage collected" d=1.838984ms snapshotter=overlayfs
2023-12-01T00:21:16.6653514Z     default: time="2023-12-01T00:18:05.192821255Z" level=debug msg="garbage collected" d="971.735µs"
2023-12-01T00:21:16.6654016Z     default: 2023/12/01 00:18:05 traces export: Post "https://localhost:4318/v1/traces": dial tcp [::1]:4318: connect: connection refused
2023-12-01T00:21:16.6655001Z     default: time="2023-12-01T00:18:07.091279759Z" level=error msg="get state for 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f" error="context deadline exceeded: unknown"
2023-12-01T00:21:16.6655367Z     default: time="2023-12-01T00:18:07.091341695Z" level=warning msg="unknown status" status=0
2023-12-01T00:21:16.6655864Z     default: time="2023-12-01T00:18:12.867950705Z" level=error msg="ttrpc: received message on inactive stream" stream=43
2023-12-01T00:21:16.6656353Z     default: time="2023-12-01T00:18:12.868456434Z" level=error msg="ttrpc: received message on inactive stream" stream=45
2023-12-01T00:21:16.6656834Z     default: time="2023-12-01T00:18:12.868980868Z" level=error msg="ttrpc: received message on inactive stream" stream=47
2023-12-01T00:21:16.6657318Z     default: time="2023-12-01T00:18:12.869006245Z" level=error msg="ttrpc: received message on inactive stream" stream=49
2023-12-01T00:21:16.6658401Z     default: time="2023-12-01T00:18:12.871859016Z" level=debug msg="failed to delete task" error="rpc error: code = NotFound desc = cannot delete a deleted process: not found" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f
2023-12-01T00:21:16.6659142Z     default: time="2023-12-01T00:18:12.872592575Z" level=info msg="shim disconnected" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f namespace=k8s.io
2023-12-01T00:21:16.6659974Z     default: time="2023-12-01T00:18:12.872704644Z" level=warning msg="cleaning up after shim disconnected" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f namespace=k8s.io
2023-12-01T00:21:16.6660401Z     default: time="2023-12-01T00:18:12.872726004Z" level=info msg="cleaning up dead shim" namespace=k8s.io
2023-12-01T00:21:16.6661021Z     default: time="2023-12-01T00:18:12.883471725Z" level=debug msg="event forwarded" ns=k8s.io topic=/tasks/delete type=containerd.events.TaskDelete
2023-12-01T00:21:16.6662049Z     default: time="2023-12-01T00:18:12.887517437Z" level=warning msg="cleanup warnings time=\"2023-12-01T00:18:12Z\" level=debug msg=\"starting signal loop\" namespace=k8s.io pid=75195 runtime=io.containerd.runc.v2\n" namespace=k8s.io
2023-12-01T00:21:16.6662808Z     default: time="2023-12-01T00:18:12.888038725Z" level=debug msg="event published" namespace=k8s.io ns=k8s.io topic=/tasks/exit type=containerd.events.TaskExit
2023-12-01T00:21:16.6663496Z     default: time="2023-12-01T00:18:12.888136066Z" level=debug msg="event published" namespace=k8s.io ns=k8s.io topic=/tasks/delete type=containerd.events.TaskDelete
2023-12-01T00:21:16.6665871Z     default: time="2023-12-01T00:18:12.888205053Z" level=error msg="failed to delete bundle" error="unmount rootfs /run/containerd-test/io.containerd.runtime.v2.task/k8s.io/906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f/rootfs: lstat /run/containerd-test/io.containerd.runtime.v2.task/k8s.io/906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f: no such file or directory" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f
2023-12-01T00:21:16.6668235Z     default: time="2023-12-01T00:18:12.888247423Z" level=error msg="failed to delete shim" error="failed to delete bundle: unmount rootfs /run/containerd-test/io.containerd.runtime.v2.task/k8s.io/906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f/rootfs: lstat /run/containerd-test/io.containerd.runtime.v2.task/k8s.io/906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f: no such file or directory" id=906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f
2023-12-01T00:21:16.6669122Z     default: time="2023-12-01T00:18:12.888327070Z" level=info msg="Ensure that sandbox 906d3efd8ad2663c3550b9351abac46d7916aff7d3a58c5121d95e6db567b52f in task-service has been cleanup successfully"
2023-12-01T00:21:16.6669782Z     default: time="2023-12-01T00:18:12.889304956Z" level=debug msg="event published" ns=k8s.io topic=/snapshot/remove type=containerd.events.SnapshotRemove
2023-12-01T00:21:16.6670523Z     default: time="2023-12-01T00:18:12.889943883Z" level=debug msg="event published" ns=k8s.io topic=/containers/delete type=containerd.events.ContainerDelete

Steps to reproduce the issue

No idea

Describe the results you received and expected

Shim should be deleted.

What version of containerd are you using?

main

Any other relevant information

No response

Show configuration if it is related to CRI plugin.

No response