FSUIPC_WAPI and ExecuteCalclatorCode Issue

[Flex45]

Hi John,

I notice a weird issue when using executecalccode to set an Hvar (using FSUIPC_WAPI module) and looking in the forum I can only find related topics but not the same.

Specifically I try to set a simple Hvar for the A32NX using executecalclatorcode and everything is working perfectly except is some random cases which I cannot figure out when they occur.

 The call in my code is similar to this:

WasmPtr->executecalclatorCode("(>H:A320_Neo_CDU_2_BTN_CLR)");

As said above everything works ok most of the time but there are some random cases where it fails and the main issue is that everything else breaks as well. eg. getLvar() (which I call from anothier function in my code) also stops working etc (see log data below).

Looking in the FSUIPC_WASMIF debug log, in normal conditions I have the following:

[INFO]: **** Starting FSUIPC7 WASM Interface (WAPI) version 0.9.1 (WASM version 0.9.1)
[INFO]: Connected to MSFS 

but when executecalclatorCode fails I have the following:

[INFO]: **** Starting FSUIPC7 WASM Interface (WAPI) version 0.9.1 (WASM version 0.9.1)
[INFO]: Connected to MSFS 

[ERROR]: Error setting Client Data Calculator Code: '(>H:A320_Neo_CDU_2_BTN_CLR)'
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: Error setting Client Data Calculator Code: '(>H:A320_Neo_CDU_2_BTN_CLR)'
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!
[ERROR]: SimConnect_RequestClientData for lvars failed!!!!

and log goes on like this......

Any ideas as to why this might happening? Also is there a way I can protect it from breaking completely in case the Hvar call fails?

Thanks in advance,

Regards,

 

[John Dowson]

3 hours ago, Flex45 said:

As said above everything works ok most of the time but there are some random cases where it fails and the main issue is that everything else breaks as well. eg. getLvar() (which I call from anothier function in my code) also stops working etc (see log data below).

What do you do to get it working again - restart your application or restart MSFS? If you have to do the latter, it could be an issue with the WASM. Did you check your FSUIPC_WASM.log file?

Are you using any other WAPI clients (e.g. FSUIPC7)?

Could you set Debug level logging in the WAPI (WasmPtr->setLogLevel(LOG_LEVEL_DEBUG)) and in the WASM (via the FSUIPC_WASM.ini file) and show me both your WAPI log file and the WASM log file the next time this occurs.

Thanks,

John

[Flex45]

It's an external application so just a restart of the application restores everything.... No need for a simulator restart. 

I don't use anything else, just the fsuipc wapi to get and set the variables through my code. In my code I have some setLvar and executecalclatorCode calls on demand and a general getLvar function which is called every 1 or 2 seconds.... 

Also if it helps you further, when the issue occurs, trying the same executecalclatorCode command through your Wasm Client application works perfectly and then retrying from my code still does nothing (execute CalculatorCode line still hit in my code but the command never reaches the aircraft). Is there a chance the connection to the module terminates when this occurs? 

I will enable the debug as you suggested and I will let you know. 

Thanks

[John Dowson]

It won't be an issue with the WASM then. You could try and see if you can reproduce in a debugger to see what the issue is?
Otherwise a debug (or maybe even a trace) log from the WAPI for when this issue occurs would be helpful.

12 minutes ago, Flex45 said:

a general getLvar function which is called every 1 or 2 seconds.... 

You shouldn't need to do this - you can use registerLvarUpdateCallback to get a callback when an lvar value changes, which would be better than polling.

John

[Flex45]

21 hours ago, John Dowson said:

It won't be an issue with the WASM then. You could try and see if you can reproduce in a debugger to see what the issue is?
Otherwise a debug (or maybe even a trace) log from the WAPI for when this issue occurs would be helpful.

I enabled the debug level logging and waiting for the issue to occur again as I can't reproduce on demand.

I will let you know once I have the data you need.

Thanks once more

[John Dowson]

39 minutes ago, Flex45 said:

I enabled the debug level logging and waiting for the issue to occur again as I can't reproduce on demand.

Ok. But better if you could catch/trace in a debugger.

[Flex45]

19 hours ago, John Dowson said:

Ok. But better if you could catch/trace in a debugger.

I already debugged my code when the issue is active and all seems ok (executecalclatorCode lines still running). 

I am not sure how to debug WAPI though. 

[Flex45]

Hi John,

Issue occured again and got the debug log:

Wed Jan 25 2023 10:44:08.348    [INFO]: **** Starting FSUIPC7 WASM Interface (WAPI) version 0.9.1 (WASM version 0.9.1)
Wed Jan 25 2023 10:44:08.349    [INFO]: Connected to MSFS
Wed Jan 25 2023 10:44:08.349   [DEBUG]: Starting config request timer...
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 0: name=FSUIPC_VNAME7, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 1: name=FSUIPC_VNAME8, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 2: name=FSUIPC_VNAME9, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 3: name=FSUIPC_VNAME10, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 4: name=FSUIPC_VNAME11, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 5: name=FSUIPC_VNAME12, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 6: name=FSUIPC_VNAME13, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 7: name=FSUIPC_VNAME14, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 8: name=FSUIPC_VNAME15, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 9: name=FSUIPC_VNAME16, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 10: name=FSUIPC_VNAME17, size=8176, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 11: name=FSUIPC_VNAME18, size=6216, type=0
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 12: name=FSUIPC_lvalues0, size=8192, type=2
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 13: name=FSUIPC_lvalues1, size=8192, type=2
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Config Data 14: name=FSUIPC_lvalues2, size=8192, type=2
Wed Jan 25 2023 10:44:08.384   [DEBUG]: SIMCONNECT_RECV_ID_CLIENT_DATA received: EVENT_CONFIG_RECEIVED
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA name FSUIPC_VNAME7 mapped to ID 4 [requestId=16]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data area created with id=4 (size=8176) [requestID=17]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data definition added with id=4 (size=8176)
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA 'FSUIPC_VNAME7 with id=4 and definitionId=4 requested
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA name FSUIPC_VNAME8 mapped to ID 5 [requestId=20]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data area created with id=5 (size=8176) [requestID=21]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data definition added with id=5 (size=8176)
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA 'FSUIPC_VNAME8 with id=5 and definitionId=5 requested
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA name FSUIPC_VNAME9 mapped to ID 6 [requestId=24]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data area created with id=6 (size=8176) [requestID=25]
Wed Jan 25 2023 10:44:08.384   [DEBUG]: Client data definition added with id=6 (size=8176)
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA 'FSUIPC_VNAME9 with id=6 and definitionId=6 requested
Wed Jan 25 2023 10:44:08.384   [DEBUG]: CDA name FSUIPC_VNAME10 mapped to ID 7 [requestId=28]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=7 (size=8176) [requestID=29]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=7 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME10 with id=7 and definitionId=7 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME11 mapped to ID 8 [requestId=32]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=8 (size=8176) [requestID=33]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=8 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME11 with id=8 and definitionId=8 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME12 mapped to ID 9 [requestId=36]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=9 (size=8176) [requestID=37]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=9 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME12 with id=9 and definitionId=9 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME13 mapped to ID 10 [requestId=40]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=10 (size=8176) [requestID=41]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=10 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME13 with id=10 and definitionId=10 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME14 mapped to ID 11 [requestId=44]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=11 (size=8176) [requestID=45]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=11 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME14 with id=11 and definitionId=11 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME15 mapped to ID 12 [requestId=48]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=12 (size=8176) [requestID=49]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=12 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME15 with id=12 and definitionId=12 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME16 mapped to ID 13 [requestId=52]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=13 (size=8176) [requestID=53]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=13 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME16 with id=13 and definitionId=13 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME17 mapped to ID 14 [requestId=56]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=14 (size=8176) [requestID=57]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=14 (size=8176)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME17 with id=14 and definitionId=14 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_VNAME18 mapped to ID 15 [requestId=60]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=15 (size=6216) [requestID=61]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=15 (size=6216)
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA 'FSUIPC_VNAME18 with id=15 and definitionId=15 requested
Wed Jan 25 2023 10:44:08.385   [DEBUG]: CDA name FSUIPC_lvalues0 mapped to ID 16 [requestId=64]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data area created with id=16 (size=8192) [requestID=65]
Wed Jan 25 2023 10:44:08.385   [DEBUG]: Client data definition added with id=16 (size=8192)
Wed Jan 25 2023 10:44:08.386   [DEBUG]: CDA 'FSUIPC_lvalues0 with id=16 and definitionId=16 requested
Wed Jan 25 2023 10:44:08.386   [DEBUG]: CDA name FSUIPC_lvalues1 mapped to ID 17 [requestId=68]
Wed Jan 25 2023 10:44:08.386   [DEBUG]: Client data area created with id=17 (size=8192) [requestID=69]
Wed Jan 25 2023 10:44:08.386   [DEBUG]: Client data definition added with id=17 (size=8192)
Wed Jan 25 2023 10:44:08.386   [DEBUG]: CDA 'FSUIPC_lvalues1 with id=17 and definitionId=17 requested
Wed Jan 25 2023 10:44:08.386   [DEBUG]: CDA name FSUIPC_lvalues2 mapped to ID 18 [requestId=72]
Wed Jan 25 2023 10:44:08.386   [DEBUG]: Client data area created with id=18 (size=8192) [requestID=73]
Wed Jan 25 2023 10:44:08.386   [DEBUG]: Client data definition added with id=18 (size=8192)
Wed Jan 25 2023 10:44:08.386   [DEBUG]: CDA 'FSUIPC_lvalues2 with id=18 and definitionId=18 requested
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:1 of 12: dwObjectID=0, dwDefineID=4, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:2 of 12: dwObjectID=0, dwDefineID=5, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:3 of 12: dwObjectID=0, dwDefineID=6, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:4 of 12: dwObjectID=0, dwDefineID=7, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:5 of 12: dwObjectID=0, dwDefineID=8, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:6 of 12: dwObjectID=0, dwDefineID=9, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:7 of 12: dwObjectID=0, dwDefineID=10, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:8 of 12: dwObjectID=0, dwDefineID=11, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:9 of 12: dwObjectID=0, dwDefineID=12, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.386   [DEBUG]: EVENT_LVARS_RECEIVED:10 of 12: dwObjectID=0, dwDefineID=13, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.387   [DEBUG]: EVENT_LVARS_RECEIVED:11 of 12: dwObjectID=0, dwDefineID=14, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 10:44:08.387   [DEBUG]: EVENT_LVARS_RECEIVED:12 of 12: dwObjectID=0, dwDefineID=15, dwDefineCount=1, dwentrynumber=1, dwoutof=1
Wed Jan 25 2023 11:27:03.557   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:03.728   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:03.882   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.052   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.224   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.379   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.549   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.720   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:04.875   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.043   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.213   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.383   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.552   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.709   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:05.878   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.049   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.204   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.374   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.545   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.715   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:06.869   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.040   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.209   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.379   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.533   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.703   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:07.873   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.043   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.198   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.368   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.538   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.693   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:08.864   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.032   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.200   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.370   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.525   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.696   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:09.866   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.035   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.191   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.361   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.531   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.686   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.855   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:10.903   [ERROR]: Error setting Client Data Calculator Code: '(>H:A320_Neo_CDU_2_BTN_L6)'
Wed Jan 25 2023 11:27:11.027   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:11.197   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:11.353   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:11.523   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:11.693   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:11.847   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:12.018   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:12.187   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!
Wed Jan 25 2023 11:27:12.358   [ERROR]: SimConnect_RequestClientData for lvars failed!!!!

Note: Before the execcalclatorCode call that failed (BTN_L6) there was another executecalclatorCode call for another mcdu button which worked ok and the fault triggered between the two calls, thus the first error is not a calc code. 

Any ideas?

Thanks

[John Dowson]

2 hours ago, Flex45 said:

Before the execcalclatorCode call that failed (BTN_L6) there was another executecalclatorCode call for another mcdu button which worked ok

Then why is there no logging for that call? Maybe you need to set the logging level to Trace for this - can you do this please.

You also have your client application requesting lvar updates. It is better to have the WASM push the updates instead - which it does by default anyway. Try setting the lvar update frequency to 0 (wasmPtr->setLvarUpdateFrequency(0)) and use the WASM ini parameter LvarUpdateFrequency to set the required frequency for updates.

Could it be a threading issue? There are no critical sections around the executeCalaculatorCode calls as I didn't think these were needed as the the SimConnect_SetClientData calls should be thread-safe. If you are using multiple threads, you could try adding a CS around your executeCalaculatorCode calls to see if that improves things.

Anyway, for now just update your logging to Trace, use the WASM for the lvar updates, and show me (attach please, not paste the contents) the log file if it happens with that change.

6 hours ago, Flex45 said:

I am not sure how to debug WAPI though. 

See https://devblogs.microsoft.com/visualstudio/debugging-external-sources-with-visual-studio/.

Note that there is a debug enabled library available for the WAPI, no pdb file though but the source for the WAPI is available on github.
And I am not suggesting you debug the WAPI (this shouldn't be necessary anyway!), but to use the debugger to try and determine what is occurring when you get the first error.
But try without the client requesting lvar updates for now - this has caused some issues in the past for some developers using the WAPI, but I don't understand why, This was the default method that FSUIPC used before I decided to switch to updating via the WASM, and I never saw any issues (and none were reported in FSUIPC).

John

[John Dowson]

Oh - and you could also enable a simconnect log to see if that shows anything...if needed, try what I have already advised first...

[Flex45]

19 hours ago, John Dowson said:

Then why is there no logging for that call? Maybe you need to set the logging level to Trace for this - can you do this please.

[DEBUG] never logged successful execcalcCode calls, only [ERROR] ones were logged. In [TRACE] level unfortunately, file size becomes excessive very fast, which makes it impossible to log in that level for too long. (I have to start the flight from cold and dark and then hope the issue occurs in flight to be logged otherwise it never occured up to now).

19 hours ago, John Dowson said:

Oh - and you could also enable a simconnect log to see if that shows anything...if needed, try what I have already advised first...

I tried this as well but error logged by simconnect isn't of much help I think. 

3821.27980 [336] I/O Error! (2, 80004004)

 

As a temporary workaround for now (since execcalclatorCode calls in my code are in only 3 instances and called on demand/not frequently) I tried, after those calls to stop and start connection again to the module (using end() and start() functions). After the restart everything is back to normal, also execcalclatorCode calls. I know it's not the best solution/fix but at least it protects things from breaking after the error, for now. (reload() call didn't help)

Thanks

[John Dowson]

Did you do as I advised? i.e. do not use your client to request lvar updates, use the WASM...that is what you should try first...

8 minutes ago, Flex45 said:

I tried this as well but error logged by simconnect isn't of much help I think. 

3821.27980 [336] I/O Error! (2, 80004004)

Need to see the logging around this, and  the full log would be interesting....

John

[Flex45]

4 hours ago, John Dowson said:

Did you do as I advised? i.e. do not use your client to request lvar updates, use the WASM...that is what you should try first...

Not yet I will implement this tonight/tomorrow and let you know.

4 hours ago, John Dowson said:

Need to see the logging around this, and  the full log would be interesting....

Attached it's the simconnect log.....

simconnect000.log

[John Dowson]

21 minutes ago, Flex45 said:

Attached it's the simconnect log.....

That doesn't tell me anything I'm afraid...I would need to see the full log  - you can try zipping and attaching...

You have quite a few simconnect connections running: 322, 323, 324, 325, 326, 334, 335, 336 & 337 - at least, according to that short log extract, and all  of them just giving errors...

What are all those connections (a full log file would tell me....)? Search for Open: strings - that will tell you the connection name and thus the programs using them...

Your SimConnect is certainly having issues before the I/O error with all those exceptions reported...

John

[Flex45]

18 hours ago, John Dowson said:

That doesn't tell me anything I'm afraid...I would need to see the full log  - you can try zipping and attaching...

That was because simconnect.ini logging was at Error level....I increased to Verbose and now it's logging all the data however I need to reproduce the issue again and send you the log.

I did check those simconnect connections throwing the exceptions though and are mostly other aircrafts/applications exe when autoloading with MSFS start.  After that simconnect runs without any exceptions. (I will send you the log once I reproduce the issue to have a look as well).

 

Meanwhile I am trying to register the callbacks however as easy as it should be, I must be doing something wrong and get some build errors.

My workflow up to the errors point is the following:

 In the initialization I do:

WasmPtr = WASMIF::GetInstance();

WasmPtr->setLvarUpdateFrequency(6);

WasmPtr->Start();

 

and then I add the following function (which I expect to be called when loading is completed, as described here https://github.com/jldowson/FSUIPC_WAPI)

void WASMIF::registerUpdateCallback(void(*callbackFunction)(void))

{

}

When I build the code I get an error that registerUpdateCallback function is already defined. 

Is there an example/workflow somewhere I can follow to do the callback registers correctly?

Thanks

[John Dowson]

41 minutes ago, Flex45 said:

WasmPtr->setLvarUpdateFrequency(6);

This should be
    WasmPtr->setLvarUpdateFrequency(0);
The default WASM update frequency is 6Hz, so you shouldn't need to change anything, but you can check.

46 minutes ago, Flex45 said:

and then I add the following function (which I expect to be called when loading is completed, as described here https://github.com/jldowson/FSUIPC_WAPI)

void WASMIF::registerUpdateCallback(void(*callbackFunction)(void))

{

}

When I build the code I get an error that registerUpdateCallback function is already defined. 

Is there an example/workflow somewhere I can follow to do the callback registers correctly?

Of course it is defined - you have to register your own function, and before you start the WAPI, i.e.
 

WasmPtr->registerUpdateCallback(&LvarsChanged);
WasmPtr->registerLvarUpdateCallback(lvarsUpdatedById); // if needed
WasmPtr->Start();

and then supply two functions:
   

void LvarsChanged(void) // Called when lvar names have been received and are available
{
    ...
    // use registerLvarsForCallbck here if needed
}

void lvarsUpdatedById(int id[], double newValue[]) // Called when an lvar value has changed
{
    ...
}

 

 

[Flex45]

Hi John,

Many thanks for the help, it works perfectly now using the callback.

I keep simconnect logging and once the issue with execcalclatorCode occurs again (if it does), I will send you the logs.

Many thanks 

[John Dowson]

No problem - but your issue should be resolved. I hope - especially if you have turned off lvar update requests from the client.

Cheers,

John

 

[Flex45]

16 hours ago, John Dowson said:

especially if you have turned off lvar update requests from the client.

Yes, now there are no getLvar calls, just a few setLvar calls on demand along with the 3 instances with execcalclatorCode. Let's see how it goes, I will test it for a couple of days and let you know the results either case.

Regards, 

[Flex45]

Hi John,

A quick update on how it worked out. I had some issues as well with the callback method.

1) Even though I was waiting for a call that Lvars are loaded and available before using them, they never initialized properly. However when an Lvar was changing I was getting a callback with the proper value - not for all of them at init though. I even increased LvarScanDelay from 5 to 50 but still with no luck. I didn't investigate further though as it wasn't the only issue.

2) A few variables, never called back even when their value was changed. Out of my head, to name a few:

- A32NX_HYD_BRAKE_ALTN_RIGHT_PRESS (A32NX_HYD_BRAKE_ALTN_LEFT_PRESS updates normally or vice versa 🙂) Eg. Parking brake on->off....One gives the callback with the updated value the other one doesn't.

- A32NX_FMA_VERTICAL_MODE

Also I didn't investigate too much on this, there might be more. (Doing a getLvar Call though returns the correct value).

3) Even though this is not a bug, I think callback method works for my project less optimally compared to the getLvar individual call method. (Explained below)

If throughout the flight I use for example 50 Lvars, those 50 are not used all the time and for the whole flight. At a given flight phase a few are only used and might not be used again for the rest of the flight. The getLvar method allows me to call only the few I need and don't bother with the rest that won't be used anymore. The register for callback method, unless there is a way I am missing, will keep monitoring all the Lvars all the time.

Regards,

[John Dowson]

2 hours ago, Flex45 said:

1) Even though I was waiting for a call that Lvars are loaded and available before using them, they never initialized properly. However when an Lvar was changing I was getting a callback with the proper value - not for all of them at init though. I even increased LvarScanDelay from 5 to 50 but still with no luck. I didn't investigate further though as it wasn't the only issue.

The lvars-ready callback is performed once all lvars have been loaded (i.e. the names known), not when they have received an initialisation value. All lvars are initialised to 0.0, If you need the values initialised, you should set a timer in this callback (200ms or so should be ok)and perform your actions in the timer callback.
I guess I could delay the callback until the first set of values have been received - I will look into this.

2 hours ago, Flex45 said:

2) A few variables, never called back even when their value was changed. Out of my head, to name a few:

- A32NX_HYD_BRAKE_ALTN_RIGHT_PRESS (A32NX_HYD_BRAKE_ALTN_LEFT_PRESS updates normally or vice versa 🙂) Eg. Parking brake on->off....One gives the callback with the updated value the other one doesn't.

- A32NX_FMA_VERTICAL_MODE

Also I didn't investigate too much on this, there might be more. (Doing a getLvar Call though returns the correct value).

I really can't see how this can happen...the code doesn't know anything about any particular lvar, they are all treated the same. Try setting Debug level logging in the WAPI - this should tell you when am lvar is flagged for callback when values are received. If you can generate a log showing your issue (it will be large so will need to be compressed/zipped) I will take a look.

2 hours ago, Flex45 said:

3) Even though this is not a bug, I think callback method works for my project less optimally compared to the getLvar individual call method. (Explained below)

If throughout the flight I use for example 50 Lvars, those 50 are not used all the time and for the whole flight. At a given flight phase a few are only used and might not be used again for the rest of the flight. The getLvar method allows me to call only the few I need and don't bother with the rest that won't be used anymore. The register for callback method, unless there is a way I am missing, will keep monitoring all the Lvars all the time.

Only the lvars that you register to receive a callback when changed will be monitored. There is currently no way to deregister an lvar for a callback - this could be added if needed. But you can use whatever method works best for what you are trying to achieve.

Cheers,

John

[Flex45]

On 2/17/2023 at 11:51 AM, John Dowson said:

I really can't see how this can happen...the code doesn't know anything about any particular lvar, they are all treated the same.

Not sure either, but it happens every time and can be reproduced very easily. Initialize with park brake set and then release parking brake. You will see that one side gives the callback and drops pressure to 0 the other one remains to the old value without callback. 

On 2/17/2023 at 11:51 AM, John Dowson said:

There is currently no way to deregister an lvar for a callback - this could be added if needed. But you can use whatever method works best for what you are trying to achieve.

Yes for the moment and for my project the getLvar method works more optimally I think.

Regards,

[John Dowson]

1 hour ago, Flex45 said:

Not sure either, but it happens every time and can be reproduced very easily. Initialize with park brake set and then release parking brake. You will see that one side gives the callback and drops pressure to 0 the other one remains to the old value without callback. 

I suspect that it this is happening then it is the lvar that is not changing value. but I will take a look. Is this in the Asobo or FBW A320. and if the latter which version (stable, development, experimental)?

Btw, please also update to the latest beta, if not using this already: 

 

John

[John Dowson]

On 2/17/2023 at 8:12 AM, Flex45 said:

2) A few variables, never called back even when their value was changed. Out of my head, to name a few:

- A32NX_HYD_BRAKE_ALTN_RIGHT_PRESS (A32NX_HYD_BRAKE_ALTN_LEFT_PRESS updates normally or vice versa 🙂) Eg. Parking brake on->off....One gives the callback with the updated value the other one doesn't.

I have checked this now and it seems to be working as expected. I added these lvars to an FSUIPC offset, which will flag them for a callback:

Quote

[LvarOffsets]
1=L:A32NX_HYD_BRAKE_ALTN_LEFT_PRESS=UW0xA002
2=L:A32NX_HYD_BRAKE_ALTN_RIGHT_PRESS=UW0xA004

Then in the log, I can see these being flagged for a callback:

Quote

...
   16468  [DEBUG]: EVENT_LVARS_RECEIVED:30 of 30: dwObjectID=0, dwDefineID=35, dwDefineCount=1, dwentrynumber=1, dwoutof=1
    16484 Lvars received: 4325 L:vars & 220 H:vars now available
    16500 Lvars/Hvars received - checking aircraft autos....
    16640  [DEBUG]: Flagging lvar for callback: id=2243
    16640  [DEBUG]: Flagging lvar for callback: id=2244
...

where

Quote

   523562   [INFO]:     ID=2243 A32NX_HYD_BRAKE_ALTN_LEFT_PRESS = 2103.000000
   523562   [INFO]:     ID=2244 A32NX_HYD_BRAKE_ALTN_RIGHT_PRESS = 2103.000000

And if I log offsets 0xA002 and 0xA004 I can see these values change when I release and then apply the parking brake:

Quote

   644593  [DEBUG]: Flagging lvar for callback: id=2243
   644593  [DEBUG]: Flagging lvar for callback: id=2244
   644593 Monitor IPC:A002 (U16) = 1796
   644593 Monitor IPC:A004 (U16) = 1796
   644640  [DEBUG]: Flagging lvar for callback: id=2243
   644640  [DEBUG]: Flagging lvar for callback: id=2244
   644640 Monitor IPC:A002 (U16) = 1642
   644640 Monitor IPC:A004 (U16) = 1642
   644703  [DEBUG]: Flagging lvar for callback: id=2243
   644703  [DEBUG]: Flagging lvar for callback: id=2244
   644703 Monitor IPC:A002 (U16) = 1335
   644703 Monitor IPC:A004 (U16) = 1335
   644765  [DEBUG]: Flagging lvar for callback: id=2243
   644765  [DEBUG]: Flagging lvar for callback: id=2244
   644765 Monitor IPC:A002 (U16) = 1028
   644765 Monitor IPC:A004 (U16) = 1028
   644812  [DEBUG]: Flagging lvar for callback: id=2243
   644812  [DEBUG]: Flagging lvar for callback: id=2244
   644812 Monitor IPC:A002 (U16) = 875
   644812 Monitor IPC:A004 (U16) = 875
   644875  [DEBUG]: Flagging lvar for callback: id=2243
   644875  [DEBUG]: Flagging lvar for callback: id=2244
   644875 Monitor IPC:A002 (U16) = 568
   644875 Monitor IPC:A004 (U16) = 568
   644921  [DEBUG]: Flagging lvar for callback: id=2243
   644921  [DEBUG]: Flagging lvar for callback: id=2244
   644937 Monitor IPC:A002 (U16) = 261
   644937 Monitor IPC:A004 (U16) = 261
   644984  [DEBUG]: Flagging lvar for callback: id=2243
   644984  [DEBUG]: Flagging lvar for callback: id=2244
   644984 Monitor IPC:A002 (U16) = 0
   644984 Monitor IPC:A004 (U16) = 0
   649421  [DEBUG]: Flagging lvar for callback: id=2243
   649421  [DEBUG]: Flagging lvar for callback: id=2244
   649421 Monitor IPC:A002 (U16) = 153
   649421 Monitor IPC:A004 (U16) = 153
   649500  [DEBUG]: Flagging lvar for callback: id=2243
   649500  [DEBUG]: Flagging lvar for callback: id=2244
   649500 Monitor IPC:A002 (U16) = 460
   649500 Monitor IPC:A004 (U16) = 460
   649562  [DEBUG]: Flagging lvar for callback: id=2243
   649562  [DEBUG]: Flagging lvar for callback: id=2244
   649562 Monitor IPC:A002 (U16) = 767
   649562 Monitor IPC:A004 (U16) = 767
   649625  [DEBUG]: Flagging lvar for callback: id=2243
   649625  [DEBUG]: Flagging lvar for callback: id=2244
   649625 Monitor IPC:A002 (U16) = 1074
   649625 Monitor IPC:A004 (U16) = 1074
   649671  [DEBUG]: Flagging lvar for callback: id=2243
   649671  [DEBUG]: Flagging lvar for callback: id=2244
   649671 Monitor IPC:A002 (U16) = 1227
   649671 Monitor IPC:A004 (U16) = 1227
   649750  [DEBUG]: Flagging lvar for callback: id=2243
   649750  [DEBUG]: Flagging lvar for callback: id=2244
   649750 Monitor IPC:A002 (U16) = 1687
   649750 Monitor IPC:A004 (U16) = 1687
   649781  [DEBUG]: Flagging lvar for callback: id=2243
   649781  [DEBUG]: Flagging lvar for callback: id=2244
   649796 Monitor IPC:A002 (U16) = 1841
   649796 Monitor IPC:A004 (U16) = 1841
   649843  [DEBUG]: Flagging lvar for callback: id=2243
   649843  [DEBUG]: Flagging lvar for callback: id=2244
   649843 Monitor IPC:A002 (U16) = 2103
   649843 Monitor IPC:A004 (U16) = 2103

Note that the [Debug] messages are from the WAPI and show the lvars being flagged for callback when a value change is detected. This callback is then used by FSUIPC to update the values held in the offsets.

This therefore seems to be working as expected and the error must be in your code somewhere.

John

[John Dowson]

On 2/17/2023 at 8:12 AM, Flex45 said:

1) Even though I was waiting for a call that Lvars are loaded and available before using them, they never initialized properly.

I have looked at his now as well and have updated so that the lvars-loaded callback will be called after the initial values have been received.
The downside of this is that you wont get an lvar-update callback for the initial value.

I haven't released this update yet though - I will do some further testing first.