1. AusOcean developer Avatar AusOcean developer
  2. Untitled project
  3. vidgrind
  4. Issues

OceanCron: does not run until a request has been made

Issue #289 wontfix
Alan Noble created an issue

Despite setting min_idle_instances and min_instances to 1, OceanCron does not appear to run until one request has been made.

Comments (3)

  1. Trek Hopton

    I tested this with a re-deploy:

    11:00 - Set a cron to execute at 11:20

    11:05 - I re-deployed OceanCron

    11:07 - Build finished with logs:

    INFO 2023-08-25T01:37:17.276597947Z Finished Step #3 - "post-buildpack"
INFO 2023-08-25T01:37:17.276729930Z PUSH
INFO 2023-08-25T01:37:17.276766275Z DONE

    11:08 - session was shutdown for some reason:

    INFO 2023-08-25T01:38:31.256580Z [pid1] Received terminated signal [session:KRLLK5F]
INFO 2023-08-25T01:38:31.256862Z [pid1] Sending terminated signal to processes [session:KRLLK5F]
INFO 2023-08-25T01:38:31.256876Z [pid1] Waiting 2s to allow shutdown processing [session:KRLLK5F]
INFO 2023-08-25T01:38:31.256885Z [pid1-nginx] Propagating terminated signal to nginx (pid 20) [session:KRLLK5F]
INFO 2023-08-25T01:38:31.256893Z [pid1-app] Propagating terminated signal to app (pid 11) [session:KRLLK5F]
WARNING 2023-08-25T01:38:31.259964Z [pid1-app] Exit -1 app (pid 11): /layers/google.go.build/bin/main [session:KRLLK5F]
INFO 2023-08-25T01:38:31.264364Z [pid1-nginx] Exit 0 nginx (pid 20): /usr/sbin/nginx -c /tmp/nginxconf-3919711033/nginx.conf [session:KRLLK5F]
INFO 2023-08-25T01:38:33.257165Z [pid1] Stopping all processes [session:KRLLK5F]
INFO 2023-08-25T01:38:33.257420Z [pid1] Done [session:KRLLK5F]
INFO 2023-08-25T01:38:33.257429Z [pid1] shutdown [session:KRLLK5F]

    11:20 - The cron did not run.

    11:22 - Loaded OceanCron homepage in my browser, it took roughly 25 seconds to load. The logs were as follows:

    INFO 2023-08-25T01:52:25.307215Z [pid1] started [session:RB2VX85]
DEBUG 2023-08-25T01:52:25.307793Z [pid1-app] Using app start info from /srv/.googleconfig/app_start.json: &main.appStart{Entrypoint:struct { Type string "json:\"type\""; UnparsedValue string "json:\"unparsed_value\""; Command string "json:\"command\""; WorkDir string "json:\"workdir\"" }{Type:"Generated", UnparsedValue:"", Command:"main", WorkDir:""}, EntrypointFromAppYAML:"", EntrypointContents:"", Runtime:"go118"} [session:RB2VX85]
INFO 2023-08-25T01:52:25.308081Z [pid1] Starting processes [app nginx] [session:RB2VX85]
INFO 2023-08-25T01:52:25.308792Z [pid1-app] app has no prerequisites, starting immediately [session:RB2VX85]
INFO 2023-08-25T01:52:25.309035Z [pid1-nginx] nginx waiting for any of 4 prerequisite(s): [portbind:tcp:127.0.0.1:8081 portbind:tcp:localhost:8080 portbind:tcp:localhost:8081 portbind:unix:/tmp/google-config/app.sock] [session:RB2VX85]
INFO 2023-08-25T01:52:25.354648Z [pid1-app] Starting app (pid 11): /layers/google.go.build/bin/main [session:RB2VX85]
DEFAULT 2023-08-25T01:52:25.608732Z 2023/08/25 01:52:25 Running in App Engine mode
DEFAULT 2023-08-25T01:52:26.253005Z 2023/08/25 01:52:26 cron mode
DEFAULT 2023-08-25T01:52:27.958936Z 2023/08/25 01:52:27 setting cron: TestCron
DEFAULT 2023-08-25T01:52:27.958961Z 2023/08/25 01:52:27 cron: TestCron spec: 0 10 * * *
DEFAULT 2023-08-25T01:52:27.958991Z 2023/08/25 01:52:27 setting cron: TestCron3
DEFAULT 2023-08-25T01:52:27.958995Z 2023/08/25 01:52:27 cron: TestCron3 spec: 0 11 * * *
DEFAULT 2023-08-25T01:52:28.841779Z 2023/08/25 01:52:28 setting cron: TestCron
DEFAULT 2023-08-25T01:52:33.169568Z 2023/08/25 01:52:33 setting cron: Test
DEFAULT 2023-08-25T01:52:33.169598Z 2023/08/25 01:52:33 failed to set job {Skey:201489903059 ID:Test Time:1970-01-01 05:03:00 +0000 UTC TOD: Repeat:false Minutes:303 Action:set Var:Test Data:true Enabled:true} from site=201489903059: could not get cron spec for job: Test: no time spec specified for job
DEFAULT 2023-08-25T01:52:33.533200Z 2023/08/25 01:52:33 setting cron: CamOff
DEFAULT 2023-08-25T01:52:33.533211Z 2023/08/25 01:52:33 cron: CamOff spec: Sunset
DEFAULT 2023-08-25T01:52:33.533239Z 2023/08/25 01:52:33 failed to set job {Skey:214536881915 ID:CamOff Time:1970-01-01 18:00:00 +0000 UTC TOD:Sunset Repeat:false Minutes:1080 Action:set Var:ExampleESP.Power Data:false Enabled:true} from site=214536881915: failed to add cron spec Sunset to the cron scheduler: expected exactly 5 fields, found 1: [Sunset]
DEFAULT 2023-08-25T01:52:33.533245Z 2023/08/25 01:52:33 setting cron: CamOn
DEFAULT 2023-08-25T01:52:33.533251Z 2023/08/25 01:52:33 cron: CamOn spec: Sunrise
DEFAULT 2023-08-25T01:52:33.533260Z 2023/08/25 01:52:33 failed to set job {Skey:214536881915 ID:CamOn Time:1970-01-01 06:00:00 +0000 UTC TOD:Sunrise Repeat:false Minutes:360 Action:set Var:ExampleESP.Power Data:true Enabled:true} from site=214536881915: failed to add cron spec Sunrise to the cron scheduler: expected exactly 5 fields, found 1: [Sunrise]
DEFAULT 2023-08-25T01:52:33.533265Z 2023/08/25 01:52:33 setting cron: NavlightOff
DEFAULT 2023-08-25T01:52:33.533271Z 2023/08/25 01:52:33 cron: NavlightOff spec: Sunrise
DEFAULT 2023-08-25T01:52:33.533280Z 2023/08/25 01:52:33 failed to set job {Skey:214536881915 ID:NavlightOff Time:1970-01-01 06:00:00 +0000 UTC TOD:Sunrise Repeat:false Minutes:360 Action:set Var:ExampleESP.Suppress Data:true Enabled:true} from site=214536881915: failed to add cron spec Sunrise to the cron scheduler: expected exactly 5 fields, found 1: [Sunrise]
DEFAULT 2023-08-25T01:52:33.533285Z 2023/08/25 01:52:33 setting cron: NavlightOn
DEFAULT 2023-08-25T01:52:33.533291Z 2023/08/25 01:52:33 cron: NavlightOn spec: Sunset
DEFAULT 2023-08-25T01:52:33.533299Z 2023/08/25 01:52:33 failed to set job {Skey:214536881915 ID:NavlightOn Time:1970-01-01 18:00:00 +0000 UTC TOD:Sunset Repeat:false Minutes:1080 Action:set Var:ExampleESP.Suppress Data:false Enabled:true} from site=214536881915: failed to add cron spec Sunset to the cron scheduler: expected exactly 5 fields, found 1: [Sunset]
DEFAULT 2023-08-25T01:52:34.283909Z 2023/08/25 01:52:34 setting cron: CameraOff
DEFAULT 2023-08-25T01:52:34.283921Z 2023/08/25 01:52:34 setting cron: CameraOn
DEFAULT 2023-08-25T01:52:34.283925Z 2023/08/25 01:52:34 setting cron: LightOff
DEFAULT 2023-08-25T01:52:34.283930Z 2023/08/25 01:52:34 cron: LightOff spec: Sunrise
DEFAULT 2023-08-25T01:52:34.283938Z 2023/08/25 01:52:34 failed to set job {Skey:229721404051 ID:LightOff Time:1970-01-01 20:14:00 +0000 UTC TOD:Sunrise Repeat:false Minutes:644 Action:set Var:ESP_0A8839.SuppressLight Data:true Enabled:true} from site=229721404051: failed to add cron spec Sunrise to the cron scheduler: expected exactly 5 fields, found 1: [Sunrise]
DEFAULT 2023-08-25T01:52:34.283941Z 2023/08/25 01:52:34 setting cron: LightOn
DEFAULT 2023-08-25T01:52:34.283946Z 2023/08/25 01:52:34 cron: LightOn spec: Sunset
DEFAULT 2023-08-25T01:52:34.283953Z 2023/08/25 01:52:34 failed to set job {Skey:229721404051 ID:LightOn Time:1970-01-01 09:50:00 +0000 UTC TOD:Sunset Repeat:false Minutes:680 Action:set Var:ESP_0A8839.SuppressLight Data:false Enabled:true} from site=229721404051: failed to add cron spec Sunset to the cron scheduler: expected exactly 5 fields, found 1: [Sunset]
DEFAULT 2023-08-25T01:52:34.613641Z 2023/08/25 01:52:34 setting cron: Mic-Off
DEFAULT 2023-08-25T01:52:34.613649Z 2023/08/25 01:52:34 cron: Mic-Off spec: 0 1 * * *
DEFAULT 2023-08-25T01:52:34.613664Z 2023/08/25 01:52:34 setting cron: Mic-On
DEFAULT 2023-08-25T01:52:34.613668Z 2023/08/25 01:52:34 cron: Mic-On spec: 0 14 * * *
DEFAULT 2023-08-25T01:52:38.647409Z 2023/08/25 01:52:38 setting cron: CamOff
DEFAULT 2023-08-25T01:52:38.647417Z 2023/08/25 01:52:38 cron: CamOff spec: 0 18 * * *
DEFAULT 2023-08-25T01:52:38.647433Z 2023/08/25 01:52:38 setting cron: Rapid Bay Live by AusOcean
DEFAULT 2023-08-25T01:52:38.647438Z 2023/08/25 01:52:38 cron: Rapid Bay Live by AusOcean spec: 50 8 * * *
DEFAULT 2023-08-25T01:52:41.962510Z 2023/08/25 01:52:41 setting cron: PowerOff
DEFAULT 2023-08-25T01:52:41.962521Z 2023/08/25 01:52:41 cron: PowerOff spec: 0 18 * * *
DEFAULT 2023-08-25T01:52:41.962526Z 2023/08/25 01:52:41 setting cron: PowerOn
DEFAULT 2023-08-25T01:52:41.962530Z 2023/08/25 01:52:41 cron: PowerOn spec: 0 9 * * *
DEFAULT 2023-08-25T01:52:42.250126Z 2023/08/25 01:52:42 setting cron: SaxonPuter
DEFAULT 2023-08-25T01:52:42.676222Z 2023/08/25 01:52:42 setting cron: CamOff
DEFAULT 2023-08-25T01:52:42.676234Z 2023/08/25 01:52:42 cron: CamOff spec: 00 18 * * *
DEFAULT 2023-08-25T01:52:42.676238Z 2023/08/25 01:52:42 setting cron: PowerOn
DEFAULT 2023-08-25T01:52:42.676242Z 2023/08/25 01:52:42 cron: PowerOn spec: 20 11 * * *
DEFAULT 2023-08-25T01:52:42.676275Z 2023/08/25 01:52:42 setting cron: Willunga_Tcam
DEFAULT 2023-08-25T01:52:42.676279Z 2023/08/25 01:52:42 cron: Willunga_Tcam spec: 0 9 * * *
DEFAULT 2023-08-25T01:52:50.273845Z 2023/08/25 01:52:50 setting cron: CamOff
DEFAULT 2023-08-25T01:52:50.273857Z 2023/08/25 01:52:50 setting cron: CamOn
DEFAULT 2023-08-25T01:52:51.394151Z 2023/08/25 01:52:51 setting cron: CPEOff
DEFAULT 2023-08-25T01:52:51.394160Z 2023/08/25 01:52:51 cron: CPEOff spec: 0 19 * * *
DEFAULT 2023-08-25T01:52:51.394164Z 2023/08/25 01:52:51 setting cron: CPEOn
DEFAULT 2023-08-25T01:52:51.394223Z 2023/08/25 01:52:51 setting cron: CamOff
DEFAULT 2023-08-25T01:52:51.394242Z 2023/08/25 01:52:51 cron: CamOff spec: 0 18 * * *
DEFAULT 2023-08-25T01:52:51.394289Z 2023/08/25 01:52:51 setting cron: Stony Point CuttleCam by AusOcean
DEFAULT 2023-08-25T01:52:53.960817Z 2023/08/25 01:52:53 setting cron: CamOff
DEFAULT 2023-08-25T01:52:53.960827Z 2023/08/25 01:52:53 cron: CamOff spec: 0 20 * * *
DEFAULT 2023-08-25T01:52:53.960843Z 2023/08/25 01:52:53 setting cron: Edithburgh Live by AusOcean
DEFAULT 2023-08-25T01:52:53.960848Z 2023/08/25 01:52:53 cron: Edithburgh Live by AusOcean spec: 50 8 * * *
DEFAULT 2023-08-25T01:52:55.054403Z 2023/08/25 01:52:55 Listening on localhost:8081
INFO 2023-08-25T01:52:55.061077Z [pid1-nginx] Successfully connected to 127.0.0.1:8081 after 29.751328091s [session:RB2VX85]
INFO 2023-08-25T01:52:55.061391Z [pid1-nginx] Successfully connected to localhost:8081 after 29.751732207s [session:RB2VX85]
INFO 2023-08-25T01:52:55.061938Z [pid1-nginx] Creating config at /tmp/nginxconf-4026391081/nginx.conf [session:RB2VX85]
INFO 2023-08-25T01:52:55.063098Z [pid1-nginx] Starting nginx (pid 21): /usr/sbin/nginx -c /tmp/nginxconf-4026391081/nginx.conf [session:RB2VX85]
DEFAULT 2023-08-25T01:52:55.401529Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 3.96 KiB] [protoPayload.latency: 1 ms] [protoPayload.userAgent: Chrome 112.0.0.0] /s/tiny_logo.png
DEFAULT 2023-08-25T01:52:55.402030Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 3.74 KiB] [protoPayload.latency: 0 ms] [protoPayload.userAgent: Chrome 112.0.0.0] /s/main.css
DEFAULT 2023-08-25T01:52:55.681633Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 15.04 KiB] [protoPayload.latency: 0 ms] [protoPayload.userAgent: Chrome 112.0.0.0] /favicon.ico

    In summary this test confirmed that no instance is running after OceanCron is deployed until the first request is made.

  2. Alan Noble reporter

    It would seem that not automatically restarting a re-deployed app that has the same version is a “feature” of App Engine Standard Edition.

    Only when a new version is deployed is the app automatically restarted.

    With Flex Edition, you can force a restart with the following command after deploying:
    gcloud app instances restart <project-id>

    There is no such option for Standard Edition, though.

    Of course, hitting the home page has exactly the same effect :-)

    ‌

  4. Log in to comment
Assignee
Type
bug
Priority
minor
Status
wontfix
Votes
0
Watchers
2
Jira: the preferred issue tracker for Bitbucket. Join the team!