St2chatops with Mattermost not replying

Good afternoon,

For the past couple weeks, I’ve been attemping to troubleshoot st2chatops/hubot connected to Mattermost not replying with the output after running a command except for help. I believe that this is caused by the bot not being connected to the event stream, but I am unsure how to fix this.

I have installed StackStorm by following the Centos 7 install guide in your documentation.

Running !help returns the help output as expected.
Running, for example, !pack get docker returns nothing at all. I can see, however, that in the StackStorm history tab on the web ui, that both the packs.get action and the chatops.post_result action resulted in a Succeeded status.

The following will contain my config files/log files. If you need any more of them, do let me know.

/opt/stackstorm/chatops/st2chatops.env

export ST2_HOSTNAME="127.0.0.1"
export NODE_TLS_REJECT_UNAUTHORIZED="${NODE_TLS_REJECT_UNAUTHORIZED:-0}"
export EXPRESS_PORT="${EXPRESS_PORT:-8081}"
export HUBOT_LOG_LEVEL="${HUBOT_LOG_LEVEL:-debug}"
export HUBOT_NAME="${HUBOT_NAME:-hubot}"
export HUBOT_ALIAS="${HUBOT_ALIAS:-!}"
export ST2_API_URL="https://${ST2_HOSTNAME}/api"
export ST2_AUTH_URL="https://${ST2_HOSTNAME}/auth"
export ST2_STREAM_URL="https://${ST2_HOSTNAME}/stream"
export ST2_API_KEY="API_KEY"
export ST2_AUTH_USERNAME="st2admin"
export ST2_AUTH_PASSWORD="PASSWORD"
export ST2_WEBUI_URL="https://STACKSTORM"
export HUBOT_ADAPTER=matteruser
export MATTERMOST_HOST=HOST
export MATTERMOST_GROUP=StackStorm
export MATTERMOST_USER=hubot
export MATTERMOST_PASSWORD="PASSWORD"
export MATTERMOST_WSS_PORT=443
export MATTERMOST_HTTP_PORT=443
export MATTERMOST_TLS_VERIFY=false
export MATTERMOST_USE_TLS=true
export MATTERMOST_LOG_LEVEL=debug
export MATTERMOST_REPLY=true

/etc/st2/st2.conf

[api]
host = 127.0.0.1
port = 9101
logging = /etc/st2/logging.api.gunicorn.conf
mask_secrets = True
debug = True
[stream]
logging = /etc/st2/logging.stream.gunicorn.conf
host = 127.0.0.1
port = 9102
debug = True
[sensorcontainer]
logging = /etc/st2/logging.sensorcontainer.conf
[rulesengine]
logging = /etc/st2/logging.rulesengine.conf
[actionrunner]
logging = /etc/st2/logging.actionrunner.conf
virtualenv_opts =
[resultstracker]
logging = /etc/st2/logging.resultstracker.conf
[notifier]
logging = /etc/st2/logging.notifier.conf
[exporter]
logging = /etc/st2/logging.exporter.conf
[garbagecollector]
logging = /etc/st2/logging.garbagecollector.conf
[timersengine]
logging = /etc/st2/logging.timersengine.conf
[auth]
host = 127.0.0.1
port = 9100
use_ssl = True
debug = False
enable = True
cert = /etc/ssl/st2/st2.crt
key = /etc/ssl/st2/st2.key
logging = /etc/st2/logging.auth.gunicorn.conf
debug = True
mode = standalone
backend = flat_file
backend_kwargs = {"file_path": "/etc/st2/htpasswd"}
api_url = http://127.0.0.1:9101/
[system]
base_path = /opt/stackstorm
[webui]
webui_base_url = https://STACKSTORM
[syslog]
host = 127.0.0.1
port = 514
facility = local7
protocol = udp
[log]
excludes = requests,paramiko
redirect_stderr = False
mask_secrets = True
[system_user]
user = stanley
ssh_key_file = /home/stanley/.ssh/stanley_rsa
[messaging]
url = amqp://guest:[email protected]:5672/
[ssh_runner]
remote_dir = /tmp
[workflow_engine]
logging = /etc/st2/logging.workflowengine.conf
[scheduler]
logging = /etc/st2/logging.scheduler.conf
[keyvalue]
encryption_key_path = /etc/st2/keys/datastore_key.json

/etc/nginx/conf.d/st2.conf

output of journalctl after systemctl restart st2chatops

-- Logs begin at Mon 2019-06-24 05:40:30 UTC, end at Tue 2019-06-25 16:04:25 UTC. --
Jun 25 15:54:55 SERVER systemd[1]: Started StackStorm service st2chatops.
-- Subject: Unit st2chatops.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit st2chatops.service has finished starting up.
-- 
-- The start-up result is done.
Jun 25 15:54:55 SERVER hubot[40886]: Tue, 25 Jun 2019 15:54:55 GMT body-parser deprecated undefined extended: provide extended option at node_modules/hubot/src/robot.js:445:21
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Loading adapter matteruser
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Logging in...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG POST /users/login
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users/login
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Websocket URL: wss://MATTERMOST:443/api/v4/websocket
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Logged in as user "hubot" but not connected yet.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users/me
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users/me
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users/me
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users/me/preferences
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users/me/preferences
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users/me/preferences
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users/me/teams
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users/me/teams
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users/me/teams
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loaded Me...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Found 1 teams.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Testing stackstorm == StackStorm
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Found team! bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users?page=0&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users?page=0&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users?page=0&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users/me/teams/bkt3m3ah3bdb7p4asyoporaafe/channels
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users/me/teams/bkt3m3ah3bdb7p4asyoporaafe/channels
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users/me/teams/bkt3m3ah3bdb7p4asyoporaafe/channels
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Connecting...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loaded Preferences...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Found 5 subscribed channels.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Found 2 profiles.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Adding user 1dwugfdxui8sjfrz7q5a15snah
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Adding user c1tjrej1pibk9xgxnajo3br8rw
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading /users?page=1&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG GET /users?page=1&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO api url:https://MATTERMOST:443/api/v4/users?page=1&per_page=200&in_team=bkt3m3ah3bdb7p4asyoporaafe
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Found 0 profiles.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Connected to Mattermost.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Loading scripts from /opt/stackstorm/chatops/scripts
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Loading scripts from /opt/stackstorm/chatops/src/scripts
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Sending challenge...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Starting pinger...
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Mattermost server: 5.9.0.5.9.1.9f13f073fc130ee6975f57c436fabfee.false
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Received unhandled message:
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG { status: 'OK', seq_reply: 1 }
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Loading external-scripts from npm packages
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Using ST2_API_KEY as authentication. Expiry will lead to bot exit.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Using matteruser post data handler.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Parsing help for /opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO Loading commands....
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Parsing help for /opt/stackstorm/chatops/node_modules/hubot-help/src/help.coffee
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack get <pack> - Get information about installed StackStorm pack.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack get {{ pack }} - Get information about installed StackStorm pack.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack install <pack_name|git_url>[,<pack_name|git_url>] - Install/upgrade StackStorm packs.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack install {{ packs }} - Install/upgrade StackStorm packs.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack search <query> - Search for packs in StackStorm Exchange and other directories.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack search {{ query }} - Search for packs in StackStorm Exchange and other directories.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack show <pack> - Show information about the pack from StackStorm Exchange.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] DEBUG Added command: pack show {{ pack }} - Show information about the pack from StackStorm Exchange.
Jun 25 15:54:55 SERVER hubot[40886]: [Tue Jun 25 2019 15:54:55 GMT+0000 (UTC)] INFO 4 commands are loaded

st2chatop only supports Mattermost version 5.
Could you provide st2chatops log after run actions !pack get docker?

ChatOps Troubleshooting Guide:

Hello and sorry for the late reply,

I am using Mattermost 5.9.1. I do not think that my Mattermost version is the problem, as the bot responds to ‘!help’ and reads my commands correctly, it just doesn’t send back the result of the StackStorm action.
Here’s the output of !pack get docker:

Jun 26 11:07:09 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:09 GMT+0000 (UTC)] INFO Someone is typing... { event: 'typing',
Jun 26 11:07:09 SERVER hubot[19601]: data: { parent_id: '', user_id: 'c1tjrej1pibk9xgxnajo3br8rw' },
Jun 26 11:07:09 SERVER hubot[19601]: broadcast:
Jun 26 11:07:09 SERVER hubot[19601]: { omit_users: { c1tjrej1pibk9xgxnajo3br8rw: true },
Jun 26 11:07:09 SERVER hubot[19601]: user_id: '',
Jun 26 11:07:09 SERVER hubot[19601]: channel_id: 'bb6gusgg7ffp9je7br6bnckaxa',
Jun 26 11:07:09 SERVER hubot[19601]: team_id: '' },
Jun 26 11:07:09 SERVER hubot[19601]: seq: 2 }
Jun 26 11:07:09 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:09 GMT+0000 (UTC)] INFO ping
Jun 26 11:07:09 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:09 GMT+0000 (UTC)] INFO ACK ping (2)
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Message {
Jun 26 11:07:13 SERVER hubot[19601]: event: 'posted',
Jun 26 11:07:13 SERVER hubot[19601]: data:
Jun 26 11:07:13 SERVER hubot[19601]: { channel_display_name: '@USERNAME',
Jun 26 11:07:13 SERVER hubot[19601]: channel_name: '1dwugfdxui8sjfrz7q5a15snah__c1tjrej1pibk9xgxnajo3br8rw',
Jun 26 11:07:13 SERVER hubot[19601]: channel_type: 'D',
Jun 26 11:07:13 SERVER hubot[19601]: mentions: '["1dwugfdxui8sjfrz7q5a15snah"]',
Jun 26 11:07:13 SERVER hubot[19601]: post: '{"id":"sg3p9kwxht8npgcargm9mk4b9c","create_at":1561547234522,"update_at":1561547234522,"edit_at":0,"delete_at":0,"is_pinned":false,"user_id":"c1tjrej1pibk9xgxnajo3br8rw","channel_id":"bb6gusgg7ffp9je7br6bnckaxa","root_id":"","parent_id":"","original_id":"","message":"pack get docker","type":"","props":{},"hashtags":"","pending_post_id":"c1tjrej1pibk9xgxnajo3br8rw:1561547151471","metadata":{}}',
Jun 26 11:07:13 SERVER hubot[19601]: sender_name: 'USERNAME',
Jun 26 11:07:13 SERVER hubot[19601]: team_id: '' },
Jun 26 11:07:13 SERVER hubot[19601]: broadcast:
Jun 26 11:07:13 SERVER hubot[19601]: { omit_users: null,
Jun 26 11:07:13 SERVER hubot[19601]: user_id: '',
Jun 26 11:07:13 SERVER hubot[19601]: channel_id: 'bb6gusgg7ffp9je7br6bnckaxa',
Jun 26 11:07:13 SERVER hubot[19601]: team_id: '' },
Jun 26 11:07:13 SERVER hubot[19601]: seq: 3 }
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG From: c1tjrej1pibk9xgxnajo3br8rw, To: 1dwugfdxui8sjfrz7q5a15snah
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Text: hubot pack get docker
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Message sent to hubot brain.
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Message 'hubot pack get docker' matched regex //^\s*[@]?(?:hubot[:,]?|![:,]?)\s*(?:([\s\S]+?)$)/i/; listener.options = { id: null }
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Executing listener callback for Message 'hubot pack get docker'
Jun 26 11:07:13 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:13 GMT+0000 (UTC)] DEBUG Sending command payload: {"name":"pack_get","format":"pack get {{ pack }}","command":"pack get docker","user":"USERNAME","source_channel":"bb6gusgg7ffp9je7br6bnckaxa","source_context":{"room":"bb6gusgg7ffp9je7br6bnckaxa","user":{"id":"c1tjrej1pibk9xgxnajo3br8rw","name":"USERNAME","real_name":"LASTNAME, FIRSTNAME","email_address":"[email protected]","mm":{"dm_channel_id":"bb6gusgg7ffp9je7br6bnckaxa","id":"c1tjrej1pibk9xgxnajo3br8rw","create_at":1560781196718,"update_at":1560781983164,"delete_at":0,"username":"USERNAME","auth_data":"","auth_service":"","email":"[email protected]","nickname":"","first_name":"LASTNAME,","last_name":"FIRSTNAME","position":"","roles":"system_user system_admin","locale":"en","timezone":{"automaticTimezone":"","manualTimezone":"","useAutomaticTimezone":"true"}},"room":"bb6gusgg7ffp9je7br6bnckaxa","room_name":"@USERNAME","channel_type":"D"},"message":{"user":{"id":"c1tjrej1pibk9xgxnajo3br8rw","name":"USERNAME","real_name":"LASTNAME, FIRSTNAME","email_address":"[email protected]","mm":{"dm_channel_id":"bb6gusgg7ffp9je7br6bnckaxa","id":"c1tjrej1pibk9xgxnajo3br8rw","create_at":1560781196718,"update_at":1560781983164,"delete_at":0,"username":"USERNAME","auth_data":"","auth_service":"","email":"[email protected]","nickname":"","first_name":"LASTNAME,","last_name":"FIRSTNAME","position":"","roles":"system_user system_admin","locale":"en","timezone":{"automaticTimezone":"","manualTimezone":"","useAutomaticTimezone":"true"}},"room":"bb6gusgg7ffp9je7br6bnckaxa","room_name":"@USERNAME","channel_type":"D"},"done":false,"room":"bb6gusgg7ffp9je7br6bnckaxa","text":"hubot pack get docker","id":"sg3p9kwxht8npgcargm9mk4b9c"}},"notification_route":"hubot"}
Jun 26 11:07:16 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:16 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "sg3p9kwxht8npgcargm9mk4b9c", "text": "hubot pack get docker", "done": false, "user": {"room": "bb6gusgg7ffp9je7br6bnckaxa", "mm": {"username": "USERNAME", "first_name": "LASTNAME,", "last_name": "FIRSTNAME", "roles": "system_user system_admin", "locale": "en", "dm_channel_id": "bb6gusgg7ffp9je7br6bnckaxa", "update_at": 1560781983164, "create_at": 1560781196718, "auth_service": "", "email": "[email protected]", "auth_data": "", "timezone": {"automaticTimezone": "", "useAutomaticTimezone": "true", "manualTimezone": ""}, "delete_at": 0, "position": "", "nickname": "", "id": "c1tjrej1pibk9xgxnajo3br8rw"}, "room_name": "@USERNAME", "real_name": "LASTNAME, FIRSTNAME", "channel_type": "D", "email_address": "[email protected]", "id": "c1tjrej1pibk9xgxnajo3br8rw", "name": "USERNAME"}, "room": "bb6gusgg7ffp9je7br6bnckaxa"}, "room": "bb6gusgg7ffp9je7br6bnckaxa", "user": {"room": "bb6gusgg7ffp9je7br6bnckaxa", "mm": {"username": "USERNAME", "first_name": "LASTNAME,", "last_name": "FIRSTNAME", "roles": "system_user system_admin", "locale": "en", "dm_channel_id": "bb6gusgg7ffp9je7br6bnckaxa", "update_at": 1560781983164, "create_at": 1560781196718, "auth_service": "", "id": "c1tjrej1pibk9xgxnajo3br8rw", "auth_data": "", "position": "", "delete_at": 0, "timezone": {"automaticTimezone": "", "useAutomaticTimezone": "true", "manualTimezone": ""}, "nickname": "", "email": "[email protected]"}, "room_name": "@USERNAME", "real_name": "LASTNAME, FIRSTNAME", "channel_type": "D", "email_address": "[email protected]", "id": "c1tjrej1pibk9xgxnajo3br8rw", "name": "USERNAME"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "bb6gusgg7ffp9je7br6bnckaxa"}}
Jun 26 11:07:39 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:39 GMT+0000 (UTC)] INFO ping
Jun 26 11:07:39 SERVER hubot[19601]: [Wed Jun 26 2019 11:07:39 GMT+0000 (UTC)] INFO ACK ping (2)

As you can see in the “Chatops message received” line near the bottom, it does contain the ‘message’ field that is supposed to be printed in Mattermost, but it isn’t.
As for the troubleshooting guide, I have went through it multiple times. I believe that my problem is my following:

* Gives an acknowledgement message without result:

If you get an acknowledgement message, but then nothing happens, Hubot is most likely disconnected from the StackStorm stream. The main reason for it is a wrong networking setup (Hubot can't connect to your StackStorm instance); check nginx configuration and the parameters in `/opt/stackstorm/chatops/st2chatops.env` (most importantly, `ST2_HOSTNAME` ). Another reason is that either the StackStorm action you're trying to launch or your alias fails with an unexpected error that the bot can't process. This can be checked in StackStorm execution history through CLI or Web UI.

I have also ran the self-check.sh script, and every time it fails at the last step: ‘End to end test failed: Hubot not responding to “st2 list” command.’ I have never had any of the ‘st2’ commands in my help, but I do get the ‘pack’ commands. The script recommends re-installing st2chatops, which I have done just now to make sure, for a grand total of 3 times.

To be sure that the problem is in fact the bot not connecting to the event stream, I have installed a server running Rocket.Chat.

Setup: Stackstorm + st2chatops on a CentOS 7 box and Rocket.Chat in docker on a different CentOS 7 box

Result: The same thing happens, the bot connects properly, is online, responds to !help, sees that I am typing, reads !pack get docker and runs it. Stackstorm then runs the chatops.post_result workflow, but it doesn’t post the response to Rocket.Chat. However, I do actually get an errors in journalctl -u st2chatops so that may help.

Jun 27 16:46:42 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:42 GMT+0000 (UTC)] ERROR Stream error: Event { type: 'error' }
Jun 27 16:46:43 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:43 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:46:43 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:43 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:46:43 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:46:43 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:46:43 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:46:43 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:46:43 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:46:43 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:46:43 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:46:43 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:43 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:46:43 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:46:43 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:46:43 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:46:43 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:43 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:46:43 SERVER hubot[93283]: at IncomingMessage.Readable.read (_stream_readable.js:475:10)
Jun 27 16:46:43 SERVER hubot[93283]: at flow (_stream_readable.js:846:34)
Jun 27 16:46:43 SERVER hubot[93283]: at resume_ (_stream_readable.js:828:3)
Jun 27 16:46:43 SERVER hubot[93283]: at _combinedTickCallback (internal/process/next_tick.js:139:11)
Jun 27 16:46:43 SERVER hubot[93283]: at process._tickCallback (internal/process/next_tick.js:181:9)
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] INFO [received] Message in room GENERAL
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] INFO Message receive callback ID gRvCWNTqTnBwbTAJH at Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] INFO [Incoming] USERNAME: !pack get docker
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG [getRoomNameById] Calling (caching): GENERAL
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG [getRoomNameById] Success: "general"
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] INFO Filters passed, will receive message
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG TextMessage: !pack get docker
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG Message '!pack get docker' matched regex //^\s*[@]?(?:hubot[:,]?|![:,]?)\s*(?:([\s\S]+?)$)/i/; listener.options = { id: null }
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG Executing listener callback for Message '!pack get docker'
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG Sending command payload: {"name":"pack_get","format":"pack get {{ pack }}","command":"pack get docker","user":"USERNAME","source_channel":"general","source_context":{"room":"general","user":{"id":"3fgyFYzZD6wnNoNaf","name":"USERNAME","roomID":"GENERAL","roomType":"c","room":"general"},"message":{"user":{"id":"3fgyFYzZD6wnNoNaf","name":"USERNAME","roomID":"GENERAL","roomType":"c","room":"general"},"done":false,"room":"general","text":"!pack get docker","id":"gRvCWNTqTnBwbTAJH"}},"notification_route":"hubot"}
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:46:56 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:46:56 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:46:56 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:46:56 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:46:56 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:46:56 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:46:56 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:46:56 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:56 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:46:56 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:46:56 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:46:56 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:46:56 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:56 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:46:56 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:56 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:56 SERVER hubot[93283]: at IncomingMessage.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:56 SERVER hubot[93283]: at HTTPParser.parserOnBody (_http_common.js:137:22)
Jun 27 16:46:56 SERVER hubot[93283]: at TLSSocket.socketOnData (_http_client.js:454:20)
Jun 27 16:46:56 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:56 SERVER hubot[93283]: at TLSSocket.emit (events.js:211:7)
Jun 27 16:46:56 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:56 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:56 SERVER hubot[93283]: at TLSSocket.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:56 SERVER hubot[93283]: at TLSWrap.onread (net.js:601:20)
Jun 27 16:46:56 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:56 GMT+0000 (UTC)] ERROR Stream error: Event { type: 'error' }
Jun 27 16:46:57 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:57 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:46:57 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:57 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:46:57 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:46:57 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:46:57 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:46:57 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:46:57 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:46:57 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:46:57 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:46:57 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:57 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:46:57 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:46:57 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:46:57 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:46:57 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:57 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:46:57 SERVER hubot[93283]: at IncomingMessage.Readable.read (_stream_readable.js:475:10)
Jun 27 16:46:57 SERVER hubot[93283]: at flow (_stream_readable.js:846:34)
Jun 27 16:46:57 SERVER hubot[93283]: at resume_ (_stream_readable.js:828:3)
Jun 27 16:46:57 SERVER hubot[93283]: at _combinedTickCallback (internal/process/next_tick.js:139:11)
Jun 27 16:46:57 SERVER hubot[93283]: at process._tickCallback (internal/process/next_tick.js:181:9)
Jun 27 16:46:58 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:58 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:46:58 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:58 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:46:58 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:46:58 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:46:58 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:46:58 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:46:58 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:46:58 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:46:58 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:46:58 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:58 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:46:58 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:46:58 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:46:58 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:46:58 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:58 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:46:58 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:58 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:58 SERVER hubot[93283]: at IncomingMessage.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:58 SERVER hubot[93283]: at HTTPParser.parserOnBody (_http_common.js:137:22)
Jun 27 16:46:58 SERVER hubot[93283]: at TLSSocket.socketOnData (_http_client.js:454:20)
Jun 27 16:46:58 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:58 SERVER hubot[93283]: at TLSSocket.emit (events.js:211:7)
Jun 27 16:46:58 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:58 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:58 SERVER hubot[93283]: at TLSSocket.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:58 SERVER hubot[93283]: at TLSWrap.onread (net.js:601:20)
Jun 27 16:46:58 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:58 GMT+0000 (UTC)] ERROR Stream error: Event { type: 'error' }
Jun 27 16:46:59 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:59 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:46:59 SERVER hubot[93283]: [Thu Jun 27 2019 16:46:59 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:46:59 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:46:59 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:46:59 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:46:59 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:46:59 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:46:59 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:46:59 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:46:59 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:59 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:46:59 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:46:59 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:46:59 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:46:59 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:59 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:46:59 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:59 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:59 SERVER hubot[93283]: at IncomingMessage.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:59 SERVER hubot[93283]: at HTTPParser.parserOnBody (_http_common.js:137:22)
Jun 27 16:46:59 SERVER hubot[93283]: at TLSSocket.socketOnData (_http_client.js:454:20)
Jun 27 16:46:59 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:46:59 SERVER hubot[93283]: at TLSSocket.emit (events.js:211:7)
Jun 27 16:46:59 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:46:59 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:46:59 SERVER hubot[93283]: at TLSSocket.Readable.push (_stream_readable.js:208:10)
Jun 27 16:46:59 SERVER hubot[93283]: at TLSWrap.onread (net.js:601:20)
Jun 27 16:47:24 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:24 GMT+0000 (UTC)] ERROR Stream error: Event { type: 'error' }
Jun 27 16:47:25 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:25 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:47:25 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:25 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:47:25 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:47:25 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:47:25 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:47:25 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:47:25 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:47:25 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:47:25 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:47:25 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:25 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:47:25 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:47:25 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:47:25 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:47:25 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:25 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:47:25 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:47:25 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:47:25 SERVER hubot[93283]: at IncomingMessage.Readable.push (_stream_readable.js:208:10)
Jun 27 16:47:25 SERVER hubot[93283]: at HTTPParser.parserOnBody (_http_common.js:137:22)
Jun 27 16:47:25 SERVER hubot[93283]: at TLSSocket.socketOnData (_http_client.js:454:20)
Jun 27 16:47:25 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:25 SERVER hubot[93283]: at TLSSocket.emit (events.js:211:7)
Jun 27 16:47:25 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:47:25 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:47:25 SERVER hubot[93283]: at TLSSocket.Readable.push (_stream_readable.js:208:10)
Jun 27 16:47:25 SERVER hubot[93283]: at TLSWrap.onread (net.js:601:20)
Jun 27 16:47:50 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:50 GMT+0000 (UTC)] ERROR Stream error: Event { type: 'error' }
Jun 27 16:47:51 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:51 GMT+0000 (UTC)] DEBUG Chatops message received: {"trace_context": null, "payload": {"extra": {}, "whisper": false, "user": "USERNAME", "context": {"message": {"id": "jPJcsEzXcBwxw89Sd", "text": "!pack get docker", "done": false, "user": {"room": "general", "roomType": "c", "roomID": "GENERAL", "id": "3fgyFYzZD6wnNoNaf", "name": "USERNAME"}, "room": "general"}, "room": "general", "user": {"roomType": "c", "roomID": "GENERAL", "room": "general", "name": "USERNAME", "id": "3fgyFYzZD6wnNoNaf"}}, "message": "The requested pack is not present in your StackStorm installation.\nTo install the pack: `pack install docker`\n", "channel": "general"}}
Jun 27 16:47:51 SERVER hubot[93283]: [Thu Jun 27 2019 16:47:51 GMT+0000 (UTC)] ERROR TypeError: Cannot read property 'roomID' of undefined
Jun 27 16:47:51 SERVER hubot[93283]: at strings.map (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:155:25)
Jun 27 16:47:51 SERVER hubot[93283]: at Array.map (<anonymous>:null:null)
Jun 27 16:47:51 SERVER hubot[93283]: at RocketChatBotAdapter.send (/opt/stackstorm/chatops/node_modules/hubot-rocketchat/index.js:154:20)
Jun 27 16:47:51 SERVER hubot[93283]: at Robot.messageRoom (/opt/stackstorm/chatops/node_modules/hubot/src/robot.js:608:23)
Jun 27 16:47:51 SERVER hubot[93283]: at sendChunk (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:454:25)
Jun 27 16:47:51 SERVER hubot[93283]: at RocketChatDataPostHandler.postData (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/lib/post_data.js:459:5)
Jun 27 16:47:51 SERVER hubot[93283]: at EventSource.<anonymous> (/opt/stackstorm/chatops/node_modules/hubot-stackstorm/scripts/stackstorm.js:390:25)
Jun 27 16:47:51 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:51 SERVER hubot[93283]: at EventSource.emit (events.js:211:7)
Jun 27 16:47:51 SERVER hubot[93283]: at _emit (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:172:17)
Jun 27 16:47:51 SERVER hubot[93283]: at parseEventStreamLine (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:186:9)
Jun 27 16:47:51 SERVER hubot[93283]: at IncomingMessage.<anonymous> (/opt/stackstorm/chatops/node_modules/eventsource/lib/eventsource.js:150:11)
Jun 27 16:47:51 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:51 SERVER hubot[93283]: at IncomingMessage.emit (events.js:211:7)
Jun 27 16:47:51 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:47:51 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:47:51 SERVER hubot[93283]: at IncomingMessage.Readable.push (_stream_readable.js:208:10)
Jun 27 16:47:51 SERVER hubot[93283]: at HTTPParser.parserOnBody (_http_common.js:137:22)
Jun 27 16:47:51 SERVER hubot[93283]: at TLSSocket.socketOnData (_http_client.js:454:20)
Jun 27 16:47:51 SERVER hubot[93283]: at emitOne (events.js:116:13)
Jun 27 16:47:51 SERVER hubot[93283]: at TLSSocket.emit (events.js:211:7)
Jun 27 16:47:51 SERVER hubot[93283]: at addChunk (_stream_readable.js:263:12)
Jun 27 16:47:51 SERVER hubot[93283]: at readableAddChunk (_stream_readable.js:250:11)
Jun 27 16:47:51 SERVER hubot[93283]: at TLSSocket.Readable.push (_stream_readable.js:208:10)
Jun 27 16:47:51 SERVER hubot[93283]: at TLSWrap.onread (net.js:601:20)

I can see that the chat bot is requesting /stream/v1/stream with his API key and that it returns a 200.

127.0.0.1 - - [27/Jun/2019:16:59:22 +0000] "GET /stream/v1/stream?st2-api-key=MY_API_KEY HTTP/1.1" 200 2 "-" "-"

Again, if anyone could help me, that would be great.

Have a great day.

Thanks for the clarifications. We will try to get more information and get back to you soon.

It’s curious that your error messages refer to RocketChat, not Mattermost

@lhill good catch!

Thanks for replying,

As I said in my previous reply, I have set up a RocketChat server to confirm if the problem was only with my Mattermost instance. So it is normal that my error messages on my last post refers to RocketChat, as this from when I connected the bot to RocketChat.

The problem still stands, as the bot behaves in the same way whether I use Mattermost or RocketChat: It runs the command that I send, but does not reply with the result, even though the chatops.post_result is successful.

Are you saying you tested with RocketChat and it worked, while switching to MatterMost which didn’t work in the same environment?

Is it a CentOS7 Docker environment where you installed StackStom? Are you running systemd and installing all services in one container?

Good morning,

Thank you so much for responding.

I tested RocketChat because I wanted to verify that my problem was not with my Mattermost installation itself.

I have tested RocketChat and Mattermost and it has not worked for both, I actually run into the same problem for both (the bot reads and runs any action-alias successfully on Mattermost, but doesn’t respond with the chatops.post_result or chatops.post_message if I try manually).

Example:
I run !pack get docker on Mattermost.
On the StackStorm web ui, I can see that packs.get gets successfully manually ran by st2admin.
Still on the ui, I can see that chatops.post_result is also successful and that core.st2.generic.notifytrigger triggered chatops.notify.
In the TRIGGER OUTPUT of chatops.post_result I can see that it contains the message that it is supposed to post to Mattermost, but it never does.

Do note however, that the bot does post !help result and will post the ack message if there is one. (for example, doing !pack search docker, the bot will respond with Alright! Let me check if that matches anything in the StackStorm Exchange index. but nothing else.

Currently, StackStorm is installed on a CentOS7 VM (no docker) in an environment that is disconnected from the Internet. I have also tried it with docker containers beforehand (from GitHub - StackStorm/st2-docker: Demo all-in-one Docker container for StackStorm) also on a CentOS7 VM. I use st2chatops, so hubot is on the same VM as StackStorm. The api, auth and stream endpoint are on the same VM.
My Mattermost server is on a different CentOS7 VM. Both can contact eachother without any problem.
Finally, to make sure that it was not a problem with the fact that I did not have Internet in this network, I installed it at home on another CentOS7 VM connected to the Internet. Every attempt has resulted in the same problem mentionned above.

I see there are stream errors from the st2chatops logs when running RocketChat.

ERROR Stream error: Event { type: 'error' }

Do you see something similar for Mattermost after running st2chatops for a while? Any other errors appearing in logs?

Is there any custom configuration related to CA/self-signed certificates involved in this config?

For debugging reasons/isolation try to switch Mattermost configs to HTTP, same for StackStorm API endpoints (ST2_API_URL (http://127.0.0.1:9101), ST2_STREAM_URL (http://127.0.0.1:9102)).

I do not see the Stream error in st2chatops logs when running st2chatops with Mattermost or any other errors.

I do indeed run self-signed certs on my StackStorm server. I have followed the CentOS7 installation guide and created my cert and key with the command that can be found on that guide. Could you elaborate on what you mean by custom configuration?

I have changed my Mattermost to HTTP and changed ST2_API_URL to ‘http://127.0.0.1:9101’ and ST2_STREAM_URL to ‘http://127.0.0.1:9102’. I did however leave ST2_AUTH_URL to its original
‘https://${ST2_HOSTNAME}/auth’.

I am having the same problem, no response even though chatops.post_result is successful. There is no error in journalctl -u st2chatops.

I have no errors in /var/log/nginx/ssl-st2webui.error.log, but I do notice that after I do !pack get docker, there is no GET request for the stream api in /var/log/nginx/ssl-st2webui.access.log or /var/log/nginx/st2webui.access.log. I do not know if this is normal.

How about Mattermost HTTPS/TLS config?

MATTERMOST_WSS_PORT
MATTERMOST_HTTP_PORT
MATTERMOST_TLS_VERIFY
MATTERMOST_USE_TLS

Did you change that to force HTTP as well?

Yes, otherwise the bot wouldn’t be able to see my commands and execute them.

export MATTERMOST_WSS_PORT=80
export MATTERMOST_HTTP_PORT=80
export MATTERMOST_TLS_VERIFY=false
export MATTERMOST_USE_TLS=false

Just for the record, what are current st2/st2chatops package versions you’re running? Latest?

I’m out of ideas for now.
We’ll likely need to try to reproduce it on latest st2 scripted install with default configs and Mattermost server.

If nothing works, might be indeed bug or incompatibility issues with recent Mattermost server which is probably different comparing to what we’ve tested before.

How would I be able to check which version of the packages I am running?

Considering that even RocketChat has the same symptoms, shouldn’t the problem be with my installation of st2 rather than compatibility with Mattermost?

I have tried to curl http://127.0.0.1:9102/stream?st2-api-key=MY-API-KEY and the stream seems to work correctly with a lot of events showing up when I run a command from Mattermost. So I do not know why GET requests do not show up in nginx logs for the stream from the bot.

Google should help how to find package versions on CentOS7.

Alright, here is an example from my VM:

[vagrant@centos7 ~]$ yum list | grep @StackStorm
st2.x86_64                              3.1.0-1                        @StackStorm_stable
st2chatops.x86_64                       3.1.0-2                        @StackStorm_stable
st2mistral.x86_64                       3.1.0-1                        @StackStorm_stable
st2web.x86_64                           3.1.0-1                        @StackStorm_stable

Sorry, for some reason I thought there would be a st2ctl command to show the version.

yum list | grep @StackStorm does not work because I installed the packages locally due to the network not having access to the internet.

yum list | grep st2 says:
st2.x86_64 is 3.0.1-4
st2chatops.x86_64 is 3.0.1-1
st2mistral.x86_64 is 3.0.1-1
st2web.x86_64 is 3.0.1-1

Thanks, the versions look pretty much almost latest, at least no diff for Mattermost in that st2/st2chatops version range.

Tonight, I’ll re-install again from home and try to use st2chatops with Slack instead to try to pinpoint my problem. I’ll let you know how it went tomorrow.