Exit code to hook script seems to be ignored

[hickey]

To report a bug...

A bit of context around this bug report.

I have a hook script that has been developed to add or modify the task on a Kanban board. In order to do so the hook script interacts with Vault to retrieve the token to interact with the Kanban API.

Everything works fine except that once in a while the Vault database is sealed and needs to be unsealed. Previously I would see a Python exception and just know that Vault was sealed. I was just doing a bit of work to handle the situation a little more gracefully.

Here is the bit of Python code that I just updated by adding the exception handling.

        try:
            task['kanboard_id'] = add_task(project=kanboard_proj,
                                           title=task['description'],
                                           options=options)
        except VaultError as e:
            print(json.dumps(task))
            print(e)
            sys.exit(2)

• What command(s) did you run?

task add TASK_TO_BE_ADDED

• What did you expect to happen?

In the condition that Vault is sealed , I would expect that the task be dropped and not added to the Taskwarrior database.

Consulting the documentation for the Taskwarrior hooks at https://taskwarrior.org/docs/hooks/#exit-status, it seems to indicate that if a hook exists with a non-zero exit status that the task would be discarded.

• What actually happened?

❯ task add foobar
Context 'work' set. Use 'task context none' to remove.
Vault is sealed, on post https://moab.wt0f.com:8200/v1/auth/userpass/login/hickey

As can be seen in the output above, I capture the exception and Taskwarrior is processing the exception message as a feedback message. The hook then exits with a exit code of 2 which should signal that the task is to be discarded. That does not seem to be happening as you can see in the following output.

❯ task

ID Age   Project Description                                    Urg
 1  8w   GitLab  Remove extreneous values from helm values file 2.11
 2  7w           Create ticket to turn on GL Pages              1.08
 3  1h           Creating SOS to Confluence                      0.8
 4  1h           foobar                                          0.8
 5  1h           foobar                                          0.8
 6 53min         foobar                                          0.8
 7 52min         foobar                                          0.8

7 tasks
Context 'work' set. Use 'task context none' to remove.

• Paste the output of the task diag command.

❯ task diag

task 3.0.2
   Platform: Darwin

Compiler
    Version: Apple LLVM 15.0.0 (clang-1500.3.9.4)
       Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64
 Compliance: C++17

Build Features
      CMake: 3.29.2
    libuuid: libuuid + uuid_unparse_lower
 Build type: Release

Configuration
       File: /Users/hickey/.taskrc (found), 1421 bytes, mode 100644
       Data: /Users/hickey/.task (found), dir, mode 40755
    Locking: Enabled
         GC: Enabled
    $VISUAL: vi
Hooks
     System: Enabled
   Location: /Users/hickey/.task/hooks
     Active: on-add.blocks_attr.py    (executable) (symlink)
             on-add.kanboard.py       (executable)
             on-launch.blocks_attr.py (executable) (symlink)
             on-modify.blocks_attr.py (executable)
             on-modify.kanboard.py    (executable)
             on-modify.timewarrior    (executable)
   Inactive: kanboard_functions.py    (executable)unrecognized hook name
             on-add.sync              (not executable)
             on-exit.sync             (not executable)
             on-modify.sync           (not executable)

Tests
   Terminal: 335x71
       Dups: Scanned 25 tasks for duplicate UUIDs:
             No duplicates found
 Broken ref: Scanned 25 tasks for broken references:
             No broken references found

[djmitche]

It looks like this should be implemented by throwing 0 (weird, but ok..):

taskwarrior/src/Hooks.cpp

Lines 152 to 163 in d1a3573

	if (status == 0)
	{
	for (auto& message : outputFeedback)
	Context::getContext ().footnote (message);
	}
	else
	{
	assertFeedback (outputFeedback, script);
	for (auto& message : outputFeedback)
	Context::getContext ().error (message);
	throw 0; // This is how hooks silently terminate processing.

And the onHook method where that code appears is called before the task is imported into the DB:

taskwarrior/src/TDB2.cpp

Lines 76 to 79 in d1a3573

	// run hooks for this new task
	Context::getContext ().hooks.onAdd (task);
	auto innertask = replica.import_task_with_uuid (uuid);

There's also a test for this behavior:

taskwarrior/test/hooks.on-add.test.py

Lines 78 to 94 in d1a3573

	def test_onadd_builtin_reject(self):
	"""on-add-reject - a well-behaved, failing, on-add hook."""
	hookname = 'on-add-reject'
	self.t.hooks.add_default(hookname, log=True)
	code, out, err = self.t.runError("add foo")
	hook = self.t.hooks[hookname]
	hook.assertTriggeredCount(1)
	hook.assertExitcode(1)
	logs = hook.get_logs()
	self.assertEqual(logs["output"]["msgs"][0], "FEEDBACK")
	# task was not added
	code, out, err = self.t.runError("1 info")
	self.assertIn("No matches", err)

So I'm not sure what's wrong here. One thought is that maybe

            print(json.dumps(task))

is being read from the hook before it exits, and the add proceeds? I don't think it should do that, but commenting out that line should be a quick way to check.

[hickey]

Sure I can give that a try. Report back in a few mins with results.

Before I updated the code, it would exit with the Python exception. Arguably because the exception was not handled gracefully and the hook was not providing the feedback message back to Taskwarrior, Taskwarrior was ignoring the exit status? But in this state the task would still be added to the database.

Here is the full output from this morning when I decide to take a few moments to handle the exception. You can see at the very end Taskwarrior stating that it did not get a feedback message.

❯ task add Creating SOS to Confluence
Traceback (most recent call last):
  File "/Users/hickey/.task/hooks/on-add.kanboard.py", line 58, in <module>
    task['kanboard_id'] = add_task(project=kanboard_proj,
                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.task/hooks/kanboard_functions.py", line 36, in add_task
    kb = kanboard_connect()
         ^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.task/hooks/kanboard_functions.py", line 23, in kanboard_connect
    v_client.auth.userpass.login(v_user, v_pass, mount_point='userpass')
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/api/auth_methods/userpass.py", line 163, in login
    return self._adapter.login(
           ^^^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/adapters.py", line 230, in login
    response = self.post(url, **kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/adapters.py", line 159, in post
    return self.request("post", url, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/adapters.py", line 408, in request
    response = super().request(*args, **kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/adapters.py", line 376, in request
    self._raise_for_error(method, url, response)
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/adapters.py", line 294, in _raise_for_error
    utils.raise_for_error(
  File "/Users/hickey/.pyenv/versions/3.12.2/lib/python3.12/site-packages/hvac/utils.py", line 41, in raise_for_error
    raise exceptions.VaultError.from_status(
hvac.exceptions.VaultDown: Vault is sealed, on post https://moab.wt0f.com:8200/v1/auth/userpass/login/hickey
Context 'work' set. Use 'task context none' to remove.
Hook Error: Expected feedback from failing hook script: on-add.kanboard.py

It also occurs to me that there are other hook scripts and that may be a factor. Here is a list of the hook scripts so that you have a more complete picture of the environment.

❯ ls -l ~/.task/hooks
total 80
drwxr-xr-x  3 hickey  HQ\Domain Users    96 Jul  5 10:02 __pycache__
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  5255 Jul  5 10:00 kanboard_functions.py
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-add.blocks_attr.py -> on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2594 Jul  5 10:30 on-add.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-add.sync
----------  1 hickey  HQ\Domain Users    93 Apr 26 22:32 on-exit.sync
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-launch.blocks_attr.py -> on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2662 Apr 26 22:32 on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  6673 Apr 26 22:32 on-modify.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-modify.sync
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2198 Apr 26 22:32 on-modify.timewarrior

I can not tell you at this point if on-add.blocks_attr.py executes before or after on-add.kanboard.py or if it is a factor in the failure.

[hickey]

I am sorry to say that even removing the JSON of the task from stdout when the failure occurs does not change the behavior.

❯ task add foobar
Context 'work' set. Use 'task context none' to remove.
Vault is sealed, on post https://moab.wt0f.com:8200/v1/auth/userpass/login/hickey
❯ task

ID Age   Project Description                                         Urg
 1  8w   GitLab  Remove extreneous values from helm values file      2.11
 2  7w           Create ticket to turn on GL Pages                   1.08
 3 55min         Document adding GitLab SOS to Confluence             0.8
 4 52min         Create Nexus proxy to pull from registry.gitlab.com  0.8
 5 52min         Create Nexus proxy to pull from ghcr.io              0.8
 6  5s           foobar                                               0.8

6 tasks
Context 'work' set. Use 'task context none' to remove.

I will also tell you that before submitting the bug report, I tried to change the task status to deleted prior to outputing the task JSON when the exception was caught. It had no effect and the task was still added to the database.

Also, in the exit-status section of the hooks documentation the following statement is found.

A hook script may exit with a non-zero status which signals a problem. This terminates processing. All tasks emitted will be ignored. Feedback is required in this case, and will be shown as an error.

Does this not tend to indicate that the task should be emitted whether there is a failure or not?

[djmitche]

It does indicate that, but I thought perhaps that was the bug. I guess not!

[hickey]

Also, on a hunch I just disabled the on-add.blocks_attr.py hook and tried to add another task to see if the behavior is as expected. Unfortunately not.

❯ ls -l
total 80
drwxr-xr-x  3 hickey  HQ\Domain Users    96 Jul  5 10:02 __pycache__
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  5255 Jul  5 10:00 kanboard_functions.py
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-add.blocks_attr.py -> on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2596 Jul  5 12:21 on-add.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-add.sync
----------  1 hickey  HQ\Domain Users    93 Apr 26 22:32 on-exit.sync
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-launch.blocks_attr.py -> on-modify.blocks_attr.py
----------  1 hickey  HQ\Domain Users  2662 Apr 26 22:32 on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  6673 Apr 26 22:32 on-modify.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-modify.sync
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2198 Apr 26 22:32 on-modify.timewarrior
❯
❯
❯
❯ task add foobar2
Context 'work' set. Use 'task context none' to remove.
Vault is sealed, on post https://moab.wt0f.com:8200/v1/auth/userpass/login/hickey
❯ task

ID Age  Project Description                                         Urg
 1 8w   GitLab  Remove extreneous values from helm values file      2.11
 2 7w           Create ticket to turn on GL Pages                   1.08
 3 1h           Document adding GitLab SOS to Confluence             0.8
 4 1h           Create Nexus proxy to pull from registry.gitlab.com  0.8
 5 1h           Create Nexus proxy to pull from ghcr.io              0.8
 6 8min         foobar                                               0.8
 7 5s           foobar2                                              0.8

7 tasks
Context 'work' set. Use 'task context none' to remove.

[djmitche]

Just to check, is the script really exiting with a nonzero status? It's hard to see how this could differ from

taskwarrior/test/test_hooks/on-add-reject

Lines 1 to 19 in d1a3573

	#!/bin/sh
	# The on-add event is triggered separately for each task added. This hook
	# script can accept/reject the addition. Processing will continue.
	# Input:
	# - Line of JSON for proposed new task.
	read new_task
	# Output:
	# - JSON, modified or unmodified.
	# - Optional feedback/error.
	echo $new_task
	echo 'FEEDBACK'
	# Status:
	# - 0: JSON accepted, non-JSON is feedback.
	# - non-0: JSON ignored, non-JSON is error.
	exit 1

[hickey]

Added the script as on-add.force-exit.sh, but still getting added to Taskwarrior DB.

❯ ls -l
total 88
drwxr-xr-x  3 hickey  HQ\Domain Users    96 Jul  5 10:02 __pycache__
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  5255 Jul  5 10:00 kanboard_functions.py
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-add.blocks_attr.py -> on-modify.blocks_attr.py
-rw-r--r--  1 hickey  HQ\Domain Users   453 Jul  5 12:40 on-add.force-exit.sh
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2596 Jul  5 12:21 on-add.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-add.sync
----------  1 hickey  HQ\Domain Users    93 Apr 26 22:32 on-exit.sync
lrwxr-xr-x@ 1 hickey  HQ\Domain Users    24 Apr 26 22:32 on-launch.blocks_attr.py -> on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2662 Apr 26 22:32 on-modify.blocks_attr.py
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  6673 Apr 26 22:32 on-modify.kanboard.py
----------  1 hickey  HQ\Domain Users    52 Apr 26 22:32 on-modify.sync
-rwxr-xr-x@ 1 hickey  HQ\Domain Users  2198 Apr 26 22:32 on-modify.timewarrior
❯ chmod 755 on-add.force-exit.sh
❯
❯
❯ task add foobar3
Context 'work' set. Use 'task context none' to remove.
FEEDBACK
❯ task

ID Age   Project Description                                         Urg
 1  8w   GitLab  Remove extreneous values from helm values file      2.11
 2  7w           Create ticket to turn on GL Pages                   1.08
 3  1h           Document adding GitLab SOS to Confluence             0.8
 4  1h           Create Nexus proxy to pull from registry.gitlab.com  0.8
 5  1h           Create Nexus proxy to pull from ghcr.io              0.8
 6 16min         foobar                                               0.8
 7  8min         foobar2                                              0.8
 8  6s           foobar3                                              0.8

8 tasks
Context 'work' set. Use 'task context none' to remove.

[djmitche]

I'm stumped! Locally, with a copy of the reject hook quoted above installed:

⸩ t add foobar
TASKRC override: /home/dustin/p/taskwarrior/.taskrc
FEEDBACK
⸩ echo $?
4
⸩ t /foobar/
TASKRC override: /home/dustin/p/taskwarrior/.taskrc
No matches.
There are 6 local changes.  Sync required.

I suppose the context is different -- I don't really know how contexts work -- but that seems unrelated.

[hickey]

I am with you also. Completed stumped.

I just verified that I am also getting an exit code of 4 when the hook signals a failure.

I will keep looking at this and see if I can make any headway as to what is going on. Is there any debug output that can be enabled to see what task is doing internally?

[djmitche]

You can try rc.debug=1 (or debug=1 in .taskrc) but I'm not confident that will produce any additional useful output.