Using the latest NaviServer head (last commit 2019-07-09) on Linux
(Ubuntu 16.04.2 LTS) and Tcl 8.6.9 (built from source), I'm getting
'make test' failures that I don't understand, primarily in http.test.
Can anyone advice, please? Brief failure messages are below, full
test output is attached.
Tests ended at Mon Jul 15 04:23:22 EDT 2019
all.tcl: Total 1391 Passed 1380 Skipped 8 Failed 3
Sourced 69 Test Files.
Files with failing tests: http.test ns_server.test
==== http-3.3new limits: too many headers FAILED
==== Contents of test case:
nstest::http -http 1.1 -getbody 1 -setheaders [split [string repeat xy
1024] ""] GET /limits
---- Result was:
ns_http failed: recv failed
---- Result should have been (exact matching):
414
==== http-3.3new FAILED
==== http-5.5 check encoding ns_conn content POST, binary FAILED
==== Contents of test case:
set string "Testing <????????>"
nstest::http -getbody 1 -setheaders {content-type text/html} POST /post
$string
---- Result was:
200 {utf-8 <text/html> A??ATesting <????????????????>Z??Z}
---- Result should have been (exact matching):
200 {utf-8 <text/html> A??ATesting <????????>Z??Z}
==== http-5.5 FAILED
==== ns_server-2.5 basic operation FAILED
---- Result was:
10
---- Result should have been (exact matching):
9
==== ns_server-2.5 FAILED
--
Andrew Piskorski <a...@piskorski.com>
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsthread'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsthread'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsd'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsd'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nssock'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nssock'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nscgi'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nscgi'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nscp'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nscp'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nslog'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nslog'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsperm'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsperm'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsdb'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsdb'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsdbtest'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsdbtest'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsssl'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsssl'
make[1]: Entering directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsproxy'
make[1]: Nothing to be done for 'all'.
make[1]: Leaving directory
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/nsproxy'
LD_LIBRARY_PATH="/usr/local/src/web/ns-head-pub/naviserver/nsd:/usr/local/src/web/ns-head-pub/naviserver/nsthread:/usr/local/src/web/ns-head-pub/naviserver/nsdb:/usr/local/src/web/ns-head-pub/naviserver/nsproxy:$LD_LIBRARY_PATH"
DYLD_LIBRARY_PATH="/usr/local/src/web/ns-head-pub/naviserver/nsd:/usr/local/src/web/ns-head-pub/naviserver/nsthread:/usr/local/src/web/ns-head-pub/naviserver/nsdb:/usr/local/src/web/ns-head-pub/naviserver/nsproxy:$DYLD_LIBRARY_PATH"
./nsd/nsd -u root -c -d -t
/usr/local/src/web/ns-head-pub/naviserver/tests/test.nscfg
/usr/local/src/web/ns-head-pub/naviserver/tests/all.tcl
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: try ::1 8000
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: configure LOOPBACK
::1
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: configure LISTENURL
http://[::1]:8000
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain: enable
progress statistics for uploads >= 1 bytes
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain:
NaviServer/4.99.18 (26eb09ce6111 default tip) starting
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain: security
info: uid=1010, euid=1010, gid=501, egid=501
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain: Tcl version:
8.6.9
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain: max files:
soft limit 1048576, hard limit 1048576
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Warning: nsmain: rl_cur
(1048576) > FD_SETSIZE (1024), select() calls should not be used
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice:
vhost[testvhost]: www.example.com:80 ->
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/vhosts/e/x/a/example.com/pages
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: pool
default: queueLength 97 low water 9 high water 77
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice:
nsd/init.tcl[testvhost]: booting virtual server: Tcl system encoding: "utf-8"
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: Using
ns_cache implemented as a Tcl proc
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: limits:
confLimit1: maxrun=99 maxwait=100 maxupload=10240000 timeout=60
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: limits:
confLimit2: maxrun=100 maxwait=100 maxupload=10240000 timeout=60
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice:
tcl[testvhost]: enabletclpages for {GET HEAD POST} requests
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: limits:
confLimit1: maxrun=99 maxwait=100 maxupload=10240000 timeout=60
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: limits:
confLimit2: maxrun=100 maxwait=100 maxupload=10240000 timeout=60
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Warning: ns_md,
ns_hmac, ns_hotp and ns_totp are not available
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost-] Notice: update
interpreter to epoch 1, trace deallocate, time 0.006376 secs
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Notice: pool
default: queueLength 96 low water 9 high water 76
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Notice:
nsd/init.tcl[testvhost2]: booting virtual server: Tcl system encoding: "utf-8"
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Notice: Using
ns_cache implemented as a Tcl proc
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Notice:
tcl[testvhost2]: enabletclpages for {GET HEAD POST} requests
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Warning: ns_md,
ns_hmac, ns_hotp and ns_totp are not available
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:testvhost2-] Notice: update
interpreter to epoch 1, trace deallocate, time 0.005821 secs
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: pool default:
queueLength 90 low water 9 high water 72
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: pool emergency:
queueLength 99 low water 9 high water 79
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
nsd/init.tcl[test]: booting virtual server: Tcl system encoding: "utf-8"
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: modload: loading
module nslog from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nslog/nslog.so
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: nslog: opened
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/access.log'
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: modload: loading
module nsdb from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nsdb/nsdb.so
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: modload: loading
module ns/db/driver/nsdbtest from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nsdbtest/nsdbtest.so
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: modload: loading
module nsproxy from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nsproxy/nsproxy.so
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: Using ns_cache
implemented as a Tcl proc
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: limits[test]:
confLimit1 -> GET /confLimit1
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: adp[test]:
mapped {GET HEAD POST} *.adp
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: adp[test]:
mapped {GET HEAD POST} *_adp
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: tcl[test]:
mapped {GET HEAD POST} *.tcl
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: limits[test]:
confLimit1 -> GET /confLimit1
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Warning: ns_md, ns_hmac,
ns_hotp and ns_totp are not available
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../tcl/nslog
is not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/modules/nslog
is not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../tcl/nsdb is
not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/modules/nsdb
is not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../tcl/nsproxy
is not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/modules/nsproxy
is not a readable directory (ignored)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main:test-] Notice: update
interpreter to epoch 1, trace deallocate, time 0.004852 secs
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: update interpreter to
epoch 1, trace none, time 0.004513 secs
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: modload: loading
module nssock from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nssock/nssock
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nssock:0: enable 3
spooler thread(s) for uploads >= 1025 bytes
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Warning: config:
ns/module/nssock:writerratelimit value=-1 below minimum, reset to 0
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nssock:0: enable 3
writer thread(s) for downloads >= 1026 bytes, bufsize=512 bytes, HTML streaming 0
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: modload: loading
module nsssl from file
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/../nsssl/nsssl
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl:0: enable 0
spooler thread(s)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Warning: config:
ns/module/nsssl:writerratelimit value=-1 below minimum, reset to 0
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl:0: enable 2
writer thread(s) for downloads >= 2048 bytes, bufsize=8192 bytes, HTML
streaming 0
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: OpenSSL OpenSSL
1.0.2g 1 Mar 2016 initialized
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl: disabling SSLv2
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl: disabling SSLv3
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl: version 2.1
loaded, based on OpenSSL 1.0.2g 1 Mar 2016
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsssl:0: adding
virtual host entry for host <minbari> location: https://minbari mapped to
server: test
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: Global driver has no
mapping from host to server (section 'nsssl' missing)
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nssock:0: adding
virtual host entry for host <test:8000> location: http://test:8000 mapped to
server: test
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nssock:0: adding
virtual host entry for host <testvhost:8000> location: http://testvhost:8000
mapped to server: testvhost
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nssock:0: adding
virtual host entry for host <testvhost2:8000> location: http://testvhost2:8000
mapped to server: testvhost2
[15/Jul/2019:04:21:46][1991.7feadaffd700][-driver:nsssl:0-] Notice: starting
[15/Jul/2019:04:21:46][1991.7feadaffd700][-driver:nsssl:0-] Notice: nsssl:0:
listening on [::1]:8443
[15/Jul/2019:04:21:46][1991.7feadaffd700][-driver:nsssl:0-] Notice: driver:
accepting connections
[15/Jul/2019:04:21:46][1991.7feada7fc700][-writer1-] Notice: writer1: accepting
connections
[15/Jul/2019:04:21:46][1991.7fead9ffb700][-writer0-] Notice: writer0: accepting
connections
[15/Jul/2019:04:21:46][1991.7fead97fa700][-driver:nssock:0-] Notice: starting
[15/Jul/2019:04:21:46][1991.7fead97fa700][-driver:nssock:0-] Notice: nssock:0:
listening on [::1]:8000
[15/Jul/2019:04:21:46][1991.7feaa77fe700][-spooler0-] Notice: spooler0:
accepting connections
[15/Jul/2019:04:21:46][1991.7fead8ff9700][-spooler2-] Notice: spooler2:
accepting connections
[15/Jul/2019:04:21:46][1991.7feaaffff700][-spooler1-] Notice: spooler1:
accepting connections
[15/Jul/2019:04:21:46][1991.7feaaf7fe700][-writer2-] Notice: writer2: accepting
connections
[15/Jul/2019:04:21:46][1991.7fead97fa700][-driver:nssock:0-] Notice: driver:
accepting connections
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain:
NaviServer/4.99.18 (26eb09ce6111 default tip) running
[15/Jul/2019:04:21:46][1991.7feae6dfc700][-main-] Notice: nsmain: security
info: uid=1010, euid=1010, gid=501, egid=501
[15/Jul/2019:04:21:46][1991.7feaaeffd700][-writer1-] Notice: writer1: accepting
connections
[15/Jul/2019:04:21:46][1991.7feae2d5e700][-sched-] Notice: sched: starting
[15/Jul/2019:04:21:46][1991.7feaae7fc700][-writer0-] Notice: writer0: accepting
connections
[15/Jul/2019:04:21:46][1991.7feae1544700][-conn:test:0:0-] Notice: update
interpreter to epoch 1, trace none, time 0.010403 secs
[15/Jul/2019:04:21:46][1991.7feae1544700][-conn:test:0:0-] Notice: thread
initialized (0.017043 secs)
[15/Jul/2019:04:21:46][1991.7feae1d45700][-conn:test:emergency:0:0-] Notice:
update interpreter to epoch 1, trace none, time 0.010423 secs
[15/Jul/2019:04:21:46][1991.7feae1d45700][-conn:test:emergency:0:0-] Notice:
thread initialized (0.017281 secs)
[15/Jul/2019:04:21:46][1991.7feae0d43700][-conn:test:1:0-] Notice: update
interpreter to epoch 1, trace none, time 0.010330 secs
[15/Jul/2019:04:21:46][1991.7feae0d43700][-conn:test:1:0-] Notice: thread
initialized (0.017345 secs)
[15/Jul/2019:04:21:46][1991.7feadbfff700][-conn:testvhost:0:0-] Notice: update
interpreter to epoch 1, trace none, time 0.010486 secs
[15/Jul/2019:04:21:46][1991.7feadb7fe700][-conn:testvhost2:0:0-] Notice: update
interpreter to epoch 1, trace none, time 0.010186 secs
[15/Jul/2019:04:21:46][1991.7feadbfff700][-conn:testvhost:0:0-] Notice: thread
initialized (0.017407 secs)
[15/Jul/2019:04:21:46][1991.7feadb7fe700][-conn:testvhost2:0:0-] Notice: thread
initialized (0.017229 secs)
[15/Jul/2019:04:21:46][1991.7feae419f700][-command-] Notice: update interpreter
to epoch 1, trace none, time 0.009987 secs
Tests running in interp:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/nsd/nsd
Tests located in:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests
Tests running in:
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests
Temporary files stored in
/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests
Test files sourced into current interpreter
Running tests that match: *
Skipping test files that match: l.*.test
Only running test files that match: *.test
Tests began at Mon Jul 15 04:21:46 EDT 2019
adp.test
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:1-] Notice: Writer(27):
started: id=2 fd=-1, size=8855, flags=100030, rate 0 KB/s: GET
/helloworld.tcl?data=x&repeat=8666 HTTP/1.0
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:3-] Notice: Writer(27):
started: id=1 fd=-1, size=8854, flags=100030, rate 0 KB/s: GET
/helloworld.adp?data=x&repeat=8666 HTTP/1.0
compat.test
[15/Jul/2019:04:21:47][1991.7feae419f700][-command-] Warning: ns_cp f1 f2 is
deprecated. Use 'file copy' instead!
cookies.test
encoding.test
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:58-] Notice: Writer(27):
started: id=0 fd=-1, size=8382, flags=100030, rate 0 KB/s: GET /encoding
HTTP/1.0
errordoc.test
http.test
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Notice:
pre-HTTP/1.0 request <GET /noexist>
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <GET a> -> ERROR
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'GET a' offsets: read 7 write
7 content 0 avail 0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: GET a\x00\x0a
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <GET a b> -> ERROR
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'GET a b' offsets: read 9
write 9 content 0 avail 0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: GET a b\x00\x0a
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <GET a b c> -> ERROR
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'GET a b c' offsets: read 11
write 11 content 0 avail 0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: GET a b c\x00\x0a
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <a b> -> ERROR
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'a b' offsets: read 5 write 5
content 0 avail 0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: a b\x00\x0a
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <a b c> -> ERROR
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'a b c' offsets: read 7 write
7 content 0 avail 0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: a b c\x00\x0a
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:68-] Notice: Writer(27):
started: id=2 fd=-1, size=2260, flags=100000, rate 0 KB/s: GET /2048bytes
HTTP/1.0
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:69-] Notice: Writer(27):
started: id=1 fd=30, size=16693, flags=100000, rate 0 KB/s: GET /16480bytes
HTTP/1.0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Notice:
pre-HTTP/1.0 request <GET /10bytes>
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: request
line is too long (1072 bytes)
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: request
header line is too long (1054 bytes)
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: request
header line is too long (1054 bytes)
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
SockParse: request too large, length=1000002, maxinput=1000001
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress end url
'/put'
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 414 (Too Many Request Headers) from peer ::1 request 'GET /limits
HTTP/1.1' offsets: read 124 write 1024 content 0 avail 900
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: GET /limits HTTP/1.1\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x00\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0a
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 414 (Too Many Request Headers) from peer ::1 request 'GET /limits
HTTP/1.0' offsets: read 124 write 1024 content 0 avail 900
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: GET /limits HTTP/1.0\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x00\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax: y\x0d\x0ax:
y\x0d\x0ax: y\x0d\x0a
[15/Jul/2019:04:21:47][1991.7feae419f700][-command-] Warning: HttpProc:
NS_SOCK_READ receive failed
==== http-3.3new limits: too many headers FAILED
==== Contents of test case:
nstest::http -http 1.1 -getbody 1 -setheaders [split [string repeat xy
1024] ""] GET /limits
---- Result was:
ns_http failed: recv failed
---- Result should have been (exact matching):
414
==== http-3.3new FAILED
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:75-] Notice: Writer(27):
started: id=0 fd=-1, size=1213, flags=100030, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:76-] Notice: Writer(27):
started: id=2 fd=-1, size=1214, flags=100030, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7feaaffff700][-spooler1-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:77-] Notice: Writer(27):
started: id=1 fd=-1, size=1215, flags=100030, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7feaa77fe700][-spooler0-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:78-] Notice: Writer(27):
started: id=0 fd=-1, size=1216, flags=100030, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress end url
'/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:79-] Notice: Writer(27):
started: id=2 fd=-1, size=100175, flags=100000, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7feaaffff700][-spooler1-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7feaaffff700][-spooler1-] Notice: progress end url
'/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:80-] Notice: Writer(27):
started: id=1 fd=-1, size=100175, flags=100000, rate 0 KB/s: PUT /put HTTP/1.0
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
SockParse: request too large, length=1000002, maxinput=1000001
[15/Jul/2019:04:21:47][1991.7feaa77fe700][-spooler0-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7feaa77fe700][-spooler0-] Notice: progress end url
'/put'
[15/Jul/2019:04:21:47][1991.7fead97fa700][-driver:nssock:0-] Warning:
SockParse: request too large, length=1000002, maxinput=1000001
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress start
url '/put'
[15/Jul/2019:04:21:47][1991.7fead8ff9700][-spooler2-] Notice: progress end url
'/put'
[15/Jul/2019:04:21:47][1991.7feae0d43700][-conn:test:1:87-] Notice: encoding
system utf-8 conn charset utf-8
==== http-5.5 check encoding ns_conn content POST, binary FAILED
==== Contents of test case:
set string "Testing <????????>"
nstest::http -getbody 1 -setheaders {content-type text/html} POST /post
$string
---- Result was:
200 {utf-8 <text/html> A??ATesting <????????????????>Z??Z}
---- Result should have been (exact matching):
200 {utf-8 <text/html> A??ATesting <????????>Z??Z}
==== http-5.5 FAILED
[15/Jul/2019:04:21:48][1991.7feaaffff700][-spooler1-] Notice: progress start
url '/post'
[15/Jul/2019:04:21:48][1991.7feaaffff700][-spooler1-] Notice: progress end url
'/post'
[15/Jul/2019:04:21:49][1991.7feaa77fe700][-spooler0-] Notice: progress start
url '/post'
[15/Jul/2019:04:21:49][1991.7feaa77fe700][-spooler0-] Notice: progress end url
'/post'
[15/Jul/2019:04:21:49][1991.7feaadffb700][task:tclhttp] Notice: Taskthread:
starting
[15/Jul/2019:04:21:49][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:49][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:49][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:49][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/put'
[15/Jul/2019:04:21:51][1991.7feae419f700][-command-] Notice: OK
[15/Jul/2019:04:21:51][1991.7feaadffb700][task:tclhttp] Notice: update
interpreter to epoch 1, trace none, time 0.009665 secs
http_byteranges.test
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:126-] Notice:
Writer(31): started: id=0 fd=-1, size=1760, flags=100000, rate 0 KB/s: GET
/2048bytes HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:145-] Notice:
Writer(31): started: id=2 fd=33, size=16693, flags=100000, rate 0 KB/s: GET
/16480bytes HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:146-] Notice:
Writer(31): started: id=1 fd=33, size=17755, flags=100000, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:147-] Warning: invalid
syntax: last byte position is smaller than first byte position in range
specification 'bytes=3-2'; ignore range
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:149-] Warning: range
specification does not start with 'bytes=': 'bytes'; ignore.
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:150-] Warning: range
specification does not start with 'bytes=': '0-1'; ignore.
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:151-] Warning: range
specification does not start with 'bytes=': '='; ignore.
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:152-] Warning: range
specification does not start with 'bytes=': '=-'; ignore.
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:153-] Warning: invalid
syntax (character 45, '-' position 7) in range specification 'bytes=--6-9';
ignore range
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:154-] Warning: invalid
syntax (character 45, '-' position 8) in range specification 'bytes=1--6';
ignore range
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:155-] Warning: invalid
syntax (character 0, ' ' position 7) in range specification 'bytes=1'; ignore
range
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:159-] Notice:
Writer(31): started: id=0 fd=33, size=133, flags=100000, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:160-] Notice:
Writer(31): started: id=2 fd=33, size=126, flags=100000, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:161-] Notice:
Writer(31): started: id=1 fd=33, size=124, flags=100000, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:162-] Notice:
Writer(31): started: id=0 fd=33, size=125, flags=100000, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:174-] Warning: maximum
number of ranges per request (32) reached; truncate at maximum
[15/Jul/2019:04:21:54][1991.7feae1544700][-conn:test:0:175-] Notice:
Writer(31): started: id=2 fd=-1, size=1891, flags=100000, rate 0 KB/s: GET
/2048bytes HTTP/1.0
http_chunked.test
http_keep.test
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/keep'
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/keep'
http_persistent.test
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Warning:
Ns_ParseRequest <TOOMUCH> -> ERROR
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Warning: invalid
request: 400 (Bad Request) from peer ::1 request 'TOOMUCH' offsets: read 9
write 9 content 0 avail 0
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Warning: REQ
BUFFER: TOOMUCH\x00\x0a
[15/Jul/2019:04:22:00][1991.7fead97fa700][-driver:nssock:0-] Notice: progress
start url '/1'
https.test
[15/Jul/2019:04:22:00][1991.7feae1544700][-conn:test:0:218-] Notice:
Writer(31): started: id=1 fd=-1, size=5189, flags=100030, rate 0 KB/s: GET /get
HTTP/1.0
[15/Jul/2019:04:22:00][1991.7feae1544700][-conn:test:0:219-] Notice:
Writer(31): started: id=0 fd=-1, size=500191, flags=100030, rate 0 KB/s: GET
/get HTTP/1.0
init.test
[15/Jul/2019:04:22:00][1991.7feaacff9700][-ns_job_0-] Notice: Starting thread:
-ns_job_0-
[15/Jul/2019:04:22:00][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 1, trace none, time 0.008985 secs
keylist.test
misc.test
[15/Jul/2019:04:22:00][1991.7feae419f700][-command-] Notice: random: generating
1 seed
ns_accesslog.test
ns_addrbyhost.test
ns_adp_compress.test
ns_base64.test
ns_cache.test
[15/Jul/2019:04:22:14][1991.7feaa7fff700][-tcl-nsthread:0-] Notice: update
interpreter to epoch 1, trace none, time 0.009722 secs
[15/Jul/2019:04:22:16][1991.7feaa7fff700][-tcl-nsthread:1-] Notice: update
interpreter to epoch 1, trace none, time 0.009175 secs
[15/Jul/2019:04:22:21][1991.7feaa7fff700][-tcl-nsthread:2-] Notice: update
interpreter to epoch 1, trace none, time 0.009389 secs
[15/Jul/2019:04:22:29][1991.7feae419f700][-command-] Warning: cache trans_c1:
adding entry 0x7fea84022660 with key 'k4' multiple times to pending table
[15/Jul/2019:04:22:29][1991.7feae419f700][-command-] Notice:
CacheTransactionFinish: rolled back 2 elements in (0.000009 secs)
[15/Jul/2019:04:22:29][1991.7feae419f700][-command-] Warning: cache trans_c1:
adding entry 0x7fea84022660 with key 'k4' multiple times to pending table
[15/Jul/2019:04:22:29][1991.7feae419f700][-command-] Notice:
CacheTransactionFinish: committed 2 elements in (0.000007 secs)
ns_cond.test
[15/Jul/2019:04:22:29][1991.7feae419f700][-command-] Notice: tst_cond_master:
New thread '' started for running tst_cond_worker.
[15/Jul/2019:04:22:29][1991.7feaa7fff700][-tcl-nsthread:3-] Notice: update
interpreter to epoch 1, trace none, time 0.009632 secs
[15/Jul/2019:04:22:29][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: 2 work items: 0 1
[15/Jul/2019:04:22:30][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: Event 'ns:condition:tcl:0' - got it.
[15/Jul/2019:04:22:30][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: 1 work items: 2
[15/Jul/2019:04:22:31][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: Event 'ns:condition:tcl:0' - got it.
[15/Jul/2019:04:22:31][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: 1 work items: 3
[15/Jul/2019:04:22:32][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: Event 'ns:condition:tcl:0' - got it.
[15/Jul/2019:04:22:32][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: 1 work items: 4
[15/Jul/2019:04:22:33][1991.7feae419f700][-command-] Notice: tst_cond_master: 5
work items done: 0 1 2 3 4
[15/Jul/2019:04:22:33][1991.7feae419f700][-command-] Notice: tst_cond_master: 0
work items NOT done:
[15/Jul/2019:04:22:33][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: Event 'ns:condition:tcl:0' - got it.
[15/Jul/2019:04:22:33][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: 0 work items:
[15/Jul/2019:04:22:33][1991.7feaa7fff700][-tcl-nsthread:3-] Notice:
tst_cond_worker: No more work for me today.
ns_config.test
ns_conn.test
ns_conn_host.test
ns_crypt.test
ns_crypto.test
ns_driver.test
ns_env.test
ns_file.test
ns_gifsize.test
ns_hashpath.test
ns_hostbyaddr.test
[15/Jul/2019:04:22:33][1991.7feae419f700][-command-] Notice: dns: getnameinfo
failed for addr <0.0.0.0>: Name or service not known
ns_hrefs.test
ns_httptime.test
ns_image.test
ns_info.test
ns_jpegsize.test
ns_limits.test
ns_listencallback.test
[15/Jul/2019:04:22:35][1991.7feaa7fff700][-socks-] Notice: socks: starting
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Notice: open sockent on
::1 7227
[15/Jul/2019:04:22:35][1991.7feaa7fff700][-socks-] Notice: ... query IP +
PROTO: SockAddr family AF_INET6, ip ::1, port 7227
[15/Jul/2019:04:22:35][1991.7feaa7fff700][-socks-] Notice: update interpreter
to epoch 1, trace none, time 0.008325 secs
ns_log.test
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-3.4:
(ns_log + severity "fatal" never writes)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Fatal: test
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-5.2:
(count buffered log entries)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-5.7:
(get)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-5.8:
(flush)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Notice: test
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-5.9:
(flush)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Notice: test
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.1:
(configuration)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.2:
(configuration)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.3:
(enable/disable)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.4:
(list severities)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.5:
(bounds check)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-6.6:
(bounds check)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Dev: >->-> ns_log-7.0:
(two callbacks test)
[15/Jul/2019:04:22:35][1991.7feae419f700][-command-] Notice: Log callback test
7.0
ns_md5.test
ns_mime.test
ns_nsv.test
ns_pagepath.test
ns_parseargs.test
[15/Jul/2019:04:22:35][1991.7feaa6ffd700][-tcl-nsthread:4-] Notice: update
interpreter to epoch 1, trace none, time 0.008753 secs
ns_parsefieldvalue.test
ns_parseurl.test
ns_proxy.test
[15/Jul/2019:04:22:35][2027.7f6945f99700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][1991.7feaa6ffd700][-nsproxy:reap-] Notice: starting
[15/Jul/2019:04:22:35][2029.7fcc94478700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][2030.7fcd20435700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][2031.7f4dfe20a700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][2032.7f2ee7df6700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][1991.7feaa67fc700][-tcl-nsthread:5-] Notice: update
interpreter to epoch 1, trace none, time 0.005749 secs
[15/Jul/2019:04:22:35][1991.7feaa67fc700][-tcl-nsthread:6-] Notice: update
interpreter to epoch 1, trace none, time 0.005332 secs
[15/Jul/2019:04:22:35][2035.7fc673d9a700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:35][2036.7f66d079e700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:36][1991.7feae419f700][-command-] Notice: releasing busy
proxy testpool-8
[15/Jul/2019:04:22:37][2038.7f678b530700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:38][1991.7feae419f700][-command-] Notice: releasing busy
proxy testpool-8
[15/Jul/2019:04:22:39][2039.7fe9862b9700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:40][1991.7feae419f700][-command-] Notice: releasing busy
proxy testpool-8
[15/Jul/2019:04:22:41][2040.7f90ea8c0700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:42][1991.7feae419f700][-command-] Notice: releasing busy
proxy testpool-8
[15/Jul/2019:04:22:43][2042.7f915557c700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2043.7fa991c38700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2044.7fa64cb05700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2045.7ffaff3b7700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2046.7f3000ef0700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2047.7feed51c6700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2048.7f2f5a5ab700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2049.7f7dbcff0700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:43][2050.7f17230b3700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:45][1991.7feaa6ffd700][-nsproxy:reap-] Warning: [testpool]:
pid 2042 won't die, send signal 15
[15/Jul/2019:04:22:45][1991.7feae419f700][-command-] Notice: proxy maxrun
reached pool testpool slave 2052
[15/Jul/2019:04:22:45][1991.7feaa6ffd700][-nsproxy:reap-] Notice: nsproxy
process 2042 killed with signal 15 (Terminated)
[15/Jul/2019:04:22:45][2052.7fcd56571700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:45][2053.7f6eab5b8700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:46][1991.7feae419f700][-command-] Notice: proxy maxrun
reached pool testpool slave 2053
[15/Jul/2019:04:22:46][2054.7fd883848700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
[15/Jul/2019:04:22:46][1991.7feae419f700][-command-] Notice: proxy maxrun
reached pool testpool slave 2054
[15/Jul/2019:04:22:46][2055.7fb064123700][-main-] Notice: OpenSSL 1.0.2g 1 Mar
2016 initialized
ns_reflow_text.test
ns_register_filter.test
ns_register_proc.test
ns_schedule.test
[15/Jul/2019:04:22:56][1991.7feae2d5e700][-sched-] Notice: update interpreter
to epoch 1, trace none, time 0.009898 secs
[15/Jul/2019:04:23:07][1991.7feaa67fc700][-sched:idle0-] Notice: starting
[15/Jul/2019:04:23:07][1991.7feaa67fc700][-sched:0:1:6-] Notice: update
interpreter to epoch 1, trace none, time 0.009266 secs
ns_server.test
==== ns_server-2.5 basic operation FAILED
---- Result was:
10
---- Result should have been (exact matching):
9
==== ns_server-2.5 FAILED
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Notice: pool[test]: mapped
GET /foo -> emergency
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Notice: pool[test]:
unmapped GET /foo
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Notice: pool[test]: mapped
GET /foo -> emergency
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Notice: pool[test]:
unmapped GET /foo
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Notice: pool[test]: mapped
GET /foo/*.png -> emergency
[15/Jul/2019:04:23:12][1991.7feae419f700][-command-] Warning: pool[test]: could
not unmap GET /foo
ns_serverpath.test
ns_set.test
ns_sha1.test
ns_sls.test
ns_striphtml.test
ns_thread.test
[15/Jul/2019:04:23:12][1991.7feaa5ffb700][-tcl-nsthread:7-] Notice: update
interpreter to epoch 1, trace none, time 0.006729 secs
[15/Jul/2019:04:23:12][1991.7feaa57fa700][-tcl-nsthread:8-] Notice: update
interpreter to epoch 1, trace none, time 0.006601 secs
[15/Jul/2019:04:23:12][1991.7feaa57fa700][-tcl-nsthread:9-] Notice: update
interpreter to epoch 1, trace none, time 0.006074 secs
[15/Jul/2019:04:23:12][1991.7feaa57fa700][-tcl-nsthread:10-] Notice: update
interpreter to epoch 1, trace none, time 0.017999 secs
[15/Jul/2019:04:23:12][1991.7feaa5ffb700][-tcl-nsthread:11-] Notice: update
interpreter to epoch 1, trace none, time 0.016916 secs
[15/Jul/2019:04:23:12][1991.7feaa4ff9700][-tcl-nsthread:12-] Notice: update
interpreter to epoch 1, trace none, time 0.012522 secs
[15/Jul/2019:04:23:12][1991.7fea6ffff700][-tcl-nsthread:13-] Notice: update
interpreter to epoch 1, trace none, time 0.006541 secs
[15/Jul/2019:04:23:12][1991.7fea6f7fe700][-tcl-nsthread:17-] Notice: update
interpreter to epoch 1, trace none, time 0.006352 secs
[15/Jul/2019:04:23:12][1991.7fea9dffb700][-tcl-nsthread:15-] Notice: update
interpreter to epoch 1, trace none, time 0.006645 secs
[15/Jul/2019:04:23:12][1991.7fea377fe700][-tcl-nsthread:28-] Notice: update
interpreter to epoch 1, trace none, time 0.007286 secs
ns_thread_crash.test
[15/Jul/2019:04:23:12][1991.7fea9e7fc700][-tcl-nsthread:21-] Notice: update
interpreter to epoch 1, trace none, time 0.012811 secs
[15/Jul/2019:04:23:12][1991.7fea9effd700][-tcl-nsthread:19-] Notice: update
interpreter to epoch 1, trace none, time 0.016448 secs
[15/Jul/2019:04:23:12][1991.7fea1a7fc700][-tcl-nsthread:37-] Notice: update
interpreter to epoch 1, trace none, time 0.017757 secs
[15/Jul/2019:04:23:12][1991.7fea11ffb700][-tcl-nsthread:45-] Notice: update
interpreter to epoch 1, trace none, time 0.018380 secs
[15/Jul/2019:04:23:12][1991.7fea137fe700][-tcl-nsthread:42-] Notice: update
interpreter to epoch 1, trace none, time 0.021787 secs
[15/Jul/2019:04:23:12][1991.7fe90a7fc700][-tcl-nsthread:93-] Notice: update
interpreter to epoch 1, trace none, time 0.019960 secs
[15/Jul/2019:04:23:12][1991.7fe9aa7fc700][-tcl-nsthread:58-] Notice: update
interpreter to epoch 1, trace none, time 0.020065 secs
[15/Jul/2019:04:23:12][1991.7fea9d7fa700][-tcl-nsthread:20-] Notice: update
interpreter to epoch 1, trace none, time 0.021047 secs
[15/Jul/2019:04:23:12][1991.7fea19ffb700][-tcl-nsthread:38-] Notice: update
interpreter to epoch 1, trace none, time 0.031081 secs
[15/Jul/2019:04:23:12][1991.7fea127fc700][-tcl-nsthread:44-] Notice: update
interpreter to epoch 1, trace none, time 0.024645 secs
[15/Jul/2019:04:23:12][1991.7fea9cff9700][-tcl-nsthread:18-] Notice: update
interpreter to epoch 1, trace none, time 0.024473 secs
[15/Jul/2019:04:23:12][1991.7fea6e7fc700][-tcl-nsthread:23-] Notice: update
interpreter to epoch 1, trace none, time 0.025162 secs
[15/Jul/2019:04:23:12][1991.7fea36ffd700][-tcl-nsthread:29-] Notice: update
interpreter to epoch 1, trace none, time 0.020588 secs
[15/Jul/2019:04:23:12][1991.7fea1b7fe700][-tcl-nsthread:35-] Notice: update
interpreter to epoch 1, trace none, time 0.023434 secs
[15/Jul/2019:04:23:12][1991.7fe9927fc700][-tcl-nsthread:65-] Notice: update
interpreter to epoch 1, trace none, time 0.018327 secs
[15/Jul/2019:04:23:12][1991.7fe9ab7fe700][-tcl-nsthread:57-] Notice: update
interpreter to epoch 1, trace none, time 0.020801 secs
[15/Jul/2019:04:23:12][1991.7fea1affd700][-tcl-nsthread:36-] Notice: update
interpreter to epoch 1, trace none, time 0.022611 secs
[15/Jul/2019:04:23:12][1991.7fea37fff700][-tcl-nsthread:27-] Notice: update
interpreter to epoch 1, trace none, time 0.023539 secs
[15/Jul/2019:04:23:12][1991.7fe940ff9700][-tcl-nsthread:89-] Notice: update
interpreter to epoch 1, trace none, time 0.026725 secs
[15/Jul/2019:04:23:12][1991.7fe9abfff700][-tcl-nsthread:55-] Notice: update
interpreter to epoch 1, trace none, time 0.025743 secs
[15/Jul/2019:04:23:12][1991.7fea6dffb700][-tcl-nsthread:24-] Notice: update
interpreter to epoch 1, trace none, time 0.021346 secs
[15/Jul/2019:04:23:12][1991.7fe9a9ffb700][-tcl-nsthread:59-] Notice: update
interpreter to epoch 1, trace none, time 0.018938 secs
[15/Jul/2019:04:23:12][1991.7fea18ff9700][-tcl-nsthread:41-] Notice: update
interpreter to epoch 1, trace none, time 0.020352 secs
[15/Jul/2019:04:23:12][1991.7fe9917fa700][-tcl-nsthread:68-] Notice: update
interpreter to epoch 1, trace none, time 0.021697 secs
[15/Jul/2019:04:23:12][1991.7fe9aaffd700][-tcl-nsthread:56-] Notice: update
interpreter to epoch 1, trace none, time 0.019301 secs
[15/Jul/2019:04:23:12][1991.7fea367fc700][-tcl-nsthread:31-] Notice: update
interpreter to epoch 1, trace none, time 0.026530 secs
[15/Jul/2019:04:23:12][1991.7fea34ff9700][-tcl-nsthread:33-] Notice: update
interpreter to epoch 1, trace none, time 0.027652 secs
[15/Jul/2019:04:23:12][1991.7fea9ffff700][-tcl-nsthread:16-] Notice: update
interpreter to epoch 1, trace none, time 0.026706 secs
[15/Jul/2019:04:23:12][1991.7fe9ca7fc700][-tcl-nsthread:51-] Notice: update
interpreter to epoch 1, trace none, time 0.025095 secs
[15/Jul/2019:04:23:12][1991.7fea35ffb700][-tcl-nsthread:32-] Notice: update
interpreter to epoch 1, trace none, time 0.025953 secs
[15/Jul/2019:04:23:12][1991.7fea6d7fa700][-tcl-nsthread:25-] Notice: update
interpreter to epoch 1, trace none, time 0.029157 secs
[15/Jul/2019:04:23:12][1991.7fe991ffb700][-tcl-nsthread:67-] Notice: update
interpreter to epoch 1, trace none, time 0.016919 secs
[15/Jul/2019:04:23:12][1991.7fea6effd700][-tcl-nsthread:22-] Notice: update
interpreter to epoch 1, trace none, time 0.028358 secs
[15/Jul/2019:04:23:12][1991.7fe9a97fa700][-tcl-nsthread:60-] Notice: update
interpreter to epoch 1, trace none, time 0.022468 secs
[15/Jul/2019:04:23:12][1991.7fe98b7fe700][-tcl-nsthread:63-] Notice: update
interpreter to epoch 1, trace none, time 0.022804 secs
[15/Jul/2019:04:23:12][1991.7fea197fa700][-tcl-nsthread:39-] Notice: update
interpreter to epoch 1, trace none, time 0.027450 secs
[15/Jul/2019:04:23:12][1991.7fea117fa700][-tcl-nsthread:46-] Notice: update
interpreter to epoch 1, trace none, time 0.023379 secs
[15/Jul/2019:04:23:12][1991.7fe9c8ff9700][-tcl-nsthread:54-] Notice: update
interpreter to epoch 1, trace none, time 0.018270 secs
[15/Jul/2019:04:23:12][1991.7fea9f7fe700][-tcl-nsthread:14-] Notice: update
interpreter to epoch 1, trace none, time 0.018556 secs
[15/Jul/2019:04:23:12][1991.7fea12ffd700][-tcl-nsthread:43-] Notice: update
interpreter to epoch 1, trace none, time 0.024211 secs
[15/Jul/2019:04:23:12][1991.7fe9937fe700][-tcl-nsthread:64-] Notice: update
interpreter to epoch 1, trace none, time 0.025726 secs
[15/Jul/2019:04:23:12][1991.7fe990ff9700][-tcl-nsthread:69-] Notice: update
interpreter to epoch 1, trace none, time 0.019206 secs
[15/Jul/2019:04:23:12][1991.7fea1bfff700][-tcl-nsthread:34-] Notice: update
interpreter to epoch 1, trace none, time 0.027580 secs
[15/Jul/2019:04:23:12][1991.7fea6cff9700][-tcl-nsthread:26-] Notice: update
interpreter to epoch 1, trace none, time 0.032708 secs
[15/Jul/2019:04:23:12][1991.7fea357fa700][-tcl-nsthread:30-] Notice: update
interpreter to epoch 1, trace none, time 0.031864 secs
[15/Jul/2019:04:23:12][1991.7fe993fff700][-tcl-nsthread:61-] Notice: update
interpreter to epoch 1, trace none, time 0.025082 secs
[15/Jul/2019:04:23:12][1991.7fe9caffd700][-tcl-nsthread:50-] Notice: update
interpreter to epoch 1, trace none, time 0.025237 secs
[15/Jul/2019:04:23:12][1991.7fe9c97fa700][-tcl-nsthread:53-] Notice: update
interpreter to epoch 1, trace none, time 0.025388 secs
[15/Jul/2019:04:23:12][1991.7fe9c9ffb700][-tcl-nsthread:52-] Notice: update
interpreter to epoch 1, trace none, time 0.023136 secs
[15/Jul/2019:04:23:12][1991.7fea10ff9700][-tcl-nsthread:48-] Notice: update
interpreter to epoch 1, trace none, time 0.026883 secs
[15/Jul/2019:04:23:12][1991.7fe8e1ffb700][-tcl-nsthread:108-] Notice: update
interpreter to epoch 1, trace none, time 0.022192 secs
[15/Jul/2019:04:23:12][1991.7fe9a8ff9700][-tcl-nsthread:62-] Notice: update
interpreter to epoch 1, trace none, time 0.026391 secs
[15/Jul/2019:04:23:12][1991.7fe8ebfff700][-tcl-nsthread:97-] Notice: update
interpreter to epoch 1, trace none, time 0.009475 secs
[15/Jul/2019:04:23:12][1991.7fe9417fa700][-tcl-nsthread:88-] Notice: update
interpreter to epoch 1, trace none, time 0.008541 secs
[15/Jul/2019:04:23:12][1991.7fe909ffb700][-tcl-nsthread:94-] Notice: update
interpreter to epoch 1, trace none, time 0.009063 secs
[15/Jul/2019:04:23:12][1991.7fe94affd700][-tcl-nsthread:79-] Notice: update
interpreter to epoch 1, trace none, time 0.009208 secs
[15/Jul/2019:04:23:12][1991.7fe94bfff700][-tcl-nsthread:76-] Notice: update
interpreter to epoch 1, trace none, time 0.011161 secs
[15/Jul/2019:04:23:12][1991.7fe8eb7fe700][-tcl-nsthread:98-] Notice: update
interpreter to epoch 1, trace none, time 0.009634 secs
[15/Jul/2019:04:23:12][1991.7fe8e97fa700][-tcl-nsthread:103-] Notice: update
interpreter to epoch 1, trace none, time 0.008477 secs
[15/Jul/2019:04:23:12][1991.7fe9497fa700][-tcl-nsthread:82-] Notice: update
interpreter to epoch 1, trace none, time 0.009615 secs
[15/Jul/2019:04:23:12][1991.7fe8ea7fc700][-tcl-nsthread:101-] Notice: update
interpreter to epoch 1, trace none, time 0.010035 secs
[15/Jul/2019:04:23:12][1991.7fe9437fe700][-tcl-nsthread:85-] Notice: update
interpreter to epoch 1, trace none, time 0.009825 secs
[15/Jul/2019:04:23:12][1991.7fe941ffb700][-tcl-nsthread:87-] Notice: update
interpreter to epoch 1, trace none, time 0.009886 secs
[15/Jul/2019:04:23:12][1991.7fe8e8ff9700][-tcl-nsthread:104-] Notice: update
interpreter to epoch 1, trace none, time 0.010125 secs
[15/Jul/2019:04:23:12][1991.7fe988ff9700][-tcl-nsthread:75-] Notice: update
interpreter to epoch 1, trace none, time 0.010032 secs
[15/Jul/2019:04:23:12][1991.7fe90bfff700][-tcl-nsthread:90-] Notice: update
interpreter to epoch 1, trace none, time 0.008857 secs
[15/Jul/2019:04:23:12][1991.7fe989ffb700][-tcl-nsthread:73-] Notice: update
interpreter to epoch 1, trace none, time 0.010057 secs
[15/Jul/2019:04:23:12][1991.7fe90b7fe700][-tcl-nsthread:91-] Notice: update
interpreter to epoch 1, trace none, time 0.010381 secs
[15/Jul/2019:04:23:12][1991.7fe94a7fc700][-tcl-nsthread:80-] Notice: update
interpreter to epoch 1, trace none, time 0.010431 secs
[15/Jul/2019:04:23:12][1991.7fea13fff700][-tcl-nsthread:40-] Notice: update
interpreter to epoch 1, trace none, time 0.010189 secs
[15/Jul/2019:04:23:12][1991.7fe98affd700][-tcl-nsthread:71-] Notice: update
interpreter to epoch 1, trace none, time 0.009102 secs
[15/Jul/2019:04:23:12][1991.7fe8e9ffb700][-tcl-nsthread:102-] Notice: update
interpreter to epoch 1, trace none, time 0.010623 secs
[15/Jul/2019:04:23:12][1991.7fe8e3fff700][-tcl-nsthread:100-] Notice: update
interpreter to epoch 1, trace none, time 0.010572 secs
[15/Jul/2019:04:23:12][1991.7fe943fff700][-tcl-nsthread:84-] Notice: update
interpreter to epoch 1, trace none, time 0.010483 secs
[15/Jul/2019:04:23:12][1991.7fe9cbfff700][-tcl-nsthread:47-] Notice: update
interpreter to epoch 1, trace none, time 0.010513 secs
[15/Jul/2019:04:23:12][1991.7fe8e17fa700][-tcl-nsthread:109-] Notice: update
interpreter to epoch 1, trace none, time 0.010700 secs
[15/Jul/2019:04:23:12][1991.7fe94b7fe700][-tcl-nsthread:77-] Notice: update
interpreter to epoch 1, trace none, time 0.010671 secs
[15/Jul/2019:04:23:12][1991.7fe949ffb700][-tcl-nsthread:81-] Notice: update
interpreter to epoch 1, trace none, time 0.010646 secs
[15/Jul/2019:04:23:12][1991.7fe908ff9700][-tcl-nsthread:96-] Notice: update
interpreter to epoch 1, trace none, time 0.010693 secs
[15/Jul/2019:04:23:12][1991.7fe942ffd700][-tcl-nsthread:78-] Notice: update
interpreter to epoch 1, trace none, time 0.009575 secs
[15/Jul/2019:04:23:12][1991.7fe9097fa700][-tcl-nsthread:95-] Notice: update
interpreter to epoch 1, trace none, time 0.010784 secs
[15/Jul/2019:04:23:12][1991.7fe992ffd700][-tcl-nsthread:66-] Notice: update
interpreter to epoch 1, trace none, time 0.010933 secs
[15/Jul/2019:04:23:12][1991.7fe8e37fe700][-tcl-nsthread:105-] Notice: update
interpreter to epoch 1, trace none, time 0.009599 secs
[15/Jul/2019:04:23:12][1991.7fe8e27fc700][-tcl-nsthread:107-] Notice: update
interpreter to epoch 1, trace none, time 0.009773 secs
[15/Jul/2019:04:23:12][1991.7fe90affd700][-tcl-nsthread:92-] Notice: update
interpreter to epoch 1, trace none, time 0.011319 secs
[15/Jul/2019:04:23:12][1991.7fe98a7fc700][-tcl-nsthread:72-] Notice: update
interpreter to epoch 1, trace none, time 0.011134 secs
[15/Jul/2019:04:23:12][1991.7fe9cb7fe700][-tcl-nsthread:49-] Notice: update
interpreter to epoch 1, trace none, time 0.011583 secs
[15/Jul/2019:04:23:12][1991.7fe8e2ffd700][-tcl-nsthread:106-] Notice: update
interpreter to epoch 1, trace none, time 0.010081 secs
[15/Jul/2019:04:23:12][1991.7fe9897fa700][-tcl-nsthread:74-] Notice: update
interpreter to epoch 1, trace none, time 0.012481 secs
[15/Jul/2019:04:23:12][1991.7fe98bfff700][-tcl-nsthread:70-] Notice: update
interpreter to epoch 1, trace none, time 0.012269 secs
[15/Jul/2019:04:23:12][1991.7fe9427fc700][-tcl-nsthread:86-] Notice: update
interpreter to epoch 1, trace none, time 0.011368 secs
[15/Jul/2019:04:23:12][1991.7fe8eaffd700][-tcl-nsthread:99-] Notice: update
interpreter to epoch 1, trace none, time 0.013340 secs
[15/Jul/2019:04:23:12][1991.7fe948ff9700][-tcl-nsthread:83-] Notice: update
interpreter to epoch 1, trace none, time 0.013698 secs
[15/Jul/2019:04:23:12][1991.7fe948ff9700][-tcl-nsthread:110-] Notice: update
interpreter to epoch 1, trace none, time 0.005644 secs
ns_urlencode.test
ns_urlspace.test
ns_uuencode.test
ns_writer.test
nsdb.test
progress.test
tclconnio.test
[15/Jul/2019:04:23:12][1991.7feae1544700][-conn:test:0:330-] Notice:
'ns_connsendfp file40 5 ' is deprecated. Use 'ns_writefp fileid ?nbytes?'
instead.
tclresp.test
[15/Jul/2019:04:23:17][1991.7feae1544700][-conn:test:0:346-] Notice:
Writer(38): started: id=1 fd=-1, size=1216, flags=100030, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:23:17][1991.7feae1544700][-conn:test:0:347-] Notice:
Writer(38): started: id=0 fd=-1, size=49172, flags=100030, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:23:17][1991.7feae1544700][-conn:test:0:348-] Notice:
Writer(38): started: id=2 fd=-1, size=49173, flags=100030, rate 0 KB/s: GET
/tclresp HTTP/1.0
[15/Jul/2019:04:23:17][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 2, trace deallocate, time 0.009114 secs
[15/Jul/2019:04:23:17][1991.7feae1544700][-conn:test:0:359-] Notice: update
interpreter to epoch 2, trace allocate, time 0.010037 secs
[15/Jul/2019:04:23:17][1991.7feae0d43700][-conn:test:1:360-] Notice: update
interpreter to epoch 2, trace allocate, time 0.010849 secs
[15/Jul/2019:04:23:17][1991.7fe948ff9700][-ns_job_1-] Notice: Starting thread:
-ns_job_1-
[15/Jul/2019:04:23:17][1991.7fe90b7fe700][-ns_job_2-] Notice: Starting thread:
-ns_job_2-
[15/Jul/2019:04:23:17][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 3, trace deallocate, time 0.008976 secs
[15/Jul/2019:04:23:17][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 4, trace deallocate, time 0.007676 secs
[15/Jul/2019:04:23:17][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 5, trace deallocate, time 0.007100 secs
[15/Jul/2019:04:23:17][1991.7feaacff9700][-ns_job_0-] Notice: update
interpreter to epoch 6, trace deallocate, time 0.006371 secs
[15/Jul/2019:04:23:17][1991.7feae1544700][-conn:test:0:364-] Notice: update
interpreter to epoch 6, trace allocate, time 0.008878 secs
[15/Jul/2019:04:23:17][1991.7fe948ff9700][-ns_job_1-] Notice: update
interpreter to epoch 6, trace none, time 0.010332 secs
[15/Jul/2019:04:23:17][1991.7fe948ff9700][-ns_job_1-] Notice: update
interpreter to epoch 7, trace deallocate, time 0.008590 secs
[15/Jul/2019:04:23:22][1991.7feae1544700][-conn:test:0:381-] Notice: update
interpreter to epoch 7, trace allocate, time 0.009720 secs
timeout.test
url2file.test
Tests ended at Mon Jul 15 04:23:22 EDT 2019
all.tcl: Total 1391 Passed 1380 Skipped 8 Failed 3
Sourced 69 Test Files.
Files with failing tests: http.test ns_server.test
Number of tests skipped for each constraint:
2 knownBug
1 notDarwin
4 nsf
1 stress
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: nsmain:
NaviServer/4.99.18 (26eb09ce6111 default tip) stopping
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: [driver:nsssl:0]:
stopping
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: [driver:nssock:0]:
stopping
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [test]:
stopping
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [testvhost]:
stopping
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [testvhost2]:
stopping
[15/Jul/2019:04:23:22][1991.7feadaffd700][-driver:nsssl:0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feae1d45700][-conn:test:emergency:0:0-] Notice:
exiting: shutdown pending
[15/Jul/2019:04:23:22][1991.7fead97fa700][-driver:nssock:0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feadbfff700][-conn:testvhost:0:9-] Notice:
exiting: shutdown pending
[15/Jul/2019:04:23:22][1991.7feadb7fe700][-conn:testvhost2:0:8-] Notice:
exiting: shutdown pending
[15/Jul/2019:04:23:22][1991.7feae1544700][-conn:test:0:388-] Notice: exiting:
shutdown pending
[15/Jul/2019:04:23:22][1991.7feae0d43700][-conn:test:1:360-] Notice: exiting:
shutdown pending
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [test]:
connection threads stopped
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [testvhost]:
connection threads stopped
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: server [testvhost2]:
connection threads stopped
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: driver: stopping
writer and spooler threads
[15/Jul/2019:04:23:22][1991.7feada7fc700][-writer1-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7fead9ffb700][-writer0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaaf7fe700][-writer2-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaaeffd700][-writer1-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaae7fc700][-writer0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7fead8ff9700][-spooler2-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaaffff700][-spooler1-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaa77fe700][-spooler0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: sched: shutdown
pending
[15/Jul/2019:04:23:22][1991.7feae2d5e700][-sched-] Notice: sched: shutdown
started
[15/Jul/2019:04:23:22][1991.7feae2d5e700][-sched-] Notice: sched: waiting for
1/1 event threads...
[15/Jul/2019:04:23:22][1991.7feaa7fff700][-socks-] Notice: socks: shutdown
pending
[15/Jul/2019:04:23:22][1991.7feaadffb700][task:tclhttp] Notice: TaskThread:
shutdown pending
[15/Jul/2019:04:23:22][1991.7fe90b7fe700][-ns_job_2-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feaadffb700][task:tclhttp] Notice: TaskThread:
shutdown complete
[15/Jul/2019:04:23:22][1991.7feaa7fff700][-socks-] Notice: socks: shutdown
complete
[15/Jul/2019:04:23:22][1991.7feaa67fc700][-sched:idle0-] Notice: exiting, 0
threads, 0 idle
[15/Jul/2019:04:23:22][1991.7feaacff9700][-ns_job_0-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7fe948ff9700][-ns_job_1-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feae2d5e700][-sched-] Notice: sched: shutdown
complete
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: [driver:nsssl:0]:
stopped
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: [driver:nssock:0]:
stopped
[15/Jul/2019:04:23:22][1991.7feaa77fe700][-shutdown-] Notice: update
interpreter to epoch 7, trace none, time 0.010468 secs
[15/Jul/2019:04:23:22][1991.7feaa77fe700][-shutdown-] Notice: nslog: closed
'/net/pinky/home/local-16.04/src/web/ns-head-pub/naviserver/tests/testserver/access.log'
[15/Jul/2019:04:23:22][1991.7feaa77fe700][-shutdown-] Notice: update
interpreter to epoch 1, trace none, time 0.009247 secs
[15/Jul/2019:04:23:22][1991.7feaa77fe700][-shutdown-] Notice: update
interpreter to epoch 1, trace none, time 0.008618 secs
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: nsproxy: shutdown
started
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: nsproxy: shutdown
complete
[15/Jul/2019:04:23:22][1991.7feaa6ffd700][-nsproxy:reap-] Notice: exiting
[15/Jul/2019:04:23:22][1991.7feae6dfc700][-main-] Notice: nsmain:
NaviServer/4.99.18 (26eb09ce6111 default tip) exiting
for i in ; do \
( cd $i && make test ) || exit 1; \
done
_______________________________________________
naviserver-devel mailing list
naviserver-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/naviserver-devel
