I don't understand termux-notification behavior, can someone please explain

[akim-13]

I'm trying to integrate a CLI to-do managing app Taskwarrior using termux-notification. The command I'm trying to run below is supposed to create a task and output "Created task number ..." in the log file when I click on the notification:

termux-notification --action "task rc:'/data/data/com.termux/files/home/.config/taskwarrior/taskrc' rc.hook.location='/data/data/com.termux/files/home/.config/taskwarrior/hooks' add TEST123 ntf:tom > /data/data/com.termux/files/home/.config/taskwarrior/log.log"

It seems lengthy because I'm using absolute paths everywhere just in case, but actually the specifics of this task command are irrelevant. If I run it by itself everything works fine. However, when I try to execute it through termux-notification it does not create a task and it doesn't even output anything in the log file. Why????? It definitely has something to do with a different environment in which termux-notification executes commands, however I fail to see how this is an issue if I specify absolute paths everywhere.

[agnostic-apollo]

The logcat logs should show errors after setting log level to verbose.

https://github.com/termux/termux-app#debugging

Also check differences for plugin background commands.

https://github.com/termux/termux-widget/#termux-environment

[akim-13]

I removed the pipe to termux-toast, here are the logs now:

08-03 14:54:01.520 14438 14438 D Termux:TermuxService: onStartCommand
08-03 14:54:01.523 14438 14438 D Termux:TermuxService: ACTION_SERVICE_EXECUTE intent received
08-03 14:54:01.523 14438 14438 D Termux:TermuxService: Executing background "(1004) Execution Intent Command" TermuxTask command
08-03 14:54:01.523 14438 14438 D Termux:TermuxService: Creating "(1004) Execution Intent Command" TermuxTask
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: (1004) Execution Intent Command:
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Current State: `Pre-Execution`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Executable: `/data/data/com.termux/files/usr/bin/sh`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Arguments:
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: ```
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Arg 1: `-c`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Arg 2: `/data/data/com.termux/files/home/.config/taskwarrior/test.sh`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: ```
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Working Directory: `null`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: inBackground: `true`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: isFailsafe: `false`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: isPluginExecutionCommand: `true`
08-03 14:54:01.523 14438 14438 V Termux:TermuxService: Result Pending: `false`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: (1004) Execution Intent Command:
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Current State: `Executing`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Executable: `/data/data/com.termux/files/usr/bin/sh`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Arguments:
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: ```
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Arg 1: `-c`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Arg 2: `/data/data/com.termux/files/home/.config/taskwarrior/test.sh`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: ```
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Working Directory: `/data/data/com.termux/files/home`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: inBackground: `true`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: isFailsafe: `false`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: isPluginExecutionCommand: `true`
08-03 14:54:01.525 14438 14438 D Termux:TermuxTask: Result Pending: `false`
08-03 14:54:01.523 15973 15973 W com.termux: type=1400 audit(0.0:525007): avc: granted { execute } for name="dash" dev="dm-48" ino=291624 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:01.523 15973 15973 W com.termux: type=1400 audit(0.0:525008): avc: granted { execute_no_trans } for path="/data/data/com.termux/files/usr/bin/dash" dev="dm-48" ino=291624 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:01.523 15973 15973 W sh      : type=1400 audit(0.0:525009): avc: granted { execute } for path="/data/data/com.termux/files/usr/bin/dash" dev="dm-48" ino=291624 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:01.528 14438 15975 D Termux:TermuxTask: Running "(1004) Execution Intent Command" TermuxTask with pid 15973
08-03 14:54:01.523 15973 15973 W sh      : type=1400 audit(0.0:525010): avc: denied { search } for name="tests" dev="dm-48" ino=112 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:shell_test_data_file:s0 tclass=dir permissive=0 app=com.termux.api
08-03 14:54:01.523 15973 15973 W sh      : type=1400 audit(0.0:525011): avc: denied { search } for name="tests" dev="dm-48" ino=112 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:shell_test_data_file:s0 tclass=dir permissive=0 app=com.termux.api
08-03 14:54:01.558 14438 15975 D Termux:TermuxTask: The "(1004) Execution Intent Command" TermuxTask with pid 15973 exited with code: 4
08-03 14:54:01.559 14438 15975 D Termux:TermuxTask: Processing "(1004) Execution Intent Command" TermuxTask result
08-03 14:54:01.559 14438 14438 V Termux:TermuxService: The onTermuxTaskExited() callback called for "(1004) Execution Intent Command" TermuxTask command
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: (1004) Execution Intent Command:
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: Previous State: `Executing`
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: Current State: `Executed`
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: 
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: Exit Code: `4`
08-03 14:54:01.559 14438 14438 D Termux:TermuxService: 
08-03 14:54:03.707 15980 15980 W runsvdir: type=1400 audit(0.0:525052): avc: granted { execute } for name="runsv" dev="dm-48" ino=293312 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:03.707 15980 15980 W runsvdir: type=1400 audit(0.0:525053): avc: granted { execute } for name="runsv" dev="dm-48" ino=293312 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:03.707 15981 15981 W runsvdir: type=1400 audit(0.0:525054): avc: granted { execute } for name="runsv" dev="dm-48" ino=293312 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:03.707 15980 15980 W runsvdir: type=1400 audit(0.0:525055): avc: granted { execute_no_trans } for path="/data/data/com.termux/files/usr/bin/runsv" dev="dm-48" ino=293312 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:03.707 15981 15981 W runsvdir: type=1400 audit(0.0:525056): avc: granted { execute } for name="runsv" dev="dm-48" ino=293312 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:07.103 15982 15982 W zsh     : type=1400 audit(0.0:525072): avc: granted { execute } for name="logcat" dev="dm-48" ino=115430 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:07.103 15982 15982 W zsh     : type=1400 audit(0.0:525073): avc: granted { execute } for name="logcat" dev="dm-48" ino=115430 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:07.103 15982 15982 W zsh     : type=1400 audit(0.0:525074): avc: granted { execute_no_trans } for path="/data/data/com.termux/files/usr/bin/logcat" dev="dm-48" ino=115430 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:07.103 15982 15982 W zsh     : type=1400 audit(0.0:525075): avc: granted { execute } for name="dash" dev="dm-48" ino=291624 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api
08-03 14:54:07.107 15982 15982 W logcat  : type=1400 audit(0.0:525076): avc: granted { execute } for path="/data/data/com.termux/files/usr/bin/dash" dev="dm-48" ino=291624 scontext=u:r:untrusted_app_27:s0:c222,c256,c512,c768 tcontext=u:object_r:app_data_file:s0:c222,c256,c512,c768 tclass=file app=com.termux.api

Now I do see exit code 4 instead of 0.

Edit: I also specified full path to the task binary, however it didn't help either.

[agnostic-apollo]

What "exact" command are you running to get the logs?

There ideally should be log entries for stdout or stderr in logcat, but there are none in this log or previous. So either you are not posting all entries or task is not sending errors to stderr. It could be sending to some log file instead.

[akim-13]

I am using logcat -d > logcat.log. However, for some reason it doesn't pickup stderr from task, so after redirecting stderr inside the script to a log file (&> log.txt), I get this:

Failed to execute '/data/data/com.termux/files/home/.config/ta
skwarrior/hooks/on-add.add-ntf.sh' Error: No such file or dire
ctory
Hook Error: Expected feedback from failing hook script: on-add
.add-ntf.sh

Initially I though it's taskwarrior's problem, so I reported this error (see the relevant discussion), however it doesn't seem to be so. The file on-add.add-ntf.sh does actually exist, since if I try to cat it out from inside the same test.sh called with termux-notification, it works perfectly fine.

[akim-13]

Solved! Apparently ALL scripts that are called within the termux-notification environment must have absolute shebangs. Since this hook is also just a script, changing #!/bin/bash to #!/data/data/com.termux/files/usr/bin/bash resolved the issue.

I should've spotted it much earlier, however the absence of errors in logs and cryptic error messages threw me off a bit. Appreciate your help @agnostic-apollo !

[agnostic-apollo]

I already sent you a link for that issue in above comment.

#3533 (comment)