Fix Audioservice startup

[forslund]

Description

Handle ntp sync in audioservice ready wait. Events (and python threading in general) don't use monotonic time and can be affected by an ntp sync.

The log from @krisgesling shows the following

2020-04-01 17:24:12.190 | INFO     |   467 | __main__:main:50 | Starting Audio Services
2020-04-01 17:24:12.198 | INFO     |   467 | mycroft.messagebus.client.client:on_open:114 | Connected
2020-04-01 17:24:12.204 | INFO     |   467 | mycroft.audio.audioservice:get_services:61 | Loading services from /home/mycroft/mycroft-core/mycroft/audio/services/
2020-04-01 17:24:12.215 | INFO     |   467 | mycroft.audio.audioservice:load_services:105 | Loading chromecast
2020-09-02 02:02:49.463 | ERROR    |   467 | __main__:on_error:34 | Audio service failed to launch ('No audio services loaded').

Notice the timestamp difference on the two last entries. Between these the time jumped ~5 months which is longer than the 3 minute timeout on the wait. Likely (possibly/maybe) network connection was established during this time adjusting the time and thus ending the Event wait.

This adds logic to repeat the wait if the monotonic time don't agree with the event timeout.

How to test

It's sort of tricky to test in a good way. Firstly make sure the audioservice starts in normal circumstances (run the service, add a delay in loading services and make sure the result of the wait is as expected).

Secondly try to repeat the actual issue using the date command:

• inject a long sleep (time.sleep(300) on L204
• launch the audio service
• run sudo date +%T -s "HH:MM:SS" with a suitable clock time in the future

Make sure the service doesn't exit directly, but waits the expected 3 minutes before shutting down.

Contributor license agreement signed?

CLA [ ] (Whether you have signed a CLA - Contributor Licensing Agreement

[devops-mycroft]

Voight Kampff Integration Test Succeeded (Results)

[krisgesling]

Great work on figuring this out!

Have confirmed that switching the clock forward during loading of the audioservice causes the timeout to trigger and the service loading fails. Also confirmed the fix works as expected using the methods you suggested.

As discussed in chat, it looks like this also exists in the hotword factory so will wait for that before merging.

[devops-mycroft]

Voight Kampff Integration Test Succeeded (Results)

[forslund]

Updated PR with a refactor and handling of the wait in the hotword_factory.py as well as the one in audioservice

[krisgesling]

Working great, thanks again!!