Strange Cbc behavior

[andreaslundell]

When solving e.g. autocorr_bern25-13 from MINLPLib, which SHOT can reformulate into an MILP problem, Cbc has some strange behavior.

If calling SHOT with --mip=cbc --timelimit=70 Dual.Relaxation.Use=false Subsolver.Cbc.DeterministicParallelMode=true --threads=1 --debug (on the stability branch), the first and only SHOT iteration produces the following output:

release git:(stability) ./SHOT ~/Research/minlplib2/21122018/minlplib/gms/autocorr_bern25-13.gms --mip=cbc --timelimit=70 Dual.Relaxation.Use=false Subsolver.Cbc.DeterministicParallelMode=true --threads=1 --debug

╶ Supporting Hyperplane Optimization Toolkit (SHOT) ──────────────────────────────────────────────────────────────────╴

 Andreas Lundell and Jan Kronqvist, Åbo Akademi University, Finland.
 See documentation for full list of contributors and utilized software libraries.

 Version: 1.0.alpha 1. Git hash: 4be53ff4. Released Mar  7 2020.

 For more information visit https://shotsolver.dev

╶ Modeling system ────────────────────────────────────────────────────────────────────────────────────────────────────╴

 Modeling system:            GAMS
 Problem read from file:     /home/aton3/alundell/Research/minlplib2/21122018/minlplib/gms/autocorr_bern25-13.gms

 Performing bound tightening on original problem.
  - Bounds for 1 variables tightened in 0.36 s.

╶ Problem instance ───────────────────────────────────────────────────────────────────────────────────────────────────╴

                                    Original             Reformulated

 Problem classification:            MINLP, nonconvex     MILP, convex

 Objective function direction:      minimize             minimize
 Objective function type:           linear               linear

 Number of constraints:             1                    3737
  - linear:                         0                    3737
  - nonconvex nonlinear:            1                    0

 Number of variables:               26                   1783
  - real:                           1                    223
  - binary:                         25                   1560
  - nonlinear:                      25                   0

╶ Options ────────────────────────────────────────────────────────────────────────────────────────────────────────────╴

 No options file specified.

 Nondefault options used:

  - Dual.MIP.NumberOfThreads = 1
  - Dual.MIP.Solver = 2
  - Dual.Relaxation.Use = false
  - Dual.TreeStrategy = 0
  - Model.Reformulation.Quadratics.Strategy = 0
  - Output.Console.DualSolver.Show = true
  - Primal.Tolerance.TrustLinearConstraintValues = false
  - Subsolver.Cbc.DeterministicParallelMode = true
  - Termination.TimeLimit = 70.0

 Dual strategy:              Multi-tree
  - cut algorithm:           ESH
  - solver:                  Cbc 2.10.4

 Primal NLP solver:          Ipopt 3.13.0 with Ipopt default linear solver

    Iteration     │  Time  │  Dual cuts  │     Objective value     │   Objective gap   │     Current solution
     #: type      │  tot.  │   + | tot.  │       dual | primal     │    abs. | rel.    │    obj.fn. | max.err.
╶─────────────────┴────────┴─────────────┴─────────────────────────┴───────────────────┴───────────────────────────╴

Welcome to the CBC MILP Solver
Version: 2.10.4
Build Date: Feb 17 2020

command line -  -autoscale off -nodestrategy fewest -scaling automatic -strategy 1 -cutoff 1e+100 -sec 69.478272985 -threads 101 -solve -quit
Option for nodeStrategy changed from hybrid to fewest
cutoff was changed from 1e+100 to 1e+100
seconds was changed from 1e+100 to 69.4783
threads was changed from 0 to 101
Continuous objective value is -131872 - 0.19 seconds
Cgl0004I processed model has 3737 rows, 1783 columns (1560 integer (1560 of which binary)) and 16587 elements
Cbc0031I 1342 added rows had average density of 9.7242921
Cbc0013I At root node, 1342 cuts changed objective from -131872 to -70095.095 in 85 passes
Cbc0014I Cut generator 0 (Probing) - 14259 row cuts average 2.0 elements, 0 column cuts (739 active)  in 3.506 seconds - new frequency is 1
Cbc0014I Cut generator 1 (Gomory) - 21638 row cuts average 42.2 elements, 0 column cuts (0 active)  in 3.766 seconds - new frequency is 1
Cbc0014I Cut generator 2 (Knapsack) - 336 row cuts average 2.0 elements, 0 column cuts (0 active)  in 0.787 seconds - new frequency is 1
Cbc0014I Cut generator 3 (Clique) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.286 seconds - new frequency is -100
Cbc0014I Cut generator 4 (MixedIntegerRounding2) - 18 row cuts average 32.1 elements, 0 column cuts (0 active)  in 2.082 seconds - new frequency is -100
Cbc0014I Cut generator 5 (FlowCover) - 1 row cuts average 9.0 elements, 0 column cuts (0 active)  in 0.080 seconds - new frequency is -100
Cbc0014I Cut generator 6 (TwoMirCuts) - 2658 row cuts average 30.9 elements, 0 column cuts (0 active)  in 0.665 seconds - new frequency is 1
Cbc0010I After 0 nodes, 1 on tree, 1e+50 best solution, best possible -70095.095 (31.98 seconds)
Cbc0016I Integer solution of -7636 found by strong branching after 94997 iterations and 21 nodes (61.21 seconds)
Cbc0012I Integer solution of -7916 found by heuristic after 94589 iterations and 18 nodes (65.26 seconds)
Cbc0030I Thread 0 used 5 times,  waiting to start 20.832898, 16.763806 cpu time, 0 locks, 0 locked, 0 waiting for locks
Cbc0030I Main thread 16.856859 waiting for threads,  0 locks, 0 locked, 0 waiting for locks
Cbc0020I Exiting on maximum time
Cbc0005I Partial search - best objective -7916 (best possible -66530.32), took 106525 iterations and 39 nodes (69.54 seconds)
Cbc0032I Strong branching done 606 times (47018 iterations), fathomed 2 nodes and fixed 0 variables
Cbc0035I Maximum depth 7, 8 variables fixed on reduced cost
Cuts at root node changed objective from -131872 to -70095.1
Probing was tried 292 times and created 56631 cuts of which 1478 were active after adding rounds of cuts (5.380 seconds)
Gomory was tried 291 times and created 56774 cuts of which 0 were active after adding rounds of cuts (5.212 seconds)
Knapsack was tried 291 times and created 2076 cuts of which 0 were active after adding rounds of cuts (1.098 seconds)
Clique was tried 170 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.286 seconds)
MixedIntegerRounding2 was tried 170 times and created 36 cuts of which 0 were active after adding rounds of cuts (2.082 seconds)
FlowCover was tried 170 times and created 2 cuts of which 0 were active after adding rounds of cuts (0.080 seconds)
TwoMirCuts was tried 291 times and created 10239 cuts of which 0 were active after adding rounds of cuts (1.762 seconds)
ZeroHalf was tried 2 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.065 seconds)
ImplicationCuts was tried 93 times and created 2223 cuts of which 0 were active after adding rounds of cuts (0.595 seconds)

Result - Stopped on time limit

Objective value:                100000000000000007629769841091887003294964970946560.00000000
Lower bound:                    -66530.320
Gap:                            1503074085339087925432970472628447629652525056.00
Enumerated nodes:               39
Total iterations:               106525
Time (CPU seconds):             69.63
Time (Wallclock seconds):       70.05

Total time (CPU seconds):       69.63   (Wallclock seconds):       70.05

     1: MIP-TL      70.58                       -inf. | inf.            inf. | inf.                 | inf.

╶ Solution report ────────────────────────────────────────────────────────────────────────────────────────────────────╴

 Terminated since time limit was reached.

 No solution found. Try modifying the termination criteria.

 Objective bound (minimization) [dual, primal]:  [-inf., inf.]
 Objective gap absolute / relative:              inf. / inf.

 Fulfilled termination criteria:
  - solution time limit (s)                      70.5761 > 70

 Unfulfilled termination criteria:
  - absolute objective gap tolerance             inf > 0.001
  - relative objective gap tolerance             inf > 0.001
  - maximal constraint tolerance                 1.79769e+308 > 1e-08
  - iteration limit                              1 <= 200000

 Dual problems solved in main step:              1
  - MILP problems, feasible                      1

 Number of explored nodes:                       39

 Total solution time:                            70.5761
  - problem reformulation:                       0.00574987
  - bound tightening:                            0.364141
    - feasibility based (original problem):      0.364127
  - dual strategy:                               70.0614
    - root search for constraint cuts:           8.351e-06
  - primal strategy:                             0.000580469
    - solving NLP problems:                      0.000495661

╶─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╴

 Results written to: /home/aton3/alundell/Research/SHOT/SHOT-COINOR/build/release/autocorr_bern25-13.osrl
 Log written to:     /home/aton3/alundell/Research/SHOT/SHOT-COINOR/build/release/SHOT.log

So although it has found an integer solution, it claims the problem is infeasible. Also the return status should not be infeasible, but that a time limit has occured.

Well if I then run it with standalone Cbc (and the LP-file produced by Cbc in the same run), I get the following output:

Welcome to the CBC MILP Solver
Version: 2.10.4
Build Date: Feb 17 2020

command line - /opt/cbc-2.10.4/bin/cbc lp0.lp -autoscale off -nodestrategy fewest -scaling automatic -strategy 1 -cutoff 1e+100 -sec 69.478272985 -threads 101 -solve -quit
cutoff was changed from 1e+100 to 1e+100
seconds was changed from 1e+100 to 69.4783
threads was changed from 0 to 101
Continuous objective value is -131872 - 0.20 seconds
Cgl0004I processed model has 3737 rows, 1783 columns (1560 integer (1560 of which binary)) and 16587 elements
Cbc0038I Initial state - 1075 integers unsatisfied sum - 537.5
Cbc0038I Pass   1: (0.35 seconds) suminf.  118.51282 (449) obj. -39926.9 iterations 1380
Cbc0038I Pass   2: (0.36 seconds) suminf.  118.25000 (419) obj. -38690 iterations 37
Cbc0038I Pass   3: (0.37 seconds) suminf.  118.25000 (419) obj. -38690 iterations 31
Cbc0038I Pass   4: (0.38 seconds) suminf.  112.16667 (396) obj. -36811.7 iterations 91
Cbc0038I Pass   5: (0.39 seconds) suminf.  111.95833 (403) obj. -36430 iterations 35
Cbc0038I Pass   6: (0.39 seconds) suminf.  111.95833 (403) obj. -36430 iterations 31
Cbc0038I Pass   7: (0.40 seconds) suminf.  111.95833 (403) obj. -36430 iterations 13
Cbc0038I Pass   8: (0.41 seconds) suminf.  108.45455 (418) obj. -37136.1 iterations 85
Cbc0038I Pass   9: (0.42 seconds) suminf.  108.16667 (384) obj. -34832.2 iterations 41
Cbc0038I Pass  10: (0.43 seconds) suminf.  103.44444 (386) obj. -34836.8 iterations 70
Cbc0038I Pass  11: (0.44 seconds) suminf.  103.25000 (366) obj. -34295 iterations 52
Cbc0038I Pass  12: (0.45 seconds) suminf.  103.25000 (366) obj. -34295 iterations 18
Cbc0038I Pass  13: (0.46 seconds) suminf.  103.25000 (366) obj. -34295 iterations 15
Cbc0038I Pass  14: (0.51 seconds) suminf.   96.66667 (290) obj. -8682.67 iterations 620
Cbc0038I Pass  15: (0.52 seconds) suminf.   96.66667 (290) obj. -8682.67 iterations 26
Cbc0038I Pass  16: (0.53 seconds) suminf.   93.66667 (281) obj. -7786.67 iterations 58
Cbc0038I Pass  17: (0.54 seconds) suminf.   93.66667 (281) obj. -7786.67 iterations 27
Cbc0038I Pass  18: (0.55 seconds) suminf.   88.00000 (264) obj. -6954.67 iterations 98
Cbc0038I Pass  19: (0.56 seconds) suminf.   88.00000 (264) obj. -6954.67 iterations 34
Cbc0038I Pass  20: (0.57 seconds) suminf.   86.66667 (260) obj. -6677.33 iterations 50
Cbc0038I Pass  21: (0.57 seconds) suminf.   86.66667 (260) obj. -6677.33 iterations 25
Cbc0038I Pass  22: (0.58 seconds) suminf.   82.66667 (248) obj. -5717.33 iterations 57
Cbc0038I Pass  23: (0.59 seconds) suminf.   82.66667 (248) obj. -5717.33 iterations 18
Cbc0038I Pass  24: (0.60 seconds) suminf.   75.61111 (226) obj. -5761.78 iterations 105
Cbc0038I Pass  25: (0.61 seconds) suminf.   75.16667 (225) obj. -5690.67 iterations 22
Cbc0038I Pass  26: (0.61 seconds) suminf.   74.66667 (224) obj. -5754.67 iterations 2
Cbc0038I Pass  27: (0.62 seconds) suminf.   71.33333 (214) obj. -5882.67 iterations 55
Cbc0038I Pass  28: (0.62 seconds) suminf.   71.33333 (214) obj. -5882.67 iterations 17
Cbc0038I Pass  29: (0.63 seconds) suminf.   68.66667 (206) obj. -5221.33 iterations 59
Cbc0038I Pass  30: (0.64 seconds) suminf.   68.66667 (206) obj. -5221.33 iterations 32
Cbc0038I Rounding solution of 5889.33 is better than previous of 1e+50

Cbc0038I Before mini branch and bound, 430 integers at bound fixed and 0 continuous
Cbc0038I Full problem 3737 rows 1783 columns, reduced to 3307 rows 1353 columns - too large
Cbc0038I Mini branch and bound did not improve solution (0.66 seconds)
Cbc0038I Round again with cutoff of -7886.8
Cbc0038I Pass  30: (0.66 seconds) suminf.  118.51282 (449) obj. -39926.9 iterations 0
Cbc0038I Pass  31: (0.67 seconds) suminf.  118.25000 (419) obj. -38690 iterations 70
Cbc0038I Pass  32: (0.68 seconds) suminf.  110.08333 (398) obj. -34710 iterations 66
Cbc0038I Pass  33: (0.69 seconds) suminf.  110.08333 (398) obj. -34710 iterations 22
Cbc0038I Pass  34: (0.69 seconds) suminf.  110.08333 (398) obj. -34710 iterations 16
Cbc0038I Pass  35: (0.74 seconds) suminf.  102.66667 (308) obj. -7886.8 iterations 579
Cbc0038I Pass  36: (0.74 seconds) suminf.  102.66667 (308) obj. -7886.8 iterations 31
Cbc0038I Pass  37: (0.77 seconds) suminf.   98.66667 (296) obj. -7886.8 iterations 141
Cbc0038I Pass  38: (0.77 seconds) suminf.   98.66667 (296) obj. -7886.8 iterations 26
Cbc0038I Pass  39: (0.80 seconds) suminf.   95.82796 (287) obj. -7886.8 iterations 213
Cbc0038I Pass  40: (0.81 seconds) suminf.   95.80786 (287) obj. -7886.8 iterations 30
Cbc0038I Pass  41: (0.82 seconds) suminf.   87.33333 (262) obj. -9930.67 iterations 106
Cbc0038I Pass  42: (0.83 seconds) suminf.   87.33333 (262) obj. -9930.67 iterations 30
Cbc0038I Pass  43: (0.84 seconds) suminf.   82.00000 (246) obj. -8032 iterations 57
Cbc0038I Pass  44: (0.85 seconds) suminf.   82.00000 (246) obj. -8032 iterations 20
Cbc0038I Pass  45: (0.87 seconds) suminf.   76.20080 (228) obj. -7886.8 iterations 197
Cbc0038I Pass  46: (0.88 seconds) suminf.   76.07585 (228) obj. -7886.8 iterations 24
Cbc0038I Pass  47: (0.88 seconds) suminf.   73.25126 (218) obj. -7886.8 iterations 42
Cbc0038I Pass  48: (0.89 seconds) suminf.   73.25126 (218) obj. -7886.8 iterations 25
Cbc0038I Pass  49: (0.90 seconds) suminf.   68.33333 (205) obj. -10712 iterations 68
Cbc0038I Pass  50: (0.91 seconds) suminf.   68.33333 (205) obj. -10712 iterations 15
Cbc0038I Pass  51: (0.92 seconds) suminf.   64.72222 (193) obj. -10098.7 iterations 75
Cbc0038I Pass  52: (0.92 seconds) suminf.   63.33333 (190) obj. -10088 iterations 25
Cbc0038I Pass  53: (0.93 seconds) suminf.   59.33333 (178) obj. -8530.67 iterations 59
Cbc0038I Pass  54: (0.94 seconds) suminf.   59.33333 (178) obj. -8530.67 iterations 28
Cbc0038I Pass  55: (0.95 seconds) suminf.   54.05556 (161) obj. -8152 iterations 105
Cbc0038I Pass  56: (0.96 seconds) suminf.   53.16667 (159) obj. -7896 iterations 31
Cbc0038I Pass  57: (0.97 seconds) suminf.   50.44663 (150) obj. -7886.8 iterations 64
Cbc0038I Pass  58: (0.97 seconds) suminf.   50.44663 (150) obj. -7886.8 iterations 20
Cbc0038I Pass  59: (0.99 seconds) suminf.   45.60220 (136) obj. -7886.8 iterations 127
Cbc0038I Rounding solution of -3525.33 is better than previous of 5889.33

Cbc0038I Before mini branch and bound, 431 integers at bound fixed and 0 continuous
Cbc0038I Full problem 3737 rows 1783 columns, reduced to 3306 rows 1352 columns - too large
Cbc0038I Mini branch and bound did not improve solution (1.00 seconds)
Cbc0038I Round again with cutoff of -32683.8
Cbc0038I Pass  59: (1.01 seconds) suminf.  118.51282 (449) obj. -39926.9 iterations 0
Cbc0038I Pass  60: (1.02 seconds) suminf.  118.25000 (419) obj. -38690 iterations 70
Cbc0038I Pass  61: (1.02 seconds) suminf.  118.25000 (419) obj. -38690 iterations 10
Cbc0038I Pass  62: (1.04 seconds) suminf.  112.25926 (420) obj. -38372.6 iterations 93
Cbc0038I Pass  63: (1.05 seconds) suminf.  112.25926 (420) obj. -38372.6 iterations 59
Cbc0038I Pass  64: (1.06 seconds) suminf.  111.92593 (426) obj. -36912 iterations 49
Cbc0038I Pass  65: (1.07 seconds) suminf.  111.91667 (394) obj. -36832.2 iterations 57
Cbc0038I Pass  66: (1.07 seconds) suminf.  110.00000 (414) obj. -36852 iterations 59
Cbc0038I Pass  67: (1.08 seconds) suminf.  110.00000 (414) obj. -36852 iterations 52
Cbc0038I Pass  68: (1.10 seconds) suminf.  105.11111 (407) obj. -36018.9 iterations 119
Cbc0038I Pass  69: (1.11 seconds) suminf.  104.37037 (399) obj. -34869.2 iterations 87
Cbc0038I Pass  70: (1.12 seconds) suminf.  104.37037 (399) obj. -34869.2 iterations 9
Cbc0038I Pass  71: (1.13 seconds) suminf.   98.18519 (381) obj. -32850.6 iterations 122
Cbc0038I Pass  72: (1.15 seconds) suminf.   96.80000 (335) obj. -36657.6 iterations 85
Cbc0038I Pass  73: (1.15 seconds) suminf.   96.33333 (334) obj. -36642.7 iterations 6
Cbc0038I Pass  74: (1.16 seconds) suminf.   93.91667 (344) obj. -35420.2 iterations 51
Cbc0038I Pass  75: (1.17 seconds) suminf.   93.92500 (343) obj. -35451.5 iterations 43
Cbc0038I Pass  76: (1.18 seconds) suminf.   90.96795 (358) obj. -33252.5 iterations 70
Cbc0038I Pass  77: (1.18 seconds) suminf.   90.58333 (349) obj. -33897.2 iterations 40
Cbc0038I Pass  78: (1.19 seconds) suminf.   81.83333 (322) obj. -32683.8 iterations 71
Cbc0038I Pass  79: (1.20 seconds) suminf.   81.56061 (325) obj. -32683.8 iterations 24
Cbc0038I Pass  80: (1.21 seconds) suminf.   81.31818 (326) obj. -32683.8 iterations 37
Cbc0038I Pass  81: (1.22 seconds) suminf.   74.81004 (311) obj. -32683.8 iterations 54
Cbc0038I Pass  82: (1.22 seconds) suminf.   74.80133 (310) obj. -32683.8 iterations 27
Cbc0038I Pass  83: (1.24 seconds) suminf.   69.10270 (265) obj. -32683.8 iterations 132
Cbc0038I Pass  84: (1.24 seconds) suminf.   69.10270 (265) obj. -32683.8 iterations 22
Cbc0038I Pass  85: (1.25 seconds) suminf.   68.98541 (265) obj. -32683.8 iterations 35
Cbc0038I Pass  86: (1.26 seconds) suminf.   68.98541 (265) obj. -32683.8 iterations 25
Cbc0038I Pass  87: (1.26 seconds) suminf.   67.51870 (261) obj. -32683.8 iterations 49
Cbc0038I Pass  88: (1.27 seconds) suminf.   67.20352 (261) obj. -32683.8 iterations 15
Cbc0038I No solution found this major pass
Cbc0038I Before mini branch and bound, 450 integers at bound fixed and 19 continuous
Cbc0038I Full problem 3737 rows 1783 columns, reduced to 3249 rows 1314 columns - too large
Cbc0038I Mini branch and bound did not improve solution (1.29 seconds)
Cbc0038I After 1.29 seconds - Feasibility pump exiting with objective of -3525.33 - took 1.02 seconds
Cbc0012I Integer solution of -7520 found by feasibility pump after 0 iterations and 0 nodes (1.29 seconds)
Cbc0031I 1344 added rows had average density of 11.306548
Cbc0013I At root node, 1344 cuts changed objective from -131872 to -69829.321 in 91 passes
Cbc0014I Cut generator 0 (Probing) - 12737 row cuts average 2.0 elements, 0 column cuts (377 active)  in 7.849 seconds - new frequency is 1
Cbc0014I Cut generator 1 (Gomory) - 17555 row cuts average 44.3 elements, 0 column cuts (0 active)  in 5.412 seconds - new frequency is 1
Cbc0014I Cut generator 2 (Knapsack) - 989 row cuts average 2.0 elements, 0 column cuts (0 active)  in 0.818 seconds - new frequency is 1
Cbc0014I Cut generator 3 (Clique) - 0 row cuts average 0.0 elements, 0 column cuts (0 active)  in 0.298 seconds - new frequency is -100
Cbc0014I Cut generator 4 (MixedIntegerRounding2) - 47 row cuts average 36.0 elements, 0 column cuts (0 active)  in 2.428 seconds - new frequency is -100
Cbc0014I Cut generator 5 (FlowCover) - 3 row cuts average 2.0 elements, 0 column cuts (0 active)  in 0.107 seconds - new frequency is -100
Cbc0014I Cut generator 6 (TwoMirCuts) - 2614 row cuts average 31.3 elements, 0 column cuts (0 active)  in 0.784 seconds - new frequency is 1
Cbc0010I After 0 nodes, 1 on tree, -7520 best solution, best possible -69829.321 (40.70 seconds)
Cbc0016I Integer solution of -7832 found by strong branching after 98191 iterations and 28 nodes (69.15 seconds)
Clp0006I 0  Obj -7840.0005 Primal inf 0.20250189 (1)
Cbc0012I Integer solution of -7832 found by heuristic after 98148 iterations and 27 nodes (69.49 seconds)
Cbc0030I Thread 0 used 3 times,  waiting to start 14.004904, 14.835831 cpu time, 0 locks, 0 locked, 0 waiting for locks
Cbc0030I Main thread 14.890258 waiting for threads,  0 locks, 0 locked, 0 waiting for locks
Cbc0020I Exiting on maximum time
Cbc0005I Partial search - best objective -7832 (best possible -69829.321), took 98602 iterations and 37 nodes (69.54 seconds)
Cbc0032I Strong branching done 696 times (33924 iterations), fathomed 1 nodes and fixed 0 variables
Cbc0035I Maximum depth 26, 15 variables fixed on reduced cost
Cuts at root node changed objective from -131872 to -69829.3
Probing was tried 301 times and created 56797 cuts of which 754 were active after adding rounds of cuts (9.763 seconds)
Gomory was tried 300 times and created 51105 cuts of which 0 were active after adding rounds of cuts (7.003 seconds)
Knapsack was tried 300 times and created 3547 cuts of which 0 were active after adding rounds of cuts (1.087 seconds)
Clique was tried 182 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.298 seconds)
MixedIntegerRounding2 was tried 182 times and created 94 cuts of which 0 were active after adding rounds of cuts (2.428 seconds)
FlowCover was tried 182 times and created 6 cuts of which 0 were active after adding rounds of cuts (0.107 seconds)
TwoMirCuts was tried 300 times and created 8827 cuts of which 0 were active after adding rounds of cuts (1.604 seconds)
ZeroHalf was tried 2 times and created 0 cuts of which 0 were active after adding rounds of cuts (0.068 seconds)
ImplicationCuts was tried 80 times and created 3007 cuts of which 0 were active after adding rounds of cuts (1.876 seconds)

Result - Stopped on time limit

Objective value:                -7832.00000000
Lower bound:                    -69829.321
Gap:                            0.89
Enumerated nodes:               37
Total iterations:               98602
Time (CPU seconds):             69.67
Time (Wallclock seconds):       69.92

Total time (CPU seconds):       69.67   (Wallclock seconds):       69.93

I do not know if there is something wrong in the Cbc call by SHOT or a bug in Cbc, but there seems to be different behavior when calling Cbc directly. The return status is correct in this case, and the solution is reported. There also seems to be a lot more output lines written to screen when calling Cbc directly.

Can you verify this @svigerske? And do you have any suggestions, or do you believe this is a bug in Cbc?

[svigerske]

There is one fix in Cbc stable/2.10 since 2.10.4 that had to do with the result when Clp ran into the timelimit: https://github.com/coin-or/Cbc/commit/4590be2c465cbd1229873f37afece9d62c7a327e Can you try whether this helps regarding the solution status?

The run from SHOT has the line Option for nodeStrategy changed from hybrid to fewest, while the standalone Cbc doesn't, but seems to run feasibility pump. I don't know at the moment why that happens.

[andreaslundell]

Yes, using that fix seems to work. Thanks!

[svigerske]

Regarding the different behavior from Cbc called by SHOT and Cbc called alone, I believe I found the cause. SHOT calls

CbcMain0(model);
CbcMain1(nargs, args, model);

CbcMain0 is https://github.com/coin-or/Cbc/blob/3b94d71b94520d41e065104ebf4c87af4a2b1f3c/Cbc/src/CbcSolver.cpp#L10641-L10650 So it creates an object solverData and calls the other CbcMain0 routine with it. That other routine changes a lot of parameters in solverData. Then the first CbcMain0 frees solverData again. So CbcMain0(model) doesn't seem to make much sense.

This change in SHOT seems to bring it closer to what the Cbc executable is doing:

--- a/src/MIPSolver/MIPSolverCbc.cpp
+++ b/src/MIPSolver/MIPSolverCbc.cpp
@@ -483,15 +483,13 @@ E_ProblemSolutionStatus MIPSolverCbc::solveProblem()
             env->output->outputError("        Error when adding MIP start to Cbc", e.what());
         }

-        CbcMain0(*cbcModel);
-
         if(!env->settings->getSetting<bool>("Console.DualSolver.Show", "Output"))
         {
             cbcModel->setLogLevel(0);
             osiInterface->setHintParam(OsiDoReducePrint, false, OsiHintTry);
         }

-        CbcMain1(numArguments, const_cast<const char**>(argv), *cbcModel);
+        CbcMain(numArguments, const_cast<const char**>(argv), *cbcModel);

         MIPSolutionStatus = getSolutionStatus();
     }

Unfortunately, turning off Cbc output doesn't work this way, because noPrinting is hardcoded to false: https://github.com/coin-or/Cbc/blob/3b94d71b94520d41e065104ebf4c87af4a2b1f3c/Cbc/src/CbcSolver.cpp#L10632-L10639 But I guess you could just copy do a

  CbcSolverUsefulData cbcData;
  CbcMain0(*cbcModel, cbcData);
  CbcMain1(numArguments, const_cast<const char**>(argv), *cbcModel, dummyCallBack, cbcData);

in SHOT, where dummyCallBack is

static int dummyCallBack(CbcModel * /*model*/, int /*whereFrom*/) { return 0; }

And I'll have to fixup the GAMS/Cbc interface.