naviserver-devel — Developer discussion

Re: [naviserver-devel] Using tcllib ::try

[Zoran V. <zv...@ar...>]

On Tue, 29 Jan 2019 12:12:12 +0100
Gustaf Neumann <ne...@wu...> wrote:

> So, i think, it is the best strategy for NaviServer to put the
> fingers away on stuff
> coming from Tcl. 

... indeed, and not *only* Tcl.

I doubt we can be absolutely correct at that place, since 
the task itself is far to complex to be solved in a 
"cost-effective" way (the task is to replicate a fully loaded
Tcl interpreter from one thread to another). 
So "problems" like this one will re-appear in the future and
in other setups. 

Perhaps we can put the "magic" that ttrace module is doing
out of the main configuration setup and use it for special
purposes? The people then need to use [ns_ictl] to register
callbacks for interp initialization themselves. In that case
they (should) know what they can expect. In the moment all
is pretty "spooky" and it is difficult to grasp...

Cheers,
Zoran

Re: [naviserver-devel] Using tcllib ::try

[Gustaf N. <ne...@wu...>]

On 28.01.19 18:10, David Osborne wrote:
> Thanks Gustaf,
>
> That got me past the immediate problem - but I'm now seeing some 
> further issues which I can't fully explain.
>
> 1. Tcl8.5 only - After clock scan : invalid command name 
> "::tcl::clock::scan"
> 2. Tcl8.5 & Tcl8.6 After ::try .. on error : can't read "magicCodes": 
> no such variable
>
> The errors only seem to happen after the commands are executed on 
> startup within ns/tcl
actually, i cannot reproduce this problem (while i could reproduce the 
original "::try" issue
with Tcl 8.5.19). The underlying problem is that Tcl does some 
optimization upon
initialization of Tcl, assuming a certain initialization sequence. The 
order on vars,
procs and namespaces in NaviServer is more or less random (depending on 
hash
table populations).

So, i think, it is the best strategy for NaviServer to put the fingers 
away on stuff
coming from Tcl. The "clock" command seems to populate as well the ::msgcat
namespace (it would be better if it had been named ::tcl::msgcat). When 
"clock" is called
during initialization (where content for the blueprint is collected), 
then NaviServer puts
this as well into the blueprint. I have made now a modification [1] to 
exclude the ::msgcat
namespace as well. All my test continue to work, maybe this is some 
improvement
for the problem in your configuration.

-g


[1] 
https://bitbucket.org/naviserver/naviserver/commits/641903183cc8e836109edb06d01450f041aa7818


# cat  ~/test.tcl
package require try
::try {
     ns_log Notice "=== scan returns [clock scan "+365 days"]"
} on error [list message options] {
     ns_log Notice "=== scan fails $message"
     ns_log Notice "=== scan fails $options"
}

# /usr/local/bin/nsd -u nsadmin -c
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: OpenSSL 1.1.1  11 Sep 2018 initialized
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: NaviServer/4.99.17 (bb78064b1137+ default tip) starting
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: security info: uid=1000, euid=1000, gid=1000, egid=1000
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: Tcl version: 8.5.19
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: max files: soft limit 1073741816, hard limit 1073741816
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Warning: nsmain: rl_cur (1073741816) > FD_SETSIZE (1024), select() calls should not be used
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Error: pidfile: failed to open pid file '/usr/local/logs/nsd.pid': 'Permission denied'
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: pool default: queueLength 90 low water 9 high water 72
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsd/init.tcl[default]: booting virtual server:  Tcl system encoding: "utf-8"
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: binder: started
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: Using ns_cache implemented as a Tcl proc
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Warning: ns_md, ns_hmac, ns_hotp and ns_totp are not available
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: === scan returns 1580252400
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: update interpreter to epoch 1, trace deallocate, time 0.002598 secs
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: update interpreter to epoch 1, trace none, time 0.002262 secs
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: NaviServer/4.99.17 (bb78064b1137+ default tip) running
[29/Jan/2019:11:57:09][22340.7f8bfc178740][-main-] Notice: nsmain: security info: uid=1000, euid=1000, gid=1000, egid=1000
[29/Jan/2019:11:57:09][22340.7f8beeef0700][-command-] Notice: update interpreter to epoch 1, trace none, time 0.002163 secs
[29/Jan/2019:11:57:09][22340.7f8bfc178740][binder] Notice: binder: stopped
[29/Jan/2019:11:57:09][22340.7f8bee62f700][-conn:default:0:0-] Notice: update interpreter to epoch 1, trace none, time 0.002218 secs
[29/Jan/2019:11:57:09][22340.7f8bee62f700][-conn:default:0:0-] Notice: thread initialized (0.003557 secs)
%

>
>
> $ uname -a
> Linux stretch 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) 
> x86_64 GNU/Linux
> $ cat /etc/debian_version
> 9.6
> $ apt-cache policy tcl8.5
> tcl8.5:
> Installed: 8.5.19-2+b1
> Candidate: 8.5.19-2+b1
> $ hg clonehttps://bitbucket.org/naviserver/naviserver
> $ cd naviserver
> $ ./autogen.sh --disable-ipv6 --with-tcl=/usr/lib/tcl8.5 
> --enable-rpath --enable-threads --enable-symbols
> $ make
> $ sudo make install
> $ cat ~/test.tcl
>
> package require try
> ::try {
> ns_log Notice "[clock scan "+365 days"]"
> } on error [list message options] {
> ns_log Notice "$message"
> ns_log Notice "$options"
> }
>
> ## Copy test.tcl into tcl dir
>
> $ sudo cp test.tcl /usr/local/ns/tcl/
> $ sudo /usr/local/ns/bin/nsd -u nsd -t 
> /usr/local/ns/conf/nsd-config.tcl -c
>
> ## Not working
>
> % ::try { puts trying } on error [list message options] { puts error }
> can't read "magicCodes": no such variable
> % clock scan "+365 days"
> invalid command name "::tcl::clock::scan"
>
> ## Remove test.tcl from tcl dir
>
> $ sudo rm /usr/local/ns/tcl/test.tcl
>
> ## Working
>
> % package require try
> 1
> % ::try { puts trying } on error [list message options] { puts error }
> trying
> % clock scan "+365 days"
> 1580169600
>
>
>
>
>
> On Fri, 25 Jan 2019 at 18:42, Gustaf Neumann <ne...@wu... 
> <mailto:ne...@wu...>> wrote:
>
>     On 25.01.19 13:44, David Osborne wrote:
>>     When attempting to use the tip version of NaviServer, whenever we
>>     use the tcllib's ::try command (which we need because we're
>>     running Tcl8.5) we get an error: "unknown namespace in import
>>     pattern "::tcl::control::try"
>>
>>     I've tried to simplify the testcase as much as I can to the
>>     following under Debian Stretch. The error also occurs under
>>     Debian Jessie.
>
>     Dear David,
>
>     you might try the following change
>
>     https://bitbucket.org/naviserver/naviserver/commits/0cac39752fbb1026061df8b0a63212584c5f190d
>
>     thanks for the good test specification and case!
>
>     -g
>
>
>     _______________________________________________
>     naviserver-devel mailing list
>     nav...@li...
>     <mailto:nav...@li...>
>     https://lists.sourceforge.net/lists/listinfo/naviserver-devel
>
>
>
> -- 
> David Osborne
> Qcode Software Limited
> http://www.qcode.co.uk
> T: +44 (0)1463 896484
>
>
>
> _______________________________________________
> naviserver-devel mailing list
> nav...@li...
> https://lists.sourceforge.net/lists/listinfo/naviserver-devel


-- 
Univ.Prof. Dr. Gustaf Neumann
WU Vienna
Institute of Information Systems and New Media
Welthandelsplatz 1, A-1020 Vienna, Austria

Re: [naviserver-devel] ns_log output garbled on Windows

[Gustaf N. <ne...@wu...>]

On 28.01.19 16:51, Andrew Piskorski wrote:
> Btw, the log output differs between Windows and Linux in other minor
> but suspicious ways!  Linux says "Notice:" as I expect, while Windows
> instead says "[Notice]" for the severity.  The 3rd Linux field,
> "[-main-]", is completely missing on Windows!  Likely that's related
> somehow?  If Ns_ThreadGetName() returns NULL or empty string there,
> could that mess up the formatting of the rest of the line?
this is weird. actually, the thread name should not be NULL, and
even, when it is NULL, it should not lead to these results.

In case, the name is for unknown reason not initialized, the change [1]
should help.

The function Ns_ThreadId() returns uintptr_t, which is printed with 
format-code PRIxPTR, maybe here is something
wrong. There is some indication [2], that the C99 prefix "ll" does not 
work in all versions of MSC.
However, newer versions of MSC support inttypes.h. Do you compile with 
the macro HAVE_INTTYPES_H
enabled?

 > not know why one is relevant here, but maybe the string formatting
> actually happens in LogToDString().

yes, formatting happens in LogToDString().


[1] 
https://bitbucket.org/naviserver/naviserver/commits/a1a07e7f1397e71809c74ca3a4bf93649affd8b2

[2] 
https://stackoverflow.com/questions/18107426/printf-format-for-unsigned-int64-on-windows

-gn

Re: [naviserver-devel] Using tcllib ::try

[David O. <da...@qc...>]

Thanks Gustaf,

That got me past the immediate problem - but I'm now seeing some further
issues which I can't fully explain.

1. Tcl8.5 only - After clock scan : invalid command name
"::tcl::clock::scan"
2. Tcl8.5 & Tcl8.6 After ::try .. on error : can't read "magicCodes": no
such variable

The errors only seem to happen after the commands are executed on startup
within ns/tcl


$ uname -a
Linux stretch 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64
GNU/Linux
$ cat /etc/debian_version
9.6
$ apt-cache policy tcl8.5
tcl8.5:
  Installed: 8.5.19-2+b1
  Candidate: 8.5.19-2+b1
$ hg clone https://bitbucket.org/naviserver/naviserver
$ cd naviserver
$ ./autogen.sh --disable-ipv6 --with-tcl=/usr/lib/tcl8.5 --enable-rpath
--enable-threads --enable-symbols
$ make
$ sudo make install
$ cat ~/test.tcl

package require try
::try {
    ns_log Notice "[clock scan "+365 days"]"
} on error [list message options] {
    ns_log Notice "$message"
    ns_log Notice "$options"
}

## Copy test.tcl into tcl dir

$ sudo cp test.tcl /usr/local/ns/tcl/
$ sudo /usr/local/ns/bin/nsd -u nsd -t /usr/local/ns/conf/nsd-config.tcl -c

## Not working

% ::try { puts trying } on error [list message options] { puts error }
can't read "magicCodes": no such variable
% clock scan "+365 days"
invalid command name "::tcl::clock::scan"

## Remove test.tcl from tcl dir

$ sudo rm /usr/local/ns/tcl/test.tcl

## Working

% package require try
1
% ::try { puts trying } on error [list message options] { puts error }
trying
% clock scan "+365 days"
1580169600





On Fri, 25 Jan 2019 at 18:42, Gustaf Neumann <ne...@wu...> wrote:

> On 25.01.19 13:44, David Osborne wrote:
>
> When attempting to use the tip version of NaviServer, whenever we use the
> tcllib's ::try command (which we need because we're running Tcl8.5) we get
> an error: "unknown namespace in import pattern "::tcl::control::try"
>
> I've tried to simplify the testcase as much as I can to the following
> under Debian Stretch. The error also occurs under Debian Jessie.
>
> Dear David,
>
> you might try the following change
>
>
> https://bitbucket.org/naviserver/naviserver/commits/0cac39752fbb1026061df8b0a63212584c5f190d
>
> thanks for the good test specification and case!
>
> -g
>
> _______________________________________________
> naviserver-devel mailing list
> nav...@li...
> https://lists.sourceforge.net/lists/listinfo/naviserver-devel
>


-- 
David Osborne
Qcode Software Limited
http://www.qcode.co.uk
T: +44 (0)1463 896484

[naviserver-devel] ns_log output garbled on Windows

[Andrew P. <at...@pi...>]

On Windows, ns_log output is garbled.  Below is some of the output
from running "nsd.exe -f" in a Windows Command Prompt window.

The 4th printed field, immediately after the severity, always has some
garbled junk, which is then followed by readable text. This happens
regardless of what NaviServer config file I use, including the
simple-config.tcl that ships with NaviSever.  This never happened with
old c. 2014 versions of NaviServer on Windows.

Btw, the log output differs between Windows and Linux in other minor
but suspicious ways!  Linux says "Notice:" as I expect, while Windows
instead says "[Notice]" for the severity.  The 3rd Linux field,
"[-main-]", is completely missing on Windows!  Likely that's related
somehow?  If Ns_ThreadGetName() returns NULL or empty string there,
could that mess up the formatting of the rest of the line?

The code that prints the log lines appears to be Ns_VALog() in
"naviserver/nsd/log.c", either the Ns_DStringVPrintf() there or (more
likely) the LogFlush() call.  There are several code paths, and I do
not know why one is relevant here, but maybe the string formatting
actually happens in LogToDString().


## Windows -f log output:
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] \⌡0: No support for OpenSSL compiled in
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] Φ√0: nsmain: NaviServer/4.99 (NaviServer 4.99.17) starting
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] ╨√0: nsmain: Tcl version: 8.5.16
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] h∙0: pool default: queueLength 90 low water 9 high water 72
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] L°0: nsd/init.tcl[default]: booting virtual server:  Tcl system encoding: "utf-8"
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] ä≥0: modload: loading module nscp from file nscp
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] T≥0: nscp[default]: listening on [::1]:2080
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Warning] (±0: nscp[default]: no authorized users
[25/Jan/2019:16:10:43][12164.1cc0470000006a0][Notice] ä≥0: modload: loading module nslog from file nslog

## Linux -f log output:
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: OpenSSL 1.0.2g  1 Mar 2016 initialized
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nsmain: NaviServer/4.99.17 (7460924484c2 default tip) starting
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nsmain: security info: uid=1010, euid=1010, gid=501, egid=501
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nsmain: Tcl version: 8.6.5
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nsmain: max files: soft limit 1048576, hard limit 1048576
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Warning: nsmain: rl_cur (1048576) > FD_SETSIZE (1024), select() calls should not be used
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: pool default: queueLength 90 low water 9 high water 72
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nsd/init.tcl[default]: booting virtual server:  Tcl system encoding: "utf-8"
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: modload: loading module nscp from file nscp
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: nscp[default]: listening on [::1]:2080
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Warning: nscp[default]: no authorized users
[28/Jan/2019:10:33:20][28016.7fb29de89700][-main-] Notice: modload: loading module nslog from file nslog

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] Using tcllib ::try

[Gustaf N. <ne...@wu...>]

On 25.01.19 13:44, David Osborne wrote:
> When attempting to use the tip version of NaviServer, whenever we use 
> the tcllib's ::try command (which we need because we're running 
> Tcl8.5) we get an error: "unknown namespace in import pattern 
> "::tcl::control::try"
>
> I've tried to simplify the testcase as much as I can to the following 
> under Debian Stretch. The error also occurs under Debian Jessie.

Dear David,

you might try the following change

https://bitbucket.org/naviserver/naviserver/commits/0cac39752fbb1026061df8b0a63212584c5f190d

thanks for the good test specification and case!

-g

[naviserver-devel] Using tcllib ::try

[David O. <da...@qc...>]

Hi,

I was wondering of you would be able to help us get past this issue. When
attempting to use the tip version of NaviServer, whenever we use the
tcllib's ::try command (which we need because we're running Tcl8.5) we get
an error: "unknown namespace in import pattern "::tcl::control::try"

I've tried to simplify the testcase as much as I can to the following under
Debian Stretch. The error also occurs under Debian Jessie.
Any idea what's going on?

$ uname -a
Linux stretch 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64
GNU/Linux
$ cat /etc/debian_version
8.6
$ apt-cache policy tcl8.5
tcl8.5:
  Installed: 8.5.19-2+b1
  Candidate: 8.5.19-2+b1
$ apt-cache policy tcllib
tcllib:
  Installed: 1.18-dfsg-3
  Candidate: 1.18-dfsg-3
$ hg clone https://bitbucket.org/naviserver/naviserver
$ cd naviserver
$ ./autogen.sh --disable-ipv6 --with-tcl=/usr/lib/tcl8.5 --enable-rpath
--enable-threads --enable-symbols
$ make
$ sudo make install
$ cat ~/test.tcl
package require try
::try {
puts trying
}
$ sudo cp test.tcl /usr/local/ns/tcl/
$ sudo /usr/local/ns/bin/nsd -u nsd -t /usr/local/ns/conf/nsd-config.tcl


[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: OpenSSL 1.1.0j
20 Nov 2018 initialized
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain: enable
progress statistics for uploads >= 1048576 bytes
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain:
NaviServer/4.99.17 (bb78064b1137 default tip) starting
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain: security
info: uid=1004, euid=1004, gid=1004, egid=1004
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain: Tcl
version: 8.5.19
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain: max
files: soft limit 1048576, hard limit 1048576
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Warning: nsmain: rl_cur
(1048576) > FD_SETSIZE (1024), select() calls should not be used
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: pool default:
queueLength 0 low water 0 high water 0
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice:
nsd/init.tcl[default]: booting virtual server:  Tcl system encoding: "utf-8"
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: modload: loading
module nscp from file nscp
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: binder: started
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nscp[default]:
listening on [0.0.0.0]:4080
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nscp[default]:
added user: ""
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: modload: loading
module nslog from file nslog
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nslog: opened
'/usr/local/ns/logs/access.log'
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: modload: loading
module nscgi from file nscgi
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nscgi: GET
/cgi-bin -> /usr/local/ns/cgi-bin
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nscgi: POST
/cgi-bin -> /usr/local/ns/cgi-bin
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: modload: loading
module nssock from file nssock
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nssock:0: enable
0 spooler thread(s)
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nssock:0: enable
1 writer thread(s) for downloads >= 1048576 bytes, bufsize=8192 bytes, HTML
streaming 0
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: Using ns_cache
implemented as a Tcl proc
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: adp[default]:
mapped {GET HEAD POST} /*.adp
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: tcl[default]:
enabletclpages for {GET HEAD POST} requests
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Warning: ns_md, ns_hmac,
ns_hotp and ns_totp are not available
trying
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: update
interpreter to epoch 1, trace deallocate, time 0.002691 secs
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: update
interpreter to epoch 1, trace none, time 0.002875 secs
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Error: unknown namespace
in import pattern "::tcl::control::try"
unknown namespace in import pattern "::tcl::control::try"
    while executing
"namespace import -force ::tcl::control::try"
    (in namespace eval "::" script line 2)
    invoked from within
"namespace eval :: {
namespace import -force ::tcl::control::try
namespace eval ::tcl::chan {::nstrace::_create_or_config_ensemble ::chan
{-map {blocke..."
(context: update interpreter)
[25/Jan/2019:12:42:08][10914.7fcadbfff700][-driver:nssock:0-] Notice:
starting
[25/Jan/2019:12:42:08][10914.7fcadbfff700][-driver:nssock:0-] Notice:
nssock:0: listening on 0.0.0.0:8080
[25/Jan/2019:12:42:08][10914.7fcadbfff700][-driver:nssock:0-] Notice:
driver: accepting connections
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain:
NaviServer/4.99.17 (bb78064b1137 default tip) running
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][-main-] Notice: nsmain: security
info: uid=1004, euid=1004, gid=1004, egid=1004
[25/Jan/2019:12:42:08][10914.7fcae37fe700][-sched-] Notice: sched: starting
[25/Jan/2019:12:42:08][10914.7fcae3fff700][-socks-] Notice: socks: starting
[25/Jan/2019:12:42:08][10914.7fcaeb9eb700][binder] Notice: binder: stopped
[25/Jan/2019:12:42:08][10914.7fcae957c700][-command-] Notice: update
interpreter to epoch 1, trace none, time 0.003851 secs
[25/Jan/2019:12:42:08][10914.7fcae957c700][-command-] Error: unknown
namespace in import pattern "::tcl::control::try"
unknown namespace in import pattern "::tcl::control::try"
    while executing
"namespace import -force ::tcl::control::try"
    (in namespace eval "::" script line 2)
    invoked from within
"namespace eval :: {
namespace import -force ::tcl::control::try
namespace eval ::tcl::chan {::nstrace::_create_or_config_ensemble ::chan
{-map {blocke..."
(context: update interpreter)
% [25/Jan/2019:12:42:08][10914.7fcadb7fe700][-writer0-] Notice: writer0:
accepting connections
[25/Jan/2019:12:42:08][10914.7fcae0df6700][-conn:default:0:0-] Notice:
update interpreter to epoch 1, trace none, time 0.015119 secs
[25/Jan/2019:12:42:08][10914.7fcae0df6700][-conn:default:0:0-] Error:
unknown namespace in import pattern "::tcl::control::try"
unknown namespace in import pattern "::tcl::control::try"
    while executing
...




-- 
David

Re: [naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Andrew P. <at...@pi...>]

On Tue, Jan 22, 2019 at 10:09:26AM +0100, Gustaf Neumann wrote:

> One thing, which is different with?? SSL_get_version() and 
> SSL_get_cipher() to
> other SSL* function called from tclhttp.c is that these calls are not
> guarded by "HAVE_OPENSSL_EVP_H" (but should probably).

I added that additional ifdef, and now linking nsd.exe works!  I think
actually using nsssl on Windows is still broken, but now NaviServer
builds and appears to run the simple-config.tcl ok.  These fixes are
here:

https://bitbucket.org/naviserver/naviserver/pull-requests/19/windows-build-works-now/diff

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Andrew P. <at...@pi...>]

On Tue, Jan 22, 2019 at 10:09:26AM +0100, Gustaf Neumann wrote:

> After merging it, i had to revert a change, otherwise i got a 
> compilation error:
> 
> ../include/Makefile.module:88: *** Recursive variable `CLEAN' references 
> itself (eventually).?? Stop.

Sorry about that one, Gustaf.  That "simple" change fixed Windows, but
I forgot to also test it on Linux.

Unfortunately Gnu make and Microsoft nmake are only compatible for
very simple makefiles.  The other NaviServer core module makefiles are
so simple that they do work in both versions, but appending to the
CLEAN variable does not.  I'll see if I can come up with some workaround.

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] ns_sourceproc vs. ns_register_tcl

[Zoran V. <zv...@ar...>]

ns_sourceproc is ancient and might as well be declared deprecated. at some point in time one should throw away at least some of the burden carried arround for a long time.
The ns_register_tcl is the way to go. i am sure we have quite a few of such things in the code that require cleanup...

Cheers,
Zoran



> Am 22.01.2019 um 20:58 schrieb Gustaf Neumann <ne...@wu...>:
> 
> Here is a question for the people longer than me at the project:
> 
> - NaviServer has currently two implementations for .tcl requests:
>    "ns_register_tcl" and "ns_sourceproc", where the first one
>    does similar things in C what the latter does in Tcl.
> 
> - "ns_register_tcl" is used by default, when "enabletclpages" is set.
>    However, the documentation [1] mentions "ns_sourceproc"
> 
> Is my interpretation right that "ns_sourceproc" is outdated, or is there
> any reason aside of backward compatibility to use this? If so,
> then "ns_sourceproc" should be deprecated. Anyway, the documentation
> has to be updated. Do i miss here anything?
> 
> All the best
> 
> -g
> 
> [1] https://naviserver.sourceforge.io/n/manual/files/tcl-lib-file.html
> 
> 
> 
> _______________________________________________
> naviserver-devel mailing list
> nav...@li...
> https://lists.sourceforge.net/lists/listinfo/naviserver-devel

[naviserver-devel] ns_sourceproc vs. ns_register_tcl

[Gustaf N. <ne...@wu...>]

Here is a question for the people longer than me at the project:

- NaviServer has currently two implementations for .tcl requests:
    "ns_register_tcl" and "ns_sourceproc", where the first one
    does similar things in C what the latter does in Tcl.

- "ns_register_tcl" is used by default, when "enabletclpages" is set.
    However, the documentation [1] mentions "ns_sourceproc"

Is my interpretation right that "ns_sourceproc" is outdated, or is there
any reason aside of backward compatibility to use this? If so,
then "ns_sourceproc" should be deprecated. Anyway, the documentation
has to be updated. Do i miss here anything?

All the best

-g

[1] https://naviserver.sourceforge.io/n/manual/files/tcl-lib-file.html

Re: [naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Gustaf N. <ne...@wu...>]

On 22.01.19 07:44, Andrew Piskorski wrote:
> On Thu, Jan 17, 2019 at 10:10:35PM +0100, Gustaf Neumann wrote:
>
>> Maurizio has built binaries of NaviServer 4.99.17 with openssl-1.1.1a [2].
> I sure could use some hints on how he built NaviServer on Windows!
> I guess he's not reading this, so I'll try contacting him by email.
>
>> Are you sure, you comipile and link against OpenSSL 1.1.1a?
> I'm fairly sure I'm linking against OpenSSL 1.1.1a, because the link
> error about SSL_get_version went away.  The mystery is why I still get
> the SSL_get_cipher link error.
>
> I suspect that the compile may NOT be correct, because of those
> "SSL_get_cipher undefined; assuming extern returning int" warnings.
> But nothing I tried seemed to fix that.
>
> Btw, nsssl.dll now appears to build fine!  It's just libnsd.dll and
> nsd.exe that fail to link.  (Perhaps because SSL_get_cipher is not
> used in nsssl/nsssl.c, it's only in nsd/tclhttp.c.)

One thing, which is different with  SSL_get_version() and 
SSL_get_cipher() to
other SSL* function called from tclhttp.c is that these calls are not
guarded by "HAVE_OPENSSL_EVP_H" (but should probably).

This macro is used to check whether openSSL (or similar) with its 
include files
is available during compilation. So it has to be set probably manually 
either in
Makefile.win32 (DEFS). Not sure, what the best trick for windows is to 
set the
variable, when the openssl library (+includes) are available.

> Weirdly, I could not add Gustaf as a reviewer, as
> the reviewer look-up box refuses to find him!  (Same thing for Zoran.)
> Hopefully that's some sort of temporary bitbucket.org bug.

bitbucket sent me a mail (at least to me) with the pull request.

After merging it, i had to revert a change, otherwise i got a 
compilation error:

../include/Makefile.module:88: *** Recursive variable `CLEAN' references 
itself (eventually).  Stop.

All the best,

-gn

Re: [naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Andrew P. <at...@pi...>]

On Thu, Jan 17, 2019 at 10:10:35PM +0100, Gustaf Neumann wrote:

> Maurizio has built binaries of NaviServer 4.99.17 with openssl-1.1.1a [2].

I sure could use some hints on how he built NaviServer on Windows!
I guess he's not reading this, so I'll try contacting him by email.

> Are you sure, you comipile and link against OpenSSL 1.1.1a?

I'm fairly sure I'm linking against OpenSSL 1.1.1a, because the link
error about SSL_get_version went away.  The mystery is why I still get
the SSL_get_cipher link error.

I suspect that the compile may NOT be correct, because of those
"SSL_get_cipher undefined; assuming extern returning int" warnings.
But nothing I tried seemed to fix that.

Btw, nsssl.dll now appears to build fine!  It's just libnsd.dll and
nsd.exe that fail to link.  (Perhaps because SSL_get_cipher is not
used in nsssl/nsssl.c, it's only in nsd/tclhttp.c.)

My recent Windows build fixes are now here in this pull request:

  https://bitbucket.org/naviserver/naviserver/pull-requests/18/windows-build-fixes-and-attempted-fixes/diff

That includes some working fixes, plus my attempts (failures) to get
nsd.exe to build.  Weirdly, I could not add Gustaf as a reviewer, as
the reviewer look-up box refuses to find him!  (Same thing for Zoran.)
Hopefully that's some sort of temporary bitbucket.org bug.

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] ns_striphtml test failures?

[Andrew P. <at...@pi...>]

On Thu, Jan 17, 2019 at 11:11:08PM +0100, Gustaf Neumann wrote:

> I've now replaced the UTF-8 string literals by 
> hexadecimal-escape-sequences on bitbucket [1].
> [1] 
> https://bitbucket.org/naviserver/naviserver/commits/5c915e2412de64d0ee9e5c85a9fd46c59bc64ea4

I tried it, no difference, still the same 8 ns_striphtml test failures
as before.  After that, I also rebuilt with "-finput-charset=UTF-8"
added to CFLAGS_EXTRA in include/Makefile.global; that also made no
difference.

However, next I built Tcl 8.6.9 from source myself, and to my
surprise, THAT fixed the ns_striphtml test failures!  For some reason
NaviServer now skipped the 4 nsf tests, but hopefully that doesn't
matter, since they passed before.


## Newer from-source Tcl:
$ /usr/local/pkg/tcl-8.6.9-20190118/bin/tclsh8.6
% info patchlevel
8.6.9

## Older Ubuntu Tcl, ns_striphtml tests fail:
$ /usr/bin/tclsh8.6
% info patchlevel
8.6.5
	    
-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] ns_striphtml test failures?

[Gustaf N. <ne...@wu...>]

On 17.01.19 09:55, Gustaf Neumann wrote:
> maybe one has to add for older gccs "-finput-charset" or setting 
> "LANG=en_US.UTF-8" before compiling. If this is the case, one has to 
> replace the utf-8 strings in tclmisc.c to backslash sequences.

I've now replaced the UTF-8 string literals by 
hexadecimal-escape-sequences on bitbucket [1].
Please check, if this helps in your case.

-gn

[1] 
https://bitbucket.org/naviserver/naviserver/commits/5c915e2412de64d0ee9e5c85a9fd46c59bc64ea4

Re: [naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Gustaf N. <ne...@wu...>]

On 17.01.19 19:08, Andrew Piskorski wrote:
> I'm using the pre-compiled Windows OpenSSL libraries build found here:
>
>    http://www.slproweb.com/products/Win32OpenSSL.html
>    Win32OpenSSL-1_1_1a.exe
>
> Below in my nmake run, you can see that tclhttp.c throws warnings
> about not finding SSL_get_version and SSL_get_cipher, and then the nsd
> DLL and EXE files fail to link.

SSL_get_version() [1] is in OpenSSL at least since 0.9.7 (the oldest 
version i have around).

it is declared in openssl/ssl.h and is defined in libssl:

    % nm /usr/local/lib/libssl.1.1.dylib |fgrep SSL_get_version
    0000000000022520 T _SSL_get_version

Maurizio has built binaries of NaviServer 4.99.17 with openssl-1.1.1a [2].
Are you sure, you comipile and link against OpenSSL 1.1.1a?

-g

[1] https://www.openssl.org/docs/man1.1.0/ssl/SSL_get_version.html
[2] https://www.spazioit.com/pages_en/sol_inf_en/windows-openacs_en

[naviserver-devel] Windows nsd build breaks on tclhttp.c SSL_get_cipher

[Andrew P. <at...@pi...>]

I'm stuck trying to get the latest NaviServer to build on Windows, due
to the OpenSSL support integrated a while back.  Does anyone have
advice on how I should debug this?

I'm using the pre-compiled Windows OpenSSL libraries build found here:

  http://www.slproweb.com/products/Win32OpenSSL.html
  Win32OpenSSL-1_1_1a.exe

Below in my nmake run, you can see that tclhttp.c throws warnings
about not finding SSL_get_version and SSL_get_cipher, and then the nsd
DLL and EXE files fail to link.

Originally the link threw two errors like this:

  tclhttp.o : error LNK2019: unresolved external symbol _SSL_get_cipher  referenced in function _HttpConnect
  tclhttp.o : error LNK2019: unresolved external symbol _SSL_get_version referenced in function _HttpConnect

But then I fixed my build commands, and the _SSL_get_version error
went away.  Weirdly, the _SSL_get_cipher link error is still there,
even though it is defined in that same OpenSSL library!  I don't know
why.

In nsd/tclhttp.c, if I add a line to include openssl/ssl.h, the
undefined warnings go away, but then I get much worse errors:

  error C2371:  'intmax_t' : redefinition; different basic types
  error C2371: 'uintmax_t' : redefinition; different basic types

I attempted to edit openssl/ssl.h to remove the intmax_t and uintmax_t
typedefs, but that didn't seem to work.  So I stopped trying to
include ssl.h

Currently I am stuck...  Any helpful hints?

Note, the run below required some hacks to Makefile.win32 and
include/Makefile.win32 to get this far, so you can't just run it
verbatim:

------------------------------------------------------------
Z:\src\web\ns-fork-dtk\naviserver>nmake -f Makefile.win32  _nsd  NAVISERVER=..\naviserver

Microsoft (R) Program Maintenance Utility Version 10.00.30319.01
Copyright (C) Microsoft Corporation.  All rights reserved.

openssl_dir is set to [1]:  C:\P\OpenSSL-Win32
Appending to LIB and INCLUDE.
        pushd nsd & nmake /nologo TCLPATH="C:\P\Tcl-32" TCLLIB="tcl85.lib" LIB="C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\Lib;C:\Program Files\Microsoft SDKs\Windows\v7.1\Lib;C:\Windows\Microsoft.NET\Framework\v4.0.30319;C:\Windows\Microsoft.NET\Framework\v3.5;;;C:\P\Tcl-32\lib;C:\P\OpenSSL-Win32\lib;C:\P\OpenSSL-Win32\lib\VC;C:\P\OpenSSL-Win32\lib\VC\static" DEBUG=1 openssl_dir=C:\P\OpenSSL-Win32 & popd
Library names are:  DLLBIN: libnsd.dll  DLLLIB: libnsd.lib
        cl /W3 /nologo /c /EHsc /MDd /Od /Zi /RTC1 /I "..\include" /I "C:\P\OpenSSL-Win32\include"  /I "C:\P\Tcl-32\include" /D "_WINDOWS" /D "TCL_THREADS=1"  /D "FD_SETSIZE=128" /D "_MBCS"  /D _CRT_SECURE_NO_WARNINGS /D _CRT_SECURE_NO_DEPRECATE /D _USE_32BIT_TIME_T /D "_DEBUG" /c /Fotclhttp.o tclhttp.c
tclhttp.c
tclhttp.c(1950) : warning C4013: 'SSL_get_version' undefined; assuming extern returning int
tclhttp.c(1950) : warning C4047: 'function' : 'const char *' differs in levels of indirection from 'int'
tclhttp.c(1950) : warning C4024: 'HttpTaskAddInfo' : different types for formal and actual parameter 3
tclhttp.c(1951) : warning C4013: 'SSL_get_cipher' undefined; assuming extern returning int
tclhttp.c(1951) : warning C4047: 'function' : 'const char *' differs in levels of indirection from 'int'
tclhttp.c(1951) : warning C4024: 'HttpTaskAddInfo' : different types for formal and actual parameter 3
        link.exe /NOLOGO /SUBSYSTEM:CONSOLE /OPT:NOREF /OPT:NOICF /DEBUG  /DLL /OUT:libnsd.dll /IMPLIB:libnsd.lib     adpcmds.o adpeval.o adpparse.o adprequest.o auth.o binder.o  cache.o callbacks.o cls.o compress.o config.o conn.o connio.o  cookies.o connchan.o  crypt.o dns.o driver.o dstring.o encoding.o event.o exec.o  fastpath.o fd.o filter.o form.o httptime.o index.o info.o  init.o limits.o lisp.o listen.o log.o mimetypes.o modload.o nsconf.o  nsmain.o nsthread.o op.o pathname.o pidfile.o proc.o progress.o queue.o  quotehtml.o random.o range.o request.o return.o returnresp.o rollfile.o  sched.o server.o set.o sls.o sock.o sockcallback.o sockfile.o str.o  task.o tclcache.o tclcallbacks.o tclcmds.o tclconf.o tclenv.o tclfile.o  tclhttp.o tclimg.o tclinit.o
tcljob.o tclmisc.o tclobj.o tclobjv.o  tclrequest.o tclresp.o tclsched.o tclset.o tclsock.o sockaddr.o  tclthread.o tcltime.o tclvar.o tclxkeylist.o tls.o stamp.o  url.o url2file.o urlencode.o urlopen.o urlspace.o uuencode.o  unix.o watchdog.o nswin32.o tclcrypto.o   /LIBPATH:"..\nsthread" nsthread.lib "/LIBPATH:C:\P\OpenSSL-Win32\lib\VC" libssl32MDd.lib libcrypto32MDd.lib /LIBPATH:"C:\P\Tcl-32\lib" tcl85.lib tcl85.lib kernel32.lib advapi32.lib ws2_32.lib user32.lib
   Creating library libnsd.lib and object libnsd.exp
tclhttp.o : error LNK2019: unresolved external symbol _SSL_get_cipher referenced in function _HttpConnect
libnsd.dll : fatal error LNK1120: 1 unresolved externals
NMAKE : fatal error U1077: '"C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\Bin\link.exe"' : return code '0x460'
Stop.
------------------------------------------------------------

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] ns_striphtml test failures?

[Gustaf N. <ne...@wu...>]

On 16.01.19 20:39, Andrew Piskorski wrote:
> I built the latest NaviServer head from source (on Linux, Ubuntu
> 16.04.2 LTS), and "make test" is reporting 8 failures, all with
> ns_striphtml.  Is this a known problem, or do I have something broken?

Just a quick feedback: it is not a known problem, i don't see this on 
our systems
(checked quickly with Debian sid and macOS). The version i am testing is two
(unrelated) commits ahead of yours, but there is no relation in these 
commits.

You have on the system an older Tcl version (8.6.5), but i would be 
surprised,
if this makes a difference. Debian sid is the bleeding edge Debian, so this
has newer compilers etc., maybe one has to add for older gccs 
"-finput-charset"
or setting "LANG=en_US.UTF-8" before compiling. If this is the case, one 
has to
replace the utf-8 strings in tclmisc.c to backslash sequences.

If the above sheds no light, I'll try to test with Tcl 8.6.5 and
Ubuntu 16.04.2 the next days.

all the best

-g
PS: The log message about <NULL> is a false warning, i've removed it 
already.

================================================================
% make test TESTFLAGS="-verbose start -file ns_striphtml.test"
...
[15/Jan/2019:20:07:13][5226.7fe5a5153740][-main-] Notice: nsmain: NaviServer/4.99.17 (49c314f2b1e9+ default tip) starting
...
[15/Jan/2019:20:07:13][5226.7fe5a5153740][-main-] Notice: nsmain: Tcl version: 8.6.9
...
Only running test files that match:  ns_striphtml.test
Tests began at Tue Jan 15 20:07:13 CET 2019
ns_striphtml.test
---- ns_striphtml-1.0 start
---- ns_striphtml-2.0.1 start
---- ns_striphtml-2.0.2 start
---- ns_striphtml-2.0.3 start
---- ns_striphtml-2.1 start
---- ns_striphtml-2.2 start
---- ns_striphtml-2.2b start
---- ns_striphtml-2.3 start
---- ns_striphtml-2.3b start
---- ns_striphtml-2.4 start
---- ns_striphtml-2.4b start
---- ns_striphtml-3.0 start
[15/Jan/2019:20:07:13][5226.7fe597ecb700][-command-] Notice: name length of <NULL> incorrect, should be 4
---- ns_striphtml-4.0 start

Tests ended at Tue Jan 15 20:07:13 CET 2019
all.tcl:        Total   13      Passed  13      Skipped 0       Failed  0
Sourced 1 Test Files.
...
% env
LC_ALL=en_US.UTF-8
LANG=en_US.UTF-8


> >From the test output, it looks like the test failures are always
> because ns_striphtml is stripping MORE than it is supposed to, e.g.:
>
> ==== ns_striphtml-2.0.1 nbsp entity FAILED
> ---- Result was:
> helloworld
> ---- Result should have been (exact matching):
> hello world
> ==== ns_striphtml-2.0.1 FAILED
>
> ==== ns_striphtml-2.0.2 nbsp entity FAILED
> ---- Result was:
> helloworld
> ---- Result should have been (exact matching):
> hello<world
> ==== ns_striphtml-2.0.2 FAILED
>
> Btw, I ran the tests from shells with each of these two different LANG
> settings, but (fortunately) that seemed to make no difference, the
> same 8 tests fail the same way in both cases:
>
>    LANG=en_US.UTF-8
>    LANG=en_US.iso-8859-1
>
> I've also attached the full "make test" output file.

[naviserver-devel] ns_striphtml test failures?

[Andrew P. <at...@pi...>]

I built the latest NaviServer head from source (on Linux, Ubuntu
16.04.2 LTS), and "make test" is reporting 8 failures, all with
ns_striphtml.  Is this a known problem, or do I have something broken?

>From the test output, it looks like the test failures are always
because ns_striphtml is stripping MORE than it is supposed to, e.g.:

==== ns_striphtml-2.0.1 nbsp entity FAILED
---- Result was:
helloworld
---- Result should have been (exact matching):
hello world
==== ns_striphtml-2.0.1 FAILED

==== ns_striphtml-2.0.2 nbsp entity FAILED
---- Result was:
helloworld
---- Result should have been (exact matching):
hello<world
==== ns_striphtml-2.0.2 FAILED

Btw, I ran the tests from shells with each of these two different LANG
settings, but (fortunately) that seemed to make no difference, the
same 8 tests fail the same way in both cases:

  LANG=en_US.UTF-8
  LANG=en_US.iso-8859-1

I've also attached the full "make test" output file.

-- 
Andrew Piskorski <at...@pi...>

Re: [naviserver-devel] keepalive performance issue

[Jeff R. <dv...@di...>]

Thanks!   This was puzzling me;  I had found a few references to Nagle in
searching but it didn't seem to make sense.  TCP_CORK appears to be already
used which I thought was in essence manual management of the packet
delays, but I guess not.  Yay, linux?

In any case, setting the option correctly makes the server do just what 
I was
expecting it to do in the first place.

-J

On 12/04/2018 12:48 AM, Gustaf Neumann wrote:
> > Hi Jeff, > > I found the problem: One has just to tell Linux to turn 
the delay > off. > > What sounds as a joke can be done in the config 
file as shown below, >  which turns off the good old Nagle algorithm for 
incoming packages > on the keep-alive socket. This reduces the delay 
seen from poll() > substantially. > > We should probably change the 
default for "nodelay" on nssock and > nsssl from "false" to "true". It 
seems, that e.g. mozilla has done > this ~8 years ago. > > all the best 
-g > > PS: setting minthreads is limited to the current value of 
maxthreads. > so, when setting only minthreads to a value of 20 (as in 
your > example) the effective value is 10 (the default for maxthreads). 
So, > probably we should align the value of maxthreads when setting the 
 > value of minthreads above maxthreads, and vice versa when setting > 
maxthreads to a value lower than minthreads. > > > ns_section      
"ns/servers" ns_param         default Naviserver > > ns_section      
"ns/server/default" ns_param maxthreads 20 ns_param > minthreads 20 > > 
ns_section      "ns/server/default/modules" ns_param         nssock > 
nssock.so ns_param         nslog           nslog.so > > ns_section      
"ns/server/default/module/nssock" ns_param port 8080 >  ns_param nodelay 
true > >> On 30.11.18 21:17, Jeff Rogers wrote: >>> Ok, thickening the 
plot a little bit - if I enable adp parsing >>> and serve the exact same 
file as adp, the delay on localhost >>> goes away.   So, something weird 
with plain file handling on >>> loopback? >> i tested now with 
debian-sid and can confirm the behavior, which >> happens on linux, but 
not on macOS. > > > > > _______________________________________________ 
naviserver-devel > mailing list nav...@li... > 
https://lists.sourceforge.net/lists/listinfo/naviserver-devel

Re: [naviserver-devel] keepalive performance issue

[Gustaf N. <ne...@wu...>]

Hi Jeff,

I found the problem: One has just to tell Linux to turn the delay off.

What sounds as a joke can be done in the config file as shown below,
which turns off the good old Nagle algorithm for incoming packages
on the keep-alive socket. This reduces the delay seen from poll()
substantially.

We should probably change the default for "nodelay" on nssock and
nsssl from "false" to "true". It seems, that e.g. mozilla has done this
~8 years ago.

all the best
-g

PS: setting minthreads is limited to the current value of maxthreads.
so, when setting only minthreads to a value of 20 (as in your example)
the effective value is 10 (the default for maxthreads). So, probably
we should align the value of maxthreads when setting the value
of minthreads above maxthreads, and vice versa when setting
maxthreads to a value lower than minthreads.


ns_section      "ns/servers"
ns_param         default         Naviserver

ns_section      "ns/server/default"
ns_param maxthreads 20
ns_param minthreads 20

ns_section      "ns/server/default/modules"
ns_param         nssock          nssock.so
ns_param         nslog           nslog.so

ns_section      "ns/server/default/module/nssock"
ns_param port 8080
ns_param nodelay true

> On 30.11.18 21:17, Jeff Rogers wrote:
>> Ok, thickening the plot a little bit - if I enable adp parsing and 
>> serve the exact same file as adp, the delay on localhost goes away.   
>> So, something weird with plain file handling on loopback?
> i tested now with debian-sid and can confirm the behavior, which
> happens on linux, but not on macOS.

Re: [naviserver-devel] keepalive performance issue

[Gustaf N. <ne...@wu...>]

On 30.11.18 21:17, Jeff Rogers wrote:
> Ok, thickening the plot a little bit - if I enable adp parsing and 
> serve the exact same file as adp, the delay on localhost goes away.   
> So, something weird with plain file handling on loopback?
i tested now with debian-sid and can confirm the behavior, which
happens on linux, but not on macOS.

This is really strange:

- adp works via NsAdpPageProc(), the plain file works via Ns_FastPathProc()
    but the driver calls are the same.

- Ns_FastPathProc() has actually three modes, "mmap", "cache" and 
"delivery via fd"
    (last is default). The behavior is the same in all three modes.

- when configuring writerthreads (which is recommended), and one 
requests content larger than
    1K then the behavior disappears.

    The 1k lower limit is currently hard-coded, under the assumption for 
very small
    chunks, the context switch overhead might be more expensive than a 
potential
    gain of the writer thread.

- The behavior lust like this on loopback devices.

There is no special handling of loopback devices in NaviServer.

-gn

Re: [naviserver-devel] keepalive performance issue

[Jeff R. <dv...@di...>]

Ok, thickening the plot a little bit - if I enable adp parsing and serve 
the exact same file as adp, the delay on localhost goes away.   So, 
something weird with plain file handling on loopback?

-J


On 11/30/2018 11:51 AM, Jeff Rogers wrote:
>
> So really, this appears to be NOT a naviserver issue...

Re: [naviserver-devel] keepalive performance issue

[Jeff R. <dv...@di...>]

Hi Gustaf,

The results are completely stable, from 5 to 5000 requests, and with 
concurrency from 1 to 10ish.   I'm running on linux, haven't had any 
issues with ab before.   I actually initially noticed the issue using 
jmeter.

The timing is stable enough that it feels like a timeout or artificial 
delay, but no idea what that would be.   Here is a snippet from 'strace 
-r' output that highlights a delay of about the right amount of time:

[pid 19394]      0.000012 write(2, 
"[30/Nov/2018:10:24:11][19386.7fd"..., 108 <unfinished ...>
[30/Nov/2018:10:24:11][19386.7fdb0b086700][-conn:default:1:1-] 
Debug(request): end GET /hello.html HTTP/1.0
[pid 19395]      0.000008 poll([{fd=5, events=POLLIN}, {fd=7, 
events=POLLIN}, {fd=8, events=POLLIN}], 3, 5001 <unfinished ...>
[pid 19394]      0.000016 <... write resumed> ) = 108
[pid 19394]      0.000021 write(2, 
"[30/Nov/2018:10:24:11][19386.7fd"..., 
269[30/Nov/2018:10:24:11][19386.7fdb0b086700][-conn:default:1:1-] Debug: 
[1] end of job, waiting 0 current 2 idle 1 ncons 9998 fromQueue 0 start 
1543602251.352459 1543602251.352459 accept 0.000000 queue 0.000491 
filter 0.000051 run 0.000971 netrun 0.000920 total 0.001462
) = 269
[pid 19394]      0.000039 futex(0x1722224, 
FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 5, {1543602371, 
353964000}, ffffffff <unfinished ...>
[pid 19395]      0.039269 <... poll resumed> ) = 1 ([{fd=8, 
revents=POLLIN}])
[pid 19395]      0.000058 write(2, 
"[30/Nov/2018:10:24:11][19386.7fd"..., 
118[30/Nov/2018:10:24:11][19386.7fdb0a885700][-driver:nssock:0-] 
Debug(ns:driver): === PollWait returned 1, trigger[0] 0
) = 118
[pid 19395]      0.000065 write(2, 
"[30/Nov/2018:10:24:11][19386.7fd"..., 
108[30/Nov/2018:10:24:11][19386.7fdb0a885700][-driver:nssock:0-] 
Debug(ns:driver): RequestNew reuses a Request
) = 108

Right around 39ms in "... poll resumed".

I tried running ab from a different host, and there, things work as 
expected.   I wonder if there is some localhost network delay being 
injected here (delayed ack or nagle?).   Strangely tho, tclhttpd isn't 
affected; the keepalive and non-keepalive times are both in the 1 
ms/request range.

So really, this appears to be NOT a naviserver issue...

-J

On 11/30/2018 01:11 AM, Gustaf Neumann wrote:
> Hi Jeff,
>
> 30 requests are not a lot. Are these results stable?
> When I tried to repeat your results, I started the server
> with your configuration:
>
>     /usr/local/ns/bin/nsd -u nsadmin -t ~/scripts/aol/jeff-conf.tcl -f
>
> When running "ab" without -k" and 1000 requests:
>     ab -n 1000 -c 1http://localhost:8080/hello.html
>     ...
>     Time per request:       0.168 [ms] (mean)
> When running  "ab" with -k" and 1000 requests:
>     ab -k -n 1000 -c 1http://localhost:8080/hello.html
>     ...
>     Time per request:       0.098 [ms] (mean)
> The results of "ab" are most probably platform dependent.
> My results are on a notebook with macOS Darwin 17.7.0,
> NaviServer 4.99.17, some snapshot of Tcl 8.7,
> most components without C-level optimization.
>
> The reported times show that the keepalive option
> improves the results, which is an expected result.
>
> With high numbers for "-c", "ab" hangs sometimes, but that
> might be a problem with "ab" on the mac (Apple version);
> i remember that i had to fix "ab" in the past in order to get results
> on the mac at all.
>
> all the best
> -gn
>
> On 29.11.18 23:48, Jeff Rogers wrote:
>> Hi all,
>>
>> I am running a test using ab against a local naviserver instance with 
>> a vanilla config, and I am seeing requests with http keepalive 
>> enabled having a delay of ~38ms per request compared to 
>> non-keepalive.   This rather surprised me;  is there a config setting 
>> to avoid that delay, or is it otherwise to be expected?
>>
>> My config:
>>
>> ns_section      "ns/servers"
>> ns_param         default         Naviserver
>>
>> ns_section      "ns/server/default"
>> ns_param minthreads 20
>>
>> ns_section      "ns/server/default/modules"
>> ns_param         nscp            nscp.so
>> ns_param         nssock          nssock.so
>> ns_param         nslog           nslog.so
>>
>> ns_section      "ns/server/default/module/nssock"
>> ns_param port 8080
>>
>>
>> Tests:
>>
>> $ ab -n 30 -c 1 http://localhost:8080/hello.html
>> ...
>>
>> Time per request:       0.170 [ms] (mean)
>>
>> $ ab -k -n 30 -c 1 http://localhost:8080/hello.html
>> ...
>>
>> Time per request:       38.666 [ms] (mean) 
>
>
>
>
>
> _______________________________________________
> naviserver-devel mailing list
> nav...@li...
> https://lists.sourceforge.net/lists/listinfo/naviserver-devel

Re: [naviserver-devel] keepalive performance issue

[Gustaf N. <ne...@wu...>]

Hi Jeff,

30 requests are not a lot. Are these results stable?
When I tried to repeat your results, I started the server
with your configuration:

     /usr/local/ns/bin/nsd -u nsadmin -t ~/scripts/aol/jeff-conf.tcl -f

When running "ab" without -k" and 1000 requests:

    ab -n 1000 -c 1  http://localhost:8080/hello.html
    ...
    Time per request:       0.168 [ms] (mean)

When running  "ab" with -k" and 1000 requests:

    ab -k -n 1000 -c 1  http://localhost:8080/hello.html
    ...
    Time per request:       0.098 [ms] (mean)

The results of "ab" are most probably platform dependent.
My results are on a notebook with macOS Darwin 17.7.0,
NaviServer 4.99.17, some snapshot of Tcl 8.7,
most components without C-level optimization.

The reported times show that the keepalive option
improves the results, which is an expected result.

With high numbers for "-c", "ab" hangs sometimes, but that
might be a problem with "ab" on the mac (Apple version);
i remember that i had to fix "ab" in the past in order to get results
on the mac at all.

all the best
-gn

On 29.11.18 23:48, Jeff Rogers wrote:
> Hi all,
>
> I am running a test using ab against a local naviserver instance with 
> a vanilla config, and I am seeing requests with http keepalive enabled 
> having a delay of ~38ms per request compared to non-keepalive.   This 
> rather surprised me;  is there a config setting to avoid that delay, 
> or is it otherwise to be expected?
>
> My config:
>
> ns_section      "ns/servers"
> ns_param         default         Naviserver
>
> ns_section      "ns/server/default"
> ns_param minthreads 20
>
> ns_section      "ns/server/default/modules"
> ns_param         nscp            nscp.so
> ns_param         nssock          nssock.so
> ns_param         nslog           nslog.so
>
> ns_section      "ns/server/default/module/nssock"
> ns_param port 8080
>
>
> Tests:
>
> $ ab -n 30 -c 1  http://localhost:8080/hello.html
> ...
>
> Time per request:       0.170 [ms] (mean)
>
> $ ab -k -n 30 -c 1  http://localhost:8080/hello.html
> ...
>
> Time per request:       38.666 [ms] (mean)