Server not calling `HandleSubscription` when client re-subscribe to previous track

Scenario: client subscribed to audio and hd track, server is forwarding objs to client without problem. Then client subscribes to md (client unsubscribes hd from server, server replys with SubscribeDone, client gets SubscribeDone message, then subscribes to md track), server is forwarding objs to client, my session_manager logs the actions above:

📜session_manager 🔢115:  🔔 Subscription received: audio
📜session_manager 🔢157:  🔔 Track subscription: audio, subscription Id: 2
📜session_manager 🔢115:  🔔 Subscription received: hd
📜session_manager 🔢157:  🔔 Track subscription: hd, subscription Id: 3
📜session_manager 🔢115:  🔔 Subscription received: md
📜session_manager 🔢157:  🔔 Track subscription: md, subscription Id: 4

Issue trigger: after client subscribed to md, and now client wanna subscribe back to hd track, but this time there is no log from session_manager that indicates this subscription to hd track, we expect(but didnot get) new logs as
```
📜session_manager 🔢115:  🔔 Subscription received: hd
📜session_manager 🔢157:  🔔 Track subscription: md, subscription Id: 5
```
to be added to the session_manager log.

Investigation:

[ ] Does the server receive the subscribe message from client when client changes subscription from md to hd?

Yes. Here’s the server log: the last two lines indicate subscription on hd track with id 5 is received and SubscribeOk is sent the client (client also gets the SubscribeOk msg)

time=2024-10-24T13:39:02.235+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.SubscribeMessage MOQ_SESSION_SERVER.message="&{SubscribeID:2 TrackAlias:2 TrackNamespace:ninja TrackName:audio SubscriberPriority:0 GroupOrder:1 FilterType:1 StartGroup:0 StartObject:0 EndGroup:0 EndObject:0 Parameters:}"
time=2024-10-24T13:39:02.235+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeOkMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:2 Expires:0s GroupOrder:1 ContentExists:false FinalGroup:0 FinalObject:0}"
time=2024-10-24T13:39:02.238+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.SubscribeMessage MOQ_SESSION_SERVER.message="&{SubscribeID:3 TrackAlias:3 TrackNamespace:ninja TrackName:hd SubscriberPriority:0 GroupOrder:1 FilterType:1 StartGroup:0 StartObject:0 EndGroup:0 EndObject:0 Parameters:}"
time=2024-10-24T13:39:02.238+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeOkMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:3 Expires:0s GroupOrder:1 ContentExists:false FinalGroup:0 FinalObject:0}"
time=2024-10-24T13:39:09.558+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.UnsubscribeMessage MOQ_SESSION_SERVER.message=&{SubscribeID:3}
time=2024-10-24T13:39:09.558+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeDoneMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:3 StatusCode:0 ReasonPhrase:unsubscribed ContentExists:false FinalGroup:0 FinalObject:0}"
time=2024-10-24T13:39:09.559+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.SubscribeMessage MOQ_SESSION_SERVER.message="&{SubscribeID:4 TrackAlias:4 TrackNamespace:ninja TrackName:md SubscriberPriority:0 GroupOrder:1 FilterType:1 StartGroup:0 StartObject:0 EndGroup:0 EndObject:0 Parameters:}"
time=2024-10-24T13:39:09.560+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeOkMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:4 Expires:0s GroupOrder:1 ContentExists:false FinalGroup:0 FinalObject:0}"
time=2024-10-24T13:39:24.030+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.UnsubscribeMessage MOQ_SESSION_SERVER.message=&{SubscribeID:4}
time=2024-10-24T13:39:24.030+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeDoneMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:4 StatusCode:0 ReasonPhrase:unsubscribed ContentExists:false FinalGroup:0 FinalObject:0}"
time=2024-10-24T13:39:24.031+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/session.go:330 msg="received control message" MOQ_SESSION_SERVER.type=*wire.SubscribeMessage MOQ_SESSION_SERVER.message="&{SubscribeID:5 TrackAlias:5 TrackNamespace:ninja TrackName:hd SubscriberPriority:0 GroupOrder:1 FilterType:1 StartGroup:0 StartObject:0 EndGroup:0 EndObject:0 Parameters:}"
time=2024-10-24T13:39:24.031+02:00 level=INFO source=/Users/enderwang/go/pkg/mod/github.com/mengelbart/moqtransport@v0.3.1-0.20240715134205-0c18f3a3b439/control_stream.go:64 msg="sending control message" MOQ_CONTROL_STREAM.type=*wire.SubscribeOkMessage MOQ_CONTROL_STREAM.message="&{SubscribeID:5 Expires:0s GroupOrder:1 ContentExists:false FinalGroup:0 FinalObject:0}"

[ ] If server gets the subscribe message, is server forwarding objs to client?
- No. Even tho server got the subscription on hd track with id 5, and responded with SubscribeOk, we did not see a log in the session manager that indicates session_manager gets the subscription on hd track with id 5, hence no new LocalTrack is returned to this subscription with id 5, so client is not getting any objs on hd video track (client is getting audio track objs all the time).
```
// session_manager.go
func (sm *sessionManager) HandleSubscription(subscriberSession *moqtransport.Session, s *moqtransport.Subscription, srw moqtransport.SubscriptionResponseWriter) {
    log.Printf("🔔 Subscription received: %s", s.TrackName) // Line 115
    ...
}
```
So the problem happens on the server side that it gets the subscription on hd track with id 5, but did not call HandleSubscription to handle it.

Possible cause:

this function is blocking?

// local_track.go
func (t *LocalTrack) subscribe(
    subscriber ObjectWriter,
) (subscriberID, error) {
    if subscriber == nil {
        return 0, errors.New("nil subscriber")
    }
    addOp := addSubscriberOp{
        subscriber: subscriber,
        resultCh:   make(chan subscriberID),
    }
    // TODO: Should this have a timeout or similar?
    t.addSubscriberCh <- addOp
    res := <-addOp.resultCh
    return res, nil
}

or related to:

// session.go
func (s *Session) handleSubscribe(msg *wire.SubscribeMessage) {
    var authValue string
    auth, ok := msg.Parameters[wire.AuthorizationParameterKey]
    authString, isStringParam := auth.(*wire.StringParameter)
    if ok && isStringParam {
        authValue = authString.Value
    }
    sub := &Subscription{
        ID:            msg.SubscribeID,
        TrackAlias:    msg.TrackAlias,
        Namespace:     msg.TrackNamespace,
        TrackName:     msg.TrackName,
        Authorization: authValue,
    }
    t, ok := s.si.localTracks.get(trackKey{
        namespace: msg.TrackNamespace,
        trackname: msg.TrackName,
    })
    if ok {
        s.subscribeToLocalTrack(sub, t)
        return
    }
    if s.SubscriptionHandler != nil {
        s.SubscriptionHandler.HandleSubscription(s, sub, &defaultSubscriptionResponseWriter{
            subscription: sub,
            session:      s,
        })
        return
    }
    s.rejectSubscription(sub, ErrorCodeTrackNotFound, "track not found")
}

mengelbart / moqtransport

Server not calling `HandleSubscription` when client re-subscribe to previous track #156