Question, how should "Log()" behave in the scripts?

[Taomyn]

EDDI version in which issue is found

3.5.2 and earlier

VoiceAttack version in which issue is found (as applicable)

n/a

Steps to reproduce

1. Add "Log()" to speech responder script
2. Monitor the EDDI log file

Expected

Logged data should be logged at the same points where the script is currently happening, with date/time of when it happened. If I place two "Log()" with a pauses of a total 7sec, I would expect each log entry to be 7 seconds apart

Observed

All the logged data comes out at the same moment at the start of the script regardless of what part of the script is currently running, all with the same date/time even when there are large pauses/waits

Investigation

Perhaps this is intended behaviour but it confused the heck out of me for a while. I'm debugging the FSD Engaged speech responder script by adding some logging lines and an extra pause. When I look at the log the date/time stamps for every "Log()" is the same and are all generated at the same time when monitored live - so it's not that the wrong date/time is logged they actually all appear in the log at the same time. Makes trying to check the timing of when to do things in a script a bit more difficult.

I add some lines:

{set departsystem to lastsystem.name}
{Log("Leaving")}
{Log(departsystem)}

    {_ Wait for the FSD countdown and initial jump}
    {Pause(5000)} Pause 5000.

    {OneOf("Destination confirmed","Jump in progress","Telemetry obtained")}.
    {ShipName()} is {OneOf("heading to", "on route to", "travelling to", "in transit to")} the {P(reportsystem.name)} system.

{Pause(2000)} Pause 2000.
{set arrivalsystem to system.name}
{Log("Arriving")}
{Log(arrivalsystem)}

I see the following when tailing the log:

2020-01-15T19:31:06 [Info] SpeechResponder:.ctor Initialized Speech responder 
2020-01-15T19:31:07 [Info] ScriptResolver:buildStore Leaving 
2020-01-15T19:31:07 [Info] ScriptResolver:buildStore Qieduia VY-Y d1-24 
2020-01-15T19:31:07 [Info] ScriptResolver:buildStore Arriving 
2020-01-15T19:31:07 [Info] ScriptResolver:buildStore Qieduia ZE-A g1

[richardbuckle]

Thanks for the report! This is an interesting one. This is by design, and I should also note that the log is intended as a debugging and diagnostic tool rather than user-oriented.

As things stand, the script is compiled, at which point all custom functions in it, including Log() are run immediately, producing the output you are seeing, then the text output is fed to the text-to-speech engine for async processing. Any Pause() commands etc are handled asyncronously by the text-to-speech engine.

Given your description, it looks like enabling the speechresponder.out file and viewing it in Notepad++ with the "tail" option might better suit your needs.

[richardbuckle]

[Tkael]

I think the Log() function is working as designed and as @richardbuckle described above. The parser resolved the script (including logging the requested data) then passed it to the speech synthesizer. The speech synthesizer just works much slower than the parser. ;-)

Though I think I know how we could revise the program to respect pauses and other vocalizations when logging, I'm not certain there is much utility in doing so.

[Taomyn]

Thank you @richardbuckle and @Tkael for the explanation, which makes sense. I suspected there was some kind of reason for the behaviour hence why I reported it as a question.

I will try the speechresponder.out option to see if that helps me when I debug my scripts.

[richardbuckle]

I think we can call this closed.