Forum OpenACS Development: apm_package_instantiate_and_mount triggers QD bug?

RH 7.1, PG 7.1.3, AOLserver 3.3.1+ad13, current OpenACS4 from CVS.

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:

Database operation "0or1row" failed (exception NSDB, "Query was not a statement returning rows.")
[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"