Improve logging when performing site updates

[pfrenssen]

Here is an example log output I pulled from one of our test servers:

    [drush] Executing command: /srv/project/vendor/bin/drush --root="/srv/project/web" --yes updatedb 
 ----------- ------------------ ------------- ---------------------------------  
  Module      Update ID          Type          Description                       
 ----------- ------------------ ------------- ---------------------------------  
  collectio   show_events_face   post-update   Updates the collection content    
  n           t                                field to show the events facet.   
  joinup_co   install_joinup_i   post-update   Enable the Joinup Invite          
  re          nvite                            module.                           
  joinup_co   install_smart_tr   post-update   Enable the Smart Trim module.     
  re          im                                                                 
  joinup_co   move_contact_for   post-update   Move the contact form             
  re          m_attachments                    attachments under the private     
                                               scheme.                           
  joinup_di   enable_changed_f   post-update   Enable the Changed Fields API     
  scussion    ields                            module.                           
  joinup_mi   copy_about_text_   post-update   Copy the about text to            
  grate       ctt_spain                        distributions for CTT Spain       
                                               [ISAICP-4057].                    
  joinup_mi   same_name_distri   post-update   Fix distribution files with the   
  grate       bution_files                     same name [ISAICP-3968].          
  joinup_su   install_flag       post-update   Install the 'flag' module.        
  bscriptio                                                                      
  n                                                                              
  joinup_us   add_subscribe_di   post-update   Adds permissions to subscribe     
  er          scussion_permiss                 to discussions for                
              ions                             authenticated users.              
 ----------- ------------------ ------------- ---------------------------------  
 
 // Do you wish to run the specified pending updates?: yes.                      
 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Could not apply Half width image style to  because the style does not support it. 
 [warning] Could not apply Full width image style to  because the style does not support it. 
 [warning] Missing file with ID 508501. ImageItem.php:328 
 [ok] Post updating collection 
 [ok] Post updating joinup_core 
 [ok] Post updating joinup_core 
 [ok] Post updating joinup_core 
 [ok] Post updating joinup_discussion 
 [ok] Post updating joinup_migrate 
 [ok] Post updating joinup_migrate 
 [ok] Post updating joinup_subscription 
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [warning] Illegal string offset 'query' UpdateDBCommands.php:374 
 [notice] D 
 [notice]  
 [warning] Illegal string offset 'query' UpdateDBCommands.php:374 
 [notice] C 
 [notice]  
 [notice]  
 [notice]  
 [notice]  
 [notice]  
Array   Array   Array   Array   Array   Array 
 [success] Cache rebuild complete. 
 [success] Finished performing updates. 

The log shows evidence of bugs in the update command, and the existing output can be improved:

• The name of the post_update hook that is being executed is not output. Instead it outputs the name of the module that contains the hooks repeatedly.
• There are a bunch of empty notices being output.
• Some puzzling notices that contain single letters (D and C).
• PHP warnings Illegal string offset 'query' UpdateDBCommands.php:374.
• Array Array Array ... ??
• The final line proclaims that the updates were finished successfully but this is not correct, an error occurred during one of the updates, and the last one was not even executed. The log should reflect this information.

[pfrenssen]

Starting on this by running the existing test suite. Here is the raw output of UpdateDBTest::testFailedUpdate():

 -------- ----------- --------------- ---------------------- 
  Module   Update ID   Type            Description           
 -------- ----------- --------------- ---------------------- 
  woot     8101        hook_update_n   Good update.          
  woot     8102        hook_update_n   Failing update.       
  woot     failing     post-update     Failing post-update.  
 -------- ----------- --------------- ---------------------- 

 // Do you wish to run the specified pending updates?: yes.                     

Array	Array

And the raw STDERR output:

 [notice] Executing woot_update_8101
 [ok] Performing woot_update_8101
 [notice] Executing woot_update_8102
 [error]  8102 error 
 [ok] Performing woot_update_8102
 [notice] woot_update_8101
 [error]  Failed batch process: woot_update_8102 
 [error]  Finished performing updates. 

What is already apparent from running this test:

• The Array Array output is present here in the STDOUT, so we can easily extend this test to make sure this doesn't happen. -> fixed in Improve logging for the UpdateDB commands #3300
• The command already fails after woot_update_8002() as is expected. It also checks the error code and this appears to work fine. However this also means that the failing post update hook is never executed. We need a separate test for this so we can check if this also returns the correct error code.
• The output from STDERR is very confusing:
  • There appears to be duplicated information about "executing" and "performing" each individual update. -> fixed in Improve the log of the updatedb command #3303
  • [ok] Performing woot_update_8102 is output AFTER the error occurs?? -> fixed in Improve the log of the updatedb command #3303
  • [notice] woot_update_8101 is output AFTER update 8101 has been completed and update 8102 has been started? -> fixed in Update messages are logged in the wrong order #3302.
  • Update 8102 failed, so there should not be any [ok] associated with it. -> fixed in Improve the log of the updatedb command #3303
  • Minor, but also a possible improvement: it shouldn't mention that the "batch process" failed. That the batch API is used behind the scenes is an implementation detail and not important to mention in the log output. -> fixed in Improve the log of the updatedb command #3303

[weitzman]

@pfrenssen has everything here been addressed?

[pfrenssen]

Yes this is all covered, this can be closed.