Permission Error on Writing to logging.ini File

[johnwchambers]

I have my nightly cronjob do a git pull every night at 0200. After the pull on the 19th, I saw this error my main server that does the post*arr processing. I've since overwrote the logging.ini in /opt/mp4automator/config with the copy from /opt/mp4automator/setup/logging.ini.sample and adjusted the perms to 777.

Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: Traceback (most recent call last): Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/postRadarr.py", line 11, in Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: log = getLogger("RadarrPostProcess") Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/resources/log.py", line 121, in getLogger Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: checkLoggingConfig(configfile) Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/resources/log.py", line 95, in checkLoggingConfig Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: fp = open(configfile, "w") Mar 19 02:16:15 plex mono: [Error] postRadarr.sh: PermissionError: [Errno 13] Permission denied: '/opt/mp4automator/config/logging.ini'

What are the proper permissions that should be set for the config/logging.ini and config/autoProcess.ini files?

[johnwchambers]

After the changes I mentioned above, and importing in a movie, I noticed this /var/log/messages:

Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: Traceback (most recent call last): Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/postRadarr.py", line 11, in Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: log = getLogger("RadarrPostProcess") Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/resources/log.py", line 132, in getLogger Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: fileConfig(configfile, defaults={'logfilename': logfile}) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/config.py", line 84, in fileConfig Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: handlers = _install_handlers(cp, formatters) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/config.py", line 148, in _install_handlers Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: h = klass(*args) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/handlers.py", line 150, in init Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: BaseRotatingHandler.init(self, filename, mode, encoding, delay) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/handlers.py", line 57, in init Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: logging.FileHandler.init(self, filename, mode, encoding, delay) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/init.py", line 1032, in init Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: StreamHandler.init(self, self._open()) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/init.py", line 1061, in _open Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: return open(self.baseFilename, self.mode, encoding=self.encoding) Mar 20 06:22:08 plex mono: [Error] postRadarr.sh: PermissionError: [Errno 13] Permission denied: '/opt/mp4automator/config/sma.log'

I've created the sma.log file in the config folder and have the perms set to 777 for now.

[johnwchambers]

And after touching the sma.log file and setting the perms to it, saw the following in /var/log/messages:

Mar 20 06:25:00 plex mono: [Info] MovieService: Linking [SIN CITY - [2005] - [BLURAY-1080P].mp4] > [[Sin City (2005)][tt0401792, 187]] Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: Traceback (most recent call last): Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/postRadarr.py", line 11, in Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: log = getLogger("RadarrPostProcess") Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/opt/mp4automator/resources/log.py", line 132, in getLogger Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: fileConfig(configfile, defaults={'logfilename': logfile}) Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/config.py", line 84, in fileConfig Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: handlers = _install_handlers(cp, formatters) Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/config.py", line 151, in _install_handlers Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: h.setLevel(level) Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/init.py", line 827, in setLevel Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: self.level = _checkLevel(level) Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: File "/usr/lib64/python3.6/logging/init.py", line 195, in _checkLevel Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: raise ValueError("Unknown level: %r" % level) Mar 20 06:25:01 plex mono: [Error] postRadarr.sh: ValueError: Unknown level: 'INF'

I've updated the config.ini file to add the missing 'O' for now.

[johnwchambers]

Everything seems to be in order now. post*arr log succeeded.

2020-03-20 06:27:25 - RadarrPostProcess - INFO - Radarr extra script post processing started. 2020-03-20 06:27:25 - resources.readsettings - INFO - /usr/bin/python3 2020-03-20 06:27:25 - resources.readsettings - INFO - Loading config file /opt/mp4automator/config/autoProcess.ini. 2020-03-20 06:27:25 - RadarrPostProcess - INFO - environ({'radarr_moviefile_scenename': '', 'SHELL': '/bin/bash', 'radarr_movie_year': '2005', 'radarr_moviefile_path': '/plex/Movies/SIN CITY - [2005]/SIN CITY - [ 2005] - [BLURAY-1080P].mp4', 'radarr_movie_imdbid': 'tt0401792', 'radarr_movie_title': 'Sin City', 'USER': 'radarr', 'radarr_deletedrelativepaths': 'SIN CITY - [2005] - [BLURAY-1080P].mp4', 'radarr_movie_id': '43 72', 'radarr_moviefile_relativepath': 'SIN CITY - [2005] - [BLURAY-1080P].mp4', 'radarr_moviefile_id': '4314', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin', 'radarr_moviefile_quality': 'Bluray-1080 p', 'PWD': '/', 'radarr_movie_in_cinemas_date': '3/31/2005 3:00:00 PM', 'radarr_moviefile_sourcefolder': '/dwnldr/tor/converted/Sin.City.EXTENDED and UNRATED.2005.1080p.BluRay.x264.DTS-HD MA 5.1-OMEGA', 'LANG': ' en_US.UTF-8', 'radarr_moviefile_qualityversion': '1', 'radarr_eventtype': 'Download', 'radarr_moviefile_releasegroup': '', 'radarr_movie_physical_release_date': '3/25/2009 12:00:00 AM', 'SHLVL': '1', 'HOME': '/ho me/radarr', 'radarr_movie_tmdbid': '187', 'LOGNAME': 'radarr', 'radarr_isupgrade': 'True', 'radarr_moviefile_sourcepath': '/dwnldr/tor/converted/Sin.City.EXTENDED and UNRATED.2005.1080p.BluRay.x264.DTS-HD MA 5.1- OMEGA/SIN CITY - [2005] - [BLURAY-1080P].mp4', 'radarr_download_id': '', 'radarr_deletedpaths': '/plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4', 'radarr_movie_path': '/plex/Movies/SIN CITY

• [2005]', '_': '/usr/bin/python3'}) 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Processing /plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Input Data 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - { "format": "mov,mp4,m4a,3gp,3g2,mj2", "format-fullname": "QuickTime / MOV", "video": { "index": 0, "codec": "h264", "bitrate": 12697179, "pix_fmt": "yuv420p", "profile": "high", "fps": 23.976023976023978, "level": 4.1, "field_order": null }, "audio": [ { "index": 1, "codec": "aac", "bitrate": 265415, "channels": 2, "samplerate": 48000, "language": "eng", "disposition": "+default" }, { "index": 2, "codec": "ac3", "bitrate": 640000, "channels": 6, "samplerate": 48000, "language": "eng", "disposition": "+default" } ], "subtitle": [ { "index": 3, "codec": "mov_text", "disposition": null, "language": "eng" } ], "attachment": [] } 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Reading video stream. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Video codec detected: h264. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Pix Fmt: yuv420p. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Profile: high. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Reading audio streams. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Audio detected for stream 1 - aac eng 2 channel. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Creating copy audio stream from source stream 1. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Audio detected for stream 2 - ac3 eng 6 channel. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Creating aac audio stream source audio stream 2 [universal-audio]. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Creating copy audio stream from source stream 2. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Default audio stream set to eng copy 6 channel stream [default-more-channels: True]. 2020-03-20 06:27:25 - resources.mediaprocessor - INFO - Reading subtitle streams. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Text-based subtitle detected for stream 3 - mov_text eng. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Scanned for external subtitles and found 1 results in your approved languages. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Skipping external subtitle file SIN CITY - [2005] - [BLURAY-1080P].en.srt, no appropriate codecs found or embed disabled. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Output Data 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - { "source": [ "/plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4" ], "format": "mp4", "video": { "codec": "copy", "map": 0, "bitrate": 12076.441799999999, "crf": -1, "maxrate": null, "bufsize": null, "level": 5.1, "profile": null, "pix_fmt": null, "field_order": null, "width": null, "debug": "video" }, "audio": [ { "map": 1, "codec": "copy", "channels": 2, "bitrate": 256, "filter": null, "samplerate": null, "language": "eng", "disposition": null, "bsf": null, "title": "Stereo", "debug": "universal-audio" }, { "map": 2, "codec": "aac", "channels": 2, "bitrate": 256, "samplerate": null, "filter": "", "language": "eng", "disposition": null, "title": "Stereo", "debug": "universal-audio" }, { "map": 2, "codec": "copy", "channels": 6, "bitrate": 1536, "filter": null, "samplerate": null, "language": "eng", "disposition": "+default", "bsf": null, "title": "5.1 Channel", "debug": "audio" } ], "subtitle": [], "attachment": [] } 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Preopts 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - [] 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Postopts 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - [ "-threads", "0", "-metadata:g", "encoding_tool=SMA" ] 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Subtitle Extracts 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - [ { "source": [ "/plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4" ], "format": "mov_text", "subtitle": [ { "map": 3, "codec": "mov_text", "language": "eng", "debug": "subtitle" } ], "forced": false, "default": false, "language": "eng", "index": 3 } ] 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Wasn't able to determine subtitle file extension, defaulting to codec mov_text. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Ripping eng subtitle from source stream 3 into external file. 2020-03-20 06:27:26 - resources.mediaprocessor - ERROR - Unable to create external mov_text subtitle file for stream 3, may be an incompatible format. 2020-03-20 06:27:26 - resources.mediaprocessor - INFO - Input and output extensions are the same so passing back the original file [process-same-extensions: False]. 2020-03-20 06:27:27 - resources.mediaprocessor - INFO - Tagging /plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4 with TMDB ID 187. 2020-03-20 06:27:27 - resources.metadata - INFO - Tagging file: /plex/Movies/SIN CITY - [2005]/SIN CITY - [2005] - [BLURAY-1080P].mp4. 2020-03-20 06:27:28 - resources.metadata - INFO - Trying to write tags. 2020-03-20 06:27:28 - resources.metadata - INFO - Tags written successfully. 2020-03-20 06:27:28 - resources.mediaprocessor - INFO - Relocating MOOV atom to start of file. 2020-03-20 06:27:28 - qtfaststart - INFO - Patching co64 with 203919 entries 2020-03-20 06:27:28 - qtfaststart - INFO - Patching co64 with 334362 entries 2020-03-20 06:27:28 - qtfaststart - INFO - Patching co64 with 265788 entries 2020-03-20 06:27:28 - qtfaststart - INFO - Patching stco with 1 entries 2020-03-20 06:27:28 - qtfaststart - INFO - Writing output... 2020-03-20 06:31:14 - resources.mediaprocessor - INFO - Plex refreshed: movie 2020-03-20 06:31:14 - RadarrPostProcess - INFO - Radarr response: ID 1089681 queued. 2020-03-20 06:31:14 - RadarrPostProcess - INFO - Waiting rescan to complete 2020-03-20 06:31:14 - RadarrPostProcess - INFO - started 2020-03-20 06:31:24 - RadarrPostProcess - INFO - Command completed 2020-03-20 06:31:24 - RadarrPostProcess - INFO - Requesting updated information from Radarr for movie ID 4372. 2020-03-20 06:31:24 - RadarrPostProcess - INFO - {'title': 'Sin City', 'alternativeTitles': [{'sourceType': 'tmdb', 'movieId': 4372, 'title': "Frank Miller's Sin City", 'sourceId': 187, 'votes': 0, 'voteCount': 0, 'language': 'english', 'id': 5972}, {'sourceType': 'tmdb', 'movieId': 4372, 'title': 'Sin City 01 Sin City', 'sourceId': 187, 'votes': 0, 'voteCount': 0, 'language': 'english', 'id': 5973}], 'secondaryYearSourceId': 0, 'sortTitle': 'sin city', 'sizeOnDisk': 14477464758, 'status': 'released', 'overview': 'Welcome to Sin City. This town beckons to the tough, the corrupt, the brokenhearted. Some call it dark… Hard-boiled. Then there are those who call it home — Crooked cops, sexy dames, desperate vigilantes. Some are seeking revenge, others lust after redemption, and then there are those hoping for a little of both. A universe of unlikely and reluctant heroes still trying to do the right thing in a city that refuses to care.', 'inCinemas': '2005-03-31T15:00:00Z', 'physicalRelease': '2009-03-25T00:00:00Z', 'images': [{'coverType': 'poster', 'url': '/MediaCover/4372/poster.jpg'}, {'coverType': 'fanart', 'url': '/MediaCover/4372/fanart.jpg'}], 'website': 'http://www.miramax.com/movie/sin-city/', 'downloaded': True, 'year': 2005, 'hasFile': True, 'youTubeTrailerId': 'T2Dj6ktPU5c', 'studio': 'Dimension Films', 'path': '/plex/Movies/SIN CITY - [2005]', 'profileId': 1, 'pathState': 'static', 'monitored': True, 'minimumAvailability': 'released', 'isAvailable': True, 'folderName': '/plex/Movies/SIN CITY - [2005]', 'runtime': 124, 'lastInfoSync': '2020-03-18T13:52:58.968582Z', 'cleanTitle': 'sincity', 'imdbId': 'tt0401792', 'tmdbId': 187, 'titleSlug': 'sin-city-187', 'genres': [], 'tags': [], 'added': '2020-03-18T13:52:58.671124Z', 'ratings': {'votes': 5178, 'value': 7.4}, 'movieFile': {'movieId': 0, 'relativePath': 'SIN CITY - [2005] - [BLURAY-1080P].mp4', 'size': 14477464758, 'dateAdded': '2020-03-19T21:27:24.669753Z', 'quality': {'quality': {'id': 7, 'name': 'Bluray-1080p', 'source': 'bluray', 'resolution': 'r1080P', 'modifier': 'none'}, 'customFormats': [], 'revision': {'version': 1, 'real': 0}}, 'edition': '', 'mediaInfo': {'containerFormat': 'MPEG-4', 'videoFormat': 'AVC', 'videoCodecID': 'avc1', 'videoProfile': 'High@L4.1', 'videoCodecLibrary': 'x264 - core 155 r2901 7d0ff22', 'videoBitrate': 12700000, 'videoBitDepth': 8, 'videoMultiViewCount': 0, 'videoColourPrimaries': 'BT.709', 'videoTransferCharacteristics': 'BT.709', 'width': 1920, 'height': 1040, 'audioFormat': 'AAC', 'audioCodecID': 'mp4a-40-2', 'audioCodecLibrary': '', 'audioAdditionalFeatures': 'LC', 'audioBitrate': 264600, 'runTime': '02:21:45.1630000', 'audioStreamCount': 2, 'audioChannels': 2, 'audioChannelPositions': '2/0/0', 'audioChannelPositionsText': 'Front: L R', 'audioProfile': '', 'videoFps': 23.976, 'audioLanguages': 'English / English', 'subtitles': '', 'scanType': 'Progressive', 'schemaRevision': 5}, 'id': 4314}, 'qualityProfileId': 1, 'id': 4372}

Is the new location of the log file going to be ~/config/sma.log now?

[johnwchambers]

And on all my boxes with sma setup, /var/log/sma.log exists with it's perm set to 777 as well. No other modifications were done to the logging.ini file except for adding the missing 'O' from the sample provided.

[mdhiggins]

I moved the logging file to the config folder recently outside of /var/log because lots of people were having permission issues as /var/log is only root access usually. The config folder was the default behavior on windows so that's the fallback. Also added a SysLogHandler for non windows systems to keep system level logging going. That folder should generally have write permissions since the config files expect write permissions as well and that directory should have write permissions

Was that not the case when the file was generated?

Also note sure why you would be missing an O from INFO I don't see anywhere where that could be missing

[johnwchambers]

The O is missing from the logging.ini sample. I copied that when I saw the initial permission issue just to be on the safe side lol.

[root@plex mp4automator]# cat setup/logging.ini.sample [loggers] keys = root, manual, nzbget

[handlers]
keys = consoleHandler, nzbgetHandler, fileHandler, manualHandler, sysLogHandler

[formatters]
keys = simpleFormatter, minimalFormatter, nzbgetFormatter

[logger_root]
level = DEBUG
handlers = consoleHandler, fileHandler

[logger_nzbget]
level = DEBUG
handlers = nzbgetHandler, fileHandler
propagate = 0
qualname = NZBGetPostProcess

[logger_manual]
level = DEBUG
handlers = manualHandler, fileHandler
propagate = 0
qualname = MANUAL

[handler_consoleHandler]
class = StreamHandler
level = INFO
formatter = simpleFormatter
args = (sys.stdout,)

[handler_nzbgetHandler]
class = StreamHandler
level = INFO
formatter = nzbgetFormatter
args = (sys.stdout,)

[handler_manualHandler]
class = StreamHandler
level = INFO
formatter = minimalFormatter
args = (sys.stdout,)

[handler_fileHandler]
class = handlers.RotatingFileHandler
level = INFO
formatter = simpleFormatter
args = ('%(logfilename)s', 10000, 1)

[handler_sysLogHandler]
class = handlers.SysLogHandler
level = INF
formatter = simpleFormatter
args = ('/dev/log', 'sma')

[formatter_simpleFormatter]
format = %(asctime)s - %(name)s - %(levelname)s - %(message)s
datefmt = %Y-%m-%d %H:%M:%S

[formatter_minimalFormatter]
format = %(message)s
datefmt =

[formatter_nzbgetFormatter]
format = [%(levelname)s] %(message)s
datefmt =

Perms for the root mp4automator folder:

[root@plex mp4automator]# stat -c %a /opt/mp4automator/ 755

Perms for the /opt/mp4automator/config folder:

[root@plex mp4automator]# stat -c %a /opt/mp4automator/config/ 755

Is there anything else I'm missing that I should probably double-check?

[johnwchambers]

And to answer the question about the logging.ini file not being generated, it didn't get created since I had a file already there, just the perms weren't enough to be written too it seems.

[mdhiggins]

177a4de265d0fb140b674fb2b9202676b84c7eb7 Fixed the sample

Looks like there's no way to store write permissions in git so I can't by default have that be a group writable directory. A fresh pull works fine on my end but if you're running a more restricted user than the one who is making the pull I would just relax the permissions recursively throughout the directory and open up group writing if that's your intention

[johnwchambers]

Yah my two downloader systems only have those respective users that own the /opt/mp4automator directories. My plex/*arr/etc server has multiple users that all belong to the same mediamgmt group. I'll recursively set the group perms on the /opt/mp4automator folder on that server.

Thanks!