frequently receiving messages from slackbot * this message was deleted

[ericmigi]

getting this message when nothing apparent has happened in the bridged slack room

Apr-27 04:51:37.807 [SlackPuppet:slack] info: Received create request for channel update puppetId=1 roomId=T02A11S1M-G0C07RXCG
Apr-27 04:51:37.811 [SlackPuppet:slack] info: Received create request for channel update puppetId=2 roomId=T02A11S1M-G0C07RXCG
Apr-27 04:51:37.811 [SlackPuppet:slack] info: Received create request for channel update puppetId=3 roomId=T02A11S1M-G0C07RXCG
Apr-27 04:51:37.812 [RemoteEventHandler] info: Received redact from T02A11S1M-U2U2R193L to send to T02A11S1M-G0C07RXCG
Apr-27 04:51:37.813 [UserSync] info: Fetching client for -1
Apr-27 04:51:37.814 [Util] info: Processing profile update...
Apr-27 04:51:37.817 [RoomSync] info: Fetching mxid for roomId T02A11S1M-G0C07RXCG and puppetId -1
Apr-27 04:51:37.828 [Util] info: Processing profile update...
Apr-27 04:51:37.829 [bot-sdk-MatrixLiteClient] info: (REQ-28) PUT https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/state/m.room.topic/
Apr-27 04:51:38.460 [SlackPuppet:slack] info: Received create request for channel update puppetId=1 roomId=T02A11S1M-G0CN3CNF4
Apr-27 04:51:38.462 [SlackPuppet:slack] info: Received create request for channel update puppetId=2 roomId=T02A11S1M-G0CN3CNF4
Apr-27 04:51:38.462 [SlackPuppet:slack] info: Received create request for channel update puppetId=3 roomId=T02A11S1M-G0CN3CNF4
Apr-27 04:51:38.464 [RemoteEventHandler] info: Received edit from T02A11S1M-USLACKBOT to send to T02A11S1M-G0CN3CNF4
Apr-27 04:51:38.466 [UserSync] info: Fetching client for -1
Apr-27 04:51:38.467 [Util] info: Processing profile update...
Apr-27 04:51:38.470 [RoomSync] info: Fetching mxid for roomId T02A11S1M-G0CN3CNF4 and puppetId -1
Apr-27 04:51:38.475 [Util] info: Processing profile update...
Apr-27 04:51:38.476 [bot-sdk-MatrixLiteClient] info: (REQ-29) PUT https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/state/m.room.topic/
Apr-27 04:51:40.171 [bot-sdk-MatrixLiteClient] info: (REQ-30) POST https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/invite
Apr-27 04:51:40.334 [bot-sdk-MatrixLiteClient] info: (REQ-31) POST https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/invite
Apr-27 04:51:40.616 [SlackPuppet:slack] info: Received create request for channel update puppetId=1 roomId=T02A11S1M-G5122908Y
Apr-27 04:51:40.616 [SlackPuppet:slack] info: Received create request for channel update puppetId=2 roomId=T02A11S1M-G5122908Y
Apr-27 04:51:40.617 [SlackPuppet:slack] info: Received create request for channel update puppetId=3 roomId=T02A11S1M-G5122908Y
Apr-27 04:51:40.617 [RemoteEventHandler] info: Received redact from T02A11S1M-UA8GH6B7G to send to T02A11S1M-G5122908Y
Apr-27 04:51:40.620 [UserSync] info: Fetching client for -1
Apr-27 04:51:40.625 [bot-sdk-MatrixLiteClient] info: (REQ-1) POST https://asmux.nova.chat/_matrix/client/r0/register
Apr-27 04:51:43.623 [bot-sdk-Appservice] error: Error registering user: User ID is in use
Apr-27 04:51:43.624 [Util] info: Processing profile update...
Apr-27 04:51:43.627 [RoomSync] info: Fetching mxid for roomId T02A11S1M-G5122908Y and puppetId -1
Apr-27 04:51:43.632 [Util] info: Processing profile update...
Apr-27 04:51:43.633 [bot-sdk-MatrixLiteClient] info: (REQ-32) PUT https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/state/m.room.topic/
Apr-27 04:51:48.450 [bot-sdk-MatrixLiteClient] error: (REQ-30) {"errcode":"M_FORBIDDEN","error":"@eric:nova.chat is already in the room."}
Apr-27 04:51:48.457 [bot-sdk-MatrixLiteClient] error: (REQ-31) {"errcode":"M_FORBIDDEN","error":"@eric:nova.chat is already in the room."}
Apr-27 04:51:48.468 [RemoteEventHandler] warn: Couldn't find event, sending as normal message...
Apr-27 04:51:48.469 [bot-sdk-MatrixLiteClient] info: (REQ-10) PUT https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/send/m.room.message/
Apr-27 04:51:49.588 [bot-sdk-MatrixLiteClient] info: (REQ-2) GET https://asmux.nova.chat/_matrix/client/r0/joined_rooms
Apr-27 04:51:51.118 [bot-sdk-MatrixLiteClient] info: (REQ-33) POST https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/invite
Apr-27 04:51:52.023 [bot-sdk-MatrixLiteClient] info: (REQ-34) POST https://asmux.nova.chat/_matrix/client/r0/rooms/!%3Anova.chat/receipt/m.read/%24tgDTwYTaO_NMuPSm5dTBX6xkCXo8wvO1-eL9BvTqRKU
Apr-27 04:51:53.023 [bot-sdk-MatrixLiteClient] error: (REQ-33) {"errcode":"M_FORBIDDEN","error":"@eric:nova.chat is already in the room."}
Apr-27 04:51:53.037 [bot-sdk-Appservice] info: Processing transaction 29185
Apr-27 04:51:53.038 [bot-sdk-Appservice] info: Processing event of type m.room.message
127.0.0.1 - - [27/Apr/2020:04:51:53 +0000] "PUT /_matrix/app/v1/transactions/29185?access_token= HTTP/1.1" 200 2 "-" "Python/3.8 aiohttp/3.6.2"

[Sorunome]

Can you increase your logging to "silly" so that it logs the contents of that slack event? Thank you!

[ericmigi]

figured it out! It looks these messages show as 'User changed their avatar' on RiotX but show up as * This message shows as deleted on Riot-web because I have 'show avatar changes' disabled. Intended functionality should be no message displayed right?

[Sorunome]

uuuuuuh, wut? Do you mean this message is originating from slack or from matrix? If it is from slack, what does the raw slack payload look like? (visible when log levels are set to "silly")

[ericmigi]

sorry for the delay, the issue is still occurring, here are the logs for several messages that came through as '* this message was deleted'

May-21 04:56:00.634 [Util] info: Processing profile update...
May-21 04:56:00.635 [Util] verbose: {
  mxid: '!KADNkjxDVAJiwcPnuf:nova.chat',
  roomId: 'T02A11S1M-C02A2M5DZ',
  puppetId: -1,
  isDirect: false,
  e2be: false,
  isUsed: true,
  name: 'inthenews  - YC Slack',
  avatarUrl: 'https://avatars.slack-edge.com/2014-11-25/3051004e8bd67f13d72a1_original.jpg',
  avatarMxc: 'mxc://nova.chat/ErmOsdgRTSLnzgO',
  avatarHash: '5f806eed7273c6afc64e0745457e999f85b69d167b529924c7ecde6508698b7a80d8a28a204f1a52bf3',
  topic: 'News stories in the YC universe',
  groupId: null,
  externalUrl: null
} --> {
  puppetId: 3,
  roomId: 'T02A11S1M-C02A2M5DZ',
  nameVars: { name: 'inthenews', team: 'YC', type: 'channel' },
  avatarUrl: 'https://avatars.slack-edge.com/2014-11-25/308843d72a1_original.jpg',
  topic: 'News stories in the YC universe',
  isDirect: false,
  groupId: 'T02A11S1M'
}
May-21 04:56:00.636 [Util] verbose: Old profile exists, looking at diff...
May-21 04:56:00.636 [RoomSync] verbose: Group sync is disabled
May-21 04:56:00.636 [RoomSync] verbose: Returning mxid
May-21 04:56:00.637 [RemoteEventHandler] silly: Joining ghost to room...
May-21 04:56:00.638 [bot-sdk-MatrixLiteClient] info: (REQ-1) GET https://asmux.nova.chat/_matrix/client/r0/joined_rooms
May-21 04:56:00.638 [bot-sdk-MatrixLiteClient] debug: (REQ-1) qs = {"user_id":"@_eric_slack___t02_a11_s1_m=2d_u2_v958_h_m_m:nova.chat"}
May-21 04:56:00.640 [bot-sdk-Metrics] debug: intent_function_call
May-21 04:56:00.713 [SlackClient:Client] debug: RTM event: message
May-21 04:56:00.714 [SlackClient:Client] silly: Processing message with data {
  type: 'message',
  subtype: 'message_deleted',
  hidden: true,
  deleted_ts: '1587397979.064200',
  channel: 'C02A2M5DZ',
  previous_message: {
    client_msg_id: '2c3b4a7f-1afc-441b-9277-065f804776d7',
    type: 'message',
    text: "Do  grass?",
    user: 'UE01AE6E8',
    ts: '1587397979.064200',
    team: 'T02A11S1M',
    blocks: [ [Object] ],
    thread_ts: '1587397979.064200',
    reply_count: 0,
    reply_users_count: 0,
    latest_reply: '0000000000.000000',
    reply_users: []
  },
  event_ts: '1590036960.119100',
  ts: '1590036960.119100',
  team_id: 'T02A11S1M'
}
May-21 04:56:00.714 [SlackPuppet:slack] verbose: Got new message deleted event
May-21 04:56:00.715 [NamespaceHandler] debug: In global namespace, determining if it should be blocked... puppetId=3 userId=T02A11S1M-UE01AE6E8 roomId=T02A11S1M-C02A2M5DZ
May-21 04:56:00.719 [SlackPuppet:slack] info: Received create request for channel update puppetId=2 roomId=T02A11S1M-C02A2M5DZ
May-21 04:56:00.720 [SlackPuppet:slack] info: Received create request for channel update puppetId=1 roomId=T02A11S1M-C02A2M5DZ
May-21 04:56:00.720 [SlackPuppet:slack] info: Received create request for channel update puppetId=4 roomId=T02A11S1M-C02A2M5DZ
May-21 04:56:00.720 [SlackPuppet:slack] info: Received create request for channel update puppetId=3 roomId=T02A11S1M-C02A2M5DZ