From cb2a05c2705a4b3870d03d42da386402aa2c214a Mon Sep 17 00:00:00 2001 From: Joachim Bauch Date: Wed, 6 Apr 2022 14:32:33 +0200 Subject: [PATCH] Migrate to structured logging using "go.uber.org/zap". First step: migrate standard logging calls to "zap" logger calls. --- .golangci.yml | 10 ++ Makefile | 3 +- backend_client.go | 57 +++++----- backend_client_test.go | 9 +- backend_configuration.go | 45 ++++---- backend_configuration_test.go | 45 +++++--- backend_server.go | 51 ++++----- backend_server_test.go | 7 +- client.go | 39 +++---- client/main.go | 94 +++++++++------- clientsession.go | 51 ++++----- clientsession_test.go | 4 +- deferred_executor.go | 11 +- deferred_executor_test.go | 25 +++-- geoip.go | 16 +-- geoip_test.go | 12 +- go.mod | 2 +- hub.go | 159 +++++++++++++-------------- hub_test.go | 17 +-- janus_client.go | 27 ++--- logger.go | 76 +++++++++++++ logger_test.go | 46 ++++++++ mcu_janus.go | 128 +++++++++++----------- mcu_proxy.go | 200 +++++++++++++++++----------------- mcu_test.go | 9 +- natsclient.go | 26 +++-- natsclient_loopback.go | 9 +- natsclient_loopback_test.go | 3 +- natsclient_test.go | 3 +- proxy/logger_test.go | 48 ++++++++ proxy/main.go | 37 ++++--- proxy/proxy_client.go | 11 +- proxy/proxy_server.go | 88 +++++++-------- proxy/proxy_server_test.go | 3 +- proxy/proxy_session.go | 17 +-- proxy/proxy_tokens_etcd.go | 23 ++-- proxy/proxy_tokens_static.go | 23 ++-- room.go | 45 ++++---- room_test.go | 12 +- server/main.go | 88 ++++++++------- virtualsession.go | 11 +- 41 files changed, 933 insertions(+), 657 deletions(-) create mode 100644 logger.go create mode 100644 logger_test.go create mode 100644 proxy/logger_test.go diff --git a/.golangci.yml b/.golangci.yml index 32aa7ce..61c7673 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -1,9 +1,19 @@ linters: enable: - gofmt + - govet - revive linters-settings: + govet: + settings: + printf: + funcs: + - (github.com/strukturag/nextcloud-spreed-signaling.Logger).Debugf + - (github.com/strukturag/nextcloud-spreed-signaling.Logger).Errorf + - (github.com/strukturag/nextcloud-spreed-signaling.Logger).Fatalf + - (github.com/strukturag/nextcloud-spreed-signaling.Logger).Infof + - (github.com/strukturag/nextcloud-spreed-signaling.Logger).Warnf revive: ignoreGeneratedHeader: true severity: warning diff --git a/Makefile b/Makefile index d443e16..f10d8ed 100644 --- a/Makefile +++ b/Makefile @@ -12,6 +12,7 @@ VERSION := $(shell "$(CURDIR)/scripts/get-version.sh") TARVERSION := $(shell "$(CURDIR)/scripts/get-version.sh" --tar) PACKAGENAME := github.com/strukturag/nextcloud-spreed-signaling ALL_PACKAGES := $(PACKAGENAME) $(PACKAGENAME)/client $(PACKAGENAME)/proxy $(PACKAGENAME)/server +PRINTF_FUNCTIONS := ($(PACKAGENAME).Logger).Debugf,($(PACKAGENAME).Logger).Errorf,($(PACKAGENAME).Logger).Fatalf,($(PACKAGENAME).Logger).Infof,($(PACKAGENAME).Logger).Warnf ifneq ($(VERSION),) INTERNALLDFLAGS := -X main.version=$(VERSION) @@ -74,7 +75,7 @@ fmt: hook $(GOFMT) -s -w *.go client proxy server vet: common - $(GO) vet $(ALL_PACKAGES) + $(GO) vet -printf.funcs "$(PRINTF_FUNCTIONS)" $(ALL_PACKAGES) test: vet common $(GO) test -v -timeout $(TIMEOUT) $(TESTARGS) $(ALL_PACKAGES) diff --git a/backend_client.go b/backend_client.go index de64e1d..8eb07fe 100644 --- a/backend_client.go +++ b/backend_client.go @@ -29,7 +29,6 @@ import ( "errors" "fmt" "io" - "log" "net/http" "net/url" "strings" @@ -56,6 +55,7 @@ const ( ) type BackendClient struct { + logger Logger hub *Hub transport *http.Transport version string @@ -71,15 +71,15 @@ type BackendClient struct { nextCapabilities map[string]time.Time } -func NewBackendClient(config *goconf.ConfigFile, maxConcurrentRequestsPerHost int, version string) (*BackendClient, error) { - backends, err := NewBackendConfiguration(config) +func NewBackendClient(logger Logger, config *goconf.ConfigFile, maxConcurrentRequestsPerHost int, version string) (*BackendClient, error) { + backends, err := NewBackendConfiguration(logger, config) if err != nil { return nil, err } skipverify, _ := config.GetBool("backend", "skipverify") if skipverify { - log.Println("WARNING: Backend verification is disabled!") + logger.Warn("Backend verification is disabled!") } tlsconfig := &tls.Config{ @@ -91,6 +91,7 @@ func NewBackendClient(config *goconf.ConfigFile, maxConcurrentRequestsPerHost in } return &BackendClient{ + logger: logger, transport: transport, version: version, backends: backends, @@ -196,24 +197,24 @@ func (b *BackendClient) getCapabilities(ctx context.Context, u *url.URL) (map[st capUrl.Path = capUrl.Path[:pos+11] + "/cloud/capabilities" } - log.Printf("Capabilities expired for %s, updating", capUrl.String()) + b.logger.Infof("Capabilities expired for %s, updating", capUrl.String()) pool, err := b.getPool(&capUrl) if err != nil { - log.Printf("Could not get client pool for host %s: %s", capUrl.Host, err) + b.logger.Errorf("Could not get client pool for host %s: %s", capUrl.Host, err) return nil, err } c, err := pool.Get(ctx) if err != nil { - log.Printf("Could not get client for host %s: %s", capUrl.Host, err) + b.logger.Errorf("Could not get client for host %s: %s", capUrl.Host, err) return nil, err } defer pool.Put(c) req, err := http.NewRequestWithContext(ctx, "GET", capUrl.String(), nil) if err != nil { - log.Printf("Could not create request to %s: %s", &capUrl, err) + b.logger.Errorf("Could not create request to %s: %s", &capUrl, err) return nil, err } req.Header.Set("Accept", "application/json") @@ -228,38 +229,38 @@ func (b *BackendClient) getCapabilities(ctx context.Context, u *url.URL) (map[st ct := resp.Header.Get("Content-Type") if !strings.HasPrefix(ct, "application/json") { - log.Printf("Received unsupported content-type from %s: %s (%s)", capUrl.String(), ct, resp.Status) + b.logger.Errorf("Received unsupported content-type from %s: %s (%s)", capUrl.String(), ct, resp.Status) return nil, ErrUnsupportedContentType } body, err := io.ReadAll(resp.Body) if err != nil { - log.Printf("Could not read response body from %s: %s", capUrl.String(), err) + b.logger.Errorf("Could not read response body from %s: %s", capUrl.String(), err) return nil, err } var ocs OcsResponse if err := json.Unmarshal(body, &ocs); err != nil { - log.Printf("Could not decode OCS response %s from %s: %s", string(body), capUrl.String(), err) + b.logger.Errorf("Could not decode OCS response %s from %s: %s", string(body), capUrl.String(), err) return nil, err } else if ocs.Ocs == nil || ocs.Ocs.Data == nil { - log.Printf("Incomplete OCS response %s from %s", string(body), u) + b.logger.Errorf("Incomplete OCS response %s from %s", string(body), u) return nil, fmt.Errorf("incomplete OCS response") } var response CapabilitiesResponse if err := json.Unmarshal(*ocs.Ocs.Data, &response); err != nil { - log.Printf("Could not decode OCS response body %s from %s: %s", string(*ocs.Ocs.Data), capUrl.String(), err) + b.logger.Errorf("Could not decode OCS response body %s from %s: %s", string(*ocs.Ocs.Data), capUrl.String(), err) return nil, err } capa, found := response.Capabilities[AppNameSpreed] if !found { - log.Printf("No capabilities received for app spreed from %s: %+v", capUrl.String(), response) + b.logger.Errorf("No capabilities received for app %s from %s: %+v", AppNameSpreed, capUrl.String(), response) return nil, nil } - log.Printf("Received capabilities %+v from %s", capa, capUrl.String()) + b.logger.Infof("Received capabilities %+v from %s", capa, capUrl.String()) b.capabilitiesLock.Lock() b.capabilities[key] = capa b.nextCapabilities[key] = now.Add(CapabilitiesCacheDuration) @@ -270,7 +271,7 @@ func (b *BackendClient) getCapabilities(ctx context.Context, u *url.URL) (map[st func (b *BackendClient) HasCapabilityFeature(ctx context.Context, u *url.URL, feature string) bool { caps, err := b.getCapabilities(ctx, u) if err != nil { - log.Printf("Could not get capabilities for %s: %s", u, err) + b.logger.Errorf("Could not get capabilities for %s: %s", u, err) return false } @@ -281,7 +282,7 @@ func (b *BackendClient) HasCapabilityFeature(ctx context.Context, u *url.URL, fe features, ok := featuresInterface.([]interface{}) if !ok { - log.Printf("Invalid features list received for %s: %+v", u, featuresInterface) + b.logger.Errorf("Invalid features list received for %s: %+v", u, featuresInterface) return false } @@ -317,26 +318,26 @@ func (b *BackendClient) PerformJSONRequest(ctx context.Context, u *url.URL, requ pool, err := b.getPool(u) if err != nil { - log.Printf("Could not get client pool for host %s: %s", u.Host, err) + b.logger.Errorf("Could not get client pool for host %s: %s", u.Host, err) return err } c, err := pool.Get(ctx) if err != nil { - log.Printf("Could not get client for host %s: %s", u.Host, err) + b.logger.Errorf("Could not get client for host %s: %s", u.Host, err) return err } defer pool.Put(c) data, err := json.Marshal(request) if err != nil { - log.Printf("Could not marshal request %+v: %s", request, err) + b.logger.Errorf("Could not marshal request %+v: %s", request, err) return err } req, err := http.NewRequestWithContext(ctx, "POST", requestUrl.String(), bytes.NewReader(data)) if err != nil { - log.Printf("Could not create request to %s: %s", requestUrl, err) + b.logger.Errorf("Could not create request to %s: %s", requestUrl, err) return err } req.Header.Set("Content-Type", "application/json") @@ -352,20 +353,20 @@ func (b *BackendClient) PerformJSONRequest(ctx context.Context, u *url.URL, requ resp, err := c.Do(req) if err != nil { - log.Printf("Could not send request %s to %s: %s", string(data), req.URL, err) + b.logger.Errorf("Could not send request %s to %s: %s", string(data), req.URL, err) return err } defer resp.Body.Close() ct := resp.Header.Get("Content-Type") if !strings.HasPrefix(ct, "application/json") { - log.Printf("Received unsupported content-type from %s: %s (%s)", req.URL, ct, resp.Status) + b.logger.Errorf("Received unsupported content-type from %s: %s (%s)", req.URL, ct, resp.Status) return ErrUnsupportedContentType } body, err := io.ReadAll(resp.Body) if err != nil { - log.Printf("Could not read response body from %s: %s", req.URL, err) + b.logger.Errorf("Could not read response body from %s: %s", req.URL, err) return err } @@ -380,17 +381,17 @@ func (b *BackendClient) PerformJSONRequest(ctx context.Context, u *url.URL, requ // } var ocs OcsResponse if err := json.Unmarshal(body, &ocs); err != nil { - log.Printf("Could not decode OCS response %s from %s: %s", string(body), req.URL, err) + b.logger.Errorf("Could not decode OCS response %s from %s: %s", string(body), req.URL, err) return err } else if ocs.Ocs == nil || ocs.Ocs.Data == nil { - log.Printf("Incomplete OCS response %s from %s", string(body), req.URL) + b.logger.Errorf("Incomplete OCS response %s from %s", string(body), req.URL) return fmt.Errorf("incomplete OCS response") } else if err := json.Unmarshal(*ocs.Ocs.Data, response); err != nil { - log.Printf("Could not decode OCS response body %s from %s: %s", string(*ocs.Ocs.Data), req.URL, err) + b.logger.Errorf("Could not decode OCS response body %s from %s: %s", string(*ocs.Ocs.Data), req.URL, err) return err } } else if err := json.Unmarshal(body, response); err != nil { - log.Printf("Could not decode response body %s from %s: %s", string(body), req.URL, err) + b.logger.Errorf("Could not decode response body %s from %s: %s", string(body), req.URL, err) return err } return nil diff --git a/backend_client_test.go b/backend_client_test.go index c9ff35e..3367472 100644 --- a/backend_client_test.go +++ b/backend_client_test.go @@ -95,7 +95,8 @@ func TestPostOnRedirect(t *testing.T) { if u.Scheme == "http" { config.AddOption("backend", "allowhttp", "true") } - client, err := NewBackendClient(config, 1, "0.0") + logger := NewLoggerForTest(t) + client, err := NewBackendClient(logger, config, 1, "0.0") if err != nil { t.Fatal(err) } @@ -134,7 +135,8 @@ func TestPostOnRedirectDifferentHost(t *testing.T) { if u.Scheme == "http" { config.AddOption("backend", "allowhttp", "true") } - client, err := NewBackendClient(config, 1, "0.0") + logger := NewLoggerForTest(t) + client, err := NewBackendClient(logger, config, 1, "0.0") if err != nil { t.Fatal(err) } @@ -187,7 +189,8 @@ func TestPostOnRedirectStatusFound(t *testing.T) { if u.Scheme == "http" { config.AddOption("backend", "allowhttp", "true") } - client, err := NewBackendClient(config, 1, "0.0") + logger := NewLoggerForTest(t) + client, err := NewBackendClient(logger, config, 1, "0.0") if err != nil { t.Fatal(err) } diff --git a/backend_configuration.go b/backend_configuration.go index 4cde69f..31a1c1a 100644 --- a/backend_configuration.go +++ b/backend_configuration.go @@ -22,7 +22,6 @@ package signaling import ( - "log" "net/url" "reflect" "strings" @@ -106,6 +105,7 @@ func (b *Backend) RemoveSession(session Session) { } type BackendConfiguration struct { + logger Logger backends map[string][]*Backend // Deprecated @@ -114,7 +114,7 @@ type BackendConfiguration struct { compatBackend *Backend } -func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, error) { +func NewBackendConfiguration(logger Logger, config *goconf.ConfigFile) (*BackendConfiguration, error) { allowAll, _ := config.GetBool("backend", "allowall") allowHttp, _ := config.GetBool("backend", "allowhttp") commonSecret, _ := config.GetString("backend", "secret") @@ -126,7 +126,7 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, var compatBackend *Backend numBackends := 0 if allowAll { - log.Println("WARNING: All backend hostnames are allowed, only use for development!") + logger.Warn("All backend hostnames are allowed, only use for development!") compatBackend = &Backend{ id: "compat", secret: []byte(commonSecret), @@ -137,14 +137,14 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, sessionLimit: uint64(sessionLimit), } if sessionLimit > 0 { - log.Printf("Allow a maximum of %d sessions", sessionLimit) + logger.Infof("Allow a maximum of %d sessions", sessionLimit) } numBackends++ } else if backendIds, _ := config.GetString("backend", "backends"); backendIds != "" { - for host, configuredBackends := range getConfiguredHosts(backendIds, config) { + for host, configuredBackends := range getConfiguredHosts(logger, backendIds, config) { backends[host] = append(backends[host], configuredBackends...) for _, be := range configuredBackends { - log.Printf("Backend %s added for %s", be.id, be.url) + logger.Infof("Backend %s added for %s", be.id, be.url) } numBackends += len(configuredBackends) } @@ -154,7 +154,7 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, for _, u := range strings.Split(allowedUrls, ",") { u = strings.TrimSpace(u) if idx := strings.IndexByte(u, '/'); idx != -1 { - log.Printf("WARNING: Removing path from allowed hostname \"%s\", check your configuration!", u) + logger.Warnf("Removing path from allowed hostname \"%s\", check your configuration!", u) u = u[:idx] } if u != "" { @@ -163,7 +163,7 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, } if len(allowMap) == 0 { - log.Println("WARNING: No backend hostnames are allowed, check your configuration!") + logger.Warn("WARNING: No backend hostnames are allowed, check your configuration!") } else { compatBackend = &Backend{ id: "compat", @@ -180,11 +180,11 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, backends[host] = []*Backend{compatBackend} } if len(hosts) > 1 { - log.Println("WARNING: Using deprecated backend configuration. Please migrate the \"allowed\" setting to the new \"backends\" configuration.") + logger.Warn("Using deprecated backend configuration. Please migrate the \"allowed\" setting to the new \"backends\" configuration.") } - log.Printf("Allowed backend hostnames: %s", hosts) + logger.Infof("Allowed backend hostnames: %s", hosts) if sessionLimit > 0 { - log.Printf("Allow a maximum of %d sessions", sessionLimit) + logger.Infof("Allow a maximum of %d sessions", sessionLimit) } numBackends++ } @@ -194,6 +194,7 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, statsBackendsCurrent.Add(float64(numBackends)) return &BackendConfiguration{ + logger: logger, backends: backends, allowAll: allowAll, @@ -205,7 +206,7 @@ func NewBackendConfiguration(config *goconf.ConfigFile) (*BackendConfiguration, func (b *BackendConfiguration) RemoveBackendsForHost(host string) { if oldBackends := b.backends[host]; len(oldBackends) > 0 { for _, backend := range oldBackends { - log.Printf("Backend %s removed for %s", backend.id, backend.url) + b.logger.Infof("Backend %s removed for %s", backend.id, backend.url) } statsBackendsCurrent.Sub(float64(len(oldBackends))) } @@ -225,14 +226,14 @@ func (b *BackendConfiguration) UpsertHost(host string, backends []*Backend) { found = true b.backends[host][existingIndex] = newBackend backends = append(backends[:index], backends[index+1:]...) - log.Printf("Backend %s updated for %s", newBackend.id, newBackend.url) + b.logger.Infof("Backend %s updated for %s", newBackend.id, newBackend.url) break } index++ } if !found { removed := b.backends[host][existingIndex] - log.Printf("Backend %s removed for %s", removed.id, removed.url) + b.logger.Infof("Backend %s removed for %s", removed.id, removed.url) b.backends[host] = append(b.backends[host][:existingIndex], b.backends[host][existingIndex+1:]...) statsBackendsCurrent.Dec() } @@ -240,7 +241,7 @@ func (b *BackendConfiguration) UpsertHost(host string, backends []*Backend) { b.backends[host] = append(b.backends[host], backends...) for _, added := range backends { - log.Printf("Backend %s added for %s", added.id, added.url) + b.logger.Infof("Backend %s added for %s", added.id, added.url) } statsBackendsCurrent.Add(float64(len(backends))) } @@ -264,12 +265,12 @@ func getConfiguredBackendIDs(backendIds string) (ids []string) { return ids } -func getConfiguredHosts(backendIds string, config *goconf.ConfigFile) (hosts map[string][]*Backend) { +func getConfiguredHosts(logger Logger, backendIds string, config *goconf.ConfigFile) (hosts map[string][]*Backend) { hosts = make(map[string][]*Backend) for _, id := range getConfiguredBackendIDs(backendIds) { u, _ := config.GetString(id, "url") if u == "" { - log.Printf("Backend %s is missing or incomplete, skipping", id) + logger.Warnf("Backend %s is missing or incomplete, skipping", id) continue } @@ -278,7 +279,7 @@ func getConfiguredHosts(backendIds string, config *goconf.ConfigFile) (hosts map } parsed, err := url.Parse(u) if err != nil { - log.Printf("Backend %s has an invalid url %s configured (%s), skipping", id, u, err) + logger.Warnf("Backend %s has an invalid url %s configured (%s), skipping", id, u, err) continue } @@ -289,7 +290,7 @@ func getConfiguredHosts(backendIds string, config *goconf.ConfigFile) (hosts map secret, _ := config.GetString(id, "secret") if u == "" || secret == "" { - log.Printf("Backend %s is missing or incomplete, skipping", id) + logger.Warnf("Backend %s is missing or incomplete, skipping", id) continue } @@ -298,7 +299,7 @@ func getConfiguredHosts(backendIds string, config *goconf.ConfigFile) (hosts map sessionLimit = 0 } if sessionLimit > 0 { - log.Printf("Backend %s allows a maximum of %d sessions", id, sessionLimit) + logger.Infof("Backend %s allows a maximum of %d sessions", id, sessionLimit) } maxStreamBitrate, err := config.GetInt(id, "maxstreambitrate") @@ -329,12 +330,12 @@ func getConfiguredHosts(backendIds string, config *goconf.ConfigFile) (hosts map func (b *BackendConfiguration) Reload(config *goconf.ConfigFile) { if b.compatBackend != nil { - log.Println("Old-style configuration active, reload is not supported") + b.logger.Warnf("Old-style configuration active, reload is not supported") return } if backendIds, _ := config.GetString("backend", "backends"); backendIds != "" { - configuredHosts := getConfiguredHosts(backendIds, config) + configuredHosts := getConfiguredHosts(b.logger, backendIds, config) // remove backends that are no longer configured for hostname := range b.backends { diff --git a/backend_configuration_test.go b/backend_configuration_test.go index 17e7508..f6e9f8c 100644 --- a/backend_configuration_test.go +++ b/backend_configuration_test.go @@ -104,7 +104,8 @@ func TestIsUrlAllowed_Compat(t *testing.T) { config.AddOption("backend", "allowed", "domain.invalid") config.AddOption("backend", "allowhttp", "true") config.AddOption("backend", "secret", string(testBackendSecret)) - cfg, err := NewBackendConfiguration(config) + logger := NewLoggerForTest(t) + cfg, err := NewBackendConfiguration(logger, config) if err != nil { t.Fatal(err) } @@ -125,7 +126,8 @@ func TestIsUrlAllowed_CompatForceHttps(t *testing.T) { config := goconf.NewConfigFile() config.AddOption("backend", "allowed", "domain.invalid") config.AddOption("backend", "secret", string(testBackendSecret)) - cfg, err := NewBackendConfiguration(config) + logger := NewLoggerForTest(t) + cfg, err := NewBackendConfiguration(logger, config) if err != nil { t.Fatal(err) } @@ -170,7 +172,8 @@ func TestIsUrlAllowed(t *testing.T) { config.AddOption("baz", "secret", string(testBackendSecret)+"-baz") config.AddOption("lala", "url", "https://otherdomain.invalid/") config.AddOption("lala", "secret", string(testBackendSecret)+"-lala") - cfg, err := NewBackendConfiguration(config) + logger := NewLoggerForTest(t) + cfg, err := NewBackendConfiguration(logger, config) if err != nil { t.Fatal(err) } @@ -187,7 +190,8 @@ func TestIsUrlAllowed_EmptyAllowlist(t *testing.T) { config := goconf.NewConfigFile() config.AddOption("backend", "allowed", "") config.AddOption("backend", "secret", string(testBackendSecret)) - cfg, err := NewBackendConfiguration(config) + logger := NewLoggerForTest(t) + cfg, err := NewBackendConfiguration(logger, config) if err != nil { t.Fatal(err) } @@ -207,7 +211,8 @@ func TestIsUrlAllowed_AllowAll(t *testing.T) { config.AddOption("backend", "allowall", "true") config.AddOption("backend", "allowed", "") config.AddOption("backend", "secret", string(testBackendSecret)) - cfg, err := NewBackendConfiguration(config) + logger := NewLoggerForTest(t) + cfg, err := NewBackendConfiguration(logger, config) if err != nil { t.Fatal(err) } @@ -247,7 +252,8 @@ func TestBackendReloadNoChange(t *testing.T) { original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") original_config.AddOption("backend2", "url", "http://domain2.invalid") original_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -260,7 +266,7 @@ func TestBackendReloadNoChange(t *testing.T) { new_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") new_config.AddOption("backend2", "url", "http://domain2.invalid") new_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } @@ -282,7 +288,8 @@ func TestBackendReloadChangeExistingURL(t *testing.T) { original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") original_config.AddOption("backend2", "url", "http://domain2.invalid") original_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -296,7 +303,7 @@ func TestBackendReloadChangeExistingURL(t *testing.T) { new_config.AddOption("backend1", "sessionlimit", "10") new_config.AddOption("backend2", "url", "http://domain2.invalid") new_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } @@ -322,7 +329,8 @@ func TestBackendReloadChangeSecret(t *testing.T) { original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") original_config.AddOption("backend2", "url", "http://domain2.invalid") original_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -335,7 +343,7 @@ func TestBackendReloadChangeSecret(t *testing.T) { new_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend3") new_config.AddOption("backend2", "url", "http://domain2.invalid") new_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } @@ -358,7 +366,8 @@ func TestBackendReloadAddBackend(t *testing.T) { original_config.AddOption("backend", "allowall", "false") original_config.AddOption("backend1", "url", "http://domain1.invalid") original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -372,7 +381,7 @@ func TestBackendReloadAddBackend(t *testing.T) { new_config.AddOption("backend2", "url", "http://domain2.invalid") new_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") new_config.AddOption("backend2", "sessionlimit", "10") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } @@ -400,7 +409,8 @@ func TestBackendReloadRemoveHost(t *testing.T) { original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") original_config.AddOption("backend2", "url", "http://domain2.invalid") original_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -411,7 +421,7 @@ func TestBackendReloadRemoveHost(t *testing.T) { new_config.AddOption("backend", "allowall", "false") new_config.AddOption("backend1", "url", "http://domain1.invalid") new_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } @@ -437,7 +447,8 @@ func TestBackendReloadRemoveBackendFromSharedHost(t *testing.T) { original_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") original_config.AddOption("backend2", "url", "http://domain1.invalid/bar/") original_config.AddOption("backend2", "secret", string(testBackendSecret)+"-backend2") - o_cfg, err := NewBackendConfiguration(original_config) + logger := NewLoggerForTest(t) + o_cfg, err := NewBackendConfiguration(logger, original_config) if err != nil { t.Fatal(err) } @@ -448,7 +459,7 @@ func TestBackendReloadRemoveBackendFromSharedHost(t *testing.T) { new_config.AddOption("backend", "allowall", "false") new_config.AddOption("backend1", "url", "http://domain1.invalid/foo/") new_config.AddOption("backend1", "secret", string(testBackendSecret)+"-backend1") - n_cfg, err := NewBackendConfiguration(new_config) + n_cfg, err := NewBackendConfiguration(logger, new_config) if err != nil { t.Fatal(err) } diff --git a/backend_server.go b/backend_server.go index 8eafdb8..ebaf55d 100644 --- a/backend_server.go +++ b/backend_server.go @@ -29,7 +29,6 @@ import ( "encoding/json" "fmt" "io" - "log" "net" "net/http" "net/url" @@ -52,6 +51,7 @@ const ( ) type BackendServer struct { + logger Logger hub *Hub nats NatsClient roomSessions RoomSessions @@ -68,7 +68,7 @@ type BackendServer struct { invalidSecret []byte } -func NewBackendServer(config *goconf.ConfigFile, hub *Hub, version string) (*BackendServer, error) { +func NewBackendServer(logger Logger, config *goconf.ConfigFile, hub *Hub, version string) (*BackendServer, error) { turnapikey, _ := config.GetString("turn", "apikey") turnsecret, _ := config.GetString("turn", "secret") turnservers, _ := config.GetString("turn", "servers") @@ -91,22 +91,22 @@ func NewBackendServer(config *goconf.ConfigFile, hub *Hub, version string) (*Bac return nil, fmt.Errorf("need a shared TURN secret if TURN servers are configured") } - log.Printf("Using configured TURN API key") - log.Printf("Using configured shared TURN secret") + logger.Info("Using configured TURN API key") + logger.Info("Using configured shared TURN secret") for _, s := range turnserverslist { - log.Printf("Adding \"%s\" as TURN server", s) + logger.Infof("Adding \"%s\" as TURN server", s) } } statsAllowed, _ := config.GetString("stats", "allowed_ips") var statsAllowedIps map[string]bool if statsAllowed == "" { - log.Printf("No IPs configured for the stats endpoint, only allowing access from 127.0.0.1") + logger.Info("No IPs configured for the stats endpoint, only allowing access from 127.0.0.1") statsAllowedIps = map[string]bool{ "127.0.0.1": true, } } else { - log.Printf("Only allowing access to the stats endpoing from %s", statsAllowed) + logger.Infof("Only allowing access to the stats endpoing from %s", statsAllowed) statsAllowedIps = make(map[string]bool) for _, ip := range strings.Split(statsAllowed, ",") { ip = strings.TrimSpace(ip) @@ -122,6 +122,7 @@ func NewBackendServer(config *goconf.ConfigFile, hub *Hub, version string) (*Bac } return &BackendServer{ + logger: logger, hub: hub, nats: hub.nats, roomSessions: hub.roomSessions, @@ -229,7 +230,7 @@ func (b *BackendServer) getTurnCredentials(w http.ResponseWriter, r *http.Reques data, err := json.Marshal(result) if err != nil { - log.Printf("Could not serialize TURN credentials: %s", err) + b.logger.Errorf("Could not serialize TURN credentials: %s", err) w.WriteHeader(http.StatusInternalServerError) io.WriteString(w, "Could not serialize credentials.") // nolint return @@ -256,7 +257,7 @@ func (b *BackendServer) parseRequestBody(f func(http.ResponseWriter, *http.Reque } ct := r.Header.Get("Content-Type") if !strings.HasPrefix(ct, "application/json") { - log.Printf("Received unsupported content-type: %s", ct) + b.logger.Errorf("Received unsupported content-type: %s", ct) http.Error(w, "Unsupported Content-Type", http.StatusBadRequest) return } @@ -269,7 +270,7 @@ func (b *BackendServer) parseRequestBody(f func(http.ResponseWriter, *http.Reque body, err := io.ReadAll(r.Body) if err != nil { - log.Println("Error reading body: ", err) + b.logger.Errorf("Error reading body: %s", err) http.Error(w, "Could not read body", http.StatusBadRequest) return } @@ -292,7 +293,7 @@ func (b *BackendServer) sendRoomInvite(roomid string, backend *Backend, userids } for _, userid := range userids { if err := b.nats.PublishMessage(GetSubjectForUserId(userid, backend), msg); err != nil { - log.Printf("Could not publish room invite for user %s in backend %s: %s", userid, backend.Id(), err) + b.logger.Errorf("Could not publish room invite for user %s in backend %s: %s", userid, backend.Id(), err) } } } @@ -313,7 +314,7 @@ func (b *BackendServer) sendRoomDisinvite(roomid string, backend *Backend, reaso } for _, userid := range userids { if err := b.nats.PublishMessage(GetSubjectForUserId(userid, backend), msg); err != nil { - log.Printf("Could not publish room disinvite for user %s in backend %s: %s", userid, backend.Id(), err) + b.logger.Errorf("Could not publish room disinvite for user %s in backend %s: %s", userid, backend.Id(), err) } } @@ -329,10 +330,10 @@ func (b *BackendServer) sendRoomDisinvite(roomid string, backend *Backend, reaso go func(sessionid string) { defer wg.Done() if sid, err := b.lookupByRoomSessionId(sessionid, nil, timeout); err != nil { - log.Printf("Could not lookup by room session %s: %s", sessionid, err) + b.logger.Errorf("Could not lookup by room session %s: %s", sessionid, err) } else if sid != "" { if err := b.nats.PublishMessage("session."+sid, msg); err != nil { - log.Printf("Could not publish room disinvite for session %s: %s", sid, err) + b.logger.Errorf("Could not publish room disinvite for session %s: %s", sid, err) } } }(sessionid) @@ -363,14 +364,14 @@ func (b *BackendServer) sendRoomUpdate(roomid string, backend *Backend, notified } if err := b.nats.PublishMessage(GetSubjectForUserId(userid, backend), msg); err != nil { - log.Printf("Could not publish room update for user %s in backend %s: %s", userid, backend.Id(), err) + b.logger.Errorf("Could not publish room update for user %s in backend %s: %s", userid, backend.Id(), err) } } } func (b *BackendServer) lookupByRoomSessionId(roomSessionId string, cache *ConcurrentStringStringMap, timeout time.Duration) (string, error) { if roomSessionId == sessionIdNotInMeeting { - log.Printf("Trying to lookup empty room session id: %s", roomSessionId) + b.logger.Infof("Trying to lookup empty room session id: %s", roomSessionId) return "", nil } @@ -407,13 +408,13 @@ func (b *BackendServer) fixupUserSessions(cache *ConcurrentStringStringMap, user roomSessionId, ok := roomSessionIdOb.(string) if !ok { - log.Printf("User %+v has invalid room session id, ignoring", user) + b.logger.Infof("User %+v has invalid room session id, ignoring", user) delete(user, "sessionId") continue } if roomSessionId == sessionIdNotInMeeting { - log.Printf("User %+v is not in the meeting, ignoring", user) + b.logger.Infof("User %+v is not in the meeting, ignoring", user) delete(user, "sessionId") continue } @@ -422,7 +423,7 @@ func (b *BackendServer) fixupUserSessions(cache *ConcurrentStringStringMap, user go func(roomSessionId string, u map[string]interface{}) { defer wg.Done() if sessionId, err := b.lookupByRoomSessionId(roomSessionId, cache, timeout); err != nil { - log.Printf("Could not lookup by room session %s: %s", roomSessionId, err) + b.logger.Errorf("Could not lookup by room session %s: %s", roomSessionId, err) delete(u, "sessionId") } else if sessionId != "" { u["sessionId"] = sessionId @@ -484,14 +485,14 @@ loop: sessionId := user["sessionId"].(string) permissionsList, ok := permissionsInterface.([]interface{}) if !ok { - log.Printf("Received invalid permissions %+v (%s) for session %s", permissionsInterface, reflect.TypeOf(permissionsInterface), sessionId) + b.logger.Errorf("Received invalid permissions %+v (%s) for session %s", permissionsInterface, reflect.TypeOf(permissionsInterface), sessionId) continue } var permissions []Permission for idx, ob := range permissionsList { permission, ok := ob.(string) if !ok { - log.Printf("Received invalid permission at position %d %+v (%s) for session %s", idx, ob, reflect.TypeOf(ob), sessionId) + b.logger.Errorf("Received invalid permission at position %d %+v (%s) for session %s", idx, ob, reflect.TypeOf(ob), sessionId) continue loop } permissions = append(permissions, Permission(permission)) @@ -505,7 +506,7 @@ loop: Permissions: permissions, } if err := b.nats.Publish("session."+sessionId, message); err != nil { - log.Printf("Could not send permissions update (%+v) to session %s: %s", permissions, sessionId, err) + b.logger.Errorf("Could not send permissions update (%+v) to session %s: %s", permissions, sessionId, err) } }(sessionId, permissions) } @@ -564,7 +565,7 @@ func (b *BackendServer) roomHandler(w http.ResponseWriter, r *http.Request, body var request BackendServerRoomRequest if err := json.Unmarshal(body, &request); err != nil { - log.Printf("Error decoding body %s: %s", string(body), err) + b.logger.Errorf("Error decoding body %s: %s", string(body), err) http.Error(w, "Could not read body", http.StatusBadRequest) return } @@ -597,7 +598,7 @@ func (b *BackendServer) roomHandler(w http.ResponseWriter, r *http.Request, body } if err != nil { - log.Printf("Error processing %s for room %s: %s", string(body), roomid, err) + b.logger.Errorf("Error processing %s for room %s: %s", string(body), roomid, err) http.Error(w, "Error while processing", http.StatusInternalServerError) return } @@ -630,7 +631,7 @@ func (b *BackendServer) statsHandler(w http.ResponseWriter, r *http.Request) { stats := b.hub.GetStats() statsData, err := json.MarshalIndent(stats, "", " ") if err != nil { - log.Printf("Could not serialize stats %+v: %s", stats, err) + b.logger.Errorf("Could not serialize stats %+v: %s", stats, err) http.Error(w, "Internal server error", http.StatusInternalServerError) return } diff --git a/backend_server_test.go b/backend_server_test.go index 82716dd..31836ba 100644 --- a/backend_server_test.go +++ b/backend_server_test.go @@ -85,15 +85,16 @@ func CreateBackendServerForTestFromConfig(t *testing.T, config *goconf.ConfigFil config.AddOption("sessions", "blockkey", "09876543210987654321098765432109") config.AddOption("clients", "internalsecret", string(testInternalSecret)) config.AddOption("geoip", "url", "none") - nats, err := NewLoopbackNatsClient() + logger := NewLoggerForTest(t) + nats, err := NewLoopbackNatsClient(logger) if err != nil { t.Fatal(err) } - hub, err := NewHub(config, nats, r, "no-version") + hub, err := NewHub(logger, config, nats, r, "no-version") if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, hub, "no-version") + b, err := NewBackendServer(logger, config, hub, "no-version") if err != nil { t.Fatal(err) } diff --git a/client.go b/client.go index fce3fdd..5979849 100644 --- a/client.go +++ b/client.go @@ -24,7 +24,6 @@ package signaling import ( "bytes" "encoding/json" - "log" "strconv" "strings" "sync" @@ -94,6 +93,7 @@ type WritableClientMessage interface { } type Client struct { + logger Logger conn *websocket.Conn addr string agent string @@ -116,7 +116,7 @@ type Client struct { OnRTTReceived func(*Client, time.Duration) } -func NewClient(conn *websocket.Conn, remoteAddress string, agent string) (*Client, error) { +func NewClient(logger Logger, conn *websocket.Conn, remoteAddress string, agent string) (*Client, error) { remoteAddress = strings.TrimSpace(remoteAddress) if remoteAddress == "" { remoteAddress = "unknown remote address" @@ -126,6 +126,7 @@ func NewClient(conn *websocket.Conn, remoteAddress string, agent string) (*Clien agent = "unknown user agent" } client := &Client{ + logger: logger, conn: conn, addr: remoteAddress, agent: agent, @@ -261,7 +262,7 @@ func (c *Client) ReadPump() { conn := c.conn c.mu.Unlock() if conn == nil { - log.Printf("Connection from %s closed while starting readPump", addr) + c.logger.Warnf("Connection from %s closed while starting readPump", addr) return } @@ -277,9 +278,9 @@ func (c *Client) ReadPump() { if c.logRTT { rtt_ms := rtt.Nanoseconds() / time.Millisecond.Nanoseconds() if session := c.GetSession(); session != nil { - log.Printf("Client %s has RTT of %d ms (%s)", session.PublicId(), rtt_ms, rtt) + c.logger.Infof("Client %s has RTT of %d ms (%s)", session.PublicId(), rtt_ms, rtt) } else { - log.Printf("Client from %s has RTT of %d ms (%s)", addr, rtt_ms, rtt) + c.logger.Infof("Client from %s has RTT of %d ms (%s)", addr, rtt_ms, rtt) } } c.OnRTTReceived(c, rtt) @@ -298,9 +299,9 @@ func (c *Client) ReadPump() { websocket.CloseGoingAway, websocket.CloseNoStatusReceived) { if session := c.GetSession(); session != nil { - log.Printf("Error reading from client %s: %v", session.PublicId(), err) + c.logger.Errorf("Error reading from client %s: %v", session.PublicId(), err) } else { - log.Printf("Error reading from %s: %v", addr, err) + c.logger.Errorf("Error reading from %s: %v", addr, err) } } break @@ -308,9 +309,9 @@ func (c *Client) ReadPump() { if messageType != websocket.TextMessage { if session := c.GetSession(); session != nil { - log.Printf("Unsupported message type %v from client %s", messageType, session.PublicId()) + c.logger.Errorf("Unsupported message type %v from client %s", messageType, session.PublicId()) } else { - log.Printf("Unsupported message type %v from %s", messageType, addr) + c.logger.Errorf("Unsupported message type %v from %s", messageType, addr) } c.SendError(InvalidFormat) continue @@ -321,9 +322,9 @@ func (c *Client) ReadPump() { if _, err := decodeBuffer.ReadFrom(reader); err != nil { bufferPool.Put(decodeBuffer) if session := c.GetSession(); session != nil { - log.Printf("Error reading message from client %s: %v", session.PublicId(), err) + c.logger.Errorf("Error reading message from client %s: %v", session.PublicId(), err) } else { - log.Printf("Error reading message from %s: %v", addr, err) + c.logger.Errorf("Error reading message from %s: %v", addr, err) } break } @@ -380,9 +381,9 @@ func (c *Client) writeInternal(message json.Marshaler) bool { } if session := c.GetSession(); session != nil { - log.Printf("Could not send message %+v to client %s: %v", message, session.PublicId(), err) + c.logger.Errorf("Could not send message %+v to client %s: %v", message, session.PublicId(), err) } else { - log.Printf("Could not send message %+v to %s: %v", message, c.RemoteAddr(), err) + c.logger.Errorf("Could not send message %+v to %s: %v", message, c.RemoteAddr(), err) } closeData = websocket.FormatCloseMessage(websocket.CloseInternalServerErr, "") goto close @@ -393,9 +394,9 @@ close: c.conn.SetWriteDeadline(time.Now().Add(writeWait)) // nolint if err := c.conn.WriteMessage(websocket.CloseMessage, closeData); err != nil { if session := c.GetSession(); session != nil { - log.Printf("Could not send close message to client %s: %v", session.PublicId(), err) + c.logger.Errorf("Could not send close message to client %s: %v", session.PublicId(), err) } else { - log.Printf("Could not send close message to %s: %v", c.RemoteAddr(), err) + c.logger.Errorf("Could not send close message to %s: %v", c.RemoteAddr(), err) } } return false @@ -420,9 +421,9 @@ func (c *Client) writeError(e error) bool { // nolint c.conn.SetWriteDeadline(time.Now().Add(writeWait)) // nolint if err := c.conn.WriteMessage(websocket.CloseMessage, closeData); err != nil { if session := c.GetSession(); session != nil { - log.Printf("Could not send close message to client %s: %v", session.PublicId(), err) + c.logger.Errorf("Could not send close message to client %s: %v", session.PublicId(), err) } else { - log.Printf("Could not send close message to %s: %v", c.RemoteAddr(), err) + c.logger.Errorf("Could not send close message to %s: %v", c.RemoteAddr(), err) } } return false @@ -469,9 +470,9 @@ func (c *Client) sendPing() bool { c.conn.SetWriteDeadline(time.Now().Add(writeWait)) // nolint if err := c.conn.WriteMessage(websocket.PingMessage, []byte(msg)); err != nil { if session := c.GetSession(); session != nil { - log.Printf("Could not send ping to client %s: %v", session.PublicId(), err) + c.logger.Errorf("Could not send ping to client %s: %v", session.PublicId(), err) } else { - log.Printf("Could not send ping to %s: %v", c.RemoteAddr(), err) + c.logger.Errorf("Could not send ping to %s: %v", c.RemoteAddr(), err) } return false } diff --git a/client/main.go b/client/main.go index 1338de9..0039db0 100644 --- a/client/main.go +++ b/client/main.go @@ -95,7 +95,7 @@ func (s *Stats) reset(start time.Time) { s.start = start } -func (s *Stats) Log() { +func (s *Stats) Log(logger signaling.Logger) { now := time.Now() duration := now.Sub(s.start) perSec := uint64(duration / time.Second) @@ -107,7 +107,7 @@ func (s *Stats) Log() { sentMessages := totalSentMessages - s.resetSentMessages totalRecvMessages := atomic.AddUint64(&s.numRecvMessages, 0) recvMessages := totalRecvMessages - s.resetRecvMessages - log.Printf("Stats: sent=%d (%d/sec), recv=%d (%d/sec), delta=%d", + logger.Infof("Stats: sent=%d (%d/sec), recv=%d (%d/sec), delta=%d", totalSentMessages, sentMessages/perSec, totalRecvMessages, recvMessages/perSec, totalSentMessages-totalRecvMessages) @@ -119,6 +119,8 @@ type MessagePayload struct { } type SignalingClient struct { + logger signaling.Logger + readyWg *sync.WaitGroup cookie *securecookie.SecureCookie @@ -135,13 +137,15 @@ type SignalingClient struct { userId string } -func NewSignalingClient(cookie *securecookie.SecureCookie, url string, stats *Stats, readyWg *sync.WaitGroup, doneWg *sync.WaitGroup) (*SignalingClient, error) { +func NewSignalingClient(logger signaling.Logger, cookie *securecookie.SecureCookie, url string, stats *Stats, readyWg *sync.WaitGroup, doneWg *sync.WaitGroup) (*SignalingClient, error) { conn, _, err := websocket.DefaultDialer.Dial(url, nil) if err != nil { return nil, err } client := &SignalingClient{ + logger: logger.With("url", url), + readyWg: readyWg, cookie: cookie, @@ -207,13 +211,13 @@ func (c *SignalingClient) processMessage(message *signaling.ServerMessage) { case "message": c.processMessageMessage(message) case "bye": - log.Printf("Received bye: %+v", message.Bye) + c.logger.Infof("Received bye: %+v", message.Bye) c.Close() case "error": - log.Printf("Received error: %+v", message.Error) + c.logger.Errorf("Received error: %+v", message.Error) c.Close() default: - log.Printf("Unsupported message type: %+v", *message) + c.logger.Warnf("Unsupported message type: %+v", *message) } } @@ -239,7 +243,7 @@ func (c *SignalingClient) processHelloMessage(message *signaling.ServerMessage) c.privateSessionId = message.Hello.ResumeId c.publicSessionId = c.privateToPublicSessionId(c.privateSessionId) c.userId = message.Hello.UserId - log.Printf("Registered as %s (userid %s)", c.privateSessionId, c.userId) + c.logger.Infof("Registered as %s (userid %s)", c.privateSessionId, c.userId) c.readyWg.Done() } @@ -252,14 +256,14 @@ func (c *SignalingClient) PublicSessionId() string { func (c *SignalingClient) processMessageMessage(message *signaling.ServerMessage) { var msg MessagePayload if err := json.Unmarshal(*message.Message.Data, &msg); err != nil { - log.Println("Error in unmarshal", err) + c.logger.Errorf("Error in unmarshal %s", err) return } now := time.Now() duration := now.Sub(msg.Now) if duration > messageReportDuration { - log.Printf("Message took %s", duration) + c.logger.Warnf("Message took %s", duration) } } @@ -286,13 +290,13 @@ func (c *SignalingClient) readPump() { websocket.CloseNormalClosure, websocket.CloseGoingAway, websocket.CloseNoStatusReceived) { - log.Printf("Error: %v", err) + c.logger.Errorf("Error: %v", err) } break } if messageType != websocket.TextMessage { - log.Println("Unsupported message type", messageType) + c.logger.Warnf("Unsupported message type %d", messageType) break } @@ -300,7 +304,7 @@ func (c *SignalingClient) readPump() { if _, err := decodeBuffer.ReadFrom(reader); err != nil { c.lock.Lock() if c.conn != nil { - log.Println("Error reading message", err) + c.logger.Errorf("Error reading message %s", err) } c.lock.Unlock() break @@ -308,7 +312,7 @@ func (c *SignalingClient) readPump() { var message signaling.ServerMessage if err := message.UnmarshalJSON(decodeBuffer.Bytes()); err != nil { - log.Printf("Error: %v", err) + c.logger.Errorf("Error: %v", err) break } @@ -330,7 +334,7 @@ func (c *SignalingClient) writeInternal(message *signaling.ClientMessage) bool { return false } - log.Println("Could not send message", message, err) + c.logger.Errorf("Could not send message %+v: %s", message, err) // TODO(jojo): Differentiate between JSON encode errors and websocket errors. closeData = websocket.FormatCloseMessage(websocket.CloseInternalServerErr, "") goto close @@ -416,29 +420,29 @@ func (c *SignalingClient) SendMessages(clients []*SignalingClient) { } } -func registerAuthHandler(router *mux.Router) { +func registerAuthHandler(logger signaling.Logger, router *mux.Router) { router.HandleFunc("/auth", func(w http.ResponseWriter, r *http.Request) { body, err := io.ReadAll(r.Body) if err != nil { - log.Println("Error reading body:", err) + logger.Errorf("Error reading body: %s", err) return } rnd := r.Header.Get(signaling.HeaderBackendSignalingRandom) checksum := r.Header.Get(signaling.HeaderBackendSignalingChecksum) if rnd == "" || checksum == "" { - log.Println("No checksum headers found") + logger.Error("No checksum headers found") return } if verify := signaling.CalculateBackendChecksum(rnd, body, backendSecret); verify != checksum { - log.Println("Backend checksum verification failed") + logger.Error("Backend checksum verification failed") return } var request signaling.BackendClientRequest if err := request.UnmarshalJSON(body); err != nil { - log.Println(err) + logger.Errorf("Could not unmarshal request: %s", err) return } @@ -452,7 +456,7 @@ func registerAuthHandler(router *mux.Router) { data, err := response.MarshalJSON() if err != nil { - log.Println(err) + logger.Errorf("Could not marshal response: %s", err) return } @@ -470,7 +474,7 @@ func registerAuthHandler(router *mux.Router) { jsonpayload, err := payload.MarshalJSON() if err != nil { - log.Println(err) + logger.Error("Could not marshal payload: %s", err) return } @@ -480,10 +484,10 @@ func registerAuthHandler(router *mux.Router) { }) } -func getLocalIP() string { +func getLocalIP(logger signaling.Logger) string { interfaces, err := net.InterfaceAddrs() if err != nil { - log.Fatal(err) + logger.Fatalf("Could not get interface addresses: %s", err) } for _, intf := range interfaces { switch t := intf.(type) { @@ -510,12 +514,18 @@ func reverseSessionId(s string) (string, error) { } func main() { + log.SetFlags(log.Lshortfile | log.Ldate | log.Ltime | log.Lmicroseconds) flag.Parse() - log.SetFlags(0) + + logger, err := signaling.NewLogger() + if err != nil { + log.Fatalf("Could not create logger: %s", err) + } + defer logger.Sync() // nolint config, err := goconf.ReadConfigFile(*config) if err != nil { - log.Fatal("Could not read configuration: ", err) + logger.Fatalf("Could not read configuration: %s", err) } secret, _ := config.GetString("backend", "secret") @@ -526,7 +536,7 @@ func main() { case 32: case 64: default: - log.Printf("WARNING: The sessions hash key should be 32 or 64 bytes but is %d bytes", len(hashKey)) + logger.Warnf("The sessions hash key should be 32 or 64 bytes but is %d bytes", len(hashKey)) } blockKey, _ := config.GetString("sessions", "blockkey") @@ -538,24 +548,24 @@ func main() { case 24: case 32: default: - log.Fatalf("The sessions block key must be 16, 24 or 32 bytes but is %d bytes", len(blockKey)) + logger.Fatalf("The sessions block key must be 16, 24 or 32 bytes but is %d bytes", len(blockKey)) } cookie := securecookie.New([]byte(hashKey), blockBytes).MaxAge(0) cpus := runtime.NumCPU() runtime.GOMAXPROCS(cpus) - log.Printf("Using a maximum of %d CPUs", cpus) + logger.Infof("Using a maximum of %d CPUs", cpus) interrupt := make(chan os.Signal, 1) signal.Notify(interrupt, os.Interrupt) r := mux.NewRouter() - registerAuthHandler(r) + registerAuthHandler(logger, r) - localIP := getLocalIP() + localIP := getLocalIP(logger) listener, err := net.Listen("tcp", localIP+":0") if err != nil { - log.Fatal(err) + logger.Fatal(err) } server := http.Server{ @@ -565,7 +575,7 @@ func main() { server.Serve(listener) // nolint }() backendUrl := "http://" + listener.Addr().String() - log.Println("Backend server running on", backendUrl) + logger.Infof("Backend server running on %s", backendUrl) urls := make([]url.URL, 0) urlstrings := make([]string, 0) @@ -578,24 +588,24 @@ func main() { urls = append(urls, u) urlstrings = append(urlstrings, u.String()) } - log.Printf("Connecting to %s", urlstrings) + logger.Infof("Connecting to %s", urlstrings) clients := make([]*SignalingClient, 0) stats := &Stats{} if *maxClients < 2 { - log.Fatalf("Need at least 2 clients, got %d", *maxClients) + logger.Fatalf("Need at least 2 clients, got %d", *maxClients) } - log.Printf("Starting %d clients", *maxClients) + logger.Infof("Starting %d clients", *maxClients) var doneWg sync.WaitGroup var readyWg sync.WaitGroup for i := 0; i < *maxClients; i++ { - client, err := NewSignalingClient(cookie, urls[i%len(urls)].String(), stats, &readyWg, &doneWg) + client, err := NewSignalingClient(logger, cookie, urls[i%len(urls)].String(), stats, &readyWg, &doneWg) if err != nil { - log.Fatal(err) + logger.Fatalf("Could not create client: %s", err) } defer client.Close() readyWg.Add(1) @@ -615,10 +625,10 @@ func main() { clients = append(clients, client) } - log.Println("Clients created") + logger.Info("Clients created") readyWg.Wait() - log.Println("All connections established") + logger.Info("All connections established") for _, c := range clients { doneWg.Add(1) @@ -635,14 +645,14 @@ loop: for { select { case <-interrupt: - log.Println("Interrupted") + logger.Info("Interrupted") break loop case <-report.C: - stats.Log() + stats.Log(logger) } } - log.Println("Waiting for clients to terminate ...") + logger.Info("Waiting for clients to terminate ...") for _, c := range clients { c.Close() } diff --git a/clientsession.go b/clientsession.go index 2d1b476..4f21809 100644 --- a/clientsession.go +++ b/clientsession.go @@ -25,7 +25,6 @@ import ( "context" "encoding/json" "fmt" - "log" "net/url" "strings" "sync" @@ -50,6 +49,7 @@ var ( type ClientSession struct { roomJoinTime int64 + logger Logger running int32 hub *Hub privateId string @@ -93,8 +93,9 @@ type ClientSession struct { virtualSessions map[*VirtualSession]bool } -func NewClientSession(hub *Hub, privateId string, publicId string, data *SessionIdData, backend *Backend, hello *HelloClientMessage, auth *BackendClientAuthResponse) (*ClientSession, error) { +func NewClientSession(logger Logger, hub *Hub, privateId string, publicId string, data *SessionIdData, backend *Backend, hello *HelloClientMessage, auth *BackendClientAuthResponse) (*ClientSession, error) { s := &ClientSession{ + logger: logger, hub: hub, privateId: privateId, publicId: publicId, @@ -260,7 +261,7 @@ func (s *ClientSession) SetPermissions(permissions []Permission) { s.permissions = p s.supportsPermissions = true - log.Printf("Permissions of session %s changed: %s", s.PublicId(), permissions) + s.logger.Infof("Permissions of session %s changed: %s", s.PublicId(), permissions) } func (s *ClientSession) Backend() *Backend { @@ -372,13 +373,13 @@ func (s *ClientSession) closeAndWait(wait bool) { defer s.mu.Unlock() if s.userSubscription != nil { if err := s.userSubscription.Unsubscribe(); err != nil { - log.Printf("Error closing user subscription in session %s: %s", s.PublicId(), err) + s.logger.Errorf("Error closing user subscription in session %s: %s", s.PublicId(), err) } s.userSubscription = nil } if s.sessionSubscription != nil { if err := s.sessionSubscription.Unsubscribe(); err != nil { - log.Printf("Error closing session subscription in session %s: %s", s.PublicId(), err) + s.logger.Errorf("Error closing session subscription in session %s: %s", s.PublicId(), err) } s.sessionSubscription = nil } @@ -444,7 +445,7 @@ func (s *ClientSession) SubscribeRoomNats(n NatsClient, roomid string, roomSessi return err } } - log.Printf("Session %s joined room %s with room session id %s", s.PublicId(), roomid, roomSessionId) + s.logger.Infof("Session %s joined room %s with room session id %s", s.PublicId(), roomid, roomSessionId) s.roomSessionId = roomSessionId return nil } @@ -458,7 +459,7 @@ func (s *ClientSession) LeaveCall() { return } - log.Printf("Session %s left call %s", s.PublicId(), room.Id()) + s.logger.Infof("Session %s left call %s", s.PublicId(), room.Id()) s.releaseMcuObjects() } @@ -488,7 +489,7 @@ func (s *ClientSession) UnsubscribeRoomNats() { func (s *ClientSession) doUnsubscribeRoomNats(notify bool) { if s.roomSubscription != nil { if err := s.roomSubscription.Unsubscribe(); err != nil { - log.Printf("Error closing room subscription in session %s: %s", s.PublicId(), err) + s.logger.Errorf("Error closing room subscription in session %s: %s", s.PublicId(), err) } s.roomSubscription = nil } @@ -502,9 +503,9 @@ func (s *ClientSession) doUnsubscribeRoomNats(notify bool) { request.Room.Action = "leave" var response map[string]interface{} if err := s.hub.backend.PerformJSONRequest(ctx, s.ParsedBackendUrl(), request, &response); err != nil { - log.Printf("Could not notify about room session %s left room %s: %s", sid, room.Id(), err) + s.logger.Errorf("Could not notify about room session %s left room %s: %s", sid, room.Id(), err) } else { - log.Printf("Removed room session %s: %+v", sid, response) + s.logger.Infof("Removed room session %s: %+v", sid, response) } }(s.roomSessionId) } @@ -522,7 +523,7 @@ func (s *ClientSession) clearClientLocked(client *Client) { if s.client == nil { return } else if client != nil && s.client != client { - log.Printf("Trying to clear other client in session %s", s.PublicId()) + s.logger.Warnf("Trying to clear other client in session %s", s.PublicId()) return } @@ -575,7 +576,7 @@ func (s *ClientSession) sendOffer(client McuClient, sender string, streamType st } offer_data, err := json.Marshal(offer_message) if err != nil { - log.Println("Could not serialize offer", offer_message, err) + s.logger.Errorf("Could not serialize offer %+v: %s", offer_message, err) return } response_message := &ServerMessage{ @@ -604,7 +605,7 @@ func (s *ClientSession) sendCandidate(client McuClient, sender string, streamTyp } candidate_data, err := json.Marshal(candidate_message) if err != nil { - log.Println("Could not serialize candidate", candidate_message, err) + s.logger.Errorf("Could not serialize candidate %+v: %s", candidate_message, err) return } response_message := &ServerMessage{ @@ -687,7 +688,7 @@ func (s *ClientSession) OnIceCandidate(client McuClient, candidate interface{}) } } - log.Printf("Session %s received candidate %+v for unknown client %s", s.PublicId(), candidate, client.Id()) + s.logger.Errorf("Session %s received candidate %+v for unknown client %s", s.PublicId(), candidate, client.Id()) } func (s *ClientSession) OnIceCompleted(client McuClient) { @@ -894,7 +895,7 @@ func (s *ClientSession) GetOrCreatePublisher(ctx context.Context, mcu Mcu, strea } else { s.publishers[streamType] = publisher } - log.Printf("Publishing %s as %s for session %s", streamType, publisher.Id(), s.PublicId()) + s.logger.Infof("Publishing %s as %s for session %s", streamType, publisher.Id(), s.PublicId()) } return publisher, nil @@ -935,7 +936,7 @@ func (s *ClientSession) GetOrCreateSubscriber(ctx context.Context, mcu Mcu, id s } else { s.subscribers[id+"|"+streamType] = subscriber } - log.Printf("Subscribing %s from %s as %s in session %s", streamType, id, subscriber.Id(), s.PublicId()) + s.logger.Infof("Subscribing %s from %s as %s in session %s", streamType, id, subscriber.Id(), s.PublicId()) } return subscriber, nil @@ -951,7 +952,7 @@ func (s *ClientSession) GetSubscriber(id string, streamType string) McuSubscribe func (s *ClientSession) processClientMessage(msg *nats.Msg) { var message NatsMessage if err := s.hub.nats.Decode(msg, &message); err != nil { - log.Printf("Could not decode NATS message %+v for session %s: %s", *msg, s.PublicId(), err) + s.logger.Errorf("Could not decode NATS message %+v for session %s: %s", *msg, s.PublicId(), err) return } @@ -967,7 +968,7 @@ func (s *ClientSession) processClientMessage(msg *nats.Msg) { if (publisher.HasMedia(MediaTypeAudio) && !s.hasPermissionLocked(PERMISSION_MAY_PUBLISH_AUDIO)) || (publisher.HasMedia(MediaTypeVideo) && !s.hasPermissionLocked(PERMISSION_MAY_PUBLISH_VIDEO)) { delete(s.publishers, streamTypeVideo) - log.Printf("Session %s is no longer allowed to publish media, closing publisher %s", s.PublicId(), publisher.Id()) + s.logger.Infof("Session %s is no longer allowed to publish media, closing publisher %s", s.PublicId(), publisher.Id()) go func() { publisher.Close(context.Background()) }() @@ -978,7 +979,7 @@ func (s *ClientSession) processClientMessage(msg *nats.Msg) { if !s.hasPermissionLocked(PERMISSION_MAY_PUBLISH_SCREEN) { if publisher, found := s.publishers[streamTypeScreen]; found { delete(s.publishers, streamTypeScreen) - log.Printf("Session %s is no longer allowed to publish screen, closing publisher %s", s.PublicId(), publisher.Id()) + s.logger.Infof("Session %s is no longer allowed to publish screen, closing publisher %s", s.PublicId(), publisher.Id()) go func() { publisher.Close(context.Background()) }() @@ -992,7 +993,7 @@ func (s *ClientSession) processClientMessage(msg *nats.Msg) { s.mu.Lock() roomSessionId := s.RoomSessionId() s.mu.Unlock() - log.Printf("Closing session %s because same room session %s connected", s.PublicId(), roomSessionId) + s.logger.Warnf("Closing session %s because same room session %s connected", s.PublicId(), roomSessionId) s.LeaveRoom(false) defer s.closeAndWait(false) } @@ -1020,7 +1021,7 @@ func (s *ClientSession) storePendingMessage(message *ServerMessage) { } s.pendingClientMessages = append(s.pendingClientMessages, message) if len(s.pendingClientMessages) >= warnPendingMessagesCount { - log.Printf("Session %s has %d pending messages", s.PublicId(), len(s.pendingClientMessages)) + s.logger.Infof("Session %s has %d pending messages", s.PublicId(), len(s.pendingClientMessages)) } } @@ -1028,7 +1029,7 @@ func (s *ClientSession) processNatsMessage(msg *NatsMessage) *ServerMessage { switch msg.Type { case "message": if msg.Message == nil { - log.Printf("Received NATS message without payload: %+v", msg) + s.logger.Errorf("Received NATS message without payload: %+v", msg) return nil } @@ -1068,7 +1069,7 @@ func (s *ClientSession) processNatsMessage(msg *NatsMessage) *ServerMessage { // Can happen mostly during tests where an older room NATS message // could be received by a subscriber that joined after it was sent. if msg.SendTime.Before(s.getRoomJoinTime()) { - log.Printf("Message %+v was sent before room was joined, ignoring", msg.Message) + s.logger.Infof("Message %+v was sent before room was joined, ignoring", msg.Message) return nil } } @@ -1076,7 +1077,7 @@ func (s *ClientSession) processNatsMessage(msg *NatsMessage) *ServerMessage { return msg.Message default: - log.Printf("Received NATS message with unsupported type %s: %+v", msg.Type, msg) + s.logger.Errorf("Received NATS message with unsupported type %s: %+v", msg.Type, msg) return nil } } @@ -1098,7 +1099,7 @@ func (s *ClientSession) NotifySessionResumed(client *Client) { s.hasPendingParticipantsUpdate = false s.mu.Unlock() - log.Printf("Send %d pending messages to session %s", len(messages), s.PublicId()) + s.logger.Infof("Send %d pending messages to session %s", len(messages), s.PublicId()) // Send through session to handle connection interruptions. s.SendMessages(messages) diff --git a/clientsession_test.go b/clientsession_test.go index 427761f..7363ef9 100644 --- a/clientsession_test.go +++ b/clientsession_test.go @@ -128,7 +128,7 @@ func Test_permissionsEqual(t *testing.T) { func TestBandwidth_Client(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { @@ -212,7 +212,7 @@ func TestBandwidth_Backend(t *testing.T) { backend.maxScreenBitrate = 1000 backend.maxStreamBitrate = 2000 - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { diff --git a/deferred_executor.go b/deferred_executor.go index ee00b57..0c4ce80 100644 --- a/deferred_executor.go +++ b/deferred_executor.go @@ -22,7 +22,6 @@ package signaling import ( - "log" "reflect" "runtime" "runtime/debug" @@ -32,17 +31,19 @@ import ( // DeferredExecutor will asynchronously execute functions while maintaining // their order. type DeferredExecutor struct { + logger Logger queue chan func() closeChan chan bool closed chan bool closeOnce sync.Once } -func NewDeferredExecutor(queueSize int) *DeferredExecutor { +func NewDeferredExecutor(logger Logger, queueSize int) *DeferredExecutor { if queueSize < 0 { queueSize = 0 } result := &DeferredExecutor{ + logger: logger, queue: make(chan func(), queueSize), closeChan: make(chan bool, 1), closed: make(chan bool, 1), @@ -73,9 +74,9 @@ func getFunctionName(i interface{}) string { func (e *DeferredExecutor) Execute(f func()) { defer func() { - if e := recover(); e != nil { - log.Printf("Could not defer function %v: %+v", getFunctionName(f), e) - log.Printf("Called from %s", string(debug.Stack())) + if err := recover(); err != nil { + e.logger.Errorf("Could not defer function %v: %+v", getFunctionName(f), err) + e.logger.Errorf("Called from %s", string(debug.Stack())) } }() diff --git a/deferred_executor_test.go b/deferred_executor_test.go index 5aa8c08..b398077 100644 --- a/deferred_executor_test.go +++ b/deferred_executor_test.go @@ -26,17 +26,24 @@ import ( "time" ) +func NewDeferredExecutorForTest(t *testing.T, queueSize int) *DeferredExecutor { + logger := NewLoggerForTest(t) + e := NewDeferredExecutor(logger, queueSize) + t.Cleanup(func() { + e.waitForStop() + }) + return e +} + func TestDeferredExecutor_MultiClose(t *testing.T) { - e := NewDeferredExecutor(0) - defer e.waitForStop() + e := NewDeferredExecutorForTest(t, 0) e.Close() e.Close() } func TestDeferredExecutor_QueueSize(t *testing.T) { - e := NewDeferredExecutor(0) - defer e.waitForStop() + e := NewDeferredExecutorForTest(t, 0) defer e.Close() delay := 100 * time.Millisecond @@ -58,8 +65,7 @@ func TestDeferredExecutor_QueueSize(t *testing.T) { } func TestDeferredExecutor_Order(t *testing.T) { - e := NewDeferredExecutor(64) - defer e.waitForStop() + e := NewDeferredExecutorForTest(t, 64) defer e.Close() var entries []int @@ -87,8 +93,7 @@ func TestDeferredExecutor_Order(t *testing.T) { } func TestDeferredExecutor_CloseFromFunc(t *testing.T) { - e := NewDeferredExecutor(64) - defer e.waitForStop() + e := NewDeferredExecutorForTest(t, 64) done := make(chan bool) e.Execute(func() { @@ -100,9 +105,7 @@ func TestDeferredExecutor_CloseFromFunc(t *testing.T) { } func TestDeferredExecutor_DeferAfterClose(t *testing.T) { - e := NewDeferredExecutor(64) - defer e.waitForStop() - + e := NewDeferredExecutorForTest(t, 64) e.Close() e.Execute(func() { diff --git a/geoip.go b/geoip.go index 40cd4e1..705e15a 100644 --- a/geoip.go +++ b/geoip.go @@ -26,7 +26,6 @@ import ( "compress/gzip" "fmt" "io" - "log" "net" "net/http" "net/url" @@ -55,6 +54,7 @@ func GetGeoIpDownloadUrl(license string) string { } type GeoLookup struct { + logger Logger url string isFile bool client http.Client @@ -66,15 +66,17 @@ type GeoLookup struct { reader *maxminddb.Reader } -func NewGeoLookupFromUrl(url string) (*GeoLookup, error) { +func NewGeoLookupFromUrl(logger Logger, url string) (*GeoLookup, error) { geoip := &GeoLookup{ - url: url, + logger: logger, + url: url, } return geoip, nil } -func NewGeoLookupFromFile(filename string) (*GeoLookup, error) { +func NewGeoLookupFromFile(logger Logger, filename string) (*GeoLookup, error) { geoip := &GeoLookup{ + logger: logger, url: filename, isFile: true, } @@ -122,7 +124,7 @@ func (g *GeoLookup) updateFile() error { } metadata := reader.Metadata - log.Printf("Using %s GeoIP database from %s (built on %s)", metadata.DatabaseType, g.url, time.Unix(int64(metadata.BuildEpoch), 0).UTC()) + g.logger.Infof("Using %s GeoIP database from %s (built on %s)", metadata.DatabaseType, g.url, time.Unix(int64(metadata.BuildEpoch), 0).UTC()) g.mu.Lock() if g.reader != nil { @@ -149,7 +151,7 @@ func (g *GeoLookup) updateUrl() error { defer response.Body.Close() if response.StatusCode == http.StatusNotModified { - log.Printf("GeoIP database at %s has not changed", g.url) + g.logger.Infof("GeoIP database at %s has not changed", g.url) return nil } else if response.StatusCode/100 != 2 { return fmt.Errorf("downloading %s returned an error: %s", g.url, response.Status) @@ -198,7 +200,7 @@ func (g *GeoLookup) updateUrl() error { } metadata := reader.Metadata - log.Printf("Using %s GeoIP database from %s (built on %s)", metadata.DatabaseType, g.url, time.Unix(int64(metadata.BuildEpoch), 0).UTC()) + g.logger.Infof("Using %s GeoIP database from %s (built on %s)", metadata.DatabaseType, g.url, time.Unix(int64(metadata.BuildEpoch), 0).UTC()) g.mu.Lock() if g.reader != nil { diff --git a/geoip_test.go b/geoip_test.go index 2d359dd..bce4605 100644 --- a/geoip_test.go +++ b/geoip_test.go @@ -63,7 +63,8 @@ func TestGeoLookup(t *testing.T) { t.Skip("No MaxMind GeoLite2 license was set in MAXMIND_GEOLITE2_LICENSE environment variable.") } - reader, err := NewGeoLookupFromUrl(GetGeoIpDownloadUrl(license)) + logger := NewLoggerForTest(t) + reader, err := NewGeoLookupFromUrl(logger, GetGeoIpDownloadUrl(license)) if err != nil { t.Fatal(err) } @@ -82,7 +83,8 @@ func TestGeoLookupCaching(t *testing.T) { t.Skip("No MaxMind GeoLite2 license was set in MAXMIND_GEOLITE2_LICENSE environment variable.") } - reader, err := NewGeoLookupFromUrl(GetGeoIpDownloadUrl(license)) + logger := NewLoggerForTest(t) + reader, err := NewGeoLookupFromUrl(logger, GetGeoIpDownloadUrl(license)) if err != nil { t.Fatal(err) } @@ -128,7 +130,8 @@ func TestGeoLookupContinent(t *testing.T) { } func TestGeoLookupCloseEmpty(t *testing.T) { - reader, err := NewGeoLookupFromUrl("ignore-url") + logger := NewLoggerForTest(t) + reader, err := NewGeoLookupFromUrl(logger, "ignore-url") if err != nil { t.Fatal(err) } @@ -193,7 +196,8 @@ func TestGeoLookupFromFile(t *testing.T) { t.Fatal("Did not find MaxMind database in tarball") } - reader, err := NewGeoLookupFromFile(tmpfile.Name()) + logger := NewLoggerForTest(t) + reader, err := NewGeoLookupFromFile(logger, tmpfile.Name()) if err != nil { t.Fatal(err) } diff --git a/go.mod b/go.mod index 73b750e..d51685e 100644 --- a/go.mod +++ b/go.mod @@ -18,6 +18,7 @@ require ( github.com/prometheus/client_golang v1.12.1 go.etcd.io/etcd/client/pkg/v3 v3.5.2 go.etcd.io/etcd/client/v3 v3.5.2 + go.uber.org/zap v1.17.0 ) require ( @@ -41,7 +42,6 @@ require ( go.etcd.io/etcd/api/v3 v3.5.2 // indirect go.uber.org/atomic v1.7.0 // indirect go.uber.org/multierr v1.6.0 // indirect - go.uber.org/zap v1.17.0 // indirect golang.org/x/crypto v0.0.0-20220112180741-5e0467b6c7ce // indirect golang.org/x/net v0.0.0-20211112202133-69e39bad7dc2 // indirect golang.org/x/sys v0.0.0-20220325203850-36772127a21f // indirect diff --git a/hub.go b/hub.go index 706fb85..f2a9d8d 100644 --- a/hub.go +++ b/hub.go @@ -30,7 +30,6 @@ import ( "encoding/json" "fmt" "hash/fnv" - "log" "net" "net/http" "strings" @@ -103,6 +102,7 @@ type Hub struct { // 64-bit members that are accessed atomically must be 64-bit aligned. sid uint64 + logger Logger nats NatsClient upgrader websocket.Upgrader cookie *securecookie.SecureCookie @@ -149,13 +149,13 @@ type Hub struct { geoipUpdating int32 } -func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version string) (*Hub, error) { +func NewHub(logger Logger, config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version string) (*Hub, error) { hashKey, _ := config.GetString("sessions", "hashkey") switch len(hashKey) { case 32: case 64: default: - log.Printf("WARNING: The sessions hash key should be 32 or 64 bytes but is %d bytes", len(hashKey)) + logger.Warnf("WARNING: The sessions hash key should be 32 or 64 bytes but is %d bytes", len(hashKey)) } blockKey, _ := config.GetString("sessions", "blockkey") @@ -172,7 +172,7 @@ func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version s internalClientsSecret, _ := config.GetString("clients", "internalsecret") if internalClientsSecret == "" { - log.Println("WARNING: No shared secret has been set for internal clients.") + logger.Warn("WARNING: No shared secret has been set for internal clients.") } maxConcurrentRequestsPerHost, _ := config.GetInt("backend", "connectionsperhost") @@ -180,18 +180,18 @@ func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version s maxConcurrentRequestsPerHost = defaultMaxConcurrentRequestsPerHost } - backend, err := NewBackendClient(config, maxConcurrentRequestsPerHost, version) + backend, err := NewBackendClient(logger, config, maxConcurrentRequestsPerHost, version) if err != nil { return nil, err } - log.Printf("Using a maximum of %d concurrent backend connections per host", maxConcurrentRequestsPerHost) + logger.Infof("Using a maximum of %d concurrent backend connections per host", maxConcurrentRequestsPerHost) backendTimeoutSeconds, _ := config.GetInt("backend", "timeout") if backendTimeoutSeconds <= 0 { backendTimeoutSeconds = defaultBackendTimeoutSeconds } backendTimeout := time.Duration(backendTimeoutSeconds) * time.Second - log.Printf("Using a timeout of %s for backend connections", backendTimeout) + logger.Infof("Using a timeout of %s for backend connections", backendTimeout) mcuTimeoutSeconds, _ := config.GetInt("mcu", "timeout") if mcuTimeoutSeconds <= 0 { @@ -201,7 +201,7 @@ func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version s allowSubscribeAnyStream, _ := config.GetBool("app", "allowsubscribeany") if allowSubscribeAnyStream { - log.Printf("WARNING: Allow subscribing any streams, this is insecure and should only be enabled for testing") + logger.Warn("Allow subscribing any streams, this is insecure and should only be enabled for testing") } decodeCaches := make([]*LruCache, 0, numDecodeCaches) @@ -229,11 +229,11 @@ func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version s if geoipUrl != "" { if strings.HasPrefix(geoipUrl, "file://") { geoipUrl = geoipUrl[7:] - log.Printf("Using GeoIP database from %s", geoipUrl) - geoip, err = NewGeoLookupFromFile(geoipUrl) + logger.Infof("Using GeoIP database from %s", geoipUrl) + geoip, err = NewGeoLookupFromFile(logger, geoipUrl) } else { - log.Printf("Downloading GeoIP database from %s", geoipUrl) - geoip, err = NewGeoLookupFromUrl(geoipUrl) + logger.Infof("Downloading GeoIP database from %s", geoipUrl) + geoip, err = NewGeoLookupFromUrl(logger, geoipUrl) } if err != nil { return nil, err @@ -270,23 +270,24 @@ func NewHub(config *goconf.ConfigFile, nats NatsClient, r *mux.Router, version s value, _ := config.GetString("geoip-overrides", option) value = strings.ToUpper(strings.TrimSpace(value)) if value == "" { - log.Printf("IP %s doesn't have a country assigned, skipping", option) + logger.Errorf("IP %s doesn't have a country assigned, skipping", option) continue } else if !IsValidCountry(value) { - log.Printf("Country %s for IP %s is invalid, skipping", value, option) + logger.Errorf("Country %s for IP %s is invalid, skipping", value, option) continue } - log.Printf("Using country %s for %s", value, ipNet) + logger.Infof("Using country %s for %s", value, ipNet) geoipOverrides[ipNet] = value } } } else { - log.Printf("Not using GeoIP database") + logger.Infof("Not using GeoIP database") } hub := &Hub{ - nats: nats, + logger: logger, + nats: nats, upgrader: websocket.Upgrader{ ReadBufferSize: websocketReadBufferSize, WriteBufferSize: websocketWriteBufferSize, @@ -376,7 +377,7 @@ func (h *Hub) SetMcu(mcu Mcu) { removeFeature(h.infoInternal, ServerFeatureSimulcast) removeFeature(h.infoInternal, ServerFeatureUpdateSdp) } else { - log.Printf("Using a timeout of %s for MCU requests", h.mcuTimeout) + h.logger.Infof("Using a timeout of %s for MCU requests", h.mcuTimeout) addFeature(h.info, ServerFeatureMcu) addFeature(h.info, ServerFeatureSimulcast) addFeature(h.info, ServerFeatureUpdateSdp) @@ -417,7 +418,7 @@ func (h *Hub) updateGeoDatabase() { break } - log.Printf("Could not update GeoIP database, will retry later (%s)", err) + h.logger.Warnf("Could not update GeoIP database, will retry later (%s)", err) time.Sleep(delay) delay = delay * 2 if delay > 5*time.Minute { @@ -573,7 +574,7 @@ func (h *Hub) checkExpiredSessions(now time.Time) { for s := range h.expiredSessions { if s.IsExpired(now) { h.mu.Unlock() - log.Printf("Closing expired session %s (private=%s)", s.PublicId(), s.PrivateId()) + h.logger.Infof("Closing expired session %s (private=%s)", s.PublicId(), s.PrivateId()) s.Close() h.mu.Lock() // Should already be deleted by the close code, but better be sure. @@ -723,21 +724,21 @@ func (h *Hub) processRegister(client *Client, message *ClientMessage, backend *B userId := auth.Auth.UserId if userId != "" { - log.Printf("Register user %s@%s from %s in %s (%s) %s (private=%s)", userId, backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) + h.logger.Infof("Register user %s@%s from %s in %s (%s) %s (private=%s)", userId, backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) } else if message.Hello.Auth.Type != HelloClientTypeClient { - log.Printf("Register %s@%s from %s in %s (%s) %s (private=%s)", message.Hello.Auth.Type, backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) + h.logger.Infof("Register %s@%s from %s in %s (%s) %s (private=%s)", message.Hello.Auth.Type, backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) } else { - log.Printf("Register anonymous@%s from %s in %s (%s) %s (private=%s)", backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) + h.logger.Infof("Register anonymous@%s from %s in %s (%s) %s (private=%s)", backend.Id(), client.RemoteAddr(), client.Country(), client.UserAgent(), publicSessionId, privateSessionId) } - session, err := NewClientSession(h, privateSessionId, publicSessionId, sessionIdData, backend, message.Hello, auth.Auth) + session, err := NewClientSession(h.logger, h, privateSessionId, publicSessionId, sessionIdData, backend, message.Hello, auth.Auth) if err != nil { client.SendMessage(message.NewWrappedErrorServerMessage(err)) return } if err := backend.AddSession(session); err != nil { - log.Printf("Error adding session %s to backend %s: %s", session.PublicId(), backend.Id(), err) + h.logger.Errorf("Error adding session %s to backend %s: %s", session.PublicId(), backend.Id(), err) session.Close() client.SendMessage(message.NewWrappedErrorServerMessage(err)) return @@ -784,7 +785,7 @@ func (h *Hub) processUnregister(client *Client) *ClientSession { } h.mu.Unlock() if session != nil { - log.Printf("Unregister %s (private=%s)", session.PublicId(), session.PrivateId()) + h.logger.Infof("Unregister %s (private=%s)", session.PublicId(), session.PrivateId()) session.ClearClient(client) } @@ -796,10 +797,10 @@ func (h *Hub) processMessage(client *Client, data []byte) { var message ClientMessage if err := message.UnmarshalJSON(data); err != nil { if session := client.GetSession(); session != nil { - log.Printf("Error decoding message from client %s: %v", session.PublicId(), err) + h.logger.Errorf("Error decoding message from client %s: %v", session.PublicId(), err) session.SendError(InvalidFormat) } else { - log.Printf("Error decoding message from %s: %v", client.RemoteAddr(), err) + h.logger.Errorf("Error decoding message from %s: %v", client.RemoteAddr(), err) client.SendError(InvalidFormat) } return @@ -807,10 +808,10 @@ func (h *Hub) processMessage(client *Client, data []byte) { if err := message.CheckValid(); err != nil { if session := client.GetSession(); session != nil { - log.Printf("Invalid message %+v from client %s: %v", message, session.PublicId(), err) + h.logger.Errorf("Invalid message %+v from client %s: %v", message, session.PublicId(), err) session.SendMessage(message.NewErrorServerMessage(InvalidFormat)) } else { - log.Printf("Invalid message %+v from %s: %v", message, client.RemoteAddr(), err) + h.logger.Errorf("Invalid message %+v from %s: %v", message, client.RemoteAddr(), err) client.SendMessage(message.NewErrorServerMessage(InvalidFormat)) } return @@ -841,9 +842,9 @@ func (h *Hub) processMessage(client *Client, data []byte) { case "bye": h.processByeMsg(client, &message) case "hello": - log.Printf("Ignore hello %+v for already authenticated connection %s", message.Hello, session.PublicId()) + h.logger.Warnf("Ignore hello %+v for already authenticated connection %s", message.Hello, session.PublicId()) default: - log.Printf("Ignore unknown message %+v from %s", message, session.PublicId()) + h.logger.Errorf("Ignore unknown message %+v from %s", message, session.PublicId()) } } @@ -885,7 +886,7 @@ func (h *Hub) processHello(client *Client, message *ClientMessage) { if !ok { // Should never happen as clients only can resume their own sessions. h.mu.Unlock() - log.Printf("Client resumed non-client session %s (private=%s)", session.PublicId(), session.PrivateId()) + h.logger.Infof("Client resumed non-client session %s (private=%s)", session.PublicId(), session.PrivateId()) statsHubSessionResumeFailed.Inc() client.SendMessage(message.NewErrorServerMessage(NoSuchSession)) return @@ -898,7 +899,7 @@ func (h *Hub) processHello(client *Client, message *ClientMessage) { } if prev := clientSession.SetClient(client); prev != nil { - log.Printf("Closing previous client from %s for session %s", prev.RemoteAddr(), session.PublicId()) + h.logger.Infof("Closing previous client from %s for session %s", prev.RemoteAddr(), session.PublicId()) prev.SendByeResponseWithReason(nil, "session_resumed") } @@ -907,7 +908,7 @@ func (h *Hub) processHello(client *Client, message *ClientMessage) { delete(h.expectHelloClients, client) h.mu.Unlock() - log.Printf("Resume session from %s in %s (%s) %s (private=%s)", client.RemoteAddr(), client.Country(), client.UserAgent(), session.PublicId(), session.PrivateId()) + h.logger.Infof("Resume session from %s in %s (%s) %s (private=%s)", client.RemoteAddr(), client.Country(), client.UserAgent(), session.PublicId(), session.PrivateId()) statsHubSessionsResumedTotal.WithLabelValues(clientSession.Backend().Id(), clientSession.ClientType()).Inc() h.sendHelloResponse(clientSession, message) @@ -993,7 +994,7 @@ func (h *Hub) disconnectByRoomSessionId(roomSessionId string) { if err == ErrNoSuchRoomSession { return } else if err != nil { - log.Printf("Could not get session id for room session %s: %s", roomSessionId, err) + h.logger.Errorf("Could not get session id for room session %s: %s", roomSessionId, err) return } @@ -1007,12 +1008,12 @@ func (h *Hub) disconnectByRoomSessionId(roomSessionId string) { }, } if err := h.nats.PublishMessage("session."+sessionId, msg); err != nil { - log.Printf("Could not send reconnect bye to session %s: %s", sessionId, err) + h.logger.Errorf("Could not send reconnect bye to session %s: %s", sessionId, err) } return } - log.Printf("Closing session %s because same room session %s connected", session.PublicId(), roomSessionId) + h.logger.Infof("Closing session %s because same room session %s connected", session.PublicId(), roomSessionId) session.LeaveRoom(false) switch sess := session.(type) { case *ClientSession: @@ -1086,7 +1087,7 @@ func (h *Hub) processRoom(client *Client, message *ClientMessage) { sessionId := message.Room.SessionId if sessionId == "" { // TODO(jojo): Better make the session id required in the request. - log.Printf("User did not send a room session id, assuming session %s", session.PublicId()) + h.logger.Warnf("User did not send a room session id, assuming session %s", session.PublicId()) sessionId = session.PublicId() } request := NewBackendClientRoomRequest(roomId, session.UserId(), sessionId) @@ -1127,7 +1128,7 @@ func (h *Hub) removeRoom(room *Room) { func (h *Hub) createRoom(id string, properties *json.RawMessage, backend *Backend) (*Room, error) { // Note the write lock must be held. - room, err := NewRoom(id, properties, h, h.nats, backend) + room, err := NewRoom(h.logger, id, properties, h, h.nats, backend) if err != nil { return nil, err } @@ -1343,7 +1344,7 @@ func (h *Hub) processMessageMsg(client *Client, message *ClientMessage) { } } if subject == "" { - log.Printf("Unknown recipient in message %+v from %s", msg, session.PublicId()) + h.logger.Errorf("Unknown recipient in message %+v from %s", msg, session.PublicId()) return } @@ -1363,7 +1364,7 @@ func (h *Hub) processMessageMsg(client *Client, message *ClientMessage) { return } - log.Printf("Closing screen publisher for %s", session.PublicId()) + h.logger.Infof("Closing screen publisher for %s", session.PublicId()) ctx, cancel := context.WithTimeout(context.Background(), h.mcuTimeout) defer cancel() publisher.Close(ctx) @@ -1386,7 +1387,7 @@ func (h *Hub) processMessageMsg(client *Client, message *ClientMessage) { // The recipient is connected to this instance, no need to go through NATS. if clientData != nil && clientData.Type == "sendoffer" { if err := session.IsAllowedToSend(clientData); err != nil { - log.Printf("Session %s is not allowed to send offer for %s, ignoring (%s)", session.PublicId(), clientData.RoomType, err) + h.logger.Infof("Session %s is not allowed to send offer for %s, ignoring (%s)", session.PublicId(), clientData.RoomType, err) sendNotAllowed(session, message, "Not allowed to send offer") return } @@ -1406,11 +1407,11 @@ func (h *Hub) processMessageMsg(client *Client, message *ClientMessage) { } else { if clientData != nil && clientData.Type == "sendoffer" { // TODO(jojo): Implement this. - log.Printf("Sending offers to remote clients is not supported yet (client %s)", session.PublicId()) + h.logger.Errorf("Sending offers to remote clients is not supported yet (client %s)", session.PublicId()) return } if err := h.nats.PublishMessage(subject, response); err != nil { - log.Printf("Error publishing message to remote session: %s", err) + h.logger.Errorf("Error publishing message to remote session: %s", err) } } } @@ -1436,7 +1437,7 @@ func (h *Hub) processControlMsg(client *Client, message *ClientMessage) { // Client is not connected yet. return } else if !isAllowedToControl(session) { - log.Printf("Ignore control message %+v from %s", msg, session.PublicId()) + h.logger.Infof("Ignore control message %+v from %s", msg, session.PublicId()) return } @@ -1491,7 +1492,7 @@ func (h *Hub) processControlMsg(client *Client, message *ClientMessage) { } } if subject == "" { - log.Printf("Unknown recipient in message %+v from %s", msg, session.PublicId()) + h.logger.Errorf("Unknown recipient in message %+v from %s", msg, session.PublicId()) return } @@ -1511,7 +1512,7 @@ func (h *Hub) processControlMsg(client *Client, message *ClientMessage) { recipient.SendMessage(response) } else { if err := h.nats.PublishMessage(subject, response); err != nil { - log.Printf("Error publishing message to remote session: %s", err) + h.logger.Errorf("Error publishing message to remote session: %s", err) } } } @@ -1523,7 +1524,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { // Client is not connected yet. return } else if session.ClientType() != HelloClientTypeInternal { - log.Printf("Ignore internal message %+v from %s", msg, session.PublicId()) + h.logger.Infof("Ignore internal message %+v from %s", msg, session.PublicId()) return } @@ -1532,19 +1533,19 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { msg := msg.AddSession room := h.getRoomForBackend(msg.RoomId, session.Backend()) if room == nil { - log.Printf("Ignore add session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) + h.logger.Infof("Ignore add session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) return } sessionIdData := h.newSessionIdData(session.Backend()) privateSessionId, err := h.encodeSessionId(sessionIdData, privateSessionName) if err != nil { - log.Printf("Could not encode private virtual session id: %s", err) + h.logger.Errorf("Could not encode private virtual session id: %s", err) return } publicSessionId, err := h.encodeSessionId(sessionIdData, publicSessionName) if err != nil { - log.Printf("Could not encode public virtual session id: %s", err) + h.logger.Errorf("Could not encode public virtual session id: %s", err) return } @@ -1561,14 +1562,14 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { var response BackendClientResponse if err := h.backend.PerformJSONRequest(ctx, session.ParsedBackendUrl(), request, &response); err != nil { - log.Printf("Could not join virtual session %s at backend %s: %s", virtualSessionId, session.BackendUrl(), err) + h.logger.Errorf("Could not join virtual session %s at backend %s: %s", virtualSessionId, session.BackendUrl(), err) reply := message.NewErrorServerMessage(NewError("add_failed", "Could not join virtual session.")) session.SendMessage(reply) return } if response.Type == "error" { - log.Printf("Could not join virtual session %s at backend %s: %+v", virtualSessionId, session.BackendUrl(), response.Error) + h.logger.Errorf("Could not join virtual session %s at backend %s: %+v", virtualSessionId, session.BackendUrl(), response.Error) reply := message.NewErrorServerMessage(NewError("add_failed", response.Error.Error())) session.SendMessage(reply) return @@ -1577,21 +1578,21 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { request := NewBackendClientSessionRequest(room.Id(), "add", publicSessionId, msg) var response BackendClientSessionResponse if err := h.backend.PerformJSONRequest(ctx, session.ParsedBackendUrl(), request, &response); err != nil { - log.Printf("Could not add virtual session %s at backend %s: %s", virtualSessionId, session.BackendUrl(), err) + h.logger.Errorf("Could not add virtual session %s at backend %s: %s", virtualSessionId, session.BackendUrl(), err) reply := message.NewErrorServerMessage(NewError("add_failed", "Could not add virtual session.")) session.SendMessage(reply) return } } - sess := NewVirtualSession(session, privateSessionId, publicSessionId, sessionIdData, msg) + sess := NewVirtualSession(h.logger, session, privateSessionId, publicSessionId, sessionIdData, msg) h.mu.Lock() h.sessions[sessionIdData.Sid] = sess h.virtualSessions[virtualSessionId] = sessionIdData.Sid h.mu.Unlock() statsHubSessionsCurrent.WithLabelValues(session.Backend().Id(), sess.ClientType()).Inc() statsHubSessionsTotal.WithLabelValues(session.Backend().Id(), sess.ClientType()).Inc() - log.Printf("Session %s added virtual session %s with initial flags %d", session.PublicId(), sess.PublicId(), sess.Flags()) + h.logger.Infof("Session %s added virtual session %s with initial flags %d", session.PublicId(), sess.PublicId(), sess.Flags()) session.AddVirtualSession(sess) sess.SetRoom(room) room.AddSession(sess, nil) @@ -1599,7 +1600,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { msg := msg.UpdateSession room := h.getRoomForBackend(msg.RoomId, session.Backend()) if room == nil { - log.Printf("Ignore remove session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) + h.logger.Infof("Ignore remove session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) return } @@ -1622,7 +1623,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { } } } else { - log.Printf("Ignore update request for non-virtual session %s", sess.PublicId()) + h.logger.Infof("Ignore update request for non-virtual session %s", sess.PublicId()) } if update { room.NotifySessionChanged(sess) @@ -1632,7 +1633,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { msg := msg.RemoveSession room := h.getRoomForBackend(msg.RoomId, session.Backend()) if room == nil { - log.Printf("Ignore remove session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) + h.logger.Infof("Ignore remove session message %+v for invalid room %s from %s", *msg, msg.RoomId, session.PublicId()) return } @@ -1648,7 +1649,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { sess := h.sessions[sid] h.mu.Unlock() if sess != nil { - log.Printf("Session %s removed virtual session %s", session.PublicId(), sess.PublicId()) + h.logger.Infof("Session %s removed virtual session %s", session.PublicId(), sess.PublicId()) if vsess, ok := sess.(*VirtualSession); ok { // We should always have a VirtualSession here. vsess.CloseWithFeedback(session, message) @@ -1657,7 +1658,7 @@ func (h *Hub) processInternalMsg(client *Client, message *ClientMessage) { } } default: - log.Printf("Ignore unsupported internal message %+v from %s", msg, session.PublicId()) + h.logger.Errorf("Ignore unsupported internal message %+v from %s", msg, session.PublicId()) return } } @@ -1768,14 +1769,14 @@ func (h *Hub) processMcuMessage(senderSession *ClientSession, session *ClientSes switch data.Type { case "requestoffer": if session.PublicId() == message.Recipient.SessionId { - log.Printf("Not requesting offer from itself for session %s", session.PublicId()) + h.logger.Infof("Not requesting offer from itself for session %s", session.PublicId()) return } // A user is only allowed to subscribe a stream if she is in the same room // as the other user and both have their "inCall" flag set. if !h.allowSubscribeAnyStream && !h.isInSameCall(senderSession, message.Recipient.SessionId) { - log.Printf("Session %s is not in the same call as session %s, not requesting offer", session.PublicId(), message.Recipient.SessionId) + h.logger.Infof("Session %s is not in the same call as session %s, not requesting offer", session.PublicId(), message.Recipient.SessionId) sendNotAllowed(senderSession, client_message, "Not allowed to request offer.") return } @@ -1790,18 +1791,18 @@ func (h *Hub) processMcuMessage(senderSession *ClientSession, session *ClientSes clientType = "publisher" mc, err = session.GetOrCreatePublisher(ctx, h.mcu, data.RoomType, data) if err, ok := err.(*PermissionError); ok { - log.Printf("Session %s is not allowed to offer %s, ignoring (%s)", session.PublicId(), data.RoomType, err) + h.logger.Infof("Session %s is not allowed to offer %s, ignoring (%s)", session.PublicId(), data.RoomType, err) sendNotAllowed(senderSession, client_message, "Not allowed to publish.") return } if err, ok := err.(*SdpError); ok { - log.Printf("Session %s sent unsupported offer %s, ignoring (%s)", session.PublicId(), data.RoomType, err) + h.logger.Infof("Session %s sent unsupported offer %s, ignoring (%s)", session.PublicId(), data.RoomType, err) sendNotAllowed(senderSession, client_message, "Not allowed to publish.") return } case "selectStream": if session.PublicId() == message.Recipient.SessionId { - log.Printf("Not selecting substream for own %s stream in session %s", data.RoomType, session.PublicId()) + h.logger.Infof("Not selecting substream for own %s stream in session %s", data.RoomType, session.PublicId()) return } @@ -1810,7 +1811,7 @@ func (h *Hub) processMcuMessage(senderSession *ClientSession, session *ClientSes default: if session.PublicId() == message.Recipient.SessionId { if err := session.IsAllowedToSend(data); err != nil { - log.Printf("Session %s is not allowed to send candidate for %s, ignoring (%s)", session.PublicId(), data.RoomType, err) + h.logger.Infof("Session %s is not allowed to send candidate for %s, ignoring (%s)", session.PublicId(), data.RoomType, err) sendNotAllowed(senderSession, client_message, "Not allowed to send candidate.") return } @@ -1823,18 +1824,18 @@ func (h *Hub) processMcuMessage(senderSession *ClientSession, session *ClientSes } } if err != nil { - log.Printf("Could not create MCU %s for session %s to send %+v to %s: %s", clientType, session.PublicId(), data, message.Recipient.SessionId, err) + h.logger.Errorf("Could not create MCU %s for session %s to send %+v to %s: %s", clientType, session.PublicId(), data, message.Recipient.SessionId, err) sendMcuClientNotFound(senderSession, client_message) return } else if mc == nil { - log.Printf("No MCU %s found for session %s to send %+v to %s", clientType, session.PublicId(), data, message.Recipient.SessionId) + h.logger.Errorf("No MCU %s found for session %s to send %+v to %s", clientType, session.PublicId(), data, message.Recipient.SessionId) sendMcuClientNotFound(senderSession, client_message) return } mc.SendMessage(context.TODO(), message, data, func(err error, response map[string]interface{}) { if err != nil { - log.Printf("Could not send MCU message %+v for session %s to %s: %s", data, session.PublicId(), message.Recipient.SessionId, err) + h.logger.Errorf("Could not send MCU message %+v for session %s to %s: %s", data, session.PublicId(), message.Recipient.SessionId, err) sendMcuProcessingFailed(senderSession, client_message) return } else if response == nil { @@ -1859,7 +1860,7 @@ func (h *Hub) sendMcuMessageResponse(session *ClientSession, message *MessageCli } answer_data, err := json.Marshal(answer_message) if err != nil { - log.Printf("Could not serialize answer %+v to %s: %s", answer_message, session.PublicId(), err) + h.logger.Errorf("Could not serialize answer %+v to %s: %s", answer_message, session.PublicId(), err) return } response_message = &ServerMessage{ @@ -1883,7 +1884,7 @@ func (h *Hub) sendMcuMessageResponse(session *ClientSession, message *MessageCli } offer_data, err := json.Marshal(offer_message) if err != nil { - log.Printf("Could not serialize offer %+v to %s: %s", offer_message, session.PublicId(), err) + h.logger.Errorf("Could not serialize offer %+v to %s: %s", offer_message, session.PublicId(), err) return } response_message = &ServerMessage{ @@ -1898,7 +1899,7 @@ func (h *Hub) sendMcuMessageResponse(session *ClientSession, message *MessageCli }, } default: - log.Printf("Unsupported response %+v received to send to %s", response, session.PublicId()) + h.logger.Errorf("Unsupported response %+v received to send to %s", response, session.PublicId()) return } @@ -1941,7 +1942,7 @@ func (h *Hub) processRoomInCallChanged(message *BackendServerRoomRequest) { if err := json.Unmarshal(message.InCall.InCall, &flags); err != nil { var incall bool if err := json.Unmarshal(message.InCall.InCall, &incall); err != nil { - log.Printf("Unsupported InCall flags type: %+v, ignoring", string(message.InCall.InCall)) + h.logger.Errorf("Unsupported InCall flags type: %+v, ignoring", string(message.InCall.InCall)) return } @@ -2013,7 +2014,7 @@ func (h *Hub) lookupClientCountry(client *Client) string { country, err := h.geoip.LookupCountry(ip) if err != nil { - log.Printf("Could not lookup country for %s: %s", ip, err) + h.logger.Errorf("Could not lookup country for %s: %s", ip, err) return unknownCountry } @@ -2029,13 +2030,13 @@ func (h *Hub) serveWs(w http.ResponseWriter, r *http.Request) { conn, err := h.upgrader.Upgrade(w, r, nil) if err != nil { - log.Printf("Could not upgrade request from %s: %s", addr, err) + h.logger.Errorf("Could not upgrade request from %s: %s", addr, err) return } - client, err := NewClient(conn, addr, agent) + client, err := NewClient(h.logger, conn, addr, agent) if err != nil { - log.Printf("Could not create client for %s: %s", addr, err) + h.logger.Errorf("Could not create client for %s: %s", addr, err) return } diff --git a/hub_test.go b/hub_test.go index 9305275..0c5985d 100644 --- a/hub_test.go +++ b/hub_test.go @@ -102,7 +102,8 @@ func CreateHubForTestWithConfig(t *testing.T, getConfigFunc func(*httptest.Serve registerBackendHandler(t, r) server := httptest.NewServer(r) - nats, err := NewLoopbackNatsClient() + logger := NewLoggerForTest(t) + nats, err := NewLoopbackNatsClient(logger) if err != nil { t.Fatal(err) } @@ -110,11 +111,11 @@ func CreateHubForTestWithConfig(t *testing.T, getConfigFunc func(*httptest.Serve if err != nil { t.Fatal(err) } - h, err := NewHub(config, nats, r, "no-version") + h, err := NewHub(logger, config, nats, r, "no-version") if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, h, "no-version") + b, err := NewBackendServer(logger, config, h, "no-version") if err != nil { t.Fatal(err) } @@ -2303,7 +2304,7 @@ func TestClientTakeoverRoomSession(t *testing.T) { func TestClientSendOfferPermissions(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { @@ -2430,7 +2431,7 @@ func TestClientSendOfferPermissions(t *testing.T) { func TestClientSendOfferPermissionsAudioOnly(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { @@ -2521,7 +2522,7 @@ func TestClientSendOfferPermissionsAudioOnly(t *testing.T) { func TestClientSendOfferPermissionsAudioVideo(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { @@ -2649,7 +2650,7 @@ loop: func TestClientSendOfferPermissionsAudioVideoMedia(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { @@ -2781,7 +2782,7 @@ loop: func TestClientRequestOfferNotInRoom(t *testing.T) { hub, _, _, server := CreateHubForTest(t) - mcu, err := NewTestMCU() + mcu, err := NewTestMCU(hub.logger) if err != nil { t.Fatal(err) } else if err := mcu.Start(); err != nil { diff --git a/janus_client.go b/janus_client.go index d496b32..645d268 100644 --- a/janus_client.go +++ b/janus_client.go @@ -33,7 +33,6 @@ import ( "context" "encoding/json" "fmt" - "log" "net/http" "strconv" "sync" @@ -227,6 +226,7 @@ func (l *dummyGatewayListener) ConnectionInterrupted() { type JanusGateway struct { nextTransaction uint64 + logger Logger listener GatewayListener // Sessions is a map of the currently active sessions to the gateway. @@ -263,13 +263,14 @@ type JanusGateway struct { // return gateway, nil // } -func NewJanusGateway(wsURL string, listener GatewayListener) (*JanusGateway, error) { +func NewJanusGateway(logger Logger, wsURL string, listener GatewayListener) (*JanusGateway, error) { conn, _, err := janusDialer.Dial(wsURL, nil) if err != nil { return nil, err } gateway := new(JanusGateway) + gateway.logger = logger gateway.conn = conn gateway.transactions = make(map[uint64]*transaction) gateway.Sessions = make(map[uint64]*JanusSession) @@ -380,7 +381,7 @@ loop: err := gateway.conn.WriteControl(websocket.PingMessage, []byte{}, time.Now().Add(20*time.Second)) gateway.writeMu.Unlock() if err != nil { - log.Println("Error sending ping to MCU:", err) + gateway.logger.Errorf("Error sending ping to MCU: %s", err) } case <-gateway.closeChan: break loop @@ -405,7 +406,7 @@ func (gateway *JanusGateway) recv() { _, reader, err := conn.NextReader() if err != nil { - log.Printf("conn.NextReader: %s", err) + gateway.logger.Errorf("conn.NextReader: %s", err) gateway.writeMu.Lock() gateway.conn = nil gateway.writeMu.Unlock() @@ -416,7 +417,7 @@ func (gateway *JanusGateway) recv() { decodeBuffer.Reset() if _, err := decodeBuffer.ReadFrom(reader); err != nil { - log.Printf("decodeBuffer.ReadFrom: %s", err) + gateway.logger.Errorf("decodeBuffer.ReadFrom: %s", err) gateway.writeMu.Lock() gateway.conn = nil gateway.writeMu.Unlock() @@ -429,13 +430,13 @@ func (gateway *JanusGateway) recv() { decoder := json.NewDecoder(data) decoder.UseNumber() if err := decoder.Decode(&base); err != nil { - log.Printf("json.Unmarshal of %s: %s", decodeBuffer.String(), err) + gateway.logger.Errorf("json.Unmarshal of %s: %s", decodeBuffer.String(), err) continue } typeFunc, ok := msgtypes[base.Type] if !ok { - log.Printf("Unknown message type received: %s", decodeBuffer.String()) + gateway.logger.Errorf("Unknown message type received: %s", decodeBuffer.String()) continue } @@ -444,7 +445,7 @@ func (gateway *JanusGateway) recv() { decoder = json.NewDecoder(data) decoder.UseNumber() if err := decoder.Decode(&msg); err != nil { - log.Printf("json.Unmarshal of %s: %s", decodeBuffer.String(), err) + gateway.logger.Errorf("json.Unmarshal of %s: %s", decodeBuffer.String(), err) continue // Decode error } @@ -454,14 +455,14 @@ func (gateway *JanusGateway) recv() { if base.Handle == 0 { // Nope. No idea what's going on... // Error() - log.Printf("Received event without handle, ignoring: %s", decodeBuffer.String()) + gateway.logger.Errorf("Received event without handle, ignoring: %s", decodeBuffer.String()) } else { // Lookup Session gateway.Lock() session := gateway.Sessions[base.Session] gateway.Unlock() if session == nil { - log.Printf("Unable to deliver message %s. Session %d gone?", decodeBuffer.String(), base.Session) + gateway.logger.Errorf("Unable to deliver message %s. Session %d gone?", decodeBuffer.String(), base.Session) continue } @@ -470,7 +471,7 @@ func (gateway *JanusGateway) recv() { handle := session.Handles[base.Handle] session.Unlock() if handle == nil { - log.Printf("Unable to deliver message %s. Handle %d gone?", decodeBuffer.String(), base.Handle) + gateway.logger.Errorf("Unable to deliver message %s. Handle %d gone?", decodeBuffer.String(), base.Handle) continue } @@ -480,7 +481,7 @@ func (gateway *JanusGateway) recv() { } else { id, err := strconv.ParseUint(base.ID, 10, 64) if err != nil { - log.Printf("Could not decode transaction id %s: %s", base.ID, err) + gateway.logger.Errorf("Could not decode transaction id %s: %s", base.ID, err) continue } @@ -490,7 +491,7 @@ func (gateway *JanusGateway) recv() { gateway.Unlock() if transaction == nil { // Error() - log.Printf("Received event for unknown transaction, ignoring: %s", decodeBuffer.String()) + gateway.logger.Errorf("Received event for unknown transaction, ignoring: %s", decodeBuffer.String()) continue } diff --git a/logger.go b/logger.go new file mode 100644 index 0000000..fa34623 --- /dev/null +++ b/logger.go @@ -0,0 +1,76 @@ +/** + * Standalone signaling server for the Nextcloud Spreed app. + * Copyright (C) 2022 struktur AG + * + * @author Joachim Bauch + * + * @license GNU AGPL version 3 or any later version + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package signaling + +import ( + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +type Logger interface { + Debug(args ...interface{}) + Debugf(template string, args ...interface{}) + + Error(args ...interface{}) + Errorf(template string, args ...interface{}) + + Fatal(args ...interface{}) + Fatalf(template string, args ...interface{}) + + Info(args ...interface{}) + Infof(template string, args ...interface{}) + + Warn(args ...interface{}) + Warnf(template string, args ...interface{}) + + With(args ...interface{}) Logger + + Sync() error +} + +type logger struct { + *zap.SugaredLogger +} + +func (l *logger) With(args ...interface{}) Logger { + sugar := l.SugaredLogger.With(args...) + return WrapSugaredLogger(sugar) +} + +func NewLogger() (Logger, error) { + cfg := zap.NewProductionConfig() + cfg.EncoderConfig.TimeKey = "timestamp" + cfg.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + l, err := cfg.Build() + if err != nil { + return nil, err + } + + sugar := l.Sugar() + return WrapSugaredLogger(sugar), nil +} + +func WrapSugaredLogger(sugar *zap.SugaredLogger) Logger { + return &logger{ + sugar, + } +} diff --git a/logger_test.go b/logger_test.go new file mode 100644 index 0000000..d57a3f5 --- /dev/null +++ b/logger_test.go @@ -0,0 +1,46 @@ +/** + * Standalone signaling server for the Nextcloud Spreed app. + * Copyright (C) 2022 struktur AG + * + * @author Joachim Bauch + * + * @license GNU AGPL version 3 or any later version + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package signaling + +import ( + "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func NewLoggerForTest(t *testing.T) Logger { + cfg := zap.NewDevelopmentConfig() + cfg.EncoderConfig.TimeKey = "timestamp" + cfg.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + logger, err := cfg.Build() + if err != nil { + t.Fatalf("could not create logger: %s", err) + } + + t.Cleanup(func() { + logger.Sync() // nolint + }) + + sugar := logger.Sugar() + return WrapSugaredLogger(sugar) +} diff --git a/mcu_janus.go b/mcu_janus.go index f4b6f45..e67c46c 100644 --- a/mcu_janus.go +++ b/mcu_janus.go @@ -25,7 +25,6 @@ import ( "context" "encoding/json" "fmt" - "log" "reflect" "strconv" "sync" @@ -96,7 +95,7 @@ func convertIntValue(value interface{}) (uint64, error) { } } -func getPluginIntValue(data janus.PluginData, pluginName string, key string) uint64 { +func getPluginIntValue(logger Logger, data janus.PluginData, pluginName string, key string) uint64 { val := getPluginValue(data, pluginName, key) if val == nil { return 0 @@ -104,7 +103,7 @@ func getPluginIntValue(data janus.PluginData, pluginName string, key string) uin result, err := convertIntValue(val) if err != nil { - log.Printf("Invalid value %+v for %s: %s", val, key, err) + logger.Errorf("Invalid value %+v for %s: %s", val, key, err) result = 0 } return result @@ -134,8 +133,9 @@ type mcuJanus struct { // 64-bit members that are accessed atomically must be 64-bit aligned. clientId uint64 - url string - mu sync.Mutex + logger Logger + url string + mu sync.Mutex maxStreamBitrate int maxScreenBitrate int @@ -165,7 +165,7 @@ type mcuJanus struct { func emptyOnConnected() {} func emptyOnDisconnected() {} -func NewMcuJanus(url string, config *goconf.ConfigFile) (Mcu, error) { +func NewMcuJanus(logger Logger, url string, config *goconf.ConfigFile) (Mcu, error) { maxStreamBitrate, _ := config.GetInt("mcu", "maxstreambitrate") if maxStreamBitrate <= 0 { maxStreamBitrate = defaultMaxStreamBitrate @@ -181,6 +181,7 @@ func NewMcuJanus(url string, config *goconf.ConfigFile) (Mcu, error) { mcuTimeout := time.Duration(mcuTimeoutSeconds) * time.Second mcu := &mcuJanus{ + logger: logger.With("url", url), url: url, maxStreamBitrate: maxStreamBitrate, maxScreenBitrate: maxScreenBitrate, @@ -206,20 +207,20 @@ func NewMcuJanus(url string, config *goconf.ConfigFile) (Mcu, error) { func (m *mcuJanus) disconnect() { if m.handle != nil { if _, err := m.handle.Detach(context.TODO()); err != nil { - log.Printf("Error detaching handle %d: %s", m.handle.Id, err) + m.logger.Errorf("Error detaching handle %d: %s", m.handle.Id, err) } m.handle = nil } if m.session != nil { m.closeChan <- true if _, err := m.session.Destroy(context.TODO()); err != nil { - log.Printf("Error destroying session %d: %s", m.session.Id, err) + m.logger.Errorf("Error destroying session %d: %s", m.session.Id, err) } m.session = nil } if m.gw != nil { if err := m.gw.Close(); err != nil { - log.Println("Error while closing connection to MCU", err) + m.logger.Errorf("Error while closing connection to MCU: %s", err) } m.gw = nil } @@ -227,7 +228,7 @@ func (m *mcuJanus) disconnect() { func (m *mcuJanus) reconnect() error { m.disconnect() - gw, err := NewJanusGateway(m.url, m) + gw, err := NewJanusGateway(m.logger, m.url, m) if err != nil { return err } @@ -247,7 +248,7 @@ func (m *mcuJanus) doReconnect() { return } - log.Println("Reconnection to Janus gateway successful") + m.logger.Info("Reconnection to Janus gateway successful") m.mu.Lock() m.publishers = make(map[string]*mcuJanusPublisher) m.publisherCreated.Reset() @@ -267,9 +268,9 @@ func (m *mcuJanus) scheduleReconnect(err error) { defer m.mu.Unlock() m.reconnectTimer.Reset(m.reconnectInterval) if err == nil { - log.Printf("Connection to Janus gateway was interrupted, reconnecting in %s", m.reconnectInterval) + m.logger.Warnf("Connection to Janus gateway was interrupted, reconnecting in %s", m.reconnectInterval) } else { - log.Printf("Reconnect to Janus gateway failed (%s), reconnecting in %s", err, m.reconnectInterval) + m.logger.Errorf("Reconnect to Janus gateway failed (%s), reconnecting in %s", err, m.reconnectInterval) } m.reconnectInterval = m.reconnectInterval * 2 @@ -290,38 +291,38 @@ func (m *mcuJanus) Start() error { return err } - log.Printf("Connected to %s %s by %s", info.Name, info.VersionString, info.Author) + m.logger.Infof("Connected to %s %s by %s", info.Name, info.VersionString, info.Author) plugin, found := info.Plugins[pluginVideoRoom] if !found { return fmt.Errorf("Plugin %s is not supported", pluginVideoRoom) } - log.Printf("Found %s %s by %s", plugin.Name, plugin.VersionString, plugin.Author) + m.logger.Infof("Found %s %s by %s", plugin.Name, plugin.VersionString, plugin.Author) if !info.DataChannels { return fmt.Errorf("Data channels are not supported") } - log.Println("Data channels are supported") + m.logger.Info("Data channels are supported") if !info.FullTrickle { - log.Println("WARNING: Full-Trickle is NOT enabled in Janus!") + m.logger.Warn("Full-Trickle is NOT enabled in Janus!") } else { - log.Println("Full-Trickle is enabled") + m.logger.Info("Full-Trickle is enabled") } - log.Printf("Maximum bandwidth %d bits/sec per publishing stream", m.maxStreamBitrate) - log.Printf("Maximum bandwidth %d bits/sec per screensharing stream", m.maxScreenBitrate) + m.logger.Infof("Maximum bandwidth %d bits/sec per publishing stream", m.maxStreamBitrate) + m.logger.Infof("Maximum bandwidth %d bits/sec per screensharing stream", m.maxScreenBitrate) if m.session, err = m.gw.Create(ctx); err != nil { m.disconnect() return err } - log.Println("Created Janus session", m.session.Id) + m.logger.Infof("Created Janus session %d", m.session.Id) m.connectedSince = time.Now() if m.handle, err = m.session.Attach(ctx, pluginVideoRoom); err != nil { m.disconnect() return err } - log.Println("Created Janus handle", m.handle.Id) + m.logger.Infof("Created Janus handle %d", m.handle.Id) go m.run() @@ -418,7 +419,7 @@ func (m *mcuJanus) GetStats() interface{} { func (m *mcuJanus) sendKeepalive() { ctx := context.TODO() if _, err := m.session.KeepAlive(ctx); err != nil { - log.Println("Could not send keepalive request", err) + m.logger.Errorf("Could not send keepalive request: %s", err) if e, ok := err.(*janus.ErrorMsg); ok { switch e.Err.Code { case JANUS_ERROR_SESSION_NOT_FOUND: @@ -429,6 +430,7 @@ func (m *mcuJanus) sendKeepalive() { } type mcuJanusClient struct { + logger Logger mcu *mcuJanus listener McuListener mu sync.Mutex // nolint @@ -471,7 +473,7 @@ func (c *mcuJanusClient) closeClient(ctx context.Context) bool { c.closeChan <- true if _, err := handle.Detach(ctx); err != nil { if e, ok := err.(*janus.ErrorMsg); !ok || e.Err.Code != JANUS_ERROR_HANDLE_NOT_FOUND { - log.Println("Could not detach client", handle.Id, err) + c.logger.Errorf("Could not detach client %d: %s", handle.Id, err) } } return true @@ -501,7 +503,7 @@ loop: case *TrickleMsg: c.handleTrickle(t) default: - log.Println("Received unsupported event type", msg, reflect.TypeOf(msg)) + c.logger.Errorf("Received unsupported event type: %+v %s", msg, reflect.TypeOf(msg)) } case f := <-c.deferred: f() @@ -549,7 +551,7 @@ func (c *mcuJanusClient) sendAnswer(ctx context.Context, answer map[string]inter callback(err, nil) return } - log.Println("Started listener", start_response) + c.logger.Infof("Started listener: %+v", start_response) callback(nil, nil) } @@ -723,7 +725,7 @@ func (m *mcuJanus) getOrCreatePublisherHandle(ctx context.Context, id string, st return nil, 0, 0, err } - log.Printf("Attached %s as publisher %d to plugin %s in session %d", streamType, handle.Id, pluginVideoRoom, session.Id) + m.logger.Infof("Attached %s as publisher %d to plugin %s in session %d", streamType, handle.Id, pluginVideoRoom, session.Id) create_msg := map[string]interface{}{ "request": "create", "description": id + "|" + streamType, @@ -748,20 +750,20 @@ func (m *mcuJanus) getOrCreatePublisherHandle(ctx context.Context, id string, st create_response, err := handle.Request(ctx, create_msg) if err != nil { if _, err2 := handle.Detach(ctx); err2 != nil { - log.Printf("Error detaching handle %d: %s", handle.Id, err2) + m.logger.Errorf("Error detaching handle %d: %s", handle.Id, err2) } return nil, 0, 0, err } - roomId := getPluginIntValue(create_response.PluginData, pluginVideoRoom, "room") + roomId := getPluginIntValue(m.logger, create_response.PluginData, pluginVideoRoom, "room") if roomId == 0 { if _, err := handle.Detach(ctx); err != nil { - log.Printf("Error detaching handle %d: %s", handle.Id, err) + m.logger.Errorf("Error detaching handle %d: %s", handle.Id, err) } return nil, 0, 0, fmt.Errorf("No room id received: %+v", create_response) } - log.Println("Created room", roomId, create_response.PluginData) + m.logger.Infof("Created room %d: %+v", roomId, create_response.PluginData) msg := map[string]interface{}{ "request": "join", @@ -773,7 +775,7 @@ func (m *mcuJanus) getOrCreatePublisherHandle(ctx context.Context, id string, st response, err := handle.Message(ctx, msg, nil) if err != nil { if _, err2 := handle.Detach(ctx); err2 != nil { - log.Printf("Error detaching handle %d: %s", handle.Id, err2) + m.logger.Errorf("Error detaching handle %d: %s", handle.Id, err2) } return nil, 0, 0, err } @@ -793,6 +795,7 @@ func (m *mcuJanus) NewPublisher(ctx context.Context, listener McuListener, id st client := &mcuJanusPublisher{ mcuJanusClient: mcuJanusClient{ + logger: m.logger, mcu: m, listener: listener, @@ -818,7 +821,7 @@ func (m *mcuJanus) NewPublisher(ctx context.Context, listener McuListener, id st client.mcuJanusClient.handleMedia = client.handleMedia m.registerClient(client) - log.Printf("Publisher %s is using handle %d", client.id, client.handleId) + m.logger.Infof("Publisher %s is using handle %d", client.id, client.handleId) go client.run(handle, client.closeChan) m.mu.Lock() m.publishers[id+"|"+streamType] = client @@ -834,38 +837,38 @@ func (p *mcuJanusPublisher) handleEvent(event *janus.EventMsg) { ctx := context.TODO() switch videoroom { case "destroyed": - log.Printf("Publisher %d: associated room has been destroyed, closing", p.handleId) + p.logger.Infof("Publisher %d: associated room has been destroyed, closing", p.handleId) go p.Close(ctx) case "slow_link": // Ignore, processed through "handleSlowLink" in the general events. default: - log.Printf("Unsupported videoroom publisher event in %d: %+v", p.handleId, event) + p.logger.Errorf("Unsupported videoroom publisher event in %d: %+v", p.handleId, event) } } else { - log.Printf("Unsupported publisher event in %d: %+v", p.handleId, event) + p.logger.Errorf("Unsupported publisher event in %d: %+v", p.handleId, event) } } func (p *mcuJanusPublisher) handleHangup(event *janus.HangupMsg) { - log.Printf("Publisher %d received hangup (%s), closing", p.handleId, event.Reason) + p.logger.Infof("Publisher %d received hangup (%s), closing", p.handleId, event.Reason) go p.Close(context.Background()) } func (p *mcuJanusPublisher) handleDetached(event *janus.DetachedMsg) { - log.Printf("Publisher %d received detached, closing", p.handleId) + p.logger.Infof("Publisher %d received detached, closing", p.handleId) go p.Close(context.Background()) } func (p *mcuJanusPublisher) handleConnected(event *janus.WebRTCUpMsg) { - log.Printf("Publisher %d received connected", p.handleId) + p.logger.Infof("Publisher %d received connected", p.handleId) p.mcu.publisherConnected.Notify(p.id + "|" + p.streamType) } func (p *mcuJanusPublisher) handleSlowLink(event *janus.SlowLinkMsg) { if event.Uplink { - log.Printf("Publisher %s (%d) is reporting %d lost packets on the uplink (Janus -> client)", p.listener.PublicId(), p.handleId, event.Lost) + p.logger.Infof("Publisher %s (%d) is reporting %d lost packets on the uplink (Janus -> client)", p.listener.PublicId(), p.handleId, event.Lost) } else { - log.Printf("Publisher %s (%d) is reporting %d lost packets on the downlink (client -> Janus)", p.listener.PublicId(), p.handleId, event.Lost) + p.logger.Infof("Publisher %s (%d) is reporting %d lost packets on the downlink (client -> Janus)", p.listener.PublicId(), p.handleId, event.Lost) } } @@ -887,7 +890,7 @@ func (p *mcuJanusPublisher) NotifyReconnected() { ctx := context.TODO() handle, session, roomId, err := p.mcu.getOrCreatePublisherHandle(ctx, p.id, p.streamType, p.bitrate) if err != nil { - log.Printf("Could not reconnect publisher %s: %s", p.id, err) + p.logger.Errorf("Could not reconnect publisher %s: %s", p.id, err) // TODO(jojo): Retry return } @@ -897,7 +900,7 @@ func (p *mcuJanusPublisher) NotifyReconnected() { p.session = session p.roomId = roomId - log.Printf("Publisher %s reconnected on handle %d", p.id, p.handleId) + p.logger.Infof("Publisher %s reconnected on handle %d", p.id, p.handleId) } func (p *mcuJanusPublisher) Close(ctx context.Context) { @@ -909,9 +912,9 @@ func (p *mcuJanusPublisher) Close(ctx context.Context) { "room": p.roomId, } if _, err := handle.Request(ctx, destroy_msg); err != nil { - log.Printf("Error destroying room %d: %s", p.roomId, err) + p.logger.Errorf("Error destroying room %d: %s", p.roomId, err) } else { - log.Printf("Room %d destroyed", p.roomId) + p.logger.Infof("Room %d destroyed", p.roomId) } p.mcu.mu.Lock() delete(p.mcu.publishers, p.id+"|"+p.streamType) @@ -1007,7 +1010,7 @@ func (m *mcuJanus) getOrCreateSubscriberHandle(ctx context.Context, publisher st return nil, nil, err } - log.Printf("Attached subscriber to room %d of publisher %s in plugin %s in session %d as %d", pub.roomId, publisher, pluginVideoRoom, session.Id, handle.Id) + m.logger.Infof("Attached subscriber to room %d of publisher %s in plugin %s in session %d as %d", pub.roomId, publisher, pluginVideoRoom, session.Id, handle.Id) return handle, pub, nil } @@ -1023,6 +1026,7 @@ func (m *mcuJanus) NewSubscriber(ctx context.Context, listener McuListener, publ client := &mcuJanusSubscriber{ mcuJanusClient: mcuJanusClient{ + logger: m.logger, mcu: m, listener: listener, @@ -1059,7 +1063,7 @@ func (p *mcuJanusSubscriber) handleEvent(event *janus.EventMsg) { ctx := context.TODO() switch videoroom { case "destroyed": - log.Printf("Subscriber %d: associated room has been destroyed, closing", p.handleId) + p.logger.Infof("Subscriber %d: associated room has been destroyed, closing", p.handleId) go p.Close(ctx) case "event": // Handle renegotiations, but ignore other events like selected @@ -1071,33 +1075,33 @@ func (p *mcuJanusSubscriber) handleEvent(event *janus.EventMsg) { case "slow_link": // Ignore, processed through "handleSlowLink" in the general events. default: - log.Printf("Unsupported videoroom event %s for subscriber %d: %+v", videoroom, p.handleId, event) + p.logger.Errorf("Unsupported videoroom event %s for subscriber %d: %+v", videoroom, p.handleId, event) } } else { - log.Printf("Unsupported event for subscriber %d: %+v", p.handleId, event) + p.logger.Errorf("Unsupported event for subscriber %d: %+v", p.handleId, event) } } func (p *mcuJanusSubscriber) handleHangup(event *janus.HangupMsg) { - log.Printf("Subscriber %d received hangup (%s), closing", p.handleId, event.Reason) + p.logger.Infof("Subscriber %d received hangup (%s), closing", p.handleId, event.Reason) go p.Close(context.Background()) } func (p *mcuJanusSubscriber) handleDetached(event *janus.DetachedMsg) { - log.Printf("Subscriber %d received detached, closing", p.handleId) + p.logger.Infof("Subscriber %d received detached, closing", p.handleId) go p.Close(context.Background()) } func (p *mcuJanusSubscriber) handleConnected(event *janus.WebRTCUpMsg) { - log.Printf("Subscriber %d received connected", p.handleId) + p.logger.Infof("Subscriber %d received connected", p.handleId) p.mcu.SubscriberConnected(p.Id(), p.publisher, p.streamType) } func (p *mcuJanusSubscriber) handleSlowLink(event *janus.SlowLinkMsg) { if event.Uplink { - log.Printf("Subscriber %s (%d) is reporting %d lost packets on the uplink (Janus -> client)", p.listener.PublicId(), p.handleId, event.Lost) + p.logger.Infof("Subscriber %s (%d) is reporting %d lost packets on the uplink (Janus -> client)", p.listener.PublicId(), p.handleId, event.Lost) } else { - log.Printf("Subscriber %s (%d) is reporting %d lost packets on the downlink (client -> Janus)", p.listener.PublicId(), p.handleId, event.Lost) + p.logger.Infof("Subscriber %s (%d) is reporting %d lost packets on the downlink (client -> Janus)", p.listener.PublicId(), p.handleId, event.Lost) } } @@ -1111,7 +1115,7 @@ func (p *mcuJanusSubscriber) NotifyReconnected() { handle, pub, err := p.mcu.getOrCreateSubscriberHandle(ctx, p.publisher, p.streamType) if err != nil { // TODO(jojo): Retry? - log.Printf("Could not reconnect subscriber for publisher %s: %s", p.publisher, err) + p.logger.Errorf("Could not reconnect subscriber for publisher %s: %s", p.publisher, err) p.Close(context.Background()) return } @@ -1119,7 +1123,7 @@ func (p *mcuJanusSubscriber) NotifyReconnected() { p.handle = handle p.handleId = handle.Id p.roomId = pub.roomId - log.Printf("Subscriber %d for publisher %s reconnected on handle %d", p.id, p.publisher, p.handleId) + p.logger.Infof("Subscriber %d for publisher %s reconnected on handle %d", p.id, p.publisher, p.handleId) } func (p *mcuJanusSubscriber) Close(ctx context.Context) { @@ -1160,7 +1164,7 @@ retry: return } - if error_code := getPluginIntValue(join_response.Plugindata, pluginVideoRoom, "error_code"); error_code > 0 { + if error_code := getPluginIntValue(p.logger, join_response.Plugindata, pluginVideoRoom, "error_code"); error_code > 0 { switch error_code { case JANUS_VIDEOROOM_ERROR_ALREADY_JOINED: // The subscriber is already connected to the room. This can happen @@ -1189,16 +1193,16 @@ retry: p.roomId = pub.roomId p.closeChan = make(chan bool, 1) go p.run(p.handle, p.closeChan) - log.Printf("Already connected subscriber %d for %s, leaving and re-joining on handle %d", p.id, p.streamType, p.handleId) + p.logger.Warnf("Already connected subscriber %d for %s, leaving and re-joining on handle %d", p.id, p.streamType, p.handleId) goto retry case JANUS_VIDEOROOM_ERROR_NO_SUCH_ROOM: fallthrough case JANUS_VIDEOROOM_ERROR_NO_SUCH_FEED: switch error_code { case JANUS_VIDEOROOM_ERROR_NO_SUCH_ROOM: - log.Printf("Publisher %s not created yet for %s, wait and retry to join room %d as subscriber", p.publisher, p.streamType, p.roomId) + p.logger.Infof("Publisher %s not created yet for %s, wait and retry to join room %d as subscriber", p.publisher, p.streamType, p.roomId) case JANUS_VIDEOROOM_ERROR_NO_SUCH_FEED: - log.Printf("Publisher %s not sending yet for %s, wait and retry to join room %d as subscriber", p.publisher, p.streamType, p.roomId) + p.logger.Infof("Publisher %s not sending yet for %s, wait and retry to join room %d as subscriber", p.publisher, p.streamType, p.roomId) } if !loggedNotPublishingYet { @@ -1210,7 +1214,7 @@ retry: callback(err, nil) return } - log.Printf("Retry subscribing %s from %s", p.streamType, p.publisher) + p.logger.Infof("Retry subscribing %s from %s", p.streamType, p.publisher) goto retry default: // TODO(jojo): Should we handle other errors, too? @@ -1218,7 +1222,7 @@ retry: return } } - //log.Println("Joined as listener", join_response) + //p.logger.Infof("Joined as listener: %+v", join_response) p.session = join_response.Session callback(nil, join_response.Jsep) diff --git a/mcu_proxy.go b/mcu_proxy.go index 1d12272..909c6a6 100644 --- a/mcu_proxy.go +++ b/mcu_proxy.go @@ -27,7 +27,6 @@ import ( "crypto/tls" "encoding/json" "fmt" - "log" "net" "net/http" "net/url" @@ -75,6 +74,7 @@ const ( ) type mcuProxyPubSubCommon struct { + logger Logger streamType string proxyId string conn *mcuProxyConnection @@ -97,7 +97,7 @@ func (c *mcuProxyPubSubCommon) doSendMessage(ctx context.Context, msg *ProxyClie } if proxyDebugMessages { - log.Printf("Response from %s: %+v", c.conn, response) + c.logger.Debugf("Response from %s: %+v", c.conn, response) } if response.Type == "error" { callback(response.Error, nil) @@ -116,7 +116,7 @@ func (c *mcuProxyPubSubCommon) doProcessPayload(client McuClient, msg *PayloadPr case "candidate": c.listener.OnIceCandidate(client, msg.Payload["candidate"]) default: - log.Printf("Unsupported payload from %s: %+v", c.conn, msg) + c.logger.Errorf("Unsupported payload from %s: %+v", c.conn, msg) } } @@ -127,9 +127,10 @@ type mcuProxyPublisher struct { mediaTypes MediaType } -func newMcuProxyPublisher(id string, streamType string, mediaTypes MediaType, proxyId string, conn *mcuProxyConnection, listener McuListener) *mcuProxyPublisher { +func newMcuProxyPublisher(logger Logger, id string, streamType string, mediaTypes MediaType, proxyId string, conn *mcuProxyConnection, listener McuListener) *mcuProxyPublisher { return &mcuProxyPublisher{ mcuProxyPubSubCommon: mcuProxyPubSubCommon{ + logger: logger, streamType: streamType, proxyId: proxyId, conn: conn, @@ -161,11 +162,11 @@ func (p *mcuProxyPublisher) Close(ctx context.Context) { } if _, err := p.conn.performSyncRequest(ctx, msg); err != nil { - log.Printf("Could not delete publisher %s at %s: %s", p.proxyId, p.conn, err) + p.logger.Errorf("Could not delete publisher %s at %s: %s", p.proxyId, p.conn, err) return } - log.Printf("Delete publisher %s at %s", p.proxyId, p.conn) + p.logger.Infof("Delete publisher %s at %s", p.proxyId, p.conn) } func (p *mcuProxyPublisher) SendMessage(ctx context.Context, message *MessageClientMessage, data *MessageClientMessageData, callback func(error, map[string]interface{})) { @@ -192,7 +193,7 @@ func (p *mcuProxyPublisher) ProcessEvent(msg *EventProxyServerMessage) { case "publisher-closed": p.NotifyClosed() default: - log.Printf("Unsupported event from %s: %+v", p.conn, msg) + p.logger.Errorf("Unsupported event from %s: %+v", p.conn, msg) } } @@ -202,9 +203,10 @@ type mcuProxySubscriber struct { publisherId string } -func newMcuProxySubscriber(publisherId string, streamType string, proxyId string, conn *mcuProxyConnection, listener McuListener) *mcuProxySubscriber { +func newMcuProxySubscriber(logger Logger, publisherId string, streamType string, proxyId string, conn *mcuProxyConnection, listener McuListener) *mcuProxySubscriber { return &mcuProxySubscriber{ mcuProxyPubSubCommon: mcuProxyPubSubCommon{ + logger: logger, streamType: streamType, proxyId: proxyId, conn: conn, @@ -236,11 +238,11 @@ func (s *mcuProxySubscriber) Close(ctx context.Context) { } if _, err := s.conn.performSyncRequest(ctx, msg); err != nil { - log.Printf("Could not delete subscriber %s at %s: %s", s.proxyId, s.conn, err) + s.logger.Errorf("Could not delete subscriber %s at %s: %s", s.proxyId, s.conn, err) return } - log.Printf("Delete subscriber %s at %s", s.proxyId, s.conn) + s.logger.Infof("Delete subscriber %s at %s", s.proxyId, s.conn) } func (s *mcuProxySubscriber) SendMessage(ctx context.Context, message *MessageClientMessage, data *MessageClientMessageData, callback func(error, map[string]interface{})) { @@ -267,7 +269,7 @@ func (s *mcuProxySubscriber) ProcessEvent(msg *EventProxyServerMessage) { case "subscriber-closed": s.NotifyClosed() default: - log.Printf("Unsupported event from %s: %+v", s.conn, msg) + s.logger.Errorf("Unsupported event from %s: %+v", s.conn, msg) } } @@ -277,6 +279,7 @@ type mcuProxyConnection struct { msgId int64 load int64 + logger Logger proxy *mcuProxy rawUrl string url *url.URL @@ -308,13 +311,14 @@ type mcuProxyConnection struct { subscribers map[string]*mcuProxySubscriber } -func newMcuProxyConnection(proxy *mcuProxy, baseUrl string, ip net.IP) (*mcuProxyConnection, error) { +func newMcuProxyConnection(logger Logger, proxy *mcuProxy, baseUrl string, ip net.IP) (*mcuProxyConnection, error) { parsed, err := url.Parse(baseUrl) if err != nil { return nil, err } conn := &mcuProxyConnection{ + logger: logger, proxy: proxy, rawUrl: baseUrl, url: parsed, @@ -413,7 +417,7 @@ func (c *mcuProxyConnection) readPump() { rtt := now.Sub(time.Unix(0, ts)) if rtt >= rttLogDuration { rtt_ms := rtt.Nanoseconds() / time.Millisecond.Nanoseconds() - log.Printf("Proxy at %s has RTT of %d ms (%s)", c, rtt_ms, rtt) + c.logger.Infof("Proxy at %s has RTT of %d ms (%s)", c, rtt_ms, rtt) } } return nil @@ -427,14 +431,14 @@ func (c *mcuProxyConnection) readPump() { websocket.CloseNormalClosure, websocket.CloseGoingAway, websocket.CloseNoStatusReceived) { - log.Printf("Error reading from %s: %v", c, err) + c.logger.Errorf("Error reading from %s: %v", c, err) } break } var msg ProxyServerMessage if err := json.Unmarshal(message, &msg); err != nil { - log.Printf("Error unmarshaling %s from %s: %s", string(message), c, err) + c.logger.Errorf("Error unmarshaling %s from %s: %s", string(message), c, err) continue } @@ -453,7 +457,7 @@ func (c *mcuProxyConnection) sendPing() bool { msg := strconv.FormatInt(now.UnixNano(), 10) c.conn.SetWriteDeadline(now.Add(writeWait)) // nolint if err := c.conn.WriteMessage(websocket.PingMessage, []byte(msg)); err != nil { - log.Printf("Could not send ping to proxy at %s: %v", c, err) + c.logger.Errorf("Could not send ping to proxy at %s: %v", c, err) c.scheduleReconnect() return false } @@ -505,7 +509,7 @@ func (c *mcuProxyConnection) stop(ctx context.Context) { c.closeChan <- true if err := c.sendClose(); err != nil { if err != ErrNotConnected { - log.Printf("Could not send close message to %s: %s", c, err) + c.logger.Errorf("Could not send close message to %s: %s", c, err) } c.close() return @@ -515,7 +519,7 @@ func (c *mcuProxyConnection) stop(ctx context.Context) { case <-c.closedChan: case <-ctx.Done(): if err := ctx.Err(); err != nil { - log.Printf("Error waiting for connection to %s get closed: %s", c, err) + c.logger.Errorf("Error waiting for connection to %s get closed: %s", c, err) c.close() } } @@ -550,7 +554,7 @@ func (c *mcuProxyConnection) closeIfEmpty() bool { c.subscribersLock.RUnlock() if total > 0 { // Connection will be closed once all clients have disconnected. - log.Printf("Connection to %s is still used by %d clients, defer closing", c, total) + c.logger.Infof("Connection to %s is still used by %d clients, defer closing", c, total) return false } @@ -558,7 +562,7 @@ func (c *mcuProxyConnection) closeIfEmpty() bool { ctx, cancel := context.WithTimeout(context.Background(), closeTimeout) defer cancel() - log.Printf("All clients disconnected, closing connection to %s", c) + c.logger.Infof("All clients disconnected, closing connection to %s", c) c.stop(ctx) c.proxy.removeConnection(c) @@ -568,7 +572,7 @@ func (c *mcuProxyConnection) closeIfEmpty() bool { func (c *mcuProxyConnection) scheduleReconnect() { if err := c.sendClose(); err != nil && err != ErrNotConnected { - log.Printf("Could not send close message to %s: %s", c, err) + c.logger.Errorf("Could not send close message to %s: %s", c, err) } c.close() @@ -585,7 +589,7 @@ func (c *mcuProxyConnection) scheduleReconnect() { func (c *mcuProxyConnection) reconnect() { u, err := c.url.Parse("proxy") if err != nil { - log.Printf("Could not resolve url to proxy at %s: %s", c, err) + c.logger.Errorf("Could not resolve url to proxy at %s: %s", c, err) c.scheduleReconnect() return } @@ -614,12 +618,12 @@ func (c *mcuProxyConnection) reconnect() { } conn, _, err := dialer.Dial(u.String(), nil) if err != nil { - log.Printf("Could not connect to %s: %s", c, err) + c.logger.Errorf("Could not connect to %s: %s", c, err) c.scheduleReconnect() return } - log.Printf("Connected to %s", c) + c.logger.Infof("Connected to %s", c) atomic.StoreUint32(&c.closed, 0) c.mu.Lock() @@ -630,7 +634,7 @@ func (c *mcuProxyConnection) reconnect() { atomic.StoreInt64(&c.reconnectInterval, int64(initialReconnectInterval)) atomic.StoreUint32(&c.shutdownScheduled, 0) if err := c.sendHello(); err != nil { - log.Printf("Could not send hello request to %s: %s", c, err) + c.logger.Errorf("Could not send hello request to %s: %s", c, err) c.scheduleReconnect() return } @@ -730,19 +734,19 @@ func (c *mcuProxyConnection) processMessage(msg *ProxyServerMessage) { switch msg.Type { case "error": if msg.Error.Code == "no_such_session" { - log.Printf("Session %s could not be resumed on %s, registering new", c.sessionId, c) + c.logger.Warnf("Session %s could not be resumed on %s, registering new", c.sessionId, c) c.clearPublishers() c.clearSubscribers() c.clearCallbacks() c.sessionId = "" if err := c.sendHello(); err != nil { - log.Printf("Could not send hello request to %s: %s", c, err) + c.logger.Errorf("Could not send hello request to %s: %s", c, err) c.scheduleReconnect() } return } - log.Printf("Hello connection to %s failed with %+v, reconnecting", c, msg.Error) + c.logger.Errorf("Hello connection to %s failed with %+v, reconnecting", c, msg.Error) c.scheduleReconnect() case "hello": resumed := c.sessionId == msg.Hello.SessionId @@ -750,30 +754,30 @@ func (c *mcuProxyConnection) processMessage(msg *ProxyServerMessage) { country := "" if msg.Hello.Server != nil { if country = msg.Hello.Server.Country; country != "" && !IsValidCountry(country) { - log.Printf("Proxy %s sent invalid country %s in hello response", c, country) + c.logger.Warnf("Proxy %s sent invalid country %s in hello response", c, country) country = "" } } c.country.Store(country) if resumed { - log.Printf("Resumed session %s on %s", c.sessionId, c) + c.logger.Infof("Resumed session %s on %s", c.sessionId, c) } else if country != "" { - log.Printf("Received session %s from %s (in %s)", c.sessionId, c, country) + c.logger.Infof("Received session %s from %s (in %s)", c.sessionId, c, country) } else { - log.Printf("Received session %s from %s", c.sessionId, c) + c.logger.Infof("Received session %s from %s", c.sessionId, c) } if atomic.CompareAndSwapUint32(&c.trackClose, 0, 1) { statsConnectedProxyBackendsCurrent.WithLabelValues(c.Country()).Inc() } default: - log.Printf("Received unsupported hello response %+v from %s, reconnecting", msg, c) + c.logger.Errorf("Received unsupported hello response %+v from %s, reconnecting", msg, c) c.scheduleReconnect() } return } if proxyDebugMessages { - log.Printf("Received from %s: %+v", c, msg) + c.logger.Debugf("Received from %s: %+v", c, msg) } callback := c.getCallback(msg.Id) if callback != nil { @@ -789,7 +793,7 @@ func (c *mcuProxyConnection) processMessage(msg *ProxyServerMessage) { case "bye": c.processBye(msg) default: - log.Printf("Unsupported message received from %s: %+v", c, msg) + c.logger.Errorf("Unsupported message received from %s: %+v", c, msg) } } @@ -811,37 +815,37 @@ func (c *mcuProxyConnection) processPayload(msg *ProxyServerMessage) { return } - log.Printf("Received payload for unknown client %+v from %s", payload, c) + c.logger.Errorf("Received payload for unknown client %+v from %s", payload, c) } func (c *mcuProxyConnection) processEvent(msg *ProxyServerMessage) { event := msg.Event switch event.Type { case "backend-disconnected": - log.Printf("Upstream backend at %s got disconnected, reset MCU objects", c) + c.logger.Warnf("Upstream backend at %s got disconnected, reset MCU objects", c) c.clearPublishers() c.clearSubscribers() c.clearCallbacks() // TODO: Should we also reconnect? return case "backend-connected": - log.Printf("Upstream backend at %s is connected", c) + c.logger.Infof("Upstream backend at %s is connected", c) return case "update-load": if proxyDebugMessages { - log.Printf("Load of %s now at %d", c, event.Load) + c.logger.Debugf("Load of %s now at %d", c, event.Load) } atomic.StoreInt64(&c.load, event.Load) statsProxyBackendLoadCurrent.WithLabelValues(c.url.String()).Set(float64(event.Load)) return case "shutdown-scheduled": - log.Printf("Proxy %s is scheduled to shutdown", c) + c.logger.Infof("Proxy %s is scheduled to shutdown", c) atomic.StoreUint32(&c.shutdownScheduled, 1) return } if proxyDebugMessages { - log.Printf("Process event from %s: %+v", c, event) + c.logger.Debugf("Process event from %s: %+v", c, event) } c.publishersLock.RLock() publisher, found := c.publishers[event.ClientId] @@ -859,17 +863,17 @@ func (c *mcuProxyConnection) processEvent(msg *ProxyServerMessage) { return } - log.Printf("Received event for unknown client %+v from %s", event, c) + c.logger.Errorf("Received event for unknown client %+v from %s", event, c) } func (c *mcuProxyConnection) processBye(msg *ProxyServerMessage) { bye := msg.Bye switch bye.Reason { case "session_resumed": - log.Printf("Session %s on %s was resumed by other client, resetting", c.sessionId, c) + c.logger.Warnf("Session %s on %s was resumed by other client, resetting", c.sessionId, c) c.sessionId = "" default: - log.Printf("Received bye with unsupported reason from %s %+v", c, bye) + c.logger.Errorf("Received bye with unsupported reason from %s %+v", c, bye) } } @@ -911,7 +915,7 @@ func (c *mcuProxyConnection) sendMessage(msg *ProxyClientMessage) error { func (c *mcuProxyConnection) sendMessageLocked(msg *ProxyClientMessage) error { if proxyDebugMessages { - log.Printf("Send message to %s: %+v", c, msg) + c.logger.Debugf("Send message to %s: %+v", c, msg) } if c.conn == nil { return ErrNotConnected @@ -979,8 +983,8 @@ func (c *mcuProxyConnection) newPublisher(ctx context.Context, listener McuListe } proxyId := response.Command.Id - log.Printf("Created %s publisher %s on %s for %s", streamType, proxyId, c, id) - publisher := newMcuProxyPublisher(id, streamType, mediaTypes, proxyId, c, listener) + c.logger.Infof("Created %s publisher %s on %s for %s", streamType, proxyId, c, id) + publisher := newMcuProxyPublisher(c.logger, id, streamType, mediaTypes, proxyId, c, listener) c.publishersLock.Lock() c.publishers[proxyId] = publisher c.publisherIds[id+"|"+streamType] = proxyId @@ -1014,8 +1018,8 @@ func (c *mcuProxyConnection) newSubscriber(ctx context.Context, listener McuList } proxyId := response.Command.Id - log.Printf("Created %s subscriber %s on %s for %s", streamType, proxyId, c, publisher) - subscriber := newMcuProxySubscriber(publisher, streamType, proxyId, c, listener) + c.logger.Infof("Created %s subscriber %s on %s for %s", streamType, proxyId, c, publisher) + subscriber := newMcuProxySubscriber(c.logger, publisher, streamType, proxyId, c, listener) c.subscribersLock.Lock() c.subscribers[proxyId] = subscriber c.subscribersLock.Unlock() @@ -1029,6 +1033,7 @@ type mcuProxy struct { connRequests int64 nextSort int64 + logger Logger urlType string tokenId string tokenKey *rsa.PrivateKey @@ -1060,7 +1065,7 @@ type mcuProxy struct { continentsMap atomic.Value } -func NewMcuProxy(config *goconf.ConfigFile) (Mcu, error) { +func NewMcuProxy(logger Logger, config *goconf.ConfigFile) (Mcu, error) { urlType, _ := config.GetString("mcu", "urltype") if urlType == "" { urlType = proxyUrlTypeStatic @@ -1088,7 +1093,7 @@ func NewMcuProxy(config *goconf.ConfigFile) (Mcu, error) { proxyTimeoutSeconds = defaultProxyTimeoutSeconds } proxyTimeout := time.Duration(proxyTimeoutSeconds) * time.Second - log.Printf("Using a timeout of %s for proxy requests", proxyTimeout) + logger.Infof("Using a timeout of %s for proxy requests", proxyTimeout) maxStreamBitrate, _ := config.GetInt("mcu", "maxstreambitrate") if maxStreamBitrate <= 0 { @@ -1100,6 +1105,7 @@ func NewMcuProxy(config *goconf.ConfigFile) (Mcu, error) { } mcu := &mcuProxy{ + logger: logger, urlType: urlType, tokenId: tokenId, tokenKey: tokenKey, @@ -1128,7 +1134,7 @@ func NewMcuProxy(config *goconf.ConfigFile) (Mcu, error) { skipverify, _ := config.GetBool("mcu", "skipverify") if skipverify { - log.Println("WARNING: MCU verification is disabled!") + logger.Warn("MCU verification is disabled!") mcu.dialer.TLSClientConfig = &tls.Config{ InsecureSkipVerify: skipverify, } @@ -1166,7 +1172,7 @@ func (m *mcuProxy) loadContinentsMap(config *goconf.ConfigFile) error { for _, option := range options { option = strings.ToUpper(strings.TrimSpace(option)) if !IsValidContinent(option) { - log.Printf("Ignore unknown continent %s", option) + m.logger.Errorf("Ignore unknown continent %s", option) continue } @@ -1175,18 +1181,18 @@ func (m *mcuProxy) loadContinentsMap(config *goconf.ConfigFile) error { for _, v := range strings.Split(value, ",") { v = strings.ToUpper(strings.TrimSpace(v)) if !IsValidContinent(v) { - log.Printf("Ignore unknown continent %s for override %s", v, option) + m.logger.Errorf("Ignore unknown continent %s for override %s", v, option) continue } values = append(values, v) } if len(values) == 0 { - log.Printf("No valid values found for continent override %s, ignoring", option) + m.logger.Errorf("No valid values found for continent override %s, ignoring", option) continue } continentsMap[option] = values - log.Printf("Mapping users on continent %s to %s", option, values) + m.logger.Infof("Mapping users on continent %s to %s", option, values) } m.setContinentsMap(continentsMap) @@ -1206,8 +1212,8 @@ func (m *mcuProxy) Start() error { m.connectionsMu.RLock() defer m.connectionsMu.RUnlock() - log.Printf("Maximum bandwidth %d bits/sec per publishing stream", m.maxStreamBitrate) - log.Printf("Maximum bandwidth %d bits/sec per screensharing stream", m.maxScreenBitrate) + m.logger.Infof("Maximum bandwidth %d bits/sec per publishing stream", m.maxStreamBitrate) + m.logger.Infof("Maximum bandwidth %d bits/sec per screensharing stream", m.maxScreenBitrate) for _, c := range m.connections { if err := c.start(); err != nil { @@ -1239,7 +1245,7 @@ func (m *mcuProxy) Stop() { } func (m *mcuProxy) monitorProxyIPs() { - log.Printf("Start monitoring proxy IPs") + m.logger.Info("Start monitoring proxy IPs") ticker := time.NewTicker(updateDnsInterval) for { select { @@ -1268,7 +1274,7 @@ func (m *mcuProxy) updateProxyIPs() { ips, err := net.LookupIP(host) if err != nil { - log.Printf("Could not lookup %s: %s", host, err) + m.logger.Errorf("Could not lookup %s: %s", host, err) continue } @@ -1288,24 +1294,24 @@ func (m *mcuProxy) updateProxyIPs() { if !found { changed = true - log.Printf("Removing connection to %s", conn) + m.logger.Infof("Removing connection to %s", conn) conn.closeIfEmpty() } } for _, ip := range ips { - conn, err := newMcuProxyConnection(m, u, ip) + conn, err := newMcuProxyConnection(m.logger, m, u, ip) if err != nil { - log.Printf("Could not create proxy connection to %s (%s): %s", u, ip, err) + m.logger.Errorf("Could not create proxy connection to %s (%s): %s", u, ip, err) continue } if err := conn.start(); err != nil { - log.Printf("Could not start new connection to %s: %s", conn, err) + m.logger.Errorf("Could not start new connection to %s: %s", conn, err) continue } - log.Printf("Adding new connection to %s", conn) + m.logger.Infof("Adding new connection to %s", conn) m.connections = append(m.connections, conn) newConns = append(newConns, conn) changed = true @@ -1359,7 +1365,7 @@ func (m *mcuProxy) configureStatic(config *goconf.ConfigFile, fromReload bool) e return err } - log.Printf("Could not parse URL %s: %s", u, err) + m.logger.Errorf("Could not parse URL %s: %s", u, err) continue } @@ -1370,33 +1376,33 @@ func (m *mcuProxy) configureStatic(config *goconf.ConfigFile, fromReload bool) e ips, err = net.LookupIP(parsed.Host) if err != nil { // Will be retried later. - log.Printf("Could not lookup %s: %s\n", parsed.Host, err) + m.logger.Errorf("Could not lookup %s: %s\n", parsed.Host, err) continue } } var conns []*mcuProxyConnection if ips == nil { - conn, err := newMcuProxyConnection(m, u, nil) + conn, err := newMcuProxyConnection(m.logger, m, u, nil) if err != nil { if !fromReload { return err } - log.Printf("Could not create proxy connection to %s: %s", u, err) + m.logger.Errorf("Could not create proxy connection to %s: %s", u, err) continue } conns = append(conns, conn) } else { for _, ip := range ips { - conn, err := newMcuProxyConnection(m, u, ip) + conn, err := newMcuProxyConnection(m.logger, m, u, ip) if err != nil { if !fromReload { return err } - log.Printf("Could not create proxy connection to %s (%s): %s", u, ip, err) + m.logger.Errorf("Could not create proxy connection to %s (%s): %s", u, ip, err) continue } @@ -1417,11 +1423,11 @@ func (m *mcuProxy) configureStatic(config *goconf.ConfigFile, fromReload bool) e var started []*mcuProxyConnection for _, conn := range conns { if err := conn.start(); err != nil { - log.Printf("Could not start new connection to %s: %s", conn, err) + m.logger.Errorf("Could not start new connection to %s: %s", conn, err) continue } - log.Printf("Adding new connection to %s", conn) + m.logger.Infof("Adding new connection to %s", conn) started = append(started, conn) m.connections = append(m.connections, conn) } @@ -1476,7 +1482,7 @@ func (m *mcuProxy) configureEtcd(config *goconf.ConfigFile, ignoreErrors bool) e return fmt.Errorf("No proxy URL endpoints configured") } - log.Printf("No proxy URL endpoints configured, not changing client") + m.logger.Infof("No proxy URL endpoints configured, not changing client") } else { cfg := clientv3.Config{ Endpoints: endpoints, @@ -1500,7 +1506,7 @@ func (m *mcuProxy) configureEtcd(config *goconf.ConfigFile, ignoreErrors bool) e return fmt.Errorf("Could not setup TLS configuration: %s", err) } - log.Printf("Could not setup TLS configuration, will be disabled (%s)", err) + m.logger.Errorf("Could not setup TLS configuration, will be disabled (%s)", err) } else { cfg.TLS = tlsConfig } @@ -1512,19 +1518,19 @@ func (m *mcuProxy) configureEtcd(config *goconf.ConfigFile, ignoreErrors bool) e return err } - log.Printf("Could not create new client from proxy URL endpoints %+v: %s", endpoints, err) + m.logger.Errorf("Could not create new client from proxy URL endpoints %+v: %s", endpoints, err) } else { prev := m.getEtcdClient() if prev != nil { prev.Close() } m.client.Store(c) - log.Printf("Using proxy URL endpoints %+v", endpoints) + m.logger.Infof("Using proxy URL endpoints %+v", endpoints) go func(client *clientv3.Client) { - log.Printf("Wait for leader and start watching on %s", keyPrefix) + m.logger.Infof("Wait for leader and start watching on %s", keyPrefix) ch := client.Watch(clientv3.WithRequireLeader(context.Background()), keyPrefix, clientv3.WithPrefix()) - log.Printf("Watch created for %s", keyPrefix) + m.logger.Infof("Watch created for %s", keyPrefix) m.processWatches(ch) }(c) @@ -1536,9 +1542,9 @@ func (m *mcuProxy) configureEtcd(config *goconf.ConfigFile, ignoreErrors bool) e response, err := m.getProxyUrls(keyPrefix) if err != nil { if err == context.DeadlineExceeded { - log.Printf("Timeout getting initial list of proxy URLs, retry in %s", waitDelay) + m.logger.Errorf("Timeout getting initial list of proxy URLs, retry in %s", waitDelay) } else { - log.Printf("Could not get initial list of proxy URLs, retry in %s: %s", waitDelay, err) + m.logger.Errorf("Could not get initial list of proxy URLs, retry in %s: %s", waitDelay, err) } time.Sleep(waitDelay) @@ -1573,9 +1579,9 @@ func (m *mcuProxy) waitForConnection() { for { if err := m.syncClient(); err != nil { if err == context.DeadlineExceeded { - log.Printf("Timeout waiting for etcd client to connect to the cluster, retry in %s", waitDelay) + m.logger.Errorf("Timeout waiting for etcd client to connect to the cluster, retry in %s", waitDelay) } else { - log.Printf("Could not sync etcd client with the cluster, retry in %s: %s", waitDelay, err) + m.logger.Errorf("Could not sync etcd client with the cluster, retry in %s: %s", waitDelay, err) } time.Sleep(waitDelay) @@ -1586,7 +1592,7 @@ func (m *mcuProxy) waitForConnection() { continue } - log.Printf("Client using endpoints %+v", m.getEtcdClient().Endpoints()) + m.logger.Infof("Client using endpoints %+v", m.getEtcdClient().Endpoints()) return } } @@ -1600,13 +1606,13 @@ func (m *mcuProxy) syncClient() error { func (m *mcuProxy) Reload(config *goconf.ConfigFile) { if err := m.loadContinentsMap(config); err != nil { - log.Printf("Error loading continents map: %s", err) + m.logger.Errorf("Error loading continents map: %s", err) } switch m.urlType { case proxyUrlTypeStatic: if err := m.configureStatic(config, true); err != nil { - log.Printf("Could not configure static proxy urls: %s", err) + m.logger.Errorf("Could not configure static proxy urls: %s", err) } default: // Reloading not supported yet. @@ -1622,7 +1628,7 @@ func (m *mcuProxy) processWatches(ch clientv3.WatchChan) { case clientv3.EventTypeDelete: m.removeEtcdProxy(string(ev.Kv.Key)) default: - log.Printf("Unsupported event %s %q -> %q", ev.Type, ev.Kv.Key, ev.Kv.Value) + m.logger.Errorf("Unsupported event %s %q -> %q", ev.Type, ev.Kv.Key, ev.Kv.Value) } } } @@ -1631,11 +1637,11 @@ func (m *mcuProxy) processWatches(ch clientv3.WatchChan) { func (m *mcuProxy) addEtcdProxy(key string, data []byte) { var info ProxyInformationEtcd if err := json.Unmarshal(data, &info); err != nil { - log.Printf("Could not decode proxy information %s: %s", string(data), err) + m.logger.Errorf("Could not decode proxy information %s: %s", string(data), err) return } if err := info.CheckValid(); err != nil { - log.Printf("Received invalid proxy information %s: %s", string(data), err) + m.logger.Errorf("Received invalid proxy information %s: %s", string(data), err) return } @@ -1649,7 +1655,7 @@ func (m *mcuProxy) addEtcdProxy(key string, data []byte) { } if otherKey, found := m.urlToKey[info.Address]; found && otherKey != key { - log.Printf("Address %s is already registered for key %s, ignoring %s", info.Address, otherKey, key) + m.logger.Errorf("Address %s is already registered for key %s, ignoring %s", info.Address, otherKey, key) return } @@ -1662,18 +1668,18 @@ func (m *mcuProxy) addEtcdProxy(key string, data []byte) { conn.stopCloseIfEmpty() } } else { - conn, err := newMcuProxyConnection(m, info.Address, nil) + conn, err := newMcuProxyConnection(m.logger, m, info.Address, nil) if err != nil { - log.Printf("Could not create proxy connection to %s: %s", info.Address, err) + m.logger.Errorf("Could not create proxy connection to %s: %s", info.Address, err) return } if err := conn.start(); err != nil { - log.Printf("Could not start new connection to %s: %s", info.Address, err) + m.logger.Errorf("Could not start new connection to %s: %s", info.Address, err) return } - log.Printf("Adding new connection to %s (from %s)", info.Address, key) + m.logger.Infof("Adding new connection to %s (from %s)", info.Address, key) m.keyInfos[key] = &info m.urlToKey[info.Address] = key m.connections = append(m.connections, conn) @@ -1698,7 +1704,7 @@ func (m *mcuProxy) removeEtcdProxyLocked(key string) { delete(m.keyInfos, key) delete(m.urlToKey, info.Address) - log.Printf("Removing connection to %s (from %s)", info.Address, key) + m.logger.Infof("Removing connection to %s (from %s)", info.Address, key) m.connectionsMu.RLock() defer m.connectionsMu.RUnlock() @@ -1934,7 +1940,7 @@ func (m *mcuProxy) NewPublisher(ctx context.Context, listener McuListener, id st } publisher, err := conn.newPublisher(subctx, listener, id, streamType, bitrate, mediaTypes) if err != nil { - log.Printf("Could not create %s publisher for %s on %s: %s", streamType, id, conn, err) + m.logger.Errorf("Could not create %s publisher for %s on %s: %s", streamType, id, conn, err) continue } @@ -1957,7 +1963,7 @@ func (m *mcuProxy) getPublisherConnection(ctx context.Context, publisher string, return conn } - log.Printf("No %s publisher %s found yet, deferring", streamType, publisher) + m.logger.Warnf("No %s publisher %s found yet, deferring", streamType, publisher) m.mu.Lock() defer m.mu.Unlock() diff --git a/mcu_test.go b/mcu_test.go index 605f0a9..d098c00 100644 --- a/mcu_test.go +++ b/mcu_test.go @@ -24,7 +24,6 @@ package signaling import ( "context" "fmt" - "log" "sync" "sync/atomic" @@ -37,12 +36,14 @@ const ( ) type TestMCU struct { + logger Logger mu sync.Mutex publishers map[string]*TestMCUPublisher } -func NewTestMCU() (*TestMCU, error) { +func NewTestMCU(logger Logger) (*TestMCU, error) { return &TestMCU{ + logger: logger, publishers: make(map[string]*TestMCUPublisher), }, nil } @@ -81,6 +82,7 @@ func (m *TestMCU) NewPublisher(ctx context.Context, listener McuListener, id str } pub := &TestMCUPublisher{ TestMCUClient: TestMCUClient{ + logger: m.logger, id: id, streamType: streamType, }, @@ -119,6 +121,7 @@ func (m *TestMCU) NewSubscriber(ctx context.Context, listener McuListener, publi } type TestMCUClient struct { + logger Logger closed int32 id string @@ -134,7 +137,7 @@ func (c *TestMCUClient) StreamType() string { } func (c *TestMCUClient) Close(ctx context.Context) { - log.Printf("Close MCU client %s", c.id) + c.logger.Infof("Close MCU client %s", c.id) atomic.StoreInt32(&c.closed, 1) } diff --git a/natsclient.go b/natsclient.go index c82c00b..f9287e4 100644 --- a/natsclient.go +++ b/natsclient.go @@ -24,7 +24,6 @@ package signaling import ( "encoding/base64" "fmt" - "log" "os" "os/signal" "time" @@ -76,17 +75,20 @@ func GetEncodedSubject(prefix string, suffix string) string { } type natsClient struct { - nc *nats.Conn - conn *nats.EncodedConn + logger Logger + nc *nats.Conn + conn *nats.EncodedConn } -func NewNatsClient(url string) (NatsClient, error) { +func NewNatsClient(logger Logger, url string) (NatsClient, error) { if url == ":loopback:" { - log.Println("No NATS url configured, using internal loopback client") - return NewLoopbackNatsClient() + logger.Info("No NATS url configured, using internal loopback client") + return NewLoopbackNatsClient(logger) } - client := &natsClient{} + client := &natsClient{ + logger: logger, + } var err error client.nc, err = nats.Connect(url, @@ -102,7 +104,7 @@ func NewNatsClient(url string) (NatsClient, error) { timer := time.NewTimer(delay) // The initial connect must succeed, so we retry in the case of an error. for err != nil { - log.Printf("Could not create connection (%s), will retry in %s", err, delay) + logger.Errorf("Could not create connection (%s), will retry in %s", err, delay) timer.Reset(delay) select { case <-interrupt: @@ -117,7 +119,7 @@ func NewNatsClient(url string) (NatsClient, error) { client.nc, err = nats.Connect(url) } - log.Printf("Connection established to %s (%s)", client.nc.ConnectedUrl(), client.nc.ConnectedServerId()) + logger.Infof("Connection established to %s (%s)", client.nc.ConnectedUrl(), client.nc.ConnectedServerId()) // All communication will be JSON based. client.conn, _ = nats.NewEncodedConn(client.nc, nats.JSON_ENCODER) @@ -129,15 +131,15 @@ func (c *natsClient) Close() { } func (c *natsClient) onClosed(conn *nats.Conn) { - log.Println("NATS client closed", conn.LastError()) + c.logger.Errorf("NATS client closed: %s", conn.LastError()) } func (c *natsClient) onDisconnected(conn *nats.Conn) { - log.Println("NATS client disconnected") + c.logger.Error("NATS client disconnected") } func (c *natsClient) onReconnected(conn *nats.Conn) { - log.Printf("NATS client reconnected to %s (%s)", conn.ConnectedUrl(), conn.ConnectedServerId()) + c.logger.Infof("NATS client reconnected to %s (%s)", conn.ConnectedUrl(), conn.ConnectedServerId()) } func (c *natsClient) Subscribe(subject string, ch chan *nats.Msg) (NatsSubscription, error) { diff --git a/natsclient_loopback.go b/natsclient_loopback.go index aaa1699..9443f2f 100644 --- a/natsclient_loopback.go +++ b/natsclient_loopback.go @@ -24,7 +24,6 @@ package signaling import ( "container/list" "encoding/json" - "log" "strings" "sync" "time" @@ -33,6 +32,8 @@ import ( ) type LoopbackNatsClient struct { + logger Logger + mu sync.Mutex subscriptions map[string]map[*loopbackNatsSubscription]bool @@ -41,8 +42,10 @@ type LoopbackNatsClient struct { incoming list.List } -func NewLoopbackNatsClient() (NatsClient, error) { +func NewLoopbackNatsClient(logger Logger) (NatsClient, error) { client := &LoopbackNatsClient{ + logger: logger, + subscriptions: make(map[string]map[*loopbackNatsSubscription]bool), } client.wakeup.L = &client.mu @@ -82,7 +85,7 @@ func (c *LoopbackNatsClient) processMessage(msg *nats.Msg) { select { case ch <- msg: default: - log.Printf("Slow consumer %s, dropping message", msg.Subject) + c.logger.Warnf("Slow consumer %s, dropping message", msg.Subject) } } } diff --git a/natsclient_loopback_test.go b/natsclient_loopback_test.go index 3cb35b1..a8e79d3 100644 --- a/natsclient_loopback_test.go +++ b/natsclient_loopback_test.go @@ -49,7 +49,8 @@ func (c *LoopbackNatsClient) waitForSubscriptionsEmpty(ctx context.Context, t *t } func CreateLoopbackNatsClientForTest(t *testing.T) NatsClient { - result, err := NewLoopbackNatsClient() + logger := NewLoggerForTest(t) + result, err := NewLoopbackNatsClient(logger) if err != nil { t.Fatal(err) } diff --git a/natsclient_test.go b/natsclient_test.go index 62defca..4b0638d 100644 --- a/natsclient_test.go +++ b/natsclient_test.go @@ -45,7 +45,8 @@ func startLocalNatsServer(t *testing.T) string { func CreateLocalNatsClientForTest(t *testing.T) NatsClient { url := startLocalNatsServer(t) - result, err := NewNatsClient(url) + logger := NewLoggerForTest(t) + result, err := NewNatsClient(logger, url) if err != nil { t.Fatal(err) } diff --git a/proxy/logger_test.go b/proxy/logger_test.go new file mode 100644 index 0000000..b6178b8 --- /dev/null +++ b/proxy/logger_test.go @@ -0,0 +1,48 @@ +/** + * Standalone signaling server for the Nextcloud Spreed app. + * Copyright (C) 2022 struktur AG + * + * @author Joachim Bauch + * + * @license GNU AGPL version 3 or any later version + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + */ +package main + +import ( + "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + + signaling "github.com/strukturag/nextcloud-spreed-signaling" +) + +func NewLoggerForTest(t *testing.T) signaling.Logger { + cfg := zap.NewDevelopmentConfig() + cfg.EncoderConfig.TimeKey = "timestamp" + cfg.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + logger, err := cfg.Build() + if err != nil { + t.Fatalf("could not create logger: %s", err) + } + + t.Cleanup(func() { + logger.Sync() // nolint + }) + + sugar := logger.Sugar() + return signaling.WrapSugaredLogger(sugar) +} diff --git a/proxy/main.go b/proxy/main.go index c8008b0..bb5ed62 100644 --- a/proxy/main.go +++ b/proxy/main.go @@ -36,6 +36,7 @@ import ( "github.com/dlintw/goconf" "github.com/gorilla/mux" + signaling "github.com/strukturag/nextcloud-spreed-signaling" ) var ( @@ -54,7 +55,7 @@ const ( ) func main() { - log.SetFlags(log.Lshortfile) + log.SetFlags(log.Lshortfile | log.Ldate | log.Ltime | log.Lmicroseconds) flag.Parse() if *showVersion { @@ -67,26 +68,32 @@ func main() { signal.Notify(sigChan, syscall.SIGHUP) signal.Notify(sigChan, syscall.SIGUSR1) - log.Printf("Starting up version %s/%s as pid %d", version, runtime.Version(), os.Getpid()) + logger, err := signaling.NewLogger() + if err != nil { + log.Fatalf("Could not create logger: %s", err) + } + defer logger.Sync() // nolint + + logger.Infof("Starting up version %s/%s as pid %d", version, runtime.Version(), os.Getpid()) config, err := goconf.ReadConfigFile(*configFlag) if err != nil { - log.Fatal("Could not read configuration: ", err) + logger.Fatalf("Could not read configuration: %s", err) } cpus := runtime.NumCPU() runtime.GOMAXPROCS(cpus) - log.Printf("Using a maximum of %d CPUs", cpus) + logger.Infof("Using a maximum of %d CPUs", cpus) r := mux.NewRouter() - proxy, err := NewProxyServer(r, version, config) + proxy, err := NewProxyServer(logger, r, version, config) if err != nil { - log.Fatal(err) + logger.Fatal(err) } if err := proxy.Start(config); err != nil { - log.Fatal(err) + logger.Fatal(err) } defer proxy.Stop() @@ -102,10 +109,10 @@ func main() { for _, address := range strings.Split(addr, " ") { go func(address string) { - log.Println("Listening on", address) + logger.Infof("Listening on %s", address) listener, err := net.Listen("tcp", address) if err != nil { - log.Fatal("Could not start listening: ", err) + logger.Fatalf("Could not start listening: %s", err) } srv := &http.Server{ Handler: r, @@ -115,7 +122,7 @@ func main() { WriteTimeout: time.Duration(writeTimeout) * time.Second, } if err := srv.Serve(listener); err != nil { - log.Fatal("Could not start server: ", err) + logger.Fatalf("Could not start server: %s", err) } }(address) } @@ -127,21 +134,21 @@ loop: case sig := <-sigChan: switch sig { case os.Interrupt: - log.Println("Interrupted") + logger.Info("Interrupted") break loop case syscall.SIGHUP: - log.Printf("Received SIGHUP, reloading %s", *configFlag) + logger.Infof("Received SIGHUP, reloading %s", *configFlag) if config, err := goconf.ReadConfigFile(*configFlag); err != nil { - log.Printf("Could not read configuration from %s: %s", *configFlag, err) + logger.Errorf("Could not read configuration from %s: %s", *configFlag, err) } else { proxy.Reload(config) } case syscall.SIGUSR1: - log.Printf("Received SIGUSR1, scheduling server to shutdown") + logger.Infof("Received SIGUSR1, scheduling server to shutdown") proxy.ScheduleShutdown() } case <-proxy.ShutdownChannel(): - log.Printf("All clients disconnected, shutting down") + logger.Infof("All clients disconnected, shutting down") break loop } } diff --git a/proxy/proxy_client.go b/proxy/proxy_client.go index 10ccf7d..ac924a8 100644 --- a/proxy/proxy_client.go +++ b/proxy/proxy_client.go @@ -26,21 +26,22 @@ import ( "unsafe" "github.com/gorilla/websocket" - - "github.com/strukturag/nextcloud-spreed-signaling" + signaling "github.com/strukturag/nextcloud-spreed-signaling" ) type ProxyClient struct { signaling.Client - proxy *ProxyServer + logger signaling.Logger + proxy *ProxyServer session unsafe.Pointer } -func NewProxyClient(proxy *ProxyServer, conn *websocket.Conn, addr string) (*ProxyClient, error) { +func NewProxyClient(logger signaling.Logger, proxy *ProxyServer, conn *websocket.Conn, addr string) (*ProxyClient, error) { client := &ProxyClient{ - proxy: proxy, + logger: logger, + proxy: proxy, } client.SetConn(conn, addr) return client, nil diff --git a/proxy/proxy_server.go b/proxy/proxy_server.go index 6868779..eed76b1 100644 --- a/proxy/proxy_server.go +++ b/proxy/proxy_server.go @@ -26,7 +26,6 @@ import ( "crypto/rand" "encoding/json" "fmt" - "log" "net" "net/http" "net/http/pprof" @@ -85,6 +84,8 @@ type ProxyServer struct { // 64-bit members that are accessed atomically must be 64-bit aligned. load int64 + logger signaling.Logger + version string country string @@ -110,7 +111,7 @@ type ProxyServer struct { clientsLock sync.RWMutex } -func NewProxyServer(r *mux.Router, version string, config *goconf.ConfigFile) (*ProxyServer, error) { +func NewProxyServer(logger signaling.Logger, r *mux.Router, version string, config *goconf.ConfigFile) (*ProxyServer, error) { hashKey := make([]byte, 64) if _, err := rand.Read(hashKey); err != nil { return nil, fmt.Errorf("Could not generate random hash key: %s", err) @@ -130,9 +131,9 @@ func NewProxyServer(r *mux.Router, version string, config *goconf.ConfigFile) (* switch tokenType { case TokenTypeEtcd: - tokens, err = NewProxyTokensEtcd(config) + tokens, err = NewProxyTokensEtcd(logger, config) case TokenTypeStatic: - tokens, err = NewProxyTokensStatic(config) + tokens, err = NewProxyTokensStatic(logger, config) default: return nil, fmt.Errorf("Unsupported token type configured: %s", tokenType) } @@ -143,12 +144,12 @@ func NewProxyServer(r *mux.Router, version string, config *goconf.ConfigFile) (* statsAllowed, _ := config.GetString("stats", "allowed_ips") var statsAllowedIps map[string]bool if statsAllowed == "" { - log.Printf("No IPs configured for the stats endpoint, only allowing access from 127.0.0.1") + logger.Infof("No IPs configured for the stats endpoint, only allowing access from 127.0.0.1") statsAllowedIps = map[string]bool{ "127.0.0.1": true, } } else { - log.Printf("Only allowing access to the stats endpoing from %s", statsAllowed) + logger.Infof("Only allowing access to the stats endpoing from %s", statsAllowed) statsAllowedIps = make(map[string]bool) for _, ip := range strings.Split(statsAllowed, ",") { ip = strings.TrimSpace(ip) @@ -161,16 +162,17 @@ func NewProxyServer(r *mux.Router, version string, config *goconf.ConfigFile) (* country, _ := config.GetString("app", "country") country = strings.ToUpper(country) if signaling.IsValidCountry(country) { - log.Printf("Sending %s as country information", country) + logger.Infof("Sending %s as country information", country) } else if country != "" { return nil, fmt.Errorf("Invalid country: %s", country) } else { - log.Printf("Not sending country information") + logger.Infof("Not sending country information") } result := &ProxyServer{ version: version, country: country, + logger: logger, shutdownChannel: make(chan bool, 1), @@ -192,7 +194,7 @@ func NewProxyServer(r *mux.Router, version string, config *goconf.ConfigFile) (* result.upgrader.CheckOrigin = result.checkOrigin if debug, _ := config.GetBool("app", "debug"); debug { - log.Println("Installing debug handlers in \"/debug/pprof\"") + logger.Infof("Installing debug handlers in \"/debug/pprof\"") r.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index)) r.Handle("/debug/pprof/cmdline", http.HandlerFunc(pprof.Cmdline)) r.Handle("/debug/pprof/profile", http.HandlerFunc(pprof.Profile)) @@ -237,7 +239,7 @@ func (s *ProxyServer) Start(config *goconf.ConfigFile) error { for { switch mcuType { case signaling.McuTypeJanus: - mcu, err = signaling.NewMcuJanus(s.url, config) + mcu, err = signaling.NewMcuJanus(s.logger, s.url, config) if err == nil { signaling.RegisterJanusMcuStats() } @@ -249,14 +251,14 @@ func (s *ProxyServer) Start(config *goconf.ConfigFile) error { mcu.SetOnDisconnected(s.onMcuDisconnected) err = mcu.Start() if err != nil { - log.Printf("Could not create %s MCU at %s: %s", mcuType, s.url, err) + s.logger.Warnf("Could not create %s MCU at %s: %s", mcuType, s.url, err) } } if err == nil { break } - log.Printf("Could not initialize %s MCU at %s (%s) will retry in %s", mcuType, s.url, err, mcuRetry) + s.logger.Warnf("Could not initialize %s MCU at %s (%s) will retry in %s", mcuType, s.url, err, mcuRetry) mcuRetryTimer.Reset(mcuRetry) select { case <-interrupt: @@ -348,7 +350,7 @@ func (s *ProxyServer) expireSessions() { continue } - log.Printf("Delete expired session %s", session.PublicId()) + s.logger.Infof("Delete expired session %s", session.PublicId()) s.deleteSessionLocked(session.Sid()) } } @@ -423,13 +425,13 @@ func (s *ProxyServer) proxyHandler(w http.ResponseWriter, r *http.Request) { addr := getRealUserIP(r) conn, err := s.upgrader.Upgrade(w, r, nil) if err != nil { - log.Printf("Could not upgrade request from %s: %s", addr, err) + s.logger.Debugf("Could not upgrade request from %s: %s", addr, err) return } - client, err := NewProxyClient(s, conn, addr) + client, err := NewProxyClient(s.logger, s, conn, addr) if err != nil { - log.Printf("Could not create client for %s: %s", addr, err) + s.logger.Errorf("Could not create client for %s: %s", addr, err) return } @@ -453,11 +455,11 @@ func (s *ProxyServer) proxyHandler(w http.ResponseWriter, r *http.Request) { } func (s *ProxyServer) clientClosed(client *signaling.Client) { - log.Printf("Connection from %s closed", client.RemoteAddr()) + s.logger.Infof("Connection from %s closed", client.RemoteAddr()) } func (s *ProxyServer) onMcuConnected() { - log.Printf("Connection to %s established", s.url) + s.logger.Infof("Connection to %s established", s.url) msg := &signaling.ProxyServerMessage{ Type: "event", Event: &signaling.EventProxyServerMessage{ @@ -476,7 +478,7 @@ func (s *ProxyServer) onMcuDisconnected() { return } - log.Printf("Connection to %s lost", s.url) + s.logger.Warnf("Connection to %s lost", s.url) msg := &signaling.ProxyServerMessage{ Type: "event", Event: &signaling.EventProxyServerMessage{ @@ -513,14 +515,14 @@ func (s *ProxyServer) sendShutdownScheduled(session *ProxySession) { func (s *ProxyServer) processMessage(client *ProxyClient, data []byte) { if proxyDebugMessages { - log.Printf("Message: %s", string(data)) + s.logger.Debugf("Message: %s", string(data)) } var message signaling.ProxyClientMessage if err := message.UnmarshalJSON(data); err != nil { if session := client.GetSession(); session != nil { - log.Printf("Error decoding message from client %s: %v", session.PublicId(), err) + s.logger.Warnf("Error decoding message from client %s: %v", session.PublicId(), err) } else { - log.Printf("Error decoding message from %s: %v", client.RemoteAddr(), err) + s.logger.Warnf("Error decoding message from %s: %v", client.RemoteAddr(), err) } client.SendError(signaling.InvalidFormat) return @@ -528,9 +530,9 @@ func (s *ProxyServer) processMessage(client *ProxyClient, data []byte) { if err := message.CheckValid(); err != nil { if session := client.GetSession(); session != nil { - log.Printf("Invalid message %+v from client %s: %v", message, session.PublicId(), err) + s.logger.Warnf("Invalid message %+v from client %s: %v", message, session.PublicId(), err) } else { - log.Printf("Invalid message %+v from %s: %v", message, client.RemoteAddr(), err) + s.logger.Warnf("Invalid message %+v from %s: %v", message, client.RemoteAddr(), err) } client.SendMessage(message.NewErrorServerMessage(signaling.InvalidFormat)) return @@ -555,7 +557,7 @@ func (s *ProxyServer) processMessage(client *ProxyClient, data []byte) { return } - log.Printf("Resumed session %s", session.PublicId()) + s.logger.Infof("Resumed session %s", session.PublicId()) session.MarkUsed() if atomic.LoadUint32(&s.shutdownScheduled) != 0 { s.sendShutdownScheduled(session) @@ -640,16 +642,16 @@ func (s *ProxyServer) processCommand(ctx context.Context, client *ProxyClient, s id := uuid.New().String() publisher, err := s.mcu.NewPublisher(ctx, session, id, cmd.StreamType, cmd.Bitrate, cmd.MediaTypes, &emptyInitiator{}) if err == context.DeadlineExceeded { - log.Printf("Timeout while creating %s publisher %s for %s", cmd.StreamType, id, session.PublicId()) + s.logger.Errorf("Timeout while creating %s publisher %s for %s", cmd.StreamType, id, session.PublicId()) session.sendMessage(message.NewErrorServerMessage(TimeoutCreatingPublisher)) return } else if err != nil { - log.Printf("Error while creating %s publisher %s for %s: %s", cmd.StreamType, id, session.PublicId(), err) + s.logger.Errorf("Error while creating %s publisher %s for %s: %s", cmd.StreamType, id, session.PublicId(), err) session.sendMessage(message.NewWrappedErrorServerMessage(err)) return } - log.Printf("Created %s publisher %s as %s for %s", cmd.StreamType, publisher.Id(), id, session.PublicId()) + s.logger.Infof("Created %s publisher %s as %s for %s", cmd.StreamType, publisher.Id(), id, session.PublicId()) session.StorePublisher(ctx, id, publisher) s.StoreClient(id, publisher) @@ -668,16 +670,16 @@ func (s *ProxyServer) processCommand(ctx context.Context, client *ProxyClient, s publisherId := cmd.PublisherId subscriber, err := s.mcu.NewSubscriber(ctx, session, publisherId, cmd.StreamType) if err == context.DeadlineExceeded { - log.Printf("Timeout while creating %s subscriber on %s for %s", cmd.StreamType, publisherId, session.PublicId()) + s.logger.Errorf("Timeout while creating %s subscriber on %s for %s", cmd.StreamType, publisherId, session.PublicId()) session.sendMessage(message.NewErrorServerMessage(TimeoutCreatingSubscriber)) return } else if err != nil { - log.Printf("Error while creating %s subscriber on %s for %s: %s", cmd.StreamType, publisherId, session.PublicId(), err) + s.logger.Errorf("Error while creating %s subscriber on %s for %s: %s", cmd.StreamType, publisherId, session.PublicId(), err) session.sendMessage(message.NewWrappedErrorServerMessage(err)) return } - log.Printf("Created %s subscriber %s as %s for %s", cmd.StreamType, subscriber.Id(), id, session.PublicId()) + s.logger.Infof("Created %s subscriber %s as %s for %s", cmd.StreamType, subscriber.Id(), id, session.PublicId()) session.StoreSubscriber(ctx, id, subscriber) s.StoreClient(id, subscriber) @@ -714,7 +716,7 @@ func (s *ProxyServer) processCommand(ctx context.Context, client *ProxyClient, s } go func() { - log.Printf("Closing %s publisher %s as %s", client.StreamType(), client.Id(), cmd.ClientId) + s.logger.Info("Closing %s publisher %s as %s", client.StreamType(), client.Id(), cmd.ClientId) client.Close(context.Background()) }() @@ -749,7 +751,7 @@ func (s *ProxyServer) processCommand(ctx context.Context, client *ProxyClient, s } go func() { - log.Printf("Closing %s subscriber %s as %s", client.StreamType(), client.Id(), cmd.ClientId) + s.logger.Infof("Closing %s subscriber %s as %s", client.StreamType(), client.Id(), cmd.ClientId) client.Close(context.Background()) }() @@ -762,7 +764,7 @@ func (s *ProxyServer) processCommand(ctx context.Context, client *ProxyClient, s } session.sendMessage(response) default: - log.Printf("Unsupported command %+v", message.Command) + s.logger.Infof("Unsupported command %+v", message.Command) session.sendMessage(message.NewErrorServerMessage(UnsupportedCommand)) } } @@ -815,7 +817,7 @@ func (s *ProxyServer) processPayload(ctx context.Context, client *ProxyClient, s mcuClient.SendMessage(ctx, nil, mcuData, func(err error, response map[string]interface{}) { var responseMsg *signaling.ProxyServerMessage if err != nil { - log.Printf("Error sending %+v to %s client %s: %s", mcuData, mcuClient.StreamType(), payload.ClientId, err) + s.logger.Errorf("Error sending %+v to %s client %s: %s", mcuData, mcuClient.StreamType(), payload.ClientId, err) responseMsg = message.NewWrappedErrorServerMessage(err) } else { responseMsg = &signaling.ProxyServerMessage{ @@ -835,34 +837,34 @@ func (s *ProxyServer) processPayload(ctx context.Context, client *ProxyClient, s func (s *ProxyServer) NewSession(hello *signaling.HelloProxyClientMessage) (*ProxySession, error) { if proxyDebugMessages { - log.Printf("Hello: %+v", hello) + s.logger.Debugf("Hello: %+v", hello) } reason := "auth-failed" token, err := jwt.ParseWithClaims(hello.Token, &signaling.TokenClaims{}, func(token *jwt.Token) (interface{}, error) { // Don't forget to validate the alg is what you expect: if _, ok := token.Method.(*jwt.SigningMethodRSA); !ok { - log.Printf("Unexpected signing method: %v", token.Header["alg"]) + s.logger.Errorf("Unexpected signing method: %v", token.Header["alg"]) reason = "unsupported-signing-method" return nil, fmt.Errorf("Unexpected signing method: %v", token.Header["alg"]) } claims, ok := token.Claims.(*signaling.TokenClaims) if !ok { - log.Printf("Unsupported claims type: %+v", token.Claims) + s.logger.Errorf("Unsupported claims type: %+v", token.Claims) reason = "unsupported-claims" return nil, fmt.Errorf("Unsupported claims type") } tokenKey, err := s.tokens.Get(claims.Issuer) if err != nil { - log.Printf("Could not get token for %s: %s", claims.Issuer, err) + s.logger.Errorf("Could not get token for %s: %s", claims.Issuer, err) reason = "missing-issuer" return nil, err } if tokenKey == nil || tokenKey.key == nil { - log.Printf("Issuer %s is not supported", claims.Issuer) + s.logger.Errorf("Issuer %s is not supported", claims.Issuer) reason = "unsupported-issuer" return nil, fmt.Errorf("No key found for issuer") } @@ -907,8 +909,8 @@ func (s *ProxyServer) NewSession(hello *signaling.HelloProxyClientMessage) (*Pro return nil, err } - log.Printf("Created session %s for %+v", encoded, claims) - session := NewProxySession(s, sid, encoded) + s.logger.Infof("Created session %s for %+v", encoded, claims) + session := NewProxySession(s.logger, s, sid, encoded) s.StoreSession(sid, session) statsSessionsCurrent.Inc() statsSessionsTotal.Inc() @@ -1029,7 +1031,7 @@ func (s *ProxyServer) statsHandler(w http.ResponseWriter, r *http.Request) { stats := s.getStats() statsData, err := json.MarshalIndent(stats, "", " ") if err != nil { - log.Printf("Could not serialize stats %+v: %s", stats, err) + s.logger.Errorf("Could not serialize stats %+v: %s", stats, err) http.Error(w, "Internal server error", http.StatusInternalServerError) return } diff --git a/proxy/proxy_server_test.go b/proxy/proxy_server_test.go index 70a128f..55a708c 100644 --- a/proxy/proxy_server_test.go +++ b/proxy/proxy_server_test.go @@ -86,7 +86,8 @@ func newProxyServerForTest(t *testing.T) (*ProxyServer, *rsa.PrivateKey) { config := goconf.NewConfigFile() config.AddOption("tokens", TokenIdForTest, pubkey.Name()) - if server, err = NewProxyServer(r, "0.0", config); err != nil { + logger := NewLoggerForTest(t) + if server, err = NewProxyServer(logger, r, "0.0", config); err != nil { t.Fatalf("could not create server: %s", err) } return server, key diff --git a/proxy/proxy_session.go b/proxy/proxy_session.go index 1e22352..724469a 100644 --- a/proxy/proxy_session.go +++ b/proxy/proxy_session.go @@ -23,7 +23,6 @@ package main import ( "context" - "log" "sync" "sync/atomic" "time" @@ -40,9 +39,10 @@ type ProxySession struct { // 64-bit members that are accessed atomically must be 64-bit aligned. lastUsed int64 - proxy *ProxyServer - id string - sid uint64 + logger signaling.Logger + proxy *ProxyServer + id string + sid uint64 clientLock sync.Mutex client *ProxyClient @@ -57,8 +57,9 @@ type ProxySession struct { subscriberIds map[signaling.McuSubscriber]string } -func NewProxySession(proxy *ProxyServer, sid uint64, id string) *ProxySession { +func NewProxySession(logger signaling.Logger, proxy *ProxyServer, sid uint64, id string) *ProxySession { return &ProxySession{ + logger: logger.With("sessionid", id), proxy: proxy, id: id, sid: sid, @@ -125,7 +126,7 @@ func (s *ProxySession) SetClient(client *ProxyClient) *ProxyClient { func (s *ProxySession) OnUpdateOffer(client signaling.McuClient, offer map[string]interface{}) { id := s.proxy.GetClientId(client) if id == "" { - log.Printf("Received offer %+v from unknown %s client %s (%+v)", offer, client.StreamType(), client.Id(), client) + s.logger.Warnf("Received offer %+v from unknown %s client %s (%+v)", offer, client.StreamType(), client.Id(), client) return } @@ -145,7 +146,7 @@ func (s *ProxySession) OnUpdateOffer(client signaling.McuClient, offer map[strin func (s *ProxySession) OnIceCandidate(client signaling.McuClient, candidate interface{}) { id := s.proxy.GetClientId(client) if id == "" { - log.Printf("Received candidate %+v from unknown %s client %s (%+v)", candidate, client.StreamType(), client.Id(), client) + s.logger.Warnf("Received candidate %+v from unknown %s client %s (%+v)", candidate, client.StreamType(), client.Id(), client) return } @@ -178,7 +179,7 @@ func (s *ProxySession) sendMessage(message *signaling.ProxyServerMessage) { func (s *ProxySession) OnIceCompleted(client signaling.McuClient) { id := s.proxy.GetClientId(client) if id == "" { - log.Printf("Received ice completed event from unknown %s client %s (%+v)", client.StreamType(), client.Id(), client) + s.logger.Warnf("Received ice completed event from unknown %s client %s (%+v)", client.StreamType(), client.Id(), client) return } diff --git a/proxy/proxy_tokens_etcd.go b/proxy/proxy_tokens_etcd.go index 74879aa..c9594a5 100644 --- a/proxy/proxy_tokens_etcd.go +++ b/proxy/proxy_tokens_etcd.go @@ -25,7 +25,6 @@ import ( "bytes" "context" "fmt" - "log" "strings" "sync/atomic" "time" @@ -50,14 +49,18 @@ type tokenCacheEntry struct { } type tokensEtcd struct { + logger signaling.Logger + client atomic.Value tokenFormats atomic.Value tokenCache *signaling.LruCache } -func NewProxyTokensEtcd(config *goconf.ConfigFile) (ProxyTokens, error) { +func NewProxyTokensEtcd(logger signaling.Logger, config *goconf.ConfigFile) (ProxyTokens, error) { result := &tokensEtcd{ + logger: logger, + tokenCache: signaling.NewLruCache(tokenCacheSize), } if err := result.load(config, false); err != nil { @@ -97,7 +100,7 @@ func (t *tokensEtcd) getByKey(id string, key string) (*ProxyToken, error) { if len(resp.Kvs) == 0 { return nil, nil } else if len(resp.Kvs) > 1 { - log.Printf("Received multiple keys for %s, using last", key) + t.logger.Warnf("Received multiple keys for %s, using last", key) } keyValue := resp.Kvs[len(resp.Kvs)-1].Value @@ -126,7 +129,7 @@ func (t *tokensEtcd) Get(id string) (*ProxyToken, error) { for _, k := range t.getKeys(id) { token, err := t.getByKey(id, k) if err != nil { - log.Printf("Could not get public key from %s for %s: %s", k, id, err) + t.logger.Errorf("Could not get public key from %s for %s: %s", k, id, err) continue } else if token == nil { continue @@ -164,7 +167,7 @@ func (t *tokensEtcd) load(config *goconf.ConfigFile, ignoreErrors bool) error { return fmt.Errorf("No token endpoints configured") } - log.Printf("No token endpoints configured, not changing client") + t.logger.Infof("No token endpoints configured, not changing client") } else { cfg := clientv3.Config{ Endpoints: endpoints, @@ -188,7 +191,7 @@ func (t *tokensEtcd) load(config *goconf.ConfigFile, ignoreErrors bool) error { return fmt.Errorf("Could not setup TLS configuration: %s", err) } - log.Printf("Could not setup TLS configuration, will be disabled (%s)", err) + t.logger.Errorf("Could not setup TLS configuration, will be disabled (%s)", err) } else { cfg.TLS = tlsConfig } @@ -200,14 +203,14 @@ func (t *tokensEtcd) load(config *goconf.ConfigFile, ignoreErrors bool) error { return err } - log.Printf("Could not create new client from token endpoints %+v: %s", endpoints, err) + t.logger.Errorf("Could not create new client from token endpoints %+v: %s", endpoints, err) } else { prev := t.getClient() if prev != nil { prev.Close() } t.client.Store(c) - log.Printf("Using token endpoints %+v", endpoints) + t.logger.Infof("Using token endpoints %+v", endpoints) } } @@ -226,13 +229,13 @@ func (t *tokensEtcd) load(config *goconf.ConfigFile, ignoreErrors bool) error { } t.tokenFormats.Store(tokenFormats) - log.Printf("Using %v as token formats", tokenFormats) + t.logger.Infof("Using %v as token formats", tokenFormats) return nil } func (t *tokensEtcd) Reload(config *goconf.ConfigFile) { if err := t.load(config, true); err != nil { - log.Printf("Error reloading etcd tokens: %s", err) + t.logger.Errorf("Error reloading etcd tokens: %s", err) } } diff --git a/proxy/proxy_tokens_static.go b/proxy/proxy_tokens_static.go index 8ee7fb8..0c3fe9b 100644 --- a/proxy/proxy_tokens_static.go +++ b/proxy/proxy_tokens_static.go @@ -23,21 +23,26 @@ package main import ( "fmt" - "log" "os" "sort" "sync/atomic" "github.com/dlintw/goconf" "github.com/golang-jwt/jwt" + + signaling "github.com/strukturag/nextcloud-spreed-signaling" ) type tokensStatic struct { + logger signaling.Logger + tokenKeys atomic.Value } -func NewProxyTokensStatic(config *goconf.ConfigFile) (ProxyTokens, error) { - result := &tokensStatic{} +func NewProxyTokensStatic(logger signaling.Logger, config *goconf.ConfigFile) (ProxyTokens, error) { + result := &tokensStatic{ + logger: logger, + } if err := result.load(config, false); err != nil { return nil, err } @@ -69,7 +74,7 @@ func (t *tokensStatic) load(config *goconf.ConfigFile, ignoreErrors bool) error return fmt.Errorf("No filename given for token %s", id) } - log.Printf("No filename given for token %s, ignoring", id) + t.logger.Warnf("No filename given for token %s, ignoring", id) continue } @@ -79,7 +84,7 @@ func (t *tokensStatic) load(config *goconf.ConfigFile, ignoreErrors bool) error return fmt.Errorf("Could not read public key from %s: %s", filename, err) } - log.Printf("Could not read public key from %s, ignoring: %s", filename, err) + t.logger.Errorf("Could not read public key from %s, ignoring: %s", filename, err) continue } key, err := jwt.ParseRSAPublicKeyFromPEM(keyData) @@ -88,7 +93,7 @@ func (t *tokensStatic) load(config *goconf.ConfigFile, ignoreErrors bool) error return fmt.Errorf("Could not parse public key from %s: %s", filename, err) } - log.Printf("Could not parse public key from %s, ignoring: %s", filename, err) + t.logger.Errorf("Could not parse public key from %s, ignoring: %s", filename, err) continue } @@ -99,14 +104,14 @@ func (t *tokensStatic) load(config *goconf.ConfigFile, ignoreErrors bool) error } if len(tokenKeys) == 0 { - log.Printf("No token keys loaded") + t.logger.Warnf("No token keys loaded") } else { var keyIds []string for k := range tokenKeys { keyIds = append(keyIds, k) } sort.Strings(keyIds) - log.Printf("Enabled token keys: %v", keyIds) + t.logger.Infof("Enabled token keys: %v", keyIds) } t.setTokenKeys(tokenKeys) return nil @@ -114,7 +119,7 @@ func (t *tokensStatic) load(config *goconf.ConfigFile, ignoreErrors bool) error func (t *tokensStatic) Reload(config *goconf.ConfigFile) { if err := t.load(config, true); err != nil { - log.Printf("Error reloading static tokens: %s", err) + t.logger.Errorf("Error reloading static tokens: %s", err) } } diff --git a/room.go b/room.go index db00b14..42786bc 100644 --- a/room.go +++ b/room.go @@ -26,7 +26,6 @@ import ( "context" "encoding/json" "fmt" - "log" "net/url" "strconv" "sync" @@ -54,6 +53,7 @@ func init() { } type Room struct { + logger Logger id string hub *Hub nats NatsClient @@ -108,7 +108,7 @@ func getRoomIdForBackend(id string, backend *Backend) string { return backend.Id() + "|" + id } -func NewRoom(roomId string, properties *json.RawMessage, hub *Hub, n NatsClient, backend *Backend) (*Room, error) { +func NewRoom(logger Logger, roomId string, properties *json.RawMessage, hub *Hub, n NatsClient, backend *Backend) (*Room, error) { natsReceiver := make(chan *nats.Msg, 64) backendSubscription, err := n.Subscribe(GetSubjectForBackendRoomId(roomId, backend), natsReceiver) if err != nil { @@ -117,6 +117,7 @@ func NewRoom(roomId string, properties *json.RawMessage, hub *Hub, n NatsClient, } room := &Room{ + logger: logger, id: roomId, hub: hub, nats: n, @@ -217,7 +218,7 @@ func (r *Room) unsubscribeBackend() { go func(subscription NatsSubscription) { if err := subscription.Unsubscribe(); err != nil { - log.Printf("Error closing backend subscription for room %s: %s", r.Id(), err) + r.logger.Errorf("Error closing backend subscription for room %s: %s", r.Id(), err) } }(r.backendSubscription) r.backendSubscription = nil @@ -243,7 +244,7 @@ func (r *Room) Close() []Session { func (r *Room) processNatsMessage(message *nats.Msg) { var msg NatsMessage if err := r.nats.Decode(message, &msg); err != nil { - log.Printf("Could not decode nats message %+v, %s", message, err) + r.logger.Errorf("Could not decode nats message %+v, %s", message, err) return } @@ -251,7 +252,7 @@ func (r *Room) processNatsMessage(message *nats.Msg) { case "room": r.processBackendRoomRequest(msg.Room) default: - log.Printf("Unsupported NATS room request with type %s: %+v", msg.Type, msg) + r.logger.Errorf("Unsupported NATS room request with type %s: %+v", msg.Type, msg) } } @@ -259,9 +260,9 @@ func (r *Room) processBackendRoomRequest(message *BackendServerRoomRequest) { received := message.ReceivedTime if last, found := r.lastNatsRoomRequests[message.Type]; found && last > received { if msg, err := json.Marshal(message); err == nil { - log.Printf("Ignore old NATS backend room request for %s: %s", r.Id(), string(msg)) + r.logger.Errorf("Ignore old NATS backend room request for %s: %s", r.Id(), string(msg)) } else { - log.Printf("Ignore old NATS backend room request for %s: %+v", r.Id(), message) + r.logger.Errorf("Ignore old NATS backend room request for %s: %+v", r.Id(), message) } return } @@ -281,7 +282,7 @@ func (r *Room) processBackendRoomRequest(message *BackendServerRoomRequest) { case "message": r.publishRoomMessage(message.Message) default: - log.Printf("Unsupported NATS backend room request with type %s in %s: %+v", message.Type, r.Id(), message) + r.logger.Errorf("Unsupported NATS backend room request with type %s in %s: %+v", message.Type, r.Id(), message) } } @@ -290,7 +291,7 @@ func (r *Room) AddSession(session Session, sessionData *json.RawMessage) []Sessi if sessionData != nil && len(*sessionData) > 0 { roomSessionData = &RoomSessionData{} if err := json.Unmarshal(*sessionData, roomSessionData); err != nil { - log.Printf("Error decoding room session data \"%s\": %s", string(*sessionData), err) + r.logger.Errorf("Error decoding room session data \"%s\": %s", string(*sessionData), err) roomSessionData = nil } } @@ -325,7 +326,7 @@ func (r *Room) AddSession(session Session, sessionData *json.RawMessage) []Sessi } if roomSessionData != nil { r.roomSessionData[sid] = roomSessionData - log.Printf("Session %s sent room session data %+v", session.PublicId(), roomSessionData) + r.logger.Infof("Session %s sent room session data %+v", session.PublicId(), roomSessionData) } r.mu.Unlock() if !found { @@ -415,7 +416,7 @@ func (r *Room) UpdateProperties(properties *json.RawMessage) { }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish update properties message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish update properties message in room %s: %s", r.Id(), err) } } @@ -454,7 +455,7 @@ func (r *Room) PublishSessionJoined(session Session, sessionData *RoomSessionDat message.Event.Join[0].RoomSessionId = session.RoomSessionId() } if err := r.publish(message); err != nil { - log.Printf("Could not publish session joined message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish session joined message in room %s: %s", r.Id(), err) } if session.ClientType() == HelloClientTypeInternal { @@ -479,7 +480,7 @@ func (r *Room) PublishSessionLeft(session Session) { }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish session left message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish session left message in room %s: %s", r.Id(), err) } if session.ClientType() == HelloClientTypeInternal { @@ -583,7 +584,7 @@ func (r *Room) PublishUsersInCallChanged(changed []map[string]interface{}, users r.mu.Lock() if !r.inCallSessions[session] { r.inCallSessions[session] = true - log.Printf("Session %s joined call %s", session.PublicId(), r.id) + r.logger.Infof("Session %s joined call %s", session.PublicId(), r.id) } r.mu.Unlock() } else { @@ -612,7 +613,7 @@ func (r *Room) PublishUsersInCallChanged(changed []map[string]interface{}, users }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish incall message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish incall message in room %s: %s", r.Id(), err) } } @@ -642,7 +643,7 @@ func (r *Room) PublishUsersInCallChangedAll(inCall int) { return } - log.Printf("Sessions %v joined call %s", joined, r.id) + r.logger.Infof("Sessions %v joined call %s", joined, r.id) } else if len(r.inCallSessions) > 0 { // Perform actual leaving asynchronously. ch := make(chan *ClientSession, 1) @@ -684,7 +685,7 @@ func (r *Room) PublishUsersInCallChangedAll(inCall int) { }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish incall message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish incall message in room %s: %s", r.Id(), err) } } @@ -705,7 +706,7 @@ func (r *Room) PublishUsersChanged(changed []map[string]interface{}, users []map }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish users changed message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish users changed message in room %s: %s", r.Id(), err) } } @@ -752,7 +753,7 @@ func (r *Room) NotifySessionChanged(session Session) { func (r *Room) publishUsersChangedWithInternal() { message := r.getParticipantsUpdateMessage(r.users) if err := r.publish(message); err != nil { - log.Printf("Could not publish users changed message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish users changed message in room %s: %s", r.Id(), err) } } @@ -770,7 +771,7 @@ func (r *Room) publishSessionFlagsChanged(session *VirtualSession) { }, } if err := r.publish(message); err != nil { - log.Printf("Could not publish flags changed message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish flags changed message in room %s: %s", r.Id(), err) } } @@ -832,7 +833,7 @@ func (r *Room) publishActiveSessions() (int, *sync.WaitGroup) { request := NewBackendClientPingRequest(r.id, entries) var response BackendClientResponse if err := r.hub.backend.PerformJSONRequest(ctx, url, request, &response); err != nil { - log.Printf("Error pinging room %s for active entries %+v: %s", r.id, entries, err) + r.logger.Errorf("Error pinging room %s for active entries %+v: %s", r.id, entries, err) } }(urls[u], e) } @@ -856,7 +857,7 @@ func (r *Room) publishRoomMessage(message *BackendRoomMessageRequest) { }, } if err := r.publish(msg); err != nil { - log.Printf("Could not publish room message in room %s: %s", r.Id(), err) + r.logger.Errorf("Could not publish room message in room %s: %s", r.Id(), err) } } diff --git a/room_test.go b/room_test.go index ab7caf4..e93e3a5 100644 --- a/room_test.go +++ b/room_test.go @@ -79,7 +79,8 @@ func TestRoom_Update(t *testing.T) { if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, hub, "no-version") + logger := NewLoggerForTest(t) + b, err := NewBackendServer(logger, config, hub, "no-version") if err != nil { t.Fatal(err) } @@ -216,7 +217,8 @@ func TestRoom_Delete(t *testing.T) { if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, hub, "no-version") + logger := NewLoggerForTest(t) + b, err := NewBackendServer(logger, config, hub, "no-version") if err != nil { t.Fatal(err) } @@ -358,7 +360,8 @@ func TestRoom_RoomSessionData(t *testing.T) { if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, hub, "no-version") + logger := NewLoggerForTest(t) + b, err := NewBackendServer(logger, config, hub, "no-version") if err != nil { t.Fatal(err) } @@ -427,7 +430,8 @@ func TestRoom_InCallAll(t *testing.T) { if err != nil { t.Fatal(err) } - b, err := NewBackendServer(config, hub, "no-version") + logger := NewLoggerForTest(t) + b, err := NewBackendServer(logger, config, hub, "no-version") if err != nil { t.Fatal(err) } diff --git a/server/main.go b/server/main.go index ea14bd6..0072c9c 100644 --- a/server/main.go +++ b/server/main.go @@ -90,7 +90,7 @@ func createTLSListener(addr string, certFile, keyFile string) (net.Listener, err } func main() { - log.SetFlags(log.Lshortfile) + log.SetFlags(log.Lshortfile | log.Ldate | log.Ltime | log.Lmicroseconds) flag.Parse() if *showVersion { @@ -98,6 +98,12 @@ func main() { os.Exit(0) } + logger, err := signaling.NewLogger() + if err != nil { + log.Fatalf("Could not create logger: %s", err) + } + defer logger.Sync() // nolint + sigChan := make(chan os.Signal, 1) signal.Notify(sigChan, os.Interrupt) signal.Notify(sigChan, syscall.SIGHUP) @@ -105,41 +111,41 @@ func main() { if *cpuprofile != "" { f, err := os.Create(*cpuprofile) if err != nil { - log.Fatal(err) + logger.Fatal(err) } if err := runtimepprof.StartCPUProfile(f); err != nil { - log.Fatalf("Error writing CPU profile to %s: %s", *cpuprofile, err) + logger.Fatalf("Error writing CPU profile to %s: %s", *cpuprofile, err) } - log.Printf("Writing CPU profile to %s ...", *cpuprofile) + logger.Infof("Writing CPU profile to %s ...", *cpuprofile) defer runtimepprof.StopCPUProfile() } if *memprofile != "" { f, err := os.Create(*memprofile) if err != nil { - log.Fatal(err) + logger.Fatal(err) } defer func() { - log.Printf("Writing Memory profile to %s ...", *memprofile) + logger.Info("Writing Memory profile to %s ...", *memprofile) runtime.GC() if err := runtimepprof.WriteHeapProfile(f); err != nil { - log.Printf("Error writing Memory profile to %s: %s", *memprofile, err) + logger.Infof("Error writing Memory profile to %s: %s", *memprofile, err) } }() } - log.Printf("Starting up version %s/%s as pid %d", version, runtime.Version(), os.Getpid()) + logger.Infof("Starting up version %s/%s as pid %d", version, runtime.Version(), os.Getpid()) config, err := goconf.ReadConfigFile(*configFlag) if err != nil { - log.Fatal("Could not read configuration: ", err) + logger.Fatalf("Could not read configuration: %s", err) } cpus := runtime.NumCPU() runtime.GOMAXPROCS(cpus) - log.Printf("Using a maximum of %d CPUs", cpus) + logger.Infof("Using a maximum of %d CPUs", cpus) signaling.RegisterStats() @@ -148,24 +154,24 @@ func main() { natsUrl = nats.DefaultURL } - nats, err := signaling.NewNatsClient(natsUrl) + nats, err := signaling.NewNatsClient(logger, natsUrl) if err != nil { - log.Fatal("Could not create NATS client: ", err) + logger.Fatalf("Could not create NATS client: %s", err) } r := mux.NewRouter() - hub, err := signaling.NewHub(config, nats, r, version) + hub, err := signaling.NewHub(logger, config, nats, r, version) if err != nil { - log.Fatal("Could not create hub: ", err) + logger.Fatalf("Could not create hub: %s", err) } mcuUrl, _ := config.GetString("mcu", "url") mcuType, _ := config.GetString("mcu", "type") if mcuType == "" && mcuUrl != "" { - log.Printf("WARNING: Old-style MCU configuration detected with url but no type, defaulting to type %s", signaling.McuTypeJanus) + logger.Warnf("Old-style MCU configuration detected with url but no type, defaulting to type %s", signaling.McuTypeJanus) mcuType = signaling.McuTypeJanus } else if mcuType == signaling.McuTypeJanus && mcuUrl == "" { - log.Printf("WARNING: Old-style MCU configuration detected with type but no url, disabling") + logger.Warn("Old-style MCU configuration detected with type but no url, disabling") mcuType = "" } @@ -177,45 +183,45 @@ func main() { for { switch mcuType { case signaling.McuTypeJanus: - mcu, err = signaling.NewMcuJanus(mcuUrl, config) + mcu, err = signaling.NewMcuJanus(logger, mcuUrl, config) signaling.UnregisterProxyMcuStats() signaling.RegisterJanusMcuStats() case signaling.McuTypeProxy: - mcu, err = signaling.NewMcuProxy(config) + mcu, err = signaling.NewMcuProxy(logger, config) signaling.UnregisterJanusMcuStats() signaling.RegisterProxyMcuStats() default: - log.Fatal("Unsupported MCU type: ", mcuType) + logger.Fatalf("Unsupported MCU type: %s", mcuType) } if err == nil { err = mcu.Start() if err != nil { - log.Printf("Could not create %s MCU: %s", mcuType, err) + logger.Errorf("Could not create %s MCU: %s", mcuType, err) } } if err == nil { break } - log.Printf("Could not initialize %s MCU (%s) will retry in %s", mcuType, err, mcuRetry) + logger.Errorf("Could not initialize %s MCU (%s) will retry in %s", mcuType, err, mcuRetry) mcuRetryTimer.Reset(mcuRetry) select { case sig := <-sigChan: switch sig { case os.Interrupt: - log.Fatalf("Cancelled") + logger.Fatal("Cancelled") case syscall.SIGHUP: - log.Printf("Received SIGHUP, reloading %s", *configFlag) + logger.Info("Received SIGHUP, reloading %s", *configFlag) if config, err = goconf.ReadConfigFile(*configFlag); err != nil { - log.Printf("Could not read configuration from %s: %s", *configFlag, err) + logger.Infof("Could not read configuration from %s: %s", *configFlag, err) } else { mcuUrl, _ = config.GetString("mcu", "url") mcuType, _ = config.GetString("mcu", "type") if mcuType == "" && mcuUrl != "" { - log.Printf("WARNING: Old-style MCU configuration detected with url but no type, defaulting to type %s", signaling.McuTypeJanus) + logger.Warnf("Old-style MCU configuration detected with url but no type, defaulting to type %s", signaling.McuTypeJanus) mcuType = signaling.McuTypeJanus } else if mcuType == signaling.McuTypeJanus && mcuUrl == "" { - log.Printf("WARNING: Old-style MCU configuration detected with type but no url, disabling") + logger.Warnf("Old-style MCU configuration detected with type but no url, disabling") mcuType = "" break mcuTypeLoop } @@ -232,7 +238,7 @@ func main() { if mcu != nil { defer mcu.Stop() - log.Printf("Using %s MCU", mcuType) + logger.Infof("Using %s MCU", mcuType) hub.SetMcu(mcu) } } @@ -240,16 +246,16 @@ func main() { go hub.Run() defer hub.Stop() - server, err := signaling.NewBackendServer(config, hub, version) + server, err := signaling.NewBackendServer(logger, config, hub, version) if err != nil { - log.Fatal("Could not create backend server: ", err) + logger.Fatalf("Could not create backend server: %s", err) } if err := server.Start(r); err != nil { - log.Fatal("Could not start backend server: ", err) + logger.Fatalf("Could not start backend server: %s", err) } if debug, _ := config.GetBool("app", "debug"); debug { - log.Println("Installing debug handlers in \"/debug/pprof\"") + logger.Info("Installing debug handlers in \"/debug/pprof\"") r.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index)) r.Handle("/debug/pprof/cmdline", http.HandlerFunc(pprof.Cmdline)) r.Handle("/debug/pprof/profile", http.HandlerFunc(pprof.Profile)) @@ -265,7 +271,7 @@ func main() { cert, _ := config.GetString("https", "certificate") key, _ := config.GetString("https", "key") if cert == "" || key == "" { - log.Fatal("Need a certificate and key for the HTTPS listener") + logger.Fatal("Need a certificate and key for the HTTPS listener") } readTimeout, _ := config.GetInt("https", "readtimeout") @@ -278,10 +284,10 @@ func main() { } for _, address := range strings.Split(saddr, " ") { go func(address string) { - log.Println("Listening on", address) + logger.Infof("Listening on %s", address) listener, err := createTLSListener(address, cert, key) if err != nil { - log.Fatal("Could not start listening: ", err) + logger.Fatalf("Could not start listening: %s", err) } srv := &http.Server{ Handler: r, @@ -290,7 +296,7 @@ func main() { WriteTimeout: time.Duration(writeTimeout) * time.Second, } if err := srv.Serve(listener); err != nil { - log.Fatal("Could not start server: ", err) + logger.Fatalf("Could not start server: %s", err) } }(address) } @@ -308,10 +314,10 @@ func main() { for _, address := range strings.Split(addr, " ") { go func(address string) { - log.Println("Listening on", address) + logger.Infof("Listening on %s", address) listener, err := createListener(address) if err != nil { - log.Fatal("Could not start listening: ", err) + logger.Fatalf("Could not start listening: %s", err) } srv := &http.Server{ Handler: r, @@ -321,7 +327,7 @@ func main() { WriteTimeout: time.Duration(writeTimeout) * time.Second, } if err := srv.Serve(listener); err != nil { - log.Fatal("Could not start server: ", err) + logger.Fatalf("Could not start server: %s", err) } }(address) } @@ -331,12 +337,12 @@ loop: for sig := range sigChan { switch sig { case os.Interrupt: - log.Println("Interrupted") + logger.Info("Interrupted") break loop case syscall.SIGHUP: - log.Printf("Received SIGHUP, reloading %s", *configFlag) + logger.Infof("Received SIGHUP, reloading %s", *configFlag) if config, err := goconf.ReadConfigFile(*configFlag); err != nil { - log.Printf("Could not read configuration from %s: %s", *configFlag, err) + logger.Errorf("Could not read configuration from %s: %s", *configFlag, err) } else { hub.Reload(config) } diff --git a/virtualsession.go b/virtualsession.go index 87943da..07640ac 100644 --- a/virtualsession.go +++ b/virtualsession.go @@ -24,7 +24,6 @@ package signaling import ( "context" "encoding/json" - "log" "net/url" "sync/atomic" "time" @@ -38,6 +37,7 @@ const ( ) type VirtualSession struct { + logger Logger hub *Hub session *ClientSession privateId string @@ -56,8 +56,9 @@ func GetVirtualSessionId(session *ClientSession, sessionId string) string { return session.PublicId() + "|" + sessionId } -func NewVirtualSession(session *ClientSession, privateId string, publicId string, data *SessionIdData, msg *AddSessionInternalClientMessage) *VirtualSession { +func NewVirtualSession(logger Logger, session *ClientSession, privateId string, publicId string, data *SessionIdData, msg *AddSessionInternalClientMessage) *VirtualSession { return &VirtualSession{ + logger: logger, hub: session.hub, session: session, privateId: privateId, @@ -159,7 +160,7 @@ func (s *VirtualSession) notifyBackendRemoved(room *Room, session *ClientSession var response BackendClientResponse if err := s.hub.backend.PerformJSONRequest(ctx, s.ParsedBackendUrl(), request, &response); err != nil { virtualSessionId := GetVirtualSessionId(s.session, s.PublicId()) - log.Printf("Could not leave virtual session %s at backend %s: %s", virtualSessionId, s.BackendUrl(), err) + s.logger.Errorf("Could not leave virtual session %s at backend %s: %s", virtualSessionId, s.BackendUrl(), err) if session != nil && message != nil { reply := message.NewErrorServerMessage(NewError("remove_failed", "Could not remove virtual session from backend.")) session.SendMessage(reply) @@ -169,7 +170,7 @@ func (s *VirtualSession) notifyBackendRemoved(room *Room, session *ClientSession if response.Type == "error" { virtualSessionId := GetVirtualSessionId(s.session, s.PublicId()) - log.Printf("Could not leave virtual session %s at backend %s: %+v", virtualSessionId, s.BackendUrl(), response.Error) + s.logger.Errorf("Could not leave virtual session %s at backend %s: %+v", virtualSessionId, s.BackendUrl(), response.Error) if session != nil && message != nil { reply := message.NewErrorServerMessage(NewError("remove_failed", response.Error.Error())) session.SendMessage(reply) @@ -181,7 +182,7 @@ func (s *VirtualSession) notifyBackendRemoved(room *Room, session *ClientSession var response BackendClientSessionResponse err := s.hub.backend.PerformJSONRequest(ctx, s.ParsedBackendUrl(), request, &response) if err != nil { - log.Printf("Could not remove virtual session %s from backend %s: %s", s.PublicId(), s.BackendUrl(), err) + s.logger.Errorf("Could not remove virtual session %s from backend %s: %s", s.PublicId(), s.BackendUrl(), err) if session != nil && message != nil { reply := message.NewErrorServerMessage(NewError("remove_failed", "Could not remove virtual session from backend.")) session.SendMessage(reply)