Luke Kolin Posted April 21, 2021 Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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. Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 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! Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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). Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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. Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 (edited) 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 Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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.... Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 No change. Here's the log and INI. Cheers FSUIPC6.ini FSUIPC6.log Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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? Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 Sorry, brain fart - I removed event.cancel(). I'll remove event.terminate as well. Cheers Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 It definitely made a difference. I got a warning, but the process terminated. Cheers! FSUIPC6.log Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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. Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 OK. Thanks! Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 and also please try this one (same ini settings): FSUIPC6.dll I would like to see the logs for both dlls please.... Link to comment Share on other sites More sharing options...
John Dowson Posted April 21, 2021 Report Share Posted April 21, 2021 and also try this one (and show me the log): FSUIPC6.dll Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 21, 2021 Author Report Share Posted April 21, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 22, 2021 Report Share Posted April 22, 2021 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 Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 22, 2021 Author Report Share Posted April 22, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 22, 2021 Report Share Posted April 22, 2021 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 Link to comment Share on other sites More sharing options...
Luke Kolin Posted April 22, 2021 Author Report Share Posted April 22, 2021 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 Link to comment Share on other sites More sharing options...
John Dowson Posted April 22, 2021 Report Share Posted April 22, 2021 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. Link to comment Share on other sites More sharing options...
Recommended Posts
Create an account or sign in to comment
You need to be a member in order to leave a comment
Create an account
Sign up for a new account in our community. It's easy!
Register a new accountSign in
Already have an account? Sign in here.
Sign In Now