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

We just upgraded the OS (freebsd 7) on an OpenACS 5.3.2 system to use the latest ports and aolserver4.5.1 from aolserver4.5. Most of the pages work, but the first level ones return with a system error and log message "failed to redirect 'GET /global/file-not-found.html': exceeded recursion limit of 3"

/robots.txt and /SYSTEM/dbtest.tcl return with 500 error, but files in /resources/ and /xowiki and subsites work fine.

These messages seem to indicate a problem:

[11/May/2009:15:22:45][79655.16785584][-main-] Notice: Executing initialization code block procs_register in /usr/local/www/website/openacs
/packages/acs-tcl/tcl/request-processor-init.tcl
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[NotFoundResponse]: mapped GET /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[NotFoundResponse]: mapped HEAD /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[NotFoundResponse]: mapped POST /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: conf: [ns/server/NotFoundResponse]enabletclpages = 0
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: default thread pool: minthreads 5 maxthreads 10 idle 0 current 0 maxconns 15 queued 0 timeout 1 sp
read 20
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: XOTcl version 1.6.3 loaded
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerBusyResponse]: mapped GET /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerBusyResponse]: mapped HEAD /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerBusyResponse]: mapped POST /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: conf: [ns/server/ServerBusyResponse]enabletclpages = 0
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: default thread pool: minthreads 5 maxthreads 10 idle 0 current 0 maxconns 15 queued 0 timeout 1 sp
read 20
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: XOTcl version 1.6.3 loaded
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerInternalErrorResponse]: mapped GET /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerInternalErrorResponse]: mapped HEAD /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: fastpath[ServerInternalErrorResponse]: mapped POST /
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: conf: [ns/server/ServerInternalErrorResponse]enabletclpages = 0
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: default thread pool: minthreads 5 maxthreads 10 idle 0 current 0 maxconns 15 queued 0 timeout 1 spread 20
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: XOTcl version 1.6.3 loaded
[11/May/2009:15:22:46][79655.16785584][-main-] Notice: nsmain: AOLserver/4.5.1 running

Any ideas what it means and/or how to fix?

btw, /xotcl/version-numbers returns 500 Server Error also.
What happens, if you deactivate fastpath?
ns_section "ns/server/${servername}/fastpath"
    ns_param   cache  false
do you have mmap defined? see: http://panoptic.com/wiki/aolserver/Annotated_AOLserver_Configuration_Reference
ns_section fastpath and mmap were not defined, so I added these, turned off and restarted, resulting in no change to symptoms.
I've also grepped for fastpath in the db and code.. nothing appears to be different from a standard install.

debug is now set true in config.tcl, so hopefully more info will come from that.

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

You're right, Gustaf. Thank you. Multiple enabletclpages was the clue.

Problem solved.

Apparently, the config.tcl file lost about 8 lines when the system crashed while the file was being edited.

Case closed.

Thank you.