Forum OpenACS Development: install issue due to silent error

Collapse
Posted by Benjamin Brink on
Could this be due to a recent change in acs-bootstrap-installer?

The installation process worked 21 July.

For the last couple of days (at least) the following occurs during installation on ubuntu 14.04 LTS using the scripts at http://github.com/gustafn/install-ns and on freebsd10 using a modified script.

Server starts fine.

After entering initial config the following page looks like this:

-- snip --
OpenACS Installation
Installing the OpenACS kernel data model...

CREATE VIEW
..
0
(1 row)
acs_privilege__add_child
--------------------------
0
(1 row)

Done installing the OpenACS kernel data model.

Installing Kernel 5.8.1d5

Installed Kernel, version 5.8.1d5.

Package enabled.

Loading package .info files.

Done loading package .info files

Installing OpenACS Core Services

At least one core package has an unsatisifed dependency. No packages have been installed. Here's what the APM has computed:

{acs-api-browser /var/www/oacs-5-8b/packages/acs-api-browser/acs-api-browser.info {} {} {{acs-api-browser 5.8.1d2}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-automated-testing /var/www/oacs-5-8b/packages/acs-automated-testing/acs-automated-testing.info {} {} {{acs-automated-testing 5.8.1d2}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-bootstrap-installer /var/www/oacs-5-8b/packages/acs-bootstrap-installer/acs-bootstrap-installer.info {} {} {{acs-bootstrap-installer 5.8.1d3}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-reference /var/www/oacs-5-8b/packages/acs-reference/acs-reference.info {} {} {{acs-reference 5.8.1d2}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-service-contract /var/www/oacs-5-8b/packages/acs-service-contract/acs-service-contract.info {} {} {{acs-service-contract 5.8.1d2}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-templating /var/www/oacs-5-8b/packages/acs-templating/acs-templating.info {} {} {{acs-templating 5.8.1d2}} {{acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {acs-translations /var/www/oacs-5-8b/packages/acs-translations/acs-translations.info {} {} {{acs-translations 5.8.1d2}} {} t {Package satisfies dependencies.}} {acs-tcl /var/www/oacs-5-8b/packages/acs-tcl/acs-tcl.info {} {} {{acs-tcl 5.8.1d6}} {{acs-bootstrap-installer 5.8.1d1} {acs-kernel 5.8.1d1}} t {Package satisfies dependencies.}} {ref-countries /var/www/oacs-5-8b/packages/ref-countries/ref-countries.info {} {} {{ref-countries 5.8.1d2}} {{acs-kernel 5.8.1d1} {acs-reference 5.8.1d1}} t {Package satisfies dependencies.}} {ref-language /var/www/oacs-5-8b/packages/ref-language/ref-language.info {} {} {{ref-language 5.8.1d2}} {{acs-kernel 5.8.1d1} {acs-reference 5.8.1d1}} t {Package satisfies dependencies.}} {ref-timezones /var/www/oacs-5-8b/packages/ref-timezones/ref-timezones.info {} {} {{ref-timezones 5.8.1d2}} {{acs-kernel 5.8.1d1} {acs-reference 5.8.1d1}} t {Package satisfies dependencies.}} {search /var/www/oacs-5-8b/packages/search/search.info {} {} {{search 5.8.1d3}} {{acs-service-contract 5.8.1d1}} t {Package satisfies dependencies.}} {acs-content-repository /var/www/oacs-5-8b/packages/acs-content-repository/acs-content-repository.info {} {} {{acs-content-repository 5.8.1d6}} {{acs-kernel 5.8.1d1} {acs-service-contract 5.8.1d1} {search 5.8.1d1}} t {Package satisfies dependencies.}} {acs-core-docs /var/www/oacs-5-8b/packages/acs-core-docs/acs-core-docs.info {} {} {{acs-core-docs 5.8.1d1}} {{acs-kernel 5.8.1d1} {acs-tcl 5.8.1d1}} t {Package satisfies dependencies.}} {acs-lang /var/www/oacs-5-8b/packages/acs-lang/acs-lang.info {} {} {{acs-lang 5.8.1d3}} {{acs-kernel 5.8.1d1} {acs-translations 5.8.1d1} {ref-countries 5.8.1d1} {ref-language 5.8.1d1} {ref-timezones 5.8.1d1}} t {Package satisfies dependencies.}} {acs-admin /var/www/oacs-5-8b/packages/acs-admin/acs-admin.info {} {} {{acs-admin 5.8.1d3}} {{acs-kernel 5.8.1d1} {acs-mail-lite 5.8.1d1}} f {{Requires acs-mail-lite of version >= 5.8.1d1.}}} {acs-authentication /var/www/oacs-5-8b/packages/acs-authentication/acs-authentication.info {} {} {{acs-authentication 5.8.1d2}} {{acs-kernel 5.8.1d1} {acs-service-contract 5.8.1d1} {acs-mail-lite 5.8.1d1}} f {{Requires acs-service-contract of version >= 5.8.1d1.} {Requires acs-mail-lite of version >= 5.8.1d1.}}} {acs-messaging /var/www/oacs-5-8b/packages/acs-messaging/acs-messaging.info {} {} {{acs-messaging 5.8.1d1}} {{acs-content-repository 5.8.1d1} {acs-kernel 5.8.1d1} {acs-mail-lite 5.8.1d1}} f {{Requires acs-content-repository of version >= 5.8.1d1.} {Requires acs-mail-lite of version >= 5.8.1d1.}}} {acs-subsite /var/www/oacs-5-8b/packages/acs-subsite/acs-subsite.info {} {} {{acs-subsite 5.8.1d3}} {{acs-authentication 5.8.1d1} {acs-content-repository 5.8.1d1} {acs-kernel 5.8.1d1} {acs-lang 5.8.1d1} {acs-mail-lite 5.8.1d1} {acs-tcl 5.8.1d1}} f {{Requires acs-authentication of version >= 5.8.1d1.}}} {openacs-default-theme /var/www/oacs-5-8b/packages/openacs-default-theme/openacs-default-theme.info {} {} {{openacs-default-theme 5.8.1d2}} {{acs-subsite 5.8.1d1}} f {{Requires acs-subsite of version >= 5.8.1d1.}}}

-- snip --

Log file shows only this warning:

[07/Aug/2014:16:21:23][3433.7f85ab293740][-main-] Warning: nsmain: rl_cur > FD_SETSIZE

and only this error:

[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: ***Installing Kernel 5.8.1d5
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Installed Kernel, version 5.8.1d5.
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Package enabled.
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: apm_scan_packages: Scanning for new unregistered packages...
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Skipping the directory "CVS".
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-tcl init file utilities-init.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-tcl init file site-nodes-init.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/apm-callback-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/application-group-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/approval-expiration-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/attribute-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/callback-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/email-image-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/group-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/group-type-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/package-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/party-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/plpgsql-utility-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/plsql-utility-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/rel-segments-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/rel-types-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/relation-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/subsite-callback-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/subsite-navigation-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Loading acs-subsite/tcl/subsite-procs.tcl
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: apm_scan_packages: Scanning for new unregistered packages...
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Notice: Skipping the directory "CVS".
[07/Aug/2014:16:22:04][3433.7f8597efe700][-conn:oacs-5-8b:1] Error: Error sourcing /var/www/oacs-5-8b/packages/acs-bootstrap-installer/installer/install.tcl:
invalid command name "auth::create_local_account_helper"
while executing
"auth::create_local_account_helper $email $first_names $last_name $password "" "" "" "t" "approved" "" $username "
("uplevel" body line 16)
invoked from within
"uplevel 1 $transaction_code "
(procedure "db_transaction" line 1)
invoked from within
"db_transaction {

# Can't use auth::create_user
# Operation GetParameters is not implemented in 'local' implementation of contract 'auth_r..."
invoked from within
"if { ![db_string user_exists {
select count(*) from parties where email = lower(:email)
}] } {

db_transaction {

# Can't use auth::crea..."
(file "/var/www/oacs-5-8b/packages/acs-bootstrap-installer/installer/install.tcl" line 58)
invoked from within
"source $__file "

Collapse
Posted by Benjamin Brink on
The oacs-5-8b was used so I can compare with a working install from 21 July.

I suspected environmental variables, but a working and nonworking share the same ubuntu, only differing in the config.tcl file and oacs-5-8 files from cvs.

Collapse
Posted by Benjamin Brink on
I had also spent some time diagnosing on freebsd10 with a working diagnosis that there was a silent error with clang or gcc build, since there is a local working installation from a few days ago on ubuntu.. and freebsd10 no longer includes gcc by default..
Collapse
Posted by Benjamin Brink on

After setting debug to true in ns config.tcl files, I wrote a little tcl to lob off the first 42 characters of each error.log file for the length of the problem case (plus a few lines) and edited both instances (cases) to appear to use 'oacs-5-8' to minimize changes.

Here's the diff between the two error.log files:

155c155
< [-main-] Dev: config: ns/server/oacs-5-8/module/nssock:port value=8000 min=0 max=65535 default=80 (int)
---
> [-main-] Dev: config: ns/server/oacs-5-8/module/nssock:port value=8002 min=0 max=65535 default=80 (int)
192a193
> [-main-] Notice: 'ns_info tcllib ' is deprecated. Use 'ns_server ?-server s? tcllib' instead. 
195d195
< [-main-] Notice: bootstrap begin encoding utf-8
216c216
< [-main-] Debug: 0x2596360 convert type none to sql < select count(*) from pg_class>
---
> [-main-] Debug: 0x21f8b40 convert type none to sql < select count(*) from pg_class>
325d324
< [-main-] Notice: Loading acs-tcl/tcl/http-client-procs.tcl
354c353
< [-main-] Debug: nsproxy: slave 13439 started
---
> [-main-] Debug: nsproxy: slave 14069 started
388c387
< [-main-] Debug: 0x2bcf7a0 convert type none to sql <
---
> [-main-] Debug: 0x280d1b0 convert type none to sql <
403,465d401
< [-main-] Debug: NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count --> using default SQL
< [-main-] Debug: 0x2bcf7a0 REUSE sql
< [-main-] Notice: nsdbpg: Querying '
< ass
< e_nodes') and
< relkind = 'r';'
< [-main-] Notice: dbinit: sql(localhost::oacs-5-8): '
< ass
< e_nodes') and
< relkind = 'r'
< 
< [-main-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count
< [-main-] Debug: 0x2bcc4a0 convert type none to sql <
< 
< 
< 
< 
< [-main-] Notice: nsdbpg: Querying '
< 
< 
< 
< [-main-] Notice: dbinit: sql(localhost::oacs-5-8): '
< 
< 
< 
< 
< [-main-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.apm-procs.apm_package_installed_p_not_cached.apm_package_installed_p
< [-main-] Debug: 0x2bcad00 convert type none to sql <
< 
< 
< 
< 
< y_privilege_map m, users u, acs_magic_objects amo
< amo.object_id
< curity_context_root'
< .user_id
< 'admin')
< 
< 
< [-main-] Notice: nsdbpg: Querying '
< 
< 
< 
< 
< y_privilege_map m, users u, acs_magic_objects amo
< amo.object_id
< curity_context_root'
< .user_id
< 'admin');'
< [-main-] Notice: dbinit: sql(localhost::oacs-5-8): '
< 
< 
< 
< 
< y_privilege_map m, users u, acs_magic_objects amo
< amo.object_id
< curity_context_root'
< .user_id
< 'admin')
< 
< 
< [-main-] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.acs-kernel-procs.ad_acs_administrator_exists_p.admin_exists_p
< [-main-] Debug: Verifying Installation: Kernel Installed? 1  An Administrator? 0
468c404,405
< [-main-] Notice: Sourcing files for postload..  tcllib = '/var/www/oacs-5-8/tcl'
---
> [-main-] Notice: 'ns_info tcllib ' is deprecated. Use 'ns_server ?-server s? tcllib' instead. 
> [-main-] Notice: Sourcing files for postload... tcllib == '/var/www/oacs-5-8/tcl'
483,488c420,425
< [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-main-] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0x122a890
< [-main-] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x22c1fb0
< [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f29708de1e0 a:0x22c1f30
---
> [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-main-] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0xe85890
> [-main-] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x1f83560
> [-main-] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54b687f1e0 a:0x1f834e0
497,500d433
< [-driver:nssock-] Notice: nssock: listening on 200.46.204.54:8000
< [-driver:nssock-] Notice: driver: accepting connections
< [-main-] Notice: nsmain: NaviServer/4.99.6 running
< [-main-] Notice: nsmain: security info: uid=1001, euid=1001, gid=1001, egid=1001
502a436,439
> [-driver:nssock-] Notice: nssock: listening on 200.46.204.54:8002
> [-main-] Notice: nsmain: NaviServer/4.99.6 running
> [-main-] Notice: nsmain: security info: uid=1001, euid=1001, gid=1001, egid=1001
> [-driver:nssock-] Notice: driver: accepting connections
506,512d442
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nslog:initinterp /var/www/oacs-5-8/log//access.log
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0x122a890
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x22c1fb0
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f29708de1e0 a:0x22c1f30
514,524c444,456
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f297906d4a0 a:(nil)
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0x122a890
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x22c1fb0
< [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f29708de1e0 a:0x22c1f30
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: allocate ns:tcltrace ns_init
< [-conn:oacs-5-8:1] Notice: thread initialized (0.271512 secs)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsproxy:cleanup a:(nil)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsdb:releasehandles a:(nil)
< [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate ns:tcltrace ns_cleanup
---
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nslog:initinterp /var/www/oacs-5-8/log//access.log
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54bef794a0 a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0xe85890
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create nsdb:initinterp a:0xe85890
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x1f83560
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create nsproxy:initinterp a:0x1f83560
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54b687f1e0 a:0x1f834e0
> [-conn:oacs-5-8:0] Debug: ns:interptrace[oacs-5-8]: create p:0x7f54b687f1e0 a:0x1f834e0
526c458
< [-conn:oacs-5-8:0] Notice: thread initialized (0.275749 secs)
---
> [-conn:oacs-5-8:0] Notice: thread initialized (0.300907 secs)
---
> [-conn:oacs-5-8:0] Notice: thread initialized (0.300907 secs)
530,554c462,999
< [-nsproxy:reap-] Debug: nsproxy: slave 13439 closed
< [-main-] Notice: nsmain: NaviServer/4.99.6 stopping
< [-main-] Notice: [driver:nssock]: stopping
< [-main-] Notice: server [oacs-5-8]: stopping
< [-conn:oacs-5-8:0] Debug: CondTimedWait returned an unexpected result, maybe shutdown?
< [-conn:oacs-5-8:1] Debug: CondTimedWait returned an unexpected result, maybe shutdown?
< [-conn:oacs-5-8:1] Notice: exiting: shutdown pending
< [-conn:oacs-5-8:0] Notice: exiting: shutdown pending
< [-driver:nssock-] Notice: exiting
< [-main-] Notice: server [oacs-5-8]: connection threads stopped
< [-main-] Notice: driver: stopping writer and spooler threads
< [-main-] Debug: writer1: triggering shutdown
< [-writer1-] Notice: exiting
< [-main-] Debug: writer0: triggering shutdown
< [-writer0-] Notice: exiting
< [-main-] Notice: sched: shutdown pending
< [-sched-] Notice: sched: shutdown started
< [-sched-] Notice: sched: shutdown complete
< [-main-] Notice: [driver:nssock]: stopped
< [-shutdown-] Notice: nslog: closed '/var/www/oacs-5-8/log//access.log'
< [-main-] Notice: nsproxy: shutdown started
< [-nsproxy:reap-] Notice: exiting
< [-main-] Notice: nsproxy: shutdown complete
< [-main-] Dev: config: ns/parameters:pidfile value=/var/www/oacs-5-8/log//nsd.pid (string)
< [-main-] Notice: nsmain: NaviServer/4.99.6 exiting
---
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: allocate ns:tcltrace ns_init
> [-conn:oacs-5-8:1] Notice: thread initialized (0.302961 secs)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsproxy:cleanup a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsdb:releasehandles a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate ns:tcltrace ns_cleanup
> [-driver:nssock-] Debug: [1] dequeue thread connPtr 0xea1080 idle 2 state 4 create 0
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: allocate ns:tcltrace ns_init
> [-conn:oacs-5-8:1] Dev: config: ns/server/oacs-5-8/adp:DefaultParser value= (string)
> [-conn:oacs-5-8:1] Dev: config: ns/threads:StackSize value=1048576 (string)
> [-conn:oacs-5-8:1] Debug: NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count --> using default SQL
> [-conn:oacs-5-8:1] Debug: 0x7f54ac00f040 convert type none to sql <
> ass
> le_name) and
> relkind = 'r'
> 
> [-conn:oacs-5-8:1] Notice: nsdbpg: Querying '
> ass
> _packages') and
> relkind = 'r';'
> [-conn:oacs-5-8:1] Notice: dbinit: sql(localhost::oacs-5-8): '
> ass
> _packages') and
> relkind = 'r'
> 
> [-conn:oacs-5-8:1] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count
> [-conn:oacs-5-8:1] Dev: config: ns/server/oacs-5-8/module/nssock:hostname value=q.or97.net (string)
> [-conn:oacs-5-8:1] Dev: config: ns/server/oacs-5-8/module/nssock:port value=8002 (string)
> [-conn:oacs-5-8:1] Debug: Ns_ConnClose 0xea1080 stream 000040 chunk 000000 via writer 000000 sockPtr 0x7f54a0001230
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsproxy:cleanup a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate nsdb:releasehandles a:(nil)
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: deallocate ns:tcltrace ns_cleanup
> [-conn:oacs-5-8:1] Debug: [1] end of job, waiting 0 current 2 idle 1 ncons 999 fromQueue 0 start 1407471277.165986 1407471277.170933 accept 0.004947 
queue 0.001134 filter 0.020655 run 0.022000 netrun 0.001345 total 0.023134
> [-driver:nssock-] Debug: [1] dequeue thread connPtr 0xea1080 idle 2 state 4 create 0
> [-conn:oacs-5-8:1] Debug: ns:interptrace[oacs-5-8]: allocate ns:tcltrace ns_init
> [-conn:oacs-5-8:1] Debug: NO FULLQUERY FOR dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count --> using default SQL
> [-conn:oacs-5-8:1] Debug: 0x7f54ac00f040 REUSE sql
> [-conn:oacs-5-8:1] Notice: nsdbpg: Querying '
> ass
> _objects') and
> relkind = 'r';'
> [-conn:oacs-5-8:1] Notice: dbinit: sql(localhost::oacs-5-8): '
> ass
> _objects') and
> relkind = 'r'
> 
> [-conn:oacs-5-8:1] Debug: db_exec: timing 0 seconds nsdb0 0or1row dbqd.acs-tcl.tcl.00-database-procs.db_table_exists.table_count
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:User value=nsadmin (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:DataSource value=localhost::oacs-5-8 (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:Password value= (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:DataSource value=localhost::oacs-5-8 (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:Driver value=postgres (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/driver/postgres:pgbin value= (string)
> [-conn:oacs-5-8:1] Dev: config: ns/db/pool/pool1:DataSource value=localhost::oacs-5-8 (string)
> [-conn:oacs-5-8:1] Notice: CREATE VIEW
> 
> [-conn:oacs-5-8:1] Notice: CREATE SEQUENCE
> 
> [-conn:oacs-5-8:1] Notice: CREATE VIEW
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
> 
> [-conn:oacs-5-8:1] Notice: CREATE FUNCTION
..

Collapse
Posted by Benjamin Brink on
Although tcllib was flagged in one case with tcl/zz-postload.tcl, both cases were equivalently set, only differing in the instance name.
Collapse
Posted by Benjamin Brink on
The truncated log lines should have skipped truncating sql. If it's helpful, I can repost with the full sql logged..
Collapse
Posted by Gustaf Neumann on
This was quite a subtle bug (took me 2h to understand what's going on). The problem was that probably by accident, the info file of acs-mail-lite package was changed on july 25 to include false for the initial installs. The initial loader just loads these files. But since other essential packages depend on this, the package dependencies could not be satisfied.

The fix is trival: [1]

To recover from the broken install, do something along these lines:

dropdb -U nsadmin oacs-5-8
createdb -U nsadmin -E UNICODE oacs-5-8
psql -U nsadmin -d oacs-5-8 -tAc "create extension hstore"

On the next opportunity, i'll try to improve the error report.

all the best
-g

[1] http://cvs.openacs.org/changelog/OpenACS?cs=oacs-5-8%3Agustafn%3A20140808125705

Collapse
Posted by Benjamin Brink on
Excellent, Gustaf. Quite subtle indeed. Thank you!
Collapse
Posted by Gustaf Neumann on
The error reporting of the bootstrap loader is now improved. Firstly, it formats now the missing dependencies in a human oriented manner. Secondly, for several more load operations, errors are reported directly to the installer window.

It should be easier now to figure out, what's going on if something goes wrong....

all the best
-gustaf

Collapse
Posted by Benjamin Brink on
Excellent!

It's such a luxury to work with a system that provides useful information when things break.

Collapse
Posted by Antonio Pisano on
I Think I take the blame for this issue... Don't really know why that flag got false.

Thanks for the fix

Collapse
Posted by Gustaf Neumann on
no worry, shit happens. maybe the .info file generator has a flaw. -gustaf
Collapse
Posted by Benjamin Brink on
Antonio, you're not to blame. For all we know, there was a glitch in a cvs process that caused it.

General code oversight that made it difficult to identify and trace certain start-up problems. The main thing is that an issue was identified and fixed, and similar issues will be recognized (and fixed) faster.

cheers,
Ben