Skip to content

Commit b88f193

Browse files
piehpvdz
andauthored
feat(gatsby-cli): log what activities prevent from transitioning to idle when stuck (#26618)
* fix(gatsby-cli): make sure to add pending activity ID to pending activity object in redux state * feat(gatsby-cli): allow displaying diagnostic information when "stuck" for some time * add a little bit more context to message when reseting reseting timer (add actual log action there) * store startTime for pending activities * add `diagnostics_elapsed_seconds` to activity diagnostics logs * fix lint * Update packages/gatsby-cli/src/reporter/redux/index.ts Co-authored-by: Peter van der Zee <[email protected]> * drop commented out comment * refactor: move all the diagnostics related code to its own module exposing minimal API to be used in our custom "middleware" * use same common function when deciding if activity is in progress for global status generation and diagnostics code * comments are hard * nullify stored timer identifiers after cancelling them to avoid trying to cancel same thing multiple times Co-authored-by: Peter van der Zee <[email protected]>
1 parent 6287c73 commit b88f193

File tree

6 files changed

+202
-4
lines changed

6 files changed

+202
-4
lines changed
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,182 @@
1+
import { ActionsUnion } from "./types"
2+
import { ActivityStatuses } from "../constants"
3+
import { calcElapsedTime } from "../../util/calc-elapsed-time"
4+
import { isActivityInProgress } from "./utils"
5+
import type { Reporter } from "../reporter"
6+
import type { GatsbyCLIStore } from "./"
7+
8+
function calculateTimeoutDelay(
9+
envVarValue: string | undefined,
10+
defaultValue: number,
11+
min: number
12+
): number {
13+
if (!envVarValue) {
14+
return 0
15+
} else if (envVarValue === `1`) {
16+
// Toggling env vars with "1" is quite common - because we allow to set
17+
// specific timeout values with env var, this special case is added
18+
// (1ms timeout makes little sense - that's too low value to be used as-is)
19+
return defaultValue
20+
}
21+
22+
const parsedToNumber = parseInt(envVarValue, 10)
23+
if (isNaN(parsedToNumber)) {
24+
// It's truthy, but not a number - let's enable it with default value
25+
return defaultValue
26+
}
27+
28+
// Allow to custom specific timeout value, but also put some minimal
29+
// timeout bound as there is little usefulness of setting it to
30+
// something less than few seconds.
31+
return Math.max(parsedToNumber, min)
32+
}
33+
34+
type DiagnosticsMiddleware = (action: ActionsUnion) => void
35+
36+
const FIVE_MINUTES = 1000 * 60 * 5
37+
const FIVE_SECONDS = 1000 * 5
38+
const TEN_MINUTES = 1000 * 60 * 10
39+
const TEN_SECONDS = 1000 * 10
40+
41+
export function createStructuredLoggingDiagnosticsMiddleware(
42+
store: GatsbyCLIStore
43+
): DiagnosticsMiddleware {
44+
const stuckStatusDiagnosticTimeoutDelay = calculateTimeoutDelay(
45+
process.env.GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT,
46+
FIVE_MINUTES, // default timeout
47+
FIVE_SECONDS // minimal timeout (this is mostly useful for debugging diagnostic code itself)
48+
)
49+
50+
const stuckStatusWatchdogTimeoutDelay = calculateTimeoutDelay(
51+
process.env.GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT,
52+
TEN_MINUTES, // default timeout
53+
TEN_SECONDS // minimal timeout (this is mostly useful for debugging diagnostic code itself)
54+
)
55+
56+
if (!stuckStatusDiagnosticTimeoutDelay && !stuckStatusWatchdogTimeoutDelay) {
57+
// none of timers are enabled, so this is no-op middleware
58+
return (): void => {}
59+
}
60+
61+
let displayedStuckStatusDiagnosticWarning = false
62+
let displayingStuckStatusDiagnosticWarning = false
63+
let stuckStatusDiagnosticTimer: NodeJS.Timeout | null = null
64+
let stuckStatusWatchdogTimer: NodeJS.Timeout | null = null
65+
let reporter: Reporter
66+
67+
function generateStuckStatusDiagnosticMessage(): string {
68+
const { activities } = store.getState().logs
69+
70+
return JSON.stringify(
71+
Object.values(activities)
72+
.filter(activity => isActivityInProgress(activity.status))
73+
.map(activity => {
74+
if (!activity.startTime) {
75+
return activity
76+
}
77+
78+
return {
79+
...activity,
80+
diagnostics_elapsed_seconds: calcElapsedTime(activity.startTime),
81+
}
82+
}),
83+
null,
84+
2
85+
)
86+
}
87+
88+
return function diagnosticMiddleware(action: ActionsUnion): void {
89+
// ignore diagnostic logs, otherwise diagnostic message itself will reset
90+
// the timers
91+
if (!displayingStuckStatusDiagnosticWarning) {
92+
const currentStatus = store.getState().logs.status
93+
94+
if (!reporter) {
95+
// yuck, we have situation of circular dependencies here
96+
// so this `reporter` import is delayed until it's actually needed
97+
reporter = require(`../reporter`).reporter
98+
}
99+
100+
if (stuckStatusDiagnosticTimeoutDelay) {
101+
if (stuckStatusDiagnosticTimer) {
102+
clearTimeout(stuckStatusDiagnosticTimer)
103+
stuckStatusDiagnosticTimer = null
104+
}
105+
106+
if (displayedStuckStatusDiagnosticWarning) {
107+
// using nextTick here to prevent infinite recursion (report.warn would
108+
// result in another call of this function and so on)
109+
process.nextTick(() => {
110+
const activitiesDiagnosticsMessage = generateStuckStatusDiagnosticMessage()
111+
reporter.warn(
112+
`This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):\n\nThere was activity since last diagnostic message. Log action:\n\n${JSON.stringify(
113+
action,
114+
null,
115+
2
116+
)}\n\nCurrently Gatsby is in: "${
117+
store.getState().logs.status
118+
}" state.${
119+
activitiesDiagnosticsMessage.length > 0
120+
? `\n\nActivities preventing Gatsby from transitioning to idle state:\n\n${activitiesDiagnosticsMessage}`
121+
: ``
122+
}`
123+
)
124+
})
125+
displayedStuckStatusDiagnosticWarning = false
126+
}
127+
128+
if (currentStatus === ActivityStatuses.InProgress) {
129+
stuckStatusDiagnosticTimer = setTimeout(
130+
function logStuckStatusDiagnostic() {
131+
displayingStuckStatusDiagnosticWarning = true
132+
reporter.warn(
133+
`This is just diagnostic information (enabled by GATSBY_DIAGNOSTIC_STUCK_STATUS_TIMEOUT):\n\nGatsby is in "${
134+
store.getState().logs.status
135+
}" state without any updates for ${(
136+
stuckStatusDiagnosticTimeoutDelay / 1000
137+
).toFixed(
138+
3
139+
)} seconds. Activities preventing Gatsby from transitioning to idle state:\n\n${generateStuckStatusDiagnosticMessage()}${
140+
stuckStatusWatchdogTimeoutDelay
141+
? `\n\nProcess will be terminated in ${(
142+
(stuckStatusWatchdogTimeoutDelay -
143+
stuckStatusDiagnosticTimeoutDelay) /
144+
1000
145+
).toFixed(3)} seconds if nothing will change.`
146+
: ``
147+
}`
148+
)
149+
displayingStuckStatusDiagnosticWarning = false
150+
displayedStuckStatusDiagnosticWarning = true
151+
},
152+
stuckStatusDiagnosticTimeoutDelay
153+
)
154+
}
155+
}
156+
157+
if (stuckStatusWatchdogTimeoutDelay) {
158+
if (stuckStatusWatchdogTimer) {
159+
clearTimeout(stuckStatusWatchdogTimer)
160+
stuckStatusWatchdogTimer = null
161+
}
162+
163+
if (currentStatus === ActivityStatuses.InProgress) {
164+
stuckStatusWatchdogTimer = setTimeout(
165+
function fatalStuckStatusHandler() {
166+
reporter.panic(
167+
`Terminating the process (due to GATSBY_WATCHDOG_STUCK_STATUS_TIMEOUT):\n\nGatsby is in "${
168+
store.getState().logs.status
169+
}" state without any updates for ${(
170+
stuckStatusWatchdogTimeoutDelay / 1000
171+
).toFixed(
172+
3
173+
)} seconds. Activities preventing Gatsby from transitioning to idle state:\n\n${generateStuckStatusDiagnosticMessage()}`
174+
)
175+
},
176+
stuckStatusWatchdogTimeoutDelay
177+
)
178+
}
179+
}
180+
}
181+
}
182+
}

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

+7
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import { createStore, combineReducers } from "redux"
22
import { reducer } from "./reducer"
33
import { ActionsUnion, ISetLogs } from "./types"
44
import { isInternalAction } from "./utils"
5+
import { createStructuredLoggingDiagnosticsMiddleware } from "./diagnostics"
56
import { Actions } from "../constants"
67

78
let store = createStore(
@@ -11,6 +12,10 @@ let store = createStore(
1112
{}
1213
)
1314

15+
const diagnosticsMiddleware = createStructuredLoggingDiagnosticsMiddleware(
16+
store
17+
)
18+
1419
export type GatsbyCLIStore = typeof store
1520
type StoreListener = (store: GatsbyCLIStore) => void
1621
type ActionLogListener = (action: ActionsUnion) => any
@@ -46,6 +51,8 @@ export const dispatch = (action: ActionsUnion | Thunk): void => {
4651

4752
store.dispatch(action)
4853

54+
diagnosticsMiddleware(action)
55+
4956
if (isInternalAction(action)) {
5057
// consumers (ipc, yurnalist, json logger) shouldn't have to
5158
// deal with actions needed just for internal tracking of status

packages/gatsby-cli/src/reporter/redux/internal-actions.ts

+1
Original file line numberDiff line numberDiff line change
@@ -160,6 +160,7 @@ export const createPendingActivity = ({
160160
payload: {
161161
id,
162162
type: ActivityTypes.Pending,
163+
startTime: process.hrtime(),
163164
status,
164165
},
165166
},

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

+1
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,7 @@ export const reducer = (
5151
...state.activities,
5252
[id]: {
5353
...activity,
54+
id,
5455
...rest,
5556
},
5657
},

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

+1
Original file line numberDiff line numberDiff line change
@@ -70,6 +70,7 @@ export interface IPendingActivity {
7070
id: string
7171
type: ActivityTypes
7272
status: ActivityStatuses
73+
startTime?: [number, number]
7374
}
7475
}
7576

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

+10-4
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,15 @@ import { Actions, ActivityTypes, ActivityStatuses } from "../constants"
44
import { ActionsUnion, IActivity } from "./types"
55
import signalExit from "signal-exit"
66

7+
export function isActivityInProgress(
8+
activityStatus: ActivityStatuses
9+
): boolean {
10+
return (
11+
activityStatus === ActivityStatuses.InProgress ||
12+
activityStatus === ActivityStatuses.NotStarted
13+
)
14+
}
15+
716
export const getGlobalStatus = (
817
id: string,
918
status: ActivityStatuses
@@ -20,10 +29,7 @@ export const getGlobalStatus = (
2029
const activityStatus =
2130
activityId === id ? status : logs.activities[activityId].status
2231

23-
if (
24-
activityStatus === ActivityStatuses.InProgress ||
25-
activityStatus === ActivityStatuses.NotStarted
26-
) {
32+
if (isActivityInProgress(activityStatus)) {
2733
return ActivityStatuses.InProgress
2834
} else if (
2935
activityStatus === ActivityStatuses.Failed &&

0 commit comments

Comments
 (0)