
------------------------------------------------------------------------------------
$Id$
$HeadURL$
$Author$
------------------------------------------------------------------------------------

LOGGER:
Log-File: ctc_mdm.log

------------------------------------------------------------------------------------
NLDEVCTRL-844: NASAT: Weiterleitung der Luftunterstützung sporadisch ausser Funktion
------------------------------------------------------------------------------------



##########################################################################################
##                                                                                      ##
##  Das hier geschilderte Phänomen sollte seit dem FTC Umbau nicht mehr auftreten! -MW  ##
##                                                                                      ##
##########################################################################################



NASAT-Telegramme von Flugzeug sind:
1) position
   -> TrainingAreaBase::Interface::Dts::publish(pos);
2) NineLiner
   -> GuezNasat::Interface::Dts::publish(nl);
3) WeaponRelease
   -> AreaEffectSimulation::Interface::Ftc::airSupportImpactModifyRequest(req, handler);

Auffällig ist, das nur 3) sporadisch hängen blieb.

Unterschiede:
Für 1) und 2) gilt:
- Dts DataTopic
- erfordern KEINE Antwort
- sind übergeordnet (TAB, GNA)

Für 3) gilt:
- Fts FunctionTopic
- erfordert eine Antwort (2. Parameter)
- muss in mehrere Exercises gesendet werden.
- In der Ausgangslage existiert ein NasatAircraftParticpant pro ex _> 2 Stück;
  => es werden in 2 WORKER-Threads quasi zeitgleich 'new connext::Requester' aufgerufen, also Requester erstellt.


Fazit:
- Das Öffnen des WebSockets für eingehende Telegramm wird um 30Sec verzögert, damit
  sich GNA erstmal richtig initialisieren kann. Damit ist die Eintrittswahrscheinlichkeit des Hängers
  wohl reduziert, aber nicht null - schade.
- Ein try catch im WorkerThread von generic_ftc_impl.h brachte keine Erkenntnis
- Warum 'new connext::Requester' hängen bleibt? Leider keine Erkenntnis

-> 'new connext::Requester' in mainThread verschieben (vorziehen, nicht gleichzeitig)


------------------------------------------------------------------------------------

Durch Provzieren (unter Zuhilfenahme von nasat_simulator.py, ./simulate_weapon_release.sh) ergab sich:
Zwei exercises (35, 42) ; jeweils ein NasatAircraftParticpant:

2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] GNA::WebSocketHandler |#| incoming telegram: {"type": "NasatWeaponRelease", "data": {"releaseMode": 0, "munition": 2, "timestamp": 1612363838.368936, "fuseType": 1, "impactPosition": {"lat": 53.061, "lon": 8.9711}, "aircraftId": 1, "flightTime": 5.1234}, "uuid": "NasatWeaponRelease-UUID"} (/Lts/Proxies/GuezNasat/abstract_socket_handler.cpp:53)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| void GuezNasat::HandlerNasatImpact::nasatImpact(int, const Core::GeoPosition&, qint64, int, int) START, nasatId=1, pos=[[lon: 0.156575232525663, lat: 0.926089154400711]z: 0], impactTimeMsec=1612363843492 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:59)

EX_42 this=0x2c43570
 Request wird vom mainThread per std::queue<Request> m_requests an den WorkerThread (WT) übergeben
 WT nimmt den Req auf und erzeugt 'WHILE LOOP.. new connext::Requester..., this=0x2c43570'
 danach ist von dem Thread nicht mehr zu sehen :-(

EX_35
 Request wird vom mainThread per std::queue<Request> m_requests an den WorkerThread (WT) übergeben
 WT nimmt den Req auf und erzeugt 'WHILE LOOP.. new connext::Requester..., this=0x2c45380'
 Danach sehen wir 3 mal '#sendRequest:...
 Nachdem die whileLoop von vorn beginnt, ist die queue leer und der Thread endet:
 'No more requests -> leaving thread, this=0x2c45380'
 :-)


Ca. 30 Sek. später (so das shell script) wird erneut eine NasatWeaponRelease gesendet, dies wird dann für EX_42 aber nur noch in die queue gesteckt... Es hängt :-(


2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  Sending air support impact: number of participant= 2 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:81)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Qos for dataReader:  (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:234)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| resourceLimit.max_samples 8000 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:235)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| policy dds.data_reader.history.memory_manager.fast_pool.pool_buffer_max_size:  2048 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:255)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Default Qos for dataWriter:  (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:242)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| ReliabilityKind: 1 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:243)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Publish mode: 1 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:244)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| policy dds.data_writer.history.memory_manager.fast_pool.pool_buffer_max_size:  2048 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:255)
2021-02-03 15:50:38.369 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| => Static request using request/reply topic names: LTS_AirSupportImpactModifyRequest, reply: LTS_AirSupportImpactModifyReply (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:96)

2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=0, this=0x2c43570, threadId=139905918381760, m_terminate=0 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:157)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData - fill m_requests and start new thread., this=0x2c43570, threadId=139905918381760, m_requests=0x2c43f68, m_requests.size()=0), request.uniqueId=1 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:189)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=1, this=0x2c43570, threadId=139905918381760, m_terminate=0 done (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:200)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| Sending air support impact create request: [id: 0, name: NASAT_1_2_03 15:50:38, effectStart: 1612363843492, chargeTypeId: 472, impactPosition: [lon: 0.156575232525663, lat: 0.926089154400711], partyId: 3, participantId: 90, flightTime: 5123, externalId: null] to exercise 42, nap=[id: 1, nasatAircraftId: 1, exerciseId: 42, participantId: 90] -> success = 1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:88)
2021-02-03 15:50:38.370 INFO  [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  requestCounter =  1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:97)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Qos for dataReader:  (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:234)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| resourceLimit.max_samples 8000 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:235)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| policy dds.data_reader.history.memory_manager.fast_pool.pool_buffer_max_size:  2048 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:255)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Default Qos for dataWriter:  (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:242)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| ReliabilityKind: 1 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:243)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| Publish mode: 1 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:244)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| policy dds.data_writer.history.memory_manager.fast_pool.pool_buffer_max_size:  2048 (S/TDS-source/Lts/DDS/QosProfile/DDS_DefaultQos.cpp:255)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| => Static request using request/reply topic names: LTS_AirSupportImpactModifyRequest, reply: LTS_AirSupportImpactModifyReply (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:96)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=0, this=0x2c45380, threadId=139905918381760, m_terminate=0 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:157)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData - fill m_requests and start new thread., this=0x2c45380, threadId=139905918381760, m_requests=0x2c45d78, m_requests.size()=0), request.uniqueId=1 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:189)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=1, this=0x2c45380, threadId=139905918381760, m_terminate=0 done (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:200)
2021-02-03 15:50:38.370 DEBUG [0x00007f3da4000f20] DDS::FTC::AirSupportImpactModify |#|  START WHILE LOOP.., this=0x2c43570, threadId=139902809986816, m_requests=0x2c43f68, m_requests.size()=1 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:225)
2021-02-03 15:50:38.370 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#|  START WHILE LOOP.., this=0x2c45380, threadId=139902801594112, m_requests=0x2c45d78, m_requests.size()=1 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:225)
2021-02-03 15:50:38.370 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| Sending air support impact create request: [id: 0, name: NASAT_1_2_03 15:50:38, effectStart: 1612363843492, chargeTypeId: 472, impactPosition: [lon: 0.156575232525663, lat: 0.926089154400711], partyId: 3, participantId: 62, flightTime: 5123, externalId: null] to exercise 35, nap=[id: 8, nasatAircraftId: 1, exerciseId: 35, participantId: 62] -> success = 1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:88)
2021-02-03 15:50:38.370 DEBUG [0x00007f3da4000f20] DDS::FTC::AirSupportImpactModify |#| IN waitForEvents, this=0x2c43570, request.uniqueId=1, threadId=139902809986816 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:245)
2021-02-03 15:50:38.370 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| IN waitForEvents, this=0x2c45380, request.uniqueId=1, threadId=139902801594112 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:245)
2021-02-03 15:50:38.370 INFO  [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  requestCounter =  2 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:97)

lazy init von connext::Requester, (noch) im jeweiligen WORKER-Thread:

2021-02-03 15:50:38.370 DEBUG [0x00007f3da4000f20] DDS::FTC::AirSupportImpactModify |#|  WHILE LOOP.. new connext::Requester..., this=0x2c43570, request.uniqueId=1, threadId=139902809986816 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:254)
2021-02-03 15:50:38.371 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#|  WHILE LOOP.. new connext::Requester..., this=0x2c45380, request.uniqueId=1, threadId=139902801594112 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:254)
2021-02-03 15:50:38.371 FATAL [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  bOk= 1, requestCounter =  2, replyCounter =  0 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:102)
2021-02-03 15:50:38.371 DEBUG [0x0000000001dfc6f0] GNA::WebSocketHandler |#| Websocket connection closed, ptr: 0x2c1ba10 (ource/Lts/Proxies/GuezNasat/web_socket_handler.cpp:155)
2021-02-03 15:50:38.371 DEBUG [0x00007f3d9c000f20] connext::requester |#| connext::Requester<REQUEST, REPLY>::Requester(const connext::RequesterParams&) [with REQUEST = AreaEffectSimulation::AirSupportImpactModifyRequest; REPLY = Core::FunctionReply] START   (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:292)
2021-02-03 15:50:38.371 DEBUG [0x00007f3d9c000f20] connext::requester |#| connext::Requester<REQUEST, REPLY>::Requester(const connext::RequesterParams&) [with REQUEST = AreaEffectSimulation::AirSupportImpactModifyRequest; REPLY = Core::FunctionReply] END   (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:293)
2021-02-03 15:50:38.371 INFO  [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| #sendRequest: SeqNumber: -1, this=0x2c45380, request.uniqueId=1, threadId=139902801594112 ... (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:261)
2021-02-03 15:50:38.373 DEBUG [0x00007f3d9c000f20] connext::requester |#| content filter for topic LTS_AirSupportImpactModifyRequest - related_sample_identity should be: 0101aaeead199ead8d523da780006303 (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:322)
2021-02-03 15:50:38.373 DEBUG [0x00007f3d9c000f20] connext::requester |#| send_request for topic LTS_AirSupportImpactModifyRequest, m_currentSampleIdentity: SeqNo: 1, Guid-DW: 0101aaeead199ead8d523da780006303 (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:359)
2021-02-03 15:50:38.373 INFO  [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| #sendRequest: SeqNumber: 1, this=0x2c45380, request.uniqueId=1, threadId=139902801594112 ... done (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:268)
2021-02-03 15:50:38.373 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| Waiting for reply  (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:331)
2021-02-03 15:50:38.373 DEBUG [0x000000000232ee10] DDS::DTC::SubscriberListener |#| on_liveliness_changed: 1, 0, 1, 0 for type Core::FunctionReply (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:130)
2021-02-03 15:50:38.399 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_AirSupportImpactModifyReply 0101aaeead199ead8d523da780006303, type Core::FunctionReply, this 0x1ece220 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:38.400 DEBUG [0x00007f3d9c000f20] connext::requester |#| receive_reply for topic LTS_AirSupportImpactModifyRequest, SampleIdentity - original publication virtual: SeqNo: 30, Guid-DW: 0101c38b58f3acefce8ec8c480000003 (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:379)
2021-02-03 15:50:38.400 DEBUG [0x00007f3d9c000f20] connext::requester |#| receive_reply for topic LTS_AirSupportImpactModifyRequest, SampleIdentity - related original: SeqNo: 1, Guid-DW: 0101aaeead199ead8d523da780006303 (-source/Lts/DDS/QosProfile/../../DDS/FTS/connext.h:384)
2021-02-03 15:50:38.400 INFO  [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| #receiveReply for AreaEffectSimulation::AirSupportImpactModifyReply (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:362)
2021-02-03 15:50:38.400 INFO  [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| #sendRequest: SeqNumber: 1, this=0x2c45380, request.uniqueId=1, threadId=139902801594112 ... getRequestedData done (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:279)
2021-02-03 15:50:38.400 INFO  [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| Got create reply: (id=291), this=0x2aa18f0 - replyCounter=1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:39)
2021-02-03 15:50:38.400 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#|  START WHILE LOOP.., this=0x2c45380, threadId=139902801594112, m_requests=0x2c45d78, m_requests.size()=0 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:225)
2021-02-03 15:50:38.400 DEBUG [0x00007f3d9c000f20] DDS::FTC::AirSupportImpactModify |#| No more requests -> leaving thread, this=0x2c45380, threadId=139902801594112 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:237)
2021-02-03 15:50:38.404 DEBUG [0x00000000024dbc40] DDS::DTS::Core::CurrentRunningState |#| IN write (Core::CurrentRunningState) (urce/Lts/DDS/Core/../../DDS/DTS/generic_dts_impl.h:44)
2021-02-03 15:50:38.404 DEBUG [0x00000000024dbc40] DDS::DataWriter::Core::CurrentRunningState |#| IN write (Core::CurrentRunningState)  (s/DDS/Core/../../DDS/Generic/generic_data_writer.h:102)
2021-02-03 15:50:38.404 DEBUG [0x00000000024dbc40] DDS::DTS::Core::CurrentRunningState |#| TopicData (Core::CurrentRunningState) written (urce/Lts/DDS/Core/../../DDS/DTS/generic_dts_impl.h:57)
2021-02-03 15:50:38.905 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_PartitionTime, type Core::PartitionTime, this 0x21f0f80 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:38.906 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_PartitionTime, type Core::PartitionTime, this 0x21f0f80 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:38.906 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_PartitionTime, type Core::PartitionTime, this 0x21f0f80 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:38.907 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| sampleSize = 1 (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:122)
2021-02-03 15:50:38.907 DEBUG [0x0000000001dfc6f0] DDS::DTC::Core::PartitionTime |#| IN droDataAvailable(), topic name: LTS_PartitionTime, type name Core::PartitionTime, this: 0x24d4580, m_dataReaderObject: 0x24ec320, hasSamples: 1 (urce/Lts/DDS/Core/../../DDS/DTC/generic_dtc_impl.h:210)
2021-02-03 15:50:38.907 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| IN read (Core::PartitionTime), this: 0x24ec320, instance handle 0101aaeead199ead8d523da780000004 (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:167)
2021-02-03 15:50:38.907 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| got 1 samples from reader for Core::PartitionTime (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:197)
2021-02-03 15:50:39.903 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_PartitionTime, type Core::PartitionTime, this 0x21f0f80 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:39.903 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| sampleSize = 1 (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:122)
2021-02-03 15:50:39.903 DEBUG [0x0000000001dfc6f0] DDS::DTC::Core::PartitionTime |#| IN droDataAvailable(), topic name: LTS_PartitionTime, type name Core::PartitionTime, this: 0x24d4580, m_dataReaderObject: 0x24ec320, hasSamples: 1 (urce/Lts/DDS/Core/../../DDS/DTC/generic_dtc_impl.h:210)
2021-02-03 15:50:39.903 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| IN read (Core::PartitionTime), this: 0x24ec320, instance handle 0101aaeead199ead8d523da780000004 (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:167)
2021-02-03 15:50:39.903 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| got 1 samples from reader for Core::PartitionTime (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:197)
2021-02-03 15:50:39.904 DEBUG [0x0000000002413aa0] DDS::DTC::SubscriberListener |#| Data available for LTS_PartitionTime, type Core::PartitionTime, this 0x21f0f80 (TDS-source/Lts/DDS/Generic/subscriber_listener.cpp:99)
2021-02-03 15:50:39.904 DEBUG [0x0000000001dfc6f0] DDS::DataReader::Core::PartitionTime |#| sampleSize = 1 (s/DDS/Core/../../DDS/Generic/generic_data_reader.h:122)
2021-02-03 15:50:39.905 DEBUG [0x0000000001dfc6f0] DDS::DTC::Core::PartitionTime |#| IN droDataAvailable(), topic name: LTS_PartitionTime, type name Core::PartitionTime, this: 0x24d4580, m_dataReaderObject: 0x24ec320, hasSamples: 1 (urce/Lts/DDS/Core/../../DDS/DTC/generic_dtc_impl.h:210)


...

2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] GNA::WebSocketHandler |#| incoming telegram: {"type": "NasatWeaponRelease", "data": {"releaseMode": 0, "munition": 2, "timestamp": 1612363870.398409, "fuseType": 1, "impactPosition": {"lat": 53.061, "lon": 8.9711}, "aircraftId": 1, "flightTime": 5.1234}, "uuid": "NasatWeaponRelease-UUID"} (/Lts/Proxies/GuezNasat/abstract_socket_handler.cpp:53)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| void GuezNasat::HandlerNasatImpact::nasatImpact(int, const Core::GeoPosition&, qint64, int, int) START, nasatId=1, pos=[[lon: 0.156575232525663, lat: 0.926089154400711]z: 0], impactTimeMsec=1612363875522 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:59)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  Sending air support impact: number of participant= 2 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:81)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=1, this=0x2c43570, threadId=139905918381760, m_terminate=0 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:157)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| thread is still running - just fill m_requests., this=0x2c43570, threadId=139905918381760, m_requests=0x2c43f68, m_requests.size()=0), request.uniqueId=2 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:174)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| Sending air support impact create request: [id: 0, name: NASAT_1_2_03 15:51:10, effectStart: 1612363875522, chargeTypeId: 472, impactPosition: [lon: 0.156575232525663, lat: 0.926089154400711], partyId: 3, participantId: 90, flightTime: 5123, externalId: null] to exercise 42, nap=[id: 1, nasatAircraftId: 1, exerciseId: 42, participantId: 90] -> success = 1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:88)
2021-02-03 15:51:10.398 INFO  [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  requestCounter =  3 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:97)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=1, this=0x2c45380, threadId=139905918381760, m_terminate=2 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:157)
2021-02-03 15:51:10.398 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData - fill m_requests and start new thread., this=0x2c45380, threadId=139905918381760, m_requests=0x2c45d78, m_requests.size()=0), request.uniqueId=2 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:189)
2021-02-03 15:51:10.399 DEBUG [0x0000000001dfc6f0] DDS::FTC::AirSupportImpactModify |#| requestData m_future.valid()=1, this=0x2c45380, threadId=139905918381760, m_terminate=0 done (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:200)
2021-02-03 15:51:10.399 DEBUG [0x00007f3d9c007080] DDS::FTC::AirSupportImpactModify |#|  START WHILE LOOP.., this=0x2c45380, threadId=139902712801024, m_requests=0x2c45d78, m_requests.size()=1 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:225)
2021-02-03 15:51:10.399 DEBUG [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#| Sending air support impact create request: [id: 0, name: NASAT_1_2_03 15:51:10, effectStart: 1612363875522, chargeTypeId: 472, impactPosition: [lon: 0.156575232525663, lat: 0.926089154400711], partyId: 3, participantId: 62, flightTime: 5123, externalId: null] to exercise 35, nap=[id: 8, nasatAircraftId: 1, exerciseId: 35, participantId: 62] -> success = 1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:88)
2021-02-03 15:51:10.399 DEBUG [0x00007f3d9c007080] DDS::FTC::AirSupportImpactModify |#| IN waitForEvents, this=0x2c45380, request.uniqueId=2, threadId=139902712801024 (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:245)
2021-02-03 15:51:10.399 INFO  [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  requestCounter =  4 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:97)
2021-02-03 15:51:10.399 INFO  [0x00007f3d9c007080] DDS::FTC::AirSupportImpactModify |#| #sendRequest: SeqNumber: -1, this=0x2c45380, request.uniqueId=2, threadId=139902712801024 ... (ts/DDS/QosProfile/../../DDS/FTC/generic_ftc_impl.h:261)
2021-02-03 15:51:10.399 FATAL [0x0000000001dfc6f0] GNA::HandlerNasatImpact |#|  bOk= 0, requestCounter =  4, replyCounter =  1 (rce/Lts/Proxies/GuezNasat/handler_nasat_impact.cpp:102)

