Forum OpenACS Development: Re: install issue due to silent error

Collapse
4: Re: install issue due to silent error (response to 1)
Posted by Benjamin Brink on 08/08/14 07:02 AM

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
5: Re: install issue due to silent error (response to 4)
Posted by Benjamin Brink on 08/08/14 07:04 AM
Although tcllib was flagged in one case with tcl/zz-postload.tcl, both cases were equivalently set, only differing in the instance name.
Collapse
6: Re: install issue due to silent error (response to 4)
Posted by Benjamin Brink on 08/08/14 07:24 AM
The truncated log lines should have skipped truncating sql. If it's helpful, I can repost with the full sql logged..