[RFC] Launch broken when using wechaty-puppet-padchat

[windmemory]

Recently we found that launching a brand new account with wechaty usually caused broken. It got broken in the middle of sync contact and room process.

Here are some findings when I dig into the logs:

12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="8782232552750441268"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="1462326259527763698"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="8735059677077650799"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="2504461861627333859"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="1100112026148355327"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="8588166431672172548"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="2096699474679277066"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="2382475819182337035"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="4073329493334221770"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="8174939221126134399"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="872796766615663343"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="3934004771815351677"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="53885304707962676"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="2320166463976022502"})
12:16:12 VERB PuppetPadChat messageRawPayloadParser({msg_id="8845650378455313091"})
12:16:12 VERB Contact load(qq-yatou) init pool
12:16:12 SILL Accessory #52<Contact> constructor()
12:16:12 SILL Contact constructor(qq-yatou)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(qq-yatou) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(qq-yatou)
12:16:12 SILL PuppetPadchatManager contactRawPayload(qq-yatou)
12:16:12 SILL Accessory #53<Contact> constructor()
12:16:12 SILL Contact constructor(wxid_ivs3h8f596pj22)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_ivs3h8f596pj22) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_ivs3h8f596pj22)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_ivs3h8f596pj22)
12:16:12 SILL Accessory #54<Contact> constructor()
12:16:12 SILL Contact constructor(wxid_rsv890vmlf3k1)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_rsv890vmlf3k1) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_rsv890vmlf3k1)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_rsv890vmlf3k1)
12:16:12 SILL Accessory #55<Contact> constructor()
12:16:12 SILL Contact constructor(wxid_s8r3vfuih0lw22)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_s8r3vfuih0lw22) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_s8r3vfuih0lw22) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_s8r3vfuih0lw22) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0
12:16:12 SILL Puppet contactPayload(wxid_s8r3vfuih0lw22) cache MISS
12:16:12 SILL PuppetPadchat contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL PuppetPadchatManager contactRawPayload(wxid_s8r3vfuih0lw22)
12:16:12 SILL Accessory #56<Contact> constructor()
12:16:12 SILL Contact constructor(wxid_cf35qjq9amh221)
12:16:12 SILL Contact ready() @ Puppet#0<PuppetPadchat>(test)/PuppetPadchat#0

I realized that after these part of logs, wechaty-puppet-padchat started to call WXGenContact rapidly, from my estimate, it would be more than 50 times/s, which is an abnormal behavior. I think this is the root cause of the broken.

This is triggered by new message, so I looked into the code that we deal with the new message:

case 'message':
  puppet.on('message', async messageId => {
    const msg = this.Message.load(messageId)
    await msg.ready()
    this.emit('message', msg)
  })
  break

When we receive a new message, we call Message.ready() method. Here is the Message.ready() method:

public async ready (): Promise<void> {
  log.verbose('Message', 'ready()')

  if (this.isReady()) {
    return
  }

  this.payload = await this.puppet.messagePayload(this.id)

  if (!this.payload) {
    throw new Error('no payload')
  }

  const fromId = this.payload.fromId
  const roomId = this.payload.roomId
  const toId   = this.payload.toId

  if (fromId) {
    await this.wechaty.Contact.load(fromId).ready()
  }
  if (roomId) {
    await this.wechaty.Room.load(roomId).ready()
  }
  if (toId) {
    await this.wechaty.Contact.load(toId).ready()
  }
}

As we can see, this Message.ready() method will also call the ready() method on fromId, roomId and toId. Here is the Room.ready() function:

public async ready (
  forceSync = false,
): Promise<void> {
  log.verbose('Room', 'ready()')

  if (!forceSync && this.isReady()) {
    return
  }

  if (forceSync) {
    await this.puppet.roomPayloadDirty(this.id)
    await this.puppet.roomMemberPayloadDirty(this.id)
  }
  this.payload = await this.puppet.roomPayload(this.id)

  if (!this.payload) {
    throw new Error('ready() no payload')
  }

  const memberIdList = await this.puppet.roomMemberList(this.id)

  await Promise.all(
    memberIdList
      .map(id => this.wechaty.Contact.load(id))
      .map(contact => {
        contact.ready()
          .catch(e => {
            log.verbose('Room', 'ready() member.ready() rejection: %s', e)
          })
      }),
  )
}

From the code above, I noticed that this logic will call Contact.ready() on each room member. If wechaty is just started, the data of room member won't be in contact, so it will fire up an WXGetContact request to Wechat server.

[windmemory]

I will try to fix this in wechaty-puppet-padchat layer by populate room member data into contact when getRoomMemberList(). Will update in this issue.

[huan]

@windmemory thanks for the analysis!

I have a question:

1. Did you find out the reason that why we did not have this problem before?

And, BTW: If you populate room member data into contact, then please also consider a situation: one contact is the bot's friend and it also in one room. If you populate the room member data to contact payload, then the contact payload will be the room member data instead of a normal contact payload,some properties might be empty forever because it will not be get from the server anymore.

[windmemory]

Patch fix: wechaty/wechaty-puppet-padchat@03fa49f

[windmemory]

@zixia
I haven't went that far in this problem, so I don't know why it doesn't happened before.

I think you make a good point here, I should also consider the situation that you brought up. I think when we are syncing contact, contact will always override the data in cache for lower level(puppet-padchat), thus it is promised that the data in the cache will be correct eventually. But for upper level(wecahty), I think it would be hard to determine that whether a contact is a friend or stranger in a room. Do you have any better idea?

[huan]

Thanks for the fix!

About the contact payload, a friend payload will be different with a room member payload, especially when the room member is a stranger(not a friend) to the bot, which is the most common case.

Let's start thinking and try to find a better way to solve this problem.

[windmemory]

Yeah, I do understand the difference between a friend and a stranger. The thing that I was struggled with is that, from wechaty perspective, when it receive a message from a room, it loads all room members with details and require those information to be up to date, but during the launch period, most information are not ready to be loaded in lower layer. So lower layer can not provide up to date information. Either loaded the information with interval, or do things like current implementation.

If we re-consider the design we have currently, maybe we change the flow that we are loading these contact. We could mimic the behavior in wechat app. Unless we want to check the detail data for a user, we never get the information from wechat. For basic usage, like search or get the list, properties nick_name and id are enough I think.

Let me know your thought. Maybe we could also discuss this face to face.

[huan]

Did you find the reason that caused so many WXGetContact call?

As I remember, Wechaty will only call room.ready() when it receives a message in a room, and room.ready() will not call WXGetContact, it will call WXGetChatRoomMember instead.

[windmemory]

Notice the code I pasted above

await Promise.all(
    memberIdList
      .map(id => this.wechaty.Contact.load(id))
      .map(contact => {
        contact.ready()
          .catch(e => {
            log.verbose('Room', 'ready() member.ready() rejection: %s', e)
          })
      }),
  )

This is loading the room member as a contact, if the data is not loaded, WXGetContact will be triggered for each of the room member.

[huan]

Can we get rid of this part of the code?

I can not remember more details, but it seems that load all payload at here is not a good idea for now.

[windmemory]

From my understanding, I think it should be okay to remove it. do you need me to send out a PR for this?

[huan]

Thanks for share your thought.

Please hold it to think it more for some days, we do not make a decision right now.

[windmemory]

Okay, let's discuss this later.

[windmemory]

I think this could be closed since the issue is not exist anymore.

[huan]

Glad to hear that, thanks!