Homotopy logging does not work together with nonlinear solver logging in OMEdit

[Francesco Casella]

@AnHeuermann, please check the attached package with test cases that demonstrate the issue.

M1 fails at lambda = 0. Without homotopy logging, one can see what happens from the Newton solver log

M2 and M3 are the same as M1, but with homotopy logging or full init logging. As you can see, the process exits without giving any logging of either solver. What I'd expect to see would be that the process started at lamda = 0, then see the newton iteration going bad.

The other three models demonstrate the same problem with a model that fails at an intermediate value of lambda, during the homotopy transformation. Also in this case, one would like to see the markers of the homotopy steps interspersed with the nonlinear solver logging.

Fixing this issue is of paramount importance for debugging of models using homotopy and failing at initialization, otherwise not knowing at which value of lambda things are taking place makes the debugging even harder than it already is.

Thank you!

[Andreas Heuermann]

Log of simulation of M1

[Andreas Heuermann]

Log of simulation of M2

[Andreas Heuermann]

Log simulation M3

[Andreas Heuermann]

I'm not sure what you are expecting to get, on my logs I get exactly what you are describing. So I can't reproduce your error.
See attached logs: M1.log, M2.log and M3.log

When comparing M1 and M2 in the second one we have everything from M1 plus 5 messages from LOG_INIT_HOMOTOPY.
The same for comparing M1 and M3 with additional LOG_INIT dumps.

EDIT: Are you working on Windows with OMEdit? Are the logs from shell the same as mine?

[Francesco Casella]

I am working on Windows with OMEdit, as I guess most end-users would, and I am reporting what I see in the Simulation Output window, which matches what I see in the log file, e.g.

d:/temp/OMEdit/TestFailedHomotopy.M2/TestFailedHomotopy.M2.exe -port=52593 -logFormat=xmltcp -override=startTime=0,stopTime=1,stepSize=0.002,tolerance=1e-6,solver=dassl,outputFormat=mat,variableFilter=.* -r=d:/temp/OMEdit/TestFailedHomotopy.M2/TestFailedHomotopy.M2_res.mat -w -lv=LOG_INIT_HOMOTOPY,LOG_NLS_V,LOG_STATS -inputPath=d:/temp/OMEdit/TestFailedHomotopy.M2 -outputPath=d:/temp/OMEdit/TestFailedHomotopy.M2
update static data of non-linear system solvers
Model contains homotopy operator: Use adaptive homotopy method to solve initialization problem. To disable initialization with homotpy operator use "-noHomotopyOnFirstTry".
Global homotopy with equidistant step size started.
The homotopy path will be exported to TestFailedHomotopy.M2_equidistant_global_homotopy.csv.
Simulation process failed. Exited with code -1.

I confirm that if I run those models from a command-line script, everything works fine.

@adeas31, any clue why this could happen?

[Adeel Asghar]

@AnHeuermann can you share the mos script?

[Adeel Asghar]

I debugged this and it seems that it crashes at ​data->callback->functionInitialEquations_lambda0(data, threadData); when -logFormat=xmltcp is used which is a default flag in OMEdit. It works as expected without the flag.

I further investigated and noticed that changing the indentation value fixes the problem. So changing

infoStreamPrint(LOG_INIT_HOMOTOPY, 1, "homotopy process\n---------------------------");

to

infoStreamPrint(LOG_INIT_HOMOTOPY, 0, "homotopy process\n---------------------------");

​here gives the expected results.

I have no idea how could the indentation argument affect the simulation code. I added Martin in the CC since he implemented the xmltcp flag.

[Adeel Asghar]

I also noticed that few *.homotopy.csv files are generated in wrong directory because -outputPath is not considered when writing the file.

[Andreas Heuermann]

I tested without logFormat, with -logFormat=xml and -logFormat=xmltcp. The last is hard to test for me since I need to do it from OMEdit.

loadFile("TestFailedHomotopy.mo"); getErrorString();

setCommandLineOptions("-d=newInst"); getErrorString();

buildModel(TestFailedHomotopy.M1); getErrorString();
buildModel(TestFailedHomotopy.M2); getErrorString();
buildModel(TestFailedHomotopy.M3); getErrorString();

// Simulate without logFormat
system("./TestFailedHomotopy.M1 -lv=LOG_NLS_V","M1_expected.log"); getErrorString();
system("./TestFailedHomotopy.M2 -lv=LOG_NLS_V,LOG_INIT_HOMOTOPY", "M2_expected.log"); getErrorString();
system("./TestFailedHomotopy.M3 -lv=LOG_NLS_V,LOG_INIT_V", "M3_expected.log"); getErrorString();

// Simulate with xml
system("./TestFailedHomotopy.M1 -lv=LOG_NLS_V -logFormat=xml", "M1_xml.log"); getErrorString();
system("./TestFailedHomotopy.M2 -lv=LOG_NLS_V,LOG_INIT_HOMOTOPY -logFormat=xml", "M2_xml.log"); getErrorString();
system("./TestFailedHomotopy.M3 -lv=LOG_NLS_V,LOG_INIT_V -logFormat=xml", "M3_xml.log"); getErrorString();

Indeed only -logFormat=xmltcp has not all output.

I don't know how tcp works here, but my guess is that the problem is that we indent one info Strem

infoStreamPrint(LOG_INIT_HOMOTOPY, 1, "homotopy process\n---------------------------");

and before closing that message with

messageClose(LOG_INIT_HOMOTOPY);

we call function data->callback->functionInitialEquations_lambda0(data, threadData); which has loggin for LOG_DS, LOG_NLS_EXTRAPOLATE, LOG_NLS, LOG_NLS_V and LOG_INIT_HOMOTOPY (again) and some more.

[Andreas Heuermann]

@sjoelund What exactly is the problem here?

Is it not possible to do

a) Any different log inside a indented message

infoStreamPrint(LOG_STREAM_A, 1, "Start stream A\n---------------------------");
    infoStreamPrint(LOG_STREAM_B, 0, "Message from stream B");
infoStreamPrint(LOG_STREAM_A, 0, "Close stream A\n---------------------------");
messageClose(STREAM_A);

or

b) Start a new indented message inside a indented message

infoStreamPrint(LOG_STREAM_A, 1, "Start stream A\n---------------------------");
    infoStreamPrint(LOG_STREAM_B, 1, "Start stream B\n=================");
        infoStreamPrint(LOG_STREAM_B, 0, "Message to B");
    infoStreamPrint(LOG_STREAM_B, 0, "Close stream B\n=================");
infoStreamPrint(LOG_STREAM_A, 0, "Close stream A\n---------------------------");
messageClose(STREAM_A);

together with xmltcp?

EDITED

[Karim Adbdelhak]

Replying to AnHeuermann:

@sjoelund What exactly is the problem here?

Is it not possible to do

a) Any different log inside a indented message

or

b) Start a new indented message inside a indented message

I actually am pretty confident that both should not pose a problem. In theory at least...

[Andreas Heuermann]

Without -logFormat=xmltcp both cases work. But for tcp I assume that a bunch of messages like

<message stream="LOG_INIT_HOMOTOPY" type="info" text="homotopy process
---------------------------">
<message stream="LOG_INIT_HOMOTOPY" type="info" text="homotopy parameter lambda = 0" />
<message stream="LOG_NLS" type="info" text="############ Solve nonlinear system 4 at time 0 ############">
<message stream="LOG_NLS" type="info" text="initial variable values:">
<message stream="LOG_NLS" type="info" text="[ 1]                              x  =                0		 nom =                1" />
</message>

will be send. If the XML is not correct it is apparently not working.

I implemented a workaround for this, see ​PR #964.

[Martin Sjölund]

That XML is wrong. You are missing some </message> from either LOG_INIT or LOG_NLS.

[Andreas Heuermann]

Okay, searching a bit for why the xml is invalid. As @sjoeliund noticed the generated xml is missing an </message>. The reason for this is, that the indention is started with

infoStreamPrint(LOG_INIT_HOMOTOPY, 1, "homotopy process\n---------------------------");

​Line 296 initialization.c
and the corresponding

messageClose(LOG_INIT_HOMOTOPY);

​Line 329 initialization.c
will never be reached to close to message due to an assert thrown.

So we need to catch the error, close the message and re-throw.
I guess we have those kind of errors in various locations of our code, but they are very hard to find.

Added PR ​https://github.com/OpenModelica/OpenModelica/pull/6814.

[Andreas Heuermann]

Resolved with ​fd748b6.

I can now simulate M2 in OMEdit and see the error log.
@francesco If you encounter this problem again or it is not solved for you (with the next nightly build) please reopen this ticket.

[Francesco Casella]

Excellent, thank you very much for the fix!

[Francesco Casella]

I am currently working on large power grid models for my presentation at the Workshop in February. I have some test cases that work fine, but for which the lambda0-phase of initialization takes too long a time. I'd like to investigate why, but LOG_NLS and LOG_NLS_V do not report any information, not even if running the test from a script.

I cannot post the code here because it is not yet public, but I'll send you the test case privately by email.

Help would be highly appreciated, particularly in view of the forthcoming Workshop.

[Andreas Heuermann]

For initialization we should have a system for lambda=0 which get's called before the first homotopy step.

For your example nothing is reported because the function ScalableTestGrids_GridModelGenerators_Type1Sample_N_2_functionInitialEquations_lambda0 does literally nothing. It's empty.

int ScalableTestGrids_GridModelGenerators_Type1Sample_N_2_functionInitialEquations_lambda0(DATA *data, threadData_t *threadData)
{
  TRACE_PUSH

  data->simulationInfo->discreteCall = 1;
  data->simulationInfo->discreteCall = 0;
  
  TRACE_POP
  return 0;
}

When I dump the SimCode I can see there are no equations in SimCode.initialEquations_lambda0.

When debugging a bit more I found something that is most likely the cause:
In ​Initialization.mo#L262 we fail during the call of BackendDAEUtil.postOptimizeDAE.

So the problem is unrelated to logging but a backend problem. I'll open a new ticket for this.

[Andreas Heuermann]

We'll continue the discussion in #6338.

Closing this ticket again.