[systemd-devel] Timeout for 'Activating (start)' status

Mikhail Kasimov mikhail.kasimov at gmail.com
Fri Jul 7 11:56:42 UTC 2017 

Hello, everyone!


06.07.2017 19:17, Mikhail Kasimov пишет:
>
> 06.07.2017 19:12, Mikhail Kasimov пишет:
>> 06.07.2017 18:27, Michael Chapman пишет:
>>> On Fri, 7 Jul 2017, Mikhail Kasimov wrote:
>>>> 06.07.2017 17:18, Michael Chapman пишет:
>>>>> On Thu, 6 Jul 2017, Mikhail Kasimov wrote:
>>>>>> Hello!
>>>>>>
>>>>>> 've got an interesting trouble on timer-activated service --
>>>>>> 'systemctl
>>>>>> status' returns a log with 'Activating (start)' status:
>>>>>>
>>>>>> [1]
>>>>>> ==========
>>>>>> k_mikhail at linux-mk500:~> systemctl status vba32update.service
>>>>>> ● vba32update.service - VBA32 Anti-Virus Update Service
>>>>>>   Loaded: loaded (/etc/systemd/system/vba32update.service; disabled;
>>>>>> vendor preset: disabled)
>>>>>>   Active: activating (start) since Чтв 2017-07-06 15:32:35 EEST;
>>>>>> 35min ago
>>>>>> Main PID: 6214 (vbaupdx)
>>>>>>    Tasks: 1 (limit: 512)
>>>>>>   CGroup: /system.slice/vba32update.service
>>>>>>           └─6214 ./vbaupdx http://anti-virus.by/beta/update
>>>>>>
>>>>>> Июл 06 15:32:35 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus
>>>>>> Update
>>>>>> Service...
>>>>>> Июл 06 15:32:35 linux-mk500 vbacl[6214]: Vba32 console scanner update
>>>>>> process started
>>>>>> Июл 06 15:32:35 linux-mk500 vbacl[6214]: Reading configuration options
>>>>>> from ./vbacl.ini
>>>>>> Июл 06 15:32:35 linux-mk500 vbacl[6214]: Using direct connection for
>>>>>> update
>>>>>> k_mikhail at linux-mk500:~>
>>>>>> ==========
>>>>>>
>>>>>>
>>>>>> Simultaneously:
>>>>>> [2]
>>>>>> ==========
>>>>>> k_mikhail at linux-mk500:~> systemctl list-units -t timer
>>>>>> UNIT                         LOAD   ACTIVE SUB     DESCRIPTION
>>>>>> vba32update.timer            loaded active running Runs VBA32 Update
>>>>>> Hourly
>>>>>> ==========
>>>>>>
>>>>>> And that is normal. But 35 minutes for activating service is too long,
>>>>>> as for me.
>>>>> Is this a Type=oneshot service?
>>>>>
>>>>> It's a bit weird, but Type=oneshot services are not considered to be
>>>>> fully started until the ExecStart= command has exited. Until that time
>>>>> they're still "activating".
>>>>>
>>>>> You may be better off making the service Type=simple instead. A
>>>>> Type=simple service is fully started as soon as it has spawned the
>>>>> ExecStart= command.
>>>> Yes, Type=oneshot, because, if Type=simple, service will be active
>>>> permanently in case of its start. But this is not what is needed here --
>>>> service should be started, then to check the updates of anti-virus
>>>> software and then be successfully closed. Nothing more. Only one thing
>>>> can impact here -- remote anti-virus server connection timeout. And if
>>>> server connection timeout is set in wrong way, having a native systemd
>>>> forced timeout for oneshot-services may be useful.
>>> I still think you want Type=simple there. A Type=simple service can
>>> exit when it's finished doing whatever it needs to do. The service
>>> will then transition back to its inactive state.
>>>
>>> Really, I think the only time Type=oneshot should be used is when you
>>> have a _sequence_ of units, where one unit shouldn't be started until
>>> the previous one has finished. You don't have that here.
>> Ok, here is Type=oneshot. And we can see two sessions of our service
>> (at1 7:06:52 and 18:06:57):
>> ==================
>> [1]
>> Июл 06 17:06:52 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
>> Service...
>> Июл 06 17:06:52 linux-mk500 vbacl[8058]: Vba32 console scanner update
>> process started
>> Июл 06 17:06:52 linux-mk500 vbacl[8058]: Reading configuration options
>> from ./vbacl.ini
>> Июл 06 17:06:52 linux-mk500 vbacl[8058]: Using direct connection for update
>> Июл 06 17:06:56 linux-mk500 vbacl[8058]: Current dir is ./
>> Июл 06 17:06:56 linux-mk500 vbacl[8058]: Start update from
>> http://anti-virus.by/beta/update
>> Июл 06 17:06:56 linux-mk500 vbacl[8058]: Receiving file list
>> Июл 06 17:06:56 linux-mk500 vbacl[8058]: File list received
>> Июл 06 17:06:56 linux-mk500 vbacl[8058]: Update is not needed
>> Июл 06 17:06:57 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
>> Service.
>>
>> [2]
>> Июл 06 18:06:57 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
>> Service...
>> Июл 06 18:06:57 linux-mk500 vbacl[8842]: Vba32 console scanner update
>> process started
>> Июл 06 18:06:57 linux-mk500 vbacl[8842]: Reading configuration options
>> from ./vbacl.ini
>> Июл 06 18:06:57 linux-mk500 vbacl[8842]: Using direct connection for update
>> Июл 06 18:07:00 linux-mk500 vbacl[8842]: Current dir is ./
>> Июл 06 18:07:00 linux-mk500 vbacl[8842]: Start update from
>> http://anti-virus.by/beta/update
>> Июл 06 18:07:00 linux-mk500 vbacl[8842]: Receiving file list
>> Июл 06 18:07:00 linux-mk500 vbacl[8842]: File list received
>> Июл 06 18:07:00 linux-mk500 vbacl[8842]: Update is not needed
>> Июл 06 18:07:00 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
>> Service.
>> ==================
>>
>>
>> And here when Type=simple:
>> ==================
>> Июл 06 18:47:29 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
>> Service.
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Vba32 console scanner update
>> process started
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Reading configuration options
>> from ./vbacl.ini
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Using direct connection for update
>> ==================
>>
>> 'systemctl status' output here:
>> ============================
>> k_mikhail at linux-mk500:~> systemctl status -l vba32update.service
>> ● vba32update.service - VBA32 Anti-Virus Update Service
>>    Loaded: loaded (/etc/systemd/system/vba32update.service; disabled;
>> vendor preset: disabled)
>>    Active: active (running) since Чтв 2017-07-06 18:47:29 EEST; 13min ago
>>  Main PID: 10042 (vbaupdx)
>>     Tasks: 1 (limit: 512)
>>    CGroup: /system.slice/vba32update.service
>>            └─10042 ./vbaupdx http://anti-virus.by/beta/update
>>
>> Июл 06 18:47:29 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
>> Service.
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Vba32 console scanner update
>> process started
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Reading configuration options
>> from ./vbacl.ini
>> Июл 06 18:47:29 linux-mk500 vbacl[10042]: Using direct connection for update
>> ============================
>>
>> Service is _still_active_ and this is not what is needed here. The
>> service behavior correct is when it has Type=oneshot _only_.
>>
>> " Type=simple service can exit when it's finished doing whatever it
>> needs to do. The service will then transition back to its inactive
>> state." -- as you can see, no. And in this case (when Type=oneshot), we
>> have to be able to close 'Activating (start)'-stated service, if this
>> status is on for a long time. I understand, that my use-case is very
>> specific, but it is real. So, let's try to find the method together.
>>
>>
>> To be more informative, here are 'systemctl cat' outputs both for
>> .service and .timer:
>>
>> k_mikhail at linux-mk500:~> systemctl cat vba32update.service
>> ===============================================
>> # /etc/systemd/system/vba32update.service
>> [Unit]
>>
>> Description=VBA32 Anti-Virus Update Service
>> Requires=network.target
>> Wants=network-online.target
>> After=network.target network-online.target
>>
>> [Service]
>> Type=oneshot
>> WorkingDirectory=/opt/vba/vbacl/
>> ExecStart=/opt/vba/vbacl/vbacl --update
>> EnvironmentFile=/opt/vba/vbacl/vbacl.ini
>>
>> [Install]
>> WantedBy=multi-user.target
>> ===============================================
>>
>> ===============================================
>> k_mikhail at linux-mk500:~> systemctl cat vba32update.timer
>> # /etc/systemd/system/vba32update.timer
>> [Unit]
>> Description=Runs VBA32 Update Hourly
>> Requires=timers.target
>>
>> [Timer]
>> OnBootSec=2min
>> OnUnitInactiveSec=1h
>> AccuracySec=1us
>>
>> [Install]
>> WantedBy=timers.target
>> k_mikhail at linux-mk500:~>
>> ===============================================
>
> UPD: BTW, when I (re-)start service manually, it works as expected
> (service is getting started, then checks for updates, then is getting
> exited):
>
> k_mikhail at linux-mk500:~> sudo systemctl restart vba32update.service
>
> k_mikhail at linux-mk500:~> systemctl status vba32update.service
> ● vba32update.service - VBA32 Anti-Virus Update Service
>    Loaded: loaded (/etc/systemd/system/vba32update.service; disabled;
> vendor preset: disabled)
>    Active: inactive (dead) since Чтв 2017-07-06 19:14:33 EEST; 23s ago
>   Process: 10476 ExecStart=/opt/vba/vbacl/vbacl --update (code=exited,
> status=0/SUCCESS)
>  Main PID: 10476 (code=exited, status=0/SUCCESS)
>
> Июл 06 19:14:30 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
> Service...
> Июл 06 19:14:30 linux-mk500 vbacl[10476]: Vba32 console scanner update
> process started
> Июл 06 19:14:30 linux-mk500 vbacl[10476]: Reading configuration options
> from ./vbacl.ini
> Июл 06 19:14:30 linux-mk500 vbacl[10476]: Using direct connection for update
> Июл 06 19:14:33 linux-mk500 vbacl[10476]: Current dir is ./
> Июл 06 19:14:33 linux-mk500 vbacl[10476]: Start update from
> http://anti-virus.by/beta/update
> Июл 06 19:14:33 linux-mk500 vbacl[10476]: Receiving file list
> Июл 06 19:14:33 linux-mk500 vbacl[10476]: File list received
> Июл 06 19:14:33 linux-mk500 vbacl[10476]: Update is not needed
> Июл 06 19:14:33 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
> Service.



My further investigation results:

============================================
[a] k_mikhail at linux-mk500:~> systemctl status vba32update.timer
● vba32update.timer - Runs VBA32 Update Hourly
   Loaded: loaded (/etc/systemd/system/vba32update.timer; enabled;
vendor preset: disabled)
   Active: active (running) since Чтв 2017-07-06 19:14:21 EEST; 5h 18min ago

Июл 06 19:14:21 linux-mk500 systemd[1]: Stopped Runs VBA32 Update Hourly.
Июл 06 19:14:21 linux-mk500 systemd[1]: Stopping Runs VBA32 Update Hourly.
Июл 06 19:14:21 linux-mk500 systemd[1]: Started Runs VBA32 Update Hourly.


[b] k_mikhail at linux-mk500:~> systemctl status vba32update.service
● vba32update.service - VBA32 Anti-Virus Update Service
   Loaded: loaded (/etc/systemd/system/vba32update.service; disabled;
vendor preset: disabled)
   Active: activating (start) since Чтв 2017-07-06 22:14:41 EEST; 2h
17min ago
 Main PID: 13310 (vbaupdx)
    Tasks: 1 (limit: 512)
   CGroup: /system.slice/vba32update.service
           └─13310 ./vbaupdx http://anti-virus.by/beta/update

Июл 06 22:14:41 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
Service...
Июл 06 22:14:41 linux-mk500 vbacl[13310]: Vba32 console scanner update
process started
Июл 06 22:14:41 linux-mk500 vbacl[13310]: Reading configuration options
from ./vbacl.ini
Июл 06 22:14:41 linux-mk500 vbacl[13310]: Using direct connection for update

[c] k_mikhail at linux-mk500:~> sudo systemctl restart vba32update.service

[d] k_mikhail at linux-mk500:~> systemctl status vba32update.timer
● vba32update.timer - Runs VBA32 Update Hourly
   Loaded: loaded (/etc/systemd/system/vba32update.timer; enabled;
vendor preset: disabled)
   Active: active (waiting) since Чтв 2017-07-06 19:14:21 EEST; 5h 18min ago

Июл 06 19:14:21 linux-mk500 systemd[1]: Stopped Runs VBA32 Update Hourly.
Июл 06 19:14:21 linux-mk500 systemd[1]: Stopping Runs VBA32 Update Hourly.
Июл 06 19:14:21 linux-mk500 systemd[1]: Started Runs VBA32 Update Hourly.

[e] k_mikhail at linux-mk500:~> systemctl status vba32update.service
● vba32update.service - VBA32 Anti-Virus Update Service
   Loaded: loaded (/etc/systemd/system/vba32update.service; disabled;
vendor preset: disabled)
   Active: inactive (dead) since Птн 2017-07-07 00:32:44 EEST; 38s ago
  Process: 15252 ExecStart=/opt/vba/vbacl/vbacl --update (code=exited,
status=0/SUCCESS)
 Main PID: 15252 (code=exited, status=0/SUCCESS)

Июл 07 00:32:40 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
Service...
Июл 07 00:32:40 linux-mk500 vbacl[15252]: Vba32 console scanner update
process started
Июл 07 00:32:40 linux-mk500 vbacl[15252]: Reading configuration options
from ./vbacl.ini
Июл 07 00:32:40 linux-mk500 vbacl[15252]: Using direct connection for update
Июл 07 00:32:44 linux-mk500 vbacl[15252]: Current dir is ./
Июл 07 00:32:44 linux-mk500 vbacl[15252]: Start update from
http://anti-virus.by/beta/update
Июл 07 00:32:44 linux-mk500 vbacl[15252]: Receiving file list
Июл 07 00:32:44 linux-mk500 vbacl[15252]: File list received
Июл 07 00:32:44 linux-mk500 vbacl[15252]: Update is not needed
Июл 07 00:32:44 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
Service.
============================================

[a] -- we can see, that .timer service has 'running' status, hence
.service is working now.
[b] -- we can see, that .service has 'activating (start)' status during
2h 17min (omg!!!).
[c] -- we can see, that .service was restarted manually by my own hands.
[d] -- we can see, that .timer status is 'waiting', hence .service is
inactive now.
[e] -- we can see, that .service has done its job normally and this
confirms the [d].


On 7th July 2017:
==============================================================
k_mikhail at linux-mk500:~> journalctl -e -u vba32update.service
Июл 07 11:33:11 linux-mk500 vbacl[22351]: File list received
Июл 07 11:33:11 linux-mk500 vbacl[22351]: Update is not needed
Июл 07 11:33:11 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
Service.

Июл 07 12:33:11 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
Service...
Июл 07 12:33:11 linux-mk500 vbacl[23066]: Vba32 console scanner update
process started
Июл 07 12:33:11 linux-mk500 vbacl[23066]: Reading configuration options
from ./vbacl.ini
Июл 07 12:33:11 linux-mk500 vbacl[23066]: Using direct connection for update
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Current dir is ./
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Start update from
http://anti-virus.by/beta/update
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Receiving file list
Июл 07 12:33:28 linux-mk500 vbacl[23066]: File list received
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Download from
'http://anti-virus.by/beta/update'
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Downloading 2 file(s) (5658.16 Kb)
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Downloading file win32.udb
Июл 07 12:33:28 linux-mk500 vbacl[23066]: File win32.udb download completed
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Downloading file VBA32_L.ini
Июл 07 12:33:28 linux-mk500 vbacl[23066]: File VBA32_L.ini download
completed
Июл 07 12:33:28 linux-mk500 vbacl[23066]: Update is successfully completed
Июл 07 12:33:28 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
Service.

Июл 07 13:33:29 linux-mk500 systemd[1]: Starting VBA32 Anti-Virus Update
Service...
Июл 07 13:33:29 linux-mk500 vbacl[24307]: Vba32 console scanner update
process started
Июл 07 13:33:29 linux-mk500 vbacl[24307]: Reading configuration options
from ./vbacl.ini
Июл 07 13:33:29 linux-mk500 vbacl[24307]: Using direct connection for update
Июл 07 13:33:34 linux-mk500 vbacl[24307]: Current dir is ./
Июл 07 13:33:34 linux-mk500 vbacl[24307]: Start update from
http://anti-virus.by/beta/update
Июл 07 13:33:34 linux-mk500 vbacl[24307]: Receiving file list
Июл 07 13:33:34 linux-mk500 vbacl[24307]: File list received
Июл 07 13:33:34 linux-mk500 vbacl[24307]: Update is not needed
Июл 07 13:33:34 linux-mk500 systemd[1]: Started VBA32 Anti-Virus Update
Service.
==============================================================

Here everything is working as expected, and this is brilliant.

Now, really wanna to reach the nature of such hangings with 'activating
(start)' status.

BTW, using of RuntimeMaxSec= directive won't help here: "Note that this
setting does not have any effect on Type=oneshot services, as they
terminate immediately after activation completed." (source:
https://www.freedesktop.org/software/systemd/man/systemd.service.html)
Hence, if I use Type=simple with RuntimeMaxSec= directive instead of
Type=oneshot, the .service will be always stopped with 'failure' state
by its timeout. And this is a vicious practice as for me, so unacceptable.

Summary:
==============================================================
1. Using Type=oneshot is normal for my use-case, because service must be
started periodically, do its job and then must be finished. Nothing more.
2. Problem with hanging on 'activating (start)' state has random
character, because 'On 7th July 2017' snippet shows, that scheme '.timer
+ .oneshot_service' works normally during a long time. Hence, scheme is
valid.
3. Systemd has no mechanism now for taking care of oneshot services,
which are hung in some reason.

More information about the systemd-devel mailing list