Event Scheduler is not working at all

farmS1m · June 24, 2024, 10:21pm

Hello guys,

For some reason in my setup all scheduled events do never run. Don’t know whats going wrong. Nothing is logged in the logs according to event starts. As discussed this is normal under some circumstances (Request for log entry when a scheduled task (Farmbot Event) is run) But at least I expect they do run Tested events with various sequences, One of them I’ve configured sending me a Teams notification whenever it gets executed.

Executing the sequence manually works, without issues.
Scheduling a regime, is not working.

Today I was checking If something more can be fetched from the API. Unfortunately not discovered anything helpful. But a possible workaround would be to setup a cronjob on an external machine to trigger the sequence. But not so nice, since I would love to use the builtin scheduler

To troubleshoot the issue I already did the following:

Rebooted the FB.
Disabled automatic updates, as suggested here: Farm events not initiating - #7 by SigurdH
Checked if NTP is open → is open
Checked the local time → OK
Checked if the issue is limited to LUA sequences only? → No, also others do not work, tested: “Take photo of plant” and a simple sequence, just having a move to 0,0,0 coordinates.

/api/farm_events output:

[
  {
    "id": 25370,
    "created_at": "2024-06-24T21:36:09.090Z",
    "updated_at": "2024-06-24T21:38:14.648Z",
    "start_time": "2024-06-24T21:45:00.000Z",
    "end_time": "2024-07-05T22:01:00.000Z",
    "repeat": 1,
    "time_unit": "hourly",
    "executable_id": 209931,
    "executable_type": "Sequence",
    "body": [
      {
        "kind": "parameter_application",
        "args": {
          "label": "Plant",
          "data_value": {
            "kind": "point",
            "args": {
              "pointer_type": "Plant",
              "pointer_id": 1283598
            }
          }
        }
      }
    ]
  }
]

Any ideas what could be the cause? Any suggestion to further troubleshoot the issue, or fetching some additional related logs / data?

jsimmonds · June 25, 2024, 3:16am

Hi @farmS1m

When a Farm Event starts executing it’s selected Sequence there should be log records like

03:04:00.023 [info] Starting Meta Fungus

03:04:00.523 [info]  [ log records arising within the Sequence code ]

03:04:00.633 [info] Completed Meta Fungus

Did you mean Regimen ? or Sequence here ?

When you created that repeating Farm Event did you see future executions listed on the Events tab ?

Did you edit any future Farm Event execution ?

farmS1m · June 25, 2024, 7:08pm

Both do not work, tried both. Just wan’t highlight that they do not work to. I do understand, that regimes always must be triggered via Farm Event. (Its not enough to just configure them in the regime tab.) But lets first stick to the Farm Events schedules linked to a sequenze. I think they have less complexity behind the scenes…

Yes, I see them.

No events at all recording the Farm Event execution.

No, just to be sure I deleted all of them once more and configured a new one. In the printscreen above at 21:00 it did not got executed. It should run every 30’

jsimmonds · June 26, 2024, 2:34am

Hi @farmS1m thanks for those images. The only item not shown is the Sequence code, but I think you said it will execute fine for a manual one-shot.

Time to connect to FarmBot Inc. for some support. I’m not sure that there’s much else we can do to debug this, outside of building a bespoke “instrumented” version of FarmbotOS (I’ve done this in the past while learning how the code actually works).

Every running FarmbotOS instance comes with

Crash reporting to Rollbar Inc.
Device Telemetry of basic machine metrics
A command-line tty over MQTT for ad-hoc inspections

FarmBot Inc. has access to all those on your machine (unless you’re self-hosting).

farmS1m · June 26, 2024, 4:22pm

Thank you for your efforts @jsimmonds !

Followed your advice and sent an email to the FB support. Will keep you posted about the progress.

jsimmonds · June 27, 2024, 7:52am

Thank you

Sharing the finding will be helpful. Maybe not too many others have this issue, but, whatever the root cause(s) is/are in your device, this knowledge should help improve the product and the UX . . I’m sure FarmBot Inc. will want to fix whatever ‘vulnerabilities’ your device Configuration or its Environment reveal

farmS1m · June 30, 2024, 3:25pm

Hello @roryaronson , thanks for getting in touch with me by email.

I think I’ve discovered something new which may can be considered as a bug.

In my setup, whenever a sequence is getting triggered by the farm events scheduler and the linked sequence has a location variable, the sequence itself will not run. And also further sequences (also those who have no sequence variables assigned) do not run anymore. Its like the scheduler process will crash and will never come back until you do:

Remove the event (ensure no more sequences getting triggered whose have a location variable)
Restart FB
Wait until next event (without having a variable) is being executed

Result: The next none variable based event does run!

In summary, I think Farm Events do have issues with sequences having variables. It makes no difference if the variable is a point_group or point.

@jsimmonds Do you may have time to reproduce this?

Does not run:

Does run

FYI: Manual sequence executions do run all the time

jsimmonds · July 1, 2024, 2:08am

Hi @farmS1m yes I have done that and matches all your details perfectly.

In addition, if the FarmEvent still exists after the FBOS reboot then the Boot Sequence ( if you have one set up ) silently fails to run.

Here’s a screen grab showing some detail for whoever debugs this issue, and the FarmEvent object is shown after that.

Final screen capture is after editing the Farm Event the Scheduler process is stopped ( I think this is intentional in the code ) but maybe a new Scheduler never starts or runs properly ?
Edit: [ the above scenario needs testing / fixing ]

The FarmEvent object =>

After editing the Farm Event =>

jsimmonds · July 2, 2024, 5:59am

@farmS1m there’s a simple workaround for this issue. Add a Default value to the Sequence variable, then apply your desired variable value to your Farm Event when you create it.

Edit: A careful code change is needed to allow for Sequence variable Default value: none
[e.g. see farmbot_os/lib/celery/compilers/scope.ex]

i.e. code needs to handle this

08:34:00.002 [info] Next execution is ready for execution: now

08:34:00.006 [debug] [
  %FarmbotOS.Celery.AST{
    args: %{
      label: "Location 7",
      default_value: %FarmbotOS.Celery.AST{args: %{}, body: [], kind: :location_placeholder, comment: nil, meta: nil}
    },
    body: [],
    kind: :parameter_declaration,
    comment: nil,
    meta: nil
  },
  %FarmbotOS.Celery.AST{
    args: %{
      label: "Location 7",
      data_value: %FarmbotOS.Celery.AST{args: %{point_group_id: 95793}, body: [], kind: :point_group, comment: nil, meta: nil}
    },
    body: [],
    kind: :parameter_application,
    comment: nil,
    meta: nil
  }
]

08:34:00.006 [debug] %FarmbotOS.Celery.Compiler.Scope{parent: nil, declarations: %{}, valid: true}

08:34:00.016 [info] No value provided for Location 7

and this

08:31:00.002 [info] Next execution is ready for execution: now

08:31:00.006 [debug] [
  %FarmbotOS.Celery.AST{
    args: %{
      label: "Location 7",
      default_value: %FarmbotOS.Celery.AST{args: %{tool_id: 4822}, body: [], kind: :tool, comment: nil, meta: nil}
    },
    body: [],
    kind: :parameter_declaration,
    comment: nil,
    meta: nil
  },
  %FarmbotOS.Celery.AST{
    args: %{
      label: "Location 7",
      data_value: %FarmbotOS.Celery.AST{args: %{point_group_id: 95793}, body: [], kind: :point_group, comment: nil, meta: nil}
    },
    body: [],
    kind: :parameter_application,
    comment: nil,
    meta: nil
  }
]

08:31:00.006 [debug] %FarmbotOS.Celery.Compiler.Scope{parent: nil, declarations: %{}, valid: true}

08:31:00.069 [info] [1/3] Starting --- Forum 9221 Farm Event with arg ---

roryaronson · July 2, 2024, 11:46pm

Thanks for the detailed reporting and investigation! I am able to reproduce the issue as well, and the bug does occur with other variable types with a default value of None as well.

As jsimmonds pointed out, for now please use a default value other than None while we work on a fix for this

jsimmonds · July 4, 2024, 10:55am

Hi @roryaronson

Subtly, executing this Sequence when having Location Default value: none works just fine over an RPC.
Here’s my simple debug output (from inside scope.ex) where the RPC supplies one parameter_application for “Location 7” :

10:39:02.212 [debug] [
  %FarmbotOS.Celery.AST{
    args: %{
      label: "Location 7",
      default_value: %FarmbotOS.Celery.AST{args: %{}, body: [], kind: :location_placeholder, comment: nil, meta: nil}
    },
    body: [],
    kind: :parameter_declaration,
    comment: nil,
    meta: nil
  }
]

10:39:02.214 [debug] %FarmbotOS.Celery.Compiler.Scope{
  parent: %FarmbotOS.Celery.Compiler.Scope{parent: nil, declarations: %{}, valid: true},
  declarations: %{
    "Location 7" => %FarmbotOS.Celery.AST{args: %{point_group_id: 99567}, body: [], kind: :point_group, comment: nil, meta: nil}
  },
  valid: true
}

10:39:02.268 [info] [1/6] Starting --- Forum 9221 Farm Event with arg ---

Why does the Scheduler have a different take on a parameter_declaration with location_placeholder ?

roryaronson · July 4, 2024, 10:01pm

The problem seemed to arise when there were more than one parameter_applications for the same variable and one of the values was holding a placeholder. For example, an event that runs a sequence with an externally defined variable would have parameter_applications from both the event and the sequence. The compiler, upon encountering the application with the placeholder was prematurely exiting. Instead it should have kept looking to find the application with the correct value.

When sending the RPC, my guess is the compiler was not seeing multiple parameter_applications and so it was working just fine.

We just released FBOS v15.4.10 that doesn’t prematurely exit the compiler (so that it finds the needed variable value) and has more graceful handling (no longer requiring a reboot) in situations where it doesn’t find a non-placeholder value. Please let us know if it resolves the problem on your end!

jsimmonds · July 5, 2024, 3:21am

Big Thanks @roryaronson and @Gabriel for this rapid FBOS fix .

Final nit-pick from me :

The CS node with the default_value: argument is actually a :parameter_declaration

Curious how this bug lived for so long ??

tonytwong · July 5, 2024, 4:10am

Thank you, it solves my problem.

roryaronson · July 5, 2024, 5:59pm

Ah, yes I still have a hard time keeping applications and declarations straight in my mind!

And yes, very surprising to us too that this bug lived so long. Deep parts of the CeleryScript Virtual Machine like this have not been changed in years. But with so many ways to setup one’s sequences/regimens/events/variables I guess just not that many people were setting default values of None and getting to this point

farmS1m · July 6, 2024, 10:20pm

I am pleased to share that I was able to contribute to identifying a longstanding bug in the FB OS. This achievement makes me very happy, as it brings it one step closer to improving the product.

Thank you all for your support and collaboration. And a special thank to @jsimmonds for the quick workaround and first aid help

jsimmonds · July 7, 2024, 10:02am

I think you did !! . . please find another nice s/w bug soon

system · August 6, 2024, 10:02am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.