ProppFrexx ONAIR User-Forum

Hello,

We just have another error in the overlay.
2 weeks ago I reported also the same error here.

The overlay is loaded and shown. All tracks seems to be loaded correctly.
But the overlay player seems to be stuck because it's not counting down to playtime: xx:59.40, so it is not playing!

Below I have the debug log:

8-5-2014 15:47:12: Processing Script-Line 1 (Retries=1000): 1 Random : /Disco (Filter=, Options=None)
8-5-2014 15:47:12: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Disco\Bee Gees - You should be dancing.mp3).
8-5-2014 15:53:02: UpdateEntryStatistics 'The Buggles - Lenny' PlayStart=2014-05-08T15:53:02
8-5-2014 15:53:04: Processing Script-Line 2 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:53:05: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starts processing.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' start loading.
8-5-2014 15:54:40: OverlayScheduler: Overlay:Nieuws, Command:News (Nieuws), Start:8-5-2014 15:59:40 processed
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' ProgressChanged State=0.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starting LoadScript.
8-5-2014 15:54:40: Processing Script-Line 1 (Retries=1000): 1 Random : Kris en Lisanne (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Reclame\Kris en Lisanne\Spot-Kris-en-Lisanne-voice-Jeroen.mp3).
8-5-2014 15:54:40: Processing Script-Line 2 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\AFM nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\AFM nieuws.mp3).
8-5-2014 15:54:40: Processing Script-Line 3 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\nieuws.mp3).
8-5-2014 15:54:40: Processing Script-Line 4 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\Uuropener Aladna Fm.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\Uuropener Aladna Fm.mp3).
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' LoadScript 4 Script-Tracks found.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' LoadScript finished 4 Total-Tracks (00:03:17.2090000 Playtime).
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' finish loading.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starting (4 Tracks).
8-5-2014 15:56:08: UpdateEntryStatistics 'Adele - Rolling In The Deep' PlayStart=2014-05-08T15:56:08
8-5-2014 15:59:47: ProgramScheduler: Program:Automaat Overdag (Automaat), Start:8-5-2014 16:01:00, End:8-5-2014 17:00:00, Started:True
8-5-2014 15:59:48: Processing Script-Line 1 (Retries=1000): 1 Random : /Disco (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Disco\Labelle - Voulez-vous coucher avec moi.mp3).
8-5-2014 15:59:48: Processing Script-Line 2 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Oldies\oldies 60-70\Barbra Streisand - Second Hand Rose.mp3).
8-5-2014 15:59:48: Processing Script-Line 3 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:48: Processing Script-Line 4 (Retries=1000): 1 Random : /Recurrent (Filter=, Options=None)
8-5-2014 15:59:48: Script-History: entry 'Artist' word matches in history (Entry=Ilse Delange - Winter of love, Artist1=ilse delange, Artist2=ilse delange, MaxHistory=250)
8-5-2014 15:59:48: Global-History: entry directly contain in history (Entry=Alexandra Stan - Mr. Saxobeat, MaxHistory=500)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Recurrent\2012\Fun. - carry on.mp3).
8-5-2014 15:59:48: Processing Script-Line 5 (Retries=1000): 1 Random : /Gold (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Gold\2004\Counting Crows - Accidentally in love.mp3).
8-5-2014 15:59:48: Processing Script-Line 6 (Retries=1000): 1 Random : /Nederlands (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:48: Processing Script-Line 7 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Oldies\oldies 60-70\Bill Withers - Ain't no sunshine.mp3).
8-5-2014 15:59:48: Processing Script-Line 8 (Retries=1000): 1 Random : /Disco (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Disco\Labelle - Lady Marmalade.mp3).
8-5-2014 15:59:48: Processing Script-Line 9 (Retries=1000): 1 Random : /Powergold (Filter=, Options=None)
8-5-2014 15:59:48: Global-History: entry 'Artist' word matches in history (Entry=Pink - Nobody knows, Artist1=pink, Artist2=pink, MaxHistory=500)
8-5-2014 15:59:48: Script-History: entry 'Artist' word matches in history (Entry=Alain Clark - Blow me away, Artist1=alain clark, Artist2=alain clark, MaxHistory=250)
8-5-2014 15:59:48: Script-History: entry 'Artist' word matches in history (Entry=Alain Clark - Love Is Everywhere, Artist1=alain clark, Artist2=alain clark, MaxHistory=250)
8-5-2014 15:59:48: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:48: Processing Script-Line 10 (Retries=1000): 1 Random : /Hits (Filter=, Options=None)
8-5-2014 15:59:48: Script-History: entry 'Album' word matches in history (Entry=Avicii & Aloe Blacc - Wake Me Up, Album1=week 25, Album2=nederlandse top 40 week 25 2012, MaxHistory=250)
8-5-2014 15:59:48: Script-History: entry 'Artist' word matches in history (Entry=Passenger - The Wrong Direction, Artist1=passenger, Artist2=passenger, MaxHistory=250)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Hits\2014\Jett Rebel Tonight.mp3).
8-5-2014 15:59:48: Processing Script-Line 11 (Retries=1000): 1 Random : /Gold (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Gold\2002\Sarah Connor - From Sarah with love.mp3).
8-5-2014 15:59:48: Processing Script-Line 12 (Retries=1000): 1 Random : /Recurrent (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:48: Processing Script-Line 13 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Oldies\oldies 60-70\Byrds - Turn turn turn.mp3).
8-5-2014 15:59:48: Processing Script-Line 14 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:48: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Oldies\oldies 80\flavium - nightlife.mp3).
8-5-2014 15:59:48: Processing Script-Line 15 (Retries=1000): 1 Random : /Powergold (Filter=, Options=None)
8-5-2014 15:59:48: Script-History: entry directly contain in history (Entry=Lily Allen - 22, MaxHistory=250)
8-5-2014 15:59:48: Global-History: entry 'Artist' word matches in history (Entry=Coldplay - Viva la vida, Artist1=coldplay, Artist2=coldplay, MaxHistory=500)
8-5-2014 15:59:48: Script-History: entry 'Artist' word matches in history (Entry=Ilse DeLange - I love you, Artist1=ilse delange, Artist2=ilse delange, MaxHistory=250)
8-5-2014 15:59:49: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:49: Processing Script-Line 16 (Retries=1000): 1 Random : /Gold (Filter=, Options=None)
8-5-2014 15:59:49: Script-History: entry 'Album' word matches in history (Entry=Ashlee Simpson - Pieces of me, Album1=top 40 2004 - week 38, Album2=top 40 2004 - week 38, MaxHistory=250)
8-5-2014 15:59:49: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Gold\2006\Nelly Furtado ft. Timbaland - Promiscuous.mp3).
8-5-2014 15:59:49: Processing Script-Line 1 (Retries=1000): 1 Random : /Disco (Filter=, Options=None)
8-5-2014 15:59:49: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Disco\The Sugarhill Gang - Rappers Delight.mp3).
8-5-2014 15:59:53: UpdateEntryStatistics 'Aladna FM - Dit is Aladna FM' PlayStart=2014-05-08T15:59:53
8-5-2014 15:59:55: Processing Script-Line 2 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 15:59:55: GetNextTracks processed, 2 script result entries returned.
8-5-2014 15:59:55: UpdateEntryStatistics 'DHT ft Edmee - Listen to your heart' PlayStart=2014-05-08T15:59:55
8-5-2014 16:01:00: UpdateEntryStatistics 'Labelle - Voulez-vous coucher avec moi' PlayStart=2014-05-08T16:01:00
8-5-2014 16:01:01: Processing Script-Line 3 (Retries=1000): 1 Random : /Oldies (Filter=, Options=None)
8-5-2014 16:01:01: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Muziek Collectie\Oldies\oldies 60-70\Mott The Hoople - All The Young Dudes.mp3).
8-5-2014 16:03:34: ProgramScheduler: Scheduler stopped

The log shows that the overlay starts loading and all track all loaded succesfully.
But in fact the overlay is stuck and not counting down to 59,40 when it should be played.
Can you see what went wrong?

Greetz,
Jesper, Aladna Fm

To analyze where it got stuck I would need to know your exact overlay settings...i.e.:
- the start type?
- did you specify manual playout?
- did you set any options, e.g. AsPlaylistInsert

If I assume an automatic playout and no AsPlaylistInsert option, then it very much looks like the playlist stream could not be created.
What means the system got stuck in opening and processing the 4 tracks!
This should actually never really happen, except the tracks are somehow corrupt.

As you happen to know the exact 4 track being involved (see above), can you post them to me to take a look at!?
Is one of them being downloaded dynamically and probably didn't got released by it's download process?
Else than that there is no real chance.

I just looked to your other post again and it was exactly the same symptom - funny enough to see, that it was also the same time slot?!
So I closed the other post to only continue here.

Still, from why you say/write/log it really looks like one of the mp3 files can not be processed, is corrupt or is locked by the OS form being opened.
Actually I believe, that the file in somehow inaccessible resp. is locked by some other process and as such any sub-sequent process (like ProppFrexx) can not process it.
The bad thing is, that I can not really monitor this, as a file-open request might wait infinite and it looks, like this is actually happening here.

One other alternative might also be a defect hard drive - have you checked that already?

The harddrive is functioning well, but I think something is going wrong in the 3 news tracks or the overlay settings.
I have send the overlay settings screenshot and a script screenshot with this message.

The overlay control commands are:
Mixer_input_mute_on Live
Sleep 2000
PLS_current_close

a) the control-commands are executed when the tracks have been played - but we do not even come to that point here, so that can not be the issue.

b) the overlay settings are all fine and could also not lead to the blocking

c) The overlay got stuck when trying to open the tracks for playback.
So the only chance it can get blocked there is as said:
- a locked/blocked file on the OS level
- a corrupt file
- a defect hard disk
I am pretty sure, that this is the only chance...
Btw, a hard disk might work just perfectly fine, up until a defect block is accessed, which could be totally random.

Btw, why do you reload all these media libs with this script (as you are not even using those media libs in this script), looks useless...

Ok that's clear, it has to do something with the tracks.
I will check it en test.

But it leaves me with on last question:
Why is it working properly for weeks and suddenly is goes wrong? If its a track error I think the error should happen everytime the overlay player gets loaded.

You said, you download a new track every hour?!
That might be the reason. E.g.:
- the newly downloaded track might be corrupt
- the newly downloaded track might occupy a defect block of the hard disk
- the newly downloaded track wasn't closed properly by the download process and is still locked
- etc.

What you might do (if it happens again), as all the news tracks do use the same name all the time:
- place a link onto the ProppFrexx Trackboard
- if it got stuck again, immediately try to double-click the track(s) from the Trackboard (a double-click will just open them in the PFL-Player)
- and also try to copy those news files physically to a different location in order to be able to send them to me

PLUS: when the overlay gets stuck again, you might create a DUMP file from within the TaskManager.

I have did a full check up of the hard drive and there are no damaged sectors.
And i have checked the news download log and everything went fine with the download and the mp3 was copied succesfully to the destination folder.

But one question: I have take another look to the debug log en found the following:


YESTERDAY WHEN THINGS WENT WRONG

8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starts processing.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' start loading.
8-5-2014 15:54:40: OverlayScheduler: Overlay:Nieuws, Command:News (Nieuws), Start:8-5-2014 15:59:40 processed
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' ProgressChanged State=0.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starting LoadScript.
8-5-2014 15:54:40: Processing Script-Line 1 (Retries=1000): 1 Random : Kris en Lisanne (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Reclame\Kris en Lisanne\Spot-Kris-en-Lisanne-voice-Jeroen.mp3).
8-5-2014 15:54:40: Processing Script-Line 2 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\AFM nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\AFM nieuws.mp3).
8-5-2014 15:54:40: Processing Script-Line 3 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\nieuws.mp3).
8-5-2014 15:54:40: Processing Script-Line 4 (Retries=1000): 1 LoadTrack : D:\ProppFrexx Media\Nieuws\Uuropener Aladna Fm.mp3 (Filter=, Options=SuppressHistoryCheck)
8-5-2014 15:54:40: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Nieuws\Uuropener Aladna Fm.mp3).
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' LoadScript 4 Script-Tracks found.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' LoadScript finished 4 Total-Tracks (00:03:17.2090000 Playtime).
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' finish loading.
8-5-2014 15:54:40: Overlay 'Nieuws@2014-05-08T15:59:40' starting (4 Tracks).


TODAY WHEN THINGS WORKS FINE

9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' starts processing.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' start loading.
9-5-2014 7:54:37: OverlayScheduler: Overlay:Nieuws, Command:News (Nieuws), Start:9-5-2014 7:59:40 processed
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' ProgressChanged State=0.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' starting LoadScript.
9-5-2014 7:54:37: Processing Script-Line 1 (Retries=1000): 1 Random : Kris en Lisanne (Filter=, Options=SuppressHistoryCheck)
9-5-2014 7:54:37: GetNextTracks processed, 1 script result entries returned (File=D:\ProppFrexx Media\Reclame\Kris en Lisanne\Spot-Kris-en-Lisanne-voice-Hannelore.mp3).
9-5-2014 7:54:37: Processing Script-Line 2 (Retries=1000): 1 LoadTrack : C:\Nieuws\AFM nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
9-5-2014 7:54:37: GetNextTracks processed, 1 script result entries returned (File=C:\Nieuws\AFM nieuws.mp3).
9-5-2014 7:54:37: Processing Script-Line 3 (Retries=1000): 1 LoadTrack : C:\Nieuws\nieuws.mp3 (Filter=, Options=SuppressHistoryCheck)
9-5-2014 7:54:37: GetNextTracks processed, 1 script result entries returned (File=C:\Nieuws\nieuws.mp3).
9-5-2014 7:54:37: Processing Script-Line 4 (Retries=1000): 1 LoadTrack : C:\Nieuws\Uuropener Aladna Fm.mp3 (Filter=, Options=SuppressHistoryCheck)
9-5-2014 7:54:37: GetNextTracks processed, 1 script result entries returned (File=C:\Nieuws\Uuropener Aladna Fm.mp3).
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' LoadScript 4 Script-Tracks found.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' LoadScript finished 4 Total-Tracks (00:02:57.0050000 Playtime).
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' finish loading.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' starting (4 Tracks).
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' PrepareOverlayStream (4 Tracks, Duration=00:02:57.0050000).
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' prepared.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' DoPlayOverlay started.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' ProgressChanged State=1.

Notice when things went WRONG YESTERDAY the following script lines were NOT processed:

9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' PrepareOverlayStream (4 Tracks, Duration=00:02:57.0050000).
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' prepared.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' DoPlayOverlay started.
9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' ProgressChanged State=1.

Does this have to do with the mp3's or something else??
And the overlayplayer was already showing the player with the 4 tracks and already was counting down for a minute.
And suddenly at 5 minutes to go, it went stuck and it shows loading instead of waiting.

Greetz
Jesper, Aladna Fm

Yes of course, that is the difference in the logs!
And tat the reason, why I believe, that something must go wrong with the downloaded mp3's.
The reason, why there are missing debug log entries is, that is got stuck.
That actually shows us/me the exact position where something went wrong and where it got stuck!
Meaning exactly between these two log-lines:
1) 9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' starting (4 Tracks).
2) 9-5-2014 7:54:37: Overlay 'Nieuws@2014-05-09T07:59:40' PrepareOverlayStream (4 Tracks, Duration=00:02:57.0050000).
And inbetween these two log-lines the only thing done is opening the mp3s for playback, nothing more!
And that means, that the opening of the files got somehow blocked...