@tbordaz @mreynolds You may bee interested to look at this patch please :)

Should this be removed since it doesn't do anything, or is it incomplete?

Also, please don't use java style comments

Can this comment above be removed? If you want to record the history of the logic perhaps use a more appropriate comment?

I see a lot of code that looks like it was experimentally commented out. If it's not needed it should be cleaned up, and the java style comments should also not be used.

The rest of the code looks okay, but I want @tbordaz to look it over, and I would really like @vashirov to run some tests on it (maybe even an IPA install).

Yeah, I have done a clean up since. I've run it with tests and they seem to do well. I need to clean up the NS=ON by default again, and probably extend the python tests to support an env/config setting for it? That way we can test against IPA.

I really commited because I wanted the code in git, and not lost to the sands of time in my laptop.

As promised, cleanup provided - this still enables NS=ON by default in libglobs which is easier for testing, but obviously we don't want to let that slip into master.

@tbordaz Ping

@firstyear thank you so much for this patch. I started reviewing it but soon it was clear it requires a deep review. I discussed with you (on private emails) the outcome of the team discussions but forgot to update the PR. Sorry for that.

Before doing any fix/enhancements in NS, we decided to invest in test coverage. The tests aim to measure the benefit of NS and isolate (when it is possible) reproducible test cases of the known failures (connection leak and hang). Then regarding the expected benefits we will be able to justify the need of enabling NS and work (i.e. review) on NS robustness.

@tbordaz Thanks for that. I'd like to just remind you and everyone that I'm not able to access private Red Hat emails any more, so it would be better if these discussions were had on 389-devel .... :(

Anyway, with the patch I think we could merge and trust the feature gating (nunc-stans: off) in cn=config, so that we can continue to test. If it's already disabled and we trust that flag to operate, then merging this prevents further bitrot and divergence between potential fixes. Then we can continue to test and improve, and the discussion is not 'merge this patch' but 're-enable by default'.

Does that sound like a better plan? My concern is this patch has been going for a long time and it's harder and harder to rebase every time....

@firstyear you are right the discussion also need to be on 389-devel. I just posted https://lists.fedoraproject.org/archives/list/389-devel@lists.fedoraproject.org/thread/DDUBRHDDGI5YCJBSOXJ2HUPUUS6ZALTT/

Hey @firstyear, I apologize for the delay, but I finally started to test this PR.
I've got a hang during suites/paged_results/paged_results_test.py::test_search_multiple_paging, here's the stacktrace. In the errors log I see:

[23/Oct/2018:13:39:10.433425941 -0400] - WARN - ns_handle_pr_read_ready - conn 2 for fd=65 - socket is already closing
[23/Oct/2018:13:39:10.434146277 -0400] - WARN - ns_handle_pr_read_ready - conn 3 for fd=66 - socket is already closing
[23/Oct/2018:13:39:10.434603631 -0400] - WARN - ns_handle_pr_read_ready - conn 4 for fd=67 - socket is already closing
[23/Oct/2018:13:39:47.678581690 -0400] - WARN - ns_handle_pr_read_ready - conn 6 for fd=66 - socket is already closing
[23/Oct/2018:13:39:49.979713098 -0400] - WARN - ns_handle_pr_read_ready - conn 7 for fd=66 - socket is already closing
[23/Oct/2018:13:39:49.980524182 -0400] - WARN - ns_handle_pr_read_ready - conn 8 for fd=67 - socket is already closing
[23/Oct/2018:13:39:52.519567804 -0400] - WARN - ns_handle_pr_read_ready - conn 9 for fd=66 - socket is already closing
[23/Oct/2018:13:39:59.945238135 -0400] - WARN - ns_handle_pr_read_ready - conn 10 for fd=66 - socket is already closing
[23/Oct/2018:13:39:59.945955597 -0400] - WARN - ns_handle_pr_read_ready - conn 11 for fd=67 - socket is already closing
[23/Oct/2018:13:40:31.652500670 -0400] - WARN - ns_handle_pr_read_ready - conn 12 for fd=66 - socket is already closing
[23/Oct/2018:13:40:34.885272354 -0400] - WARN - ns_handle_pr_read_ready - conn 13 for fd=66 - socket is already closing
[23/Oct/2018:13:40:38.085292444 -0400] - WARN - ns_handle_pr_read_ready - conn 5 for fd=65 - socket is already closing
[23/Oct/2018:14:26:09.948360955 -0400] - WARN - ns_handle_pr_read_ready - conn 16 for fd=67 - socket is already closing

It's 100% reproducible on my VM, please let me know if you need more info.

@vashirov Thanks for this! I'll run those tests and try that out, and fix it up.

@tbordaz We said a few things on the ML but didn't come to a conclusion?

PS: @vashirov I probably don't need more info, but I do need more time :)

@firstyear I was waiting for some feedback from others members. I updated the thread on the ML.

https://pagure.io/389-ds-base/pull-request/49869 canceled to focus on this PR

Okay, I have rebased and updated this patch - I will begin to look at the issues that @vashirov has identified!

Interesting - I see a failure in paged results, but it occurs both ON and OFF with nunc-stans. I'm not seeing a deadlock or a hang as you report. I'll investigate properly to be sure it is not NS related.

The failure appears to be separate from NS, it looks like it's in the design of the test case. @tbordaz and I were discussing today about how to continue testing this patch now to avoid the deadlock case.

I would like to propose though, that we merge this patch "as is" - it is already an improvement from the current state of nunc-stans. We have NS disabled in cn=config, and this patch would leave it disabled. By merging it, we can then start to test it more frequently, and we would not have such a long review hanging for so long.

There are some small patch clean ups still to perform before we merge, but I think if we continue to delay it keeps getting harder to move this forward and test effectively.

Thoughts?

Clean it up and merge it!

Will do! I will ask @tbordaz to have a look today then also :)

This update rebases to master, and defaults to NS off. It changes the model of integration so that jobs are for the lifetime of a connection, instead of "one per event". This reduces allocator load, and makes the whole system deterministic. Additionally, it prevents reuse of the memory structures for operation, removing a possible serialisation point and memory growth point.

It should be safe to merge, and we can test it with nunc-stans enable via cn=config!

Thanks for getting this done! I'm feeling optimistic!

I'm going to keep my schedule for the next month free to work on this in case there are issues :P

Wrong date?

Typo "anyting"

Maybe a comment on why this code block is commented out?

Same thing here...

Why was this removed?

Looks good!!! A few questions but nothing major. No complier warnings either, but I am waiting for covscan to complete... I'll report those results later.

Covscan issues reported:

Error: DEADCODE (CWE-561): [#def228]
389-ds-base-1.4.1.4.20190619git2daf26aa8/ldap/servers/slapd/connection.c:1448: assignment: Assigning: "is_timedout" = "0".
389-ds-base-1.4.1.4.20190619git2daf26aa8/ldap/servers/slapd/connection.c:1814: const: At condition "1 == is_timedout", the value of "is_timedout" must be equal to 0.
389-ds-base-1.4.1.4.20190619git2daf26aa8/ldap/servers/slapd/connection.c:1814: dead_error_condition: The condition "1 == is_timedout" cannot be true.
389-ds-base-1.4.1.4.20190619git2daf26aa8/ldap/servers/slapd/connection.c:1816: dead_error_begin: Execution cannot reach this statement: "connection_make_readable_no...".
# 1814|                   } else if (1 == is_timedout) {
# 1815|                       /* covscan reports this code is unreachable  (2019/6/4) */
# 1816|->                     connection_make_readable_nolock(conn);
# 1817|                       signal_listner();
# 1818|                   }
Error: LOCK (CWE-667): [#def467]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:267: lock: "pthread_mutex_lock" locks "job->monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:278: double_lock: "event_q_notify" locks "job->monitor" while it is locked.
#  276|   
#  277|       if (NS_JOB_IS_IO(job->job_type) || NS_JOB_IS_TIMER(job->job_type) || NS_JOB_IS_SIGNAL(job->job_type)) {
#  278|->         event_q_notify(job);
#  279|       } else {
#  280|           /* if this is a non event task, just queue it on the work q */
Error: LOCK (CWE-667): [#def468]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:267: lock: "pthread_mutex_lock" locks "job->monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:282: double_lock: "work_q_notify" locks "job->monitor" while it is locked.
#  280|           /* if this is a non event task, just queue it on the work q */
#  281|           /* Prevents an un-necessary queue / dequeue to the event_q */
#  282|->         work_q_notify(job);
#  283|       }
#  284|       pthread_mutex_unlock(&(job->monitor));
Error: MISSING_LOCK (CWE-667): [#def469]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:745: missing_lock: Accessing "job->state" without holding lock "ns_job_t.monitor". Elsewhere, "ns_job_t.state" is accessed with "ns_job_t.monitor" held 17 out of 19 times (6 of these accesses strongly imply that it is necessary).
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:218: example_lock: Example 1: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:240: example_access: Example 1 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:267: example_lock: Example 2: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:273: example_access: Example 2 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:801: example_lock: Example 3: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:827: example_access: Example 3 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1282: example_lock: Example 4: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1293: example_access: Example 4 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1572: example_lock: Example 5: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1579: example_access: Example 5 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
#  743|       ns_log(LOG_DEBUG, "new_ns_job %x initial NS_JOB_WAITING\n", job);
#  744|   #endif
#  745|->     job->state = NS_JOB_WAITING;
#  746|       return job;
#  747|   }
Error: MISSING_LOCK (CWE-667): [#def470]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:771: missing_lock: Accessing "job->tv" without holding lock "ns_job_t.monitor". Elsewhere, "ns_job_t.tv" is accessed with "ns_job_t.monitor" held 1 out of 2 times (1 of these accesses strongly imply that it is necessary).
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1006: example_lock: Example 1: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1007: example_access: Example 1 (cont.): "ns_job_t.tv" is accessed with lock "ns_job_t.monitor" held.
#  769|   {
#  770|       ns_job_t *job = new_ns_job(tp, NULL, NS_JOB_TIMER | job_type, func, done_func, data);
#  771|->     job->tv = *tv;
#  772|   
#  773|       return job;
Error: MISSING_LOCK (CWE-667): [#def471]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1091: missing_lock: Accessing "_job->state" without holding lock "ns_job_t.monitor". Elsewhere, "ns_job_t.state" is accessed with "ns_job_t.monitor" held 17 out of 19 times (6 of these accesses strongly imply that it is necessary).
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:218: example_lock: Example 1: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:240: example_access: Example 1 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:267: example_lock: Example 2: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:273: example_access: Example 2 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:801: example_lock: Example 3: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:827: example_access: Example 3 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1282: example_lock: Example 4: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1293: example_access: Example 4 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1572: example_lock: Example 5: Locking "ns_job_t.monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1579: example_access: Example 5 (cont.): "ns_job_t.state" is accessed with lock "ns_job_t.monitor" held.
# 1089|       ns_log(LOG_DEBUG, "ns_add_job %x state %d moving to NS_JOB_ARMED\n", _job, (_job)->state);
# 1090|   #endif
# 1091|->     _job->state = NS_JOB_NEEDS_ARM;
# 1092|       internal_ns_job_rearm(_job);
# 1093|   
Error: LOCK (CWE-667): [#def472]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1282: lock: "pthread_mutex_lock" locks "job->monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1286: missing_unlock: Returning without unlocking "job->monitor".
# 1284|   
# 1285|       if (ns_thrpool_is_shutdown(job->tp)) {
# 1286|->         return NS_SHUTDOWN;
# 1287|       }
# 1288|   
Error: LOCK (CWE-667): [#def473]
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1282: lock: "pthread_mutex_lock" locks "job->monitor".
389-ds-base-1.4.1.4.20190619git2daf26aa8/src/nunc-stans/ns/ns_thrpool.c:1294: double_lock: "internal_ns_job_rearm" locks "job->monitor" while it is locked.
# 1292|   #endif
# 1293|           job->state = NS_JOB_NEEDS_ARM;
# 1294|->         internal_ns_job_rearm(job);
# 1295|           pthread_mutex_unlock(&(job->monitor));
# 1296|           return NS_SUCCESS;

I don't think any of these are new, but worth looking over one more time...

I'm glad you sent me the covscan report - reviewing these, there was an issue in here, which I have resolved (maybe I'm just more patient with coverity today :) )

EDIT: I have also fixed/commented all the locations you mentioned in the review. The date is "correct" because that's when I look at the patch last apparently ;)

The patch is nice but huge and difficult to check confirm if it fixes deadlock or not. I think I found a scenario of deadlock but before a general comment.

With your patch we have per opened connection a unique and same ns_job for all the life of the connection. It could be better than the previous implementation where we had continuously changing ns_job. However the scenario of deadlock was because of two locks (c_mutex and job->monitor) taken in the opposite order. The current patch keeps those two locks and I think there is still a risk of taking them in the opposite order.

The following scenario could create deadlock but I do not know if it is realistic:

Thread A, is a ns_thread that detects activity on the connection and call the callback function

worker_thread_func ->
   work_job_execute ->
     lock(job_monitor)
     call ns_handle_work -> 
          lock(c_mutex)

Thread B, is returning data (entries or result) to a search and detecting error condition it disconnect the server

op_shared_search ->
   send_results ->
      do_disconnect ->
          lock(c_mutex)
          disconnect_server ->
                ns_handle_closure_conn_nomutex ->
                       ns_add_job(ns_handle_closure) ->
                           internal_ns_job_rearm ->
                              lock(job_monitor)

If there is conn<-->job is unique and stable, do you think it could be possible to use a unique lock to protect those two struct ?

I think you may have an excellent point here. Perhaps when nunc_stans is true, since there is a conn<-->job as you say, we could exclusively use the job lock in that case. That would allow us to more easily find and see these deadlocks.

I think the scenario you have put here is sound and reasonable, so I'll think about what's right to do here. There is meant to be "protection" inside of the ns_add_job or re-arm to allow self-re-arming if we are on the worker, but Ithink here because you correctly state they are on seperate threads it may not come into effect.

Let me have some time to think about the solution, but I certainly think you may be correct here.

After a lot of discussion yesterday with @tbordaz we agreed to use the c_mutex, and to have a method to supply an external monitor into NS at io-event create. I think the only complexity would be that c_mutex is a PR_Monitor, but ns use pthread mutex with monitor enabled. So we may need to cchange c_mutex to be pthread (which is faster anyway ....) so that we can then keep the current ns monitor for it's internal usage.

The alternative is that we have to write a lock-wrapper for c_mutex that does "if nunc_stans -> use job monitor, else us pr_monitor c_mutex". But that's also a lot of code to touch and replace.

https://pagure.io/389-ds-base/issue/50459

I think I will implement this, then I can come back and rebase this code onto it? Does that seem reasonable @tbordaz ?

IMHO #50459 (NSPR mutex/monitor -> pthread mutex/monitor) and #49569 (nunc stans deadlock) are independant.
I would vote to first get #49569 pushed into master, then confirm the performance benefit of pthread monitor on c_mutex with another ticket. The when benefit is proven applies it to the full server with #50459.

But they aren't - if we are going to make nunc-stans job and conn to use the same lock to avoid the lock pattern you mention, then we need a way to supply the monitor to the ns_job at io event create time. Today NS uses pthread, so the conn monitor has to be pthread also to give that to the ns event to allow the single lock.

That's why I suggested 50459 first.

So if we were to merge 49569 today, yeah, it's a huge improvement over the current NS code, but we still could not "enable" it due to the deadlock concern you raised. It would only be after 50459 that we could really do this to create the single lock to avoid the case.

I'm open to merging this today of course - I think the op_stack clean up is really valuable, and the NS code really already is unsafe, so merging "better but still unsafe" code is not harmful. But again, we really couldn't enable it until after 50459 ....

Arghhh.. sorry for the confusion I did not understand your proposal.

Yes it is fine. Fixing #50459 first then #49569

Great! I'll do that soon then (but there may be a small delay as I have some SUSE responsibilities for the next two -> three weeks which may delay my progress)

Okay, this update rebases to master to allow the pthread_mutex rewrite of c_mutex to be present in preparation to work on the ns-lock sharing.

In general though, I can conform that this passes a few test suites, so I think this is getting closer to completion.

Saying this, as a reminder, this feature IS feature gated with a config option, defaulting to OFF, so merging "early" is not a dangerous action as it won't be released to actual users until we change the default.

@tbordaz Review in the mind of not fixing deadlock, but fixes the double-handler and connection leak :) Thank you!

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/2695

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.