Re: [naviserver-devel] Crashing on all versions >4.99.24 on Ubuntu

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

On 16.08.23 15:37, Brian Fenton wrote:
> We don't issue any "ns_set cleanup" ourselves, but when I added your 
> recommendation of tracing "ns_set", I saw plenty in the logs. The docs 
> say that "This command is autoamtically executed by ns_cleanup, which 
> runs after every request, freeing all sets created via *ns_set*", so I 
> presume that is where the calls come from.

Hi Brian,

Yes, it is clear from the log that the crash happens in the automatic 
cleanup, but I just wanted to make sure, that the application has not 
tried the same earlier - this would be a good place to start debugging.

> Is there something in particular I should be looking for in the trace 
> output? There is an enormous amount of information the logs.

see below


> I ran another backtrace and this time the error was a little bit 
> different
as i said before, the messages one gets from the operating system are 
not always helpful to find the source of the problem.

> ("error: Cannot access memory at address 0x2" - see below).

This is actually not a message of the operating system, but a message 
from gdb about an unused C-structure, which is here not relevant.

... but we are getting closer.  The crash happens on an dynamic ns_set 
(in yesterday's mail in "d6").

#11 0x00007ffff7f3e119 in NsTclSetObjCmd
(clientData=0x7fffdc035570, interp=0x7fffdc005250, objc=2,
objv=0x7fffdc245650) at tclset.c:330

         key = 0x7fffdc3aa070 "d6"

In this case, one has to watch out for operations on "d6". You might ask 
"What is a dynamic ns_set?".

Background: ns_sets might be

- C-only structures, or
- Tcl-exposed structures, which might be
    * dynamic (i.e., freed after every request, the Tcl-name of these 
starts with a "d"), or
    * static (the structures will be reused).

The Tcl-exposed ns_sets are "entered" (NaviServer terminology) into Tcl 
interpreters. It might be the case, that you do not find anything 
interesting in the log concerning the crashing ns_set (here "d6") in the 
Tcl trace output, ... since the ns_sets are as well manipulated from C.

In case, you find nothing revealing on "d6", I've added more debugging 
output for C-level ns_set operations. Get the newest version from the 
branch "release/4.99", activate debug output on Debug(nsset)

     ns_logctl severity Debug(nsset) on

and then you will see some more output, like e.g. the following:

[16/Aug/2023:19:53:13.016627][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [29] key 'item_id' value '1066' size -1
[16/Aug/2023:19:53:13.016630][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [30] key 'revision_id' value '163776' size -1
[16/Aug/2023:19:53:13.016633][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [31] key 'publish_date' value '2021-11-13 13:35:27.423904+01' size -1
[16/Aug/2023:19:53:13.016637][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [32] key 'modifying_user' value '' size -1
[16/Aug/2023:19:53:13.016640][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [33] key 'last_modified' value '2017-08-08 13:26:49.138414+02' size -1
[16/Aug/2023:19:53:13.016644][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [34] key 'modifying_ip' value '::1' size -1
[16/Aug/2023:19:53:13.016647][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [35] key 'modifying_user' value '704' size -1
[16/Aug/2023:19:53:13.016651][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetPut 0x600002845600 [36] key 'parent_id' value '1064' size -1
[16/Aug/2023:19:53:13.016655][-conn:oacs-head:default:0:11-] Debug(nsset): EnterSet 0x600002845600 with name 'd15'
[16/Aug/2023:19:53:13.016678][-conn:oacs-head:default:0:11-] Notice: trace: ns_set array d15

...
[16/Aug/2023:20:04:31.283342][-conn:oacs-head:default:0:11-] Debug(nsset): ns_set cleanup key <d15> dynamic 1
[16/Aug/2023:20:04:31.283344][-conn:oacs-head:default:0:11-] Debug(nsset): Ns_SetFree 0x600002845600 'db': elements 37
[16/Aug/2023:20:04:31.283346][-conn:oacs-head:default:0:11-] Debug(nsset): ... 0: key <object_type> value <::xowiki::Form>
[16/Aug/2023:20:04:31.283349][-conn:oacs-head:default:0:11-] Debug(nsset): ... 1: key <package_id> value <1060>
[16/Aug/2023:20:04:31.283351][-conn:oacs-head:default:0:11-] Debug(nsset): ... 2: key <creation_user> value <704>
...

In this example output, there is a bunch of Ns_SetPut() operations on a 
set "0x600002845600"  which is entered then to Tcl as set "d15".... 
somewhere later it is freed via "ns_set cleanup".

Let me know if you need some help on getting/compiling a branch of 
NaviServer from Bitbucket.

all the best

-g