Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

playout stops every few days #100

Closed
edwoodza opened this issue Jun 12, 2021 · 54 comments
Closed

playout stops every few days #100

edwoodza opened this issue Jun 12, 2021 · 54 comments
Labels
bug Something isn't working

Comments

@edwoodza
Copy link

edwoodza commented Jun 12, 2021

Installer 3.1.0 installed
playout works well.

BUT 2x now have see it has issues loading playlist. basically every 2 days now.
Playout streaming output STOPS. BUT GUI shows play GREEN

logs show
[2021-06-13 00:00:00,125] [ERROR] Playlist not long enough!
[2021-06-13 00:00:00,135] [ERROR] Playlist is not long enough: 86338.86 seconds needed
[2021-06-13 00:00:00,135] [ERROR] File not exist: None

I check the playlist it exists and is 24 hours long (slightly over)

also the loop file does not play when playlist is too short or missing.
I have the file set to the mapped video drive
/media/povideo/loop/loop.mp4
(.mp4 .mkv SHUFFLE)

The video file is valid and read write access is the same as the rest of the video files.

Also logging not logging for encode but all the rest logs.

Tonight when the issue showed i used the YELLOW Restart playout 3x
On the 3rd time the playlist file started playing (and the error no longer showed in log)

CPU remains constant at 40%
RAM:
Total: 3.9GiB
Used: 2.2GiB
Free: 129.5MiB
Cached: 968.0MiB

Am posting here as its the installer used. not sure where the issue may be api, engine etc
also not sure if this is a known bug fixed with latest installer. Rather than assume i posted here

@jb-alvarado jb-alvarado transferred this issue from another repository Jun 14, 2021
@jb-alvarado
Copy link
Member

This issues relate to the engine.

I need the ffplayout.yml and full logs, as Attachments, or code blocks. Logs also from day before.

@edwoodza
Copy link
Author

edwoodza commented Jun 14, 2021

Loggin on the day was not set to debug so only shows the error i posted.
I have since set it back to debug for logging.
but this is the day before:

[2021-06-12 11:01:23,453] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 21:04:39.369000, target length is: 1 day, 0:00:00
[2021-06-12 11:01:48,168] [ERROR]  MediaProbe error in: "/media/video/video files/Advert/THEMES 2021.mp4" Command '['ffprobe', '-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', '/media/video/video files/Advert/THEMES 2021.mp4']' died with .
[2021-06-12 11:01:51,541] [ERROR]  MediaProbe error in: "/media/video/video files/RS/ep4/The Request Show EP 4 SEG B.mp4" Command '['ffprobe', '-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', '/media/ctvvideo/video files/RS/ep4/The Request Show EP 4 SEG B.mp4']' died with .
[2021-06-12 11:01:52,776] [ERROR]  MediaProbe error in: "/media/ctvvideo/video files/AC/amazing creations EP 1.mp4" Command '['ffprobe', '-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', '/media/video/video files/AC/amazing creations EP 1.mp4']' died with .
[2021-06-12 11:01:56,474] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 21:04:39.369000, target length is: 1 day, 0:00:00
[2021-06-12 11:27:53,514] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 17:22:05.949000, target length is: 1 day, 0:00:00
[2021-06-12 11:46:25,155] [ERROR]  MediaProbe error in: "/media/video/video files/RS/ep4/The Request Show EP 4 SEG C.mp4" Command '['ffprobe', '-v', 'quiet', '-print_format', 'json', '-show_format', '-show_streams', '/media/video/video files/RS/ep4/The Request Show EP 4 SEG C.mp4']' died with .
[2021-06-12 11:46:28,831] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 19:44:29.978000, target length is: 1 day, 0:00:00
[2021-06-12 11:46:43,288] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 19:44:29.978000, target length is: 1 day, 0:00:00
[2021-06-12 13:12:33,985] [ERROR]  Playlist from 2021-06-12 is not long enough! Total play time is: 22:00:29.750000, target length is: 1 day, 0:00:00

ffplayout.yml:

    helptext: Sometimes it can happen, that a file is corrupt but still playable,
        this can produce an streaming error over all following files. The only way
        in this case is, to stop ffplayout and start it again here we only say it
        can stop, the starting process is in your hand. Best way is a systemd serivce
        on linux. 'stop_threshold' stop ffplayout, if it is async in time above this
        value.
    stop_on_error: false
    stop_threshold: 11
mail:
    helptext: Send error messages to email address, like missing playlist; unvalid
        json format; missing clip path. Leave recipient blank, if you don't need this.
        'mail_level' can be WARNING or ERROR.
    subject: Playout Error
    smpt_server: mail.example.org
    smpt_port: 587
    sender_addr: ffplayout@example.org
    sender_pass: abc123
    recipient: null
    mail_level: ERROR
logging:
    helptext: Logging to file, if 'log_to_file' False log to console. 'backup_count'
        says how long log files will be saved in days. Path to /var/log/ only if you
        run this program as deamon. 'log_level' can be DEBUG, INFO, WARNING, ERROR.
        'ffmpeg_level' can be INFO, WARNING, ERROR.
    log_to_file: true
    backup_count: 7
    log_path: /var/log/ffplayout/
    log_level: DEBUG
    ffmpeg_level: ERROR
processing:
    helptext: Default processing, for all clips that they get prepared in that way,
        so the output is unique. 'aspect' must be a float number. 'logo' is only used
        if the path exist. 'logo_scale' scale the logo to target size, leave it blank
        when no scaling is needed, format is 'number:number', for example '100:-1'
        for proportional scaling. With 'logo_opacity' logo can become transparent.
        With 'logo_filter' 'overlay=W-w-12:12' you can modify the logo position. With
        'use_loudnorm' you can activate single pass EBU R128 loudness normalization.
        'loud_*' can adjust the loudnorm filter. 'output_count' sets the outputs for
        the filtering, > 1 gives the option to use the same filters for multiple outputs.
        This outputs can be taken in 'ffmpeg_param', names will be vout2, vout3; aout2,
        aout2 etc.
    width: 1024
    height: 576
    aspect: 1.778
    fps: 25
    add_logo: true
    logo: /media/video/logo/logo.png
    logo_scale: null
    logo_opacity: 0.7
    logo_filter: overlay=W-w-30:30
    add_loudnorm: true
    loud_I: -18
    loud_TP: -1.5
    loud_LRA: 11
    output_count: 1
playlist:
    helptext: Set 'playlist_mode' to 'False' if you want to play clips from the 'storage'
        section. Put only the root path here, for example '/playlists' subfolders
        are readed by the script. Subfolders needs this structur '/playlists/2018/01'
        (/playlists/year/month). 'day_start' means at which time the playlist should
        start, leave day_start blank when playlist should always start at the begin.
        'length' represent the target length from playlist, when is blank real length
        will not consider.
    playlist_mode: true
    path: /opt/playlists
    day_start: 00:00:00
    length: '24:00:00'
storage:
    helptext: Play ordered or ramdomly files from path. 'filler_clip' is for fill
        the end to reach 24 hours, it will loop when is necessary. 'extensions' search
        only files with this extension. Set 'shuffle' to 'True' to pick files randomly.
    path: /media/video/video files
    filler_clip: /media/video/loop/
    extensions:
    - .mp4
    - .mkv
    shuffle: true
text:
    helptext: Overlay text in combination with libzmq for remote text manipulation.
        On windows fontfile path need to be like this 'C\:/WINDOWS/fonts/DejaVuSans.ttf'.
        In a standard environment the filter drawtext node is Parsed_drawtext_2. 'over_pre'
        if True text will be overlay in pre processing. Continue same text over multiple
        files is in that mode not possible. 'text_from_filename' activate the extraction
        from text of a filename. With 'style' you can define the drawtext parameters
        like position, color, etc. Post Text over API will override this. With 'regex'
        you can format file names, to get a title from it.
    add_text: true
    over_pre: false
    bind_address: 127.0.0.1:5555
    fontfile: /usr/share/fonts/truetype/dejavu/DejaVuSans.ttf
    text_from_filename: false
    style: x=(w-tw)/2:y=(h-line_h)*0.9:fontsize=24:fontcolor=#ffffff:box=1:boxcolor=#000000:boxborderw=4
    regex: ^(.*)_
out:

@jb-alvarado
Copy link
Member

Loggin on the day was not set to debug so only shows the error i posted.
I have since set it back to debug for logging.

Then maybe is better that we wait, until the error comes again. Then I need both logs, from day before and current day.

For simulating day transitions you could also play with time_machine script. But you need to have a bit knowledge about the app structure.

@edwoodza
Copy link
Author

I found this.
if the playlist is 24 hours BUT the last entry is not at 24h or more it creates this.

if client does playlist 24 hours and clicks the loop function (where t auto completes playlist) then it does not give issue (so far)

the other weird parts are

  1. not logging encoder infor
  2. when issue starts streaming output STOPS (even while green play button show on gui)
  3. loop file does not work (likely why encode stops, but would think in absence of loop file it would push black out and keep encode output going)

@edwoodza
Copy link
Author

edwoodza commented Jun 19, 2021

happened again

day before log:

[2021-06-19 23:59:59,996] [ERROR]  Playlist not long enough!
[2021-06-19 23:59:59,997] [DEBUG]  delta: 0.002942
[2021-06-19 23:59:59,997] [DEBUG]  total_delta: 86400.002942
[2021-06-19 23:59:59,997] [DEBUG]  List end
[2021-06-19 23:59:59,997] [ERROR]  Playlist is not long enough: 86339.00 seconds needed
[2021-06-19 23:59:59,997] [ERROR]  File not exist: None

New day log:

[2021-06-20 00:00:00,230] [INFO]  Loop "/media/video/loop/loop.mp4" 2 times, total duration: 60.00
  1. Playlist existed and was valid
  2. loop file did not play
  3. streaming output STOPPED
  4. when i restarted playout (yellow reloah button) then it loaded Ok and started playout and stream again

log after restart

[2021-06-20 00:09:03,420] [INFO]  Using drawtext node, listening on address: 127.0.0.1:5555
[2021-06-20 00:09:03,421] [DEBUG]  Encoder CMD: "ffmpeg -v level+debug -hide_banner -nostats -re -thread_queue_size 160 -i pipe:0 -vf null,zmq=b=tcp\\://'127.0.0.1\:5555',drawtext=text='':fontfile='/usr/share/fonts/truetype/dejavu/DejaVuSans.ttf' -metadata service_name=TV -metadata service_provider=Provider -metadata year=2021 -s -c:v xxxx stream info xxxxx"
[2021-06-20 00:09:03,423] [INFO]  Open: /media/video/playlists/2021/06/2021-06-20.json
[2021-06-20 00:09:03,424] [DEBUG]  List init
[2021-06-20 00:09:03,645] [INFO]  Play: /media/video/video files/IM/exports/7 MAY 2019.mp4

[2021-06-20 00:09:03,645] [DEBUG]  Decoder CMD: "ffmpeg -v level+debug -hide_banner -nostats -ss 543.425 -i /media/video/video files/IM/exports/7 MAY 2019.mp4 -filter_complex [0:v]scale=1024:576,fade=in:st=0:d=0.5[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11,afade=in:st=0:d=0.5[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"

@edwoodza
Copy link
Author

is this issue resolved with installer v3.2.0?

@jb-alvarado
Copy link
Member

jb-alvarado commented Jun 21, 2021

Until I can reproduce or validate the error, I can not fix it. More up I ask for both full logs, not only a snipped. Private data you can hide in it, but I need the rest.

And when you have not a really good reason for it, then let stop_on_error: on true.

@jb-alvarado
Copy link
Member

Ok, I found the bug, you don't have to send the logs any more.

@jb-alvarado jb-alvarado added the bug Something isn't working label Jun 21, 2021
@edwoodza
Copy link
Author

edwoodza commented Jun 21, 2021

Logs show nothing out of the norm much

The one thing i noted not sure it it changes things.
On this occasion and the other.
The playlist at midlight was not full 24 hours but it started playing ok

During the day we added files to the playlist to make it a full 24 hours and saved it. its why it played till mid night no issue.
BUT the next day playlist then did not load.

nor did the loop file play in absence of playlist
and streaming output STOPPED dead
also not logging anything for encoder

Could it be video file issue that does not play? or character in file name eg the period in the file below?

[2021-06-19 23:59:23,254] [WARNING] Clip length is not in time, new duration is: 36.75
[2021-06-19 23:59:23,280] [INFO] Play: /media/video/files/Local music/Nyac ft. Tata Mai.mp4
and
[2021-06-19 23:59:59,996] [WARNING] Clip length is not in time, new duration is: 0.00
[2021-06-19 23:59:59,996] [WARNING] Last clip less then 1 second long, skip: /media/video/video files/Advert/THEMES 2021.mp4

@jb-alvarado
Copy link
Member

Bug should be fixed in version v3.4.0 and updated in installer.

@edwoodza
Copy link
Author

To avoid me updating incorrectly and creating bugs that waste time.
Please can you advise the best way to update with installer.
Is it a case of simply run it?
OR do i need to do things before.

I want to be sure update done correctly to avoid creating bugs that do not need to be there

@jb-alvarado
Copy link
Member

Normally you can delete the folder (/opt/ffplayout_engine) and run the updated installer.

@edwoodza
Copy link
Author

ok so ONLY engine in this case right?

if it were GUI would be its folder in /opt then as well right?

@jb-alvarado
Copy link
Member

No the GUI is under /var/www. Is not an official upgrade method, but I think it should work, without guaranty.

@edwoodza
Copy link
Author

what is the BEST way to upgrade to avoid creating bugs
delete folders and run latest installer
or just run latest installer?

@edwoodza
Copy link
Author

update applied by removing /opt/ffplayout_engine and then downloading installer 3.2.0 zip and installing.
will keep you posted if this cures the issue

@edwoodza
Copy link
Author

edwoodza commented Jul 3, 2021

playout and streaming stoped again

[2021-07-03 23:56:53,261] [ERROR] Playlist not long enough!
[2021-07-03 23:56:53,261] [DEBUG] delta: -0.000008
[2021-07-03 23:56:53,261] [DEBUG] total_delta: 186.738636
[2021-07-03 23:56:53,261] [DEBUG] List end
[2021-07-03 23:56:53,261] [ERROR] Playlist is not long enough: 125.74 seconds needed
[2021-07-03 23:56:53,261] [ERROR] File not exist: None

playlist was short of 24 hours
and the loop file may have not been set correct.

but at 00:00:00 it did not start new playlist and restart streaming output until i had to manually click the YELLOW reload icon then it started again

@jb-alvarado jb-alvarado reopened this Jul 4, 2021
@jb-alvarado
Copy link
Member

I was not able to reproduce it. But maybe you can help me debugging it.

You can clone the master repo to the machine where you get this error.

  • then cd in the repo
  • create a virtual environment: virtualenv -p python3 venv
  • source ./venv/bin/activate
  • pip install -r requirements-base.txt
  • pip install -r requirements-dev.txt
  • edit tests/run_time_machine.py change time zone to yours and set SOURCE_TIME = [2021, 7, 3, 23, 55, 0]
  • run ./tests/run_time_machine.py -m null -l none for 7 minutes and past here the output.

@edwoodza
Copy link
Author

edwoodza commented Jul 5, 2021

I am waiting to confirm if again.
I suspect this is what may have happened.

  1. playlist was to short
  2. system then tried to use loop file to fill, but this failed (not sure why yet)
  3. So playout stopped when playlist ended and terminated streaming output as well (BUT on GUI it showed the new days playlist and as if it was playing so seems GUI does not check in with the engine to see if its working and shows as working but is not until reset)
  4. when the new playlist started it did not trigger because playout had stopped.

May be an idea to hard code the system to fill with black if loop file is missing.
This way output keeps working even if its just sending black.

Then the new days playlist load will work to engine (as currently engine stops so when new list loaded engine does nothing)

@jb-alvarado
Copy link
Member

No, normally all these behaviours should be catched. If not, the fault is somewhere else, we have to find out now.

@edwoodza
Copy link
Author

Ok seems the issue before was happening because the loop file specified the file name and was set to shuffle.
So since the system could not find the directory it errored and broke streaming out, not even playing black rather.

with the loop file specified and shuffle unticked. it has not presented this issue again yet again.

so may be related to issue with loop file triggering a stop of everything

@jb-alvarado
Copy link
Member

jb-alvarado commented Jul 13, 2021

I really don't think so. To verify I have also try to reproduce it, but I was not able. The shuffle mode also affect only the folder mode, not playlist mode.

The easiest would be, when you follow the steps from before. Because your last error was on 2021-07-03, it is better to use that situation as a starting point.

I guess with loop file you mean filler_clip?

@edwoodza
Copy link
Author

Ok i will try clone the machine for testing (i dont want to risk breaking a test system we know is not developing these bugs anymore)

Yes loop = filler_clip

@jb-alvarado
Copy link
Member

Ok i will try clone the machine for testing (i dont want to risk breaking a test system we know is not developing these bugs anymore)

Yes that would be nice.

@edwoodza
Copy link
Author

edwoodza commented Jul 14, 2021

also what CPU and RAM is best for test machine so i can be sure its not part of the issues.
I have 4 Core (averages 30% CPU use) and 4 gig ram it works well, system caches around 1gig of ram and only uses 2
ram

and here is the last 24 hour ram use as well
ram2

However i started to see this error daily which breaks output briefly.

[2021-07-14 06:42:16,160] av_interleaved_write_frame(): Cannot allocate memory
[2021-07-14 06:42:16,514] Error writing trailer of udp://224.1.1.1:1234: Cannot allocate memory

running UDP for local testing rather than pushing RTMP

@jb-alvarado
Copy link
Member

I would say that the system specs are enough, but I have not much experience with UDP. When you don't need a output you can use the null mode, as I wrote before. Or you try multicast like: stream_output: -flags +global_header -f mpegts udp://239.0.0.1:1234?ttl=13.

@edwoodza
Copy link
Author

This showed on decoder logs today

[2021-07-19 00:29:04,901] av_interleaved_write_frame(): Broken pipe
[2021-07-19 06:40:50,743] [av1 @ 0x556e1ef0eec0] Your platform doesn't suppport hardware accelerated AV1 decoding.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Failed to get pixel format.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.

@jb-alvarado
Copy link
Member

For issues related to ffmpeg I can not give support.

@edwoodza
Copy link
Author

edwoodza commented Jul 20, 2021

the bug was back now log was

[2021-07-20 23:51:34,945] [ERROR] Playlist not long enough!
[2021-07-20 23:51:34,945] [DEBUG] delta: -0.000009
[2021-07-20 23:51:34,945] [DEBUG] total_delta: 505.054347
[2021-07-20 23:51:34,945] [DEBUG] List end
[2021-07-20 23:51:34,945] [ERROR] Playlist is not long enough: 444.05 seconds needed
[2021-07-20 23:51:34,945] [ERROR] File not exist: None
[2021-07-20 23:51:35,105] [INFO] Loop "/media/video/loop/loop.mp4" 2 times, total duration: 60.00

Decode error log:
[2021-07-21 00:00:53,201] av_interleaved_write_frame(): Broken pipe

The issue was the loop video (filler) did not play to fill in the short
streaming output stopped as well
until new playlist was loaded at 00:00:00

@edwoodza
Copy link
Author

For issues related to ffmpeg I can not give support.

i realize that but i am just making you aware of the bug found as it may have bearings on future faults being caused

@edwoodza
Copy link
Author

edwoodza commented Jul 22, 2021

This morning again

Decoder log:

[2021-07-22 08:03:50,795]  [av1 @ 0x55b0ab374ec0] Your platform doesn't suppport hardware accelerated AV1 decoding.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Failed to get pixel format.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.
[2021-07-22 08:03:50,797]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.
[2021-07-22 08:03:50,798]  [av1 @ 0x55b0ab374ec0] Missing Sequence Header.

and the GUI logs up and does not load well after loading decoder log (that takes long) have to reload whole page

Playout log:

[2021-07-22 07:50:58,826] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Have My Heart (feat. Chan) - Maverick City   TRIBL.mp4
[2021-07-22 07:50:58,826] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Have My Heart (feat. Chandler Moore _ Chris Brown) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:03:50,685] [DEBUG]  delta: 1.242086
[2021-07-22 08:03:50,686] [DEBUG]  total_delta: 57369.314086
[2021-07-22 08:03:50,778] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4
[2021-07-22 08:03:50,778] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576,tpad=stop_mode=add:stop_duration=0.1197109999999384[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:04:30,999] [DEBUG]  delta: 908.953758
[2021-07-22 08:04:30,999] [DEBUG]  total_delta: 57329.000758
[2021-07-22 08:04:31,104] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Man of Your Word (feat. Chandler Moore _ KJ Scriven) - Maverick City   TRIBL.mp4
[2021-07-22 08:04:31,104] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Man of Your Word (feat. Chandler Moore _ KJ Scriven) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:04:53,771] [DEBUG]  delta: 1431.734817
[2021-07-22 08:04:53,771] [DEBUG]  total_delta: 57306.228817
[2021-07-22 08:04:53,850] [INFO]  Play: /media/[2021-07-22 07:50:58,826] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Have My Heart (feat. Chandler Moore _ Chris Brown) - Maverick City   TRIBL.mp4
[2021-07-22 07:50:58,826] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Have My Heart (feat. Chandler Moore _ Chris Brown) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:03:50,685] [DEBUG]  delta: 1.242086
[2021-07-22 08:03:50,686] [DEBUG]  total_delta: 57369.314086
[2021-07-22 08:03:50,778] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4
[2021-07-22 08:03:50,778] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576,tpad=stop_mode=add:stop_duration=0.1197109999999384[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:04:30,999] [DEBUG]  delta: 908.953758
[2021-07-22 08:04:30,999] [DEBUG]  total_delta: 57329.000758
[2021-07-22 08:04:31,104] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Man of Your Word (feat. Chandler Moore _ KJ Scriven) - Maverick City   TRIBL.mp4
[2021-07-22 08:04:31,104] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Man of Your Word (feat. Chandler Moore _ KJ Scriven) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:04:53,771] [DEBUG]  delta: 1431.734817
[2021-07-22 08:04:53,771] [DEBUG]  total_delta: 57306.228817
[2021-07-22 08:04:53,850] [INFO]  Play: /media/video/video files/FW/2021/Advanced Everything Workout in FL (Cardio, Strength, Kickboxing, Core & More).mp4
[2021-07-22 08:04:53,851] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/FW/2021/Advanced Everything Workout in FL (Cardio, Strength, Kickboxing, Core & More).mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:05:55,654] [ERROR]  Broken Pipe!
[2021-07-22 08:05:57,390] [DEBUG]  Encoder CMD: "ffmpeg -v level+error -hide_banner -nostats -re -thread_queue_size 160 -i pipe:0 -metadata service_name=ChristTV -metadata service_provider=Purple Turtle -metadata year=2021 -s 720x576 -c:v libx264 -x264opts nal-hrd=cbr:force-cfr=1 -b:v 900k -minrate 900k -maxrate 900k -muxrate 1100k -bufsize 500k -preset medium -profile:v Main -level 3.1 -c:a mp2 -ar 44100 -b:a 96k -flags +global_header -f mpegts -mpegts_original_network_id 1 -mpegts_transport_stream_id 1 -mpegts_pmt_start_pid 7166 -streamid 0:256 -streamid 1:257 udp://224.1.1.1:1234?pkt_size=1316&bitrate=1100000"
[2021-07-22 08:05:57,393] [INFO]  Open: /media/video/playlists/2021/07/2021-07-22.json
[2021-07-22 08:05:57,394] [DEBUG]  List init
[2021-07-22 08:05:57,428] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4
[2021-07-22 08:05:57,428] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -ss 125.466 -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576,tpad=stop_mode=add:stop_duration=0.1197109999999384,fade=in:st=0:d=0.5[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11,afade=in:st=0:d=0.5[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:06:31,874] [DEBUG]  delta: 788.078329
[2021-07-22 08:06:31,874] [DEBUG]  total_delta: 57208.125329/video files/FW/2021/Advanced Everything Workout in FL (Cardio, Strength, Kickboxing, Core & More).mp4
[2021-07-22 08:04:53,851] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -i /media/video/video files/FW/2021/Advanced Everything Workout in FL (Cardio, Strength, Kickboxing, Core & More).mp4 -filter_complex [0:v]fps=25,scale=1024:576[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:05:55,654] [ERROR]  Broken Pipe!
[2021-07-22 08:05:57,390] [DEBUG]  Encoder CMD: "ffmpeg -v level+error -hide_banner -nostats -re -thread_queue_size 160 -i pipe:0 -metadata service_name=ChristTV -metadata service_provider=Purple Turtle -metadata year=2021 -s 720x576 -c:v libx264 -x264opts nal-hrd=cbr:force-cfr=1 -b:v 900k -minrate 900k -maxrate 900k -muxrate 1100k -bufsize 500k -preset medium -profile:v Main -level 3.1 -c:a mp2 -ar 44100 -b:a 96k -flags +global_header -f mpegts -mpegts_original_network_id 1 -mpegts_transport_stream_id 1 -mpegts_pmt_start_pid 7166 -streamid 0:256 -streamid 1:257 udp://224.1.1.1:1234?pkt_size=1316&bitrate=1100000"
[2021-07-22 08:05:57,393] [INFO]  Open: /media/video/playlists/2021/07/2021-07-22.json
[2021-07-22 08:05:57,394] [DEBUG]  List init
[2021-07-22 08:05:57,428] [INFO]  Play: /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4
[2021-07-22 08:05:57,428] [DEBUG]  Decoder CMD: "ffmpeg -v level+error -hide_banner -nostats -ss 125.466 -i /media/video/video files/NEW VIDEOS/week3 sept-20200916T195419Z-001/week3 sept/Lean Back (feat. Amanda Lindsey Cook and Chandler Moore) - Maverick City   TRIBL.mp4 -filter_complex [0:v]fps=25,scale=1024:576,tpad=stop_mode=add:stop_duration=0.1197109999999384,fade=in:st=0:d=0.5[v];movie=/media/video/logo/logo.png,loop=loop=-1:size=1:start=0,format=rgba,colorchannelmixer=aa=0.7[l];[v][l]overlay=W-w-30:30:shortest=1[vout1] -filter_complex [0:a]anull,loudnorm=I=-18:TP=-1.5:LRA=11,afade=in:st=0:d=0.5[aout1] -map [vout1] -map [aout1] -pix_fmt yuv420p -r 25 -c:v mpeg2video -intra -b:v 58982.4k -minrate 58982.4k -maxrate 58982.4k -bufsize 29491.2k -c:a mp2 -b:a 384k -ar 48000 -ac 2 -f mpegts -"
[2021-07-22 08:06:31,874] [DEBUG]  delta: 788.078329
[2021-07-22 08:06:31,874] [DEBUG]  total_delta: 57208.125329

Encode log error:

[2021-07-22 08:05:16,564]  av_interleaved_write_frame(): Cannot allocate memory

when the pipe broke streaming output and playout stopped and no filler played either.

system has been up and running 20 days now and seems to have this error more and more the longer it runs.

ram use below
po22

CPU use below
po222

You can also see lan use when it dropped and stopped streaming (red) and then GREEN spikes when it was loading logs on gui slowly
po223

@jb-alvarado
Copy link
Member

I think at the moment we mixing different issues, that gets complicated for later tracking. Let's try to stay fist on the main issue.

You should also let:

stop_on_error: true
stop_threshold: 11

on default. Most time it will not help you, when you change this settings.Your playout log show very high delta values, that means that something is not right with your file, or playlist, or ffmpeg can not handle the file correctly.

@edwoodza
Copy link
Author

edwoodza commented Jul 22, 2021

these last few days are a follow on on the original issue.

ok that may be part of it mine was set
po224

The high delta might that be caused by files with differing frame rate and resolutions (i noted my test video files seem to be a mixed bag of formats)

@jb-alvarado
Copy link
Member

Different frame rates and resolutions doesn't impact duration and so on has no influence on the delta value.

@edwoodza
Copy link
Author

edwoodza commented Jul 26, 2021

I applied the above.
today it errored but ffmpeg did not restart nor did the filler file play

Playout logs showed:
[2021-07-26 06:41:32,263] [ERROR] Sync tolerance value exceeded with 908.01 seconds, program terminated!

then it showed it started the stream output, then the internal lossless encode

then again

[2021-07-26 06:42:11,275] [DEBUG] delta: 868.997552
[2021-07-26 06:42:11,275] [DEBUG] total_delta: 62268.724552
[2021-07-26 06:42:11,275] [ERROR] Sync tolerance value exceeded with 869.00 seconds, program terminated!

and it goes in a loop again doing all the same over and over

The only way i could restart it was to untick Stop_on_error and then restart playout. (it was 10 min before i had to force it to restart)

usually when it stops i see CPU drop. but during this CPU usage stayed at the usual amount it is when running normally.
so wither the restart command did not work or something else possibly?

system up for 24 days straight. not sure if things may be creeping in with system running so long possibly hence why does not show up on localized simulation tests

just noted DECODER log files are 117MiB currently and last logs some files around 50MiB

@jb-alvarado
Copy link
Member

[2021-07-19 00:29:04,901] av_interleaved_write_frame(): Broken pipe
[2021-07-19 06:40:50,743] [av1 @ 0x556e1ef0eec0] Your platform doesn't suppport hardware accelerated AV1 decoding.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Failed to get pixel format.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.
[2021-07-19 06:40:50,744] [av1 @ 0x556e1ef0eec0] Missing Sequence Header.

Just for the record: this errors are happen when ffmpeg tries to decode AV1 with a bad decoder. I would recommend to compile ffmpeg with libdav1d.

@edwoodza
Copy link
Author

edwoodza commented Oct 7, 2021

HI

AV1 codecs not used at all. I did a check to be sure.

also finding server "leaks" memory and either freezes or needs to be rebooted every 30-40 days or so.
see attached memory log for last 100 days of testing
(red lines are dates i had to reboot testing server)

po er oct

@jb-alvarado
Copy link
Member

AV1 codecs not used at all. I did a check to be sure.

Maybe now not anymore, but here it was ;-)

also finding server "leaks" memory and either freezes or needs to be rebooted every 30-40 days or so. see attached memory log for last 100 days of testing (red lines are dates i had to reboot testing server)

I have not see it before, but I will pay attention to it the next weeks. When you see it again, please try to figure out, which component will produce this: the python script it self, or one of the both ffmpeg instances.

@jengajenga
Copy link

I'm following this keenly as I would like to restart using this system.

@jb-alvarado
Copy link
Member

Since some weeks I have upgrade our production system to the latest version. I see also that the engine restarted sometimes, but in my case there is a error with a specific video file. It has a different duration, so it hits the threshold. A memory leak I could not see until now.

@edwoodza
Copy link
Author

HI, has this been resolved. Soak testing server shows consistant issues on old ver every 45 days and locks machine up still.
Has it been resolved with new installer version and elements.

For best testing whats best way to update the testing server other and full new install?

@jb-alvarado
Copy link
Member

To update you can pass --update parameter to the installer. But it will work only on minor version changes from the engine.

@edwoodza
Copy link
Author

please can you explain how to correctly fully use the --update command.
I dont want to cock it up and create bugs that will give us wrong feedback on fixes etc (and that feedback will waste your time as well which i do not want to do)

@jb-alvarado
Copy link
Member

The problem is, I don't know, what are your current version, so is difficult to guarantee that everything works like it should.

The update process will not update the ffplayout.yml config.

I would recommend to run the update process on a test system and see if everything goes smooth.

When you only need a newer engine, you can replace that one alone. Here was the same situation. But I do not recommend to use the version from master, this will have many changes in the next days.
When you update the engine, you need to compare the existing config with the new one and fix the missing parts.

@edwoodza
Copy link
Author

installer 3.2.0 was used and updated manually last by removing /opt/ffplayout_engine and runing the zip

what is the correct use or update pricess

@jb-alvarado
Copy link
Member

installer 3.2.0 was used and updated manually last by removing /opt/ffplayout_engine and runing the zip

Yes that you can do so. Only take care that you create the virtual environment again.

what is the correct use or update pricess

This question I don't understand.

@edwoodza
Copy link
Author

edwoodza commented Apr 4, 2022

please can you clarify the correct way to use the --update command.

want to update to latest version to see that all bugs gone.

45 days again and seeing.

  1. Logging page takes minutes to show and update
  2. gives cant find file error (for the filler file)

I suspected before that low resources may have contributed to this so i increases resources, but no change. confirming not a resource issue

@jb-alvarado
Copy link
Member

I would recommend:

  1. make a snapshot of your VM, to be able to role back
  2. login as root
  3. get latest installer
  4. run ./install.sh --update
  5. run diff /opt/ffplayout_engine/ffplayout.yml /etc/ffplayout/ffplayout.yml and check changes in the config file.
    • when changes exists update your config
  6. reboot your system
  7. check systemctl status ffplayout_engine ffplayout-api
  8. when everything runs normal remove your snapshot

@edwoodza
Copy link
Author

edwoodza commented Apr 4, 2022

will give it a run and revert. Thanks a million
keep up the epic job you doing.

any news on timeline for GUI for live yet?

@jb-alvarado
Copy link
Member

I need to figure out how I will continue with the GUI. It uses Nuxt 2.* with bootstrap 4, and until now there is no way to upgrade to Nuxt 3 and bootstrap 5. For adding new features, it makes no sense, and getting better performance is not possible.

I have to wait until they support a clean upgrade path, or I have to rewrite the hole page. But when I have to rewrite, I'm not sure if I want to still stick on Nuxt, or I use something else, like svelte.

@edwoodza
Copy link
Author

edwoodza commented Apr 4, 2022

Yeah make sense to upgrade rather but makes alot more work but gives more flexibility and options (without the gun to your head waiting for them)

@jb-alvarado
Copy link
Member

I'm closing here. Feel free to open a new issue when something is happen.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants