Completed Server not responding after several hours uptime

razaq · Aug 26, 2018

Hello.
The server stops responding to any telnet/ts3 client connections after running for a couple hours.
This has happended every day so far. There is no crash logs created whatsoever unfortunately.
It takes around 12 hours of uptime, before the next connecting client crashes the server.
The logs just end in the middle of the connection process:

Code:

[2018-08-25 18:27:55] [ERROR] Timer ConnectedClient::tick needs more than 3724 microseconds. Max allowed was 2000 microseconds.
[2018-08-25 18:27:55] [ERROR]     3 | Ticking of client XX.XX.X.XXX:56245 (Username) needs more that 2500 microseconds! (5345 microseconds)
END LOG

Code:

[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Creating VoiceClient instance at 0x52733ae4
[2018-08-26 15:23:41] [DEBUG]     3 | Allocated new voice client connection at 0x393015a8
[2018-08-26 15:23:41] [DEBUG]     3 | Remote address (v4) 192.168.178.41 destination address 192.168.178.41
[2018-08-26 15:23:41] [DEBUG]     3 | Having new voice client. Remote address: XX.XX.X.XXX:65297
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (11ms)
[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client 3.1 protocol with build timestamp 177256836
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (164ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client ek!
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Command needs more than 10ms (17ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 12, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]   GEN | Query permission manager
[2018-08-26 15:23:42] [DEBUG]     3 | Loaded client from database. Database id: 6 Unique id: XXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got client init. (HWID: XXXX,XXXX)
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission] Value test result for test type 0.
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission]    Permission: b_client_ignore_bans Required value: 1 Gained value: 1 Force required: 1 Channel: none Result: 1
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_lastconnected' for 6 (New value: 1535289822, SQL: UPDATE clients SET lastConnect = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 13, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [ERROR]     3 | Command handling of command clientinit needs 47ms
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_last_client_connect. New value: 1535289822. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/Username] Handling of packet Command needs more than 10ms (49ms)
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_client_connections. New value: 30. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [DEBUG]   GEN | Client Username|XX.XX.X.XXX comes from XXXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got a channel talk power of 75 Talk power set is 0
[2018-08-26 15:23:42] [DEBUG]     3 | Client id: 1
END LOG

After that there is absolutely not response from the server anymore.
Journalctl has no reported errors either, so the process is still running.

Kevinos · Aug 26, 2018

razaq said:

Hello.
The server stops responding to any telnet/ts3 client connections after running for a couple hours.
This has happended every day so far. There is no crash logs created whatsoever unfortunately.
It takes around 12 hours of uptime, before the next connecting client crashes the server.
The logs just end in the middle of the connection process:

Code:

[2018-08-25 18:27:55] [ERROR] Timer ConnectedClient::tick needs more than 3724 microseconds. Max allowed was 2000 microseconds.
[2018-08-25 18:27:55] [ERROR]     3 | Ticking of client XX.XX.X.XXX:56245 (Username) needs more that 2500 microseconds! (5345 microseconds)
END LOG

Code:

[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Creating VoiceClient instance at 0x52733ae4
[2018-08-26 15:23:41] [DEBUG]     3 | Allocated new voice client connection at 0x393015a8
[2018-08-26 15:23:41] [DEBUG]     3 | Remote address (v4) 192.168.178.41 destination address 192.168.178.41
[2018-08-26 15:23:41] [DEBUG]     3 | Having new voice client. Remote address: XX.XX.X.XXX:65297
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (11ms)
[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client 3.1 protocol with build timestamp 177256836
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (164ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client ek!
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Command needs more than 10ms (17ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 12, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]   GEN | Query permission manager
[2018-08-26 15:23:42] [DEBUG]     3 | Loaded client from database. Database id: 6 Unique id: XXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got client init. (HWID: XXXX,XXXX)
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission] Value test result for test type 0.
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission]    Permission: b_client_ignore_bans Required value: 1 Gained value: 1 Force required: 1 Channel: none Result: 1
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_lastconnected' for 6 (New value: 1535289822, SQL: UPDATE clients SET lastConnect = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 13, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [ERROR]     3 | Command handling of command clientinit needs 47ms
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_last_client_connect. New value: 1535289822. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/Username] Handling of packet Command needs more than 10ms (49ms)
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_client_connections. New value: 30. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [DEBUG]   GEN | Client Username|XX.XX.X.XXX comes from XXXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got a channel talk power of 75 Talk power set is 0
[2018-08-26 15:23:42] [DEBUG]     3 | Client id: 1
END LOG

After that there is absolutely not response from the server anymore.
Journalctl has no reported errors either, so the process is still running.

Same here

DrN00bish · Aug 26, 2018

Which version are we talking about?
Also do you use MySQL/MariaDB or sqlite?
Could you possibly tell a cpl things about the system it's running on? For starters which distribution but also is it a VPS or something like that?

Seems strange though. If there's no errors or no other logs indicating anything else than things slowing down it would become rather hard to diagnose.
I see it's two different logs but none of them indicate anything out of the ordinary really... Well unless you would count that ticking for a client is over 5 seconds which in itself seems a tad high.

mola19 · Aug 27, 2018

razaq said:

Hello.
The server stops responding to any telnet/ts3 client connections after running for a couple hours.
This has happended every day so far. There is no crash logs created whatsoever unfortunately.
It takes around 12 hours of uptime, before the next connecting client crashes the server.
The logs just end in the middle of the connection process:

Code:

[2018-08-25 18:27:55] [ERROR] Timer ConnectedClient::tick needs more than 3724 microseconds. Max allowed was 2000 microseconds.
[2018-08-25 18:27:55] [ERROR]     3 | Ticking of client XX.XX.X.XXX:56245 (Username) needs more that 2500 microseconds! (5345 microseconds)
END LOG

Code:

[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Creating VoiceClient instance at 0x52733ae4
[2018-08-26 15:23:41] [DEBUG]     3 | Allocated new voice client connection at 0x393015a8
[2018-08-26 15:23:41] [DEBUG]     3 | Remote address (v4) 192.168.178.41 destination address 192.168.178.41
[2018-08-26 15:23:41] [DEBUG]     3 | Having new voice client. Remote address: XX.XX.X.XXX:65297
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (11ms)
[2018-08-26 15:23:41] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client 3.1 protocol with build timestamp 177256836
[2018-08-26 15:23:41] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Init1 needs more than 10ms (164ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/undefined] Got client ek!
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/undefined] Handling of packet Command needs more than 10ms (17ms)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 12, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]   GEN | Query permission manager
[2018-08-26 15:23:42] [DEBUG]     3 | Loaded client from database. Database id: 6 Unique id: XXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got client init. (HWID: XXXX,XXXX)
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission] Value test result for test type 0.
[2018-08-26 15:23:42] [DEBUG]     3 | [Permission]    Permission: b_client_ignore_bans Required value: 1 Gained value: 1 Force required: 1 Channel: none Result: 1
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_lastconnected' for 6 (New value: 1535289822, SQL: UPDATE clients SET lastConnect = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [DEBUG]     3 | [Property] Changing client property 'client_totalconnections' for 6 (New value: 13, SQL: UPDATE clients SET connections = :value WHERE serverId = :serverId AND cldbid = :cldbid)
[2018-08-26 15:23:42] [ERROR]     3 | Command handling of command clientinit needs 47ms
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_last_client_connect. New value: 1535289822. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [ERROR]     3 | [XX.XX.X.XXX:65297/Username] Handling of packet Command needs more than 10ms (49ms)
[2018-08-26 15:23:42] [DEBUG]     3 | Updating server property: virtualserver_client_connections. New value: 30. Query: UPDATE properties SET value = :value WHERE serverId = :sid AND type = :type AND id = :id AND key = :key
[2018-08-26 15:23:42] [DEBUG]   GEN | Client Username|XX.XX.X.XXX comes from XXXXX
[2018-08-26 15:23:42] [DEBUG]     3 | [XX.XX.X.XXX:65297/Username] Got a channel talk power of 75 Talk power set is 0
[2018-08-26 15:23:42] [DEBUG]     3 | Client id: 1
END LOG

After that there is absolutely not response from the server anymore.
Journalctl has no reported errors either, so the process is still running.

I have the same problem, I am using debian 8.

razaq · Aug 27, 2018

Debian 9 here. Also using SQLite. Running lastest version currently.

Seems like this is a common problem...

angelocrr · Aug 27, 2018

Check your RAM and CPU usage

Kevinos · Aug 27, 2018

Operating system Debian Linux 9
Server OVH GAME 32GB
Memory OK CPU OK
Mysql

1 hours ago just have the crash, last logs

Code:

[2018-08-27 07:06:19] [ERROR]  2619 | Failed to close socket 1434 (0.0.0.0:10581)
[2018-08-27 07:06:19] [ERROR]  2620 | Failed to close socket 1455 (0.0.0.0:10582)
[2018-08-27 07:06:19] [INFO]    GEN | Stopping application
[2018-08-27 07:06:19] [DEBUG] GLOBL | Stopping all virtual servers

angelocrr · Aug 27, 2018

Update TeaSpeak at latest version

Kevinos · Aug 27, 2018

angelocrr said:
Update TeaSpeak at latest version

It's already the last version

angelocrr · Aug 27, 2018

It's strange..

mola19 · Aug 27, 2018

angelocrr said:
It's strange..

Yes, that's happening to me too, it happens when the RAM reaches 50% or 60% approximately.

angelocrr · Aug 27, 2018

I am on Debian 8 and all works fine. No more problem of Ram.

razaq · Aug 27, 2018

Im going to try using MySQL instead, lets see if that changes anything

WolverinDEV · Aug 27, 2018

Well it seems more like the server hang up and you have to kill him manually?
Or did it just get killed by the system? If its getting killed by the system you may have to take a look at the system log to find out why it got killed.
If the server hang up, dont stop it just enter the terminal and type dummycrash. This should kill the server and create a crashdump.

razaq · Aug 27, 2018

i cant enter telnet terminal cause its not even reachable via telnet anymore.

razaq · Aug 29, 2018

still having this issue after swapping to MySQL

razaq · Aug 30, 2018

Okay i checked all the syslogs etc. The process has died, but there is absolutely nothing in the logs that indicates that the system is killing it. Any idea ideas on what i can do or which logs i have to check to find it?

dspcorp · Sep 2, 2018

i have crash too;

[2018-09-01 11:13:39] [INFO] 1 | Voice client 0/hlpmxxxmk0wqFgkxxxxkzA= (undefined) from 82.244.xx.xx:50025 left.
[2018-09-01 11:13:39] [DEBUG] 1 | Updating server property: virtualserver_last_client_disconnect. New value: 1535793219. Query: UPDATE `properties` SET `value` = :value WHERE `serverId` = :sid AND `type` = :type AND `id` = :id AND `key` = :key
[2018-09-01 11:13:50] [DEBUG] 1 | [Property] Changed property in db key: client_month_online_time value: 960
[2018-09-01 11:13:50] [DEBUG] 1 | [Property] Changed property in db key: client_total_online_time value: 960
[2018-09-01 11:15:50] [DEBUG] 1 | [Property] Changed property in db key: client_month_online_time value: 1080
[2018-09-01 11:15:50] [DEBUG] 1 | [Property] Changed property in db key: client_total_online_time value: 1080
[2018-09-01 11:16:52] [INFO] GEN | Got stop signal!
[2018-09-01 11:16:52] [INFO] GEN | Stopping all server instances!
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Closing voice client connection. (Flush: true)
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Tried to disconnect, but isn't connected anymore! State: 4
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Awaiting write prepare, write and acknowledge queue flushed
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Write prepare queue progressed
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Received disconnect acknowledge!
[2018-09-01 11:16:52] [DEBUG] 1 | [90.47.xx.xx:31425/moi] Closing voice client connection. (Flush: false)
[2018-09-01 11:16:52] [INFO] 1 | Voice client 4/9b5xxxxxxgdOY= (moi) from 90.47.xx.xx:31425 left.
[2018-09-01 11:16:52] [DEBUG] 1 | Updating server property: virtualserver_last_client_disconnect. New value: 1535793412. Query: UPDATE `properties` SET `value` = :value WHERE `serverId` = :sid AND `type` = :type AND `id` = :id AND `key` = :key
[2018-09-01 11:16:52] [DEBUG] 1 | Web-Server accept thread terminated
[2018-09-01 11:16:52] [INFO] GEN | Stopping application
[2018-09-01 11:16:52] [DEBUG] GLOBL | Stopping all virtual servers
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c2a8ba100 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c2a8b9b00 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c2a8b9e00 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c25811c00 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c25811f00 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c25811900 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c15276600 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c15276c00 finished!
[2018-09-01 11:16:53] [DEBUG] GEN | Dispatching io base 0x7f8c15276900 finished!
[2018-09-01 11:16:53] [DEBUG] GLOBL | All virtual server stopped
[2018-09-01 11:16:53] [DEBUG] QUERY | Stopping query server
[2018-09-01 11:16:53] [DEBUG] QUERY | Event base terminated (0x7f8c2a8b8c00)
[2018-09-01 11:16:53] [DEBUG] QUERY | Query server stopped
[2018-09-01 11:16:53] [DEBUG] FILE | Stopping file server
[2018-09-01 11:16:53] [DEBUG] FILE | File-Server accept thread terminated
[2018-09-01 11:16:53] [DEBUG] FILE | File server stopped
[2018-09-01 11:16:53] [INFO] GEN | Application suspend successful!

i test with blacklist Tea*Speak hosts and iptables block. i wait next crash

DrN00bish · Sep 2, 2018

dspcorp said:
[2018-09-01 11:16:52] [INFO] GEN | Got stop signal!

Doesn't look at all like a crash....

dspcorp · Sep 3, 2018

not crashing today, i have blocked Tea*Speak official server to hosts and iptables, i have 1 error:

[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection is invalid! Closing connection!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection was closed! Attemp reconnect!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection reconnect attemp failed! Dropping connection!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection is invalid! Closing connection!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection was closed! Attemp reconnect!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection reconnect attemp failed! Dropping connection!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection is invalid! Closing connection!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection was closed! Attemp reconnect!
[2018-09-03 06:06:13] [ERROR] GEN | MySQL connection reconnect attemp failed! Dropping connection!

10 sec after, the server works.

PS: MySQL is localhost last version mariadb on debian 9 64 bits

Completed Server not responding after several hours uptime

Well-known member

Fanatic member

Well-known member

Fanatic member

Well-known member

Well-known member

Fanatic member

Well-known member

Fanatic member

Well-known member

Fanatic member

Well-known member

Well-known member

TeaSpeak Team

Well-known member

Well-known member

Well-known member

New member

Well-known member

New member