Unusable after upgrade to 5.25.1

Troubleshooting
1

Summary

After upgrading to 5.25.1, clients can’t edit, or reply.

Steps to reproduce

Server: Ubuntu 18.04.4 LTS, proxy’d behind nginx
Clients: Mostly 4.5.2 on Mac, but also web via Firefox, mobile on iOS and Android

Expected behavior

Reply to a thread times out, providing the “Retry” UI. Clicking “Retry” times out.

Clicking Edit on a post does nothing.

Some clients are unable to post new messages but continue getting other people’s posts.

All clients in question refreshed and/or restarted their client software with no difference in behaviour.

Observed behavior

Replies, editing, posting (for some people), all don’t work.

We reverted to 5.21.0 and everything works fine.

We had the same issue with 5.24.1, which we also reverted.

2

@Taffer What Mattermost log errors do you see when the issue occurs?

1 Like
3

@Taffer can we see you logs?

Also check you mattermost permission. wrong permission broke mine.

1 Like
4

Hi, @Taffer

On top of the request for information from @amy.blais and @moebius, it will be good if you can also check on the Network tab of the View > Developer Tools for Current Server on the desktop app level. In Firefox, you can refer to the steps in HAR Analyzer for more details.

image
image2880×1800 389 KB

Perhaps we can shed more light on top of the mattermost.log file too.

May I know which upgrade documentation you referred to? Did you go through every step without missing out on any?

Also, any configuration changes done on the server / NGINX level after the upgrade?

1 Like
5

Thanks folks, here’s some additional information:

Here’s the timeline:

UTC is +4 from Eastern, so 10AM = 2PM, 11AM = 3PM

2020-07-31 10:30AM - upgrade started
           10:49AM - trouble loading chats
           10:51AM - can't edit
           10:56AM - can't reply
           11:01AM - reply eventually results in "someone deleted the message you commented on"
           11:06AM - down for revert

And here are the contents of mattermost.log starting when I shut down the server to perform the upgrade until I shut it down again to revert:

{"level":"info","ts":1596205821.248324,"caller":"jobs/workers.go:184","msg":"Stopped workers"}
{"level":"info","ts":1596205821.2626688,"caller":"jobs/schedulers.go:145","msg":"Stopping schedulers."}
{"level":"info","ts":1596205821.2627118,"caller":"jobs/schedulers.go:77","msg":"Schedulers stopped."}
{"level":"info","ts":1596205821.2741547,"caller":"sqlstore/supplier.go:916","msg":"Closing SqlStore"}
{"level":"info","ts":1596205821.3173385,"caller":"app/server.go:414","msg":"Server stopped"}
{"level":"info","ts":1596206131.5591407,"caller":"utils/i18n.go:83","msg":"Loaded system translations","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"level":"info","ts":1596206131.5718052,"caller":"app/server_app_adapters.go:58","msg":"Server is initializing..."}
{"level":"info","ts":1596206131.5749965,"caller":"sqlstore/supplier.go:227","msg":"Pinging SQL","database":"master"}
{"level":"warn","ts":1596206131.636173,"caller":"sqlstore/upgrade.go:200","msg":"Attempting to upgrade the database schema version","current_version":"5.24.0","new_version":"5.25.0"}
{"level":"warn","ts":1596206131.6376688,"caller":"sqlstore/upgrade.go:195","msg":"The database schema version has been upgraded","version":"5.25.0"}
{"level":"info","ts":1596206131.7685926,"caller":"app/license.go:40","msg":"License key from https://mattermost.com required to unlock enterprise features."}
{"level":"info","ts":1596206131.7742198,"caller":"mlog/log.go:167","msg":"Starting up plugins"}
{"level":"info","ts":1596206131.7742925,"caller":"app/plugin.go:202","msg":"Syncing plugins from the file store"}
{"level":"warn","ts":1596206131.7762866,"caller":"app/plugin.go:222","msg":"Skipping sync for unmanaged plugin","plugin_id":"rssfeed"}
{"level":"warn","ts":1596206131.7763255,"caller":"app/plugin.go:222","msg":"Skipping sync for unmanaged plugin","plugin_id":"ca.taffer.mm-quotebot"}
{"level":"warn","ts":1596206131.777314,"caller":"app/plugin.go:222","msg":"Skipping sync for unmanaged plugin","plugin_id":"ca.taffer.mm-rolly"}
{"level":"warn","ts":1596206131.7773712,"caller":"app/plugin.go:222","msg":"Skipping sync for unmanaged plugin","plugin_id":"matttermost-plugin-newchannelnotify"}
{"level":"warn","ts":1596206131.7774174,"caller":"app/plugin.go:222","msg":"Skipping sync for unmanaged plugin","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"info","ts":1596206131.8743732,"caller":"app/plugin.go:262","msg":"Syncing plugin from file store","bundle":"plugins/com.github.moussetc.mattermost.plugin.spoiler.tar.gz"}
{"level":"info","ts":1596206131.8744094,"caller":"app/plugin.go:262","msg":"Syncing plugin from file store","bundle":"plugins/com.github.matterpoll.matterpoll.tar.gz"}
{"level":"info","ts":1596206131.8744392,"caller":"app/plugin.go:262","msg":"Syncing plugin from file store","bundle":"plugins/com.github.moussetc.mattermost.plugin.giphy.tar.gz"}
{"level":"info","ts":1596206135.5373168,"caller":"mlog/sugar.go:19","msg":"Plugin loaded","plugin_id":"matttermost-plugin-newchannelnotify"}
{"level":"info","ts":1596206135.548195,"caller":"mlog/sugar.go:19","msg":"Heartbeat time = \u001e","plugin_id":"rssfeed"}
{"level":"info","ts":1596206135.5485132,"caller":"mlog/sugar.go:19","msg":"Heartbeat","plugin_id":"rssfeed"}
{"level":"info","ts":1596206135.549638,"caller":"app/server.go:273","msg":"Current version is 5.25.0 (5.25.1/Thu Jul 23 20:08:58 UTC 2020/7c21fabef8a03c0e130da73cd8419f263c876e32/210a06c086d933076c6a7e6adb5da122f5c8d367)","current_version":"5.25.0","build_number":"5.25.1","build_date":"Thu Jul 23 20:08:58 UTC 2020","build_hash":"7c21fabef8a03c0e130da73cd8419f263c876e32","build_hash_enterprise":"210a06c086d933076c6a7e6adb5da122f5c8d367"}
{"level":"info","ts":1596206135.5496988,"caller":"app/server.go:282","msg":"Enterprise Build","enterprise_build":true}
{"level":"info","ts":1596206135.5497408,"caller":"app/server.go:288","msg":"Printing current working","directory":"/opt/mattermost"}
{"level":"info","ts":1596206135.549766,"caller":"app/server.go:289","msg":"Loaded config","source":"file:///opt/mattermost/config/config.json"}
{"level":"warn","ts":1596206135.5497878,"caller":"app/server.go:769","msg":"Your push notification server is configured with HTTP. For improved security, update to HTTPS in your configuration."}
{"level":"info","ts":1596206136.3389513,"caller":"sqlstore/post_store.go:1571","msg":"Post.Message has size restrictions","max_characters":16383,"max_bytes":65535}
{"level":"info","ts":1596206136.7126331,"caller":"jobs/workers.go:73","msg":"Starting workers"}
{"level":"info","ts":1596206136.7127216,"caller":"bleveengine/bleve.go:267","msg":"UpdateConf Bleve"}
{"level":"info","ts":1596206136.7133904,"caller":"jobs/schedulers.go:74","msg":"Starting schedulers."}
{"level":"info","ts":1596206136.7140167,"caller":"app/license.go:40","msg":"License key from https://mattermost.com required to unlock enterprise features."}
{"level":"info","ts":1596206136.720859,"caller":"app/web_hub.go:83","msg":"Starting websocket hubs","number_of_hubs":12}
{"level":"info","ts":1596206136.7332625,"caller":"app/server.go:525","msg":"Starting Server..."}
{"level":"info","ts":1596206136.7336795,"caller":"app/server.go:594","msg":"Server is listening on 127.0.0.1:8065","address":"127.0.0.1:8065"}
{"level":"info","ts":1596206136.733734,"caller":"commands/server.go:106","msg":"Sending systemd READY notification."}
{"level":"error","ts":1596206162.5498953,"caller":"mlog/log.go:175","msg":"Invalid MFA token.","path":"/api/v4/users/login","request_id":"o8xg5f4irfnpxf59xeg1763sce","ip_addr":"172.31.5.52","user_id":"","method":"POST","err_where":"ValidateToken","http_code":401,"err_details":"invalid code"}
{"level":"info","ts":1596206178.262127,"caller":"bleveengine/bleve.go:267","msg":"UpdateConf Bleve"}
{"level":"error","ts":1596206209.311168,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"1uckomoqj78wj8zoy4ptbnw5oc","ip_addr":"172.31.5.52","user_id":"gxr5d8h8cibstmhx9yigzatu8h","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206224.374323,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"89jm18ednfyiujqxegj979ia8w","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206231.084806,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"xf7yw5xxabbn3c16cdbc9s9sxa","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206236.1448324,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"5obxsps9opb4jnwr9q1txsx7pa","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206248.8215399,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"6jmued3nn7brtniku8jo3iff1w","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206312.0868998,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"unc97gnkbfg4im4kbp7p9ay36r","ip_addr":"172.31.5.52","user_id":"eijx5yg4g7nt5e694ouxsi5u4c","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206374.2761185,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"amna83u3z3gn98e48emx9f1cpy","ip_addr":"172.31.5.52","user_id":"agwpi7x6ubrbdfg84rtc7qi9xh","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206379.2702336,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"bpih6ueinpyfukr4tq918impfc","ip_addr":"172.31.5.52","user_id":"xt34pnchajbp8mhje7bp36sreo","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206614.626759,"caller":"mlog/log.go:175","msg":"Rejected post since another client is making the same request.","path":"/api/v4/posts","request_id":"p138884sqjfntetybnmssxwebe","ip_addr":"172.31.5.52","user_id":"ugm35inno3fo9ebwpq3wc4mhjr","method":"POST","err_where":"deduplicateCreatePost","http_code":500,"err_details":""}
{"level":"error","ts":1596206655.425116,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"trjdtu6abtnwtexf4k1di6j1ma","ip_addr":"172.31.5.52","user_id":"ugm35inno3fo9ebwpq3wc4mhjr","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596206767.1810594,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"cawbr16jrf8ciq3ayhima9b87o","ip_addr":"172.31.5.52","user_id":"ugm35inno3fo9ebwpq3wc4mhjr","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596206813.239033,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"914c6dr15bfk3e8or59egpdwio","ip_addr":"172.31.5.52","user_id":"agwpi7x6ubrbdfg84rtc7qi9xh","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596206959.1807117,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"nj1mhmp663dp8qxoufc53inony","ip_addr":"172.31.5.52","user_id":"bzaqfso85pybzqq48iky3di8ec","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596206985.5481422,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"zewnk174a3n5mqeztt1inzjpjy","ip_addr":"172.31.5.52","user_id":"bzaqfso85pybzqq48iky3di8ec","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"info","ts":1596207039.4204545,"caller":"mlog/sugar.go:19","msg":"Heartbeat","plugin_id":"rssfeed"}
{"level":"error","ts":1596207048.6016877,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"giaon6979inytf4pou9io6rkrw","ip_addr":"172.31.5.52","user_id":"bzaqfso85pybzqq48iky3di8ec","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207379.3575451,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"3i17xuabi3ygub6jitrrfbo4ge","ip_addr":"172.31.5.52","user_id":"ugm35inno3fo9ebwpq3wc4mhjr","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207465.381316,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"scscj13dipntpysw1riatkrkga","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207468.5496376,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"rkpjgbqbkjn8mfkbi8wsasy9ba","ip_addr":"172.31.5.52","user_id":"f7qpa88t7fyo9k16o3mnaryhfc","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207473.120355,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"ndf93tts3pdo9rissdfyem94nw","ip_addr":"172.31.5.52","user_id":"rz81dfzgm7rgb89dc79dfxj1jw","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207489.9103491,"caller":"mlog/log.go:175","msg":"Rejected post since another client is making the same request.","path":"/api/v4/posts","request_id":"637hoiukuprxzmi5g191z1451e","ip_addr":"172.31.5.52","user_id":"fntu4aw5ufgg5mqx3ahbz4zobr","method":"POST","err_where":"deduplicateCreatePost","http_code":500,"err_details":""}
{"level":"error","ts":1596207491.8886714,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"nfgtpihse7guf81kf7qopgr97o","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207491.9337296,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"j3r1yjyz5tbfxktsfsrzhktjph","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207492.279183,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"neebirg4fpbmbpb7wxa6xgufnw","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207492.3417437,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"ue4gpu4d1brtirzyk56owiay9o","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207492.3484297,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"wrwbrtspr78t9x1pqf5r9nda7a","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207492.3882208,"caller":"mlog/log.go:175","msg":"Invalid or missing name parameter in request URL.","path":"/api/v4/emoji/autocomplete","request_id":"5p35nb51gp8x7mrokcn5pdfi8e","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"GET","err_where":"Context","http_code":400,"err_details":""}
{"level":"error","ts":1596207492.4995542,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"yt74989p67f49jhfm1fpzaqefy","ip_addr":"172.31.5.52","user_id":"agwpi7x6ubrbdfg84rtc7qi9xh","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596207532.362217,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"dp61skxeob8z9gmqarzmoiopyy","ip_addr":"172.31.5.52","user_id":"9dbtyg199bd98ftt3kamzpaoxa","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207538.1290603,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"d7sqeuijnpbn3qefrdh5gzs7ny","ip_addr":"172.31.5.52","user_id":"fntu4aw5ufgg5mqx3ahbz4zobr","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207563.305936,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"1waxrpwpf3yj3no3zck75hne6y","ip_addr":"172.31.5.52","user_id":"y3see9ger3bdukq5k5k19u68ne","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207568.4368727,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"jqybfbn1utr5dfomyq3498u6sw","ip_addr":"172.31.5.52","user_id":"4993r9ags7dg5fu7ryqryiqxee","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207653.6906521,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"ra5uh8hwqjd1tq38139kjshyra","ip_addr":"172.31.5.52","user_id":"rz81dfzgm7rgb89dc79dfxj1jw","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207680.0162363,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"8yfx88supb8a7dsotsq8epahtw","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596207785.9865592,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"ox7w3sctkbnb7nqzu63dfecprr","ip_addr":"172.31.5.52","user_id":"bzaqfso85pybzqq48iky3di8ec","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207789.6291344,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"at6tcpsphpyh5fdcf8ym5dca9h","ip_addr":"172.31.5.52","user_id":"fntu4aw5ufgg5mqx3ahbz4zobr","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1596207808.643565,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"nkhqfodtotnr5g4z6uemxn1xer","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"error","ts":1596207816.36193,"caller":"mlog/log.go:175","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"jwudmq769tf1p8edwxg3yokcza","ip_addr":"172.31.5.52","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"info","ts":1596207940.9760938,"caller":"mlog/sugar.go:19","msg":"Heartbeat","plugin_id":"rssfeed"}
{"level":"error","ts":1596207950.878144,"caller":"mlog/log.go:175","msg":"Unable to get post counts.","path":"/api/v4/analytics/old","request_id":"bn19qd4eriytuxfpg56crid9zh","ip_addr":"172.31.5.52","user_id":"agwpi7x6ubrbdfg84rtc7qi9xh","method":"GET","err_where":"SqlPostStore.AnalyticsPostCount","http_code":500,"err_details":"pq: canceling statement due to user request"}
{"level":"info","ts":1596208044.146182,"caller":"app/server.go:416","msg":"Stopping Server..."}
{"level":"info","ts":1596208044.146243,"caller":"app/web_hub.go:130","msg":"stopping websocket hub connections"}
{"level":"info","ts":1596208044.3970883,"caller":"app/plugin.go:279","msg":"Shutting down plugins"}
{"level":"error","ts":1596208044.3971782,"caller":"mlog/log.go:175","msg":"RPC call OnDeactivate to plugin failed.","plugin_id":"ca.taffer.mm-quotebot","error":"connection is shut down"}
{"level":"error","ts":1596208044.397194,"caller":"mlog/log.go:175","msg":"RPC call OnDeactivate to plugin failed.","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","error":"connection is shut down"}
{"level":"error","ts":1596208044.3972032,"caller":"mlog/log.go:175","msg":"RPC call OnDeactivate to plugin failed.","plugin_id":"com.github.matterpoll.matterpoll","error":"connection is shut down"}
{"level":"warn","ts":1596208044.664223,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"matttermost-plugin-newchannelnotify","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6656337,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"ca.taffer.mm-quotebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6656518,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"matttermost-plugin-newchannelnotify"}
{"level":"warn","ts":1596208044.6656632,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"ca.taffer.mm-quotebot"}
{"level":"warn","ts":1596208044.664038,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"com.github.moussetc.mattermost.plugin.spoiler","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6656682,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"github","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6657104,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"github"}
{"level":"warn","ts":1596208044.6656804,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"com.github.moussetc.mattermost.plugin.spoiler"}
{"level":"warn","ts":1596208044.6461034,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"com.github.matterpoll.matterpoll","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6465063,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6657376,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"com.github.matterpoll.matterpoll"}
{"level":"warn","ts":1596208044.665744,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"com.github.scottleedavis.mattermost-plugin-remind"}
{"level":"warn","ts":1596208044.646112,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"mattermost-autolink","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.665755,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"com.github.moussetc.mattermost.plugin.giphy","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.665771,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"com.github.moussetc.mattermost.plugin.giphy"}
{"level":"warn","ts":1596208044.6657603,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"mattermost-autolink"}
{"level":"warn","ts":1596208044.647024,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"rssfeed","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6657856,"caller":"plugin/hclog_adapter.go:69","msg":"error closing client during Kill","plugin_id":"com.mattermost.welcomebot","wrapped_extras":"errconnection is shut down"}
{"level":"warn","ts":1596208044.6657953,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"rssfeed"}
{"level":"warn","ts":1596208044.6657996,"caller":"plugin/hclog_adapter.go:71","msg":"plugin failed to exit gracefully","plugin_id":"com.mattermost.welcomebot"}
{"level":"warn","ts":1596208045.9525564,"caller":"app/server.go:400","msg":"Unable to shutdown server","error":"context deadline exceeded"}
{"level":"info","ts":1596208046.5437195,"caller":"jobs/workers.go:205","msg":"Stopped workers"}
{"level":"info","ts":1596208046.5438263,"caller":"jobs/schedulers.go:145","msg":"Stopping schedulers."}
{"level":"info","ts":1596208046.5438697,"caller":"jobs/schedulers.go:77","msg":"Schedulers stopped."}
{"level":"info","ts":1596208046.6029923,"caller":"app/server.go:469","msg":"Server stopped"}
6

Just tried again with the current version (5.30.1) same result.

All clients are up to date. I’ve restarted the Nginx that sits infront of Mattermost. Lots of this in the logs:

{"level":"error","ts":1610131989.283049,"caller":"mlog/log.go:229","msg":"Unable to get the posts for the channel.","path":"/api/v4/channels/xoj6c9gx3tfkzx5yr7w7bezjqe/posts","request_id":"u9n88tkcnpfjfkxcsoxsi7jtch","ip_addr":"157.52.11.88","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"GetPostsBeforePost","http_code":500,"err_details":"failed to find Posts with channelId=xoj6c9gx3tfkzx5yr7w7bezjqe: pq: canceling statement due to user request"}
{"level":"error","ts":1610131990.3335214,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/agwpi7x6ubrbdfg84rtc7qi9xh/channels/wfpmeiuo47nr7goedpungdzx6y/posts/unread","request_id":"fe5exwdkobnrp8bqdbaruz7uxc","ip_addr":"99.251.88.232","user_id":"agwpi7x6ubrbdfg84rtc7qi9xh","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=5567jrimapb6fkqgjs5ckjkf4w: pq: canceling statement due to user request"}
{"level":"error","ts":1610131997.360991,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/pcds894dbbrjjbgm1egz3u9qph/channels/jkmc3nf8p7nq9youiga5fkhy9w/posts/unread","request_id":"jeceh3gq4tnjbmrbnyx6wikzkr","ip_addr":"70.29.68.177","user_id":"pcds894dbbrjjbgm1egz3u9qph","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=tg5bm8jht78et8pd78r6xt5jfy: pq: canceling statement due to user request"}
{"level":"error","ts":1610131997.3611197,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/pcds894dbbrjjbgm1egz3u9qph/channels/34smcwpxmpnumydj3tnto1ecuy/posts/unread","request_id":"76sp114zzt8t9r8qxsrncw58mw","ip_addr":"70.29.68.177","user_id":"pcds894dbbrjjbgm1egz3u9qph","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=19ipyumyxbruu8ycjmnd3z5rwa: pq: canceling statement due to user request"}
{"level":"error","ts":1610132018.5855455,"caller":"mlog/log.go:229","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"kpqsdrpf6tbetnjgfg9b8esj6c","ip_addr":"157.52.11.88","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"POST","err_where":"createPost","http_code":400,"err_details":""}
{"level":"error","ts":1610132021.6502228,"caller":"mlog/log.go:229","msg":"Your license does not support cloud requests.","path":"/api/v4/cloud/subscription","request_id":"3f8b5gorn3yomnpzacjtm386iy","ip_addr":"157.52.11.88","user_id":"86wyy4d69tyfmjupze3orobmrc","method":"GET","err_where":"Api4.getSubscription","http_code":501,"err_details":""}
{"level":"error","ts":1610132023.493093,"caller":"mlog/log.go:229","msg":"Invalid RootId parameter.","path":"/api/v4/posts","request_id":"cx4oteobafbgx8scteiwopbpjr","ip_addr":"135.23.123.185","user_id":"9dbtyg199bd98ftt3kamzpaoxa","method":"POST","err_where":"createPost","http_code":400,"err_details":""}

It looks like the server can’t find the posts that the client is attempting to reply to.

Did the database back-end get upper and lower-case hex confused or something?

I have no idea how to fix this, and I’m slightly afraid of reverting because the database schema claims to have been upgraded to 5.30 now.

7

Postgres seems very busy, is it maybe upgrading tables behind the scenes for the new schema and those requests will eventually be able to succeed? If this is the case, the UI really needs some sort of progress indicator, or to handle these failures better.

8

Leaving it over the weekend didn’t help at all; server is mostly idle (under 10% CPU utilization at all times), but queries are timing out constantly (replies time out and fail after the Mattermost QueryTimeout setting’s value). Lots of this in the MM log:

{"level":"error","ts":1610372929.7626736,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/isc1exemebr8fmf9par7g4y6yw/channels/z1nhpog8npdubqjmhym6oquycr/posts/unread","request_id":"htu5g9xfo3ymfyt5pn8bxgso5a","ip_addr":"198.251.52.219","user_id":"isc1exemebr8fmf9par7g4y6yw","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=g1dckxk6ctnfdkuwaiqfiyd3fe: pq: canceling statement due to user request"}
{"level":"error","ts":1610372931.0141468,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/isc1exemebr8fmf9par7g4y6yw/channels/51wupdcaq7yw3q8mfftptw47ho/posts/unread","request_id":"fp5emt89opd5zj8ry8kz1kq84a","ip_addr":"198.251.52.219","user_id":"isc1exemebr8fmf9par7g4y6yw","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=zb47uz181pbippqhy6egcur4xc: pq: canceling statement due to user request"}
{"level":"error","ts":1610372931.0144043,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/isc1exemebr8fmf9par7g4y6yw/channels/h5jo949oi7d7dcnxstwoocx7nr/posts/unread","request_id":"8xyjkrn85b8s7dbrudxk3e6aih","ip_addr":"198.251.52.219","user_id":"isc1exemebr8fmf9par7g4y6yw","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=49bkt77kdib7mn6oso54mpqbpy: pq: canceling statement due to user request"}
{"level":"error","ts":1610372934.1321552,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/isc1exemebr8fmf9par7g4y6yw/channels/syc1iuesr38mimwibxgasu7obr/posts/unread","request_id":"uqwuowz8up8zmjmwa9f3cgi7oe","ip_addr":"198.251.52.219","user_id":"isc1exemebr8fmf9par7g4y6yw","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=xd8e5bfrmtr63xeqm7c4ieouwc: pq: canceling statement due to user request"}
{"level":"error","ts":1610372934.1486177,"caller":"mlog/log.go:229","msg":"Unable to get the post.","path":"/api/v4/users/isc1exemebr8fmf9par7g4y6yw/channels/ccrfxcsydp8zbmpzsknpnimako/posts/unread","request_id":"79h7aj6suffr7bknnmycjghw3y","ip_addr":"198.251.52.219","user_id":"isc1exemebr8fmf9par7g4y6yw","method":"GET","err_where":"GetPostThread","http_code":500,"err_details":"failed to get Post with id=k83whdae7bym7gr6ahmkz79t1r: pq: canceling statement due to user request"}
9

I’ve created a GitHub issue with lots of details, log entries, etc. for our latest misadventure: Upgraded to 5.30.1 from 5.21.0, numerous (database?) problems · Issue #16662 · mattermost/mattermost-server · GitHub

1 Like
10

Can you provide the Nginx reverse proxy configuration that you are using? I’m wondering if there is a network configuration issue that is preventing the API from properly receiving and sending requests.

11

Certainly; IIRC this is from the Mattermost installation instructions for running behind an nginx proxy:

upstream backend {
   server localhost:8065;
   keepalive 32;
}

proxy_cache_path /var/cache/nginx levels=1:2 keys_zone=mattermost_cache:10m max_size=3g inactive=120m use_temp_path=off;

server {
  listen 80 default_server;
  #listen [::]:80 ipv6only=on default_server;
  server_name chat.isara.com;
  server_tokens off;
  return 301 https://$server_name$request_uri;
  access_log  /var/log/nginx/access.log;
  error_log   /var/log/nginx/error.log;
}

server {
    listen 443 ssl default_server;
    #listen [::]:443 ipv6only=on ssl default_server;
    server_name chat.isara.com;
    server_tokens off;

    gzip off;
    ssl_certificate /home/chrish/star_isara_com.pem;
    ssl_certificate_key /home/chrish/chat.isara.com.key;
    ssl_protocols TLSv1.2 TLSv1.3;
    ssl_ciphers "TLS13-CHACHA20-POLY1305-SHA256;TLS13-AES-256-GCM-SHA384;TLS13-AES-128-GCM-SHA256;ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:kEDH+AESGCM:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:AES:CAMELLIA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA";
    ssl_prefer_server_ciphers on;
    ssl_session_timeout 5m;
    ssl_session_cache shared:SSL:10m;

    add_header Strict-Transport-Security "max-age=31536000";
    # This seems to be on by default in current nginx; this will result
    # in a duplicate header, which is invalid.
    #add_header X-Frame-Options "SAMEORIGIN";
    add_header X-XSS-Protection "1; mode=block";
    add_header X-Content-Type-Options "nosniff";
    add_header Referrer-Policy "same-origin";
    add_header Feature-Policy "geolocation 'self'; notifications 'self'";

    location ~ /api/v[0-9]+/(users/)?websocket$ {
       proxy_set_header Upgrade $http_upgrade;
       proxy_set_header Connection "upgrade";
       client_max_body_size 50M;
       proxy_set_header Host $http_host;
       proxy_set_header X-Real-IP $remote_addr;
       proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
       proxy_set_header X-Forwarded-Proto $scheme;
       # See comment above for X-Frame-Options.
       #proxy_set_header X-Frame-Options SAMEORIGIN;
       proxy_buffers 256 16k;
       proxy_buffer_size 16k;
       client_body_timeout 60;
       send_timeout 300;
       lingering_timeout 5;
       proxy_connect_timeout 90;
       proxy_send_timeout 300;
       proxy_read_timeout 90s;
       proxy_pass http://backend;
    }

    location / {
       client_max_body_size 50M;
       proxy_set_header Connection "";
       proxy_set_header Host $http_host;
       proxy_set_header X-Real-IP $remote_addr;
       proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
       proxy_set_header X-Forwarded-Proto $scheme;
       # See comment above for X-Frame-Options
       #proxy_set_header X-Frame-Options SAMEORIGIN;
       proxy_buffers 256 16k;
       proxy_buffer_size 16k;
       proxy_read_timeout 600s;
       proxy_cache mattermost_cache;
       proxy_cache_revalidate on;
       proxy_cache_min_uses 2;
       proxy_cache_use_stale timeout;
       proxy_cache_lock on;
       proxy_http_version 1.1;
       proxy_pass http://backend;
    }
}
12

I’ve tweaked the nginx settings a bit to match the values suggested in High Availability Cluster (E20) — Mattermost 5.30 documentation ; replies and edits (and whatever else is broken in the API for me?) still not working, same timeout behaviour as before.

13

Reconfigured back to this: Configuring NGINX as a proxy for Mattermost Server — Mattermost 5.30 documentation

14

Again, I should point out that this config worked fine with MM 5.21.0 and failed when upgrading to 5.24.1 originally, so I’m thinking it’s something in the code. Hopefully the releases are tagged so I can see what changed…

15

That’s quite interesting, it does seem that your configuration is properly setup.
I noticed the URL to your Mattermost instance here

and took a look at just the login page, since I obviously can’t log in, and I noticed something interesting.

image
image1920×937 51.9 KB

image
image1327×26 2.22 KB

It seems as though there is a variable missing in a configuration file, such as config.json that is causing the actual name of the domain, which I would assume should be chat.isara.com to instead just render as https://plugins/com.github.moussetc.mattermost.plugin.spoiler/config
Upon investigating this, it does appear that when inserting the name of the domain into the URL, it works, leading me to believe that there is a configuration or proxy error somewhere along the lines here.
https://chat.isara.com/plugins/com.github.moussetc.mattermost.plugin.spoiler/config
image
image1194×927 5.87 KB

Could you check your Mattermost config.json file and make sure that your domain is properly set in the site URL parameter?

16 
{
    "ServiceSettings": {
        "SiteURL": "https://chat.isara.com",
        "WebsocketURL": "",
...
}

The only lines with moussetc in them are the blocks for those plugins’ settings:

chrish@hostname:/opt/mattermost/config$ grep moussetc *.json
config.json:            "com.github.moussetc.mattermost.plugin.giphy": {
config.json:            "com.github.moussetc.mattermost.plugin.spoiler": {
config.json:            "com.github.moussetc.mattermost.plugin.diceroller": {
config.json:            "com.github.moussetc.mattermost.plugin.emoticon2emoji": {
config.json:            "com.github.moussetc.mattermost.plugin.giphy": {
config.json:            "com.github.moussetc.mattermost.plugin.spoiler": {
17

I went and found the spoiler plugin and installed it myself, I believe there is an issue in the code since it’s not inserting the URL of my Mattermost instance into the URL in the same way as I mentioned in my previous post.

18

I also saw from this URL on your installation that your using Mattermost version 5.21.0 while the latest version is 5.3, can I ask if you plan on upgrading to 5.3, or even 5.28.1, which is the version I am currently running?

19

My latest adventures were with 5.30.1; I’ve been running into this (these?) problems since 2.24.1. I narrowed it down the 5.22.0 as the first occurrence, so the MM devs have created a ticket to look into the changes between 5.21 and 5.22.

I’m setting up a new server with up-to-date PostgreSQL and up-to-date Mattermost and it’s running fine. Magic!

1 Like
20

Alright, glad it is working alright! I’m wondering if it may have been an incomplete database schema or something along those lines to be honest. I’ll be interested to see the outcome!