[MM-54589] Report job statuses, review connectivity check, structured…

… logging

* [MM-54589] Report job start failure (#46)

* [MM-54749] Make connectivity check more resilient to errors (#47)

* [MM-54747] Implement structured logging (#48)

.github/workflows/ci.yml

@@ -11,7 +11,7 @@ jobs:
 
     strategy:
       matrix:
-        go-version: [1.18.x]
+        go-version: [1.21.x]
 
     runs-on: ubuntu-latest
 

.github/workflows/golangci-lint.yml

@@ -7,7 +7,7 @@ jobs:
     name: lint
     strategy:
       matrix:
-        go-version: [1.18.x]
+        go-version: [1.21.x]
     runs-on: ubuntu-latest
     steps:
       - name: Install Go
@@ -19,7 +19,7 @@ jobs:
       - name: golangci-lint
         uses: golangci/golangci-lint-action@v2
         with:
-          version: v1.50.1
+          version: v1.54.2
 
           # Optional: if set to true then the action will use pre-installed Go.
           skip-go-installation: true

Makefile

@@ -49,8 +49,8 @@ DOCKER_REGISTRY_REPO    ?= mattermost/${APP_NAME}-daily
 DOCKER_USER             ?= user
 DOCKER_PASSWORD         ?= password
 ## Docker Images
-DOCKER_IMAGE_GO         += "golang:${GO_VERSION}@sha256:fa71e1447cb0241324162a6c51297206928d755b16142eceec7b809af55061e5"
-DOCKER_IMAGE_GOLINT     += "golangci/golangci-lint:v1.50.1@sha256:94388e00f07c64262b138a7508f857473e30fdf0f59d04b546a305fc12cb5961"
+DOCKER_IMAGE_GO         += "golang:${GO_VERSION}@sha256:b17c35044f4062d83c815434615997eed97697daae8745c6dd39dc3673b87efb"
+DOCKER_IMAGE_GOLINT     += "golangci/golangci-lint:v1.54.2@sha256:abe731fe6bb335a30eab303a41dd5c2b630bb174372a4da08e3d42eab5324127"
 DOCKER_IMAGE_DOCKERLINT += "hadolint/hadolint:v2.9.2@sha256:d355bd7df747a0f124f3b5e7b21e9dafd0cb19732a276f901f0fdee243ec1f3b"
 DOCKER_IMAGE_COSIGN     += "bitnami/cosign:1.8.0@sha256:8c2c61c546258fffff18b47bb82a65af6142007306b737129a7bd5429d53629a"
 DOCKER_IMAGE_GH_CLI     += "registry.internal.mattermost.com/images/build-ci:3.16.0@sha256:f6a229a9ababef3c483f237805ee4c3dbfb63f5de4fbbf58f4c4b6ed8fcd34b6"

build/Dockerfile

@@ -1,7 +1,7 @@
 # This dockerfile is used to build Mattermost calls-recorder
 # A multi stage build, with golang used as a builder
 # and ubuntu:22.04 as runner
-ARG GO_IMAGE=golang:1.18@sha256:fa71e1447cb0241324162a6c51297206928d755b16142eceec7b809af55061e5
+ARG GO_IMAGE=golang:1.21@sha256:b17c35044f4062d83c815434615997eed97697daae8745c6dd39dc3673b87efb
 ARG ARCH
 ARG RUNNER_IMAGE
 

build/pkgs_list

@@ -1,7 +1,7 @@
 ca-certificates=20230311
-chromium=117.0.5938.132-1
-chromium-driver=117.0.5938.132-1
-chromium-sandbox=117.0.5938.132-1
+chromium=117.0.5938.132-2
+chromium-driver=117.0.5938.132-2
+chromium-sandbox=117.0.5938.132-2
 ffmpeg=7:6.0-7
 fonts-recommended=1
 pulseaudio=16.1+dfsg1-2+b1

cmd/recorder/cmd.go

@@ -2,7 +2,7 @@ package main
 
 import (
 	"io"
-	"log"
+	"log/slog"
 	"os/exec"
 	"strings"
 )
@@ -12,7 +12,7 @@ const (
 )
 
 func runCmd(cmd string, args string) (*exec.Cmd, error) {
-	log.Printf("running %s: %q", cmd, args)
+	slog.Debug("running cmd", slog.String("cmd", cmd), slog.String("args", args))
 	c := exec.Command(cmd, strings.Split(args, " ")...)
 
 	stdout, err := c.StdoutPipe()
@@ -37,10 +37,17 @@ func runCmd(cmd string, args string) (*exec.Cmd, error) {
 				return
 			}
 			if err != nil {
-				log.Printf("%s (%s): error reading: %s", cmd, name, err)
+				slog.Debug("error reading log buffer",
+					slog.String("cmd", cmd),
+					slog.String("name", name),
+					slog.String("err", err.Error()),
+				)
 				return
 			}
-			log.Printf("%s (%s): %s", cmd, name, strings.TrimSuffix(string(buf[:n]), "\n"))
+			slog.Debug(strings.TrimSuffix(string(buf[:n]), "\n"),
+				slog.String("cmd", cmd),
+				slog.String("name", name),
+			)
 		}
 	}
 

cmd/recorder/job.go

@@ -0,0 +1,46 @@
+package main
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+	"net/http"
+
+	"github.com/mattermost/mattermost-plugin-calls/server/public"
+)
+
+func (rec *Recorder) postJobStatus(status public.JobStatus) error {
+	apiURL := fmt.Sprintf("%s/plugins/%s/bot/calls/%s/jobs/%s/status",
+		rec.client.URL, pluginID, rec.cfg.CallID, rec.cfg.RecordingID)
+
+	payload, err := json.Marshal(&status)
+	if err != nil {
+		return fmt.Errorf("failed to marshal: %w", err)
+	}
+
+	ctx, cancelCtx := context.WithTimeout(context.Background(), httpRequestTimeout)
+	defer cancelCtx()
+	resp, err := rec.client.DoAPIRequestBytes(ctx, http.MethodPost, apiURL, payload, "")
+	if err != nil {
+		return fmt.Errorf("request failed%w", err)
+	}
+	defer resp.Body.Close()
+	cancelCtx()
+
+	return nil
+}
+
+func (rec *Recorder) ReportJobFailure(errMsg string) error {
+	return rec.postJobStatus(public.JobStatus{
+		JobType: public.JobTypeRecording,
+		Status:  public.JobStatusTypeFailed,
+		Error:   errMsg,
+	})
+}
+
+func (rec *Recorder) ReportJobStarted() error {
+	return rec.postJobStatus(public.JobStatus{
+		JobType: public.JobTypeRecording,
+		Status:  public.JobStatusTypeStarted,
+	})
+}

cmd/recorder/job_test.go

@@ -0,0 +1,94 @@
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/mattermost/calls-recorder/cmd/recorder/config"
+	"github.com/mattermost/mattermost-plugin-calls/server/public"
+
+	"github.com/stretchr/testify/require"
+)
+
+func TestReportJobFailure(t *testing.T) {
+	middlewares := []middleware{}
+
+	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		for _, mw := range middlewares {
+			if mw(w, r) {
+				return
+			}
+		}
+		http.NotFound(w, r)
+	}))
+	defer ts.Close()
+
+	cfg := config.RecorderConfig{
+		SiteURL:     ts.URL,
+		CallID:      "8w8jorhr7j83uqr6y1st894hqe",
+		ThreadID:    "udzdsg7dwidbzcidx5khrf8nee",
+		RecordingID: "67t5u6cmtfbb7jug739d43xa9e",
+		AuthToken:   "qj75unbsef83ik9p7ueypb6iyw",
+	}
+	cfg.SetDefaults()
+	rec, err := NewRecorder(cfg)
+	require.NoError(t, err)
+	require.NotNil(t, rec)
+
+	t.Run("request failure", func(t *testing.T) {
+		middlewares = []middleware{
+			func(w http.ResponseWriter, r *http.Request) bool {
+				if r.URL.Path != "/plugins/com.mattermost.calls/bot/calls/8w8jorhr7j83uqr6y1st894hqe/jobs/67t5u6cmtfbb7jug739d43xa9e/status" {
+					w.WriteHeader(404)
+					return true
+				}
+
+				w.WriteHeader(400)
+				fmt.Fprintln(w, `{"message": "server error"}`)
+				return true
+			},
+		}
+		err := rec.ReportJobFailure("")
+		require.EqualError(t, err, "request failed: server error")
+	})
+
+	t.Run("success", func(t *testing.T) {
+		var errMsg string
+		middlewares = []middleware{
+			func(w http.ResponseWriter, r *http.Request) bool {
+				if r.URL.Path != "/plugins/com.mattermost.calls/bot/calls/8w8jorhr7j83uqr6y1st894hqe/jobs/67t5u6cmtfbb7jug739d43xa9e/status" {
+					w.WriteHeader(404)
+					return true
+				}
+
+				var status public.JobStatus
+				if err := json.NewDecoder(r.Body).Decode(&status); err != nil {
+					w.WriteHeader(400)
+					fmt.Fprintf(w, `{"message": %q}`, err.Error())
+					return true
+				}
+
+				if status.JobType != public.JobTypeRecording {
+					w.WriteHeader(400)
+					return true
+				}
+
+				if status.Status != public.JobStatusTypeFailed {
+					w.WriteHeader(400)
+					return true
+				}
+
+				errMsg = status.Error
+
+				w.WriteHeader(200)
+				return true
+			},
+		}
+		err := rec.ReportJobFailure("some error")
+		require.Nil(t, err)
+		require.Equal(t, "some error", errMsg)
+	})
+}

cmd/recorder/main.go

@@ -2,7 +2,7 @@ package main
 
 import (
 	"fmt"
-	"log"
+	"log/slog"
 	"os"
 	"os/signal"
 	"syscall"
@@ -11,41 +11,56 @@ import (
 )
 
 func main() {
-	log.SetFlags(log.LstdFlags | log.Lmicroseconds)
+	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		AddSource:   true,
+		Level:       slog.LevelDebug,
+		ReplaceAttr: slogReplaceAttr,
+	}))
+	slog.SetDefault(logger)
 
 	pid := os.Getpid()
 	if err := os.WriteFile("/tmp/recorder.pid", []byte(fmt.Sprintf("%d", pid)), 0666); err != nil {
-		log.Fatalf("failed to write pid file: %s", err)
+		slog.Error("failed to write pid file", slog.String("err", err.Error()))
+		os.Exit(1)
 	}
 
 	cfg, err := config.LoadFromEnv()
 	if err != nil {
-		log.Fatalf("failed to load config: %s", err)
+		slog.Error("failed to load config", slog.String("err", err.Error()))
+		os.Exit(1)
 	}
 	cfg.SetDefaults()
 
+	slog.SetDefault(logger.With("jobID", cfg.RecordingID))
+
 	recorder, err := NewRecorder(cfg)
 	if err != nil {
-		log.Fatalf("failed to create recorder: %s", err)
+		slog.Error("failed to create recorder", slog.String("err", err.Error()))
+		os.Exit(1)
 	}
 
-	log.Printf("starting recordinig")
+	slog.Info("starting recording")
 
 	if err := recorder.Start(); err != nil {
-		log.Fatalf("failed to start recording: %s", err)
+		if err := recorder.ReportJobFailure(err.Error()); err != nil {
+			slog.Error("failed to report job failure", slog.String("err", err.Error()))
+		}
+		slog.Error("failed to start recording", slog.String("err", err.Error()))
+		os.Exit(1)
 	}
 
-	log.Printf("recording has started")
+	slog.Info("recording has started")
 
 	sig := make(chan os.Signal, 1)
 	signal.Notify(sig, os.Interrupt, syscall.SIGINT, syscall.SIGTERM)
 	<-sig
 
-	log.Printf("received SIGTERM, stopping recording")
+	slog.Info("received SIGTERM, stopping recording")
 
 	if err := recorder.Stop(); err != nil {
-		log.Fatalf("failed to stop recording: %s", err)
+		slog.Error("failed to stop recording", slog.String("err", err.Error()))
+		os.Exit(1)
 	}
 
-	log.Printf("recording has finished, exiting")
+	slog.Info("recording has finished, exiting")
 }