Our development server running the latest LibreTime clone from github is getting a flood of errors in daemon.log and syslog as well, to the point where I’ve shut down LibreTime until I have time to file a bug report and/or fix the problem.
Turning off logging does not fix the problem, it merely hides the symptoms, and also hides any other problems that exist. Instead, you may need to roll back to a previous version of LibreTime, possibly v4.2.0 LibreTime 4.2.0 | LibreTime I’ve had problems with v4.2.0 as well, but not those problems.
–Bob.
For reference, here’s a 1 second snippet of daemon.log
Jan 30 00:38:10 dev-libretime libretime-playout[836]: 2025-01-30 00:38:10,997 | WARNING | kombu.mixins:run:180 - Connection to broker lost, trying to re-establish connection...
Jan 30 00:38:10 dev-libretime libretime-playout[836]: Traceback (most recent call last):
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/mixins.py", line 175, in run
Jan 30 00:38:10 dev-libretime libretime-playout[836]: for _ in self.consume(limit=None, **kwargs):
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/mixins.py", line 191, in consume
Jan 30 00:38:10 dev-libretime libretime-playout[836]: with self.consumer_context(**kwargs) as (conn, channel, consumers):
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/usr/lib/python3.9/contextlib.py", line 117, in __enter__
Jan 30 00:38:10 dev-libretime libretime-playout[836]: return next(self.gen)
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/mixins.py", line 184, in consumer_context
Jan 30 00:38:10 dev-libretime libretime-playout[836]: with self.Consumer() as (connection, channel, consumers):
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/usr/lib/python3.9/contextlib.py", line 117, in __enter__
Jan 30 00:38:10 dev-libretime libretime-playout[836]: return next(self.gen)
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/mixins.py", line 227, in Consumer
Jan 30 00:38:10 dev-libretime libretime-playout[836]: with self.establish_connection() as conn:
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/usr/lib/python3.9/contextlib.py", line 117, in __enter__
Jan 30 00:38:10 dev-libretime libretime-playout[836]: return next(self.gen)
Jan 30 00:38:10 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/mixins.py", line 221, in establish_connection
Jan 30 00:38:11 dev-libretime libretime-playout[836]: conn.ensure_connection(self.on_connection_error,
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/connection.py", line 389, in ensure_connection
Jan 30 00:38:11 dev-libretime libretime-playout[836]: self._ensure_connection(*args, **kwargs)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/connection.py", line 441, in _ensure_connection
Jan 30 00:38:11 dev-libretime libretime-playout[836]: return retry_over_time(
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/utils/functional.py", line 344, in retry_over_time
Jan 30 00:38:11 dev-libretime libretime-playout[836]: return fun(*args, **kwargs)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/connection.py", line 874, in _connection_factory
Jan 30 00:38:11 dev-libretime libretime-playout[836]: self._connection = self._establish_connection()
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/connection.py", line 809, in _establish_connection
Jan 30 00:38:11 dev-libretime libretime-playout[836]: conn = self.transport.establish_connection()
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/kombu/transport/pyamqp.py", line 130, in establish_connection
Jan 30 00:38:11 dev-libretime libretime-playout[836]: conn.connect()
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/connection.py", line 320, in connect
Jan 30 00:38:11 dev-libretime libretime-playout[836]: self.drain_events(timeout=self.connect_timeout)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/connection.py", line 508, in drain_events
Jan 30 00:38:11 dev-libretime libretime-playout[836]: while not self.blocking_read(timeout):
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/connection.py", line 514, in blocking_read
Jan 30 00:38:11 dev-libretime libretime-playout[836]: return self.on_inbound_frame(frame)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/method_framing.py", line 55, in on_frame
Jan 30 00:38:11 dev-libretime libretime-playout[836]: callback(channel, method_sig, buf, None)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/connection.py", line 520, in on_inbound_method
Jan 30 00:38:11 dev-libretime libretime-playout[836]: return self.channels[channel_id].dispatch_method(
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/abstract_channel.py", line 145, in dispatch_method
Jan 30 00:38:11 dev-libretime libretime-playout[836]: listener(*args)
Jan 30 00:38:11 dev-libretime libretime-playout[836]: File "/opt/libretime/lib/python3.9/site-packages/amqp/connection.py", line 650, in _on_close
Jan 30 00:38:11 dev-libretime libretime-playout[836]: raise error_for_code(reply_code, reply_text,
Jan 30 00:38:11 dev-libretime libretime-playout[836]: amqp.exceptions.AccessRefused: (0, 0): (403) ACCESS_REFUSED - Login was refused using authentication mechanism AMQPLAIN. For details see the broker logfile.
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]:
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: -------------- celery@dev-libretime v4.4.7 (cliffs)
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: --- ***** -----
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: -- ******* ---- Linux-6.1.0-18-amd64-x86_64-with-glibc2.31 2025-01-30 00:38:09
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - *** --- * ---
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - ** ---------- [config]
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - ** ---------- .> app: __main__:0x7f03385642b0
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - ** ---------- .> transport: amqp://libretime:**@localhost:5672//libretime
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - ** ---------- .> results: amqp://
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: - *** --- * --- .> concurrency: 1 (prefork)
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: --- ***** -----
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: -------------- [queues]
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: .> exchange=celeryresults(direct) key=celery
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: .> celery exchange=celery(direct) key=celery
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: .> podcast exchange=podcast(direct) key=podcast
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: [tasks]
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: . libretime_worker.tasks.legacy_trigger_task_manager
Jan 30 00:38:11 dev-libretime libretime-worker[1658091]: . podcast-download
Jan 30 00:38:11 dev-libretime systemd[1]: libretime-worker.service: Succeeded.
Jan 30 00:38:11 dev-libretime systemd[1]: libretime-worker.service: Consumed 1.678s CPU time.
Jan 30 00:38:11 dev-libretime systemd[1]: libretime-worker.service: Scheduled restart job, restart counter is at 77603.
Jan 30 00:38:11 dev-libretime systemd[1]: Stopped LibreTime Worker Service.
Jan 30 00:38:11 dev-libretime systemd[1]: libretime-worker.service: Consumed 1.678s CPU time.
Jan 30 00:38:11 dev-libretime systemd[1]: Started LibreTime Worker Service.
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,891 | INFO | pika.adapters.utils.connection_workflow:start:179 - Pika version 1.3.2 connecting to ('::1', 5672, 0, 0)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,891 | INFO | pika.adapters.utils.io_services_utils:_on_writable:345 - Socket connected: <socket.socket fd=7, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::1', 46790, 0, 0), raddr=('::1', 5672, 0, 0)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,892 | INFO | pika.adapters.utils.connection_workflow:_on_transport_establishment_done:428 - Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7ff569da0a00>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7ff569da0a00> params=<ConnectionParameters host=localhost port=5672 virtual_host=/libretime ssl=False>>).
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,893 | INFO | pika.adapters.utils.io_services_utils:abort:731 - Aborting transport connection: state=1; <socket.socket fd=7, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::1', 46790, 0, 0), raddr=('::1', 5672, 0, 0)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,894 | INFO | pika.adapters.utils.io_services_utils:_initiate_abort:904 - _AsyncTransportBase._initate_abort(): Initiating abrupt asynchronous transport shutdown: state=1; error=None; <socket.socket fd=7, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::1', 46790, 0, 0), raddr=('::1', 5672, 0, 0)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,894 | INFO | pika.adapters.utils.io_services_utils:_deactivate:869 - Deactivating transport: state=1; <socket.socket fd=7, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::1', 46790, 0, 0), raddr=('::1', 5672, 0, 0)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,894 | INFO | pika.connection:_on_stream_terminated:2017 - AMQP stack terminated, failed to connect, or aborted: opened=False, error-arg=None; pending-error=ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,894 | ERROR | pika.connection:_on_stream_terminated:2052 - Connection closed while authenticating indicating a probable authentication error
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,894 | INFO | pika.connection:_on_stream_terminated:2082 - Connection setup terminated due to ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,895 | ERROR | pika.adapters.utils.connection_workflow:_report_completion_and_cleanup:291 - AMQPConnector - reporting failure: AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,895 | INFO | pika.adapters.utils.connection_workflow:start:179 - Pika version 1.3.2 connecting to ('127.0.0.1', 5672)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,895 | INFO | pika.adapters.utils.io_services_utils:_close_and_finalize:882 - Closing transport socket and unlinking: state=3; <socket.socket fd=7, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::1', 46790, 0, 0), raddr=('::1', 5672, 0, 0)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,895 | INFO | pika.adapters.utils.io_services_utils:_on_writable:345 - Socket connected: <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 44474), raddr=('127.0.0.1', 5672)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,896 | INFO | pika.adapters.utils.connection_workflow:_on_transport_establishment_done:428 - Streaming transport linked up: (<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7ff569a52340>, _StreamingProtocolShim: <SelectConnection PROTOCOL transport=<pika.adapters.utils.io_services_utils._AsyncPlaintextTransport object at 0x7ff569a52340> params=<ConnectionParameters host=localhost port=5672 virtual_host=/libretime ssl=False>>).
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,897 | INFO | pika.adapters.utils.io_services_utils:abort:731 - Aborting transport connection: state=1; <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 44474), raddr=('127.0.0.1', 5672)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,897 | INFO | pika.adapters.utils.io_services_utils:_initiate_abort:904 - _AsyncTransportBase._initate_abort(): Initiating abrupt asynchronous transport shutdown: state=1; error=None; <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 44474), raddr=('127.0.0.1', 5672)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,897 | INFO | pika.adapters.utils.io_services_utils:_deactivate:869 - Deactivating transport: state=1; <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 44474), raddr=('127.0.0.1', 5672)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | INFO | pika.connection:_on_stream_terminated:2017 - AMQP stack terminated, failed to connect, or aborted: opened=False, error-arg=None; pending-error=ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.connection:_on_stream_terminated:2052 - Connection closed while authenticating indicating a probable authentication error
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | INFO | pika.connection:_on_stream_terminated:2082 - Connection setup terminated due to ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.adapters.utils.connection_workflow:_report_completion_and_cleanup:291 - AMQPConnector - reporting failure: AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.adapters.utils.connection_workflow:_start_new_cycle_async:746 - AMQP connection workflow failed: AMQPConnectionWorkflowFailed: 2 exceptions in all; last exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",); first exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",).
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.adapters.utils.connection_workflow:_report_completion_and_cleanup:723 - AMQPConnectionWorkflow - reporting failure: AMQPConnectionWorkflowFailed: 2 exceptions in all; last exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",); first exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | INFO | pika.adapters.utils.io_services_utils:_close_and_finalize:882 - Closing transport socket and unlinking: state=3; <socket.socket fd=8, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('127.0.0.1', 44474), raddr=('127.0.0.1', 5672)>
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.adapters.blocking_connection:_create_connection:450 - Connection workflow failed: AMQPConnectionWorkflowFailed: 2 exceptions in all; last exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",); first exception - AMQPConnectorAMQPHandshakeError: ProbableAuthenticationError: Client was disconnected at a connection stage indicating a probable authentication error: ("ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'",)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,898 | ERROR | pika.adapters.blocking_connection:_create_connection:457 - Error in _create_connection().
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: Traceback (most recent call last):
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: File "/opt/libretime/lib/python3.9/site-packages/pika/adapters/blocking_connection.py", line 451, in _create_connection
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: raise self._reap_last_connection_workflow_error(error)
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: pika.exceptions.ProbableAuthenticationError: ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,899 | ERROR | libretime_analyzer.message_listener:__init__:47 - Connection to message queue failed.
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,899 | ERROR | libretime_analyzer.message_listener:__init__:48 - ConnectionClosedByBroker: (403) 'ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.'
Jan 30 00:38:11 dev-libretime libretime-analyzer[833]: 2025-01-30 00:38:11,899 | INFO | libretime_analyzer.message_listener:__init__:49 - Retrying in 5 seconds...
type or paste code here