[BUG] The callback is not executed #236

vasily-22 · 2021-09-05T15:02:31Z

Describe the bug
The callback is not executed.

To Reproduce
Put any command with visible effect as daemon.callback in ~/.config/pueue/pueue.yml.
There are examples in the wiki, or just touch a file in the home directory.

Restart the daemon: systemctl --user restart pueued.service

Add an example task: pueue add -- sleep 2

Expected behavior
The callback should run when the task finishes.

I don't see a notification when I try the notify-send example. When I try to touch a file as a callback - no file is created. The log doesn't say anything about a callback:

14:39:11 [INFO] Didn't find pueue alias file.
14:39:11 [INFO] Started task: sleep 2
14:39:13 [INFO] Task 6 just finished

It seems that it isn't executed.

Additional context
I'm using pueue 1.0.1 on Arch Linux, installed from the community with pacman.

The text was updated successfully, but these errors were encountered:

vasily-22 · 2021-09-05T15:40:49Z

What pueued does mention in the log is this file: ~/.local/share/pueue/state.json. In it it says this: "callback": null, regardless of what I put as callback in ~/.config/pueue/pueue.yml.

If I stop pueued, modify the callback in state.json then start pueued - it works. The callback is executed. However, the callback is not updated from pueue.yml.

Nukesor · 2021-09-05T18:31:56Z

Weird, could you provide me with the exact key + value callback config you're trying to execute?
That way I might be able to reproduce your issue.

vasily-22 · 2021-09-06T18:44:50Z

You can use the example from the wiki:

callback: "notify-send \"Task {{ id }}\nCommand: {{ command }}\nPath: {{ path }}\nFinished with status '{{ result }}'\nTook: $(bc <<< \"{{end}} - {{start}}\") seconds\""

or touch /home/<yourname>/it_works_maybe. I've tried multiple commands and it looks like the command doesn't matter. pueued just reuses the callback from the state file and doesn't update it from pueue.yml.

Nukesor · 2021-09-07T06:42:44Z

This is super weird. I'm using the exact same version of Pueue on the same Linux distribution, but I cannot reproduce your issue, even when taking the exact line you posted above. Callbacks seem to work perfectly fine.

The fact that its null in the state.json suggests, that there's an error while parsing the config file.

Could you check pueued's logs?

Stop any previous pueued instances and run pueued in a terminal without the -d flag.
This should already give you some info on which configs are found and read.

Just execute any command with pueue afterwards, such as pueue add ls. This will show you all network traffic + logs from the callback spawner.

vasily-22 · 2021-09-07T09:41:00Z

Below is a session which demonstrates the issue. You can see pueued executes the callback stored in the state and not the one from the configuration file.

The state and config files, before:

[vasily@vostro ~]$ bat /home/vasily/.local/share/pueue/state.json
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /home/vasily/.local/share/pueue/state.json
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ {
   2   │   "settings": {
   3   │     "client": {
   4   │       "restart_in_place": false,
   5   │       "read_local_logs": true,
   6   │       "show_confirmation_questions": false,
   7   │       "show_expanded_aliases": false,
   8   │       "dark_mode": false,
   9   │       "max_status_lines": null,
  10   │       "status_time_format": "%H:%M:%S",
  11   │       "status_datetime_format": "%Y-%m-%d\n%H:%M:%S"
  12   │     },
  13   │     "daemon": {
  14   │       "default_parallel_tasks": 1,
  15   │       "pause_group_on_failure": false,
  16   │       "pause_all_on_failure": false,
  17   │       "callback": "touch ~/old",
  18   │       "callback_log_lines": 10,
  19   │       "groups": { "default": 1 }
  20   │     },
  21   │     "shared": {
  22   │       "pueue_directory": "/home/vasily/.local/share/pueue",
  23   │       "use_unix_socket": true,
  24   │       "unix_socket_path": "/home/vasily/.local/share/pueue/pueue_vasily.socket",
  25   │       "host": "127.0.0.1",
  26   │       "port": "6924",
  27   │       "daemon_cert": "/home/vasily/.local/share/pueue/certs/daemon.cert",
  28   │       "daemon_key": "/home/vasily/.local/share/pueue/certs/daemon.key",
  29   │       "shared_secret_path": "/home/vasily/.local/share/pueue/shared_secret"
  30   │     }
  31   │   },
  32   │   "tasks": {},
  33   │   "groups": { "default": "Running" },
  34   │   "config_path": null
  35   │ }
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[vasily@vostro ~]$
[vasily@vostro ~]$ bat ~/.config/pueue/pueue.yml
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /home/vasily/.config/pueue/pueue.yml
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ ---
   2   │ client:
   3   │   restart_in_place: false
   4   │   read_local_logs: true
   5   │   show_confirmation_questions: false
   6   │   show_expanded_aliases: false
   7   │   dark_mode: false
   8   │   max_status_lines: ~
   9   │   status_time_format: "%H:%M:%S"
  10   │   status_datetime_format: "%Y-%m-%d\n%H:%M:%S"
  11   │ daemon:
  12   │   default_parallel_tasks: 1
  13   │   pause_group_on_failure: false
  14   │   pause_all_on_failure: false
  15   │   callback: "touch ~/new"
  16   │   callback_log_lines: 10
  17   │   groups: {}
  18   │ shared:
  19   │   pueue_directory: /home/vasily/.local/share/pueue
  20   │   use_unix_socket: true
  21   │   unix_socket_path: /home/vasily/.local/share/pueue/pueue_vasily.socket
  22   │   host: 127.0.0.1
  23   │   port: "6924"
  24   │   daemon_cert: /home/vasily/.local/share/pueue/certs/daemon.cert
  25   │   daemon_key: /home/vasily/.local/share/pueue/certs/daemon.key
  26   │   shared_secret_path: /home/vasily/.local/share/pueue/shared_secret
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[vasily@vostro ~]$

The result files, before:

[vasily@vostro ~]$ exa -l ~/{new,old}
"/home/vasily/new": No such file or directory (os error 2)
"/home/vasily/old": No such file or directory (os error 2)
[vasily@vostro ~]$

pueued session in terminal 1:

[vasily@vostro ~]$ pwd
/home/vasily
[vasily@vostro ~]$
[vasily@vostro ~]$ pueued -vvv
09:31:36 [INFO] Parsing config files
09:31:36 [INFO] Checking path: "/etc/pueue/pueue.yml"
09:31:36 [INFO] Checking path: "/home/vasily/.config/pueue/pueue.yml"
09:31:36 [INFO] Found config file at: "/home/vasily/.config/pueue/pueue.yml"
09:31:36 [INFO] Checking path: "./pueue.yml"
09:31:36 [INFO] Start restoring state
09:31:36 [DEBUG] (1) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:45 [DEBUG] (4) pueue_lib::network::protocol: Received 3987 bytes
09:31:45 [DEBUG] (4) pueue_lib::network::protocol: Received message: Add(AddMessage { command: "sleep 2", path: "/home/vasily", envs: {"[REDACTED]": "[REDACTED]"}, start_immediately: false, stashed: false, group: "default", enqueue_at: None, dependencies: [], label: None, print_task_id: false })
09:31:45 [DEBUG] (4) pueue_daemon_lib::network::socket: Received instruction: Add(AddMessage { command: "sleep 2", path: "/home/vasily", envs: {"[REDACTED]": "[REDACTED]"}, start_immediately: false, stashed: false, group: "default", enqueue_at: None, dependencies: [], label: None, print_task_id: false })
09:31:45 [INFO] Didn't find pueue alias file.
09:31:45 [DEBUG] (4) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:45 [DEBUG] (4) pueue_lib::network::protocol: Sending message: Success("New task added (id 0).")
09:31:45 [INFO] Started task: sleep 2
09:31:45 [DEBUG] (7) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:47 [INFO] Task 0 just finished
09:31:47 [DEBUG] (7) pueue_daemon_lib::task_handler::callback: Spawned callback for task 0
09:31:47 [DEBUG] (7) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:47 [INFO] Callback finished with exit code Some(ExitStatus(ExitStatus(0)))
09:31:53 [DEBUG] (5) pueue_lib::network::protocol: Received 25 bytes
09:31:53 [DEBUG] (5) pueue_lib::network::protocol: Received message: Clean(CleanMessage { successful_only: true })
09:31:53 [DEBUG] (5) pueue_daemon_lib::network::socket: Received instruction: Clean(CleanMessage { successful_only: true })
09:31:53 [DEBUG] (5) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:53 [DEBUG] (5) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
09:31:53 [DEBUG] (5) pueue_lib::network::protocol: Sending message: Success("All successfully finished tasks have been removed")
^C09:31:58 [INFO] Killing all running tasks
09:31:58 [DEBUG] (7) pueue_daemon_lib::state_helper: State saved at: "/home/vasily/.local/share/pueue/state.json"
[vasily@vostro ~]$

The commands issued in terminal 2:

[vasily@vostro ~]$ pueue add -- sleep 2
New task added (id 0).
[vasily@vostro ~]$ pueue clean -s
All successfully finished tasks have been removed
[vasily@vostro ~]$

The result files, after:

[vasily@vostro ~]$ exa -l ~/{old,new}
"/home/vasily/new": No such file or directory (os error 2)
.rw-r--r-- 0 vasily  7 сеп 12:23 /home/vasily/old
[vasily@vostro ~]$

The state and config files, after:

[vasily@vostro ~]$ bat ~/.config/pueue/pueue.yml
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /home/vasily/.config/pueue/pueue.yml
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ ---
   2   │ client:
   3   │   restart_in_place: false
   4   │   read_local_logs: true
   5   │   show_confirmation_questions: false
   6   │   show_expanded_aliases: false
   7   │   dark_mode: false
   8   │   max_status_lines: ~
   9   │   status_time_format: "%H:%M:%S"
  10   │   status_datetime_format: "%Y-%m-%d\n%H:%M:%S"
  11   │ daemon:
  12   │   default_parallel_tasks: 1
  13   │   pause_group_on_failure: false
  14   │   pause_all_on_failure: false
  15   │   callback: touch ~/new
  16   │   callback_log_lines: 10
  17   │   groups: {}
  18   │ shared:
  19   │   pueue_directory: /home/vasily/.local/share/pueue
  20   │   use_unix_socket: true
  21   │   unix_socket_path: /home/vasily/.local/share/pueue/pueue_vasily.socket
  22   │   host: 127.0.0.1
  23   │   port: "6924"
  24   │   daemon_cert: /home/vasily/.local/share/pueue/certs/daemon.cert
  25   │   daemon_key: /home/vasily/.local/share/pueue/certs/daemon.key
  26   │   shared_secret_path: /home/vasily/.local/share/pueue/shared_secret
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[vasily@vostro ~]$
[vasily@vostro ~]$ bat /home/vasily/.local/share/pueue/state.json
───────┬────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
       │ File: /home/vasily/.local/share/pueue/state.json
───────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
   1   │ {
   2   │   "settings": {
   3   │     "client": {
   4   │       "restart_in_place": false,
   5   │       "read_local_logs": true,
   6   │       "show_confirmation_questions": false,
   7   │       "show_expanded_aliases": false,
   8   │       "dark_mode": false,
   9   │       "max_status_lines": null,
  10   │       "status_time_format": "%H:%M:%S",
  11   │       "status_datetime_format": "%Y-%m-%d\n%H:%M:%S"
  12   │     },
  13   │     "daemon": {
  14   │       "default_parallel_tasks": 1,
  15   │       "pause_group_on_failure": false,
  16   │       "pause_all_on_failure": false,
  17   │       "callback": "touch ~/old",
  18   │       "callback_log_lines": 10,
  19   │       "groups": { "default": 1 }
  20   │     },
  21   │     "shared": {
  22   │       "pueue_directory": "/home/vasily/.local/share/pueue",
  23   │       "use_unix_socket": true,
  24   │       "unix_socket_path": "/home/vasily/.local/share/pueue/pueue_vasily.socket",
  25   │       "host": "127.0.0.1",
  26   │       "port": "6924",
  27   │       "daemon_cert": "/home/vasily/.local/share/pueue/certs/daemon.cert",
  28   │       "daemon_key": "/home/vasily/.local/share/pueue/certs/daemon.key",
  29   │       "shared_secret_path": "/home/vasily/.local/share/pueue/shared_secret"
  30   │     }
  31   │   },
  32   │   "tasks": {},
  33   │   "groups": { "default": "Running" },
  34   │   "config_path": null
  35   │ }
───────┴────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[vasily@vostro ~]$

Nukesor · 2021-09-07T23:14:35Z

Daamn.
I was able to reproduce the issue and found the bug. It's a one-liner fix.

During the large-scale refactoring for v1.0.0, the logic for overwriting the settings on the recovered state of the previous session got somehow lost.

I'll fix this in a patch release as soon as I managed to reproduce this in tests. I want some regression tests for this.

Thanks for your detailed bug report and detailed log outputs.
This sped up the debugging process by a lot!

Nukesor · 2021-09-12T08:01:57Z

New patch has been released

vasily-22 added the t: Bug label Sep 5, 2021

vasily-22 assigned Nukesor Sep 5, 2021

vasily-22 changed the title ~~[BUG]~~ [BUG] The callback is not executed Sep 5, 2021

Nukesor mentioned this issue Sep 12, 2021

test: Ensure settings are read on restore #238

Merged

Nukesor closed this as completed in #238 Sep 12, 2021

Nukesor mentioned this issue Sep 15, 2021

[BUG] pueue 1.0.2 test issue #242

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] The callback is not executed #236

[BUG] The callback is not executed #236

vasily-22 commented Sep 5, 2021

vasily-22 commented Sep 5, 2021

Nukesor commented Sep 5, 2021 •

edited

Loading

vasily-22 commented Sep 6, 2021

Nukesor commented Sep 7, 2021

vasily-22 commented Sep 7, 2021

Nukesor commented Sep 7, 2021 •

edited

Loading

Nukesor commented Sep 12, 2021

[BUG] The callback is not executed #236

[BUG] The callback is not executed #236

Comments

vasily-22 commented Sep 5, 2021

vasily-22 commented Sep 5, 2021

Nukesor commented Sep 5, 2021 • edited Loading

vasily-22 commented Sep 6, 2021

Nukesor commented Sep 7, 2021

vasily-22 commented Sep 7, 2021

Nukesor commented Sep 7, 2021 • edited Loading

Nukesor commented Sep 12, 2021

Nukesor commented Sep 5, 2021 •

edited

Loading

Nukesor commented Sep 7, 2021 •

edited

Loading