Assertion in connection.c, ln. 258 (ITS#191)

[azeltser@safeword.com]

Full_Name: Alex Zeltser
Version: Devel as of 6/4/99
OS: Win NT 4.0, SP3
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (204.242.227.157)


This may be of the same flavor as ITS#190 submitted on 6/3/99.  Running slapd
under NT and ldapsearch dumping the entire database.  ldapsearch is ran from a
script performing the same action 100 times.  This time got an assertion in a
different place.  See the trace dump below of the last few lines:

=> acl_access_allowed: read access to value "any" by ""
<= acl_access_allowed: granted by default (no matching to)
<= send_search_entry
entry_rdwr_runlock: ID: 34
====> cache_return_entry_r( 34 ): returned (0)
=> id2entry_r( 35 )
=> ldbm_cache_open( "C:/ldap/aztest\id2entry.dbb", 7, 600 )
<= ldbm_cache_open (cache 1)
<= id2entry_r( 35 ) not found
candidate 35 not found
send_ldap_result 0::
daemon: activity on 1 descriptors
daemon: activity on: 2672r
daemon: read activity on 2672
connection_get(2672): got connid=93
connection_read(2672): checking for input on id=93
ber_get_next
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf 0x1176200, ptr 0x1176200, end 0x1176205
        02 01 03  B 00
ber_get_next
ber_get_next on fd 2672 failed errno 0 (No error)
        *** got 18310892 of 0 so far
connection_read(2672): input error=-2 id=93, closing.
connection_closing: readying conn=93 sd=2672 for close.
connection_close: deferring conn=93 sd=2672.
daemon: select: tcps=16 active_threads=1 tvp=NULL
daemon: activity on 1 descriptors
daemon: new connection on 2536
daemon: added 2536r
daemon: select: tcps=16 active_threads=1 tvp=NULL
daemon: activity on 1 descriptors
daemon: new connection on 2688
Assedo_unbind
connection_resched: attempting closing conn=93 sd=2672.
connection_close: conn=93 sd=2672.
daemon: removing 2672
rtion failed: c->c_conn_state == SLAP_C_INVALID, file
C:\ldap\servers\slapd\connection.c, line 258

Locals:
	s	2688
+	name	0x00000000 ""
+	addr	0x0048094c "127.0.0.1"
	id	4729152
-	c	0x004806e0
	c_struct_state	1
	c_conn_state	4720356
	c_mutex	0x004806e4
-	c_sb	0x004806ec
-	sb_opts	{...}
	lbo_valid	1772
	lbo_options	72
	lbo_debug	4720364
	sb_non_block	0
	sb_read_ahead	0
	sb_buf_ready	0
	sb_trans_ready	0
	sb_sec_ready	0
	sb_fd	-1
	sb_iodata	0x00000000
+	sb_io	0x00000000
	sb_sd	0
-	sb_buf	{...}
	buf_size	0
	buf_ptr	8980608
	buf_end	-1
+	buf_base	0x00000000 ""
	c_starttime	4720364
	c_connid	8980576
+	c_client_addr	0xffffffff ""
+	c_client_name	0x00000000 ""
+	c_cdn	0x00000000 ""
+	c_dn	0x00000000 ""
	c_protocol	0
	c_authtype	8980608
+	c_ops	0xffffffff
+	c_pending_ops	0x00000000
	c_write_mutex	0x00000000
	c_write_cv	0x00000000
+	c_currentber	0x00000000
	c_writewaiter	1296778016
	c_n_ops_received	4720448
	c_n_ops_executing	4720528
	c_n_ops_pending	2
	c_n_ops_completed	0

Possibly another race condition due to a synchronization problem?  The fact that
the last few lines of the trace are 'interleaved' (e.g. the word 'Assertion' is
split by more than one trace) may also be indicative of a synchronization issue.