feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck #26618

pieh · 2020-08-24T14:43:07Z

Description

This PR allows to run Gatsby with following env vars (you can use one of those or both or ... well none):

GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT - to just log information when Gatsby is stuck in IN_PROGRESS
GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT - to terminate the process when stuck in IN_PROGRESS

Way it determines wether Gatsby is stuck is by (re)setting timer(s) on every log activity - it might mean log line, it might be tick() in progress bar, it might even be things not visible to users (setting activity as pending or using one of those hidden activities that are too fine grained to display in UI).

Few notes about usage:

when setting env var to a number (just any other than "1" - more about it in a sec) - it will try to use those numbers as timeout delay (but I did add, so at minimum it's 5s for diagnostic logs and 10s for termination)
when setting env var to truthy or "1" (which I reckon is quite popular way of "toggling" env vars), it will use some default timeouts (5 minutes for diagnostic logs and 10 minutes for termination).

In terminal results might look a little like this:

Both flags:

$ ENABLE_GATSBY_REFRESH_ENDPOINT=1 GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT=10000 GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT=5000  gatsby develop

[...]

success write out requires - 0.001s
success run page queries - 0.010s - 1/1 102.49/s
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 5.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167025,
      903782122
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "5.236"
  },
  {
    "id": "hidden one",
    "uuid": "eae76780-6d77-4685-aa0a-d8e959b53124",
    "text": "hidden one",
    "type": "hidden",
    "status": "IN_PROGRESS",
    "startTime": [
      167025,
      904008910
    ],
    "statusText": "",
    "diagnostics_elapsed_seconds": "5.236"
  }
]

Process will be terminated in 5.000 seconds if nothing will change.
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

There was activity since last diagnostic message. Log action:

{
  "type": "ACTIVITY_END",
  "payload": {
    "uuid": "eae76780-6d77-4685-aa0a-d8e959b53124",
    "id": "hidden one",
    "status": "SUCCESS",
    "duration": 7.51006542,
    "type": "hidden"
  },
  "timestamp": "2020-08-24T14:32:25.307Z"
}

Currently Gatsby is in: "IN_PROGRESS" state.

Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167025,
      903782122
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "7.512"
  }
]
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 5.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167025,
      903782122
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "12.515"
  }
]

Process will be terminated in 5.000 seconds if nothing will change.

 ERROR 

Terminating the process (due to GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 10.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167025,
      903782122
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "17.516"
  }
]

Just `GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT`:

$ ENABLE_GATSBY_REFRESH_ENDPOINT=1 GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT=5000  gatsby develop

[...]

success write out requires - 0.001s
success run page queries - 0.010s - 1/1 103.75/s
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 5.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167090,
      531910219
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "5.249"
  },
  {
    "id": "hidden one",
    "uuid": "8e952af8-dd37-418a-9b99-55fd49c331db",
    "text": "hidden one",
    "type": "hidden",
    "status": "IN_PROGRESS",
    "startTime": [
      167090,
      532129975
    ],
    "statusText": "",
    "diagnostics_elapsed_seconds": "5.249"
  }
]
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

There was activity since last diagnostic message. Log action:

{
  "type": "ACTIVITY_END",
  "payload": {
    "uuid": "8e952af8-dd37-418a-9b99-55fd49c331db",
    "id": "hidden one",
    "status": "SUCCESS",
    "duration": 7.506380937,
    "type": "hidden"
  },
  "timestamp": "2020-08-24T14:33:29.933Z"
}

Currently Gatsby is in: "IN_PROGRESS" state.

Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167090,
      531910219
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "7.507"
  }
]
warn This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 5.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167090,
      531910219
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "12.508"
  }
]

Just `GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT`:

$ ENABLE_GATSBY_REFRESH_ENDPOINT=1 GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT=10000  gatsby develop

[...]

success write out requires - 0.002s
success run page queries - 0.010s - 1/1 101.11/s

 ERROR 

Terminating the process (due to GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT):

Gatsby is in "IN_PROGRESS" state without any updates for 10.000 seconds. Activities preventing Gatsby from transitioning to idle state:

[
  {
    "id": "pending-but-not-really-running",
    "type": "pending",
    "startTime": [
      167245,
      698002618
    ],
    "status": "NOT_STARTED",
    "diagnostics_elapsed_seconds": "17.517"
  }
]

[ch14090]

…vity object in redux state

…" for some time

… (add actual log action there)

gatsby-cloud · 2020-08-24T14:45:20Z

Gatsby Cloud Build Report

using-styled-components

🎉 Your build was successful! See the Deploy preview here.

Build Details

View the build logs here.

🕐 Build time: 12s

Performance

Lighthouse report

Metric	Score
Performance	💚 100
Accessibility	💚 90
Best Practices	💚 100
SEO	💚 90

🔗 View full report

gatsby-cloud · 2020-08-24T14:45:26Z

Gatsby Cloud Build Report

client-only-paths

🎉 Your build was successful! See the Deploy preview here.

Build Details

View the build logs here.

🕐 Build time: 12s

Performance

Lighthouse report

Metric	Score
Performance	💚 100
Accessibility	🔶 85
Best Practices	💚 100
SEO	🔶 70

🔗 View full report

gatsby-cloud · 2020-08-24T14:45:33Z

Gatsby Cloud Build Report

using-reach-skip-nav

🎉 Your build was successful! See the Deploy preview here.

Build Details

View the build logs here.

🕐 Build time: 12s

Performance

Lighthouse report

Metric	Score
Performance	💚 100
Accessibility	💚 100
Best Practices	💚 100
SEO	🔶 82

🔗 View full report

gatsby-cloud · 2020-08-24T15:08:46Z

Gatsby Cloud Build Report

gatsby

🎉 Your build was successful! See the Deploy preview here.

Build Details

View the build logs here.

🕐 Build time: 8m

vladar

Can we have it as Redux middleware? It sounds like a good fit for something like this?

pieh · 2020-08-25T08:21:29Z

Can we have it as Redux middleware? It sounds like a good fit for something like this?

It kind of is in the "middleware" - all structured logs related actions go through it (but also worth mentioning that this is resetting timer only on structured logging actions).

It's just it's not using builtin redux middleware API because logic there for the most part only relates to logging (deciding whether to forward action to ipc) and it supports changing the target store instance (it always starts with store that is local to gatsby-cli, but can swap to gatsby store).

By using redux middleware did you mean to use proper middleware API or that it should reset timer on any action (doesn't have to be structured logging one)? Or both?

vladar · 2020-08-25T09:18:15Z

Oh, right, I forgot about swapping stores thing. Discard my previous comment.

pvdz

No major problems but some things to double check.

packages/gatsby-cli/src/reporter/redux/index.ts

packages/gatsby-cli/src/reporter/redux/types.ts

pvdz · 2020-08-25T10:38:55Z

packages/gatsby-cli/src/reporter/redux/index.ts

@@ -46,6 +117,95 @@ export const dispatch = (action: ActionsUnion | Thunk): void => {

  store.dispatch(action)

+  // ignore diagnostic logs, otherwise diagnostic message itself will reset


I understand what this block is doing. It seems to be quite verbose in terms of code for what it's doing (debouncing a "stuck" warning). Can it be abstracted a little bit into a global function? Closures may make that more difficult.

I moved almost all diagnostics related code to its own file/module (other than calls to init and calling handler in our custom dispatch function). I didn't do much changes otherwise - while there are similarities in 2 timers that I add they are different enough that I'm not sure if there's much value in trying to DRY it too much)

Co-authored-by: Peter van der Zee <209817+pvdz@users.noreply.github.com>

sidharthachatterjee · 2020-08-25T11:13:14Z

packages/gatsby-cli/src/reporter/redux/index.ts

+
+    // yuck, we have situation of circular dependencies here
+    // so this is `reporter` import is delayed until it's actually needed
+    const { reporter } = require(`../reporter`)


sidharthachatterjee · 2020-08-25T11:15:53Z

@pieh Is this a noop when those env vars are not set or do they have defaults?

pieh · 2020-08-25T11:22:02Z

@pieh Is this a noop when those env vars are not set or do they have defaults?

They don't have defaults so it is (more or less) no-op when env vars are not set.

…osing minimal API to be used in our custom "middleware"

… global status generation and diagnostics code

…g to cancel same thing multiple times

pieh added 5 commits August 24, 2020 10:53

fix(gatsby-cli): make sure to add pending activity ID to pending acti…

7ce0bf5

…vity object in redux state

feat(gatsby-cli): allow displaying diagnostic information when "stuck…

30868e7

…" for some time

add a little bit more context to message when reseting reseting timer…

577a4c7

… (add actual log action there)

store startTime for pending activities

bfc2b46

add diagnostics_elapsed_seconds to activity diagnostics logs

dab2a33

pieh added the topic: reporter label Aug 24, 2020

gatsbot bot added the status: triage needed Issue or pull request that need to be triaged and assigned to a reviewer label Aug 24, 2020

pieh removed the status: triage needed Issue or pull request that need to be triaged and assigned to a reviewer label Aug 24, 2020

fix lint

374eb15

pieh marked this pull request as ready for review August 25, 2020 07:26

vladar reviewed Aug 25, 2020

View reviewed changes

pvdz previously approved these changes Aug 25, 2020

View reviewed changes

Update packages/gatsby-cli/src/reporter/redux/index.ts

f6fcf6d

Co-authored-by: Peter van der Zee <209817+pvdz@users.noreply.github.com>

pieh dismissed pvdz’s stale review via f6fcf6d August 25, 2020 10:58

drop commented out comment

17fcfe0

sidharthachatterjee reviewed Aug 25, 2020

View reviewed changes

pieh added 4 commits August 25, 2020 14:09

refactor: move all the diagnostics related code to its own module exp…

e10a556

…osing minimal API to be used in our custom "middleware"

use same common function when deciding if activity is in progress for…

84334fe

… global status generation and diagnostics code

comments are hard

34596d8

nullify stored timer identifiers after cancelling them to avoid tryin…

4f7f0bb

…g to cancel same thing multiple times

pvdz approved these changes Aug 25, 2020

View reviewed changes

pieh merged commit b88f193 into master Aug 26, 2020

delete-merged-branch bot deleted the log-what-activities-prevent-from-transitioning-to-idle-when-stuck branch August 26, 2020 11:43

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck #26618

feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck #26618

pieh commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

vladar left a comment

pieh commented Aug 25, 2020

vladar commented Aug 25, 2020

pvdz left a comment

pvdz Aug 25, 2020

pieh Aug 25, 2020

sidharthachatterjee Aug 25, 2020

sidharthachatterjee commented Aug 25, 2020

pieh commented Aug 25, 2020

		@@ -46,6 +117,95 @@ export const dispatch = (action: ActionsUnion \| Thunk): void => {

		store.dispatch(action)

		// ignore diagnostic logs, otherwise diagnostic message itself will reset

feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck #26618

feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck #26618

Conversation

pieh commented Aug 24, 2020 • edited

Description

gatsby-cloud bot commented Aug 24, 2020 • edited

Gatsby Cloud Build Report

Build Details

Performance

Lighthouse report

gatsby-cloud bot commented Aug 24, 2020 • edited

Gatsby Cloud Build Report

Build Details

Performance

Lighthouse report

gatsby-cloud bot commented Aug 24, 2020 • edited

Gatsby Cloud Build Report

Build Details

Performance

Lighthouse report

gatsby-cloud bot commented Aug 24, 2020 • edited

Gatsby Cloud Build Report

Build Details

vladar left a comment

Choose a reason for hiding this comment

pieh commented Aug 25, 2020

vladar commented Aug 25, 2020

pvdz left a comment

Choose a reason for hiding this comment

pvdz Aug 25, 2020

Choose a reason for hiding this comment

pieh Aug 25, 2020

Choose a reason for hiding this comment

sidharthachatterjee Aug 25, 2020

Choose a reason for hiding this comment

sidharthachatterjee commented Aug 25, 2020

pieh commented Aug 25, 2020

pieh commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited

gatsby-cloud bot commented Aug 24, 2020 •

edited