package appservice import ( "context" "encoding/json" "errors" "sync" "time" "github.com/dariuszjaniak/warp/server/internal/matrix/event" "github.com/dariuszjaniak/warp/server/internal/roomserver" "github.com/dariuszjaniak/warp/server/internal/storage" ) // transactionSize is the most events one transaction carries, which is // also how far the stream is read ahead at a time. Synapse sends 100. const transactionSize = 100 // The backoff after a failed transaction: it doubles from the first value // to the second and stays there. A bridge that is down for maintenance is // tried every few minutes, not hammered, and is caught up within a minute // or so of coming back. const ( minBackoff = 2 * time.Second maxBackoff = 5 * time.Minute ) // idleRecheck is how often an idle worker looks at the stream without // being woken. Wake-ups come from the emit stage and are never missed in // a running server; this is the safety net for one that is. const idleRecheck = 30 * time.Second // Status is what the admin API shows of one service's delivery. type Status struct { ID string URL string SenderUserID string StreamPos int64 TxnID int64 Failures int LastError string LastSuccessMS int64 LastFailureMS int64 RetryAtMS int64 EventsDelivered int64 } // worker delivers to one service. type worker struct { svc *Service wake chan struct{} // retry cuts a backoff short: a service that has just answered a ping // is up, and making it wait out minutes of backoff helps nobody. retry chan struct{} mu sync.Mutex status Status } func newWorker(svc *Service) *worker { return &worker{ svc: svc, wake: make(chan struct{}, 1), retry: make(chan struct{}, 1), status: Status{ ID: svc.ID, URL: svc.URL, SenderUserID: svc.SenderUserID(), }, } } // poke wakes the worker without blocking; one pending wake-up is as good // as many. func (w *worker) poke() { select { case w.wake <- struct{}{}: default: } } // retryNow cuts the current backoff short, without blocking. func (w *worker) retryNow() { select { case w.retry <- struct{}{}: default: } } func (w *worker) update(fn func(*Status)) { w.mu.Lock() defer w.mu.Unlock() fn(&w.status) } func (w *worker) snapshot() Status { w.mu.Lock() defer w.mu.Unlock() return w.status } // run is a worker's loop: read the stream from the cursor, keep what the // service is interested in, send it as a transaction until the service // takes it, move the cursor, repeat. // // The cursor is in the database, and so is the transaction in flight, so // a restart resumes where it stopped — with the same transaction ID for // the same events, if one was being sent — and nothing is lost or sent // twice under two IDs. func (a *API) run(ctx context.Context, w *worker) { defer a.wg.Done() log := a.log.With("appservice", w.svc.ID) state, ok := a.loadState(ctx, w) if !ok { return } var pending []json.RawMessage for ctx.Err() == nil { if state.TxnTo != 0 { if pending == nil { // A transaction left in flight by an earlier run: read its // events again. events, err := a.collect(ctx, w.svc, state.StreamPos, state.TxnTo) if err != nil { log.Warn("could not read the events of a transaction in flight", "txn_id", state.TxnID, "error", err) if !sleep(ctx, minBackoff) { return } continue } pending = events } if !a.deliver(ctx, w, state.TxnID, pending) { return } if err := a.store.CompleteTransaction(ctx, w.svc.ID, state.TxnTo); err != nil { log.Warn("could not record a delivered transaction", "txn_id", state.TxnID, "error", err) if !sleep(ctx, minBackoff) { return } continue } delivered := int64(len(pending)) state.StreamPos, state.TxnTo, pending = state.TxnTo, 0, nil w.update(func(s *Status) { s.StreamPos, s.TxnID = state.StreamPos, state.TxnID s.EventsDelivered += delivered }) continue } batch, err := a.rooms.StreamEvents(ctx, state.StreamPos, 0, transactionSize) if err != nil { log.Warn("could not read the event stream", "error", err) if !sleep(ctx, minBackoff) { return } continue } if len(batch) == 0 { select { case <-ctx.Done(): return case <-w.wake: case <-time.After(idleRecheck): } continue } to := batch[len(batch)-1].Position events, err := a.interesting(ctx, w.svc, batch) if err != nil { log.Warn("could not decide which events concern the service", "error", err) if !sleep(ctx, minBackoff) { return } continue } if len(events) == 0 { // Nothing here for the service: move past it without a // transaction. if err := a.store.CompleteTransaction(ctx, w.svc.ID, to); err != nil { log.Warn("could not advance the cursor", "error", err) if !sleep(ctx, minBackoff) { return } continue } state.StreamPos = to w.update(func(s *Status) { s.StreamPos = to }) continue } txnID := state.TxnID + 1 if err := a.store.BeginTransaction(ctx, w.svc.ID, txnID, to); err != nil { log.Warn("could not record a transaction", "error", err) if !sleep(ctx, minBackoff) { return } continue } state.TxnID, state.TxnTo, pending = txnID, to, events } } // loadState reads (or starts) the service's cursor. A service seen for the // first time starts at the top of the stream: it is told what happens from // now on, not the server's whole history. func (a *API) loadState(ctx context.Context, w *worker) (storage.AppServiceState, bool) { for { top, err := a.rooms.StreamTop(ctx) if err == nil { var state storage.AppServiceState if state, err = a.store.AppServiceState(ctx, w.svc.ID, top); err == nil { w.update(func(s *Status) { s.StreamPos, s.TxnID = state.StreamPos, state.TxnID }) return state, true } } a.log.Warn("could not read an application service's cursor", "appservice", w.svc.ID, "error", err) if !sleep(ctx, minBackoff) { return storage.AppServiceState{}, false } } } // collect reads the events of (from, to] the service is interested in. func (a *API) collect(ctx context.Context, svc *Service, from, to int64) ([]json.RawMessage, error) { var out []json.RawMessage for from < to { batch, err := a.rooms.StreamEvents(ctx, from, to, transactionSize) if err != nil { return nil, err } if len(batch) == 0 { break } events, err := a.interesting(ctx, svc, batch) if err != nil { return nil, err } out = append(out, events...) from = batch[len(batch)-1].Position } if out == nil { out = []json.RawMessage{} } return out, nil } // interesting keeps the events of a batch that concern a service, encoded // for a transaction. // // An event concerns a service when its sender or (for a membership) its // target is one of the service's users, when its room is in the service's // room namespaces, or when its room has one of the service's users in it // or one of the service's aliases pointing at it. The last two are the // rules that make a bridge see the conversations its puppets are in, and // they are read once per room per batch, as the room is now: an event // read late, from a backlog, is judged by who is in the room when it is // read rather than when it happened. func (a *API) interesting(ctx context.Context, svc *Service, batch []roomserver.StreamEvent) ([]json.RawMessage, error) { rooms := map[string]bool{} var out []json.RawMessage for _, se := range batch { e := se.Event keep := svc.InterestedInUser(e.Sender) || svc.InterestedInRoom(e.RoomID) if !keep && e.Type == event.TypeMember && e.StateKey != nil { keep = svc.InterestedInUser(*e.StateKey) } if !keep { roomInterest, seen := rooms[e.RoomID] if !seen { var err error if roomInterest, err = a.roomConcerns(ctx, svc, e.RoomID); err != nil { return nil, err } rooms[e.RoomID] = roomInterest } keep = roomInterest } if !keep { continue } raw, err := json.Marshal(e) if err != nil { return nil, err } out = append(out, raw) } return out, nil } // roomConcerns reports whether a room has one of a service's users in it // or one of its aliases pointing at it. func (a *API) roomConcerns(ctx context.Context, svc *Service, roomID string) (bool, error) { members, err := a.rooms.JoinedUserIDs(ctx, roomID) if err != nil && !errors.Is(err, storage.ErrNoSuchRoom) { return false, err } for _, m := range members { if svc.OwnsUser(m) { return true, nil } } if len(svc.Namespaces.Aliases) == 0 { return false, nil } aliases, err := a.rooms.LocalAliases(ctx, roomID) if err != nil && !errors.Is(err, storage.ErrNoSuchRoom) { return false, err } for _, alias := range aliases { if svc.OwnsAlias(alias) { return true, nil } } return false, nil } // deliver sends one transaction until the service accepts it. It returns // false only when the worker is being stopped. func (a *API) deliver(ctx context.Context, w *worker, txnID int64, events []json.RawMessage) bool { backoff := minBackoff for { err := a.client.SendTransaction(ctx, w.svc, txnID, events) now := a.now().UnixMilli() if err == nil { w.update(func(s *Status) { s.Failures, s.LastError, s.RetryAtMS, s.LastSuccessMS = 0, "", 0, now }) return true } if ctx.Err() != nil { return false } w.update(func(s *Status) { s.Failures++ s.LastError = err.Error() s.LastFailureMS = now s.RetryAtMS = now + backoff.Milliseconds() }) a.log.Warn("could not deliver a transaction to an application service", "appservice", w.svc.ID, "txn_id", txnID, "events", len(events), "retry_in", backoff, "error", err) select { case <-ctx.Done(): return false case <-time.After(backoff): case <-w.retry: } backoff = min(backoff*2, maxBackoff) } } // sleep waits for d or for ctx, reporting whether the wait ran its course. func sleep(ctx context.Context, d time.Duration) bool { select { case <-ctx.Done(): return false case <-time.After(d): return true } }