From f6f1a758848d7b1bdce659147e4ad95a59591880 Mon Sep 17 00:00:00 2001 From: William Elwood Date: Fri, 1 Nov 2019 07:56:57 +0000 Subject: [PATCH] Improve logging by keeping a Source's configured name on the struct --- dnscrypt-proxy/config.go | 2 +- dnscrypt-proxy/sources.go | 70 +++++++++++++++++----------------- dnscrypt-proxy/sources_test.go | 33 ++++++++-------- 3 files changed, 51 insertions(+), 54 deletions(-) diff --git a/dnscrypt-proxy/config.go b/dnscrypt-proxy/config.go index c80cb52c..9d85a638 100644 --- a/dnscrypt-proxy/config.go +++ b/dnscrypt-proxy/config.go @@ -613,7 +613,7 @@ func (config *Config) loadSource(proxy *Proxy, requiredProps stamps.ServerInform if cfgSource.RefreshDelay <= 0 { cfgSource.RefreshDelay = 72 } - source, err := NewSource(proxy.xTransport, cfgSource.URLs, cfgSource.MinisignKeyStr, cfgSource.CacheFile, cfgSource.FormatStr, time.Duration(cfgSource.RefreshDelay)*time.Hour) + source, err := NewSource(cfgSourceName, proxy.xTransport, cfgSource.URLs, cfgSource.MinisignKeyStr, cfgSource.CacheFile, cfgSource.FormatStr, time.Duration(cfgSource.RefreshDelay)*time.Hour) if err != nil { dlog.Criticalf("Unable to retrieve source [%s]: [%s]", cfgSourceName, err) return err diff --git a/dnscrypt-proxy/sources.go b/dnscrypt-proxy/sources.go index bbae357d..804b0e68 100644 --- a/dnscrypt-proxy/sources.go +++ b/dnscrypt-proxy/sources.go @@ -31,6 +31,7 @@ const ( ) type Source struct { + name string urls []string format SourceFormat in []byte @@ -51,7 +52,7 @@ func (source *Source) checkSignature(bin, sig []byte) (err error) { // timeNow can be replaced by tests to provide a static value var timeNow = time.Now -func (source *Source) fetchFromCache() (delayTillNextUpdate time.Duration, err error) { +func (source *Source) fetchFromCache() (delay time.Duration, err error) { var bin, sig []byte if bin, err = ioutil.ReadFile(source.cacheFile); err != nil { return @@ -68,10 +69,10 @@ func (source *Source) fetchFromCache() (delayTillNextUpdate time.Duration, err e return } if elapsed := timeNow().Sub(fi.ModTime()); elapsed < source.cacheTTL { - delayTillNextUpdate = source.prefetchDelay - elapsed - dlog.Debugf("Cache file [%s] is still fresh, next update: %v", source.cacheFile, delayTillNextUpdate) + delay = source.prefetchDelay - elapsed + dlog.Debugf("Source [%s] cache file [%s] is still fresh, next update: %v", source.name, source.cacheFile, delay) } else { - dlog.Debugf("Cache file [%s] needs to be refreshed", source.cacheFile) + dlog.Debugf("Source [%s] cache file [%s] needs to be refreshed", source.name, source.cacheFile) } return } @@ -104,20 +105,19 @@ func fetchFromURL(xTransport *XTransport, u *url.URL) (bin []byte, err error) { return } -func (source *Source) fetchWithCache(xTransport *XTransport, urlStr string) (delayTillNextUpdate time.Duration, err error) { - if delayTillNextUpdate, err = source.fetchFromCache(); err != nil { +func (source *Source) fetchWithCache(xTransport *XTransport, urlStr string) (delay time.Duration, err error) { + if delay, err = source.fetchFromCache(); err != nil { if len(urlStr) == 0 { - dlog.Errorf("Cache file [%s] not present and no URL given to retrieve it", source.cacheFile) + dlog.Errorf("Source [%s] cache file [%s] not present and no URL given", source.name, source.cacheFile) return } - dlog.Debugf("Cache file [%s] not present", source.cacheFile) + dlog.Debugf("Source [%s] cache file [%s] not present", source.name, source.cacheFile) } - if err == nil && delayTillNextUpdate > 0 { - dlog.Debugf("Delay till next update: %v", delayTillNextUpdate) + if delay > 0 { return } - delayTillNextUpdate = MinimumPrefetchInterval - dlog.Infof("Loading source information from URL [%s]", urlStr) + delay = MinimumPrefetchInterval + dlog.Infof("Source [%s] loading from URL [%s]", source.name, urlStr) var srcURL *url.URL if srcURL, err = url.Parse(urlStr); err != nil { @@ -138,15 +138,16 @@ func (source *Source) fetchWithCache(xTransport *XTransport, urlStr string) (del } source.in = bin source.writeToCache(bin, sig) // ignore error: not fatal - delayTillNextUpdate = source.prefetchDelay + delay = source.prefetchDelay return } -func NewSource(xTransport *XTransport, urls []string, minisignKeyStr string, cacheFile string, formatStr string, refreshDelay time.Duration) (source *Source, err error) { +// NewSource loads a new source using the given cacheFile and urls, ensuring it has a valid signature +func NewSource(name string, xTransport *XTransport, urls []string, minisignKeyStr string, cacheFile string, formatStr string, refreshDelay time.Duration) (source *Source, err error) { if refreshDelay < DefaultPrefetchDelay { refreshDelay = DefaultPrefetchDelay } - source = &Source{urls: urls, cacheFile: cacheFile, cacheTTL: refreshDelay, prefetchDelay: DefaultPrefetchDelay} + source = &Source{name: name, urls: urls, cacheFile: cacheFile, cacheTTL: refreshDelay, prefetchDelay: DefaultPrefetchDelay} if formatStr == "v2" { source.format = SourceFormatV2 } else { @@ -159,48 +160,45 @@ func NewSource(xTransport *XTransport, urls []string, minisignKeyStr string, cac } now := timeNow() - var delayTillNextUpdate time.Duration + var delay time.Duration if len(urls) <= 0 { - delayTillNextUpdate, err = source.fetchWithCache(xTransport, "") + delay, err = source.fetchWithCache(xTransport, "") } else { for _, url := range urls { - delayTillNextUpdate, err = source.fetchWithCache(xTransport, url) + delay, err = source.fetchWithCache(xTransport, url) if err == nil { break } - dlog.Infof("Loading from [%s] failed", url) + dlog.Infof("Source [%s] failed to load from [%s]", name, url) } - source.refresh = now.Add(delayTillNextUpdate) + source.refresh = now.Add(delay) } if err != nil { return } - - dlog.Noticef("Source [%s] loaded", cacheFile) + dlog.Noticef("Source [%s] loaded", name) return } +// PrefetchSources downloads latest versions of given sources, ensuring they have a valid signature before caching func PrefetchSources(xTransport *XTransport, sources []*Source) time.Duration { now := timeNow() interval := MinimumPrefetchInterval for _, source := range sources { - if source.refresh.IsZero() { + if source.refresh.IsZero() || source.refresh.After(now) { continue } + dlog.Debugf("Prefetching [%s]", source.name) for _, u := range source.urls { - if source.refresh.After(now) { - continue - } - dlog.Debugf("Prefetching [%s]", u) - delay, err := source.fetchWithCache(xTransport, u) - if err != nil { - dlog.Debugf("Prefetching [%s] failed: %v", u, err) - continue - } - dlog.Debugf("Prefetching [%s] succeeded. Next refresh scheduled for %v", u, source.refresh) - source.refresh = now.Add(delay) - if delay >= MinimumPrefetchInterval && (interval == MinimumPrefetchInterval || interval > delay) { - interval = delay + if delay, err := source.fetchWithCache(xTransport, u); err != nil { + dlog.Debugf("Prefetching [%s] from [%s] failed: %v", source.name, u, err) + } else { + dlog.Debugf("Prefetching [%s] succeeded, next update: %v", source.name, delay) + source.refresh = now.Add(delay) + if delay >= MinimumPrefetchInterval && (interval == MinimumPrefetchInterval || interval > delay) { + interval = delay + } + break } } } diff --git a/dnscrypt-proxy/sources_test.go b/dnscrypt-proxy/sources_test.go index 024e879f..8d8c89f1 100644 --- a/dnscrypt-proxy/sources_test.go +++ b/dnscrypt-proxy/sources_test.go @@ -54,12 +54,11 @@ type SourceTestData struct { } type SourceTestExpect struct { - success bool - cachePath string - cache []SourceFixture - Source *Source - delay time.Duration - err string + success bool + err, cachePath string + cache []SourceFixture + Source *Source + delay time.Duration } func readFixture(t *testing.T, name string) []byte { @@ -308,7 +307,7 @@ func setupSourceTestCase(t *testing.T, d *SourceTestData, i int, e = &SourceTestExpect{ cachePath: filepath.Join(d.tempDir, id), } - e.Source = &Source{urls: []string{}, format: SourceFormatV2, minisignKey: d.key, + e.Source = &Source{name: id, urls: []string{}, format: SourceFormatV2, minisignKey: d.key, cacheFile: e.cachePath, cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay} if cacheTest != nil { prepSourceTestCache(t, d, e, d.sources[i], *cacheTest) @@ -334,17 +333,17 @@ func TestNewSource(t *testing.T) { } d.n++ for _, tt := range []struct { - name, key, v string - refresh time.Duration - e *SourceTestExpect + v, key string + refresh time.Duration + e *SourceTestExpect }{ - {"old format", d.keyStr, "v1", DefaultPrefetchDelay * 3, &SourceTestExpect{ - Source: &Source{cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}, err: "Unsupported source format"}}, - {"invalid public key", "", "v2", DefaultPrefetchDelay * 3, &SourceTestExpect{ - Source: &Source{cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}, err: "Invalid encoded public key"}}, + {"v1", d.keyStr, DefaultPrefetchDelay * 2, &SourceTestExpect{err: "Unsupported source format", + Source: &Source{name: "old format", cacheTTL: DefaultPrefetchDelay * 2, prefetchDelay: DefaultPrefetchDelay}}}, + {"v2", "", DefaultPrefetchDelay * 3, &SourceTestExpect{err: "Invalid encoded public key", + Source: &Source{name: "invalid public key", cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}}}, } { - t.Run(tt.name, func(t *testing.T) { - got, err := NewSource(d.xTransport, tt.e.Source.urls, tt.key, tt.e.cachePath, tt.v, tt.refresh) + t.Run(tt.e.Source.name, func(t *testing.T) { + got, err := NewSource(tt.e.Source.name, d.xTransport, tt.e.Source.urls, tt.key, tt.e.cachePath, tt.v, tt.refresh) checkResult(t, tt.e, got, err) }) } @@ -354,7 +353,7 @@ func TestNewSource(t *testing.T) { for i := range d.sources { id, e := setupSourceTestCase(t, d, i, &cacheTest, downloadTest) t.Run("cache "+cacheTestName+", download "+downloadTestName+"/"+id, func(t *testing.T) { - got, err := NewSource(d.xTransport, e.Source.urls, d.keyStr, e.cachePath, "v2", DefaultPrefetchDelay*3) + got, err := NewSource(id, d.xTransport, e.Source.urls, d.keyStr, e.cachePath, "v2", DefaultPrefetchDelay*3) checkResult(t, e, got, err) }) }