Forum OpenACS Q&A: still have problem with set address and server not going beyond login screen
Setup your own web ba16/Jan/2009:19:07:56][4468.3083184320][-main-] Notice: ns_register_proc GET /finish-component-element* rp_invoke_proc {0$
[16/Jan/2009:19:07:56][4468.3083184320][-main-] Notice: ns_register_proc POST /finish-component-element* rp_invoke_proc {$
[16/Jan/2009:19:08:00][4468.3083184320][-main-] Notice: nsmain: AOLserver/4.5.0 running
[16/Jan/2009:19:08:00][4468.3083184320][-main-] Notice: nsmain: security info: uid=33, euid=33, gid=33, egid=33
[16/Jan/2009:19:08:00][4468.3074554768][-sched-] Notice: sched: starting
[16/Jan/2009:19:08:00][4468.3083184320][-main-] Notice: driver: starting: nssock
[16/Jan/2009:19:08:00][4468.3031493520][-nssock:driver-] Notice: starting
[16/Jan/2009:19:08:00][4468.3031493520][-nssock:driver-] Notice: nssock: listening on 0.0.0.0:8000
[16/Jan/2009:19:08:36][4468.3027291024][-sched:idle0-] Notice: starting
[16/Jan/2009:19:08:45][4468.3023088528][-sched:idle1-] Notice: starting
[16/Jan/2009:19:09:20][4468.3052506000][-conn:0-] Notice: random: generating 1 seed
[16/Jan/2009:19:09:45][4468.3027291024][-sched:13-] Notice: dbdrv: opening database 'postgres:localhost:5432:dotlrn'
[16/Jan/2009:19:09:45][4468.3027291024][-sched:13-] Notice: Opening dotlrn on localhost
[16/Jan/2009:19:09:45][4468.3027291024][-sched:13-] Notice: Ns_PgOpenDb(postgres): Openned connection to localhost:5432:d$
[16/Jan/2009:20:32:23][4468.3018886032][-conn:5-] Notice: encoding: loaded: iso8859-1
Tcl_SetBooleanObj called with shared object
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: nsmain: AOLserver/4.5.0 starting
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: nsmain: security info: uid=33, euid=33, gid=33, egid=33
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: nsmain: max files: FD_SETSIZE = 1024, rl_cur = 1024, rl_max = 1024
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: encoding: loaded: utf-8
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: fastpath[dotlrn]: mapped GET /
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: fastpath[dotlrn]: mapped HEAD /
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: fastpath[dotlrn]: mapped POST /
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: adp[dotlrn]: mapped GET /*.adp
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: adp[dotlrn]: mapped HEAD /*.adp
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: adp[dotlrn]: mapped POST /*.adp
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: modload: loading '/usr/lib/aolserver4/bin/nssock.so'
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: modload: loading '/usr/lib/aolserver4/bin/nslog.so'
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: nslog: opened '/usr/share/dotlrn/log/dotlrn.log'
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: modload: loading '/usr/lib/aolserver4/bin/nssha1.so'
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: modload: loading '/usr/lib/aolserver4/bin/nscache.so'
[16/Jan/2009:20:32:28][4830.3083647168][-main-] Notice: nscache module version 1.4 server: dotlrn
snip......
....without me doing anything except logging in and trying to register from yet another computer
...the following from the end of the file 2 minutes later and some 5000 lines later of it loading all kinds of stuff
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/lars-blogger/tcl/technorati-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/lars-blogger/tcl/technorati-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/notifications/tcl/reply-sweep-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/notifications/tcl/reply-sweep-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/notifications/tcl/sweep-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/notifications/tcl/sweep-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/oacs-dav/tcl/oacs-dav-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: OACS-DAV preauth filters loaded on /dav/*
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/oacs-dav/tcl/oacs-dav-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/rss-support/tcl/rss-generation-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/rss-support/tcl/rss-generation-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/search/tcl/search-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/search/tcl/search-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/xml-rpc/tcl/system-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/xml-rpc/tcl/system-init.tcl.
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loading packages/xml-rpc/tcl/validator-init.tcl...
[16/Jan/2009:20:34:25][4830.3083647168][-main-] Notice: Loaded packages/xml-rpc/tcl/validator-init.tcl.
[16/Jan/2009:20:34:34][4830.3083647168][-main-] Notice: Loading packages/news/tcl/test/news-db-test-init.tcl...
[16/Jan/2009:20:34:35][4830.3083647168][-main-] Notice: Loaded packages/news/tcl/test/news-db-test-init.tcl.
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Bootstrap: Done loading OpenACS.
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Sourcing files for postload...
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Done.
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Executing initialization code blocks...
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Executing initialization code block filters_register in /usr/share$
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: Executing initialization code block procs_register in /usr/share/d$
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: ns_register_proc GET /grades-sheet-csv* rp_invoke_proc {0 0 0 eva$
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: ns_register_proc POST /grades-sheet-csv* rp_invoke_proc {0 0 0 ev$
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: ns_register_proc GET /finish-component-element* rp_invoke_proc {0$
[16/Jan/2009:20:34:36][4830.3083647168][-main-] Notice: ns_register_proc POST /finish-component-element* rp_invoke_proc {$
[16/Jan/2009:20:34:40][4830.3083647168][-main-] Notice: nsmain: AOLserver/4.5.0 running
[16/Jan/2009:20:34:40][4830.3083647168][-main-] Notice: nsmain: security info: uid=33, euid=33, gid=33, egid=33
[16/Jan/2009:20:34:40][4830.3075017616][-sched-] Notice: sched: starting
[16/Jan/2009:20:34:40][4830.3083647168][-main-] Notice: driver: starting: nssock
[16/Jan/2009:20:34:40][4830.3031956368][-nssock:driver-] Notice: starting
[16/Jan/2009:20:34:40][4830.3031956368][-nssock:driver-] Notice: nssock: listening on 0.0.0.0:8000
It seems that the instance is restarting when you register, but there is no clue for me on the log of why is it doing this way. Does it happens every time you login, or just one time?
-- Héctor
I'm wondering if there are any optimizations that could be done to affect this. I'm also wondering if this computer is powerful enough to handle the dotlrn.
MemTotal: 515212 kB
MemFree: 8876 kB
Buffers: 3116 kB
Cached: 87276 kB
SwapCached: 1116 kB
Active: 415588 kB
Inactive: 37292 kB
HighTotal: 0 kB
HighFree: 0 kB
LowTotal: 515212 kB
LowFree: 8876 kB
SwapTotal: 859436 kB
SwapFree: 856140 kB
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 8
model name : Pentium III (Coppermine)
stepping : 10
cpu MHz : 996.778
cache size : 256 KB
I've also noticed that the /var/log/aolserver4/dotlrn/error.log
starts loading modules which tie up the system and causes it to become unreachable, temporarily.
debian:/var/log/aolserver4/dotlrn# tail error.log
[20/Jan/2009:09:24:32][3112.3083745472][-main-] Notice: ns_register_proc GET /grades-sheet-csv* rp
_invoke_proc {0 0 0 evaluation::generate_grades_sheet {}}
[20/Jan/2009:09:24:32][3112.3083745472][-main-] Notice: ns_register_proc POST /grades-sheet-csv* r
p_invoke_proc {0 0 0 evaluation::generate_grades_sheet {}}
[20/Jan/2009:09:24:32][3112.3083745472][-main-] Notice: ns_register_proc GET /finish-component-ele
ment* rp_invoke_proc {0 0 1 imsld::finish_component_element {}}
[20/Jan/2009:09:24:32][3112.3083745472][-main-] Notice: ns_register_proc POST /finish-component-el
ement* rp_invoke_proc {0 0 1 imsld::finish_component_element {}}
[20/Jan/2009:09:24:38][3112.3083745472][-main-] Notice: nsmain: AOLserver/4.5.0 running
[20/Jan/2009:09:24:38][3112.3083745472][-main-] Notice: nsmain: security info: uid=33, euid=33, gid
=33, egid=33
[20/Jan/2009:09:24:38][3112.3075115920][-sched-] Notice: sched: starting
[20/Jan/2009:09:24:38][3112.3083745472][-main-] Notice: driver: starting: nssock
[20/Jan/2009:09:24:38][3112.3032054672][-nssock:driver-] Notice: starting
[20/Jan/2009:09:24:38][3112.3032054672][-nssock:driver-] Notice: nssock: listening on 0.0.0.0:8000
debian:/var/log/aolserver4/dotlrn# tail error.log
[20/Jan/2009:09:28:28][3112.3044662160][-conn:2-] Warning: adding fs admin portlet to page - fs_adm
in_portlet
[20/Jan/2009:09:28:28][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_fs
[20/Jan/2009:09:28:28][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_forums
[20/Jan/2009:09:28:28][3112.3044662160][-conn:2-] Notice: dotlrn::mount_package: object_type apm_pa
ckage url /dotlrn/clubs/menlo1600/ object_id 5834 instance_name {Menlo 1600} package_type apm_appli
cation package_id 5834 name menlo1600 node_id 5833 directory_p t package_key dotlrn pattern_p t par
ent_id 2149
[20/Jan/2009:09:28:29][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_calendar
[20/Jan/2009:09:28:29][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_faq
[20/Jan/2009:09:28:29][3112.3044662160][-conn:2-] Notice: apm_invoke_callback_proc: invoking callba
ck after-instantiate with command news::install::after_instantiate -package_id 5982
[20/Jan/2009:09:28:29][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_news
[20/Jan/2009:09:28:29][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_static
[20/Jan/2009:09:28:30][3112.3044662160][-conn:2-] Notice: Added applet:::: dotlrn_bm
debian:/var/log/aolserver4/dotlrn#
I left the instance up all day yesterday. I hit it and hammered it at the same time from 2 different computers. Once I restarted it at the beginning it did stay up.
I shut it down late last night and fired it back up this morning. After about 10 minutes I went to the other computer and it errored. I tried it again, shortly after that and it was up. So I'm not sure that it will continue to be stable but for now, it's doing what it was intended to do.
thanks.
Just to keep you posted. We have been in contact with the aolserver maintainer for debian for a while now. Similar incidences have been discussed over at the aolserver list, see e.g. http://article.gmane.org/gmane.comp.web.aolserver/15470.
To cut it short: the issue you encountered has to do with a fundamental conflict between the binary-level coupling of AOLServer core and its modules, on the one hand, and a packaging mechanism with dependency structuring as debian's, on the other hand. In situations of debian package *updates* (aolserver4-core, for instance), you risk running into situations that the module binaries delivered by the debian module packages (aolserver4-nscache etc.) are incompatible with the new core, causing faults of all kind. The inverse (old core, new module) might also occur but is less probable.
Anyways, the debian maintainer came up with a fix to guarantee binary compatibility of core and modules, starting with the upcoming 4.5.1, by playing an elegant trick on the debian packaging infrastructure.
Cheers
//stefan