ServerJoin event not sent

[j178]

I enabled join_leave on channel, the client did receive ServerLeave event when unsubscribed, but never a SeverJoin event when subscribed.

Centrifugo version:
Centrifugo v3.2.2 (Go version: go1.17.11)

Server config

{
 "token_hmac_secret_key":"secret",
 "admin_password":"e28338ac-eb67-457a-bfe8-4adf7bb30745",
 "admin_secret":"3d32207c-d725-4817-9d8e-f0e11faeced4",
 "api_key":"ba7a2b9e-60f2-4552-84b1-af3bc026b788",
 "allowed_origins":[
    "http://localhost:*"
 ],
 "namespaces":[
    {
       "name":"channel",
       "join_leave":true
    }
 ]
}

Client program `main.go`

package main

import (
    "github.com/centrifugal/centrifuge-go"
    "github.com/golang-jwt/jwt"
    "log"
    "os"
)


func connToken(user string, exp int64) string {
    claims := jwt.MapClaims{"sub": user}
    if exp > 0 {
        claims["exp"] = exp
    }
    t, err := jwt.NewWithClaims(jwt.SigningMethodHS256, claims).SignedString([]byte("secret"))
    if err != nil {
        panic(err)
    }
    return t
}

type eventHandler struct{}

func (h *eventHandler) OnServerSubscribe(_ *centrifuge.Client, e centrifuge.ServerSubscribeEvent) {
    log.Printf(
        "Subscribe to server-side channel %s: (resubscribe: %t, recovered: %t)",
        e.Channel,
        e.Resubscribed,
        e.Recovered,
    )
}

func (h *eventHandler) OnServerUnsubscribe(_ *centrifuge.Client, e centrifuge.ServerUnsubscribeEvent) {
    log.Printf("Unsubscribe from server-side channel %s", e.Channel)
}

func (h *eventHandler) OnServerJoin(_ *centrifuge.Client, e centrifuge.ServerJoinEvent) {
    log.Printf("Server-side join to channel %s: %s (%s)", e.Channel, e.User, e.Client)
}

func (h *eventHandler) OnServerLeave(_ *centrifuge.Client, e centrifuge.ServerLeaveEvent) {
    log.Printf("Server-side leave from channel %s: %s (%s)", e.Channel, e.User, e.Client)
}

func newClient(handler *eventHandler, user string) *centrifuge.Client {
    wsURL := "ws://localhost:8000/connection/websocket"
    c := centrifuge.NewJsonClient(wsURL, centrifuge.DefaultConfig())
    c.SetToken(connToken(user, 0))
    c.OnServerSubscribe(handler)
    c.OnServerUnsubscribe(handler)
    c.OnServerJoin(handler)
    c.OnServerLeave(handler)

    return c
}

func main() {
    handler := &eventHandler{}
    user := os.Args[1]

    c := newClient(handler, user)
    defer func() { _ = c.Close() }()

    err := c.Connect()
    if err != nil {
        log.Fatalln(err)
    }

    select {}
}

Steps to reproduce:

# 1. run the server
centrifugo -c config.json --log_level trace

# 2. start client `alice`
go run main.go alice

# 3. subscribe `alice` to `channel:1` using HTTP API
curl http://localhost:8000/api -H 'Authorization: apikey ba7a2b9e-60f2-4552-84b1-af3bc026b788' -X POST --data '{"method": "subscribe", "params": {"user": "alice", "channel": "channel:1"}}'

# 4. start client `bob`
go run main.go bob

# 5. subscribe `bob` to `channel:1`
curl http://localhost:8000/api -H 'Authorization: apikey ba7a2b9e-60f2-4552-84b1-af3bc026b788' -X POST --data '{"method": "subscribe", "params": {"user": "bob", "channel": "channel:1"}}'

# !!! problem occured, alice doesn't get a ServerJoin event.

# 6.  unsubscribe `bob` from `channel:1` 
curl http://localhost:8000/api -H 'Authorization: apikey ba7a2b9e-60f2-4552-84b1-af3bc026b788' -X POST --data '{"method": "unsubscribe", "params": {"user": "bob", "channel": "channel:1"}}'

# Both `alice` and `bob` got the `ServerLeave` event.

Server trace log

2022-06-30 01:41:37 [INF] starting Centrifugo engine=Memory gomaxprocs=12 pid=84720 runtime=go1.17.11 version=3.2.2
2022-06-30 01:41:37 [INF] using config file path=/tmp/config.json
2022-06-30 01:41:37 [INF] enabled JWT verifiers algorithms="HS256, HS384, HS512"
2022-06-30 01:41:37 [INF] serving websocket, API endpoints on :8000
2022-06-30 01:41:42 [DBG] http request addr=[::1]:51748 duration="130.317µs" method=GET path=/connection/websocket status=101
2022-06-30 01:41:42 [DBG] client connection established client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 transport=websocket
2022-06-30 01:41:42 [TRC] <-- client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 data="\"{\\\"id\\\":1,\\\"params\\\":{\\\"token\\\":\\\"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJhbGljZSJ9.c3brGQkxoiCgrl5LGiV0go9qgN0MtrdnDBCCfJ45f_Q\\\",\\\"name\\\":\\\"go\\\"}}\"" user=
2022-06-30 01:41:42 [DBG] client authenticated client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 user=alice
2022-06-30 01:41:42 [TRC] --> client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 data="\"{\\\"id\\\":1,\\\"result\\\":{\\\"client\\\":\\\"1a6c1052-928c-48a1-a60f-b4ff27a642e7\\\",\\\"version\\\":\\\"3.2.2\\\"}}\"" user=alice
2022-06-30 01:41:50 [DBG] client subscribed to channel channel=channel:1 client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 user=alice
2022-06-30 01:41:50 [TRC] --> client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 data="\"{\\\"result\\\":{\\\"type\\\":5,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{}}}\"" user=alice
2022-06-30 01:41:50 [DBG] http request addr=127.0.0.1:51793 duration="436.473µs" method=POST path=/api status=200
2022-06-30 01:41:54 [DBG] http request addr=[::1]:51821 duration="77.857µs" method=GET path=/connection/websocket status=101
2022-06-30 01:41:54 [DBG] client connection established client=5c59645b-d75e-4d4c-96a0-1508187bafe8 transport=websocket
2022-06-30 01:41:54 [TRC] <-- client=5c59645b-d75e-4d4c-96a0-1508187bafe8 data="\"{\\\"id\\\":1,\\\"params\\\":{\\\"token\\\":\\\"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJib2IifQ.-51G5JQmpJleARHp8rIljBczPFanWT93d_N_7LQGUXU\\\",\\\"name\\\":\\\"go\\\"}}\"" user=
2022-06-30 01:41:54 [DBG] client authenticated client=5c59645b-d75e-4d4c-96a0-1508187bafe8 user=bob
2022-06-30 01:41:54 [TRC] --> client=5c59645b-d75e-4d4c-96a0-1508187bafe8 data="\"{\\\"id\\\":1,\\\"result\\\":{\\\"client\\\":\\\"5c59645b-d75e-4d4c-96a0-1508187bafe8\\\",\\\"version\\\":\\\"3.2.2\\\"}}\"" user=bob
2022-06-30 01:41:59 [DBG] client subscribed to channel channel=channel:1 client=5c59645b-d75e-4d4c-96a0-1508187bafe8 user=bob
2022-06-30 01:41:59 [DBG] http request addr=127.0.0.1:51848 duration="140.787µs" method=POST path=/api status=200
2022-06-30 01:41:59 [TRC] --> client=5c59645b-d75e-4d4c-96a0-1508187bafe8 data="\"{\\\"result\\\":{\\\"type\\\":5,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{}}}\"" user=bob
2022-06-30 01:42:03 [DBG] client unsubscribed from channel channel=channel:1 client=5c59645b-d75e-4d4c-96a0-1508187bafe8 user=bob
2022-06-30 01:42:03 [DBG] http request addr=127.0.0.1:51868 duration="324.795µs" method=POST path=/api status=200
2022-06-30 01:42:03 [TRC] --> client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 data="\"{\\\"result\\\":{\\\"type\\\":2,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{\\\"info\\\":{\\\"user\\\":\\\"bob\\\",\\\"client\\\":\\\"5c59645b-d75e-4d4c-96a0-1508187bafe8\\\"}}}}\"" user=alice
2022-06-30 01:42:03 [TRC] --> client=5c59645b-d75e-4d4c-96a0-1508187bafe8 data="\"{\\\"result\\\":{\\\"type\\\":2,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{\\\"info\\\":{\\\"user\\\":\\\"bob\\\",\\\"client\\\":\\\"5c59645b-d75e-4d4c-96a0-1508187bafe8\\\"}}}}\"" user=bob
2022-06-30 01:42:03 [TRC] --> client=5c59645b-d75e-4d4c-96a0-1508187bafe8 data="\"{\\\"result\\\":{\\\"type\\\":3,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{\\\"code\\\":2000,\\\"reason\\\":\\\"server unsubscribe\\\"}}}\"" user=bob
^C2022-06-30 01:42:05 [INF] signal received: interrupt
2022-06-30 01:42:05 [INF] shutting down ...
2022-06-30 01:42:05 [DBG] client unsubscribed from channel channel=channel:1 client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 user=alice
2022-06-30 01:42:05 [TRC] --> client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 data="\"{\\\"result\\\":{\\\"type\\\":2,\\\"channel\\\":\\\"channel:1\\\",\\\"data\\\":{\\\"info\\\":{\\\"user\\\":\\\"alice\\\",\\\"client\\\":\\\"1a6c1052-928c-48a1-a60f-b4ff27a642e7\\\"}}}}\"" user=alice
2022-06-30 01:42:05 [DBG] client connection completed client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 duration=23639.94935 transport=websocket
2022-06-30 01:42:05 [DBG] client connection completed client=5c59645b-d75e-4d4c-96a0-1508187bafe8 duration=10882.313435 transport=websocket
2022-06-30 01:42:05 [DBG] closing client connection client=5c59645b-d75e-4d4c-96a0-1508187bafe8 reason=shutdown user=bob
2022-06-30 01:42:05 [DBG] closing client connection client=1a6c1052-928c-48a1-a60f-b4ff27a642e7 reason=shutdown user=alice

[FZambia]

Thanks for opening and for a detailed description!

The reason is that dynamic Subscribe is one more path in code, and the emission of Join was simply missed in it.

#232 should fix the issue

Just a note: join and leave messages are sent on a best-effort basis, with at most once only delivery guarantee.

[FZambia]

Let's reopen while it's not landed to Centrifugo.

[j178]

I can confirm it is fixed now. Thank you!

[FZambia]

Released Centrifugo v3.2.3 with the fix