Switch logging to be managed/rotated by Supervisord.

Rationale: under the current system, Supervisord simply pipes its per-process logs out to stdout/stderr on Docker, meaning it has no ability to read back those logs in the case of an error, leading to cryptic error messages like "SPAWN_ERROR" instead of the actual problem. This refactors the logging to be handled by Supervisord, which also is itself capable of log rotation (removing the need for AzuraCast to rotate radio software logs).

composer.json

@@ -91,8 +91,8 @@
         "plugins/*/composer.json"
       ],
       "recurse": true,
-      "replace": false,
-      "ignore-duplicates": true,
+      "replace": true,
+      "ignore-duplicates": false,
       "merge-dev": true,
       "merge-extra": false,
       "merge-extra-deep": false,

composer.lock

@@ -4,7 +4,7 @@
         "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies",
         "This file is @generated automatically"
     ],
-    "content-hash": "5930a9ec972c64b73a8ed2bf39d8100c",
+    "content-hash": "89d96840eefe93f2b9c0dc8ef5f0fe89",
     "packages": [
         {
             "name": "aws/aws-sdk-php",
@@ -94,12 +94,12 @@
             "source": {
                 "type": "git",
                 "url": "https://github.com/AzuraCast/azuracore.git",
-                "reference": "a2f47bb6626d22dc007ffd9d3cd2a1fcb3f0ef35"
+                "reference": "19c3872875f3f452b7d554d19555d402c2a313ef"
             },
             "dist": {
                 "type": "zip",
-                "url": "https://api.github.com/repos/AzuraCast/azuracore/zipball/a2f47bb6626d22dc007ffd9d3cd2a1fcb3f0ef35",
-                "reference": "a2f47bb6626d22dc007ffd9d3cd2a1fcb3f0ef35",
+                "url": "https://api.github.com/repos/AzuraCast/azuracore/zipball/19c3872875f3f452b7d554d19555d402c2a313ef",
+                "reference": "19c3872875f3f452b7d554d19555d402c2a313ef",
                 "shasum": ""
             },
             "require": {
@@ -149,7 +149,7 @@
                 }
             ],
             "description": "A lightweight core application framework.",
-            "time": "2019-03-03T04:05:10+00:00"
+            "time": "2019-03-08T01:38:02+00:00"
         },
         {
             "name": "azuracast/azuraforms",

docker-compose.dev.yml

@@ -87,6 +87,7 @@ services:
      - station_data:/var/azuracast/stations
      - letsencrypt:/etc/nginx/ssl:ro
      - shoutcast2_install:/var/azuracast/servers/shoutcast2
+     - tmp_data:/var/azuracast/www_tmp
     init: true
     restart: always
     logging: *default-logging

docker-compose.sample.yml

@@ -99,6 +99,7 @@ services:
      - station_data:/var/azuracast/stations
      - shoutcast2_install:/var/azuracast/servers/shoutcast2
      - letsencrypt:/etc/nginx/ssl:ro
+     - tmp_data:/var/azuracast/www_tmp
     init: true
     restart: always
     logging: *default-logging

src/Controller/Traits/LogViewerTrait.php

@@ -105,7 +105,7 @@ trait LogViewerTrait
                 ];
                 $log_paths['icecast_error_log'] = [
                     'name' => __('Icecast Error Log'),
-                    'path' => $station_config_dir.'/icecast_error.log',
+                    'path' => $station_config_dir.'/icecast.log',
                     'tail' => true,
                 ];
                 $log_paths['icecast_xml'] = [
@@ -118,7 +118,7 @@ trait LogViewerTrait
             case Adapters::FRONTEND_SHOUTCAST:
                 $log_paths['shoutcast_log'] = [
                     'name' => __('SHOUTcast Log'),
-                    'path' => $station_config_dir.'/sc_serv.log',
+                    'path' => $station_config_dir.'/shoutcast.log',
                     'tail' => true,
                 ];
                 $log_paths['shoutcast_conf'] = [

src/Entity/Api/Error.php

@@ -8,10 +8,15 @@ use OpenApi\Annotations as OA;
  */
 class Error
 {
-    public function __construct($code = 500, $message = 'General Error', $extra_data = [])
+    public function __construct(
+        $code = 500,
+        $message = 'General Error',
+        $formatted_message = null,
+        $extra_data = [])
     {
         $this->code = (int)$code;
         $this->message = (string)$message;
+        $this->formatted_message = (string)($formatted_message ?? $message);
         $this->extra_data = (array)$extra_data;
         $this->success = false;
     }
@@ -32,6 +37,14 @@ class Error
      */
     public $message;
 
+    /**
+     * The HTML-formatted text description of the error.
+     *
+     * @OA\Property(example="<b>Error description.</b><br>Detailed error text.")
+     * @var string
+     */
+    public $formatted_message;
+
     /**
      * Stack traces and other supplemental data.
      *

src/Entity/Api/Status.php

@@ -9,10 +9,15 @@ use OpenApi\Annotations as OA;
  */
 class Status
 {
-    public function __construct($success = true, $message = 'Changes saved successfully.')
+    public function __construct(
+        $success = true,
+        $message = 'Changes saved successfully.',
+        $formatted_message = null)
     {
         $this->success = (bool)$success;
         $this->message = (string)$message;
+
+        $this->formatted_message = (string)($formatted_message ?? $message);
     }
 
     /**
@@ -26,4 +31,10 @@ class Status
      * @var string
      */
     public $message;
+
+    /**
+     * @OA\Property(example="<b>Changes saved successfully.</b>")
+     * @var string
+     */
+    public $formatted_message;
 }

src/Exception/Supervisor.php

@@ -2,5 +2,4 @@
 namespace App\Exception;
 
 class Supervisor extends \Azura\Exception
-{
-}
+{}

src/Http/ErrorHandler.php

@@ -65,13 +65,12 @@ class ErrorHandler
         $show_detailed = !APP_IN_PRODUCTION && $e_level >= Logger::ERROR;
 
         $e_extra = [];
+        if ($e instanceof \Azura\Exception) {
+            $e_extra['context'] = $e->getLoggingContext();
+            $e_extra = array_merge($e_extra, $e->getExtraData());
+        }
         if ($show_detailed) {
             $e_extra['trace'] = array_slice($e->getTrace(), 0, 5);
-
-            if ($e instanceof \Azura\Exception) {
-                $e_extra['context'] = $e->getLoggingContext();
-                $e_extra = array_merge($e_extra, $e->getExtraData());
-            }
         }
 
         $this->logger->addRecord($e_level, $e->getMessage(), [
@@ -132,6 +131,7 @@ class ErrorHandler
             $api_response = new Entity\Api\Error(
                 $e->getCode(),
                 $e->getMessage(),
+                ($e instanceof \Azura\Exception) ? $e->getFormattedMessage() : $e->getMessage(),
                 $e_extra
             );
 

src/Middleware/GetStation.php

@@ -66,7 +66,7 @@ class GetStation
         } catch (StationNotFound $e) {
             if ($request->isApiCall()) {
                 return $response->withStatus(404)
-                    ->withJson(new Entity\Api\Error(404, $e->getMessage()));
+                    ->withJson(new Entity\Api\Error(404, $e->getMessage(), $e->getFormattedMessage()));
             }
 
             throw $e;

src/Middleware/Permissions.php

@@ -49,7 +49,7 @@ class Permissions
         } catch (PermissionDenied $e) {
             if ($request->isApiCall()) {
                 return $response->withStatus(403)
-                    ->withJson(new Entity\Api\Error(403, $e->getMessage()));
+                    ->withJson(new Entity\Api\Error(403, $e->getMessage(), $e->getFormattedMessage()));
             }
 
             throw $e;

src/Radio/AbstractAdapter.php

@@ -155,6 +155,22 @@ abstract class AbstractAdapter
      */
     abstract public function getProgramName(Entity\Station $station): string;
 
+    /**
+     * Return the path where logs are written to.
+     *
+     * @param Entity\Station $station
+     * @return string
+     */
+     public function getLogPath(Entity\Station $station): string
+     {
+         $config_dir = $station->getRadioConfigDir();
+
+         $class_parts = explode('\\', static::class);
+         $class_name = array_pop($class_parts);
+
+         return $config_dir.'/'.strtolower($class_name).'.log';
+     }
+
     /**
      * Internal handling of any Supervisor-related exception, to add richer data to it.
      *
@@ -172,33 +188,44 @@ abstract class AbstractAdapter
         $class_name = array_pop($class_parts);
 
         if (false !== stripos($e->getMessage(), 'ALREADY_STARTED')) {
+            $e_headline = __('%s cannot start', $class_name);
+            $e_body = __('It is already running.');
+
             $app_e = new \App\Exception\Supervisor\AlreadyRunning(
-                __('%s cannot start; it is already running.', $class_name),
+                $e_headline.'; '.$e_body,
                 $e->getCode(),
                 $e
             );
         } else if (false !== stripos($e->getMessage(), 'NOT_RUNNING')) {
+            $e_headline = __('%s cannot stop', $class_name);
+            $e_body = __('It is not running.');
+
             $app_e = new \App\Exception\Supervisor\NotRunning(
-                __('%s cannot stop; it is not running.', $class_name),
+                $e_headline.'; '.$e_body,
                 $e->getCode(),
                 $e
             );
         } else {
-            $message = (false !== stripos($e->getMessage(), 'SPAWN_ERROR'))
-                ? __('%s encountered an error when starting; check the logs for details.', $class_name)
-                : $class_name.': '.$e->getMessage();
+            $e_headline = __('%s encountered an error', $class_name);
 
-            $app_e = new \App\Exception\Supervisor($message, $e->getCode(), $e);
+            // Get more detailed information for more significant errors.
+            $process_log = $this->supervisor->tailProcessStdoutLog($program_name, 0, 500);
+            $process_log = array_filter(explode("\n", $process_log[0]));
+            $process_log = array_slice($process_log, -6);
+
+            $e_body = (!empty($process_log))
+                ? implode('<br>', $process_log)
+                : __('Check the log for details.');
+
+            $app_e = new \App\Exception\Supervisor($e_headline, $e->getCode(), $e);
+            $app_e->addExtraData('supervisor_log', $process_log);
+            $app_e->addExtraData('supervisor_process_info', $this->supervisor->getProcessInfo($program_name));
         }
 
+        $app_e->setFormattedMessage('<b>'.$e_headline.'</b><br>'.$e_body);
         $app_e->addLoggingContext('station_id', $station->getId());
         $app_e->addLoggingContext('station_name', $station->getName());
 
-        // Get more detailed information for more significant errors.
-        if ($app_e->getLoggerLevel() !== Logger::INFO) {
-            $app_e->addExtraData('Supervisor Process Info', $this->supervisor->getProcessInfo($program_name));
-        }
-
         throw $app_e;
     }
 

src/Radio/Backend/Liquidsoap.php

@@ -95,8 +95,7 @@ class Liquidsoap extends AbstractBackend implements EventSubscriberInterface
         $event->appendLines([
             'set("init.daemon", false)',
             'set("init.daemon.pidfile.path","' . $config_path . '/liquidsoap.pid")',
-            'set("log.file.path","' . $config_path . '/liquidsoap.log")',
-            (APP_INSIDE_DOCKER ? 'set("log.stdout", true)' : ''),
+            'set("log.stdout", true)',
             'set("server.telnet",true)',
             'set("server.telnet.bind_addr","'.(APP_INSIDE_DOCKER ? '0.0.0.0' : '127.0.0.1').'")',
             'set("server.telnet.port", ' . $this->_getTelnetPort($station) . ')',

src/Radio/Configuration.php

@@ -102,20 +102,12 @@ class Configuration
 
         // Write frontend
         if ($frontend->hasCommand($station)) {
-            $this->_writeConfigurationSection($supervisor_config, $frontend_program, [
-                'directory' => $config_path,
-                'command' => $frontend->getCommand($station),
-                'priority' => 90,
-            ]);
+            $supervisor_config[] = $this->_writeConfigurationSection($station, $frontend, 90);
         }
 
         // Write backend
         if ($backend->hasCommand($station)) {
-            $this->_writeConfigurationSection($supervisor_config, $backend_program, [
-                'directory' => $config_path,
-                'command' => $backend->getCommand($station),
-                'priority' => 100,
-            ]);
+            $supervisor_config[] = $this->_writeConfigurationSection($station, $backend, 100);
         }
 
         // Write config contents
@@ -125,28 +117,34 @@ class Configuration
         $this->_reloadSupervisorForStation($station, $force_restart);
     }
 
-    protected function _writeConfigurationSection(&$supervisor_config, $program_name, $config_lines): void
+    protected function _writeConfigurationSection(
+        Station $station,
+        AbstractAdapter $adapter,
+        $priority): string
     {
-        $defaults = [
+        $config_path = $station->getRadioConfigDir();
+
+        [,$program_name] = explode(':', $adapter->getProgramName($station));
+
+        $config_lines = [
             'user' => 'azuracast',
-            'priority' => 100,
+            'priority' => $priority,
+            'command' => $adapter->getCommand($station),
+            'directory' => $config_path,
+            'stdout_logfile' => $adapter->getLogPath($station),
+            'stdout_logfile_maxbytes' => '5MB',
+            'stdout_logfile_backups' => '10',
+            'redirect_stderr' => 'true',
         ];
 
-        if (APP_INSIDE_DOCKER) {
-            $defaults['stdout_logfile'] = '/dev/stdout';
-            $defaults['stdout_logfile_maxbytes'] = 0;
-            $defaults['stderr_logfile'] = '/dev/stderr';
-            $defaults['stderr_logfile_maxbytes'] = 0;
-        }
-
         $supervisor_config[] = '[program:' . $program_name . ']';
-        $config_lines = array_merge($defaults, $config_lines);
 
         foreach($config_lines as $config_key => $config_value) {
             $supervisor_config[] = $config_key . '=' . $config_value;
         }
 
         $supervisor_config[] = '';
+        return implode("\n", $supervisor_config);
     }
 
     /**

src/Radio/Frontend/Icecast.php

@@ -235,7 +235,7 @@ class Icecast extends AbstractFrontend
             ],
             'logging' => [
                 'accesslog' => 'icecast_access.log',
-                'errorlog' => 'icecast_error.log',
+                'errorlog' => '/dev/stderr',
                 'loglevel' => (APP_IN_PRODUCTION) ? self::LOGLEVEL_WARN : self::LOGLEVEL_INFO,
                 'logsize' => 10000,
             ],

src/Radio/Frontend/SHOUTcast.php

@@ -182,7 +182,7 @@ class SHOUTcast extends AbstractFrontend
         $defaults = [
             'password' => Utilities::generatePassword(),
             'adminpassword' => Utilities::generatePassword(),
-            'logfile' => $config_path . '/sc_serv.log',
+            'logfile' => '/dev/stdout',
             'w3clog' => $config_path . '/sc_w3c.log',
             'banfile' => $config_path . '/sc_serv.ban',
             'ripfile' => $config_path . '/sc_serv.rip',

src/Sync/Task/RotateLogs.php

@@ -75,58 +75,9 @@ class RotateLogs extends AbstractTask
      */
     public function rotateStationLogs(Entity\Station $station): void
     {
-        $this->_rotateLiquidsoapLog($station);
         $this->_cleanUpIcecastLog($station);
     }
 
-    /**
-     * @param Entity\Station $station
-     * @throws Rotate\FilenameFormatException
-     * @throws \App\Exception\NotFound
-     */
-    protected function _rotateLiquidsoapLog(Entity\Station $station): void
-    {
-        if ($station->getBackendType() !== Adapters::BACKEND_LIQUIDSOAP) {
-            return;
-        }
-
-        $log_context = [
-            'id' => $station->getId(),
-            'name' => $station->getName(),
-        ];
-
-        /** @var Liquidsoap $backend_adapter */
-        $backend_adapter = $this->adapters->getBackendAdapter($station);
-
-        try
-        {
-            $config_path = $station->getRadioConfigDir();
-
-            $rotate = new Rotate\Rotate($config_path . '/liquidsoap.log');
-            $rotate->keep(5);
-            $rotate->size('5MB');
-            $rotate->run();
-        }
-        catch(Rotate\RotateException $e)
-        {
-            $this->logger->error('Log rotation exception: '.$e->getMessage(), $log_context);
-            return;
-        }
-
-        try
-        {
-            // Send the "USR1" signal to Liquidsoap via Supervisord to have it update its log pointer.
-            $backend_supervisor_name = $backend_adapter->getProgramName($station);
-
-            $this->supervisor->signalProcess($backend_supervisor_name, 'USR1');
-        }
-        catch(\Exception $e)
-        {
-            $this->logger->error('Supervisor exception: '.$e->getMessage(), $log_context);
-            return;
-        }
-    }
-
     protected function _cleanUpIcecastLog(Entity\Station $station): void
     {
         $config_path = $station->getRadioConfigDir();
@@ -137,7 +88,7 @@ class RotateLogs extends AbstractTask
             ->files()
             ->in($config_path)
             ->name('icecast_*.log.*')
-            ->date('before 1 week ago');
+            ->date('before 1 month ago');
 
         foreach($finder as $file)
         {

templates/stations/profile/index.js.phtml

@@ -91,30 +91,35 @@ $(function() {
     var is_first_load = true;
 
     function checkServiceStatus() {
-        $.getJSON('<?=$router->fromHere('api:stations:status') ?>', function(data) {
-            var backend_status = $('#backend_status');
-            backend_status.removeClass('text-success text-danger');
+        $.ajax({
+            cache: false,
+            dataType: "json",
+            url: '<?=$router->fromHere('api:stations:status') ?>',
+            success: function(data) {
+                var backend_status = $('#backend_status');
+                backend_status.removeClass('text-success text-danger');
 
-            if (data.backend_running) {
-                backend_status.addClass('text-success').text(service_status_lang.running);
-            } else {
-                backend_status.addClass('text-danger').text(service_status_lang.not_running);
-            }
+                if (data.backend_running) {
+                    backend_status.addClass('text-success').text(service_status_lang.running);
+                } else {
+                    backend_status.addClass('text-danger').text(service_status_lang.not_running);
+                }
 
-            var frontend_status = $('#frontend_status');
-            frontend_status.removeClass('text-success text-danger');
+                var frontend_status = $('#frontend_status');
+                frontend_status.removeClass('text-success text-danger');
 
-            if (data.frontend_running) {
-                frontend_status.addClass('text-success').text(service_status_lang.running);
-            } else {
-                frontend_status.addClass('text-danger').text(service_status_lang.not_running);
-            }
+                if (data.frontend_running) {
+                    frontend_status.addClass('text-success').text(service_status_lang.running);
+                } else {
+                    frontend_status.addClass('text-danger').text(service_status_lang.not_running);
+                }
 
-            if (is_first_load) {
-                setTimeout(checkServiceStatus, 5000);
-                is_first_load = false;
-            } else {
-                setTimeout(checkServiceStatus, 15000);
+                if (is_first_load) {
+                    setTimeout(checkServiceStatus, 5000);
+                    is_first_load = false;
+                } else {
+                    setTimeout(checkServiceStatus, 15000);
+                }
             }
         }).fail(function() {
             setTimeout(checkServiceStatus, 30000);

templates/stations/sidebar.js.phtml

@@ -23,11 +23,11 @@ $(function() {
                 }
 
                 var notify_type = (data.success) ? 'success' : 'warning';
-                notify(data.message, notify_type);
+                notify(data.formatted_message, notify_type);
             },
             error: function(response) {
                 data = jQuery.parseJSON(response.responseText);
-                notify(data.message, 'danger');
+                notify(data.formatted_message, 'danger');
 
                 btn.removeClass('disabled').html(btn_original_text);
             },