corteza icon indicating copy to clipboard operation
corteza copied to clipboard

Published 20 hours ago • verified publisher icon cortezaproject

Server panic on compose record list with conditional roles

Open jackmaninov opened this issue 8 months ago • 13 comments

Is there an existing issue for this?

  • [X] I have searched the existing issues

Version of Corteza

2023.9.6

Current Behavior

I've been seeing a server panic intermittently on corteza server over the last two versions (also on 2023.9.5) in my production setup. The panic usually occurs while a viewer is on a module's record list page and loading a decent number of records (more than 10). Usually the user is unaffected, the server simply records the panic in its log and proceeds.

However, today I had a user complaining about a persistent 500 error popping up in the lower-right hand corner of their screen, and their records would not load. Each time they reloaded the record list, the same panic is written to the log:

2024-05-29 17:32:31	runtime/debug.PrintStack()
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/runtime/debug/stack.go:16 +0x19
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/api/server.panicRecovery({0x2abfcf0, 0xc003eb17c0}, {0x2abd510, 0xc000dc8e00})
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/api/server/middleware.go:43 +0x111
2024-05-29 17:32:31	panic({0x1f70ce0, 0x3b40bb0})
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/runtime/panic.go:884 +0x212
2024-05-29 17:32:31	github.com/getsentry/sentry-go/http.(*Handler).recoverWithSentry(0xc003f48910, 0x189bc2b?, 0xc00408e500)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/getsentry/[email protected]/http/sentryhttp.go:117 +0xf0
2024-05-29 17:32:31	panic({0x1f70ce0, 0x3b40bb0})
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/runtime/panic.go:884 +0x212
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/types.(*Record).GetValue(0x0, {0xc0046bf1b0, 0x9}, 0x0)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/types/getters_setters.gen.go:401 +0x450
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/store/adapters/rdbms/dal.(*iterator).collectCursorValues(0xc001821380, {0x2ab3730, 0x0})
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/store/adapters/rdbms/dal/iterator.go:298 +0x1b4
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/store/adapters/rdbms/dal.(*iterator).More(0xc001821380, 0x1?, {0x2ab3730?, 0x0?})
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/store/adapters/rdbms/dal/iterator.go:72 +0xe8
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/dalutils.drainIterator({_, _}, {_, _}, _, {0x56b2549f4850001, 0x5179049fa000446, {0x0, 0x0}, 0x0, ...})
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/dalutils/records.go:188 +0x42b
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/dalutils.ComposeRecordsList({_, _}, {_, _}, _, {0x56b2549f4850001, 0x5179049fa000446, {0x0, 0x0}, 0x0, ...})
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/dalutils/records.go:41 +0x165
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/service.record.Find.func1({0x2abfd98, 0xc001715860}, 0xc0010ee460, 0xc00506f9a0, 0xc0010ee410, 0xc0010ee428, 0xc0010ee438, 0xc0010ee5b0)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/service/record.go:387 +0x236
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/service.record.Find({{0x2ac8130, 0xc00056da00}, {0x2ab37d0, 0xc000bbb770}, {0x2ad7fe0, 0xc000bbb890}, {0x2ab4108, 0xc00055a078}, {0x2b13d78, 0xc000756080}, ...}, ...)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/service/record.go:400 +0x175
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/rest.(*Record).List(0xc005007680, {0x2abfd98, 0xc001715860}, 0xc0050c31a0)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/rest/record.go:146 +0x36a
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/compose/rest/handlers.NewRecord.func2({0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/compose/rest/handlers/record.go:93 +0x16f
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x1?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/auth.HttpTokenValidator.func1.1({0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/auth/token_middleware.go:80 +0xba
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc005062c00?, {0x2abd510?, 0xc000dc8e00?}, 0xc00055daa0?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*ChainHandler).ServeHTTP(0x1f566e0?, {0x2abd510?, 0xc000dc8e00?}, 0xc00168e180?)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/chain.go:31 +0x2c
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).routeHTTP(0xc005007620, {0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:442 +0x216
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc0010eee20?, {0x2abd510?, 0xc000dc8e00?}, 0xc0010eee00?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).ServeHTTP(0xc005007620, {0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:71 +0x355
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).Mount.func1({0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:314 +0x19c
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x1f566e0?, {0x2abd510?, 0xc000dc8e00?}, 0xc0012865f0?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).routeHTTP(0xc005006420, {0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:442 +0x216
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc0010eefa0?, {0x2abd510?, 0xc000dc8e00?}, 0xc0010eef80?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).ServeHTTP(0xc005006420, {0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:71 +0x355
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).Mount.func1({0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:314 +0x19c
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x1f566e0?, {0x2abd510?, 0xc000dc8e00?}, 0xc001286500?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).routeHTTP(0xc0010c9f20, {0x2abd510, 0xc000dc8e00}, 0xc00408ec00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:442 +0x216
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x3dc59b8?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/auth.verifier.func1.1({0x2abd510, 0xc000dc8e00}, 0xc00408ea00)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/auth/token_middleware.go:42 +0x291
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x3dc59b8?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/api/server.contextLogger.func1.1({0x2abd510, 0xc000dc8e00}, 0xc00408e900)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/api/server/logger.go:28 +0x394
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x3dc59b8?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/api.DebugToContext.func1.1({0x2abd510, 0xc000dc8e00}, 0xc00408e800)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/api/debug.go:15 +0x151
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x2a9db38?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5/middleware.RequestID.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e700)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/middleware/request_id.go:76 +0x22d
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x2a9db38?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/api.RemoteAddrToContext.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e600)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/api/ipaddr.go:17 +0x16e
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc00408e600?, {0x2abd510?, 0xc000dc8e00?}, 0xc00408e600?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5/middleware.RealIP.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e600)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/middleware/realip.go:35 +0x9e
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfd98?, {0x2abd510?, 0xc000dc8e00?}, 0x3dc59b8?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/locale.DetectLanguage.func1.1({0x2abd510, 0xc000dc8e00}, 0xc00408e500)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/locale/http.go:26 +0x2ad
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc003f70a00?, {0x2abd510?, 0xc000dc8e00?}, 0xc00408e500?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/cors.(*Cors).Handler.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e500)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/[email protected]/cors.go:228 +0x1bd
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc0043004b0?, {0x2abd510?, 0xc000dc8e00?}, 0xb?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/getsentry/sentry-go/http.(*Handler).handle.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e400)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/getsentry/[email protected]/http/sentryhttp.go:103 +0x3c3
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc001714ba0?, {0x2abd510?, 0xc000dc8e00?}, 0xc0010ef800?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).ServeHTTP(0xc0010c9f20, {0x2abd510, 0xc000dc8e00}, 0xc00408e400)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:71 +0x355
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).Mount.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e400)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:314 +0x19c
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x1f566e0?, {0x2abd510?, 0xc000dc8e00?}, 0xc000140424?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).routeHTTP(0xc0010c9ec0, {0x2abd510, 0xc000dc8e00}, 0xc00408e400)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:442 +0x216
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0xc00506e3c0?, {0x2abd510?, 0xc000dc8e00?}, 0xc00408e400?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/cors.(*Cors).Handler.func1({0x2abd510, 0xc000dc8e00}, 0xc00408e400)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/[email protected]/cors.go:228 +0x1bd
2024-05-29 17:32:31	net/http.HandlerFunc.ServeHTTP(0x2abfcf0?, {0x2abd510?, 0xc000dc8e00?}, 0x3b40570?)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2109 +0x2f
2024-05-29 17:32:31	github.com/go-chi/chi/v5.(*Mux).ServeHTTP(0xc0010c9ec0, {0x2abd510, 0xc000dc8e00}, 0xc00153fe00)
2024-05-29 17:32:31		/home/runner/go/pkg/mod/github.com/go-chi/chi/[email protected]/mux.go:88 +0x310
2024-05-29 17:32:31	github.com/cortezaproject/corteza/server/pkg/api/server.(*demux).ServeHTTP(0xc000140470?, {0x2abd510?, 0xc000dc8e00}, 0xc00153fe00)
2024-05-29 17:32:31		/home/runner/work/corteza/corteza/server/pkg/api/server/demux.go:51 +0x113
2024-05-29 17:32:31	net/http.serverHandler.ServeHTTP({0xc0018f44b0?}, {0x2abd510, 0xc000dc8e00}, 0xc00153fe00)
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2947 +0x30c
2024-05-29 17:32:31	net/http.(*conn).serve(0xc0009f1ae0, {0x2abfd98, 0xc0002ab920})
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:1991 +0x607
2024-05-29 17:32:31	created by net/http.(*Server).Serve
2024-05-29 17:32:31		/opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:3102 +0x4db

The panics happen on the record lists of different modules, and looking at corteza/server/compose/types/getters_setters.gen.go:401 it seems the issue is while trying to read the createdAt field on a record, so I don't think the specifics of the module matter. However, the line that usually leads to the panic is /home/runner/work/corteza/corteza/server/compose/types/getters_setters.gen.go:409 which reads the ID field.

The issue does seem related to the number of records being fetched, as the user was able to get out of the situation and view their records by adding a new record. Amusingly enough, the problem was when they had a lucky 13 records; adding the 14th got past. There was only one other record of this module, owned by a different user, that wouldn't have been visible to the affected user. Some off by 1 issue?

There is nothing special about the modules that I've seen the error happening on, they two I'm sure of have 15 and 25 fields on them, respectively. What is special is that they're being listed to users with a conditional role (which is behaving as expected, not sure if it is related):

resource.ownedBy == userID || has(resource.values.authorizedEditors ?? [], userID)

Very stumped on this one, I'll need some guidance on what this could be related to and how I could attempt to generate a minimum reproducible case.

Expected Behavior

Records list as normal, no server panic

Steps To Reproduce

Not sure how I can reproduce this one, I'll need some guidance from the devs.

Environment and versions

Running under a kubernetes system with the following environment for corteza-server:


    ACTIONLOG_ENABLED: "true"                                                                                                              
    CORREDOR_ADDR: localhost:53051                                                                                                         
    CORREDOR_ADDR_INT: 0.0.0.0:53051                                                                                                       
    CORREDOR_ENABLED: "true"                                                                                                               
    CORREDOR_EXEC_CSERVERS_API_BASEURL_TEMPLATE: localhost:53051/api/{service}                                                             
    CORREDOR_EXEC_CSERVERS_API_HOST: localhost:53051/api                                                                                   
    CORREDOR_EXT_SEARCH_PATHS: /data                                                                                                       
    CORREDOR_LOG_ENABLED: "true"                                                                                                           
    CORREDOR_LOG_LEVEL: info                                                                                                               
    CORREDOR_LOG_PRETTY: "true"                                                                                                            
    DOMAIN: crm.mysite.com                                                                                                                 
    HTTP_SSL_TERMINATED: "true"                                                                                                            
    HTTP_WEBAPP_ENABLED: "true"                                                                                                            
    LOG_DEBUG: "true"                                                                                                                      
    LOG_LEVEL: debug                                                                                                                       
    RBAC_LOG: "false"                                                                                                                      
    UPGRADE_DEBUG: "true"                                                                                                                  
    VERSION: 2023.9.6                                                                                                                      
    WEBSOCKET_LOG_ENABLED: "true"


The corteza database is running on postgresql 14.8.0

Anything else?

No response

jackmaninov avatar May 29 '24 16:05 jackmaninov