Scheduler job won't get run again after quitting due to syntax error in variable

Infos:

  • Used Zammad version: 3.3.x
  • Used Zammad installation source: package
  • Operating system: Debian 4.9.189-3+deb9u2 (2019-11-11) x86_64 GNU/Linux
  • Browser + version: any

Some background:

Yesterday I fiddled around with methods that work within rails console and tried them as variables within a scheduler’s e-mail notifications, e.g.

#{article.first / no such method}
#{article.last_customer_agent_article / no such method}

Later, I also tried something more complex—I can’t remember the exact variable, but I think it was something containing parentheses and apostrophes, like:

#{Ticket.find_by(number:'101234').articles.first

—which seems to have broken that particular scheduler job completely. A second scheduler job (clone from the first one without the bad syntax does indeed run:


Also, after editing the older job, the ‘planned for’ time will change in the UI—but it won’t execute and it will stay at that exact timestamp.

@MrGeneration Could you maybe explain how Scheduler works technically, and why it didn’t try to run again later? I’d love to understand it and contribute something to the documentation!

Expected behavior:

  • Scheduler job should be run again after removing not working variables
  • Ideally Zammad would do better error handling before running the job, i.e. maybe ignore the syntax errors and just throw an error in production.log

Actual behavior:

E, [2020-03-04T19:12:06.670017 #27160-69883551029620] ERROR -- : execute Job.run (try_count 0) exited with a non standard-error #<SyntaxError: (erb):1: syntax error, unexpected tIDENTIFIER, expecting tSTRING_DEND
I, [2020-03-04T19:12:06.671689 #27160-46960850806260]  INFO -- : Scheduler stopped.
  • Scheduler stopped
  • That particular job wouldn’t execute again (even though I removed the variable completely)

(Also, I’d love to understand the log file better—what exactly does #27160 refer to? PID?)

Thanks,
Ben

Please share this output:
zammad run rails r "p Job.all"

Before that that’s an absolute blackbox :man_shrugging:


This log message is totally fine. It just tells you the scheduler run has endet. You’ll find these kind of messages dozen of times within your logfile - nothing crashed there.

#27160 is the PID of the current running process that’s causing the log entry, correct!

Sorry, but I’m not really sure what I can provide as additional information.
Schedulers act like a cronjob, so basically run at a defined time (UTC) on a regular basis (that you configured).

Most of the times scheduler jobs that are not running as expected are simply hung at that moment.
It possibly is still running - or at least Zammad thinks so.

Above requested output will tell us more about that.

Thank you for the explanation—(un)fortunately it just started to work again. Maybe the latest Zammad update (minor) fixed it. :man_shrugging:t2: Thanks anyway :slight_smile:

Small update: Ran into the same error again. Looks like the Job was aborted due to a syntax error (as stated above), but it still says running: true.

irb(main):184:0> Job.where(id: 13)
=> #<ActiveRecord::Relation [#<Job id: 13, name: "TEST: Erinnerung alle 10 Minuten #1", timeplan: {"days"=>{"Mon"=>true, "Tue"=>true, "Wed"=>true, "Thu"=>true, "Fri"=>true, "Sat"=>true, "Sun"=>true}, "hours"=>{"0"=>true, "1"=>true, "2"=>true, "3"=>true, "4"=>true, "5"=>true, "6"=>true, "7"=>true, "8"=>true, "9"=>true, "10"=>true, "11"=>true, "12"=>true, "13"=>true, "14"=>true, "15"=>true, "16"=>true, "17"=>true, "18"=>true, "19"=>true, "20"=>true, "21"=>true, "22"=>true, "23"=>true}, "minutes"=>{"0"=>true, "10"=>true, "20"=>true, "30"=>true, "40"=>true, "50"=>true}}, condition: {"ticket.group_id"=>{"operator"=>"is", "value"=>"4"}, "ticket.state_id"=>{"operator"=>"is", "value"=>"8"}, "ticket.pending_time"=>{"operator"=>"before (relative)", "value"=>"1", "range"=>"minute"}}, perform: {"article.note"=>{"body"=>"<div>Scheduler #1 (ALT)</div>", "internal"=>"true", "subject"=>"..."}, "notification.email"=>{"body"=>"redacted", "internal"=>"false", "recipient"=>"ticket_customer", "subject"=>"Rückmeldung erforderlich / \#{ticket.title}"}}, disable_notification: true, last_run_at: "2020-03-10 15:41:22", next_run_at: "2020-03-10 15:50:00", running: true, processed: 1, matching: 1, pid: nil, note: "", active: true, updated_by_id: 1, created_by_id: 3, created_at: "2020-03-04 11:08:05", updated_at: "2020-03-10 15:41:22">]>

Update: I have found the syntax error within my scheduler job—it was a missing closing parentheses:

#{article.body_as_html
instead of
#{article.body_as_html}

One question remains: Why would the job still be running even after logging that it has stopped? Should this be considered a bug?

Yes, I’d consider this as a bug, as Zammad does not notice it’s process to be crashing. Or rather doesn’t handle that well. Maybe it shouldn’t just disable “running: true”, but also notify within monitoring endpoint.

1 Like

So, will you open an issue on Github, or should I? Or should we ignore it since it seems that I’m the only one that made that mistake yet? :smiley:

Please go ahead, I’m a bit busy right now :smiley: