Hubot Brain not loading?

[johnseekins-pathccm]

I'm working on adding cron jobs to our installation of Hubot. I found this plugin and decaffeinated it. So far, so good, right? Well...I did run in to some issues with the plugin as it was initially implemented, so I ended up re-writing some parts of it. But you know what? It still works! And most of my changes were removing complexity, so it's actually a bit easier to read! Neat!

Here's the issue: I can't get the plugin to load data written to a Redis brain at start up. I've tried robot.brain.on('running', robot.on('running', and robot.brain.on('loaded'. In every case, the plugin fails to load crons from the brain.

What's interesting is that crons are successfully written to the brain, so I know there should be data loaded.

Example of brain data:

"{\"users\":{\"1\":{\"id\":\"1\",\"name\":\"Shell\",\"room\":\"Shell\"}},\"_private\":{\"cronjobs\":{\"833575\":[\"30 9 * * *\",{\"id\":\"1\",\"name\":\"Shell\",\"room\":\"Shell\"},\"@hubot-dev ecs list clusters\",\"America/Chicago\",false]}}}"

actual code

"use strict"
// Description:
//   register cron jobs to schedule commands on the current channel
//
// Commands:
//   hubot cron new job "<crontab format>" <message> - Schedule a cron job to execute another hubot command
//   hubot cron new job "<crontab format>" tz=<timezone> <message> - Schedule a cron job to execute another hubot command with cron executing in $timestamp, (default 'America/Chicago', full list: https://en.wikipedia.org/wiki/List_of_tz_database_time_zones)
//   hubot cron list jobs - List current cron jobs running in the current channel
//   hubot cron list all jobs - List current cron jobs running in all channels
//   hubot cron remove job <id> - remove job
//   hubot cron timezone job <id> - Set the timezone of an existing cron job
//   hubot cron silence job <id> - Once you have verified that a job works correctly, stop posting the "attempting to execute" message
//   hubot cron verbose job <id> - un-silence a job for debugging or clarity
//
// Author:
//   <>
//   Originally based on:
//   Jack Ellenberger <[email protected]> based on work by miyagawa
    
import { CronJob } from "cron"
import { TextMessage, Response } from "hubot"
    
let JOBS = {}
const defaultTZ = "America/Chicago"
const datastoreKey = 'cronjobs'

export default async robot => {
  robot.brain.on('running', robot => {
    loadJobs(robot)
  })
  
  robot.respond(
    /cron (?:new|add) job (?:'|"|“)(.*?)(?:'|"|”) (?:(?:tz=|timezone=)([_/A-z]*))? ?(.*)$/i,
    async context => {
      let id = Math.floor(Math.random() * 1000000)
      let pattern = context.match[1]
      let message = context.match[3]
      let timezone = context.match[2] || defaultTZ
      robot.logger.debug(`Defining ${id} as ${pattern} -> ${message} (${timezone}) for ${context.message.user.name}`)
      JOBS[id] = startJob(robot, id, pattern, context.message.user, message, timezone, false)
      await syncJobs(robot)
      await context.send(`Job ${id} created`)
    }
  )
  
  robot.respond(/cron (?:list|ls) jobs?/i, async context => {
    let text = `Jobs in ${context.message.user.room}:`
    let count = 0
    for (let id in JOBS) {
      const job = JOBS[id]
      const room = job.user.reply_to || job.user.room
      if (
        room === context.message.user.reply_to ||
        room === context.message.user.room
      ) {
        text += `\n\t\`${id}\`: ${job.pattern} "${job.message}" (${job.timezeone})`
        count++
      } else {
        robot.logger.debug(`${job} isn't in ${room}`)
      }
    }
    if (count > 0) {
      await context.send(text)
    } else {
      await context.send("No jobs defined in this channel.")
    }
  })

  robot.respond(/cron (?:list|ls) all jobs?/i, async context => {
    let text = "Jobs in all rooms:"
    let count = 0
    for (var id in JOBS) {
      var job = JOBS[id]
      var room = job.user.reply_to || job.user.room
      text += `\n\t\`${id}\`: ${job.pattern} @${room} "${job.message}" (${job.timezone})`
      count++
    }
    if (count > 0) {
      await context.send(text)
    } else {
      await context.send("No jobs found in any channel.")
    }
  })

  robot.respond(/cron (?:rm|remove|del|delete) job (\d+)/i, async context => {
    let id = context.match[1]
    if (JOBS[id]) {
      JOBS[id].stop()
      delete JOBS[id]
      await syncJobs(robot)
      await context.send(`Job ${id} deleted`)
    } else {
      await context.send(`Job ${id} does not exist`)
    }
  })

  robot.respond(/cron (?:tz|timezone) job (\d+) (.*)/i, async context => {
    let id = context.match[1]
    let timezone = context.match[2]
    if (JOBS[id]) {
      JOBS[id].stop()
      JOBS[id].timezone = timezone
      JOBS[id].start(robot)
      await syncJobs(robot)
      await context.send(`Job ${id} updated to use ${timezone}`)
    } else {
      await context.send(`Job ${id} does not exist`)
    }
  })

  robot.respond(/cron silence job (\d+)/i, async context => {
    let id = context.match[1]
    if (JOBS[id]) {
      JOBS[id].silent = true
      await syncJobs(robot)
      await context.send(`Job ${id} silenced`)
    } else {
      await context.send(`Job ${id} could not be silenced`)
    }
  })

  robot.respond(/cron verbose job (\d+)/i, async context => {
    let id = context.match[1]
    if (JOBS[id]) {
      JOBS[id].silent = false
      await syncJobs(robot)
      await context.send(`Job ${id} unsilenced`)
    } else {
      await context.send(`Job ${id} could not be unsilenced`)
    }
  })
}

class Job {
  constructor(id, pattern, user, message, timezone, silent) {
    this.id = id
    this.pattern = pattern
    // cloning user because adapter may touch it later
    const clonedUser = {}
    for (var k in user) {
      var v = user[k]
      clonedUser[k] = v
    }
    this.user = clonedUser
    this.message = message
    this.timezone = timezone
    this.silent = silent
  }

  start(robot) {
    this.cronjob = new CronJob(
      this.pattern,
      () => {
        return this.executeCommand(robot)
      },
      null,
      false,
      this.timezone,
      this.silent,
    )
    robot.logger.debug(`Starting ${this.id}: ${this.message} (${this.timezone}) in ${this.user.room}`)
    return this.cronjob.start()
  }

  stop() {
    return this.cronjob.stop()
  }

  serialize() {
    return [this.pattern, this.user, this.message, this.timezone, this.silent]
  }

  executeCommand(robot) {
    const { message } = this
    const { user } = this
    const envelope = { user: this.user, room: this.user.room }
    if (!this.silent) {
      robot.send(
        envelope,
        `Attempting to execute job ${this.id}, crontab \`${this.pattern} ${this.message}\``,
      )
    }
    return robot.listeners.forEach(function (listener) {
      let match
      if ((match = message.match(listener.regex))) {
        const textMessage = new TextMessage(user, message)
        const newcontext = new Response(robot, textMessage, match)
        return listener.callback(newcontext)
      }
    })
  }
}

function startJob (robot, id, pattern, user, message, timezone, silent) {
  robot.logger.debug(`Defining ${id} as ${pattern} -> ${message} (${timezone}) for ${user.name}`)
  try {
    const job = new Job(id, pattern, user, message, timezone, silent)
    job.start(robot)
    return job
  } catch (error) {
    context.send(
      `Error caught parsing crontab pattern: ${error}. See http://crontab.org/ for the syntax`,
    )
    return {}
  }
}

function serializeJobs () {
  /*
   * flatten the Job representation so it stores in the brain well
   */
  let jobsString = {}
  for (let idx in JOBS) {
    jobsString[idx] = JOBS[idx].serialize()
  }
  return jobsString
}

async function syncJobs (robot) {
  /*
   * Syncing job lists from memory to actual brain
   * Since we only ever write to the datastore after startup,
   * this should be a simple command
   */
  const jobsString = serializeJobs()
  robot.logger.debug(`Writing ${JSON.stringify(jobsString)} to datastore`)
  robot.brain.set(datastoreKey, jobsString)
  await robot.brain.save()
}

function loadJobs (robot) {
  let jobStrings = robot._private[datastoreKey] || {}
  robot.logger.debug(`Loaded cron jobs from brain: ${jobStrings}`)
  jobStrings = robot.brain.get(datastoreKey) || {}
  robot.logger.debug(`Tried loading cron jobs from brain: ${jobStrings}`)
  for (let key in jobStrings) {
    JOBS[key] = startJob(robot, key, ...Array.from(jobStrings[key]))
  }
  robot.logger.info(`Loaded ${jobStrings.length} jobs from brain...`)
}

(also, sorry for using this repo as a tech support channel, but I'm not really sure where else to ask Hubot questions like this...)

[joeyguerra]

Brain doesn't emit an event called running, Robot does. I believe the design is "listen to the loaded event on Brain".

Here's one of the places where Brain emits the loaded event.

Try changing

  robot.brain.on('running', robot => {
    loadJobs(robot)
  })

to

  robot.brain.on('loaded', data => {
    loadJobs(robot)
  })

[johnseekins-pathccm]

I did actually try that with no success. But I'll show the output from that:

$ grep brain src/scripts/cron.mjs 
  robot.brain.on('loaded', robot => {
   * flatten the Job representation so it stores in the brain well
   * Syncing job lists from memory to actual brain
  robot.brain.set(datastoreKey, jobsString)

{"level":30,"time":1709569783292,"pid":19679,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Using default redis on localhost:6379"}
{"level":20,"time":1709569783297,"pid":19679,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"Parsing help for /Users/johnseekins/gitroot/hubot/node_modules/hubot-redis-brain/src/RedisBrain.mjs"}
{"level":20,"time":1709569783299,"pid":19679,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Successfully connected to Redis"}
{"level":30,"time":1709569783312,"pid":19679,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Data for hubot brain retrieved from Redis"}
{"level":50,"time":1709569783312,"pid":19679,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Unable to get data from Redis: TypeError: Cannot read properties of undefined (reading 'debug')"}

^ This last line is failing on robot.logger.debug(`Loaded cron jobs from brain: ${jobStrings}`). Implying the logger object within robot isn't loaded yet? Which seems impossible?

[johnseekins-pathccm]

{"level":50,"time":1709570131239,"pid":20434,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Unable to get data from Redis: TypeError: Cannot read properties of undefined (reading 'info')"}

[johnseekins-pathccm]

I'd also note that robot.logger.info(`Loaded ${jobStrings.length} jobs from brain...`) never shows up in the logs (which is probably because of the earlier error...

Okay. Removing those debug logs, I get this error:

{"level":50,"time":1709570285145,"pid":20854,"hostname":"John-Seekins-MacBook-Pro-16-inch-2023-","name":"hubot-dev","msg":"hubot-redis-brain: Unable to get data from Redis: TypeError: Cannot read properties of undefined (reading 'get')"}

Which to me says the brain object within robot is also empty? Seems like this command is passing the robot object poorly?

[joeyguerra]

I haven't pin pointed the problem, but I have some bug fixes for the script posted above. Can you make these modifications and then see what's happening?

from (the signature for the Brain loaded event passes the data, not the robot.:

    robot.brain.on('loaded', robot => {
      robot.logger.info(`Loading cron jobs from brain: ${robot.brain.get(datastoreKey)}`)
      loadJobs(robot)
  })

to:

    robot.brain.on('loaded', data => {
      robot.logger.info(`Loading cron jobs from brain: ${robot.brain.get(datastoreKey)}`)
      loadJobs(robot)
  })

and in loadJobs

from:

  let jobStrings = robot._private[datastoreKey] || {}

to:

  let jobStrings = robot.brain.get(datastoreKey) || {}

[johnseekins-pathccm]

The answer!

We don't need a function for this step:

  robot.brain.on('loaded', data => {
    const jobStrings = robot.brain.get(datastoreKey) || {}
    robot.logger.debug(`Loaded jobs from brain: ${JSON.stringify(jobStrings)}`)
    let count = 0
    for (let key in jobStrings) {
      JOBS[key] = startJob(robot, key, ...Array.from(jobStrings[key]))
      robot.logger.debug(`Starting ${jobStrings[key]}`)
      count++
    }
    robot.logger.info(`Loaded ${count} jobs from brain...`)
  })

Now I'm actually successfully loading messages!

Thanks for the help @joeyguerra

[joeyguerra]

Glad you got it working as desired.