Import Failed, Permission Denied whatever the file is

[SeBLeL]

Greetings,

We’ve just installed our first LibreTime instance (non-docker) and everything seems to run fine.
But, when we try to upload files, they are successuflly copied onto the server directory, but are shown as Import Failed because analyzer could not be performed:

We are using Libretime 3.0.0 official release with Ubuntu 20.04.5 and
rabbitmq-server Version: 3.8.2-0ubuntu1.3
liquidsoap Version: 1.4.2-1~ltppa2
postgresql Version: 12+214ubuntu0.1
ffpmeg Version: 7:4.2.7-0ubuntu0.1
python Version: 3.8.2-0ubuntu2

Do you have any clue on this issue?

Best Regards,

PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/18-14-nash.mp3'
2022-10-17 19:14:27.327 | ERROR    | libretime_analyzer.message_listener:spawn_analyzer_process:177 - Analyzer pipeline exception: [Errno 13] Permission denied: '/home/libretime/organize/18-14-nash.mp3'
Traceback (most recent call last):

  File "/usr/local/bin/libretime-analyzer", line 8, in <module>
    sys.exit(cli())
    │   │    └ <Command cli>
    │   └ <built-in function exit>
    └ <module 'sys' (built-in)>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
           │    │     │       └ {}
           │    │     └ ()
           │    └ <function BaseCommand.main at 0x7fae62038700>
           └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
         │    │      └ <click.core.Context object at 0x7fae622ae6d0>
         │    └ <function Command.invoke at 0x7fae6202e1f0>
         └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           │   │      │    │           │   └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
           │   │      │    │           └ <click.core.Context object at 0x7fae622ae6d0>
           │   │      │    └ <function cli at 0x7fae607f4820>
           │   │      └ <Command cli>
           │   └ <function Context.invoke at 0x7fae62033f70>
           └ <click.core.Context object at 0x7fae622ae6d0>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
                       │       └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
                       └ ()

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/main.py", line 44, in cli
    MessageListener(config)
    │               └ Config(general=GeneralConfig(public_url=AnyHttpUrl('http://wrnc-diffusion:80', ), api_key='VFNihvLc7DoD5kzjnVhfeIQ8JJqhzYz5',...
    └ <class 'libretime_analyzer.message_listener.MessageListener'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
    self.wait_for_messages()
    │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
    self._channel.start_consuming()
    │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
    │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
    self._process_data_events(time_limit=None)
    │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
    self.connection.process_data_events(time_limit=time_limit)
    │    │                                         └ None
    │    └ <property object at 0x7fae60be4130>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
    self._dispatch_channel_events()
    │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
    └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
    impl_channel._get_cookie()._dispatch_events()
    │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
    └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
    consumer_info.on_message_callback(self, evt.method,
    │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
    │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5edde8b0>
    │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
    └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
    metadata = MessageListener.spawn_analyzer_process(
               │               └ <staticmethod object at 0x7fae610213a0>
               └ <class 'libretime_analyzer.message_listener.MessageListener'>

> File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
    Pipeline.run_analysis(
    │        └ <staticmethod object at 0x7fae60c0b640>
    └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 103, in run_analysis
    raise exception

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
    metadata = analyze_metadata(audio_file_path, metadata)
               │                │                └ {'ftype': 'audioclip', 'hidden': False}
               │                └ '/home/libretime/organize/18-14-nash.mp3'
               └ <function analyze_metadata at 0x7fae60be78b0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
    metadata["filesize"] = filepath.stat().st_size
    │                      │        └ <function Path.stat at 0x7fae621ce820>
    │                      └ PosixPath('/home/libretime/organize/18-14-nash.mp3')
    └ {'ftype': 'audioclip', 'hidden': False}

  File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
    return self._accessor.stat(self)
           │    │              └ PosixPath('/home/libretime/organize/18-14-nash.mp3')
           │    └ <member '_accessor' of 'Path' objects>
           └ PosixPath('/home/libretime/organize/18-14-nash.mp3')

[joola]

Seems like your libretime user doesn’t have write permission to the /home/libretime/organize folder.

[SeBLeL]

It does

Files are copied successfully on /home/libretime/organize folder. it’s the analyzer step that’s coming next that doesn’t work / produces this error above.

[joola]

Then you will have to give me more information or I can’t help you.

[SeBLeL]

What would you need?

I’m more than happy to help!

[joola]

How to ask for help?

To ask for help, you need to provide as much information about your setup and the problem you are facing. This will greatly reduce the time required to provide you with help. Some useful links: Install documentation Troubleshooting documentation. Here is a template we require you to fill when asking for help, copy paste it into your new topic and fill out the missing data: Describe the problem A clear and concise description of what the problem is. To reproduce Steps to reproduce the b…

[SeBLeL]

There you go! I reproduced the error, but all the other informations are from the Original Post.
Do not hesitate if you need more infos.

Describe the problem
when we try to upload files, they are successuflly copied onto the server directory, but are shown as Import Failed because analyzer could not be performed

To reproduce
Log in to the Management Interface
Click “Upload”
Click on “Drop files here or click to browse your computer.”
Choose a file
File is uploaded, but shown as “Import Failed” on the Recent Upload Panel

Expected behavior
An import done successfully

Relevant log output or error messages

==> /var/log/libretime/legacy.log <==
2022-10-18T17:22:17+02:00 INFO (6): Moving file /tmp/phpI4MKzD to /home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3

==> /var/log/libretime/analyzer.log <==
2022-10-18 17:22:17.154 | INFO     | libretime_analyzer.message_listener:msg_received_callback:101 -  - Received 'b'{"file_id":20,"tmp_file_path":"\\/home\\/libretime\\/organize\\/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3","import_directory":"\\/home\\/libretime\\/\\/imported\\/1","original_filename":"BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3"}'' on routing_key ''
2022-10-18 17:22:17.154 | ERROR    | libretime_analyzer.pipeline.pipeline:run_analysis:102 - [Errno 13] Permission denied: '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
Traceback (most recent call last):

  File "/usr/local/bin/libretime-analyzer", line 8, in <module>
    sys.exit(cli())
    │   │    └ <Command cli>
    │   └ <built-in function exit>
    └ <module 'sys' (built-in)>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
           │    │     │       └ {}
           │    │     └ ()
           │    └ <function BaseCommand.main at 0x7fae62038700>
           └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
         │    │      └ <click.core.Context object at 0x7fae622ae6d0>
         │    └ <function Command.invoke at 0x7fae6202e1f0>
         └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           │   │      │    │           │   └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
           │   │      │    │           └ <click.core.Context object at 0x7fae622ae6d0>
           │   │      │    └ <function cli at 0x7fae607f4820>
           │   │      └ <Command cli>
           │   └ <function Context.invoke at 0x7fae62033f70>
           └ <click.core.Context object at 0x7fae622ae6d0>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
                       │       └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
                       └ ()

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/main.py", line 44, in cli
    MessageListener(config)
    │               └ Config(general=GeneralConfig(public_url=AnyHttpUrl('http://wrnc-diffusion:80', ), api_key='',...
    └ <class 'libretime_analyzer.message_listener.MessageListener'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
    self.wait_for_messages()
    │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
    self._channel.start_consuming()
    │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
    │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
    self._process_data_events(time_limit=None)
    │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
    self.connection.process_data_events(time_limit=time_limit)
    │    │                                         └ None
    │    └ <property object at 0x7fae60be4130>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
    self._dispatch_channel_events()
    │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
    └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
    impl_channel._get_cookie()._dispatch_events()
    │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
    └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
    consumer_info.on_message_callback(self, evt.method,
    │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
    │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5edde3b0>
    │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
    └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
    metadata = MessageListener.spawn_analyzer_process(
               │               └ <staticmethod object at 0x7fae610213a0>
               └ <class 'libretime_analyzer.message_listener.MessageListener'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
    Pipeline.run_analysis(
    │        └ <staticmethod object at 0x7fae60c0b640>
    └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>

> File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
    metadata = analyze_metadata(audio_file_path, metadata)
               │                │                └ {'ftype': 'audioclip', 'hidden': False}
               │                └ '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
               └ <function analyze_metadata at 0x7fae60be78b0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
    metadata["filesize"] = filepath.stat().st_size
    │                      │        └ <function Path.stat at 0x7fae621ce820>
    │                      └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
    └ {'ftype': 'audioclip', 'hidden': False}

  File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
    return self._accessor.stat(self)
           │    │              └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
           │    └ <member '_accessor' of 'Path' objects>
           └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')

PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
2022-10-18 17:22:17.161 | ERROR    | libretime_analyzer.message_listener:spawn_analyzer_process:177 - Analyzer pipeline exception: [Errno 13] Permission denied: '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
Traceback (most recent call last):

  File "/usr/local/bin/libretime-analyzer", line 8, in <module>
    sys.exit(cli())
    │   │    └ <Command cli>
    │   └ <built-in function exit>
    └ <module 'sys' (built-in)>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
           │    │     │       └ {}
           │    │     └ ()
           │    └ <function BaseCommand.main at 0x7fae62038700>
           └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
         │    │      └ <click.core.Context object at 0x7fae622ae6d0>
         │    └ <function Command.invoke at 0x7fae6202e1f0>
         └ <Command cli>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           │   │      │    │           │   └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
           │   │      │    │           └ <click.core.Context object at 0x7fae622ae6d0>
           │   │      │    └ <function cli at 0x7fae607f4820>
           │   │      └ <Command cli>
           │   └ <function Context.invoke at 0x7fae62033f70>
           └ <click.core.Context object at 0x7fae622ae6d0>

  File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
                       │       └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
                       └ ()

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/main.py", line 44, in cli
    MessageListener(config)
    │               └ Config(general=GeneralConfig(public_url=AnyHttpUrl('http://wrnc-diffusion:80', ), api_key='',...
    └ <class 'libretime_analyzer.message_listener.MessageListener'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
    self.wait_for_messages()
    │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
    self._channel.start_consuming()
    │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
    │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
    self._process_data_events(time_limit=None)
    │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
    self.connection.process_data_events(time_limit=time_limit)
    │    │                                         └ None
    │    └ <property object at 0x7fae60be4130>
    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
    self._dispatch_channel_events()
    │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
    └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
    impl_channel._get_cookie()._dispatch_events()
    │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
    └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...

  File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
    consumer_info.on_message_callback(self, evt.method,
    │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
    │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5edde3b0>
    │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
    │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
    └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
    metadata = MessageListener.spawn_analyzer_process(
               │               └ <staticmethod object at 0x7fae610213a0>
               └ <class 'libretime_analyzer.message_listener.MessageListener'>

> File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
    Pipeline.run_analysis(
    │        └ <staticmethod object at 0x7fae60c0b640>
    └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 103, in run_analysis
    raise exception

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
    metadata = analyze_metadata(audio_file_path, metadata)
               │                │                └ {'ftype': 'audioclip', 'hidden': False}
               │                └ '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
               └ <function analyze_metadata at 0x7fae60be78b0>

  File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
    metadata["filesize"] = filepath.stat().st_size
    │                      │        └ <function Path.stat at 0x7fae621ce820>
    │                      └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
    └ {'ftype': 'audioclip', 'hidden': False}

  File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
    return self._accessor.stat(self)
           │    │              └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
           │    └ <member '_accessor' of 'Path' objects>
           └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')

PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
2022-10-18 17:22:17.217 | INFO     | libretime_analyzer.status_reporter:send_http_request:106 - HTTP request sent successfully.


wrnc@wrnc-diffusion:~$ sudo tail -n 100 -f "/var/log/syslog" | egrep 'libretime|nginx|php.*-fpm'
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     self.wait_for_messages()
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     self._channel.start_consuming()
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     self._process_data_events(time_limit=None)
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     self.connection.process_data_events(time_limit=time_limit)
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    │                                         └ None
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    └ <property object at 0x7fae60be4130>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     self._dispatch_channel_events()
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     impl_channel._get_cookie()._dispatch_events()
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     consumer_info.on_message_callback(self, evt.method,
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5edde3b0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     metadata = MessageListener.spawn_analyzer_process(
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:                │               └ <staticmethod object at 0x7fae610213a0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:                └ <class 'libretime_analyzer.message_listener.MessageListener'>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]: > File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     Pipeline.run_analysis(
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │        └ <staticmethod object at 0x7fae60c0b640>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 103, in run_analysis
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     raise exception
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     metadata = analyze_metadata(audio_file_path, metadata)
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:                │                │                └ {'ftype': 'audioclip', 'hidden': False}
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:                │                └ '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:                └ <function analyze_metadata at 0x7fae60be78b0>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     metadata["filesize"] = filepath.stat().st_size
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │                      │        └ <function Path.stat at 0x7fae621ce820>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     │                      └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     └ {'ftype': 'audioclip', 'hidden': False}
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:   File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:     return self._accessor.stat(self)
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:            │    │              └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:            │    └ <member '_accessor' of 'Path' objects>
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]:            └ PosixPath('/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3')
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]: PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'
Oct 18 17:22:17 wrnc-diffusion libretime-analyzer[894]: 2022-10-18 17:22:17.217 | INFO     | libretime_analyzer.status_reporter:send_http_request:106 - HTTP request sent successfully.
Oct 18 17:28:11 wrnc-diffusion libretime-playout[900]: 2022-10-18 17:28:11.249 | INFO     | libretime_playout.player.fetch:main:413 - Queue timeout. Fetching schedule manually
Oct 18 17:28:11 wrnc-diffusion libretime-playout[900]: 2022-10-18 17:28:11.320 | INFO     | libretime_playout.player.fetch:main:392 - Loop #252
Oct 18 17:28:11 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/18 17:28:11 [server:3] New client: 127.0.0.1.
Oct 18 17:28:11 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/18 17:28:11 [lang:3] dynamic_source.get_id
Oct 18 17:28:11 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/18 17:28:11 [server:3] Client 127.0.0.1 disconnected.
Oct 18 17:28:11 wrnc-diffusion libretime-playout[900]: 2022-10-18 17:28:11.325 | INFO     | libretime_playout.player.queue:main:54 - New schedule received
Oct 18 17:28:11 wrnc-diffusion libretime-playout[900]: 2022-10-18 17:28:11.326 | INFO     | libretime_playout.player.queue:main:33 - waiting indefinitely for schedule


● libretime-worker.service - LibreTime Worker Service
     Loaded: loaded (/lib/systemd/system/libretime-worker.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2022-10-17 15:34:17 CEST; 1 day 2h ago
   Main PID: 903 (sh)
      Tasks: 3 (limit: 18837)
     Memory: 47.8M
     CGroup: /system.slice/libretime-worker.service
             ├─ 903 /usr/bin/sh -c celery worker      --app=libretime_worker.tasks:worker      --config=libretime_worker.config      --time-limit=1800      --concurrency=1      --loglevel=INFO      --logfile=$LIBRETIME_LOG_FILEPATH
             ├─1032 /usr/bin/python3 /usr/local/bin/celery worker --app=libretime_worker.tasks:worker --config=libretime_worker.config --time-limit=1800 --concurrency=1 --loglevel=INFO --logfile=/var/log/libretime/worker.log
             └─1359 /usr/bin/python3 /usr/local/bin/celery worker --app=libretime_worker.tasks:worker --config=libretime_worker.config --time-limit=1800 --concurrency=1 --loglevel=INFO --logfile=/var/log/libretime/worker.log

oct. 17 15:34:17 wrnc-diffusion systemd[1]: Started LibreTime Worker Service.
oct. 17 17:49:31 wrnc-diffusion systemd[1]: /lib/systemd/system/libretime-worker.service:18: Unknown key name 'ProtectProc' in section 'Service', ignoring.
oct. 17 17:49:31 wrnc-diffusion systemd[1]: /lib/systemd/system/libretime-worker.service:18: Unknown key name 'ProtectProc' in section 'Service', ignoring.
oct. 17 17:49:31 wrnc-diffusion systemd[1]: /lib/systemd/system/libretime-worker.service:18: Unknown key name 'ProtectProc' in section 'Service', ignoring.
oct. 17 17:49:31 wrnc-diffusion systemd[1]: /lib/systemd/system/libretime-worker.service:18: Unknown key name 'ProtectProc' in section 'Service', ignoring.
oct. 17 17:49:32 wrnc-diffusion systemd[1]: /lib/systemd/system/libretime-worker.service:18: Unknown key name 'ProtectProc' in section 'Service', ignoring.



~$ sudo systemctl --all --plain | egrep 'libretime|nginx|php.*-fpm'
  srv-libretime.mount                                                                                   loaded    active     mounted   /srv/libretime
  libretime-analyzer.service                                                                            loaded    active     running   LibreTime Media Analyzer Service
  libretime-api.service                                                                                 loaded    active     running   LibreTime API Service
  libretime-liquidsoap.service                                                                          loaded    active     running   LibreTime Liquidsoap Service
  libretime-playout.service                                                                             loaded    active     running   LibreTime Playout Service
  libretime-worker.service                                                                              loaded    active     running   LibreTime Worker Service
  nginx.service                                                                                         loaded    active     running   A high performance web server and a reverse proxy server
  php7.4-fpm.service                                                                                    loaded    active     running   The PHP 7.4 FastCGI Process Manager
  libretime-api.socket                                                                                  loaded    active     running   LibreTime API Socket
  libretime.target                                                                                      loaded    active     active    LibreTime Services

LibreTime version
LibreTime Version 3.0.0
rabbitmq-server Version: 3.8.2-0ubuntu1.3
liquidsoap Version: 1.4.2-1~ltppa2
postgresql Version: 12+214ubuntu0.1
ffpmeg Version: 7:4.2.7-0ubuntu0.1
python Version: 3.8.2-0ubuntu2

Installation method and OS / Environment
Operating system: Ubuntu 20.04.5 (Focal)
Method: Installer script

~$ ls -al /home/libretime/
total 12
drwxrwxr-x 3 libretime libretime 4096 oct.  17 17:23 .
drwxr-xr-x 5 root      root      4096 oct.  15 12:31 ..
drwxrwxr-x 2 libretime libretime 4096 oct.  18 17:22 organize

~$ findmnt | grep  "\[|home"
├─/home                               /dev/nvme2n1p4             ext4            rw,relatime
├─/srv/libretime                      /dev/nvme2n1p4[/libretime] ext4            rw,relatime

~$ ls -al /home/libretime/organize/
-rw-r--r-- 1 libretime libretime 9129600 oct.  18 17:22 '/home/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'

~$ ls -al /srv/libretime/organize/
-rw-r--r-- 1 libretime libretime 9129600 oct.  18 17:22 '/srv/libretime/organize/20-BLACK COUNTRY NEW ROAD - ATHENS, FRANCE.MP3'

Best Regards,

[SeBLeL]

Greetings, I posted the infos but the message got caught by the spam bot and is currently under review and should reappear soon, I hope

[SeBLeL]

Describe the problem
We try to upload files, they are successuflly copied onto the server directory, but are shown as Import Failed because analyzer could not be performed:

To reproduce
Steps to reproduce the behavior.

1. Login to the Management Portal as Admin
2. Click on Upload
3. Click on “Drag Files here or Click …” adn choose a file (tested with both MP3 and WAV)
4. See error “Import Failed” on the right Panel

Expected behavior
A media imported and analyzed successfully so it can be scheduled.

Relevant log output or error messages

~/$ sudo tail -n 100 -f "/var/log/syslog"
Oct 19 09:31:03 wrnc-diffusion systemd[1]: Started Session 420 of user wrnc.
Oct 19 09:31:22 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:31:22 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:31:34 wrnc-diffusion systemd[1]: Started Session 421 of user wrnc.
Oct 19 09:32:22 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:33:24 wrnc-diffusion rtkit-daemon[1449]: message repeated 3 times: [ Supervising 4 threads of 3 processes of 1 users.]
Oct 19 09:34:13 wrnc-diffusion systemd[1]: Started Run anacron jobs.
Oct 19 09:34:13 wrnc-diffusion anacron[333623]: Anacron 2.3 started on 2022-10-19
Oct 19 09:34:13 wrnc-diffusion anacron[333623]: Normal exit (0 jobs run)
Oct 19 09:34:13 wrnc-diffusion systemd[1]: anacron.service: Succeeded.
Oct 19 09:34:25 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:34:25 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:35:01 wrnc-diffusion CRON[333743]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Oct 19 09:35:01 wrnc-diffusion libretime-playout[900]: 2022-10-19 09:35:01.640 | INFO     | libretime_playout.player.fetch:main:413 - Queue timeout. Fetching schedule manually
Oct 19 09:35:01 wrnc-diffusion libretime-playout[900]: 2022-10-19 09:35:01.717 | INFO     | libretime_playout.player.fetch:main:392 - Loop #397
Oct 19 09:35:01 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/19 09:35:01 [server:3] New client: 127.0.0.1.
Oct 19 09:35:01 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/19 09:35:01 [lang:3] dynamic_source.get_id
Oct 19 09:35:01 wrnc-diffusion libretime-liquidsoap[898]: 2022/10/19 09:35:01 [server:3] Client 127.0.0.1 disconnected.
Oct 19 09:35:01 wrnc-diffusion libretime-playout[900]: 2022-10-19 09:35:01.722 | INFO     | libretime_playout.player.queue:main:54 - New schedule received
Oct 19 09:35:01 wrnc-diffusion libretime-playout[900]: 2022-10-19 09:35:01.723 | INFO     | libretime_playout.player.queue:main:33 - waiting indefinitely for schedule
Oct 19 09:35:23 wrnc-diffusion PackageKit: daemon quit
Oct 19 09:35:23 wrnc-diffusion systemd[1]: packagekit.service: Succeeded.
Oct 19 09:35:25 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:35:25 wrnc-diffusion rtkit-daemon[1449]: Supervising 4 threads of 3 processes of 1 users.
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: 2022-10-19 09:35:27.498 | INFO     | libretime_analyzer.message_listener:msg_received_callback:101 -  - Received 'b'{"file_id":22,"tmp_file_path":"\\/home\\/libretime\\/organize\\/22-TARAH WHO - COPYCAT.MP3","import_directory":"\\/home\\/libretime\\/\\/imported\\/1","original_filename":"TARAH WHO - COPYCAT.MP3"}'' on routing_key ''
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: 2022-10-19 09:35:27.498 | ERROR    | libretime_analyzer.pipeline.pipeline:run_analysis:102 - [Errno 13] Permission denied: '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: Traceback (most recent call last):
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/bin/libretime-analyzer", line 8, in <module>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     sys.exit(cli())
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │   │    └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │   └ <built-in function exit>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <module 'sys' (built-in)>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1128, in __call__
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return self.main(*args, **kwargs)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │     │       └ {}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │     └ ()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    └ <function BaseCommand.main at 0x7fae62038700>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1053, in main
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     rv = self.invoke(ctx)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          │    │      └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          │    └ <function Command.invoke at 0x7fae6202e1f0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1395, in invoke
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return ctx.invoke(self.callback, **ctx.params)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    │           │   └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    │           └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    └ <function cli at 0x7fae607f4820>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   └ <function Context.invoke at 0x7fae62033f70>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 754, in invoke
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return __callback(*args, **kwargs)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                        │       └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                        └ ()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/main.py", line 44, in cli
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     MessageListener(config)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │               └ Config(general=GeneralConfig(public_url=AnyHttpUrl('http://wrnc-diffusion:80', ), api_key='',...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <class 'libretime_analyzer.message_listener.MessageListener'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self.wait_for_messages()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._channel.start_consuming()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._process_data_events(time_limit=None)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self.connection.process_data_events(time_limit=time_limit)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    │                                         └ None
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <property object at 0x7fae60be4130>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._dispatch_channel_events()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     impl_channel._get_cookie()._dispatch_events()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     consumer_info.on_message_callback(self, evt.method,
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5eddee50>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata = MessageListener.spawn_analyzer_process(
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │               └ <staticmethod object at 0x7fae610213a0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                └ <class 'libretime_analyzer.message_listener.MessageListener'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     Pipeline.run_analysis(
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │        └ <staticmethod object at 0x7fae60c0b640>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: > File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata = analyze_metadata(audio_file_path, metadata)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │                │                └ {'ftype': 'audioclip', 'hidden': False}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │                └ '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                └ <function analyze_metadata at 0x7fae60be78b0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata["filesize"] = filepath.stat().st_size
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │                      │        └ <function Path.stat at 0x7fae621ce820>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │                      └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ {'ftype': 'audioclip', 'hidden': False}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return self._accessor.stat(self)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │              └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    └ <member '_accessor' of 'Path' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: 2022-10-19 09:35:27.501 | ERROR    | libretime_analyzer.message_listener:spawn_analyzer_process:177 - Analyzer pipeline exception: [Errno 13] Permission denied: '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: Traceback (most recent call last):
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/bin/libretime-analyzer", line 8, in <module>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     sys.exit(cli())
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │   │    └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │   └ <built-in function exit>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <module 'sys' (built-in)>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1128, in __call__
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return self.main(*args, **kwargs)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │     │       └ {}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │     └ ()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    └ <function BaseCommand.main at 0x7fae62038700>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1053, in main
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     rv = self.invoke(ctx)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          │    │      └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          │    └ <function Command.invoke at 0x7fae6202e1f0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:          └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 1395, in invoke
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return ctx.invoke(self.callback, **ctx.params)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    │           │   └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    │           └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      │    └ <function cli at 0x7fae607f4820>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   │      └ <Command cli>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │   └ <function Context.invoke at 0x7fae62033f70>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ <click.core.Context object at 0x7fae622ae6d0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/click/core.py", line 754, in invoke
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return __callback(*args, **kwargs)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                        │       └ {'log_filepath': PosixPath('/var/log/libretime/analyzer.log'), 'log_level': 'info', 'config_filepath': PosixPath('/etc/libret...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                        └ ()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/main.py", line 44, in cli
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     MessageListener(config)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │               └ Config(general=GeneralConfig(public_url=AnyHttpUrl('http://wrnc-diffusion:80', ), api_key='VFNihvLc7DoD5kzjnVhfeIQ8JJqhzYz5',...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <class 'libretime_analyzer.message_listener.MessageListener'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 37, in __init__
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self.wait_for_messages()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function MessageListener.wait_for_messages at 0x7fae607f4430>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 81, in wait_for_messages
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._channel.start_consuming()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    │        └ <function BlockingChannel.start_consuming at 0x7fae60be6280>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <libretime_analyzer.message_listener.MessageListener object at 0x7fae5ff6b4c0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1880, in start_consuming
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._process_data_events(time_limit=None)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingChannel._process_data_events at 0x7fae60be6430>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 2041, in _process_data_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self.connection.process_data_events(time_limit=time_limit)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    │                                         └ None
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <property object at 0x7fae60be4130>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 848, in process_data_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     self._dispatch_channel_events()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │    └ <function BlockingConnection._dispatch_channel_events at 0x7fae60bdca60>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <BlockingConnection impl=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport obj...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 567, in _dispatch_channel_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     impl_channel._get_cookie()._dispatch_events()
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │            └ <function Channel._get_cookie at 0x7fae60c4d3a0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport ...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/pika/adapters/blocking_connection.py", line 1507, in _dispatch_events
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     consumer_info.on_message_callback(self, evt.method,
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     │   └ <member 'method' of '_ConsumerDeliveryEvt' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   │     └ <pika.adapters.blocking_connection._ConsumerDeliveryEvt object at 0x7fae5eddee50>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             │                   └ <BlockingChannel impl=<Channel number=1 OPEN conn=<SelectConnection OPEN transport=<pika.adapters.utils.io_services_utils._As...
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │             └ <member 'on_message_callback' of '_ConsumerInfo' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <pika.adapters.blocking_connection._ConsumerInfo object at 0x7fae5eecba40>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 121, in msg_received_callback
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata = MessageListener.spawn_analyzer_process(
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │               └ <staticmethod object at 0x7fae610213a0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                └ <class 'libretime_analyzer.message_listener.MessageListener'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: > File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/message_listener.py", line 169, in spawn_analyzer_process
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     Pipeline.run_analysis(
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │        └ <staticmethod object at 0x7fae60c0b640>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ <class 'libretime_analyzer.pipeline.pipeline.Pipeline'>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 103, in run_analysis
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     raise exception
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/pipeline.py", line 80, in run_analysis
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata = analyze_metadata(audio_file_path, metadata)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │                │                └ {'ftype': 'audioclip', 'hidden': False}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                │                └ '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:                └ <function analyze_metadata at 0x7fae60be78b0>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/local/lib/python3.8/dist-packages/libretime_analyzer/pipeline/analyze_metadata.py", line 21, in analyze_metadata
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     metadata["filesize"] = filepath.stat().st_size
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │                      │        └ <function Path.stat at 0x7fae621ce820>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     │                      └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     └ {'ftype': 'audioclip', 'hidden': False}
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:   File "/usr/lib/python3.8/pathlib.py", line 1198, in stat
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:     return self._accessor.stat(self)
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    │              └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            │    └ <member '_accessor' of 'Path' objects>
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]:            └ PosixPath('/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3')
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: PermissionError: [Errno 13] Permission denied: '/home/libretime/organize/22-TARAH WHO - COPYCAT.MP3'
Oct 19 09:35:27 wrnc-diffusion libretime-analyzer[894]: 2022-10-19 09:35:27.514 | INFO     | libretime_analyzer.status_reporter:send_http_request:106 - HTTP request sent successfully.

~$ sudo -u libretime libretime-analyzer --config /etc/libretime/config.yml --log-level debug
2022-10-19 09:31:14.073 | INFO     | libretime_analyzer.message_listener:connect_to_messaging_server:76 -  Listening for messages...


~$ tail -f /var/log/libretime/*.log
==> /var/log/libretime/playout.log <==
2022-10-19 09:35:01.640 | INFO     | libretime_playout.player.fetch:main:413 - Queue timeout. Fetching schedule manually
2022-10-19 09:35:01.717 | INFO     | libretime_playout.player.fetch:main:392 - Loop #397

==> /var/log/libretime/liquidsoap.log <==
2022/10/19 09:35:01 [server:3] New client: 127.0.0.1.
2022/10/19 09:35:01 [lang:3] dynamic_source.get_id
2022/10/19 09:35:01 [server:3] Client 127.0.0.1 disconnected.

==> /var/log/libretime/playout.log <==
2022-10-19 09:35:01.722 | INFO     | libretime_playout.player.queue:main:54 - New schedule received
2022-10-19 09:35:01.723 | INFO     | libretime_playout.player.queue:main:33 - waiting indefinitely for schedule

==> /var/log/libretime/legacy.log <==
2022-10-19T09:35:27+02:00 INFO (6): Moving file /tmp/phpYpvDEi to /home/libretime/organize/22-TARAH WHO - COPYCAT.MP3

LibreTime version
The version of LibreTime your are running.
LibreTime version: 3.0.0
rabbitmq-server Version: 3.8.2-0ubuntu1.3
liquidsoap Version: 1.4.2-1~ltppa2
postgresql Version: 12+214ubuntu0.1
ffpmeg Version: 7:4.2.7-0ubuntu0.1
python Version: 3.8.2-0ubuntu2

Installation method and OS / Environment
config.yml:

general:
  public_url: http://wrnc-diffusion:80
  api_key: <redacted>

  allowed_cors_origins: []

  timezone: Europe/Paris

  cache_ahead_hours: 1

  auth: local

storage:
  path: /home/libretime

database:
  host: localhost
  port: 5432
  name: libretime
  user: libretime
  password: <redacted>

rabbitmq:
  host: localhost
  port: 5672
  vhost: /libretime
  user: libretime
  password: <redacted>

playout:
  liquidsoap_host: localhost
  liquidsoap_port: 1234

  record_file_format: ogg
  record_bitrate: 256
  record_samplerate: 44100
  record_channels: 2
  record_sample_size: 16

liquidsoap:
  server_listen_address: "127.0.0.1"
  server_listen_port: 1234

  harbor_listen_address: ["0.0.0.0"]

stream:
  inputs:
    main:
      public_url:
      mount: main
      port: 8001

    show:
      public_url:
      mount: show
      port: 8002

  outputs:
    .default_icecast_output: &default_icecast_output
      host: localhost
      port: 8000
      source_password: <redacted>
      admin_password: <redacted>
      name: WRNC
      description: World Radio Normandie Caen
      website: https://worldradionormandiecaen.com
      genre: various

    icecast:
      - <<: *default_icecast_output
        enabled: true
        public_url:
        mount: main
        audio:
          format: ogg
          bitrate: 256

      - <<: *default_icecast_output
        enabled: false
        mount: main-low
        audio:
          format: ogg
          bitrate: 128

        enabled: false
        public_url:
        host: localhost
        port: 8000
        mount: main
        source_user: source
        source_password: <redacted>
        admin_user: admin
        admin_password: <redacted>

        audio:
          format: ogg
          bitrate: 256

          enable_metadata: false

        name: WRNC
        description: World Radio Normandie Caen
        website: https://worldradionormandiecaen.com
        genre: various

    shoutcast:
        enabled: false
        public_url:
        host: localhost
        port: 8000
        source_user: source
        source_password: <redacted>
        admin_user: admin
        admin_password: <redacted>

        audio:
          format: mp3
          bitrate: 256

        name: WRNC
        website: https://worldradionormandiecaen.com
        genre: various

    system:
        enabled: false
        kind: alsa

Operating system: Ubuntu Focal 20.04.5
Method: Installer script

[joola]

Thanks for all the details.

Weird, and could you show me the permissions of the /home/libretime folder, and the user running your services ?

ls -al /home/libretime

ls -al /var/lib/libretime
sudo systemctl cat libretime-analyzer.service

I’ll try to reproduce this, locally, maybe this is an obvious bug.

[joola]

Yes, I just approved your reply, it was marked as spam.

[SeBLeL]

Thank you for your reply!

/home/libretime is mounted with bind to /srv/libretime ( /home is the real ext4 partition, and /home/libretime is mounted bind on /srv/libretime )

There you go!

~$ sudo ls -al /home/libretime
total 12
drwxrwxr-x 3 libretime libretime 4096 oct.  17 17:23 .
drwxr-xr-x 5 root      root      4096 oct.  15 12:31 ..
drwxrwxr-x 2 libretime libretime 4096 oct.  19 09:35 organize

~$ sudo ls -al /srv/libretime
total 12
drwxrwxr-x 3 libretime libretime 4096 oct.  17 17:23 .
drwxrwxr-x 3 root      root      4096 oct.  15 12:26 ..
drwxrwxr-x 2 libretime libretime 4096 oct.  19 09:35 organize

~$ findmnt | grep  "nvme2n1p4"
├─/home                               /dev/nvme2n1p4             ext4            rw,relatime
├─/srv/libretime                      /dev/nvme2n1p4[/libretime] ext4            rw,relatime

~$ sudo ls -al /var/lib/libretime
total 24
drwxr-xr-x  6 libretime libretime 4096 oct.  15 12:45 .
drwxr-xr-x 72 root      root      4096 oct.  15 12:30 ..
drwxr-xr-x  2 libretime libretime 4096 oct.  15 12:28 analyzer
drwx------  3 libretime libretime 4096 oct.  15 12:45 .cache
drwxr-xr-x  4 libretime libretime 4096 oct.  15 12:45 playout
drwxr-xr-x  2 libretime libretime 4096 oct.  15 12:28 worker

~$ sudo systemctl cat libretime-analyzer.service
# /lib/systemd/system/libretime-analyzer.service
[Unit]
Description=LibreTime Media Analyzer Service
PartOf=libretime.target

[Service]
NoNewPrivileges=true
CapabilityBoundingSet=
PrivateDevices=true
PrivateTmp=true
PrivateUsers=true
ProtectClock=true
ProtectControlGroups=true
ProtectHome=true
ProtectHostname=true
ProtectKernelLogs=true
ProtectKernelModules=true
ProtectKernelTunables=true
ProtectProc=invisible
ProtectSystem=full

Environment=LIBRETIME_CONFIG_FILEPATH=/etc/libretime/config.yml
Environment=LIBRETIME_LOG_FILEPATH=/var/log/libretime/analyzer.log
WorkingDirectory=/var/lib/libretime/analyzer

ExecStart=/usr/local/bin/libretime-analyzer
Restart=always

User=libretime
Group=libretime

[Install]
WantedBy=multi-user.target
~$

[joola]

Ok, could you try to disable the ProtectHome=true security feature the systemd service ?

sed -i -e "s|^ProtectHome=|#ProtectHome=|" /usr/lib/systemd/system/libretime-analyzer.service

If that fixes your issue, you might want to disable this feature for all the libretime services, or move your storage somewhere else.

[SeBLeL]

Import has been done successfully! Thank you!

I will disable the ProtectHome feature from all services, sin ce /home is our largest storage point on this instance.

thank you!

[joola]

Thanks for reporting the issue !

Don’t forget to change you api key in your config file, you leaked this info in some of your logs.

Cheers