Troubleshooting bot failure to join DM

[brandoncurtis]

I have installed and run mx-puppet-slack from source, created a Slack app and configured according to the OAUTH instructions in #63

I've set up other bridges before so I'm reasonably familiar with the Matrix configuration files. I use Riot as a client.

When I open a DM with the puppetbot, it shows up as "Slack Puppet Bridge", so it appears that the user is being created on the Matrix side. However, the puppetbot never joins the DM and no further logs ever appear in the bridge logs.

Where can I get started troubleshooting this?

Bridge Logs

May-31 20:11:10.422 [Store] info: Starting DB Init
May-31 20:11:10.425 [Store] info: Filename present in config, using sqlite
May-31 20:11:10.427 [SQLite3] info: Opening database.db
May-31 20:11:10.432 [Store] info: Database schema version is 14, latest version is 14
May-31 20:11:10.437 [Store] info: Starting DB Init
May-31 20:11:10.437 [Store] info: Database schema version is 1, latest version is 1
May-31 20:11:10.438 [PuppetBridge] info: Starting application service....
May-31 20:11:10.448 [bot-sdk-MatrixLiteClient] info: (REQ-1) POST https://mydomain.org/_matrix/client/r0/register
May-31 20:11:10.576 [PuppetBridge] info: Application service started!
May-31 20:11:10.577 [PuppetBridge] info: Setting bridge user data...
May-31 20:11:10.579 [bot-sdk-MatrixLiteClient] info: (REQ-2) GET https://mydomain.org/_matrix/client/r0/account/whoami
May-31 20:11:10.598 [bot-sdk-MatrixLiteClient] info: (REQ-3) PUT https://mydomain.org/_matrix/client/r0/profile/%40_slackpuppet_bot%3Amydomain.org/displayname
May-31 20:11:10.641 [PuppetBridge] info: Activating users...
May-31 20:11:10.643 [PresenceHandler] info: Starting presence handler with new interval 500ms

Synapse Logs

2020-05-31 13:41:25,387 - synapse.handlers.auth - 604 - INFO - POST-97- Logging in user @_slackpuppet_bot:mydomain.org on device <DEVICESTRING>
2020-05-31 13:41:25,395 - synapse.access.http.8008 - 301 - INFO - POST-97- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.069sec/0.000sec (0.005sec, 0.002sec) (0.003sec/0.058sec/7) 338
B 200 "POST /_matrix/client/r0/register HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts]
2020-05-31 13:41:25,420 - synapse.access.http.8008 - 301 - INFO - GET-98- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.001sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 66B 200 "GET /_matrix/client/r0/account/whoami HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts]
2020-05-31 13:41:25,437 - synapse.access.http.8008 - 301 - INFO - PUT-99- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.005sec/0.000sec (0.001sec, 0.000sec) (0.001sec/0.002sec/2) 22B 
200 "PUT /_matrix/client/r0/profile/@_slackpuppet_bot:mydomain.org/displayname HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts]

2020-05-31 19:30:06,853 - synapse.config.appservice - 89 - INFO - None- Loaded application service: ApplicationService: {'token': '<redacted>', 'url': 'http://localhost:8432', 'hs_token': '<redacted>', 'sender': '@_slackpuppet_bot:mydomain.org', 'server_name': 'mydomain.org', 'namespaces': {'users': [{'exclusive': True, 'regex': re.compile('@_slackpuppet_.*')}], 'rooms': [], 'aliases': [{'exclusive': True, 'regex': re.compile('#_slackpuppet_.*')}]}, 'id': 'slack-puppet', 'ip_range_whitelist': None, 'protocols': set(), 'rate_limited': False}

2020-05-31 19:31:08,016 - synapse.http.server - 81 - INFO - POST-56- <SynapseRequest at 0xf5211d0c method='POST' uri='/_matrix/client/r0/register' clientproto='HTTP/1.1' site=8008> SynapseError: 400 - User ID already taken.
2020-05-31 19:31:08,017 - synapse.access.http.8008 - 301 - INFO - POST-56- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.005sec/0.000sec (0.003sec, 0.000sec) (0.000sec/0.001sec/1) 74B 400 "POST /_matrix/client/r0/register HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts]
2020-05-31 19:31:08,044 - synapse.access.http.8008 - 301 - INFO - GET-57- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.001sec/0.000sec (0.000sec, 0.000sec) (0.000sec/0.000sec/0) 66B 200 "GET /_matrix/client/r0/account/whoami HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts] 
2020-05-31 19:31:08,089 - synapse.access.http.8008 - 301 - INFO - PUT-58- 127.0.0.1 - 8008 - {@_slackpuppet_bot:mydomain.org} Processed request: 0.029sec/0.000sec (0.003sec, 0.001sec) (0.001sec/0.025sec/3) 22B 200 "PUT /_matrix/client/r0/profile/@_slackpuppet_bot:mydomain.org/displayname HTTP/1.1" "got (https://github.com/sindresorhus/got)" [0 dbevts]

[brandoncurtis]

Not a bridge problem; caused by some bad events in the database gumming up the appservice event notifications matrix-org/synapse#7615