Forum OpenACS Q&A: site-map problems with aolserver 4

Collapse
Posted by Vinod Kurup on
test case:

Using IE 6 for windows or IE 5 for Mac. AOLServer 4, OpenACS 4.6.2

  • go to /admin/site-map
  • create a new subfolder under / and call it 'test'
  • Submit the form
  • IE returns 'The page cannot be displayed'
The page works on Camino (Mozilla). It also works fine if I use AOLServer 3.3.

I found the problem when I was using Til's excellent tclwebtest and the included site-map.test file failed. Basically, the folder gets added, but the redirect back to the site map returns no data.

I haven't narrowed it down yet, but I wanted to see if anyone running AOLServer4 had seen this or could confirm it first.

Thanks.

Collapse
Posted by Tom Jackson on

Maybe the return just isn't large enough for IE to show you what was returned. I think short responses are somehow considered incorrect by IE. If it works in Camino, maybe you can see just how big the response is.

Collapse
Posted by Vinod Kurup on
I initially found the problem using tclwebtest which uses tcl's http module and no data is returned at all. In Camino a full page is returned (the site-map page). I'm thinking that maybe I've got something misconfigured or something, so I wanted to see if anyone else was having the same problem.
Collapse
Posted by Tom Jackson on

What is your server log showing for the connection? I had an issue with AOLserver4 where a filter was incorrectly defined, or an error is thrown in the filter. What happens is that AOLserver would log the error and close the conn with no return at all. It should have returned a 500 response, but there was a bug in the filter processing code. I think the return value of the function was also the value signalling AOLserver that it should close the conn.

I'm not sure this has been fixed yet. What version of AOLserver 4 are you using? BTW: Mozilla has an annoying habit of trying the same conn 6-7 times when nothing is returned.

Collapse
Posted by Vinod Kurup on
I think you might be right. I'm getting an "invalid database id : nsdb0" from 'rp_filter preauth', but no 500 response. When I get home tonight, I'll try to look into what might be causing that error.

I'm using AOLserver 4 from CVS around the time of beta3. Mozilla's repeat requests may also explain why it works in that browser, because if I reload the sitemap about 6 times in IE, it eventually works too.

Thanks for the help.

Collapse
Posted by Tom Jackson on

Vinod: thanks to you also. Please post your result here so I can verify that the bug still exists. I'll make sure this is looked into again, or maybe for the first time!

Collapse
Posted by tammy m on
Hi I'm glad you posted this! I have been having the problem. It happens on adding a subfolder in SiteMap and also on New Application. If I then click on any other link immediately afterword (like Administration), then I get the same error for that link, however the 2nd time I click the Administration link, The Administration page loads fine. Actually, I just tried this, and I can click any link immediately afterward (even my homepage) and it also gets an error, the first time only.

This happens on 4.0beta3 and beta4. I am using IE 5.2 on Mac OS X. It does not happen on Mozilla 1.0 on Mac OS X though.

Here is my output from the server log:

[22/Apr/2003:11:18:13][32185.10244][-conn:openacs-dev::6] Debug: RP (17.773 ms): rp_filter: setting up request: GET /admin/site-map expand=2115&root_id=2115
[22/Apr/2003:11:18:13][32185.10244][-conn:openacs-dev::6] Debug: Security: Getting token_id 629, value D5D92E410131F7E6C88B94B226B333F47DE8389D
[22/Apr/2003:11:18:13][32185.10244][-conn:openacs-dev::6] Debug: Security: Expire_Time is 1051036650 (compare to 1051035493), hash is 32BA0FA6F92101D1DA264B89D628B664449053A1
[22/Apr/2003:11:18:13][32185.10244][-conn:openacs-dev::6] Debug: Security: Done calling get_cookie 150001,2123 {629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1} for ad_session_id; received 1051036650 expiration, getting 150001,2123 and 629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1.
[22/Apr/2003:11:18:13][32185.10244][-conn:openacs-dev::6] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_pg_bind 0or1row nsdb0 {
            select 1
            where 't' = acs_permission__permission_p(:object_id, :party_id, :privilege)
        }"
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_pg_bind $type $db $sql"
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
        set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 22)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege admin"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
        } else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
        if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege adm..."
    (procedure "rp_filter" line 152)
    invoked from within
"rp_filter preauth"
[22/Apr/2003:11:18:17][32185.13319][-conn:openacs-dev::8] Debug: RP (34.706 ms): rp_filter: setting up request: GET /admin/site-map expand=2115&root_id=2115
[22/Apr/2003:11:18:17][32185.13319][-conn:openacs-dev::8] Debug: Security: Getting token_id 629, value D5D92E410131F7E6C88B94B226B333F47DE8389D
[22/Apr/2003:11:18:17][32185.13319][-conn:openacs-dev::8] Debug: Security: Expire_Time is 1051036650 (compare to 1051035497), hash is 32BA0FA6F92101D1DA264B89D628B664449053A1
[22/Apr/2003:11:18:17][32185.13319][-conn:openacs-dev::8] Debug: Security: Done calling get_cookie 150001,2123 {629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1} for ad_session_id; received 1051036650 expiration, getting 150001,2123 and 629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1.
[22/Apr/2003:11:18:18][32185.13319][-conn:openacs-dev::8] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_pg_bind 0or1row nsdb0 {
            select 1
            where 't' = acs_permission__permission_p(:object_id, :party_id, :privilege)
        }"
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_pg_bind $type $db $sql"
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
        set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 22)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege admin"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
        } else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
        if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege adm..."
    (procedure "rp_filter" line 152)
    invoked from within
"rp_filter preauth"
[22/Apr/2003:11:18:34][32185.2051][-sched-] Notice: Running scheduled proc search_indexer...
[22/Apr/2003:11:18:34][32185.2051][-sched-] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_pg_bind select nsdb0 {
            select object_id, event_date, event
            from search_observer_queue
            order by event_date asc
 ..."
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_pg_bind $type $db $sql"
    invoked from within
"db_exec select $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec select $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
        set selection [db_exec select $db $full_statement_name $sql]

        set counter 0
        while { [db_getrow $db $selection] } {
            incr co..."
    (procedure "db_foreach" line 35)
    invoked from within
"db_foreach search_observer_queue_entry {} {

        switch $event {
            INSERT {
                set object_type [acs_object_type $object_id]..."
    (procedure "search_indexer" line 5)
    invoked from within
"search_indexer"
    ("eval" body line 1)
    invoked from within
"eval [concat [list $proc] $args]"
    (procedure "ad_run_scheduled_proc" line 43)
    invoked from within
"ad_run_scheduled_proc {f f 30 search_indexer {} 1050957902 0 t}"
[22/Apr/2003:11:18:41][32185.12294][-conn:openacs-dev::7] Debug: RP (12.053 ms): rp_filter: setting up request: GET / 
[22/Apr/2003:11:18:41][32185.12294][-conn:openacs-dev::7] Debug: Security: Getting token_id 629, value D5D92E410131F7E6C88B94B226B333F47DE8389D
[22/Apr/2003:11:18:41][32185.12294][-conn:openacs-dev::7] Debug: Security: Expire_Time is 1051036650 (compare to 1051035521), hash is 32BA0FA6F92101D1DA264B89D628B664449053A1
[22/Apr/2003:11:18:41][32185.12294][-conn:openacs-dev::7] Debug: Security: Done calling get_cookie 150001,2123 {629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1} for ad_session_id; received 1051036650 expiration, getting 150001,2123 and 629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1.
[22/Apr/2003:11:18:41][32185.12294][-conn:openacs-dev::7] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_pg_bind 0or1row nsdb0 {
            select 1
            where 't' = acs_permission__permission_p(:object_id, :party_id, :privilege)
        }"
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_pg_bind $type $db $sql"
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
        set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 22)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege read"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
        } else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
        if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege adm..."
    (procedure "rp_filter" line 152)
    invoked from within
"rp_filter preauth"
[22/Apr/2003:11:18:42][32185.14344][-conn:openacs-dev::9] Debug: RP (11.946 ms): rp_filter: setting up request: GET / 
[22/Apr/2003:11:18:42][32185.14344][-conn:openacs-dev::9] Debug: Security: Getting token_id 629, value D5D92E410131F7E6C88B94B226B333F47DE8389D
[22/Apr/2003:11:18:42][32185.14344][-conn:openacs-dev::9] Debug: Security: Expire_Time is 1051036650 (compare to 1051035522), hash is 32BA0FA6F92101D1DA264B89D628B664449053A1
[22/Apr/2003:11:18:42][32185.14344][-conn:openacs-dev::9] Debug: Security: Done calling get_cookie 150001,2123 {629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1} for ad_session_id; received 1051036650 expiration, getting 150001,2123 and 629 1051036650 32BA0FA6F92101D1DA264B89D628B664449053A1.
[22/Apr/2003:11:18:42][32185.14344][-conn:openacs-dev::9] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_pg_bind 0or1row nsdb0 {
            select 1
            where 't' = acs_permission__permission_p(:object_id, :party_id, :privilege)
        }"
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_pg_bind $type $db $sql"
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
        set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 22)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege read"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
        } else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
        if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege adm..."
    (procedure "rp_filter" line 152)
    invoked from within
"rp_filter preauth"
Collapse
Posted by Michael Bluett on
Off-topic, but it looks like the above text is an example of the automatic HTML tag-closer not working.  It doesn't look to have closed the <code> tag.
Collapse
Posted by Vinod Kurup on
Tammy, thanks for confirming that you're having a problem with this too. I see you're using PG and I'm using Oracle, so it's db independent.

I'm still trying to figure out why the 'invalid handle' error comes up in the first place. I've narrowed the problem down to the ns_eval command. I put the following 2 commands into a .tcl file:


ns_eval {}
ns_return 200 text/plain "Hello"
IE and tclwebtest return no data unless you reload a few times. Here's the error:

[23/Apr/2003:19:42:15][12078.81926][-conn:openacs4::2] Debug: RP (40.286 ms): rp_filter: setting up request: GET /test/new 
[23/Apr/2003:19:42:15][12078.81926][-conn:openacs4::2] Notice: Security: 1051141335 sec_generate_session_id_cookie setting 3602, 0.
[23/Apr/2003:19:42:15][12078.81926][-conn:openacs4::2] Debug: Security: 1051141335 sec_generate_session_id_cookie setting 3602, 0.
[23/Apr/2003:19:42:15][12078.81926][-conn:openacs4::2] Debug: Security: Getting token_id 377, value 03B4887F014487C04E086720B19965FA10B8FEC1
[23/Apr/2003:19:42:15][12078.81926][-conn:openacs4::2] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_ora 0or1row nsdb0 {
            select 1
            from dual
            where 't' = acs_permission.permission_p(:object_id, :party_id, :privileg..."
    ("uplevel" body line 1)
    invoked from within
"uplevel $ulevel [list ns_ora $type $db $sql] $args"
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle db {
	set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 22)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege read"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
	} else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
          if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -priv..."
    (procedure "rp_filter" line 152)
    invoked from within
"rp_filter preauth"
Again, this works fine on aolserver 3.3+ad13. Unfortunately, I still don't know what ns_eval has to do with it or why the problem only happens during rp_filter.
Collapse
Posted by Jamie Rasmussen on
If it helps, I also see that error with PostgreSQL. Using your hello script, I get:

[24/Apr/2003:19:45:38][1288.1416][-conn:openacs4::0] Error: invalid database id:  "nsdb0"
invalid database id:  "nsdb0"
    while executing
"ns_db poolname $handle"
    (procedure "db_driverkey" line 7)
    invoked from within
"db_driverkey -handle_p 1 $db"
    (procedure "db_exec" line 3)
    invoked from within
"db_exec 0or1row $db $full_statement_name $sql"
    invoked from within
"set selection [db_exec 0or1row $db $full_statement_name $sql]"
    ("uplevel" body line 2)
    invoked from within
"uplevel 1 $code_block "
    invoked from within
"db_with_handle -dbn $dbn db {
        set selection [db_exec 0or1row $db $full_statement_name $sql]
    }"
    (procedure "db_0or1row" line 23)
    invoked from within
"db_0or1row select_permission_p {}"
    (procedure "permission::permission_p_not_cached" line 6)
    invoked from within
"permission::permission_p_not_cached -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission_p" line 8)
    invoked from within
"permission_p -party_id $party_id -object_id $object_id -privilege $privilege"
    (procedure "permission::require_permission" line 7)
    invoked from within
"permission::require_permission -object_id [ad_conn object_id] -privilege read"
    invoked from within
"if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege admin
        } else..."
    ("uplevel" body line 2)
    invoked from within
"uplevel $code"
    invoked from within
"ad_try {
        if {[string match "admin/*" [ad_conn extra_url]]} {
            permission::require_permission -object_id [ad_conn object_id] -privilege adm..."
    (procedure "rp_filter" line 162)
    invoked from within
"rp_filter preauth"
Collapse
Posted by Jamie Rasmussen on
I only skimmed the db code but noticed some nsv_exists and nsv_set calls.  Perhaps this is related to this AOLserver 4.0 bug that Andrew Piskorski submitted?  (Still unassigned.)
"[ 712241 ] Creating empty nsv fails in AOLserver 4"
http://sourceforge.net/tracker/index.php?func=detail&aid=712241&group_id=3152&atid=103152
Collapse
Posted by Vinod Kurup on
The latest AOLserver 4 CVS has fixed the 'return no data' problem. Instead, it properly returns a 500 error, so now adding a subfolder to the sitemap errors out in all browsers. At least it's consistent now 😊 So we need to find out why the error is happening in the first place.

I haven't found any spots which match Andy's bug report for the nsv problem (but I haven't looked exhaustively yet). Here's what I do know:

Adding a folder to the site map calls site_node::update_cache which runs this bit of code:


ns_eval {
    global tcl_site_nodes
    if { [info exists tcl_site_nodes] } {
        array unset tcl_site_nodes "${node(url)}*"
    }
}
According to the docs, ns_eval is meant to maintain global vars across interpreters. But, this is the only place in the toolkit that ns_eval is used. Usually we use nsv's to maintain info across interps, right? Getting rid of the ns_eval brackets solves the problem. Does it make sense to switch to a nsv in this case?
Collapse
Posted by Andrew Piskorski on
ns_eval, funky, yet another little bit of AOLserver API I've never personally used.

Vinod, good catch! If that's really the only use of ns_eval in OpenACS, and replacing it with nsv fixes the problem, yes definitely you should make the change! (And grep for any other use of tcl_site_nodes, etc.) Nsv should be both clearer and faster, anyway.

Also, sounds like ns_eval may be buggy in AOLserver 4.0, so please do submit a bug report on SourceForge.

Ah, in AOLserver 3, ns_eval was a C command, but in 4.0 it's a Tcl proc, in "aolserver/nsd/init.tcl". It's quite short. More importantly, the comments in the code make it clear that the above tcl_site_nodes usage is a misuse and abuse of ns_eval, not what ns_eval is intended for:

# ns_eval -- 
# 
#   Evaluate a script which should contain 
#   new procs commands and then save the 
#   state of the procs for other interps 
#   to sync with on their next _ns_atalloc.
Collapse
Posted by Vinod Kurup on
tcl_site_nodes is used in only 1 place. It's supposed to be a cache of site node information, but it's implemented as a global var (which are global only to 1 interpreter), so it really doesn't do what it's supposed to do:

Slightly simplified code from rp_filter (in request-processor-procs.tcl)


    global tcl_site_nodes
    if [catch { array set node $tcl_site_nodes([ad_conn url]) }] {
        array set node [site_node [ad_conn url]]
        set tcl_site_nodes([ad_conn url]) [array get node]
    }
The answer would be to make it an NSV, but I noticed that there's already an NSV that maintains this info properly (inside the site_node call above). So, I can just get rid of tcl_site_nodes var, right? A patch is forthcoming...
Collapse
Posted by Andrew Piskorski on
Looks like the nasty use of ns_eval has not yet been removed from acs-tcl/tcl/site-nodes-procs.tcl either on the 4.6 branch or the Head.
Collapse
Posted by Andrew Piskorski on
Oh, reason I was checking is maybe Mohan's troubles with AOLserver 4 and OpenACS on Solaris are related.
Collapse
Posted by Andrew Piskorski on
Vinod filed a bug report and patch to fix this.