Handling exceptions when applications do not report errors but time out in stateful transitions - #868
Conversation
…to agreement with SWIT as to where to host these configs)
…M timeouts and death on FSM, REQUIRES TESTING
|
…to be propagated down to the actual failing app level
|
|
Integration tests passed on |
|
Duplicate code is present in develop between |
|
@emmuhamm should be good to go |
|
Note that for the review process, this PR and the dependency is up to date with develop as of today's (23 july) nightly. A few changes that were implemented are porting over some of the new functionality that now exists in develop (particularly about how all lines should have stripped_ansi now) and minor changes to get some of the other tests working. Including increasing the widths of the table. as well as changing the column names. I'll proceed to give comments, but this may come in bits and pieces |
emmuhamm
left a comment
There was a problem hiding this comment.
Review 1/?
Ran out of bandwidth for now but this should be most of my comments for the testing side of things.
Pretty minor comments for this PR, some could be defferred for a bigger issue. Importantly, all the tests run just fine
| pytestmark = pytest.mark.skipif( | ||
| drunc_missing, | ||
| reason="drunc is not present in DUNEDAQ_DB_PATH, skipping drunc integration tests", | ||
| ) |
There was a problem hiding this comment.
This error message should also say how to fix this. (this applied to all the files)
There was a problem hiding this comment.
This is a good point to raise. However, the way in which the configuration file is packaged for retrieval by the integration tests defined within python-only DD repos is still under discussion. Please leave this unresolved so this can be addressed ASAP.
| drunc_missing = not any( | ||
| "drunc" == segment for path in db_path_env.split(":") for segment in path.split("/") | ||
| ) |
There was a problem hiding this comment.
For posterity: why is this necessary?
There was a problem hiding this comment.
This is the way to check if drunc is included as part of the DUNEDAQ_DB_PATH env var, so that the path to the configuration file can actually be matched (and the session can be run). This need to be explicitly stated as equality, as initial implementations matched this for druncschema, which did caused failure of the integration tests (the session wouldn't run as it wouldn't find the config, and would just print a stack of errors)
There was a problem hiding this comment.
This makes sense, thanks. Can this be added in the comment / error message then?
Mainly that this is one of the checks that the tests actually perform, and when I saw it fail I wasn't sure initially why we had this check in the first place just from reading the code. Will be useful in the future when other people develop drunc and encounter this failing.
Also, I wonder if the comments / error message should also say how this is fixed? eg
export DUNEDAQ_DB_PATH=$PWD:$DUNEDAQ_DB_PATH. Mainly cuz this appears to be a 'user configuration issue' when installing drunc rather than a genuine 'uh oh my development caused drunc to break' thing
| except FileNotFoundError: | ||
| print(f"Error: {file} not found.") | ||
| return False |
There was a problem hiding this comment.
Do we want to return false here or throw? Feels like in a testing environment if we cant find the file it should throw
There was a problem hiding this comment.
This should be left as a boolean return, mainly for cleaner output. The way that the test is currently structured is on a query base, where we check whether the line exists, and if it does not, then we return. Both can achieve the same functionaltiy, but I think this is cleaner. Should this fail in the future, when running with pytest -s (-s allows seeing the print statements in the tests), the error will be a one line solution, rather than a stacktrace.
| _PS_COLUMNS = ["session", "friendly_name", "user", "host", "uuid", "alive", "exit_code"] | ||
| _STATUS_COLUMNS = [ | ||
| "name", | ||
| "info", | ||
| "state", | ||
| "substate", | ||
| "in_error", | ||
| "included", | ||
| "endpoint", | ||
| ] | ||
| _EXEC_REPORT_COLUMNS = ["name", "command_execution", "fsm_transition"] |
There was a problem hiding this comment.
After the big developments of this tests, im starrting to think we should improve this part. Specifically, the columns themselves are called in the tests 'eg check if [substate] exists'
We should definitely strive to improve this, but this is beyond the scope of this PR.
If you agree, can convert this to an issue?
There was a problem hiding this comment.
Sorry the question here is unclear to me, what would you propose changing with these variables?
| #! Replace this with a generic one | ||
| def get_rows_by_friendly_name_from_ps_table( | ||
| ps_table: list[dict[str, str]], friendly_name: str | ||
| ) -> list[dict[str, str]]: | ||
| """Return all rows whose `friendly_name` matches exactly after stripping.""" | ||
| return [row for row in ps_table if row["friendly_name"].strip() == friendly_name] | ||
|
|
||
|
|
||
| def get_rows_by_name_from_status_table( | ||
| status_table: list[dict[str, str]], name: str | ||
| ) -> list[dict[str, str]]: | ||
| """Return all rows whose `Name` matches exactly after stripping.""" | ||
| return [row for row in status_table if row["name"].strip() == name] | ||
|
|
There was a problem hiding this comment.
The two functions are nearly identical. Suggest
def get_rows_by_name_from_table(table: list[dict[str,str]], name:str, row_name : str) -> list:
return [row for row in table if row[row_name].strip() == name]Would this be easy to implement? If not, happy to fold this into the issue i mentioned above about the columns
There was a problem hiding this comment.
The issue is that the ps table lists the process name as friendly_name, and the status table lists the process name as name. I think we could do this, but this should be a separate PR, including changing the actual ps table process name to just name and not friendly_name
|
Thanks @emmuhamm I will look tomorrow |
Co-authored-by: Emir Muhammad <49058518+emmuhamm@users.noreply.github.com>
PawelPlesniak
left a comment
There was a problem hiding this comment.
Sorry, for some reason parts of these comments were just comment replies, others were a second review.
| _PS_COLUMNS = ["session", "friendly_name", "user", "host", "uuid", "alive", "exit_code"] | ||
| _STATUS_COLUMNS = [ | ||
| "name", | ||
| "info", | ||
| "state", | ||
| "substate", | ||
| "in_error", | ||
| "included", | ||
| "endpoint", | ||
| ] | ||
| _EXEC_REPORT_COLUMNS = ["name", "command_execution", "fsm_transition"] |
There was a problem hiding this comment.
Sorry the question here is unclear to me, what would you propose changing with these variables?
| #! Replace this with a generic one | ||
| def get_rows_by_friendly_name_from_ps_table( | ||
| ps_table: list[dict[str, str]], friendly_name: str | ||
| ) -> list[dict[str, str]]: | ||
| """Return all rows whose `friendly_name` matches exactly after stripping.""" | ||
| return [row for row in ps_table if row["friendly_name"].strip() == friendly_name] | ||
|
|
||
|
|
||
| def get_rows_by_name_from_status_table( | ||
| status_table: list[dict[str, str]], name: str | ||
| ) -> list[dict[str, str]]: | ||
| """Return all rows whose `Name` matches exactly after stripping.""" | ||
| return [row for row in status_table if row["name"].strip() == name] | ||
|
|
There was a problem hiding this comment.
The issue is that the ps table lists the process name as friendly_name, and the status table lists the process name as name. I think we could do this, but this should be a separate PR, including changing the actual ps table process name to just name and not friendly_name
| except FileNotFoundError: | ||
| print(f"Error: {file} not found.") | ||
| return False |
There was a problem hiding this comment.
This should be left as a boolean return, mainly for cleaner output. The way that the test is currently structured is on a query base, where we check whether the line exists, and if it does not, then we return. Both can achieve the same functionaltiy, but I think this is cleaner. Should this fail in the future, when running with pytest -s (-s allows seeing the print statements in the tests), the error will be a one line solution, rather than a stacktrace.
…lication times out
…ithub.com:DUNE-DAQ/drunc into PawelPlesniak/IncompleteStatefulCommandTransition
| log = get_logger("unified_shell.log_on_server") | ||
| log.debug("Logging message to server(s)...") | ||
|
|
||
| if target_server in ["", "process_manager"]: |
There was a problem hiding this comment.
log --target-server df-controller "hello3"
I would expect this to send a hello3 to the 'df-controller' server. But this doesnt work.
Maybe a smarter system that can distribute it?
(Maybe beyond the scope of this PR but useful to think about)
| def log_on_server( | ||
| self, | ||
| text: str, | ||
| severity: str = "INFO", | ||
| target: str = "", | ||
| execute_along_path: bool = False, | ||
| execute_on_all_subsequent_children_in_path: bool = True, | ||
| ) -> LogOnServerResponse: |
| flag=ResponseFlag.EXECUTED_SUCCESSFULLY, | ||
| ) | ||
|
|
||
| def log_on_server( |
| execute_on_all_subsequent_children_in_path: bool, | ||
| extended: bool, | ||
| ) -> None: | ||
| obj.log.warning(f"Getting status for target '{target}'...") |
emmuhamm
left a comment
There was a problem hiding this comment.
Review 3/?
Just a quick set of review again to keep the ball rolling. Not sure if GitHub tracks which files I've viewed and which I haven't that you can see but I've gone through a significant chunk of the code now :)
| # Original author: KAB, 10-Oct-2023 | ||
|
|
||
| integtest_list=( "process_manager_test.py" "controller_test.py" ) | ||
| integtest_list=( "process_manager_test.py" "controller_test.py" "test_failure_mode_death_on_boot_nest_app.py" "test_failure_mode_death_on_boot_top_app.py" "test_failure_mode_death_post_boot_nest_app.py" "test_failure_mode_death_post_boot_top_app.py" "test_failure_mode_fsm_cmd_timeout_nest_app.py" "test_failure_mode_fsm_cmd_death_nest_app.py") |
There was a problem hiding this comment.
Minor comment but we should standardise how we name these tests.
eg. the pm and controller is *_test.py, whereas these failure modes are test_*.py. I don't mind which of these choices we go for either way, but I think we should definitely standardise them
| # The following line is outdated, but in the future when error states and their | ||
| # recovery are better defined, we can provide better options to the user. |
There was a problem hiding this comment.
Can you say a few words on why this is outdated?
emmuhamm
left a comment
There was a problem hiding this comment.
Review 3/?
Currently at 30/43 viewed now :)
In the description somewhere, please mention that send_msg is now superseded by the new log message
|
|
||
| def count_processes_in_status_response(response: StatusResponse) -> int: | ||
| """ | ||
| Count the number of processes in the status table, including all children. |
There was a problem hiding this comment.
Minor comment but should add 'Recursively' somewhere here in the desc
| put_in_error_state: bool = False | ||
|
|
||
| # If the session applications are not found on the connectivity serivce, then the | ||
| # session is not booted correctly. This is a critical error, the user should be |
There was a problem hiding this comment.
Should an error be sent over ERS as well?
|
|
||
| # Local connectivity serivces are not reported in the status table, but they should | ||
| # be. Increment the status_process_count by 1 if using the LCS. | ||
| # TODO: Remove this once the LCS is reported in the status table (issue 745). |
There was a problem hiding this comment.
Make sure you link this in the relevant issue as well so it doesn't get lost
|
|
||
| if ps_process_count != status_process_count: | ||
| # time.sleep(1) | ||
| log.debug( # TODO - once issue 793 is resolved, this should be a log.error |
There was a problem hiding this comment.
Make sure you link this in the relevant issue as well so it doesn't get lost
| "failure." | ||
| ) | ||
| # TODO: Uncomment this once the cause of inconsistent status table printing is | ||
| # understood (issue 793) |
There was a problem hiding this comment.
Make sure you link this in the relevant issue as well so it doesn't get lost
|
|
||
| dead_process_count = expected_booted_processes - alive_process_count | ||
| if dead_process_count > 0: | ||
| time.sleep(1) |
| # successful and we can return, otherwise, we will log the error and place the | ||
| # session in an error state if required. | ||
| in_error_state = obj.get_driver("controller").status().status.in_error | ||
| if not in_error_state and not put_in_error_state: |
There was a problem hiding this comment.
why the need for two 'in error state' flags? From a cursory look they can be combined?
eg in the line above something like
put_in_error_state = (put_in_error_state or obj.get_driver("controller").status().status.in_error)There was a problem hiding this comment.
My issues:
- the logic gets a bit messy below this line, not entirely sure how the two states are different and disentangled. Might be best to try and rewrite the logic below to prevent the need for two in the first place
- If the logic has to remain as such with the two different error flags, the names of the flags should be changed. Just from reading the name its not entirely clear why we have an 'in error state' and a 'put in error state'. A hint on the origin might come in handy for later debugging. Eg 'why do we need to have it be put in error state? shouldn't it be already in an error state anyway?'
|
|
||
| # Keep track of whether the session uses a local connectivity service | ||
| ctx.obj.session_uses_local_connectivity_service = ( | ||
| session_dal.connectivity_service.host == "localhost" |
There was a problem hiding this comment.
Can you quickly verify that if this logic holds? Remember that in the PMaaS work we've done theres quite a lot of remapping localhost to whatever the actual hostname is.
It might be better to check for another way instead of checking via the connectivity_service.host?
| # Determine the path to the test configurations | ||
| cwd = Path(os.path.abspath(__file__)) | ||
| test_configs = cwd.parent / ".." / "config" / "tests" | ||
| test_configs = cwd.parent / ".." / "config" / "drunc" |
There was a problem hiding this comment.
For posterity, why the change?
emmuhamm
left a comment
There was a problem hiding this comment.
Review 4/4
I think that should cover all the files so far.
Thanks for all of this very nice work, last time I checked it performed all the functionality that was desired so this is great!
The comments are mostly in the view of maintainability and clarity I think, rather than any fundamental functionality changes. Let me know if you have any questions and we can chat :)
Also let me know if this is ready for another round of review. Note that currently there are conflicts between this and develop.
| <info name="" type="" num-of-items="6" oks-format="data" oks-version="862f2957270" created-by="gjc" created-on="thinkpad" creation-time="20231207T105549" last-modified-by="eflumerf" last-modified-on="ironvirt9.IRONDOMAIN.local" last-modification-time="20241022T175827"/> | ||
|
|
||
| <include> | ||
| <!-- <file path="schema/confmodel/dunedaq.schema.xml"/> --> |
| <!-- Configs for apps timing out on FSM command execution --> | ||
| <obj class="Variable" id="drunc-ft-fsm-cmd-timeout"> | ||
| <attr name="name" type="string" val="DRUNC_FT_FSM_CMD_TIMEOUT"/> | ||
| <attr name="value" type="string" val="100"/> |
There was a problem hiding this comment.
If I understand right, this line is what sets how long the timeout is for the tests?
If so, I was wondering if it was prudent to make this number smaller? If not its just waiting for 100 seconds to pass for no reason? Or am I missing a reason on why it has to be this long?
| @@ -0,0 +1,205 @@ | |||
| """ | |||
| Run a session with a nested segment application dying at the start of boot. | |||
There was a problem hiding this comment.
Minor comment: it might be worth mentioning which app is the one dying, eg.
| Run a session with a nested segment application dying at the start of boot. | |
| Run a session with the nested segment application (ft-nested-segment-2-application) dying at the start of the boot |
L72 says dead_app_name = "ft-nested-segment-2-application", so good to tell the people which app youre killing. Especially important if we have to debug why this test fails in the future (like what we did some time ago :D )
Can you do this for all the tests?
Also maybe moving the dead_app_name up to the top of the file might help in maintenance later down the line as well.
| # Connectivity Service) | ||
| # conf_dict.connsvc_port = 12345 | ||
|
|
||
| # Collate tthe drunc config arguments into a dict to pass to the fixture |
There was a problem hiding this comment.
| # Collate tthe drunc config arguments into a dict to pass to the fixture | |
| # Collate the drunc config arguments into a dict to pass to the fixture |
| status | ||
| """.split() | ||
|
|
||
| dead_app_name = "ft-nested-segment-2-application" |
There was a problem hiding this comment.
See the above comment I made about moving this up to the top of the file
| def log(self, msg: str) -> None: | ||
| # simulate sending a message; tests don't assert on this, so store it | ||
| self._last_sent_msg = msg | ||
|
|
||
| def log_on_server(self, msg: str) -> None: |
There was a problem hiding this comment.
Can you also specify in the description of this PR what log and log_on_server do, and how they differ?
| import requests | ||
| from flask import Flask, Response, request | ||
| from flask_restful import Api, Resource | ||
| from werkzeug.serving import make_server |
There was a problem hiding this comment.
Ooh new package! Primarily a curiosity question, but what does werkzeug do? Does it come natively installed or do we have to include this in the dependency?
| # Set up logging | ||
| get_root_logger("info") | ||
| log = get_logger("fake_daqapp_rest", rich_handler=True) | ||
| log = get_logger("fake_daqapp_rest", stream_handlers=True) |
There was a problem hiding this comment.
Why the change from rich to stream? Im guessing its for easier log parsing but for posterity
| get_root_logger("info") | ||
| log = get_logger("fake_daqapp_rest", rich_handler=True) | ||
| log = get_logger("fake_daqapp_rest", stream_handlers=True) | ||
| log.setLevel("INFO") |
There was a problem hiding this comment.
Whats the purpose of this line? I thought that get_logger by default sets it up as INFO? Or alternatively, cant you set the log level in get_logger directly?
| self.state = "INITIAL" | ||
| self.executing_command = False | ||
| self.log = get_logger("fake_daqapp_rest.AppState") | ||
| self.log.setLevel("INFO") |
There was a problem hiding this comment.
Same comment here, why setLevel?

Description
Fixes #803
Fixes #869
Fixes #911
If a segment does not reach the target state, it is marked as in error, and the timeout is logged in the relevant server.
Also defines a set of configurations constructed to fail, and defines a set of unit tests to demonstrate this behaviour.
Error recovery with the supervisor will address what happens if an application completes this outside of the designated window. This is defined in #840
Type of change
List of required branches from other repositories
Requires DUNE-DAQ/druncschema#87
Change log
Addressed issues
Now when an application does not complete its transition in the allocated timeout, the session is put into an error state.
Defines a new click command
logthat allows the user to send a message to the relevant controller or process manager to put into their log file with a selectable severity level.Other new features
When running in batch mode, the user can start the run with
--no-stop-error-batch-mode. Should an error state be encountered, the session is not terminated, and commands can continue to be executed. This is primarily intended for use with integration tests, such that we can inspect thepsandstatustables.Integration tests for failure modes
Defines a set of intentionally failing configurations in
config/tests/failure-testing.data.xml, which contain configurations with a set offake-daq-apps that fail at configurable points in the session lifecycle. These configurations areft-death-on-boot-nest-app- this kills a nested application (2 segments deep) onboot.ft-death-on-boot-top-app- this kills the top application onboot.ft-death-post-boot-nest-app- this kills a nested application (2 segments deep) afterboot, before applications are marked as ready.ft-death-post-boot-top-app- this kills the top application afterboot, before applications are marked as ready.ft-fsm-cmd-timeout-nest-app- this times out an FSM transition on a nested application.ft-fsm-cmd-timeout-top-app- this times out an FSM transition on the top application.ft-fsm-cmd-death-nest-app- this kills a nested fake daq app during a FSM transition.ft-fsm-cmd-death-top-app- this kills the top fake daq app during a FSM transition.The differences between the
on-bootandpost-bootare useful to see, as thepost-bootconfigs allow the applications that die to register themselves on the connectivity service before dying, hence there is different behaviour.The differences between the
nest-appandtop-appallow the user to visualize the effect of a nested hierarchy on the control tree, and how the releveant children applications register themselves to the segment parents. The user shoudl expect to see the majority of the apps in the status table onbootwhen using anestconfig, and only the top two apps when using thetopconfig.Note that these configurations use the
FSMconfiguration_noActionstate machine, and will not behave fulliy in the standard way. An example includes not being able to reach the running state as there is no run number allocated, which will be reported as a genericgRPCerror.These tests have been integrated into the unit test framework, which can be executed as (from the local
druncroot)It is recommended for the tester to use
--integtest-verbosity 5to see what is happening during the process, and if more details are wanted from thepytestside, the user can run the tests aspytest -sto show what would be printed.Suggested manual testing checklist
Run each of the integration tests as defined above.
Developer checklist
Prior to marking this as "Ready for Review"
Tests ran on:
np04-srv-029from releaseNFD_DEV_260709_A9.Unit tests - some tests can't be ran on the CI. This is documented. If this PR checks a feature that can't be tested with CI, this has been marked appropriately.
Integration tests - the
daqsystemtest_integtest_bundlerequires a lot of resources, and connections to the EHN1 infrastructure. Check the cross referenced list if you can't run these. The developer needs to run at least the .pytest --marker) passeddaqsystemtest_integtest_bundle.sh -k minimal_system_quick_test.pydaqsystemtest_integtest_bundle.shFinal checklist prior to marking this as "Ready for Review"
Reviewer checklist
druncare in the log filesdruncfailure appears:Once the features are validated and both the unit and integration tests pass, the PRs is ready to be merged.
Choose one of the following an complete all substepsPrior to merging
Once completed, the reviewer can merge the PR.
Notification message for a Slack channel
Note - this should be to #dunedaq-integration for general workflow that isn't during a release candidate period, and to #daq-release-prep otherwise.
For an single merge that changes the user workflow
For co-ordinated merge