[Bug 1891358] [NEW] systemd not respecting EXTEND_TIMEOUT_USEC when stopping service

Adrian Barkus 1891358 at bugs.launchpad.net
Wed Aug 12 16:20:47 UTC 2020 

Public bug reported:

It seems like systemd is not consistently respecting
EXTEND_TIMEOUT_USEC. When I stop a service, it is being killed
prematurely even after EXTEND_TIMEOUT_USEC was recently sent to systemd
(however it is not killed immediately after the default TimeoutStopSec
either).

The service `ihm-eco-sputnik-agent.service` includes the following
configuration:

  [Service]
  Restart=always
  RestartSec=5
  Type=notify
  TimeoutStartSec=10
  WatchdogSec=60
  TimeoutStopSec=60
  KillMode=mixed
  ...

When I `systemctl restart ihm-eco-sputnik-agent.service`, I see the
following logs in `journalctl`:

```
Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Trying to enqueue job ihm-eco-sputnik-agent.service/restart/replace
Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Installed new job ihm-eco-sputnik-agent.service/restart as 1149303
Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Enqueued job ihm-eco-sputnik-agent.service/restart as 1149303
Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Changed running -> stop-sigterm
Aug 12 15:43:59 00044bcbe9bc systemd[1]: Stopping ihm-eco
sputnik-agent...
-- Subject: Unit ihm-eco-sputnik-agent.service has begun shutting down
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit ihm-eco-sputnik-agent.service has begun shutting down.
Aug 12 15:44:49 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (WATCHDOG=1)
Aug 12 15:44:49 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (EXTEND_TIMEOUT_USEC=60000000)
Aug 12 15:45:09 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (WATCHDOG=1)
Aug 12 15:45:09 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (EXTEND_TIMEOUT_USEC=60000000)
Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: State 'stop-sigterm' timed out. Killing.
Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 19520 (ihm-eco-sputnik) with signal SIGKILL.
Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 21114 (systemctl) with signal SIGKILL.
Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 21111 (200_IhmEcoDeplo) with signal SIGKILL.
Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Main process exited, code=killed, status=9/KILL
```

I'm not sure if this is related but I'm also seeing the application
successfully writing notification messages which systemd apparently
doesn't receive (they aren't logged).

lsb_release -rd:
```
Description:	Ubuntu 18.04.5 LTS
Release:	18.04
```

apt-cache policy systemd:
```
systemd:
  Installed: 237-3ubuntu10.42
  Candidate: 237-3ubuntu10.42
  Version table:
 *** 237-3ubuntu10.42 500
        500 s3://ihm-eco-apt-repository-us-west-2.s3-accelerate.amazonaws.com/ihm-eco-apt-repository-us-west-2 bionic-20200810/ubuntu arm64 Packages
        100 /var/lib/dpkg/status
```

** Affects: systemd (Ubuntu)
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1891358

Title:
  systemd not respecting EXTEND_TIMEOUT_USEC when stopping service

Status in systemd package in Ubuntu:
  New

Bug description:
  It seems like systemd is not consistently respecting
  EXTEND_TIMEOUT_USEC. When I stop a service, it is being killed
  prematurely even after EXTEND_TIMEOUT_USEC was recently sent to
  systemd (however it is not killed immediately after the default
  TimeoutStopSec either).

  The service `ihm-eco-sputnik-agent.service` includes the following
  configuration:

    [Service]
    Restart=always
    RestartSec=5
    Type=notify
    TimeoutStartSec=10
    WatchdogSec=60
    TimeoutStopSec=60
    KillMode=mixed
    ...

  When I `systemctl restart ihm-eco-sputnik-agent.service`, I see the
  following logs in `journalctl`:

  ```
  Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Trying to enqueue job ihm-eco-sputnik-agent.service/restart/replace
  Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Installed new job ihm-eco-sputnik-agent.service/restart as 1149303
  Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Enqueued job ihm-eco-sputnik-agent.service/restart as 1149303
  Aug 12 15:43:59 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Changed running -> stop-sigterm
  Aug 12 15:43:59 00044bcbe9bc systemd[1]: Stopping ihm-eco
  sputnik-agent...
  -- Subject: Unit ihm-eco-sputnik-agent.service has begun shutting down
  -- Defined-By: systemd
  -- Support: http://www.ubuntu.com/support
  --
  -- Unit ihm-eco-sputnik-agent.service has begun shutting down.
  Aug 12 15:44:49 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (WATCHDOG=1)
  Aug 12 15:44:49 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (EXTEND_TIMEOUT_USEC=60000000)
  Aug 12 15:45:09 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (WATCHDOG=1)
  Aug 12 15:45:09 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Got notification message from PID 19520 (EXTEND_TIMEOUT_USEC=60000000)
  Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: State 'stop-sigterm' timed out. Killing.
  Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 19520 (ihm-eco-sputnik) with signal SIGKILL.
  Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 21114 (systemctl) with signal SIGKILL.
  Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Killing process 21111 (200_IhmEcoDeplo) with signal SIGKILL.
  Aug 12 15:45:10 00044bcbe9bc systemd[1]: ihm-eco-sputnik-agent.service: Main process exited, code=killed, status=9/KILL
  ```

  I'm not sure if this is related but I'm also seeing the application
  successfully writing notification messages which systemd apparently
  doesn't receive (they aren't logged).

  lsb_release -rd:
  ```
  Description:	Ubuntu 18.04.5 LTS
  Release:	18.04
  ```

  apt-cache policy systemd:
  ```
  systemd:
    Installed: 237-3ubuntu10.42
    Candidate: 237-3ubuntu10.42
    Version table:
   *** 237-3ubuntu10.42 500
          500 s3://ihm-eco-apt-repository-us-west-2.s3-accelerate.amazonaws.com/ihm-eco-apt-repository-us-west-2 bionic-20200810/ubuntu arm64 Packages
          100 /var/lib/dpkg/status
  ```

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1891358/+subscriptions

More information about the foundations-bugs mailing list