In the short period of time it takes for us to get organised/draining mavlink connections, the ArduPilot process might block writing to the primary mavlink connection - in which case we'll never get the message we requested.
Should solve
2022-08-31T23:17:43.6904119Z AT-0227.6: waiting for a message - any message....
2022-08-31T23:17:43.6904958Z AT-0227.6: Received (ATTITUDE {time_boot_ms : 3146, roll : 0.00013471684360411018, pitch : -4.076504410477355e-05, yaw : -2.1274349689483643, rollspeed : 6.679168291157112e-05, pitchspeed : 3.297374496469274e-05, yawspeed : 9.125166684498254e-07})
2022-08-31T23:17:43.6905505Z AT-0227.6: Waiting for mission count of (3) from (1:1) to (243:250)
2022-08-31T23:17:43.6905909Z AT-0227.6: Asserted mission count (type=2) is 3 after 0.100000s
2022-08-31T23:17:43.6906252Z AT-0227.6: Get first item on new link
2022-08-31T23:17:43.6906620Z AT-0289.2: Received exception (Did not receive MISSION_ITEM_INT
2022-08-31T23:17:43.6907047Z Traceback (most recent call last):
2022-08-31T23:17:43.6907386Z File "/__w/ardupilot/ardupilot/Tools/autotest/rover.py", line 3067, in test_rally
2022-08-31T23:17:43.6907719Z m2 = self.get_mission_item_int_on_link(
2022-08-31T23:17:43.6908080Z File "/__w/ardupilot/ardupilot/Tools/autotest/rover.py", line 2288, in get_mission_item_int_on_link
2022-08-31T23:17:43.6908469Z raise NotAchievedException("Did not receive MISSION_ITEM_INT")
2022-08-31T23:17:43.6908841Z common.NotAchievedException: Did not receive MISSION_ITEM_INT
2022-08-31T23:17:43.6909118Z )
2022-08-31T23:17:43.6909468Z AT-0289.2: Exception caught: Did not receive MISSION_ITEM_INT
This has been unused for a long time, and is getting in the way of reforms. Its position as a test rather than as a part of a framework was always going to cause oddities, particularly after we split the Copter tests into several chunks.
We had a pattern emerging of using the test name as the method name to contain the actual test. We also tended to duplicate the docstrings in the test description - or omit the docstring.
This uses reflection to retrieve both the test name and the description, meaning less duplication of this information and enforcing having docstrings on the test methods.
The stack trace is already extremely useful... but mapping back to the
relevant dataflash log is a bit of a pain.
Adding more stuff to this method in the future might be good, too.
This is important when running under Valgrind as the text can be
significantly delayed. wait_statustext times out in simulation time,
whereas mavproxy.expect has a flat 60s timeout
autotest: prevent method-on-undef problem in case of early test failure
autotest: plumb MAVProxy rc input back in for switch test
autotest: close off rc thread in case of timeout
Should fix this scenario:
- Plane soaring test uses different defaults file
- soaring test sets a parameter away from default value
- context pop sets it back to the value in the defaults file
- it is now in permanent storage with the default found in the
different defaults file used by the soaring test
- we finish running the soaring test an reset the SITL command line
back to default, with the old defaults file
- we go on to running the next test. At this point the value for that
parameter is the default in the defaults file used by the soaring test.
Something similar applies in the Callisto test.
# avoid a timeout race condition where ArduPilot re-requests a
# fence point before we receive and respond to the first one.
# Since ArduPilot has a 1s timeout on re-requesting, This only
# requires a round-trip delay of 1/speedup seconds to trigger
# - and that has been seen in practise on Travis
AT-0417.0: Sending item with seq=0
AT-0417.2: Got (MISSION_REQUEST {target_system : 243, target_component : 250, seq : 0, mission_type : 1})
AT-0417.2: Got (MISSION_REQUEST {target_system : 243, target_component : 250, seq : 0, mission_type : 1})
AT-0417.2: Exception caught: Traceback (most recent call last):
File "/home/travis/build/ArduPilot/ardupilot/Tools/autotest/common.py", line 3950, in run_one_test
test_function()
File "/home/travis/build/ArduPilot/ardupilot/Tools/autotest/rover.py", line 4216, in test_poly_fence
self.test_fence_upload_timeouts()
File "/home/travis/build/ArduPilot/ardupilot/Tools/autotest/rover.py", line 4057, in test_fence_upload_timeouts
target_component=target_component)
File "/home/travis/build/ArduPilot/ardupilot/Tools/autotest/rover.py", line 4010, in test_fence_upload_timeouts_2
self.expect_request_for_item(item)
File "/home/travis/build/ArduPilot/ardupilot/Tools/autotest/rover.py", line 3958, in expect_request_for_item
raise NotAchievedException("Expected request for seq=%u" % item.seq)
NotAchievedException: Expected request for seq=1
The "AT" timestamps there are wallclock time. Since speedup for Rover
is 8 by default, that could be as much as 1.6 seconds meaning a
re-request from ArduPilot would be legitimate.
I've added some debug, too - we now emit "Sending item with seq=1"
between those two "Got" lines. That should make the problem clearer -
we've received a re-request rather than a request for the item after the
one we've already sent.
On the assumption that ArduPilot processes mavlink packets
synchronously (or at least in order), after we have run a timesync
roundtrip we can reasonably expect any mavlink command we have sent
prior to the roundtrip to have been processed, and we should be able to
see the results in the mavlink stream.