Problems making synapse (1.4.1) reliable working together with coturn (4.5.0.7)

[chrissi55]

Description

Steps to reproduce

• list the steps

1. install synapse, install coturn

2. config /etc/matrix-synapse/homeserver.yaml
   using lets encrypt certs for ssl

3. use for turnserver the following instruction:
   https://gist.github.com/maxidorius/2b0acc2e707ae9a2d6d0267026a1024f

4. in my case that means
   homeserver.yaml =
   `turn_uris:
   - "turns:turn.my.domain?transport=udp"
   - "turns:turn.my.domain?transport=tcp"
   - "turn:turn.my.domain?transport=udp"
   - "turn:turn.my.domain?transport=tcp"

     # The shared secret used to compute passwords for the TURN server
     #
     turn_shared_secret:MY.SECRET.KEY
   
     turn_user_lifetime: 1h
     turn_allow_guests: True
   

5. for the coturn i edit the /etc/turnserver.conf as followssyslog

 lt-cred-mech
 use-auth-secret
 static-auth-secret=MY.SECRET.KEY
 realm=my.domain

 cert=/path-to-the-letsencrypt-cert-folder/fullchain.pem
 pkey=/path-to-the-letsencrypt-cert-folder/privkey.pem

 no-udp
 external-ip=my.public.IPv4.from.Provider
 min-port=64000
 max-port=65535`    

6. Turnserver is configured as "Exposed Host" no local rules (iptables) that block transfer of UDP, TCP or Ports like 3478, 3479, 5349 and/or 5350

• then restart all services (reboot server)
• then make a testcall between riot-android client (connected via LTE, mobile Data - WLAN disabled!!) and another client outside the synapse server network.
• make calls between clients that are in the same Network as the synapse-server with clients that are ouside the network of the synapse server

I expected that a initiated call will cause a "incoming call event" on the other client side.
This is working well in all cases. When clicking on "accept call" sometimes it works - after a few seconds i see the counter of the elapsed time working and can hear my called client.
But in many cases (later tried it with same call partner or new partners) the connection is not successfully established. I see "call partner has stopped the call"...

My logfiles of coturn says:

Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <>: incoming packet BINDING processed, success Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:25 turnserver: 30: IPv4. tcp or tls connected to: [public.IPv4.client]:18170 Oct 12 08:26:25 turnserver: 30: IPv4. Local relay addr: [local.IPv4.turnserver]:60947 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: new, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=600 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:25 turnserver: 30: IPv4. tcp or tls connected to: [public.IPv4.client]:21151 Oct 12 08:26:25 turnserver: 30: IPv4. tcp or tls connected to: [public.IPv4.client]:9059 Oct 12 08:26:25 turnserver: 30: session 001000000000000003: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:25 turnserver: 30: session 000000000000000003: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 30: session 000000000000000003: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 30: session 000000000000000003: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 30: session 000000000000000003: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 30: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 30: IPv4. Local relay addr: [local.IPv4.turnserver]:55690 Oct 12 08:26:25 turnserver: 30: session 001000000000000003: new, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=600 Oct 12 08:26:25 turnserver: 30: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:25 turnserver: 30: session 000000000000000004: TLS/TCP socket disconnected: [public.IPv4.client]:18170 Oct 12 08:26:25 turnserver: 30: session 000000000000000004: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.client]:18170, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:25 turnserver: 31: session 000000000000000005: TLS/TCP socket disconnected: [public.IPv4.client]:9059 Oct 12 08:26:25 turnserver: 31: session 000000000000000005: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.client]:9059, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:25 turnserver: 31: session 001000000000000003: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000003: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000003: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000003: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000002: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000002: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000001: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000002: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000002: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000002: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000002: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000001: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 001000000000000002: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 001000000000000002: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000001: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000001: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000003: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:25 turnserver: 31: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:25 turnserver: 31: session 000000000000000003: peer [public.IPv4.client] lifetime updated: 600 Oct 12 08:26:25 turnserver: 31: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 12 08:26:26 turnserver: 31: session 000000000000000001: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:26 turnserver: 31: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:30 turnserver: 36: session 000000000000000003: refreshed, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=0 Oct 12 08:26:30 turnserver: 36: session 000000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:26:30 turnserver: 36: session 001000000000000003: refreshed, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=0 Oct 12 08:26:30 turnserver: 36: session 001000000000000003: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:26:30 turnserver: 36: session 001000000000000003: TCP socket closed remotely [public.IPv4.client]:21151 Oct 12 08:26:30 turnserver: 36: session 001000000000000003: closed (2nd stage), user <1570864258:@user1:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:21151, reason: TCP connection closed by client (callback) Oct 12 08:26:30 turnserver: 36: session 001000000000000003: delete: realm=<my.domain>, username=<1570864258:@user1:chat.my.domain> Oct 12 08:26:30 turnserver: 36: session 001000000000000003: peer [local.IPv4.turnserver] deleted Oct 12 08:26:30 turnserver: 36: session 001000000000000003: peer [public.IPv4.client] deleted Oct 12 08:26:30 turnserver: 36: session 001000000000000003: peer [public.IPv4.client] deleted Oct 12 08:26:31 turnserver: 36: session 000000000000000001: refreshed, realm=<my.domain>, username=<1570863445:@user2:chat.my.domain>, lifetime=0 Oct 12 08:26:31 turnserver: 36: session 000000000000000001: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:26:31 turnserver: 36: session 001000000000000002: refreshed, realm=<my.domain>, username=<1570863445:@user2:chat.my.domain>, lifetime=0 Oct 12 08:26:31 turnserver: 36: session 001000000000000002: realm <my.domain> user <1570863445:@user2:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:26:31 turnserver: 36: session 001000000000000002: TCP socket closed remotely [public.IPv4.client]:4045 Oct 12 08:26:31 turnserver: 36: session 001000000000000002: closed (2nd stage), user <1570863445:@user2:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:4045, reason: TCP connection closed by client (callback) Oct 12 08:26:31 turnserver: 36: session 001000000000000002: delete: realm=<my.domain>, username=<1570863445:@user2:chat.my.domain> Oct 12 08:26:31 turnserver: 36: session 001000000000000002: peer [public.IPv4.client] deleted Oct 12 08:26:31 turnserver: 36: session 001000000000000002: peer [local.IPv4.turnserver] deleted Oct 12 08:26:31 turnserver: 36: session 001000000000000002: peer [public.IPv4.client] deleted Oct 12 08:26:31 turnserver: 37: session 000000000000000003: closed (2nd stage), user <1570864258:@user1:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:15525, reason: allocation timeout Oct 12 08:26:31 turnserver: 37: session 000000000000000003: delete: realm=<my.domain>, username=<1570864258:@user1:chat.my.domain> Oct 12 08:26:31 turnserver: 37: session 000000000000000003: peer [local.IPv4.turnserver] deleted Oct 12 08:26:31 turnserver: 37: session 000000000000000003: peer [public.IPv4.client] deleted Oct 12 08:26:31 turnserver: 37: session 000000000000000003: peer [public.IPv4.client] deleted Oct 12 08:26:32 turnserver: 37: session 000000000000000001: closed (2nd stage), user <1570863445:@user2:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:15122, reason: allocation timeout Oct 12 08:26:32 turnserver: 37: session 000000000000000001: delete: realm=<my.domain>, username=<1570863445:@user2:chat.my.domain> Oct 12 08:26:32 turnserver: 37: session 000000000000000001: peer [public.IPv4.client] deleted Oct 12 08:26:32 turnserver: 37: session 000000000000000001: peer [local.IPv4.turnserver] deleted Oct 12 08:26:32 turnserver: 37: session 000000000000000001: peer [public.IPv4.client] deleted Oct 12 08:26:44 mail synapse[10421]: 2019-10-12 08:26:44,172 - synapse.http.site - 203 - WARNING - GET-1345- Error processing request <XForwardedForRequest at 0x7f6632fb5e48 method='GET' uri='/_matrix/client/r0/sync?filter=6&timeout=30000&since=s222065_4528381_10_157998_25249_404_37024_19146_2' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly. Oct 12 08:26:49 turnserver: 54: handle_udp_packet: New UDP endpoint: local addr [local.IPv4.turnserver]:3478, remote addr [public.IPv4.client]:6516 Oct 12 08:26:49 turnserver: 54: session 001000000000000004: realm <my.domain> user <>: incoming packet BINDING processed, success Oct 12 08:26:49 turnserver: 54: session 001000000000000004: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:49 turnserver: 54: IPv4. Local relay addr: [local.IPv4.turnserver]:60616 Oct 12 08:26:49 turnserver: 54: session 001000000000000004: new, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=600 Oct 12 08:26:49 turnserver: 54: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:49 turnserver: 54: IPv4. tcp or tls connected to: [public.IPv4.client]:12315 Oct 12 08:26:49 turnserver: 54: IPv4. tcp or tls connected to: [public.IPv4.client]:19929 Oct 12 08:26:49 turnserver: 54: IPv4. tcp or tls connected to: [public.IPv4.client]:17384 Oct 12 08:26:49 turnserver: 54: session 000000000000000007: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:49 turnserver: 54: session 001000000000000005: TLS/TCP socket disconnected: [public.IPv4.client]:12315 Oct 12 08:26:49 turnserver: 54: session 001000000000000005: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.client]:12315, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:49 synapse[10421]: 2019-10-12 08:26:49,156 - synapse.http.server - 458 - WARNING - GET-1345- Not sending response to request <XForwardedForRequest at 0x7f6632fb5e48 method='GET' uri='/_matrix/client/r0/sync?filter=6&timeout=30000&since=s222065_4528381_10_157998_25249_404_37024_19146_2' clientproto='HTTP/1.0' site=8008>, already disconnected. Oct 12 08:26:49 turnserver: 54: session 000000000000000006: TLS/TCP socket disconnected: [public.IPv4.client]:19929 Oct 12 08:26:49 turnserver: 54: session 000000000000000006: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.client]:19929, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:49 turnserver: 54: IPv4. Local relay addr: [local.IPv4.turnserver]:55952 Oct 12 08:26:49 turnserver: 54: session 000000000000000007: new, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=600 Oct 12 08:26:49 turnserver: 54: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:50 turnserver: 56: handle_udp_packet: New UDP endpoint: local addr [local.IPv4.turnserver]:3478, remote addr [public.IPv4.server]:40606 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <>: incoming packet BINDING processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:50 turnserver: 56: IPv4. Local relay addr: [local.IPv4.turnserver]:55581 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: new, realm=<my.domain>, username=<1570862114:@user2:chat.my.domain>, lifetime=600 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000008: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000008: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000008: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000008: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: IPv4. tcp or tls connected to: [public.IPv4.server]:57330 Oct 12 08:26:50 turnserver: 56: IPv4. tcp or tls connected to: [public.IPv4.server]:47692 Oct 12 08:26:50 turnserver: 56: IPv4. tcp or tls connected to: [public.IPv4.server]:57332 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 12 08:26:50 turnserver: 56: IPv4. Local relay addr: [local.IPv4.turnserver]:65397 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: new, realm=<my.domain>, username=<1570862114:@user2:chat.my.domain>, lifetime=600 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000010: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000009: TLS/TCP socket disconnected: [public.IPv4.server]:57330 Oct 12 08:26:50 turnserver: 56: session 000000000000000009: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.server]:57330, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:50 turnserver: 56: session 001000000000000006: TLS/TCP socket disconnected: [public.IPv4.server]:57332 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 001000000000000006: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.server]:57332, reason: TLS/TCP socket buffer operation error (callback) Oct 12 08:26:50 turnserver: 56: session 000000000000000010: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:50 turnserver: 56: session 000000000000000010: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:50 turnserver: 56: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 000000000000000007: peer [local.IPv4.riot-web-client] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 000000000000000007: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 001000000000000004: peer [local.IPv4.riot-web-client] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 000000000000000007: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 000000000000000007: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 001000000000000004: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 001000000000000004: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 56: session 001000000000000004: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 12 08:26:51 turnserver: 56: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 57: session 000000000000000010: peer [local.IPv4.turnserver] lifetime updated: 600 Oct 12 08:26:51 turnserver: 57: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 12 08:26:51 turnserver: 57: session 000000000000000007: peer [local.IPv4.turnserver] lifetime updated: 600 Oct 12 08:26:51 turnserver: 57: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 12 08:26:51 turnserver: 57: session 000000000000000008: peer [public.IPv4.client] lifetime updated: 300 Oct 12 08:26:51 turnserver: 57: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 12 08:26:51 turnserver: 57: session 000000000000000008: peer [public.IPv4.client] lifetime updated: 600 Oct 12 08:26:51 turnserver: 57: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 12 08:26:59 turnserver: 64: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet BINDING processed, success Oct 12 08:27:00 turnserver: 66: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet BINDING processed, success Oct 12 08:27:04 turnserver: 69: session 000000000000000008: refreshed, realm=<my.domain>, username=<1570862114:@user2:chat.my.domain>, lifetime=0 Oct 12 08:27:04 turnserver: 69: session 000000000000000008: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:27:04 turnserver: 69: session 000000000000000010: refreshed, realm=<my.domain>, username=<1570862114:@user2:chat.my.domain>, lifetime=0 Oct 12 08:27:04 turnserver: 69: session 000000000000000010: realm <my.domain> user <1570862114:@user2:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:27:04 turnserver: 69: session 000000000000000010: TCP socket closed remotely [public.IPv4.server]:47692 Oct 12 08:27:04 turnserver: 69: session 000000000000000010: closed (2nd stage), user <1570862114:@user2:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.server]:47692, reason: TCP connection closed by client (callback) Oct 12 08:27:04 turnserver: 69: session 000000000000000010: delete: realm=<my.domain>, username=<1570862114:@user2:chat.my.domain> Oct 12 08:27:04 turnserver: 69: session 000000000000000010: peer [public.IPv4.client] deleted Oct 12 08:27:04 turnserver: 69: session 000000000000000010: peer [local.IPv4.turnserver] deleted Oct 12 08:27:04 turnserver: 69: session 000000000000000010: peer [public.IPv4.client] deleted Oct 12 08:27:04 turnserver: 70: session 001000000000000004: refreshed, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=0 Oct 12 08:27:04 turnserver: 70: session 001000000000000004: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:27:04 turnserver: 70: session 000000000000000007: refreshed, realm=<my.domain>, username=<1570864258:@user1:chat.my.domain>, lifetime=0 Oct 12 08:27:04 turnserver: 70: session 000000000000000007: realm <my.domain> user <1570864258:@user1:chat.my.domain>: incoming packet REFRESH processed, success Oct 12 08:27:04 turnserver: 70: session 000000000000000007: TCP socket closed remotely [public.IPv4.client]:17384 Oct 12 08:27:04 turnserver: 70: session 000000000000000007: closed (2nd stage), user <1570864258:@user1:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:17384, reason: TCP connection closed by client (callback) Oct 12 08:27:04 turnserver: 70: session 000000000000000007: delete: realm=<my.domain>, username=<1570864258:@user1:chat.my.domain> Oct 12 08:27:04 turnserver: 70: session 000000000000000007: peer [local.IPv4.riot-web-client] deleted Oct 12 08:27:04 turnserver: 70: session 000000000000000007: peer [local.IPv4.turnserver] deleted Oct 12 08:27:05 turnserver: 70: session 000000000000000008: closed (2nd stage), user <1570862114:@user2:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.server]:40606, reason: allocation timeout Oct 12 08:27:05 turnserver: 70: session 000000000000000008: delete: realm=<my.domain>, username=<1570862114:@user2:chat.my.domain> Oct 12 08:27:05 turnserver: 70: session 000000000000000008: peer [public.IPv4.client] deleted Oct 12 08:27:05 turnserver: 70: session 000000000000000008: peer [local.IPv4.turnserver] deleted Oct 12 08:27:05 turnserver: 70: session 000000000000000008: peer [public.IPv4.client] deleted Oct 12 08:27:05 turnserver: 71: session 001000000000000004: closed (2nd stage), user <1570864258:@user1:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.client]:6516, reason: allocation timeout Oct 12 08:27:05 turnserver: 71: session 001000000000000004: delete: realm=<my.domain>, username=<1570864258:@user1:chat.my.domain> Oct 12 08:27:05 turnserver: 71: session 001000000000000004: peer [local.IPv4.riot-web-client] deleted Oct 12 08:27:05 turnserver: 71: session 001000000000000004: peer [local.IPv4.turnserver] deleted

Version information

I don't understand why sometimes it works (for a few calls) between same clients after i restarted the server and restarted the clients.

When testing between clients in different networks (local net and external Provider or foreign WLAN) sometimes it works with same config and a few hours later same clients can't establish a VoIP Connection. My problem is not reproducable for me.

So if a firewall rule hinders my connections it should do that all time in the same way i expect. And on the other hand i expect that if firewall is well configured or disabled no traffic between voip clients is blocked.

What does that mean if my logfile says:

"....closed (2nd stage), user <1570864258:@user_xy:chat.my.domain> realm <my.domain> origin <>, local Turnserver.IPv4:3478, remote public Client.IPv4:17384, reason: TCP connection closed by client (callback)...."

• Homeserver: own matrix-synapse Homeserver on VMware Server

If not matrix.org:

• (synapse)Version: 1.4.0
• (coturn)Version: 4.5.0.7
• Install method: from repositories (apt-get install coturn && apt-get install matrix-synapse)

• Platform: ubuntu server 18.04.3

My homeserver is running as VM on an VMware Server with 4GB RAM, configured to use PostgreSQL 11.5 as DataBase (psycopg2)
The Homeserver is behind a reverse Proxy (Nginx 1.17.4) with OpenSSL 1.1.1 (TLS 1.3) Support
Federation Tester says "success" in all checked points.

[chrissi55]

When a successful connection between a Apple iPad (Testaccount on matrix.org) and my Smartphone (@christian:chat.my.homeserver) is established i have these logs in syslog

Oct 13 10:53:46 [servername] systemd[1]: Stopped LSB: coturn TURN Server. Oct 13 10:53:46 [servername] systemd[1]: Starting LSB: coturn TURN Server... Oct 13 10:53:46 [servername] coturn[9317]: * Starting coturn turnserver Oct 13 10:53:46 [servername] turnserver: 0: Domain name: Oct 13 10:53:46 [servername] turnserver: 0: Default realm: my.domain Oct 13 10:53:46 [servername] turnserver: 0: #012CONFIG ERROR: Empty cli-password, and so telnet cli interface is disabled! Please set a non empty cli-password! Oct 13 10:53:46 [servername] turnserver: 0: SSL23: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: SSL23: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.0: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.0: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.1: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.1: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.2: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS1.2: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: TLS cipher suite: DEFAULT Oct 13 10:53:46 [servername] turnserver: 0: DTLS1.2: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: DTLS1.2: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: DTLS: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 10:53:46 [servername] turnserver: 0: DTLS: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 10:53:46 [servername] turnserver: 0: DTLS cipher suite: DEFAULT Oct 13 10:53:46 [servername] turnserver: 0: NO EXPLICIT LISTENER ADDRESS(ES) ARE CONFIGURED Oct 13 10:53:46 [servername] turnserver: 0: ===========Discovering listener addresses: ========= Oct 13 10:53:46 [servername] turnserver: 0: Listener address to use: 127.0.0.1 Oct 13 10:53:46 [servername] turnserver: 0: Listener address to use: [local.IPv4.turnserver] Oct 13 10:53:46 [servername] turnserver: 0: ===================================================== Oct 13 10:53:46 [servername] turnserver: 0: Total: 1 'real' addresses discovered Oct 13 10:53:46 [servername] turnserver: 0: ===================================================== Oct 13 10:53:46 [servername] turnserver: 0: NO EXPLICIT RELAY ADDRESS(ES) ARE CONFIGURED Oct 13 10:53:46 [servername] turnserver: 0: ===========Discovering relay addresses: ============= Oct 13 10:53:46 [servername] turnserver: 0: Relay address to use: [local.IPv4.turnserver] Oct 13 10:53:46 [servername] turnserver: 0: ===================================================== Oct 13 10:53:46 [servername] turnserver: 0: Total: 1 relay addresses discovered Oct 13 10:53:46 [servername] turnserver: 0: ===================================================== Oct 13 10:53:46 [servername] turnserver: 0: pid file created: /var/run/turnserver.pid Oct 13 10:53:46 [servername] systemd[1]: Started LSB: coturn TURN Server. Oct 13 10:53:46 [servername] coturn[9317]: ...done. Oct 13 10:53:46 [servername] turnserver: 0: IO method (main listener thread): epoll (with changelist) Oct 13 10:53:46 [servername] turnserver: 0: WARNING: I cannot support STUN CHANGE_REQUEST functionality because only one IP address is provided Oct 13 10:53:46 [servername] turnserver: 0: Wait for relay ports initialization... Oct 13 10:53:46 [servername] turnserver: 0: relay [local.IPv4.turnserver] initialization... Oct 13 10:53:46 [servername] turnserver: 0: relay [local.IPv4.turnserver] initialization done Oct 13 10:53:46 [servername] turnserver: 0: Relay ports initialization done Oct 13 10:53:46 [servername] turnserver: 0: IO method (general relay thread): epoll (with changelist) Oct 13 10:53:46 [servername] turnserver: 0: turn server id=0 created Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 10:53:46 [servername] turnserver: 0: IO method (general relay thread): epoll (with changelist) Oct 13 10:53:46 [servername] turnserver: 0: turn server id=1 created Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. DTLS listener opened on: 127.0.0.1:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. DTLS listener opened on: [local.IPv4.turnserver]:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 10:53:46 [servername] turnserver: 0: Total General servers: 2 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 10:53:46 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 10:53:46 [servername] turnserver: 0: IO method (auth thread): epoll (with changelist) Oct 13 10:53:46 [servername] turnserver: 0: SQLite DB connection success: /var/lib/turn/turndb Oct 13 10:53:46 [servername] turnserver: 0: IO method (auth thread): epoll (with changelist) Oct 13 10:53:46 [servername] turnserver: 0: IO method (admin thread): epoll (with changelist) Oct 13 10:54:03 [servername] turnserver: 17: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:5949 Oct 13 10:54:03 [servername] turnserver: 17: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:25538 Oct 13 10:54:03 [servername] turnserver: 17: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:6700 Oct 13 10:54:03 [servername] turnserver: 17: session 000000000000000001: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 13 10:54:03 [servername] turnserver: 17: IPv4. Local relay addr: [local.IPv4.turnserver]:57963 Oct 13 10:54:03 [servername] turnserver: 17: session 000000000000000001: new, realm=<my.domain>, username=<1570959907:@christian:chat.my.domain>, lifetime=600 Oct 13 10:54:03 [servername] turnserver: 17: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 13 10:54:03 [servername] turnserver: 17: session 000000000000000002: TLS/TCP socket disconnected: [public.IPv4.smartphone.client]:25538 Oct 13 10:54:03 [servername] turnserver: 17: session 000000000000000002: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.smartphone.client]:25538, reason: TLS/TCP socket buffer operation error (callback) Oct 13 10:54:03 [servername] turnserver: 17: session 001000000000000001: TLS/TCP socket disconnected: [public.IPv4.smartphone.client]:6700 Oct 13 10:54:03 [servername] turnserver: 17: session 001000000000000001: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.smartphone.client]:6700, reason: TLS/TCP socket buffer operation error (callback) Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: peer [local.IPv4.guest-network] lifetime updated: 300 Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 300 Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 300 Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 600 Oct 13 10:54:06 [servername] turnserver: 20: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: refreshed, realm=<my.domain>, username=<1570959907:@christian:chat.my.domain>, lifetime=0 Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet REFRESH processed, success Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: TCP socket error: Connection reset by peer [public.IPv4.smartphone.client]:5949 Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: closed (2nd stage), user <1570959907:@christian:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.smartphone.client]:5949, reason: TCP socket buffer operation error (callback) Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: delete: realm=<my.domain>, username=<1570959907:@christian:chat.my.domain> Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: peer [public.IPv4.turnserver] deleted Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: peer [local.IPv4.guest-network] deleted Oct 13 10:54:13 [servername] turnserver: 26: session 000000000000000001: peer [local.IPv4.turnserver] deleted

[chrissi55]

After a second reboot of synapse and coturn my connection crashed with that logs:

Oct 13 11:08:39 [servername] systemd[1]: Starting LSB: coturn TURN Server... Oct 13 11:08:39 [servername] coturn[14861]: * Starting coturn turnserver Oct 13 11:08:40 [servername] turnserver: 0: Domain name: Oct 13 11:08:40 [servername] turnserver: 0: Default realm: my.domain Oct 13 11:08:40 [servername] turnserver: 0: #012CONFIG ERROR: Empty cli-password, and so telnet cli interface is disabled! Please set a non empty cli-password! Oct 13 11:08:40 [servername] turnserver: 0: SSL23: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: SSL23: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.0: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.0: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.1: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.1: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.2: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS1.2: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: TLS cipher suite: DEFAULT Oct 13 11:08:40 [servername] turnserver: 0: DTLS1.2: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: DTLS1.2: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: DTLS: Certificate file found: /etc/matrix-synapse/ssl/fullchain.pem Oct 13 11:08:40 [servername] turnserver: 0: DTLS: Private key file found: /etc/matrix-synapse/ssl/privkey.pem Oct 13 11:08:40 [servername] turnserver: 0: DTLS cipher suite: DEFAULT Oct 13 11:08:40 [servername] turnserver: 0: NO EXPLICIT LISTENER ADDRESS(ES) ARE CONFIGURED Oct 13 11:08:40 [servername] turnserver: 0: ===========Discovering listener addresses: ========= Oct 13 11:08:40 [servername] turnserver: 0: Listener address to use: 127.0.0.1 Oct 13 11:08:40 [servername] turnserver: 0: Listener address to use: [local.IPv4.turnserver] Oct 13 11:08:40 [servername] turnserver: 0: ===================================================== Oct 13 11:08:40 [servername] turnserver: 0: Total: 1 'real' addresses discovered Oct 13 11:08:40 [servername] turnserver: 0: ===================================================== Oct 13 11:08:40 [servername] turnserver: 0: NO EXPLICIT RELAY ADDRESS(ES) ARE CONFIGURED Oct 13 11:08:40 [servername] turnserver: 0: ===========Discovering relay addresses: ============= Oct 13 11:08:40 [servername] turnserver: 0: Relay address to use: [local.IPv4.turnserver] Oct 13 11:08:40 [servername] turnserver: 0: ===================================================== Oct 13 11:08:40 [servername] turnserver: 0: Total: 1 relay addresses discovered Oct 13 11:08:40 [servername] turnserver: 0: ===================================================== Oct 13 11:08:40 [servername] turnserver: 0: pid file created: /var/run/turnserver.pid Oct 13 11:08:40 [servername] turnserver: 0: IO method (main listener thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: WARNING: I cannot support STUN CHANGE_REQUEST functionality because only one IP address is provided Oct 13 11:08:40 [servername] turnserver: 0: Wait for relay ports initialization... Oct 13 11:08:40 [servername] turnserver: 0: relay [local.IPv4.turnserver] initialization... Oct 13 11:08:40 [servername] coturn[14861]: ...done. Oct 13 11:08:40 [servername] systemd[1]: Started LSB: coturn TURN Server. Oct 13 11:08:40 [servername] turnserver: 0: relay [local.IPv4.turnserver] initialization done Oct 13 11:08:40 [servername] turnserver: 0: Relay ports initialization done Oct 13 11:08:40 [servername] turnserver: 0: IO method (general relay thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: turn server id=0 created Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 11:08:40 [servername] turnserver: 0: IO method (general relay thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: turn server id=1 created Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. DTLS listener opened on: 127.0.0.1:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. DTLS listener opened on: [local.IPv4.turnserver]:5349 Oct 13 11:08:40 [servername] turnserver: 0: Total General servers: 2 Oct 13 11:08:40 [servername] turnserver: 0: IO method (admin thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: IO method (auth thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: IO method (auth thread): epoll (with changelist) Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : 127.0.0.1:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : 127.0.0.1:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:3478 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/SCTP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 11:08:40 [servername] turnserver: 0: IPv4. TLS/TCP listener opened on : [local.IPv4.turnserver]:5349 Oct 13 11:08:40 [servername] turnserver: 0: SQLite DB connection success: /var/lib/turn/turndb Oct 13 11:10:56 [servername] turnserver: 136: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:5952 Oct 13 11:10:56 [servername] turnserver: 136: session 000000000000000001: realm <my.domain> user <>: incoming packet message processed, error 401: Unauthorized Oct 13 11:10:56 [servername] turnserver: 136: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:1642 Oct 13 11:10:56 [servername] turnserver: 136: IPv4. tcp or tls connected to: [public.IPv4.smartphone.client]:8766 Oct 13 11:10:56 [servername] turnserver: 136: IPv4. Local relay addr: [local.IPv4.turnserver]:50753 Oct 13 11:10:56 [servername] turnserver: 136: session 000000000000000001: new, realm=<my.domain>, username=<1570959907:@christian:chat.my.domain>, lifetime=600 Oct 13 11:10:56 [servername] turnserver: 136: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet ALLOCATE processed, success Oct 13 11:10:56 [servername] turnserver: 136: session 001000000000000001: TLS/TCP socket disconnected: [public.IPv4.smartphone.client]:1642 Oct 13 11:10:56 [servername] turnserver: 136: session 001000000000000001: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.smartphone.client]:1642, reason: TLS/TCP socket buffer operation error (callback) Oct 13 11:10:56 [servername] turnserver: 136: session 000000000000000002: TLS/TCP socket disconnected: [public.IPv4.smartphone.client]:8766 Oct 13 11:10:56 [servername] turnserver: 136: session 000000000000000002: closed (2nd stage), user <> realm <my.domain> origin <>, local [local.IPv4.turnserver]:5349, remote [public.IPv4.smartphone.client]:8766, reason: TLS/TCP socket buffer operation error (callback) Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: peer [local.IPv4.guest-network] lifetime updated: 300 Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: peer [local.IPv4.turnserver] lifetime updated: 300 Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 300 Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 300 Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CREATE_PERMISSION processed, success Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: peer [public.IPv4.turnserver] lifetime updated: 600 Oct 13 11:11:06 [servername] turnserver: 146: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet CHANNEL_BIND processed, success Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: refreshed, realm=<my.domain>, username=<1570959907:@christian:chat.my.domain>, lifetime=0 Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: realm <my.domain> user <1570959907:@christian:chat.my.domain>: incoming packet REFRESH processed, success Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: TCP socket closed remotely [public.IPv4.smartphone.client]:5952 Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: closed (2nd stage), user <1570959907:@christian:chat.my.domain> realm <my.domain> origin <>, local [local.IPv4.turnserver]:3478, remote [public.IPv4.smartphone.client]:5952, reason: TCP connection closed by client (callback) Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: delete: realm=<my.domain>, username=<1570959907:@christian:chat.my.domain> Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: peer [public.IPv4.turnserver] deleted Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: peer [local.IPv4.guest-network] deleted Oct 13 11:11:14 [servername] turnserver: 154: session 000000000000000001: peer [local.IPv4.turnserver] deleted Oct 13 11:11:23 [servername] synapse[10426]: 2019-10-13 11:11:23,391 - synapse.http.site - 203 - WARNING - GET-4038- Error processing request <XForwardedForRequest at 0x7f82f6a97e48 method='GET' uri='/_matrix/client/r0/sync?filter=6&timeout=30000&since=s222288_4534640_56_158364_25357_404_37186_19149_2' clientproto='HTTP/1.0' site=8008>: <class 'twisted.internet.error.ConnectionDone'> Connection was closed cleanly. Oct 13 11:11:23 [servername] synapse[10426]: 2019-10-13 11:11:23,912 - synapse.http.server - 458 - WARNING - GET-4038- Not sending response to request <XForwardedForRequest at 0x7f82f6a97e48 method='GET' uri='/_matrix/client/r0/sync?filter=6&timeout=30000&since=s222288_4534640_56_158364_25357_404_37186_19149_2' clientproto='HTTP/1.0' site=8008>, already disconnected.

[chrissi55]

The Difference between the "working-log" and the "non-working-log" today was:

1st -> Smartphone Client connected via mobile Data (LTE Provider)
2nd -> Smartphone Client connected via WLAN (internal Network)

In both cases my called device - a iPad - was connected via WLAN (Guest Network)
=> different IP Range than the "internal Network" and Traffic between internal / external is blocked by the SoHo Router (Fritz!Box)

[richvdh]

This doesn't immediately look like a synapse bug: as a reminder, the place to go for support is #synapse:matrix.org, not github.

If you think there is a synapse bug, can you try to make it clear what you think the problem is, and format the logs so that they are legible?

[chrissi55]

Thanks for your help. I opened my problem here because of several reasons.

1st too many infos to flood the chat on #synapse:matrix.org and i did that earlier but no answer because my posting gets more and more in the past and no one has read it any more.

2nd i'm not really sure what my problem exactly is, that why i gave the community my logs - i'm not that familiar in reading them and interprete what the messages mean

3rd it is an old problem - maybe not concerning a very new version of synapse / coturn - so on matrix.org many people in the past thought when i post it now my problem is the newest version of synapse concerned but no i have it a while - also had it with older versions of synapse in combination with coturn.

What i miss is a really working config for both (synapse AND coturn) to reliable setup a voip chat for SoHo

That why i posted the Link above to give you a hint what i've tried allready ....

[chrissi55]

Well, i changed to synapse 1.4.1

I posted - as adviced - to chat synapse but the persons who helped me saw my logs and said that it seems to be ok.

So my coturn config should be ok.

With nextcloud talk i reliable get connections with that. When coturn isn't the problem, then synapse or the clients (android / iOS / web) might be the problem.

What is curious - sometimes i get a conmnection (mostly after reloaded / rebootet the client(s) and/or synapse

[petercipov]

@chrissi55 Hello I fighting with similar issue. Currently I have found out that in recent versions of coturn maintainers have moved REST API from turn endpoint (coturn/coturn#355 (comment))

try to use --web-admin-listen-on-workers in your conturn config. It helped me to remove 401 unauthorised messages

[richvdh]

I'm still confused about what the issue is here. the logs are illegible.