Forum OpenACS Q&A: Re: fastpath / request-processor weird behavior after OS upgrade

Here's a /robots.txt request

[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: RP (0 ms): rp_filter: setting up request: GET /robots.txt 
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= sec_handler: enter
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS: Not a valid session cookie, looking for login cookie
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= sec_login_handler: enter
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= sec_setup_session: enter
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= empty session_id
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs.db_nextval.nextval_sequence --> using default SQL
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: Querying '
                select nextval('sec_id_seq') as nextval
                where (select relkind 
                       from pg_class 
                       where relname = 'sec_id_seq') = 'S';'
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: dbinit: sql(localhost:5432:integ_solar_com82): '
                select nextval('sec_id_seq') as nextval
                where (select relkind 
                       from pg_class 
                       where relname = 'sec_id_seq') = 'S'
            '
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.00-database-procs.db_nextval.nextval_sequence
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: db_nextval: sequence(sec_id_seq) is not a real sequence.  perhaps it uses the view hack.
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs.db_nextval.nextval_view --> using default SQL
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: Querying 'select nextval from sec_id_seq;'
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: dbinit: sql(localhost:5432:integ_solar_com82): 'select nextval from sec_id_seq'
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.00-database-procs.db_nextval.nextval_view
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= newly allocated session 16860001
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= about to generate session id cookie
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: Security: 1242074595 sec_generate_session_id_cookie setting session_id=16860001, user_id=0, login_level=0
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: Security: Getting token_id 313, value 81695CB8DD76A55F85C5C7CD8A9263F09890E7FE
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: OACS= done generating session id cookie
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: Querying '
                select 1 from dual
                where exists
                        ( select 1
                        from acs_object_party_privilege_map ppm
                        where ppm.object_id = '521' and ppm.party_id = '0' and ppm.privilege = 'read' );'
[11/May/2009:20:43:15][19930.16787184][-default:0-] Notice: dbinit: sql(localhost:5432:integ_solar_com82): '
                select 1 from dual
                where exists
                        ( select 1
                        from acs_object_party_privilege_map ppm
                        where ppm.object_id = '521' and ppm.party_id = '0' and ppm.privilege = 'read' )
        '
[11/May/2009:20:43:15][19930.16787184][-default:0-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.acs-permissions-procs.permission::permission_p_not_cached.select_permission_p
[11/May/2009:20:43:15][19930.16787184][-default:0-] Error: return: failed to redirect 'GET /global/file-not-found.html': exceeded recursion limit of 3

It almost seems like a file permissions issue..

..but it's not file permissions.. it's been verified against other working systems.
Looks like section: "ns_section ns/server/${server}" is munged with servers section in config.tcl. Grepping the "enabletclpages" in the log indicates 4 servers defined.. when there should be only 1.

Thank you,

Torben

From your output:

[11/May/2009:15:22:46][79655.16785584][-main-] Notice: conf: [ns/server/NotFoundResponse]enabletclpages = 0

In the line above, "NotFoundResponse" should be your server name. I doubt, that you are using such a strange name, but who knows.

How do you specify the section including enabletclpages? ns_section "ns/server/${server}"? If yes, how do you set the variable "server" in your config-file?

-gustaf neumann