Improve logging by keeping a Source's configured name on the struct

This commit is contained in:
William Elwood 2019-11-01 07:56:57 +00:00 committed by Frank Denis
parent b697283309
commit f6f1a75884
3 changed files with 51 additions and 54 deletions

View File

@ -613,7 +613,7 @@ func (config *Config) loadSource(proxy *Proxy, requiredProps stamps.ServerInform
if cfgSource.RefreshDelay <= 0 { if cfgSource.RefreshDelay <= 0 {
cfgSource.RefreshDelay = 72 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 { if err != nil {
dlog.Criticalf("Unable to retrieve source [%s]: [%s]", cfgSourceName, err) dlog.Criticalf("Unable to retrieve source [%s]: [%s]", cfgSourceName, err)
return err return err

View File

@ -31,6 +31,7 @@ const (
) )
type Source struct { type Source struct {
name string
urls []string urls []string
format SourceFormat format SourceFormat
in []byte 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 // timeNow can be replaced by tests to provide a static value
var timeNow = time.Now 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 var bin, sig []byte
if bin, err = ioutil.ReadFile(source.cacheFile); err != nil { if bin, err = ioutil.ReadFile(source.cacheFile); err != nil {
return return
@ -68,10 +69,10 @@ func (source *Source) fetchFromCache() (delayTillNextUpdate time.Duration, err e
return return
} }
if elapsed := timeNow().Sub(fi.ModTime()); elapsed < source.cacheTTL { if elapsed := timeNow().Sub(fi.ModTime()); elapsed < source.cacheTTL {
delayTillNextUpdate = source.prefetchDelay - elapsed delay = source.prefetchDelay - elapsed
dlog.Debugf("Cache file [%s] is still fresh, next update: %v", source.cacheFile, delayTillNextUpdate) dlog.Debugf("Source [%s] cache file [%s] is still fresh, next update: %v", source.name, source.cacheFile, delay)
} else { } 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 return
} }
@ -104,20 +105,19 @@ func fetchFromURL(xTransport *XTransport, u *url.URL) (bin []byte, err error) {
return return
} }
func (source *Source) fetchWithCache(xTransport *XTransport, urlStr string) (delayTillNextUpdate time.Duration, err error) { func (source *Source) fetchWithCache(xTransport *XTransport, urlStr string) (delay time.Duration, err error) {
if delayTillNextUpdate, err = source.fetchFromCache(); err != nil { if delay, err = source.fetchFromCache(); err != nil {
if len(urlStr) == 0 { 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 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 { if delay > 0 {
dlog.Debugf("Delay till next update: %v", delayTillNextUpdate)
return return
} }
delayTillNextUpdate = MinimumPrefetchInterval delay = MinimumPrefetchInterval
dlog.Infof("Loading source information from URL [%s]", urlStr) dlog.Infof("Source [%s] loading from URL [%s]", source.name, urlStr)
var srcURL *url.URL var srcURL *url.URL
if srcURL, err = url.Parse(urlStr); err != nil { 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.in = bin
source.writeToCache(bin, sig) // ignore error: not fatal source.writeToCache(bin, sig) // ignore error: not fatal
delayTillNextUpdate = source.prefetchDelay delay = source.prefetchDelay
return 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 { if refreshDelay < DefaultPrefetchDelay {
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" { if formatStr == "v2" {
source.format = SourceFormatV2 source.format = SourceFormatV2
} else { } else {
@ -159,48 +160,45 @@ func NewSource(xTransport *XTransport, urls []string, minisignKeyStr string, cac
} }
now := timeNow() now := timeNow()
var delayTillNextUpdate time.Duration var delay time.Duration
if len(urls) <= 0 { if len(urls) <= 0 {
delayTillNextUpdate, err = source.fetchWithCache(xTransport, "") delay, err = source.fetchWithCache(xTransport, "")
} else { } else {
for _, url := range urls { for _, url := range urls {
delayTillNextUpdate, err = source.fetchWithCache(xTransport, url) delay, err = source.fetchWithCache(xTransport, url)
if err == nil { if err == nil {
break 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 { if err != nil {
return return
} }
dlog.Noticef("Source [%s] loaded", name)
dlog.Noticef("Source [%s] loaded", cacheFile)
return return
} }
// PrefetchSources downloads latest versions of given sources, ensuring they have a valid signature before caching
func PrefetchSources(xTransport *XTransport, sources []*Source) time.Duration { func PrefetchSources(xTransport *XTransport, sources []*Source) time.Duration {
now := timeNow() now := timeNow()
interval := MinimumPrefetchInterval interval := MinimumPrefetchInterval
for _, source := range sources { for _, source := range sources {
if source.refresh.IsZero() { if source.refresh.IsZero() || source.refresh.After(now) {
continue continue
} }
dlog.Debugf("Prefetching [%s]", source.name)
for _, u := range source.urls { for _, u := range source.urls {
if source.refresh.After(now) { if delay, err := source.fetchWithCache(xTransport, u); err != nil {
continue dlog.Debugf("Prefetching [%s] from [%s] failed: %v", source.name, u, err)
} } else {
dlog.Debugf("Prefetching [%s]", u) dlog.Debugf("Prefetching [%s] succeeded, next update: %v", source.name, delay)
delay, err := source.fetchWithCache(xTransport, u) source.refresh = now.Add(delay)
if err != nil { if delay >= MinimumPrefetchInterval && (interval == MinimumPrefetchInterval || interval > delay) {
dlog.Debugf("Prefetching [%s] failed: %v", u, err) interval = delay
continue }
} break
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
} }
} }
} }

View File

@ -54,12 +54,11 @@ type SourceTestData struct {
} }
type SourceTestExpect struct { type SourceTestExpect struct {
success bool success bool
cachePath string err, cachePath string
cache []SourceFixture cache []SourceFixture
Source *Source Source *Source
delay time.Duration delay time.Duration
err string
} }
func readFixture(t *testing.T, name string) []byte { func readFixture(t *testing.T, name string) []byte {
@ -308,7 +307,7 @@ func setupSourceTestCase(t *testing.T, d *SourceTestData, i int,
e = &SourceTestExpect{ e = &SourceTestExpect{
cachePath: filepath.Join(d.tempDir, id), 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} cacheFile: e.cachePath, cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}
if cacheTest != nil { if cacheTest != nil {
prepSourceTestCache(t, d, e, d.sources[i], *cacheTest) prepSourceTestCache(t, d, e, d.sources[i], *cacheTest)
@ -334,17 +333,17 @@ func TestNewSource(t *testing.T) {
} }
d.n++ d.n++
for _, tt := range []struct { for _, tt := range []struct {
name, key, v string v, key string
refresh time.Duration refresh time.Duration
e *SourceTestExpect e *SourceTestExpect
}{ }{
{"old format", d.keyStr, "v1", DefaultPrefetchDelay * 3, &SourceTestExpect{ {"v1", d.keyStr, DefaultPrefetchDelay * 2, &SourceTestExpect{err: "Unsupported source format",
Source: &Source{cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}, err: "Unsupported source format"}}, Source: &Source{name: "old format", cacheTTL: DefaultPrefetchDelay * 2, prefetchDelay: DefaultPrefetchDelay}}},
{"invalid public key", "", "v2", DefaultPrefetchDelay * 3, &SourceTestExpect{ {"v2", "", DefaultPrefetchDelay * 3, &SourceTestExpect{err: "Invalid encoded public key",
Source: &Source{cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}, err: "Invalid encoded public key"}}, Source: &Source{name: "invalid public key", cacheTTL: DefaultPrefetchDelay * 3, prefetchDelay: DefaultPrefetchDelay}}},
} { } {
t.Run(tt.name, func(t *testing.T) { t.Run(tt.e.Source.name, func(t *testing.T) {
got, err := NewSource(d.xTransport, tt.e.Source.urls, tt.key, tt.e.cachePath, tt.v, tt.refresh) 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) checkResult(t, tt.e, got, err)
}) })
} }
@ -354,7 +353,7 @@ func TestNewSource(t *testing.T) {
for i := range d.sources { for i := range d.sources {
id, e := setupSourceTestCase(t, d, i, &cacheTest, downloadTest) id, e := setupSourceTestCase(t, d, i, &cacheTest, downloadTest)
t.Run("cache "+cacheTestName+", download "+downloadTestName+"/"+id, func(t *testing.T) { 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) checkResult(t, e, got, err)
}) })
} }