search

AzuraCast / AzuraCast

A self-hosted web radio management suite, including turnkey installer tools for the full radio software stack and a modern, easy-to-use web app to manage your stations.
https://www.azuracast.com/
GNU Affero General Public License v3.0
3.02k stars 562 forks source link

Synchronization Not Recently Run #5937

Closed Marcioghiraldelli closed 7 months ago

Marcioghiraldelli commented 1 year ago

Installation Method

Docker Installation

AzuraCast Release Channel

Rolling Release Channel

Current AzuraCast Version

Rolling Release #4b72fbe (2022-12-12 18:47) • Docker • PHP 8.1

What happened?

I recently updated my azuracast and noticed that mysql is having a higher than normal usage and every 10 to 20 minutes the message appears

Synchronization Not Recently Run The routine synchronization task has not run recently. This may indicate an error with your installation.

I did the test to see which one is not running and I realize that App\Sync\Task\RunAnalyticsTask App\Sync\Task\RotateLogsTask App\Sync\Task\CleanupStorageTask

They are having difficulties in executing, loading all the time and it does not finish.

Currently this server has 15 radios 6 core processor with 24gb of memory. Ubuntu 20 system ARM Architecture.

https://prnt.sc/cyPRRWdNM7r0 https://prnt.sc/jF7boQocn6ON

Relevant log output

[2022-12-13T04:33:10.705506+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":181,"name":"Web Radio Santuario"}}
[2022-12-13T04:33:17.414056+00:00] AzuraCast.ERROR: No valid playlists detected. Skipping AutoDJ calculations. [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:17.434556+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:17.434755+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fultra.flac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:17.434912+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:17.435031+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fhigh.aac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:17.444759+00:00] AzuraCast.ERROR: No track to update. {"exception":"[object] (RuntimeException(code: 0): No track to update. at /var/azuracast/www/src/Entity/Repository/SongHistoryRepository.php:78)"} {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:33:19.172369+00:00] AzuraCast.ERROR: No HLS streams. [] {"station":{"id":192,"name":"NATIVOS"}}
[2022-12-13T04:33:26.463377+00:00] AzuraCast.WARNING: Duplicate prevention yielded no playable song; resetting song queue. [] {"station":{"id":27,"name":"IlheusFM"}}
[2022-12-13T04:33:26.482598+00:00] AzuraCast.WARNING: Playlist "VINHETAS RÁDIO" did not return a playable track. {"playlist_id":229,"playlist_order":"shuffle","allow_duplicates":false} {"station":{"id":27,"name":"IlheusFM"}}
[2022-12-13T04:33:26.483979+00:00] AzuraCast.WARNING: No way to avoid same title OR same artist; using least recently played song. {"media_id":183820,"title":"Dom Áudio & Produtora.","artist":"DJ JUNIOR ALVES"} {"station":{"id":27,"name":"IlheusFM"}}
[2022-12-13T04:34:03.087890+00:00] AzuraCast.ERROR: Symfony\Component\Process\Exception\ProcessTimedOutException: The process "'php' '/var/azuracast/www/bin/console' 'azuracast:sync:task' 'App\Sync\Task\RunAnalyticsTask'" exceeded the timeout of 1800 seconds. (uncaught exception) at /var/azuracast/www/vendor/symfony/process/Process.php line 1152 while running console command `azuracast:sync:run` {"exception":"[object] (Symfony\\Component\\Process\\Exception\\ProcessTimedOutException(code: 0): The process \"'php' '/var/azuracast/www/bin/console' 'azuracast:sync:task' 'App\\Sync\\Task\\RunAnalyticsTask'\" exceeded the timeout of 1800 seconds. at /var/azuracast/www/vendor/symfony/process/Process.php:1152)"} []
[2022-12-13T04:34:03.090507+00:00] AzuraCast.WARNING: Console command `azuracast:sync:run` exited with error code 1. [] []
[2022-12-13T04:34:05.994738+00:00] AzuraCast.NOTICE: SFTP user "Root" not found. [] []
[2022-12-13T04:34:17.074153+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":181,"name":"Web Radio Santuario"}}
[2022-12-13T04:34:24.810821+00:00] AzuraCast.ERROR: No valid playlists detected. Skipping AutoDJ calculations. [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:24.832847+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:24.833065+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fultra.flac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:24.833228+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:24.833363+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fhigh.aac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:24.845492+00:00] AzuraCast.ERROR: No track to update. {"exception":"[object] (RuntimeException(code: 0): No track to update. at /var/azuracast/www/src/Entity/Repository/SongHistoryRepository.php:78)"} {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:34:25.797093+00:00] AzuraCast.ERROR: No HLS streams. [] {"station":{"id":192,"name":"NATIVOS"}}
[2022-12-13T04:35:03.490282+00:00] AzuraCast.ERROR: Storage location is full; skipping broadcasts. {"storageLocation":"Local: /var/azuracast/stations/web_radio_santuario/media/Recordings"} {"task":"MoveBroadcastsTask"}
[2022-12-13T04:35:04.057387+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":60,"name":"Diocese de Caruaru"},"task":"QueueInterruptingTracks"}
[2022-12-13T04:35:04.103240+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":73,"name":"ofmsantoantonio"},"task":"QueueInterruptingTracks"}
[2022-12-13T04:35:25.783083+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":181,"name":"Web Radio Santuario"}}
[2022-12-13T04:35:35.346066+00:00] AzuraCast.ERROR: No valid playlists detected. Skipping AutoDJ calculations. [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:35.367339+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:35.367551+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fultra.flac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:35.367722+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/stats produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:35.367854+00:00] AzuraCast.ERROR: HTTP client GET call to http://127.0.0.1:8140/admin/listclients?mount=%2Fhigh.aac produced response NULL [] {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:35.379029+00:00] AzuraCast.ERROR: No track to update. {"exception":"[object] (RuntimeException(code: 0): No track to update. at /var/azuracast/www/src/Entity/Repository/SongHistoryRepository.php:78)"} {"station":{"id":188,"name":"Radio Star"}}
[2022-12-13T04:35:36.350241+00:00] AzuraCast.ERROR: No HLS streams. [] {"station":{"id":192,"name":"NATIVOS"}}
[2022-12-13T04:35:37.661098+00:00] AzuraCast.NOTICE: Failed to define an expiration for the "{resource}" lock, someone else acquired the lock. {"resource":{"Symfony\\Component\\Lock\\Key":"lock_nowplaying_radiosindelp"}} []
[2022-12-13T04:35:37.663743+00:00] AzuraCast.ERROR: Symfony\Component\Lock\Exception\LockConflictedException:  (uncaught exception) at /var/azuracast/www/vendor/symfony/lock/Store/RedisStore.php line 165 while running console command `azuracast:sync:nowplaying` {"exception":"[object] (Symfony\\Component\\Lock\\Exception\\LockConflictedException(code: 0):  at /var/azuracast/www/vendor/symfony/lock/Store/RedisStore.php:165)"} []
[2022-12-13T04:35:37.664077+00:00] AzuraCast.WARNING: Console command `azuracast:sync:nowplaying` exited with error code 1. [] []
[2022-12-13T04:36:00.132425+00:00] AzuraCast.WARNING: Duplicate prevention yielded no playable song; resetting song queue. [] {"station":{"id":62,"name":"rezendew336"}}
[2022-12-13T04:36:00.144879+00:00] AzuraCast.WARNING: Playlist "tem q ter nome as playlist" did not return a playable track. {"playlist_id":1147,"playlist_order":"shuffle","allow_duplicates":false} {"station":{"id":62,"name":"rezendew336"}}
[2022-12-13T04:36:00.146234+00:00] AzuraCast.WARNING: No way to avoid same title OR same artist; using least recently played song. {"media_id":212489,"title":"big sean","artist":"pharrell williams"} {"station":{"id":62,"name":"rezendew336"}}
[2022-12-13T04:36:04.328524+00:00] AzuraCast.ERROR: Handling "App\Message\ReprocessMediaMessage" failed: MIME type "image/jxl" is not processable. {"file":"/var/azuracast/www/vendor/symfony/messenger/Middleware/HandleMessageMiddleware.php","line":129,"code":0} []
[2022-12-13T04:36:04.858677+00:00] AzuraCast.ERROR: Storage location is full; skipping broadcasts. {"storageLocation":"Local: /var/azuracast/stations/web_radio_santuario/media/Recordings"} {"task":"MoveBroadcastsTask"}
[2022-12-13T04:36:05.643126+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":60,"name":"Diocese de Caruaru"},"task":"QueueInterruptingTracks"}
[2022-12-13T04:36:05.724917+00:00] AzuraCast.ERROR: No playable tracks were found. [] {"station":{"id":73,"name":"ofmsantoantonio"},"task":"QueueInterruptingTracks"}
scysys commented 1 year ago

This should be the Nginx Timeout in your case.

Read here: https://docs.azuracast.com/en/administration/docker Navigate to "Adding custom NGINX configurations".

fastcgi_read_timeout 1800 -> This should what you looking for to increase.

Maybe its just enough to look into your azuracast.env and "SYNC_LONG_EXECUTION_TIME". Not sure before i not run into it myself :p

Marcioghiraldelli commented 1 year ago

I changed SYNC_LONG_EXECUTION_TIME in azuracast.env to 2800, I don't know if it was a correct change. Does the high use of mysql have something to do with this? or should I increase the number of concurrent mysql connections?

Marcioghiraldelli commented 1 year ago

App\Sync\Task\RunAnalyticsTask

Log-------------- [2022-12-13T20:17:48.880481+00:00] AzuraCast.NOTICE: Failed to define an expiration for the "{resource}" lock, someone else acquired the lock. {"resource":{"Symfony\Component\Lock\Key":"lock_nowplaying_a_voz_do_evangelho"}} [] [2022-12-13T20:17:48.883745+00:00] AzuraCast.ERROR: Symfony\Component\Lock\Exception\LockConflictedException: (uncaught exception) at /var/azuracast/www/vendor/symfony/lock/Store/RedisStore.php line 179 while running console command azuracast:sync:nowplaying {"exception":"[object] (Symfony\Component\Lock\Exception\LockConflictedException(code: 0): at /var/azuracast/www/vendor/symfony/lock/Store/RedisStore.php:179)"} [] [2022-12-13T20:17:48.884244+00:00] AzuraCast.WARNING: Console command azuracast:sync:nowplaying exited with error code 1. [] [] [2022-12-13T20:18:36.333671+00:00] AzuraCast.ERROR: An exception occurred while executing a query: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction {"file":"/var/azuracast/www/vendor/doctrine/dbal/src/Driver/API/MySQL/ExceptionConverter.php","line":42,"code":1205} {"task":"RunAnalyticsTask"} [2022-12-13T20:18:47.291271+00:00] AzuraCast.WARNING: Duplicate prevention yielded no playable song; resetting song queue. [] {"station":{"id":264,"name":"estacaocapoeira"}}

Marcioghiraldelli commented 1 year ago

when running App\Sync\Task\RunAnalyticsTask

it gives this error in the log

An exception occurred while executing a query: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction ExceptionConverter.php : 42

radiobellissima commented 1 year ago

We live the same situation but with the latest stable version. Were there any valid solutions found?

sachinshakya507 commented 1 year ago

Docker installation: v0.17.7 Stable I am also getting same issue

Trying to run task App\Sync\Task\RunAnalyticsTask manually

Error Message: An exception occurred while executing a query: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction ExceptionConverter.php : 42

pavlos2 commented 1 year ago

same error here, with # SYNC_LONG_EXECUTION_TIME=2200 and # SYNC_SHORT_EXECUTION_TIME=900

radiobellissima commented 1 year ago

Still no solution to this? Rolling Release #[bb163c2] (2023-03-02 14:33)

Moonbase59 commented 1 year ago

I’m running ~155k songs from a NFS network mount, AzuraCast Rolling Release on a 2 CPU, 4GB RAM, 40GB SSD Ubuntu 22.04 LTS VM, and use these settings with no problems so far:

.env (only selected entries shown):

NGINX_TIMEOUT=3600

azuracast.env (only selected entries shown):

APPLICATION_ENV=production
PHP_MAX_FILE_SIZE=256M
PHP_MEMORY_LIMIT=1G
PHP_MAX_EXECUTION_TIME=120
SYNC_SHORT_EXECUTION_TIME=1200
SYNC_LONG_EXECUTION_TIME=3600

For testing, I updated SYNC_SHORT_EXECUTION_TIME from default 600 to 1200 recently, because I sometimes got "not recently run" on App\Sync\Task\CleanupHistoryTask (17 ), although this should use the SYNC_LONG_EXECUTION_TIME, I think.

github-actions[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

SysadminJeroen commented 1 year ago

I still occasionally have this issue.

github-actions[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

SysadminJeroen commented 1 year ago

Bump.

github-actions[bot] commented 11 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

pavlos2 commented 11 months ago

However, allow me to say that this issue remains unresolved.

github-actions[bot] commented 9 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

SysadminJeroen commented 9 months ago

I can confirm that this still happens. Although the frequency for me has decreased after I migrated my Azuracast installation to a new server.

Op ma 11 dec. 2023 01:06 schreef github-actions[bot] < @.***>:

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

— Reply to this email directly, view it on GitHub https://github.com/AzuraCast/AzuraCast/issues/5937#issuecomment-1849137415, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAWHZRRLNXTRZF3X4MCKDPDYIZFA5AVCNFSM6AAAAAAS4XPBSKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQNBZGEZTONBRGU . You are receiving this because you are subscribed to this thread.Message ID: @.***>

pavlos2 commented 9 months ago

I managed to fix it by increasing the server resources.

github-actions[bot] commented 7 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] commented 7 months ago

Thank you for your bug report, this issue has been closed due to inactivity. Should this issue persist, please re-open the bug report.

pavlos2 commented 3 months ago

Does v0.20.0 fix this issue?

BusterNeece commented 3 months ago

@pavlos2 It certainly should help.

pavlos2 commented 3 months ago

Thank you Buster.

pavlos2 commented 3 months ago

Thank you Buster.

SysadminJeroen commented 3 months ago

I haven't seen the issue anymore since v0.20.0.

pavlos2 commented 3 months ago

While in azuracast.env it is set # SYNC_LONG_EXECUTION_TIME=2200. I still get the error:

[2024-05-30T20:34:01.596385+00:00] AzuraCast.ERROR: Symfony\Component\Process\Exception\ProcessTimedOutException: The process "'php' '/var/azuracast/www/bin/console' 'azuracast:sync:task' 'App\Sync\Task\RunAnalyticsTask'" exceeded the timeout of 1800 seconds. (uncaught exception) at /var/azuracast/www/vendor/symfony/process/Process.php line 1150 while running console command azuracast:sync:run {"exception":"[object] (Symfony\Component\Process\Exception\ProcessTimedOutException(code: 0): The process \"'php' '/var/azuracast/www/bin/console' 'azuracast:sync:task' 'App\Sync\Task\RunAnalyticsTask'\" exceeded the timeout of 1800 seconds. at /var/azuracast/www/vendor/symfony/process/Process.php:1150)"} []