historysync.go 31 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872
  1. // mautrix-whatsapp - A Matrix-WhatsApp puppeting bridge.
  2. // Copyright (C) 2021 Tulir Asokan
  3. //
  4. // This program is free software: you can redistribute it and/or modify
  5. // it under the terms of the GNU Affero General Public License as published by
  6. // the Free Software Foundation, either version 3 of the License, or
  7. // (at your option) any later version.
  8. //
  9. // This program is distributed in the hope that it will be useful,
  10. // but WITHOUT ANY WARRANTY; without even the implied warranty of
  11. // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
  12. // GNU Affero General Public License for more details.
  13. //
  14. // You should have received a copy of the GNU Affero General Public License
  15. // along with this program. If not, see <https://www.gnu.org/licenses/>.
  16. package main
  17. import (
  18. "crypto/sha256"
  19. "encoding/base64"
  20. "fmt"
  21. "time"
  22. "maunium.net/go/mautrix/util/variationselector"
  23. waProto "go.mau.fi/whatsmeow/binary/proto"
  24. "go.mau.fi/whatsmeow/types"
  25. "maunium.net/go/mautrix"
  26. "maunium.net/go/mautrix/appservice"
  27. "maunium.net/go/mautrix/event"
  28. "maunium.net/go/mautrix/id"
  29. "maunium.net/go/mautrix/util/dbutil"
  30. "maunium.net/go/mautrix-whatsapp/config"
  31. "maunium.net/go/mautrix-whatsapp/database"
  32. )
  33. // region User history sync handling
  34. type wrappedInfo struct {
  35. *types.MessageInfo
  36. Type database.MessageType
  37. Error database.MessageErrorType
  38. SenderMXID id.UserID
  39. ReactionTarget types.MessageID
  40. MediaKey []byte
  41. ExpirationStart time.Time
  42. ExpiresIn time.Duration
  43. }
  44. func (user *User) handleHistorySyncsLoop() {
  45. if !user.bridge.Config.Bridge.HistorySync.Backfill {
  46. return
  47. }
  48. batchSend := user.bridge.SpecVersions.Supports(mautrix.BeeperFeatureBatchSending)
  49. if batchSend {
  50. // Start the backfill queue.
  51. user.BackfillQueue = &BackfillQueue{
  52. BackfillQuery: user.bridge.DB.Backfill,
  53. reCheckChannels: []chan bool{},
  54. log: user.log.Sub("BackfillQueue"),
  55. }
  56. forwardAndImmediate := []database.BackfillType{database.BackfillImmediate, database.BackfillForward}
  57. // Immediate backfills can be done in parallel
  58. for i := 0; i < user.bridge.Config.Bridge.HistorySync.Immediate.WorkerCount; i++ {
  59. go user.HandleBackfillRequestsLoop(forwardAndImmediate, []database.BackfillType{})
  60. }
  61. // Deferred backfills should be handled synchronously so as not to
  62. // overload the homeserver. Users can configure their backfill stages
  63. // to be more or less aggressive with backfilling at this stage.
  64. go user.HandleBackfillRequestsLoop([]database.BackfillType{database.BackfillDeferred}, forwardAndImmediate)
  65. }
  66. if user.bridge.Config.Bridge.HistorySync.MediaRequests.AutoRequestMedia &&
  67. user.bridge.Config.Bridge.HistorySync.MediaRequests.RequestMethod == config.MediaRequestMethodLocalTime {
  68. go user.dailyMediaRequestLoop()
  69. }
  70. // Always save the history syncs for the user. If they want to enable
  71. // backfilling in the future, we will have it in the database.
  72. for {
  73. select {
  74. case evt := <-user.historySyncs:
  75. if evt == nil {
  76. return
  77. }
  78. user.storeHistorySync(evt.Data)
  79. case <-user.enqueueBackfillsTimer.C:
  80. if batchSend {
  81. user.enqueueAllBackfills()
  82. } else {
  83. user.backfillAll()
  84. }
  85. }
  86. }
  87. }
  88. const EnqueueBackfillsDelay = 30 * time.Second
  89. func (user *User) enqueueAllBackfills() {
  90. nMostRecent := user.bridge.DB.HistorySync.GetNMostRecentConversations(user.MXID, user.bridge.Config.Bridge.HistorySync.MaxInitialConversations)
  91. if len(nMostRecent) > 0 {
  92. user.log.Infofln("%v has passed since the last history sync blob, enqueueing backfills for %d chats", EnqueueBackfillsDelay, len(nMostRecent))
  93. // Find the portals for all the conversations.
  94. portals := []*Portal{}
  95. for _, conv := range nMostRecent {
  96. jid, err := types.ParseJID(conv.ConversationID)
  97. if err != nil {
  98. user.log.Warnfln("Failed to parse chat JID '%s' in history sync: %v", conv.ConversationID, err)
  99. continue
  100. }
  101. portals = append(portals, user.GetPortalByJID(jid))
  102. }
  103. user.EnqueueImmediateBackfills(portals)
  104. user.EnqueueForwardBackfills(portals)
  105. user.EnqueueDeferredBackfills(portals)
  106. // Tell the queue to check for new backfill requests.
  107. user.BackfillQueue.ReCheck()
  108. }
  109. }
  110. func (user *User) backfillAll() {
  111. conversations := user.bridge.DB.HistorySync.GetNMostRecentConversations(user.MXID, -1)
  112. if len(conversations) > 0 {
  113. user.zlog.Info().
  114. Int("conversation_count", len(conversations)).
  115. Msg("Probably received all history sync blobs, now backfilling conversations")
  116. limit := user.bridge.Config.Bridge.HistorySync.MaxInitialConversations
  117. // Find the portals for all the conversations.
  118. for i, conv := range conversations {
  119. jid, err := types.ParseJID(conv.ConversationID)
  120. if err != nil {
  121. user.zlog.Warn().Err(err).
  122. Str("conversation_id", conv.ConversationID).
  123. Msg("Failed to parse chat JID in history sync")
  124. continue
  125. }
  126. portal := user.GetPortalByJID(jid)
  127. if portal.MXID != "" {
  128. user.zlog.Debug().
  129. Str("portal_jid", portal.Key.JID.String()).
  130. Msg("Chat already has a room, deleting messages from database")
  131. user.bridge.DB.HistorySync.DeleteConversation(user.MXID, portal.Key.JID.String())
  132. } else if limit < 0 || i < limit {
  133. err = portal.CreateMatrixRoom(user, nil, true, true)
  134. if err != nil {
  135. user.zlog.Err(err).Msg("Failed to create Matrix room for backfill")
  136. }
  137. }
  138. }
  139. }
  140. }
  141. func (portal *Portal) legacyBackfill(user *User) {
  142. defer portal.latestEventBackfillLock.Unlock()
  143. // This should only be called from CreateMatrixRoom which locks latestEventBackfillLock before creating the room.
  144. if portal.latestEventBackfillLock.TryLock() {
  145. panic("legacyBackfill() called without locking latestEventBackfillLock")
  146. }
  147. // TODO use portal.zlog instead of user.zlog
  148. log := user.zlog.With().
  149. Str("portal_jid", portal.Key.JID.String()).
  150. Str("action", "legacy backfill").
  151. Logger()
  152. conv := user.bridge.DB.HistorySync.GetConversation(user.MXID, portal.Key)
  153. messages := user.bridge.DB.HistorySync.GetMessagesBetween(user.MXID, portal.Key.JID.String(), nil, nil, portal.bridge.Config.Bridge.HistorySync.MessageCount)
  154. log.Debug().Int("message_count", len(messages)).Msg("Got messages to backfill from database")
  155. for i := len(messages) - 1; i >= 0; i-- {
  156. msgEvt, err := user.Client.ParseWebMessage(portal.Key.JID, messages[i])
  157. if err != nil {
  158. log.Warn().Err(err).
  159. Int("msg_index", i).
  160. Str("msg_id", messages[i].GetKey().GetId()).
  161. Uint64("msg_time_seconds", messages[i].GetMessageTimestamp()).
  162. Msg("Dropping historical message due to parse error")
  163. continue
  164. }
  165. portal.handleMessage(user, msgEvt)
  166. }
  167. if conv != nil {
  168. isUnread := conv.MarkedAsUnread || conv.UnreadCount > 0
  169. isTooOld := user.bridge.Config.Bridge.HistorySync.UnreadHoursThreshold > 0 && conv.LastMessageTimestamp.Before(time.Now().Add(time.Duration(-user.bridge.Config.Bridge.HistorySync.UnreadHoursThreshold)*time.Hour))
  170. shouldMarkAsRead := !isUnread || isTooOld
  171. if shouldMarkAsRead {
  172. user.markSelfReadFull(portal)
  173. }
  174. }
  175. log.Debug().Msg("Backfill complete, deleting leftover messages from database")
  176. user.bridge.DB.HistorySync.DeleteConversation(user.MXID, portal.Key.JID.String())
  177. }
  178. func (user *User) dailyMediaRequestLoop() {
  179. // Calculate when to do the first set of media retry requests
  180. now := time.Now()
  181. userTz, err := time.LoadLocation(user.Timezone)
  182. if err != nil {
  183. userTz = now.Local().Location()
  184. }
  185. tonightMidnight := time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, userTz)
  186. midnightOffset := time.Duration(user.bridge.Config.Bridge.HistorySync.MediaRequests.RequestLocalTime) * time.Minute
  187. requestStartTime := tonightMidnight.Add(midnightOffset)
  188. // If the request time for today has already happened, we need to start the
  189. // request loop tomorrow instead.
  190. if requestStartTime.Before(now) {
  191. requestStartTime = requestStartTime.AddDate(0, 0, 1)
  192. }
  193. // Wait to start the loop
  194. user.log.Infof("Waiting until %s to do media retry requests", requestStartTime)
  195. time.Sleep(time.Until(requestStartTime))
  196. for {
  197. mediaBackfillRequests := user.bridge.DB.MediaBackfillRequest.GetMediaBackfillRequestsForUser(user.MXID)
  198. user.log.Infof("Sending %d media retry requests", len(mediaBackfillRequests))
  199. // Send all of the media backfill requests for the user at once
  200. for _, req := range mediaBackfillRequests {
  201. portal := user.GetPortalByJID(req.PortalKey.JID)
  202. _, err := portal.requestMediaRetry(user, req.EventID, req.MediaKey)
  203. if err != nil {
  204. user.log.Warnf("Failed to send media retry request for %s / %s", req.PortalKey.String(), req.EventID)
  205. req.Status = database.MediaBackfillRequestStatusRequestFailed
  206. req.Error = err.Error()
  207. } else {
  208. user.log.Debugfln("Sent media retry request for %s / %s", req.PortalKey.String(), req.EventID)
  209. req.Status = database.MediaBackfillRequestStatusRequested
  210. }
  211. req.MediaKey = nil
  212. req.Upsert()
  213. }
  214. // Wait for 24 hours before making requests again
  215. time.Sleep(24 * time.Hour)
  216. }
  217. }
  218. func (user *User) backfillInChunks(req *database.Backfill, conv *database.HistorySyncConversation, portal *Portal) {
  219. portal.backfillLock.Lock()
  220. defer portal.backfillLock.Unlock()
  221. if len(portal.MXID) > 0 && !user.bridge.AS.StateStore.IsInRoom(portal.MXID, user.MXID) {
  222. portal.ensureUserInvited(user)
  223. }
  224. backfillState := user.bridge.DB.Backfill.GetBackfillState(user.MXID, &portal.Key)
  225. if backfillState == nil {
  226. backfillState = user.bridge.DB.Backfill.NewBackfillState(user.MXID, &portal.Key)
  227. }
  228. backfillState.SetProcessingBatch(true)
  229. defer backfillState.SetProcessingBatch(false)
  230. var timeEnd *time.Time
  231. var forward, shouldMarkAsRead bool
  232. portal.latestEventBackfillLock.Lock()
  233. if req.BackfillType == database.BackfillForward {
  234. // TODO this overrides the TimeStart set when enqueuing the backfill
  235. // maybe the enqueue should instead include the prev event ID
  236. lastMessage := portal.bridge.DB.Message.GetLastInChat(portal.Key)
  237. start := lastMessage.Timestamp.Add(1 * time.Second)
  238. req.TimeStart = &start
  239. // Sending events at the end of the room (= latest events)
  240. forward = true
  241. } else {
  242. firstMessage := portal.bridge.DB.Message.GetFirstInChat(portal.Key)
  243. if firstMessage != nil {
  244. end := firstMessage.Timestamp.Add(-1 * time.Second)
  245. timeEnd = &end
  246. user.log.Debugfln("Limiting backfill to end at %v", end)
  247. } else {
  248. // Portal is empty -> events are latest
  249. forward = true
  250. }
  251. }
  252. if !forward {
  253. // We'll use normal batch sending, so no need to keep blocking new message processing
  254. portal.latestEventBackfillLock.Unlock()
  255. } else {
  256. // This might involve sending events at the end of the room as non-historical events,
  257. // make sure we don't process messages until this is done.
  258. defer portal.latestEventBackfillLock.Unlock()
  259. isUnread := conv.MarkedAsUnread || conv.UnreadCount > 0
  260. isTooOld := user.bridge.Config.Bridge.HistorySync.UnreadHoursThreshold > 0 && conv.LastMessageTimestamp.Before(time.Now().Add(time.Duration(-user.bridge.Config.Bridge.HistorySync.UnreadHoursThreshold)*time.Hour))
  261. shouldMarkAsRead = !isUnread || isTooOld
  262. }
  263. allMsgs := user.bridge.DB.HistorySync.GetMessagesBetween(user.MXID, conv.ConversationID, req.TimeStart, timeEnd, req.MaxTotalEvents)
  264. sendDisappearedNotice := false
  265. // If expired messages are on, and a notice has not been sent to this chat
  266. // about it having disappeared messages at the conversation timestamp, send
  267. // a notice indicating so.
  268. if len(allMsgs) == 0 && conv.EphemeralExpiration != nil && *conv.EphemeralExpiration > 0 {
  269. lastMessage := portal.bridge.DB.Message.GetLastInChat(portal.Key)
  270. if lastMessage == nil || conv.LastMessageTimestamp.After(lastMessage.Timestamp) {
  271. sendDisappearedNotice = true
  272. }
  273. }
  274. if !sendDisappearedNotice && len(allMsgs) == 0 {
  275. user.log.Debugfln("Not backfilling %s: no bridgeable messages found", portal.Key.JID)
  276. return
  277. }
  278. if len(portal.MXID) == 0 {
  279. user.log.Debugln("Creating portal for", portal.Key.JID, "as part of history sync handling")
  280. err := portal.CreateMatrixRoom(user, nil, true, false)
  281. if err != nil {
  282. user.log.Errorfln("Failed to create room for %s during backfill: %v", portal.Key.JID, err)
  283. return
  284. }
  285. }
  286. // Update the backfill status here after the room has been created.
  287. portal.updateBackfillStatus(backfillState)
  288. if sendDisappearedNotice {
  289. user.log.Debugfln("Sending notice to %s that there are disappeared messages ending at %v", portal.Key.JID, conv.LastMessageTimestamp)
  290. resp, err := portal.sendMessage(portal.MainIntent(), event.EventMessage, &event.MessageEventContent{
  291. MsgType: event.MsgNotice,
  292. Body: portal.formatDisappearingMessageNotice(),
  293. }, nil, conv.LastMessageTimestamp.UnixMilli())
  294. if err != nil {
  295. portal.log.Errorln("Error sending disappearing messages notice event")
  296. return
  297. }
  298. msg := portal.bridge.DB.Message.New()
  299. msg.Chat = portal.Key
  300. msg.MXID = resp.EventID
  301. msg.JID = types.MessageID(resp.EventID)
  302. msg.Timestamp = conv.LastMessageTimestamp
  303. msg.SenderMXID = portal.MainIntent().UserID
  304. msg.Sent = true
  305. msg.Type = database.MsgFake
  306. msg.Insert(nil)
  307. user.markSelfReadFull(portal)
  308. return
  309. }
  310. user.log.Infofln("Backfilling %d messages in %s, %d messages at a time (queue ID: %d)", len(allMsgs), portal.Key.JID, req.MaxBatchEvents, req.QueueID)
  311. toBackfill := allMsgs[0:]
  312. for len(toBackfill) > 0 {
  313. var msgs []*waProto.WebMessageInfo
  314. if len(toBackfill) <= req.MaxBatchEvents || req.MaxBatchEvents < 0 {
  315. msgs = toBackfill
  316. toBackfill = nil
  317. } else {
  318. msgs = toBackfill[:req.MaxBatchEvents]
  319. toBackfill = toBackfill[req.MaxBatchEvents:]
  320. }
  321. if len(msgs) > 0 {
  322. time.Sleep(time.Duration(req.BatchDelay) * time.Second)
  323. user.log.Debugfln("Backfilling %d messages in %s (queue ID: %d)", len(msgs), portal.Key.JID, req.QueueID)
  324. portal.backfill(user, msgs, forward, shouldMarkAsRead)
  325. }
  326. }
  327. user.log.Debugfln("Finished backfilling %d messages in %s (queue ID: %d)", len(allMsgs), portal.Key.JID, req.QueueID)
  328. err := user.bridge.DB.HistorySync.DeleteMessages(user.MXID, conv.ConversationID, allMsgs)
  329. if err != nil {
  330. user.log.Warnfln("Failed to delete %d history sync messages after backfilling (queue ID: %d): %v", len(allMsgs), req.QueueID, err)
  331. }
  332. if req.TimeStart == nil {
  333. // If the time start is nil, then there's no more history to backfill.
  334. backfillState.BackfillComplete = true
  335. if conv.EndOfHistoryTransferType == waProto.Conversation_COMPLETE_BUT_MORE_MESSAGES_REMAIN_ON_PRIMARY {
  336. // Since there are more messages on the phone, but we can't
  337. // backfill any more of them, indicate that the last timestamp
  338. // that we expect to be backfilled is the oldest one that was just
  339. // backfilled.
  340. backfillState.FirstExpectedTimestamp = allMsgs[len(allMsgs)-1].GetMessageTimestamp()
  341. } else if conv.EndOfHistoryTransferType == waProto.Conversation_COMPLETE_AND_NO_MORE_MESSAGE_REMAIN_ON_PRIMARY {
  342. // Since there are no more messages left on the phone, we've
  343. // backfilled everything. Indicate so by setting the expected
  344. // timestamp to 0 which means that the backfill goes to the
  345. // beginning of time.
  346. backfillState.FirstExpectedTimestamp = 0
  347. }
  348. backfillState.Upsert()
  349. portal.updateBackfillStatus(backfillState)
  350. }
  351. }
  352. func (user *User) storeHistorySync(evt *waProto.HistorySync) {
  353. if evt == nil || evt.SyncType == nil {
  354. return
  355. }
  356. log := user.bridge.ZLog.With().
  357. Str("method", "User.storeHistorySync").
  358. Str("user_id", user.MXID.String()).
  359. Str("sync_type", evt.GetSyncType().String()).
  360. Uint32("chunk_order", evt.GetChunkOrder()).
  361. Uint32("progress", evt.GetProgress()).
  362. Logger()
  363. if evt.GetGlobalSettings() != nil {
  364. log.Debug().Interface("global_settings", evt.GetGlobalSettings()).Msg("Got global settings in history sync")
  365. }
  366. if evt.GetSyncType() == waProto.HistorySync_INITIAL_STATUS_V3 || evt.GetSyncType() == waProto.HistorySync_PUSH_NAME || evt.GetSyncType() == waProto.HistorySync_NON_BLOCKING_DATA {
  367. log.Debug().
  368. Int("conversation_count", len(evt.GetConversations())).
  369. Int("pushname_count", len(evt.GetPushnames())).
  370. Int("status_count", len(evt.GetStatusV3Messages())).
  371. Int("recent_sticker_count", len(evt.GetRecentStickers())).
  372. Int("past_participant_count", len(evt.GetPastParticipants())).
  373. Msg("Ignoring history sync")
  374. return
  375. }
  376. log.Info().
  377. Int("conversation_count", len(evt.GetConversations())).
  378. Int("past_participant_count", len(evt.GetPastParticipants())).
  379. Msg("Storing history sync")
  380. successfullySavedTotal := 0
  381. totalMessageCount := 0
  382. for _, conv := range evt.GetConversations() {
  383. jid, err := types.ParseJID(conv.GetId())
  384. if err != nil {
  385. totalMessageCount += len(conv.GetMessages())
  386. log.Warn().Err(err).
  387. Str("chat_jid", conv.GetId()).
  388. Int("msg_count", len(conv.GetMessages())).
  389. Msg("Failed to parse chat JID in history sync")
  390. continue
  391. } else if jid.Server == types.BroadcastServer {
  392. log.Debug().Str("chat_jid", jid.String()).Msg("Skipping broadcast list in history sync")
  393. continue
  394. } else if jid.Server == types.HiddenUserServer {
  395. log.Debug().Str("chat_jid", jid.String()).Msg("Skipping hidden user JID chat in history sync")
  396. continue
  397. }
  398. totalMessageCount += len(conv.GetMessages())
  399. portal := user.GetPortalByJID(jid)
  400. log := log.With().
  401. Str("chat_jid", portal.Key.JID.String()).
  402. Int("msg_count", len(conv.GetMessages())).
  403. Logger()
  404. historySyncConversation := user.bridge.DB.HistorySync.NewConversationWithValues(
  405. user.MXID,
  406. conv.GetId(),
  407. &portal.Key,
  408. getConversationTimestamp(conv),
  409. conv.GetMuteEndTime(),
  410. conv.GetArchived(),
  411. conv.GetPinned(),
  412. conv.GetDisappearingMode().GetInitiator(),
  413. conv.GetEndOfHistoryTransferType(),
  414. conv.EphemeralExpiration,
  415. conv.GetMarkedAsUnread(),
  416. conv.GetUnreadCount())
  417. historySyncConversation.Upsert()
  418. var minTime, maxTime time.Time
  419. var minTimeIndex, maxTimeIndex int
  420. successfullySaved := 0
  421. unsupportedTypes := 0
  422. for i, rawMsg := range conv.GetMessages() {
  423. // Don't store messages that will just be skipped.
  424. msgEvt, err := user.Client.ParseWebMessage(portal.Key.JID, rawMsg.GetMessage())
  425. if err != nil {
  426. log.Warn().Err(err).
  427. Int("msg_index", i).
  428. Str("msg_id", rawMsg.GetMessage().GetKey().GetId()).
  429. Uint64("msg_time_seconds", rawMsg.GetMessage().GetMessageTimestamp()).
  430. Msg("Dropping historical message due to parse error")
  431. continue
  432. }
  433. if minTime.IsZero() || msgEvt.Info.Timestamp.Before(minTime) {
  434. minTime = msgEvt.Info.Timestamp
  435. minTimeIndex = i
  436. }
  437. if maxTime.IsZero() || msgEvt.Info.Timestamp.After(maxTime) {
  438. maxTime = msgEvt.Info.Timestamp
  439. maxTimeIndex = i
  440. }
  441. msgType := getMessageType(msgEvt.Message)
  442. if msgType == "unknown" || msgType == "ignore" || msgType == "unknown_protocol" {
  443. unsupportedTypes++
  444. continue
  445. }
  446. // Don't store unsupported messages.
  447. if !containsSupportedMessage(msgEvt.Message) {
  448. unsupportedTypes++
  449. continue
  450. }
  451. message, err := user.bridge.DB.HistorySync.NewMessageWithValues(user.MXID, conv.GetId(), msgEvt.Info.ID, rawMsg)
  452. if err != nil {
  453. log.Error().Err(err).
  454. Int("msg_index", i).
  455. Str("msg_id", msgEvt.Info.ID).
  456. Time("msg_time", msgEvt.Info.Timestamp).
  457. Msg("Failed to save historical message")
  458. continue
  459. }
  460. err = message.Insert()
  461. if err != nil {
  462. log.Error().Err(err).
  463. Int("msg_index", i).
  464. Str("msg_id", msgEvt.Info.ID).
  465. Time("msg_time", msgEvt.Info.Timestamp).
  466. Msg("Failed to save historical message")
  467. }
  468. successfullySaved++
  469. }
  470. successfullySavedTotal += successfullySaved
  471. log.Debug().
  472. Int("saved_count", successfullySaved).
  473. Int("unsupported_msg_type_count", unsupportedTypes).
  474. Time("lowest_time", minTime).
  475. Int("lowest_time_index", minTimeIndex).
  476. Time("highest_time", maxTime).
  477. Int("highest_time_index", maxTimeIndex).
  478. Msg("Saved messages from history sync conversation")
  479. }
  480. log.Info().
  481. Int("total_saved_count", successfullySavedTotal).
  482. Int("total_message_count", totalMessageCount).
  483. Msg("Finished storing history sync")
  484. // If this was the initial bootstrap, enqueue immediate backfills for the
  485. // most recent portals. If it's the last history sync event, start
  486. // backfilling the rest of the history of the portals.
  487. if user.bridge.Config.Bridge.HistorySync.Backfill {
  488. user.enqueueBackfillsTimer.Reset(EnqueueBackfillsDelay)
  489. }
  490. }
  491. func getConversationTimestamp(conv *waProto.Conversation) uint64 {
  492. convTs := conv.GetConversationTimestamp()
  493. if convTs == 0 && len(conv.GetMessages()) > 0 {
  494. convTs = conv.Messages[0].GetMessage().GetMessageTimestamp()
  495. }
  496. return convTs
  497. }
  498. func (user *User) EnqueueImmediateBackfills(portals []*Portal) {
  499. for priority, portal := range portals {
  500. maxMessages := user.bridge.Config.Bridge.HistorySync.Immediate.MaxEvents
  501. initialBackfill := user.bridge.DB.Backfill.NewWithValues(user.MXID, database.BackfillImmediate, priority, &portal.Key, nil, maxMessages, maxMessages, 0)
  502. initialBackfill.Insert()
  503. }
  504. }
  505. func (user *User) EnqueueDeferredBackfills(portals []*Portal) {
  506. numPortals := len(portals)
  507. for stageIdx, backfillStage := range user.bridge.Config.Bridge.HistorySync.Deferred {
  508. for portalIdx, portal := range portals {
  509. var startDate *time.Time = nil
  510. if backfillStage.StartDaysAgo > 0 {
  511. startDaysAgo := time.Now().AddDate(0, 0, -backfillStage.StartDaysAgo)
  512. startDate = &startDaysAgo
  513. }
  514. backfillMessages := user.bridge.DB.Backfill.NewWithValues(
  515. user.MXID, database.BackfillDeferred, stageIdx*numPortals+portalIdx, &portal.Key, startDate, backfillStage.MaxBatchEvents, -1, backfillStage.BatchDelay)
  516. backfillMessages.Insert()
  517. }
  518. }
  519. }
  520. func (user *User) EnqueueForwardBackfills(portals []*Portal) {
  521. for priority, portal := range portals {
  522. lastMsg := user.bridge.DB.Message.GetLastInChat(portal.Key)
  523. if lastMsg == nil {
  524. continue
  525. }
  526. backfill := user.bridge.DB.Backfill.NewWithValues(
  527. user.MXID, database.BackfillForward, priority, &portal.Key, &lastMsg.Timestamp, -1, -1, 0)
  528. backfill.Insert()
  529. }
  530. }
  531. // endregion
  532. // region Portal backfilling
  533. func (portal *Portal) deterministicEventID(sender types.JID, messageID types.MessageID, partName string) id.EventID {
  534. data := fmt.Sprintf("%s/whatsapp/%s/%s", portal.MXID, sender.User, messageID)
  535. if partName != "" {
  536. data += "/" + partName
  537. }
  538. sum := sha256.Sum256([]byte(data))
  539. return id.EventID(fmt.Sprintf("$%s:whatsapp.com", base64.RawURLEncoding.EncodeToString(sum[:])))
  540. }
  541. var (
  542. PortalCreationDummyEvent = event.Type{Type: "fi.mau.dummy.portal_created", Class: event.MessageEventType}
  543. BackfillStatusEvent = event.Type{Type: "com.beeper.backfill_status", Class: event.StateEventType}
  544. )
  545. func (portal *Portal) backfill(source *User, messages []*waProto.WebMessageInfo, isForward, atomicMarkAsRead bool) *mautrix.RespBeeperBatchSend {
  546. var req mautrix.ReqBeeperBatchSend
  547. var infos []*wrappedInfo
  548. req.Forward = isForward
  549. if atomicMarkAsRead {
  550. req.MarkReadBy = source.MXID
  551. }
  552. portal.log.Infofln("Processing history sync with %d messages (forward: %t)", len(messages), isForward)
  553. // The messages are ordered newest to oldest, so iterate them in reverse order.
  554. for i := len(messages) - 1; i >= 0; i-- {
  555. webMsg := messages[i]
  556. msgEvt, err := source.Client.ParseWebMessage(portal.Key.JID, webMsg)
  557. if err != nil {
  558. continue
  559. }
  560. msgType := getMessageType(msgEvt.Message)
  561. if msgType == "unknown" || msgType == "ignore" || msgType == "unknown_protocol" {
  562. if msgType != "ignore" {
  563. portal.log.Debugfln("Skipping message %s with unknown type in backfill", msgEvt.Info.ID)
  564. }
  565. continue
  566. }
  567. if webMsg.GetPushName() != "" && webMsg.GetPushName() != "-" {
  568. existingContact, _ := source.Client.Store.Contacts.GetContact(msgEvt.Info.Sender)
  569. if !existingContact.Found || existingContact.PushName == "" {
  570. changed, _, err := source.Client.Store.Contacts.PutPushName(msgEvt.Info.Sender, webMsg.GetPushName())
  571. if err != nil {
  572. source.log.Errorfln("Failed to save push name of %s from historical message in device store: %v", msgEvt.Info.Sender, err)
  573. } else if changed {
  574. source.log.Debugfln("Got push name %s for %s from historical message", webMsg.GetPushName(), msgEvt.Info.Sender)
  575. }
  576. }
  577. }
  578. puppet := portal.getMessagePuppet(source, &msgEvt.Info)
  579. if puppet == nil {
  580. continue
  581. }
  582. converted := portal.convertMessage(puppet.IntentFor(portal), source, &msgEvt.Info, msgEvt.Message, true)
  583. if converted == nil {
  584. portal.log.Debugfln("Skipping unsupported message %s in backfill", msgEvt.Info.ID)
  585. continue
  586. }
  587. if converted.ReplyTo != nil {
  588. portal.SetReply(converted.Content, converted.ReplyTo, true)
  589. }
  590. err = portal.appendBatchEvents(source, converted, &msgEvt.Info, webMsg, &req.Events, &infos)
  591. if err != nil {
  592. portal.log.Errorfln("Error handling message %s during backfill: %v", msgEvt.Info.ID, err)
  593. }
  594. }
  595. portal.log.Infofln("Made %d Matrix events from messages in batch", len(req.Events))
  596. if len(req.Events) == 0 {
  597. return nil
  598. }
  599. resp, err := portal.MainIntent().BeeperBatchSend(portal.MXID, &req)
  600. if err != nil {
  601. portal.log.Errorln("Error batch sending messages:", err)
  602. return nil
  603. } else {
  604. txn, err := portal.bridge.DB.Begin()
  605. if err != nil {
  606. portal.log.Errorln("Failed to start transaction to save batch messages:", err)
  607. return nil
  608. }
  609. portal.finishBatch(txn, resp.EventIDs, infos)
  610. err = txn.Commit()
  611. if err != nil {
  612. portal.log.Errorln("Failed to commit transaction to save batch messages:", err)
  613. return nil
  614. }
  615. if portal.bridge.Config.Bridge.HistorySync.MediaRequests.AutoRequestMedia {
  616. go portal.requestMediaRetries(source, resp.EventIDs, infos)
  617. }
  618. return resp
  619. }
  620. }
  621. func (portal *Portal) requestMediaRetries(source *User, eventIDs []id.EventID, infos []*wrappedInfo) {
  622. for i, info := range infos {
  623. if info != nil && info.Error == database.MsgErrMediaNotFound && info.MediaKey != nil {
  624. switch portal.bridge.Config.Bridge.HistorySync.MediaRequests.RequestMethod {
  625. case config.MediaRequestMethodImmediate:
  626. err := source.Client.SendMediaRetryReceipt(info.MessageInfo, info.MediaKey)
  627. if err != nil {
  628. portal.log.Warnfln("Failed to send post-backfill media retry request for %s: %v", info.ID, err)
  629. } else {
  630. portal.log.Debugfln("Sent post-backfill media retry request for %s", info.ID)
  631. }
  632. case config.MediaRequestMethodLocalTime:
  633. req := portal.bridge.DB.MediaBackfillRequest.NewMediaBackfillRequestWithValues(source.MXID, &portal.Key, eventIDs[i], info.MediaKey)
  634. req.Upsert()
  635. }
  636. }
  637. }
  638. }
  639. func (portal *Portal) appendBatchEvents(source *User, converted *ConvertedMessage, info *types.MessageInfo, raw *waProto.WebMessageInfo, eventsArray *[]*event.Event, infoArray *[]*wrappedInfo) error {
  640. if portal.bridge.Config.Bridge.CaptionInMessage {
  641. converted.MergeCaption()
  642. }
  643. mainEvt, err := portal.wrapBatchEvent(info, converted.Intent, converted.Type, converted.Content, converted.Extra, "")
  644. if err != nil {
  645. return err
  646. }
  647. expirationStart := info.Timestamp
  648. if raw.GetEphemeralStartTimestamp() > 0 {
  649. expirationStart = time.Unix(int64(raw.GetEphemeralStartTimestamp()), 0)
  650. }
  651. mainInfo := &wrappedInfo{
  652. MessageInfo: info,
  653. Type: database.MsgNormal,
  654. SenderMXID: mainEvt.Sender,
  655. Error: converted.Error,
  656. MediaKey: converted.MediaKey,
  657. ExpirationStart: expirationStart,
  658. ExpiresIn: converted.ExpiresIn,
  659. }
  660. if converted.Caption != nil {
  661. captionEvt, err := portal.wrapBatchEvent(info, converted.Intent, converted.Type, converted.Caption, nil, "caption")
  662. if err != nil {
  663. return err
  664. }
  665. *eventsArray = append(*eventsArray, mainEvt, captionEvt)
  666. *infoArray = append(*infoArray, mainInfo, nil)
  667. } else {
  668. *eventsArray = append(*eventsArray, mainEvt)
  669. *infoArray = append(*infoArray, mainInfo)
  670. }
  671. if converted.MultiEvent != nil {
  672. for i, subEvtContent := range converted.MultiEvent {
  673. subEvt, err := portal.wrapBatchEvent(info, converted.Intent, converted.Type, subEvtContent, nil, fmt.Sprintf("multi-%d", i))
  674. if err != nil {
  675. return err
  676. }
  677. *eventsArray = append(*eventsArray, subEvt)
  678. *infoArray = append(*infoArray, nil)
  679. }
  680. }
  681. for _, reaction := range raw.GetReactions() {
  682. reactionEvent, reactionInfo := portal.wrapBatchReaction(source, reaction, mainEvt.ID, info.Timestamp)
  683. if reactionEvent != nil {
  684. *eventsArray = append(*eventsArray, reactionEvent)
  685. *infoArray = append(*infoArray, &wrappedInfo{
  686. MessageInfo: reactionInfo,
  687. SenderMXID: reactionEvent.Sender,
  688. ReactionTarget: info.ID,
  689. Type: database.MsgReaction,
  690. })
  691. }
  692. }
  693. return nil
  694. }
  695. func (portal *Portal) wrapBatchReaction(source *User, reaction *waProto.Reaction, mainEventID id.EventID, mainEventTS time.Time) (reactionEvent *event.Event, reactionInfo *types.MessageInfo) {
  696. var senderJID types.JID
  697. if reaction.GetKey().GetFromMe() {
  698. senderJID = source.JID.ToNonAD()
  699. } else if reaction.GetKey().GetParticipant() != "" {
  700. senderJID, _ = types.ParseJID(reaction.GetKey().GetParticipant())
  701. } else if portal.IsPrivateChat() {
  702. senderJID = portal.Key.JID
  703. }
  704. if senderJID.IsEmpty() {
  705. return
  706. }
  707. reactionInfo = &types.MessageInfo{
  708. MessageSource: types.MessageSource{
  709. Chat: portal.Key.JID,
  710. Sender: senderJID,
  711. IsFromMe: reaction.GetKey().GetFromMe(),
  712. IsGroup: portal.IsGroupChat(),
  713. },
  714. ID: reaction.GetKey().GetId(),
  715. Timestamp: mainEventTS,
  716. }
  717. puppet := portal.getMessagePuppet(source, reactionInfo)
  718. if puppet == nil {
  719. return
  720. }
  721. intent := puppet.IntentFor(portal)
  722. content := event.ReactionEventContent{
  723. RelatesTo: event.RelatesTo{
  724. Type: event.RelAnnotation,
  725. EventID: mainEventID,
  726. Key: variationselector.Add(reaction.GetText()),
  727. },
  728. }
  729. if rawTS := reaction.GetSenderTimestampMs(); rawTS >= mainEventTS.UnixMilli() && rawTS <= time.Now().UnixMilli() {
  730. reactionInfo.Timestamp = time.UnixMilli(rawTS)
  731. }
  732. wrappedContent := event.Content{Parsed: &content}
  733. intent.AddDoublePuppetValue(&wrappedContent)
  734. reactionEvent = &event.Event{
  735. ID: portal.deterministicEventID(senderJID, reactionInfo.ID, ""),
  736. Type: event.EventReaction,
  737. Content: wrappedContent,
  738. Sender: intent.UserID,
  739. Timestamp: reactionInfo.Timestamp.UnixMilli(),
  740. }
  741. return
  742. }
  743. func (portal *Portal) wrapBatchEvent(info *types.MessageInfo, intent *appservice.IntentAPI, eventType event.Type, content *event.MessageEventContent, extraContent map[string]interface{}, partName string) (*event.Event, error) {
  744. wrappedContent := event.Content{
  745. Parsed: content,
  746. Raw: extraContent,
  747. }
  748. newEventType, err := portal.encrypt(intent, &wrappedContent, eventType)
  749. if err != nil {
  750. return nil, err
  751. }
  752. intent.AddDoublePuppetValue(&wrappedContent)
  753. return &event.Event{
  754. ID: portal.deterministicEventID(info.Sender, info.ID, partName),
  755. Sender: intent.UserID,
  756. Type: newEventType,
  757. Timestamp: info.Timestamp.UnixMilli(),
  758. Content: wrappedContent,
  759. }, nil
  760. }
  761. func (portal *Portal) finishBatch(txn dbutil.Transaction, eventIDs []id.EventID, infos []*wrappedInfo) {
  762. for i, info := range infos {
  763. if info == nil {
  764. continue
  765. }
  766. eventID := eventIDs[i]
  767. portal.markHandled(txn, nil, info.MessageInfo, eventID, info.SenderMXID, true, false, info.Type, info.Error)
  768. if info.Type == database.MsgReaction {
  769. portal.upsertReaction(txn, nil, info.ReactionTarget, info.Sender, eventID, info.ID)
  770. }
  771. if info.ExpiresIn > 0 {
  772. portal.MarkDisappearing(txn, eventID, info.ExpiresIn, info.ExpirationStart)
  773. }
  774. }
  775. portal.log.Infofln("Successfully sent %d events", len(eventIDs))
  776. }
  777. func (portal *Portal) updateBackfillStatus(backfillState *database.BackfillState) {
  778. backfillStatus := "backfilling"
  779. if backfillState.BackfillComplete {
  780. backfillStatus = "complete"
  781. }
  782. _, err := portal.bridge.Bot.SendStateEvent(portal.MXID, BackfillStatusEvent, "", map[string]interface{}{
  783. "status": backfillStatus,
  784. "first_timestamp": backfillState.FirstExpectedTimestamp * 1000,
  785. })
  786. if err != nil {
  787. portal.log.Errorln("Error sending backfill status event:", err)
  788. }
  789. }
  790. // endregion