Forum OpenACS Q&A: Re: naviserver signal 11 core backtrace (revproxy)
Posted by
Marty Israelsen
on 04/20/22 01:09 AM
Here is another core dump with logging for connchan.c turned on -- See "SIGNAL 11 HERE" below for reference. ... [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes recvSockState 0001 (driver nssock_v4) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan read returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): WS: send msgLen toSend 16384 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend try to send [0] 16384 bytes (total 16384) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend NsDriverSend returned result 16384 errorState 1 --- Success [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend check partialResult 16384 nSent 16384 toSend 0 partial ? 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ### check result 16384 == -1 || 16384 == 16384 (partial 0 && ok 1) => try again 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): ... buffered 1 buffedLen 0 msgLength 16384 everything was sent, remaining 0, (BYTES from 98304 to 1146 88) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan write returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc Tcl eval <::revproxy::spool> returned <1> [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): NsTclConnChanProc <::revproxy::spool conn108122 conn108123 http://east-intra-node-pages/content/js/pag e-content-admin-announcements~page-content1-edit-related-links~page-edit-favorites~page-news-edit~8b5ce8cf.js?user_id=46843 {-timeout 0 -sendtimeout 0.0 -receivetimeou t 0.5} 0 r> numeric result 1 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc why r (1) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes recvSockState 0001 (driver nssock_v4) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan read returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): WS: send msgLen toSend 16384 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend try to send [0] 16384 bytes (total 16384) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend NsDriverSend returned result 16384 errorState 1 --- Success [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend check partialResult 16384 nSent 16384 toSend 0 partial ? 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ### check result 16384 == -1 || 16384 == 16384 (partial 0 && ok 1) => try again 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): ... buffered 1 buffedLen 0 msgLength 16384 everything was sent, remaining 0, (BYTES from 114688 to 131 072) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan write returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc Tcl eval <::revproxy::spool> returned <1> [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): NsTclConnChanProc <::revproxy::spool conn108122 conn108123 http://east-intra-node-pages/content/js/pag e-content-admin-announcements~page-content1-edit-related-links~page-edit-favorites~page-news-edit~8b5ce8cf.js?user_id=46843 {-timeout 0 -sendtimeout 0.0 -receivetimeou t 0.5} 0 r> numeric result 1 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc why r (1) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes recvSockState 0001 (driver nssock_v4) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan read returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): WS: send msgLen toSend 16384 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend try to send [0] 16384 bytes (total 16384) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend NsDriverSend returned result 16384 errorState 1 --- Success [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend check partialResult 16384 nSent 16384 toSend 0 partial ? 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ### check result 16384 == -1 || 16384 == 16384 (partial 0 && ok 1) => try again 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): ... buffered 1 buffedLen 0 msgLength 16384 everything was sent, remaining 0, (BYTES from 147456 to 163 840) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan write returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc Tcl eval <::revproxy::spool> returned <1> [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): NsTclConnChanProc <::revproxy::spool conn108122 conn108123 http://east-intra-node-pages/content/js/pag e-content-admin-announcements~page-content1-edit-related-links~page-edit-favorites~page-news-edit~8b5ce8cf.js?user_id=46843 {-timeout 0 -sendtimeout 0.0 -receivetimeou t 0.5} 0 r> numeric result 1 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc why r (1) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan exists returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes recvSockState 0001 (driver nssock_v4) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan NsDriverRecv 16384 bytes [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 ns_connchan read returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): WS: send msgLen toSend 16384 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend try to send [0] 16384 bytes (total 16384) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend NsDriverSend returned result 0 errorState 1 --- resource temporarily una vailable [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ConnchanDriverSend would block, no timeout configured, origLength 16384 still to send 16384 already sent 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): ... keep for later 16384 bytes of 16384 (buffered 16384) will be BYTES from 163840 to 180224 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan write returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108123 ns_connchan callback returns 0 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc Tcl eval <::revproxy::spool> returned <2> [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): NsTclConnChanProc <::revproxy::spool conn108122 conn108123 http://east-intra-node-pages/content/js/pag e-content-admin-announcements~page-content1-edit-related-links~page-edit-favorites~page-news-edit~8b5ce8cf.js?user_id=46843 {-timeout 0 -sendtimeout 0.0 -receivetimeou t 0.5} 0 r> numeric result 2 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): conn108122 NsTclConnChanProc client requested to CANCEL (suspend) callback 0x7f918c643260 [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Debug(connchan): e="4548"q\x88\xc4 NsTclConnChanProc why r (1) [19/Apr/2022:16:26:27][1.7f926ffff700][-socks-] Fatal: received fatal signal 11 <==== SIGNAL 11 HERE ORA-24550: signal received: [si_signo=6] [si_errno=0] [si_code=-6] [si_int=0] [si_ptr=(nil)] [si_addr=0x1] kpedbg_dmp_stack()+396<-kpeDbgCrash()+204<-kpeDbgSignalHandler()+113<-skgesig_sigactionHandler()+258<-__sighandler()<-gsignal()+203<-abort()+299<-Ns_LogTime()<-Tcl_Pan icVA()+189[19/Apr/2022:16:26:27][1.7f933bfff700][-conn:east_intra:default:25:89397-] Debug(connchan): ns_connchan open http://east-intra-node-pages/content/js/page-con tent-admin-announcements~._src_c.js?user_id=46843 => conn108124 [19/Apr/2022:16:26:27][1.7f933bfff700][-conn:east_intra:default:25:89397-] Debug(connchan): conn108124 ConnchanDriverSend try to send [0] 82 bytes (total 1439) [19/Apr/2022:16:26:27][1.7f933bfff700][-conn:east_intra:default:25:89397-] Debug(connchan): conn108124 ConnchanDriverSend NsDriverSend returned result 1439 errorState 0 --- operation now in progress [19/Apr/2022:16:26:27][1.7f933bfff700][-conn:east_intra:default:25:89397-] Debug(connchan): conn108124 ConnchanDriverSend check partialResult 1439 nSent 1439 toSend 0 partial ? 0 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:conf-] Notice: nsmain: NaviServer/4.99.23 (tar-4.99.23) starting [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:conf-] Notice: nsmain: security info: uid=0, euid=0, gid=0, egid=0 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:conf-] Notice: nsmain: Tcl version: 8.6.11 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:conf-] Notice: nsmain: max files: soft limit 1048576, hard limit 1048576 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:conf-] Warning: nsmain: current limit of maximum number of files > FD_SETSIZE (1024), select() calls should not be used [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: pool default: queueLength 1940 low water 194 high water 1940 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: pool monitor: queueLength 95 low water 9 high water 76 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: pool image: queueLength 94 low water 9 high water 75 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: nsd/init.tcl[east_intra]: booting virtual server: Tcl system encoding: "utf-8" [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: modload: loading module nslog from file /usr/local/ns/bin/nslog.so [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: nslog: opened '/web/logs/access.log' [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: modload: loading module nsdb from file /usr/local/ns/bin/nsdb.so [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: modload: loading module ns/db/driver/postgres from file /usr/local/ns/bin/nsdbpg.so [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: nsdbpg: version 2.6 loaded, based on PostgreSQL 14.2 (Ubuntu 14.2-1.pgdg20.04+1) and libbpq 140002 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: dbinit: set LogMinDuration for pool pool1 to 0.010000 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: dbinit: set LogMinDuration for pool pool2 to 0.010000 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: modload: loading module ns/db/driver/oracle from file /usr/local/ns/bin/nsoracle.so [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: oracle driver LobBufferSize = 32768 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: oracle driver PrefetchRows = 0 [19/Apr/2022:16:26:43][1.7f38c43d8800][-main:east_intra-] Notice: oracle driver PrefetchMemory = 0 ... ... ... ... Here is the core backtrace that goes with the logging above. (gdb) bt full #0 __GI_abort () at abort.c:107 act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {18446744073709551615 <repeats 16 times>}}, sa_flags = 0, sa_restorer = 0x0} sigs = {__val = {32, 0 <repeats 15 times>}} #1 0x00007f93da4b3064 in skgdbgcra () from /opt/oracle/instantclient_21_1/libclntsh.so.21.1 No symbol table info available. #2 0x00007f93da480693 in skgesigCrash () from /opt/oracle/instantclient_21_1/libclntsh.so.21.1 No symbol table info available. #3 0x00007f93da4809de in skgesig_sigactionHandler () from /opt/oracle/instantclient_21_1/libclntsh.so.21.1 No symbol table info available. #4 <signal handler called> No locals. #5 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 set = {__val = {21511, 80, 140266920991088, 12551935152, 140264708986032, 140260746985472, 80, 14430764422706361600, 140268751068288, 140268751068288, 140266920991296, 140273161794766, 0, 24, 140264708986032, 140267325079688}} pid = <optimized out> tid = <optimized out> ret = <optimized out> #6 0x00007f93e3d58859 in __GI_abort () at abort.c:79 save_stage = 1 act = {__sigaction_handler = {sa_handler = 0x5626d738c6c0, sa_sigaction = 0x5626d738c6c0}, sa_mask = {__val = {140266786786960, 140266920991408, 1, 0, 140267325079680, 0, 140264708986032, 0, 14430764422706361600, 140266920991488, 140273161786694, 450971566080, 140266920991520, 140273162413039, 12884901888, 140267325079680}}, sa_flags = 1744834192, sa_restorer = 0x7f92dd149c80} sigs = {__val = {32, 0 <repeats 15 times>}} #7 0x00007f93e3fad995 in Panic (fmt=0x7f93e40463ef "received fatal signal %d") at log.c:943 ap = {{gp_offset = 8, fp_offset = 48, overflow_arg_area = 0x7f926fffdc00, reg_save_area = 0x7f926fffdb40}} #8 0x00007f93e3c21f8d in Tcl_PanicVA (format=<optimized out>, argList=argList@entry=0x7f926fffdc40) at /usr/local/src/tcl8.6.11/generic/tclPanic.c:99 arg1 = 0xb <error: Cannot access memory at address 0xb> arg2 = 0x0 arg3 = 0x7f93e3d7903b <__GI_raise+203> "H\213\204$\b\001" arg4 = 0x0 arg5 = 0x7f926fffd8c0 "\aT" arg6 = 0x246 <error: Cannot access memory at address 0x246> arg7 = 0xbffffffff <error: Cannot access memory at address 0xbffffffff> arg8 = 0x0 #9 0x00007f93e3c220ff in Tcl_Panic (format=<optimized out>) at /usr/local/src/tcl8.6.11/generic/tclPanic.c:160 argList = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7f926fffdd38, reg_save_area = 0x7f926fffdc60}} #10 0x00007f93e401791b in Abort (signal=11) at unix.c:1119 No locals. #11 <signal handler called> No locals. #12 0x00007f93e3fe5538 in RunTraces (itPtr=0x7f92680ffca0, why=NS_TCL_TRACE_CREATE) at tclinit.c:2388 tracePtr = 0x6665726946203130 servPtr = 0x7f93240001e0 __PRETTY_FUNCTION__ = "RunTraces" #13 0x00007f93e3fe4c8b in PopInterp (servPtr=0x7f93240001e0, interp=0x7f9268082690) at tclinit.c:1963 --Type <RET> for more, q to quit, c to continue without paging-- itPtr = 0x7f92680ffca0 hPtr = 0x7f91c90149c0 lock = 0x0 #14 0x00007f93e3fe2f35 in NsTclAllocateInterp (servPtr=0x7f93240001e0) at tclinit.c:503 itPtr = 0x7f9301ffa37f #15 0x00007f93e3f8922e in NsTclConnChanProc (UNUSED_sock=42, arg=0x7f918c9ec880, why=1) at connchan.c:601 interp = 0x7f926800d9b0 w = 0x7f93e40237d6 "r" localsock = 603979968 result = 0 script = {string = 0x7f926fffeb40 "::revproxy::spool conn108123 conn108122 client {-timeout 0 -sendtimeout 0.0 -receivetimeout 0.5} 0 r", length = 100, spaceAvl = 200, staticSpace = "::revproxy::spool conn108123 conn108122 client {-timeout 0 -sendtimeout 0.0 -receivetimeout 0.5} 0 r\000age\000\354\377o\005\000\000\000\250\065\002\344\223\177\000\000er_i\v\000\000\000\020\354\377o\222\177\000\000|\323\372\343\223\177\000\000\000\000\000\000\000\000\000\000\060\354\377o\222\177\000\000\266\231\003\344\223\177\000\000\300\354\377o\005\000\000\000\200\354\377o\222\177\000\000\066\205\315\343\223\177\000\000\020\000\000\000\060\000\000"} channelName = 0x7f92682e9ec0 "e=\"4548\"q\210\304" logEnabled = true scriptCmdNameLength = 17 whenBuffer = "r\000\000\000\000" servPtr = 0x7f93240001e0 cbPtr = 0x7f918c9ec880 success = true __PRETTY_FUNCTION__ = "NsTclConnChanProc" #16 0x00007f93e3fccaba in SockCallbackThread (UNUSED_arg=0x0) at sockcallback.c:531 stop = false pollTimeout = 30000 nfds = 3 now = {sec = 1650407187, usec = 901622} diff = {sec = 0, usec = 0} c = 0 '\000' when = {1, 2, 20} events = {1, 4, 2} n = 2 i = 0 isNew = 0 maxPollfds = 100 cbPtr = 0x7f918c645480 nextPtr = 0x0 hPtr = 0x7f91d8bc9510 search = {tablePtr = 0x7f93e4070800 <activeCallbacks>, nextIndex = 11, nextEntryPtr = 0x0} pfds = 0x7f92680012b0 #17 0x00007f93e3cd7538 in NsThreadMain (arg=0x7f92dd149c80) at thread.c:232 thrPtr = 0x7f92dd149c80 #18 0x00007f93e3cd92b7 in ThreadMain (arg=0x7f92dd149c80) at pthread.c:870 No locals. #19 0x00007f93e3637609 in start_thread (arg=<optimized out>) at pthread_create.c:477 --Type <RET> for more, q to quit, c to continue without paging-- ret = <optimized out> pd = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140266920998656, 6551434630419898174, 140269370450814, 140269370450815, 140269370451008, 140266920996608, -6498833994629587138, -6499651029876023490}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = 0 #20 0x00007f93e3e55163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 No locals.
