Fix #5030 - C++ CLI: run.log is huge and missing the runner.registerWarning messages #5035

jmarrec · 2023-11-14T01:14:49Z

Pull request overview

Fixes C++ CLI: run.log is huge and missing the runner.registerWarning messages #5030
Addresses a bunch more issues that @shorowit reported after testing the installer of this PR (thanks a lot for the testing!)

Pull Request Author

Model API Changes / Additions
Any new or modified fields have been implemented in the EnergyPlus ForwardTranslator (and ReverseTranslator as appropriate)
Model API methods are tested (in src/model/test)
EnergyPlus ForwardTranslator Tests (in src/energyplus/Test)
If a new object or method, added a test in NREL/OpenStudio-resources: Add Link
If needed, added VersionTranslation rules for the objects (src/osversion/VersionTranslator.cpp)
Verified that C# bindings built fine on Windows, partial classes used as needed, etc.
All new and existing tests passes
If methods have been deprecated, update rest of code to use the new methods

Labels:

If change to an IDD file, add the label IDDChange
If breaking existing API, add the label APIChange
If deemed ready, add label Pull Request - Ready for CI so that CI builds your PR

Review Checklist

This will not be exhaustively relevant to every PR.

Perform a Code Review on GitHub
Code Style, strip trailing whitespace, etc.
All related changes have been implemented: model changes, model tests, FT changes, FT tests, VersionTranslation, OS App
Labeling is ok
If defect, verify by running develop branch and reproducing defect, then running PR and reproducing fix
If feature, test running new feature, try creative ways to break it
CI status: all green or justified

jmarrec · 2023-11-14T01:17:48Z

src/cli/test/test_with_analysis.py

+    if not is_labs:
+        pytest.skip("classic (Ruby) CLI just ignored the top level --verbose flag for run.log")
+    assert 50 < len(run_log.splitlines()) < 100


If you did openstudio --verbose run -w workflow.osw , would you expect the run.log to contain Debug log messages?

As a reminder, we have ALL these ways of callling the CLI

openstudio --verbose ... openstudio run --debug ... openstudio run -w workflow.osw with workflow.osw having "run_options" > debug in there # Labs only openstudio --loglevel Debug ...

Follow up question: knowing that the Ruby CLI just didn’t set the run.log to Debug in that case (it only cares about run --debug ), would you:

A) Use the historical behavior.

B) Change it to respect the top level log level flag.

if --debug is passed, it will increase the log level to Debug if not already, but for openstudio --loglevel Trace run --debug -w in.osw , the Log Level for stdout and run.log would stay at Trace)

If this is going to be merged into our imminent release, then I think we need to take option A and mirror the historical behavior (plus now the --loglevel option).

However, I think post release (and early in the cycle) we should make a change to remove the logging option under the run subcommand.

@brianlball @shorowit @joseph-robertson @DavidGoldwasser

jmarrec · 2023-11-14T01:18:54Z

src/measure/OSRunner.hpp

+    /** Whether registerInfo, registerWarning, registerError, registerInitialCondition, registerFinalCondition and registerAsNotApplicable
+      * also LOG an actual message */
+    bool registerMsgAlsoLogs() const;
+    void setRegisterMsgAlsoLogs(bool registerMsgAlsoLogs);


I feel like option like this is just punting on making a decision. I think I would prefer that we just make a call one way or the other and avoid giving an option like this.

Until we remove the Ruby CLI (classic), we need an option, otherwise if always enabled, it'll log TWICE int he ruby cli

jmarrec · 2023-11-14T01:19:05Z

src/workflow/OSWorkflow.cpp

@@ -78,6 +80,8 @@ OSWorkflow::OSWorkflow(const WorkflowRunOptions& t_workflowRunOptions, ScriptEng
    m_add_timings(t_workflowRunOptions.add_timings),
    m_style_stdout(t_workflowRunOptions.style_stdout) {

+  runner.setRegisterMsgAlsoLogs(true);


To mimic https://github.com/NREL/OpenStudio-workflow-gem/blob/696306b5b24cd597edc6ab04faa1e618f99db190/lib/openstudio/workflow_runner.rb#L189-L217

…kflow-gem) is really needed.

…rkflow_runner.rb used to do

…ow log level ``` openstudio --verbose openstudio --loglevel Debug openstudio run --debug ... openstudio run -w workflow.osw with workflow.osw having “run_options” > debug in there ```

… consideration for run.log

@shorowit

Address some of @shorowit's reports: * Remove debug print for numArs * stdout-energyplus is a one-liner on windows * EnergyPlus <status> is printed twice (one by E+, one by us after parsing), so alter message

@shorowit

…`No valid weather file defined in either the osm or osw.` > The old CLI always used to print warnings (e.g., `[17:21:45.141997 WARN] No valid weather file defined in either the osm or osw.`) to stdout, though I don't know if that's important. Just pointing it out as a difference. Some users might expect that behavior? Reported by @shorowit

…amples is installed, and I don't want these tests

@shorowit

…code=1 @shorowit reported: > One of our unit tests is failing because the OS CLI is returning an exit code of 0 instead of 1 for a case where a reporting measure returns false.

ci-commercialbuildings · 2023-11-15T14:31:59Z

CI Results for 87db4fb:

Ubuntu 20.04:
Ubuntu 22.04:
- OpenStudio-3.7.0-rc2+87db4fb768-Ubuntu-22.04-x86_64.deb
- OpenStudio-3.7.0-rc2+87db4fb768-Ubuntu-22.04-x86_64.tar.gz
Darwin:
- OpenStudio-3.7.0-rc2+87db4fb768-Darwin-x86_64.dmg
- OpenStudio-3.7.0-rc2+87db4fb768-Darwin-x86_64.tar.gz
Windows:
- OpenStudio-3.7.0-rc2+87db4fb768-Windows.exe
- OpenStudio-3.7.0-rc2+87db4fb768-Windows.tar.gz
Code Coverage:

kbenne

It seems like this need to merge before release, but after release I think we should gather togethor and talk about the big picture of logging. Perhaps a wiki document or something to outline the design of logging in OpenStudio CLI and Workflow would be helpful. It is getting hard for me to track the options and I'm guessing I'm not the only one.

brianlball · 2023-11-15T16:42:01Z

yeah, it would also be good to do a quick study on the performance impact of logging. I've seen performance go to sh*t when there is too much logging going on, espically with runner.registerINFO etc

jmarrec added component - CLI Pull Request - Ready for CI This pull request if finalized and is ready for continuous integration verification prior to merge. labs labels Nov 14, 2023

jmarrec self-assigned this Nov 14, 2023

jmarrec requested a review from kbenne November 14, 2023 01:14

jmarrec commented Nov 14, 2023

View reviewed changes

jmarrec added 10 commits November 15, 2023 15:00

[ci skip] Leave a TODO to see if sanitizeKey (rename_hash_keys in wor…

3f8022a

…kflow-gem) is really needed.

#5030 - add testing for run.log (advanced pytest inside)

ab00964

#5030 - Make runner.registerWarning and co also LOG a message like wo…

a877336

…rkflow_runner.rb used to do

Clarify precedence of the way too many ways we have of setting workfl…

8130bbe

…ow log level ``` openstudio --verbose openstudio --loglevel Debug openstudio run --debug ... openstudio run -w workflow.osw with workflow.osw having “run_options” > debug in there ```

Seems like workflow-gem wasn't takingthe toplevel "--verbose" flag in…

5741642

… consideration for run.log

Address some new reported issues (see detailed message)

2dd34da

Address some of @shorowit's reports: * Remove debug print for numArs * stdout-energyplus is a one-liner on windows * EnergyPlus <status> is printed twice (one by E+, one by us after parsing), so alter message

Move the "Examples/with_analysis" under resources/workflow because Ex…

13ce020

…amples is installed, and I don't want these tests

Reorganize testing + add test for a measure with runner.registerError

fe7cb80

When reporting measure fails, let it continue, but still return exit_…

e13c0f6

…code=1 @shorowit reported: > One of our unit tests is failing because the OS CLI is returning an exit code of 0 instead of 1 for a case where a reporting measure returns false.

jmarrec force-pushed the 5030-logger_issues branch from 577789d to e13c0f6 Compare November 15, 2023 14:07

Silence the debug logs in ErrorFile, it's annoying.

87db4fb

kbenne approved these changes Nov 15, 2023

View reviewed changes

jmarrec merged commit dc35f3e into develop Nov 15, 2023
5 of 6 checks passed

jmarrec deleted the 5030-logger_issues branch November 15, 2023 17:11

jmarrec mentioned this pull request Nov 15, 2023

[refactor] Assess the Logger situation and eliminate inefficiency #5038

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix #5030 - C++ CLI: run.log is huge and missing the runner.registerWarning messages #5035

Fix #5030 - C++ CLI: run.log is huge and missing the runner.registerWarning messages #5035

jmarrec commented Nov 14, 2023 •

edited

Loading

jmarrec Nov 14, 2023

kbenne Nov 15, 2023 •

edited

Loading

jmarrec Nov 14, 2023

kbenne Nov 15, 2023

jmarrec Nov 15, 2023

kbenne Nov 15, 2023

jmarrec Nov 14, 2023

ci-commercialbuildings commented Nov 15, 2023 •

edited

Loading

kbenne left a comment

brianlball commented Nov 15, 2023

Fix #5030 - C++ CLI: run.log is huge and missing the runner.registerWarning messages #5035

Fix #5030 - C++ CLI: run.log is huge and missing the runner.registerWarning messages #5035

Conversation

jmarrec commented Nov 14, 2023 • edited Loading

Pull request overview

Pull Request Author

Review Checklist

jmarrec Nov 14, 2023

Choose a reason for hiding this comment

kbenne Nov 15, 2023 • edited Loading

Choose a reason for hiding this comment

jmarrec Nov 14, 2023

Choose a reason for hiding this comment

kbenne Nov 15, 2023

Choose a reason for hiding this comment

jmarrec Nov 15, 2023

Choose a reason for hiding this comment

kbenne Nov 15, 2023

Choose a reason for hiding this comment

jmarrec Nov 14, 2023

Choose a reason for hiding this comment

ci-commercialbuildings commented Nov 15, 2023 • edited Loading

kbenne left a comment

Choose a reason for hiding this comment

brianlball commented Nov 15, 2023

jmarrec commented Nov 14, 2023 •

edited

Loading

kbenne Nov 15, 2023 •

edited

Loading

ci-commercialbuildings commented Nov 15, 2023 •

edited

Loading