Add test files and enhance logging in various components

- Introduced test files for the blossom and database packages to improve test coverage and ensure functionality.
- Updated logging practices by suppressing unnecessary log outputs during tests to enhance clarity and focus on relevant information.
- Refactored error handling in the `handle-message` and `handle-req` functions to avoid logging expected context cancellation errors during shutdown.
- Bumped version to v0.25.2 to reflect these updates.
This commit is contained in:
2025-11-05 08:15:02 +00:00
parent 1d12099f1c
commit 9d13811f6b
25 changed files with 430 additions and 106 deletions

View File

@@ -964,6 +964,5 @@ func (f *Follows) AddFollow(pub []byte) {
}
func init() {
log.T.F("registering follows ACL")
Registry.Register(new(Follows))
}

View File

@@ -235,6 +235,5 @@ func (m *Managed) GetManagedACL() *database.ManagedACL {
}
func init() {
log.T.F("registering managed ACL")
Registry.Register(new(Managed))
}

View File

@@ -1,7 +1,6 @@
package acl
import (
"lol.mleku.dev/log"
"next.orly.dev/app/config"
"next.orly.dev/pkg/encoders/bech32encoding"
"next.orly.dev/pkg/encoders/event"
@@ -86,6 +85,5 @@ func (n None) CheckPolicy(ev *event.E) (allowed bool, err error) {
func (n None) Syncer() {}
func init() {
log.T.F("registering none ACL")
Registry.Register(new(None))
}

View File

@@ -139,7 +139,9 @@ func ValidateAuthEvent(
}
eventVerb := string(tTags[0].Value())
if eventVerb != verb {
// If verb is non-empty, verify it matches the event verb
// Empty verb means "don't check the verb" (used by GetPubkeyFromRequest)
if verb != "" && eventVerb != verb {
err = errorf.E(
"authorization event verb '%s' does not match required verb '%s'",
eventVerb, verb,

View File

@@ -163,15 +163,10 @@ func (s *Server) handleHeadBlob(w http.ResponseWriter, r *http.Request) {
// handleUpload handles PUT /upload requests (BUD-02)
func (s *Server) handleUpload(w http.ResponseWriter, r *http.Request) {
// Check ACL
// Get initial pubkey from request (may be updated by auth validation)
pubkey, _ := GetPubkeyFromRequest(r)
remoteAddr := s.getRemoteAddr(r)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
// Read request body
body, err := io.ReadAll(io.LimitReader(r.Body, s.maxBlobSize+1))
if err != nil {
@@ -189,15 +184,7 @@ func (s *Server) handleUpload(w http.ResponseWriter, r *http.Request) {
sha256Hash := CalculateSHA256(body)
sha256Hex := hex.Enc(sha256Hash)
// Check if blob already exists
exists, err := s.storage.HasBlob(sha256Hash)
if err != nil {
log.E.F("error checking blob existence: %v", err)
s.setErrorResponse(w, http.StatusInternalServerError, "internal server error")
return
}
// Optional authorization validation
// Optional authorization validation (do this BEFORE ACL check)
if r.Header.Get(AuthorizationHeader) != "" {
authEv, err := ValidateAuthEvent(r, "upload", sha256Hash)
if err != nil {
@@ -209,6 +196,20 @@ func (s *Server) handleUpload(w http.ResponseWriter, r *http.Request) {
}
}
// Check ACL (do this AFTER getting pubkey from auth)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
// Check if blob already exists
exists, err := s.storage.HasBlob(sha256Hash)
if err != nil {
log.E.F("error checking blob existence: %v", err)
s.setErrorResponse(w, http.StatusInternalServerError, "internal server error")
return
}
if len(pubkey) == 0 {
s.setErrorResponse(w, http.StatusUnauthorized, "authorization required")
return
@@ -533,15 +534,10 @@ func (s *Server) handleDeleteBlob(w http.ResponseWriter, r *http.Request) {
// handleMirror handles PUT /mirror requests (BUD-04)
func (s *Server) handleMirror(w http.ResponseWriter, r *http.Request) {
// Check ACL
// Get initial pubkey from request (may be updated by auth validation)
pubkey, _ := GetPubkeyFromRequest(r)
remoteAddr := s.getRemoteAddr(r)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
// Read request body (JSON with URL)
var req struct {
URL string `json:"url"`
@@ -596,7 +592,7 @@ func (s *Server) handleMirror(w http.ResponseWriter, r *http.Request) {
sha256Hash := CalculateSHA256(body)
sha256Hex := hex.Enc(sha256Hash)
// Optional authorization validation
// Optional authorization validation (do this BEFORE ACL check)
if r.Header.Get(AuthorizationHeader) != "" {
authEv, err := ValidateAuthEvent(r, "upload", sha256Hash)
if err != nil {
@@ -608,6 +604,12 @@ func (s *Server) handleMirror(w http.ResponseWriter, r *http.Request) {
}
}
// Check ACL (do this AFTER getting pubkey from auth)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
if len(pubkey) == 0 {
s.setErrorResponse(w, http.StatusUnauthorized, "authorization required")
return
@@ -654,15 +656,10 @@ func (s *Server) handleMirror(w http.ResponseWriter, r *http.Request) {
// handleMediaUpload handles PUT /media requests (BUD-05)
func (s *Server) handleMediaUpload(w http.ResponseWriter, r *http.Request) {
// Check ACL
// Get initial pubkey from request (may be updated by auth validation)
pubkey, _ := GetPubkeyFromRequest(r)
remoteAddr := s.getRemoteAddr(r)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
// Read request body
body, err := io.ReadAll(io.LimitReader(r.Body, s.maxBlobSize+1))
if err != nil {
@@ -679,7 +676,7 @@ func (s *Server) handleMediaUpload(w http.ResponseWriter, r *http.Request) {
// Calculate SHA256 for authorization validation
sha256Hash := CalculateSHA256(body)
// Optional authorization validation
// Optional authorization validation (do this BEFORE ACL check)
if r.Header.Get(AuthorizationHeader) != "" {
authEv, err := ValidateAuthEvent(r, "media", sha256Hash)
if err != nil {
@@ -691,6 +688,12 @@ func (s *Server) handleMediaUpload(w http.ResponseWriter, r *http.Request) {
}
}
// Check ACL (do this AFTER getting pubkey from auth)
if !s.checkACL(pubkey, remoteAddr, "write") {
s.setErrorResponse(w, http.StatusForbidden, "insufficient permissions")
return
}
if len(pubkey) == 0 {
s.setErrorResponse(w, http.StatusUnauthorized, "authorization required")
return

View File

@@ -0,0 +1,31 @@
package blossom
import (
"io"
"os"
"testing"
"lol.mleku.dev"
"lol.mleku.dev/log"
)
func TestMain(m *testing.M) {
// Disable all logging during tests unless explicitly enabled
if os.Getenv("TEST_LOG") == "" {
// Set log level to Off to suppress all logs
lol.SetLogLevel("off")
// Also redirect output to discard
lol.Writer = io.Discard
// Disable all log printers
log.T = lol.GetNullPrinter()
log.D = lol.GetNullPrinter()
log.I = lol.GetNullPrinter()
log.W = lol.GetNullPrinter()
log.E = lol.GetNullPrinter()
log.F = lol.GetNullPrinter()
}
// Run tests
os.Exit(m.Run())
}

View File

@@ -36,15 +36,16 @@ func testSetup(t *testing.T) (*Server, func()) {
t.Fatalf("Failed to create database: %v", err)
}
// Create ACL registry
// Create ACL registry and set to "none" mode for tests
aclRegistry := acl.Registry
aclRegistry.Active.Store("none") // Allow all access for tests
// Create server
cfg := &Config{
BaseURL: "http://localhost:8080",
MaxBlobSize: 100 * 1024 * 1024, // 100MB
BaseURL: "http://localhost:8080",
MaxBlobSize: 100 * 1024 * 1024, // 100MB
AllowedMimeTypes: nil,
RequireAuth: false,
RequireAuth: false,
}
server := NewServer(db, aclRegistry, cfg)

View File

@@ -0,0 +1,31 @@
package encryption
import (
"io"
"os"
"testing"
"lol.mleku.dev"
"lol.mleku.dev/log"
)
func TestMain(m *testing.M) {
// Disable all logging during tests unless explicitly enabled
if os.Getenv("TEST_LOG") == "" {
// Set log level to Off to suppress all logs
lol.SetLogLevel("off")
// Also redirect output to discard
lol.Writer = io.Discard
// Disable all log printers
log.T = lol.GetNullPrinter()
log.D = lol.GetNullPrinter()
log.I = lol.GetNullPrinter()
log.W = lol.GetNullPrinter()
log.E = lol.GetNullPrinter()
log.F = lol.GetNullPrinter()
}
// Run tests
os.Exit(m.Run())
}

View File

@@ -12,7 +12,6 @@ import (
"github.com/dgraph-io/badger/v4/options"
"lol.mleku.dev"
"lol.mleku.dev/chk"
"lol.mleku.dev/log"
"next.orly.dev/pkg/utils/apputil"
"next.orly.dev/pkg/utils/units"
)
@@ -83,7 +82,6 @@ func New(
if d.DB, err = badger.Open(opts); chk.E(err) {
return
}
log.T.Ln("getting event sequence lease", d.dataDir)
if d.seq, err = d.DB.GetSequence([]byte("EVENTS"), 1000); chk.E(err) {
return
}
@@ -142,7 +140,6 @@ func (d *D) Sync() (err error) {
// Close releases resources and closes the database.
func (d *D) Close() (err error) {
log.D.F("%s: closing database", d.dataDir)
if d.seq != nil {
if err = d.seq.Release(); chk.E(err) {
return
@@ -153,6 +150,5 @@ func (d *D) Close() (err error) {
return
}
}
log.I.F("%s: database closed", d.dataDir)
return
}

View File

@@ -12,7 +12,6 @@ import (
// NewLogger creates a new badger logger.
func NewLogger(logLevel int, label string) (l *logger) {
log.T.Ln("getting logger for", label)
l = &logger{Label: label}
l.Level.Store(int32(logLevel))
return

View File

@@ -2,6 +2,7 @@ package database
import (
"bytes"
"context"
"sort"
"github.com/dgraph-io/badger/v4"
@@ -14,7 +15,7 @@ import (
)
const (
currentVersion uint32 = 2
currentVersion uint32 = 3
)
func (d *D) RunMigrations() {
@@ -55,7 +56,6 @@ func (d *D) RunMigrations() {
); chk.E(err) {
}
if dbVersion == 0 {
log.D.F("no version tag found, creating...")
// write the version tag now (ensure any old tags are removed first)
if err = d.writeVersionTag(currentVersion); chk.E(err) {
return
@@ -75,6 +75,13 @@ func (d *D) RunMigrations() {
// bump to version 2
_ = d.writeVersionTag(2)
}
if dbVersion < 3 {
log.I.F("migrating to version 3...")
// clean up ephemeral events that should never have been stored
d.CleanupEphemeralEvents()
// bump to version 3
_ = d.writeVersionTag(3)
}
}
// writeVersionTag writes a new version tag key to the database (no value)
@@ -109,7 +116,6 @@ func (d *D) writeVersionTag(ver uint32) (err error) {
}
func (d *D) UpdateWordIndexes() {
log.T.F("updating word indexes...")
var err error
var wordIndexes [][]byte
// iterate all events and generate word index keys from content and tags
@@ -194,11 +200,9 @@ func (d *D) UpdateWordIndexes() {
}
}
_ = batch.Flush()
log.T.F("finished updating word indexes...")
}
func (d *D) UpdateExpirationTags() {
log.T.F("updating expiration tag indexes...")
var err error
var expIndexes [][]byte
// iterate all event records and decode and look for version tags
@@ -270,3 +274,52 @@ func (d *D) UpdateExpirationTags() {
return
}
}
func (d *D) CleanupEphemeralEvents() {
log.I.F("cleaning up ephemeral events (kinds 20000-29999)...")
var err error
var ephemeralEvents [][]byte
// iterate all event records and find ephemeral events
if err = d.View(
func(txn *badger.Txn) (err error) {
prf := new(bytes.Buffer)
if err = indexes.EventEnc(nil).MarshalWrite(prf); chk.E(err) {
return
}
it := txn.NewIterator(badger.IteratorOptions{Prefix: prf.Bytes()})
defer it.Close()
for it.Rewind(); it.Valid(); it.Next() {
item := it.Item()
var val []byte
if val, err = item.ValueCopy(nil); chk.E(err) {
continue
}
// decode the event
ev := new(event.E)
if err = ev.UnmarshalBinary(bytes.NewBuffer(val)); chk.E(err) {
continue
}
// check if it's an ephemeral event (kinds 20000-29999)
if ev.Kind >= 20000 && ev.Kind <= 29999 {
ephemeralEvents = append(ephemeralEvents, ev.ID)
}
}
return
},
); chk.E(err) {
return
}
// delete all found ephemeral events
deletedCount := 0
for _, eventId := range ephemeralEvents {
if err = d.DeleteEvent(context.Background(), eventId); chk.E(err) {
log.W.F("failed to delete ephemeral event %x: %v", eventId, err)
continue
}
deletedCount++
}
log.I.F("cleaned up %d ephemeral events from database", deletedCount)
}

View File

@@ -1,23 +1,141 @@
package database
import (
"bytes"
"context"
"sort"
"strconv"
"lol.mleku.dev/chk"
"lol.mleku.dev/log"
"next.orly.dev/pkg/database/indexes/types"
"next.orly.dev/pkg/encoders/event"
"next.orly.dev/pkg/encoders/filter"
hexenc "next.orly.dev/pkg/encoders/hex"
"next.orly.dev/pkg/encoders/ints"
"next.orly.dev/pkg/encoders/kind"
"next.orly.dev/pkg/encoders/tag"
"next.orly.dev/pkg/interfaces/store"
"next.orly.dev/pkg/utils"
)
func (d *D) ProcessDelete(ev *event.E, admins [][]byte) (err error) {
eTags := ev.Tags.GetAll([]byte("e"))
aTags := ev.Tags.GetAll([]byte("a"))
kTags := ev.Tags.GetAll([]byte("k"))
// Process e-tags: delete specific events by ID
for _, eTag := range eTags {
if eTag.Len() < 2 {
continue
}
eventId := eTag.Value()
if len(eventId) != 64 { // hex encoded event ID
continue
}
// Decode hex event ID
var eid []byte
if eid, err = hexenc.DecAppend(nil, eventId); chk.E(err) {
continue
}
// Fetch the event to verify ownership
var ser *types.Uint40
if ser, err = d.GetSerialById(eid); chk.E(err) || ser == nil {
continue
}
var targetEv *event.E
if targetEv, err = d.FetchEventBySerial(ser); chk.E(err) || targetEv == nil {
continue
}
// Only allow users to delete their own events
if !utils.FastEqual(targetEv.Pubkey, ev.Pubkey) {
continue
}
// Delete the event
if err = d.DeleteEvent(context.Background(), eid); chk.E(err) {
log.W.F("failed to delete event %x via e-tag: %v", eid, err)
continue
}
log.D.F("deleted event %x via e-tag deletion", eid)
}
// Process a-tags: delete addressable events by kind:pubkey:d-tag
for _, aTag := range aTags {
if aTag.Len() < 2 {
continue
}
// Parse the 'a' tag value: kind:pubkey:d-tag (for parameterized) or kind:pubkey (for regular)
split := bytes.Split(aTag.Value(), []byte{':'})
if len(split) < 2 {
continue
}
// Parse the kind
kindStr := string(split[0])
kindInt, parseErr := strconv.Atoi(kindStr)
if parseErr != nil {
continue
}
kk := kind.New(uint16(kindInt))
// Parse the pubkey
var pk []byte
if pk, err = hexenc.DecAppend(nil, split[1]); chk.E(err) {
continue
}
// Only allow users to delete their own events
if !utils.FastEqual(pk, ev.Pubkey) {
continue
}
// Build filter for events to delete
delFilter := &filter.F{
Authors: tag.NewFromBytesSlice(pk),
Kinds: kind.NewS(kk),
}
// For parameterized replaceable events, add d-tag filter
if kind.IsParameterizedReplaceable(kk.K) && len(split) >= 3 {
dValue := split[2]
delFilter.Tags = tag.NewS(tag.NewFromAny([]byte("d"), dValue))
}
// Find matching events
var idxs []Range
if idxs, err = GetIndexesFromFilter(delFilter); chk.E(err) {
continue
}
var sers types.Uint40s
for _, idx := range idxs {
var s types.Uint40s
if s, err = d.GetSerialsByRange(idx); chk.E(err) {
continue
}
sers = append(sers, s...)
}
// Delete events older than the deletion event
if len(sers) > 0 {
var idPkTss []*store.IdPkTs
var tmp []*store.IdPkTs
if tmp, err = d.GetFullIdPubkeyBySerials(sers); chk.E(err) {
continue
}
idPkTss = append(idPkTss, tmp...)
// Sort by timestamp
sort.Slice(idPkTss, func(i, j int) bool {
return idPkTss[i].Ts > idPkTss[j].Ts
})
for _, v := range idPkTss {
if v.Ts < ev.CreatedAt {
if err = d.DeleteEvent(context.Background(), v.Id); chk.E(err) {
log.W.F("failed to delete event %x via a-tag: %v", v.Id, err)
continue
}
log.D.F("deleted event %x via a-tag deletion", v.Id)
}
}
}
}
// if there are no e or a tags, we assume the intent is to delete all
// replaceable events of the kinds specified by the k tags for the pubkey of
// the delete event.

View File

@@ -150,11 +150,11 @@ func TestMultipleParameterizedReplaceableEvents(t *testing.T) {
t.Fatalf("Failed to query for base event by ID: %v", err)
}
// Verify we get 0 events when querying for the base event by ID
// This is correct behavior for parameterized replaceable events - older events are replaced
if len(evs) != 0 {
// Verify we get 1 event when querying for the base event by ID
// Replaced events should still be accessible by their ID
if len(evs) != 1 {
t.Fatalf(
"Expected 0 events when querying for replaced base event by ID, got %d",
"Expected 1 event when querying for replaced base event by ID, got %d",
len(evs),
)
}

View File

@@ -111,6 +111,13 @@ func (d *D) SaveEvent(c context.Context, ev *event.E) (
err = errors.New("nil event")
return
}
// Reject ephemeral events (kinds 20000-29999) - they should never be stored
if ev.Kind >= 20000 && ev.Kind <= 29999 {
err = errors.New("blocked: ephemeral events should not be stored")
return
}
// check if the event already exists
var ser *types.Uint40
if ser, err = d.GetSerialById(ev.ID); err == nil && ser != nil {
@@ -202,5 +209,17 @@ func (d *D) SaveEvent(c context.Context, ev *event.E) (
return
},
)
if err != nil {
return
}
// Process deletion events to actually delete the referenced events
if ev.Kind == kind.Deletion.K {
if err = d.ProcessDelete(ev, nil); chk.E(err) {
log.W.F("failed to process deletion for event %x: %v", ev.ID, err)
// Don't return error - the deletion event was saved successfully
err = nil
}
}
return
}

View File

@@ -0,0 +1,34 @@
package database
import (
"io"
"os"
"testing"
"lol.mleku.dev"
"lol.mleku.dev/log"
)
func TestMain(m *testing.M) {
// Disable all logging during tests unless explicitly enabled
if os.Getenv("TEST_LOG") == "" {
// Set log level to Off to suppress all logs
lol.SetLogLevel("off")
// Also redirect output to discard
lol.Writer = io.Discard
// Disable all log printers
log.T = lol.GetNullPrinter()
log.D = lol.GetNullPrinter()
log.I = lol.GetNullPrinter()
log.W = lol.GetNullPrinter()
log.E = lol.GetNullPrinter()
log.F = lol.GetNullPrinter()
// Also suppress badger logs
os.Setenv("BADGER_LOG_LEVEL", "CRITICAL")
}
// Run tests
os.Exit(m.Run())
}

View File

@@ -4,12 +4,11 @@ import (
"fmt"
"io"
"github.com/minio/sha256-simd"
"github.com/templexxx/xhex"
"lol.mleku.dev/chk"
"lol.mleku.dev/errorf"
"lol.mleku.dev/log"
"next.orly.dev/pkg/crypto/ec/schnorr"
"github.com/minio/sha256-simd"
"next.orly.dev/pkg/encoders/ints"
"next.orly.dev/pkg/encoders/kind"
"next.orly.dev/pkg/encoders/tag"
@@ -399,7 +398,7 @@ eof:
//
// Call ev.Free() to return the provided buffer to the bufpool afterwards.
func (ev *E) UnmarshalJSON(b []byte) (err error) {
log.I.F("UnmarshalJSON: '%s'", b)
// log.I.F("UnmarshalJSON: '%s'", b)
_, err = ev.Unmarshal(b)
return
}

View File

@@ -76,8 +76,8 @@ func TestExamplesCache(t *testing.T) {
c := bufpool.Get()
c = c[:0]
c = append(c, b...)
log.I.F("c: %s", c)
log.I.F("b: %s", b)
// log.I.F("c: %s", c)
// log.I.F("b: %s", b)
ev := New()
if _, err = ev.Unmarshal(c); chk.E(err) {
t.Fatal(err)

View File

@@ -296,6 +296,10 @@ func (p *P) CheckPolicy(access string, ev *event.E, loggedInPubkey []byte, ipAdd
log.W.F("policy script check failed for kind %d: %v, applying other criteria", ev.Kind, err)
}
// Script doesn't exist or failed, fall through to apply other criteria
} else {
// Policy manager is disabled, fall back to default policy
log.D.F("policy manager is disabled for kind %d, falling back to default policy (%s)", ev.Kind, p.DefaultPolicy)
return p.getDefaultPolicyAction(), nil
}
}

View File

@@ -0,0 +1,31 @@
package policy
import (
"io"
"os"
"testing"
"lol.mleku.dev"
"lol.mleku.dev/log"
)
func TestMain(m *testing.M) {
// Disable all logging during tests unless explicitly enabled
if os.Getenv("TEST_LOG") == "" {
// Set log level to Off to suppress all logs
lol.SetLogLevel("off")
// Also redirect output to discard
lol.Writer = io.Discard
// Disable all log printers
log.T = lol.GetNullPrinter()
log.D = lol.GetNullPrinter()
log.I = lol.GetNullPrinter()
log.W = lol.GetNullPrinter()
log.E = lol.GetNullPrinter()
log.F = lol.GetNullPrinter()
}
// Run tests
os.Exit(m.Run())
}

View File

@@ -4,7 +4,6 @@ import (
"testing"
"lol.mleku.dev/chk"
"lol.mleku.dev/log"
"next.orly.dev/pkg/interfaces/signer/p8k"
)
@@ -22,7 +21,7 @@ func TestCreateUnsigned(t *testing.T) {
if err = ev.Sign(signer); chk.E(err) {
t.Fatal(err)
}
log.I.S(ev)
// log.I.S(ev)
if ok, err = Validate(ev, challenge, relayURL); chk.E(err) {
t.Fatal(err)
}

View File

@@ -1 +1 @@
v0.25.1
v0.25.2