Add more debug logging

cmd/orchid/serve.go

@@ -14,7 +14,6 @@ import (
 	_ "github.com/mattn/go-sqlite3"
 	"github.com/mrmelon54/exit-reload"
 	"gopkg.in/yaml.v3"
-	"log"
 	"os"
 	"path/filepath"
 	"sync"
@@ -67,13 +66,13 @@ func normalLoad(conf startUpConfig, wd string) {
 	// load the MJWT RSA public key from a pem encoded file
 	mJwtVerify, err := mjwt.NewKeyStoreFromPath(filepath.Join(wd, "keys"))
 	if err != nil {
-		log.Fatalf("[Orchid] Failed to load MJWT verifier public key from file '%s': %s", filepath.Join(wd, "keys"), err)
+		logger.Logger.Fatal("Failed to load MJWT verifier public key from file", "path", filepath.Join(wd, "keys"), "err", err)
 	}
 
 	// open sqlite database
 	db, err := orchid.InitDB(filepath.Join(wd, "orchid.db.sqlite"))
 	if err != nil {
-		log.Fatal("[Orchid] Failed to open database:", err)
+		logger.Logger.Fatal("Failed to open database", "err", err)
 	}
 
 	certDir := filepath.Join(wd, "renewal-certs")
@@ -82,11 +81,11 @@ func normalLoad(conf startUpConfig, wd string) {
 	wg := &sync.WaitGroup{}
 	acmeProv, err := httpAcme.NewHttpAcmeProvider(filepath.Join(wd, "tokens.yml"), conf.Acme.PresentUrl, conf.Acme.CleanUpUrl, conf.Acme.RefreshUrl)
 	if err != nil {
-		log.Fatal("[Orchid] HTTP Acme Error:", err)
+		logger.Logger.Fatal("HTTP Acme Error", "err", err)
 	}
 	renewalService, err := renewal.NewService(wg, db, acmeProv, conf.LE, certDir, keyDir)
 	if err != nil {
-		log.Fatal("[Orchid] Service Error:", err)
+		logger.Logger.Fatal("Service Error", "err", err)
 	}
 	srv := servers.NewApiServer(conf.Listen, db, mJwtVerify, conf.Domains)
 	logger.Logger.Info("Starting API server", "listen", srv.Addr)

renewal/service.go

@@ -201,6 +201,8 @@ var ErrAlreadyRenewing = errors.New("already renewing")
 // renewalRoutine is the main loop which makes used of certTicker to constantly
 // check if the existing certificates are up-to-date.
 func (s *Service) renewalRoutine(wg *sync.WaitGroup) {
+	Logger.Debug("Starting renewalRoutine")
+
 	// Upon leaving the function stop the ticker and clear the WaitGroup.
 	defer func() {
 		s.certTicker.Stop()
@@ -226,6 +228,8 @@ func (s *Service) renewalRoutine(wg *sync.WaitGroup) {
 			// Exit if certDone has closed
 			return
 		case <-s.certTicker.C:
+			Logger.Debug("Ticking certificate renewal")
+
 			// Start a new check in a separate routine
 			go func() {
 				// run a renewal check and log errors, but ignore ErrAlreadyRenewing
@@ -246,6 +250,8 @@ func (s *Service) renewalCheck() error {
 	}
 	defer s.renewLock.Unlock()
 
+	Logger.Debug("Running renewalCheck")
+
 	// check for running out certificates in the database
 	localData, err := s.findNextCertificateToRenew()
 	if err != nil {
@@ -254,12 +260,14 @@ func (s *Service) renewalCheck() error {
 
 	// no certificates to update
 	if localData == nil {
+		Logger.Debug("No certificates to update")
 		return nil
 	}
 
 	// renew the certificate from the collected data
 	err = s.renewCert(localData)
 	if err != nil {
+		Logger.Debug("Failed to renew certificate", "err", err)
 		return err
 	}
 
@@ -392,6 +400,7 @@ func (s *Service) getPrivateKey(id int64) (*rsa.PrivateKey, error) {
 func (s *Service) renewCert(localData *localCertData) error {
 	// database synchronous state
 	s.setRenewing(localData.id, true, false)
+	Logger.Debug("No certificates to update")
 
 	// run internal renewal code and log errors
 	cert, certBytes, err := s.renewCertInternal(localData)

renewal/service_test.go

@@ -10,8 +10,10 @@ import (
 	"encoding/pem"
 	"fmt"
 	"github.com/1f349/orchid"
+	"github.com/1f349/orchid/logger"
 	"github.com/1f349/orchid/pebble"
 	"github.com/1f349/orchid/test"
+	"github.com/charmbracelet/log"
 	"github.com/go-acme/lego/v4/lego"
 	"github.com/google/uuid"
 	_ "github.com/mattn/go-sqlite3"
@@ -71,7 +73,7 @@ func setupPebbleSuite(tb testing.TB) (*certgen.CertGen, func()) {
 	assert.NoError(tb, os.WriteFile(filepath.Join(pebbleTmp, "certs", "localhost", "cert.pem"), serverTls.GetCertPem(), os.ModePerm))
 	assert.NoError(tb, os.WriteFile(filepath.Join(pebbleTmp, "certs", "localhost", "key.pem"), serverTls.GetKeyPem(), os.ModePerm))
 
-	dnsServer := test.MakeFakeDnsProv("127.0.0.34:5053") // 127.0.0.34:53
+	dnsServer := test.MakeFakeDnsProv("127.243.243.34:5053") // 127.243.243.34:53
 	dnsServer.AddRecursiveSOA("example.test.")
 	go dnsServer.Start()
 	testDnsOptions = dnsServer
@@ -140,6 +142,8 @@ func deconstructPebbleTest(t *testing.T, service *Service) {
 }
 
 func TestPebbleRenewal(t *testing.T) {
+	logger.Logger.SetLevel(log.DebugLevel)
+
 	if testing.Short() {
 		t.Skip("Skipping renewal tests in short mode")
 	}

test/fakeDnsProv.go

@@ -2,10 +2,10 @@ package test
 
 import (
 	"fmt"
+	"github.com/1f349/orchid/logger"
 	"github.com/go-acme/lego/v4/challenge"
 	"github.com/go-acme/lego/v4/challenge/dns01"
 	"github.com/miekg/dns"
-	"log"
 	"strings"
 )
 
@@ -47,13 +47,13 @@ func (f *fakeDnsProv) AddRecursiveSOA(fqdn string) {
 func (f *fakeDnsProv) Present(domain, _, keyAuth string) error {
 	info := dns01.GetChallengeInfo(domain, keyAuth)
 	f.mTxt[info.EffectiveFQDN] = info.Value
-	log.Printf("fakeDnsProv.Present(%s TXT %s)\n", info.EffectiveFQDN, info.Value)
+	logger.Logger.Infof("fakeDnsProv.Present(%s TXT %s)", info.EffectiveFQDN, info.Value)
 	return nil
 }
 func (f *fakeDnsProv) CleanUp(domain, _, keyAuth string) error {
 	info := dns01.GetChallengeInfo(domain, keyAuth)
 	delete(f.mTxt, info.EffectiveFQDN)
-	log.Printf("fakeDnsProv.CleanUp(%s TXT %s)\n", info.EffectiveFQDN, info.Value)
+	logger.Logger.Infof("fakeDnsProv.CleanUp(%s TXT %s)", info.EffectiveFQDN, info.Value)
 	return nil
 }
 func (f *fakeDnsProv) GetDnsAddrs() []string { return []string{f.Addr} }
@@ -62,7 +62,7 @@ func (f *fakeDnsProv) parseQuery(m *dns.Msg) {
 	for _, q := range m.Question {
 		switch q.Qtype {
 		case dns.TypeTXT:
-			log.Printf("Looking up %s TXT record\n", q.Name)
+			logger.Logger.Info("Looking up TXT record", "name", q.Name)
 			txt := f.mTxt[q.Name]
 			if txt != "" {
 				rr, err := dns.NewRR(fmt.Sprintf("%s 32600 IN TXT \"%s\"", q.Name, txt))
@@ -71,7 +71,7 @@ func (f *fakeDnsProv) parseQuery(m *dns.Msg) {
 				}
 			}
 		default:
-			log.Printf("Looking up %d for %s\n", q.Qtype, q.Name)
+			logger.Logger.Info("Looking up", "qtype", q.Qtype, "name", q.Name)
 		}
 	}
 }
@@ -95,10 +95,10 @@ func (f *fakeDnsProv) Start() {
 
 	// start server
 	f.srv = &dns.Server{Addr: f.Addr, Net: "udp"}
-	log.Printf("Starting fake dns service at %s\n", f.srv.Addr)
+	logger.Logger.Info("Starting fake dns service", "addr", f.srv.Addr)
 	err := f.srv.ListenAndServe()
 	if err != nil {
-		log.Fatalf("Failed to start server: %s\n ", err.Error())
+		logger.Logger.Fatal("Failed to start server", "err", err)
 	}
 }