search

slackapi / hubot-slack

Slack Developer Kit for Hubot
https://slack.dev/hubot-slack/
MIT License
2.3k stars 637 forks source link

Multiple instances of hubot-slack responding to messages #382

Closed jivany closed 2 years ago

jivany commented 7 years ago

Description

I what appears to be a random occurrence, hubot on Slack will start sending multiple responses. Sometimes it is only duplicate responses but worst case seen has resulted in >20 responses generated when a single was expected. The amount of time before this starts happening is variable - sometimes only a few minutes, other times many days.

Similar to #153 but this happens on an already running process with no indications in the logs of re-connections occurring and there is only one node process (hubot) running on the openshift gear.

Is there any way to ensure there is only one RTM connection established?

Reproducible in:

{project_name} version: 4.2.2 OS version(s): openshift.com Device(s):

Steps to reproduce:

  1. Restart hubot-slack process
  2. Wait random amount of time (sometimes minutes, other times days)
  3. Hubot will start sending multiple responses potentially flooding Slack channel/user until it is restarted

Expected result:

Expect hubot to only reply once.

Actual result:

Sometimes get duplicate responses until hubot is restarted. Worst case so far appears to be >20 responses when only a single response is expected.

Attachments:

Nothing relevant found in logs so far.

iancward commented 7 years ago

@jivany are you using the hubot reload script? I've seen issues with the hubot reload script and slack that I couldn't explain; I ended up removing the script from my installation.

jivany commented 7 years ago

@iancward not using the reload script. Had this happen again at some point last night and all I see in the logs is that the RTM connection was established:

[Fri Dec 16 2016 02:02:30 GMT-0500 (EST)] INFO Logged in as hubot of <team>
[Fri Dec 16 2016 02:02:30 GMT-0500 (EST)] INFO Slack client now connected

Could this be more like #210 where it's node-slack or even hubot reconnecting because they think the previous connection is "dead"? Anyway to prevent that or at least explicitly close the first connection before attempting to reconnect?

serkanh commented 7 years ago

@jivany We have been having the same issue with no particular pattern/timing that we could identify. Just curious, what was the node, hubot and hubot-slack packages versions when you encounter this issue.

jivany commented 7 years ago

@serkanh node 0.10.35; hubot 2.12.0 (?) and hubot-slack 4.2.2

Not 100% certain about the hubot version as I thought my package.json was set to have it pickup the latest version but my logs show 2.12.0.

Treyone commented 7 years ago

Same issue here. Hubot is in a docker container,and as soon as I start 2 instances for high availability, he starts answering messages twice.

Yan [09:38] : ping

AT Robot [09:38] :PONG
[09:38]  PONG

here are the relevant npm versions :

    "generator-hubot": "^0.4.0",
    "hubot": "^2.19.0",
    "hubot-consul-brain": "0.0.1",
    "hubot-scripts": "^2.17.2",
    "hubot-slack": "^4.3.3",
Kcharle commented 7 years ago

I'm having this same issue when working on my script to have hubot deploy my latest updates to my hubot scripts then reloading the scripts using https://github.com/vinta/hubot-reload-scripts

Basically what happens is -

I run hubot freshen up

It sends a POST request to laravel forge which deploys my latest code from master to the server hubot runs on. Which then sends a success message to the channel in slack that hubot is in, when hubot hears deployed some fresh code it runs the reload script linked above, so that all the new changes just pulled come into affect, but after the reload happens, things start to get weird and hubot responds anywhere from 2-10 times.

image

aoberoi commented 7 years ago

@Treyone in your case, if you are running two hubot processes this is the expected behavior. i'm not sure if there are any hubot scripts in the ecosystem to tackle this issue, but essentially you need to put all messages in some unified queue and each process needs to pull from that queue to "claim" it.

@jivany is this issue still occurring for you? i'm wondering if the reconnection improvements in v3.10.0 of @slack/client could have fixed these issues. if this is still occurring, then setting the environment variable HUBOT_LOG_LEVEL=debug while running your process could output some more helpful information. if at all possible, can you list all the other hubot scripts you are using, and their version? how much about your custom scripts can you share?

@Kcharle could you also set the HUBOT_LOG_LEVEL=debug environment variable and share the console output? it seems like a new RTM connection is being initialized without the old one being closed.

schuylr commented 6 years ago

@aoberoi I'm on hubot-slack version 4.4.0 and @slack/client 3.15.0 and still encountering this issue. Here's the logs:

Thu Feb  1 16:00:32 UTC 2018: Agent pid 15754
Thu Feb  1 16:00:32 UTC 2018: Identity added: /home/deploy/.ssh/id_rsa (/home/deploy/.ssh/id_rsa)
Thu Feb  1 16:00:37 UTC 2018: warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
Thu Feb  1 16:00:37 UTC 2018: warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
Thu Feb  1 16:00:38 UTC 2018: [Thu Feb 01 2018 16:00:38 GMT+0000 (UTC)] INFO Logged in as jbot of Jewlr
Thu Feb  1 16:00:38 UTC 2018: [Thu Feb 01 2018 16:00:38 GMT+0000 (UTC)] INFO Slack client now connected
Thu Feb  1 16:00:40 UTC 2018: [Thu Feb 01 2018 16:00:40 GMT+0000 (UTC)] ERROR hubot-heroku-alive included, but missing HUBOT_HEROKU_KEEPALIVE_URL. `heroku config:set HUBOT_HEROKU_KEEPALIVE_URL=$(heroku apps:info -s  | grep web_url | cut -d= -f2)`
Thu Feb  1 16:00:41 UTC 2018: [Thu Feb 01 2018 16:00:41 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
Thu Feb  1 16:00:41 UTC 2018: [Thu Feb 01 2018 16:00:41 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
Fri Feb  2 23:55:54 UTC 2018: warn: Reconnecting, on attempt 1
Fri Feb  2 23:55:55 UTC 2018: [Fri Feb 02 2018 23:55:55 GMT+0000 (UTC)] INFO Logged in as jbot of Jewlr
Fri Feb  2 23:55:55 UTC 2018: [Fri Feb 02 2018 23:55:55 GMT+0000 (UTC)] INFO Slack client now connected
Fri Feb  2 23:55:55 UTC 2018: [Fri Feb 02 2018 23:55:55 GMT+0000 (UTC)] ERROR hubot-heroku-alive included, but missing HUBOT_HEROKU_KEEPALIVE_URL. `heroku config:set HUBOT_HEROKU_KEEPALIVE_URL=$(heroku apps:info -s  | grep web_url | cut -d= -f2)`
Fri Feb  2 23:55:55 UTC 2018: [Fri Feb 02 2018 23:55:55 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
Fri Feb  2 23:55:55 UTC 2018: [Fri Feb 02 2018 23:55:55 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis

This is problematic for us because we run deploys using hubot, so it spawns multiple deploys at the exact same time when responding.

It looks like it does happen due to a reconnect. FYI I have updated my upstart config to include HUBOT_LOG_LEVEL=debug and will post the contents of the logs next time this happens.

schuylr commented 6 years ago

@aoberoi Update - it happened again and I now have HUBOT_LOG_LEVEL=debug set:

Fri Feb  9 23:01:49 UTC 2018: [Fri Feb 09 2018 23:01:49 GMT+0000 (UTC)] DEBUG Received message: 'Build succeeded for repository jewlr/jewlrorders [0ba444c]
Fri Feb  9 23:01:49 UTC 2018: Build succeeded for repository jewlr/jewlrorders [0ba444c]' in channel: minion, from: quay
Fri Feb  9 23:42:01 UTC 2018: [Fri Feb 09 2018 23:42:01 GMT+0000 (UTC)] DEBUG Received message: '@jbot deploy jewlrorders to production' in channel: minion, from: stan
Fri Feb  9 23:42:01 UTC 2018: [Fri Feb 09 2018 23:42:01 GMT+0000 (UTC)] DEBUG Message '@jbot deploy jewlrorders to production' matched regex //^s*[@]?jbot[:,]?s*(?:deploybsb(w+)bsb(on|to)bsb(w+)$)/i/
Fri Feb  9 23:42:01 UTC 2018: [Fri Feb 09 2018 23:42:01 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Okay <@stan>, I'll let you know when I'm done.
Fri Feb  9 23:44:32 UTC 2018: [Fri Feb 09 2018 23:44:32 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Deployment for jewlrorders to production by <@stan> was successful!
Sat Feb 10 03:28:02 UTC 2018: warn: Reconnecting, on attempt 1
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] INFO Logged in as jbot of Jewlr
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] INFO Slack client now connected
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180129151647/scripts
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/aws.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/deploy.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/example.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180129151647/src/scripts
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Loading hubot-scripts from /var/jbot/releases/20180129151647/node_modules/hubot-scripts/src/scripts
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-diagnostics/src/diagnostics.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-help/src/help.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] ERROR hubot-heroku-alive included, but missing HUBOT_HEROKU_KEEPALIVE_URL. `heroku config:set HUBOT_HEROKU_KEEPALIVE_URL=$(heroku apps:info -s  | grep web_url | cut -d= -f2)`
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-heroku-keepalive/src/heroku-keepalive.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-google-images/src/google-images.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-google-translate/src/google-translate.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-pugme/src/pugme.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-maps/src/maps.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-redis-brain/src/redis-brain.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-rules/src/rules.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-shipit/src/shipit.coffee
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] DEBUG hubot-redis-brain: Successfully connected to Redis
Sat Feb 10 03:28:02 UTC 2018: [Sat Feb 10 2018 03:28:02 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
Sat Feb 10 03:46:09 UTC 2018: warn: Reconnecting, on attempt 1
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] INFO Logged in as jbot of Jewlr
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] INFO Slack client now connected
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180129151647/scripts
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/aws.coffee
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/deploy.coffee
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180129151647/scripts/example.coffee
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180129151647/src/scripts
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Loading hubot-scripts from /var/jbot/releases/20180129151647/node_modules/hubot-scripts/src/scripts
Sat Feb 10 03:46:09 UTC 2018: [Sat Feb 10 2018 03:46:09 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
schuylr commented 6 years ago

@aoberoi I'd like to let you know that we're still encountering this from time to time, notably over weekends it seems but it can happen on weekdays as well.

Is it safe to say that you have the feedback that you needed? Can someone look at this?

aoberoi commented 6 years ago

@schuylr thank you so much for reporting all these logs! i'm so sorry that i overlooked these messages for as long as i did.

i can see the reconnection occurring in both cases, so that's a helpful piece of evidence. i have a suspicion that the underlying @slack/client RtmClient object is not cleaning up its event listeners on disconnect, and then on reconnect, duplicate event listeners are being added for those events. i'm going to try to reproduce this for myself given those package versions. i'll report my findings back here.

aoberoi commented 6 years ago

working on reproducing this one today!

aoberoi commented 6 years ago

@schuylr @jivany @Kcharle @serkanh

i've tried all the ways i know how to reproduce this issue, including forcing network disruptions and using the hubot-reload-scripts external script. i couldn't make the listeners fire more than once. i tried this on 4.4.0 and the latest (4.5.2).

i'm going to mark this issue as needs feedback until i can find a concrete reproduction. one piece of information that would be helpful is a list of other external scripts and the specific script that was triggered more than once.

schuylr commented 6 years ago

@aoberoi I'm not sure what to tell you other than it happened again overnight today.

I run no other external scripts that I know of other than my custom deploy script, and it's just simple listeners.

The service runs on Ubuntu 14.04.5 LTS

The service file looks like this

# hubot

description "Jewlr Slack bot"
author "Schuyler Jager <redacted>"

start on filesystem or runlevel [2345]
stop on runlevel [!2345]

# Path to Hubot installation
env HUBOT_DIR='/var/jbot/current/'
env HUBOT='bin/hubot'
env ADAPTER='slack'
# Name (and local user) to run Hubot as
env HUBOT_USER='deploy'
# httpd listen port
env PORT='5555'
env HUBOT_LOG_LEVEL='debug'
env LOGFILE='/var/log/jbot/jbot.log'

# Campfire-specific environment variables
env HUBOT_SLACK_TOKEN='REDACTED'

# Git specific environment variables
env GIT_REPOS_HOME_PATH='/home/deploy/repos/'

# Keep the process alive, limit to 5 restarts in 60s
respawn
respawn limit 5 60

exec start-stop-daemon --start --chuid ${HUBOT_USER} --chdir ${HUBOT_DIR} \
  --exec ${HUBOT_DIR}${HUBOT} -- --name ${HUBOT_USER} --adapter ${ADAPTER} \
  2>&1 | ( while read line; do echo "$(date): ${line}"; done ) > ${LOGFILE}

My package-lock.json looks like this:

{
  "name": "jbot",
  "version": "0.0.0",
  "lockfileVersion": 1,
  "requires": true,
  "dependencies": {
    "@slack/client": {
      "version": "3.15.0",
      "resolved": "https://registry.npmjs.org/@slack/client/-/client-3.15.0.tgz",
      "integrity": "sha512-MIgf5s9PrcxFaPlkJ2cFOhrfh9/KOmUKK5GG/Eka1IJK7+oBCscJFnQ6FfYnZICwIQxWkkuiXmeWYWNevZhCLg==",
      "requires": {
        "async": "1.5.2",
        "bluebird": "3.5.1",
        "eventemitter3": "1.2.0",
        "https-proxy-agent": "1.0.0",
        "inherits": "2.0.3",
        "lodash": "4.17.4",
        "pkginfo": "0.4.1",
        "request": "2.76.0",
        "retry": "0.9.0",
        "url-join": "0.0.1",
        "winston": "2.4.0",
        "ws": "1.1.5"
      },
      "dependencies": {
        "lodash": {
          "version": "4.17.4",
          "resolved": "https://registry.npmjs.org/lodash/-/lodash-4.17.4.tgz",
          "integrity": "sha1-eCA6TRwyiuHYbcpkYONptX9AVa4="
        }
      }
    },
    "agent-base": {
      "version": "2.1.1",
      "resolved": "https://registry.npmjs.org/agent-base/-/agent-base-2.1.1.tgz",
      "integrity": "sha1-1t4Q1a9hMtW9aSQn1G/FOFOQlMc=",
      "requires": {
        "extend": "3.0.1",
        "semver": "5.0.3"
      }
    },
    "ansi-regex": {
      "version": "2.1.1",
      "resolved": "https://registry.npmjs.org/ansi-regex/-/ansi-regex-2.1.1.tgz",
      "integrity": "sha1-w7M6te42DYbg5ijwRorn7yfWVN8="
    },
    "ansi-styles": {
      "version": "2.2.1",
      "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-2.2.1.tgz",
      "integrity": "sha1-tDLdM1i2NM914eRmQ2gkBTPB3b4="
    },
    "asn1": {
      "version": "0.2.3",
      "resolved": "https://registry.npmjs.org/asn1/-/asn1-0.2.3.tgz",
      "integrity": "sha1-2sh4dxPJlmhJ/IGAd36+nB3fO4Y="
    },
    "assert-plus": {
      "version": "0.2.0",
      "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-0.2.0.tgz",
      "integrity": "sha1-104bh+ev/A24qttwIfP+SBAasjQ="
    },
    "async": {
      "version": "1.5.2",
      "resolved": "https://registry.npmjs.org/async/-/async-1.5.2.tgz",
      "integrity": "sha1-7GphrlZIDAw8skHJVhjiCJL5Zyo="
    },
    "asynckit": {
      "version": "0.4.0",
      "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz",
      "integrity": "sha1-x57Zf380y48robyXkLzDZkdLS3k="
    },
    "aws-sign2": {
      "version": "0.6.0",
      "resolved": "https://registry.npmjs.org/aws-sign2/-/aws-sign2-0.6.0.tgz",
      "integrity": "sha1-FDQt0428yU0OW4fXY81jYSwOeU8="
    },
    "aws4": {
      "version": "1.6.0",
      "resolved": "https://registry.npmjs.org/aws4/-/aws4-1.6.0.tgz",
      "integrity": "sha1-g+9cqGCysy5KDe7e6MdxudtXRx4="
    },
    "bcrypt-pbkdf": {
      "version": "1.0.1",
      "resolved": "https://registry.npmjs.org/bcrypt-pbkdf/-/bcrypt-pbkdf-1.0.1.tgz",
      "integrity": "sha1-Y7xdy2EzG5K8Bf1SiVPDNGKgb40=",
      "optional": true,
      "requires": {
        "tweetnacl": "0.14.5"
      }
    },
    "bluebird": {
      "version": "3.5.1",
      "resolved": "https://registry.npmjs.org/bluebird/-/bluebird-3.5.1.tgz",
      "integrity": "sha512-MKiLiV+I1AA596t9w1sQJ8jkiSr5+ZKi0WKrYGUn6d1Fx+Ij4tIj+m2WMQSGczs5jZVxV339chE8iwk6F64wjA=="
    },
    "boom": {
      "version": "2.10.1",
      "resolved": "https://registry.npmjs.org/boom/-/boom-2.10.1.tgz",
      "integrity": "sha1-OciRjO/1eZ+D+UkqhI9iWt0Mdm8=",
      "requires": {
        "hoek": "2.16.3"
      }
    },
    "caseless": {
      "version": "0.11.0",
      "resolved": "https://registry.npmjs.org/caseless/-/caseless-0.11.0.tgz",
      "integrity": "sha1-cVuW6phBWTzDMGeSP17GDr2k99c="
    },
    "chalk": {
      "version": "1.1.3",
      "resolved": "https://registry.npmjs.org/chalk/-/chalk-1.1.3.tgz",
      "integrity": "sha1-qBFcVeSnAv5NFQq9OHKCKn4J/Jg=",
      "requires": {
        "ansi-styles": "2.2.1",
        "escape-string-regexp": "1.0.5",
        "has-ansi": "2.0.0",
        "strip-ansi": "3.0.1",
        "supports-color": "2.0.0"
      }
    },
    "colors": {
      "version": "1.0.3",
      "resolved": "https://registry.npmjs.org/colors/-/colors-1.0.3.tgz",
      "integrity": "sha1-BDP0TYCWgP3rYO0mDxsMJi6CpAs="
    },
    "combined-stream": {
      "version": "1.0.5",
      "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.5.tgz",
      "integrity": "sha1-k4NwpXtKUd6ix3wV1cX9+JUWQAk=",
      "requires": {
        "delayed-stream": "1.0.0"
      }
    },
    "commander": {
      "version": "2.13.0",
      "resolved": "https://registry.npmjs.org/commander/-/commander-2.13.0.tgz",
      "integrity": "sha512-MVuS359B+YzaWqjCL/c+22gfryv+mCBPHAv3zyVI2GN8EY6IRP8VwtasXn8jyyhvvq84R4ImN1OKRtcbIasjYA=="
    },
    "core-util-is": {
      "version": "1.0.2",
      "resolved": "https://registry.npmjs.org/core-util-is/-/core-util-is-1.0.2.tgz",
      "integrity": "sha1-tf1UIgqivFq1eqtxQMlAdUUDwac="
    },
    "cryptiles": {
      "version": "2.0.5",
      "resolved": "https://registry.npmjs.org/cryptiles/-/cryptiles-2.0.5.tgz",
      "integrity": "sha1-O9/s3GCBR8HGcgL6KR59ylnqo7g=",
      "requires": {
        "boom": "2.10.1"
      }
    },
    "cycle": {
      "version": "1.0.3",
      "resolved": "https://registry.npmjs.org/cycle/-/cycle-1.0.3.tgz",
      "integrity": "sha1-IegLK+hYD5i0aPN5QwZisEbDStI="
    },
    "dashdash": {
      "version": "1.14.1",
      "resolved": "https://registry.npmjs.org/dashdash/-/dashdash-1.14.1.tgz",
      "integrity": "sha1-hTz6D3y+L+1d4gMmuN1YEDX24vA=",
      "requires": {
        "assert-plus": "1.0.0"
      },
      "dependencies": {
        "assert-plus": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz",
          "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU="
        }
      }
    },
    "debug": {
      "version": "2.6.9",
      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
      "requires": {
        "ms": "2.0.0"
      }
    },
    "delayed-stream": {
      "version": "1.0.0",
      "resolved": "https://registry.npmjs.org/delayed-stream/-/delayed-stream-1.0.0.tgz",
      "integrity": "sha1-3zrhmayt+31ECqrgsp4icrJOxhk="
    },
    "ecc-jsbn": {
      "version": "0.1.1",
      "resolved": "https://registry.npmjs.org/ecc-jsbn/-/ecc-jsbn-0.1.1.tgz",
      "integrity": "sha1-D8c6ntXw1Tw4GTOYUj735UN3dQU=",
      "optional": true,
      "requires": {
        "jsbn": "0.1.1"
      }
    },
    "escape-string-regexp": {
      "version": "1.0.5",
      "resolved": "https://registry.npmjs.org/escape-string-regexp/-/escape-string-regexp-1.0.5.tgz",
      "integrity": "sha1-G2HAViGQqN/2rjuyzwIAyhMLhtQ="
    },
    "eventemitter3": {
      "version": "1.2.0",
      "resolved": "https://registry.npmjs.org/eventemitter3/-/eventemitter3-1.2.0.tgz",
      "integrity": "sha1-HIaZHYFq0eUEdQ5zh0Ik7PO+xQg="
    },
    "extend": {
      "version": "3.0.1",
      "resolved": "https://registry.npmjs.org/extend/-/extend-3.0.1.tgz",
      "integrity": "sha1-p1Xqe8Gt/MWjHOfnYtuq3F5jZEQ="
    },
    "extsprintf": {
      "version": "1.3.0",
      "resolved": "https://registry.npmjs.org/extsprintf/-/extsprintf-1.3.0.tgz",
      "integrity": "sha1-lpGEQOMEGnpBT4xS48V06zw+HgU="
    },
    "eyes": {
      "version": "0.1.8",
      "resolved": "https://registry.npmjs.org/eyes/-/eyes-0.1.8.tgz",
      "integrity": "sha1-Ys8SAjTGg3hdkCNIqADvPgzCC8A="
    },
    "forever-agent": {
      "version": "0.6.1",
      "resolved": "https://registry.npmjs.org/forever-agent/-/forever-agent-0.6.1.tgz",
      "integrity": "sha1-+8cfDEGt6zf5bFd60e1C2P2sypE="
    },
    "form-data": {
      "version": "2.1.4",
      "resolved": "https://registry.npmjs.org/form-data/-/form-data-2.1.4.tgz",
      "integrity": "sha1-M8GDrPGTJ27KqYFDpp6Uv+4XUNE=",
      "requires": {
        "asynckit": "0.4.0",
        "combined-stream": "1.0.5",
        "mime-types": "2.1.17"
      }
    },
    "generate-function": {
      "version": "2.0.0",
      "resolved": "https://registry.npmjs.org/generate-function/-/generate-function-2.0.0.tgz",
      "integrity": "sha1-aFj+fAlpt9TpCTM3ZHrHn2DfvnQ="
    },
    "generate-object-property": {
      "version": "1.2.0",
      "resolved": "https://registry.npmjs.org/generate-object-property/-/generate-object-property-1.2.0.tgz",
      "integrity": "sha1-nA4cQDCM6AT0eDYYuTf6iPmdUNA=",
      "requires": {
        "is-property": "1.0.2"
      }
    },
    "getpass": {
      "version": "0.1.7",
      "resolved": "https://registry.npmjs.org/getpass/-/getpass-0.1.7.tgz",
      "integrity": "sha1-Xv+OPmhNVprkyysSgmBOi6YhSfo=",
      "requires": {
        "assert-plus": "1.0.0"
      },
      "dependencies": {
        "assert-plus": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz",
          "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU="
        }
      }
    },
    "har-validator": {
      "version": "2.0.6",
      "resolved": "https://registry.npmjs.org/har-validator/-/har-validator-2.0.6.tgz",
      "integrity": "sha1-zcvAgYgmWtEZtqWnyKtw7s+10n0=",
      "requires": {
        "chalk": "1.1.3",
        "commander": "2.13.0",
        "is-my-json-valid": "2.17.1",
        "pinkie-promise": "2.0.1"
      }
    },
    "has-ansi": {
      "version": "2.0.0",
      "resolved": "https://registry.npmjs.org/has-ansi/-/has-ansi-2.0.0.tgz",
      "integrity": "sha1-NPUEnOHs3ysGSa8+8k5F7TVBbZE=",
      "requires": {
        "ansi-regex": "2.1.1"
      }
    },
    "hawk": {
      "version": "3.1.3",
      "resolved": "https://registry.npmjs.org/hawk/-/hawk-3.1.3.tgz",
      "integrity": "sha1-B4REvXwWQLD+VA0sm3PVlnjo4cQ=",
      "requires": {
        "boom": "2.10.1",
        "cryptiles": "2.0.5",
        "hoek": "2.16.3",
        "sntp": "1.0.9"
      }
    },
    "hoek": {
      "version": "2.16.3",
      "resolved": "https://registry.npmjs.org/hoek/-/hoek-2.16.3.tgz",
      "integrity": "sha1-ILt0A9POo5jpHcRxCo/xuCdKJe0="
    },
    "http-signature": {
      "version": "1.1.1",
      "resolved": "https://registry.npmjs.org/http-signature/-/http-signature-1.1.1.tgz",
      "integrity": "sha1-33LiZwZs0Kxn+3at+OE0qPvPkb8=",
      "requires": {
        "assert-plus": "0.2.0",
        "jsprim": "1.4.1",
        "sshpk": "1.13.1"
      }
    },
    "https-proxy-agent": {
      "version": "1.0.0",
      "resolved": "https://registry.npmjs.org/https-proxy-agent/-/https-proxy-agent-1.0.0.tgz",
      "integrity": "sha1-NffabEjOTdv6JkiRrFk+5f+GceY=",
      "requires": {
        "agent-base": "2.1.1",
        "debug": "2.6.9",
        "extend": "3.0.1"
      }
    },
    "hubot-slack": {
      "version": "4.4.0",
      "resolved": "https://registry.npmjs.org/hubot-slack/-/hubot-slack-4.4.0.tgz",
      "integrity": "sha512-3La7pmOEyQWhwiF7W5LPYiXKjZPaHUHS4+krKkG/ayy0uDJr5WBR9Q6NS0Q1X08CZ2wRKZEbpnpvB+30k0zFhg==",
      "requires": {
        "@slack/client": "3.15.0",
        "lodash": "3.10.1"
      }
    },
    "inherits": {
      "version": "2.0.3",
      "resolved": "https://registry.npmjs.org/inherits/-/inherits-2.0.3.tgz",
      "integrity": "sha1-Yzwsg+PaQqUC9SRmAiSA9CCCYd4="
    },
    "is-my-json-valid": {
      "version": "2.17.1",
      "resolved": "https://registry.npmjs.org/is-my-json-valid/-/is-my-json-valid-2.17.1.tgz",
      "integrity": "sha512-Q2khNw+oBlWuaYvEEHtKSw/pCxD2L5Rc1C+UQme9X6JdRDh7m5D7HkozA0qa3DUkQ6VzCnEm8mVIQPyIRkI5sQ==",
      "requires": {
        "generate-function": "2.0.0",
        "generate-object-property": "1.2.0",
        "jsonpointer": "4.0.1",
        "xtend": "4.0.1"
      }
    },
    "is-property": {
      "version": "1.0.2",
      "resolved": "https://registry.npmjs.org/is-property/-/is-property-1.0.2.tgz",
      "integrity": "sha1-V/4cTkhHTt1lsJkR8msc1Ald2oQ="
    },
    "is-typedarray": {
      "version": "1.0.0",
      "resolved": "https://registry.npmjs.org/is-typedarray/-/is-typedarray-1.0.0.tgz",
      "integrity": "sha1-5HnICFjfDBsR3dppQPlgEfzaSpo="
    },
    "isstream": {
      "version": "0.1.2",
      "resolved": "https://registry.npmjs.org/isstream/-/isstream-0.1.2.tgz",
      "integrity": "sha1-R+Y/evVa+m+S4VAOaQ64uFKcCZo="
    },
    "jsbn": {
      "version": "0.1.1",
      "resolved": "https://registry.npmjs.org/jsbn/-/jsbn-0.1.1.tgz",
      "integrity": "sha1-peZUwuWi3rXyAdls77yoDA7y9RM=",
      "optional": true
    },
    "json-schema": {
      "version": "0.2.3",
      "resolved": "https://registry.npmjs.org/json-schema/-/json-schema-0.2.3.tgz",
      "integrity": "sha1-tIDIkuWaLwWVTOcnvT8qTogvnhM="
    },
    "json-stringify-safe": {
      "version": "5.0.1",
      "resolved": "https://registry.npmjs.org/json-stringify-safe/-/json-stringify-safe-5.0.1.tgz",
      "integrity": "sha1-Epai1Y/UXxmg9s4B1lcB4sc1tus="
    },
    "jsonpointer": {
      "version": "4.0.1",
      "resolved": "https://registry.npmjs.org/jsonpointer/-/jsonpointer-4.0.1.tgz",
      "integrity": "sha1-T9kss04OnbPInIYi7PUfm5eMbLk="
    },
    "jsprim": {
      "version": "1.4.1",
      "resolved": "https://registry.npmjs.org/jsprim/-/jsprim-1.4.1.tgz",
      "integrity": "sha1-MT5mvB5cwG5Di8G3SZwuXFastqI=",
      "requires": {
        "assert-plus": "1.0.0",
        "extsprintf": "1.3.0",
        "json-schema": "0.2.3",
        "verror": "1.10.0"
      },
      "dependencies": {
        "assert-plus": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz",
          "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU="
        }
      }
    },
    "lodash": {
      "version": "3.10.1",
      "resolved": "https://registry.npmjs.org/lodash/-/lodash-3.10.1.tgz",
      "integrity": "sha1-W/Rejkm6QYnhfUgnid/RW9FAt7Y="
    },
    "mime-db": {
      "version": "1.30.0",
      "resolved": "https://registry.npmjs.org/mime-db/-/mime-db-1.30.0.tgz",
      "integrity": "sha1-dMZD2i3Z1qRTmZY0ZbJtXKfXHwE="
    },
    "mime-types": {
      "version": "2.1.17",
      "resolved": "https://registry.npmjs.org/mime-types/-/mime-types-2.1.17.tgz",
      "integrity": "sha1-Cdejk/A+mVp5+K+Fe3Cp4KsWVXo=",
      "requires": {
        "mime-db": "1.30.0"
      }
    },
    "ms": {
      "version": "2.0.0",
      "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz",
      "integrity": "sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g="
    },
    "node-uuid": {
      "version": "1.4.8",
      "resolved": "https://registry.npmjs.org/node-uuid/-/node-uuid-1.4.8.tgz",
      "integrity": "sha1-sEDrCSOWivq/jTL7HxfxFn/auQc="
    },
    "oauth-sign": {
      "version": "0.8.2",
      "resolved": "https://registry.npmjs.org/oauth-sign/-/oauth-sign-0.8.2.tgz",
      "integrity": "sha1-Rqarfwrq2N6unsBWV4C31O/rnUM="
    },
    "options": {
      "version": "0.0.6",
      "resolved": "https://registry.npmjs.org/options/-/options-0.0.6.tgz",
      "integrity": "sha1-7CLTEoBrtT5zF3Pnza788cZDEo8="
    },
    "pinkie": {
      "version": "2.0.4",
      "resolved": "https://registry.npmjs.org/pinkie/-/pinkie-2.0.4.tgz",
      "integrity": "sha1-clVrgM+g1IqXToDnckjoDtT3+HA="
    },
    "pinkie-promise": {
      "version": "2.0.1",
      "resolved": "https://registry.npmjs.org/pinkie-promise/-/pinkie-promise-2.0.1.tgz",
      "integrity": "sha1-ITXW36ejWMBprJsXh3YogihFD/o=",
      "requires": {
        "pinkie": "2.0.4"
      }
    },
    "pkginfo": {
      "version": "0.4.1",
      "resolved": "https://registry.npmjs.org/pkginfo/-/pkginfo-0.4.1.tgz",
      "integrity": "sha1-tUGO8EOd5UJfxJlQQtztFPsqhP8="
    },
    "punycode": {
      "version": "1.4.1",
      "resolved": "https://registry.npmjs.org/punycode/-/punycode-1.4.1.tgz",
      "integrity": "sha1-wNWmOycYgArY4esPpSachN1BhF4="
    },
    "qs": {
      "version": "6.3.2",
      "resolved": "https://registry.npmjs.org/qs/-/qs-6.3.2.tgz",
      "integrity": "sha1-51vV9uJoEioqDgvaYwslUMFmUCw="
    },
    "request": {
      "version": "2.76.0",
      "resolved": "https://registry.npmjs.org/request/-/request-2.76.0.tgz",
      "integrity": "sha1-vkRQWv73A2CgQ2lVEGvjlF2VVg4=",
      "requires": {
        "aws-sign2": "0.6.0",
        "aws4": "1.6.0",
        "caseless": "0.11.0",
        "combined-stream": "1.0.5",
        "extend": "3.0.1",
        "forever-agent": "0.6.1",
        "form-data": "2.1.4",
        "har-validator": "2.0.6",
        "hawk": "3.1.3",
        "http-signature": "1.1.1",
        "is-typedarray": "1.0.0",
        "isstream": "0.1.2",
        "json-stringify-safe": "5.0.1",
        "mime-types": "2.1.17",
        "node-uuid": "1.4.8",
        "oauth-sign": "0.8.2",
        "qs": "6.3.2",
        "stringstream": "0.0.5",
        "tough-cookie": "2.3.3",
        "tunnel-agent": "0.4.3"
      }
    },
    "retry": {
      "version": "0.9.0",
      "resolved": "https://registry.npmjs.org/retry/-/retry-0.9.0.tgz",
      "integrity": "sha1-b2l+UKDk3cjI9/tUeptg3q1DZ40="
    },
    "semver": {
      "version": "5.0.3",
      "resolved": "https://registry.npmjs.org/semver/-/semver-5.0.3.tgz",
      "integrity": "sha1-d0Zt5YnNXTyV8TiqeLxWmjy10no="
    },
    "sntp": {
      "version": "1.0.9",
      "resolved": "https://registry.npmjs.org/sntp/-/sntp-1.0.9.tgz",
      "integrity": "sha1-ZUEYTMkK7qbG57NeJlkIJEPGYZg=",
      "requires": {
        "hoek": "2.16.3"
      }
    },
    "sshpk": {
      "version": "1.13.1",
      "resolved": "https://registry.npmjs.org/sshpk/-/sshpk-1.13.1.tgz",
      "integrity": "sha1-US322mKHFEMW3EwY/hzx2UBzm+M=",
      "requires": {
        "asn1": "0.2.3",
        "assert-plus": "1.0.0",
        "bcrypt-pbkdf": "1.0.1",
        "dashdash": "1.14.1",
        "ecc-jsbn": "0.1.1",
        "getpass": "0.1.7",
        "jsbn": "0.1.1",
        "tweetnacl": "0.14.5"
      },
      "dependencies": {
        "assert-plus": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz",
          "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU="
        }
      }
    },
    "stack-trace": {
      "version": "0.0.10",
      "resolved": "https://registry.npmjs.org/stack-trace/-/stack-trace-0.0.10.tgz",
      "integrity": "sha1-VHxws0fo0ytOEI6hoqFZ5f3eGcA="
    },
    "stringstream": {
      "version": "0.0.5",
      "resolved": "https://registry.npmjs.org/stringstream/-/stringstream-0.0.5.tgz",
      "integrity": "sha1-TkhM1N5aC7vuGORjB3EKioFiGHg="
    },
    "strip-ansi": {
      "version": "3.0.1",
      "resolved": "https://registry.npmjs.org/strip-ansi/-/strip-ansi-3.0.1.tgz",
      "integrity": "sha1-ajhfuIU9lS1f8F0Oiq+UJ43GPc8=",
      "requires": {
        "ansi-regex": "2.1.1"
      }
    },
    "supports-color": {
      "version": "2.0.0",
      "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-2.0.0.tgz",
      "integrity": "sha1-U10EXOa2Nj+kARcIRimZXp3zJMc="
    },
    "tough-cookie": {
      "version": "2.3.3",
      "resolved": "https://registry.npmjs.org/tough-cookie/-/tough-cookie-2.3.3.tgz",
      "integrity": "sha1-C2GKVWW23qkL80JdBNVe3EdadWE=",
      "requires": {
        "punycode": "1.4.1"
      }
    },
    "tunnel-agent": {
      "version": "0.4.3",
      "resolved": "https://registry.npmjs.org/tunnel-agent/-/tunnel-agent-0.4.3.tgz",
      "integrity": "sha1-Y3PbdpCf5XDgjXNYM2Xtgop07us="
    },
    "tweetnacl": {
      "version": "0.14.5",
      "resolved": "https://registry.npmjs.org/tweetnacl/-/tweetnacl-0.14.5.tgz",
      "integrity": "sha1-WuaBd/GS1EViadEIr6k/+HQ/T2Q=",
      "optional": true
    },
    "ultron": {
      "version": "1.0.2",
      "resolved": "https://registry.npmjs.org/ultron/-/ultron-1.0.2.tgz",
      "integrity": "sha1-rOEWq1V80Zc4ak6I9GhTeMiy5Po="
    },
    "url-join": {
      "version": "0.0.1",
      "resolved": "https://registry.npmjs.org/url-join/-/url-join-0.0.1.tgz",
      "integrity": "sha1-HbSK1CLTQCRpqH99l73r/k+x48g="
    },
    "verror": {
      "version": "1.10.0",
      "resolved": "https://registry.npmjs.org/verror/-/verror-1.10.0.tgz",
      "integrity": "sha1-OhBcoXBTr1XW4nDB+CiGguGNpAA=",
      "requires": {
        "assert-plus": "1.0.0",
        "core-util-is": "1.0.2",
        "extsprintf": "1.3.0"
      },
      "dependencies": {
        "assert-plus": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/assert-plus/-/assert-plus-1.0.0.tgz",
          "integrity": "sha1-8S4PPF13sLHN2RRpQuTpbB5N1SU="
        }
      }
    },
    "winston": {
      "version": "2.4.0",
      "resolved": "https://registry.npmjs.org/winston/-/winston-2.4.0.tgz",
      "integrity": "sha1-gIBQuT1SZh7Z+2wms/DIJnCLCu4=",
      "requires": {
        "async": "1.0.0",
        "colors": "1.0.3",
        "cycle": "1.0.3",
        "eyes": "0.1.8",
        "isstream": "0.1.2",
        "stack-trace": "0.0.10"
      },
      "dependencies": {
        "async": {
          "version": "1.0.0",
          "resolved": "https://registry.npmjs.org/async/-/async-1.0.0.tgz",
          "integrity": "sha1-+PwEyjoTeErenhZBr5hXjPvWR6k="
        }
      }
    },
    "ws": {
      "version": "1.1.5",
      "resolved": "https://registry.npmjs.org/ws/-/ws-1.1.5.tgz",
      "integrity": "sha512-o3KqipXNUdS7wpQzBHSe180lBGO60SoK0yVo3CYJgb2MkobuWuBX6dhkYP5ORCLd55y+SaflMOV5fqAB53ux4w==",
      "requires": {
        "options": "0.0.6",
        "ultron": "1.0.2"
      }
    },
    "xtend": {
      "version": "4.0.1",
      "resolved": "https://registry.npmjs.org/xtend/-/xtend-4.0.1.tgz",
      "integrity": "sha1-pcbVMr5lbiPbgg77lDofBJmNY68="
    }
  }
}

Is there any other info that I can possibly provide?

Maybe this is related to some sort of connection reset from Slack's side?

schuylr commented 6 years ago

@aoberoi Here's a new log with DEBUG:

Thu Jul 12 21:24:21 UTC 2018: [Thu Jul 12 2018 21:24:21 GMT+0000 (UTC)] DEBUG Received message: '@jbot please push_instagram_feed products to productionus' in channel: minion, from: colin
Thu Jul 12 21:24:21 UTC 2018: [Thu Jul 12 2018 21:24:21 GMT+0000 (UTC)] DEBUG Message '@jbot please push_instagram_feed products to productionus' matched regex //^s*[@]?jbot[:,]?s*(?:pleasebsb(w+)bsb(w+)bsb(on|to)bsb(w+)$)/i/
Thu Jul 12 21:24:21 UTC 2018: [Thu Jul 12 2018 21:24:21 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Okay <@colin>, I'll let you know when I'm done with the products
Thu Jul 12 21:24:46 UTC 2018: [Thu Jul 12 2018 21:24:46 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Successfully ran products:push_instagram_feed for jewlr4 on productionus by <@colin>!
Thu Jul 12 21:25:55 UTC 2018: warn: Reconnecting, on attempt 1
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] INFO Logged in as jbot of Jewlr
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] INFO Slack client now connected
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180712180056/scripts
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180712180056/scripts/aws.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180712180056/scripts/deploy.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/releases/20180712180056/scripts/example.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Loading scripts from /var/jbot/releases/20180712180056/src/scripts
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Loading hubot-scripts from /var/jbot/releases/20180712180056/node_modules/hubot-scripts/src/scripts
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-diagnostics/src/diagnostics.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-help/src/help.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] ERROR hubot-heroku-alive included, but missing HUBOT_HEROKU_KEEPALIVE_URL. `heroku config:set HUBOT_HEROKU_KEEPALIVE_URL=$(heroku apps:info -s  | grep web_url | cut -d= -f2)`
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-heroku-keepalive/src/heroku-keepalive.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-google-images/src/google-images.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-google-translate/src/google-translate.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-pugme/src/pugme.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-maps/src/maps.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] INFO hubot-redis-brain: Using default redis on localhost:6379
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-redis-brain/src/redis-brain.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-rules/src/rules.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG Parsing help for /var/jbot/shared/node_modules/hubot-shipit/src/shipit.coffee
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] DEBUG hubot-redis-brain: Successfully connected to Redis
Thu Jul 12 21:25:55 UTC 2018: [Thu Jul 12 2018 21:25:55 GMT+0000 (UTC)] INFO hubot-redis-brain: Data for hubot brain retrieved from Redis
Thu Jul 12 21:28:16 UTC 2018: [Thu Jul 12 2018 21:28:16 GMT+0000 (UTC)] DEBUG Received message: '@jbot deploy jewlrorders to production' in channel: minion, from: stan
Thu Jul 12 21:28:16 UTC 2018: [Thu Jul 12 2018 21:28:16 GMT+0000 (UTC)] DEBUG Message '@jbot deploy jewlrorders to production' matched regex //^s*[@]?jbot[:,]?s*(?:deploybsb(w+)bsb(on|to)bsb(w+)$)/i/
Thu Jul 12 21:28:16 UTC 2018: [Thu Jul 12 2018 21:28:16 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Okay <@stan>, I'll let you know when I'm done.
Thu Jul 12 21:28:17 UTC 2018: [Thu Jul 12 2018 21:28:16 GMT+0000 (UTC)] DEBUG Message '@jbot deploy jewlrorders to production' matched regex //^s*[@]?jbot[:,]?s*(?:deploybsb(w+)bsb(on|to)bsb(w+)$)/i/
Thu Jul 12 21:28:17 UTC 2018: [Thu Jul 12 2018 21:28:16 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Okay <@stan>, I'll let you know when I'm done.
Thu Jul 12 21:28:18 UTC 2018: [Thu Jul 12 2018 21:28:18 GMT+0000 (UTC)] DEBUG Sending to C070BCJ75: Sorry stan, something weird is happening with the `jewlrorders` Git repository. Could you look into that for me?

Notice that the message is received once, but somehow matched twice, as if the script is loaded on top of the existing script.

aoberoi commented 6 years ago

thanks for the data @schuylr! i have some follow up questions:

  1. i took a look at the package-lock.json you provided (thanks for that). i noticed that hubot is missing from that file. i'm confused how your project could work without depending on hubot. after a closer look, it seems that hubot-slack is the only package that isn't a dependency of another package. can you explain how your application is working without any other dependencies?

  2. the version of hubot-slack you're using is v4.4.0. it would be useful to get a data point on whether this would still occur for you on the latest version (v4.5.2). would you be willing to try that version and see if anything different happens (keep those debug logs on)?

  3. what is triggering the script reload? you might not know the answer to this, but lets try and figure this out. i noticed that right after the reconnection, all the scripts start loading and parsing once again. that doesn't (and shouldn't) happen normally. so are you using some other script to reload (like hubot-reload-scripts referenced above)? is any of your code performing the reload? correct me if i'm wrong, but i thought you're just leaving your bot alone, at some point a reconnection occurs (totally normal when Slack is rebalancing load on servers or rolling out a new release), and then you see listeners triggering multiple times instead of once. is that correct?

just to illustrate my last point, here's a very verbose log taken from my machine while i try to simulate this by closing my network connection and the reconnecting it later. (note: i'm using v4.5.2, and i've turned on logging at the @slack/client level too, so my logs are slightly different. but notice the loading and parsing of scripts doesn't occur after the reconnection).

ankur:my-hubot/ (master✗) $ HUBOT_SLACK_RTM_CLIENT_OPTS='{ "logLevel": "debug" }' HUBOT_LOG_LEVEL=debug HUBOT_SLACK_TOKEN=xoxb-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx bin/hubot -a slack
npm WARN hubot-help@0.2.2 requires a peer of coffee-script@^1.12.6 but none is installed. You must install peer dependencies yourself.

audited 497 packages in 2.452s
found 22 vulnerabilities (12 low, 2 moderate, 8 high)
  run `npm audit fix` to fix them, or `npm audit` for details
[Fri Jul 13 2018 15:38:22 GMT-0700 (Pacific Daylight Time)] DEBUG Loading adapter slack
[Fri Jul 13 2018 15:38:22 GMT-0700 (Pacific Daylight Time)] INFO hubot-slack adapter v4.5.2
debug: BaseAPIClient _createFacets end
debug: BaseAPIClient initialized
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
warn: SlackDataStore is deprecated and will be removed in the next major version. See project documentation for a migration guide.
debug: BaseAPIClient registerDataStore end
debug: RTMClient initialized
[Fri Jul 13 2018 15:38:22 GMT-0700 (Pacific Daylight Time)] DEBUG RtmClient initialized with options: {"logLevel":"debug","maxRequestConcurrency":1,"retryConfig":null}
[Fri Jul 13 2018 15:38:22 GMT-0700 (Pacific Daylight Time)] DEBUG RtmClient#start() with options: {}
verbose: Attempting to connect via the RTM API
debug: BaseAPIClient _makeAPICall end
verbose: BaseAPIClient _callTransport - Retrying [object Object]
debug: BaseAPIClient _callTransport end
verbose: rtm.start successful, attempting to open websocket URL
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG SlackBot#authenticated() Found self in RTM start data
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] INFO Logged in as @example_hubot in workspace Ankur's Standard DevWorkspace
debug: {"type": "hello"}
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] INFO Connected to Slack RTM
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Loading scripts from /Users/ankur/Developer/play/my-hubot/scripts
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] WARNING Robot#react() is a deprecated method and will be removed in the next major version of hubot-slack. It is recommended to use Robot#hearReaction() which behaves exactly the same, but has a clearer name.
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/scripts/example.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] INFO /Users/ankur/Developer/play/my-hubot/scripts/example.coffee is using deprecated documentation syntax
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Loading scripts from /Users/ankur/Developer/play/my-hubot/src/scripts
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Loading external-scripts from npm packages
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-diagnostics/src/diagnostics.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-help/src/help.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] ERROR hubot-heroku-keepalive included, but missing HUBOT_HEROKU_KEEPALIVE_URL. `heroku config:set HUBOT_HEROKU_KEEPALIVE_URL=$(heroku apps:info -s | grep web.url | cut -d= -f2)`
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-heroku-keepalive/src/heroku-keepalive.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-google-images/src/google-images.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-google-translate/src/google-translate.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-pugme/src/pugme.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-maps/src/maps.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] INFO hubot-redis-brain: Using default redis on localhost:6379
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-redis-brain/src/redis-brain.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-rules/src/rules.coffee
[Fri Jul 13 2018 15:38:24 GMT-0700 (Pacific Daylight Time)] DEBUG Parsing help for /Users/ankur/Developer/play/my-hubot/node_modules/hubot-shipit/src/shipit.coffee
debug: waited 0 ms for a pong
debug: sending message via ws: {"type":"ping","id":1}
debug: {"type":"pong","reply_to":1}
debug: waited 33 ms for a pong
debug: sending message via ws: {"type":"ping","id":2}
debug: {"type":"pong","reply_to":2}
debug: waited 31 ms for a pong
debug: sending message via ws: {"type":"ping","id":3}
debug: {"type":"pong","reply_to":3}
debug: waited 33 ms for a pong
debug: sending message via ws: {"type":"ping","id":4}
debug: {"type":"pong","reply_to":4}
debug: waited 26 ms for a pong
debug: sending message via ws: {"type":"ping","id":5}
debug: {"type":"pong","reply_to":5}
debug: waited 40 ms for a pong
debug: sending message via ws: {"type":"ping","id":6}
debug: {"type":"pong","reply_to":6}
debug: waited 28 ms for a pong
debug: sending message via ws: {"type":"ping","id":7}
debug: {"type":"pong","reply_to":7}
debug: waited 26 ms for a pong
debug: sending message via ws: {"type":"ping","id":8}
debug: {"type":"pong","reply_to":8}
debug: waited 27 ms for a pong
debug: sending message via ws: {"type":"ping","id":9}
debug: {"type":"pong","reply_to":9}
debug: waited 31 ms for a pong
debug: sending message via ws: {"type":"ping","id":10}
debug: {"type":"pong","reply_to":10}
debug: waited 50 ms for a pong
debug: sending message via ws: {"type":"ping","id":11}
debug: waited 4951 ms for a pong
debug: sending message via ws: {"type":"ping","id":12}
debug: waited 9952 ms for a pong
debug: sending message via ws: {"type":"ping","id":13}
debug: waited 14957 ms for a pong
debug: sending message via ws: {"type":"ping","id":14}
debug: waited 19958 ms for a pong
debug: sending message via ws: {"type":"ping","id":15}
warn: Reconnecting, on attempt 1
verbose: Attempting to connect via the RTM API
debug: BaseAPIClient _makeAPICall end
verbose: BaseAPIClient _callTransport - Retrying [object Object]
debug: BaseAPIClient _callTransport end
verbose: rtm.start successful, attempting to open websocket URL
[Fri Jul 13 2018 15:39:42 GMT-0700 (Pacific Daylight Time)] DEBUG SlackBot#authenticated() Found self in RTM start data
[Fri Jul 13 2018 15:39:42 GMT-0700 (Pacific Daylight Time)] INFO Logged in as @example_hubot in workspace Ankur's Standard DevWorkspace
debug: {"type": "hello"}
[Fri Jul 13 2018 15:39:42 GMT-0700 (Pacific Daylight Time)] INFO Connected to Slack RTM
debug: waited 2 ms for a pong
debug: sending message via ws: {"type":"ping","id":16}
debug: {"type":"pong","reply_to":16}
debug: waited 28 ms for a pong
debug: sending message via ws: {"type":"ping","id":17}
debug: {"type":"pong","reply_to":17}
debug: waited 30 ms for a pong
debug: sending message via ws: {"type":"ping","id":18}
debug: {"type":"pong","reply_to":18}
debug: waited 24 ms for a pong
debug: sending message via ws: {"type":"ping","id":19}
debug: {"type":"pong","reply_to":19}
debug: waited 28 ms for a pong
debug: sending message via ws: {"type":"ping","id":20}
debug: {"type":"pong","reply_to":20}
debug: waited 26 ms for a pong
debug: sending message via ws: {"type":"ping","id":21}
debug: {"type":"pong","reply_to":21}
schuylr commented 6 years ago

Regarding the package-lock.json, I'm not sure why hubot is missing from there, but I guess my package.json completes the picture:

{
  "name": "jbot",
  "version": "0.0.0",
  "private": true,
  "author": "Schuyler Jager <schuyler@jewlr.com>",
  "description": "Our robotic minion",
  "dependencies": {
    "cron": "1.0.9",
    "hubot": "^2.13.2",
    "hubot-diagnostics": "0.0.1",
    "hubot-google-images": "^0.1.5",
    "hubot-google-translate": "^0.2.0",
    "hubot-help": "^0.1.1",
    "hubot-heroku-keepalive": "0.0.4",
    "hubot-maps": "0.0.2",
    "hubot-pugme": "^0.1.0",
    "hubot-redis-brain": "0.0.3",
    "hubot-rules": "^0.1.1",
    "hubot-scripts": "^2.16.1",
    "hubot-shipit": "^0.2.0",
    "hubot-slack": "^4.4.0",
    "sleep": "3.0.0",
    "sugar": "1.4.1"
  },
  "engines": {
    "node": "0.10.x"
  }
}

I will bump to 4.5.2 and see if we still encounter issues (we had another today).

what is triggering the script reload? you might not know the answer to this, but lets try and figure this out. i noticed that right after the reconnection, all the scripts start loading and parsing once again. that doesn't (and shouldn't) happen normally. so are you using some other script to reload (like hubot-reload-scripts referenced above)?

I don't have any reference to something like hubot-reload-scripts in my repo.

is any of your code performing the reload?

I also didn't write any code that would cause a reload as far as I would know. I'm not even sure of the method calls to do this.

correct me if i'm wrong, but i thought you're just leaving your bot alone, at some point a reconnection occurs (totally normal when Slack is rebalancing load on servers or rolling out a new release), and then you see listeners triggering multiple times instead of once. is that correct?

Correct, the bot is doing nothing when we're not in the office, and usually we see this happen overnight on the following day.

aoberoi commented 6 years ago

@schuylr 4.5.3 is the latest now, but thank you!

mrosenblum1 commented 5 years ago

Has anyone found this issue. I am seeing it 100% of the time.

Here is the log:

[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG Received text message in channel: CG4MG33A8, from: UEG74H3HU (human)
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG Message '@waitlist need' matched regex //^\s*[@]?waitlist[:,]?\s*(?:(?:need|want)$)//; listener.options = { id: null }
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG Executing listener callback for Message '@waitlist need'
caught need without params [object Object], res.match @waitlist need and envelope [object Object]
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG SlackClient#send() room: CG4MG33A8, message: <@UEG74H3HU>: xxxxxxx is already in first on the waitlist for evcharger
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG Message '@waitlist need' matched regex //^\s*[@]?waitlist[:,]?\s*(?:(?:need|want)$)//; listener.options = { id: null }
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG Executing listener callback for Message '@waitlist need'
caught need without params [object Object], res.match @waitlist need and envelope [object Object]
[Thu Feb 28 2019 11:38:33 GMT-0500 (Eastern Standard Time)] DEBUG SlackClient#send() room: CG4MG33A8, message: <@UEG74H3HU>: xxxxxxx is already in first on the waitlist for evcharger

Here is my packags.jason


  "name": "hubot-waitlist",
  "version": "0.0.0",
  "private": true,
  "author": "",
  "description": "Generic slack integration to generate a waitqueue for a scarce resource",
  "dependencies": {
    "@slack/client": "^4.8.0",
    "hubot": "^3.2.0",
    "hubot-redis-brain": "^1.0.0",
    "hubot-slack": "^4.6.0"
  },
  "engines": {
    "node": "0.10.x"
  }
}
github-actions[bot] commented 2 years ago

👋 It looks like this issue has been open for 30 days with no activity. We'll mark this as stale for now, and wait 10 days for an update or for further comment before closing this issue out. If you think this issue needs to be prioritized, please comment to get the thread going again! Maintainers also review issues marked as stale on a regular basis and comment or adjust status if the issue needs to be reprioritized.

github-actions[bot] commented 2 years ago

As this issue has been inactive for more than one month, we will be closing it. Thank you to all the participants! If you would like to raise a related issue, please create a new issue which includes your specific details and references this issue number.