Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

No user avatars #13159

Closed
pboguslawski opened this issue Oct 15, 2020 · 14 comments
Closed

No user avatars #13159

pboguslawski opened this issue Oct 15, 2020 · 14 comments
Labels
Milestone

Comments

@pboguslawski
Copy link
Contributor

Gitea build from release/v1.13 and master with

[picture]
DISABLE_GRAVATAR        = true
ENABLE_FEDERATED_AVATAR = false

do not show avatars for users and throws internal server error (500) on avatar image get with log:

2020/10/15 14:24:39 Started GET /user/avatar/test/-1 for 127.0.0.1
2020/10/15 14:24:39 Completed GET /user/avatar/test/-1 302 Found in 2.687614ms
2020/10/15 14:24:39 ...n@v1.5.0/recovery.go:141:1() �[1;32m[I] [Macaron] PANIC: middleware render hasn't been registered
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/render.go:653 (0x117f128)
		renderNotRegistered: panic("middleware render hasn't been registered")
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/render.go:710 (0x117f47f)
		(*DummyRender).Error: renderNotRegistered()
	/myhome/code/src/github.com/go-gitea/gitea/routers/routes/routes.go:155 (0x2c60f99)
		storageHandler.func2: ctx.Error(500, err.Error())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:79 (0x11722a2)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:112 (0x1172443)
		(*Context).Next: c.run()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/recovery.go:161 (0x118a4d6)
		Recovery.func1: c.Next()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/logger.go:40 (0x1176e2f)
		LoggerInvoker.Invoke: invoke(params[0].(*Context), params[1].(*log.Logger))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:112 (0x1172443)
		(*Context).Next: c.run()
	/myhome/code/src/github.com/go-gitea/gitea/routers/routes/routes.go:106 (0x2c60060)
		RouterHandler.func1: ctx.Next()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:79 (0x11722a2)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/router.go:187 (0x118c09e)
		(*Router).Handle.func1: c.run()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/router.go:303 (0x1182bbf)
		(*Router).ServeHTTP: h(rw, req, p)
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/macaron.go:218 (0x11787f0)
		(*Macaron).ServeHTTP: m.Router.ServeHTTP(rw, req)
	/myhome/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141 (0x189aca1)
		ClearHandler.func1: h.ServeHTTP(w, r)
	/usr/lib/go-1.13/src/net/http/server.go:2007 (0x8af463)
		HandlerFunc.ServeHTTP: f(w, r)
	/usr/lib/go-1.13/src/net/http/server.go:2802 (0x8b3c6e)
		serverHandler.ServeHTTP: handler.ServeHTTP(rw, req)
	/usr/lib/go-1.13/src/net/http/server.go:1890 (0x8ae405)
		(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)
	/usr/lib/go-1.13/src/runtime/asm_amd64.s:1357 (0x46fda0)
		goexit: BYTE	$0x90	// NOP
2020/10/15 14:24:39 Started GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 for 127.0.0.1
2020/10/15 14:24:39 Completed GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 �[1;41m500 �[1;41mInternal Server Error in 1.648505ms

No such problem with org avatars with same config.

No such problem with user avatars with default settings:

[picture]
DISABLE_GRAVATAR        = false
ENABLE_FEDERATED_AVATAR = true
@zeripath
Copy link
Contributor

Are there any earlier logs? I wouldn't be surprised if there was some earlier information with an error for this.

This is likely to do with recently merged avatar minio PR.

@zeripath
Copy link
Contributor

//If we have matched and access to release or issue
fr, err := objStore.Open(rPath)
if err != nil {
ctx.Error(500, err.Error())
return
}

The error is appearing here because the ctx.Error handler isn't actually available when this objStorage is running.

Now the problem is that L153 here is returning an error that needs to be returned. The most likely is that the object does not exist.

Now that should be handled with 404 not a 500.

So we have two bugs:

  • This code needs to be tolerant of files not existing - and return 404.
  • This code needs to have some way of handling errors.

@zeripath
Copy link
Contributor

m.Use(storageHandler(setting.Avatar.Storage, "avatars", storage.Avatars))
m.Use(storageHandler(setting.RepoAvatar.Storage, "repo-avatars", storage.RepoAvatars))
m.Use(templates.HTMLRenderer())
mailer.InitMailRender(templates.Mailer())

My suspicion is that if we moved L211-L212 to after L214 we'd probably have the error reporting correctly instead of a panic.

@pboguslawski
Copy link
Contributor Author

Full log of one dashboard refresh from release/v1.13:

API server listening at: 127.0.0.1:2345
2020-10-15T15:02:57+02:00 info layer=debugger launching process with args: [/myhome/code/src/github.com/go-gitea/gitea/__debug_bin web]
2020-10-15T15:02:58+02:00 debug layer=debugger continuing
2020/10/15 15:02:58 cmd/web.go:108:runWeb() �[1;32m[I] Starting Gitea on PID: 27765
2020/10/15 15:02:58 ...dules/setting/git.go:91:newGit() �[1;32m[I] Git Version: 2.20.1, Wire Protocol Version 2 Enabled
2020/10/15 15:02:58 routers/init.go:127:GlobalInit() �[1;36m[T] AppPath: /myhome/code/src/github.com/go-gitea/gitea/__debug_bin
2020/10/15 15:02:58 routers/init.go:128:GlobalInit() �[1;36m[T] AppWorkPath: /myhome/code/src/github.com/go-gitea/gitea
2020/10/15 15:02:58 routers/init.go:129:GlobalInit() �[1;36m[T] Custom path: /myhome/code/src/github.com/go-gitea/gitea/custom
2020/10/15 15:02:58 routers/init.go:130:GlobalInit() �[1;36m[T] Log path: /myhome/code/src/github.com/go-gitea/gitea/log
2020/10/15 15:02:58 ...dules/setting/log.go:297:newLogService() �[1;32m[I] Gitea vdevelopment built with go1.13.1
2020/10/15 15:02:58 ...dules/setting/log.go:343:newLogService() �[1;32m[I] Gitea Log Mode: Console(Console:info)
2020/10/15 15:02:58 ...dules/setting/log.go:249:generateNamedLogger() �[1;32m[I] Macaron Log: Console(console:info)
2020/10/15 15:02:58 ...dules/setting/log.go:249:generateNamedLogger() �[1;32m[I] Router Log: Console(console:info)
2020/10/15 15:02:58 ...les/setting/cache.go:70:newCacheService() �[1;32m[I] Cache Service Enabled
2020/10/15 15:02:58 ...les/setting/cache.go:81:newCacheService() �[1;32m[I] Last Commit Cache Service Enabled
2020/10/15 15:02:58 ...s/setting/session.go:63:newSessionService() �[1;32m[I] Session Service Enabled
2020/10/15 15:02:59 routers/init.go:72:initDBEngine() �[1;32m[I] Beginning ORM engine initialization.
2020/10/15 15:02:59 routers/init.go:79:initDBEngine() �[1;32m[I] ORM engine initialization attempt #1/10...
2020/10/15 15:02:59 ....5/session_schema.go:25:Ping() �[1;32m[I] PING DATABASE sqlite3
2020/10/15 15:02:59 routers/init.go:142:GlobalInit() �[1;32m[I] ORM engine initialization successful!
2020/10/15 15:02:59 ...er/issues/indexer.go:142:func2() �[1;32m[I] PID 27765: Initializing Issue Indexer: bleve
2020/10/15 15:02:59 ...er/issues/indexer.go:221:func3() �[1;32m[I] Issue Indexer Initialization took 6.799092ms
2020/10/15 15:02:59 ...xer/stats/indexer.go:38:populateRepoIndexer() �[1;32m[I] Populating the repo stats indexer with existing repositories
2020/10/15 15:02:59 routers/init.go:171:GlobalInit() �[1;32m[I] SQLite3 Supported
2020/10/15 15:02:59 routers/init.go:53:checkRunMode() �[1;32m[I] Run Mode: Production
2020/10/15 15:03:00 cmd/web.go:163:runWeb() �[1;32m[I] Listen: http://0.0.0.0:3000
2020/10/15 15:03:00 cmd/web.go:166:runWeb() �[1;32m[I] LFS server enabled
2020/10/15 15:03:00 ...s/graceful/server.go:55:NewServer() �[1;32m[I] Starting new server: tcp:0.0.0.0:3000 on PID: 27765
2020/10/15 15:03:11 Started GET / for 127.0.0.1
2020/10/15 15:03:11 Completed GET / 200 OK in 16.249782ms
2020/10/15 15:03:11 Started GET /img/gitea-sm.png for 127.0.0.1
2020/10/15 15:03:11 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /img/gitea-sm.png
2020/10/15 15:03:11 Completed GET /img/gitea-sm.png 304 Not Modified in 185.18µs
2020/10/15 15:03:11 Started GET /user/avatar/test/-1 for 127.0.0.1
2020/10/15 15:03:11 Completed GET /user/avatar/test/-1 302 Found in 2.644854ms
2020/10/15 15:03:11 Started GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 for 127.0.0.1
2020/10/15 15:03:11 ...n@v1.5.0/recovery.go:141:1() �[1;32m[I] [Macaron] PANIC: middleware render hasn't been registered
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/render.go:653 (0x117f128)
		renderNotRegistered: panic("middleware render hasn't been registered")
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/render.go:710 (0x117f47f)
		(*DummyRender).Error: renderNotRegistered()
	/myhome/code/src/github.com/go-gitea/gitea/routers/routes/routes.go:155 (0x2c60f99)
		storageHandler.func2: ctx.Error(500, err.Error())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:79 (0x11722a2)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:112 (0x1172443)
		(*Context).Next: c.run()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/recovery.go:161 (0x118a4d6)
		Recovery.func1: c.Next()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/logger.go:40 (0x1176e2f)
		LoggerInvoker.Invoke: invoke(params[0].(*Context), params[1].(*log.Logger))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:112 (0x1172443)
		(*Context).Next: c.run()
	/myhome/code/src/github.com/go-gitea/gitea/routers/routes/routes.go:106 (0x2c60060)
		RouterHandler.func1: ctx.Next()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:79 (0x11722a2)
		ContextInvoker.Invoke: invoke(params[0].(*Context))
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:157 (0x11702ff)
		(*injector).fastInvoke: return f.Invoke(in)
	/myhome/go/pkg/mod/gitea.com/macaron/inject@v0.0.0-20190805023432-d4c86e31027a/inject.go:135 (0x116fc5c)
		(*injector).Invoke: return inj.fastInvoke(v, t, t.NumIn())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/context.go:121 (0x117259f)
		(*Context).run: vals, err := c.Invoke(c.handler())
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/router.go:187 (0x118c09e)
		(*Router).Handle.func1: c.run()
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/router.go:303 (0x1182bbf)
		(*Router).ServeHTTP: h(rw, req, p)
	/myhome/go/pkg/mod/gitea.com/macaron/macaron@v1.5.0/macaron.go:218 (0x11787f0)
		(*Macaron).ServeHTTP: m.Router.ServeHTTP(rw, req)
	/myhome/go/pkg/mod/github.com/gorilla/context@v1.1.1/context.go:141 (0x189aca1)
		ClearHandler.func1: h.ServeHTTP(w, r)
	/usr/lib/go-1.13/src/net/http/server.go:2007 (0x8af463)
		HandlerFunc.ServeHTTP: f(w, r)
	/usr/lib/go-1.13/src/net/http/server.go:2802 (0x8b3c6e)
		serverHandler.ServeHTTP: handler.ServeHTTP(rw, req)
	/usr/lib/go-1.13/src/net/http/server.go:1890 (0x8ae405)
		(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)
	/usr/lib/go-1.13/src/runtime/asm_amd64.s:1357 (0x46fda0)
		goexit: BYTE	$0x90	// NOP
2020/10/15 15:03:11 Completed GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 �[1;41m500 �[1;41mInternal Server Error in 1.908451ms
2020/10/15 15:03:11 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /css/index.css
2020/10/15 15:03:11 Started GET /css/index.css?v=759b74ce43947f5f4c91aeddc3e5bad3 for 127.0.0.1
2020/10/15 15:03:11 Completed GET /css/index.css?v=759b74ce43947f5f4c91aeddc3e5bad3 304 Not Modified in 180.321µs
2020/10/15 15:03:11 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /js/index.js
2020/10/15 15:03:11 Started GET /js/index.js?v=759b74ce43947f5f4c91aeddc3e5bad3 for 127.0.0.1
2020/10/15 15:03:11 Completed GET /js/index.js?v=759b74ce43947f5f4c91aeddc3e5bad3 304 Not Modified in 163.931µs
2020/10/15 15:03:12 Started GET /serviceworker.js for 127.0.0.1
2020/10/15 15:03:12 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /serviceworker.js
2020/10/15 15:03:12 Completed GET /serviceworker.js 304 Not Modified in 170.371µs
2020/10/15 15:03:12 Started GET /api/v1/repos/search?sort=updated&order=desc&uid=1&q=&page=1&mode= for 127.0.0.1
2020/10/15 15:03:12 Completed GET /api/v1/repos/search?sort=updated&order=desc&uid=1&q=&page=1&mode= 200 OK in 3.995314ms
2020/10/15 15:03:12 Started GET /api/v1/repos/search?sort=updated&order=desc&uid=1&q=&page=1&limit=15&mode=&archived=false for 127.0.0.1
2020/10/15 15:03:12 Started GET /api/v1/users/test/heatmap for 127.0.0.1
2020/10/15 15:03:12 Completed GET /api/v1/repos/search?sort=updated&order=desc&uid=1&q=&page=1&limit=15&mode=&archived=false 200 OK in 5.746235ms
2020/10/15 15:03:12 Completed GET /api/v1/users/test/heatmap 200 OK in 6.099418ms
2020/10/15 15:03:12 Started GET /user/events for 127.0.0.1
2020/10/15 15:03:13 Started GET /serviceworker.js for 127.0.0.1
2020/10/15 15:03:13 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /serviceworker.js
2020/10/15 15:03:13 Completed GET /serviceworker.js 304 Not Modified in 143.417µs

This problem was absent in earlier master we've been testing so probably errors comes from mentioned PR.

@zeripath
Copy link
Contributor

How are you running gitea?

@pboguslawski
Copy link
Contributor Author

Build in IDE (vscodium) from sources. Same problem when building using cli and make in other system. No such problems in same environments with earlier master versions so my env problably is not a problem. Can't you reproduce it in current master and avatar config as above?

@zeripath
Copy link
Contributor

zeripath commented Oct 15, 2020

As I said above the most likely root cause is that the avatar storage can't find the appropriate avatar but quite why that should be is another q. The reality is that you shouldn't be ending up looking up avatars unless they're in your db and thence should be stored on the disk.

The most likely cause for that issue is that the default avatar location is incorrect - (but it could be that it is in the right place but that your db has incorrect data.) This leads to another issue - there is no logging anywhere or admin readable configuration stating what the configuration is - so that also needs changing.

Now why does that cause the panic?

Well as I show above the ctx.Error occurs before that handler is even set - so we need to adjust this code. In fact we need to adjust it slightly more - because sending the err directly back to the user will leak information. So we need to log the error and display something else.

Now actually not being able to find a file shouldn't cause a 500 it should be a 404 but this isn't handled currently.

So we have 4 issues:

  1. This shouldn't cause a Panic
  2. This shouldn't be attempting to return the error and should log the error instead.
  3. There needs to be 404 for missing avatars
  4. We need some way of informing the admin of what the configuration is.

One potential 5th issue is that the default location is incorrect.

@zeripath
Copy link
Contributor

OK so here's a patch that fixes the first 2:

diff --git a/routers/routes/routes.go b/routers/routes/routes.go
index a09e53efc..c59188bdf 100644
--- a/routers/routes/routes.go
+++ b/routers/routes/routes.go
@@ -7,6 +7,7 @@ package routes
 import (
 	"bytes"
 	"encoding/gob"
+	"fmt"
 	"io"
 	"net/http"
 	"path"
@@ -125,7 +126,8 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor
 			rPath := strings.TrimPrefix(req.RequestURI, "/"+prefix)
 			u, err := objStore.URL(rPath, path.Base(rPath))
 			if err != nil {
-				ctx.Error(500, err.Error())
+				log.Error("Error whilst getting URL for %s %s. Error: %v", prefix, rPath, err)
+				ctx.Error(500, fmt.Sprintf("Error whilst getting URL for %s %s", prefix, rPath))
 				return
 			}
 			http.Redirect(
@@ -152,14 +154,16 @@ func storageHandler(storageSetting setting.Storage, prefix string, objStore stor
 		//If we have matched and access to release or issue
 		fr, err := objStore.Open(rPath)
 		if err != nil {
-			ctx.Error(500, err.Error())
+			log.Error("Error whilst opening %s %s. Error: %v", prefix, rPath, err)
+			ctx.Error(500, fmt.Sprintf("Error whilst opening %s %s", prefix, rPath))
 			return
 		}
 		defer fr.Close()
 
 		_, err = io.Copy(ctx.Resp, fr)
 		if err != nil {
-			ctx.Error(500, err.Error())
+			log.Error("Error whilst rendering %s %s. Error: %v", prefix, rPath, err)
+			ctx.Error(500, fmt.Sprintf("Error whilst rendering %s %s", prefix, rPath))
 			return
 		}
 	}
@@ -208,10 +212,9 @@ func NewMacaron() *macaron.Macaron {
 		},
 	))
 
+	m.Use(templates.HTMLRenderer())
 	m.Use(storageHandler(setting.Avatar.Storage, "avatars", storage.Avatars))
 	m.Use(storageHandler(setting.RepoAvatar.Storage, "repo-avatars", storage.RepoAvatars))
-
-	m.Use(templates.HTMLRenderer())
 	mailer.InitMailRender(templates.Mailer())
 
 	localeNames, err := options.Dir("locale")

@zeripath
Copy link
Contributor

Where are you avatars actually stored on your system in comparison to your Gitea data directory?

zeripath added a commit to zeripath/gitea that referenced this issue Oct 15, 2020
* The `.Use` of storageHandler before setting up the template renderer
causes a panic if there is an error to log.
* The error passed to `ctx.Error` in that case may contain sensitive
information and should not be rendered to the end user. We should
instead log the error and render a simple error message.
* There is no handling of missing avatars and this needs a 404. Minio
errors need to be mapped to standard golang errors such as
os.ErrNotExist.
* There is no logging when storage is set up.

Related go-gitea#13159

Signed-off-by: Andrew Thornton <art27@cantab.net>
@lunny lunny added the type/bug label Oct 16, 2020
techknowlogick pushed a commit that referenced this issue Oct 16, 2020
* The `.Use` of storageHandler before setting up the template renderer
causes a panic if there is an error to log.
* The error passed to `ctx.Error` in that case may contain sensitive
information and should not be rendered to the end user. We should
instead log the error and render a simple error message.
* There is no handling of missing avatars and this needs a 404. Minio
errors need to be mapped to standard golang errors such as
os.ErrNotExist.
* There is no logging when storage is set up.

Related #13159

Signed-off-by: Andrew Thornton <art27@cantab.net>
@pboguslawski
Copy link
Contributor Author

Just tested that problem still exists in current (12a1f91) master; gitea is compiled from sources and initialized from non existing data directory and absent app.ini with web install (only db set to sqlite and gitea admin user data entered - no other changes) that creates initial app.ini with sqlite3 as db and default DISABLE_GRAVATAR = false in app.ini. Data dir and app.ini are created by gitea from scratch.

After logging to admin account (created in install) with no problem with displaying this user avatar but it seems not served from local file because avatars folder is empty:

mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls
attachments/  avatars/  gitea.db  indexers/  lfs/  queues/  repo-avatars/
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls avatars
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls repo-avatars
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ 

Then org is created and its avatar is displayed correctly and PNG file "2" is created:

mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls avatars
2
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls repo-avatars
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ 

Then gitea is stopped and DISABLE_GRAVATAR is changed false -> true in app.ini and gitea is started; now admin avatar is not displayed (empty image frame) and debug console contains errors as below (PANIC is not generated in master seems this was fixed in the meantime)...

[...]
2020/10/16 09:09:17 Started GET /user/avatar/test/-1 for 127.0.0.1
2020/10/16 09:09:17 Started GET /user/avatar/fsdsdfsd/-1 for 127.0.0.1
2020/10/16 09:09:17 Completed GET /user/avatar/test/-1 302 Found in 2.459082ms
2020/10/16 09:09:17 Completed GET /user/avatar/fsdsdfsd/-1 302 Found in 3.822325ms
2020/10/16 09:09:17 Started GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 for 127.0.0.1
2020/10/16 09:09:17 ...ers/routes/routes.go:168:func2() �[1;31m[E] Error whilst opening avatars 7112ca6ffcdbc82b1a4735aec33678c6. Error: open /myhome/code/src/github.com/go-gitea/gitea/data/avatars/7112ca6ffcdbc82b1a4735aec33678c6: no such file or directory
2020/10/16 09:09:17 Completed GET /avatars/7112ca6ffcdbc82b1a4735aec33678c6 �[1;41m500 �[1;41mInternal Server Error in 264.645µs
2020/10/16 09:09:17 Started GET /avatars/2 for 127.0.0.1
2020/10/16 09:09:17 Completed GET /avatars/2 200 OK in 281.262µs
2020/10/16 09:09:18 Started GET /serviceworker.js for 127.0.0.1
2020/10/16 09:09:18 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /serviceworker.js
2020/10/16 09:09:18 Completed GET /serviceworker.js 304 Not Modified in 140.382µs
2020/10/16 09:09:18 Started GET /api/v1/repos/search?sort=updated&order=desc&uid=2&q=&page=1&mode= for 127.0.0.1
2020/10/16 09:09:18 Started GET /api/v1/repos/search?sort=updated&order=desc&uid=2&q=&page=1&limit=15&mode=&archived=false for 127.0.0.1
2020/10/16 09:09:18 Started GET /api/v1/users/fsdsdfsd/heatmap for 127.0.0.1
2020/10/16 09:09:18 Completed GET /api/v1/repos/search?sort=updated&order=desc&uid=2&q=&page=1&mode= 200 OK in 2.940192ms
2020/10/16 09:09:18 Completed GET /api/v1/repos/search?sort=updated&order=desc&uid=2&q=&page=1&limit=15&mode=&archived=false 200 OK in 3.572757ms
2020/10/16 09:09:18 Completed GET /api/v1/users/fsdsdfsd/heatmap 200 OK in 3.034535ms
2020/10/16 09:09:18 Started GET /user/events for 127.0.0.1
2020/10/16 09:09:19 Started GET /serviceworker.js for 127.0.0.1
2020/10/16 09:09:19 ...les/public/public.go:156:handle() �[1;32m[I] [Macaron] [Static] Serving /serviceworker.js
2020/10/16 09:09:19 Completed GET /serviceworker.js 304 Not Modified in 189.525µs

...and no avatar file seems present:

mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls avatars
2
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls repo-avatars
mydevhost:~/code/src/github.com/go-gitea/gitea/data$ 

Problem does not depend on ENABLE_FEDERATED_AVATAR value (problem exist when true or false); only DISABLE_GRAVATAR = true seems to generate this problem.

Tested that problem does NOT exist in 93f7525 and user avatar is created correctly in the same environment with DISABLE_GRAVATAR = true:

mydevhost:~/code/src/github.com/go-gitea/gitea/data$ ls avatars
2  7112ca6ffcdbc82b1a4735aec33678c6

Tested that problem DOES exits in 80a6b0f (and this version throws PANIC in debug console).

Conclusions:

  • problem occurs when DISABLE_GRAVATAR = true,
  • org avatars are not affected, only user avatars (generated automatically - didn't check user avatars uploaded manually),
  • problem was introduced in 80a6b0f (93f7525 is its parent and problem does not exits there),
  • problem still exists in current (12a1f91) master and probably in release/v1.13 also so fix should be applied to both.

@zeripath
Copy link
Contributor

The reason why the panic is no longer there is because of the linked PR #13164 and its purpose was not to fix your problem but to help with debugging it.

So one thing that #13164 does is actually put a lot more logging in to inform users where Gitea is looking for, for example you should now see in your logs at start-up:

Storage Start-up Logs
2020/10/16 09:38:16 ...s/storage/storage.go:151:initAttachments() [I] Initialising Attachment storage with type: 
2020/10/16 09:38:16 ...les/storage/local.go:44:NewLocalStorage() [I] Creating new Local Storage at /home/andrew/src/go/gitea/data/attachments
2020/10/16 09:38:16 ...s/storage/storage.go:145:initAvatars() [I] Initialising Avatar storage with type: 
2020/10/16 09:38:16 ...les/storage/local.go:44:NewLocalStorage() [I] Creating new Local Storage at /home/andrew/src/go/gitea/data/avatars
2020/10/16 09:38:16 ...s/storage/storage.go:163:initRepoAvatars() [I] Initialising Repository Avatar storage with type: 
2020/10/16 09:38:16 ...les/storage/local.go:44:NewLocalStorage() [I] Creating new Local Storage at /home/andrew/src/go/gitea/data/repo-avatars
2020/10/16 09:38:16 ...s/storage/storage.go:157:initLFS() [I] Initialising LFS storage with type: 
2020/10/16 09:38:16 ...les/storage/local.go:44:NewLocalStorage() [I] Creating new Local Storage at /home/andrew/src/go/gitea/data/lfs

which tells you where the storage is being created. But it also added logging when there is an error, which you have given me here:

2020/10/16 09:09:17 ...ers/routes/routes.go:168:func2() �[1;31m[E] Error whilst opening avatars 7112ca6ffcdbc82b1a4735aec33678c6. Error: open /myhome/code/src/github.com/go-gitea/gitea/data/avatars/7112ca6ffcdbc82b1a4735aec33678c6: no such file or directory

From which I can work out that Gitea has determined that the place to store avatars is:

/myhome/code/src/github.com/go-gitea/gitea/data/avatars

(interestingly the 404 code doesn't appear to be working in #13164)

Now a link that would point to this should only be being made if and only if there is a custom or generated avatar in place.

func (u *User) RealSizedAvatarLink(size int) string {
if u.ID == -1 {
return base.DefaultAvatarLink()
}
switch {
case u.UseCustomAvatar:
if u.Avatar == "" {
return base.DefaultAvatarLink()
}
return setting.AppSubURL + "/avatars/" + u.Avatar
case setting.DisableGravatar, setting.OfflineMode:
if u.Avatar == "" {
if err := u.GenerateRandomAvatar(); err != nil {
log.Error("GenerateRandomAvatar: %v", err)
}
}
return setting.AppSubURL + "/avatars/" + u.Avatar
}
return base.SizedAvatarLink(u.AvatarEmail, size)
}

OK, so the question I asked earlier still applies:

  • Where were avatars to stored on your system?
  • Is /myhome/code/src/github.com/go-gitea/gitea/data/avatars the correct one?
  • Were they being stored somewhere else in 93f7525?

If those are the same place - then what did you previously see?

@zeripath
Copy link
Contributor

By the way it appears that your logging is a little weird. What is its configuration? If you don't want colored logs set COLORIZE=false in [log]

@pboguslawski
Copy link
Contributor Author

pboguslawski commented Oct 16, 2020

Where were avatars to stored on your system?

All not mentioned app.ini/gitea settings were default during above tests. Above ls outputs clearly show data/avatars as folder with avatars.

Is /myhome/code/src/github.com/go-gitea/gitea/data/avatars the correct one?

Yes.

Were they being stored somewhere else in 93f7525?

No. Avatars appeared in /myhome/code/src/github.com/go-gitea/gitea/data/avatars as in mentioned ls output.

If those are the same place - then what did you previously see?

When problem occurs, folder avatars does not contain 7112ca6ffcdbc82b1a4735aec33678c6 which is avatar file that should be automatically generated by gitea when DISABLE_GRAVATAR = true but is not. Please see my ls outputs above.

pboguslawski added a commit to ibpl/gitea that referenced this issue Oct 21, 2020
This mod fixes problem with initial avatar autogeneration and
avatar autogneration after deleting previous avatar.

Related: go-gitea#13159
Fixes: 80a6b0f
Author-Change-Id: IB#1105243
pboguslawski added a commit to ibpl/gitea that referenced this issue Oct 21, 2020
This mod fixes problem with initial avatar autogeneration and
avatar autogneration after deleting previous avatar.

Related: go-gitea#13159
Fixes: 80a6b0f
Author-Change-Id: IB#1105243
@pboguslawski
Copy link
Contributor Author

Problem is caused by non empty user.Avatar value that is generated on user create, before random avatar generation. Changed random generation procedure does not generate avatar if user.Avatar is non empty. More - deleting Avatar also don't make user.Avatar empty string.

Fix

#13233

works for us for both problems.

lafriks pushed a commit that referenced this issue Oct 23, 2020
This mod fixes problem with initial avatar autogeneration and
avatar autogneration after deleting previous avatar.

Related: #13159
Fixes: 80a6b0f
Author-Change-Id: IB#1105243
@lafriks lafriks added this to the 1.13.0 milestone Oct 23, 2020
@lafriks lafriks closed this as completed Oct 23, 2020
aswild pushed a commit to aswild/gitea that referenced this issue Oct 25, 2020
This mod fixes problem with initial avatar autogeneration and
avatar autogneration after deleting previous avatar.

Related: go-gitea#13159
Fixes: 80a6b0f
Author-Change-Id: IB#1105243
lafriks pushed a commit that referenced this issue Oct 26, 2020
This mod fixes problem with initial avatar autogeneration and
avatar autogneration after deleting previous avatar.

Related: #13159
Fixes: 80a6b0f
Author-Change-Id: IB#1105243
@go-gitea go-gitea locked and limited conversation to collaborators Nov 24, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

4 participants