Client accessing server resulting in 403 errors

Troubleshooting
1

For feature requests, please see: https://mattermost.com/suggestions/.

For troubleshooting questions, please post in the following format:

Summary
Client is hitting server which results in HTTP 403 errors

Steps to reproduce
Windows Client 5.5.0, Server 9.2.2.0 on Ubuntu 22.04

Expected behavior
Client should not hit URLs resulting in 403 errors, which triggered IP ban via fail2ban

Observed behavior
Multiple entries similar to below:
NGINX Log: - - [01/Dec/2023:17:02:39 -0500] "GET /api/v4/cloud/subscription/self-serve-status HTTP/2.0" 403 179 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.5845.97 Electron/26.1.0 Safari/537.36 Mattermost/5.5.0"

  • No log message in mattermost log file
2

What URL are they using? What happens when they visit that URL in a browser? This looks like an nginx misconfiguration. What does it’s config look like? Make sure it’s pointing to a valid URL.

3

They are using the client to the base URL of the server. It happened a few times in the logs.

I’m not sure that they would be going to this URL on their own - this looks like a call by the desktop client.

/api/v4/cloud/subscription/self-serve-status

When i went there directly, after logging in, this is what I got:

{"id":"app.license.generate_renewal_token.no_license","message":"No license present","detailed_error":"","request_id":"mbba6nfx13your6cs5kgsfin8r","status_code":400}

4

Exactly same problem here.
Generally Mattermost is working fine for us, but call’s has stopped working. When going to the “View” → “Developer tools for current server” as suggested by the troubleshooting guide, it get that in the developer console:
{“id”:“app.license.generate_renewal_token.no_license”,“message”:“No license present”,“detailed_error”:“”,“request_id”:“1ynmx7yejirfugztssez3myg9y”,“status_code”:400}

No proxy (nginx) in front of our Mattermost instance.

5

@thystra @MortenVinding are you seeing this with admin users, non-admin users, or both?

6

@MortenVinding what version of the Mattermost server are you running?

7

The initial complaint happened with a non-admin user. The error log I posted after came from me, logging in as an admin user directly through a web browser and not the MM desktop client.

8

@thystra I’m told this issue should be fixed in 9.3

9

Ok, I’m on to 9.4.2 presently. Glad to hear it is fixed.

10

Have only tried with my own admin user.
I will try to make a regular user test it.

11

From the about:

Mattermost Enterprise Edition
Modern communication from behind your firewall.

Mattermost Version: 9.3.0
Database Schema Version: 114
Build Number: 7014621505
Database: postgres
12

@MortenVinding I suspect you’re running into a different issue. Calls does (or should!) not depend on a license. What happened between calls working and then not working? Anything in /opt/mattermost/logs/mattermost.log? A firewall / network change could have done this too.

In case you haven’t seen it, Calls self-hosted deployment — Mattermost documentation gives a lot of details of how Calls works. That may help. I’ll ask about your “No license found” message.

13

Thank you John for prompt reply.

Actually I’m not really sure what happened between, unfortunately we have both upgraded Mattermost and made some network changes.

I have tested port connection according to Calls self-hosted deployment — Mattermost documentation

mvi@3bzrvp2:~$ for PORT in http https 8443 8045 3478; do nc -vzw2 mattermost.dmi.dk $PORT; done
Connection to mattermost.dmi.dk (172.25.4.87) 80 port [tcp/http] succeeded!
Connection to mattermost.dmi.dk (172.25.4.87) 443 port [tcp/https] succeeded!
Connection to mattermost.dmi.dk (172.25.4.87) 8443 port [tcp/*] succeeded!
nc: connect to mattermost.dmi.dk (172.25.4.87) port 8045 (tcp) failed: Connection refused
nc: connect to mattermost.dmi.dk (172.25.4.87) port 3478 (tcp) failed: Connection refused

There is no services listening on rtcd/8045 and stun/3478, but it’s my understanding that it’s also not necessary?

Yes there is a LOT in the log :slight_smile:
Here is the output when I try to make a call to a college.
He recevices the call but are not really able to answer it.

Sorry let me know if it’s better if I create a new ticket for our specefic problem?

{"timestamp":"2024-01-24 09:54:55.969 Z","level":"info","msg":"signaling state changed to have-remote-offer","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onSignalingStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:274"}
{"timestamp":"2024-01-24 09:54:55.971 Z","level":"info","msg":"signaling state changed to stable","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onSignalingStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:274"}
{"timestamp":"2024-01-24 09:54:55.971 Z","level":"info","msg":"Setting new connection state: Checking","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).updateConnectionState github.com/pion/ice/v2@v2.3.11/agent.go:504"}
{"timestamp":"2024-01-24 09:54:55.972 Z","level":"info","msg":"ICE connection state changed: checking","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onICEConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:484"}
{"timestamp":"2024-01-24 09:54:55.972 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:55.973 Z","level":"info","msg":"peer connection state changed: connecting","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:498"}
{"timestamp":"2024-01-24 09:54:55.973 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:55.974 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:55.975 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.085 Z","level":"info","msg":"Ignoring remote candidate with tcpType active: tcp4 host 172.25.29.163:9","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).AddRemoteCandidate github.com/pion/ice/v2@v2.3.11/agent.go:667"}
{"timestamp":"2024-01-24 09:54:56.110 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.111 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.313 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.314 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.516 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.517 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.719 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.720 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.922 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:56.923 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:57.126 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.163:48820: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:57.127 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:57.329 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:57.531 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:21635: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.246 Z","level":"info","msg":"signaling state changed to have-remote-offer","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onSignalingStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:274"}
{"timestamp":"2024-01-24 09:54:58.247 Z","level":"info","msg":"signaling state changed to stable","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onSignalingStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:274"}
{"timestamp":"2024-01-24 09:54:58.248 Z","level":"info","msg":"Setting new connection state: Checking","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).updateConnectionState github.com/pion/ice/v2@v2.3.11/agent.go:504"}
{"timestamp":"2024-01-24 09:54:58.248 Z","level":"info","msg":"ICE connection state changed: checking","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onICEConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:484"}
{"timestamp":"2024-01-24 09:54:58.249 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:58.249 Z","level":"info","msg":"peer connection state changed: connecting","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:498"}
{"timestamp":"2024-01-24 09:54:58.250 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:58.251 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:58.252 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:58.252 Z","level":"warn","msg":"Failed to ping without candidate pairs. Connection is not possible yet.","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*Agent).pingAllCandidates github.com/pion/ice/v2@v2.3.11/agent.go:545"}
{"timestamp":"2024-01-24 09:54:58.301 Z","level":"info","msg":"Ignoring remote candidate with tcpType active: tcp4 host 172.25.29.44:9","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).AddRemoteCandidate github.com/pion/ice/v2@v2.3.11/agent.go:667"}
{"timestamp":"2024-01-24 09:54:58.301 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.359 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.360 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.562 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.563 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.765 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.766 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.968 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:58.968 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.170 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.172 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.373 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.375 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.577 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->172.25.29.44:52998: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.578 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:54:59.780 Z","level":"info","msg":"Failed to send packet: write udp4 127.0.0.1:8443->130.225.33.62:13900: sendto: invalid argument","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*candidateBase).writeTo github.com/pion/ice/v2@v2.3.11/candidate_base.go:340"}
{"timestamp":"2024-01-24 09:55:01.042 Z","level":"warn","msg":"failed to get server reflexive address udp4 stun:stun.global.calls.mattermost.com:3478: read udp4 0.0.0.0:49394: i/o timeout","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.closeConnAndLog github.com/pion/ice/v2@v2.3.11/gather.go:35"}
{"timestamp":"2024-01-24 09:55:03.250 Z","level":"warn","msg":"failed to get server reflexive address udp4 stun:stun.global.calls.mattermost.com:3478: read udp4 0.0.0.0:60942: i/o timeout","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.closeConnAndLog github.com/pion/ice/v2@v2.3.11/gather.go:35"}
{"timestamp":"2024-01-24 09:55:03.347 Z","level":"warn","msg":"Failed to read from candidate tcp4 host 127.0.1.1:8443: io: read/write on closed pipe","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*candidateBase).recvLoop github.com/pion/ice/v2@v2.3.11/candidate_base.go:230"}
{"timestamp":"2024-01-24 09:55:03.347 Z","level":"warn","msg":"Failed to read from candidate tcp4 host 127.0.0.1:8443: io: read/write on closed pipe","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*candidateBase).recvLoop github.com/pion/ice/v2@v2.3.11/candidate_base.go:230"}
{"timestamp":"2024-01-24 09:55:03.348 Z","level":"info","msg":"Setting new connection state: Closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).updateConnectionState github.com/pion/ice/v2@v2.3.11/agent.go:504"}
{"timestamp":"2024-01-24 09:55:03.348 Z","level":"info","msg":"peer connection state changed: closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:498"}
{"timestamp":"2024-01-24 09:55:03.348 Z","level":"info","msg":"ICE connection state changed: closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onICEConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:484"}
{"timestamp":"2024-01-24 09:55:03.349 Z","level":"warn","msg":"Failed to start manager: connecting canceled by caller","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).startTransports github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:2260"}
{"timestamp":"2024-01-24 09:55:03.349 Z","level":"warn","msg":"undeclaredMediaProcessor failed to open SrtpSession: the DTLS transport has not started yet","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).undeclaredRTPMediaProcessor github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1646"}
{"timestamp":"2024-01-24 09:55:03.349 Z","level":"warn","msg":"Failed to start SCTP: DTLS not established","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).startSCTP github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1474"}
{"timestamp":"2024-01-24 09:55:03.349 Z","level":"warn","msg":"undeclaredMediaProcessor failed to open SrtcpSession: the DTLS transport has not started yet","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).undeclaredRTCPMediaProcessor github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1690"}
{"timestamp":"2024-01-24 09:55:10.942 Z","level":"warn","msg":"Failed to read from candidate tcp4 host 127.0.0.1:8443: io: read/write on closed pipe","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*candidateBase).recvLoop github.com/pion/ice/v2@v2.3.11/candidate_base.go:230"}
{"timestamp":"2024-01-24 09:55:10.942 Z","level":"warn","msg":"Failed to read from candidate tcp4 host 127.0.1.1:8443: io: read/write on closed pipe","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"ice/v2.(*candidateBase).recvLoop github.com/pion/ice/v2@v2.3.11/candidate_base.go:230"}
{"timestamp":"2024-01-24 09:55:10.942 Z","level":"info","msg":"Setting new connection state: Closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"ice/v2.(*Agent).updateConnectionState github.com/pion/ice/v2@v2.3.11/agent.go:504"}
{"timestamp":"2024-01-24 09:55:10.942 Z","level":"warn","msg":"Failed to start manager: connecting canceled by caller","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).startTransports github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:2260"}
{"timestamp":"2024-01-24 09:55:10.942 Z","level":"info","msg":"peer connection state changed: closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:498"}
{"timestamp":"2024-01-24 09:55:10.943 Z","level":"info","msg":"ICE connection state changed: closed","caller":"app/plugin_api.go:985","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Info log.go:104","origin":"webrtc/v3.(*PeerConnection).onICEConnectionStateChange github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:484"}
{"timestamp":"2024-01-24 09:55:10.943 Z","level":"warn","msg":"undeclaredMediaProcessor failed to open SrtpSession: the DTLS transport has not started yet","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).undeclaredRTPMediaProcessor github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1646"}
{"timestamp":"2024-01-24 09:55:10.943 Z","level":"warn","msg":"Failed to start SCTP: DTLS not established","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).startSCTP github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1474"}
{"timestamp":"2024-01-24 09:55:10.943 Z","level":"warn","msg":"undeclaredMediaProcessor failed to open SrtcpSession: the DTLS transport has not started yet","caller":"app/plugin_api.go:991","plugin_id":"com.mattermost.calls","origin":"main.(*logger).Warn log.go:108","origin":"webrtc/v3.(*PeerConnection).undeclaredRTCPMediaProcessor github.com/pion/webrtc/v3@v3.2.21/peerconnection.go:1690"}
14

Morten - if you have a paid-for subscription, I’d recommend opening a support ticket via https://support.mattermost.com/ Our support folks are a lot smarter than I am! This forum is for community support… we cannot guarantee any result or even response here. I try to help out as much as I can, but can’t promise to be able to resolve this!

You need to make sure you allow UDP on 8443 bidirectionally, from client to server and server to client. Your log is full of errors about can’t communicate via UDP. Newer versions of the Calls plugin will fall back to TCP, but that becomes a lot more sensitive to latency. I see errors about TCP in there too, even though your netcat test succeeded. I’d check the firewalls on both the server and the client, as well as anything in between… load balancers, security groups, whatever.

I also saw attempts to contact 130.225.33.62 as well as 172.25.4.87 ‘mattermost.dmi.dk’ does not resolve for me, so I suspect you may have a DNS issue involved as well.

15

Sorry no we do not have a subscription (governmental organization) :frowning:

But your help is very much appreciated!

I got hold of one of our network guys, and the UDP port was in fact not open.
It is now, but I get exactly the same errors in the log when trying to make a call.

Our server mattermost.dmi.dk is only accessible on our local network, and that is the one with the 172.25.4.87 ip.

130.225.33.62 is the clients exit IP to the internet, the server is using 130.226.71.190
But I don’t know where that is coming from. It a local deployment mattermost.dmi.dk is pointing at 172.25.4.87 so it shouldn’t really care about internet access.

Or am I missing something here? Is internet access somehow required for call’s?

16

No, Internet access is not required to make calls. Make sure that UDP is allowed in both directions. You may need to check the firewalls on the Mattermost server and the clients, as well as all network infrastructure in between. If something like AWS is involved, check the Security Groups.

Can you do the simple test with netcat at the bottom? How about tcpdump? Can you put a test client on the same segment as the Mattermost server and verify it works?

17

Just tested with tcpdump on the Mattermost server, lots of packages:

root@mattermost:/home/adm_mvi# tcpdump -nn -A udp port 8443 
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on ens160, link-type EN10MB (Ethernet), snapshot length 262144 bytes
12:24:22.377877 IP 172.25.4.87.8443 > 172.25.29.163.51767: UDP, length 100
E...L.@.@.s....W.... ..7.lz....P!..B..c.-...6.7.....TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~.......R..|.+(@q.S......5.".(..*:..
12:24:22.378060 IP 172.25.4.87.8443 > 172.25.29.163.51767: UDP, length 100
E...L.@.@.s....W.... ..7.lz....P!..BCG3.r.~e........TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~..........j.....g........0..(..8..O
12:24:22.534397 IP 172.25.4.87.8443 > 172.25.29.163.51767: UDP, length 100
E...L.@.@.s~...W.... ..7.lz....P!..B..q.P..9`.......TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~.......:.a\Y.....d.!..eM....(...NR.
12:24:22.534575 IP 172.25.4.87.8443 > 172.25.29.163.51767: UDP, length 100
E...L.@.@.s}...W.... ..7.lz....P!..B1..;.T.._c......TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~.......,f.LV.1q...*...T8&...(..cUfl
12:24:22.535391 IP 172.25.4.87.8443 > 130.225.33.62.2876: UDP, length 100
E.....@.@......W..!> ..<.lU....P!..Bg..=......tG....TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~........i..8e...m...4.*.O...(......
12:24:22.535606 IP 172.25.4.87.8443 > 130.225.33.62.2876: UDP, length 100
E..../@.@......W..!> ..<.lU....P!..B...n.MD...<Y....TqjE:xgYlDcVocyGfOrCx....)..j.....J..$..~...............;od......a...(..?...

netcat from the mattermost server to my client is also working, and what ever I input on the server is reflected on my client machine.

There is no firewalls enabled on either of them. (checked with “ufw status” and “iptables -L -n”).

I will se if I somehow can put a mattermost client on the same network as the server.

Thank you so much for your help :slight_smile:
I will be on holiday in next week but I will pick up on this when I return.

18

Have only tried with my own admin user.

19

I got hold of one of our network guys, and the UDP port was in fact not open..
.

20

Upraded to MM 9.5.1 and calls are working again!
Not sure if it’s the upgrade or there has been some changes in our network…