Gatsby: [feat]: improve logging by introducing structured logging

Created on 15 Jan 2019 · 13Comments · Source: gatsbyjs/gatsby

I am restructuring this issue after my pair session with @DSchau to cover the
broader problems facing (discussed while trying to fix this one)
with logging in Gatsby.

To solve the flickering issue it will require either an ugly hack
or more structural changes.

Current problems with logging:

non standard way to log in gatsby core and in packages. Plugin authors
are using a mixture of console.warn, console.info, console.log, the
reporter from gatsby-cli (more on this later), progress bars and possibly other
methods.
no way format log output depending on the platform running gatsby build.
Right now if the build is running on a CI it doesn't support color handling then
the logs are full of coloring codes. In addition logs disappear depending on
the stage of the build.
the reporter being in the gatsby-cli makes it hard for plugin authors and the
core plugins to use it. It is passed along on most the gatsby node API but then
it is up to the user to pass it along to more internal APIs such as the sharp
transformer or the createRemoteFileNode which makes the use of the reporter
in those cases non possible (besides importing in an ugly fashion the file)
there is no way for plugin authors to set a level of logging such as
INFO, ERROR to limit or make more verbose their logs
while errors are outputted on stdout it could be interesting to log errors in
a separate file (like yarn-error) that end users could be attach to issues when
describing failures, rather than searching for the interesting parts in stdout,
scrolling and c/p the logs around.
concurrent logs as shown in the image are causing issues

Quoting Kyle

blinks back and forth with the the updates from the "source and transform nodes" log line — we need to add a way to core to display multiple things at once and clean up stuff like this.

example

Source

oorestisime

Most helpful comment

I prototyped a version (in raw code, not inside Gatsby) of how this could work:

gatsby-cli-prototype

Code is:

import React from "react"
import { render, Static, Box, Color, Text } from "ink"
import BigText from "ink-big-text"
import BBox from "ink-box"
import TextInput from "ink-text-input"
import Spinner from "ink-spinner"
import { Tabs, Tab } from "ink-tab"
import _ from "lodash"

const activityList = [
  [`open and validate gatsby-configs`, `0.006 s`],
  [`load plugins`, `0.240 s`],
  [`onPreInit`, `0.991 s`],
  [`delete html and css files from previous builds`, `0.048 s`],
  [`initialize cache`, `0.014 s`],
  [`copy gatsby files`, `0.092 s`],
  [`onPreBootstrap`, `0.004 s`],
  [`source and transform nodes`, `0.060 s`],
  [`building schema`, `0.277 s`],
  [`createPages`, `0.042 s`],
  [`createPagesStatefully`, `0.030 s`],
  [`onPreExtractQueries`, `0.004 s`],
  [`update schema`, `0.133 s`],
  [`extract queries from components`, `0.077 s`],
  [`run graphql queries`, `0.074 s — 10/10 137.62 queries/second`],
  [`write out page data`, `0.002 s`],
  [`write out redirect data`, `0.000 s`],
]

const purple = [102, 51, 153]
const hexPurple = `#663399`

const GText = props => <Color rgb={purple} {...props} />

const useProgressBar = duration => {
  const [percent, setPercent] = React.useState(0)

  let timer
  React.useEffect(() => {
    if (percent === 100) {
      clearInterval(timer)
    } else {
      timer = setInterval(() => setPercent(percent + 1), duration / 100)
    }
    return () => clearInterval(timer)
  })

  return percent
}

const Activity = props => (
  <Text>
    <Color green>success</Color> {props.activity.name} —{` `}
    {props.activity.duration}
  </Text>
)

const useActivities = () => {
  const makeActivity = id => {
    if (activityList[id]) {
      return {
        state: `active`,
        id,
        name: activityList[id][0],
        duration: activityList[id][1],
      }
    }
  }

  // Generate activities
  const [activities, setActivities] = React.useState([makeActivity(0)])
  const [stage, setStage] = React.useState(`initial`)
  const [bootstrapFinished, setBootstrapFinished] = React.useState(false)

  React.useEffect(() => {
    if (activities.length <= activityList.length) {
      setTimeout(() => {
        const madeInactive = activities.map(a => {
          return {
            ...a,
            state: `inactive`,
          }
        })
        setStage(`inside  timeout ${JSON.stringify(activities)}`)
        if (activities.length < activityList.length) {
          setActivities(madeInactive.concat(makeActivity(activities.length)))
        } else {
          const madeInactive = activities.map(a => {
            return {
              ...a,
              state: `inactive`,
            }
          })
          setActivities(madeInactive)
          setBootstrapFinished(true)
        }
      }, Math.random() * 666)
    }
  }, [activities])

  // console.log(activities)
  return [
    activities.filter(a => a.state === `active`),
    activities.filter(a => a.state === `inactive`),
    stage,
    bootstrapFinished,
  ]
}

const ProgressBar = ({ duration, label, total }) => {
  const percent = useProgressBar(duration)
  return (
    <Box>
      [
      {_.range(0, Math.floor(percent / 3)).map(id => (
        <Text key={`equals ${id}`}>=</Text>
      ))}
      {_.range(0, 33 - Math.floor(percent / 3)).map(id => (
        <Text key={`space ${id}`}> </Text>
      ))}
      ] {Math.round((percent * total) / 100)} / {total} {percent}% {label}
    </Box>
  )
}

const Demo = () => {
  const [active, inactive, stage, bootstrapFinished] = useActivities()
  return (
    <Box flexDirection="column">
      <Static>
        <BigText
          font={`chrome`}
          space={true}
          colors={[`magenta`, `green`, `magenta`]}
          text="Booting Gatsby dev server"
        />
        {inactive.map(activity => (
          <Activity key={activity.id} activity={activity} />
        ))}
      </Static>
      {active.map(a => (
        <Box key={a.id}>
          <Box paddingLeft={2} paddingRight={2}>
            <Spinner green type={`dots12`} />
          </Box>
          <Box paddingLeft={2}>{a.name}</Box>
        </Box>
      ))}
      <Text> </Text>
      <ProgressBar label="Downloading Files" duration={5000} total={83} />
      <ProgressBar
        label="Processing Image Thumbnails"
        duration={4000}
        total={584}
      />
      <Text> </Text>
      <Color red bold>
        1 warning and 0 errors
      </Color>
      <Text>---</Text>
      <Text> </Text>
      <Text>
        <Color bold red>
          Warning:
        </Color>
        <Color>
          The GraphQL component in path "/what/about/me.js" was not able to be
          extracted
        </Color>
      </Text>
    </Box>
  )
}

render(<Demo />)

KyleAMathews on 26 Mar 2019

❤6 🚀4

All 13 comments

Perhaps, coming back to #4803, using https://github.com/nuxt/webpackbar is a good option?

jbolda on 15 Jan 2019

👍3

Perhaps, coming back to #4803, using https://github.com/nuxt/webpackbar is a good option?

We had a look at this over the pairing session. While it could improve a bit current state of things it wouldn't solve the general issues with logging (updated issue w.r.t those) and it would require some hacks to do it. I will rather try and focus my time on the global issue.

oorestisime on 13 Feb 2019

These aren't webpack logs, they're our own logs. So we need to put in a better framework for handling things.

KyleAMathews on 13 Feb 2019

Perhaps Ink then?

jbolda on 14 Feb 2019

Perhaps Ink then?

I was checking out ink and while using it is pretty enjoyable (using familiar React to build console output) and it does solve issue of progress bar fighting with yurnalist (if logs, activities and progressbar is rendered using ink), but it has some problems:

Once output exceed available height in console, the rerenders are causing some jumps and also if you scroll up, same logs are repeated.

Additional issue there is with using reporter.panic(onBuild) - we immediately exit process, but it means that actual error is not getting rendered. Even with delay process exit this is unreliable.

pieh on 24 Feb 2019

I opened an RFC for tackling further work on this: https://github.com/gatsbyjs/rfcs/pull/31

m-allanson on 26 Feb 2019

Update on Ink:
Recently released version 2 of Ink did a lot of nice stuff. Including adding <Static> component that solves (or rather works around) this:

Once output exceed available height in console, the rerenders are causing some jumps and also if you scroll up, same logs are repeated.

Some details about this are captured in https://github.com/facebook/jest/issues/7900#issuecomment-463924239

I have very hacky branch that uses Ink (but it's previous version, not v2): https://github.com/gatsbyjs/gatsby/commit/e3e739a74d9235bf3ee3210a18b6523460d81db1

Ink needs to be updated to v2 (as previous Ink version was just not compatible with usual babel react preset / jsx). V2 also changed rendering a bit - and <Box> component need to be used to avoid creating extra new lines
reporter.panic is still problematic

pieh on 7 Mar 2019

@wardpeet has been working on implementing this into gatsby-cli (the reporter currently).

Our current approach is to just get things working in a backwards compatible way. Soon enough, we'd like to actually add some additional features (e.g. a "block" that persists with progress indicators, a block for errors, etc.) and introduce some more structure into the CLI.

We're planning to go forward with react-ink. Some things that would be nice to think about (but don't _necessarily_ need to be solved with this PR) would be:

If we have an errors block, how do we recover from an error
- @KyleAMathews's recent work on XState could be helpful here
Should logging live in some consistent place (e.g. Redux, XState, etc.)
- This would let us solve the structured part of this quite well
- The RFC opened up here proposes Redux store, which is totally reasonable!
We'll need a way to tweak behavior in a CI environment (and other environments, e.g. Gatsby Preview)

DSchau on 25 Mar 2019

I prototyped a version (in raw code, not inside Gatsby) of how this could work:

gatsby-cli-prototype

Code is:

import React from "react"
import { render, Static, Box, Color, Text } from "ink"
import BigText from "ink-big-text"
import BBox from "ink-box"
import TextInput from "ink-text-input"
import Spinner from "ink-spinner"
import { Tabs, Tab } from "ink-tab"
import _ from "lodash"

const activityList = [
  [`open and validate gatsby-configs`, `0.006 s`],
  [`load plugins`, `0.240 s`],
  [`onPreInit`, `0.991 s`],
  [`delete html and css files from previous builds`, `0.048 s`],
  [`initialize cache`, `0.014 s`],
  [`copy gatsby files`, `0.092 s`],
  [`onPreBootstrap`, `0.004 s`],
  [`source and transform nodes`, `0.060 s`],
  [`building schema`, `0.277 s`],
  [`createPages`, `0.042 s`],
  [`createPagesStatefully`, `0.030 s`],
  [`onPreExtractQueries`, `0.004 s`],
  [`update schema`, `0.133 s`],
  [`extract queries from components`, `0.077 s`],
  [`run graphql queries`, `0.074 s — 10/10 137.62 queries/second`],
  [`write out page data`, `0.002 s`],
  [`write out redirect data`, `0.000 s`],
]

const purple = [102, 51, 153]
const hexPurple = `#663399`

const GText = props => <Color rgb={purple} {...props} />

const useProgressBar = duration => {
  const [percent, setPercent] = React.useState(0)

  let timer
  React.useEffect(() => {
    if (percent === 100) {
      clearInterval(timer)
    } else {
      timer = setInterval(() => setPercent(percent + 1), duration / 100)
    }
    return () => clearInterval(timer)
  })

  return percent
}

const Activity = props => (
  <Text>
    <Color green>success</Color> {props.activity.name} —{` `}
    {props.activity.duration}
  </Text>
)

const useActivities = () => {
  const makeActivity = id => {
    if (activityList[id]) {
      return {
        state: `active`,
        id,
        name: activityList[id][0],
        duration: activityList[id][1],
      }
    }
  }

  // Generate activities
  const [activities, setActivities] = React.useState([makeActivity(0)])
  const [stage, setStage] = React.useState(`initial`)
  const [bootstrapFinished, setBootstrapFinished] = React.useState(false)

  React.useEffect(() => {
    if (activities.length <= activityList.length) {
      setTimeout(() => {
        const madeInactive = activities.map(a => {
          return {
            ...a,
            state: `inactive`,
          }
        })
        setStage(`inside  timeout ${JSON.stringify(activities)}`)
        if (activities.length < activityList.length) {
          setActivities(madeInactive.concat(makeActivity(activities.length)))
        } else {
          const madeInactive = activities.map(a => {
            return {
              ...a,
              state: `inactive`,
            }
          })
          setActivities(madeInactive)
          setBootstrapFinished(true)
        }
      }, Math.random() * 666)
    }
  }, [activities])

  // console.log(activities)
  return [
    activities.filter(a => a.state === `active`),
    activities.filter(a => a.state === `inactive`),
    stage,
    bootstrapFinished,
  ]
}

const ProgressBar = ({ duration, label, total }) => {
  const percent = useProgressBar(duration)
  return (
    <Box>
      [
      {_.range(0, Math.floor(percent / 3)).map(id => (
        <Text key={`equals ${id}`}>=</Text>
      ))}
      {_.range(0, 33 - Math.floor(percent / 3)).map(id => (
        <Text key={`space ${id}`}> </Text>
      ))}
      ] {Math.round((percent * total) / 100)} / {total} {percent}% {label}
    </Box>
  )
}

const Demo = () => {
  const [active, inactive, stage, bootstrapFinished] = useActivities()
  return (
    <Box flexDirection="column">
      <Static>
        <BigText
          font={`chrome`}
          space={true}
          colors={[`magenta`, `green`, `magenta`]}
          text="Booting Gatsby dev server"
        />
        {inactive.map(activity => (
          <Activity key={activity.id} activity={activity} />
        ))}
      </Static>
      {active.map(a => (
        <Box key={a.id}>
          <Box paddingLeft={2} paddingRight={2}>
            <Spinner green type={`dots12`} />
          </Box>
          <Box paddingLeft={2}>{a.name}</Box>
        </Box>
      ))}
      <Text> </Text>
      <ProgressBar label="Downloading Files" duration={5000} total={83} />
      <ProgressBar
        label="Processing Image Thumbnails"
        duration={4000}
        total={584}
      />
      <Text> </Text>
      <Color red bold>
        1 warning and 0 errors
      </Color>
      <Text>---</Text>
      <Text> </Text>
      <Text>
        <Color bold red>
          Warning:
        </Color>
        <Color>
          The GraphQL component in path "/what/about/me.js" was not able to be
          extracted
        </Color>
      </Text>
    </Box>
  )
}

render(<Demo />)

KyleAMathews on 26 Mar 2019

❤6 🚀4

Hiya!

This issue has gone quiet. Spooky quiet. 👻

We get a lot of issues, so we currently close issues after 30 days of inactivity. It’s been at least 20 days since the last update here.

If we missed this issue or if you want to keep it open, please reply here. You can also add the label "not stale" to keep this issue open!

Thanks for being a part of the Gatsby community! 💪💜

gatsbot[bot] on 16 Apr 2019

👎2

This issue may have been closed by accidentally, since the PR says that it only partially fixes this issue.

cameron-martin on 21 May 2019

👍3

Thanks @cameron-martin 👍

m-allanson on 21 May 2019

So given #14973 was closed last week, I'd say this issue is resolved if I am not mistaken as the groundwork for structured logging is in as of Gatsby 2.16.0.

That said, it isn't clearly documented, but that is being tracked here: #16591 so I am going to close this issue.