• Hey Guest, we're evolving the future of TeaSpeak.
    You're invited to join the discussion here!

Pending The music bot stops playing streams

REDOSS

REDOSS

TeaSpeak Team
Staff member
TeaTeam
Version: 1.4.10 beta 3
After creating a music bot, the bot successfully plays the radio stream, but after a while something happens and the bot can't play music, but it responds successfully to all commands.

Code: 
[2020-03-14 03:33:06] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (9ms). Details: encode=9,subscriber=0,schedule=0.
[2020-03-14 03:33:06] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (10ms). Details: encode=10,subscriber=0,schedule=0.
[2020-03-14 03:33:06] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (27ms)
[2020-03-14 03:33:09] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (22ms)
[2020-03-14 03:33:13] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (6ms). Details: encode=6,subscriber=0,schedule=0.
[2020-03-14 03:33:14] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (5ms). Details: encode=5,subscriber=0,schedule=0.
[2020-03-14 03:33:14] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (6ms). Details: encode=6,subscriber=0,schedule=0.
[2020-03-14 03:33:22] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (13ms)
[2020-03-14 03:33:22] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (10ms)
[2020-03-14 03:33:24] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (7ms). Details: encode=7,subscriber=0,schedule=0.
[2020-03-14 03:33:25] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (26ms)
[2020-03-14 03:33:27] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (10ms)
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (16ms)
[2020-03-14 03:33:30] [WARNING ]     1 | Found varianzes within the server tick! (Supposed: 500ms Hold: 512ms)
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (20ms). Details: encode=20,subscriber=0,schedule=0.
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (18ms)
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (14ms). Details: encode=14,subscriber=0,schedule=0.
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (24ms). Details: encode=24,subscriber=0,schedule=0.
[2020-03-14 03:33:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (10ms)
[2020-03-14 03:33:32] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (13ms)
[2020-03-14 03:33:39] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (11ms)
[2020-03-14 03:33:46] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (16ms). Details: encode=16,subscriber=0,schedule=0.
[2020-03-14 03:33:51] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (14ms)
[2020-03-14 03:33:52] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (13ms)
[2020-03-14 03:33:56] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (20ms)
[2020-03-14 03:34:07] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (5ms). Details: encode=5,subscriber=0,schedule=0.
[2020-03-14 03:34:12] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (14ms)
[2020-03-14 03:34:15] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 484920
[2020-03-14 03:34:15] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 484920
[2020-03-14 03:34:16] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 357840
[2020-03-14 03:34:16] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 357840
[2020-03-14 03:34:25] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (22ms)
[2020-03-14 03:34:26] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (10ms). Details: encode=10,subscriber=0,schedule=0.
[2020-03-14 03:34:27] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (5ms). Details: encode=5,subscriber=0,schedule=0.
[2020-03-14 03:34:29] [WARNING ]   GEN | Timer InstanceHandler::tickInstance -> fileserver tick needs more than 5654 microseconds. Max allowed was 5000 microseconds.
[2020-03-14 03:34:30] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (17ms)
[2020-03-14 03:34:33] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (9ms). Details: encode=7,subscriber=0,schedule=1.
[2020-03-14 03:34:42] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (10ms)
[2020-03-14 03:34:46] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Resend task contained a delay of over 10ms! (44ms)
[2020-03-14 03:34:46] [WARNING ]   GEN | Timer InstanceHandler::tickInstance -> fileserver tick needs more than 18 milliseconds. Max allowed was 5 milliseconds.
[2020-03-14 03:34:46] [WARNING ]     1 | [[localhost:0/Im a music bot! | 1]] Ticking used more than 5ms to proceed (109ms). Details: encode=109,subscriber=0,schedule=0.
[2020-03-14 03:34:46] [TRACE]     1 | [Property] Changed property in db key: player_state value: 1
[2020-03-14 03:34:46] [TRACE]     1 | [Property] Not saving property 'client_flag_talking', changed for 6 (New value: 0)
[2020-03-14 03:34:46] [ERROR]     1 | Ticking of client localhost:0 (Im a music bot!) needs more that 2500 microseconds! (235461 microseconds)
[2020-03-14 03:34:46] [ERROR]     1 | Server tick tooks to long (250ms => Status updates: 2ms Client tick: 247ms, Channel tick: 0ms, Statistic tick: 0ms, Groups: 0ms, Conversation cache: 0ms)
[2020-03-14 03:34:47] [WARNING ]     1 | Found varianzes within the server tick! (Supposed: 500ms Hold: 512ms)
[2020-03-14 03:34:49] [WARNING ]     1 | Found varianzes within the server tick! (Supposed: 500ms Hold: 549ms)
[2020-03-14 03:36:16] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 485040
[2020-03-14 03:36:16] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 485040
[2020-03-14 03:36:16] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 357960
[2020-03-14 03:36:16] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 357960
[2020-03-14 03:38:16] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 485160
[2020-03-14 03:38:16] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 485160
[2020-03-14 03:38:16] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 358080
[2020-03-14 03:38:16] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 358080
[2020-03-14 03:39:23] [WARNING ]     1 | Found varianzes within the server tick! (Supposed: 500ms Hold: 513ms)
In between 03:34:46 - 03:34:50 something happened and then the problems started.

Code: 
[2020-03-14 18:28:22] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Client -> Server] Processing command: sendtextmessage targetmode='3' msg='.mbot list'
[2020-03-14 18:28:22] [TRACE]     1 | [Permission] Calculation for client 5 of permission b_client_server_textmessage_send returned 1 (Server group permission of group 9)
[2020-03-14 18:28:22] [DEBUG]     1 | Having command "mbot".
[2020-03-14 18:28:22] [DEBUG]     1 |  Argument: 'list'
[2020-03-14 18:28:22] [TRACE]     1 | [Permission] Found skip permission in client server group. Group: 9 (Server Admin), Value: true
[2020-03-14 18:28:22] [TRACE]     1 | [Permission] Calculation for client 5 of permission b_client_music_channel_list returned 1 (Server group permission of group 9)
[2020-03-14 18:28:22] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Server -> Client] Sending command notifytextmessage. Command low: false. Full command: notifytextmessage invokerid=0 invokername=Music\sManager invokeruid targetmode=3 target=0 msg=There\sare\s1\smusic\sbots\sin\sthis\schannel: timestamp=1584199702519
[2020-03-14 18:28:22] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Server -> Client] Sending command notifytextmessage. Command low: false. Full command: notifytextmessage invokerid=0 invokername=Music\sManager invokeruid targetmode=3 target=0 msg=\s-\s[color=green]6\s\p\sIm\sa\smusic\sbot![\/color] timestamp=1584199702519
[2020-03-14 18:28:27] [TRACE]     1 | [Property] Changed property in db key: client_month_online_time value: 411360
[2020-03-14 18:28:27] [TRACE]     1 | [Property] Changed property in db key: client_total_online_time value: 411360
[2020-03-14 18:28:29] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Client -> Server] Processing command: sendtextmessage targetmode='3' msg='.mbot select 6'
[2020-03-14 18:28:29] [TRACE]     1 | [Permission] Calculation for client 5 of permission b_client_server_textmessage_send returned 1 (Server group permission of group 9)
[2020-03-14 18:28:29] [DEBUG]     1 | Having command "mbot".
[2020-03-14 18:28:29] [DEBUG]     1 |  Argument: 'select'
[2020-03-14 18:28:29] [DEBUG]     1 |  Argument: '6'
[2020-03-14 18:28:29] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Server -> Client] Sending command notifytextmessage. Command low: false. Full command: notifytextmessage invokerid=0 invokername=Music\sManager invokeruid targetmode=3 target=0 msg=You\ssuccessfully\sselect\sthe\sbot\s6\s\p\sIm\sa\smusic\sbot! timestamp=1584199709158
[2020-03-14 18:28:49] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Client -> Server] Processing command: sendtextmessage targetmode='3' msg='.mbot stream [URL]http://air.radiorecord.ru:8101/rr_320[/URL]'
[2020-03-14 18:28:49] [TRACE]     1 | [Permission] Calculation for client 5 of permission b_client_server_textmessage_send returned 1 (Server group permission of group 9)
[2020-03-14 18:28:49] [DEBUG]     1 | Having command "mbot".
[2020-03-14 18:28:49] [DEBUG]     1 |  Argument: 'stream'
[2020-03-14 18:28:49] [DEBUG]     1 |  Argument: '[URL]http://air.radiorecord.ru:8101/rr_320[/URL]'
[2020-03-14 18:28:49] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Server -> Client] Sending command notifytextmessage. Command low: false. Full command: notifytextmessage invokerid=1 invokername=Im\sa\smusic\sbot! invokeruid=Xw1vVqpAg\/j0FsByJ8yim0QuTvg= targetmode=3 target=0 msg=Queueing\svideo\s[URL]http:\/\/air.radiorecord.ru:8101\/rr_320[\/URL] timestamp=1584199729975
[2020-03-14 18:28:49] [TRACE]     1 | [PlayList] Enqueueing song 2 for loading
[2020-03-14 18:28:49] [DEBUG] [Music] [FFMPEG][0x7f2427d31410] Executing command "/home/redoss/providers/bin/ffmpeg -reconnect 1 -reconnect_streamed 1 -reconnect_delay_max 5 -hide_banner -stats -i "http://air.radiorecord.ru:8101/rr_320" -vn -bufsize 512k -ac 2 -ar 48000 -f s16le -acodec pcm_s16le pipe:1"
[2020-03-14 18:28:49] [DEBUG] [Music] Got ffmpeg file descriptors for err 110 and out 108
[2020-03-14 18:29:13] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Client -> Server] Processing command: connectioninfoautoupdate connection_server2client_packetloss_speech='0.0000' connection_server2client_packetloss_keepalive='0.0000' connection_server2client_packetloss_control='0.0049' connection_server2client_packetloss_total='0.0010'
[2020-03-14 18:29:13] [TRACE]     1 | [Property] Not saving property 'connection_server2client_packetloss_control', changed for 5 (New value: 0.0049)
[2020-03-14 18:29:13] [TRACE]     1 | [Property] Not saving property 'connection_server2client_packetloss_total', changed for 5 (New value: 0.0010)
[2020-03-14 18:29:14] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Client -> Server] Processing command: clientdisconnect reasonid='8' reasonmsg='выход'
[2020-03-14 18:29:14] [TRACE]     1 | [IP:2215/REDOSS | 2][Command][Server -> Client] Sending command notifyclientleftview. Command low: false. Full command: notifyclientleftview reasonmsg=выход reasonid=8 clid=2 cfid=4 ctid=0
[2020-03-14 18:29:14] [TRACE]     1 | [CHANNEL] Updating channel property for channel 4: channel_last_left. New value: '1584199754685'. Query: UPDATE `properties` SET `value` = :value WHERE `serverId` = :serverId AND `id` = :id AND `key` = :key AND `type` = :type
[2020-03-14 18:29:14] [DEBUG]     1 | [IP:2215/REDOSS | 2] Client move timings: timings for : 0ms
[2020-03-14 18:29:14] [DEBUG]   - chan tree l: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - channel res: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - target show: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - notify view: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - lock own tr: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - src chan up: @0ms: 0ms
[2020-03-14 18:29:14] [DEBUG]   - notify cpro: @0ms: 0ms
[2020-03-14 18:29:14] [INFO ]     1 | [IP:2215/REDOSS | 2] Got remote disconnect with the reason 'выход'
[2020-03-14 18:29:14] [DEBUG]     1 | [IP:2215/REDOSS | 2] Closing voice client connection. (Flush: true)
[2020-03-14 18:29:14] [DEBUG]     1 | [IP:2215/REDOSS | 2] Awaiting write prepare, write and acknowledge queue flushed
[2020-03-14 18:29:14] [DEBUG]     1 | [IP:2215/REDOSS | 2] Write and acknowledge queue are flushed
[2020-03-14 18:29:14] [INFO ]     1 | Voice client 5/rZxCzsRdkwgKx3/SdoQES9hGm3M= (REDOSS) from IP:2215 left.
As you can see from this log commands were sent to the server:
.mbot list
.mbot select 6
.mbot stream http://air.radiorecord.ru:8101/rr_320

The bot successfully responded to the commands, but the sound of the radio stream did not appear. Then I disconnected from the server on my own.

---- Automatically Merged Double Post ----

The second case, the bot plays music for 19 hours, and then went silent. There are such entries in the log at this time:
Code: 
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] Got error message from FFMpeg:
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] [http @ 0x6249600] Will reconnect at 28882584 in 0 second(s), error=End of file.
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] Got error message from FFMpeg:
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] HTTP error 404 Not Available
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] Got error message from FFMpeg:
[2020-03-15 13:24:58] [ERROR] [Music] [FFMPEG][0x7fab2db31110] Will reconnect at 28882584 in 1 second(s), error=End of file.
[2020-03-15 13:24:59] [ERROR] [Music] [FFMPEG][0x7fab2db31110] Got error message from FFMpeg:
[2020-03-15 13:24:59] [ERROR] [Music] [FFMPEG][0x7fab2db31110] HTTP error 404 Not Available
[2020-03-15 13:24:59] [ERROR] [Music] [FFMPEG][0x7fab2db31110] [http @ 0x6249600] Will reconnect at 28882584 in 3 second(s), error=End of file.
[2020-03-15 13:25:02] [ERROR] [Music] Invalid read (error). Length: 0 Code: 0 Message: Success: Exit: 1 (0)
[2020-03-15 13:25:02] [ERROR]     1 | [[localhost:0/Im a music bot! | 1]] opus_encode(...) returns invalid code: 0
[2020-03-15 13:25:02] [TRACE]     1 | [[localhost:0/Im a music bot! | 1]] Got event 4
[2020-03-15 13:25:02] [DEBUG]     1 | [MusicBot] Got end event from music player. Playing next song!
[2020-03-15 13:25:02] [TRACE]     1 | Updating playlist property for 2. Key: playlist_flag_finished Value: 1
[2020-03-15 13:25:02] [TRACE]     1 | Updating playlist property for 2. Key: playlist_current_song_id Value: 0
[2020-03-15 13:25:02] [TRACE]     1 | [Property] Changed property in db key: player_state value: 0
[2020-03-15 13:25:02] [TRACE]     1 | [Property] Not saving property 'client_flag_talking', changed for 9 (New value: 0)

The bot responds successfully to the music playback command, but does not play it.
Code: 
[2020-03-15 17:47:37] [DEBUG]     1 | Having command "mbot".
[2020-03-15 17:47:37] [DEBUG]     1 |  Argument: 'stream'
[2020-03-15 17:47:37] [DEBUG]     1 |  Argument: '[URL]http://air.radiorecord.ru:8101/rr_320[/URL]'
[2020-03-15 17:47:37] [TRACE]     1 | [IP:2963/REDOSS | 2][Command][Server -> Client] Sending command notifytextmessage. Command low: false. Full command: notifytextmessage invokerid=1 invokername=Im\sa\smusic\sbot! invokeruid=a6njsO6JfST65YIxG+a2q0gq3CA= targetmode=2 target=0 msg=Queueing\svideo\s[URL]http:\/\/air.radiorecord.ru:8101\/rr_320[\/URL] timestamp=1584283657394
[2020-03-15 17:47:37] [TRACE]     1 | [PlayList] Enqueueing song 11 for loading
[2020-03-15 17:47:37] [DEBUG] [Music] [FFMPEG][0x7fab273d6810] Executing command "/home/redoss/providers/bin/ffmpeg -reconnect 1 -reconnect_streamed 1 -reconnect_delay_max 5 -hide_banner -stats -i "http://air.radiorecord.ru:8101/rr_320" -vn -bufsize 512k -ac 2 -ar 48000 -f s16le -acodec pcm_s16le pipe:1"
[2020-03-15 17:47:37] [DEBUG] [Music] Got ffmpeg file descriptors for err 121 and out 119
[2020-03-15 17:47:37] [TRACE] [Music] Got root entry: Input #0, mp3, from 'http://air.radiorecord.ru:8101/rr_320':
[2020-03-15 17:47:37] [TRACE] [Music] Got input stream data: Metadata:
[2020-03-15 17:47:37] [DEBUG] [Music] Available metadata:
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'StreamTitle' Value: 'GAULLIN - Moonlight (Record Mix)'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-br' Value: '192'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-description' Value: 'by Radio Record'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-genre' Value: 'Dance'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-name' Value: 'Radio Record'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-pub' Value: '0'
[2020-03-15 17:47:37] [DEBUG] [Music]  Key: 'icy-url' Value: 'http://radiorecord.ru'
[2020-03-15 17:47:37] [TRACE] [Music] Got input stream data: Duration: N/A, start: 0.000000, bitrate: 192 kb/s
[2020-03-15 17:47:37] [DEBUG] [Music] Stream does not contains a duration
[2020-03-15 17:47:37] [TRACE] [Music] Got root entry: Stream mapping:
[2020-03-15 17:47:37] [DEBUG] [Music] [FFMPEG] Failed to exit ffmpeg process handle. Deleting process handle (140372844153408) within another thread.
[2020-03-15 17:47:37] [DEBUG] [Music] [FFMPEG] Deleting process handle (140372844153408) done.
 
Last edited:
WolverinDEV

WolverinDEV

TeaSpeak Team
Staff member
Administrator
"playlist_flag_finished":
You've to manually start the bot again by double clicking a certain entry within the playlist or press play.
 
REDOSS

REDOSS

TeaSpeak Team
Staff member
TeaTeam
WolverinDEV said:
"playlist_flag_finished":
You've to manually start the bot again by double clicking a certain entry within the playlist or press play.
Click to expand...
well. try running the bot)) access to the server in your private messages.

---- Automatically Merged Double Post ----

and yes, at your command, the bot responds successfully to the command, but nothing from the music is played.
 
Last edited:
Vafin

Vafin

TeaFanatic
WolverinDEV said:
"playlist_flag_finished":
You've to manually start the bot again by double clicking a certain entry within the playlist or press play.
Click to expand...
I click on all the possible buttons that could start the music, but the bot is silent. In my case, this happens if the instance has more than one bot. The problem is still unfortunately not resolved .
 
You must log in or register to reply here.