Re: [RDD] Possible Bug - Timed Wait Behaviour

[ijames]

Arron,

You will find that When you Schedule Music with the rivenell Music 
Scheduler it will pick songs at random with different Tenths. you have 
to Refine you log by Looking at when Your run it live and Adjust your 
times with songs by adding or subtracting songs with different lengths 
to get you your desired break times. On lengths you Us A music 
scheduling system like Powergold Music master,Natural Music Play list 
creator. They will have closer times.We used a schedule but because of 
our budget no longer use one.  We now do it Manually it takes a little 
time but we get better results.
 You can also schedule your break on Hard time and  it will play you 
breaks close to the time you want them to go.




On 2020-02-19 19:29, Aaron wrote:

Hi,

I reference to a previous post
(http://caspian.paravelsystems.com/pipermail/rivendell-dev/2020-January/028460.html)
I am still having issues with a Rivendell installation stopping
playout.

I think I have isolated the random stoppages down to timed events
where there is a wait time but where the log is running late and there
is an additional event between the late-running event and the
scheduled event.

Here is an example I observed just now:

In my 23:00 hour log I have a number of timed events including one
timed event (a song picked by RDLogManager) scheduled for 23:37:10.
The event is setup to wait up to 3 minutes if another piece of audio
is playing (I don't know why the PD has done it this way but he has).

When it comes to running the log a song began at 23:34:46.  Between
this song (which was actually scheduled for 23:33:50 - no timed start)
and my timed event due to start at 23:37:10 is a 2 second jingle
(scheduled for 23:37:08 - again not timed).  The song which started at
23:34:46 doesn't end up finishing until 23:38:02 - this is of course
fine as although 23:37:10 was timed to start, it was set to wait for
three minutes.  So RDAirPlay then plays the 2 second jingle and begins
the 23:37:10 song at 23:38:12 - all good.

However when we hit 23:40:10 (three minutes from after the scheduled
time) RDAirPlay attempts to play the song again.  It is already
playing so you get an audible glitch and playout stops entirely with
RDAirPlay ignoring future timed starts despite the system being on
Auto.

This is what it looks like in the log (The 23:37:10 song is Cart
400537) - notice the entries at 23:38:12 and 23:40:10 - it is trying
to run the same log line twice.

Feb 19 23:34:42 rdplayout1 rdairplay: log engine: finished event:
Line: 1209  Cart: 101119  Cut: 1 Card: 0  Stream: 0  Port: 0
Feb 19 23:34:42 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 72
Feb 19 23:34:42 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400409_001.wav  Handle: 73
Feb 19 23:34:42 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1210  Cart: 400409  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:34:42 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 130  Handle: 73
Feb 19 23:34:42 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 73
 Length: 3657  Speed: 10  Pitch: 0
Feb 19 23:34:46 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 73
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: finished event:
Line: 1210  Cart: 400409  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:34:46 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/110064_001.wav  Handle: 74
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1211  Cart: 110064  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:34:46 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 74
Feb 19 23:34:46 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 74
 Length: 196074  Speed: 10  Pitch: 0
Feb 19 23:38:02 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 74
Feb 19 23:38:02 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400580_001.wav  Handle: 75
Feb 19 23:38:02 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1212  Cart: 400580  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:38:02 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 75
Feb 19 23:38:02 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 75
 Length: 9952  Speed: 10  Pitch: 0
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: finished event:
Line: 1212  Cart: 400580  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:38:12 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 75
Feb 19 23:38:12 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400537_001.wav  Handle: 76
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1213  Cart: 400537  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:38:12 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 2063  Handle: 76
Feb 19 23:38:12 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 76
 Length: 238420  Speed: 10  Pitch: 0
Feb 19 23:40:10 rdplayout1 caed: LoadPlay

Re: [RDD] Possible Bug - Timed Wait Behaviour

[ijames]

Arron,

You will find that When you Schedule Music with the rivenell Music 
Scheduler it will pick songs at random with different Tenths. you have 
to Refine you log by Looking at when Your run it live and Adjust your 
times with songs by adding or subtracting songs with different lengths 
to get you your desired break times. On lengths you Us A music 
scheduling system like Powergold Music master,Natural Music Play list 
creator. They will have closer times.We used a schedule but because of 
our budget no longer use one.  We now do it Manually it takes a little 
time but we get better results.
 You can also schedule your break on Hard time and  it will play you 
breaks close to the time you want them to go.


Good Luck
On 2020-02-19 19:29, Aaron wrote:

Hi,

I reference to a previous post
(http://caspian.paravelsystems.com/pipermail/rivendell-dev/2020-January/028460.html)
I am still having issues with a Rivendell installation stopping
playout.

I think I have isolated the random stoppages down to timed events
where there is a wait time but where the log is running late and there
is an additional event between the late-running event and the
scheduled event.

Here is an example I observed just now:

In my 23:00 hour log I have a number of timed events including one
timed event (a song picked by RDLogManager) scheduled for 23:37:10.
The event is setup to wait up to 3 minutes if another piece of audio
is playing (I don't know why the PD has done it this way but he has).

When it comes to running the log a song began at 23:34:46.  Between
this song (which was actually scheduled for 23:33:50 - no timed start)
and my timed event due to start at 23:37:10 is a 2 second jingle
(scheduled for 23:37:08 - again not timed).  The song which started at
23:34:46 doesn't end up finishing until 23:38:02 - this is of course
fine as although 23:37:10 was timed to start, it was set to wait for
three minutes.  So RDAirPlay then plays the 2 second jingle and begins
the 23:37:10 song at 23:38:12 - all good.

However when we hit 23:40:10 (three minutes from after the scheduled
time) RDAirPlay attempts to play the song again.  It is already
playing so you get an audible glitch and playout stops entirely with
RDAirPlay ignoring future timed starts despite the system being on
Auto.

This is what it looks like in the log (The 23:37:10 song is Cart
400537) - notice the entries at 23:38:12 and 23:40:10 - it is trying
to run the same log line twice.

Feb 19 23:34:42 rdplayout1 rdairplay: log engine: finished event:
Line: 1209  Cart: 101119  Cut: 1 Card: 0  Stream: 0  Port: 0
Feb 19 23:34:42 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 72
Feb 19 23:34:42 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400409_001.wav  Handle: 73
Feb 19 23:34:42 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1210  Cart: 400409  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:34:42 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 130  Handle: 73
Feb 19 23:34:42 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 73
 Length: 3657  Speed: 10  Pitch: 0
Feb 19 23:34:46 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 73
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: finished event:
Line: 1210  Cart: 400409  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:34:46 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/110064_001.wav  Handle: 74
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1211  Cart: 110064  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:34:46 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 74
Feb 19 23:34:46 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 74
 Length: 196074  Speed: 10  Pitch: 0
Feb 19 23:38:02 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 74
Feb 19 23:38:02 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400580_001.wav  Handle: 75
Feb 19 23:38:02 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1212  Cart: 400580  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:38:02 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 75
Feb 19 23:38:02 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 75
 Length: 9952  Speed: 10  Pitch: 0
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: finished event:
Line: 1212  Cart: 400580  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:38:12 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
Handle: 75
Feb 19 23:38:12 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0
Name: /var/snd/400537_001.wav  Handle: 76
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: started audio cart:
Line: 1213  Cart: 400537  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:38:12 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 2063  Handle: 76
Feb 19 23:38:12 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 76
 Length: 238420  Speed: 10  Pitch: 0
Feb 19 23:40:10 rdplayout1 caed: 

Re: [RDD] Possible Bug - Timed Wait Behaviour

[drew Roberts]

Fred,

welcome back from your fantastic adventure... (much needed break? bout with
the flu? you get the picture...)

On Wed, Feb 26, 2020 at 6:22 PM Fred Gleason 
wrote:

> On Feb 19, 2020, at 19:29, Aaron  wrote:
>
> I reference to a previous post (
> http://caspian.paravelsystems.com/pipermail/rivendell-dev/2020-January/028460.html)
> I am still having issues with a Rivendell installation stopping playout.
>
> I think I have isolated the random stoppages down to timed events where
> there is a wait time but where the log is running late and there is an
> additional event between the late-running event and the scheduled event.
>
>
> Fixed in Git ‘master’ [5eec297].
>
> And, I must say Aaron, this was one of the very best bug reports I’ve ever
> read. The problem was devilishly intricate and difficult to provoke, yet
> the report included clear, detailed instructions on how to ‘make it
> happen’, including log trace data. And, the theory about what might be
> going wrong ("I think what is happening here is a bug with the timer…’)
> turned out to be spot on the money. Bullseye!
>

Don't think that just because you praise Aaron so lavishly here that the
rest of us will automatically be able to match this level of bug reporting
going forward no matter how much we try.

>
> I have only one additional request that would have made this a ‘perfect
> 10’ of bug report-ness: put it in a Github Issue. You can do that by going
> to:
>
> https://github.com/ElvishArtisan/rivendell/issues
>
> and then hitting the big green button that says ‘New Issue’.
>

And here, Fred, you show an uncanny ability to answer a question I have
been meaning to ask for several days before I even get to ask it!!! This I
hope to be able to remember to do consistently going forward...


>
> The big advantage of making a GitHub Issue is that the report will then
> stay around until one of the dev team can swat it. Discussing it on the
> mailing list is perfectly fine too, but the hurly-burly of day-to-day life
> means that those reports will often roll off and get forgotten (at least by
> me). Putting it in GitHub ensures that that won’t happen.
>
Yup.

>
> I’m very proud of the community that has coalesced around Rivendell. It’s
> you gals and guys, providing feedback, help for each other (including
> newcomers to Rivendell) and generally keeping the show on the road that
> make Rivendell and its community the empowering place that it is. It is an
> honor for me to be part of this group.
>
+1 Hear, hear!

>
> Cheers!
>
>
> |-|
> | Frederick F. Gleason, Jr. | Chief Developer |
> |   | Paravel Systems |
> |-|
>
> all the best,

drew
-- 
Enjoy the *Paradise Island Cam* playing
*Bahamian Or Nuttin* - https://www.paradiseislandcam.com/
___
Rivendell-dev mailing list
Rivendell-dev@lists.rivendellaudio.org
http://caspian.paravelsystems.com/mailman/listinfo/rivendell-dev

Re: [RDD] Possible Bug - Timed Wait Behaviour

[Fred Gleason]

On Feb 19, 2020, at 19:29, Aaron  wrote:

> I reference to a previous post 
> (http://caspian.paravelsystems.com/pipermail/rivendell-dev/2020-January/028460.html
>  
> )
>  I am still having issues with a Rivendell installation stopping playout.
> 
> I think I have isolated the random stoppages down to timed events where there 
> is a wait time but where the log is running late and there is an additional 
> event between the late-running event and the scheduled event.

Fixed in Git ‘master’ [5eec297].

And, I must say Aaron, this was one of the very best bug reports I’ve ever 
read. The problem was devilishly intricate and difficult to provoke, yet the 
report included clear, detailed instructions on how to ‘make it happen’, 
including log trace data. And, the theory about what might be going wrong ("I 
think what is happening here is a bug with the timer…’) turned out to be spot 
on the money. Bullseye!

I have only one additional request that would have made this a ‘perfect 10’ of 
bug report-ness: put it in a Github Issue. You can do that by going to:

https://github.com/ElvishArtisan/rivendell/issues

and then hitting the big green button that says ‘New Issue’.

The big advantage of making a GitHub Issue is that the report will then stay 
around until one of the dev team can swat it. Discussing it on the mailing list 
is perfectly fine too, but the hurly-burly of day-to-day life means that those 
reports will often roll off and get forgotten (at least by me). Putting it in 
GitHub ensures that that won’t happen.

I’m very proud of the community that has coalesced around Rivendell. It’s you 
gals and guys, providing feedback, help for each other (including newcomers to 
Rivendell) and generally keeping the show on the road that make Rivendell and 
its community the empowering place that it is. It is an honor for me to be part 
of this group.

Cheers!


|-|
| Frederick F. Gleason, Jr. | Chief Developer |
|   | Paravel Systems |
|-|
|  There’s no limit to what you can accomplish if you don’t care who  |
|  gets the credit.   |
| |
|   -- Eric Raymond   |
|-|

___
Rivendell-dev mailing list
Rivendell-dev@lists.rivendellaudio.org
http://caspian.paravelsystems.com/mailman/listinfo/rivendell-dev

[RDD] Possible Bug - Timed Wait Behaviour

[Aaron]

Hi,

I reference to a previous post (
http://caspian.paravelsystems.com/pipermail/rivendell-dev/2020-January/028460.html)
I am still having issues with a Rivendell installation stopping playout.

I think I have isolated the random stoppages down to timed events where
there is a wait time but where the log is running late and there is an
additional event between the late-running event and the scheduled event.

Here is an example I observed just now:

In my 23:00 hour log I have a number of timed events including one timed
event (a song picked by RDLogManager) scheduled for 23:37:10.  The event is
setup to wait up to 3 minutes if another piece of audio is playing (I don't
know why the PD has done it this way but he has).

When it comes to running the log a song began at 23:34:46.  Between this
song (which was actually scheduled for 23:33:50 - no timed start) and my
timed event due to start at 23:37:10 is a 2 second jingle (scheduled for
23:37:08 - again not timed).  The song which started at 23:34:46 doesn't
end up finishing until 23:38:02 - this is of course fine as although
23:37:10 was timed to start, it was set to wait for three minutes.  So
RDAirPlay then plays the 2 second jingle and begins the 23:37:10 song at
23:38:12 - all good.

However when we hit 23:40:10 (three minutes from after the scheduled time)
RDAirPlay attempts to play the song again.  It is already playing so you
get an audible glitch and playout stops entirely with RDAirPlay ignoring
future timed starts despite the system being on Auto.

This is what it looks like in the log (The 23:37:10 song is Cart 400537) -
notice the entries at 23:38:12 and 23:40:10 - it is trying to run the same
log line twice.

Feb 19 23:34:42 rdplayout1 rdairplay: log engine: finished event: Line:
1209  Cart: 101119  Cut: 1 Card: 0  Stream: 0  Port: 0
Feb 19 23:34:42 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
 Handle: 72
Feb 19 23:34:42 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0  Name:
/var/snd/400409_001.wav  Handle: 73
Feb 19 23:34:42 rdplayout1 rdairplay: log engine: started audio cart: Line:
1210  Cart: 400409  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:34:42 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 130  Handle: 73
Feb 19 23:34:42 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 73
 Length: 3657  Speed: 10  Pitch: 0
Feb 19 23:34:46 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
 Handle: 73
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: finished event: Line:
1210  Cart: 400409  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:34:46 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0  Name:
/var/snd/110064_001.wav  Handle: 74
Feb 19 23:34:46 rdplayout1 rdairplay: log engine: started audio cart: Line:
1211  Cart: 110064  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:34:46 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 74
Feb 19 23:34:46 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 74
 Length: 196074  Speed: 10  Pitch: 0
Feb 19 23:38:02 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
 Handle: 74
Feb 19 23:38:02 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0  Name:
/var/snd/400580_001.wav  Handle: 75
Feb 19 23:38:02 rdplayout1 rdairplay: log engine: started audio cart: Line:
1212  Cart: 400580  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 1
Feb 19 23:38:02 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 0  Handle: 75
Feb 19 23:38:02 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 75
 Length: 9952  Speed: 10  Pitch: 0
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: finished event: Line:
1212  Cart: 400580  Cut: 1 Card: 0  Stream: 0  Port: 1
Feb 19 23:38:12 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
 Handle: 75
Feb 19 23:38:12 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 0  Name:
/var/snd/400537_001.wav  Handle: 76
Feb 19 23:38:12 rdplayout1 rdairplay: log engine: started audio cart: Line:
1213  Cart: 400537  Cut: 1 Pos: 0  Card: 0  Stream: 0  Port: 0
Feb 19 23:38:12 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 0
 Pos: 2063  Handle: 76
Feb 19 23:38:12 rdplayout1 caed: Play - Card: 0  Stream: 0  Handle: 76
 Length: 238420  Speed: 10  Pitch: 0
Feb 19 23:40:10 rdplayout1 caed: LoadPlayback  Card: 0  Stream: 1  Name:
/var/snd/400537_001.wav  Handle: 77
Feb 19 23:40:10 rdplayout1 rdairplay: log engine: started audio cart: Line:
1213  Cart: 400537  Cut: 1 Pos: 117116  Card: 0  Stream: 1  Port: 1
Feb 19 23:40:10 rdplayout1 caed: PlaybackPosition - Card: 0  Stream: 1
 Pos: 119179  Handle: 77
Feb 19 23:40:10 rdplayout1 caed: Play - Card: 0  Stream: 1  Handle: 77
 Length: 121304  Speed: 10  Pitch: 0
Feb 19 23:40:10 rdplayout1 caed: StopPlayback - Card: 0  Stream: 0  Handle:
76
Feb 19 23:40:10 rdplayout1 rdairplay: log engine: finished event: Line:
1213  Cart: 400537  Cut: 1 Card: 0  Stream: 1  Port: 1
Feb 19 23:40:10 rdplayout1 caed: UnloadPlayback - Card: 0  Stream: 0
 Handle: 76
Feb 19 23:40:10 rdplayout1 caed: StopPlay