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

[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!

[AnHeuermann]

Log of simulation of M1

[AnHeuermann]

Log of simulation of M2

[AnHeuermann]

Log simulation M3

[AnHeuermann]

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?

[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?

[adeas31]

@AnHeuermann can you share the mos script?

[adeas31]

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.

[adeas31]

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

[AnHeuermann]

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.

[AnHeuermann]

@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.Abdelhak]

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...

[AnHeuermann]

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.

[sjoelund.se]

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

[AnHeuermann]

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.

[AnHeuermann]

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.

[casella]

Excellent, thank you very much for the fix!

[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.

[AnHeuermann]

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.

[AnHeuermann]

We'll continue the discussion in #6338.

Closing this ticket again.