NFO file not created

[henrikmaurin]

Since about a week, NFO files are no longer created for my downloaded videos.
I have this option ticked for all my channels.

I can see the info embedded in the mkv-file, so there is not a problem with getting the description
For the videos I also save an image for, the image is still created.

EDIT
I also tried ticking the export json file, which works. So it seems to be only the export NFO that has been broken

[henrikmaurin]

LOGS:

TubeSync  | [MoveFiles] Moving file "/downloads/cache/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.mkv" to "/downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.mkv"
TubeSync  | 2024-12-28 13:07:57,191 [tubesync/INFO] Successfully downloaded media: tLhfuc_KCpM (UUID: df313ac9-0ed9-4c2e-b06c-360c47c149e9) to: "/downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.mkv"
TubeSync  | 2024-12-28 13:07:57,308 [tubesync/INFO] Copying media thumbnail from: /config/media/thumbs/df/df313ac9-0ed9-4c2e-b06c-360c47c149e9.jpg to: /downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.jpg
TubeSync  | 2024-12-28 13:07:57,348 [tubesync/INFO] Writing media NFO file to: /downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.nfo
TubeSync  | Rescheduling Downloading media for "I Built The Ultimate Hidden Gaming Room"
TubeSync  | Traceback (most recent call last):
TubeSync  |   File "/usr/local/lib/python3.11/dist-packages/background_task/tasks.py", line 43, in bg_runner
TubeSync  |     func(*args, **kwargs)
TubeSync  |   File "/app/sync/tasks.py", line 449, in download_media
TubeSync  |     write_text_file(media.nfopath, media.nfoxml)
TubeSync  |   File "/app/sync/utils.py", line 129, in write_text_file
TubeSync  |     raise ValueError(f'File cannot be edited or removed: {filepath}')
TubeSync  | ValueError: File cannot be edited or removed: /downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room.nfo
TubeSync  | Rescheduling task Downloading media for "I Built The Ultimate Hidden Gaming Room" for 0:00:06 later at 2024-12-28 12:08:17.661309+00:00
TubeSync  | 2024-12-28 13:08:22,024 [tubesync/WARNING] Download task triggered for media: tLhfuc_KCpM (UUID: df313ac9-0ed9-4c2e-b06c-360c47c149e9) but it has already been marked as downloaded, not downloading again

So I can see 2 separate problems here (I think)

1. When trying to write the NFO, the code checking for permissions prevents the NFO to be written. (On my first try, the downloded mkv was still in the destination folder causing a similar error, but at the step where the video file should be downloaded)

2. The rescheduling gets cancelled by it already being marked downloaded.

If the problem is caused by folder permissions on my host, could someone advice how to set them properly. But since the the other files getting created, I really cant see that beeing the problem

[henrikmaurin]

Ok, so I managed to add some logging myself
Seems the nfo filepath in is_editable is expanded to my host filesystem path

Since I don't know Python, I'm not going to try fix this myself.

def file_is_editable(filepath):
    '''
        Checks that a file exists and the file is in an allowed predefined tuple of
        directories we want to allow writing or deleting in.
    '''
    allowed_paths = (
        # Media item thumbnails
        Path(str(settings.MEDIA_ROOT)).resolve(),

        # Downloaded media files
        Path(str(settings.DOWNLOAD_ROOT)).resolve(),
    )
    log.info(allowed_paths)    
    filepath = Path(str(filepath)).resolve()
    if not filepath.is_file():
        log.info(f'is_file failed: {filepath}')
        return False
    log.info(f'filepath: {filepath}')
    for allowed_path in allowed_paths:
        log.info(f'allowed_path: {allowed_path}')
        log.info(f'commonpath: {os.path.commonpath([allowed_path, filepath])}')
        if str(allowed_path) == os.path.commonpath([allowed_path, filepath]):
            return True
    return False

First row from download_media, where the filename is a path within the container

TubeSync  | 2024-12-28 15:56:40,001 [tubesync/INFO] Writing media NFO file to: /downloads/video/TubeSync/Linus Tech Tips/Linus Tech Tips.(2024-12-26) - I Built The Ultimate Hidden Gaming Room [tLhfuc_KCpM] [tvdb336426].nfo

TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] (PosixPath('/config/media'), PosixPath('/downloads'))
TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] filepath: /Downloaded/Video/TubeSync/Linus Tech Tips/15o7vlc3.tmp
TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] allowed_path: /config/media
TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] commonpath: /
TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] allowed_path: /downloads
TubeSync  | 2024-12-28 15:58:18,297 [tubesync/INFO] commonpath: /

[meeb]

This looks like a path or volume issue. What's /Downloaded/ ? That's outside of /downloads/ and not part of the "permitted" directories that can be written to.

[henrikmaurin]

Yes, /Downloaded/ is a local symlink on the host
When download_media logs the path for the NFO file, it seems to be a path inside the container

but in write_text_file the TubeSynk part gets replaces by the symlink for TubeSync on my host
My guess is the NamedTemporaryFile part does something - It stopped working around the time that was added from what i can see.

I'm happy to add more logs if it would help.

Relevant parts of my docker compose file

volumes:
      - /Downloaded:/Downloaded
      - /srv/data/TubeSync:/downloads    
      - /Downloading/tubesync/cache:/downloads/cache

Relevant Symlinks on my server
TubeSync -> /Downloaded/Video/Tv
Downloaded -> /srv/data/Downloaded
Downloading -> /srv/data/Downloading
data -> /srv/dev-disk-by-uuid-18c2608f-c77d-4296-bbeb-d354839fac68

[meeb]

Do you have some custom container config? What does your setup use /Downloaded/ for? Your log snippet was for two different files so it's not especially useful to debug this unfortunately. Obviously any calls to file_is_editable(...) with a path to a file in /Downloaded/... will return False as it's not within /downloads/ or /config/media/.

[henrikmaurin]

No, I don't think I have something custom, except for using symlinks containing another symlink on my host
I have to mount /Downloaded, because TubeSync in /srv/data/TubeSync is using the symlink /Downloaded

I added som more logging, but it doesn't really add anything relevant. Did a new run for a different file

Path(str(filepath)).resolve() seems to resolve the path to the path of the file on the host.
The way I am debugging is by editing a copy of utils.py and mounting it in the container. Is there an easier way for me to debug this?

def file_is_editable(filepath):
    '''
        Checks that a file exists and the file is in an allowed predefined tuple of
        directories we want to allow writing or deleting in.
    '''
    allowed_paths = (
        # Media item thumbnails
        Path(str(settings.MEDIA_ROOT)).resolve(),

        # Downloaded media files
        Path(str(settings.DOWNLOAD_ROOT)).resolve(),
    )
    log.info(f'1(file_is_editable) filepath (before resolve): {filepath}')
    log.info(f'2(file_is_editable) {allowed_paths}')
    filepath = Path(str(filepath)).resolve()
    if not filepath.is_file():
        log.info(f'is_file failed: {filepath}')
        return False
    log.info(f'3(file_is_editable) filepath (after resolve): {filepath}')
    for allowed_path in allowed_paths:
        log.info(f'allowed_path: {allowed_path}')
        log.info(f'commonpath: {os.path.commonpath([allowed_path, filepath])}')
        if str(allowed_path) == os.path.commonpath([allowed_path, filepath]):
            return True
    return False


def write_text_file(filepath, filedata):
    if not isinstance(filedata, str):
        raise TypeError(f'filedata must be a str, got "{type(filedata)}"')
    filepath_dir = str(Path(filepath).parent)
    log.info(f'1(write_text_file) filepath: {filepath}')
    log.info(f'2(write_text_file) filepath_dir: {filepath_dir}')
    with NamedTemporaryFile(mode='wt', suffix='.tmp', prefix='', dir=filepath_dir, delete=False) as f:
        new_filepath = Path(f.name)
        bytes_written = f.write(filedata)
    log.info(f'3(write_text_file) new_filepath: {new_filepath}')
    # chmod a+r temp_file
    old_mode = new_filepath.stat().st_mode
    new_filepath.chmod(0o444 | old_mode)
    if not file_is_editable(new_filepath):
        new_filepath.unlink()
        raise ValueError(f'File cannot be edited or removed: {filepath}')
    new_filepath.replace(filepath)
    return bytes_written

TubeSync  | [MoveFiles] Moving file "/downloads/cache/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.mkv" to "/downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.mkv"
TubeSync  | 2024-12-30 18:53:36,315 [tubesync/INFO] Successfully downloaded media: n4WDRyrzVmw (UUID: 30c1dfb5-494d-45bf-a051-f1c4b13b4503) to: "/downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.mkv"
TubeSync  | 2024-12-30 18:53:38,191 [tubesync/INFO] Copying media thumbnail from: /config/media/thumbs/30/30c1dfb5-494d-45bf-a051-f1c4b13b4503.jpg to: /downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.jpg
TubeSync  | 2024-12-30 18:53:38,228 [tubesync/INFO] Writing media NFO file to: /downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.nfo
TubeSync  | 2024-12-30 18:54:59,482 [tubesync/INFO] 1(write_text_file) filepath: /downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.nfo
TubeSync  | 2024-12-30 18:54:59,482 [tubesync/INFO] 2(write_text_file) filepath_dir: /downloads/video/TubeSync/ShortCircuit
TubeSync  | 2024-12-30 18:54:59,482 [tubesync/INFO] 3(write_text_file) new_filepath: /downloads/video/TubeSync/ShortCircuit/b_bqp8x1.tmp
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] 1(file_is_editable) filepath (before resolve): /downloads/video/TubeSync/ShortCircuit/b_bqp8x1.tmp
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] 2(file_is_editable) (PosixPath('/config/media'), PosixPath('/downloads'))
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] 3(file_is_editable) filepath (after resolve): /Downloaded/Video/Tv/ShortCircuit/b_bqp8x1.tmp
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] allowed_path: /config/media
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] commonpath: /
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] allowed_path: /downloads
TubeSync  | 2024-12-30 18:54:59,483 [tubesync/INFO] commonpath: /
TubeSync  | Rescheduling Downloading media for "I Can’t Believe Apple Sells These… - Weird Apple Store Products"
TubeSync  | Traceback (most recent call last):
TubeSync  |   File "/usr/local/lib/python3.11/dist-packages/background_task/tasks.py", line 43, in bg_runner
TubeSync  |     func(*args, **kwargs)
TubeSync  |   File "/app/sync/tasks.py", line 449, in download_media
TubeSync  |     write_text_file(media.nfopath, media.nfoxml)
TubeSync  |   File "/app/sync/utils.py", line 139, in write_text_file
TubeSync  |     raise ValueError(f'File cannot be edited or removed: {filepath}')
TubeSync  | ValueError: File cannot be edited or removed: /downloads/video/TubeSync/ShortCircuit/ShortCircuit.(2024-12-29) - I Can’t Believe Apple Sells These… - Weird Apple Store Products.nfo
TubeSync  | Rescheduling task Downloading media for "I Can’t Believe Apple Sells These… - Weird Apple Store Products" for 0:00:06 later at 2024-12-30 17:55:06.072773+00:00
TubeSync  | 2024-12-30 18:55:12,465 [tubesync/WARNING] Download task triggered for media: n4WDRyrzVmw (UUID: 30c1dfb5-494d-45bf-a051-f1c4b13b4503) but it has already been marked as downloaded, not downloading again

[henrikmaurin]

I removed the call to file_is_editable on my local setup

#if not file_is_editable(new_filepath):
#        new_filepath.unlink()
#        raise ValueError(f'File cannot be edited or removed: {filepath}')

Now a NFO is created alongside the other files again. While this isn't a real sollution, it works for me until a real sollution can be found.