Backend: Improve logging #369

Signed-off-by: Michael Mayer <michael@liquidbytes.net>
This commit is contained in:
Michael Mayer 2020-06-29 13:16:55 +02:00
parent 2a2b3cb523
commit 1c72f88e8c
13 changed files with 80 additions and 48 deletions

View file

@ -167,7 +167,7 @@ func (m *Photo) String() string {
return txt.Quote(m.OriginalName)
}
return "[unknown photo]"
return "(unknown)"
}
return "uid " + txt.Quote(m.PhotoUID)
@ -573,7 +573,7 @@ func (m *Photo) UpdateTitle(labels classify.Labels) error {
// TODO: User defined title format
if title := labels.Title(loc.Name()); title != "" {
log.Infof("photo: using label %s to create title for %s", txt.Quote(title), m.PhotoUID)
log.Debugf("photo: using label %s to create title for %s", txt.Quote(title), m.PhotoUID)
if loc.NoCity() || loc.LongCity() || loc.CityContains(title) {
m.SetTitle(fmt.Sprintf("%s / %s / %s", txt.Title(title), loc.CountryName(), m.TakenAt.Format("2006")), SrcAuto)
} else {
@ -598,7 +598,7 @@ func (m *Photo) UpdateTitle(labels classify.Labels) error {
knownLocation = true
if title := labels.Title(fileTitle); title != "" {
log.Infof("photo: using label %s to create title for %s", txt.Quote(title), m.PhotoUID)
log.Debugf("photo: using label %s to create title for %s", txt.Quote(title), m.PhotoUID)
if m.Place.NoCity() || m.Place.LongCity() || m.Place.CityContains(title) {
m.SetTitle(fmt.Sprintf("%s / %s / %s", txt.Title(title), m.Place.CountryName(), m.TakenAt.Format("2006")), SrcAuto)
} else {
@ -634,7 +634,7 @@ func (m *Photo) UpdateTitle(labels classify.Labels) error {
}
if m.PhotoTitle != oldTitle {
log.Infof("photo: changed title of %s to %s", m.PhotoUID, txt.Quote(m.PhotoTitle))
log.Debugf("photo: changed title of %s to %s", m.PhotoUID, txt.Quote(m.PhotoTitle))
}
return nil

View file

@ -33,7 +33,7 @@ func FirstOrCreatePhotoKeyword(m *PhotoKeyword) *PhotoKeyword {
if err := Db().Where("photo_id = ? AND keyword_id = ?", m.PhotoID, m.KeywordID).First(&result).Error; err == nil {
return &result
} else if err := m.Create(); err != nil {
log.Errorf("photo-keyword: %s", err)
// Already exists.
return nil
}

View file

@ -67,7 +67,7 @@ func FirstOrCreatePhotoLabel(m *PhotoLabel) *PhotoLabel {
if err := Db().Where("photo_id = ? AND label_id = ?", m.PhotoID, m.LabelID).First(&result).Error; err == nil {
return &result
} else if err := m.Create(); err != nil {
log.Errorf("photo-label: %s", err)
// Already exists.
return nil
}

View file

@ -2,6 +2,7 @@ package entity
import (
"errors"
"reflect"
"strings"
"time"
@ -92,14 +93,13 @@ func (m *Photo) EstimatePlace() {
}
}
// Maintain photo data, improve if possible.
func (m *Photo) Maintain() error {
// Optimize photo data, improve if possible.
func (m *Photo) Optimize() (updated bool, err error) {
if !m.HasID() {
return errors.New("photo: can't maintain, id is empty")
return false, errors.New("photo: can't maintain, id is empty")
}
checked := Timestamp()
m.CheckedAt = &checked
current := *m
m.EstimatePlace()
@ -123,5 +123,13 @@ func (m *Photo) Maintain() error {
m.PhotoQuality = m.QualityScore()
return UnscopedDb().Save(m).Error
checked := Timestamp()
if reflect.DeepEqual(*m, current) {
return false, m.Update("CheckedAt", &checked)
}
m.CheckedAt = &checked
return true, UnscopedDb().Save(m).Error
}

View file

@ -43,3 +43,20 @@ func TestPhoto_EstimateCountry(t *testing.T) {
assert.Equal(t, "Canada", m.CountryName())
})
}
func TestPhoto_Optimize(t *testing.T) {
t.Run("update", func(t *testing.T) {
photo := PhotoFixtures.Get("Photo19")
if updated, err := photo.Optimize(); err != nil {
t.Fatal(err)
} else if !updated {
t.Error("photo should be updated")
}
if updated, err := photo.Optimize(); err != nil {
t.Fatal(err)
} else if updated {
t.Error("photo should NOT be updated")
}
})
}

View file

@ -36,7 +36,7 @@ func Exif(fileName string) (data Data, err error) {
func (data *Data) Exif(fileName string) (err error) {
defer func() {
if e := recover(); e != nil {
err = fmt.Errorf("%s (exif metadata)", e)
err = fmt.Errorf("metadata: %s (exif panic)", e)
}
}()
@ -58,10 +58,10 @@ func (data *Data) Exif(fileName string) (err error) {
_, rawExif, err = sl.Exif()
if err != nil {
if err.Error() == "no exif data" {
return fmt.Errorf("no exif data in %s", txt.Quote(filepath.Base(fileName)))
if err.Error() == "no exif header" {
return fmt.Errorf("metadata: no exif header in %s", txt.Quote(filepath.Base(fileName)))
} else {
log.Warnf("exif: %s (parse jpeg)", err)
log.Warnf("metadata: %s (parse jpeg)", err)
}
} else {
parsed = true
@ -79,9 +79,9 @@ func (data *Data) Exif(fileName string) (err error) {
if err != nil {
if err.Error() == "file does not have EXIF" {
return fmt.Errorf("no exif data in %s", txt.Quote(filepath.Base(fileName)))
return fmt.Errorf("metadata: no exif header in %s", txt.Quote(filepath.Base(fileName)))
} else {
log.Warnf("exif: %s (parse png)", err)
log.Warnf("metadata: %s (parse png)", err)
}
} else {
parsed = true
@ -95,7 +95,7 @@ func (data *Data) Exif(fileName string) (err error) {
rawExif, err = exif.SearchFileAndExtractExif(fileName)
if err != nil {
return err
return fmt.Errorf("metadata: no exif header in %s", txt.Quote(filepath.Base(fileName)))
}
}
@ -132,7 +132,7 @@ func (data *Data) Exif(fileName string) (err error) {
valueString, err = ite.FormatFirst()
if err != nil {
log.Errorf("exif: %s", err.Error())
log.Errorf("metadata: %s (exif)", err.Error())
return nil
}
@ -291,7 +291,7 @@ func (data *Data) Exif(fileName string) (err error) {
data.Lng = float32(gi.Longitude.Decimal())
data.Altitude = gi.Altitude
} else {
log.Warnf("exif: %s (gps info)", err)
log.Warnf("metadata: %s (exif gps info)", err)
}
}
@ -324,14 +324,14 @@ func (data *Data) Exif(fileName string) (err error) {
data.TakenAt = data.TakenAtLocal
if loc, err := time.LoadLocation(data.TimeZone); err != nil {
log.Warnf("exif: unknown time zone %s", data.TimeZone)
log.Warnf("metadata: unknown time zone %s", data.TimeZone)
} else if tl, err := time.ParseInLocation("2006:01:02 15:04:05", takenAt, loc); err == nil {
data.TakenAt = tl.Round(time.Second).UTC()
} else {
log.Errorf("exif: %s", err.Error()) // this should never happen
log.Errorf("metadata: %s", err.Error()) // this should never happen
}
} else {
log.Warnf("exif: invalid time %s", takenAt)
log.Warnf("metadata: invalid time %s", takenAt)
}
}

View file

@ -104,7 +104,7 @@ func TestExif(t *testing.T) {
t.Fatal("err should NOT be nil")
}
assert.Equal(t, "no exif data in tweethog.png", err.Error())
assert.Equal(t, "metadata: no exif header in tweethog.png", err.Error())
})
t.Run("iphone_7.heic", func(t *testing.T) {
@ -219,7 +219,7 @@ func TestExif(t *testing.T) {
t.Fatal("err should NOT be nil")
}
assert.Equal(t, "no exif data in no-exif-data.jpg", err.Error())
assert.Equal(t, "metadata: no exif header in no-exif-data.jpg", err.Error())
})
t.Run("screenshot.png", func(t *testing.T) {
@ -255,7 +255,7 @@ func TestExif(t *testing.T) {
assert.Equal(t, 1, data.Orientation)
if err := data.JSON("testdata/orientation.json", "foo.jpg"); err != nil {
assert.EqualError(t, err, "meta: original name foo.jpg does not match orientation.jpg (json)")
assert.EqualError(t, err, "metadata: original name foo.jpg does not match orientation.jpg (json)")
} else {
t.Error("error expected when providing wrong orginal name")
}
@ -264,6 +264,6 @@ func TestExif(t *testing.T) {
t.Run("gopher-preview.jpg", func(t *testing.T) {
_, err := Exif("testdata/gopher-preview.jpg")
assert.EqualError(t, err, "no exif data in gopher-preview.jpg")
assert.EqualError(t, err, "metadata: no exif header in gopher-preview.jpg")
})
}

View file

@ -73,7 +73,7 @@ func GpsCoord(s string) float64 {
result, err := strconv.ParseFloat(s, 64)
if err != nil {
log.Debugf("meta: %s", err)
log.Debugf("metadata: %s", err)
}
return result

View file

@ -24,7 +24,7 @@ func JSON(jsonName, originalName string) (data Data, err error) {
func (data *Data) JSON(jsonName, originalName string) (err error) {
defer func() {
if e := recover(); e != nil {
err = fmt.Errorf("%s (json metadata)", e)
err = fmt.Errorf("metadata: %s (json panic)", e)
}
}()
@ -35,14 +35,14 @@ func (data *Data) JSON(jsonName, originalName string) (err error) {
jsonString, err := ioutil.ReadFile(jsonName)
if err != nil {
log.Warnf("meta: %s", err.Error())
log.Warnf("metadata: %s (json)", err.Error())
return fmt.Errorf("can't read %s (json)", txt.Quote(filepath.Base(jsonName)))
}
j := gjson.GetBytes(jsonString, "@flatten|@join")
if !j.IsObject() {
return fmt.Errorf("data is not an object in %s (json)", txt.Quote(filepath.Base(jsonName)))
return fmt.Errorf("metadata: data is not an object in %s (json)", txt.Quote(filepath.Base(jsonName)))
}
jsonValues := j.Map()
@ -52,7 +52,7 @@ func (data *Data) JSON(jsonName, originalName string) (err error) {
}
if fileName, ok := data.All["FileName"]; ok && fileName != "" && originalName != "" && fileName != originalName {
return fmt.Errorf("meta: original name %s does not match %s (json)", txt.Quote(originalName), txt.Quote(fileName))
return fmt.Errorf("metadata: original name %s does not match %s (json)", txt.Quote(originalName), txt.Quote(fileName))
}
v := reflect.ValueOf(data).Elem()
@ -101,7 +101,7 @@ func (data *Data) JSON(jsonName, originalName string) (err error) {
case bool:
fieldValue.SetBool(jsonValue.Bool())
default:
log.Warnf("meta: can't assign value of type %s to %s", t, tagValue)
log.Warnf("metadata: can't assign value of type %s to %s (json)", t, tagValue)
}
}
}
@ -127,11 +127,11 @@ func (data *Data) JSON(jsonName, originalName string) (err error) {
if !data.TakenAtLocal.IsZero() {
if loc, err := time.LoadLocation(data.TimeZone); err != nil {
log.Warnf("meta: unknown time zone %s", data.TimeZone)
log.Warnf("metadata: unknown time zone %s (json)", data.TimeZone)
} else if tl, err := time.ParseInLocation("2006:01:02 15:04:05", data.TakenAtLocal.Format("2006:01:02 15:04:05"), loc); err == nil {
data.TakenAt = tl.Round(time.Second).UTC()
} else {
log.Errorf("meta: %s", err.Error()) // this should never happen
log.Errorf("metadata: %s (json)", err.Error()) // this should never happen
}
}
}

View file

@ -43,6 +43,6 @@ func init() {
im = exif.NewIfdMapping()
if err := exif.LoadStandardIfds(im); err != nil {
log.Errorf("meta: %s", err.Error())
log.Errorf("metadata: %s", err.Error())
}
}

View file

@ -18,14 +18,14 @@ func XMP(fileName string) (data Data, err error) {
func (data *Data) XMP(fileName string) (err error) {
defer func() {
if e := recover(); e != nil {
err = fmt.Errorf("%s (xmp metadata)", e)
err = fmt.Errorf("metadata: %s (xmp panic)", e)
}
}()
doc := XmpDocument{}
if err := doc.Load(fileName); err != nil {
return fmt.Errorf("can't read %s (xmp)", txt.Quote(filepath.Base(fileName)))
return fmt.Errorf("metadata: can't read %s (xmp)", txt.Quote(filepath.Base(fileName)))
}
if doc.Title() != "" {

View file

@ -96,8 +96,7 @@ func TestMediaFile_Location(t *testing.T) {
location, err := mediaFile.Location()
assert.Error(t, err, "meta: no exif data")
assert.Error(t, err, "metadata: no exif header in Random.docx")
assert.Nil(t, location)
})
}

View file

@ -52,14 +52,17 @@ func (worker *Prism) Start() (err error) {
mutex.PrismWorker.Stop()
if err := recover(); err != nil {
log.Errorf("prism: %s [panic]", err)
log.Errorf("metadata: %s (prism worker panic)", err)
}
}()
log.Debugf("metadata: starting routine check")
done := make(map[string]bool)
limit := 50
offset := 0
optimized := 0
for {
photos, err := query.PhotosCheck(limit, offset)
@ -71,12 +74,12 @@ func (worker *Prism) Start() (err error) {
if len(photos) == 0 {
break
} else if offset == 0 {
log.Infof("prism: starting routine check")
}
for _, photo := range photos {
if mutex.PrismWorker.Canceled() {
return errors.New("prism: check canceled")
return errors.New("metadata: check canceled")
}
if done[photo.PhotoUID] {
@ -85,11 +88,16 @@ func (worker *Prism) Start() (err error) {
done[photo.PhotoUID] = true
worker.logError(photo.Maintain())
if updated, err := photo.Optimize(); err != nil {
log.Errorf("metadata: %s", err)
} else if updated {
optimized++
log.Debugf("metadata: optimized photo %s", photo.String())
}
}
if mutex.PrismWorker.Canceled() {
return errors.New("prism: check canceled")
return errors.New("metadata: check canceled")
}
offset += limit
@ -97,8 +105,8 @@ func (worker *Prism) Start() (err error) {
time.Sleep(100 * time.Millisecond)
}
if len(done) > 0 {
log.Infof("prism: checked %d photos", len(done))
if optimized > 0 {
log.Infof("metadata: optimized %d photos", optimized)
}
worker.logError(query.ResetPhotoQuality())