COM handling preventing (?) Prepar3D clean shutdown

[Luke Kolin]

I've implemented some LUA scripts to handle extended button reads, and I've noticed that P3D isn't shutting down properly at times. Looking at my logs, it appears that my Lua shutdown function is terminating abnormally.

I call event.cancel() and then com.close() but it looks like one is failing and then the script is getting terminated by FSUIPC. The changelog for 6.1 suggests that there are some changes in com handling. Am I doing things incorrectly? Is there a conflict with the new button handling post-6.0.12?

Cheers!

Luke

FSUIPC6.log cs7x7ap.lua

[John Dowson]

Hi Luke,

36 minutes ago, Luke Kolin said:

I call event.cancel() and then com.close() but it looks like one is failing and then the script is getting terminated by FSUIPC.

I'm not sure its failing - I think the com.close call is taking to long to finish and the script is being killed from the closing thread...

37 minutes ago, Luke Kolin said:

The changelog for 6.1 suggests that there are some changes in com handling.

Yes, there were some changes, but these were to increase some waits to give more time for the com threads to close down correctly.  Was it working in the previous FSUIPC6 release before these changes? If you don't know, could you try (I can give you the previous dll if needed).

Was that the complete log you posted? If so, then it does look like FSUIPC didn't shut-down correctly, which would prevent P3D from closing.

It could be killing the thread when its in com.close that is causing the issue. Try commenting-out the event.terminate call, and see if terminating the thread without this is more reliable.

[Luke Kolin]

That's the complete log. I'll try commenting out the event.cancel and add some additional logging details to see if it makes a difference, and report back.

Cheers!

[John Dowson]

3 minutes ago, Luke Kolin said:

That's the complete log. I'll try commenting out the event.cancel and add some additional logging details to see if it makes a difference, and report back.

Not sure that will do much as its the com.close thats the issue. As I said, first try commenting out the event.terminate (which will prevent the event.cancel and com.close being called).

[Luke Kolin]

So I changed the shutdown function to be this:

function HandleShutdown()

if (hidHandle ~= 0) then
  ipc.log("Shutting down USB device hnd=" .. hidHandle)
  com.close(hidHandle)
  ipc.log("USB Device disconnected")
  hidHandle = 0
  event.cancel("HID_Poll")
  ipc.log("Event canceled")
end

ipc.log("CS757/767 Button Handler shutdown")

end

So I'll close, log, then cancel. I didn't even get the log message:

    72484 -------------------- Starting everything now ----------------------
    72563 ASN active function link set
    72563 Ready for ActiveSky WX radar with additional data
    72563 LUA.1: USB Device Connected, hnd=1
    72563 LUA.1: Poll loop started
    72563 LUA.1: Registered CS757/767 Button Handler
    73641 Advanced Weather Interface Enabled
   103406 Sim stopped: average frame rate for last 39 secs = 34.8 fps
   103406    Max AI traffic was 5 aircraft
   103406 -------------------------------------------------------------------
   108984 === Closing session: waiting for DLLStop to be called ...
   119719 === DLLStop called ...
   119719 === Closing external processes we started ...
   120719 === About to kill any Lua plug-ins still running ...
   120719 LUA.1: Shutting down USB device hnd=1
   120875 Lua threads being terminated:
   120875       1 = "C:\Users\Luke\Documents\Prepar3D v4 Add-ons\FSUIPC6\cs7x7ap.lua"
   121172 **** DevCom read/write threads still running - will exit anyway but could cause issues...
   121313 LUA: "C:\Users\Luke\Documents\Prepar3D v4 Add-ons\FSUIPC6\cs7x7ap.lua": killed
   121766 **** DevCom read/write threads still running - will exit anyway but could cause issues...

... so I think you're correct about com.close() taking too long. Is there any possibility to increase the cleanup limit? 5ms seems awfully short.

Cheers

[John Dowson]

1 minute ago, Luke Kolin said:

... so I think you're correct about com.close() taking too long. Is there any possibility to increase the cleanup limit? 5ms seems awfully short.

Possibly. But please try first without closing down first - just comment out your event.terminate call.

[John Dowson]

You could also try increasing this parameter (with your event.terminate active):

Quote

TimeForLuaClosing=2 sets the time allowed for Lua plug-ins to close correctly before the FS is closed. The time starts
as soon as the event.terminate function has been called, assuming the plug-in uses it. The value in in seconds and can be
set from 1 to 20. A longer period might help those more complex plug-ins to tidy up properly
 

You can try increasing that....looks like this is maybe set to 1 in your ini (?), as from your log:

Quote

110968 === Closing external processes we started ...
111968 === About to kill any Lua plug-ins still running ...

Only a 1s difference between those messages....

Edited April 21, 2021 by John Dowson
Further info added

[Luke Kolin]

11 minutes ago, John Dowson said:

You could also try increasing this parameter (with your event.terminate active): You can try increasing that....looks like this is maybe set to 1 in your ini (?), as from your log: Only a 1s difference between those messages....

Interestingly, I checked my INI and the parameter was already there... set to 2.

I'll try again with the event.terimate removed.

Cheers

[John Dowson]

3 minutes ago, Luke Kolin said:

15 minutes ago, John Dowson said:

You could also try increasing this parameter (with your event.terminate active): You can try increasing that....looks like this is maybe set to 1 in your ini (?), as from your log: Only a 1s difference between those messages....

Interestingly, I checked my INI and the parameter was already there... set to 2.

Yes, interesting...

3 minutes ago, Luke Kolin said:

I'll try again with the event.terimate removed.

Ok. After you have done that, could you re-enable and change that parameter to something quite large, say 5 (seconds) to see if that makes a difference, and show me your log file afterwards (or the closing  extract) so I can see if that has any affect. If not, I will look into it....

[Luke Kolin]

Doesn't appear to make a difference. I've attached the full log/ini files, and here is the relevant function:

function HandleShutdown()

if (hidHandle ~= 0) then
  ipc.log("Shutting down USB device hnd=" .. hidHandle)
  com.close(hidHandle)
  ipc.log("USB Device disconnected")
  hidHandle = 0
  -- event.cancel("HID_Poll")
  -- ipc.log("Event canceled")
end

ipc.log("CS757/767 Button Handler shutdown")

end

You can say for sure, but my uninformed guess is that the com.close is throwing an error that isn't getting caught or logged.

I'll try again with the parameter set to 5.

Cheers

FSUIPC6.log FSUIPC6.ini

[Luke Kolin]

No change. Here's the log and INI.

Cheers

 

FSUIPC6.ini FSUIPC6.log

[John Dowson]

11 minutes ago, Luke Kolin said:

No change. Here's the log and INI.

Yes, looking at this now...

23 minutes ago, Luke Kolin said:

I'll try again with the event.terimate removed.

Did you try this?

[Luke Kolin]

Sorry, brain fart - I removed event.cancel(). I'll remove event.terminate as well.

Cheers

[Luke Kolin]

It definitely made a difference.  I got a warning, but the process terminated.

Cheers!

FSUIPC6.log

[John Dowson]

Just now, Luke Kolin said:

It definitely made a difference.  I got a warning, but the process terminated.

Yes, thats the new warning I added in 6.1. I would use this for now (i.e. no event.terminate), and I'll look into why that lua delay isn't working and get back to you.

[Luke Kolin]

OK. Thanks!

[John Dowson]

Could you temporarily re-enable your event.terminate and try the attached dll please (with TimeForLuaClosing=5 set), and show me the log file after closing: FSUIPC6.dll

[John Dowson]

and also please try this one (same ini settings): FSUIPC6.dll

I would like to see the logs for both dlls please....

[John Dowson]

and also try this one (and show me the log): FSUIPC6.dll

 

[Luke Kolin]

I tried the last plugin with TimeForLuaClosing=5, and got the following log. Do you want me to try the earlier ones as well?

Cheers!

FSUIPC6.log

[John Dowson]

11 hours ago, Luke Kolin said:

Do you want me to try the earlier ones as well?

No, not necessary. Please try the following instead: FSUIPC6.dll

[Luke Kolin]

4 hours ago, John Dowson said:

No, not necessary. Please try the following instead: FSUIPC6.dll

Looks clean now! Interestingly the com.close appears to take a while... I've enclosed the log and the shutdown function (I've changed the logic a bit as we've been working and can't remember if you've seen it).

function HandleShutdown()

if (hidHandle ~= 0) then
  ipc.log("Shutting down USB device hnd=" .. hidHandle)
  com.close(hidHandle)
  ipc.log("USB Device disconnected")
  hidHandle = 0
  event.cancel("HID_Poll")
  ipc.log("Event canceled")
end

ipc.log("CS757/767 Button Handler shutdown")

end

 

FSUIPC6.log

[John Dowson]

1 hour ago, Luke Kolin said:

Looks clean now! Interestingly the com.close appears to take a while...

Yes, but that maybe because you have TimeForLuaClosing=5 still set, which is the time betwwen these messages:
    90688 Waiting for lua threads to process termination event...
   ...
    95688 Lua threads being terminated:
The com.close is done hbetween these log messages:
    90688 LUA.1: Shutting down USB device hnd=1
    ...
    91328 LUA.1: USB Device disconnected
So is taking roughly 0.65 seconds. You can try reducing the  TimeForLuaClosing back to 2, or maybe even try 1. Also, for such issues, its also a good idea to enable logging for 'Extras', as this will then log the thread that is producing the message. Most shut-down issues are thread & timings related.

 

The thread is still being killed later though, which is a bit strange, but at least the com has closed so this isn't an issue. However, I did reduce another timing that may have caused this - I will increase again slightly when I release this.

Thanks for you help on this,

John

 

 

[Luke Kolin]

So I turned on a lot of debugging (which seemed to cause some latency and interesting race conditions) and I've attached the log. Note at the end, even after event.cancel it looks like LUA is still waiting on an event, and perhaps the cancel() isn't working?

Attaching log and LUA so you can see the line numbers.

Cheers

FSUIPC6.log cs7x7ap.lua

[John Dowson]

3 minutes ago, Luke Kolin said:

So I turned on a lot of debugging (which seemed to cause some latency and interesting race conditions) and I've attached the log. Note at the end, even after event.cancel it looks like LUA is still waiting on an event, and perhaps the cancel() isn't working?

Yes, if you debug it will increase the latency. But I'm not going to adjust for this - and it still closed down correctly anyway, so I don't see an issue.