diff --git a/cmd/orchid/serve.go b/cmd/orchid/serve.go index f54a6fa..aa56cd8 100644 --- a/cmd/orchid/serve.go +++ b/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) diff --git a/renewal/service.go b/renewal/service.go index af209a7..31655cb 100644 --- a/renewal/service.go +++ b/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) diff --git a/renewal/service_test.go b/renewal/service_test.go index 23404f9..6246bc9 100644 --- a/renewal/service_test.go +++ b/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") } diff --git a/test/fakeDnsProv.go b/test/fakeDnsProv.go index 32bb42a..42705eb 100644 --- a/test/fakeDnsProv.go +++ b/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) } }