Cplex is stuck after root node relaxation solution

I am solving an MIP through Benders decomposition (coded both generic and legacy callback versions), by employing Java with Cplex 12.9. For some of the instances, Cplex is stuck for two hours (time limit is two hours) after solving root node relaxation very fast (in less than a second) and finally at the end of two hours it reports a single line of branch and bound tree (root node) and exits due to time limit. Nothing is reported after root node relaxation solution and before the first line of branch and bound tree (to understand what Cplex is doing for two hours). I turned off reductions and presolve and all possible cuts. Nothing changed. Please see that portion of the code:

master.setParam(IloCplex.IntParam.MIPDisplay, 4);
master.setParam(IloCplex.Param.Threads, nThreads);
master.setParam(IloCplex.Param.Preprocessing.Reduce, 0);
master.setParam(IloCplex.BooleanParam.PreInd, false);
master.setParam(IloCplex.IntParam.MIPEmphasis, 2);
master.setParam(IloCplex.IntParam.VarSel, 3);
master.setParam(IloCplex.Param.MIP.Strategy.HeuristicFreq, -1);
master.setParam(IloCplex.DoubleParam.TiLim, 7200);

master.setParam(IloCplex.IntParam.Cliques, -1);
master.setParam(IloCplex.IntParam.Covers, -1);
master.setParam(IloCplex.IntParam.DisjCuts, -1);
master.setParam(IloCplex.IntParam.FlowCovers, -1);
master.setParam(IloCplex.IntParam.FracCuts, -1);
master.setParam(IloCplex.IntParam.GUBCovers, -1);
master.setParam(IloCplex.IntParam.LiftProjCuts, -1);
master.setParam(IloCplex.IntParam.MCFCuts, -1);
master.setParam(IloCplex.IntParam.MIRCuts, -1);
master.setParam(IloCplex.IntParam.FlowPaths, -1);
master.setParam(IloCplex.IntParam.ZeroHalfCuts, -1);

master.setParam(IloCplex.Param.MIP.Cuts.BQP, -1);
master.setParam(IloCplex.Param.MIP.Cuts.Cliques, -1);
master.setParam(IloCplex.Param.MIP.Cuts.Covers, -1);
master.setParam(IloCplex.Param.MIP.Cuts.Disjunctive, -1);
master.setParam(IloCplex.Param.MIP.Cuts.FlowCovers, -1);
master.setParam(IloCplex.Param.MIP.Cuts.Gomory, -1);
master.setParam(IloCplex.Param.MIP.Cuts.GUBCovers, -1);
master.setParam(IloCplex.Param.MIP.Cuts.Implied, -1);
master.setParam(IloCplex.Param.MIP.Cuts.LiftProj, -1);
master.setParam(IloCplex.Param.MIP.Cuts.LocalImplied, -1);
master.setParam(IloCplex.Param.MIP.Cuts.MCFCut, -1);
master.setParam(IloCplex.Param.MIP.Cuts.MIRCut, -1);
master.setParam(IloCplex.Param.MIP.Cuts.PathCut, -1);
master.setParam(IloCplex.Param.MIP.Cuts.RLT, -1);
master.setParam(IloCplex.Param.MIP.Cuts.ZeroHalfCut, -1);


Please see the log file below:

CPXPARAM_Preprocessing_Presolve                  0
CPXPARAM_Preprocessing_Reduce                    0
CPXPARAM_Threads                                 40
CPXPARAM_MIP_Cuts_Cliques                        -1
CPXPARAM_MIP_Cuts_Covers                         -1
CPXPARAM_MIP_Display                             4
CPXPARAM_MIP_Strategy_VariableSelect             3
CPXPARAM_MIP_Cuts_FlowCovers                     -1
CPXPARAM_MIP_Cuts_Implied                        -1
CPXPARAM_MIP_Cuts_GUBCovers                      -1
CPXPARAM_MIP_Cuts_Gomory                         -1
CPXPARAM_MIP_Cuts_PathCut                        -1
CPXPARAM_MIP_Cuts_MIRCut                         -1
CPXPARAM_MIP_Cuts_Disjunctive                    -1
CPXPARAM_Emphasis_MIP                            2
CPXPARAM_MIP_Cuts_ZeroHalfCut                    -1
CPXPARAM_MIP_Cuts_MCFCut                         -1
CPXPARAM_MIP_Cuts_LiftProj                       -1
CPXPARAM_MIP_Cuts_LocalImplied                   -1
CPXPARAM_MIP_Cuts_BQP                            -1
CPXPARAM_MIP_Cuts_RLT                            -1
CPXPARAM_MIP_Strategy_HeuristicFreq              -1
CPXPARAM_TimeLimit                               7200
Lazy constraint(s) or lazy constraint callback is present.
Disabling non-linear reductions (CPX_PARAM_PRELINEAR) in presolve.
Clique table members: 114063.
MIP emphasis: optimality.
MIP search method: dynamic search.
Parallel mode: deterministic, using up to 40 threads.
Parallel mode: deterministic, using up to 40 threads for concurrent optimization.
Initializing dual steep norms . . .
Initializing dual steep norms . . .

Dual simplex solved model.

Root relaxation solution time = 0.61 sec. (227.78 ticks)

Nodes                                         Cuts/
Node  Left     Objective  IInf  Best Integer    Best Bound    ItCnt     Gap

0     0  3898607.0000     0                      0.0000        0

User cuts applied:  2

Root node processing (before b&c):
Real time             = 7199.43 sec. (2190540.20 ticks)
Parallel b&c, 40 threads:
Real time             =    0.00 sec. (0.00 ticks)
Sync time (average)   =    0.00 sec.
Wait time (average)   =    0.00 sec.
------------
Total (root+branch&cut) = 7199.43 sec. (2190540.20 ticks)


Thank you.

• Can you verify that the cuts that you are adding violate the current solution? I have seen cases where the cut does not violate, such that you get the same solution in the next iteration, after which you add the same cut again. Such an infinite loop could explain the behaviour you describe. – Kevin Dalmeijer Dec 22 '19 at 14:37
• I am adding three types of cuts. 1. Benders optimality cuts added at integer solutions, 2. Benders optimality cuts added at fractional solutions, and 3. Valid inequalities added only at the root node relaxation. To eliminate the possibility of a loop I am just using 1st type of cuts. And I am pretty sure that Benders optimality cuts are cutting off the current solution. As you can see there are only two Benders cuts added in the log file. Thank you. – Vedat BAYRAM Dec 22 '19 at 15:18
• Was this output from the legacy callback version or the generic callback version? For debugging purposes, you might set the node log frequency to 1 (so that a line is printed for every node). Also, you might want to print a time stamp each time the callback is entered and exited (also printing the thread #, to keep them straight). – prubin Dec 22 '19 at 21:41
• Thank you for the comment. Log frequency is set to 4, in which case Cplex is supposed to "Display the number of cuts added since previous display; information about the processing of each successful MIP start; elapsed time in seconds and elapsed time in deterministic ticks for integer feasible solutions and information about the LP subproblem at root" as defined by IBM support. I am now trying your advice regarding time stamp at each callback and thread id. Thank you. – Vedat BAYRAM Dec 23 '19 at 15:13
• I am using generic callback now. I checked the time stamps and thread Ids. Additionally after root node relaxation and before the single line of branch and bound tree, now I have: Time: 1.446242725 Thread Id: 0 Time: 3.146363022 Thread Id: 0 in Candidate >>> Adding optimality cut at int point: Time: 1926.164073447 Thread Id: 0 in Candidate >>> Adding optimality cut at int point: Time: 7201.699062 Thread Id: 0 – Vedat BAYRAM Dec 23 '19 at 18:24