[feat]: improve logging by introducing structured logging

[oorestisime]

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.

[jbolda]

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

[oorestisime]

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.

[KyleAMathews]

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

[jbolda]

Perhaps Ink then?

[pieh]

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.

[m-allanson]

I opened an RFC for tackling further work on this: gatsbyjs/rfcs#31

[pieh]

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 jestjs/jest#7900 (comment)

I have very hacky branch that uses Ink (but it's previous version, not v2): e3e739a

• 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

[DSchau]

@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)

[KyleAMathews]

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

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 />)

[gatsbot]

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! 💪💜

[cameron-martin]

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

[m-allanson]

Thanks @cameron-martin 👍

[lannonbr]

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.