Forum OpenACS Development: Is this a bug with the QD?

Collapse
1: Is this a bug with the QD?
Posted by Gilbert Wong on 07/14/01 12:05 AM

I've been playing around with the query error for a few hours. I am trying to access index.tcl in the instance of the ecommerce package which I created. In this case it's at /ecommerce/index. The query that breaks is a dml which uses sysdate/current_timestamp. For some reason, the QD is not reading the correct ported query in the - postgresql.xql file.

Here are the relevant files:

packages/ecommerce/www/index.tcl (line 35): 

ec_create_new_session_if_necessary "" 
cookies_are_not_required

packages/ecommerce/tcl/ecommerce-procs.tcl (line 1441-1446 within the procedure ec_create_new_session_if_necessary): 

                db_dml insert_user_session {
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address , 
sysdate, :http_user_agent)
                }

packages/ecommerce/tcl/ecommerce-procs-postgresql.xql (lines 72- 81): 

<fullquery 
name="ec_create_new_session_if_necessary.insert_user_session">
      <querytext>

                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address, 
current_timestamp, :http_user_agent)

      <rytext>
</fullquery>



Two things I have tried:

    

  1. The ported files above.  The error in the log file complains 
about sysdate not being defined.

  2. Changed sysdate to current_timestamp in the 
ecommerce/tcl/ecommerce-procs.tcl.  This works!




So I got really confused.  Then I turned on the debug mode.  Here 
is the output of the startup process and relevant lines near the 
error:


[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=0= 
db_dml insert_user_session {
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address , 
sysdate, :http_user_agent)
                }
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=1= 
template::adp_parse /home/aol30/aolserver3.3/servers/openacs-
4/packages/ecommerce/www/index {}
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=2= 
adp_parse_ad_conn_file
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=3= 
rp_serve_concrete_file /home/aol30/aolserver3.3/servers/openacs-
4/packages/ecommerce/www/index.tcl
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=4= 
rp_serve_abstract_file /home/aol30/aolserver3.3/servers/openacs-
4/packages/ecommerce/www/
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = LEVEL=5= 
rp_handler
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = the 
ad_conn file is /home/aol30/aolserver3.3/servers/openacs-
4/packages/ecommerce/www/index.tcl
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = We are in 
a WWW page sourced by apm_source, woohoo!
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = package 
key is ecommerce and rest is .www.index
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = generated 
fullname of dbqd.ecommerce.www.index.insert_user_session
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = PRE-QD: 
the SQL is
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address , 
sysdate, :http_user_agent)
                 for dbqd.ecommerce.www.index.insert_user_session
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = NO 
FULLQUERY FOR dbqd.ecommerce.www.index.insert_user_session --> using 
default SQL
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = POST-QD: 
the SQL is
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address , 
sysdate, :http_user_agent)

[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: PgBindCmd: sql =
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    (:user_session_id, :ip_address , 
sysdate, :http_user_agent)

[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: PgBindCmd: bind var: 
user_session_id = 22
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: PgBindCmd: bind var: 
ip_address = 15.111.20.6
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: PgBindCmd: bind var: 
http_user_agent = Mozilla/4.0 (compatible; MSIE 5.01; Windows NT; 
Hewlett-Packard IE5.01 SP1)
[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: PgBindCmd: query with 
bind variables substituted =
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    ('22', '15.111.20.6' , sysdate, 'Mozilla/4.0 
(compatible; MSIE 5.01; Windows NT; Hewlett-Packard IE5.01 SP1)')

[13/Jul/2001:17:46:06][2046.5][-conn0-] Notice: Querying '
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    ('22', '15.111.20.6' , sysdate, 'Mozilla/4.0 
(compatible; MSIE 5.01; Windows NT; Hewlett-Packard IE5.01 SP1)');'
[13/Jul/2001:17:46:06][2046.5][-conn0-] Error: Ns_PgExec: result 
status: 7 message: ERROR:  Attribute 'sysdate' not found

[13/Jul/2001:17:46:06][2046.5][-conn0-] Error: dbinit: error
(localhost::openacs-4,ERROR:  Attribute 'sysdate' not found
): '
                    insert into ec_user_sessions
                    (user_session_id, ip_address, start_time, 
http_user_agent)
                    values
                    ('22', '15.111.20.6' , sysdate, 'Mozilla/4.0 
(compatible; MSIE 5.01; Windows NT; Hewlett-Packard IE5.01 SP1)')
                '
[13/Jul/2001:17:46:06][2046.5][-conn0-] Notice: RP (788.032 ms): 
error in rp_handler: serving GET /ecommerce/
        ad_url "/ecommerce/" maps to 
file "/home/aol30/aolserver3.3/servers/openacs-
4/packages/ecommerce/www/index.tcl"
errmsg is Database operation "dml" failed





The line which is interesting says:


[13/Jul/2001:17:46:06][2046.5][-conn0-] Debug: QD_LOGGER = NO 
FULLQUERY FOR dbqd.ecommerce.www.index.insert_user_session --> using 
default SQL




It looks like the name given to the tcl procedure by the Query 
Extractor does not match what the Query Dispatcher created.  Is this 
a bug in the QD?


Thanks.
Collapse
2: Response to Is this a bug with the QD? (response to 1)
Posted by Don Baccus on 07/14/01 12:21 AM
Sure looks like it, Gilbert.  Ben's supposed to be back home tonight, apparently.  You should probably log this in the SDM and e-mail Ben a heads-up pointing to it.

I hope it's not because of something so basic as the fact that the proc name is 33 characters long...I don't think there's anything there
that limits names to 32 characters but I couldn't stop myself from counting...

Collapse
3: Response to Is this a bug with the QD? (response to 1)
Posted by Gilbert Wong on 07/14/01 12:26 AM
Thanks Don.  Under which package should I list the bug?  I'll send Ben an email too.
Collapse
4: Response to Is this a bug with the QD? (response to 1)
Posted by Dan Wickstrom on 07/14/01 01:05 AM
This is not a bug. It's just a side-effect of executing a query in the context of an uplevel. The proc "ec_create_new_session_if_necessary" does an uplevel before doing the query, so the QD is fooled into thinking that the query is executing from within index.tcl. You could fix this by putting the correct query in the index-postgresql.xql file in the www directory, but that might be kind of confusing. A better way to fix this would be to use db_map to fetch the query outside the scope of the uplevel, and then later pass it into the db_dml statement inside the uplevel. Since the proc in question has a long uplevel section, it might be easier to pass the sql to the db_dml statement via an upvar. Something like the following: 

ad_proc -private ec_create_new_session_if_necessary {
    {more_url_vars_exported ""}
    {cookie_requirement "cookies_are_required"}
} { Create a new session if needed } {
    uplevel "set _ec_more_url_vars_exported "$more_url_vars_exported""
    uplevel "set _ec_cookie_requirement     "$cookie_requirement""
    upvar __sql sql
    set sql [db_map insert_user_session_sql]
    uplevel {

        if { $user_session_id == 0 } {
            if {![info exists usca_p]} {

                # first time we've seen this visitor
                # no previous attempt made
                
                set user_session_id [db_nextval "ec_user_session_sequence"]
                ## use ACS 4 faster sessions
                ## set user_session_id [ad_conn session_id]
                
                set ip_address      [ns_conn peeraddr]
                set http_user_agent [ecGetUserAgentHeader]
                
                # we should be able to get rid of this in ACS 4, but
                # we need to examine longevity of ad_sessions

                db_dml insert_user_session $__sql

Now change the name of your query within the .xql file to "insert_user_session_sql", and everything should work okay.

Collapse
5: Response to Is this a bug with the QD? (response to 1)
Posted by Don Baccus on 07/14/01 01:08 AM
Hmmm...good question...it's really part of the kernel but it's such a central piece that a QD module should probably be added to the SDM.

Hey, there is one, imagine that!  Oh, I see, I just created it :)

You have the honor of submitting the first bug to this new module, how's that?

Collapse
6: Response to Is this a bug with the QD? (response to 1)
Posted by Don Baccus on 07/14/01 01:10 AM
Oops, I guess I responded too quickly, thanks Dan.  I didn't look at the source file and didn't think about the possibility that an uplevel  might be involved.

We should probably get this documented in the porting docs if it isn't
already.

Collapse
7: Response to Is this a bug with the QD? (response to 1)
Posted by Gilbert Wong on 07/15/01 09:07 AM

Dan, thanks! That worked perfectly!

I have another problem. Here is the error message I got (in debug mode): 

[14/Jul/2001:22:38:28][1262.4101][-conn0-] Debug: QD_LOGGER =
generated fullname of dbqd.ecommerce.tcl.ecommerce-procs.ec_package_url_lookup_mem.ec_mountpoint

...

[14/Jul/2001:22:38:28][1262.4101][-conn0-] Debug: QD_LOGGER = 
NO FULLQUERY FOR dbqd.ecommerce.tcl.ecommerce-procs.ec_package_url_lookup_mem.ec_mountpoint --> using default SQL

While trying to run packages/ecommerce/www/admin/customer-service/index.tcl 

<FORM METHOD=get ACTION=[ec_acs_admin_url]users/search>

From the following code in packages/ecommerce/ecommerce-procs.tcl: 

### the url to get to ec
ad_proc -public ec_package_url_lookup {package_key} {
    @return The url (without protocol or port) of a site mountpoint if it exists, 0 otherwise.
 } {
    return [util_memoize "ec_package_url_lookup_mem $package_key" [ec_cache_refresh]]
}

ad_proc -private ec_package_url_lookup_mem {package_key} {} {
    if {[db_table_exists apm_packages]} {
        return [db_string ec_mountpoint "
            select site_node.url(s.node_id)
              from site_nodes s, apm_packages a
             where s.object_id = a.package_id
               and a.package_key = '$package_key'
        " -default 0]
    } else {
        return 0
    }
}

ad_proc ec_acs_admin_url {} {
    @return The url of the package with key acs-admin
} {
    return [ec_package_url_lookup acs-admin]
}

I do have the query in packages/ecommerce/tcl/ecommerce-procs-postgresql.xql: 

<fullquery name="ec_url_lookup_mem.ec_mountpoint">
      <querytext>

            select site_node__url(s.node_id)
              from site_nodes s, apm_packages a
             where s.object_id = a.package_id
               and a.package_key = '$package_key'

      </querytext>
</fullquery>

Any ideas? Thanks.

Collapse
8: Response to Is this a bug with the QD? (response to 1)
Posted by Dan Wickstrom on 07/15/01 02:45 PM
It looks like a typo in your .xql file.  The proc name is "ec_package_url_lookup_mem", but you have it as "ec_url_lookup_mem" in your .xql file.
Collapse
9: Response to Is this a bug with the QD? (response to 1)
Posted by Gilbert Wong on 07/15/01 07:00 PM
Ack.  That's what I get for not checking the results of the query extractor.  Thanks!