naviserver-devel — Developer discussion

Re: [naviserver-devel] more logging problems on Windows

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

Dear Andrew and all,

Over the weekend, I invested some more time into the windows
port and got a better understanding of the logging  issue (a write()
operation succeeds inside nslog.c, but the identically operations
inside driver.c does not work; "not work" means, that the write
operation succeeds (i.e. reports the written number of bytes),
but the file is always empty, even after a close()).

The problem is not a argument-passing or memory problem,
but seems to be a linking problem. When a file is opened in a
module (here nslog) only this module can write successfully
to this file. Under Windows other dlls can't write to it, even
when they write to the same fd. It seems to me as if the
nslog dll is linked to a private runtime environment.
Looking up the windows handle same file descriptor
(e.g. 3) leads to a different results when performed in nslog.c
or in driver.c (or somewhere else in a function in libnsd).

The current solution is to define for windows stub-functions
ns_open, ns_close, ns_write, ns_read which are defined in libnsd.
These functions are called from ns_log instead of the native
OS functions (under windows _open, _close, _write, _read),
which have btw different prototypes, so this abstraction
seems beneficial for several reasons.

The essential change is in [1], which add the ns_* functions and
reverts the previous  _MSV_VER bypass in nslog.c. For
completeness, ns_tell should be added as well.

Andrew, can you compare the linking options for nslog with these
from Maurizio? Although the problem for nslog seems to be solved,
i would not be surprised if other weirdnesses lurch around
from other modules.

-g

[1] 
https://bitbucket.org/naviserver/naviserver/commits/70437a26eef9f5f8c801bd813434b50f761e0d4e


Am 07.11.14 14:00, schrieb Andrew Piskorski:
> On Thu, Nov 06, 2014 at 03:03:18PM +0100, Gustaf Neumann wrote:
>> The seemingly same write() operation, which refuses to write to
>> the access.log in driver.c works fine when called directly
>> in nslog.c.
>>
> Wow, weird.  I tried turning your new fix on/off, and confirm the
> behavior you see.

Re: [naviserver-devel] Code Quality

[Ibrahim T. <it...@ar...>]

Hi Maurizio,

A big thank you to you too.

I great your efforts.

I wasn't aware of those activities in the background and I just 
wanted to throw an idea into the pot without putting pressure on 
anyone. I am not sure how Coverity compares to your system and 
what the strengths and weaknesses of either are. In any case, any 
form of analysis is better than none and using one does not 
exclude the possibility of using the other some time in the future.

Zoran has done some dynamic testing using Valgrind and I have 
frequently used Purify on Windows to test our code. Zoran posted 
back the results of those tests and changes back in the past.

Cheers,
Ibrahim


On 14-Nov-14 11:31, Maurizio Martignano wrote:
> Dear Gustaf and Ibrahim,
> 	I am aware of the Coverity plugin but unfortunately I cannot change
> the current toolset cause it is the one I use for work and I cannot change
> it.
>
> On top of that the Coverity plugins runs on SonarQube 4.3.2 but our current
> platform is at 4.5.1.
>
> So basically the message is I can only offer what I use.
>
> Thanks,
> Maurizio

Re: [naviserver-devel] more logging problems on Windows

[Maurizio M. <Mau...@sp...>]

Dear Andrew,
	I would like to draw your attention to the availability of Visual
Studio 2013 Community Edition.

http://msdn.microsoft.com/en-us/visual-studio-community-vs.aspx

Hope it helps,
Maurizio


-----Original Message-----
From: Andrew Piskorski [mailto:at...@pi...] 
Sent: 07 November 2014 14:00
To: nav...@li...
Subject: Re: [naviserver-devel] more logging problems on Windows

On Thu, Nov 06, 2014 at 03:03:18PM +0100, Gustaf Neumann wrote:

> The seemingly same write() operation, which refuses to write to the 
> access.log in driver.c works fine when called directly in nslog.c.

> https://bitbucket.org/naviserver/naviserver/commits/4cb76f20a8464fde98
> ac3147c6184a90442a2808

Wow, weird.  I tried turning your new fix on/off, and confirm the behavior
you see.  Yet as you said, the new code you added to
NsAsyncWrite() is the same as the old/normal code in NsAsyncWrite()!

So what could the difference possibly be?  Since we're not actually using
the async writer thread feature at all, it's even the same thread calling
_write() in both cases.  LogTrace() is in nslog.dll while NsAsyncWrite() is
in libnsd.dll, but I don't see how/why that could possibly matter.

Microsoft's docs for _write() and _open() don't mention anything
suspicious:

  http://msdn.microsoft.com/en-us/library/1570wh78%28v=vs.100%29.aspx
  http://msdn.microsoft.com/en-us/library/z0kc8e3z%28v=vs.100%29.aspx

WinDbg thinks the source file used for Microsoft's _write() was:
  "f:\dd\vctools\crt_bld\self_x86\crt\src\write.c" 
Naturally I don't have that exact path, but I do have this, which seems to
be the same thing:
  "c:\Program Files (x86)\Microsoft Visual Studio 12.0\VC\crt\src\write.c" 

For binary files, _write() is a reasonably simple wrapper around
WriteFile(), but it's surprisingly complicated for text-mode files.

My access log seems to always be file descriptor 3, so in WinDbg I set a
breakpoint like this:

  bu NsAsyncWrite ".if (fd >= 0n3) {} .else {gc}" 

Naviserver opens its access log in text mode; that's the default, and by
stepping through in WinDbg I do see it enter some of the text-mode sections
in _write_nolock().

As a little experiment, in LogOpen() I added a _O_BINARY flag, so it opened
the access log like this:

    fd = open(logPtr->file, O_APPEND|O_WRONLY|O_CREAT|_O_BINARY, 0644); 

That made no difference to the behavior.  (I did NOT run that under WinDbg
to confirm, but presumably it was in binary mode like I asked.) So this lost
writes bug doesn't seem to depend on text vs. binary mode, it's the same for
both.

So, I have no idea.  The only ways I can imagine to try further to track
this down would be:

1. See if the bug is replicable in a standalone, non-Naviserver C program.
Maybe with two different DLLs involved.

2. Or, in NsAsyncWrite, do not use _write(), instead call WriteFile()
directly and see what happens.

That sounds like a lot of work though, much more than this really warrants.
I'm really glad you found a work-around, Gustaf!  I suggest we just leave it
as is, but add some comments about why it's there.

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

----------------------------------------------------------------------------
--
_______________________________________________
naviserver-devel mailing list
nav...@li...
https://lists.sourceforge.net/lists/listinfo/naviserver-devel

Re: [naviserver-devel] Code Quality

[Maurizio M. <Mau...@sp...>]

Dear Gustaf and Ibrahim,
	I am aware of the Coverity plugin but unfortunately I cannot change
the current toolset cause it is the one I use for work and I cannot change
it.

On top of that the Coverity plugins runs on SonarQube 4.3.2 but our current
platform is at 4.5.1.

So basically the message is I can only offer what I use.

Thanks,
Maurizio


-----Original Message-----
From: Gustaf Neumann [mailto:ne...@wu...] 
Sent: 13 November 2014 20:32
To: nav...@li...
Subject: Re: [naviserver-devel] Code Quality


Am 13.11.14 13:00, schrieb Ibrahim Tannir:
> Since Gustaf seems to have some time that he is dedicating into our 
> cause right now, an idea struck me, that could bring us and the code 
> up to the next level:
My recent activity is a consequence of finishing a book, and during this
phase some alternative fingerwork helps me to recover (e.g. before i go to
sleep). Furthermore i like to finish the work that i've started with
Maurizio to improve the static link checker ratings of naviserver (i have no
access to e.g. PC-Lint, but Maurizio has).  Maurizio is running his checkers
more or less once per day and feeds the results into

     http://sonarsrv.spazioit.com:9000/

and i try to reduce the issue count. I am very thankful to Maurizio for his
help. We started with 16.000 (or 18.000?) issues in NaviServer, and now we
are well below 3.000. There are still a couple of things, i want to
address...

NaviServer compares already quite well with other projects.
PostgreSQL shows in 0.28 issues per LOC [1], AOLserver 0.73, and NaviServer
is now at 0.19.

	     PostgreSQL	Aolserver	NaviServer
LOC	     487895	18743		14081
Issues	     140262	13712		2664
Issues/LOC   0,2875	0,7316		0,1892

Altogether i have an increasing pile of things on my todo-list such i can't
invest currently time into trying to get my hands on coverty, install it
etc. Btw, there is as well a coverty plugin for sonar server [2].

All the best
-g

[1] http://nemo.sonarqube.org/dashboard/index/706041
[2] https://github.com/coverity/coverity-sonar-plugin



----------------------------------------------------------------------------
--
Comprehensive Server Monitoring with Site24x7.
Monitor 10 servers for $9/Month.
Get alerted through email, SMS, voice calls or mobile push notifications.
Take corrective actions from your mobile device.
http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk
_______________________________________________
naviserver-devel mailing list
nav...@li...
https://lists.sourceforge.net/lists/listinfo/naviserver-devel

Re: [naviserver-devel] Code Quality

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

Am 13.11.14 13:00, schrieb Ibrahim Tannir:
> Since Gustaf seems to have some time that he is dedicating into
> our cause right now, an idea struck me, that could bring us and
> the code up to the next level:
My recent activity is a consequence of finishing a book, and
during this phase some alternative fingerwork helps me to
recover (e.g. before i go to sleep). Furthermore i like to
finish the work that i've started with Maurizio to improve
the static link checker ratings of naviserver (i have no
access to e.g. PC-Lint, but Maurizio has).  Maurizio is
running his checkers more or less once per day and
feeds the results into

     http://sonarsrv.spazioit.com:9000/

and i try to reduce the issue count. I am very thankful to Maurizio
for his help. We started with 16.000 (or 18.000?) issues in
NaviServer, and now we are well below 3.000. There are still
a couple of things, i want to address...

NaviServer compares already quite well with other projects.
PostgreSQL shows in 0.28 issues per LOC [1],
AOLserver 0.73, and NaviServer is now at 0.19.

	     PostgreSQL	Aolserver	NaviServer
LOC	     487895	18743		14081
Issues	     140262	13712		2664
Issues/LOC   0,2875	0,7316		0,1892

Altogether i have an increasing pile of things on my todo-list
such i can't invest currently time into trying to get my hands on
coverty, install it etc. Btw, there is as well a coverty plugin
for sonar server [2].

All the best
-g

[1] http://nemo.sonarqube.org/dashboard/index/706041
[2] https://github.com/coverity/coverity-sonar-plugin

Re: [naviserver-devel] Code Quality

[Maurizio M. <Mau...@sp...>]

Dear Ibrahim,
	In a way, behind the scenes, I have been helping Gustaf in improving
the quality of Naviserver.

My company, Spazio IT, is active providing Verification and Validation
activities to the European Space Agency and AIRBUS Helicopters.
http://www.spazioit.com/pages_en/sol_inf_en/code_quality_en/
For them I have developed a code quality platform based on the open source
web application SonarQube (http://www.sonarqube.org). In particular I have
modified and customized the Ada and C/C++ plugins for the special needs of
my customers.

To make a long story short I was also interested in the quality and
stability of Naviserver so I made available a demo of the above mentioned
quality platform to Gustaf and I run analyses on Naviserver on a daily basis
the system on a daily basis, spending on it something in between 30minutes -
1 hour every day.
I have been doing this since the 28th of September.
The demo system, with information on Naviserver, is available here.
http://sonarsrv.spazioit.com:9000/ 
Basically most of the improvements Gustaf has been implementing have been
triggered by the analyses results made available on this platform.


In terms of research activity I'm currently integrating into the platform as
improvements to the C/C++ static analysis it provides CBMC
(http://www.cprover.org/cbmc/) and Frama-C (http://frama-c.com/).

The results of this research  will be presented at the European Space Agency
in December. After the event I will made available the presentation and
speech also to this list.

For the time being please have a look at the following presentation.
http://www.spazioit.com/pages_en/sol_inf_en/code_quality_en/code-inspection_
en/ 

Thanks and kind regards,
Maurizio Martignano 
Tel +39 0376 1434259 - Fax +39 0376 1434187
Mob +39 349 7284927
--------------------------------------------------------------- 
Spazio IT - Soluzioni Informatiche s.a.s. 
P.IVA: IT02178630204 / REA: MN - 231014 

Registered Office: via Manzoni 40
Operating Office: via Don Bosco 10  
46030 - San Giorgio di Mantova 
ITALY 
www.spazioit.com 









-----Original Message-----
From: Ibrahim Tannir [mailto:it...@ar...] 
Sent: 13 November 2014 13:00
To: nav...@li...
Subject: [naviserver-devel] Code Quality

Hello everybody,

First of all, I'd like to thank Gustaf and Andrew who are currently
investing a lot of effort into cleaning up the code.

Since Gustaf seems to have some time that he is dedicating into our cause
right now, an idea struck me, that could bring us and the code up to the
next level:

I have been monitoring Coverity and their development for years
http://www.coverity.com/products/coverity-save/
Even tough they target high end and high profile software and companies,
they have been quite supportive of the open community. 
So I thought we might also ask them to allow us to run Naviserver and Tcl
through their static code analysis suite.

To be able to do so, someone must invest the time and the effort. 
Both Zoran and I are up to our necks in work. However, if Gustaf would be
willing to do so, given the time he is already investing, that would be
great. It might even speed up and simplify the work he is currently doing.

@Gustav, what do you think?

Cheers,
Ibrahim


----------------------------------------------------------------------------
--
Comprehensive Server Monitoring with Site24x7.
Monitor 10 servers for $9/Month.
Get alerted through email, SMS, voice calls or mobile push notifications.
Take corrective actions from your mobile device.
http://pubads.g.doubleclick.net/gampad/clk?id=154624111&iu=/4140/ostg.clktrk
_______________________________________________
naviserver-devel mailing list
nav...@li...
https://lists.sourceforge.net/lists/listinfo/naviserver-devel

[naviserver-devel] Code Quality

[Ibrahim T. <it...@ar...>]

Hello everybody,

First of all, I'd like to thank Gustaf and Andrew who are 
currently investing a lot of effort into cleaning up the code.

Since Gustaf seems to have some time that he is dedicating into 
our cause right now, an idea struck me, that could bring us and 
the code up to the next level:

I have been monitoring Coverity and their development for years
http://www.coverity.com/products/coverity-save/
Even tough they target high end and high profile software and 
companies, they have been quite supportive of the open community. 
So I thought we might also ask them to allow us to run Naviserver 
and Tcl through their static code analysis suite.

To be able to do so, someone must invest the time and the effort. 
Both Zoran and I are up to our necks in work. However, if Gustaf 
would be willing to do so, given the time he is already 
investing, that would be great. It might even speed up and 
simplify the work he is currently doing.

@Gustav, what do you think?

Cheers,
Ibrahim

Re: [naviserver-devel] more logging problems on Windows

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

On Thu, Nov 06, 2014 at 03:03:18PM +0100, Gustaf Neumann wrote:

> The seemingly same write() operation, which refuses to write to
> the access.log in driver.c works fine when called directly 
> in nslog.c.

> https://bitbucket.org/naviserver/naviserver/commits/4cb76f20a8464fde98ac3147c6184a90442a2808

Wow, weird.  I tried turning your new fix on/off, and confirm the
behavior you see.  Yet as you said, the new code you added to
NsAsyncWrite() is the same as the old/normal code in NsAsyncWrite()!

So what could the difference possibly be?  Since we're not actually
using the async writer thread feature at all, it's even the same
thread calling _write() in both cases.  LogTrace() is in nslog.dll
while NsAsyncWrite() is in libnsd.dll, but I don't see how/why that
could possibly matter.

Microsoft's docs for _write() and _open() don't mention anything
suspicious:

  http://msdn.microsoft.com/en-us/library/1570wh78%28v=vs.100%29.aspx
  http://msdn.microsoft.com/en-us/library/z0kc8e3z%28v=vs.100%29.aspx

WinDbg thinks the source file used for Microsoft's _write() was:
  "f:\dd\vctools\crt_bld\self_x86\crt\src\write.c" 
Naturally I don't have that exact path, but I do have this, which
seems to be the same thing:
  "c:\Program Files (x86)\Microsoft Visual Studio 12.0\VC\crt\src\write.c" 

For binary files, _write() is a reasonably simple wrapper around
WriteFile(), but it's surprisingly complicated for text-mode files.

My access log seems to always be file descriptor 3, so in WinDbg I set
a breakpoint like this:

  bu NsAsyncWrite ".if (fd >= 0n3) {} .else {gc}" 

Naviserver opens its access log in text mode; that's the default, and
by stepping through in WinDbg I do see it enter some of the text-mode
sections in _write_nolock().

As a little experiment, in LogOpen() I added a _O_BINARY flag, so it
opened the access log like this:

    fd = open(logPtr->file, O_APPEND|O_WRONLY|O_CREAT|_O_BINARY, 0644); 

That made no difference to the behavior.  (I did NOT run that under
WinDbg to confirm, but presumably it was in binary mode like I asked.)
So this lost writes bug doesn't seem to depend on text vs. binary
mode, it's the same for both.

So, I have no idea.  The only ways I can imagine to try further to
track this down would be:

1. See if the bug is replicable in a standalone, non-Naviserver C
program.  Maybe with two different DLLs involved.

2. Or, in NsAsyncWrite, do not use _write(), instead call WriteFile()
directly and see what happens.

That sounds like a lot of work though, much more than this really
warrants.  I'm really glad you found a work-around, Gustaf!  I suggest
we just leave it as is, but add some comments about why it's there.

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

Re: [naviserver-devel] more logging problems on Windows

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

Dear Andrew,

i've looked a little into "problem one", which looks very 
weird to me.
The seemingly same write() operation, which refuses to write to
the access.log in driver.c works fine when called directly 
in nslog.c.

My first suspicion was that write() does not work with size_t
in Windows (the msdn pages say the the length argument is
"unsigned int", while in the unix world specifies it as size_t),
but strange enough, the write operation in driver.c still 
returns the right
number of bytes written. However, a tell(fd) before and 
after the write()
operation reveals, that the write cursor is not moved. It seems
to me that size_t is unsigned 32 bit on win32 and win64 anyhow.

The change [1] fixes access.log writing for the time being, 
but it
will ignore async writing even if configured, but that's just an
optional feature for high traffic web-sites with much disk I/O.

You are much more experienced with windows development
than i am, so maybe you can find the real cause.

-g

[1] 
https://bitbucket.org/naviserver/naviserver/commits/4cb76f20a8464fde98ac3147c6184a90442a2808



On 03.11.14 04:27, Andrew Piskorski wrote:
> On Windows, I see two additional problems with logging:
>
> One, the access log file is opened and seems to get rolled/renamed
> properly, but it is always empty, zero bytes!  No content ever seems
> to make it into the access log file.
>

Re: [naviserver-devel] log rolled every time Naviserver shuts down

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

> > Andrew, how do you send SIGHUP to nsd?
> On Windows, the only way I've ever done it is by explicitly calling
> ns_logroll from the nsd process itself, typically in a scheduled
> procedure.
this explains, why i have seen not code for this... :)
 > Once the nsd debug symbols were working, that one turned out to be an 
easy fix.
 > All it took was moving the call to Ns_Log() AFTER LogOpen()
 > rather than before it.
 > Done here: 
https://bitbucket.org/apiskors/naviserver/commits/8d3c79974f084d074f44a9169be75bfa2c5f86bd 


actually, the idea of this line was to write a line to the "old" 
logfile. The proper
fix would be to figure out, why this crashes under win but not under 
unixes, ....
but that issue is not terribly important.

-g

Re: [naviserver-devel] 'nsv_unset myarray' fails to unset the array

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

Am 02.11.14 20:05, schrieb Andrew Piskorski:
> Excellent, thank you, Gustaf!
>
> When you get a chance, can you say a bit more about how it works?
the implementation of the nsv-commands in NaviServer differs from AOLserver,
by using LockArrayObj(), which uses the internal representation of Tcl_Objs
for caching the arrayPtr if possible.

> Before calling Tcl_DeleteHashTable()
> to remove the nsv array, you do something interesting with BucketIndex()
> and an extra round of locking.  Is that due to some new feature that
> AOLserver did not have, maybe the mutex timings?

nsv-arrays use two hash-tables, one "outer" for array names and one "inner"
for the values of the array. Since this structure is kept in the Array 
structure,
which is locked and has to be freed, i tried to avoid accessing freed data
element. So i implemented a second bucket lookup for deleting the
array name entry, and used the factored out function BucketIndex()
to avoid code duplication. However, after sleeping over the code,
the second lock can be avoided by separating the cleanup of
the name-entry from the actual freeing of the array structure.

https://bitbucket.org/naviserver/naviserver/commits/c82d84fdc723af4c131bd3557dc63fb5bd1fb54a
> E.g., what is the clientData for exactly, and why do some functions
> need to use it but others do not?
The clientData of all Tcl_ObjCmdProcs is the value specified when
a Tcl command is registered via Tcl_CreateObjCommand(). NaviServer
(and AOLserver) pass to all commands the extended Tcl interpreter
structure, namely NsInterp, which contains the NsServer and various
other information for adps or connections. Some functions need to
access this information, other ones don't, but every command has it
set.

-g

Re: [naviserver-devel] more logging problems on Windows

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

On Sun, Nov 02, 2014 at 10:27:21PM -0500, Andrew Piskorski wrote:

> Two, calling ns_logroll crashed Naviserver with this error:
> 
>   Debug Assertion Failed!
>   f:\dd\vctools\crt_bld\self_x86\crt\src\write.c
>   Line:  68
>   Expression:  (_osfile(fh) & FOPEN)

Once the nsd debug symbols were working, that one turned out to be an
easy fix.  All it took was moving the call to Ns_Log() AFTER LogOpen()
rather than before it.  Done here:

https://bitbucket.org/apiskors/naviserver/commits/8d3c79974f084d074f44a9169be75bfa2c5f86bd

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

[naviserver-devel] PDB debug symbols fixed on Windows

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

I finally figured out why my debug symbols on Windows were messed up.

By doing "!sym noisy", I saw that WinDbg found that nsd.pdb file was
"mismatched" with nsd.dll, and therefore ignored it.  That's why the
backtraces it was giving me were so useless.

chkmatch.exe agreed that there was a problem.  Oddly, it said the
problem was and "Age mismatch" between for nsd.pdb and nsd.dll,
whatever that really means.  Interestingly, it reported that my
nsd.pdb file WAS correctly matched with nsd.exe, just not with
nsd.dll.  Hm...

Yep, the root cause of this problem was simply that the compiler was
emitting TWO files named "nsd.pdb" into the same directory, and the
second one for nsd.exe clobbered the first one for nsd.dll!

To fix, I simply changed the (Windows only) makefiles to name the
library files "libnsd.dll" and "libnsd.lib", here:

  https://bitbucket.org/apiskors/naviserver/commits/55797002913598dd2152d2bea4dba7bbeef589bf

That's all it takes!  Now I have separate nsd.pdb (for the exe) and
libnad.pdb files, and once I set its symbol path correctly WinDbg
finds and loads them without trouble.


------------------------------------------------------------
Some WinDbg commands to check this stuff:

.sympath C:\web\nsd-32-tcl85\lib;SRV*C:\MyLocalSymbols*http://msdl.microsoft.com/download/symbols
!sym noisy
lml
.reload nsd.dll

------------------------------------------------------------
C:\web\nsd-32-tcl85>chkmatch -c bin\nsd.exe lib\nsd.pdb

Executable:
TimeDateStamp: 5456f3e9
Debug info: 2 ( CodeView )
TimeStamp: 5456f3e9  Characteristics: 0  MajorVer: 0  MinorVer: 0
Size: 62  RVA: 00059694  FileOffset: 00058094
CodeView format: RSDS
Signature: {1fd5b2d7-be66-40cd-ac8f-84e2f61d4fe6}  Age: 2
PdbFile: Z:\web\ns-fork\naviserver\nsd\nsd.pdb

Debug information file:
Format: PDB 7.00
Signature: {1fd5b2d7-be66-40cd-ac8f-84e2f61d4fe6}  Age: 2

Result: Matched

------------------------------------------------------------
C:\web\nsd-32-tcl85>chkmatch -c bin\nsd.dll lib\nsd.pdb

Executable:
TimeDateStamp: 5456f3e8
Debug info: 2 ( CodeView )
TimeStamp: 5456f3e8  Characteristics: 0  MajorVer: 0  MinorVer: 0
Size: 62  RVA: 0010c1f4  FileOffset: 0010a9f4
CodeView format: RSDS
Signature: {1fd5b2d7-be66-40cd-ac8f-84e2f61d4fe6}  Age: 1
PdbFile: Z:\web\ns-fork\naviserver\nsd\nsd.pdb

Debug information file:
Format: PDB 7.00
Signature: {1fd5b2d7-be66-40cd-ac8f-84e2f61d4fe6}  Age: 2

Result: Unmatched (reason: Age mismatch)

------------------------------------------------------------
Finally, here's my current HTML list of useful WinDbg links:

<h4>The <a href="http://msdn.microsoft.com/en-us/library/windows/hardware/hh406283%28v=vs.85%29.aspx">WinDbg</a> Debugger:</h4>
<ul>
<li>Mike Taulty's <a href="http://mtaulty.com/communityserver/blogs/mike_taultys_blog/archive/2004/08/03/4656.aspx">WinDbg debugger</a> tips
<li>Moving <a href="http://blogs.msdn.com/b/doronh/archive/2006/07/21/673317.aspx">up and down</a> the stack
<li><a href="http://windbg.info/doc/1-common-cmds.html">Common commands</a> by purpose
<li>A wordy <a href="http://www.virtualdub.org/blog/pivot/entry.php?id=215">cheat sheet</a>
<li>Debugging the damn <a href="http://msdn.microsoft.com/en-us/library/windows/hardware/ff560260%28v=vs.85%29.aspx">symbol path</a>
<li>The <a href="http://www.debuginfo.com/tools/chkmatch.html">ChkMatch.exe</a> utility
<li>Use <a href="http://www.debuginfo.com/articles/debuginfomatch.html">.symopt+0x40</a> to load mismatched symbols
<li>Use <a href="http://stackoverflow.com/questions/744870/how-can-you-change-an-age-mismatched-pdb-to-match-properly">How can you change an age-mismatched PDB to match properly?</a>
</ul>

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

[naviserver-devel] more logging problems on Windows

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

On Windows, I see two additional problems with logging:

One, the access log file is opened and seems to get rolled/renamed
properly, but it is always empty, zero bytes!  No content ever seems
to make it into the access log file.

Two, calling ns_logroll crashed Naviserver with this error:

  Debug Assertion Failed!
  f:\dd\vctools\crt_bld\self_x86\crt\src\write.c
  Line:  68
  Expression:  (_osfile(fh) & FOPEN)

This is very hard to debug because it happens AFTER we've stopped
writing to the old error log file!

Is there some good way I can temporarily direct debug statements to a
different file (or the console, or whatever)?  Maybe something as
simple as NOT redirecting stderr to the error log, and instead letting
it keep going to the console?

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

Re: [naviserver-devel] log rolled every time Naviserver shuts down

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

On Sun, Nov 02, 2014 at 01:38:37PM +0100, Gustaf Neumann wrote:

> I've changed the code by using distinct bit-patterns for signal
> detection which should address the problem, but have just
> checked that  the changes compile correctly under windows.

That seems to fix the excess rolling problem on Windows, thanks!

> However, i've not located the code, where SIGHUP is handled
> on the windows side. Andrew, how do you send SIGHUP to nsd?

The Windows SIGHUP handling is in NsHandleSignals() in nsd/nswin32.c,
which you just fixed, right?

Hm, how come NsSendSignal() only supports NS_SIGTERM, NS_SIGINT, and
NS_SIGHUP, with no support for NS_SIGQUIT and NS_SIGPIPE ?

> Andrew, how do you send SIGHUP to nsd?

In the distant past on either Linux or Solaris, I think I used an
external shell script to send an external SIGHUP to the nsd process,
but I never do that anymore.

On Windows, the only way I've ever done it is by explicitly calling
ns_logroll from the nsd process itself, typically in a scheduled
procedure.

In nsd/log.c, LogOpen() uses Ns_RegisterAtSignal() with Ns_LogRoll()
for handling an incoming SIGHUP.  But, the ns_logroll Tcl command
simply explicitly calls Ns_LogRoll(), so I don't think it exercises
the signal-handling machinery at all.

Btw, I just got a copy of this book and read some of it:

  http://www.amazon.com/gp/product/0321657748/
  Windows System Programming, 4th Edition; by Johnson M. Hart
  published Feb. 2010; ISBN-13:  978-0321657749

It seems pretty good, and has some useful compare/contrast discussion
of Windows vs. POSIX thread synchronization APIs.  Instead of Unix
signals, Windows uses Console Control Handlers or Exceptions
(depending on what you're trying to do).  Naviserver uses a Console
Control Handler.

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

Re: [naviserver-devel] 'nsv_unset myarray' fails to unset the array

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

On Thu, Oct 30, 2014 at 06:45:20PM +0100, Gustaf Neumann wrote:

> I agree that the array should be gone after the call of "nsv_unset a".

> The behavior is now fixed in the tip branch on bitbucket.

Excellent, thank you, Gustaf!

I earlier tried some simpler changes in my sandbox (essentially the
approach used in AOLserver 4.0.10), which crashed the server.
Your fix definitely works, but is more complicated than I expected.
When you get a chance, can you say a bit more about how it works?

E.g., what is the clientData for exactly, and why do some functions
need to use it but others do not?  Before calling Tcl_DeleteHashTable()
to remove the nsv array, you do something interesting with BucketIndex()
and an extra round of locking.  Is that due to some new feature that
AOLserver did not have, maybe the mutex timings?

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

Re: [naviserver-devel] log rolled every time Naviserver shuts down

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

Dear Andrew,

i've looked into the problem and addressed it in the tip branch.
Here is my understanding: Background:

AOLserver supports just 2 types of signals, namely TERM and HUP

   #define NS_SIGTERM  1
   #define NS_SIGHUP   2

NaviServer has extended this to the following set of signals

   # define NS_SIGHUP                  1
   # define NS_SIGINT                  2
   # define NS_SIGQUIT                 3
   # define NS_SIGPIPE                13
   # define NS_SIGTERM                15

As far as i can see, everything is fine in NaviServer on the unix side.
However, this extension is/was not fully handled on the windows side.
Windows does not support sets of signals (sigset_t + supporting API),
so it uses an approach based on a global variable "sigpending",
in which incoming signals are or-ed together. Later the code
checks, whether the signal in question was fired (maybe among
other signals) by testing the bits:

         if ((sig & NS_SIGHUP)) {
             NsRunSignalProcs();
         }

This works fine, as long one has just distinct bits (like in
SIGTERM and SIGHUP in aolserver), but in NaviServer this
does not work. From the bit-patterns, SIGQUIT looks like SIGHUP
and SIGINT, one gets false positives on Ctr-c, which is handled
somewhat strangely via NS_SIGTERM from the ConsoleHandler(),
containing the HUP bit, rather than SIGINT.

I've changed the code by using distinct bit-patterns for signal
detection which should address the problem, but have just
checked that  the changes compile correctly under windows.
However, i've not located the code, where SIGHUP is handled
on the windows side. Andrew, how do you send SIGHUP to nsd?

-g


Am 28.10.14 01:05, schrieb Andrew Piskorski:
> At least on Windows (I have checked this behavior on Linux), when I
> start Naviserver in a Command Shell and then shut it down by hitting
> Ctrl-c, it rolls both the error and access logs (e.g. renaming
> "myserver-error.log" to "myserver-error.log.000").
>
> That's strange, and not what I expect or want.  I want to roll logs
> only at certain times of day, not every time I restart the server.
>
> That roll-on-shutdown behavior goes away if I set these parameters:
>
> ns_section ns/parameters
>    ns_param LogRoll false
> ns_section ns/server/my_server/module/nslog
>    ns_param RollOnSignal false
>
> But I expect that will interfere with scheduled log rolling as well.
> I WOULD like to roll the logs on SIGHUP, just not every time the
> server shuts down.  Any idea why the two seem to be conflated?
> Is Windows actually sending a HUP signal when I hit Ctrl-c?  (I don't
> THINK so.)  Or is Navisever somehow misinterpreting whatever Windows
> does as SIGHUP?
>
> This is a very minor problem but I do wonder just what is going on there.
>
> (Thanks!)
>

Re: [naviserver-devel] 'nsv_unset myarray' fails to unset the array

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

Andrew,

I agree that the array should be gone after the call of "nsv_unset a".
The plain "Thread" package in Tcl 8.6 shows the same behavior:

/usr/local/src/tcl8.6.2% ./unix/tclsh
% package req Thread
2.7.0
% tsv::set a x 1
1
% tsv::unset a
%  list [tsv::exists a k1] [tsv::exists a k2] [tsv::exists a k3] [tsv::array exists a]
0 0 0 0

The behavior is now fixed in the tip branch on bitbucket.

all the best
-gustaf neumann

Am 29.10.14 20:39, schrieb Andrew Piskorski:
> If you do 'nsv_unset myarray', all the keys in the array are removed,
> but the array itself is left behind (which is wrong).  Also, no test
> checked that behavior.  Fixing the test is easy, I did that here:
>
>    https://bitbucket.org/apiskors/naviserver/commits/02e64d5e1a5c181b2668c1cf24f7321dc70baed9
>
> The (failing) test output is below.
>
> The bug is probably in NsTclNsvUnsetObjCmd().  The old AOLserver
> 4.0.10 version included special code to handle the "nsv_unset foo"
> objc == 2 case, but Naviserver's re-write in 2008 seems to have left
> that out.
>
> Also, why do both Unset() and Ns_VarUnset() exist?  Ns_VarUnset() is a
> wrapper around Unset(), but it is never actually used, instead other
> code calls Unset() directly.
>
>
> $ make test TCLTESTARGS='-file ns_nsv.test'
> ==== ns_nsv-3.5 nsv_unset array FAILED
> ==== Contents of test case:
>
>      nsv_unset a
>      list [nsv_exists a k1] [nsv_exists a k2] [nsv_exists a k3] [nsv_array exists a]
>
> ---- Result was:
> 0 0 0 1
> ---- Result should have been (exact matching):
> 0 0 0 0
> ==== ns_nsv-3.5 FAILED
>

[naviserver-devel] 'nsv_unset myarray' fails to unset the array

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

If you do 'nsv_unset myarray', all the keys in the array are removed,
but the array itself is left behind (which is wrong).  Also, no test
checked that behavior.  Fixing the test is easy, I did that here:

  https://bitbucket.org/apiskors/naviserver/commits/02e64d5e1a5c181b2668c1cf24f7321dc70baed9

The (failing) test output is below.

The bug is probably in NsTclNsvUnsetObjCmd().  The old AOLserver
4.0.10 version included special code to handle the "nsv_unset foo"
objc == 2 case, but Naviserver's re-write in 2008 seems to have left
that out.

Also, why do both Unset() and Ns_VarUnset() exist?  Ns_VarUnset() is a
wrapper around Unset(), but it is never actually used, instead other
code calls Unset() directly.


$ make test TCLTESTARGS='-file ns_nsv.test'
==== ns_nsv-3.5 nsv_unset array FAILED
==== Contents of test case:

    nsv_unset a
    list [nsv_exists a k1] [nsv_exists a k2] [nsv_exists a k3] [nsv_array exists a]

---- Result was:
0 0 0 1
---- Result should have been (exact matching):
0 0 0 0
==== ns_nsv-3.5 FAILED

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

[naviserver-devel] log rolled every time Naviserver shuts down

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

At least on Windows (I have checked this behavior on Linux), when I
start Naviserver in a Command Shell and then shut it down by hitting
Ctrl-c, it rolls both the error and access logs (e.g. renaming
"myserver-error.log" to "myserver-error.log.000").

That's strange, and not what I expect or want.  I want to roll logs
only at certain times of day, not every time I restart the server.

That roll-on-shutdown behavior goes away if I set these parameters:

ns_section ns/parameters
  ns_param LogRoll false
ns_section ns/server/my_server/module/nslog
  ns_param RollOnSignal false

But I expect that will interfere with scheduled log rolling as well.
I WOULD like to roll the logs on SIGHUP, just not every time the
server shuts down.  Any idea why the two seem to be conflated?
Is Windows actually sending a HUP signal when I hit Ctrl-c?  (I don't
THINK so.)  Or is Navisever somehow misinterpreting whatever Windows
does as SIGHUP?

This is a very minor problem but I do wonder just what is going on there.

(Thanks!)

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

Re: [naviserver-devel] Windows Service startup fails

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

On 23.10.14 22:54, Andrew Piskorski wrote:
> Does an empty string thread name indicate a problem somewhere else, or
> is it ok and just something special about Windows Services?
There was a problem in the windows initialization in service 
mode: In the
"continue service case", the thread name initialization was 
bypassed.
Now it should be fine.

all the best
-g

Re: [naviserver-devel] Windows Service startup fails

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

On Thu, Oct 23, 2014 at 12:45:36PM +0200, Gustaf Neumann wrote:

> By reading the code for windows "services", i see that
> the corresponding thread is named "-service-". I've extended
> the sanity check to include this value. if this is not
> sufficient, please report, what the returned threadName is.

With your change, it still triggered the assertion.  I added this
code, and when run as a windows service, the logged threadName is
empty string:

   char *threadName = Ns_ThreadGetName(); 
   Ns_Log(Notice, "CreateConnThread: threadName is: '%s'", threadName); 

Does an empty string thread name indicate a problem somewhere else, or
is it ok and just something special about Windows Services?

The good news is, with that the assertion turned off completely,
Naviserver now appears to run ok as a Windows Service, yay!

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

Re: [naviserver-devel] Windows Service startup fails

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

Am 22.10.14 14:35, schrieb Andrew Piskorski:
> Is this a separate problem, not a consequence of skipping some sort of
> needed initialization because the initProc from ServiceMain() was NULL?

no, it is something different: the actual code you posted is a
sanity check between  ifdefs for NDEBUG, which is meant
just for development. It is a quick check to determine,
whether the current thread looks suitable for running connection
requests.

By reading the code for windows "services", i see that
the corresponding thread is named "-service-". I've extended
the sanity check to include this value. if this is not
sufficient, please report, what the returned threadName is.

all the best
-g

Re: [naviserver-devel] Windows Service startup fails

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

On Wed, Oct 22, 2014 at 09:46:11AM +0200, Gustaf Neumann wrote:

> sorry, I've added this nonnull constraint, which was too eager. I missed
> that invocation path via windows. This is fixed in the bitbucket tip

Well, last night I tried allowing a NULL initProc there, but it then
failed this assertion on line 1624 of nsd/queue.c, in CreateConnThread():

    { char *threadName = Ns_ThreadGetName(); 
      assert(strncmp("-driver:", threadName, 8) == 0  
             || strncmp("-main-", threadName, 6) == 0 
             || strncmp("-spooler", threadName, 8) == 0 
             ); 
    } 

Is this a separate problem, not a consequence of skipping some sort of
needed initialization because the initProc from ServiceMain() was NULL?

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

Re: [naviserver-devel] Windows Service startup fails

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

Am 21.10.14 23:10, schrieb Andrew Piskorski:
> Ah, I see:  ServiceMain() explicitly passes in a NULL initProc:
>
>    Ns_Main((int)argc, argv, NULL);
>
> So, is it supposed to be passing in something else, or is it ok for
> that to be NULL and the assertion is inappropriate in this case?
sorry, I've added this nonnull constraint, which was too eager. I missed
that invocation path via windows. This is fixed in the bitbucket tip

-g