Currently, there is a problem that is occuring periodically with one of our services. Below is a snapshot of the log right just before the process "disappears" and whenever we restart openacs, after 10 mins or so the same occurance happens.

Are there any suggestions as to how one should debug this? we have another service which uses the same code and config but rarely has this problem?

Regards,

Jason

[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0]
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0]
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= sec_handler: enter
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS: Not a valid session cookie
, looking for login cookie
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= sec_login_handler: enter
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= sec_setup_session: enter
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= empty session_id
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= newly allocated session 59
523217
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= about to generate session
id cookie
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: Security: 1132125777 sec_generat
e_session_id_cookie setting session_id=59523217, user_id=0, login_level=0
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: Security: Getting token_id 39, v
alue E9550B9D21DF6C1BD6F2FF369E82D09544694CCB
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Debug: OACS= done generating session id
cookie
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Notice: Querying '
select 1
where 't' = acs_permission__permission_p('1208', '0', 'read');'
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Notice: dbinit: sql(localhost:5431:serv
ice0): '
select 1
where 't' = acs_permission__permission_p('1208', '0', 'read')
'
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Notice: sec_lookup_property starting --
jason
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Notice: Querying '

select property_value, secure_p
from sec_session_properties
where session_id = '59523217'
and module = 'acs-lang'
and property_name = 'translator_mode_p';'
[16/Nov/2005:15:22:57][11973.4123126704][-conn:service0::0] Notice: dbinit: sql(localhost:5431:serv
ice0): '

select property_value, secure_p
from sec_session_properties
where session_id = '59523217'
and module = 'acs-lang'
and property_name = 'translator_mode_p'

##script that checks existence of process and restarts if not found

[16/Nov/2005:15:24:11][12864.4142909664][-main-] Notice: nsmain: AOLserver/4.0.9 starting

Jason, I'm afraid you need to be a little - ok a lot - more specific. What do you mean by saying the process "disappears"? What are the actual symptoms you are observing?

Secondly, you seem to have edited the AOLserver log snippet you posted. Does your log really show nothing at all for the 74 seconds between 15:22:57 and 15:24:11, or is that just an artifact of how you posted the info?

What operating system?

Does aolserver post any warnings in the logs during startup?

Jason, FYI, to get the best help here on the Forums, you really should give us a lot more info first thing, e.g.: What operating system and version? What version of AOLserver? (Apparently 4.0.9 from your log.) What AOLserver modules do you have loaded? (In particular, do you have any nonstandard modules?) What version of Tcl? How did you build and install AOLserver and Tcl? What threads and stacksize settings are you using in your AOLserver config file (in the ns/parameters and ns/server/$servername sections.)?

In general there are only three ways AOLserver can be killed: It itself chooses to shut down by Tcl code calling ns_shutdown or the like, it crashes, or some other process (the kernel, the user, whatever) purposely kills it.

Your AOLserver log has no messages at all from AOLserver about shutting down, it was just running normally, and then bang, a minute or so later it's starting up again. That means that AOLserver either crashed or was kill -9'd (SIGKILL). If it had been killed with a plain kill (SIGTERM) or ns_shutdown, you'd see evidence of AOLserver doing an orderly shutdown in its log - which you don't.

Do you have some form of process resource limits configured in your operating system? Memory limits or the like? I bet that's it - some web crawler hits your (otherwise low traffic) site, AOLserver grabs a bunch more memory, and then your OS shoots the process dead with kill -9. (If true, that isn't AOLserver's fault, your OS is misconfigured.) If you're on Linux, check with "ulimit -a". Ideally, run ulimit -a from the script which actually starts AOLserver.

If on the other hand AOLserver is in fact crashing, you want it to leave a core file so that you can figure out why it crashed. If you're on Linux, make sure you do something like "ulimit -c unlimited" in the script which starts AOLserver. That sets no limit on the max size of corefiles - the default is often 0, which means you won't get any corefile at all. You may want to set that as a system-wide default in "/etc/profile".

versions
------------
Operating System: Fedora Core 3
AOLserver: version 4.0.9
tcl: version 8.4


building and installation
------------------------------
building with the instructinos given in openacs.org:
http://openacs.org/doc/current/complete-install.html
(only altered some name of folders)


configuration
-----------------
Modules Loaded: nssock nslog nssha1 nscache nsgdchart nsdb
stacksize: expr 128 * 8192


Planned kill
---------------
There is no planed kill for AOLserver process.
AOLserver process crashed itself at some point.


Clawer
--------
Yes. Clawer was the last visiter before crashes most of the time. And most of the time it is Googlebot.


resource limit
-----------------
I have not set any limit myself, but the os may set some
limit by default. Please see what I got from the OS:

[root@machine etc]# ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
file size (blocks, -f) unlimited
pending signals (-i) 1024
max locked memory (kbytes, -l) 32
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
stack size (kbytes, -s) 10240
cpu time (seconds, -t) unlimited
max user processes (-u) 16380
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

I am trying your ulimit -c unlimited option now.
See if it is related. The site was down when an unblocked Googlebot visited the CLB site.
I have block that ip now

ulimit
---------
Thanks for reminding. I didn't know that. I've set the OpenACS user (serice0, service1) ulimit now. Thanks


AOLserver crash
------------------
I think I am quite sure that it is crashed itself. Because:

1) I haven't shut it down.
2) I haven't schedule any shutdown at this frequency (10 or more in an hour sometimes)
3) There is no log for shutdown in the log file

Unless there is other evidence I can look for, I suppose the AOLserver process crashes itself.

upgrade to aolserver 4.0.10 (avail since jan) and to tcl8.4.11.

Be sure, that you do not call "ns_server threads"
(see http://panoptic.com/wiki/aolserver/Ns_server)

Whats odd is that /public/main is a valid url (there is a main.adp,tcl) and typing /public/maintestingerror redirects fine back to the home page - BUT if I try something like /public/contents/a then it crashes.

Jason, what version of openacs are you using? what version of tcl?

try the following in the shell:
set var x
set val 123
ad_page_contract_filter_proc_integer var val

(this is a valid test and returns 1) and then

set var x
set val [ns_urldecode 1017%3C/p%3E%0D%0A%3Cp%3E]
ad_page_contract_filter_proc_integer var val

(this is the test with the invalid id from your example)
If the integer test is the problem, the second one crashes.
the second call should return 0.

for me, this works nicely...

Jason, do the tests return on both systems the correct boolean value? To be sure, try to use the function ad_page_contract_filter integer from version 1.20 http://eye.openacs.org/viewrep/OpenACS/packages/acs-tcl/tcl/tcl-documentation-procs.tcl

don't you see any error message in the error log from the 500 error?

I have 2 files - test.tcl and blank-master.tcl

test.tcl

ad_page_contract {

} {
x:notnull,integer
}

ns_log Notice INSIDETEST
ad_return_template

blank-master.tcl

ad_page_contract {

} {
{x ""}
}

ns_log Notice BLANKMASTER

How might I pass value of x into blank-master in usual circumstances such as test?x=1 and test?x=a (this works;returns error) and also catch invalid urls such as test?x=1017%3C/p%3E%0D%0A%3Cp%3E (this causes server error).