Forum OpenACS Improvement Proposals (TIPs): Display errors that occurred while sourcing a file in APM package-reload page.

I implemented a patch that will gather and display errors that occur while reloading a package's source files using the APM. The mechanism can also be used to hilight packages in the APM package list which did not load all of their files properly (though that feature is not part of this patch).

Implementation Overview:

The implementation adds 2 new global variables in packages/acs-bootstrap-installer/tcl/30-apm-load-procs.tcl that are shared by all interpreters: apm_package_load_errors, and apm_load_errors_lock. If any interpreter encounters an error while sourcing a file, it will lappend'd the file-name and error message into the apm_package_load_errors shared-array using the package_key. The apm_load_errors_lock variable is a mutex used to make sure reads and writes to the shared-array are consistent.

The packages/acs-admin/www/apm/version-reload.tcl page TCL is modified to read from these variables and present their output next to the specific files with the errors. It is also modified to apm_source the changed files right away (using apm_load_any_changed_libraries) so that error messages can be immediately displayed. Without this, there would be a race between the apm_load_any_changed_libraries processing done in other interpreters and the page-building in the request-serving interpreter. The result of the race could be 1 of 3 outcomes: no error message being displayed, a partial list of error messages, or all of the error messages.

The packages/acs-admin/www/apm/version-reload.adp page ADP is modified to put the error messages into the output with an appropriate style. The full error messages are hidden and can be revealed by clicking on a short piece of text indicating that an error occurred on a particular file.

Testing:

To test the code, apply the patch, restart your server, and then insert a "{" at the end of a TCL file in any package. When you reload that package in the APM, you should see an indication that an error occurred while loading that file. You should then be able to click on the error indicator to see the full text of the error.

The Patch:

---

Index: packages/acs-admin/www/apm/version-reload.tcl
===================================================================
--- packages/acs-admin/www/apm/version-reload.tcl
+++ packages/acs-admin/www/apm/version-reload.tcl
@@ -23,7 +23,16 @@
 if { [llength $files] == 0 } {
     append body "There are no changed files to reload in this package.<p>"
 } else {
-    append body "Marked the following file[ad_decode [llength $files] 1 "" "s"] for reloading:<ul>\n"
+    append body "Marked the following file[ad_decode [llength $files] 1 "" "s"] for reloading:<ul id='files'>\n"
+
+    # Source all of the marked files using the current interpreter, accumulating
+    # errors into apm_package_load_errors
+    catch { apm_load_any_changed_libraries }
+
+    if {[nsv_exists apm_package_load_errors $package_key]} {
+	array set load_errors [nsv_get apm_package_load_errors $package_key]
+    }
+
     foreach file $files {
 	append body "<li>$file"
 	if { [nsv_exists apm_reload_watch $file] } {
@@ -38,9 +47,23 @@
 	    append body " (<a href=\"file-watch?[export_vars { version_id { paths $local_path } }]\">watch this file</a>)"
             lappend files_to_watch $local_path
 	}
-	append body "\n"
+
+	if {[info exists load_errors($file)]} {
+	    append body "<dl class='error'><dt title='click to see details'>ERROR! (click for details)</dt><dd><code><pre>$load_errors($file)</pre></code></dd></dl>"
+	}
+	append body "</li>\n"
     }
     append body "</ul>\n"
+
+    if {[array exists load_errors]} {
+	set n_errors [array size load_errors]
+	append body "
+		<p><strong style='color:red;font-size:112.5%;'>$n_errors files
+		had errors that prevented complete reloading</strong>.  Fix the
+		problem, then reload the package again to finish the reload.
+		</p>
+	"
+    }
 }
 
 
Index: packages/acs-admin/www/apm/version-reload.adp
===================================================================
--- packages/acs-admin/www/apm/version-reload.adp
+++ packages/acs-admin/www/apm/version-reload.adp
@@ -2,4 +2,19 @@
 <property name="title">@page_title;noquote@</property>
 <property name="context">@context;noquote@</property>
 
+<style type="text/css">
+  dl.error, dl.error dt { display:inline; color:red; }
+  dl.error dt { font-weight:bold; }
+  dl.error    { margin-left:1em; cursor:pointer; }
+  dl.error dd { display:none; }
+</style>
 @body;noquote@
+<script type="text/javascript">
+  <% template::head::add_javascript -src "//ajax.googleapis.com/ajax/libs/jquery/1.11.1/jquery.min.js" %>
+  $('#files dd').click(function () {
+	$(this).slideToggle();
+  });
+  $('#files dt').click(function () {
+	$(this.nextElementSibling).slideToggle();
+  });
+</script>
Index: packages/acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
===================================================================
--- packages/acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
+++ packages/acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
@@ -7,9 +7,9 @@
     @cvs-id $Id: 30-apm-load-procs.tcl,v 1.41.2.1 2013/08/24 15:27:25 gustafn Exp $
 }
 
-# FIXME: Peter M - This file cannot be watched with the APM as it re-initializes 
-# the reload level to 0 everytime it is sourced. Could we move these initialization 
-# to an -init.tcl file instead?
+# FIXME: Peter M - This file cannot be watched with the APM as it re-initializes
+# the reload level to 0 and creates a new mutex everytime it is sourced. Could
+# we move these initialization to an -init.tcl file instead?
 
 # Initialize loader NSV arrays. See apm-procs.tcl for a description of
 # these arrays.
@@ -17,6 +17,8 @@
 nsv_array set apm_version_procs_loaded_p [list]
 nsv_array set apm_reload_watch [list]
 nsv_array set apm_package_info [list]
+nsv_array set apm_package_load_errors [list]
+nsv_set apm_load_errors_lock _ [ns_mutex create apm_load_errors_lock]
 nsv_set apm_properties reload_level 0
 
 ad_proc apm_first_time_loading_p {} { 
@@ -383,19 +385,52 @@
     apm_library_mtime
 } {
     if { ![file exists $__file] } {
-		ns_log "Error" "Unable to source $__file: file does not exist."
+	ns_log "Error" "Unable to source $__file: file does not exist."
 	return 0
     }
 
+    regexp {/packages/([^/]+)/} $__file -> package_key
+
+    set r_file [ad_make_relative_path $__file]
+
     # Actually do the source.
     if { [catch { source $__file }] } {
 	global errorInfo
-		ns_log "Error" "Error sourcing $__file:\n$errorInfo"
+	ns_log "Error" "Error sourcing $__file:\n$errorInfo"
+	ns_mutex lock [nsv_get apm_load_errors_lock _]
+	nsv_lappend apm_package_load_errors $package_key $r_file $errorInfo
+	ns_mutex unlock [nsv_get apm_load_errors_lock _]
 	return 0
+    } elseif {[info exists package_key] && $package_key ne ""} {
+	ns_mutex lock [nsv_get apm_load_errors_lock _]
+	if {[nsv_exists apm_package_load_errors $package_key]} {
+	    # File sourced successfully.  Remove it from the list of package
+	    # files that caused errors if it is in that list.  Remove that
+	    # list if it is empty.
+	    set package_errors	[nsv_get apm_package_load_errors $package_key]
+	    set n_errors	[llength $package_errors]
+	    if {$n_errors > 0} {
+		set file_pos 0
+		while {$file_pos >= 0} {
+		    set file_pos [lsearch -exact $package_errors $r_file]
+		    if {$file_pos < 0} break
+		    # Found the file in the errors list.  Remove it and the
+		    # corresponding errorInfo from the list.
+		    set package_errors [lreplace $package_errors $file_pos [expr {$file_pos+1}]]
+		}
+	    }
+	    if {[llength $package_errors] < 1} {
+		# All errors were removed.  Removed the list from the nsv.
+		nsv_unset apm_package_load_errors $package_key
+	    } elseif {[llength $package_errors] < $n_errors} {
+		# Some errors were removed.  Update the list in the nsv.
+		nsv_set apm_package_load_errors $package_key $package_errors
+	    }
+	}
+	ns_mutex unlock [nsv_get apm_load_errors_lock _]
     }
 
-    nsv_set apm_library_mtime [ad_make_relative_path $__file] [file mtime $__file]    
-
+    nsv_set apm_library_mtime $r_file] [file mtime $__file]
     return 1
 }

The only thing I don't like about the patch is that it has 1 lock that is used in a lock/unlock cycle for every file that is sourced. It would be better if it could be re-worked to have 1 lock per package. This might mean something like passing errors out of the proc up to the caller so the caller can accumulate the errors into a per-package array/list. The biggest difficulty with that is probably in initializing 1 lock per package (nsv_set apm_load_errors_lock $package_key [ns_mutex create apm_load_errors_${package_key}_lock]).

The patch already only creates one mutex (in the same way as other APM bootstrap mutexes are created). The mutex is not held when sourceing package code. It is only held around an nsv_lappend invocation or when removing past error-messages from the list, as those are 2 places where a modification to a shared variable occurs.

The patch already only creates one mutex...

hmm, i thought your concern was that multiple mutexes are created, when packages/acs-bootstrap-installer/tcl/30-apm-load-procs.tcl is sourced multiple times. To avoid this, the correct approach is as noted above.

apm_source is used from all connection threads to pick up the changed files. I would think that in acs-admin/www/apm/version-reload one is not interested about what happens in various threads but just in the errors of the reloaded files. Wouldn't it be much easier the get this information directly in acs-admin/www/apm/version-reload? One could provide e.g. an optional variable name to apm_source with the effect that in case of an error this variable is set. One could use something in the lines of

 if {[apm_source $file err] == 0]} {... do something with $err ...}

in acs-admin/www/apm/version-reload.

This path looks more straightforward to me than going into more and more locking.

That patch has some errors. One is due to hand-quoting the HTML embedded in the patch (see this bug):

+  <% template::head::add_javascript -src "//ajax.googleapis.com/ajax/libs/jquery/1.11.1/jquery.min.js" %<

…should be:

+  <% template::head::add_javascript -src "//ajax.googleapis.com/ajax/libs/jquery/1.11.1/jquery.min.js" %>

Not sure if any more of those remain, so caveat emptor.

Also, it occurs to me that, as was expected in the 1st patch in the thread, apm_load_any_changed_libraries will load new code without any attention to package boundaries, so set errors($r_file) $errorInfo needs to be lappend errors($package_key) $r_file $errorInfo with suitable code for getting the package_key from the full file name. This means a number of changes to the patch chunk for acs-admin/www/apm/version-reload.tcl as well.

The patch (fixes in green)

---

Index: acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
===================================================================
--- acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
+++ acs-bootstrap-installer/tcl/30-apm-load-procs.tcl
@@ -377,25 +379,33 @@
     return [expr ![file exists "${package_path}/sql"] || [file exists "${package_path}/sql/[db_type]"]]
 }
 
-ad_proc -private apm_source { __file } {
+ad_proc -private apm_source { __file {error_set_name ""}} {
     Sources $__file in a clean environment, returning 1 if successful or 0 if not.
     Records that the file has been sourced and stores its mtime in the nsv array
     apm_library_mtime
 } {
+    if {$error_set_name ne ""} {
+	upvar $error_set_name errors
+    } else {
+	array set errors [list]
+    }
+
     if { ![file exists $__file] } {
		ns_log "Error" "Unable to source $__file: file does not exist."
 	return 0
     }
 
+    set r_file [ad_make_relative_path $__file]
+
     # Actually do the source.
     if { [catch { source $__file }] } {
 	global errorInfo
		ns_log "Error" "Error sourcing $__file:\n$errorInfo"
+	set package_key ""
+	regexp {/packages/([^/]+)/} $__file -> package_key
+	lappend errors($package_key) $r_file $errorInfo
 	return 0
     }
 
-    nsv_set apm_library_mtime [ad_make_relative_path $__file] [file mtime $__file]    
+    nsv_set apm_library_mtime $r_file [file mtime $__file]

     return 1
 }



Index: acs-bootstrap-installer/tcl/40-db-query-dispatcher-procs.tcl
===================================================================
--- acs-bootstrap-installer/tcl/40-db-query-dispatcher-procs.tcl
+++ acs-bootstrap-installer/tcl/40-db-query-dispatcher-procs.tcl
@@ -217,14 +217,24 @@
 #
 ################################################
 
-ad_proc -public db_qd_load_query_file {file_path} {
+ad_proc -public db_qd_load_query_file {file_path {error_set_name ""}} {
     A procedure that is called from the outside world (APM) 
     to load a particular file
 } { 
+    if {$error_set_name ne ""} {
+	upvar $error_set_name errors
+    } else {
+	array set errors [list]
+    }
+
     if { [catch {db_qd_internal_load_cache $file_path} errmsg] } {
         global errorInfo
         ns_log Error "Error parsing queryfile $file_path:\n\n$errmsg\n\n$errorInfo"
+	set r_file [ad_make_relative_path $file_path]
+	set package_key ""
+	regexp {/packages/([^/]+)/} $file_path -> package_key
+	lappend errors($package_key) $r_file $errorInfo
     }
 }



Index: acs-tcl/tcl/apm-procs.tcl
===================================================================
--- acs-tcl/tcl/apm-procs.tcl
+++ acs-tcl/tcl/apm-procs.tcl
@@ -739,7 +739,7 @@
     " -default "all" -bind [list db_type $db_type]]]
 }
 
-ad_proc -public apm_load_any_changed_libraries {} {
+ad_proc -public apm_load_any_changed_libraries {{error_set_name {}}} {
     
     In the running interpreter, reloads files marked for reload by
     apm_mark_version_for_reload. If any watches are set, examines watched
@@ -748,6 +748,10 @@
     before any filters or registered procedures are applied).
 
 } {
+    if {$error_set_name ne ""} {
+	upvar $error_set_name errors
+    } else {
+	array set errors [list]
+    }
+
     # Determine the current reload level in this interpreter by calling
     # apm_reload_level_in_this_interpreter. If this fails, we define the reload level to be
     # zero.
@@ -807,12 +811,12 @@
                         # Make sure this is not a -init.tcl file as those should only be sourced on server startup
                         if { ![regexp {\-init\.tcl$} $file_path] } {
                             ns_log Notice "apm_load_any_changed_libraries: Reloading $file..."
-                            apm_source $file_path
+                            apm_source $file_path errors
                         }
                     }
                     .xql { 
                         ns_log Notice "apm_load_any_changed_libraries: Reloading $file..."
-                        db_qd_load_query_file $file_path
+                        db_qd_load_query_file $file_path errors
                     }
                     default {
                         ns_log Notice "apm_load_any_changed_libraries: File $file_path has unknown extension. Not reloading."



Index: acs-admin/www/apm/version-reload.tcl
===================================================================
--- acs-admin/www/apm/version-reload.tcl
+++ acs-admin/www/apm/version-reload.tcl
@@ -23,7 +23,13 @@
 if { [llength $files] == 0 } {
     append body "There are no changed files to reload in this package.<p>"
 } else {
-    append body "Marked the following file[ad_decode [llength $files] 1 "" "s"] for reloading:<ul>\n"
+    append body "Marked the following file[ad_decode [llength $files] 1 "" "s"] for reloading:<ul id='files'>\n"
+
+    # Source all of the marked files using the current interpreter, accumulating
+    # errors into apm_package_load_errors
+    array set errors [list]
+    catch { apm_load_any_changed_libraries errors}
+
+    if {[info exists errors($package_key)]} {
+ 	array set package_errors $errors($package_key)
+    } else {
+ 	array set package_errors [list]
+    }
+
     foreach file $files {
 	append body "<li>$file"
 	if { [nsv_exists apm_reload_watch $file] } {
@@ -38,9 +44,29 @@
 	    append body " (<a href=\"file-watch?[export_vars { version_id { paths $local_path } }]\">watch this file</a>)"
             lappend files_to_watch $local_path
 	}
-	append body "\n"
+
+	if {[info exists package_errors($file)]} {
+	    append body "<dl class='error'><dt title='click to see details'>ERROR! (click for details)</dt><dd><code><pre>[ad_quotehtml $package_errors($file)]</pre></code></dd></dl>"
+	}
+	append body "</li>\n"
     }
     append body "</ul>\n"
+
+    set n_errors [array size package_errors]
+    if {$n_errors > 0} {
+	if {$n_errors != 1} {
+	    set exist_n_error_files "were $n_errors files"
+	} else {
+	    set exist_n_error_files "was $n_errors file"
+	}
+	append body "
+		<p><strong style='color:red;font-size:112.5%;'>There
+		$exist_n_error_files with errors that prevented complete
+		reloading</strong>.  Fix the problem, then reload the
+		package again to finish the reload.
+		</p>
+	"
+    }
 }



Index: acs-admin/www/apm/version-reload.adp
===================================================================
--- acs-admin/www/apm/version-reload.adp
+++ acs-admin/www/apm/version-reload.adp
@@ -2,4 +2,19 @@
 <property name="title">@page_title;noquote@</property>
 <property name="context">@context;noquote@</property>
 
+<style type="text/css">
+  dl.error, dl.error dt { display:inline; color:red; }
+  dl.error dt { font-weight:bold; }
+  dl.error    { margin-left:1em; cursor:pointer; }
+  dl.error dd { display:none; }
+</style>
 @body;noquote@
+<script type="text/javascript">
+  <% template::head::add_javascript -src "//ajax.googleapis.com/ajax/libs/jquery/1.11.1/jquery.min.js" %>
+  $('#files dd').click(function () {
+	$(this).slideToggle();
+  });
+  $('#files dt').click(function () {
+	$(this.nextElementSibling).slideToggle();
+  });
+</script>