coturn icon indicating copy to clipboard operation
coturn copied to clipboard

Published 20 hours ago • verified publisher icon coturn

turnserver is creating very large logfiles

Open mokkin opened this issue 4 years ago • 25 comments

Today I wondered why the harddisk of our server ran out of memory: Because coturn created logs between 100 and 200 MB per day. It is creating entries even when nobody is using it (via Nextcloud Talk). Coturn-4.5.0.7 Ubtuntu 18.04.5

What can I do against this?

tail -n 100 turn_1037_2020-09-11.log 
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892935: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892936: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892937: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892938: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892939: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892940: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892941: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892942: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892943: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892944: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892945: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892946: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892947: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success
1892948: session 001000000000098249: realm <turn.example.de> user <>: incoming packet BINDING processed, success


listening-port=3478
tls-listening-port=443
fingerprint
lt-cred-mech
user=turnuser:asd3Jdask-Vsd
static-auth-secret=d4fda96998eba73797abababababababab1335a71f1cfd7a9d8
realm=turn.example.de
total-quota=100
bps-capacity=0
stale-nonce=600
no-multicast-peers
no-tlsv1
no-tlsv1_1

mokkin avatar Sep 11 '20 20:09 mokkin

I suggest you to add options below. --log-file /dev/null --simple-log --no-stdout-log If you simply add --log-file to /dev/null, log file will not be created.

DevRockstarZ avatar Sep 14 '20 10:09 DevRockstarZ

Try logrotate, simple tool for this "problems".

ghost avatar Sep 28 '20 19:09 ghost

Hi all,

I'm having very similar behavior. I've also noticed that these log entries span the course of a 1 minute and begin and end with the following, respectively:

[...start of log entry] Nov 17 00:50:43 server turnserver: 35892: handle_udp_packet: New UDP endpoint: local addr X.X.X.X:3478, remote addr 147.194.81.X:61337

Nov 17 00:50:43 server turnserver: 35892: session 003000000000000095: realm <turn.example.org> user <>: incoming packet BINDING processed, success [....] (repeats for 1 minute with)

Nov 17 00:51:43 server turnserver: 35952: session 003000000000000095: closed (2nd stage), user <> realm <turn.example.org> origin <>, local X.X.X.X:3478 remote 147.194.81.X:61337, reason: allocation watchdog determined stale session state [end of log entry...]

Interestingly, I get a bunch of these per day! ...so many, I know they are not all do to clients.

While I understand your question was more directed to the actual size of the log (mine seem to be remaining under 20 MB, but this is still kinda large); my question is directed to the community regarding coTURN security.

=>Can scanners/bots be responsible for making these connections and timeouts? I suspect overwhelmingly, 'YES'. Thus, I wonder what hardening implementations might be suggested with coTURN? I am not enforcing any authentication to the coTURN server, per se, (to my knowledge). In my case, I've got coTURN with Synapse/Matrix homeserver currently running.

Also, big 'ups' to the coTURN project and its wonderful contributors.

Warmly, Kevin

ghost avatar Nov 18 '20 13:11 ghost

@mokkin Try to send log to syslog and there are well known ways like logrotate and filtering to handle this issue..

misi avatar Dec 08 '20 13:12 misi

There are other things to be considered as well:

  1. Wear leveling for SSDs and SDCards, generating so many logs will kill an SDCard in a short time
  2. The log should contain "useful" information, so that a sysadmin can act upon it.

The flood with the following message (filling MBs of log also in my case):

realm <turn.example.com> user <>: incoming packet BINDING processed, success

is meaningless, because it is simply a success INFO message without any further information. Does not help, at least at "normal" log level.

The other similar case (when an attack is performed):

2021-03-24T11:32:06+0000: ERROR: handle_udp_packet: socket to be closed
2021-03-24T11:32:06+0000: handle_udp_packet: 111.111: thrid=0x7ff6cb1dd640: Amap = 0x7ff6cb1f0ee0, socket container=0x7ff6cb1f0ee0, local addr 123.123.123.123:3478, remote addr 213.213.213.213, s=0x561f3aad9f70, done=0, tbc=1

To log this for every UDP packet (for the same attacker) is kind of overkill. One single log is useful for fail2ban scenarios, however it is not OK to log the same for every single packet with the same thrid, Amap and s values.

I kindly ask you, to move the first to verbose or Verbose level, and the second one to log once (if they are consecutive), and only log every time on verbose or Verbose level.

bszente avatar Mar 24 '21 12:03 bszente

@bszente Check latest master in the new version there is an option and by default we don't log binding request.

misi avatar Mar 24 '21 12:03 misi

@misi Thanks, you are right. Indeed, since coturn-4.5.2 (I recently upgraded) I don't have those BINDING log lines anymore.

Is there anything that can be done for the second log type? (The ERROR: handle_udp_packet: socket to be closed and the following one.)

bszente avatar Mar 24 '21 13:03 bszente

@bszente Check latest master in the new version there is an option and by default we don't log binding request.

Nice. Which commit is it exactly?

paulmenzel avatar Mar 29 '21 20:03 paulmenzel

https://github.com/coturn/coturn/commit/6a5d067d7c2b8afb14f2bd95bcf1f2c0b1bd7b73 (Merge pull request #703 from hills/no-stdout-log) which is merge/pull request https://github.com/coturn/coturn/pull/703?

paulmenzel avatar Mar 29 '21 20:03 paulmenzel

I am seeing this with Debian 10 (buster) with coturn 4.5.1.1-1.1+deb10u2.

paulmenzel avatar Mar 29 '21 20:03 paulmenzel

Having that problem with Debian Buster (coturn 4.5.1.1-1.1+deb10u2 amd64).

andyCapone avatar Apr 05 '21 16:04 andyCapone

Having that problem with Debian Buster (coturn 4.5.1.1-1.1+deb10u2 amd64).

Upgrade to coturn-4.5.2.

bszente avatar Apr 06 '21 07:04 bszente

Can you please point to the commit fixing this issue?

paulmenzel avatar Apr 06 '21 07:04 paulmenzel

27b261eb58116e1dd395124e90ccbcc09d13b135

4.5.2 on Arch doesn't fix the issue for me though.

jbg avatar Apr 06 '21 07:04 jbg

@jbg you still get binding logs even if you use 4.5.2. Can you explain more detailed?

misi avatar Apr 07 '21 22:04 misi

Just a temporary workaround if you log to syslog you can filter out in syslog. It is not a solution of course still, it will still cause IO, but it will not fill the disk.. 4.5.2 should help if it does not work, just let me know and I will adjust it to fix.

misi avatar Apr 07 '21 22:04 misi

For me the log spam is not the only issue, my server runs into ulimit issues doe to too many open sockets. The connections are not usual connections, outside of our offices working hours I would not expect so many incoming packets (5k per minute).

If there would be the IP address in addition to the session in the log message it would be easy to utilize e.g. fail2ban to block those suspicious connections / IP addresses.

Cacodaimon avatar Apr 20 '21 11:04 Cacodaimon

Same issues here with 4.5.2 from buster-backports

resoli avatar Apr 28 '21 14:04 resoli

To follow this ticket.

Neustradamus avatar Aug 15 '22 18:08 Neustradamus

Hi @jbg @resoli ! Do you still experience the issue? If yes, can you please provide a full log and your configuration settings?

eakraly avatar Aug 16 '22 01:08 eakraly

I'm having the same issue on Arch Linux coturn-4.5.2-3:

Aug 23 21:41:56 pluto turnserver[407]: 163898: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163899: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163899: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163899: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163899: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163900: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:41:57 pluto turnserver[407]: 163900: : session 002000000000000133: realm <turn.domain.tld> user <>: incoming packet BINDING processed, success
Aug 23 21:42:19 pluto turnserver[407]: 163921: : session 002000000000000133: usage: realm=<turn.domain.tld>, username=<>, rp=429, rb=8580, sp=429, sb=41184
Aug 23 21:42:19 pluto turnserver[407]: 163921: : session 002000000000000133: peer usage: realm=<turn.domain.tld>, username=<>, rp=0, rb=0, sp=0, sb=0
Aug 23 21:42:19 pluto turnserver[407]: 163921: : session 002000000000000133: closed (2nd stage), user <> realm <turn.domain.tld> origin <>, local 192.168.XXX.XXX:3478, remote 212.22.93.189:50001, reason: allocation watchdog determined stale session state

The IP seems to be from Russia and they certainly have no business with my TURN server.

Did I make security mistakes in configuring my TURN server?

haansn08 avatar Aug 23 '22 19:08 haansn08

@haansn08 Those are STUN requests My bet is that your STUN is not secure (no --secure-stun) which allows anyone to use it (for STUN, not TURN) Is this a problem or not - up to you.

If you just want to reduce the amount of logs make sure you do not have --log-binding in your configuration which will stop logging BINDING messages above (assuming you run the version that supports it)

eakraly avatar Aug 24 '22 01:08 eakraly

@eakraly Thank you! Indeed the --secure-stun option was disabled. Sadly the connection attempts did not stop, but at least they seem to be unauthorized now: incoming packet message processed, error 401: Unauthorized.

haansn08 avatar Aug 25 '22 22:08 haansn08

There is no way you can solve it AFAIK - internet is a wild place and you get incoming traffic from unexpected sources. One thing that you can do is to move to non-standard ports (away from 3478) - this might reduce amount of scanners and probes but you must validate with your application/network if they can use non-standard ports for STUN

If this answers your question - please close this issue. Thanks!

eakraly avatar Aug 26 '22 19:08 eakraly

@eakraly Thank you for your answer, but I did not create this issue.

haansn08 avatar Aug 27 '22 00:08 haansn08