deblan-mirror/nextcloud-spreed-signaling
deblan-mirror/nextcloud-spreed-signaling
1
0
Fork 0
mirror of https://github.com/strukturag/nextcloud-spreed-signaling synced 2024-05-04 06:43:11 +02:00
Code Issues Releases Wiki Activity

Migrate to structured logging using "go.uber.org/zap".

Browse source 
First step: migrate standard logging calls to "zap" logger calls.
This commit is contained in:
Joachim Bauch 2022-04-06 14:32:33 +02:00
parent e5f2d4d3cf
commit cb2a05c270
No known key found for this signature in database
GPG key ID: 77C1D22D53E15F02
41 changed files with 933 additions and 657 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

10
.golangci.yml
View file

@ -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

3
Makefile
View file

@ -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)

57
backend_client.go
View file

@ -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

9
backend_client_test.go
View file

@ -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)
}

45
backend_configuration.go
View file

@ -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 {

45
backend_configuration_test.go
View file

@ -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)
}

51
backend_server.go
View file

@ -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
}

7
backend_server_test.go
View file

@ -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)
}

39
client.go
View file

@ -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
}

94
client/main.go
View file

@ -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()
}

51
clientsession.go
View file

@ -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)

4
clientsession_test.go
View file

@ -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 {

11
deferred_executor.go
View file

@ -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()))
}
}()

25
deferred_executor_test.go
View file

@ -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() {

16
geoip.go
View file

@ -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 {

12
geoip_test.go
View file

@ -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)
}

2
go.mod
View file

@ -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

159
hub.go
View file

@ -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
}

17
hub_test.go
View file

@ -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 {

27
janus_client.go
View file

@ -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
}

76
logger.go Normal file
View file

@ -0,0 +1,76 @@
/**
* Standalone signaling server for the Nextcloud Spreed app.
* Copyright (C) 2022 struktur AG
*
* @author Joachim Bauch <bauch@struktur.de>
*
* @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 <http://www.gnu.org/licenses/>.
*/
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,
}
}

46
logger_test.go Normal file
View file

@ -0,0 +1,46 @@
/**
* Standalone signaling server for the Nextcloud Spreed app.
* Copyright (C) 2022 struktur AG
*
* @author Joachim Bauch <bauch@struktur.de>
*
* @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 <http://www.gnu.org/licenses/>.
*/
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)
}

128
mcu_janus.go
View file

@ -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)

200
mcu_proxy.go
View file

@ -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()

9
mcu_test.go
View file

@ -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)
}

26
natsclient.go
View file

@ -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) {

9
natsclient_loopback.go
View file

@ -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)
}
}
}

3
natsclient_loopback_test.go
View file

@ -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)
}

3
natsclient_test.go
View file

@ -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)
}

48
proxy/logger_test.go Normal file
View file

@ -0,0 +1,48 @@
/**
* Standalone signaling server for the Nextcloud Spreed app.
* Copyright (C) 2022 struktur AG
*
* @author Joachim Bauch <bauch@struktur.de>
*
* @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 <http://www.gnu.org/licenses/>.
*/
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)
}

37
proxy/main.go
View file

@ -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
}
}

11
proxy/proxy_client.go
View file

@ -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

88
proxy/proxy_server.go
View file

@ -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
}

3
proxy/proxy_server_test.go
View file

@ -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

17
proxy/proxy_session.go
View file

@ -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
}

23
proxy/proxy_tokens_etcd.go
View file

@ -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)
}
}

23
proxy/proxy_tokens_static.go
View file

@ -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)
}
}

45
room.go
View file

@ -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)
}
}

12
room_test.go
View file

@ -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)
}

88
server/main.go
View file

@ -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)
}

11
virtualsession.go
View file

@ -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)