broadcast: off and on actions performed too close together for powercycle

While investigating some recent broadcast failures, I noticed that the off and on actions for powercycling the camera happen within the same second. This is too fast, we need to wait for the camera to get the power variable in the off state, then we can turn it back on.
It seems like this is implemented in health.go’s handleHealth function, but I don’t know why it’s not working as expected.
This is the debugging sheet where I documented the timeline. See 9:02 on 6/9/2023, highlighted in orange the premature on action.
https://docs.google.com/spreadsheets/d/1V633n_pJuXlxsnUKmQ-7p-ot0SfzsNIWBNpypDC83B8/edit#gid=0
Here are the logs leading up to this observation:
DEFAULT 2023-09-05T23:30:14.266556Z 2023/09/05 23:30:14 broadcast: Edithburgh Live by AusOcean, ID: 22LVflUaINk, start time reached. Performing setup.
DEFAULT 2023-09-05T23:30:17.101851Z 2023/09/05 23:30:17 checking ESP_2BAD6D.Power variable exists
DEFAULT 2023-09-05T23:30:17.306475Z 2023/09/05 23:30:17 ESP_2BAD6D.Power variable exists, setting to value: true
DEFAULT 2023-09-05T23:30:17.363875Z 2023/09/05 23:30:17 checking ESP-EdJty.Power variable exists
DEFAULT 2023-09-05T23:30:17.561224Z 2023/09/05 23:30:17 ESP-EdJty.Power variable exists, setting to value: true
DEFAULT 2023-09-05T23:30:17.778516Z 2023/09/05 23:30:17 checking PI_0049.mode variable exists
DEFAULT 2023-09-05T23:30:17.988157Z 2023/09/05 23:30:17 PI_0049.mode variable exists, setting to value: Normal
DEFAULT 2023-09-05T23:30:18.016112Z 2023/09/05 23:30:18 checking Camera.mode variable exists
DEFAULT 2023-09-05T23:30:18.216004Z 2023/09/05 23:30:18 Camera.mode variable exists, setting to value: Normal
DEFAULT 2023-09-05T23:30:18.460531Z 2023/09/05 23:30:18 checking PI_0049.RTMPURL variable exists
DEFAULT 2023-09-05T23:30:18.652671Z 2023/09/05 23:30:18 PI_0049.RTMPURL variable exists, setting to value: rtmp://a.rtmp.youtube.com/live2/hxvb-e5ug-pzgp-rkmd-cxx2
DEFAULT 2023-09-05T23:30:18.757650Z 2023/09/05 23:30:18 checking Camera.RTMPURL variable exists
DEFAULT 2023-09-05T23:30:18.957405Z 2023/09/05 23:30:18 Camera.RTMPURL variable exists, setting to value: rtmp://a.rtmp.youtube.com/live2/ta7e-bps9-6ytu-zbhd-b7z0
DEFAULT 2023-09-05T23:30:21.485982Z 2023/09/05 23:30:21 waiting for ready status...
DEFAULT 2023-09-05T23:30:21.812279Z 2023/09/05 23:30:21 waiting for ready status...
DEFAULT 2023-09-05T23:30:37.088147Z 2023/09/05 23:30:37 status ready reached, breaking...
DEFAULT 2023-09-05T23:30:37.088159Z 2023/09/05 23:30:37 waiting for active status...
DEFAULT 2023-09-05T23:30:37.334295Z 2023/09/05 23:30:37 status ready reached, breaking...
DEFAULT 2023-09-05T23:30:37.334307Z 2023/09/05 23:30:37 waiting for active status...
DEFAULT 2023-09-05T23:31:00.270014Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 95 B] [protoPayload.latency: 12.435 s] [protoPayload.userAgent: AppEngine-Google; (+http://code.google.com/appengine)] /broadcastcheck
DEFAULT 2023-09-05T23:31:00.272891Z 2023/09/05 23:31:00 broadcast check handler
DEFAULT 2023-09-05T23:31:12.704768Z 2023/09/05 23:31:12 broadcast: Willunga_Tcam, ID: GQJCqgFFHqk, start time reached. Performing setup.
DEFAULT 2023-09-05T23:31:15.769774Z 2023/09/05 23:31:15 checking Willunga_Tcam.mode variable exists
DEFAULT 2023-09-05T23:31:15.968219Z 2023/09/05 23:31:15 Willunga_Tcam.mode variable exists, setting to value: Normal
DEFAULT 2023-09-05T23:31:16.452738Z 2023/09/05 23:31:16 checking ESP_4869E7.Power1 variable exists
DEFAULT 2023-09-05T23:31:16.656679Z 2023/09/05 23:31:16 ESP_4869E7.Power1 variable exists, setting to value: true
DEFAULT 2023-09-05T23:31:17.137299Z 2023/09/05 23:31:17 checking Willunga_Tcam.RTMPURL variable exists
DEFAULT 2023-09-05T23:31:17.334576Z 2023/09/05 23:31:17 Willunga_Tcam.RTMPURL variable exists, setting to value: rtmp://a.rtmp.youtube.com/live2/xdg3-ztqh-f04q-g45k-8g29
DEFAULT 2023-09-05T23:31:20.601Z 2023/09/05 23:31:20 waiting for ready status...
DEFAULT 2023-09-05T23:31:23.622473Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 249 B] [protoPayload.latency: 1.098 s] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:00:00:00:00:07&dk=89235883&ut=20
DEFAULT 2023-09-05T23:31:24.814156Z [protoPayload.method: POST] [protoPayload.status: 200] [protoPayload.responseSize: 249 B] [protoPayload.latency: 929 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:00:00:00:00:07&dk=89235883&ut=21&T0=2798
DEFAULT 2023-09-05T23:31:26.077768Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 469 B] [protoPayload.latency: 438 ms] [protoPayload.userAgent: Go-http-client 1.1] /vars?vn=161&ma=00:00:00:00:00:07&dk=89235883&ut=22
DEFAULT 2023-09-05T23:31:35.125101Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 258 B] [protoPayload.latency: 1.197 s] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:E0:4C:00:00:49&dk=90140181&ut=20
DEFAULT 2023-09-05T23:31:36.207030Z 2023/09/05 23:31:36 status ready reached, breaking...
DEFAULT 2023-09-05T23:31:36.207048Z 2023/09/05 23:31:36 waiting for active status...
DEFAULT 2023-09-05T23:31:36.643433Z [protoPayload.method: POST] [protoPayload.status: 200] [protoPayload.responseSize: 258 B] [protoPayload.latency: 684 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:E0:4C:00:00:49&dk=90140181&ut=21&T0=2803
DEFAULT 2023-09-05T23:31:37.603963Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 463 B] [protoPayload.latency: 420 ms] [protoPayload.userAgent: Go-http-client 1.1] /vars?vn=161&ma=00:E0:4C:00:00:49&dk=90140181&ut=22
DEFAULT 2023-09-05T23:31:37.802205Z 2023/09/05 23:31:37 status active reached, breaking...
DEFAULT 2023-09-05T23:31:37.802217Z 2023/09/05 23:31:37 ID: 22LVflUaINk, requesting transition to testing status...
DEFAULT 2023-09-05T23:31:39.251197Z 2023/09/05 23:31:39 waiting for testing status...
DEFAULT 2023-09-05T23:31:52.555046Z 2023/09/05 23:31:52 status active reached, breaking...
DEFAULT 2023-09-05T23:31:52.555065Z 2023/09/05 23:31:52 ID: Hcz1ZNDcN5M, requesting transition to testing status...
DEFAULT 2023-09-05T23:31:54.334745Z 2023/09/05 23:31:54 waiting for testing status...
DEFAULT 2023-09-05T23:32:00.708069Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 95 B] [protoPayload.latency: 11.471 s] [protoPayload.userAgent: AppEngine-Google; (+http://code.google.com/appengine)] /broadcastcheck
DEFAULT 2023-09-05T23:32:00.710744Z 2023/09/05 23:32:00 broadcast check handler
DEFAULT 2023-09-05T23:32:09.773450Z 2023/09/05 23:32:09 status testing reached, breaking...
DEFAULT 2023-09-05T23:32:09.773476Z 2023/09/05 23:32:09 ID: Hcz1ZNDcN5M, requesting transition to live status...
DEFAULT 2023-09-05T23:32:11.535722Z 2023/09/05 23:32:11 waiting for live status...
DEFAULT 2023-09-05T23:32:26.975528Z 2023/09/05 23:32:26 status live reached, breaking...
DEFAULT 2023-09-05T23:32:28.217604Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 249 B] [protoPayload.latency: 657 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:00:00:00:00:07&dk=89235883&ut=84
DEFAULT 2023-09-05T23:32:28.948801Z [protoPayload.method: POST] [protoPayload.status: 200] [protoPayload.responseSize: 249 B] [protoPayload.latency: 687 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:00:00:00:00:07&dk=89235883&ut=85&T0=5234
DEFAULT 2023-09-05T23:32:39.660051Z 2023/09/05 23:32:39 broadcast: Edithburgh Live by AusOcean, ID: 22LVflUaINk, could not perform transitions to go live: failed to go live, could not perform status action: 3: status wait timeout
DEFAULT 2023-09-05T23:32:39.856508Z 2023/09/05 23:32:39 notify health ops@ausocean.org
DEFAULT 2023-09-05T23:32:40.099101Z [protoPayload.method: GET] [protoPayload.status: 200] [protoPayload.responseSize: 258 B] [protoPayload.latency: 649 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:E0:4C:00:00:49&dk=90140181&ut=85
DEFAULT 2023-09-05T23:32:40.857226Z [protoPayload.method: POST] [protoPayload.status: 200] [protoPayload.responseSize: 258 B] [protoPayload.latency: 693 ms] [protoPayload.userAgent: Go-http-client 1.1] /poll?vn=161&ma=00:E0:4C:00:00:49&dk=90140181&ut=85&T0=3396
DEFAULT 2023-09-05T23:32:41.093803Z 2023/09/05 23:32:41 checking ESP-EdJty.Power variable exists
DEFAULT 2023-09-05T23:32:41.287093Z 2023/09/05 23:32:41 ESP-EdJty.Power variable exists, setting to value: false
DEFAULT 2023-09-05T23:32:41.739650Z 2023/09/05 23:32:41 checking Camera.mode variable exists
DEFAULT 2023-09-05T23:32:41.940878Z 2023/09/05 23:32:41 Camera.mode variable exists, setting to value: Paused
DEFAULT 2023-09-05T23:32:42.419425Z 2023/09/05 23:32:42 broadcast: Edithburgh Live by AusOcean, ID: 22LVflUaINk, start time reached. Performing setup.
DEFAULT 2023-09-05T23:32:45.777884Z 2023/09/05 23:32:45 checking ESP-EdJty.Power variable exists
DEFAULT 2023-09-05T23:32:45.977887Z 2023/09/05 23:32:45 ESP-EdJty.Power variable exists, setting to value: true
DEFAULT 2023-09-05T23:32:46.440305Z 2023/09/05 23:32:46 checking Camera.mode variable exists
DEFAULT 2023-09-05T23:32:46.640700Z 2023/09/05 23:32:46 Camera.mode variable exists, setting to value: Normal
DEFAULT 2023-09-05T23:32:47.123032Z 2023/09/05 23:32:47 checking Camera.RTMPURL variable exists
DEFAULT 2023-09-05T23:32:47.327899Z 2023/09/05 23:32:47 Camera.RTMPURL variable exists, setting to value: rtmp://a.rtmp.youtube.com/live2/ta7e-bps9-6ytu-zbhd-b7z0
DEFAULT 2023-09-05T23:32:50.401647Z 2023/09/05 23:32:50 waiting for ready status...
‌
Comments (2)
