transcoding-temp folder filling up

[Scott D 69]

Background:

This has been going on for some time now.  I have made it a habit to restart Emby every morning in order to clear this folder.  This morning I had over 200K files that had been abandoned.  No one was online and no recoding or live tv activity at the time of restart.

Shortly after a Roku client started playing a movie.  It required transcoding due to the bitrate exceeding the limit I have set.  I kept an eye on the event knowing that the stock answer to the bulging transcoding-temp file has been explained as a result of exiting the Roku app in the wrong way, and that the "I'm done watching" or whatever response is not getting sent from the Roku.  At 12:21p the client stopped and then exited (I can only assume) shut down the connection to Emby.

I see in the Emby log file the following:

2021-09-23 12:20:17.364 Info Server: http/1.1 Response 200 to xxx.xxx.xxx.xxx Time: 65ms. http://???.net:8096/emby/videos/2044012/hls1/main/2068.ts?DeviceId=80033f0a-15a0-509a-96cf-d4f0ff04439e&MediaSourceId=a8d38e0d24b7ac1f8ba59892ba5eb5a9&PlaySessionId=8bcadf45e55d46c0bc5f12ce81540487&VideoCodec=h264,mpeg2video&AudioCodec=aac,mp2,mp3,flac,vorbis,lpcm&VideoBitrate=2616000&AudioBitrate=384000&MaxFramerate=60&MaxWidth=1920&MaxHeight=1080&AudioStreamIndex=1&TranscodingMaxAudioChannels=2&SegmentContainer=ts&SegmentLength=3&MinSegments=1&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-maxrefframes=16&h264-videobitdepth=8&h264-profile=high,main,baseline,constrainedbaseline&h264-deinterlace=true&h264-level=41&aac-audiochannels=2&flac-audiochannels=2&lpcm-audiochannels=2&mp3-audiochannels=2&mp2-audiochannels=2&vorbis-audiochannels=2&TranscodeReasons=ContainerBitrateExceedsLimit
2021-09-23 12:21:17.478 Info SessionManager: Session 1cfa3a6a611c2bae88c340cd15ca589c has gone idle while playing
2021-09-23 12:21:17.478 Info SessionManager: Playback stopped reported by app Roku SG 4.0.31 playing XXXXXX. Stopped at 6144000 ms
2021-09-23 12:21:17.478 Info PlaybackReporting - EventMonitorEntryPoint: _sessionManager_PlaybackStop : Entered
2021-09-23 12:21:17.478 Info PlaybackReporting - EventMonitorEntryPoint: Saving final duration for Item : 80033f0a-15a0-509a-96cf-d4f0ff04439e-d47223e603df4da8a173e4d947e7b155-2044012
2021-09-23 12:21:17.497 Info PlaybackReporting - EventMonitorEntryPoint: Removing Old Key from playback_trackers : 80033f0a-15a0-509a-96cf-d4f0ff04439e-d47223e603df4da8a173e4d947e7b155-2044012

Next entry in the log file was the beginning of a scheduled recording 9 minutes later.  Nothing more from this session activity.

I checked the transcoding-temp folder and there are 2,168 files occupying 2.22 GB of space.  

Any suggestions?  If I am away from my server for any length of time, the folder will expand to consume the entire available space on the drive causing all kinds of havoc.

[Luke 38840]

Hi, this shouldn't happen anymore in the upcoming 4.7 server release. Thanks.

[Scott D 69]

Excellent!!!

Looking forward to its release.

Keep up the great work.  You all are awesome!!!

[Bingie 99]

That reminds me...

In windows, I created a batch file to delete all the *.ts files in the transcoding-temp directory, then added the task to the task scheduler:

program:  C:\Windows\System32\cmd.exe

arguments:  /C d:\Emby\Data\purge-trans-temp.bat

 

Then a simple batch file contains:

@erase d:\Emby\Data\transcoding-temp\*.ts

 

I set it to run the batch file before the nightly syncing.  It works.

 

[Scott D 69]

Still happening in 4.7.2.0

Only difference from prior post is that now the temp files are stored in individual folders.

2022-06-05 20:34:38.081 Info SessionManager: Playback stopped reported by app Roku SG 4.0.55 playing Paycheck. Stopped at 6925000 ms
2022-06-05 20:34:38.082 Info PlaybackReporting - EventMonitorEntryPoint: _sessionManager_PlaybackStop : Entered
2022-06-05 20:34:38.082 Info PlaybackReporting - EventMonitorEntryPoint: Saving final duration for Item : aaee9b10-57ae-59e2-91fb-7a5ad2c3c1fd-aa8802da38614790991a6b3f45a74f5a-690444

 

This is just one playback occurrence from last night.  It happens every day and requires a system restart to clear the files.

embyserver-63790058273.txt ffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1).txt hardware_detection-63789997839.txt

[Scott D 69]

This has been a problem for quite some time.  There are several threads explaining the exact same problem.

Best thing to do is "restart" Emby every morning.  This will erase all of the left-over transcode files.  I've been doing this for a few years now.

Some have put together batch files and the like to somewhat automate the process.  

[K22R8CT 24]

I don't know how helpful it'll be but I wrote a script for linux shell to fix this, meant to be called periodically.

I call it every 60 seconds with the watch command but you have to guard against duplicate instances.

My transcoding directory is a RAM drive so I can't let it fill up.

WARNING: Be extra cautious with scripts like this that pipe to xargs rm - different outputs on different systems could have terrible consequences. I'd advise running the commands individually by hand to make sure they work.

EDIT 5/18/2023: Updated to work with later Emby versions.

#!/bin/sh

# User-specific
TRANSCODE_DIR="/transcode/transcoding-temp"

# Prune only if disk is more than <PERCENT_LIMIT> percent full
PERCENT_LIMIT=50

# Prune <BATCH_SIZE> files at a time
BATCH_SIZE=10

if [ -d "${TRANSCODE_DIR}" ]; then
    percent_full=$(df "${TRANSCODE_DIR}" | awk '{print $5}' | tail -1 | tr -dc '0-9')
    printf "Directory size: \t %3s%%\n" ${percent_full}
    printf "Directory limit:\t %3s%%\n" ${PERCENT_LIMIT}
    echo ''
    while [ $percent_full -gt $PERCENT_LIMIT ]; do
        if [ $(find ${TRANSCODE_DIR} -type f -name "*.ts" | wc -l) -gt 0 ]; then
            echo "(${percent_full}%) exceeds limit (${PERCENT_LIMIT}%), deleting oldest (${BATCH_SIZE}) files"

            # DEBUG: Uncomment to print list of deleted files
            #find ${TRANSCODE_DIR} -type f -name "*.ts" -exec ls -1t "{}" + | tail -${BATCH_SIZE} | ls -lh
            find ${TRANSCODE_DIR} -type f -name "*.ts" -exec ls -1t "{}" + | tail -${BATCH_SIZE} | xargs rm
        else
            echo "*WARNING* (${percent_full}%) exceeds limit (${PERCENT_LIMIT}%) but files are not transcoding fragments"
            exit 1
        fi
        percent_full=$(df "${TRANSCODE_DIR}" | awk '{print $5}' | tail -1 | tr -dc '0-9')
    done
else
    echo "${TRANSCODE_DIR} (TRANSCODE_DIR): directory doesn't exist"
fi

Edited May 18, 2023 by K22R8CT
updated script for compatibility with later versions

[Scott D 69]

Provided an example here yesterday.  I am running a Windows box, but the problem is the same.

 

 

Edited June 7, 2022 by Scott D

[Luke 38840]

On 6/6/2022 at 10:00 AM, Scott D said:

Still happening in 4.7.2.0

Only difference from prior post is that now the temp files are stored in individual folders.

2022-06-05 20:34:38.081 Info SessionManager: Playback stopped reported by app Roku SG 4.0.55 playing Paycheck. Stopped at 6925000 ms
2022-06-05 20:34:38.082 Info PlaybackReporting - EventMonitorEntryPoint: _sessionManager_PlaybackStop : Entered
2022-06-05 20:34:38.082 Info PlaybackReporting - EventMonitorEntryPoint: Saving final duration for Item : aaee9b10-57ae-59e2-91fb-7a5ad2c3c1fd-aa8802da38614790991a6b3f45a74f5a-690444

 

This is just one playback occurrence from last night.  It happens every day and requires a system restart to clear the files.

embyserver-63790058273.txt 2.61 MB · 1 download ffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1).txt 5.52 MB · 0 downloads hardware_detection-63789997839.txt 213.91 kB · 2 downloads

This particular transcoding session starts at 18:39 and runs through the entirety of the rest of your server log file, with the Roku actively streaming from it the entire time. So that's why those files are there throughout all of that time.

[Scott D 69]

I'm not the best at reading the log files, but here is how things appear to have happened to me:

1. File transcoding started at or about 18:39.  Transcoding due to bitrate limitations (no know issues/problems here).

2. File was played to completion at or about 20:34:38.

3.Transcoding appears to have completed at or about 20:31.

4. Exit/Stop playing on Roku at or about 20:34:38.081 as reported in the log file.

5. The next morning (approximately 07:00) the temporary files remained along with several other sessions.  This particular session was the easiest one to provide the log files.

I have been told many times in the past that the reason for the remaining files is due to Roku's not providing the appropriate "End" signal, or a user exiting incorrectly.  From the log file it seems the "End" signal is being received.  The user is NOT exiting incorrectly.  And the only difference in this version of the server is that temp files are now being created in individual folders as opposed to the prior versions dumping them all in the "transcoding-temp" folder.

I can understand that the files would remain during the streaming process.  That makes perfect sense.  However, once the session is complete and about12 hours has passed since the end of the session, I don't understand why they would remain.  Especially when the transcoded files were played to completion.  If left unattended for more than a few days, Emby transcodes will consume the entire remaining space on the drive and cause fatal errors and become unusable.

[Happy2Play 9142]

18 minutes ago, Scott D said:

I'm not the best at reading the log files, but here is how things appear to have happened to me:

1. File transcoding started at or about 18:39.  Transcoding due to bitrate limitations (no know issues/problems here).

2. File was played to completion at or about 20:34:38.

3.Transcoding appears to have completed at or about 20:31.

4. Exit/Stop playing on Roku at or about 20:34:38.081 as reported in the log file.

5. The next morning (approximately 07:00) the temporary files remained along with several other sessions.  This particular session was the easiest one to provide the log files.

I have been told many times in the past that the reason for the remaining files is due to Roku's not providing the appropriate "End" signal, or a user exiting incorrectly.  From the log file it seems the "End" signal is being received.  The user is NOT exiting incorrectly.  And the only difference in this version of the server is that temp files are now being created in individual folders as opposed to the prior versions dumping them all in the "transcoding-temp" folder.

I can understand that the files would remain during the streaming process.  That makes perfect sense.  However, once the session is complete and about12 hours has passed since the end of the session, I don't understand why they would remain.  Especially when the transcoded files were played to completion.  If left unattended for more than a few days, Emby transcodes will consume the entire remaining space on the drive and cause fatal errors and become unusable.

Devs would need to the server log for that transcode session "93D51C" as it is not in that server log, that log show for "0F801F"

Edited June 7, 2022 by Happy2Play

[Scott D 69]

17 minutes ago, Happy2Play said:

Devs would need to the server log for that transcode session "93D51C" as it is not in that server log, that log show for "0F801F"

Posted above, but here it is again.ffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1) (1).txtffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1) (1).txt

[Happy2Play 9142]

4 minutes ago, Scott D said:

Posted above, but here it is again.ffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1) (1).txtffmpeg-transcode-336313f8-f8fb-49cf-afc3-55ddbf18ab81_1 (1) (1).txt

But the session is not in the server log.  So to me something went wrong here

ffmpeg log shows 2022-06-05 18:39:04.114 - 20:31:02.984 but "93D51C" is not in the server log 2022-06-05 19:37:53.978 - 20:37:52.580.  So I can only guess something happened in the previous log if it was caught.

A guess is a session was not shutdown properly and transcode complete per the ffmpeg log, as the server log does not show the session ended that I can see.

[Scott D 69]

I'm calling "Uncle".  I don't know what to provide and/or how to provide it.

Log files become huge if not recycled on an hourly basis.  Reading the log files as an end user is mind numbing due to the verbose nature of logging.  I honestly thought that I had provided sufficient information to at least point in the general direction.  I thought this information would indicate that the "improper" shut-down was not the issue.

For now, I'll stick with restarting the server on a daily basis and hope that someone with more knowledge than myself can provide the required information.  At least I know that I am not the only one, and that the problem has been going on for quite some time.

[Scott D 69]

Alright, one more attempt at this.  

Server Hardware/Software
Windows 10 Home
Version 21H1
O.S. Build 19043.1706
Intel i3-4130
Emby 4.7.2.0 Premiere
Internet streaming bitrate limit set to 2 (Mbps) to stay within Data Caps.  Internet connection - 940/35 (Speedtest.net)

User Hardware/Software
Samsung TV - UN60KS8000 (Remote connection)
Emby for Samsung 1.0.94

Problem - Transcoding temp files remain after streaming session has ended.  If left unattended for a few days, the hard drive assigned for transcode-temp will become filled with left over files and create errors and make Emby unusable.

I have noted this occurring on Roku and Samsung TV apps.  There may be others, but I have not paid that close attention.

This Incident - 19:30 on 6/8 user on Samsung TV starts streaming session.  20:16 on 6/8 user completes streaming session and exits Emby.  07:30 on 6/9 transcode files remain in transcoding-temp folder (along with a few other sessions).

Screencap (.jpg) Files attached - Folders.jpg shows session folders that became orphaned overnight as well as the files in FC4229 (this particular session).  Files.jpg shows timestamp for transcode files for log matching.  Activity.jpg shows Emby activity log for start and end time of session.

Log Files attached - embyserver-1.txt shows activity from 18:37 to 19:37,  embyserver-2.txt shows activity from 19:37 to 20:16. ffmpeg-trancode-??? shows the transcode session for this event.

I hope this is sufficient to at least point someone in the right direction to get this resolved.  It has been going on for quite some time, and the need for a daily restarts creates problems when the system is left unattended for more than a few days.

 

 

Also FYI - the "Anonymize log contents" function needs to add a few more items to anonymize.  In the attached log files, anywhere you see REDACTED is an indication that my DDNS name was left after Anonymization. 

 

 

embyserver-1.txt embyserver-2.txt ffmpeg-transcode-13f8b1cb-f101-4af5-bbac-2283302f5bb3_1.txt

[Happy2Play 9142]

The transcode log is for "51D57C" not "FC4229"

5 hours ago, Scott D said:

Log Files attached - embyserver-1.txt shows activity from 18:37 to 19:37,  embyserver-2.txt shows activity from 19:37 to 20:16. ffmpeg-trancode-??? shows the transcode session for this event.

So this session was actually cleaned up, but looking for FC4229 it is for "Air Warriors S04E01" not (ffmpeg log "Air Warriors S08E01").

Do you have the ffmpeg log for "Air Warriors S04E01"?

Last thing I see for this item in the log is what looks like a subtitle issue.

2022-06-08 19:28:56.746 Info Server: http/1.1 Response 500 to host6. Time: 3ms. http://host1:8096/emby/videos/2359344/hls1/subs/1.vtt?PlaySessionId=afff7f47b7ef43c99a4a02ba60989563&VttTimestampMap=900000&CurrentSubtitleStreamIndex=2

 

[Scott D 69]

Interesting, as that episode was not played at all by anyone.  There is an ffmpeg log for Air Warriors S04E01 that started at the same time as S08E01 (19:28 on 6/8, but doesn't complete until 01:00 on 6/9.  There was no activity on the dashboard indicating that it was played. 

I spoke with the user "Bill" and this is a recap of his activity:

Logged into Emby via remote connection.  Drilled down to Air Warriors series.  He browsed through prior seasons of unplayed episodes.  Season 4 was the first season on his list of unplayed episodes.  He browsed the list of unplayed episodes and returned back to the Series level of Air Warriors.  He continued browsing through other seasons and episodes until he came upon S08E01 which he chose to watch.  He played S08E01 to its completion and then exited Emby.  He confirms that he only watched the one episode.  He confirms that he did NOT start any other episodes and then change his mind and back out.

Also attached is the log file for the server from 00:37 on 6/9 to 01:33 on 6/9 the time when the ffmpeg file was closed.

ffmpeg-transcode-ae18a9c7-0f9c-4400-b1d1-2c3d0f029447_1.txt embyserver-63790335476.txt

[Scott D 69]

Did the prior post of log files and description provide any further clarity or direction toward the problem?  Anything else needed?

[Luke 38840]

On 6/13/2022 at 7:17 PM, Scott D said:

Did the prior post of log files and description provide any further clarity or direction toward the problem?  Anything else needed?

We would need to see the previous server log from 6/8. Essentially we need both the server and ffmpeg log files from all the way through.  Can you please create the situation again? Thanks.

[Scott D 69]

OK, One more time.

1. Turned on Debug in logging

2. Shut down server at about 07:00

3. Deleted all log files

4. Deleted all transcode-temp files and folders.

5.  Deleted activitylog.db

6.  Restart Emby Server

7.  At approximately 14:00, User Bruce_Kelly begins playing Episode S02E05 (Episode length 43:04)

8. At Approximately 14:49, User Bruce_Kelly starts playing Episode S02E06 (Episode Length 43:04)

9.  At Approximately 14:51, User Bruce_Kelly stops playing Episode S02E06

10.  At Approximately 15:00, Transcode-temp folder is checked and single folder remains.

11. Server is shut down.

12.  Captured all logs and activity files.

Attached are all log files, along with screencaps of folders left behind.

The transcode file matches Episode S02E05 Mother Nurture

"Heart Shaped Charm" as indicated on the activity log is Episode S02E06

 

 

activitylog.db embyserver-63791075073.txt ffmpeg-transcode-257e753f-b954-4c87-9f89-49caa28f61ce_1.txt ffmpeg-transcode-2540ee8b-581f-48cd-8e74-dcbe7715b109_1.txt ffmpeg-transcode-a6c7c5d3-bef9-4edd-a894-ce5e7ddba508_1.txt hardware_detection-63791046052.txt quick-extract-imageseries-69e43cbf-5734-4959-ac6f-a4398b006136_1.txt

Edited June 17, 2022 by Scott D
Additional information

[Scott D 69]

Original post problem is still happening in 4.7.4

Also, just started with 4.7.4 update.  I am now receiving this error when trying to play an OTA recording.

2022-06-21 13:29:35.074 Info App: CodecValidation: The Direct3D version of the decoder does not match the encoder

[Scott D 69]

This is an example of the space consumed in just a 24 hour period (restarted yesterday morning).  I have 170 Gb remaining, so if not for a morning restart, tomorrow would not b a good day.

[Luke 38840]

On 6/17/2022 at 6:32 PM, Scott D said:

OK, One more time.

1. Turned on Debug in logging

2. Shut down server at about 07:00

3. Deleted all log files

4. Deleted all transcode-temp files and folders.

5.  Deleted activitylog.db

6.  Restart Emby Server

7.  At approximately 14:00, User Bruce_Kelly begins playing Episode S02E05 (Episode length 43:04)

8. At Approximately 14:49, User Bruce_Kelly starts playing Episode S02E06 (Episode Length 43:04)

9.  At Approximately 14:51, User Bruce_Kelly stops playing Episode S02E06

10.  At Approximately 15:00, Transcode-temp folder is checked and single folder remains.

11. Server is shut down.

12.  Captured all logs and activity files.

Attached are all log files, along with screencaps of folders left behind.

The transcode file matches Episode S02E05 Mother Nurture

"Heart Shaped Charm" as indicated on the activity log is Episode S02E06

 

 

activitylog.db 8 kB · 0 downloads embyserver-63791075073.txt 6.95 MB · 1 download ffmpeg-transcode-257e753f-b954-4c87-9f89-49caa28f61ce_1.txt 179.27 kB · 0 downloads ffmpeg-transcode-2540ee8b-581f-48cd-8e74-dcbe7715b109_1.txt 1.71 MB · 0 downloads ffmpeg-transcode-a6c7c5d3-bef9-4edd-a894-ce5e7ddba508_1.txt 1.62 MB · 0 downloads hardware_detection-63791046052.txt 213.91 kB · 0 downloads quick-extract-imageseries-69e43cbf-5734-4959-ac6f-a4398b006136_1.txt 24.61 kB · 0 downloads

OK, this is a good case. How did they move from episode 5 to episode 6? Can you get the same thing to occur in the web app?

[Scott D 69]

It has been too long since this occurrence, they don't recall what buttons they pressed 5 days ago.

My guess based on the log and activity file is the end of episode 5 came up, and the next episode started playing.  Once they realized it was playing they stopped the playback and exited the system.  The run time of episode 5 is consistent with the time spent playing episode 5.  The fact that they only spent 1:45 playing the next episode would also go along with "auto play" of the next episode.

As far as this happening in a web app, I can't say as none of my family uses a web app.  We are on Roku and TV apps (Samsung, LG, etc).

[Luke 38840]

OK thanks, that's very helpful though. We should be able to track that specific case down.