Mattermost server crashes when users trying to send any files

Troubleshooting
1

Hi.

Version Mattermost: 7.4.0
Database Schema version: 93
Database: postgres

From time to time our Mattermost server stop to send any attachments.
About once a month.
To resolve this situation I usually restart the server.

systemctl restart mattermost.service

During the server fails, I’d seen the log messages (/opt/mattermost/logs) :

{"timestamp":"2023-01-10 10:01:56.498 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}

Full log during fails

{"timestamp":"2023-01-10 09:39:55.413 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 09:44:01.949 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"5tpd9wp977d9dfu6i7hfwieema"}
{"timestamp":"2023-01-10 09:54:01.987 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"e1h4ofmyab837m9uk7jbrz537a"}
{"timestamp":"2023-01-10 10:01:56.498 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 10:04:02.048 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"3df7734hyf8yipz9h1rw9fjr4y"}
{"timestamp":"2023-01-10 10:14:02.105 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"16dhdgab4pfmumns17xy9h4u6c"}
{"timestamp":"2023-01-10 10:24:02.208 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"ommhj1dgapymbexj9nnisbxw4w"}
{"timestamp":"2023-01-10 10:34:02.272 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"gkq97byfdjr75dhd7chn1r6inh"}
{"timestamp":"2023-01-10 10:34:02.554 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ProductNotices","job_id":"7ty8a538o7ne8kdypoe5wc113a"}
{"timestamp":"2023-01-10 10:38:12.443 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 10:44:02.331 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"mmh9xys8a3do3mgcypzwggzmer"}
{"timestamp":"2023-01-10 10:54:02.391 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"ycjjdwbfpifguj9ys5arq9m95c"}
{"timestamp":"2023-01-10 11:03:39.324 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:03:39.339 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:04:02.483 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"d8p3pipep3ye9npxc9es55mgkw"}
{"timestamp":"2023-01-10 11:04:16.574 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:12:37.131 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:14:02.562 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"f5p78efi5fbp9849dwopyd8aja"}
{"timestamp":"2023-01-10 11:24:02.615 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"xgy45ahz3bgutny5i1e9kbk8br"}
{"timestamp":"2023-01-10 11:34:02.732 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"3p8m7x7dei8kunzd7hy61xmjsh"}
{"timestamp":"2023-01-10 11:34:02.993 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ProductNotices","job_id":"aqefe5n15jyu5cgef8dpxanj3h"}
{"timestamp":"2023-01-10 11:35:36.455 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:40:27.961 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:44:02.827 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"qf3az39xbpfj9ym3hmd6z56p5r"}
{"timestamp":"2023-01-10 11:46:04.385 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:51:36.175 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:54:02.853 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"xnab1pgumf8ktqka7ictgui57e"}
{"timestamp":"2023-01-10 11:54:32.927 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-01-10 11:56:23.694 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"error unzipping data: zip: not a valid zip file"}
{"timestamp":"2023-01-10 12:04:02.931 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"6ysdggwkxtr7xbke4jk8ru1y8o"}
{"timestamp":"2023-01-10 12:14:02.959 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"og74461p87yejkb4ferzssynoo"}
{"timestamp":"2023-01-10 12:24:03.029 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:88","worker":"ExpiryNotify","job_id":"a7s4n54aiffqupqpdqxi6k7afh"}
{"timestamp":"2023-01-10 12:34:11.049 +03:00","level":"info","msg":"Server is initializing...","caller":"app/server.go:272","go_version":"go1.18.1"}
{"timestamp":"2023-01-10 12:34:11.065 +03:00","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:230","database":"master"}
{"timestamp":"2023-01-10 12:34:11.106 +03:00","level":"error","msg":"Failed to ping DB","caller":"sqlstore/store.go:240","error":"pq: the database system is starting up","retrying in seconds":10}
{"timestamp":"2023-01-10 12:34:21.107 +03:00","level":"info","msg":"Pinging SQL","caller":"sqlstore/store.go:230","database":"master"}
{"timestamp":"2023-01-10 12:34:22.201 +03:00","level":"info","msg":"Starting websocket hubs","caller":"app/web_hub.go:93","number_of_hubs":32}
{"timestamp":"2023-01-10 12:34:22.203 +03:00","level":"info","msg":"Loaded system translations","caller":"i18n/i18n.go:93","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"timestamp":"2023-01-10 12:34:22.320 +03:00","level":"info","msg":"Current version is 7.4.0 (7.4.0/Wed Oct 12 19:36:20 UTC 2022/8cb6718a9bcc45186f62baed2304248d3cabaa50/none)","caller":"app/server.go:583","current_version":"7.4.0","build_number":"7.4.0","build_date":"Wed Oct 12 19:36:20 UTC 2022","build_hash":"8cb6718a9bcc45186f62baed2304248d3cabaa50","build_hash_enterprise":"none"}
{"timestamp":"2023-01-10 12:34:22.320 +03:00","level":"info","msg":"Team Edition Build","caller":"app/server.go:594","enterprise_build":false}
{"timestamp":"2023-01-10 12:34:22.321 +03:00","level":"info","msg":"Printing current working","caller":"app/server.go:598","directory":"/opt/mattermost"}
{"timestamp":"2023-01-10 12:34:22.321 +03:00","level":"info","msg":"Loaded config","caller":"app/server.go:599","source":"file:///opt/mattermost/config/config.json"}
{"timestamp":"2023-01-10 12:34:22.585 +03:00","level":"info","msg":"Starting workers","caller":"jobs/workers.go:48"}
{"timestamp":"2023-01-10 12:34:22.641 +03:00","level":"info","msg":"Starting schedulers.","caller":"jobs/schedulers.go:47"}
{"timestamp":"2023-01-10 12:34:22.660 +03:00","level":"error","msg":"License key from https://mattermost.com required to unlock enterprise features.","caller":"app/license.go:152","error":"resource: License id: "}
{"timestamp":"2023-01-10 12:34:24.464 +03:00","level":"info","msg":"Starting up plugins","caller":"app/plugin.go:212"}
{"timestamp":"2023-01-10 12:34:24.473 +03:00","level":"info","msg":"Syncing plugins from the file store","caller":"app/plugin.go:286"}
{"timestamp":"2023-01-10 12:34:30.237 +03:00","level":"info","msg":"Ensuring Feedbackbot exists","caller":"app/plugin_api.go:971","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-01-10 12:34:32.188 +03:00","level":"info","msg":"activated","caller":"app/plugin_api.go:971","plugin_id":"com.mattermost.apps"}
{"timestamp":"2023-01-10 12:34:33.754 +03:00","level":"info","msg":"got public IP address","caller":"app/plugin_api.go:971","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:84","addr":"94.26.245.20"}

What I need to do, to debug the problem ?

P.S.: I was find similar issues , but they was resolved
https://forum.mattermost.com/t/running-mattermost-extract-documents-content-after-going-to-5-35-gave-errors/11717/6
https://mattermost.atlassian.net/browse/MM-35990

mattermost
mattermost1066×207 16.9 KB

2

Hi @itwhyflyru and welcome to the Mattermost forums!

This is a known issue which has been fixed in the 7.8.0 release so it should be gone after you update to this version.

3

Thanks, @agriesser .

After update, I’ll give feedback to you.

4

Hi, @agriesser .
We have updated to version:

Version Mattermost: 7.8.1
DB Schema: 101
DB: postgres

But not much time has passed . If the problems continue , I’ll write later.

Great Thanks

5

Hi, @agriesser .

Today the situation was repeated. Already at new physical server with SSD drives. With latest version of Mattermost.

The problems was started approximately from 2023-03-31 16:25 .
At 2023-03-31 16:29 I was reboted the mattermost service

systemctl restart mattermost.service

{"timestamp":"2023-03-31 15:12:06.709 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"mjb1uri8dtnj9kio3jyetzsy9e"}
{"timestamp":"2023-03-31 15:23:06.813 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"mcazrxnz7byxxd4y6kmoi5umxc"}
{"timestamp":"2023-03-31 15:34:06.906 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"ygh5sknahb8j3bjiqyqi7ia6ec"}
{"timestamp":"2023-03-31 15:45:07.012 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"w9eu8kaxubbniyw5sn5j1dywfe"}
{"timestamp":"2023-03-31 15:51:07.153 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ProductNotices","job_id":"1ocq4z7nsjd3df59fsecanabph"}
{"timestamp":"2023-03-31 15:52:03.011 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/468w5zfnrbnd5q6iqkbijexoqo/groups","request_id":"sm1wqbjngid37g5agau1z5qrew","ip_addr":"127.0.0.1","user_id":"468w5zfnrbnd5q6iqkbijexoqo","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 15:53:13.404 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/i1p7gox41irpufn158ch95ronh/groups","request_id":"sx91ntset7bgpg6hc78rginpto","ip_addr":"127.0.0.1","user_id":"i1p7gox41irpufn158ch95ronh","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 15:54:35.000 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/i1p7gox41irpufn158ch95ronh/groups","request_id":"ax1x3c7x77gg7dta5si8gtpeqo","ip_addr":"127.0.0.1","user_id":"i1p7gox41irpufn158ch95ronh","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 15:56:07.110 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"uozukm6uo3gfmmohhnwsuaftsr"}
{"timestamp":"2023-03-31 15:58:23.523 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/j5qhpw8qgpfa8mxdxc1fk7nynw/groups","request_id":"jjc3mygoatdoix3ay13q1wrsur","ip_addr":"127.0.0.1","user_id":"j5qhpw8qgpfa8mxdxc1fk7nynw","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:03:15.688 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-03-31 16:04:43.086 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-03-31 16:04:43.234 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
{"timestamp":"2023-03-31 16:07:07.213 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"f5hyd4jmnfyede3mag7qmstrnh"}
{"timestamp":"2023-03-31 16:08:24.467 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/468w5zfnrbnd5q6iqkbijexoqo/groups","request_id":"dsta69tcr3yy3bauuckw7y6zyw","ip_addr":"127.0.0.1","user_id":"468w5zfnrbnd5q6iqkbijexoqo","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:09:41.765 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/i1p7gox41irpufn158ch95ronh/groups","request_id":"bnsid1jqf3byfn9pah5ywamxdw","ip_addr":"127.0.0.1","user_id":"i1p7gox41irpufn158ch95ronh","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:18:07.313 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"nj1murf7n38w9b3mrcrnse91fc"}
{"timestamp":"2023-03-31 16:18:11.084 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/8333j39xr38w5p54nh3n7z63pa/groups","request_id":"i7ttbsm3wjdqbjyazxamkmgqew","ip_addr":"127.0.0.1","user_id":"8333j39xr38w5p54nh3n7z63pa","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:18:37.850 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/j5qhpw8qgpfa8mxdxc1fk7nynw/groups","request_id":"59qdmhsdcbg5tkqpfxzxaktrsr","ip_addr":"127.0.0.1","user_id":"j5qhpw8qgpfa8mxdxc1fk7nynw","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:19:47.372 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/18afdzfgk7r9uy9r8ma6tddpph/groups","request_id":"b36wpq3kufdb3jukzont5k8m7r","ip_addr":"127.0.0.1","user_id":"18afdzfgk7r9uy9r8ma6tddpph","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:20:29.789 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/i1p7gox41irpufn158ch95ronh/groups","request_id":"zgf9uda8miypdy5bno3ccm7ofe","ip_addr":"127.0.0.1","user_id":"i1p7gox41irpufn158ch95ronh","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:27:11.580 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/groups","request_id":"tf81djj4mjg9pe9tj6ens6g8oe","ip_addr":"127.0.0.1","user_id":"j5qhpw8qgpfa8mxdxc1fk7nynw","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:27:14.908 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/groups","request_id":"nqjx1bmjxpfwucm1gojtra8d4r","ip_addr":"127.0.0.1","user_id":"j5qhpw8qgpfa8mxdxc1fk7nynw","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:28:05.907 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/j5qhpw8qgpfa8mxdxc1fk7nynw/groups","request_id":"hyiw3icimpde5y8x5td1zhb7ce","ip_addr":"127.0.0.1","user_id":"j5qhpw8qgpfa8mxdxc1fk7nynw","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-03-31 16:29:07.414 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"mg76fei95fr18xp8ikashdotwh"}
{"timestamp":"2023-03-31 16:29:27.287 +03:00","level":"info","msg":"Stopping Server...","caller":"app/server.go:654"}
6

I cannot see an error message in your logs related to the problem you’re seeing. So you’re saying that the behaviour is the same as earlier, file uploads suddenly stop working for all users and are stuck in “Processing” state until you restart the server, right?

BTW you should install the pdftotext binary so the server is able to index the files and present them in search results (but that should not be related to your problem here, just saw it in the logs):

{"timestamp":"2023-03-31 16:03:15.688 +03:00","level":"warn","msg":"unable to extract file content","caller":"docextractor/combine.go:35","error":"exec: \"pdftotext\": executable file not found in $PATH"}
7

Hi, @agriesser .

By your advice I was enstalled pdftotext package by command sudo apt install poppler-utils at 2023-04-03 .

But today the situation has happened again. Upload progress bar was freeze .

mattermost_error
mattermost_error1586×194 6.81 KB

I am using Flameshot v11.0.0 (11.0.0-2 Debian) screenshoter. And when I’d tried to paste a some screenshot , upload progress bar was freeze. This happened not only with screenshoter , with any files , at it not depends from client OS ( we are use Linux and Windows on clients PC) .

Accurate chronology of events:

  • 2023-04-07 11:00:32.835 +03:00 - All system are still operated
  • 2023-04-07 11:35 - First accidend
  • 2023-04-07 11:42:04.686 +03:00 - I was restarted the service

log from file /opt/mattermost/logs/mattermost.log

{"timestamp":"2023-04-07 11:00:32.835 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/groups","request_id":"em35edu6utgrpxhzsyu9bxxony","ip_addr":"127.0.0.1","user_id":"e64xjsxnjjnzpkhauqp5bux9rc","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:10:48.966 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"75n71uryctrz5fxxha71ia4iah"}
{"timestamp":"2023-04-07 11:15:55.453 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/6ndkpr7fzjrcbfxre5i34c54rr/groups","request_id":"in4ucwsyubd7pba8njkhcob8ow","ip_addr":"127.0.0.1","user_id":"6ndkpr7fzjrcbfxre5i34c54rr","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:19:37.157 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/8333j39xr38w5p54nh3n7z63pa/groups","request_id":"b6yx8nbx73gemfwujpjdhnj5uh","ip_addr":"127.0.0.1","user_id":"8333j39xr38w5p54nh3n7z63pa","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:21:49.071 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"8m8ykejrkfr47yuxx7f4q8rgga"}
{"timestamp":"2023-04-07 11:23:25.145 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/t4atykcq5treukaafx16zthmdo/groups","request_id":"864hiqd5ajbepkzdskaor767te","ip_addr":"127.0.0.1","user_id":"t4atykcq5treukaafx16zthmdo","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:26:58.104 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/bado7wf79jrr3re361aceyj18w/groups","request_id":"17t9948wmj8g9gtuurkq56yqdw","ip_addr":"127.0.0.1","user_id":"bado7wf79jrr3re361aceyj18w","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:29:20.410 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/371bzei7m3rfdqgpq1gwxw54ky/groups","request_id":"8byd1b5x63neif4os966fb85ey","ip_addr":"127.0.0.1","user_id":"371bzei7m3rfdqgpq1gwxw54ky","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:29:40.855 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/groups","request_id":"q5koegfw9bf39fwfw5kfenio6h","ip_addr":"127.0.0.1","user_id":"371bzei7m3rfdqgpq1gwxw54ky","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:31:49.276 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ProductNotices","job_id":"4eajedxy9fycfgm1pob6zyd6fr"}
{"timestamp":"2023-04-07 11:32:47.636 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/groups","request_id":"5hakmoyzw3bzpmbixwxnqo6a4a","ip_addr":"127.0.0.1","user_id":"371bzei7m3rfdqgpq1gwxw54ky","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:32:49.178 +03:00","level":"info","msg":"SimpleWorker: Job is complete","caller":"jobs/base_workers.go:96","worker":"ExpiryNotify","job_id":"tyf6ae8g9tfyigj1diesh7kqrw"}
{"timestamp":"2023-04-07 11:37:36.804 +03:00","level":"info","msg":"api endpoint requires a license","caller":"web/context.go:115","path":"/api/v4/users/14pgoawq87bpdk1ruafwpxr9ah/groups","request_id":"mt5kfe3knfgbxbua4r1wg7n1fc","ip_addr":"127.0.0.1","user_id":"14pgoawq87bpdk1ruafwpxr9ah","method":"GET","err_where":"","http_code":501,"error":": api endpoint requires a license"}
{"timestamp":"2023-04-07 11:39:01.271 +03:00","level":"warn","msg":"error fetching remote image: Get \"https://mm.whyfly.ru/api/v4/users/e64xjsxnjjnzpkhauqp5bux9rc/image?_=0\": address forbidden, you may need to set AllowedUntrustedInternalConnections to allow an integration access to your internal network","caller":"imageproxy/local.go:156"}
{"timestamp":"2023-04-07 11:39:01.271 +03:00","level":"warn","msg":"error fetching remote image: Get \"https://mm.whyfly.ru/api/v4/users/4z7a98encfyxmym8ojxpmznaec/image?_=1567601322258\": address forbidden, you may need to set AllowedUntrustedInternalConnections to allow an integration access to your internal network","caller":"imageproxy/local.go:156"}
{"timestamp":"2023-04-07 11:42:03.678 +03:00","level":"info","msg":"Stopping Server...","caller":"app/server.go:654"}
{"timestamp":"2023-04-07 11:42:03.681 +03:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.nps","wrapped_extras":"pathplugins/com.mattermost.nps/server/dist/plugin-linux-amd64pid230772errorsignal: terminated"}
{"timestamp":"2023-04-07 11:42:03.681 +03:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.calls","wrapped_extras":"pathplugins/com.mattermost.calls/server/dist/plugin-linux-amd64pid230801errorsignal: terminated"}
{"timestamp":"2023-04-07 11:42:03.681 +03:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"playbooks","wrapped_extras":"pathplugins/playbooks/server/dist/plugin-linux-amd64pid230815errorsignal: terminated"}
{"timestamp":"2023-04-07 11:42:03.681 +03:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"focalboard","wrapped_extras":"pathplugins/focalboard/server/dist/plugin-linux-amd64pid230836errorsignal: terminated"}
{"timestamp":"2023-04-07 11:42:03.681 +03:00","level":"error","msg":"plugin process exited","caller":"plugin/hclog_adapter.go:79","plugin_id":"com.mattermost.apps","wrapped_extras":"pathplugins/com.mattermost.apps/server/dist/plugin-linux-amd64pid230785errorsignal: terminated"}
{"timestamp":"2023-04-07 11:42:04.679 +03:00","level":"warn","msg":"Unable to shutdown server","caller":"app/server.go:638","error":"context deadline exceeded"}
{"timestamp":"2023-04-07 11:42:04.685 +03:00","level":"info","msg":"Stopped workers","caller":"jobs/workers.go:90"}
{"timestamp":"2023-04-07 11:42:04.685 +03:00","level":"info","msg":"Stopping schedulers.","caller":"jobs/schedulers.go:118"}
{"timestamp":"2023-04-07 11:42:04.685 +03:00","level":"info","msg":"Schedulers stopped.","caller":"jobs/schedulers.go:50"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"info","msg":"Shutting down plugins","caller":"app/plugin.go:384"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.nps","error":"connection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.nps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.nps"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"focalboard","error":"connection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"playbooks","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.calls","error":"connection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"playbooks"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"focalboard","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"focalboard"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.calls","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"error","msg":"RPC call OnDeactivate to plugin failed.","caller":"plugin/client_rpc_generated.go:33","plugin_id":"com.mattermost.apps","error":"connection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.calls"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"error closing client during Kill","caller":"plugin/hclog_adapter.go:70","plugin_id":"com.mattermost.apps","wrapped_extras":"errconnection is shut down"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"warn","msg":"plugin failed to exit gracefully","caller":"plugin/hclog_adapter.go:72","plugin_id":"com.mattermost.apps"}
{"timestamp":"2023-04-07 11:42:04.686 +03:00","level":"info","msg":"stopping websocket hub connections","caller":"platform/web_hub.go:115"}
{"timestamp":"2023-04-07 11:43:34.112 +03:00","level":"info","msg":"Server is initializing...","caller":"platform/service.go:165","go_version":"go1.18.1"}

But I still don’t see any trouble . Maybe I can enable advanced log ?

1 Like
8

We have the same issue with the docker image mattermost/mattermost-team-edition:release-7.7, but we could not find which file created this issue because we have many images uploaded in days.
Something we found is:

  • When the image (or any files) is show processing forever (until timeout error) we also see that file was uploaded to S3 & already saved information to the database
9

Me neither, you could try to enable debug logging and see if that helps, but I’m not sure it will.
The hint with the poppler-utils was not related to your problem, btw, so I did not expect things to get better after you install it, but it’s one missing piece to allow indexing of PDF files.

The only error messages I can see in your logs short before you restarted the server but a few minutes after the event has happened:

{"timestamp":"2023-04-07 11:39:01.271 +03:00","level":"warn","msg":"error fetching remote image: Get \"https://mm.whyfly.ru/api/v4/users/e64xjsxnjjnzpkhauqp5bux9rc/image?_=0\": address forbidden, you may need to set AllowedUntrustedInternalConnections to allow an integration access to your internal network","caller":"imageproxy/local.go:156"}
{"timestamp":"2023-04-07 11:39:01.271 +03:00","level":"warn","msg":"error fetching remote image: Get \"https://mm.whyfly.ru/api/v4/users/4z7a98encfyxmym8ojxpmznaec/image?_=1567601322258\": address forbidden, you may need to set AllowedUntrustedInternalConnections to allow an integration access to your internal network","caller":"imageproxy/local.go:156"}

This is also unrelated to your issue, but it looks like you’re using an external image proxy. You will need to add its URL/IP address to the list of untrusted internal destinations (Environment → Developer → Allow untrusted internal connections to:) if you cannot use encryption on this proxy (https).

@hcminh thanks for the hint and welcome to the Mattermost forums!
@itwhyflyru do you also use S3 as the storage backend in your installation or local files only?

10

Hi, @agriesser

We are also use S3 storage backend in our installation. Yandex.S3 ( https://storage.yandexcloud.net ).

I have an idea why this happened.

From time to time Yandex.S3 answers with error other than 0 (AWS CLI Return Codes — AWS CLI 1.27.114 Command Reference).
This is happinned not very often, maybe 1 time from 10000.
This is Yandex.S3 trouble. I noticed this on different projects.

With a high probability, this is the main problem.

But why this external problem are broken all the service (all uploads), this is the secret for me.
When this problem will happen, must broke only one upload, from one user, not all uploads from all users.

@agriesser , Can you get advice for me , how I can enable debug log for all S3 uploads ?

11

Hello!
I have similar issue with frozen download progressbar.
pdftotext warning was also seen and suppressed by installing pdftotext.
We do not use S3 backend, only normal local file storage.

Packages’ versions:
ii mattermost 8.0.1-0 amd64 Mattermost Server
ii mattermost-omnibus 8.0.1-0 amd64 Mattermost Omnibus Package