Forum OpenACS Development: apm_package_instantiate_and_mount triggers QD bug?
I can install and play with OpenACS4 on this system now. However, in trying to get the auto-install.tcl non-interactive installer working I have found an interesting bug which I'm not sure how to track down further.
Essentially, calling the TCL function apm_package_instantiate_and_mount always generates a non-parseable db_0or1row query. The parser error message refers to "$1", which sounds like it might be a QD thing??
I turned on debug in nsd.tcl and generated masses of logfile output which still didn't show me the SQL from the failing query, beyond a plpgsql query which calls other plpgsql functions...
Here's the short testing.tcl file which reliably causes this.
ns_write "HTTP/1.0 200 OK Content-Type: text/html <title>test</title><body> <H1>Mounting packages</H1><p><pre><blockquote>" ns_log Notice "JM_IS_TESTING2: Testing2 started." ns_write " <p>Will try to instantiate and mount pkg key: page</p> <p>" ns_log Notice "JM_IS_TESTING2: Will try to instantiate and mount pkg key: page" apm_package_instantiate_and_mount -callback apm_ns_write_callback page ns_write "</blockquote></pre><p>Done.</p>" ns_log Notice "JM_IS_TESTING2: Test completed." db_release_unused_handles ns_write "<p><strong>Testing Complete.</strong></p></body></html>"
It has wrapped in a couple of places where it isn't supposed to... grrrr. And here is the AOLserver log file output, also abominably wrapped:
[27/Aug/2001:02:40:55][30817.4101][-conn0-] Notice: JM_IS_TESTING2: Testing2 started. [27/Aug/2001:02:40:55][30817.4101][-conn0-] Notice: JM_IS_TESTING2: Will try to instantiate and mount pkg key: page [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = calling namespace = [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = proc_name is -apm_package_instantiate_and_mount- [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = tcl file is packages/acs-tcl/tcl/apm-install-procs.tcl [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = TEMP - QD: proc_name is apm_package_instantiate_and_mount [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = TEMP - QD: local_name is package_instantiate_and_mount [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = generated fullname of dbqd.acs-tcl.tcl.apm-install-procs.apm_package_instantiate_and_mount.package_instantiate_and_mount [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = query dbqd.acs-tcl.tcl.apm-install-procs.apm_package_instantiate_and_mount.package_instantiate_and_mount from /var/lib/aolserver/servers/openacs4/packages/acs-tcl/tcl/apm-inst all-procs-postgresql.xql [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = PLPGSQL: using anonymous function [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = PRE-QD: the SQL is declare main_site_id site_nodes.node_id%TYPE; instance_id apm_packages.package_id%TYPE; node_id site_nodes.node_id%TYPE; begin main_site_id := site_node.node_id('/'); instance_id := apm_package.new( package_key => :package_key, context_id => main_site_id ); node_id := site_node.new( parent_id => main_site_id, name => :package_key, directory_p => 't', pattern_p => 't', object_id => instance_id ); end; [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = query dbqd.acs-tcl.tcl.apm-install-procs.apm_package_instantiate_and_mount.package_instantiate_and_mount from /var/lib/aolserver/servers/openacs4/packages/acs-tcl/tcl/apm-inst all-procs-postgresql.xql [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = POST-QD: the SQL is declare main_site_id site_nodes.node_id%TYPE; instance_id apm_packages.package_id%TYPE; node_id site_nodes.node_id%TYPE; begin main_site_id := site_node__node_id('/',null); instance_id := apm_package__new( null, null, :package_key, 'apm_package', now(), null, null, main_site_id ); node_id := site_node__new( null main_site_id, :package_key, instance_id, 't', 't', null, null ); return null; end; [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = calling namespace = [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = proc_name is -db_nextval- [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = tcl file is packages/acs-tcl/tcl/00-database-procs-postgresql.tcl [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = TEMP - QD: proc_name is db_nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = TEMP - QD: local_name is nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = generated fullname of dbqd.acs-tcl.tcl.00-database-procs-postgresql.db_nextval.nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = PRE-QD: the SQL is select anon_func_seq.nextval for dbqd.acs-tcl.tcl.00-database-procs-postgresql.db_nextval.nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs-postgresql.db_nextval.nextval --> using default SQL [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = POST-QD: the SQL is select anon_func_seq.nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: PgBindCmd: sql = select anon_func_seq.nextval [27/Aug/2001:02:40:55][30817.4101][-conn0-] Debug: QD_LOGGER = PLPGSQL: converted: declare main_site_id site_nodes.node_id%TYPE; instance_id apm_packages.package_id%TYPE; node_id site_nodes.node_id%TYPE; begin main_site_id := site_node__node_id('/',null); instance_id := apm_package__new( null, null, :package_key, 'apm_package', now(), null, null, main_site_id ); node_id := site_node__new( null main_site_id, :package_key, instance_id, 't', 't', null, null ); return null; end; to: select __exec_13_package_instantiate_and_mount () NOTICE: identifier "__exec_13_package_instantiate_and_mount" will be truncated to "__exec_13_package_instantiate_a" NOTICE: identifier "__exec_13_package_instantiate_and_mount" will be truncated to "__exec_13_package_instantiate_a" NOTICE: Adding missing FROM-clause entry for table "acs_object_id_seq" NOTICE: identifier "acs_object__initialize_attributes" will be truncated to "acs_object__initialize_attribut" NOTICE: identifier "apm_package__initialize_parameters" will be truncated to "apm_package__initialize_paramet" [27/Aug/2001:02:40:55][30817.4101][-conn0-] Error: Ns_PgExec: result status: 7 message: ERROR: parser: parse error at or near "$1" [27/Aug/2001:02:40:55][30817.4101][-conn0-] Error: dbinit: error(localhost::openacs4,ERROR: parser: parse error at or near "$1" ): 'select __exec_13_package_instantiate_and_mount ()' NOTICE: identifier "__exec_13_package_instantiate_and_mount" will be truncated to "__exec_13_package_instantiate_a" [27/Aug/2001:02:40:55][30817.4101][-conn0-] Notice: Page not mounted.Error:
[27/Aug/2001:02:40:55][30817.4101][-conn0-] Notice: JM_IS_TESTING2: Test completed. 192.168.1.192 - - [27/Aug/2001:02:40:55 +0100] "GET /acs-admin/testing2.tcl HTTP/1.0" 200 0 "" "Lynx/2.8.4dev.16 libwww-FM/2.14 SSL-MM/1.4.1 OpenSSL/0.9.6"Database operation "0or1row" failed (exception NSDB, "Query was not a statement returning rows.")