FSUIPC6 preventing P3Dv5 closing fully

[Scotfleiger]

Sorry I didn’t set the Extras value correctly. I will report again later. 

[Pete Dowson]

52 minutes ago, Scotfleiger said:

Test ran with 6.0.3d. Closed correctly. In a number of follow on tests, P3Dv5 crashed on shutdown. This occurred before [programs] started LINDA was terminated.

I don't fully understand what you are saying compared to what you've posted.

There are three logs. #1 and #3 shows a correct shutdown. #2 shows that the shutdown sequence hung on a TerminateThread call (something MS say is impossible!). TerminateThread is not supposed to block -- the thread is told to terminate and if you want to be sure it has you have to check later, which during termination of the sesion we don't.

So, at present I don't know where to go with that. It's something in Windows or its drivers and i wouldn't know how to get to the bottom of it even if we could reproduce it in debugging conditions.

I suppose we could just simple not bother to tidy up VRI device connections before closing. We might then have to "TerminateProcess" to close P3D after a timeout instead -- as ruthlessly as Task manager does. We will think about it and maybe supply another test when we have something different to try.

I agree with John, though, that this is not a change between FSUIPC5 and FSUIPC6.  Something else is going on.

But can you please explain more about "P3Dv5" crashed on shutdown. I have read quite a lot of reports now about P3Dv5 instability.  If you think this case was related to FSUIPC can you provide information of some sort -- the Event Viewer details of the crash, and the FSUIPC log to that point?

I'll probably not get back on this till later tomorrow.

Pete

 

 

[Scotfleiger]

I re-ran the tests with FSUIPC Logging Extras checkbox ticked. I achieved no hanging tasks. 603d closed fully.

To answer Pete's question about P3Dv5 crashing. I have no idea why this is happening. It is appears random with the dialog box reporting the crash. This appears before the P3D main window closes. Clicking on Debug offers no information.

Must go. Will come back later to finish my reply.

FSUIPC6_603d-Extras_1.log FSUIPC6-603d-Extras-2.log FSUIPC6-603d-extras-3.log

[Pete Dowson]

16 minutes ago, Scotfleiger said:

I re-ran the tests with FSUIPC Logging Extras checkbox ticked. I achieved no hanging tasks. 603d closed fully.

There's no difference in what is logged to the previous tests. These last three are identical to the two successful ones previously supplied (previous #1 and #2).

If you set "Debug=Please" in the [General] section of the FSUIPC6.INI file, the Logging Extras field turns into a data entry field which accepts a number. It is not a checkbox then! That's where we asked you to enter 8197 before closing the session. I think you must have done that as the logging does contain the extras we wanted.

16 minutes ago, Scotfleiger said:

To answer Pete's question about P3Dv5 crashing. I have no idea why this is happening. It is appears random with the dialog box reporting the crash. This appears before the P3D main window closes. Clicking on Debug offers no information.

I understand that. But on any Windows detected crash there will be crash information in the Windows Event Viewer! Have you never looked?  Please try it! In the left hand explorer-syle folder list select Windows logs then Application. Errors will have a red icon. Look for one mentioning Prepar3D.exe.  When selected you can copy and paste the information displayed below.

And i also wanted to see the FSUIPC log for that crashed session, just to see how far it got!

Honestly, there's no point in reporting crashes without supplying whatever information there is.

Pete

 

[Scotfleiger]

Hi Pete

My apologies for having to leave earlier. Thank you for reminding me about the event viewer. As a Mac user I don't normally see crashes!

When P3Dv5 crashes on exit it is a .NET runtime error (1926):

Application: Prepar3D.exe
Framework Version: v4.0.30319
Description: The process was terminated due to an unhandled exception.
Exception Info: exception code c0000005, exception address 00007FFD306C7056

Followed by an application error (1000):

Faulting application name: Prepar3D.exe, version: 5.0.21.34709, time stamp: 0x5e95060d
Faulting module name: ntdll.dll, version: 10.0.18362.778, time stamp: 0x0c1bb301
Exception code: 0xc0000005
Fault offset: 0x0000000000007056
Faulting process ID: 0x43f0
Faulting application start time: 0x01d6174387489c1c
Faulting application path: C:\P3Dv5\Prepar3D.exe
Faulting module path: C:\WINDOWS\SYSTEM32\ntdll.dll
Report ID: 401f7199-5d35-46a5-a14f-ddfe2e319586
Faulting package full name:
Faulting package-relative application ID:

with the resulting Windows Error (1001). See attached ,wer file:

Fault bucket 1707778556859359639, type 4
Event Name: APPCRASH
Response: Not available
Cab Id: 0

Problem signature:
P1: Prepar3D.exe
P2: 5.0.21.34709
P3: 5e95060d
P4: ntdll.dll
P5: 10.0.18362.778
P6: 0c1bb301
P7: c0000005
P8: 0000000000007056
P9:
P10:

The full debug log is attached. Somehow the .ini file edits were not saved. I ran several further tests with full debug on and there was no further hung tasks or crashes.

 

Andrew

 

Report.wer Approach crash.evtx FSUIPC6.log

[Scotfleiger]

These are the fsuipc6.log when P3Dv5 crashes on exit. All logging stops at closing DLLs.

FSUIPC6-crash 2.log FSUIPC6-crash.log Report.wer

[Pete Dowson]

2 hours ago, Scotfleiger said:

My apologies for having to leave earlier. Thank you for reminding me about the event viewer. As a Mac user I don't normally see crashes!

When P3Dv5 crashes on exit it is a .NET runtime error (1926):

Right. I don't think that's anything to do with FSUIPC. It's one of the many being reported with P3Dv5

2 hours ago, Scotfleiger said:

These are the fsuipc6.log when P3Dv5 crashes on exit. All logging stops at closing DLLs.

No, both logs show FSUIPC never started its close squence. P3D crashed out before SimConnect notified client DLLs by calling the DLLstop function.

You also had the extra logging we asked you to only enable just before you closed down operating for the entire session.

      500 LogOptions=00000000 00020051

(x2005 = 8197. the last digit contains standard log flags with 01 meaning "yes make a log" and always set).

I think this probably happened because it would have been saved like that from an earlier test. If we do any more tests with this logging (which is unlikely) we'd need you to set LogExtras=1 again in FSUIPC6.INI before each session.

Anyway, I think we've learned all we are going to from the logging we added. There's no easy answers -- the hang is somewhere in Windows or a driver, out of our reach. It simply isn't returning from a standard function which is documented as non-blocking.

We are looking only at experimenting with delays to alter timings a bit, and/or a forced TerminateProcess (which is like doing it with Task Manager) instead of bothering trying ot terminate the threads. Note that all this ONLY applies to the read and write threads for VRI devices. The general serial port COM threads are Terminating properly. So we'd only have to possibly do a forced terminate with VRI in use in FSUIPC.

One of us will be back later tomorrow.

Pete

 

[Scotfleiger]

I agree that the P3Dv5 crashes is nothing to do with you. When the crash occurs all processes are forced to close anything and the issue I have raised does not occur on next startup.

If FSUIPC6 shutdown hangs I would go with the TerminateProcess option after a set delay. We just need to see the VRI comms closed down.

Andrew 

[John Dowson]

Hi Andrew,

could you try the following dll please: FSUIPC6.dll

This one has a small delay added to during VRI closing. Could you try this with logExtras=4 please and send the log back to us.

You can also try with no extra logging (LogExtras=0 or 1).

For some final tests, you can try adding the following parameter to the [General] section of the ini:
    ForceTerminateTime=<milliseconds>
where <milliseconds> is the time it waits before forcing termination. This needs to be long enough for P3D to close down in normal situations (e.g. to rewrite the P3D CFG file if changed). Suggest you try with different values to see what works, maybe starting at 1000ms and going from there.

John

 

[Scotfleiger]

Hi John

Thanks for the updated .dll. With LogExtras=1 and x2005/8197, 6.03.e closed currently with the expected delay. I run this test 3 times without any problems. See 1st log.

I then set the VRIDisableCMDRST=No. This test failed (2nd log). The VRI Combo reset and LINDA.exe closed but the Prepar3d background task failed to terminate. I again repeated this test 3 times. It left a hanging task on each occasion.

I then tried the ForceTerminateTime. At 5000ms and 1000ms the hanging task remained open on both tests (3rd log). I allowed at least 20s for it to work.

I set LogExtras=0, VRIDisableCMDRST=yes and ForceTerminateTime=1000. This test failed (4th). I then used 10000ms without success. The log files shows logging ended but the hanging task remained.

Finally I removed the ForceTerminateTime entry. This time FSUIPC6  terminated correctly with no hanging tasks after a 5-10s delay. This was repeatable.

These results are a little strange as the 4th log shows that the CMDRST was sent and success and the log closed but something stopped the tasks ending.

AndrewFSUIPC6-603e-4th.log

 

 

 

FSUIPC6_603e-1st.log FSUIPC6-603e-2nd.log FSUIPC6-603e-3rd.log FSUIPC6-603e-5th.log

[John Dowson]

Hi Andrew,

2 hours ago, Scotfleiger said:

With LogExtras=1 and x2005/8197,

So you changed the logExtras value before closing? Really we wanted to see what happened without this, as the additional logging also affects the timings.

Also the tests with ForceTerminateTime don't really mean much at the moment - need to make some adjustments for this to work, but we'll leave this for now. Sorry about that. I'll come back to this if needed...

Could you try the attached dll please:   

I've increased the timings in this one. Please try initially with LogExtras=0 (or 1) and DO NOT CHANGE before closing down. You can try with both the VRIDisableCMDRST set to No and Yes - from your previous results I am hoping this would work with the latter option, but probably not the former. However, if this does work consistently, then we could go with this one.

If you still have issues with this, then set the LogExtras to x2005/8197 before closing to get the additional logging, and send the logs (for both VRIDisableCMDRST Yes and No).

Cheers,

John

FSUIPC6.dll

P.S. "The log files shows logging ended but the hanging task remained." - but this would indicate a P3D problem, not an FSUIPC one as the log indicates that it (and all associated threads) have closed....

And:  "Finally I removed the ForceTerminateTime entry. This time FSUIPC6  terminated correctly with no hanging tasks after a 5-10s delay. This was repeatable."

Ah, ok - so this is the test we needed (i.e no logging), so maybe just adding the 10ms delay was enough...

Try the  new dll anyway and report back. Thanks.

Edited April 21, 2020 by John Dowson
Further info added

[Scotfleiger]

Hi John

I ran 6.0.3e with VRIDisableCMDRST set to Yes and No and LogExtras=0.  With CMDRST disable everything closed correctly after a much longer delay. However, with CMDRST enabled the hanging task remained and the FSUIPC6.log was not closed fully.

FSUIPC6-603e-NoCMDRST.log FSUIPC6-603e-YesCMSRST.log

[John Dowson]

Hi Andrew,

first apologies, as there was an error with the logging statements, which means that the logging was active even if not enabled, which would affect the timings. Due to this, the test need to be redone. [And was why we were also confused with your logs!]

However, as it seems that you are getting consistent results with the CMDRST call disabled (i.e. ini param set to Yes) [but with logging!], I've taken that as another clue and have increased the wait time after this command is sent.

So, could you please try the attach dll. Again, no logging please (LogExtras=1 or 0), and try with CMDRST enabled and disabled.

Thanks,

John

FSUIPC6.dll

[Scotfleiger]

Morning John

 I ran the series of tests with 6.0.3g as requested with several runs of each. In all cases the shutdown was completed successfully. It around 30s to close LINDA, reset VRI (when VRIDisableCMDRST=no) and right to fsuipc6.ini and around 60s to close the background task stub.

NoLog = LogExtras = 0

YesLog = LogExtras = x2005

NoVRI = VRIDisableCMDRST=no

YesVRI = VRIDisableCMDRST=yes

Good work, thank you

Andrew

FSUIPC6-603g-NoLog-NoVRI.log FSUIPC6-603g-NoLog-NoVRI-LINDA running outside.log FSUIPC6-603g-YesLog-NoVRI.log FSUIPC6-603g-YesLog-YesVRI.log

[John Dowson]

Hi Andrew,

thanks for reporting back. I could try and reduce some of the delays added, but as these only total a few seconds, it wouldn't reduce the shutdown time by any noticeable amount, so I think I'll leave things as they are. I'll release these changes within the next day or two as v6.0.4 (and remember to update the IPC check version!).

Cheers,

John

 

[Scotfleiger]

That sounds good. I suggest a comment be added to the release notes about leaving 60s to close down. 
 

Andrew

[Pete Dowson]

1 hour ago, Scotfleiger said:

 I ran the series of tests with 6.0.3g as requested with several runs of each. In all cases the shutdown was completed successfully. It around 30s to close LINDA, reset VRI (when VRIDisableCMDRST=no) and right to fsuipc6.ini and around 60s to close the background task stub.

Hi Andrew

I've been looking at this in more detail this morning, and I remain a little concerned about what is actually going on.

Are these shutdown times in line with what you'd expect? 30 + 60 seconds seem mightily excessive. John's amendments have only added a few seconds.

What is LINDA doing which takes 30 seconds to close?

And what is this "background task stub"?

The logs show around 23 seconds in total from when SimConnect tells FSUIPC to close and when it actually does close (final log line). Are the additional 67 seconds you are telling us then after that? What can be responsible?

I think it is important for us to understand, especially with you advising John to add a note about an extra 60 seconds. That will need some sort of explanation, please.

Is it related to the 9 COM devices which seem to be added in addition to the two COM ports used for VRI? Are these all devices you have attached which are handled by LINDA? Is this 60 seconds extra perhaps proportional to how many devices LINDA has been asked to handle?

Anyway, in the latest version John sent, the one you seem happy with, there are still those TerminateThread functions.  I don't like those. I think they were added ages ago because of these sorts of problems which I didn't understand then either. The threads should terminate by themselves.

With that in mind I have made some changes in the code to see if we can make that happen. I wonder if you'd be so kind as to run a test or two with yet another revised version which John will provide shortly.

The results of this might not be what you want, so please treat this only as an experiment for now.  You may want to retain a copy of your current 'good' one and return to it afterwards.

Thanks,
Pete

DLL: FSUIPC6.dll

[Scotfleiger]

Hi Pete

I agree the delays times are a little excessive if you are closing and wanting to reopen P3D. Typically the shutdown took 30+ seconds to complete so I am not complaining as I and users need a full shutdown without manually checking the Task Manager.

I started my stopwatch when I clicked on the Yes button on the exit P3D dialog. It was 25-30s to FSUIPC closing the external apps (eg. LINDA), sending the CMDRST and updating fsuipc6.ini. These events all happened within a second. When FSUIPC closes LINDA it displays ‘not responding’ for several seconds, waits for several more seconds and then closes. When I close LINDA manually it takes less than 5s.

It was a further 25-30s before the ‘hanging’ P3D background task (or stub as I called it) closed. At this point the fsuipc6.log was released and could be renamed. The total time to close everything was under 60s (30+30).  

I only have 2 comms ports defined COM3 and COM4 for the 2 different VRi Combos I use for testing.

I will run tests on the new dll later.

Andrew

 

 

 

 

[Scotfleiger]

Hi Pete

I am sorry to report that 6.0.3h is a failure. On exiting P3D the auto start program LINDA displayed 'Not responding' and nothing closed even after over 2 minutes. This was both with and without logging. 6.0.3h is only killing one of the 2 LINDA LUA thread (init.lua). The other (linda.lua) is not reported. See previous logs.

Further to my earlier statement, LINDA closes and ends in task in less than a second when manually closed.

Andrew

FSUIPC6-603h-NoLog.log FSUIPC6-603h-YesLog.log

[Pete Dowson]

2 hours ago, Scotfleiger said:

It was a further 25-30s before the ‘hanging’ P3D background task (or stub as I called it) closed. At this point the fsuipc6.log was released and could be renamed.

This is what seems at odds. FSUIPC closes the log when it says it does, with the three extra lines added simultaneously. I'm really puzzled at why it isn't "released" till later.

What is this "hanging P3D background task". Is this related to something LINDA has got running and which doesn't get closed when the LINDA task is killed?

2 hours ago, Scotfleiger said:

I only have 2 comms ports defined COM3 and COM4 for the 2 different VRi Combos I use for testing.

So you don't use VRI driver linked via virtual ports?

It's only just dawned on me. The other 7 ports are USB joystick connections, your Saitek and other controls! Duh! I've been puzzling about that for ages!

1 hour ago, Scotfleiger said:

I am sorry to report that 6.0.3h is a failure

I didn't expect it to work! It was merely an attempt to get more information so i could understand what was going on, as i said earlier.

1 hour ago, Scotfleiger said:

only killing one of the 2 LINDA LUA thread (init.lua). The other (linda.lua) is not reported.

That's because it appears to be crashing or hanging during the closure of the first COM port, when the first thread is closed -- or possibly in the second thread when it is seeing that it needs to close (a note on this just below).

That might be an error in my new logging loop. i'll check.

1 hour ago, Scotfleiger said:

Further to my earlier statement, LINDA closes and ends in task in less than a second when manually closed.

By "manually closed" is this a tidy metthod you've implemented, or an assignment to an FSUIPC Kill control?  If you can do a tidy close like that, do you use  "event.terminate" to close down your Lua functions?  I think that only gives a short time extension to tidy up. Perhaps you need more?  Maybe that should be configurable in the Lua code. e.g  

event.terminate("function name", timeout)

where the timeout parameter is optional.

Pete

 

 

 

Edited April 22, 2020 by Pete Dowson

[Scotfleiger]

59 minutes ago, Pete Dowson said:

What is this "hanging P3D background task". Is this related to something LINDA has got running and which doesn't get closed when the LINDA task is killed?

The hanging background task is what started this whole conversation. It is labelled 'Prepar3d...' of size 560KB. The process of elimination you suggested identified that it was the VRI device that was stopping FSUIPC6 terminating. I say it is stopping FSUIPC6 terminating as the fusipc6.log cannot have its name changed until this task ends. LINDA is long terminated by this time - at the 25-30s point with 6.0.3g.

1 hour ago, Pete Dowson said:

So you don't use VRI driver linked via virtual ports?

The only VRI driver is the COMPORT FDTI device driver. No other VRI software is running or used.

1 hour ago, Pete Dowson said:

I didn't expect it to work! It was merely an attempt to get more information so i could understand what was going on

I take back what said. It was not a failure.

1 hour ago, Pete Dowson said:

By "manually closed" is this a tidy method you've implemented, or an assignment to an FSUIPC Kill control?

LINDA consists of 2 parts - GUI and LUA. The GUI LINDA.EXE is the on-screen interface for assigning functions to buttons and interfaces with FSUIPC. It can be started manually (before P3D) or via the FSUIPC [programs] block. The LUA code is triggered by FSUIPC running ipcReady.lua that calls linda.lua which in turn calls init.lua for loading all other LINDA code. This code can operate without the GUI. When I say 'manually close' LINDA it is me clicking on the red quit icon (top right) to close the application. I will need to double check but I believe the LUA code is left loaded and running when the GUI terminates.

1 hour ago, Pete Dowson said:

If you can do a tidy close like that, do you use  "event.terminate" to close down your Lua functions?  I think that only gives a short time extension to tidy up. Perhaps you need more? 

I will take a look at the GUI code to see what can be done.

Andrew

[Pete Dowson]

5 minutes ago, Scotfleiger said:

The hanging background task is what started this whole conversation. It is labelled 'Prepar3d...' of size 560KB.

Sorry, then I'm misunderstanding you. I took this "stub" you mentioned to be something else. You are simply talking about P3D not terminating, which we knew about. Obviously if it isn't terminating there's still the process in memory.

6 minutes ago, Scotfleiger said:

I say it is stopping FSUIPC6 terminating as the fusipc6.log cannot have its name changed until this task ends.

Yes, that is strange though. Once a file is closed it can have anything done to it.

8 minutes ago, Scotfleiger said:

When I say 'manually close' LINDA it is me clicking on the red quit icon (top right) to close the application. I will need to double check but I believe the LUA code is left loaded and running when the GUI terminates.

Ah, that makes more sense. So the "less than a second" manual close is just the external LINDA application? Not really relevant to what's going on with P3D and FSUIPC.

Thanks for the clarifications.

Pete