Issue #2828630: More verbose drush logs for drush hosting-tasks command

Author: jonpugh

queued/hosting_queued.drush.inc

@@ -62,7 +62,7 @@ function drush_hosting_queued() {
   variable_set('hosting_queued_process_started', REQUEST_TIME);
 
   watchdog('hosting_queued', 'Started Hosting queue daemon, waiting for new tasks');
-
+  drush_log('Started hosting queue daemon. Waiting for new tasks.', 'ok');
   while (TRUE) {
     try {
       // Should we terminate.
@@ -74,6 +74,11 @@ function drush_hosting_queued() {
 
     // Get some tasks to run
     if ($tasks = @_hosting_get_new_tasks()) {
+
+      drush_log(dt("Found %count tasks in queue. Running...", array(
+        '%count' => count($tasks),
+      )), "notice");
+
       if (lock_acquire('hosting_queue_tasks_running', HOSTING_QUEUE_LOCK_TIMEOUT)) {
         drush_log('Acquired lock on task queue.');
         foreach ($tasks as $task) {
@@ -85,10 +90,8 @@ function drush_hosting_queued() {
           drush_log(dt('Found task to execute. Pausing before execution.'));
           sleep(1);
 
-          watchdog('hosting_queued', 'Running task @nid.', array('@nid' => $task->nid));
-          // Execute the task in the backend
-          drush_invoke_process('@self', 'hosting-task', array($task->nid), array('strict' => FALSE), array('interactive' => TRUE));
-          drush_log(dt('Finished executing task.'));
+          // Execute the task.
+          hosting_task_execute($task, array('interactive' => TRUE));
 
           // Delay for a configurable amount of time.
           $delay = variable_get('hosting_queued_post_task_delay', 0);

task/hosting_task.module

@@ -723,10 +723,60 @@ function hosting_task_set_title(&$node) {
 function hosting_tasks_queue($count = 20) {
   global $provision_errors;
 
-  drush_log(dt("Running tasks queue"));
   $tasks = _hosting_get_new_tasks($count);
+
+  if (count($tasks)) {
+    drush_log(dt("Found @count tasks (max @max) in queue. Running...", array(
+      '@count' => count($tasks),
+      '@max' => $count,
+    )), "notice");
+  }
+  else {
+    drush_log(dt("Found no tasks in queue. Not running."), "notice");
+  }
+
   foreach ($tasks as $task) {
-    drush_invoke_process('@self', "hosting-task", array($task->nid), array('strict' => FALSE), array('fork' => TRUE));
+    hosting_task_execute($task, array('fork' => TRUE));
+  }
+}
+
+/**
+ * Executes a task while logging to watchdog and drush.
+ *
+ * @param $task
+ *   A fully loaded task node.
+ */
+function hosting_task_execute($task, $backend_options = array()) {
+  // Log in watchdog and drush.
+  watchdog('hosting_task', 'Starting task "@title" [node/@nid].', array(
+    '@title' => $task->title,
+    '@nid' => $task->nid,
+  ), WATCHDOG_NOTICE, url("node/$task->nid"));
+  drush_log(dt('Starting task "@title" [node/@nid].', array(
+    '@title' => $task->title,
+    '@nid' => $task->nid,
+  )), 'ok');
+
+  // Execute in it's own process.
+  drush_invoke_process('@self', "hosting-task", array($task->nid), array('strict' => FALSE), $backend_options);
+
+  // Log a message, depending on forked process or not.
+  // If forked, the process may not have completed yet, so we should change the message.
+  if ($backend_options['fork']) {
+    drush_log(dt('Launched task "@title" in a forked process. [node/@nid]', array(
+      '@title' => $task->title,
+      '@nid' => $task->nid,
+    )), 'ok');
+  }
+  // If not forked, load and display the task status.
+  else {
+    $task = node_load($task->nid, NULL, TRUE);
+    drush_log(dt('Finished task "@title" with status "@status" in @duration [node/@nid].', array(
+      '@title' => $task->title,
+      '@nid' => $task->nid,
+      '@status' => _hosting_parse_error_code($task->task_status),
+      '@duration' => format_interval($task->delta, 1),
+    )), 'ok');
   }
 }