On 11/18/2011 05:31 AM, "Reddy, Gandikota Rushendra (ES&N)" <gandikota-rushendra.reddy@hp.com> wrote:

This was a bounce - please check your list membership before posting again.
On a multi CPU system, ns-slapd process aborts. Stack trace says it aborted calling PR_ASSERT() at the following location in connection.c (Release version of 389 dirsrv is 1.2.0).
Is there any chance you could attempt to reproduce this issue with the latest 1.2.9.9 (stable) or 1.2.10.a5 (testing)? Or provide a reproducer.  1.2.0 is quite old.

Also, please file a bug at https://bugzilla.redhat.com/enter_bug.cgi?product=389
-----
Connection.c
1690 int connection_read_operation(Connection *conn, Operation *op, ber_tag_t *tag, int *remaining_data)
1691 {

1734         }
1735         /* If we still haven't seen a complete PDU, read from the network */
1736         while (*tag == LBER_DEFAULT) {
1737                 int ioblocktimeout_waits = config_get_ioblocktimeout() / CONN_TURBO_TIMEOUT_INTERVAL;
1738                 /* We should never get here with data remaining in the buffer */
1739                 PR_ASSERT( !new_operation || 0 == (conn->c_private->c_buffer_bytes - conn->c_private->c_buffer_offset) );    <------------------ aborted calling PR_ASSERT()
1740                 /* We make a non-blocking read call */
-----

Using instrumented image I have collected data and found that:

While a thread is working on connection's private buffer, another thread which belongs to older connection makes the connection readable again by modifying c_gettingber to zero.
This results in waking up one more thread. Finally more than one thread works simultaneously on connection's private buffer and results in aborting ns-slapd.


It happens as below:

1. Thead X is working on Connection-1's last opereration.

2. After performing the LDAP operation ( connection_dispatch_operation() ) decrementes the connection's c_refcnt  by calling connection_release_nolock() in connection_threadmain() function.

3. Since this is the last operation, c_refcnt becomes zero.

4. Thread X yet to execute the code that updates c_threadnumber and  c_gettingber. But as soon as c_refcnt of the connection becomes zero, main thread allocates the same connection object/structure to new incoming connection connection-2.  Thread-Y started executing operation belongs to this newer connection (Connection-2).

-----
connection.c

2008 static void
2009 connection_threadmain()
2010 {


2187                     if (!thread_turbo_flag && !more_data) {
2188                                 connection_release_nolock (conn);   <------------------  Thread-X decremented c_refcnt and now c_refcnt = 0
2189                         }
2190                     PR_Unlock( conn->c_mutex );
2191                 }
2192                 /* Since we didn't do so earlier, we need to make a replication connection readable again here */
2193                 if ( ((1 == is_timedout) || (replication_connection && !thread_turbo_flag)) && !more_data)
2194                         connection_make_readable(conn);
2195                 pb = NULL;
2196
2197                 if (!thread_turbo_flag && !more_data) { /* Don't do this in turbo mode */
2198                         PR_Lock( conn->c_mutex );
2199                         /* if the threadnumber of now below the maximum, wakeup
2200                          * the listener thread so that we start polling on this
2201                          * connection again
2202                          */
2203                         /* DBDB I think this code is bogus -- we already signaled the listener above here */
2204                         if (conn->c_threadnumber == config_get_maxthreadsperconn())
2205                                 need_wakeup = 1;
2206                         else
2207                                 need_wakeup = 0;
2208                         conn->c_threadnumber--;
2209                         PR_Unlock( conn->c_mutex );
2210
2211                         if (need_wakeup)
2212                                 signal_listner();
2213                 }
2214
2215
2216         } /* while (1) */
2217 }
----

5. Thread-Y started processing operation data belongs to newer connection Connection-2  (connection_read_operation() ).

6. Now Thread-X of connection-1 called make_connection_readable() and made the connection readable again by setting c_gettingbuffer to 0.

7. This wakes up another thread of connection-2 and it too starts processing operation data (connection_read_operation() ).

8. So at this point of time more than one thread is working on connection's private data.

9. As two threads are working on the connections c_buffer, c_bufferbytes and c_offset, at some time it meats conditions to abort() at the following location:

Connection.c:  connection_read_operation()

1734         }
1735         /* If we still haven't seen a complete PDU, read from the network */
1736         while (*tag == LBER_DEFAULT) {
1737                 int ioblocktimeout_waits = config_get_ioblocktimeout() / CONN_TURBO_TIMEOUT_INTERVAL;
1738                 /* We should never get here with data remaining in the buffer */
1739                 PR_ASSERT( !new_operation || 0 == (conn->c_private->c_buffer_bytes - conn->c_private->c_buffer_offset) );    <------------------ aborted calling PR_ASSERT()
1740                 /* We make a non-blocking read call */
-----



The probable fix could be:

In the connection_threadmain() function, if it is CONN_DONE don't make the connection readable again after decrementing the c_refcnt.

So should we handle CONN_DONE and CONN_TIMEDOUT situation differently as below?



Present code:

2097                 switch (ret) {
2098                         case CONN_DONE:
2099                                 /* This means that the connection was closed, so clear turbo mode */
2100                         /*FALLTHROUGH*/
2101                         case CONN_TIMEDOUT:
2102                                 thread_turbo_flag = 0;
2103                                 is_timedout = 1;


new code:


2097                 switch (ret) {
2098                         case CONN_DONE:
2099                                 /* This means that the connection was closed, so clear turbo mode */
                                     is_conn_done = 0;  <-----------------
                                     thread_turbo_flag = 0;  <-------------
2101                         case CONN_TIMEDOUT:
2102                                 thread_turbo_flag = 0;
2103                                 is_timedout = 1;
Note that you don't have to set thread_turbo_flag = 0 in the CONN_DONE case because it will be set when it falls through to the CONN_TIMEDOUT case.

Present:

2193                 if ( ((1 == is_timedout) || (replication_connection && !thread_turbo_flag)) && !more_data )
2194                         connection_make_readable(conn);
2195                 pb = NULL;



new:

2193    --------->  if ( !is_conn_done && ((1 == is_timedout) || (replication_connection && !thread_turbo_flag)) && !more_data )
2194                         connection_make_readable(conn);
2195                 pb = NULL;



Is it right way to fix it?  Please provide your inputs.
If ret is CONN_DONE, but you set is_conn_done = 0, how does the code know the connection is really done?


Thanks & regards,
Rushendra