2023-05-15T20:59:14.750Z,1684184354.750 [CommandExec](IMPORTANT): got command restart logs
2023-05-15T20:59:22.909Z,1684184362.909 [DAT](INFO): DAT read:
2023-05-15T20:59:22.910Z,1684184362.910 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series
2023-05-15T20:59:24.673Z,1684184364.673 [DAT](INFO): DAT read: MF Frequency Band
2023-05-15T20:59:24.674Z,1684184364.674 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0
2023-05-15T20:59:24.675Z,1684184364.675 [DAT](INFO): DAT read: May 15 2023 20:59:19
2023-05-15T20:59:25.937Z,1684184365.937 [DAT](INFO): DAT read: Features enabled [Bearing]
2023-05-15T20:59:25.939Z,1684184365.939 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T20:59:25.939Z,1684184365.939 [DAT](INFO): commRate: 800
2023-05-15T20:59:28.012Z,1684184368.012 [DAT](INFO): entering command mode
2023-05-15T20:59:28.012Z,1684184368.012 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.201Z,1684184368.201 [DAT](INFO): DAT read:
2023-05-15T20:59:28.202Z,1684184368.202 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.202Z,1684184368.202 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.453Z,1684184368.453 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.453Z,1684184368.453 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.704Z,1684184368.704 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.704Z,1684184368.704 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.956Z,1684184368.956 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:28.957Z,1684184368.957 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.208Z,1684184369.208 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.208Z,1684184369.208 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.460Z,1684184369.460 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.460Z,1684184369.460 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.713Z,1684184369.713 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.713Z,1684184369.713 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.964Z,1684184369.964 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:29.964Z,1684184369.964 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.216Z,1684184370.216 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.217Z,1684184370.217 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.468Z,1684184370.468 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.468Z,1684184370.468 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.720Z,1684184370.720 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.721Z,1684184370.721 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.972Z,1684184370.972 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:30.973Z,1684184370.973 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.224Z,1684184371.224 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.224Z,1684184371.224 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.477Z,1684184371.477 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.477Z,1684184371.477 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.728Z,1684184371.728 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.728Z,1684184371.728 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.980Z,1684184371.980 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:31.981Z,1684184371.981 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.232Z,1684184372.232 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.232Z,1684184372.232 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.485Z,1684184372.485 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.485Z,1684184372.485 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.736Z,1684184372.736 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.736Z,1684184372.736 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.988Z,1684184372.988 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:32.989Z,1684184372.989 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.240Z,1684184373.240 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.240Z,1684184373.240 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.492Z,1684184373.492 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.492Z,1684184373.492 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.745Z,1684184373.745 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.745Z,1684184373.745 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.996Z,1684184373.996 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:33.997Z,1684184373.997 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.248Z,1684184374.248 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.249Z,1684184374.249 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.500Z,1684184374.500 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.501Z,1684184374.501 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.752Z,1684184374.752 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:34.753Z,1684184374.753 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.004Z,1684184375.004 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.005Z,1684184375.005 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.256Z,1684184375.256 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.256Z,1684184375.256 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.508Z,1684184375.508 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.509Z,1684184375.509 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.761Z,1684184375.761 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.761Z,1684184375.761 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:35.805Z,1684184375.805 [NAL9602](INFO): Powering up NAL9602
2023-05-15T20:59:36.012Z,1684184376.012 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.013Z,1684184376.013 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.264Z,1684184376.264 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.265Z,1684184376.265 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.516Z,1684184376.516 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.516Z,1684184376.516 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.769Z,1684184376.769 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:36.769Z,1684184376.769 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.021Z,1684184377.021 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.021Z,1684184377.021 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.272Z,1684184377.272 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.272Z,1684184377.272 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.524Z,1684184377.524 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.524Z,1684184377.524 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.776Z,1684184377.776 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:37.776Z,1684184377.776 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.028Z,1684184378.028 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.028Z,1684184378.028 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.280Z,1684184378.280 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.281Z,1684184378.281 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.532Z,1684184378.532 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.532Z,1684184378.532 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.784Z,1684184378.784 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:38.785Z,1684184378.785 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.037Z,1684184379.037 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.037Z,1684184379.037 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.288Z,1684184379.288 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.289Z,1684184379.289 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.540Z,1684184379.540 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.540Z,1684184379.540 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.792Z,1684184379.792 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:39.792Z,1684184379.792 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.044Z,1684184380.044 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.044Z,1684184380.044 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.304Z,1684184380.304 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.305Z,1684184380.305 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.556Z,1684184380.556 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.556Z,1684184380.556 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.808Z,1684184380.808 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:40.808Z,1684184380.808 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.061Z,1684184381.061 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.061Z,1684184381.061 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.312Z,1684184381.312 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.312Z,1684184381.312 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.564Z,1684184381.564 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.565Z,1684184381.565 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.817Z,1684184381.817 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:41.817Z,1684184381.817 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.068Z,1684184382.068 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.068Z,1684184382.068 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.320Z,1684184382.320 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.321Z,1684184382.321 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.572Z,1684184382.572 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.572Z,1684184382.572 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.824Z,1684184382.824 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:42.824Z,1684184382.824 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:43.076Z,1684184383.076 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:43.076Z,1684184383.076 [DAT](FAULT): failed to enter command mode
2023-05-15T20:59:43.392Z,1684184383.392 [DAT](INFO): entering command mode
2023-05-15T20:59:43.392Z,1684184383.392 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T20:59:43.580Z,1684184383.580 [DAT](INFO): DAT read:
2023-05-15T20:59:43.581Z,1684184383.581 [DAT](INFO): DAT read: Command '+++' not found
2023-05-15T20:59:43.582Z,1684184383.582 [DAT](INFO): DAT read: Error
2023-05-15T20:59:43.582Z,1684184383.582 [DAT](INFO): setting verbose to 3
2023-05-15T20:59:43.833Z,1684184383.833 [DAT](INFO): DAT read: user:2>
2023-05-15T20:59:43.834Z,1684184383.834 [DAT](INFO): DAT read: Verbose | 3
2023-05-15T20:59:43.834Z,1684184383.834 [DAT](INFO): set verbose to 3
2023-05-15T20:59:43.834Z,1684184383.834 [DAT](INFO): setting DatVerbose to 27440
2023-05-15T20:59:44.085Z,1684184384.085 [DAT](INFO): DAT read: user:3>
2023-05-15T20:59:44.086Z,1684184384.086 [DAT](INFO): DAT read: DatVerbose | 27440
2023-05-15T20:59:44.086Z,1684184384.086 [DAT](INFO): set DatVerbose to 27440
2023-05-15T20:59:44.086Z,1684184384.086 [DAT](INFO): setting transmit power to 8
2023-05-15T20:59:44.337Z,1684184384.337 [DAT](INFO): DAT read: user:4>
2023-05-15T20:59:44.338Z,1684184384.338 [DAT](INFO): DAT read: TxPower | 8 (Max)
2023-05-15T20:59:44.338Z,1684184384.338 [DAT](INFO): set transmit power to 8
2023-05-15T20:59:44.338Z,1684184384.338 [DAT](INFO): setting local address to 12
2023-05-15T20:59:44.589Z,1684184384.589 [DAT](INFO): DAT read: user:5>
2023-05-15T20:59:44.590Z,1684184384.590 [DAT](INFO): DAT read: LocalAddr | 12
2023-05-15T20:59:44.590Z,1684184384.590 [DAT](INFO): set local address to 12
2023-05-15T20:59:44.591Z,1684184384.591 [DAT](INFO): Setting time to: 20:59:44 And date to:5/15/2023
2023-05-15T20:59:44.841Z,1684184384.841 [DAT](INFO): DAT read: user:6>
2023-05-15T20:59:44.842Z,1684184384.842 [DAT](INFO): DAT read: Mon May 15, 2023 20:59:44
2023-05-15T20:59:44.842Z,1684184384.842 [DAT](INFO): Local DAT time set to Mon May 15, 2023 20:59:44
2023-05-15T20:59:44.842Z,1684184384.842 [DAT](INFO): setting remote address to 10
2023-05-15T20:59:45.093Z,1684184385.093 [DAT](INFO): DAT read: user:7>
2023-05-15T20:59:45.094Z,1684184385.094 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T20:59:45.094Z,1684184385.094 [DAT](INFO): set remote address to 10
2023-05-15T20:59:45.094Z,1684184385.094 [DAT](INFO): entering online mode
2023-05-15T20:59:45.345Z,1684184385.345 [DAT](INFO): DAT read: user:8>
2023-05-15T20:59:45.345Z,1684184385.345 [DAT](INFO): DAT read:
2023-05-15T20:59:45.346Z,1684184385.346 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T20:59:45.347Z,1684184385.347 [DAT](INFO): commRate: 800
2023-05-15T20:59:45.347Z,1684184385.347 [DAT](INFO): online mode acknowledged
2023-05-15T20:59:45.347Z,1684184385.347 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T20:59:46.709Z,1684184386.709 [NAL9602](INFO): NAL9602 initialized
2023-05-15T20:59:48.621Z,1684184388.621 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:59:48.0078
2023-05-15T20:59:48.621Z,1684184388.621 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T20:59:54.686Z,1684184394.686 [DAT](INFO): DAT read: Rx Time:20:59:53.6456
2023-05-15T20:59:54.687Z,1684184394.687 [DAT](INFO): Rx dataTimestamp_ set to:1684184393.645599
2023-05-15T20:59:54.688Z,1684184394.688 [DAT](INFO): received an acoustic signal
2023-05-15T20:59:54.872Z,1684184394.872 [CommandExec](IMPORTANT): got command run ./Missions/Demo/senddata_direct_and_track_test.xml
2023-05-15T20:59:54.900Z,1684184394.900 [MissionManager](INFO): Loading Mission from file: ./Missions/Demo/senddata_direct_and_track_test.xml
2023-05-15T20:59:54.961Z,1684184394.961 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.AcousticTargetContactLabel = 10.000000 count
2023-05-15T20:59:54.964Z,1684184394.964 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.AcousticTargetDepth = 0.000000 m
2023-05-15T20:59:54.967Z,1684184394.967 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.TrackingUpdatePeriod = 15.000000 s
2023-05-15T20:59:54.969Z,1684184394.969 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.NumberOfPings = 1.000000 count
2023-05-15T20:59:54.972Z,1684184394.972 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.NumberOfFixesLowPass = 2.000000 count
2023-05-15T20:59:54.974Z,1684184394.974 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.NumberOfStartingFixesToIgnore = 2.000000 count
2023-05-15T20:59:54.977Z,1684184394.977 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.BeingInterrogatedTimeout = 1.000000 h
2023-05-15T20:59:54.979Z,1684184394.979 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.AcommsInterval = 1.000000 min
2023-05-15T20:59:55.032Z,1684184395.032 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.modemId1 = 9.000000 enum
2023-05-15T20:59:55.034Z,1684184395.034 [MissionManager](INFO): DefineArg senddata_direct_and_track_test.modemId2 = 5.000000 enum
2023-05-15T20:59:55.040Z,1684184395.040 [MissionManager](INFO): DefineOutput senddata_direct_and_track_test.ModemID = 1.000000 enum
2023-05-15T20:59:55.041Z,1684184395.041 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/AbortDrift.xml
2023-05-15T20:59:55.073Z,1684184395.073 [MissionManager](INFO): DefineArg senddata_direct_and_track_test:AbortDrift.AcousticTimeout = 96.000000 h
2023-05-15T20:59:55.075Z,1684184395.075 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](DEBUG): Construct AbortDrift.
2023-05-15T20:59:55.077Z,1684184395.077 [senddata_direct_and_track_test:AbortDrift:C.Execute](DEBUG): Construct Execute.
2023-05-15T20:59:55.079Z,1684184395.079 [MissionManager](INFO): RedefineArg senddata_direct_and_track_test:AbortDrift.AcousticTimeout = reader:senddata_direct_and_track_test.BeingInterrogatedTimeout
2023-05-15T20:59:55.105Z,1684184395.105 [senddata_direct_and_track_test:DirectData:A.Wait](DEBUG): Construct Wait.
2023-05-15T20:59:55.122Z,1684184395.122 [MissionManager](DEBUG):
The acoustic address of the asset to be tracked. 21 is waveglider Tiny
10
Depth of acoustic target if known and fixed (or nearly fixed). For
example, if the acoustic target is a Wave Glider, set it to zero. This
will improve 2D projected position estimates in the Earth reference
frame. Defaults to NaN.
0
How long to wait between acoustic queries
15
Number of return pings to request with each acoustic query (more than 1
will activate oneway mode)
1
Number of fixes to average to produce smoothed lat/lon/dep output
2
Number of fixes to ignore at the start of mission (as the vehicle just
leaves surface, contact's location estimate especailly bearing can be
erroneous. Initialized to 8, corresponding to 2 minutes if query
interval TrackingUpdatePeriod = 15 s.
2
If the vehicle does not receive an acoustic signal for more than this
length of time, it will surface for communications. Set longer than
MissionTimeout to effectively disable.
1
1
Modem ID1.
9
Modem ID2.
5
Modem ID. Set to modemId1 or modemId2. Initialized to 1.
1
2023-05-15T20:59:55.124Z,1684184395.124 [CommandExec](IMPORTANT): Running ./Missions/Demo/senddata_direct_and_track_test.xml
2023-05-15T20:59:55.239Z,1684184395.239 [Default] Stopped
2023-05-15T20:59:55.239Z,1684184395.239 [Default](DEBUG): Aggregate::uninitialize Default
2023-05-15T20:59:55.239Z,1684184395.239 [Default:B.GoToSurface] Stopped
2023-05-15T20:59:55.239Z,1684184395.239 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-15T20:59:55.239Z,1684184395.239 [Default:CheckIn] Stopped
2023-05-15T20:59:55.240Z,1684184395.240 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-15T20:59:55.240Z,1684184395.240 [Default:CheckIn:Read_GPS] Stopped
2023-05-15T20:59:55.240Z,1684184395.240 [MissionManager](IMPORTANT): Started mission senddata_direct_and_track_test
2023-05-15T20:59:55.240Z,1684184395.240 [senddata_direct_and_track_test] Running Loop=1
2023-05-15T20:59:55.240Z,1684184395.240 [senddata_direct_and_track_test](DEBUG): Aggregate::initialize senddata_direct_and_track_test
2023-05-15T20:59:55.240Z,1684184395.240 [senddata_direct_and_track_test:AbortDrift] Running Loop=1
2023-05-15T20:59:55.240Z,1684184395.240 [senddata_direct_and_track_test:AbortDrift](DEBUG): Aggregate::initialize senddata_direct_and_track_test:AbortDrift
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:AbortDrift:A] Running Loop=1
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:TrackAC.] Running Loop=1
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:TrackAC.](INFO): Initializing TrackAcousticContact.
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:DirectData] Running Loop=1
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:DirectData](DEBUG): Aggregate::initialize senddata_direct_and_track_test:DirectData
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:DirectData:A.Wait] Running Loop=1
2023-05-15T20:59:55.241Z,1684184395.241 [senddata_direct_and_track_test:DirectData:A.Wait](DEBUG): Initialize Wait Component.
2023-05-15T20:59:55.242Z,1684184395.242 [senddata_direct_and_track_test:TrackAC.] Running Loop=1
2023-05-15T20:59:55.242Z,1684184395.242 [senddata_direct_and_track_test:TrackAC.](INFO): DAT did not provide matching contact label.
2023-05-15T20:59:55.242Z,1684184395.242 [senddata_direct_and_track_test:AbortDrift] Running Loop=1
2023-05-15T20:59:55.243Z,1684184395.243 [senddata_direct_and_track_test:AbortDrift:A](INFO): Insert acoustic timeout set to 1.000000 h .
2023-05-15T20:59:55.243Z,1684184395.243 [senddata_direct_and_track_test:AbortDrift:A] Stopped
2023-05-15T20:59:55.243Z,1684184395.243 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift] Running Loop=1
2023-05-15T20:59:55.243Z,1684184395.243 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Initializing AbortDrift.
2023-05-15T20:59:55.243Z,1684184395.243 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](IMPORTANT): Acoustic timeout set to: 1.00 hours.
2023-05-15T20:59:55.442Z,1684184395.442 [DAT](INFO): DAT read: 20:59:53.6456 LVL= 4320, 5057, 4674, 5731, AGC= 34, IDX= 386, 0.23,-0.229,-0.201,-0.465,-0.047, PHS=-0.198,-0.079,-0.370, RAW= 6.1, 42.1, CAL= 6.7, 49.1, ROT= 143.3, -49.1
2023-05-15T20:59:55.443Z,1684184395.443 [DAT](INFO): got valid direction response:
20:59:53.6456 LVL= 4320, 5057, 4674, 5731, AGC= 34, IDX= 386, 0.23,-0.229,-0.201,-0.465,-0.047, PHS=-0.198,-0.079,-0.370, RAW= 6.1, 42.1, CAL= 6.7, 49.1, ROT= 143.3, -49.1
2023-05-15T20:59:55.444Z,1684184395.444 [DAT](INFO): DAT read:
2023-05-15T20:59:55.445Z,1684184395.445 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T20:59:55.445Z,1684184395.445 [DAT](INFO): Got DATA 2
2023-05-15T20:59:55.446Z,1684184395.446 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T20:59:55.446Z,1684184395.446 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T20:59:55.446Z,1684184395.446 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T20:59:55.447Z,1684184395.447 [DAT](INFO): DAT read: CRC:Pass MPD:03.4 PSNR:17.5 AGC:35 SPD:-0.1 CCERR:013
2023-05-15T20:59:55.447Z,1684184395.447 [DAT](INFO): Got CRC:Pass
2023-05-15T20:59:55.448Z,1684184395.448 [DAT](INFO): Got CRC:Pass
2023-05-15T20:59:55.448Z,1684184395.448 [DAT](INFO): Incoming data is intended for us
2023-05-15T20:59:55.448Z,1684184395.448 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T20:59:55.448Z,1684184395.448 [DAT](INFO): Got ack
2023-05-15T20:59:55.448Z,1684184395.448 [DAT](INFO): DAT read:
2023-05-15T20:59:55.449Z,1684184395.449 [DAT](INFO): DAT read:
2023-05-15T20:59:55.449Z,1684184395.449 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T20:59:55.449Z,1684184395.449 [DAT](INFO): #Rx 2: Read direction message, but no range.
2023-05-15T20:59:55.450Z,1684184395.450 [DAT](INFO): direction in FSK: [-0.524955,0.391290,0.755853]
2023-05-15T20:59:55.654Z,1684184395.654 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid gps time fix: 1684183552.00. Resetting abort timer.
2023-05-15T20:59:55.655Z,1684184395.655 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T20:59:55.689Z,1684184395.689 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T20:59:55.941Z,1684184395.941 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T20:59:59.217Z,1684184399.217 [DAT](INFO): DAT read: Forwarding Delay UpTx time:20:59:58.6078
2023-05-15T20:59:59.217Z,1684184399.217 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:00:05.265Z,1684184405.265 [DAT](INFO): DAT read: Rx Time:21:00:04.2456
2023-05-15T21:00:05.266Z,1684184405.266 [DAT](INFO): Rx dataTimestamp_ set to:1684184404.245600
2023-05-15T21:00:05.266Z,1684184405.266 [DAT](INFO): received an acoustic signal
2023-05-15T21:00:06.027Z,1684184406.027 [DAT](INFO): DAT read: 21:00:04.2456 LVL= 4064, 4961, 4594, 5859, AGC= 36, IDX= 185, 0.08,-2.493,-2.838, 3.066,-2.371, PHS=-0.138,-0.392,-0.798, RAW= 52.4, 39.1, CAL= 51.9, 47.7, ROT= 98.1, -47.7
2023-05-15T21:00:06.028Z,1684184406.028 [DAT](INFO): got valid direction response:
21:00:04.2456 LVL= 4064, 4961, 4594, 5859, AGC= 36, IDX= 185, 0.08,-2.493,-2.838, 3.066,-2.371, PHS=-0.138,-0.392,-0.798, RAW= 52.4, 39.1, CAL= 51.9, 47.7, ROT= 98.1, -47.7
2023-05-15T21:00:06.028Z,1684184406.028 [DAT](INFO): DAT read:
2023-05-15T21:00:06.029Z,1684184406.029 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:00:06.029Z,1684184406.029 [DAT](INFO): Got DATA 2
2023-05-15T21:00:06.030Z,1684184406.030 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:00:06.030Z,1684184406.030 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:00:06.030Z,1684184406.030 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:00:06.031Z,1684184406.031 [DAT](INFO): DAT read: CRC:Pass MPD:03.5 PSNR:17.5 AGC:36 SPD:+0.0 CCERR:013
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](INFO): Got CRC:Pass
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](INFO): Got CRC:Pass
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](INFO): Got ack
2023-05-15T21:00:06.032Z,1684184406.032 [DAT](INFO): DAT read:
2023-05-15T21:00:06.033Z,1684184406.033 [DAT](INFO): DAT read:
2023-05-15T21:00:06.033Z,1684184406.033 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:00:06.033Z,1684184406.033 [DAT](INFO): #Rx 3: Read direction message, but no range.
2023-05-15T21:00:06.034Z,1684184406.034 [DAT](INFO): direction in FSK: [-0.094828,0.666298,0.739631]
2023-05-15T21:00:06.162Z,1684184406.162 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:00:10.597Z,1684184410.597 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:00:10.809Z,1684184410.809 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:10.809Z,1684184410.809 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:10.872Z,1684184410.872 [DAT](INFO): entering command mode
2023-05-15T21:00:11.061Z,1684184411.061 [DAT](INFO): DAT read:
2023-05-15T21:00:11.061Z,1684184411.061 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:11.061Z,1684184411.061 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:11.061Z,1684184411.061 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:11.313Z,1684184411.313 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:11.313Z,1684184411.313 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:11.313Z,1684184411.313 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:11.564Z,1684184411.564 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:11.565Z,1684184411.565 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:11.565Z,1684184411.565 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:11.816Z,1684184411.816 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:11.817Z,1684184411.817 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:11.817Z,1684184411.817 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:12.068Z,1684184412.068 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:12.069Z,1684184412.069 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:12.069Z,1684184412.069 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:12.321Z,1684184412.321 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:12.321Z,1684184412.321 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:12.321Z,1684184412.321 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:12.573Z,1684184412.573 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:12.573Z,1684184412.573 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:12.573Z,1684184412.573 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:12.824Z,1684184412.824 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:12.825Z,1684184412.825 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:12.825Z,1684184412.825 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:13.077Z,1684184413.077 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:13.077Z,1684184413.077 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:13.077Z,1684184413.077 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:13.329Z,1684184413.329 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:13.329Z,1684184413.329 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:13.329Z,1684184413.329 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:13.581Z,1684184413.581 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:13.581Z,1684184413.581 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:13.581Z,1684184413.581 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:13.833Z,1684184413.833 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:13.833Z,1684184413.833 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:13.833Z,1684184413.833 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:14.084Z,1684184414.084 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:14.085Z,1684184414.085 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:14.085Z,1684184414.085 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:14.337Z,1684184414.337 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:14.337Z,1684184414.337 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:14.337Z,1684184414.337 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:14.588Z,1684184414.588 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:14.589Z,1684184414.589 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:14.589Z,1684184414.589 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:14.840Z,1684184414.840 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:14.841Z,1684184414.841 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:14.841Z,1684184414.841 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:15.093Z,1684184415.092 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:15.093Z,1684184415.093 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:15.093Z,1684184415.093 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:15.345Z,1684184415.345 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:15.345Z,1684184415.345 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:15.345Z,1684184415.345 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:15.597Z,1684184415.597 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:15.597Z,1684184415.597 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:15.597Z,1684184415.597 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:15.849Z,1684184415.849 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:15.849Z,1684184415.849 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:15.849Z,1684184415.849 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:16.100Z,1684184416.100 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:16.101Z,1684184416.101 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:16.101Z,1684184416.101 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:16.353Z,1684184416.353 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:16.353Z,1684184416.353 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:16.353Z,1684184416.353 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:16.605Z,1684184416.605 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:16.605Z,1684184416.605 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:16.605Z,1684184416.605 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:16.857Z,1684184416.857 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:16.857Z,1684184416.857 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:16.857Z,1684184416.857 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:17.109Z,1684184417.109 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:17.109Z,1684184417.109 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:17.109Z,1684184417.109 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:17.361Z,1684184417.361 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:17.361Z,1684184417.361 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:17.361Z,1684184417.361 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:17.613Z,1684184417.613 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:17.613Z,1684184417.613 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:17.613Z,1684184417.613 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:17.865Z,1684184417.865 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:17.865Z,1684184417.865 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:17.865Z,1684184417.865 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:18.117Z,1684184418.117 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:18.117Z,1684184418.117 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:18.117Z,1684184418.117 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:18.369Z,1684184418.369 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:18.369Z,1684184418.369 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:18.369Z,1684184418.369 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:18.620Z,1684184418.620 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:18.621Z,1684184418.621 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:18.621Z,1684184418.621 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:18.873Z,1684184418.873 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:18.873Z,1684184418.873 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:18.873Z,1684184418.873 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:19.125Z,1684184419.125 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:19.125Z,1684184419.125 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:19.125Z,1684184419.125 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:19.377Z,1684184419.377 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:19.377Z,1684184419.377 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:19.377Z,1684184419.377 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:19.629Z,1684184419.629 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:19.629Z,1684184419.629 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:19.629Z,1684184419.629 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:19.881Z,1684184419.881 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:19.881Z,1684184419.881 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:19.881Z,1684184419.881 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:20.132Z,1684184420.132 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:20.133Z,1684184420.133 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:20.133Z,1684184420.133 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:20.385Z,1684184420.385 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:20.385Z,1684184420.385 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:20.385Z,1684184420.385 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:20.636Z,1684184420.636 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:20.637Z,1684184420.637 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:20.637Z,1684184420.637 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:20.888Z,1684184420.888 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:20.889Z,1684184420.889 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:20.889Z,1684184420.889 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:21.141Z,1684184421.141 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:21.141Z,1684184421.141 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:21.141Z,1684184421.141 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:21.392Z,1684184421.392 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:21.393Z,1684184421.393 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:21.393Z,1684184421.393 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:21.645Z,1684184421.645 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:21.645Z,1684184421.645 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:21.645Z,1684184421.645 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:21.896Z,1684184421.896 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:21.897Z,1684184421.897 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:21.897Z,1684184421.897 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:22.148Z,1684184422.148 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:22.149Z,1684184422.149 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:22.149Z,1684184422.149 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:22.401Z,1684184422.401 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:22.401Z,1684184422.401 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:22.401Z,1684184422.401 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:22.652Z,1684184422.652 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:22.652Z,1684184422.652 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:22.653Z,1684184422.653 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:22.907Z,1684184422.907 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:22.908Z,1684184422.908 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:22.908Z,1684184422.908 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:23.157Z,1684184423.157 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:23.157Z,1684184423.157 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:23.157Z,1684184423.157 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:23.408Z,1684184423.408 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:23.409Z,1684184423.409 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:23.409Z,1684184423.409 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:23.661Z,1684184423.661 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:23.661Z,1684184423.661 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:23.661Z,1684184423.661 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:23.913Z,1684184423.913 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:23.913Z,1684184423.913 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:23.913Z,1684184423.913 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:24.165Z,1684184424.165 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:24.165Z,1684184424.165 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:24.165Z,1684184424.165 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:24.417Z,1684184424.417 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:24.417Z,1684184424.417 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:24.417Z,1684184424.417 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:24.668Z,1684184424.668 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:24.669Z,1684184424.669 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:24.669Z,1684184424.669 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:24.920Z,1684184424.920 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:24.921Z,1684184424.921 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:24.921Z,1684184424.921 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:25.173Z,1684184425.173 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:25.173Z,1684184425.173 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:25.173Z,1684184425.173 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:25.424Z,1684184425.424 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:25.425Z,1684184425.425 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:25.425Z,1684184425.425 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:25.677Z,1684184425.677 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:25.677Z,1684184425.677 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:25.677Z,1684184425.677 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:25.929Z,1684184425.929 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:25.929Z,1684184425.929 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:25.929Z,1684184425.929 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:00:25.929Z,1684184425.929 [DAT](FAULT): failed to enter command mode
2023-05-15T21:00:25.930Z,1684184425.930 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:00:26.180Z,1684184426.180 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:26.181Z,1684184426.181 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:26.244Z,1684184426.244 [DAT](INFO): entering command mode
2023-05-15T21:00:26.433Z,1684184426.433 [DAT](INFO): DAT read:
2023-05-15T21:00:26.433Z,1684184426.433 [DAT](INFO): DAT read: Command '+++' not found
2023-05-15T21:00:26.434Z,1684184426.434 [DAT](INFO): DAT read: Error
2023-05-15T21:00:26.434Z,1684184426.434 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:26.434Z,1684184426.434 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:26.434Z,1684184426.434 [DAT](INFO): setting remote address to 0
2023-05-15T21:00:26.685Z,1684184426.685 [DAT](INFO): DAT read: user:10>
2023-05-15T21:00:26.686Z,1684184426.686 [DAT](INFO): DAT read: RemoteAddr | 0
2023-05-15T21:00:26.686Z,1684184426.686 [DAT](INFO): set remote address to 0
2023-05-15T21:00:26.686Z,1684184426.686 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:26.687Z,1684184426.687 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:26.687Z,1684184426.687 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:00:26.937Z,1684184426.937 [DAT](INFO): DAT read: user:11>
2023-05-15T21:00:26.937Z,1684184426.937 [DAT](INFO): DAT read: Tx time:21:00:26.2585
2023-05-15T21:00:26.938Z,1684184426.938 [DAT](INFO): Ping request sent.
2023-05-15T21:00:26.938Z,1684184426.938 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:00:26.938Z,1684184426.938 [DAT](INFO): publishing transmit ping time
2023-05-15T21:00:26.938Z,1684184426.938 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000725
2023-05-15T21:00:27.189Z,1684184427.189 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.251242
2023-05-15T21:00:27.441Z,1684184427.441 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502894
2023-05-15T21:00:27.693Z,1684184427.693 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754987
2023-05-15T21:00:27.945Z,1684184427.945 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.007074
2023-05-15T21:00:28.197Z,1684184428.197 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258909
2023-05-15T21:00:28.449Z,1684184428.449 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.511024
2023-05-15T21:00:28.701Z,1684184428.701 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.762911
2023-05-15T21:00:28.953Z,1684184428.953 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.015007
2023-05-15T21:00:29.205Z,1684184429.205 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.266972
2023-05-15T21:00:29.457Z,1684184429.457 [DAT](INFO): DAT read: Rx Time:21:00:28.2890
2023-05-15T21:00:29.458Z,1684184429.458 [DAT](INFO): Rx dataTimestamp_ set to:1684184428.289000
2023-05-15T21:00:29.458Z,1684184429.458 [DAT](INFO): received an acoustic signal
2023-05-15T21:00:29.459Z,1684184429.459 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.521067
2023-05-15T21:00:29.709Z,1684184429.709 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.771140
2023-05-15T21:00:29.961Z,1684184429.961 [DAT](INFO): DAT read: Bearing 102, 26 (Remote)
2023-05-15T21:00:29.961Z,1684184429.961 [DAT](INFO): Remote Bearing received:Bearing 102, 26 (Remote)
2023-05-15T21:00:29.963Z,1684184429.963 [DAT](INFO): DAT read: Range 12 to 10 : 0.9 m (Round-trip 1.3 ms) speed 0.0 m/s
2023-05-15T21:00:29.963Z,1684184429.963 [DAT](ERROR): #Rx 1: Read range message, but no direction.
2023-05-15T21:00:29.973Z,1684184429.973 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:00:30.022Z,1684184430.022 [Reporter](INFO): DAT.acoustic_contact_range 0.900000 m
2023-05-15T21:00:30.023Z,1684184430.023 [Reporter](INFO): acoustic_contact_range 0.900000 m
2023-05-15T21:00:41.354Z,1684184441.354 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:00:41.572Z,1684184441.572 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:41.573Z,1684184441.573 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:41.573Z,1684184441.573 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:00:41.825Z,1684184441.825 [DAT](INFO): DAT read: user:12>
2023-05-15T21:00:41.825Z,1684184441.825 [DAT](INFO): DAT read: Tx time:21:00:41.1584
2023-05-15T21:00:41.826Z,1684184441.826 [DAT](INFO): Ping request sent.
2023-05-15T21:00:41.826Z,1684184441.826 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:00:41.826Z,1684184441.826 [DAT](INFO): publishing transmit ping time
2023-05-15T21:00:41.827Z,1684184441.827 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000742
2023-05-15T21:00:42.083Z,1684184442.083 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.257036
2023-05-15T21:00:42.337Z,1684184442.337 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.510881
2023-05-15T21:00:42.589Z,1684184442.589 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.762769
2023-05-15T21:00:42.841Z,1684184442.841 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.014795
2023-05-15T21:00:43.093Z,1684184443.093 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.266871
2023-05-15T21:00:43.345Z,1684184443.345 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.518907
2023-05-15T21:00:43.597Z,1684184443.597 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.770854
2023-05-15T21:00:43.849Z,1684184443.849 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.022779
2023-05-15T21:00:44.101Z,1684184444.101 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.275000
2023-05-15T21:00:44.353Z,1684184444.353 [DAT](INFO): DAT read: Rx Time:21:00:43.1889
2023-05-15T21:00:44.354Z,1684184444.354 [DAT](INFO): Rx dataTimestamp_ set to:1684184443.188900
2023-05-15T21:00:44.354Z,1684184444.354 [DAT](INFO): received an acoustic signal
2023-05-15T21:00:44.355Z,1684184444.355 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.529072
2023-05-15T21:00:44.605Z,1684184444.605 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.778888
2023-05-15T21:00:44.862Z,1684184444.862 [DAT](INFO): DAT read: 21:00:43.1889 LVL= 5136, 6337, 5810, 7139, AGC= 36, IDX= 171,-0.21,-0.666,-0.380,-1.867, 0.650, PHS=-1.332,-0.955,-2.469, RAW= 16.1, 50.9, CAL= 16.6, 57.0, ROT= 133.4, -57.0
2023-05-15T21:00:44.863Z,1684184444.863 [DAT](INFO): got valid direction response:
21:00:43.1889 LVL= 5136, 6337, 5810, 7139, AGC= 36, IDX= 171,-0.21,-0.666,-0.380,-1.867, 0.650, PHS=-1.332,-0.955,-2.469, RAW= 16.1, 50.9, CAL= 16.6, 57.0, ROT= 133.4, -57.0
2023-05-15T21:00:44.865Z,1684184444.865 [DAT](INFO): DAT read: Bearing 104, 25 (Remote)
2023-05-15T21:00:44.865Z,1684184444.865 [DAT](INFO): Remote Bearing received:Bearing 104, 25 (Remote)
2023-05-15T21:00:44.866Z,1684184444.866 [DAT](INFO): DAT read: Bearing 277.8, -56.1 (Local)
2023-05-15T21:00:44.866Z,1684184444.866 [DAT](INFO): Local bearing/azimuth received:
Bearing 277.8, -56.1 (Local)
2023-05-15T21:00:44.867Z,1684184444.867 [DAT](INFO): DAT read: Range 12 to 10 : 0.9 m (Round-trip 1.3 ms) speed 0.0 m/s
2023-05-15T21:00:44.868Z,1684184444.868 [DAT](INFO): #Rx 1: Read range and direction messages.
2023-05-15T21:00:44.869Z,1684184444.869 [DAT](INFO): direction in FSK: [-0.374215,0.395721,0.838671]
2023-05-15T21:00:44.869Z,1684184444.869 [DAT](INFO): publishing direction and range info
2023-05-15T21:00:44.981Z,1684184444.981 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:00:45.009Z,1684184445.009 [Reporter](INFO): DAT.acoustic_contact_range 0.900000 m
2023-05-15T21:00:45.009Z,1684184445.009 [Reporter](INFO): acoustic_contact_range 0.900000 m
2023-05-15T21:00:45.010Z,1684184445.010 [Reporter](INFO): TrackAcousticContact.contact_latitude 0.642281 rad
2023-05-15T21:00:45.010Z,1684184445.010 [Reporter](INFO): TrackAcousticContact.contact_longitude -2.127556 rad
2023-05-15T21:00:55.414Z,1684184455.414 [senddata_direct_and_track_test:DirectData:A.Wait](INFO): Done Waiting.
2023-05-15T21:00:55.414Z,1684184455.414 [senddata_direct_and_track_test:DirectData:A.Wait] Stopped
2023-05-15T21:00:55.414Z,1684184455.414 [senddata_direct_and_track_test:DirectData:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-15T21:00:55.414Z,1684184455.414 [senddata_direct_and_track_test:DirectData:B] Running Loop=1
2023-05-15T21:00:55.823Z,1684184455.823 [senddata_direct_and_track_test:DirectData:B](INFO): Queuing up send data for Onboard.Pressure with destination: modem:10:_.pressure
2023-05-15T21:00:55.824Z,1684184455.824 [senddata_direct_and_track_test:DirectData:B] Stopped
2023-05-15T21:00:55.824Z,1684184455.824 [senddata_direct_and_track_test:DirectData:C] Running Loop=1
2023-05-15T21:00:55.953Z,1684184455.953 [DAT](INFO): modem://10: set _.pressure 0.746086 atmosphere
2023-05-15T21:00:55.954Z,1684184455.954 [DAT](INFO): #Outgoing data=1
2023-05-15T21:00:55.954Z,1684184455.954 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:00:56.205Z,1684184456.205 [DAT](INFO): setting remote address to 10
2023-05-15T21:00:56.236Z,1684184456.236 [senddata_direct_and_track_test:DirectData:C](INFO): Queuing up send data for Onboard.Temperature with destination: modem:10:_.temperature
2023-05-15T21:00:56.236Z,1684184456.236 [senddata_direct_and_track_test:DirectData:C] Stopped
2023-05-15T21:00:56.236Z,1684184456.236 [senddata_direct_and_track_test:DirectData:D] Running Loop=1
2023-05-15T21:00:56.457Z,1684184456.457 [DAT](INFO): DAT read: user:13>
2023-05-15T21:00:56.458Z,1684184456.458 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:00:56.458Z,1684184456.458 [DAT](INFO): set remote address to 10
2023-05-15T21:00:56.458Z,1684184456.458 [DAT](INFO): entering online mode
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData:D](INFO): Queuing up send data for Onboard.Humidity with destination: modem:10:_.humidity
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData:D] Stopped
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData](INFO): Completed senddata_direct_and_track_test:DirectData
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData] Stopped
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData](DEBUG): Aggregate::uninitialize senddata_direct_and_track_test:DirectData
2023-05-15T21:00:56.640Z,1684184456.640 [senddata_direct_and_track_test:DirectData](INFO): Running loop #2
2023-05-15T21:00:56.641Z,1684184456.641 [senddata_direct_and_track_test:DirectData] Running Loop=2
2023-05-15T21:00:56.641Z,1684184456.641 [senddata_direct_and_track_test:DirectData](DEBUG): Aggregate::initialize senddata_direct_and_track_test:DirectData
2023-05-15T21:00:56.641Z,1684184456.641 [senddata_direct_and_track_test:DirectData:A.Wait] Running Loop=1
2023-05-15T21:00:56.641Z,1684184456.641 [senddata_direct_and_track_test:DirectData:A.Wait](DEBUG): Initialize Wait Component.
2023-05-15T21:00:56.641Z,1684184456.641 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:00:56.709Z,1684184456.709 [DAT](INFO): DAT read: user:14>
2023-05-15T21:00:56.709Z,1684184456.709 [DAT](INFO): DAT read:
2023-05-15T21:00:56.710Z,1684184456.710 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:00:56.711Z,1684184456.711 [DAT](INFO): commRate: 800
2023-05-15T21:00:56.711Z,1684184456.711 [DAT](INFO): online mode acknowledged
2023-05-15T21:00:56.711Z,1684184456.711 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:00:56.711Z,1684184456.711 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:56.711Z,1684184456.711 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:56.961Z,1684184456.961 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:56.961Z,1684184456.961 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:57.212Z,1684184457.212 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:57.213Z,1684184457.213 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:57.464Z,1684184457.464 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:57.465Z,1684184457.465 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:57.717Z,1684184457.717 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:57.717Z,1684184457.717 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:57.969Z,1684184457.969 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:57.969Z,1684184457.969 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:58.221Z,1684184458.221 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:58.221Z,1684184458.221 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:58.472Z,1684184458.472 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:58.473Z,1684184458.473 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:58.725Z,1684184458.725 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:58.725Z,1684184458.725 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:58.788Z,1684184458.788 [DAT](INFO): entering command mode
2023-05-15T21:00:58.977Z,1684184458.977 [DAT](INFO): DAT read:
2023-05-15T21:00:58.977Z,1684184458.977 [DAT](INFO): DAT read: user:15>
2023-05-15T21:00:58.978Z,1684184458.978 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:58.978Z,1684184458.978 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:58.978Z,1684184458.978 [DAT](INFO): setting remote address to 0
2023-05-15T21:00:59.229Z,1684184459.229 [DAT](INFO): DAT read: user:15>
2023-05-15T21:00:59.230Z,1684184459.230 [DAT](INFO): DAT read: RemoteAddr | 0
2023-05-15T21:00:59.230Z,1684184459.230 [DAT](INFO): set remote address to 0
2023-05-15T21:00:59.230Z,1684184459.230 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:00:59.230Z,1684184459.230 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:00:59.231Z,1684184459.231 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:00:59.481Z,1684184459.481 [DAT](INFO): DAT read: user:16>
2023-05-15T21:00:59.481Z,1684184459.481 [DAT](INFO): DAT read: Tx time:21:00:58.8083
2023-05-15T21:00:59.482Z,1684184459.482 [DAT](INFO): Ping request sent.
2023-05-15T21:00:59.482Z,1684184459.482 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:00:59.482Z,1684184459.482 [DAT](INFO): publishing transmit ping time
2023-05-15T21:00:59.483Z,1684184459.483 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000812
2023-05-15T21:00:59.733Z,1684184459.733 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.250847
2023-05-15T21:00:59.985Z,1684184459.985 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.503017
2023-05-15T21:01:00.237Z,1684184460.237 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.755029
2023-05-15T21:01:00.489Z,1684184460.489 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.007440
2023-05-15T21:01:00.741Z,1684184460.741 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258937
2023-05-15T21:01:00.993Z,1684184460.993 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.510846
2023-05-15T21:01:01.245Z,1684184461.245 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.762963
2023-05-15T21:01:01.497Z,1684184461.497 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.015079
2023-05-15T21:01:01.749Z,1684184461.749 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.267327
2023-05-15T21:01:02.001Z,1684184462.001 [DAT](INFO): DAT read: Rx Time:21:01:00.8388
2023-05-15T21:01:02.002Z,1684184462.002 [DAT](INFO): Rx dataTimestamp_ set to:1684184460.838800
2023-05-15T21:01:02.002Z,1684184462.002 [DAT](INFO): received an acoustic signal
2023-05-15T21:01:02.003Z,1684184462.003 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.521030
2023-05-15T21:01:02.253Z,1684184462.253 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.770909
2023-05-15T21:01:02.510Z,1684184462.510 [DAT](INFO): DAT read: 21:01:00.8387 LVL= 5104, 6257, 5826, 7123, AGC= 36, IDX= 442, 0.07, 2.053, 1.681, 1.389, 2.136, PHS=-0.099,-0.380,-0.699, RAW= 57.9, 38.7, CAL= 56.7, 47.2, ROT= 93.3, -47.2
2023-05-15T21:01:02.512Z,1684184462.512 [DAT](INFO): got valid direction response:
21:01:00.8387 LVL= 5104, 6257, 5826, 7123, AGC= 36, IDX= 442, 0.07, 2.053, 1.681, 1.389, 2.136, PHS=-0.099,-0.380,-0.699, RAW= 57.9, 38.7, CAL= 56.7, 47.2, ROT= 93.3, -47.2
2023-05-15T21:01:02.513Z,1684184462.513 [DAT](INFO): DAT read: Bearing 103, 25 (Remote)
2023-05-15T21:01:02.513Z,1684184462.513 [DAT](INFO): Remote Bearing received:Bearing 103, 25 (Remote)
2023-05-15T21:01:02.514Z,1684184462.514 [DAT](INFO): DAT read: Bearing 235.3, -45.6 (Local)
2023-05-15T21:01:02.514Z,1684184462.514 [DAT](INFO): Local bearing/azimuth received:
Bearing 235.3, -45.6 (Local)
2023-05-15T21:01:02.515Z,1684184462.515 [DAT](INFO): DAT read: Range 12 to 10 : 0.9 m (Round-trip 1.3 ms) speed 0.0 m/s
2023-05-15T21:01:02.516Z,1684184462.516 [DAT](INFO): #Rx 1: Read range and direction messages.
2023-05-15T21:01:02.517Z,1684184462.517 [DAT](INFO): direction in FSK: [-0.039111,0.678315,0.733730]
2023-05-15T21:01:02.517Z,1684184462.517 [DAT](INFO): publishing direction and range info
2023-05-15T21:01:02.703Z,1684184462.703 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:01:02.713Z,1684184462.713 [Reporter](INFO): DAT.acoustic_contact_range 0.900000 m
2023-05-15T21:01:02.713Z,1684184462.713 [Reporter](INFO): acoustic_contact_range 0.900000 m
2023-05-15T21:01:02.714Z,1684184462.714 [Reporter](INFO): TrackAcousticContact.contact_latitude 0.642281 rad
2023-05-15T21:01:02.714Z,1684184462.714 [Reporter](INFO): TrackAcousticContact.contact_longitude -2.127556 rad
2023-05-15T21:01:06.789Z,1684184466.789 [DAT](FAULT): Buffer send receipt timeout failure.
2023-05-15T21:01:06.789Z,1684184466.789 [DAT](DEBUG): In sendingTransmitVerify, timeout so go online and set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:01:07.041Z,1684184467.041 [DAT](INFO): modem://10: set _.temperature 24.178980 celsius
2023-05-15T21:01:07.041Z,1684184467.041 [DAT](INFO): #Outgoing data=1
2023-05-15T21:01:07.042Z,1684184467.042 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:01:07.293Z,1684184467.293 [DAT](INFO): setting remote address to 10
2023-05-15T21:01:07.546Z,1684184467.546 [DAT](INFO): DAT read: user:17>
2023-05-15T21:01:07.547Z,1684184467.547 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:01:07.547Z,1684184467.547 [DAT](INFO): set remote address to 10
2023-05-15T21:01:07.547Z,1684184467.547 [DAT](INFO): entering online mode
2023-05-15T21:01:07.797Z,1684184467.797 [DAT](INFO): DAT read: user:18>
2023-05-15T21:01:07.797Z,1684184467.797 [DAT](INFO): DAT read:
2023-05-15T21:01:07.799Z,1684184467.799 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:01:07.799Z,1684184467.799 [DAT](INFO): commRate: 800
2023-05-15T21:01:07.799Z,1684184467.799 [DAT](INFO): online mode acknowledged
2023-05-15T21:01:07.799Z,1684184467.799 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:01:11.073Z,1684184471.073 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:01:10.4571
2023-05-15T21:01:11.073Z,1684184471.073 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:01:11.989Z,1684184471.989 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:01:12.081Z,1684184472.081 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:12.081Z,1684184472.081 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:12.144Z,1684184472.144 [DAT](INFO): entering command mode
2023-05-15T21:01:12.333Z,1684184472.333 [DAT](INFO): DAT read:
2023-05-15T21:01:12.333Z,1684184472.333 [DAT](INFO): DAT read: user:19>
2023-05-15T21:01:12.334Z,1684184472.334 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:12.334Z,1684184472.334 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:12.334Z,1684184472.334 [DAT](INFO): setting remote address to 0
2023-05-15T21:01:12.585Z,1684184472.585 [DAT](INFO): DAT read: user:19>
2023-05-15T21:01:12.586Z,1684184472.586 [DAT](INFO): DAT read: RemoteAddr | 0
2023-05-15T21:01:12.586Z,1684184472.586 [DAT](INFO): set remote address to 0
2023-05-15T21:01:12.586Z,1684184472.586 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:12.586Z,1684184472.586 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:12.587Z,1684184472.587 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:01:12.837Z,1684184472.837 [DAT](INFO): DAT read: user:20>
2023-05-15T21:01:12.837Z,1684184472.837 [DAT](INFO): DAT read: Tx time:21:01:12.1583
2023-05-15T21:01:12.838Z,1684184472.838 [DAT](INFO): Ping request sent.
2023-05-15T21:01:12.838Z,1684184472.838 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:01:12.838Z,1684184472.838 [DAT](INFO): publishing transmit ping time
2023-05-15T21:01:12.839Z,1684184472.839 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000754
2023-05-15T21:01:13.089Z,1684184473.089 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.250960
2023-05-15T21:01:13.341Z,1684184473.341 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502978
2023-05-15T21:01:13.593Z,1684184473.593 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754966
2023-05-15T21:01:13.845Z,1684184473.845 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.007131
2023-05-15T21:01:14.097Z,1684184474.097 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258971
2023-05-15T21:01:14.349Z,1684184474.349 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.510965
2023-05-15T21:01:14.601Z,1684184474.601 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.763089
2023-05-15T21:01:14.853Z,1684184474.853 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.014882
2023-05-15T21:01:15.105Z,1684184475.105 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.267123
2023-05-15T21:01:15.357Z,1684184475.357 [DAT](INFO): DAT read: Rx Time:21:01:14.1886
2023-05-15T21:01:15.358Z,1684184475.358 [DAT](INFO): Rx dataTimestamp_ set to:1684184474.188600
2023-05-15T21:01:15.358Z,1684184475.358 [DAT](INFO): received an acoustic signal
2023-05-15T21:01:15.359Z,1684184475.359 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.521119
2023-05-15T21:01:15.613Z,1684184475.613 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.775004
2023-05-15T21:01:15.865Z,1684184475.865 [DAT](INFO): DAT read: Bearing 102, 26 (Remote)
2023-05-15T21:01:15.866Z,1684184475.866 [DAT](INFO): Remote Bearing received:Bearing 102, 26 (Remote)
2023-05-15T21:01:15.867Z,1684184475.867 [DAT](INFO): DAT read: Range 12 to 10 : 0.9 m (Round-trip 1.3 ms) speed 0.0 m/s
2023-05-15T21:01:15.868Z,1684184475.868 [DAT](ERROR): #Rx 1: Read range message, but no direction.
2023-05-15T21:01:16.035Z,1684184476.035 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:01:16.072Z,1684184476.072 [Reporter](INFO): DAT.acoustic_contact_range 0.900000 m
2023-05-15T21:01:16.073Z,1684184476.073 [Reporter](INFO): acoustic_contact_range 0.900000 m
2023-05-15T21:01:18.397Z,1684184478.397 [DAT](INFO): DAT read: user:21>Rx Time:21:01:17.1951
2023-05-15T21:01:18.905Z,1684184478.905 [DAT](INFO): DAT read: 21:01:17.1951 LVL= 4096, 5105, 4674, 5827, AGC= 37, IDX= 28,-0.17, 2.048, 1.692, 1.363, 2.115, PHS=-0.083,-0.347,-0.704, RAW= 55.1, 36.6, CAL= 54.2, 45.6, ROT= 95.8, -45.6
2023-05-15T21:01:18.906Z,1684184478.906 [DAT](INFO): got valid direction response:
21:01:17.1951 LVL= 4096, 5105, 4674, 5827, AGC= 37, IDX= 28,-0.17, 2.048, 1.692, 1.363, 2.115, PHS=-0.083,-0.347,-0.704, RAW= 55.1, 36.6, CAL= 54.2, 45.6, ROT= 95.8, -45.6
2023-05-15T21:01:18.906Z,1684184478.906 [DAT](INFO): #Rx 2: Read direction message, but no range.
2023-05-15T21:01:18.907Z,1684184478.907 [DAT](INFO): direction in FSK: [-0.070705,0.696082,0.714473]
2023-05-15T21:01:19.153Z,1684184479.153 [DAT](INFO): DAT read:
2023-05-15T21:01:19.153Z,1684184479.153 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:01:19.154Z,1684184479.154 [DAT](INFO): Got DATA 2
2023-05-15T21:01:19.154Z,1684184479.154 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:01:19.154Z,1684184479.154 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:01:19.155Z,1684184479.155 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:01:19.156Z,1684184479.156 [DAT](INFO): DAT read: CRC:Pass MPD:03.4 PSNR:17.5 AGC:37 SPD:-0.1 CCERR:013
2023-05-15T21:01:19.156Z,1684184479.156 [DAT](INFO): Got CRC:Pass
2023-05-15T21:01:19.156Z,1684184479.156 [DAT](INFO): Got CRC:Pass
2023-05-15T21:01:19.156Z,1684184479.156 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:01:19.156Z,1684184479.156 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:01:19.157Z,1684184479.157 [DAT](INFO): Got ack
2023-05-15T21:01:19.157Z,1684184479.157 [DAT](INFO): DAT read:
2023-05-15T21:01:19.157Z,1684184479.157 [DAT](INFO): DAT read:
2023-05-15T21:01:19.158Z,1684184479.158 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:01:19.302Z,1684184479.302 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:01:19.405Z,1684184479.405 [DAT](INFO): modem://10: set _.humidity 13.014284 percent
2023-05-15T21:01:19.406Z,1684184479.406 [DAT](INFO): #Outgoing data=2
2023-05-15T21:01:19.406Z,1684184479.406 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:01:19.913Z,1684184479.913 [DAT](INFO): setting remote address to 10
2023-05-15T21:01:20.164Z,1684184480.164 [DAT](INFO): DAT read:
2023-05-15T21:01:20.165Z,1684184480.165 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:01:20.166Z,1684184480.166 [DAT](INFO): set remote address to 10
2023-05-15T21:01:20.166Z,1684184480.166 [DAT](INFO): entering online mode
2023-05-15T21:01:20.417Z,1684184480.417 [DAT](INFO): DAT read: user:22>
2023-05-15T21:01:20.417Z,1684184480.417 [DAT](INFO): DAT read:
2023-05-15T21:01:20.418Z,1684184480.418 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:01:20.419Z,1684184480.419 [DAT](INFO): commRate: 800
2023-05-15T21:01:20.419Z,1684184480.419 [DAT](INFO): online mode acknowledged
2023-05-15T21:01:20.419Z,1684184480.419 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:01:23.693Z,1684184483.693 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:01:23.1070
2023-05-15T21:01:23.693Z,1684184483.693 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:01:27.343Z,1684184487.343 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:01:27.472Z,1684184487.472 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:27.473Z,1684184487.473 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:27.536Z,1684184487.536 [DAT](INFO): entering command mode
2023-05-15T21:01:27.725Z,1684184487.725 [DAT](INFO): DAT read:
2023-05-15T21:01:27.725Z,1684184487.725 [DAT](INFO): DAT read: user:23>
2023-05-15T21:01:27.726Z,1684184487.726 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:27.726Z,1684184487.726 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:27.726Z,1684184487.726 [DAT](INFO): setting remote address to 0
2023-05-15T21:01:27.977Z,1684184487.977 [DAT](INFO): DAT read: user:23>
2023-05-15T21:01:27.978Z,1684184487.978 [DAT](INFO): DAT read: RemoteAddr | 0
2023-05-15T21:01:27.978Z,1684184487.978 [DAT](INFO): set remote address to 0
2023-05-15T21:01:27.979Z,1684184487.979 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:27.979Z,1684184487.979 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:27.979Z,1684184487.979 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:01:28.229Z,1684184488.229 [DAT](INFO): DAT read: user:24>
2023-05-15T21:01:28.230Z,1684184488.230 [DAT](INFO): DAT read: Tx time:21:01:27.5581
2023-05-15T21:01:28.230Z,1684184488.230 [DAT](INFO): Ping request sent.
2023-05-15T21:01:28.230Z,1684184488.230 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:01:28.230Z,1684184488.230 [DAT](INFO): publishing transmit ping time
2023-05-15T21:01:28.231Z,1684184488.231 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000761
2023-05-15T21:01:28.481Z,1684184488.481 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.250940
2023-05-15T21:01:28.733Z,1684184488.733 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502850
2023-05-15T21:01:28.985Z,1684184488.985 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754826
2023-05-15T21:01:29.237Z,1684184489.237 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.006729
2023-05-15T21:01:29.489Z,1684184489.489 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258728
2023-05-15T21:01:29.745Z,1684184489.745 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.515155
2023-05-15T21:01:29.997Z,1684184489.997 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.766661
2023-05-15T21:01:30.249Z,1684184490.249 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.018734
2023-05-15T21:01:30.501Z,1684184490.501 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.270731
2023-05-15T21:01:30.753Z,1684184490.753 [DAT](INFO): DAT read: Rx Time:21:01:29.5884
2023-05-15T21:01:30.754Z,1684184490.754 [DAT](INFO): Rx dataTimestamp_ set to:1684184489.588400
2023-05-15T21:01:30.755Z,1684184490.755 [DAT](INFO): received an acoustic signal
2023-05-15T21:01:30.755Z,1684184490.755 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.525065
2023-05-15T21:01:31.005Z,1684184491.005 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.774698
2023-05-15T21:01:31.262Z,1684184491.262 [DAT](INFO): DAT read: 21:01:29.5884 LVL= 4128, 5041, 4690, 5875, AGC= 35, IDX= 211,-0.10, 0.440, 0.382, 0.083, 0.492, PHS=-0.068,-0.035,-0.360, RAW= 24.7, 27.8, CAL= 24.9, 36.6, ROT= 125.1, -36.6
2023-05-15T21:01:31.263Z,1684184491.263 [DAT](INFO): got valid direction response:
21:01:29.5884 LVL= 4128, 5041, 4690, 5875, AGC= 35, IDX= 211,-0.10, 0.440, 0.382, 0.083, 0.492, PHS=-0.068,-0.035,-0.360, RAW= 24.7, 27.8, CAL= 24.9, 36.6, ROT= 125.1, -36.6
2023-05-15T21:01:31.264Z,1684184491.264 [DAT](INFO): DAT read: Bearing 104, 24 (Remote)
2023-05-15T21:01:31.265Z,1684184491.265 [DAT](INFO): Remote Bearing received:Bearing 104, 24 (Remote)
2023-05-15T21:01:31.266Z,1684184491.266 [DAT](INFO): DAT read: Bearing 261.5, -35.1 (Local)
2023-05-15T21:01:31.266Z,1684184491.266 [DAT](INFO): Local bearing/azimuth received:
Bearing 261.5, -35.1 (Local)
2023-05-15T21:01:31.267Z,1684184491.267 [DAT](INFO): DAT read: Range 12 to 10 : 0.9 m (Round-trip 1.2 ms) speed 0.0 m/s
2023-05-15T21:01:31.268Z,1684184491.268 [DAT](INFO): #Rx 1: Read range and direction messages.
2023-05-15T21:01:31.269Z,1684184491.269 [DAT](INFO): direction in FSK: [-0.461624,0.656825,0.596225]
2023-05-15T21:01:31.269Z,1684184491.269 [DAT](INFO): publishing direction and range info
2023-05-15T21:01:31.391Z,1684184491.391 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:01:31.413Z,1684184491.413 [Reporter](INFO): DAT.acoustic_contact_range 0.900000 m
2023-05-15T21:01:31.414Z,1684184491.414 [Reporter](INFO): acoustic_contact_range 0.900000 m
2023-05-15T21:01:31.414Z,1684184491.414 [Reporter](INFO): TrackAcousticContact.contact_latitude 0.642281 rad
2023-05-15T21:01:31.415Z,1684184491.415 [Reporter](INFO): TrackAcousticContact.contact_longitude -2.127556 rad
2023-05-15T21:01:33.784Z,1684184493.784 [DAT](DEBUG): In sendingAckWaiting, timeout so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:01:34.037Z,1684184494.037 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:01:34.289Z,1684184494.289 [DAT](INFO): setting remote address to 10
2023-05-15T21:01:34.541Z,1684184494.541 [DAT](INFO): DAT read: user:25>
2023-05-15T21:01:34.542Z,1684184494.542 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:01:34.542Z,1684184494.542 [DAT](INFO): set remote address to 10
2023-05-15T21:01:34.542Z,1684184494.542 [DAT](INFO): entering online mode
2023-05-15T21:01:34.793Z,1684184494.793 [DAT](INFO): DAT read: user:26>
2023-05-15T21:01:34.794Z,1684184494.794 [DAT](INFO): DAT read:
2023-05-15T21:01:34.795Z,1684184494.795 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:01:34.795Z,1684184494.795 [DAT](INFO): commRate: 800
2023-05-15T21:01:34.795Z,1684184494.795 [DAT](INFO): online mode acknowledged
2023-05-15T21:01:34.796Z,1684184494.796 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:01:38.073Z,1684184498.073 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:01:37.4569
2023-05-15T21:01:38.074Z,1684184498.074 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:01:42.701Z,1684184502.701 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:01:42.861Z,1684184502.861 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:42.861Z,1684184502.861 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:42.924Z,1684184502.924 [DAT](INFO): entering command mode
2023-05-15T21:01:43.113Z,1684184503.113 [DAT](INFO): DAT read:
2023-05-15T21:01:43.113Z,1684184503.113 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:43.113Z,1684184503.113 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:43.113Z,1684184503.113 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:01:43.365Z,1684184503.365 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:43.365Z,1684184503.365 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:43.365Z,1684184503.365 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:01:43.617Z,1684184503.617 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:43.617Z,1684184503.617 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:43.617Z,1684184503.617 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:01:43.868Z,1684184503.868 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:43.869Z,1684184503.869 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:43.869Z,1684184503.869 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:01:44.121Z,1684184504.121 [DAT](INFO): DAT read: user:27>Rx Time:21:01:43.0450
2023-05-15T21:01:44.122Z,1684184504.122 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:44.122Z,1684184504.122 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:44.122Z,1684184504.122 [DAT](INFO): setting remote address to 0
2023-05-15T21:01:44.372Z,1684184504.372 [DAT](INFO): DAT read:
2023-05-15T21:01:44.373Z,1684184504.373 [DAT](INFO): DAT read: RemoteAddr | 0
2023-05-15T21:01:44.374Z,1684184504.374 [DAT](INFO): set remote address to 0
2023-05-15T21:01:44.374Z,1684184504.374 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:44.374Z,1684184504.374 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:44.374Z,1684184504.374 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:01:44.625Z,1684184504.625 [DAT](INFO): DAT read: user:28>
2023-05-15T21:01:44.626Z,1684184504.626 [DAT](INFO): ****** received valid address query ******
2023-05-15T21:01:44.626Z,1684184504.626 [DAT](INFO): ****** received valid ping request ******
2023-05-15T21:01:44.626Z,1684184504.626 [DAT](INFO): Querying Benthos address 10 with one ping in standard two-way mode.
2023-05-15T21:01:44.883Z,1684184504.883 [DAT](INFO): DAT read: 21:01:43.0450 LVL= 4112, 5089, 4722, 5843, AGC= 37, IDX= 13,-0.08, 2.590, 2.233, 1.900, 2.665, PHS=-0.090,-0.356,-0.717, RAW= 55.0, 37.1, CAL= 54.1, 45.9, ROT= 95.9, -45.9
2023-05-15T21:01:44.884Z,1684184504.884 [DAT](INFO): got valid direction response:
21:01:43.0450 LVL= 4112, 5089, 4722, 5843, AGC= 37, IDX= 13,-0.08, 2.590, 2.233, 1.900, 2.665, PHS=-0.090,-0.356,-0.717, RAW= 55.0, 37.1, CAL= 54.1, 45.9, ROT= 95.9, -45.9
2023-05-15T21:01:44.885Z,1684184504.885 [DAT](INFO): DAT read: Tx time:21:01:44.2580
2023-05-15T21:01:44.885Z,1684184504.885 [DAT](INFO): Ping request sent.
2023-05-15T21:01:44.885Z,1684184504.885 [DAT](INFO): transmitted an acoustic signal
2023-05-15T21:01:44.886Z,1684184504.886 [DAT](INFO): DAT read:
2023-05-15T21:01:44.886Z,1684184504.886 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:01:44.887Z,1684184504.887 [DAT](INFO): Got DATA 2
2023-05-15T21:01:44.888Z,1684184504.888 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:01:44.888Z,1684184504.888 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:01:44.891Z,1684184504.891 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:01:44.892Z,1684184504.892 [DAT](INFO): DAT read: CRC:Pass MPD:03.4 PSNR:17.5 AGC:33 SPD:-0.1 CCERR:013
2023-05-15T21:01:44.892Z,1684184504.892 [DAT](INFO): Got CRC:Pass
2023-05-15T21:01:44.892Z,1684184504.892 [DAT](INFO): Got CRC:Pass
2023-05-15T21:01:44.893Z,1684184504.893 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:01:44.893Z,1684184504.893 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:01:44.893Z,1684184504.893 [DAT](INFO): Got ack
2023-05-15T21:01:44.893Z,1684184504.893 [DAT](INFO): DAT read:
2023-05-15T21:01:44.893Z,1684184504.893 [DAT](INFO): DAT read:
2023-05-15T21:01:44.894Z,1684184504.894 [DAT](INFO): DAT read: user:29>Tx time:21:01:44.3580
2023-05-15T21:01:44.895Z,1684184504.895 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:01:44.895Z,1684184504.895 [DAT](INFO): #Rx 1: Read direction message, but no range.
2023-05-15T21:01:44.896Z,1684184504.896 [DAT](INFO): direction in FSK: [-0.071535,0.692226,0.718126]
2023-05-15T21:01:44.897Z,1684184504.897 [DAT](INFO): publishing transmit ping time
2023-05-15T21:01:44.899Z,1684184504.899 [DAT](INFO): publishing transmit ping time
2023-05-15T21:01:45.129Z,1684184505.129 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:01:45.131Z,1684184505.131 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Received valid acoustic ping at time: 1684184448.00. Resetting abort timer.
2023-05-15T21:01:45.381Z,1684184505.381 [DAT](INFO): setting remote address to 10
2023-05-15T21:01:45.633Z,1684184505.633 [DAT](INFO): DAT read:
2023-05-15T21:01:45.634Z,1684184505.634 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:01:45.634Z,1684184505.634 [DAT](INFO): set remote address to 10
2023-05-15T21:01:45.634Z,1684184505.634 [DAT](INFO): entering online mode
2023-05-15T21:01:45.885Z,1684184505.885 [DAT](INFO): DAT read: user:30>
2023-05-15T21:01:45.885Z,1684184505.885 [DAT](INFO): DAT read:
2023-05-15T21:01:45.886Z,1684184505.886 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:01:45.887Z,1684184505.887 [DAT](INFO): commRate: 800
2023-05-15T21:01:45.887Z,1684184505.887 [DAT](INFO): online mode acknowledged
2023-05-15T21:01:45.887Z,1684184505.887 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:01:55.964Z,1684184515.964 [DAT](FAULT): Buffer send receipt timeout failure.
2023-05-15T21:01:55.964Z,1684184515.964 [DAT](DEBUG): In sendingTransmitVerify, timeout so go online and set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:01:56.217Z,1684184516.217 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:01:56.469Z,1684184516.469 [DAT](INFO): entering online mode
2023-05-15T21:01:56.720Z,1684184516.720 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:56.972Z,1684184516.972 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:57.225Z,1684184517.225 [DAT](INFO): DAT read: Response Not Received
2023-05-15T21:01:57.225Z,1684184517.225 [DAT](INFO): response not received
2023-05-15T21:01:57.225Z,1684184517.225 [DAT](ERROR): No response from remote modem.
2023-05-15T21:01:57.261Z,1684184517.261 [senddata_direct_and_track_test:DirectData:A.Wait](INFO): Done Waiting.
2023-05-15T21:01:57.261Z,1684184517.261 [senddata_direct_and_track_test:DirectData:A.Wait] Stopped
2023-05-15T21:01:57.261Z,1684184517.261 [senddata_direct_and_track_test:DirectData:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-15T21:01:57.261Z,1684184517.261 [senddata_direct_and_track_test:DirectData:B] Running Loop=1
2023-05-15T21:01:57.476Z,1684184517.476 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:57.640Z,1684184517.640 [senddata_direct_and_track_test:DirectData:B](INFO): Queuing up send data for Onboard.Pressure with destination: modem:10:_.pressure
2023-05-15T21:01:57.640Z,1684184517.640 [senddata_direct_and_track_test:DirectData:B] Stopped
2023-05-15T21:01:57.640Z,1684184517.640 [senddata_direct_and_track_test:DirectData:C] Running Loop=1
2023-05-15T21:01:57.728Z,1684184517.728 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:57.980Z,1684184517.980 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:58.039Z,1684184518.039 [senddata_direct_and_track_test:DirectData:C](INFO): Queuing up send data for Onboard.Temperature with destination: modem:10:_.temperature
2023-05-15T21:01:58.039Z,1684184518.039 [senddata_direct_and_track_test:DirectData:C] Stopped
2023-05-15T21:01:58.039Z,1684184518.039 [senddata_direct_and_track_test:DirectData:D] Running Loop=1
2023-05-15T21:01:58.040Z,1684184518.040 [senddata_direct_and_track_test:TrackAC.](INFO): *** querying acoustic contact ***
2023-05-15T21:01:58.232Z,1684184518.232 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:58.450Z,1684184518.450 [senddata_direct_and_track_test:DirectData:D](INFO): Queuing up send data for Onboard.Humidity with destination: modem:10:_.humidity
2023-05-15T21:01:58.450Z,1684184518.450 [senddata_direct_and_track_test:DirectData:D] Stopped
2023-05-15T21:01:58.450Z,1684184518.450 [senddata_direct_and_track_test:DirectData](INFO): Completed senddata_direct_and_track_test:DirectData
2023-05-15T21:01:58.451Z,1684184518.451 [senddata_direct_and_track_test:DirectData] Stopped
2023-05-15T21:01:58.451Z,1684184518.451 [senddata_direct_and_track_test:DirectData](DEBUG): Aggregate::uninitialize senddata_direct_and_track_test:DirectData
2023-05-15T21:01:58.451Z,1684184518.451 [senddata_direct_and_track_test](INFO): Completed senddata_direct_and_track_test
2023-05-15T21:01:58.451Z,1684184518.451 [MissionManager](INFO): senddata_direct_and_track_test is completed.
2023-05-15T21:01:58.452Z,1684184518.452 [MissionManager](INFO): Uninitializing Mission senddata_direct_and_track_test
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test] Stopped
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test](DEBUG): Aggregate::uninitialize senddata_direct_and_track_test
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test:AbortDrift] Stopped
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test:AbortDrift](DEBUG): Aggregate::uninitialize senddata_direct_and_track_test:AbortDrift
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift] Stopped
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test:AbortDrift:B.AbortDrift](INFO): Uninitializing AbortDrift.
2023-05-15T21:01:58.452Z,1684184518.452 [senddata_direct_and_track_test:TrackAC.] Stopped
2023-05-15T21:01:58.453Z,1684184518.453 [senddata_direct_and_track_test:TrackAC.](DEBUG): Uninitializing TrackAcousticContact.
2023-05-15T21:01:58.500Z,1684184518.500 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:58.752Z,1684184518.752 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:58.863Z,1684184518.863 [MissionManager](IMPORTANT): Started mission Default
2023-05-15T21:01:58.863Z,1684184518.863 [Default] Running Loop=1
2023-05-15T21:01:58.864Z,1684184518.864 [Default](DEBUG): Aggregate::initialize Default
2023-05-15T21:01:58.864Z,1684184518.864 [Default:B.GoToSurface] Running Loop=1
2023-05-15T21:01:58.864Z,1684184518.864 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-15T21:01:58.864Z,1684184518.864 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-15T21:01:58.865Z,1684184518.865 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-15T21:01:58.865Z,1684184518.865 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-15T21:01:58.865Z,1684184518.865 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-15T21:01:58.865Z,1684184518.865 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-15T21:01:58.866Z,1684184518.866 [Default:A.Wait] Running Loop=1
2023-05-15T21:01:58.866Z,1684184518.866 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-15T21:01:59.005Z,1684184519.005 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:59.257Z,1684184519.257 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:59.508Z,1684184519.508 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:01:59.760Z,1684184519.760 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:00.012Z,1684184520.012 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:00.264Z,1684184520.264 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:00.517Z,1684184520.517 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:01:59.8067
2023-05-15T21:02:00.518Z,1684184520.518 [DAT](INFO): unknown deviceResponse_: Forwarding Delay UpTx time:21:01:59.8067
2023-05-15T21:02:00.518Z,1684184520.518 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:00.768Z,1684184520.768 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:01.020Z,1684184521.020 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:01.273Z,1684184521.273 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:01.524Z,1684184521.524 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:01.776Z,1684184521.776 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:02.028Z,1684184522.028 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:02.280Z,1684184522.280 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:02.532Z,1684184522.532 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:02.784Z,1684184522.784 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:03.036Z,1684184523.036 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:03.540Z,1684184523.540 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:03.792Z,1684184523.792 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:04.044Z,1684184524.044 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:04.296Z,1684184524.296 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:04.549Z,1684184524.549 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:04.800Z,1684184524.800 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:05.052Z,1684184525.052 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:05.556Z,1684184525.556 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:05.808Z,1684184525.808 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:06.061Z,1684184526.061 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:06.312Z,1684184526.312 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:06.564Z,1684184526.564 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:06.816Z,1684184526.816 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:07.068Z,1684184527.068 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:07.320Z,1684184527.320 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:07.572Z,1684184527.572 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:07.824Z,1684184527.824 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:08.076Z,1684184528.076 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:08.328Z,1684184528.328 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:08.581Z,1684184528.581 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:08.832Z,1684184528.832 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:09.085Z,1684184529.085 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:09.336Z,1684184529.336 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:09.588Z,1684184529.588 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:09.840Z,1684184529.840 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:10.092Z,1684184530.092 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:10.344Z,1684184530.344 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:10.597Z,1684184530.597 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:10.848Z,1684184530.848 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:11.100Z,1684184531.100 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:11.352Z,1684184531.352 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:11.604Z,1684184531.604 [DAT](DEBUG): checking for online mode acknowledgment
2023-05-15T21:02:11.604Z,1684184531.604 [DAT](FAULT): failed to enter online mode
2023-05-15T21:02:11.605Z,1684184531.605 [DAT](FAULT): Failure returning to online mode
2023-05-15T21:02:11.605Z,1684184531.605 [DAT] Communications Fault, FailCount= 1
2023-05-15T21:02:11.605Z,1684184531.605 [DAT](ERROR): Communications Fault
2023-05-15T21:02:11.882Z,1684184531.882 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-15T21:02:12.008Z,1684184532.008 [DAT](INFO): Powering down
2023-05-15T21:02:12.207Z,1684184532.207 [Default:A.Wait](INFO): Done Waiting.
2023-05-15T21:02:12.207Z,1684184532.207 [Default:A.Wait] Stopped
2023-05-15T21:02:12.207Z,1684184532.207 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-15T21:02:12.627Z,1684184532.627 [Default:CheckIn] Running Loop=1
2023-05-15T21:02:12.627Z,1684184532.627 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-15T21:02:12.627Z,1684184532.627 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-15T21:02:13.007Z,1684184533.007 [CBIT](INFO): Clearing failed state for component DAT
2023-05-15T21:02:13.007Z,1684184533.007 [DAT] No Fault, FailCount= 1
2023-05-15T21:02:15.056Z,1684184535.056 [DAT](INFO): Powering up
2023-05-15T21:02:15.056Z,1684184535.056 [DAT](DEBUG): Initializing DAT.
2023-05-15T21:02:27.157Z,1684184547.157 [DAT](INFO): DAT read:
2023-05-15T21:02:27.409Z,1684184547.409 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series
2023-05-15T21:02:28.921Z,1684184548.921 [DAT](INFO): DAT read: MF Frequency Band
2023-05-15T21:02:28.922Z,1684184548.922 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0
2023-05-15T21:02:28.923Z,1684184548.923 [DAT](INFO): DAT read: May 15 2023 21:02:23
2023-05-15T21:02:30.181Z,1684184550.181 [DAT](INFO): DAT read: Features enabled [Bearing]
2023-05-15T21:02:30.182Z,1684184550.182 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:02:30.183Z,1684184550.183 [DAT](INFO): commRate: 800
2023-05-15T21:02:32.260Z,1684184552.260 [DAT](INFO): entering command mode
2023-05-15T21:02:32.260Z,1684184552.260 [DAT](DEBUG): checking for command mode acknowledgment
2023-05-15T21:02:32.449Z,1684184552.449 [DAT](INFO): DAT read:
2023-05-15T21:02:32.449Z,1684184552.449 [DAT](INFO): DAT read: user:1>
2023-05-15T21:02:32.450Z,1684184552.450 [DAT](INFO): setting verbose to 3
2023-05-15T21:02:32.701Z,1684184552.701 [DAT](INFO): DAT read: user:1>
2023-05-15T21:02:32.702Z,1684184552.702 [DAT](INFO): DAT read: Verbose | 3
2023-05-15T21:02:32.702Z,1684184552.702 [DAT](INFO): set verbose to 3
2023-05-15T21:02:32.702Z,1684184552.702 [DAT](INFO): setting DatVerbose to 27440
2023-05-15T21:02:32.953Z,1684184552.953 [DAT](INFO): DAT read: user:2>
2023-05-15T21:02:32.954Z,1684184552.954 [DAT](INFO): DAT read: DatVerbose | 27440
2023-05-15T21:02:32.954Z,1684184552.954 [DAT](INFO): set DatVerbose to 27440
2023-05-15T21:02:32.954Z,1684184552.954 [DAT](INFO): setting transmit power to 8
2023-05-15T21:02:33.205Z,1684184553.205 [DAT](INFO): DAT read: user:3>
2023-05-15T21:02:33.206Z,1684184553.206 [DAT](INFO): DAT read: TxPower | 8 (Max)
2023-05-15T21:02:33.206Z,1684184553.206 [DAT](INFO): set transmit power to 8
2023-05-15T21:02:33.206Z,1684184553.206 [DAT](INFO): setting local address to 12
2023-05-15T21:02:33.457Z,1684184553.457 [DAT](INFO): DAT read: user:4>
2023-05-15T21:02:33.457Z,1684184553.457 [DAT](INFO): DAT read: LocalAddr | 12
2023-05-15T21:02:33.458Z,1684184553.458 [DAT](INFO): set local address to 12
2023-05-15T21:02:33.459Z,1684184553.459 [DAT](INFO): Setting time to: 21:2:33 And date to:5/15/2023
2023-05-15T21:02:33.709Z,1684184553.709 [DAT](INFO): DAT read: user:5>
2023-05-15T21:02:33.710Z,1684184553.710 [DAT](INFO): DAT read: Mon May 15, 2023 21:02:33
2023-05-15T21:02:33.710Z,1684184553.710 [DAT](INFO): Local DAT time set to Mon May 15, 2023 21:02:33
2023-05-15T21:02:33.711Z,1684184553.711 [DAT](INFO): setting remote address to 10
2023-05-15T21:02:33.961Z,1684184553.961 [DAT](INFO): DAT read: user:6>
2023-05-15T21:02:33.962Z,1684184553.962 [DAT](INFO): DAT read: RemoteAddr | 10
2023-05-15T21:02:33.962Z,1684184553.962 [DAT](INFO): set remote address to 10
2023-05-15T21:02:33.962Z,1684184553.962 [DAT](INFO): entering online mode
2023-05-15T21:02:34.213Z,1684184554.213 [DAT](INFO): DAT read: user:7>
2023-05-15T21:02:34.213Z,1684184554.213 [DAT](INFO): DAT read:
2023-05-15T21:02:34.214Z,1684184554.214 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP
2023-05-15T21:02:34.215Z,1684184554.215 [DAT](INFO): commRate: 800
2023-05-15T21:02:34.215Z,1684184554.215 [DAT](INFO): online mode acknowledged
2023-05-15T21:02:34.215Z,1684184554.215 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:02:37.489Z,1684184557.489 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:02:36.9996
2023-05-15T21:02:37.489Z,1684184557.489 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:02:43.789Z,1684184563.789 [DAT](INFO): DAT read: Rx Time:21:02:42.7210
2023-05-15T21:02:43.790Z,1684184563.790 [DAT](INFO): Rx dataTimestamp_ set to:1684184562.721001
2023-05-15T21:02:43.790Z,1684184563.790 [DAT](INFO): received an acoustic signal
2023-05-15T21:02:44.296Z,1684184564.296 [DAT](INFO): DAT read: 21:02:42.7210 LVL= 4208, 5089, 4738, 5747, AGC= 36, IDX= 98, 0.11,-1.979,-2.326,-2.719,-1.842, PHS=-0.153,-0.409,-0.829, RAW= 52.0, 39.8, CAL= 51.5, 48.2, ROT= 98.5, -48.2
2023-05-15T21:02:44.298Z,1684184564.298 [DAT](INFO): got valid direction response:
21:02:42.7210 LVL= 4208, 5089, 4738, 5747, AGC= 36, IDX= 98, 0.11,-1.979,-2.326,-2.719,-1.842, PHS=-0.153,-0.409,-0.829, RAW= 52.0, 39.8, CAL= 51.5, 48.2, ROT= 98.5, -48.2
2023-05-15T21:02:44.298Z,1684184564.298 [DAT](INFO): #Rx 2: Read direction message, but no range.
2023-05-15T21:02:44.299Z,1684184564.299 [DAT](INFO): direction in FSK: [-0.098520,0.659211,0.745476]
2023-05-15T21:02:44.544Z,1684184564.544 [DAT](INFO): DAT read:
2023-05-15T21:02:44.545Z,1684184564.545 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:02:44.545Z,1684184564.545 [DAT](INFO): Got DATA 2
2023-05-15T21:02:44.546Z,1684184564.546 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:02:44.546Z,1684184564.546 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:02:44.547Z,1684184564.547 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:02:44.548Z,1684184564.548 [DAT](INFO): DAT read: CRC:Pass MPD:03.5 PSNR:17.5 AGC:39 SPD:+0.0 CCERR:013
2023-05-15T21:02:44.548Z,1684184564.548 [DAT](INFO): Got CRC:Pass
2023-05-15T21:02:44.548Z,1684184564.548 [DAT](INFO): Got CRC:Pass
2023-05-15T21:02:44.548Z,1684184564.548 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:02:44.548Z,1684184564.548 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:02:44.549Z,1684184564.549 [DAT](INFO): Got ack
2023-05-15T21:02:44.549Z,1684184564.549 [DAT](INFO): DAT read:
2023-05-15T21:02:44.549Z,1684184564.549 [DAT](INFO): DAT read:
2023-05-15T21:02:44.797Z,1684184564.797 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:02:45.049Z,1684184565.049 [DAT](INFO): modem://10: set _.pressure 0.744663 atmosphere
2023-05-15T21:02:45.050Z,1684184565.050 [DAT](INFO): #Outgoing data=1
2023-05-15T21:02:45.050Z,1684184565.050 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:02:45.553Z,1684184565.553 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:02:48.829Z,1684184568.829 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:02:48.3496
2023-05-15T21:02:48.829Z,1684184568.829 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:02:55.133Z,1684184575.133 [DAT](INFO): DAT read: Rx Time:21:02:54.0711
2023-05-15T21:02:55.134Z,1684184575.134 [DAT](INFO): Rx dataTimestamp_ set to:1684184574.071098
2023-05-15T21:02:55.135Z,1684184575.135 [DAT](INFO): received an acoustic signal
2023-05-15T21:02:55.649Z,1684184575.649 [DAT](INFO): DAT read: 21:02:54.0711 LVL= 4176, 5185, 4674, 5763, AGC= 35, IDX= 300, 0.13,-0.978,-1.000,-1.263,-0.848, PHS=-0.145,-0.077,-0.366, RAW= 16.9, 38.5, CAL= 17.6, 46.5, ROT= 132.4, -46.5
2023-05-15T21:02:55.650Z,1684184575.650 [DAT](INFO): got valid direction response:
21:02:54.0711 LVL= 4176, 5185, 4674, 5763, AGC= 35, IDX= 300, 0.13,-0.978,-1.000,-1.263,-0.848, PHS=-0.145,-0.077,-0.366, RAW= 16.9, 38.5, CAL= 17.6, 46.5, ROT= 132.4, -46.5
2023-05-15T21:02:55.650Z,1684184575.650 [DAT](INFO): #Rx 3: Read direction message, but no range.
2023-05-15T21:02:55.651Z,1684184575.651 [DAT](INFO): direction in FSK: [-0.464159,0.508319,0.725374]
2023-05-15T21:02:55.897Z,1684184575.897 [DAT](INFO): DAT read:
2023-05-15T21:02:55.897Z,1684184575.897 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:02:55.898Z,1684184575.898 [DAT](INFO): Got DATA 2
2023-05-15T21:02:55.898Z,1684184575.898 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:02:55.898Z,1684184575.898 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:02:55.899Z,1684184575.899 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:02:55.900Z,1684184575.900 [DAT](INFO): DAT read: CRC:Pass MPD:03.4 PSNR:17.5 AGC:36 SPD:+0.0 CCERR:013
2023-05-15T21:02:55.900Z,1684184575.900 [DAT](INFO): Got CRC:Pass
2023-05-15T21:02:55.900Z,1684184575.900 [DAT](INFO): Got CRC:Pass
2023-05-15T21:02:55.900Z,1684184575.900 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:02:55.901Z,1684184575.901 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:02:55.901Z,1684184575.901 [DAT](INFO): Got ack
2023-05-15T21:02:55.901Z,1684184575.901 [DAT](INFO): DAT read:
2023-05-15T21:02:55.901Z,1684184575.901 [DAT](INFO): DAT read:
2023-05-15T21:02:55.902Z,1684184575.902 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:02:56.150Z,1684184576.150 [DAT](INFO): modem://10: set _.temperature 24.259546 celsius
2023-05-15T21:02:56.150Z,1684184576.150 [DAT](INFO): #Outgoing data=1
2023-05-15T21:02:56.150Z,1684184576.150 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:02:56.401Z,1684184576.401 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:02:59.681Z,1684184579.681 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:02:59.1995
2023-05-15T21:02:59.681Z,1684184579.681 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:03:05.993Z,1684184585.993 [DAT](INFO): DAT read: Rx Time:21:03:04.9210
2023-05-15T21:03:05.994Z,1684184585.994 [DAT](INFO): Rx dataTimestamp_ set to:1684184584.921000
2023-05-15T21:03:05.994Z,1684184585.994 [DAT](INFO): received an acoustic signal
2023-05-15T21:03:06.500Z,1684184586.500 [DAT](INFO): DAT read: 21:03:04.9210 LVL= 5168, 6337, 5826, 7203, AGC= 36, IDX= 435,-0.06, 2.096, 1.714, 1.461, 2.142, PHS=-0.062,-0.353,-0.634, RAW= 60.6, 36.9, CAL= 59.0, 45.7, ROT= 91.0, -45.7
2023-05-15T21:03:06.501Z,1684184586.501 [DAT](INFO): got valid direction response:
21:03:04.9210 LVL= 5168, 6337, 5826, 7203, AGC= 36, IDX= 435,-0.06, 2.096, 1.714, 1.461, 2.142, PHS=-0.062,-0.353,-0.634, RAW= 60.6, 36.9, CAL= 59.0, 45.7, ROT= 91.0, -45.7
2023-05-15T21:03:06.502Z,1684184586.502 [DAT](INFO): #Rx 4: Read direction message, but no range.
2023-05-15T21:03:06.503Z,1684184586.503 [DAT](INFO): direction in FSK: [-0.012189,0.698309,0.715693]
2023-05-15T21:03:06.749Z,1684184586.749 [DAT](INFO): DAT read:
2023-05-15T21:03:06.749Z,1684184586.749 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:03:06.750Z,1684184586.750 [DAT](INFO): Got DATA 2
2023-05-15T21:03:06.750Z,1684184586.750 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:03:06.751Z,1684184586.751 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:03:06.751Z,1684184586.751 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:03:06.752Z,1684184586.752 [DAT](INFO): DAT read: CRC:Pass MPD:03.4 PSNR:17.7 AGC:36 SPD:-0.1 CCERR:013
2023-05-15T21:03:06.752Z,1684184586.752 [DAT](INFO): Got CRC:Pass
2023-05-15T21:03:06.752Z,1684184586.752 [DAT](INFO): Got CRC:Pass
2023-05-15T21:03:06.752Z,1684184586.752 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:03:06.753Z,1684184586.753 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:03:06.753Z,1684184586.753 [DAT](INFO): Got ack
2023-05-15T21:03:06.753Z,1684184586.753 [DAT](INFO): DAT read:
2023-05-15T21:03:06.753Z,1684184586.753 [DAT](INFO): DAT read:
2023-05-15T21:03:06.754Z,1684184586.754 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:03:07.001Z,1684184587.001 [DAT](INFO): modem://10: set _.humidity 13.014284 percent
2023-05-15T21:03:07.002Z,1684184587.002 [DAT](INFO): #Outgoing data=1
2023-05-15T21:03:07.002Z,1684184587.002 [DAT](DEBUG): In sendingFillBuffer, set commsState_ = SENDING_TRANSMIT
2023-05-15T21:03:07.253Z,1684184587.253 [DAT](DEBUG): In sendingTransmit, set commsState_ = SENDING_TRANSMIT_VERIFY
2023-05-15T21:03:10.529Z,1684184590.529 [DAT](INFO): DAT read: Forwarding Delay UpTx time:21:03:10.0495
2023-05-15T21:03:10.529Z,1684184590.529 [DAT](DEBUG): In parseResponses, set commsState_ = SENDING_ACK_WAITING
2023-05-15T21:03:16.829Z,1684184596.829 [DAT](INFO): DAT read: Rx Time:21:03:15.7709
2023-05-15T21:03:16.830Z,1684184596.830 [DAT](INFO): Rx dataTimestamp_ set to:1684184595.770900
2023-05-15T21:03:16.830Z,1684184596.830 [DAT](INFO): received an acoustic signal
2023-05-15T21:03:17.337Z,1684184597.337 [DAT](INFO): DAT read: 21:03:15.7709 LVL= 4080, 4993, 4626, 5891, AGC= 36, IDX= 179, 0.12,-1.654,-1.998,-2.396,-1.503, PHS=-0.167,-0.420,-0.845, RAW= 51.7, 40.5, CAL= 51.2, 48.9, ROT= 98.8, -48.9
2023-05-15T21:03:17.338Z,1684184597.338 [DAT](INFO): got valid direction response:
21:03:15.7709 LVL= 4080, 4993, 4626, 5891, AGC= 36, IDX= 179, 0.12,-1.654,-1.998,-2.396,-1.503, PHS=-0.167,-0.420,-0.845, RAW= 51.7, 40.5, CAL= 51.2, 48.9, ROT= 98.8, -48.9
2023-05-15T21:03:17.338Z,1684184597.338 [DAT](INFO): #Rx 5: Read direction message, but no range.
2023-05-15T21:03:17.339Z,1684184597.339 [DAT](INFO): direction in FSK: [-0.100569,0.649637,0.753563]
2023-05-15T21:03:17.585Z,1684184597.585 [DAT](INFO): DAT read:
2023-05-15T21:03:17.585Z,1684184597.585 [DAT](INFO): DAT read: DATA(0002):~~
2023-05-15T21:03:17.586Z,1684184597.586 [DAT](INFO): Got DATA 2
2023-05-15T21:03:17.586Z,1684184597.586 [DAT](INFO): DAT read: Source:010 Destination:012
2023-05-15T21:03:17.586Z,1684184597.586 [DAT](INFO): Got Src/Dest after DATA
2023-05-15T21:03:17.587Z,1684184597.587 [DAT](INFO): DATA Src=10, Dst=12
2023-05-15T21:03:17.588Z,1684184597.588 [DAT](INFO): DAT read: CRC:Pass MPD:03.5 PSNR:17.5 AGC:36 SPD:-0.1 CCERR:013
2023-05-15T21:03:17.588Z,1684184597.588 [DAT](INFO): Got CRC:Pass
2023-05-15T21:03:17.588Z,1684184597.588 [DAT](INFO): Got CRC:Pass
2023-05-15T21:03:17.588Z,1684184597.588 [DAT](INFO): Incoming data is intended for us
2023-05-15T21:03:17.589Z,1684184597.589 [DAT](DEBUG): In parseResponses, got ack so set commsState_ = SENDING_VERIFIED
2023-05-15T21:03:17.589Z,1684184597.589 [DAT](INFO): Got ack
2023-05-15T21:03:17.589Z,1684184597.589 [DAT](INFO): DAT read:
2023-05-15T21:03:17.589Z,1684184597.589 [DAT](INFO): DAT read:
2023-05-15T21:03:17.590Z,1684184597.590 [DAT](DEBUG): In sendingVerified, data done so set commsState_ = SENDING_FILL_BUFFER
2023-05-15T21:04:50.541Z,1684184690.541 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-15T21:07:12.761Z,1684184832.761 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-15T21:02:12.6Z
2023-05-15T21:07:12.761Z,1684184832.761 [Default:CheckIn:Read_GPS] Stopped
2023-05-15T21:07:12.761Z,1684184832.761 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-15T21:07:19.943Z,1684184839.943 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230515T204048/Courier0010.lzma
2023-05-15T21:07:20.946Z,1684184840.946 [DataOverHttps](INFO): Moved sent file to Logs/20230515T204048/Courier0010.lzma.bak
2023-05-15T21:07:20.946Z,1684184840.946 [DataOverHttps](INFO): SBD MOMSN=18312244
2023-05-15T21:07:36.551Z,1684184856.551 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20230515T205914/Courier0000.lzma
2023-05-15T21:07:37.558Z,1684184857.558 [DataOverHttps](INFO): Moved sent file to Logs/20230515T205914/Courier0000.lzma.bak
2023-05-15T21:07:37.558Z,1684184857.558 [DataOverHttps](INFO): SBD MOMSN=18312264
2023-05-15T21:07:44.261Z,1684184864.261 [NAL9602](INFO): Not Powering down - fast GPS
2023-05-15T21:07:54.644Z,1684184874.644 [DataOverHttps](INFO): Sending 426 bytes from file Logs/20230515T204048/Express0011.lzma
2023-05-15T21:07:55.646Z,1684184875.646 [DataOverHttps](INFO): Moved sent file to Logs/20230515T204048/Express0011.lzma.bak
2023-05-15T21:07:55.646Z,1684184875.646 [DataOverHttps](INFO): SBD MOMSN=18312269
2023-05-15T21:08:12.820Z,1684184892.820 [DataOverHttps](INFO): Sending 712 bytes from file Logs/20230515T205914/Express0001.lzma
2023-05-15T21:08:13.822Z,1684184893.822 [DataOverHttps](INFO): Moved sent file to Logs/20230515T205914/Express0001.lzma.bak
2023-05-15T21:08:13.822Z,1684184893.822 [DataOverHttps](INFO): SBD MOMSN=18312284
2023-05-15T21:17:43.701Z,1684185463.701 [CommandExec](IMPORTANT): got command restart application
2023-05-15T21:17:44.704Z,1684185464.704 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2023-05-15T21:17:44.704Z,1684185464.704 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:44.704Z,1684185464.704 [CommandExec](INFO): Uninitializing the command executive.
2023-05-15T21:17:44.705Z,1684185464.705 [CommandExec](INFO): Uninitializing the command scheduler.
2023-05-15T21:17:44.705Z,1684185464.705 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:44.784Z,1684185464.784 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2023-05-15T21:17:44.784Z,1684185464.784 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2023-05-15T21:17:44.784Z,1684185464.784 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:44.785Z,1684185464.785 [NavChartDb](INFO): Join timeout helper Thread ID is 2620
2023-05-15T21:17:45.168Z,1684185465.168 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:45.168Z,1684185465.168 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:45.176Z,1684185465.176 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2023-05-15T21:17:45.176Z,1684185465.176 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:45.177Z,1684185465.177 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2621
2023-05-15T21:17:45.596Z,1684185465.596 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:45.597Z,1684185465.597 [WetLabsBB2FL](INFO): Powering down
2023-05-15T21:17:45.597Z,1684185465.597 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:45.604Z,1684185465.604 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2023-05-15T21:17:45.604Z,1684185465.604 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:45.605Z,1684185465.605 [CTD_Seabird](INFO): Join timeout helper Thread ID is 2622
2023-05-15T21:17:46.092Z,1684185466.092 [CTD_Seabird](INFO): Powering down
2023-05-15T21:17:46.104Z,1684185466.104 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:46.104Z,1684185466.104 [CTD_Seabird](INFO): Powering down
2023-05-15T21:17:46.116Z,1684185466.116 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:46.124Z,1684185466.124 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2023-05-15T21:17:46.124Z,1684185466.124 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:46.125Z,1684185466.125 [Radio_Surface](INFO): Join timeout helper Thread ID is 2623
2023-05-15T21:17:46.308Z,1684185466.308 [Radio_Surface](INFO): Powering down
2023-05-15T21:17:46.309Z,1684185466.309 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:46.309Z,1684185466.309 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:46.320Z,1684185466.320 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2023-05-15T21:17:46.320Z,1684185466.320 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:46.320Z,1684185466.320 [Onboard](INFO): Join timeout helper Thread ID is 2624
2023-05-15T21:17:48.460Z,1684185468.460 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:48.460Z,1684185468.460 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.473Z,1684185468.473 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2023-05-15T21:17:48.473Z,1684185468.473 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.473Z,1684185468.473 [DataOverHttps](INFO): Join timeout helper Thread ID is 2625
2023-05-15T21:17:48.668Z,1684185468.668 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:48.669Z,1684185468.669 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.673Z,1684185468.673 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2023-05-15T21:17:48.673Z,1684185468.673 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.673Z,1684185468.673 [DAT](INFO): Join timeout helper Thread ID is 2626
2023-05-15T21:17:48.676Z,1684185468.676 [DAT](INFO): Powering down
2023-05-15T21:17:48.749Z,1684185468.749 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:48.749Z,1684185468.749 [DAT](INFO): Powering down
2023-05-15T21:17:48.750Z,1684185468.750 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.753Z,1684185468.753 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2023-05-15T21:17:48.753Z,1684185468.753 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.753Z,1684185468.753 [BackseatComponent](INFO): Join timeout helper Thread ID is 2627
2023-05-15T21:17:48.928Z,1684185468.928 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:48.928Z,1684185468.928 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.930Z,1684185468.930 [Default:CheckIn:Read_Iridium] Stopped
2023-05-15T21:17:48.931Z,1684185468.931 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-15T21:17:48.931Z,1684185468.931 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-15T21:17:48.941Z,1684185468.941 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2023-05-15T21:17:48.941Z,1684185468.941 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.941Z,1684185468.941 [logger](INFO): Join timeout helper Thread ID is 2628
2023-05-15T21:17:48.960Z,1684185468.960 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:48.961Z,1684185468.961 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.981Z,1684185468.981 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2023-05-15T21:17:48.981Z,1684185468.981 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:48.981Z,1684185468.981 [CommandLine](INFO): Join timeout helper Thread ID is 2629
2023-05-15T21:17:49.072Z,1684185469.072 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:49.072Z,1684185469.072 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.081Z,1684185469.081 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2023-05-15T21:17:49.081Z,1684185469.081 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.081Z,1684185469.081 [CommandExec](INFO): Join timeout helper Thread ID is 2630
2023-05-15T21:17:49.083Z,1684185469.083 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2023-05-15T21:17:49.083Z,1684185469.083 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.083Z,1684185469.083 [controlThread](INFO): Join timeout helper Thread ID is 2631
2023-05-15T21:17:49.300Z,1684185469.300 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-15T21:17:49.300Z,1684185469.300 [controlThread](DEBUG): Uninitializing ControlThread
2023-05-15T21:17:49.301Z,1684185469.301 [AHRS_M2](INFO): Powering down
2023-05-15T21:17:49.373Z,1684185469.373 [NAL9602](INFO): Powering down
2023-05-15T21:17:49.375Z,1684185469.375 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2023-05-15T21:17:49.376Z,1684185469.376 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2023-05-15T21:17:49.376Z,1684185469.376 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2023-05-15T21:17:49.377Z,1684185469.377 [MissionManager](INFO): Uninitializing Mission Default
2023-05-15T21:17:49.377Z,1684185469.377 [Default] Stopped
2023-05-15T21:17:49.377Z,1684185469.377 [Default](DEBUG): Aggregate::uninitialize Default
2023-05-15T21:17:49.377Z,1684185469.377 [Default:B.GoToSurface] Stopped
2023-05-15T21:17:49.377Z,1684185469.377 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-15T21:17:49.377Z,1684185469.377 [Default:CheckIn] Stopped
2023-05-15T21:17:49.378Z,1684185469.378 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-15T21:17:49.378Z,1684185469.378 [Default:CheckIn:C.Wait] Stopped
2023-05-15T21:17:49.378Z,1684185469.378 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-15T21:17:49.381Z,1684185469.381 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2023-05-15T21:17:49.381Z,1684185469.381 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2023-05-15T21:17:49.381Z,1684185469.381 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2023-05-15T21:17:49.382Z,1684185469.382 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2023-05-15T21:17:49.382Z,1684185469.382 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2023-05-15T21:17:49.382Z,1684185469.382 [BuoyancyServo](INFO): Powering down
2023-05-15T21:17:49.396Z,1684185469.396 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2023-05-15T21:17:49.396Z,1684185469.396 [ElevatorServo](INFO): Powering down
2023-05-15T21:17:49.397Z,1684185469.397 [MassServo](DEBUG): Uninitialize Mass Servo.
2023-05-15T21:17:49.397Z,1684185469.397 [MassServo](INFO): Powering down
2023-05-15T21:17:49.398Z,1684185469.398 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2023-05-15T21:17:49.398Z,1684185469.398 [RudderServo](INFO): Powering down
2023-05-15T21:17:49.399Z,1684185469.399 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2023-05-15T21:17:49.399Z,1684185469.399 [ThrusterHE](INFO): Powering down
2023-05-15T21:17:49.400Z,1684185469.400 [SBIT](DEBUG): Uninitialize SBIT Component.
2023-05-15T21:17:49.400Z,1684185469.400 [IBIT](DEBUG): Uninitialize IBIT Component.
2023-05-15T21:17:49.401Z,1684185469.401 [CBIT](DEBUG): Uninitialize CBIT Component.
2023-05-15T21:17:49.401Z,1684185469.401 [CBIT](DEBUG): Powering off loads.
2023-05-15T21:17:49.412Z,1684185469.412 [CBIT](DEBUG): Disabling WDT.
2023-05-15T21:17:49.424Z,1684185469.424 [CBIT](DEBUG): Opening all GF detection circuits.
2023-05-15T21:17:49.425Z,1684185469.425 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.482Z,1684185469.482 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.485Z,1684185469.485 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.491Z,1684185469.491 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.497Z,1684185469.497 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.537Z,1684185469.537 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.586Z,1684185469.586 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.591Z,1684185469.591 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.627Z,1684185469.627 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-15T21:17:49.690Z,1684185469.690 [logger ThreadHandler](INFO): Thread cancelled.