Gitter driven into a state where sent messages "succeed" but never appear

[danielballan]

Description

The gitter connector eventually drives something into a state where messages are sent "successfully" but never actually appear in gitter---not even if I wait for hours, and neither in the browser nor in the iOS app. When messages are sent, gitter's response has a 200 status, and all its headers look fine, including those related to rate limiting. (See logs below.)

Restarting opsdroid does not resolve the issue. But deleting the bot's gitter account and then remaking it does immediately resolve the issue (until it occurs again some time later). I have driven into this state two separate times over a couple days of playing with the connector, and this has been the case both times. I can't identify anything unusual that occurs right before the broken state is reached.

Remaking the account in this way reset the token. Note that there is no other way to reset the token (!) according to someone from gitter. (I lost the link to where I found that information, but it seems to be accurate.)

I don't really expect any good answers here because this is time-consuming to reproduce, but I leave this report for posterity in case someone else runs into trouble. If anyone can suggest somewhere to look or something to check, I'd be glad for suggestions. In the absence of any good ideas, I may shift my attention to a more robust chat client.

Steps to Reproduce

This is transient. [I first described this as transient but that is not right. Once it happens, it does not un-happen on its own, at least not within hours.] I have not discovered a way to repeatably reproduce it.

Expected Functionality

When the connector sends a message and gets back a response with status 200 from gitter, the message should actually appear in gitter.

Experienced Functionality

The logs, augmented with some extra detailed debugging messages, look right:

Jan 05 01:09:50 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: Starting Gitter Connector.
Jan 05 01:09:50 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: Connecting with Gitter stream.
Jan 05 01:10:21 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: Listening with Gitter stream.
Jan 05 01:10:21 dogwood opsdroid[4325]: INFO opsdroid.web: Started web server on http://0.0.0.0:8080
Jan 05 01:10:21 dogwood opsdroid[4325]: INFO opsdroid.core: Opsdroid is now running, press ctrl+c to exit.
Jan 05 01:10:27 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: {'id': '5ff3bc8263fe0344963a5ee7', 'text': 'Color red', 'html': 'Color red', 'sent': '2021-01-05T01:10:26.760Z', 'readBy': 0, 'urls': [], 'mentions': [], 'issues': [], 'meta': [], 'v': 1, 'fromUser': {'id': '54ac2a22db8155e6700e6990', 'username': 'danielballan', 'displayName': 'Dan Allan', 'url': '/danielballan', 'avatarUrl': 'https://avatars-05.gitter.im/gh/uv/4/danielballan', 'avatarUrlSmall': 'https://avatars2.githubusercontent.com/u/2279598?v=4&s=60', 'avatarUrlMedium': 'https://avatars2.githubusercontent.com/u/2279598?v=4&s=128', 'v': 35, 'gv': '4'}}
Jan 05 01:10:27 dogwood opsdroid[4325]: DEBUG opsdroid.core: Parsing input: <opsdroid.events.Message(text=Color red)>.
Jan 05 01:10:27 dogwood opsdroid[4325]: INFO opsdroid.connector.gitter: Successfully responded.
Jan 05 01:10:27 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: Response from gitter: <ClientResponse(https://api.gitter.im/v1/rooms/5ff0bd39d73408ce4ff7d726/chatMessages) [200 OK]>
Jan 05 01:10:27 dogwood opsdroid[4325]: <CIMultiDictProxy('Access-Control-Expose-Headers': 'X-RateLimit-Limit,X-RateLimit-Remaining,X-RateLimit-Reset', 'Cache-Control': 'no-cache', 'Content-Encoding': 'gzip', 'Content-Type': 'application/json; charset=utf-8', 'Date': 'Tue, 05 Jan 2021 01:10:27 GMT', 'ETag': 'W/"226-KTvHfMkLwbtN4l2l1+MudHmkslg"', 'Server': 'nginx', 'Strict-Transport-Security': 'max-age=31536000', 'Vary': 'X-HTTP-Method-Override, Origin', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'DENY', 'X-RateLimit-Limit': '100', 'X-RateLimit-Remaining': '99', 'X-RateLimit-Reset': '1609809087314', 'X-Server-ID': 'webapp-03', 'X-Upstream': '127.0.0.1:5023', 'X-XSS-Protection': '1; mode=block', 'Content-Length': '324', 'Connection': 'keep-alive')>
Jan 05 01:10:27 dogwood opsdroid[4325]: DEBUG opsdroid.connector.gitter: JSON payload of response gitter: {'id': '5ff3bc8397312f4b6b0c4064', 'text': 'OK, coloring', 'html': 'OK, coloring', 'sent': '2021-01-05T01:10:27.321Z', 'unread': False, 'readBy': 0, 'urls': [], 'mentions': [], 'issues': [], 'meta': [], 'fromUser': {'id': '5ff2024ed73408ce4ff7e537', 'username': 'twinkling-tree', 'displayName': 'twinkling-tree', 'url': '/twinkling-tree', 'avatarUrl': 'https://avatars-01.gitter.im/gh/uv/4/twinkling-tree', 'avatarUrlSmall': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=60', 'avatarUrlMedium': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=128', 'v': 3, 'gv': '4'}}

but no message ever appears in gitter.

Now, immediately after re-making the account:

Jan 05 01:13:17 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: Starting Gitter Connector.
Jan 05 01:13:17 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: Connecting with Gitter stream.
Jan 05 01:13:47 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: Listening with Gitter stream.
Jan 05 01:13:47 dogwood opsdroid[4363]: INFO opsdroid.web: Started web server on http://0.0.0.0:8080
Jan 05 01:13:47 dogwood opsdroid[4363]: INFO opsdroid.core: Opsdroid is now running, press ctrl+c to exit.
Jan 05 01:14:00 dogwood opsdroid[4363]: DEBUG opsdroid.parsers.crontab: Running crontab skills at Tue Jan  5 01:14:00 2021.
Jan 05 01:15:00 dogwood opsdroid[4363]: DEBUG opsdroid.parsers.crontab: Running crontab skills at Tue Jan  5 01:15:00 2021.
Jan 05 01:15:07 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: {'id': '5ff3bd9b93af5216fc8130f1', 'text': 'Color red', 'html': 'Color red', 'sent': '2021-01-05T01:15:07.727Z', 'readBy': 0, 'urls': [], 'mentions': [], 'issues': [], 'meta': [], 'v': 1, 'fromUser': {'id': '54ac2a22db8155e6700e6990', 'username': 'danielballan', 'displayName': 'Dan Allan', 'url': '/danielballan', 'avatarUrl': 'https://avatars-05.gitter.im/gh/uv/4/danielballan', 'avatarUrlSmall': 'https://avatars2.githubusercontent.com/u/2279598?v=4&s=60', 'avatarUrlMedium': 'https://avatars2.githubusercontent.com/u/2279598?v=4&s=128', 'v': 35, 'gv': '4'}}
Jan 05 01:15:07 dogwood opsdroid[4363]: DEBUG opsdroid.core: Parsing input: <opsdroid.events.Message(text=Color red)>.
Jan 05 01:15:08 dogwood opsdroid[4363]: INFO opsdroid.connector.gitter: Successfully responded.
Jan 05 01:15:08 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: Response from gitter: <ClientResponse(https://api.gitter.im/v1/rooms/5ff0bd39d73408ce4ff7d726/chatMessages) [200 OK]>
Jan 05 01:15:08 dogwood opsdroid[4363]: <CIMultiDictProxy('Access-Control-Expose-Headers': 'X-RateLimit-Limit,X-RateLimit-Remaining,X-RateLimit-Reset', 'Cache-Control': 'no-cache', 'Content-Encoding': 'gzip', 'Content-Type': 'application/json; charset=utf-8', 'Date': 'Tue, 05 Jan 2021 01:15:08 GMT', 'ETag': 'W/"22c-PAI3heaG2ab9wL/ng8ecQB4ZkMY"', 'Server': 'nginx', 'Strict-Transport-Security': 'max-age=31536000', 'Vary': 'X-HTTP-Method-Override, Origin', 'X-Content-Type-Options': 'nosniff', 'X-Frame-Options': 'DENY', 'X-RateLimit-Limit': '100', 'X-RateLimit-Remaining': '99', 'X-RateLimit-Reset': '1609809367947', 'X-Server-ID': 'webapp-06', 'X-Upstream': '127.0.0.1:5025', 'X-XSS-Protection': '1; mode=block', 'Content-Length': '326', 'Connection': 'keep-alive')>
Jan 05 01:15:08 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: JSON payload of response gitter: {'id': '5ff3bd9c93af5216fc8130f5', 'text': 'OK, coloring', 'html': 'OK, coloring', 'sent': '2021-01-05T01:15:08.029Z', 'unread': False, 'readBy': 0, 'urls': [], 'mentions': [], 'issues': [], 'meta': [], 'v': 1, 'fromUser': {'id': '5ff3bcbad73408ce4ff80168', 'username': 'twinkling-tree', 'displayName': 'twinkling-tree', 'url': '/twinkling-tree', 'avatarUrl': 'https://avatars-01.gitter.im/gh/uv/4/twinkling-tree', 'avatarUrlSmall': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=60', 'avatarUrlMedium': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=128', 'v': 1, 'gv': '4'}}
Jan 05 01:15:08 dogwood opsdroid[4363]: DEBUG opsdroid.connector.gitter: {'id': '5ff3bd9c93af5216fc8130f5', 'text': 'OK, coloring', 'html': 'OK, coloring', 'sent': '2021-01-05T01:15:08.029Z', 'readBy': 0, 'urls': [], 'mentions': [], 'issues': [], 'meta': [], 'v': 1, 'fromUser': {'id': '5ff3bcbad73408ce4ff80168', 'username': 'twinkling-tree', 'displayName': 'twinkling-tree', 'url': '/twinkling-tree', 'avatarUrl': 'https://avatars-01.gitter.im/gh/uv/4/twinkling-tree', 'avatarUrlSmall': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=60', 'avatarUrlMedium': 'https://avatars2.githubusercontent.com/u/76883179?v=4&s=128', 'v': 1, 'gv': '4'}}
Jan 05 01:15:08 dogwood opsdroid[4363]: DEBUG opsdroid.core: Parsing input: <opsdroid.events.Message(text=OK, coloring)>.

and the reposes immediately appear.

You can also notice a difference in the logs: when it works, the bot sees its own response and parses it because of #1691.

Versions

• Opsdroid version: 0.19.0 (notably not including my recent PR into the gitter connector --- this is a standard release save for the my additional logging shown above)
• Python version: 3.7.3
• OS/Docker version: Raspbian GNU/Linux 10

Configuration File

connectors:
  gitter:
    bot-name: "twinkling-tree"
    room-id: "<room-id>"  # danielballan/twinkling-tree
    token: "<token>"

skills:
  rainbow:
    path: skills.py
logging:
  level: debug
  path: ~/.opsdroid/output.log
  console: true

Additional Details

Any other details you wish to include such as screenshots, console messages, etc.

[FabioRosado]

Thank you for raising this issue and getting into trying to figure out what was happening. I'm wondering if the issue isn't both ours and gitter? Perhaps we might need to update the connector somehow.

Also related to #1691 - if we look at the _get_messages method, I'm thinking that perhaps the issue could be because we are reading chunks of the stream and maybe something is left behind?

This is just assumptions and I'm not sure... I'm also wondering if the parse_message isn't giving us some headache there as well 🤔

[jacobtomlinson]

Thanks for raising this Dan.

Bugs like this are a real pain. I wonder if there is something on their end to filter out repeated messages. Perhaps you could add some perturbations to your bot's response to see if the same thing happens?

[danielballan]

Duplicate detection was a good hint. It looks like gitter applies duplicate detection for a two-week probation period on new accounts, and it results in the account getting permanently (silently?) banned.

/**
 * Super basic spam detection
 */
function detect(user, parsedMessage) {
  // Once a spammer, always a spammer....
  if (user.hellbanned) return true;

  var userId = user._id;
  var userCreated = mongoUtils.getTimestampFromObjectId(userId);

  // Outside of the probation period? For now, let them do anything
  if (Date.now() - userCreated > PROBATION_PERIOD) {
    return false;
  }

  return duplicateChatDetector(userId, parsedMessage.text).tap(function(isSpamming) {
    if (!isSpamming) return;

    logger.warn('Auto spam detector to hellban user for suspicious activity', {
      userId: user._id,
      username: user.username,
      text: parsedMessage.text
    });

    stats.event('auto_hellban_user', {
      userId: user._id
    });

    return hellbanUser(userId);
  });
}

Excerpted from https://gitlab.com/gitterHQ/webapp/-/blob/2bad5c88524c884b2b3e67cf5a0f82a15173fa29/modules/spam-detection/lib/chat-spam-detection.js#L34-37 (I got there from this message.)

I'm inclined to add a note about this probation period to the gitter connector documentation, close this issue, and shift my attention to Telegram or some other chat client with more robust bot support.

@FabioRosado I noticed that potential issue as well. I don't think it can be responsible for this behavior; it doesn't really matter for sending where we successfully retrieve messages. But yes I agree that could be a latent bug that would cause messages that do appear in the gitter app to fail to be visible to the bot (until / unless enough subsequent messages arrive).

[jacobtomlinson]

I'm inclined to add a note about this probation period to the gitter connector documentation, close this issue, and shift my attention to Telegram or some other chat client with more robust bot support.

That sounds very reasonable.

[jacobtomlinson]

it results in the account getting permanently (silently?) banned

Also yeah looks like they hellban (also known as shadow banning). So the user becomes invisible to everyone except themselves.

[danielballan]

This is my first encounter with the term. I can see how it would make sense from the point of view of spam management, to make it a little harder for bad actors to know when their efforts are being wasted.