Matrix rooms are not created, for an installation running with different ghost user & room prefixes

jeffcasavant commented 5 years ago

I have a room I joined on Slack that is just throwing errors when messages are sent. I have tried to leave & rejoin to get the bridge to retry creating the Matrix room, but it does not do it.

Error:

Error in handleThirdPartyRoomMessage { [M_EXCLUSIVE: This application service has not reserved this kind of alias.]
  errcode: 'M_EXCLUSIVE',
  name: 'M_EXCLUSIVE',
  message:
   'This application service has not reserved this kind of alias.',
  data:
   { errcode: 'M_EXCLUSIVE',
     error:
      'This application service has not reserved this kind of alias.' },
  httpStatus: 400 } { roomId: 'ROOM-ID',
  senderId: 'SENDER-ID',
  senderName: 'firstlast',
  avatarUrl:
   'https://slack-avatar-url',
  text: 'message',
  html: '
message

' }

Note I am running a modified version of matrix-puppet-slack (I was at one point running matrix-appservice-slack as well; see https://github.com/matrix-hacks/matrix-puppet-slack/issues/34).

Modifications:

diff --git a/app.js b/app.js
index a903f31..0970e56 100644
--- a/app.js
+++ b/app.js
@@ -15,7 +15,7 @@ class App extends MatrixPuppetBridgeBase {
   setSlackTeam(teamName, userAccessToken, notify) {
     this.teamName = teamName;
     this.userAccessToken = userAccessToken;
-    this.slackPrefix = 'slack';
+    this.slackPrefix = 'slackpuppet';
     this.servicePrefix = `${this.slackPrefix}_${this.teamName}`;
     this.notifyToSlack = notify;
   }
diff --git a/index.js b/index.js
index 8ca5de4..93d2e4f 100644
--- a/index.js
+++ b/index.js
@@ -23,7 +23,7 @@ new Cli({
       reg.setHomeserverToken(AppServiceRegistration.generateToken());
       reg.setAppServiceToken(AppServiceRegistration.generateToken());
       reg.setSenderLocalpart(`slack_bot`);
-      reg.addRegexPattern("users", `@slack_.*`, true);
+      reg.addRegexPattern("users", `@slackpuppet_.*`, true);
       callback(reg);
     }).catch(err=>{
       console.error(err.message);
@@ -81,7 +81,7 @@ new Cli({
           console.log('on alias query');
         },
         thirdPartyLookup: {
-          protocols: config.slack.map(i=>`slack_${i.team_name}`),
+          protocols: config.slack.map(i=>`slackpuppet_${i.team_name}`),
           getProtocol: function() {
             console.log('get proto');
           },

My registration.yaml does reflect this change as well:

namespaces:
  users:
    - exclusive: true
      regex: '@slackpuppet_.*'

It is possible that this issue stems from me upgrading matrix-puppet-slack and not having this modification in place for a short time (~10 minutes while I tried to figure out what I had done wrong). If that's the case, I'd expect some entries in the user & room databases to have the wrong prefix. They look empty to me otherwise I would try manually editing them.

(venv)[jeff@matrix matrix-puppet-slack]$ file user-store.db
user-store.db: empty

thomas-profitt commented 5 years ago

At this point, you're more familiar with the failure cases related to the slack_ prefix being reserved and using a new one than I am.

I can't really help digging up the cause of this problem; all I really have to contribute is, I think we should seriously consider changing our default prefix, so there's no collision with matrix-appservice-slack's, and people won't have reason to change it.

jeffcasavant commented 5 years ago

Do you happen to know where it stores the rooms it knows about?

Or does it do the following every time it receives a message:

generate matrix-side room id & user id
create matrix room & ghost user if it doesn't exist
send message

That seems a bit heavy, but much more tolerant of failures (like the one I'm probably inducing here 😛 ).

thomas-profitt commented 5 years ago

I don't know, but I would also hope that, instead of storing that state and referring to it, it does it the way you laid out, statelessly, because that would be more reliable.

You'll need to check matrix-puppet-bridge; it should be what handles that.

jeffcasavant commented 5 years ago

Can do. I'll leave this open & take notes here.

thomas-profitt commented 5 years ago

/pull/74 should fix this; closing.

jeffcasavant commented 5 years ago

Excellent! Sorry, I've been busy this past week. Will deploy & try it out.

jeffcasavant commented 5 years ago

I am still getting these errors. I checked out 1.10.1, reapplied my diff:

diff --git a/app.js b/app.js
index dad6caf..b2e35ec 100644
--- a/app.js
+++ b/app.js
@@ -15,7 +15,7 @@ class App extends MatrixPuppetBridgeBase {
   setSlackTeam(teamName, userAccessToken, notify) {
     this.teamName = teamName;
     this.userAccessToken = userAccessToken;
-    this.slackPrefix = 'slack';
+    this.slackPrefix = 'slackpuppet';
     this.servicePrefix = `${this.slackPrefix}_${this.teamName}`;
     this.notifyToSlack = notify;
   }
diff --git a/index.js b/index.js
index 450881f..b2173a5 100644
--- a/index.js
+++ b/index.js
@@ -22,9 +22,9 @@ new Cli({
       reg.setId(AppServiceRegistration.generateToken());
       reg.setHomeserverToken(AppServiceRegistration.generateToken());
       reg.setAppServiceToken(AppServiceRegistration.generateToken());
-      reg.setSenderLocalpart(`slack_bot`);
-      reg.addRegexPattern("users", `@slack_.*`, true);
-      reg.addRegexPattern("aliases", `@slack_.*`, false);
+      reg.setSenderLocalpart(`slackpuppet_bot`);
+      reg.addRegexPattern("users", `@slackpuppet_.*`, true);
+      reg.addRegexPattern("aliases", `@slackpuppet_.*`, false);
       callback(reg);
     }).catch(err=>{
       console.error(err.message);
@@ -82,7 +82,7 @@ new Cli({
           console.log('on alias query');
         },
         thirdPartyLookup: {
-          protocols: config.slack.map(i=>`slack_${i.team_name}`),
+          protocols: config.slack.map(i=>`slackpuppet_${i.team_name}`),
           getProtocol: function() {
             console.log('get proto');
           },

regenerated the registration & restarted both Synapse & matrix-puppet-slack.

I am now throwing these again:

Error in handleThirdPartyRoomMessage { [M_EXCLUSIVE: This application service has not reserved this kind of alias.]
  errcode: 'M_EXCLUSIVE',
  name: 'M_EXCLUSIVE',
  message:
   'This application service has not reserved this kind of alias.',
  data:
   { errcode: 'M_EXCLUSIVE',
     error:
      'This application service has not reserved this kind of alias.' },
  httpStatus: 400 } { roomId: '<slack-room-id>', text: '', html: '' }

I'll have to see if I can splice in some better logging with regard to what alias m-p-slack is trying to use.

thomas-profitt commented 5 years ago

After you regenerated your slack-registration.yaml, did you also install the slack-registration.yaml file in Synapse's data directory, replacing the old one, before restarting Synapse?

jeffcasavant commented 5 years ago

My synapse config points at the directory where the file is generated. So yes, Synapse would have picked up the new one.

thomas-profitt commented 5 years ago

Because the 1.10.1 fix has worked for others, I'm confident saying it's to do with the state of your installation and the changes in your branch.

Can you confirm that your matrix-puppet-slack is trying to create rooms with the @slackpuppet_ prefix, and not the old @slack_ prefix?

thomas-profitt commented 5 years ago

I think this issue is valuable for another reason too: if we ever want to change our prefix so it doesn't collide with matrix-appservice-slack's (and man i do), what we learn here will help us migrate.

thomas-profitt commented 5 years ago

Reopening since this is a different issue than the one(s) we closed with 1.10.1.

jeffcasavant commented 5 years ago

I should have some time next week to dive in on it. Maybe as early as Saturday night / Sunday night. I'll investigate what the bridge is attempting to do, and I'll also investigate how it maintains state (I do get warnings as the bridge comes up saying a certain storage class is deprecated).

jeffcasavant commented 5 years ago

Definitely late getting back to this. Diving into it now though. Here's a quick status update before I get much further.

I can confirm that my bridge is trying to create rooms with the correct aliases (this can be seen in the debug logs below).

Running on 1.11.0 with this diff:

diff --git a/app.js b/app.js
index dad6caf..5650b4c 100644
--- a/app.js
+++ b/app.js
@@ -15,7 +15,7 @@ class App extends MatrixPuppetBridgeBase {
   setSlackTeam(teamName, userAccessToken, notify) {
     this.teamName = teamName;
     this.userAccessToken = userAccessToken;
-    this.slackPrefix = 'slack';
+    this.slackPrefix = 'slackpuppet';
     this.servicePrefix = `${this.slackPrefix}_${this.teamName}`;
     this.notifyToSlack = notify;
   }
@@ -339,8 +339,6 @@ class App extends MatrixPuppetBridgeBase {
       payload.text = rawMessage;
     }

-
-
     return this.handleThirdPartyRoomMessage(payload).catch(err=>{
       console.error(err);
       this.sendStatusMsg({
diff --git a/index.js b/index.js
index 450881f..b2173a5 100644
--- a/index.js
+++ b/index.js
@@ -22,9 +22,9 @@ new Cli({
       reg.setId(AppServiceRegistration.generateToken());
       reg.setHomeserverToken(AppServiceRegistration.generateToken());
       reg.setAppServiceToken(AppServiceRegistration.generateToken());
-      reg.setSenderLocalpart(`slack_bot`);
-      reg.addRegexPattern("users", `@slack_.*`, true);
-      reg.addRegexPattern("aliases", `@slack_.*`, false);
+      reg.setSenderLocalpart(`slackpuppet_bot`);
+      reg.addRegexPattern("users", `@slackpuppet_.*`, true);
+      reg.addRegexPattern("aliases", `@slackpuppet_.*`, false);
       callback(reg);
     }).catch(err=>{
       console.error(err.message);
@@ -82,7 +82,7 @@ new Cli({
           console.log('on alias query');
         },
         thirdPartyLookup: {
-          protocols: config.slack.map(i=>`slack_${i.team_name}`),
+          protocols: config.slack.map(i=>`slackpuppet_${i.team_name}`),
           getProtocol: function() {
             console.log('get proto');
           },

Here's some relevant debug logs now that I've pulled them out.

Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:slack:client emitting typing message: { type: 'user_typing', channel: 'DGEVA00E7', user: 'UGF3G1C02' }
Feb 23 18:17:42 matrix node[19258]: { type: 'user_typing', channel: 'DGEVA00E7', user: 'UGF3G1C02' }
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getOrCreateMatrixRoomFromThirdPartyRoomId:info looking up DGEVA00E7
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getOrCreateMatrixRoomFromThirdPartyRoomId:info the room doesn't exist. we need to create it for the first time
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getOrCreateMatrixRoomFromThirdPartyRoomId:info got 3p room data { name: 'jeff.casavant_test',
Feb 23 18:17:42 matrix node[19258]: topic: 'Slack Direct Message (Team: yaap-tmp)' }
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getOrCreateMatrixRoomFromThirdPartyRoomId:info creating room !!!! >>>>slackpuppet_yaap-tmp_DGEVA00E7<<<< jeff.casavant_test Slack Direct Message (Team: yaap-tmp)
Feb 23 18:17:42 matrix node[19258]: { [M_EXCLUSIVE: This application service has not reserved this kind of alias.]
Feb 23 18:17:42 matrix node[19258]: errcode: 'M_EXCLUSIVE',
Feb 23 18:17:42 matrix node[19258]: name: 'M_EXCLUSIVE',
Feb 23 18:17:42 matrix node[19258]: message:
Feb 23 18:17:42 matrix node[19258]: 'This application service has not reserved this kind of alias.',
Feb 23 18:17:42 matrix node[19258]: data:
Feb 23 18:17:42 matrix node[19258]: { errcode: 'M_EXCLUSIVE',
Feb 23 18:17:42 matrix node[19258]: error:
Feb 23 18:17:42 matrix node[19258]: 'This application service has not reserved this kind of alias.' },
Feb 23 18:17:42 matrix node[19258]: httpStatus: 400 }
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info looking up #slackpuppet_puppetStatusRoom:casavant.org
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info found matrix room via alias. room_id: <roomid>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info ensuring puppet user has full power over this room
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info granted puppet client admin status on the protocol status room
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info making puppet join protocol status room <roomid>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info puppet joined the protocol status room
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info ensuring puppet user has full power over this room
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:getStatusRoomId:info granted puppet client admin status on the protocol status room
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT matrix-puppet:Base:sendStatusMsg:info joining protocol bot to room >>> <roomid> <<<
Feb 23 18:17:42 matrix node[19258]: sendEvent of type m.room.message in <roomid> with txnId m1550963862262.3
Feb 23 18:17:42 matrix node[19258]: Event sent to <roomid>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT express:router dispatching PUT /transactions/12?access_token=<token>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT express:router query  : /transactions/12?access_token=<token>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT express:router expressInit  : /transactions/12?access_token=<token>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT express:router logger  : /transactions/12?access_token=<token>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT express:router jsonParser  : /transactions/12?access_token=<token>
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT body-parser:json content-type "application/json"
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT body-parser:json content-encoding "identity"
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT body-parser:json read body
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT body-parser:json parse body
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT body-parser:json parse json
Feb 23 18:17:42 matrix node[19258]: Sat, 23 Feb 2019 23:17:42 GMT morgan log request

registration:

id: <id>
hs_token: <token>
as_token: <as_token>
namespaces:
  users:
    - exclusive: true
      regex: '@slackpuppet_.*'
  aliases:
    - exclusive: false
      regex: '@slackpuppet_.*'
  rooms: []
url: 'http://localhost:8092'
sender_localpart: slackpuppet_bot
rate_limited: true
protocols: null

jeffcasavant commented 5 years ago

As mentioned in the PR, changing the aliases block in the registration file to:

  aliases:
    - exclusive: false
      regex: '#slackpuppet_.*'

solved my problem.

matrix-hacks / matrix-puppet-slack

Matrix rooms are not created, for an installation running with different ghost user & room prefixes #72