Can't send any files after upgrading from team edition 3.5.1 to 4.7.3

Troubleshooting
1

For feature requests, please see: http://www.mattermost.org/feature-requests/.

For troubleshooting questions, please post in the following format:

Summary

An error is triggered when trying to send files,either by dragging/dropping, clipboard, or attaching directly. Connection is dropped and after a few seconds webhook reconnects to server.

Steps to reproduce

Send a file, either by:

  • Dragging/dropping
  • Copying/pasting images from clipboard
  • Attaching files directly

Expected behavior

File/attachment should be sent in channel.

Observed behavior

  • Service disconnects
  • After a few seconds, websocket reconnects
  • Attempting to remove attachments also causes another error
  • Have to trigger a reload from the app to be able to send messages again, since attachments can’t be removed.
webview.addEventListener.e @ index_bundle.js:47110

Uncaught TypeError: n is not a function
|dispatchEvent|@|C:\Users\Username\AppData\Local\mattermost\app-4.0.1\resources\electron.asar\renderer\web-view\web-view.js:175|
|dispatchEvent|@|C:\Users\Username\AppData\Local\mattermost\app-4.0.1\resources\electron.asar\renderer\web-view\guest-view-internal.js:55|
|(anonymous)|@|C:\Users\Username\AppData\Local\mattermost\app-4.0.1\resources\electron.asar\renderer\web-view\guest-view-internal.js:72|
|emitMany|@|events.js:127|
|emit|@|events.js:204|

2018-03-30_20-07-03

2

I’m seeing this same behavior on our Mattermost server after upgrading from 4.2.0 to 4.8.0 so I’m guessing something in that upgrade path has broken this functionality for us, too. File uploads were definitely working the day before the upgrade and previously-uploaded images still download correctly.

I don’t have any solution to this problem but can add a few things that I’ve also observed:

In the Chrome web console, I see a similar message but here it is in detail:

websocket closed
client.js:772 POST https://[hiding my server url]/api/v4/files 502 (Bad Gateway)
helpers.js:34 Uncaught TypeError: n is not a function
    at s (helpers.js:34)
    at o (file_actions.jsx:28)
    at u.callback (client.js:611)
    at u.<anonymous> (client.js:436)
    at u.a.emit (index.js:133)
    at XMLHttpRequest.t.onreadystatechange (client.js:705)
root.jsx:35 POST https://[hiding my server url]/api/v4/logs 502 (Bad Gateway)
websocket_client.jsx:49 websocket re-established connection

I don’t see any error logs in the Mattermost logs at this time. I do, however, see the following in the nginx logs:

2018/04/04 21:48:12 [error] 972#972: *1916 upstream prematurely closed connection while reading response header from upstream, client: 128.208.133.143, server: [hiding my server URL], request: "POST /api/v4/files HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/files", host: "[hiding my server URL]"
2018/04/04 21:48:12 [error] 972#972: *1916 connect() failed (111: Connection refused) while connecting to upstream, client: 128.208.133.143, server: [hiding my server URL], request: "POST /api/v4/logs HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/logs", host: "[hiding my server URLt]"

As far as I can think, we’re using a pretty vanilla install of Mattermost Enterprise Edition with nginx in front of it. nginx is redirecting all requests over standard HTTP on port 80 to use HTTPS on port 443 and we are using a Let’s Encrypt-generated SSL certificate that appears to be valid according to Symantec’s cert. checker.

I would be happy to provide any further information if anybody has questions that would help troubleshoot or has suggestions for things I should be looking at.

3

@antigaprime - Can you post your Mattermost server logs from the failed uploads?

@CraigPhillips - Thanks for that info. Do you see anything in the nginx proxy logs?

4

@paulrothrock - I did post the two lines I see in the nginx logs every time I try to upload a file but it just seems like they’re getting a rejection or error response from Mattermost web service. Here they are again:

2018/04/04 21:48:12 [error] 972#972: *1916 upstream prematurely closed connection while reading response header from upstream, client: 128.208.133.143, server: [hiding my server URL], request: "POST /api/v4/files HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/files", host: "[hiding my server URL]"
2018/04/04 21:48:12 [error] 972#972: *1916 connect() failed (111: Connection refused) while connecting to upstream, client: 128.208.133.143, server: [hiding my server URL], request: "POST /api/v4/logs HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/logs", host: "[hiding my server URL]"

Unless there is a more specific set of logs you are asking about? I don’t know a ton about nginx but can probably locate what you’re looking for if I’m missing it.

5

@paulrothrock

I can confirm similar logs

error.log:

2018/04/11 01:14:02 [error] 11661#11661: *119838 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:05 [error] 11661#11661: *119840 connect() failed (111: Connection refused) while connecting to upstream, client: 213.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:05 [error] 11661#11661: *119842 connect() failed (111: Connection refused) while connecting to upstream, client: 178.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:06 [error] 11661#11661: *119844 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:08 [error] 11661#11661: *119846 connect() failed (111: Connection refused) while connecting to upstream, client: 213.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:08 [error] 11661#11661: *119848 connect() failed (111: Connection refused) while connecting to upstream, client: 178.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:09 [error] 11661#11661: *119850 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:11 [error] 11661#11661: *119852 connect() failed (111: Connection refused) while connecting to upstream, client: 213.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:11 [error] 11661#11661: *119854 connect() failed (111: Connection refused) while connecting to upstream, client: 178.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:14:13 [error] 11661#11661: *119856 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""
2018/04/11 01:15:13 [error] 11661#11661: *119902 upstream prematurely closed connection while reading response header from upstream, client: 186.*.*.*, server: , request: "POST /api/v4/files HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/files", host: ""
2018/04/11 01:15:13 [error] 11661#11661: *119902 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "POST /api/v3/general/log_client HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v3/general/log_client", host: ""
2018/04/11 01:15:14 [error] 11661#11661: *119902 connect() failed (111: Connection refused) while connecting to upstream, client: 186.*.*.*, server: , request: "POST /api/v4/channels/members/me/view HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/channels/members/me/view", host: ""
2018/04/11 01:15:16 [error] 11661#11661: *119939 connect() failed (111: Connection refused) while connecting to upstream, client: 213.*.*.*, server: , request: "GET /api/v4/websocket HTTP/1.1", upstream: "http://127.0.0.1:8065/api/v4/websocket", host: ""

access.log (in case it helps):

213.*.*.* - - [11/Apr/2018:01:14:02 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:02 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:02 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:05 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:06 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:08 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:08 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:09 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:11 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:11 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:13 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/plugins/webapp HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 7264 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 864 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/unread HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels HTTP/1.1" 200 9549 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/channels/imbhj17e5tnub833w451jbty9r/posts?page=0&per_page=60 HTTP/1.1" 200 26524 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/plugins/webapp HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 7579 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels HTTP/1.1" 200 10066 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 1294 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/users/me/teams/unread HTTP/1.1" 200 76 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:14 +0200] "GET /api/v4/channels/9x8betkc6jrftpoww8smpxtqae/posts?page=0&per_page=60 HTTP/1.1" 200 25571 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "GET /api/v4/plugins/webapp HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels HTTP/1.1" 200 5965 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 4398 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "GET /api/v4/channels/7trbste1iffeiqnz4k7ygjpx5r/posts?page=0&per_page=60 HTTP/1.1" 200 433 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 754 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:17 +0200] "GET /api/v4/users/me/teams/unread HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:44 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 754 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:49 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:49 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:49 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 4398 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:51 +0200] "GET /api/v4/websocket HTTP/1.1" 101 791 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:51 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:52 +0200] "GET /consenda/messages/@spoveda HTTP/1.1" 200 1482 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:14:53 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 1294 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:53 +0200] "GET /api/v4/config/client?format=old HTTP/1.1" 200 3380 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/teams HTTP/1.1" 200 317 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/preferences HTTP/1.1" 200 5269 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/teams/members HTTP/1.1" 200 126 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/teams/unread HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/license/client?format=old HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/plugins/webapp HTTP/1.1" 200 2 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 755 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 4398 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:54 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels HTTP/1.1" 200 5965 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "POST /api/v4/users/ids HTTP/1.1" 200 1546 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "POST /api/v4/users/ids HTTP/1.1" 200 1546 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/channels/7trbste1iffeiqnz4k7ygjpx5r/members/me HTTP/1.1" 200 291 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "PUT /api/v4/users/zxaksjc1b3y1b8nnpb8gx7aa7h/preferences HTTP/1.1" 200 15 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/teams?page=0&per_page=200 HTTP/1.1" 200 317 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels HTTP/1.1" 200 5965 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 4398 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/users/zxaksjc1b3y1b8nnpb8gx7aa7h/status HTTP/1.1" 200 106 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/users/zxaksjc1b3y1b8nnpb8gx7aa7h/image?_=1509047755559 HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:14:55 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 862 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:55 +0200] "GET /api/v4/channels/7trbste1iffeiqnz4k7ygjpx5r/posts?page=0&per_page=30 HTTP/1.1" 200 433 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:56 +0200] "GET /api/v4/channels/7trbste1iffeiqnz4k7ygjpx5r/stats HTTP/1.1" 200 60 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:56 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:56 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:56 +0200] "POST /api/v4/users/status/ids HTTP/1.1" 200 754 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:14:56 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 41 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:08 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:08 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:08 +0200] "GET /api/v4/users/me/teams/idftcta86tf8ufk5mimjyg8gwc/channels/members HTTP/1.1" 200 4398 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:09 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 41 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:11 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:11 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 200 83 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:13 +0200] "POST /api/v4/files HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:13 +0200] "GET /api/v4/websocket HTTP/1.1" 101 1545 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
178.*.*.* - - [11/Apr/2018:01:15:13 +0200] "GET /api/v4/websocket HTTP/1.1" 101 411 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:15:13 +0200] "GET /api/v4/websocket HTTP/1.1" 101 411 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:13 +0200] "POST /api/v3/general/log_client HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
186.*.*.* - - [11/Apr/2018:01:15:14 +0200] "POST /api/v4/channels/members/me/view HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/4.0.1 Chrome/58.0.3029.110 Electron/1.7.13 Safari/537.36"
213.*.*.* - - [11/Apr/2018:01:15:16 +0200] "GET /api/v4/websocket HTTP/1.1" 502 584 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_4) AppleWebKit/537.36 (KHTML, like Gecko) Mattermost/3.7.1 Chrome/56.0.2924.87 Electron/1.6.11 Safari/537.36"

File upload was started from IP 186.*.*.*. Sorry for the long logs.

6

The Mattermost server logs might have more information on why it’s rejecting the upload. They’re located in the logs directory where you installed Mattermost.

7

@paulrothrock

The only changes I can see in those logs when uploading files are related to the service restarting (uploaded files twice, hence the repeated logs):

[2018/04/12 17:35:48 CEST] [INFO] Server is initializing...
[2018/04/12 17:35:48 CEST] [INFO] Pinging SQL master database
[2018/04/12 17:35:49 CEST] [INFO] Current version is 4.7.1 (4.7.3/Thu Mar  8 19:58:02 UTC 2018/659ce8c60012a7d5fd597997b1794ac512b3b155/none)
[2018/04/12 17:35:49 CEST] [INFO] Enterprise Enabled: false
[2018/04/12 17:35:49 CEST] [INFO] Current working directory is /srv/mattermost
[2018/04/12 17:35:49 CEST] [INFO] Loaded config file from /srv/mattermost/config/config.json
[2018/04/12 17:35:49 CEST] [INFO] Connection to S3 or minio is good. Bucket exists.
[2018/04/12 17:35:49 CEST] [INFO] Starting up plugins
[2018/04/12 17:35:49 CEST] [WARN] unable to create user namespace: fork/exec /proc/self/exe: permission denied
[2018/04/12 17:35:49 CEST] [WARN] plugin sandboxing is not supported. plugins will run with the same access level as the server
[2018/04/12 17:35:51 CEST] [INFO] Activated jira plugin
[2018/04/12 17:35:51 CEST] [INFO] Starting Server...
[2018/04/12 17:35:51 CEST] [INFO] Server is listening on [::]:8065
[2018/04/12 17:35:51 CEST] [INFO] API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.
[2018/04/12 17:35:51 CEST] [INFO] Starting 2 websocket hubs
[2018/04/12 17:35:51 CEST] [INFO] Starting workers
[2018/04/12 17:35:51 CEST] [INFO] Starting schedulers.
[2018/04/12 17:37:36 CEST] [INFO] Loaded system translations for 'en' from '/srv/mattermost/i18n/en.json'
[2018/04/12 17:37:36 CEST] [INFO] Server is initializing...
[2018/04/12 17:37:36 CEST] [INFO] Pinging SQL master database
[2018/04/12 17:37:37 CEST] [INFO] Current version is 4.7.1 (4.7.3/Thu Mar  8 19:58:02 UTC 2018/659ce8c60012a7d5fd597997b1794ac512b3b155/none)
[2018/04/12 17:37:37 CEST] [INFO] Enterprise Enabled: false
[2018/04/12 17:37:37 CEST] [INFO] Current working directory is /srv/mattermost
[2018/04/12 17:37:37 CEST] [INFO] Loaded config file from /srv/mattermost/config/config.json
[2018/04/12 17:37:37 CEST] [INFO] Connection to S3 or minio is good. Bucket exists.
[2018/04/12 17:37:37 CEST] [INFO] Starting up plugins
[2018/04/12 17:37:37 CEST] [WARN] unable to create user namespace: fork/exec /proc/self/exe: permission denied
[2018/04/12 17:37:37 CEST] [WARN] plugin sandboxing is not supported. plugins will run with the same access level as the server
[2018/04/12 17:37:39 CEST] [INFO] Activated jira plugin
[2018/04/12 17:37:39 CEST] [INFO] Starting Server...
[2018/04/12 17:37:39 CEST] [INFO] Server is listening on [::]:8065
[2018/04/12 17:37:39 CEST] [INFO] API version 3 is scheduled for deprecation. Please see https://api.mattermost.com for details.
[2018/04/12 17:37:39 CEST] [INFO] Starting 2 websocket hubs
[2018/04/12 17:37:39 CEST] [INFO] Starting workers
[2018/04/12 17:37:39 CEST] [INFO] Starting schedulers.

Hope this helps.

8

I bumped up the logging level on our server to DEBUG and tried uploading a file again. I’m still not seeing any error messages but I do see this:

[2018/04/17 22:03:03 UTC] [DEBG] POST - /api/v4/files
[2018/04/17 22:03:03 UTC] [INFO] Loaded system translations for 'en' from '/home/ubuntu/mattermost/i18n/en.json'
[2018/04/17 22:03:03 UTC] [INFO] Server is initializing...
[2018/04/17 22:03:03 UTC] [DEBG] Parsing server templates at /home/ubuntu/mattermost/templates/
[2018/04/17 22:03:03 UTC] [INFO] Pinging SQL master database
[2018/04/17 22:03:03 UTC] [DEBG] Deleting any unused pre-release features
[2018/04/17 22:03:03 UTC] [DEBG] Initializing built-in plugin: ldapextras
[2018/04/17 22:03:03 UTC] [INFO] Current version is 4.8.0 (4.8.0/Thu Mar 15 23:11:12 UTC 2018/d1ed79a66c7930020b7fda046a11050f5890c84e/6f563c1fa497d123134fd499eb37674eb2511325)
[2018/04/17 22:03:03 UTC] [INFO] Enterprise Enabled: true

Notice that a POST to /api/v4/files is detected and then the next message looks like the system is reloading which suggests to me that Mattermost is crashing while attempting to process that request. I see that repeat every time a file upload is attempted. Is there a way to get Mattermost to spit out what the error actually is?

9

If the server is crashing, there should be a stack trace printed to stderr. Can you post that?

10 
---------START-HTTP---------
POST /20180419/teams/noteam/channels/u7tbqcyetpds8r481geswme3gy/users/1aujpshixbbutkcpgu6yqq1xfa/xnzh4gghw3rtzrae3c9efn63no/test.docx?uploads= HTTP/1.1

(POST details truncated)

---------END-HTTP---------
fatal error: runtime: out of memory

runtime stack:
(stack trace truncated)

Bet you’ll never guess what the problem was! :wink:

This is a pretty small server that I maintain for a small group of friends and only runs on about half a GB of memory. I added a 4 GB swapfile to the server - it didn’t have one previously. With the extra available memory, uploads are again working.

I did notice that image uploads do take a lot longer to process. Not entirely surprising, given the performance penalty from using hard drive space for RAM.

I am still curious to know why this broke after the upgrade, though. It seems unlikely to be a coincidence that I started seeing out of memory errors during upload at the same time I upgraded, doesn’t it? And it also seems strange that even small images (<100 KB) were causing this problem and continue to take several seconds to process, even with the swapfile speed penalty. Did anything change with the way file uploads are handled?

1 Like
11

I can confirm that it seems to have been a memory issue.

My service is being run with 512mb of RAM, added a swap file as suggested by @CraigPhillips and files are now being sent without any issues at all.

12

Can also confirm problems uploading files on our collaboration platform https://geschichtenkapsel.ninja. It first occurred 2 days after updating from 4.4.2 to 4.9.2. Mattermost was down/stuck, I had to restart the service. Checking the logs didn’t help (hadn’t activated DEBUG-mode at that time). The problem first occured with rather large file (10 MB), but was reproducible with files of all sizes and kinds, then (also 45 KB images). After creating and mounting a larger SWAP, the problem vanished.

I exactly followed this manual to increase SWAP size: https://docs.bitnami.com/installer/faq/linux-faq/#how-to-increase-the-available-memory

System info:
Mattermost-Version: 4.9.2 (Team Edition)
Datenbankschema-Version: 4.9.0
Datenbank: mysql
Debian-8-x86_64 (AMI - Amazon Machine Image Mattermost Team Edition Certified by Bitnami)
AWS Virtual Server (t2.micro with 1 GB RAM)