Some commands to engine do not work
I fiddled around with the aura-playout and aura-web and found one (or two) interesting Error(s) while testing the playout.
- I tested this on the version alpha1
- Pulseaudio is disabled on my machine
- The stream and file links used exist and are reachable
- The timeslots were created via the dashboad (two hours in advance because steering#116 (closed))
- Everything is running on aura.local
- I can manually start a stream via telnet
- I can manually start a file via telnet
A timeslot with a stream scheduled for 14:12:00 :
Engine Log
2023-04-03 14:04:17,908:engine:INFO - Finished queuing programme. - [scheduler.py:283-queue_programme()]
2023-04-03 14:04:17,908:engine:INFO -
[ ENGINE COMMAND QUEUE ]
=> [TIMESLOT#34:do_start_timeslot:2023-04-03_14:05:00] exec at 2023-04-03 14:05:00.390156 (alive: True, updates: 0)
=> [TIMESLOT#34:do_end_timeslot:2023-04-03_14:29:59] exec at 2023-04-03 14:29:58.890467 (alive: True, updates: 0)
=> [PRELOAD#34:do_preload:2023-04-03_14:04:45] exec at 2023-04-03 14:04:45.407797 (alive: True, updates: 0)
=> [PLAY#34:do_play:2023-04-03_14:05:00] exec at 2023-04-03 14:05:00.408095 (alive: True, updates: 0)
- [control.py:288-log_commands()]
2023-04-03 14:04:45,408:engine:INFO - === preload('PlaylistEntry #36 [14:05:00 - 14:30:00 | 1500sec | Source: ...tream.freirad.at/live.mp3]') === - [scheduler.py:548-do_preload()]
2023-04-03 14:04:45,423:engine:DEBUG - Loading entry 'PlaylistEntry #36 [14:05:00 - 14:30:00 | 1500sec | Source: ...tream.freirad.at/live.mp3]' - [engine.py:288-preload()]
2023-04-03 14:04:45,424:engine:INFO - Got free 'http' channel 'in_stream_0' - [mixer.py:150-get_free_channel()]
2023-04-03 14:04:45,424:engine:INFO - Assign channel [2 : in_stream_0] to entry - [engine.py:312-preload()]
2023-04-03 14:04:45,424:engine:DEBUG - Loading stream 'https://stream.freirad.at/live.mp3' - [channels.py:442-load()]
2023-04-03 14:04:45,427:engine:DEBUG - [>>] in_stream_0.stop - [client.py:160-log_debug()]
2023-04-03 14:04:45,427:engine:INFO - Broken Pipe while sending command - [client.py:309-send()]
Exception in thread PRELOAD#34:do_preload:2023-04-03_14:04:45:
Traceback (most recent call last):
2023-04-03 14:04:45,428:engine:DEBUG - on_critical(..) - [events.py:302-func()]
File "/srv/src/aura_engine/core/client.py", line 305, in send
self.socket.sendall(command.encode())
BrokenPipeError: [Errno 32] Broken pipe
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/srv/src/aura_engine/core/client.py", line 116, in exec
response = self.conn.send(command)
File "/srv/src/aura_engine/core/client.py", line 311, in send
raise CoreConnectionError(msg)
aura_engine.core.client.CoreConnectionError: Broken Pipe while sending command
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.10/threading.py", line 1378, in run
self.function(*self.args, **self.kwargs)
File "/srv/src/aura_engine/control.py", line 166, in wrapper_func
self.func(
File "/srv/src/aura_engine/scheduling/scheduler.py", line 549, in do_preload
self.engine.player.preload(entries[0])
File "/srv/src/aura_engine/engine.py", line 314, in preload
is_ready = entry.channel.load(uri, metadata=metadata)
File "/srv/src/aura_engine/core/channels.py", line 447, in load
self.stop()
File "/srv/src/aura_engine/base/lang.py", line 74, in wrapper
return member(*args, **kwargs)
File "/srv/src/aura_engine/core/channels.py", line 506, in stop
response = self.mixer.client.exec(self.name, "stop")
File "/srv/src/aura_engine/base/lang.py", line 49, in wrapper
raise e
File "/srv/src/aura_engine/base/lang.py", line 45, in wrapper
result = member(*args, **kwargs)
File "/srv/src/aura_engine/core/client.py", line 122, in exec
raise CoreConnectionError(msg, e)
aura_engine.core.client.CoreConnectionError: ('Error while issuing command to Liquidsoap', CoreConnectionError('Broken Pipe while sending command'))
Engine-core Log
2023/04/03 14:11:59 [lang:3] Successfully posted playlog to Engine API.
2023/04/03 14:11:59 [amplify_2:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [on_track_0:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [on_metadata_2:5] Got metadata at position 0: calling handler...
2023/04/03 14:11:59 [on_metadata_2:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [switch_0:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [add_0:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [insert_metadata_2:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [mixer:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [stripped_stream:5] Got metadata at position 0: calling handlers...
2023/04/03 14:11:59 [lang:3] Skipping track in fallback folder ...
2023/04/03 14:11:59 [fallback_folder:4] Finished with "/var/audio/fallback/macy_gray_07_gimme_all_your_lovin_or_i_will_kill_you.ogg".
2023/04/03 14:11:59 [fallback-source:5] Got metadata at position 0: calling handlers...
2023/04/03 14:13:01 [server:4] Timeout reached while communicating to client unix socket "".
2023/04/03 14:13:01 [server:3] Client unix socket "" disconnected.
A timeslot with just music files scheduled for 14:16:00:
Engine Log
2023-04-03 14:15:44,643:engine:INFO - === preload_group('PlaylistEntry #40 [14:16:00 - 14:21:26 | 326sec | Source: ...file://musikprogramm/1], PlaylistEntry #41 [14:21:26 - 14:26:11 | 285sec | Source: ...file://musikprogramm/2], PlaylistEntry #42 [14:26:11 - 14:30:36 | 265sec | Source: ...file://musikprogramm/3], PlaylistEntry #43 [14:30:36 - 14:35:13 | 277sec | Source: ...file://musikprogramm/5]') === - [scheduler.py:545-do_preload()]
2023-04-03 14:15:44,644:engine:INFO - Got free 'fs' channel 'in_queue_1' - [mixer.py:150-get_free_channel()]
2023-04-03 14:15:44,644:engine:DEBUG - Loading entry 'PlaylistEntry #40 [14:16:00 - 14:21:26 | 326sec | Source: ...file://musikprogramm/1]' - [engine.py:351-preload_group()]
2023-04-03 14:15:44,646:engine:INFO - in_queue_1.push('/var/audio/source/musikprogramm/1.flac') - [channels.py:342-load()]
2023-04-03 14:15:44,648:engine:DEBUG - [>>] in_queue_1.push annotate:show_name="Musikprogramm",show_id="1",timeslot_id="36",playlist_id="6",playlist_item="0.0",track_type="0",track_start="",track_duration="326",track_title="Blowin up your speakers",track_album="",track_artist="Macy Gray":/var/audio/source/musikprogramm/1.flac - [client.py:160-log_debug()]
2023-04-03 14:15:44,648:engine:INFO - Broken Pipe while sending command - [client.py:309-send()]
Exception in thread PRELOAD#36:do_preload:2023-04-03_14:15:45:
Traceback (most recent call last):
2023-04-03 14:15:44,649:engine:DEBUG - on_critical(..) - [events.py:302-func()]
File "/srv/src/aura_engine/core/client.py", line 305, in send
self.socket.sendall(command.encode())
BrokenPipeError: [Errno 32] Broken pipe
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/srv/src/aura_engine/core/client.py", line 116, in exec
response = self.conn.send(command)
File "/srv/src/aura_engine/core/client.py", line 311, in send
raise CoreConnectionError(msg)
aura_engine.core.client.CoreConnectionError: Broken Pipe while sending command
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.10/threading.py", line 1378, in run
self.function(*self.args, **self.kwargs)
File "/srv/src/aura_engine/control.py", line 166, in wrapper_func
self.func(
File "/srv/src/aura_engine/scheduling/scheduler.py", line 546, in do_preload
self.engine.player.preload_group(entries)
File "/srv/src/aura_engine/engine.py", line 356, in preload_group
if entry.channel.load(file_path, metadata):
File "/srv/src/aura_engine/core/channels.py", line 345, in load
response = self.mixer.client.exec(self.name, "push", uri)
File "/srv/src/aura_engine/base/lang.py", line 49, in wrapper
raise e
File "/srv/src/aura_engine/base/lang.py", line 45, in wrapper
result = member(*args, **kwargs)
File "/srv/src/aura_engine/core/client.py", line 122, in exec
raise CoreConnectionError(msg, e)
aura_engine.core.client.CoreConnectionError: ('Error while issuing command to Liquidsoap', CoreConnectionError('Broken Pipe while sending command'))
Engine-core Log
Here engine-core tells us even less:
2023/04/03 14:13:44 [decoder:4] Available decoders: FFMPEG (priority: 10), OGG (priority: 1), IMAGE (priority: 1)
2023/04/03 14:13:44 [decoder:4] Trying decoder "FFMPEG"
2023/04/03 14:13:44 [decoder.ffmpeg:4] ffmpeg recognizes "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg" as: audio: {codec: vorbis, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2023/04/03 14:13:44 [decoder:4] Selected decoder FFMPEG for file "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2023/04/03 14:13:44 [metadata.flac:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [metadata.flac:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [metadata.mp4:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [metadata.mp4:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.ogg:5] Found a ogg logical stream, serial: 7107
2023/04/03 14:13:44 [decoder.ogg:5] Trying ogg/flac format
2023/04/03 14:13:44 [decoder.ogg:5] Trying ogg/speex format
2023/04/03 14:13:44 [decoder.ogg:5] Trying ogg/theora format
2023/04/03 14:13:44 [decoder.ogg:5] Trying ogg/vorbis format
2023/04/03 14:13:44 [decoder.ogg:5] ogg/vorbis format detected for stream 7107
2023/04/03 14:13:44 [decoder.taglib:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.taglib:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.id3:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.image.metadata:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.image.metadata:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [decoder.video.metadata:4] Unsupported file extension for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg"!
2023/04/03 14:13:44 [decoder.video.metadata:4] Unsupported MIME type for "/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg": audio/ogg!
2023/04/03 14:13:44 [request:5] Resolved to [[/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg]].
2023/04/03 14:13:44 [request:5] Resolving request [[/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg]].
2023/04/03 14:13:44 [request:5] Resolved to [[/var/audio/fallback/macy_gray_08_featuring_sunshine_anderson_dont_come_around.ogg]].
2023/04/03 14:13:44 [fallback_folder:4] Queued 1 requests
2023/04/03 14:17:25 [decoder:4] Decoding "/var/audio/source/musikprogramm/1.flac" ended: Ffmpeg_decoder.End_of_file.
2023/04/03 14:17:25 [decoder:4] Raised at Ffmpeg_decoder.mk_decoder.(fun).f in file "decoder/ffmpeg_decoder.ml", line 691, characters 12-29
2023/04/03 14:17:25 [decoder:4] Called from Decoder.mk_decoder.fill in file "decoder/decoder.ml", line 506, characters 10-31
2023/04/03 14:17:25 [decoder:4]
2023/04/03 14:17:26 [in_queue_0:4] Finished with "/var/audio/source/musikprogramm/1.flac".
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
2023/04/03 14:17:26 [on_metadata_2:5] Activations changed: static=[], dynamic=[switch_0:add_0:metadata.map_1:insert_metadata_2:mixer:stripped_stream:stripped_stream].
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
Related?
After the timeslot 14:16:00 the engine-core log file gets dumped with Queue is empty!
. So much that my pc has problems opening the log file. Here a short abstract of that file at that point:
2023/04/03 14:17:26 [request:5] Resolving request [[/var/audio/fallback/macy_gray_09_featuring_angie_stone_&_mos_def_my_nutmeg_phantasy.ogg]].
2023/04/03 14:17:26 [request:5] Resolved to [[/var/audio/fallback/macy_gray_09_featuring_angie_stone_&_mos_def_my_nutmeg_phantasy.ogg]].
2023/04/03 14:17:26 [fallback_folder:4] Queued 1 requests
2023/04/03 14:17:26 [lang:3] Successfully posted playlog to Engine API.
2023/04/03 14:17:26 [fallback_folder:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [fallback_folder:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [mksafe:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [mksafe:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [replay_metadata_0:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [replay_metadata_0:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
2023/04/03 14:17:26 [fallback-source:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [fallback-source:5] Got metadata at position 0: calling handlers...
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
2023/04/03 14:17:26 [in_queue_0:5] Queue is empty!
2023/04/03 14:17:26 [in_queue_0:5] Failed to prepare track: no file.
...
This only stops when the timeslot ends.