[Icecast] ices2, metadata, bumps and crashes

Tue Aug 16 19:39:55 UTC 2005

[In case anyone is wondering, the missing message is because I emailed 
Mike directly, not realising I wasn't sending to the list.]

On Tue, Aug 16, 2005 at 12:56:57PM +0200, Michael Smith wrote:
> On 8/16/05, Paul Martin <pm at nowster.zetnet.co.uk> wrote:
> > On Tue, Aug 16, 2005 at 10:31:09AM +0200, Michael Smith wrote:
> > 
> > > This shouldn't cause any audible artifacts in the stream - and if it's
> > > crashing the encoder thread, that's a REALLY serious problem.
> > >
> > > Can you investigate what causes it to die?
> > 
> > Difficult, as it's threaded code. Is there a particular debug setting
> > that would be useful?
> 
> Just bump it to level 4 (DEBUG logging). It should log specifically
> why the thread is shutting down.

Caught it yesterday, as I was already running level 4:

[2005-08-15  04:06:30] DBUG metadata/metadata_thread_signal meta thread wakeup
[2005-08-15  04:06:30] DBUG metadata/metadata_thread_signal reading metadata from "/var/tmp/metadata.live"
[2005-08-15  04:06:30] INFO metadata/metadata_thread_signal tag 1 is ARTIST=Bbbb Bbbbb Bbbbbb
[2005-08-15  04:06:30] INFO metadata/metadata_thread_signal tag 2 is TITLE=Bbbbbb
[2005-08-15  04:06:30] INFO metadata/metadata_thread_signal tag 3 is ALBUM=Bbbbbbbbb
[2005-08-15  04:06:30] INFO metadata/metadata_thread_signal tag 4 is ORGANIZATION=Test Radio Stream
[2005-08-15  04:06:30] INFO metadata/metadata_thread_signal Updating metadata
[2005-08-15  04:06:30] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 22050 Hz
[2005-08-15  04:06:30] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:06:30] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 22050 Hz, quality -1.010000
[2005-08-15  04:06:30] INFO audio/resample_initialise Initialised resampler for 2 channels, from 44100 Hz to 44100 Hz
[2005-08-15  04:06:30] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 16000 Hz
[2005-08-15  04:06:30] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:06:30] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 16000 Hz, quality -2.000000
[2005-08-15  04:06:30] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:06:30] INFO encode/encode_initialise Encoder initialising in VBR mode: 2 channel(s), 44100 Hz, quality -1.001000
[2005-08-15  04:10:58] INFO signals/signal_usr1_handler Metadata update requested
[2005-08-15  04:10:58] DBUG metadata/metadata_thread_signal meta thread wakeup
[2005-08-15  04:10:58] DBUG metadata/metadata_thread_signal reading metadata from "/var/tmp/metadata.live"
[2005-08-15  04:10:58] INFO metadata/metadata_thread_signal tag 1 is ARTIST=Aaaa Aaaa
[2005-08-15  04:10:58] INFO metadata/metadata_thread_signal tag 2 is TITLE=Aaaaaaa Aaaaaa
[2005-08-15  04:10:58] INFO metadata/metadata_thread_signal tag 3 is ALBUM=Aaaaa Aaaaaaa
[2005-08-15  04:10:58] INFO metadata/metadata_thread_signal tag 4 is ORGANIZATION=Test Radio Stream
[2005-08-15  04:10:58] INFO metadata/metadata_thread_signal Updating metadata
[2005-08-15  04:10:58] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 22050 Hz
[2005-08-15  04:10:58] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:10:58] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 22050 Hz, quality -1.010000
[2005-08-15  04:10:58] INFO audio/resample_initialise Initialised resampler for 2 channels, from 44100 Hz to 44100 Hz
[2005-08-15  04:10:58] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 16000 Hz
[2005-08-15  04:10:58] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:10:58] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 16000 Hz, quality -2.000000
[2005-08-15  04:10:58] EROR stream/ices_instance_stream Send error: No error (Success)
[2005-08-15  04:15:57] INFO signals/signal_usr1_handler Metadata update requested
...
[2005-08-15  04:33:22] INFO signals/signal_usr1_handler Metadata update requested
[2005-08-15  04:33:22] DBUG metadata/metadata_thread_signal meta thread wakeup
[2005-08-15  04:33:22] DBUG metadata/metadata_thread_signal reading metadata from "/var/tmp/metadata.live"
[2005-08-15  04:33:22] INFO metadata/metadata_thread_signal tag 1 is ARTIST=Xxxxxxx Xxxxxxx
[2005-08-15  04:33:22] INFO metadata/metadata_thread_signal tag 2 is TITLE=Xxxxx Xxxxx
[2005-08-15  04:33:22] INFO metadata/metadata_thread_signal tag 3 is ALBUM=Xxxxxxxx
[2005-08-15  04:33:22] INFO metadata/metadata_thread_signal tag 4 is ORGANIZATION=Test Radio Stream
[2005-08-15  04:33:22] INFO metadata/metadata_thread_signal Updating metadata
[2005-08-15  04:33:22] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 22050 Hz
[2005-08-15  04:33:22] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:33:22] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 22050 Hz, quality -1.010000
[2005-08-15  04:33:22] INFO audio/resample_initialise Initialised resampler for 1 channels, from 44100 Hz to 16000 Hz
[2005-08-15  04:33:22] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  04:33:22] INFO encode/encode_initialise Encoder initialising in VBR mode: 1 channel(s), 16000 Hz, quality -2.000000
[2005-08-15  04:36:03] EROR stream/ices_instance_stream Send error: Socket error (Broken pipe)
[2005-08-15  04:36:03] DBUG input/input_flush_queue Input queue flush requested
[2005-08-15  04:36:18] WARN stream/ices_instance_stream Trying reconnect after server socket error
[2005-08-15  04:36:18] INFO stream/ices_instance_stream Connected to server: localhost:8000/stereo44.ogg
[2005-08-15  04:36:18] DBUG input/input_flush_queue Input queue flush requested
[2005-08-15  04:37:30] INFO signals/signal_usr1_handler Metadata update requested

Note that at 04:06:30, there are three encoder threads, and that at 
04:10:58, there are only two. The error at 04:33:22 is probably icecast2 
closing the socket due to there being no data on it. Bear in mind that 
ices2 had been running for several days (not sure how long) at that 
point.

> > > How bad are the artifacts at the stream boundaries?
> > 
> > Just a little bump of silence in the sound. Nothing objectionable.
> > Monitoring using xmms, ogg123 and foobar2000.
> 
> Err... that _really_ shouldn't be happening. It certainly never has
> for me (except when playing with players that close/reopen the sound
> device for every new logical stream, which is a bad thing to do).

Well, ogg123 definitely has its own problems too, probably a 2^31 
rollover problem. (It spits out bursts of white noise after about 3 
hours at 44.1kHz.)

The bump is noticeable. I suspect it's due to the encoder being 
reinitialised in order to get a new serial number.

As I said in the previous email, I'm using the aoTuv beta4 encoder, but 
I also get the same problems with the stock Xiph Vorbis encoder. Running 
on Debian Linux 2.6.12.

-- 
Paul Martin <pm at zetnet.net> (work)
  <pm at nowster.zetnet.co.uk> (home)