track playing 2 times without scheduling
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Hi,

    I frequently got (every few hours) a problem in playout.
    Sometimes, a music is playing and then, the same music starts again from the begining.
    I've checked schedule and, there's no duplicate entry.

    In log file (airtime/pypo-liquidsoap/ls_script.log) I see many "End of track before cue-out point." and "Ignoring negative cue-in point."

    I've never changed CUE-IN and CUE out values so, can anyone help me understand why is this happening?

    Thanks

    The log file shows:
    2012/08/27 15:54:00 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
    2012/08/27 15:54:01 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3" (RID 25).
    2012/08/27 15:58:01 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
    2012/08/27 15:58:02 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
    2012/08/27 15:58:02 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3" (RID 0).
    2012/08/27 16:02:03 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".



    2012/08/27 15:58:01 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
    2012/08/27 15:58:02 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
    2012/08/27 15:58:02 [cue_cut_5152:3] End of track before cue-out point.
    2012/08/27 15:58:02 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3" (RID 0).
    2012/08/27 15:58:02 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/08/27 15:58:02 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=3850 &
    2012/08/27 15:58:02 [lang:3] Using stream_format 1
    2012/08/27 16:02:02 [decoder:3] Method "MAD" accepted "/var/tmp/airtime/pypo/cache/scheduler/7ac0ae0304b5c00e65b91b3361a66aa8.mp3".
    2012/08/27 16:02:03 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/8f001fe538563404490eda5d7e06ab27.mp3".
  • 13 Comments sorted by
  • Vote Up0Vote Down Martin KonecnyMartin Konecny
    Posts: 1,860Member
    Is it possible you have overlapping shows by mistake? 
    Airtime Pro Hosting: http://airtime.pro
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Hi,
    No, no overlapping shows. The next show starts at 18h.

    This did happened before and, I've reinstalled all so, this is a clean install of airtime, without cue in/out changes and, no liquid scripts changed.

    In Airtime schedule, music1 should start at 2012-08-27 15:54:06
    and next track at 2012-08-27 15:58:07
    Instead of next track, the same music was played

    About the track, Airtime says the lenght is 00:04:01.1
    In the playlist builder :
    Cue Out:00:04:01.084625
    Original Length:00:04:01.084625

    ffmpeg says length is: 00:04:01.05

    But, even if this is related with the 0.04 difference... this doesn't happen al the time with same track...

    Any ideas?

    Thanks for the help
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Just to share the solution...

    I've created same track in various programs (audacity, soundforge,etc) in mp3 format.
    All of the copies result in "End of track before cue-out point."

    Next test was to save it with Audacity in ogg format.
    There's no "End of track before cue-out point." message anymore.

    2012/08/30 17:51:45 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/08/30 17:51:48 [cue_cut_5152:3] Cueing out...

    something was wrong with mp3 calculations but, in ogg format seems ok now and, until now, no track repeat

    Regards,
  • Vote Up0Vote Down Martin KonecnyMartin Konecny
    Posts: 1,860Member
    Please keep us up to date. I'm not convinced this track length discrepancy was the cause of repeating tracks.
    Airtime Pro Hosting: http://airtime.pro
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Hi,

    About repeating tracks, it stopped.
    Until this moment, no repeats...

    things went smooth for the last days but, now... something bad...

    I was using hardly airtime the last few days, adding new files, editing schedule, re-editing schedule, editing it again, and again. (many insert, remove, insert, move, etc in schedule)

    The problem I found was started with log entries like this: 

    - c40212c2c63036d4cc8a2a1487c4d853 corresponds to the file scheduled in show playlist.
    - 334ebbdd6c3f37cc6132b455ce44e190 is not the file scheduled to play after "c40212c2c63036d4cc8a2a1487c4d853"


    2012/09/02 22:41:52 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/02 22:41:53 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/c40212c2c63036d4cc8a2a1487c4d853.ogg".


    I've tried to restart services, restart O.S....

    I've deleted all schedule so that, nothing should be playing and... 
    Still playing...

    Restarted airtime-playout... still playing...

    btw, ls_script.liq was not edited... 

    I've checked cc_schedule table and, there are some files scheduled... 
    I've done: "DELETE FROM cc_schedule;"

    Now, there's nothing scheduled in postgres and nothing on airtime...

    Restarted airtime-playout , scheduled some files and, started with right file.
    Until now, the schedule is going ok...

    What I think it happened is that, for some strange reason, some files were kept in cc_schedule for the show, despite I've removed it before and, deleted all schedule after.
    Only when I've clean the  cc_schedule table I've got the correct playout schedule...

    Is it possible that, removing many files from schedule the query have failed for some reason?
    I couldn't find any error in postgres log.

    Anyway, great job on Airtime, very good tool for a Radio (despite this strange problems).

  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Reply to @Martin+Konecny:
    Hi,

    I've found that, sometimes, the "End of track before cue-out point" still happens randomly.

    This file: 334ebbdd6c3f37cc6132b455ce44e190

    On 2012/09/12 have an error of "End of track before cue-out point" and, played 2 times.
    -.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.
    2012/09/12 12:02:41 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/12 12:02:42 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/c40212c2c63036d4cc8a2a1487c4d853.ogg".
    2012/09/12 12:02:42 [cue_cut_5152:3] End of track before cue-out point.
    2012/09/12 12:02:42 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg" (RID 1).
    2012/09/12 12:02:42 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/09/12 12:02:42 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=20067 &
    2012/09/12 12:02:42 [lang:3] Using stream_format 1
    2012/09/12 12:02:45 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/12 12:02:45 [cue_cut_5152:3] End of track before cue-out point.
    2012/09/12 12:02:45 [cross_5256:3] No next track ready yet.
    2012/09/12 12:02:45 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/12 12:02:45 [default_switch:3] Switch to map_metadata_5265 with forgetful transition.
    2012/09/12 12:02:45 [lang:3] transition called...
    2012/09/12 12:02:45 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg" (RID 37).
    2012/09/12 12:02:45 [default_switch:3] Switch to cross_5256 with forgetful transition.
    2012/09/12 12:02:45 [lang:3] transition called...
    2012/09/12 12:02:45 [cue_cut_5152:3] Cueing in...
    2012/09/12 12:02:45 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=20067 &
    2012/09/12 12:02:45 [lang:3] Using stream_format 1
    -.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.

    I've rescheduled the file, and next time, no error:
    -.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.
    2012/09/13 13:00:07 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/13 13:00:07 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/95151956b1e55750b2300fb66fbf840e.ogg".
    2012/09/13 13:00:07 [cue_cut_5152:3] Cueing out...
    2012/09/13 13:00:07 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg" (RID 30).
    2012/09/13 13:00:07 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/09/13 13:00:07 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=21296 &
    2012/09/13 13:00:07 [lang:3] Using stream_format 1
    2012/09/13 13:03:41 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/711eff761182feba87d5b1d1f0d2bd69.ogg".
    2012/09/13 13:03:42 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/334ebbdd6c3f37cc6132b455ce44e190.ogg".
    2012/09/13 13:03:42 [cue_cut_5152:3] Cueing out...
    2012/09/13 13:03:42 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/711eff761182feba87d5b1d1f0d2bd69.ogg" (RID 61).
    2012/09/13 13:03:42 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/09/13 13:03:42 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=21172 &
    2012/09/13 13:03:42 [lang:3] Using stream_format 1
    -.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.-.

    Checking postgres, the cue_out value is the same for all schedules..
    SELECT * FROM cc_schedule WHERE file_id='304' AND starts>='2012/09/12 11:00:00'

    cue_out
    00:03:34.08136
    00:03:34.08136
    00:03:34.08136
    00:03:34.08136
    00:03:34.08136
    00:03:34.08136
    00:03:34.08136

    What can be causing this?

    thanks for the help.
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    hi,
    anyone have a clue about this?
    This issue repeats everyday, with different tracks...
    Thanks
  • Vote Up0Vote Down James MoonJames Moon
    Posts: 197Member
    Hi Mario,

    Have you ever used action called "Delete this instance and all following"? You are on 2.1.3?

    Thank you.
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Hi James,

    Yes, I've used that action before but, many weeks ago...
    This is happening many days after I've used it.

    And yes, I'm on 2.1.3

    Any clue?

    Thanks
  • Vote Up0Vote Down James MoonJames Moon
    Posts: 197Member

    Hi Mario,

    Please take a look at this post: http://forum.sourcefabric.org/discussion/comment/19541#Comment_19541

    Long story short, try to run this command:

    sudo -u postgres psql -c 'DELETE FROM cc_schedule WHERE id in (SELECT s.id from cc_schedule s LEFT JOIN cc_show_instances si on s.instance_id = si.id WHERE si.modified_instance = true);' airtime

    Thanks!

  • Vote Up0Vote Down Martin KonecnyMartin Konecny
    Posts: 1,860Member
    Hello, 

    We will have a release soon which fixes this issue.
    Airtime Pro Hosting: http://airtime.pro
  • Vote Up0Vote Down Mario CostaMario Costa
    Posts: 19Member
    Hi,
    Thanks for the help,

    I've already done that query before but, to make sure, I've redone it and this time the result was 0 (zero)
    I think its not related with that because same randoms "End of track before cue-out point" happens... 

    Strange issue :(

    Problem is that, because of this "End of track before cue-out point" at a certain moment, the last track is repeated... 

    hope the next release fixes this.



    2012/10/05 07:15:44 [lang:3] Using stream_format 1
    2012/10/05 07:15:47 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/a1a2aa7fe41fbfb3531c7ea270eadaf3.ogg".
    2012/10/05 07:15:47 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/deba78a22035106b358c7994780578fc.ogg".
    2012/10/05 07:15:47 [cue_cut_5152:3] Cueing out...
    2012/10/05 07:15:47 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/a1a2aa7fe41fbfb3531c7ea270eadaf3.ogg" (RID 30).
    2012/10/05 07:15:47 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/10/05 07:15:47 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=42852 &
    2012/10/05 07:15:47 [lang:3] Using stream_format 1
    2012/10/05 07:19:23 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/0655db1983214807aee351d0c3809d53.ogg".
    2012/10/05 07:19:23 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/a1a2aa7fe41fbfb3531c7ea270eadaf3.ogg".
    2012/10/05 07:19:23 [cue_cut_5152:3] End of track before cue-out point.
    2012/10/05 07:19:24 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/0655db1983214807aee351d0c3809d53.ogg" (RID 31).
    2012/10/05 07:19:24 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/10/05 07:19:24 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=42830 &
    2012/10/05 07:19:24 [lang:3] Using stream_format 1
    2012/10/05 07:19:26 [decoder:3] Method "OGG" accepted "/var/tmp/airtime/pypo/cache/scheduler/182ca6e5dc53f0e254a08a07d62479d5.ogg".
    2012/10/05 07:19:26 [queue:3] Finished with "/var/tmp/airtime/pypo/cache/scheduler/0655db1983214807aee351d0c3809d53.ogg".
    2012/10/05 07:19:26 [cue_cut_5152:3] Cueing out...
    2012/10/05 07:19:26 [queue:3] Prepared "/var/tmp/airtime/pypo/cache/scheduler/182ca6e5dc53f0e254a08a07d62479d5.ogg" (RID 37).
    2012/10/05 07:19:26 [cue_cut_5152:2] Ignoring negative cue-in point.
    2012/10/05 07:19:26 [lang:3] /usr/lib/airtime/pypo/bin/liquidsoap_scripts/notify.sh --data='0' --media-id=42
  • Vote Up0Vote Down TopeaTopea
    Posts: 26Member
    I am having the same problem tracks playing without scheduling and no overlapping shows 2 times sometimes the music is streaming but the online button is grey and no sound... my log file looks almost the same like the one from up but i stream mp3

    My question is how to disable this cue-in/cue-out from liquidsoap/airtime ? what line i need to remove?

    How to disable this cue in/out feature? Is it possible?
    Post edited by Topea at 2012-10-16 16:00:53
Add a Comment