summercms/modules/cabana/action_run_log_test.go

package cabana_test

import (
	"fmt"
	"net/http"
	"strings"
	"testing"
)

// TestAdminActionRunLog pins the action run log of the admin-action-audit-log
// todo (AR-18.1-03): who ran which toolbar or widget action. A successful run
// writes one "cabana: admin action run" line with the controller, action,
// administrator id and kind (plus field and record id for a widget) and never
// the posted values, payload, answer or record contents; a refused, invalid
// or failed run writes no run line, and the failure lines carry the same
// administrator id and kind. Runs on the acme.demo.gadgets fixture
// (PostgreSQL).
func TestAdminActionRunLog(t *testing.T) {
	env, gdb := newActEnv(t)
	const widget = "/acme/demo/gadgets/widgets/lookup"
	const toolbar = "/acme/demo/gadgets/toolbar/recount"
	const runPrefix = "cabana: admin action run"
	secret := actInsert(t, gdb, "Secretname", "acme")

	me := profileOf(t, env.expect(t, http.StatusOK, http.MethodGet, "/auth/me", "", "bearer").Body.Bytes())
	if me.ID == 0 {
		t.Fatal("the signed-in administrator has id 0")
	}
	adminToken := fmt.Sprintf("admin_id=%d", me.ID)
	logs := captureLog(t)

	// A toolbar run: kind toolbar, no field and no record id.
	env.expect(t, http.StatusOK, http.MethodPost, toolbar, `{}`, "bearer")
	env.spy.take()
	runs := logs.matching(runPrefix)
	if len(runs) != 1 {
		t.Fatalf("toolbar run lines = %q", runs)
	}
	line := runs[0]
	for _, want := range []string{"controller=acme.demo.gadgets", "action=recount", "kind=toolbar", adminToken} {
		if !strings.Contains(line, want) {
			t.Fatalf("toolbar run line lacks %s: %q", want, line)
		}
	}
	for _, banned := range []string{"field=", "record_id="} {
		if strings.Contains(line, banned) {
			t.Fatalf("toolbar run line carries %s: %q", banned, line)
		}
	}

	// A widget run on a saved record: kind field, the field name and the
	// record id, but not the record, the posted value or the answer.
	env.expect(t, http.StatusOK, http.MethodPost, widget,
		fmt.Sprintf(`{"record_id":%d,"values":{"name":"typedsecret"}}`, secret), "bearer")
	env.spy.take()
	runs = logs.matching(runPrefix)
	if len(runs) != 2 {
		t.Fatalf("widget run lines = %q", runs)
	}
	line = runs[1]
	for _, want := range []string{"controller=acme.demo.gadgets", "action=lookup", "kind=field", "field=lookup", fmt.Sprintf("record_id=%d", secret), adminToken} {
		if !strings.Contains(line, want) {
			t.Fatalf("widget run line lacks %s: %q", want, line)
		}
	}
	for _, banned := range []string{"Secretname", "typedsecret", "looked-up", "filled in"} {
		if strings.Contains(line, banned) {
			t.Fatalf("widget run line carries %s: %q", banned, line)
		}
	}

	// A widget run on the create form: no record id and no payload.
	env.expect(t, http.StatusOK, http.MethodPost, widget, `{"payload":{"note":"payloadsecret"}}`, "bearer")
	env.spy.take()
	runs = logs.matching(runPrefix)
	if len(runs) != 3 {
		t.Fatalf("create-form run lines = %q", runs)
	}
	line = runs[2]
	for _, want := range []string{"kind=field", "field=lookup", adminToken} {
		if !strings.Contains(line, want) {
			t.Fatalf("create-form run line lacks %s: %q", want, line)
		}
	}
	for _, banned := range []string{"record_id=", "payloadsecret"} {
		if strings.Contains(line, banned) {
			t.Fatalf("create-form run line carries %s: %q", banned, line)
		}
	}

	// Refused, invalid and failed runs write no run line.
	env.expect(t, http.StatusUnprocessableEntity, http.MethodPost, widget, `{"values":{"name":"invalid"}}`, "bearer")
	env.expect(t, http.StatusForbidden, http.MethodPost, widget, `{"values":{"name":"refused"}}`, "bearer")
	env.expect(t, http.StatusInternalServerError, http.MethodPost, widget, `{"values":{"name":"boom"}}`, "bearer")
	env.expect(t, http.StatusInternalServerError, http.MethodPost, widget, `{"payload":"big"}`, "bearer")
	env.expect(t, http.StatusForbidden, http.MethodPost, toolbar, `{}`, "limited")
	env.expect(t, http.StatusForbidden, http.MethodPost, widget, `{}`, "limited")
	env.spy.take()
	if runs = logs.matching(runPrefix); len(runs) != 3 {
		t.Fatalf("a refused, invalid or failed run was logged as run: %q", runs)
	}

	// The failure lines name the administrator and the kind.
	failed := logs.matching("cabana: admin action failed")
	if len(failed) != 1 {
		t.Fatalf("failure lines = %q", failed)
	}
	rejected := logs.matching("cabana: admin action data rejected")
	if len(rejected) != 1 {
		t.Fatalf("data rejected lines = %q", rejected)
	}
	for _, line := range []string{failed[0], rejected[0]} {
		for _, want := range []string{"action=lookup", "kind=field", "field=lookup", adminToken} {
			if !strings.Contains(line, want) {
				t.Fatalf("failure line lacks %s: %q", want, line)
			}
		}
	}
}