Icecast - Aug 2005 - ices2, metadata, bumps and crashes

I'm using ices2's metadata facility to update the name of a track in a 
vorbis stream:

  <input>
     <module>alsa</module>
     <param name="rate">44100</param>
     <param name="channels">2</param>
     <param name="device">hw:1,0</param>
     <param name="metadata">1</param>
     <param
name="metadatafilename">/var/tmp/metadata.live</param>
  </input>

When my jukebox program sends SIGUSR1 to ices2 (to cause the metadata to 
be re-read), the vorbis stream is totally reset causing an audible bump 
in the audio on the stream. Occasionally, the lead ices2 encoding thread 
dies.

On a metadata update the logfile shows stuff like this:

[2005-08-15  23:23:01] INFO signals/signal_usr1_handler Metadata update
requested
[2005-08-15  23:23:01] DBUG metadata/metadata_thread_signal meta thread wakeup
[2005-08-15  23:23:01] DBUG metadata/metadata_thread_signal reading metadata
from "/var/tmp/metadata.live"
[2005-08-15  23:23:01] INFO metadata/metadata_thread_signal tag 1 is
ARTIST=Beatles
[2005-08-15  23:23:01] INFO metadata/metadata_thread_signal tag 2 is TITLE=Honey
Pie
[2005-08-15  23:23:01] INFO metadata/metadata_thread_signal tag 3 is
ALBUM=You're listening to a test radio stream
[2005-08-15  23:23:01] INFO metadata/metadata_thread_signal tag 4 is
ORGANIZATION=Test Radio Stream
[2005-08-15  23:23:01] INFO metadata/metadata_thread_signal Updating metadata
[2005-08-15  23:23:01] INFO audio/resample_initialise Initialised resampler for
1 channels, from 44100 Hz to 22050 Hz
[2005-08-15  23:23:01] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  23:23:01] INFO encode/encode_initialise Encoder initialising in VBR
mode: 1 channel(s), 22050 Hz, quality -1.010000
[2005-08-15  23:23:01] INFO audio/resample_initialise Initialised resampler for
2 channels, from 44100 Hz to 44100 Hz
[2005-08-15  23:23:01] INFO audio/resample_initialise Initialised resampler for
1 channels, from 44100 Hz to 16000 Hz
[2005-08-15  23:23:01] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  23:23:01] INFO encode/encode_initialise Encoder initialising in VBR
mode: 1 channel(s), 16000 Hz, quality -2.000000
[2005-08-15  23:23:01] DBUG encode/encode_clear Clearing encoder engine
[2005-08-15  23:23:01] INFO encode/encode_initialise Encoder initialising in VBR
mode: 2 channel(s), 44100 Hz, quality -1.001000

I'm on Linux 2.6.12, using the Debian 2.0.1-4 package of ices2, with the 
aotuvb4 version of libvorbis (though the problem happens with the 
standard vorbis codec).

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

On 8/16/05, Paul Martin <pm@nowster.zetnet.co.uk>
wrote:
> I'm using ices2's metadata facility to update the name of a track
in a
> vorbis stream:
> 
>   <input>
>      <module>alsa</module>
>      <param name="rate">44100</param>
>      <param name="channels">2</param>
>      <param name="device">hw:1,0</param>
>      <param name="metadata">1</param>
>      <param
name="metadatafilename">/var/tmp/metadata.live</param>
>   </input>
> 
> When my jukebox program sends SIGUSR1 to ices2 (to cause the metadata to
> be re-read), the vorbis stream is totally reset causing an audible bump
> in the audio on the stream. Occasionally, the lead ices2 encoding thread
> dies.
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?

How bad are the artifacts at the stream boundaries?

Mike

[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@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@zetnet.net> (work)
  <pm@nowster.zetnet.co.uk> (home)

On 8/16/05, Paul Martin <pm@nowster.zetnet.co.uk> wrote:
> 
> Caught it yesterday, as I was already running level 4:
This line:
[2005-08-15  04:10:58] EROR stream/ices_instance_stream Send error: No
error (Success)

is the one that catches my attention. Unfortunately, ices's error
logging is somewhat sub-standard. Can you cross reference this against
your icecast error.log to see if there's anything to indicate why this
instance errored out (which it did - the 'Success' being printed is a
problem with errno getting lost)?

> 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.)
I think I've noticed that one in the past, but I almost never use
ogg123, so I haven't looked into it.
> 
> The bump is noticeable. I suspect it's due to the encoder being
> reinitialised in order to get a new serial number.
That cause a substantial jump in both cpu usage and bitrate for a
moment, but if your client has any buffering at all (and most of them
buffer quite a lot), then that shouldn't be a problem in any way. I'm
curious as to why it is... it might just be the cpu usage causing the
(hardware) audio buffers to get starved slightly - the application
buffers (in ogg123 or other software) are more than big enough to
cope.


Mike

On Tue, Aug 16, 2005 at 12:56:57PM +0200, Michael Smith wrote:
> 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).
I've switched ogg123 from using the "OSS audio driver output" to
using
"Advanced Linux Sound Architecture (ALSA) output", and the bumps are 
there just the same.

Next to see if ogg123 outputting to wav does it, too. It'll probably 
show best on something like a continuous 1kHz tone.

By the way, RealPlayer can't cope with such a stream. It gives up at the 
serial number change.

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

On Wed, Aug 17, 2005 at 12:17:49PM +0100, Paul Martin wrote:
> Next to see if ogg123 outputting to wav does it, too. It'll probably 
> show best on something like a continuous 1kHz tone.
It does. Notice the flat bit in the waveform in the audacity screenshot 
attached (22kB). This shows that it's not a buffering problem.

This application crossfades one track to another, changing the metadata 
at the start of the crossfade. If you were to play tracks without a 
crossfade, you'd not notice the problem.

-- 
Paul Martin <pm@zetnet.net> (work)
  <pm@nowster.zetnet.co.uk> (home)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: log.png
Type: image/png
Size: 22019 bytes
Desc: not available
Url :
http://lists.xiph.org/pipermail/icecast/attachments/20050817/0b931b3f/log-0001.png