poststop hook executed twice

[chethanah]

/kind bug

Description

• poststop hook executes twice

Consider the following hooks example for podman

• Hooks config prestart-hook.json and poststop-hook.json

# ls /etc/containers/oci/hooks.d/
poststop-hook.json  prestart-hook.json

# jq .  /etc/containers/oci/hooks.d/prestart-hook.json
{
  "version": "1.0.0",
  "hook": {
    "path": "/root/podman-hook/prestart-hook.sh"
  },
  "when": {
    "annotations": {
      "testhook": "true"
    }
  },
  "stages": [
    "prestart"
  ]
}

# jq .  /etc/containers/oci/hooks.d/poststop-hook.json
{
  "version": "1.0.0",
  "hook": {
    "path": "/root/podman-hook/poststop-hook.sh"
  },
  "when": {
    "annotations": {
      "testhook": "true"
    }
  },
  "stages": [
    "poststop"
  ]
}

• prestart-hook.sh and poststop-hook.sh are executed in prestart and poststop stages respectively. Writes logs to prestart-hook.log and poststop-hook.log

root@home:~/podman-hook# cat prestart-hook.sh 
#!/bin/bash 
echo "----Prestart" >> /root/podman-hook/prestart-hook.log
date +%s >> /root/podman-hook/prestart-hook.log
#cat - | jq . >> /root/podman-hook/prestart-hook.log

root@home:~/podman-hook# cat poststop-hook.sh 
#!/bin/bash 
echo "----Poststop" >> /root/podman-hook/poststop-hook.log
date +%s >> /root/podman-hook/poststop-hook.log
#cat - | jq . >> /root/podman-hook/poststop-hook.log

# chmod 755 prestart-hook.sh poststop-hook.sh

• Launch container, with --rm option

# podman --hooks-dir="/etc/containers/oci/hooks.d/" run --annotation=testhook=true -it --rm  docker.io/library/bash
bash-5.1# ls
bin    dev    etc    home   lib    media  mnt    opt    proc   root   run    sbin   srv    sys    tmp    usr    var
bash-5.1#
exit

• Upon inspecting the prestart-hook.log and poststop-hook.log, we can notice that the poststop hook has been executed twice.

# cat prestart-hook.log
----Prestart
1617936054

# cat poststop-hook.log
----Poststop
1617936057
----Poststop
1617936059

• The same can be verified by launching container with --log-level=debug. We can see debug logs where poststop hook is executed twice for a single container launch and exit.

Issue

• The stages were prestart and poststop only. But poststop executed twice.
• poststop hook is not added to OCI spec (config.json) of container. Since it's handled locally by podman as extension stage hook, it's executed twice. Once, during cleanupRuntime and again during removeContainer.
• Without the --rm option the poststop hook executes only once, but when podman rm <ID> is run the poststop hook executes again.

How to?

• How to execute poststop hook only once? In an use case where poststop hooks operates on file, executing twice leads to unitended results.
• Is there a way to remove poststop from extension stage hooks from hooks config?
• Since, poststop hook is handled localy by podman and not by runtime, how to pass poststop hook with OCI spec?

Understood from the source the following

• "postDeleteHooks runs the poststop hooks (if any) as specified by the OCI Runtime Specification (which requires them to run post-delete, despite the stage name)"
• Also, delete(ctx) is called twice. Once, during cleanupRuntime and again during removeContainer. This is where extension stage hook is handled lcoally.

Output of podman version:

$ podman version
Version:      3.0.1
API Version:  3.0.0
Go Version:   go1.15.2
Built:        Thu Jan  1 05:30:00 1970
OS/Arch:      linux/amd64

[rhatdan]

If you run this command without the --rm flag, does the same issue happen?

[chethanah]

• Without the --rm flag the poststop hook is executed only once. But podman rm executes the poststop hook again.
• Considering the same example as above, here is a sample console output
• Launch container without --rm option

# podman --log-level=debug --hooks-dir="/etc/containers/oci/hooks.d/" run --annotation=testhook=true -it  docker.io/library/bash
bash-5.1# ls
bin    dev    etc    home   lib    media  mnt    opt    proc   root   run    sbin   srv    sys    tmp    usr    var
bash-5.1#
exit

• poststop hook executed only once

# cat prestart-hook.log
----Prestart
1618285896

# cat poststop-hook.log
----Poststop
1618285903

• Remove container using rm subcommand, notice poststop hook executed again.

# podman ps -a
CONTAINER ID  IMAGE                   COMMAND  CREATED         STATUS                     PORTS   NAMES
6b57d57fb225  docker.io/library/bash  bash     27 seconds ago  Exited (0) 19 seconds ago          elegant_goldwasser

# podman rm 6b57d57fb225
6b57d57fb2258df8cff56b1213d85c79eff8a4b8a9b04d17df213e9f588dcf49

# cat poststop-hook.log
----Poststop
1618285903
----Poststop
1618285931

• Also considering OCI: poststop hook is only executed after the container delete operation
  • https://github.com/opencontainers/runtime-spec/blob/master/config.md#poststop
  • The same hook operation can be verified with runc
    • create -> start -> run prestart hook -> stopped state -> delete -> run poststop hook
  • The poststop executes only once after container delete.