2021-05-18T02:49:43.930Z,1621306183.930 [CommandLine](IMPORTANT): got command restart logs 2021-05-18T02:49:48.477Z,1621306188.477 [Default:A.Wait](INFO): Done Waiting. 2021-05-18T02:49:48.477Z,1621306188.477 [Default:A.Wait] Stopped 2021-05-18T02:49:48.477Z,1621306188.477 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T02:49:48.889Z,1621306188.889 [Default:CheckIn] Running Loop=1 2021-05-18T02:49:48.889Z,1621306188.889 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-05-18T02:49:48.889Z,1621306188.889 [Default:CheckIn:Read_GPS] Running Loop=1 2021-05-18T02:49:54.618Z,1621306194.618 [CommandLine](IMPORTANT): got command run ./Missions/lab_range_test.xml 2021-05-18T02:49:54.618Z,1621306194.618 [MissionManager](INFO): Loading Mission: ./Missions/lab_range_test.xml 2021-05-18T02:49:54.661Z,1621306194.661 [MissionManager](INFO): DefineArg lab_range_test.MissionTimeout = 2.000000 min 2021-05-18T02:49:54.663Z,1621306194.663 [MissionManager](INFO): DefineArg lab_range_test.ContactLabel = 50.000000 count 2021-05-18T02:49:54.665Z,1621306194.665 [MissionManager](INFO): DefineArg lab_range_test.TrackingUpdatePeriod = 5.000000 s 2021-05-18T02:49:54.667Z,1621306194.667 [MissionManager](INFO): DefineArg lab_range_test.NumberOfPings = 5.000000 count 2021-05-18T02:49:54.669Z,1621306194.669 [MissionManager](INFO): DefineArg lab_range_test.ContactDepth = nan m 2021-05-18T02:49:54.682Z,1621306194.682 [lab_range_test:B.Wait](DEBUG): Construct Wait. 2021-05-18T02:49:54.686Z,1621306194.686 [MissionManager](DEBUG): LAB TEST MISSION - ping remote xponder Maximum duration of mission 2 The acoustic address of the asset to be tracked 50 How long to wait between acoustic queries 5 Number of return pings to request with each acoustic query (more than 1 will activate oneway mode) 5 The acoustic address of the asset to be tracked NaN 2021-05-18T02:49:54.687Z,1621306194.687 [CommandLine](IMPORTANT): Running ./Missions/lab_range_test.xml 2021-05-18T02:49:54.926Z,1621306194.926 [DAT](INFO): ****** received valid address query ****** 2021-05-18T02:49:54.926Z,1621306194.926 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T02:49:54.926Z,1621306194.926 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode. 2021-05-18T02:49:54.926Z,1621306194.926 [DAT](INFO): ****** ping requested ****** 2021-05-18T02:49:54.944Z,1621306194.944 [Default] Stopped 2021-05-18T02:49:54.944Z,1621306194.944 [Default](DEBUG): Aggregate::uninitialize Default 2021-05-18T02:49:54.945Z,1621306194.945 [Default:B.GoToSurface] Stopped 2021-05-18T02:49:54.945Z,1621306194.945 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-05-18T02:49:54.945Z,1621306194.945 [Default:CheckIn] Stopped 2021-05-18T02:49:54.945Z,1621306194.945 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-05-18T02:49:54.945Z,1621306194.945 [Default:CheckIn:Read_GPS] Stopped 2021-05-18T02:49:54.945Z,1621306194.945 [MissionManager](IMPORTANT): Started mission lab_range_test 2021-05-18T02:49:54.945Z,1621306194.945 [lab_range_test] Running Loop=1 2021-05-18T02:49:54.945Z,1621306194.945 [lab_range_test](DEBUG): Aggregate::initialize lab_range_test 2021-05-18T02:49:54.945Z,1621306194.945 [lab_range_test:A.] Running Loop=1 2021-05-18T02:49:54.946Z,1621306194.946 [lab_range_test:A.](INFO): Initializing Tracking. 2021-05-18T02:49:54.946Z,1621306194.946 [lab_range_test:B.Wait] Running Loop=1 2021-05-18T02:49:54.946Z,1621306194.946 [lab_range_test:B.Wait](DEBUG): Initialize Wait Component. 2021-05-18T02:49:54.946Z,1621306194.946 [lab_range_test:A.] Running Loop=1 2021-05-18T02:49:54.946Z,1621306194.946 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:54.948Z,1621306194.948 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.331389 forward, 0.935814 starboard, -0.120137 keelward ] 2021-05-18T02:49:54.948Z,1621306194.948 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:54.950Z,1621306194.950 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999312,-0.037007,-0.002497;0.037058,0.999006,0.024791;0.001577,-0.024866,0.999690 ] 2021-05-18T02:49:54.950Z,1621306194.950 [lab_range_test:A.](INFO): rangeToContact_ = 0.500000 m 2021-05-18T02:49:55.001Z,1621306195.001 [lab_range_test:A.](INFO): direction in world frame: [ 0.365651 north, 0.925607 east, -0.097727 down ] 2021-05-18T02:49:55.002Z,1621306195.002 [lab_range_test:A.](INFO): relPosInFSK: [ 0.165695 forward, 0.467907 starboard, -0.060068 keelward ] 2021-05-18T02:49:55.003Z,1621306195.003 [lab_range_test:A.](INFO): relPosInNED: [ 0.182825 north, 0.462804 east, -0.048864 down ] 2021-05-18T02:49:55.003Z,1621306195.003 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:55.003Z,1621306195.003 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:49:55.330Z,1621306195.330 [DAT](INFO): DAT read: user:42> 2021-05-18T02:49:55.331Z,1621306195.331 [DAT](INFO): DAT read: Tx time:02:49:29.7405 2021-05-18T02:49:55.332Z,1621306195.332 [DAT](INFO): Ping request sent. 2021-05-18T02:49:55.332Z,1621306195.332 [DAT](INFO): transmitted an acoustic signal 2021-05-18T02:49:55.332Z,1621306195.332 [DAT](INFO): publishing transmit ping time 2021-05-18T02:49:55.375Z,1621306195.375 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:55.750Z,1621306195.750 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:56.161Z,1621306196.161 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:56.564Z,1621306196.564 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:56.981Z,1621306196.981 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:57.361Z,1621306197.361 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:57.769Z,1621306197.769 [DAT](INFO): DAT read: Rx Time:02:49:31.8702 2021-05-18T02:49:57.769Z,1621306197.769 [DAT](INFO): received an acoustic signal 2021-05-18T02:49:57.771Z,1621306197.771 [DAT](INFO): DAT read: Bearing 70.9, -6.2 (Local) 2021-05-18T02:49:57.771Z,1621306197.771 [DAT](INFO): Local bearing/azimuth received: Bearing 70.9, -6.2 (Local) 2021-05-18T02:49:57.773Z,1621306197.773 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:49:57.774Z,1621306197.774 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:49:57.774Z,1621306197.774 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:49:57.783Z,1621306197.783 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:57.784Z,1621306197.784 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.331389 forward, 0.935814 starboard, -0.120137 keelward ] 2021-05-18T02:49:57.785Z,1621306197.785 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:57.787Z,1621306197.787 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999351,-0.035929,-0.002472;0.035979,0.999040,0.024976;0.001572,-0.025049,0.999685 ] 2021-05-18T02:49:57.788Z,1621306197.788 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:49:57.788Z,1621306197.788 [lab_range_test:A.](INFO): direction in world frame: [ 0.364655 north, 0.926019 east, -0.097545 down ] 2021-05-18T02:49:57.789Z,1621306197.789 [lab_range_test:A.](INFO): relPosInFSK: [ 0.099417 forward, 0.280744 starboard, -0.036041 keelward ] 2021-05-18T02:49:57.790Z,1621306197.790 [lab_range_test:A.](INFO): relPosInNED: [ 0.109397 north, 0.277806 east, -0.029264 down ] 2021-05-18T02:49:57.791Z,1621306197.791 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:57.835Z,1621306197.835 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:49:58.180Z,1621306198.180 [DAT](INFO): DAT read: 02:49:31.8702 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 464,-0.06, 2.335, 2.028, 2.291, 2.263, PHS= 0.068,-0.191, 0.013, RAW= 138.4, 9.3, CAL= 139.1, 6.2, ROT= 70.9, -6.2 2021-05-18T02:49:58.181Z,1621306198.181 [DAT](INFO): got valid direction response: 02:49:31.8702 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 464,-0.06, 2.335, 2.028, 2.291, 2.263, PHS= 0.068,-0.191, 0.013, RAW= 138.4, 9.3, CAL= 139.1, 6.2, ROT= 70.9, -6.2 2021-05-18T02:49:58.182Z,1621306198.182 [DAT](INFO): DAT read: Rx Time:02:49:32.3701 2021-05-18T02:49:58.215Z,1621306198.215 [DAT](INFO): received an acoustic signal 2021-05-18T02:49:58.217Z,1621306198.217 [DAT](INFO): DAT read: Bearing 72.8, -4.7 (Local) 2021-05-18T02:49:58.217Z,1621306198.217 [DAT](INFO): Local bearing/azimuth received: Bearing 72.8, -4.7 (Local) 2021-05-18T02:49:58.227Z,1621306198.227 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:49:58.228Z,1621306198.228 [DAT](INFO): Read range and messages. 2021-05-18T02:49:58.230Z,1621306198.230 [DAT](INFO): direction in vehicle frame: [ 0.325304 forward, 0.939422 starboard, -0.107999 keelward ] 2021-05-18T02:49:58.230Z,1621306198.230 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:49:58.230Z,1621306198.230 [DAT](INFO): publishing direction and range info 2021-05-18T02:49:58.276Z,1621306198.276 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:58.277Z,1621306198.277 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.325304 forward, 0.939422 starboard, -0.107999 keelward ] 2021-05-18T02:49:58.277Z,1621306198.277 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:58.292Z,1621306198.292 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999340,-0.036248,-0.002403;0.036297,0.999029,0.024958;0.001496,-0.025029,0.999686 ] 2021-05-18T02:49:58.293Z,1621306198.293 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:49:58.294Z,1621306198.294 [lab_range_test:A.](INFO): direction in world frame: [ 0.359026 north, 0.929421 east, -0.085301 down ] 2021-05-18T02:49:58.294Z,1621306198.294 [lab_range_test:A.](INFO): relPosInFSK: [ 0.065061 forward, 0.187884 starboard, -0.021600 keelward ] 2021-05-18T02:49:58.300Z,1621306198.300 [lab_range_test:A.](INFO): relPosInNED: [ 0.071805 north, 0.185884 east, -0.017060 down ] 2021-05-18T02:49:58.300Z,1621306198.300 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:58.300Z,1621306198.300 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:49:58.580Z,1621306198.580 [DAT](INFO): DAT read: 02:49:32.3701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.06, 2.390, 2.115, 2.345, 2.318, PHS= 0.068,-0.159, 0.012, RAW= 136.3, 7.7, CAL= 137.2, 4.7, ROT= 72.8, -4.7 2021-05-18T02:49:58.581Z,1621306198.581 [DAT](INFO): got valid direction response: 02:49:32.3701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.06, 2.390, 2.115, 2.345, 2.318, PHS= 0.068,-0.159, 0.012, RAW= 136.3, 7.7, CAL= 137.2, 4.7, ROT= 72.8, -4.7 2021-05-18T02:49:58.582Z,1621306198.582 [DAT](INFO): DAT read: Rx Time:02:49:32.8702 2021-05-18T02:49:58.582Z,1621306198.582 [DAT](INFO): received an acoustic signal 2021-05-18T02:49:58.583Z,1621306198.583 [DAT](INFO): DAT read: Bearing 69.6, -8.6 (Local) 2021-05-18T02:49:58.584Z,1621306198.584 [DAT](INFO): Local bearing/azimuth received: Bearing 69.6, -8.6 (Local) 2021-05-18T02:49:58.584Z,1621306198.584 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:49:58.585Z,1621306198.585 [DAT](INFO): direction in vehicle frame: [ 0.294714 forward, 0.952066 starboard, -0.081939 keelward ] 2021-05-18T02:49:58.586Z,1621306198.586 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:49:58.598Z,1621306198.598 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:58.978Z,1621306198.978 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:49:58.983Z,1621306198.983 [DAT](INFO): DAT read: 02:49:32.8702 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.66,-1.431,-1.860,-1.491,-1.517, PHS= 0.082,-0.299, 0.010, RAW= 139.8, 11.8, CAL= 140.4, 8.6, ROT= 69.6, -8.6 2021-05-18T02:49:58.984Z,1621306198.984 [DAT](INFO): got valid direction response: 02:49:32.8702 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.66,-1.431,-1.860,-1.491,-1.517, PHS= 0.082,-0.299, 0.010, RAW= 139.8, 11.8, CAL= 140.4, 8.6, ROT= 69.6, -8.6 2021-05-18T02:49:58.984Z,1621306198.984 [DAT](INFO): Read range and messages. 2021-05-18T02:49:58.985Z,1621306198.985 [DAT](INFO): direction in vehicle frame: [ 0.344653 forward, 0.926744 starboard, -0.149535 keelward ] 2021-05-18T02:49:58.986Z,1621306198.986 [DAT](INFO): publishing direction and range info 2021-05-18T02:49:59.021Z,1621306199.021 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:59.023Z,1621306199.023 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.344653 forward, 0.926744 starboard, -0.149535 keelward ] 2021-05-18T02:49:59.023Z,1621306199.023 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:59.025Z,1621306199.025 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999320,-0.036783,-0.002511;0.036834,0.999012,0.024859;0.001595,-0.024934,0.999688 ] 2021-05-18T02:49:59.026Z,1621306199.026 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:49:59.027Z,1621306199.027 [lab_range_test:A.](INFO): direction in world frame: [ 0.378316 north, 0.916879 east, -0.127317 down ] 2021-05-18T02:49:59.027Z,1621306199.027 [lab_range_test:A.](INFO): relPosInFSK: [ 0.103396 forward, 0.278023 starboard, -0.044861 keelward ] 2021-05-18T02:49:59.028Z,1621306199.028 [lab_range_test:A.](INFO): relPosInNED: [ 0.113495 north, 0.275064 east, -0.038195 down ] 2021-05-18T02:49:59.029Z,1621306199.029 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:59.029Z,1621306199.029 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:49:59.397Z,1621306199.397 [DAT](INFO): DAT read: Rx Time:02:49:33.3701 2021-05-18T02:49:59.398Z,1621306199.398 [DAT](INFO): received an acoustic signal 2021-05-18T02:49:59.399Z,1621306199.399 [DAT](INFO): DAT read: Bearing 72.0, -5.6 (Local) 2021-05-18T02:49:59.399Z,1621306199.399 [DAT](INFO): Local bearing/azimuth received: Bearing 72.0, -5.6 (Local) 2021-05-18T02:49:59.401Z,1621306199.401 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:49:59.406Z,1621306199.406 [DAT](INFO): DAT read: 02:49:33.3701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.39, 2.150, 1.868, 2.106, 2.080, PHS= 0.066,-0.168, 0.011, RAW= 137.1, 8.6, CAL= 138.0, 5.6, ROT= 72.0, -5.6 2021-05-18T02:49:59.408Z,1621306199.408 [DAT](INFO): got valid direction response: 02:49:33.3701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.39, 2.150, 1.868, 2.106, 2.080, PHS= 0.066,-0.168, 0.011, RAW= 137.1, 8.6, CAL= 138.0, 5.6, ROT= 72.0, -5.6 2021-05-18T02:49:59.408Z,1621306199.408 [DAT](INFO): Read range and messages. 2021-05-18T02:49:59.409Z,1621306199.409 [DAT](INFO): direction in vehicle frame: [ 0.307542 forward, 0.946518 starboard, -0.097583 keelward ] 2021-05-18T02:49:59.409Z,1621306199.409 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:49:59.409Z,1621306199.409 [DAT](INFO): publishing direction and range info 2021-05-18T02:49:59.420Z,1621306199.420 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:59.421Z,1621306199.421 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.307542 forward, 0.946518 starboard, -0.097583 keelward ] 2021-05-18T02:49:59.422Z,1621306199.422 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:59.424Z,1621306199.424 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999282,-0.037818,-0.002481;0.037868,0.998976,0.024739;0.001542,-0.024815,0.999691 ] 2021-05-18T02:49:59.425Z,1621306199.425 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:49:59.425Z,1621306199.425 [lab_range_test:A.](INFO): direction in world frame: [ 0.343013 north, 0.936340 east, -0.074900 down ] 2021-05-18T02:49:59.426Z,1621306199.426 [lab_range_test:A.](INFO): relPosInFSK: [ 0.061508 forward, 0.189304 starboard, -0.019517 keelward ] 2021-05-18T02:49:59.463Z,1621306199.463 [lab_range_test:A.](INFO): relPosInNED: [ 0.068603 north, 0.187268 east, -0.014980 down ] 2021-05-18T02:49:59.464Z,1621306199.464 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:59.464Z,1621306199.464 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:49:59.794Z,1621306199.794 [DAT](INFO): DAT read: Rx Time:02:49:33.8701 2021-05-18T02:49:59.794Z,1621306199.794 [DAT](INFO): received an acoustic signal 2021-05-18T02:49:59.796Z,1621306199.796 [DAT](INFO): DAT read: Bearing 120.1, 6.5 (Local) 2021-05-18T02:49:59.796Z,1621306199.796 [DAT](INFO): Local bearing/azimuth received: Bearing 120.1, 6.5 (Local) 2021-05-18T02:49:59.807Z,1621306199.807 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:49:59.808Z,1621306199.808 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:49:59.808Z,1621306199.808 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:49:59.862Z,1621306199.862 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:49:59.871Z,1621306199.871 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.307542 forward, 0.946518 starboard, -0.097583 keelward ] 2021-05-18T02:49:59.871Z,1621306199.871 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:49:59.873Z,1621306199.873 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999332,-0.036456,-0.002480;0.036507,0.999023,0.024897;0.001570,-0.024971,0.999687 ] 2021-05-18T02:49:59.874Z,1621306199.874 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:49:59.874Z,1621306199.874 [lab_range_test:A.](INFO): direction in world frame: [ 0.341738 north, 0.936818 east, -0.074750 down ] 2021-05-18T02:49:59.883Z,1621306199.883 [lab_range_test:A.](INFO): relPosInFSK: [ 0.061508 forward, 0.189304 starboard, -0.019517 keelward ] 2021-05-18T02:49:59.884Z,1621306199.884 [lab_range_test:A.](INFO): relPosInNED: [ 0.068348 north, 0.187364 east, -0.014950 down ] 2021-05-18T02:49:59.885Z,1621306199.885 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:49:59.885Z,1621306199.885 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:00.197Z,1621306200.197 [DAT](INFO): DAT read: 02:49:33.8701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 512,-0.31, 0.260,-2.134,-2.092,-1.381, PHS= 1.637,-0.709,-0.726, RAW= 89.6, -1.7, CAL= 89.9, -6.5, ROT= 120.1, 6.5 2021-05-18T02:50:00.198Z,1621306200.198 [DAT](INFO): got valid direction response: 02:49:33.8701 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 512,-0.31, 0.260,-2.134,-2.092,-1.381, PHS= 1.637,-0.709,-0.726, RAW= 89.6, -1.7, CAL= 89.9, -6.5, ROT= 120.1, 6.5 2021-05-18T02:50:00.198Z,1621306200.198 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:50:00.199Z,1621306200.199 [DAT](INFO): direction in vehicle frame: [ -0.498287 forward, 0.859590 starboard, 0.113203 keelward ] 2021-05-18T02:50:00.209Z,1621306200.209 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:00.597Z,1621306200.597 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:00.997Z,1621306200.997 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:01.406Z,1621306201.406 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:01.829Z,1621306201.829 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:02.232Z,1621306202.232 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:02.625Z,1621306202.625 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:03.022Z,1621306203.022 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:03.434Z,1621306203.434 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:03.848Z,1621306203.848 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:04.249Z,1621306204.249 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:04.654Z,1621306204.654 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:05.050Z,1621306205.050 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:05.051Z,1621306205.051 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:05.051Z,1621306205.051 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:05.443Z,1621306205.443 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:05.857Z,1621306205.857 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:06.269Z,1621306206.269 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:06.673Z,1621306206.673 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:07.057Z,1621306207.057 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:07.462Z,1621306207.462 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:07.868Z,1621306207.868 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2021-05-18T02:50:07.868Z,1621306207.868 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2021-05-18T02:50:07.870Z,1621306207.870 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:07.878Z,1621306207.878 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2021-05-18T02:50:08.275Z,1621306208.275 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:08.284Z,1621306208.284 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2021-05-18T02:50:08.284Z,1621306208.284 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2021-05-18T02:50:08.672Z,1621306208.672 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:09.094Z,1621306209.094 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:09.500Z,1621306209.500 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:09.901Z,1621306209.901 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:10.289Z,1621306210.289 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:10.290Z,1621306210.290 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:10.290Z,1621306210.290 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:10.697Z,1621306210.697 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:11.094Z,1621306211.094 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:11.513Z,1621306211.513 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:11.929Z,1621306211.929 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:12.338Z,1621306212.338 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:12.729Z,1621306212.729 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:13.132Z,1621306213.132 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:13.545Z,1621306213.545 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:13.932Z,1621306213.932 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:14.332Z,1621306214.332 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:14.745Z,1621306214.745 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:15.161Z,1621306215.161 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:15.568Z,1621306215.568 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:15.568Z,1621306215.568 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:15.569Z,1621306215.569 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:15.961Z,1621306215.961 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:16.355Z,1621306216.355 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:16.761Z,1621306216.761 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:17.173Z,1621306217.173 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:17.582Z,1621306217.582 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:17.973Z,1621306217.973 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:18.385Z,1621306218.385 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:18.793Z,1621306218.793 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:19.173Z,1621306219.173 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:19.581Z,1621306219.581 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:19.982Z,1621306219.982 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:20.396Z,1621306220.396 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:20.809Z,1621306220.809 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:20.810Z,1621306220.810 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:20.810Z,1621306220.810 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:21.205Z,1621306221.205 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:21.613Z,1621306221.613 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:22.021Z,1621306222.021 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:22.406Z,1621306222.406 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:22.809Z,1621306222.809 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:23.238Z,1621306223.238 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:23.662Z,1621306223.662 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:24.057Z,1621306224.057 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:24.453Z,1621306224.453 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:24.845Z,1621306224.845 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:25.253Z,1621306225.253 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:25.642Z,1621306225.642 [DAT](INFO): ****** received valid address query ****** 2021-05-18T02:50:25.642Z,1621306225.642 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T02:50:25.643Z,1621306225.643 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode. 2021-05-18T02:50:25.644Z,1621306225.644 [DAT](INFO): ****** ping requested ****** 2021-05-18T02:50:25.721Z,1621306225.721 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:26.051Z,1621306226.051 [DAT](INFO): DAT read: user:43> 2021-05-18T02:50:26.052Z,1621306226.052 [DAT](INFO): DAT read: Tx time:02:50:00.4401 2021-05-18T02:50:26.052Z,1621306226.052 [DAT](INFO): Ping request sent. 2021-05-18T02:50:26.052Z,1621306226.052 [DAT](INFO): transmitted an acoustic signal 2021-05-18T02:50:26.053Z,1621306226.053 [DAT](INFO): publishing transmit ping time 2021-05-18T02:50:26.074Z,1621306226.074 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:26.075Z,1621306226.075 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:26.075Z,1621306226.075 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:26.474Z,1621306226.474 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:26.882Z,1621306226.882 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:27.273Z,1621306227.273 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:27.713Z,1621306227.713 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:28.094Z,1621306228.094 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:28.464Z,1621306228.464 [DAT](INFO): DAT read: Rx Time:02:50:02.5698 2021-05-18T02:50:28.465Z,1621306228.465 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:28.466Z,1621306228.466 [DAT](INFO): DAT read: Bearing 71.8, -6.0 (Local) 2021-05-18T02:50:28.467Z,1621306228.467 [DAT](INFO): Local bearing/azimuth received: Bearing 71.8, -6.0 (Local) 2021-05-18T02:50:28.469Z,1621306228.469 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:50:28.470Z,1621306228.470 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:50:28.470Z,1621306228.470 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:28.535Z,1621306228.535 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:28.536Z,1621306228.536 [lab_range_test:A.](INFO): direction in vehicle frame: [ -0.498287 forward, 0.859590 starboard, 0.113203 keelward ] 2021-05-18T02:50:28.536Z,1621306228.536 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:28.541Z,1621306228.541 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999303,-0.037250,-0.002478;0.037300,0.998996,0.024812;0.001551,-0.024888,0.999689 ] 2021-05-18T02:50:28.541Z,1621306228.541 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:50:28.542Z,1621306228.542 [lab_range_test:A.](INFO): direction in world frame: [ -0.465701 north, 0.874471 east, 0.135731 down ] 2021-05-18T02:50:28.543Z,1621306228.543 [lab_range_test:A.](INFO): relPosInFSK: [ -0.149486 forward, 0.257877 starboard, 0.033961 keelward ] 2021-05-18T02:50:28.573Z,1621306228.573 [lab_range_test:A.](INFO): relPosInNED: [ -0.139710 north, 0.262341 east, 0.040719 down ] 2021-05-18T02:50:28.573Z,1621306228.573 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:28.573Z,1621306228.573 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:28.878Z,1621306228.878 [DAT](INFO): DAT read: 02:50:02.5698 LVL= 32752, 32753, 32754, 32755, AGC= 68, IDX= 225,-0.42, 0.136,-0.214, 0.078, 0.050, PHS= 0.083,-0.219, 0.014, RAW= 137.4, 9.0, CAL= 138.2, 6.0, ROT= 71.8, -6.0 2021-05-18T02:50:28.884Z,1621306228.884 [DAT](INFO): got valid direction response: 02:50:02.5698 LVL= 32752, 32753, 32754, 32755, AGC= 68, IDX= 225,-0.42, 0.136,-0.214, 0.078, 0.050, PHS= 0.083,-0.219, 0.014, RAW= 137.4, 9.0, CAL= 138.2, 6.0, ROT= 71.8, -6.0 2021-05-18T02:50:28.885Z,1621306228.885 [DAT](INFO): DAT read: Rx Time:02:50:03.0699 2021-05-18T02:50:28.885Z,1621306228.885 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:28.886Z,1621306228.886 [DAT](INFO): DAT read: Bearing 69.1, -7.9 (Local) 2021-05-18T02:50:28.887Z,1621306228.887 [DAT](INFO): Local bearing/azimuth received: Bearing 69.1, -7.9 (Local) 2021-05-18T02:50:28.890Z,1621306228.890 [DAT](INFO): DAT read: Range 7 to 50 : 0.5 m (trip time 0.3 ms) speed 0.0 2021-05-18T02:50:28.895Z,1621306228.895 [DAT](INFO): Read range and messages. 2021-05-18T02:50:28.896Z,1621306228.896 [DAT](INFO): direction in vehicle frame: [ 0.310624 forward, 0.944768 starboard, -0.104528 keelward ] 2021-05-18T02:50:28.896Z,1621306228.896 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:28.897Z,1621306228.897 [DAT](INFO): publishing direction and range info 2021-05-18T02:50:28.957Z,1621306228.957 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:28.988Z,1621306228.988 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.310624 forward, 0.944768 starboard, -0.104528 keelward ] 2021-05-18T02:50:28.988Z,1621306228.988 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:28.999Z,1621306228.999 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999358,-0.035732,-0.002627;0.035787,0.999048,0.024931;0.001734,-0.025009,0.999686 ] 2021-05-18T02:50:28.000Z,1621306229.000 [lab_range_test:A.](INFO): rangeToContact_ = 0.500000 m 2021-05-18T02:50:29.001Z,1621306229.001 [lab_range_test:A.](INFO): direction in world frame: [ 0.344054 north, 0.935384 east, -0.081758 down ] 2021-05-18T02:50:29.002Z,1621306229.002 [lab_range_test:A.](INFO): relPosInFSK: [ 0.155312 forward, 0.472384 starboard, -0.052264 keelward ] 2021-05-18T02:50:29.002Z,1621306229.002 [lab_range_test:A.](INFO): relPosInNED: [ 0.172027 north, 0.467692 east, -0.040879 down ] 2021-05-18T02:50:29.019Z,1621306229.019 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:29.019Z,1621306229.019 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:29.277Z,1621306229.277 [DAT](INFO): DAT read: 02:50:03.0699 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 497,-0.19,-0.030,-0.342,-0.066,-0.092, PHS= 0.058,-0.205, 0.012, RAW= 140.4, 11.1, CAL= 140.9, 7.9, ROT= 69.1, -7.9 2021-05-18T02:50:29.278Z,1621306229.278 [DAT](INFO): got valid direction response: 02:50:03.0699 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 497,-0.19,-0.030,-0.342,-0.066,-0.092, PHS= 0.058,-0.205, 0.012, RAW= 140.4, 11.1, CAL= 140.9, 7.9, ROT= 69.1, -7.9 2021-05-18T02:50:29.279Z,1621306229.279 [DAT](INFO): DAT read: Rx Time:02:50:03.5698 2021-05-18T02:50:29.279Z,1621306229.279 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:29.280Z,1621306229.280 [DAT](INFO): DAT read: Bearing 71.9, -6.0 (Local) 2021-05-18T02:50:29.280Z,1621306229.280 [DAT](INFO): Local bearing/azimuth received: Bearing 71.9, -6.0 (Local) 2021-05-18T02:50:29.281Z,1621306229.281 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:50:29.282Z,1621306229.282 [DAT](INFO): direction in vehicle frame: [ 0.353352 forward, 0.925338 starboard, -0.137445 keelward ] 2021-05-18T02:50:29.282Z,1621306229.282 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:29.338Z,1621306229.338 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:29.672Z,1621306229.672 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:50:29.677Z,1621306229.677 [DAT](INFO): DAT read: 02:50:03.5698 LVL= 32752, 32753, 32754, 32755, AGC= 66, IDX= 496,-0.06,-0.628,-0.950,-0.680,-0.707, PHS= 0.075,-0.198, 0.012, RAW= 137.3, 9.0, CAL= 138.1, 6.0, ROT= 71.9, -6.0 2021-05-18T02:50:29.678Z,1621306229.678 [DAT](INFO): got valid direction response: 02:50:03.5698 LVL= 32752, 32753, 32754, 32755, AGC= 66, IDX= 496,-0.06,-0.628,-0.950,-0.680,-0.707, PHS= 0.075,-0.198, 0.012, RAW= 137.3, 9.0, CAL= 138.1, 6.0, ROT= 71.9, -6.0 2021-05-18T02:50:29.679Z,1621306229.679 [DAT](INFO): Read range and messages. 2021-05-18T02:50:29.680Z,1621306229.680 [DAT](INFO): direction in vehicle frame: [ 0.308974 forward, 0.945309 starboard, -0.104528 keelward ] 2021-05-18T02:50:29.680Z,1621306229.680 [DAT](INFO): publishing direction and range info 2021-05-18T02:50:29.700Z,1621306229.700 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:29.701Z,1621306229.701 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.308974 forward, 0.945309 starboard, -0.104528 keelward ] 2021-05-18T02:50:29.701Z,1621306229.701 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:29.706Z,1621306229.706 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999338,-0.036299,-0.002556;0.036351,0.999029,0.024908;0.001650,-0.024985,0.999686 ] 2021-05-18T02:50:29.715Z,1621306229.715 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:50:29.716Z,1621306229.716 [lab_range_test:A.](INFO): direction in world frame: [ 0.342960 north, 0.935787 east, -0.081739 down ] 2021-05-18T02:50:29.717Z,1621306229.717 [lab_range_test:A.](INFO): relPosInFSK: [ 0.092692 forward, 0.283593 starboard, -0.031359 keelward ] 2021-05-18T02:50:29.718Z,1621306229.718 [lab_range_test:A.](INFO): relPosInNED: [ 0.102888 north, 0.280736 east, -0.024522 down ] 2021-05-18T02:50:29.718Z,1621306229.718 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:29.719Z,1621306229.719 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:30.086Z,1621306230.086 [DAT](INFO): DAT read: Rx Time:02:50:04.0698 2021-05-18T02:50:30.086Z,1621306230.086 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:30.088Z,1621306230.088 [DAT](INFO): DAT read: Bearing 70.1, -7.5 (Local) 2021-05-18T02:50:30.088Z,1621306230.088 [DAT](INFO): Local bearing/azimuth received: Bearing 70.1, -7.5 (Local) 2021-05-18T02:50:30.090Z,1621306230.090 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:50:30.099Z,1621306230.099 [DAT](INFO): DAT read: 02:50:04.0698 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.07,-0.106,-0.390,-0.142,-0.166, PHS= 0.056,-0.180, 0.009, RAW= 139.3, 10.7, CAL= 139.9, 7.5, ROT= 70.1, -7.5 2021-05-18T02:50:30.100Z,1621306230.100 [DAT](INFO): got valid direction response: 02:50:04.0698 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496, 0.07,-0.106,-0.390,-0.142,-0.166, PHS= 0.056,-0.180, 0.009, RAW= 139.3, 10.7, CAL= 139.9, 7.5, ROT= 70.1, -7.5 2021-05-18T02:50:30.100Z,1621306230.100 [DAT](INFO): Read range and messages. 2021-05-18T02:50:30.101Z,1621306230.101 [DAT](INFO): direction in vehicle frame: [ 0.337468 forward, 0.932244 starboard, -0.130526 keelward ] 2021-05-18T02:50:30.102Z,1621306230.102 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:30.102Z,1621306230.102 [DAT](INFO): publishing direction and range info 2021-05-18T02:50:30.128Z,1621306230.128 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:30.129Z,1621306230.129 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.337468 forward, 0.932244 starboard, -0.130526 keelward ] 2021-05-18T02:50:30.130Z,1621306230.130 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:30.140Z,1621306230.140 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999329,-0.036543,-0.002644;0.036598,0.999020,0.024883;0.001732,-0.024964,0.999687 ] 2021-05-18T02:50:30.140Z,1621306230.140 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:50:30.141Z,1621306230.141 [lab_range_test:A.](INFO): direction in world frame: [ 0.371133 north, 0.922257 east, -0.108180 down ] 2021-05-18T02:50:30.142Z,1621306230.142 [lab_range_test:A.](INFO): relPosInFSK: [ 0.101240 forward, 0.279673 starboard, -0.039158 keelward ] 2021-05-18T02:50:30.142Z,1621306230.142 [lab_range_test:A.](INFO): relPosInNED: [ 0.111340 north, 0.276677 east, -0.032454 down ] 2021-05-18T02:50:30.179Z,1621306230.179 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:30.179Z,1621306230.179 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:30.514Z,1621306230.514 [DAT](INFO): DAT read: Rx Time:02:50:04.5696 2021-05-18T02:50:30.514Z,1621306230.514 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:30.521Z,1621306230.521 [DAT](INFO): DAT read: Bearing 71.7, -6.5 (Local) 2021-05-18T02:50:30.521Z,1621306230.521 [DAT](INFO): Local bearing/azimuth received: Bearing 71.7, -6.5 (Local) 2021-05-18T02:50:30.542Z,1621306230.542 [DAT](INFO): DAT read: Range 7 to 50 : 0.0 m (trip time 0.0 ms) speed 0.0 2021-05-18T02:50:30.542Z,1621306230.542 [DAT](INFO): unknown deviceResponse_: Range 7 to 50 : 0.0 m (trip time 0.0 ms) speed 0.0 2021-05-18T02:50:30.568Z,1621306230.568 [DAT](INFO): DAT read: 02:50:04.5696 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.18,-0.035,-0.303,-0.073,-0.097, PHS= 0.058,-0.162, 0.008, RAW= 137.5, 9.6, CAL= 138.3, 6.5, ROT= 71.7, -6.5 2021-05-18T02:50:30.569Z,1621306230.569 [DAT](INFO): got valid direction response: 02:50:04.5696 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 495, 0.18,-0.035,-0.303,-0.073,-0.097, PHS= 0.058,-0.162, 0.008, RAW= 137.5, 9.6, CAL= 138.3, 6.5, ROT= 71.7, -6.5 2021-05-18T02:50:30.569Z,1621306230.569 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:50:30.570Z,1621306230.570 [DAT](INFO): direction in vehicle frame: [ 0.311974 forward, 0.943322 starboard, -0.113203 keelward ] 2021-05-18T02:50:30.571Z,1621306230.571 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:30.598Z,1621306230.598 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:30.945Z,1621306230.945 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:31.322Z,1621306231.322 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:31.734Z,1621306231.734 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:32.117Z,1621306232.117 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:32.519Z,1621306232.519 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:32.938Z,1621306232.938 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:33.346Z,1621306233.346 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:33.733Z,1621306233.733 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:34.133Z,1621306234.133 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:34.543Z,1621306234.543 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:34.937Z,1621306234.937 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:35.382Z,1621306235.382 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:35.382Z,1621306235.382 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:35.383Z,1621306235.383 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:35.750Z,1621306235.750 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:36.158Z,1621306236.158 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:36.581Z,1621306236.581 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:36.974Z,1621306236.974 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:37.365Z,1621306237.365 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:37.806Z,1621306237.806 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:38.214Z,1621306238.214 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:38.572Z,1621306238.572 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:39.006Z,1621306239.006 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:39.413Z,1621306239.413 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:39.809Z,1621306239.809 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:40.198Z,1621306240.198 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:40.604Z,1621306240.604 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:40.605Z,1621306240.605 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:40.605Z,1621306240.605 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:41.009Z,1621306241.009 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:41.425Z,1621306241.425 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:41.859Z,1621306241.859 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:42.257Z,1621306242.257 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:42.673Z,1621306242.673 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:43.047Z,1621306243.047 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:43.416Z,1621306243.416 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:43.868Z,1621306243.868 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:44.253Z,1621306244.253 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:44.668Z,1621306244.668 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:45.078Z,1621306245.078 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:45.470Z,1621306245.470 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:45.872Z,1621306245.872 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:45.873Z,1621306245.873 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:45.873Z,1621306245.873 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:46.318Z,1621306246.318 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:46.665Z,1621306246.665 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:47.058Z,1621306247.058 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:47.474Z,1621306247.474 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:47.883Z,1621306247.883 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:48.297Z,1621306248.297 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:48.685Z,1621306248.685 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:49.078Z,1621306249.078 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:49.477Z,1621306249.477 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:49.881Z,1621306249.881 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:50.288Z,1621306250.288 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:50.686Z,1621306250.686 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:51.118Z,1621306251.118 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:51.118Z,1621306251.118 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:51.119Z,1621306251.119 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:51.513Z,1621306251.513 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:51.921Z,1621306251.921 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:52.317Z,1621306252.317 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:52.710Z,1621306252.710 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:53.113Z,1621306253.113 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:53.521Z,1621306253.521 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:53.941Z,1621306253.941 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:54.348Z,1621306254.348 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:54.746Z,1621306254.746 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:55.141Z,1621306255.141 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:55.549Z,1621306255.549 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:55.941Z,1621306255.941 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:56.335Z,1621306256.335 [DAT](INFO): ****** received valid address query ****** 2021-05-18T02:50:56.335Z,1621306256.335 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T02:50:56.336Z,1621306256.336 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode. 2021-05-18T02:50:56.338Z,1621306256.338 [DAT](INFO): ****** ping requested ****** 2021-05-18T02:50:56.353Z,1621306256.353 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:56.354Z,1621306256.354 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:50:56.354Z,1621306256.354 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:50:56.746Z,1621306256.746 [DAT](INFO): DAT read: user:44> 2021-05-18T02:50:56.747Z,1621306256.747 [DAT](INFO): DAT read: Tx time:02:50:31.1397 2021-05-18T02:50:56.748Z,1621306256.748 [DAT](INFO): Ping request sent. 2021-05-18T02:50:56.748Z,1621306256.748 [DAT](INFO): transmitted an acoustic signal 2021-05-18T02:50:56.748Z,1621306256.748 [DAT](INFO): publishing transmit ping time 2021-05-18T02:50:56.802Z,1621306256.802 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:57.173Z,1621306257.173 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:57.592Z,1621306257.592 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:57.989Z,1621306257.989 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:58.371Z,1621306258.371 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:58.786Z,1621306258.786 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:59.168Z,1621306259.168 [DAT](INFO): DAT read: Rx Time:02:50:33.2694 2021-05-18T02:50:59.169Z,1621306259.169 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:59.170Z,1621306259.170 [DAT](INFO): DAT read: Bearing 70.7, -6.5 (Local) 2021-05-18T02:50:59.170Z,1621306259.170 [DAT](INFO): Local bearing/azimuth received: Bearing 70.7, -6.5 (Local) 2021-05-18T02:50:59.173Z,1621306259.173 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:50:59.174Z,1621306259.174 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:50:59.174Z,1621306259.174 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:59.183Z,1621306259.183 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:59.184Z,1621306259.184 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.311974 forward, 0.943322 starboard, -0.113203 keelward ] 2021-05-18T02:50:59.185Z,1621306259.185 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:59.240Z,1621306259.240 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999389,-0.034861,-0.002520;0.034913,0.999076,0.025053;0.001644,-0.025126,0.999683 ] 2021-05-18T02:50:59.241Z,1621306259.241 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:50:59.241Z,1621306259.241 [lab_range_test:A.](INFO): direction in world frame: [ 0.344532 north, 0.934420 east, -0.090320 down ] 2021-05-18T02:50:59.242Z,1621306259.242 [lab_range_test:A.](INFO): relPosInFSK: [ 0.093592 forward, 0.282997 starboard, -0.033961 keelward ] 2021-05-18T02:50:59.259Z,1621306259.259 [lab_range_test:A.](INFO): relPosInNED: [ 0.103360 north, 0.280326 east, -0.027096 down ] 2021-05-18T02:50:59.259Z,1621306259.259 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:59.260Z,1621306259.260 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:50:59.591Z,1621306259.591 [DAT](INFO): DAT read: 02:50:33.2694 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 224, 0.27,-1.206,-1.469,-1.239,-1.265, PHS= 0.055,-0.160, 0.011, RAW= 138.6, 9.6, CAL= 139.3, 6.5, ROT= 70.7, -6.5 2021-05-18T02:50:59.593Z,1621306259.593 [DAT](INFO): got valid direction response: 02:50:33.2694 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 224, 0.27,-1.206,-1.469,-1.239,-1.265, PHS= 0.055,-0.160, 0.011, RAW= 138.6, 9.6, CAL= 139.3, 6.5, ROT= 70.7, -6.5 2021-05-18T02:50:59.594Z,1621306259.594 [DAT](INFO): DAT read: Rx Time:02:50:33.7694 2021-05-18T02:50:59.594Z,1621306259.594 [DAT](INFO): received an acoustic signal 2021-05-18T02:50:59.596Z,1621306259.596 [DAT](INFO): DAT read: Bearing 69.2, -8.1 (Local) 2021-05-18T02:50:59.596Z,1621306259.596 [DAT](INFO): Local bearing/azimuth received: Bearing 69.2, -8.1 (Local) 2021-05-18T02:50:59.598Z,1621306259.598 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:50:59.599Z,1621306259.599 [DAT](INFO): Read range and messages. 2021-05-18T02:50:59.600Z,1621306259.600 [DAT](INFO): direction in vehicle frame: [ 0.328390 forward, 0.937734 starboard, -0.113203 keelward ] 2021-05-18T02:50:59.600Z,1621306259.600 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:50:59.600Z,1621306259.600 [DAT](INFO): publishing direction and range info 2021-05-18T02:50:59.612Z,1621306259.612 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:50:59.614Z,1621306259.614 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.328390 forward, 0.937734 starboard, -0.113203 keelward ] 2021-05-18T02:50:59.614Z,1621306259.614 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:50:59.616Z,1621306259.616 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999347,-0.036048,-0.002505;0.036100,0.999038,0.024913;0.001604,-0.024987,0.999686 ] 2021-05-18T02:50:59.617Z,1621306259.617 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:50:59.618Z,1621306259.618 [lab_range_test:A.](INFO): direction in world frame: [ 0.361846 north, 0.927822 east, -0.090629 down ] 2021-05-18T02:50:59.619Z,1621306259.619 [lab_range_test:A.](INFO): relPosInFSK: [ 0.098517 forward, 0.281320 starboard, -0.033961 keelward ] 2021-05-18T02:50:59.620Z,1621306259.620 [lab_range_test:A.](INFO): relPosInNED: [ 0.108554 north, 0.278347 east, -0.027189 down ] 2021-05-18T02:50:59.620Z,1621306259.620 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:50:59.620Z,1621306259.620 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:00.003Z,1621306260.003 [DAT](INFO): DAT read: 02:50:33.7694 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 481,-0.49,-2.842, 3.130,-2.878,-2.904, PHS= 0.058,-0.206, 0.010, RAW= 140.3, 11.3, CAL= 140.8, 8.1, ROT= 69.2, -8.1 2021-05-18T02:51:00.005Z,1621306260.005 [DAT](INFO): got valid direction response: 02:50:33.7694 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 481,-0.49,-2.842, 3.130,-2.878,-2.904, PHS= 0.058,-0.206, 0.010, RAW= 140.3, 11.3, CAL= 140.8, 8.1, ROT= 69.2, -8.1 2021-05-18T02:51:00.006Z,1621306260.006 [DAT](INFO): DAT read: Rx Time:02:50:34.2693 2021-05-18T02:51:00.006Z,1621306260.006 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:00.011Z,1621306260.011 [DAT](INFO): DAT read: Bearing 69.1, -8.2 (Local) 2021-05-18T02:51:00.012Z,1621306260.012 [DAT](INFO): Local bearing/azimuth received: Bearing 69.1, -8.2 (Local) 2021-05-18T02:51:00.012Z,1621306260.012 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:51:00.013Z,1621306260.013 [DAT](INFO): direction in vehicle frame: [ 0.351564 forward, 0.925500 starboard, -0.140901 keelward ] 2021-05-18T02:51:00.014Z,1621306260.014 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:00.072Z,1621306260.072 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:00.390Z,1621306260.390 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:51:00.395Z,1621306260.395 [DAT](INFO): DAT read: 02:50:34.2693 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.27, 2.157, 1.839, 2.120, 2.095, PHS= 0.059,-0.211, 0.010, RAW= 140.4, 11.4, CAL= 140.9, 8.2, ROT= 69.1, -8.2 2021-05-18T02:51:00.396Z,1621306260.396 [DAT](INFO): got valid direction response: 02:50:34.2693 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.27, 2.157, 1.839, 2.120, 2.095, PHS= 0.059,-0.211, 0.010, RAW= 140.4, 11.4, CAL= 140.9, 8.2, ROT= 69.1, -8.2 2021-05-18T02:51:00.396Z,1621306260.396 [DAT](INFO): Read range and messages. 2021-05-18T02:51:00.397Z,1621306260.397 [DAT](INFO): direction in vehicle frame: [ 0.353091 forward, 0.924653 starboard, -0.142629 keelward ] 2021-05-18T02:51:00.398Z,1621306260.398 [DAT](INFO): publishing direction and range info 2021-05-18T02:51:00.408Z,1621306260.408 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:00.409Z,1621306260.409 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.353091 forward, 0.924653 starboard, -0.142629 keelward ] 2021-05-18T02:51:00.410Z,1621306260.410 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:00.412Z,1621306260.412 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999373,-0.035309,-0.002594;0.035363,0.999062,0.024991;0.001709,-0.025068,0.999684 ] 2021-05-18T02:51:00.413Z,1621306260.413 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:51:00.414Z,1621306260.414 [lab_range_test:A.](INFO): direction in world frame: [ 0.385324 north, 0.914894 east, -0.120391 down ] 2021-05-18T02:51:00.414Z,1621306260.414 [lab_range_test:A.](INFO): relPosInFSK: [ 0.070618 forward, 0.184931 starboard, -0.028526 keelward ] 2021-05-18T02:51:00.415Z,1621306260.415 [lab_range_test:A.](INFO): relPosInNED: [ 0.077065 north, 0.182979 east, -0.024078 down ] 2021-05-18T02:51:00.416Z,1621306260.416 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:00.416Z,1621306260.416 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:00.798Z,1621306260.798 [DAT](INFO): DAT read: Rx Time:02:50:34.7695 2021-05-18T02:51:00.798Z,1621306260.798 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:00.807Z,1621306260.807 [DAT](INFO): DAT read: Bearing 71.6, -6.6 (Local) 2021-05-18T02:51:00.808Z,1621306260.808 [DAT](INFO): Local bearing/azimuth received: Bearing 71.6, -6.6 (Local) 2021-05-18T02:51:00.810Z,1621306260.810 [DAT](INFO): DAT read: Range 7 to 50 : 0.5 m (trip time 0.3 ms) speed 0.0 2021-05-18T02:51:00.815Z,1621306260.815 [DAT](INFO): DAT read: 02:50:34.7695 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 1,-0.13,-2.445,-2.784,-2.499,-2.525, PHS= 0.076,-0.215, 0.011, RAW= 137.7, 9.7, CAL= 138.4, 6.6, ROT= 71.6, -6.6 2021-05-18T02:51:00.848Z,1621306260.848 [DAT](INFO): got valid direction response: 02:50:34.7695 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 1,-0.13,-2.445,-2.784,-2.499,-2.525, PHS= 0.076,-0.215, 0.011, RAW= 137.7, 9.7, CAL= 138.4, 6.6, ROT= 71.6, -6.6 2021-05-18T02:51:00.848Z,1621306260.848 [DAT](INFO): Read range and messages. 2021-05-18T02:51:00.849Z,1621306260.849 [DAT](INFO): direction in vehicle frame: [ 0.313557 forward, 0.942588 starboard, -0.114937 keelward ] 2021-05-18T02:51:00.849Z,1621306260.849 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:00.850Z,1621306260.850 [DAT](INFO): publishing direction and range info 2021-05-18T02:51:00.892Z,1621306260.892 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:00.893Z,1621306260.893 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.313557 forward, 0.942588 starboard, -0.114937 keelward ] 2021-05-18T02:51:00.894Z,1621306260.894 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:00.905Z,1621306260.905 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999337,-0.036321,-0.002539;0.036373,0.999028,0.024895;0.001632,-0.024970,0.999687 ] 2021-05-18T02:51:00.905Z,1621306260.905 [lab_range_test:A.](INFO): rangeToContact_ = 0.500000 m 2021-05-18T02:51:00.906Z,1621306260.906 [lab_range_test:A.](INFO): direction in world frame: [ 0.347446 north, 0.933153 east, -0.092232 down ] 2021-05-18T02:51:00.906Z,1621306260.906 [lab_range_test:A.](INFO): relPosInFSK: [ 0.156779 forward, 0.471294 starboard, -0.057469 keelward ] 2021-05-18T02:51:00.916Z,1621306260.916 [lab_range_test:A.](INFO): relPosInNED: [ 0.173723 north, 0.466576 east, -0.046116 down ] 2021-05-18T02:51:00.916Z,1621306260.916 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:00.916Z,1621306260.916 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:01.192Z,1621306261.192 [DAT](INFO): DAT read: Rx Time:02:50:35.2694 2021-05-18T02:51:01.192Z,1621306261.192 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:01.194Z,1621306261.194 [DAT](INFO): DAT read: Bearing 69.1, -8.0 (Local) 2021-05-18T02:51:01.194Z,1621306261.194 [DAT](INFO): Local bearing/azimuth received: Bearing 69.1, -8.0 (Local) 2021-05-18T02:51:01.197Z,1621306261.197 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:51:01.198Z,1621306261.198 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:51:01.198Z,1621306261.198 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:01.226Z,1621306261.226 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:01.232Z,1621306261.232 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.313557 forward, 0.942588 starboard, -0.114937 keelward ] 2021-05-18T02:51:01.232Z,1621306261.232 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:01.234Z,1621306261.234 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999344,-0.036121,-0.002558;0.036174,0.999035,0.024918;0.001655,-0.024994,0.999686 ] 2021-05-18T02:51:01.235Z,1621306261.235 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:51:01.244Z,1621306261.244 [lab_range_test:A.](INFO): direction in world frame: [ 0.347258 north, 0.933224 east, -0.092216 down ] 2021-05-18T02:51:01.245Z,1621306261.245 [lab_range_test:A.](INFO): relPosInFSK: [ 0.094067 forward, 0.282776 starboard, -0.034481 keelward ] 2021-05-18T02:51:01.245Z,1621306261.245 [lab_range_test:A.](INFO): relPosInNED: [ 0.104178 north, 0.279967 east, -0.027665 down ] 2021-05-18T02:51:01.246Z,1621306261.246 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:01.246Z,1621306261.246 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:01.590Z,1621306261.590 [DAT](INFO): DAT read: 02:50:35.2694 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.01,-3.084, 2.900,-3.118, 3.140, PHS= 0.055,-0.196, 0.010, RAW= 140.4, 11.3, CAL= 140.9, 8.0, ROT= 69.1, -8.0 2021-05-18T02:51:01.592Z,1621306261.592 [DAT](INFO): got valid direction response: 02:50:35.2694 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 496,-0.01,-3.084, 2.900,-3.118, 3.140, PHS= 0.055,-0.196, 0.010, RAW= 140.4, 11.3, CAL= 140.9, 8.0, ROT= 69.1, -8.0 2021-05-18T02:51:01.592Z,1621306261.592 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:51:01.593Z,1621306261.593 [DAT](INFO): direction in vehicle frame: [ 0.353266 forward, 0.925113 starboard, -0.139173 keelward ] 2021-05-18T02:51:01.656Z,1621306261.656 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:02.001Z,1621306262.001 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:02.402Z,1621306262.402 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:02.859Z,1621306262.859 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:03.233Z,1621306263.233 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:03.649Z,1621306263.649 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:04.022Z,1621306264.022 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:04.434Z,1621306264.434 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:04.850Z,1621306264.850 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:05.261Z,1621306265.261 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:05.653Z,1621306265.653 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:06.050Z,1621306266.050 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:06.458Z,1621306266.458 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:06.459Z,1621306266.459 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:06.459Z,1621306266.459 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:06.873Z,1621306266.873 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:07.273Z,1621306267.273 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:07.682Z,1621306267.682 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:08.080Z,1621306268.080 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:08.473Z,1621306268.473 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:08.869Z,1621306268.869 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:09.277Z,1621306269.277 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:09.692Z,1621306269.692 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:10.104Z,1621306270.104 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:10.505Z,1621306270.505 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:10.913Z,1621306270.913 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:11.305Z,1621306271.305 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:11.732Z,1621306271.732 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:11.734Z,1621306271.734 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:11.734Z,1621306271.734 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:12.119Z,1621306272.119 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:12.517Z,1621306272.517 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:12.934Z,1621306272.934 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:13.342Z,1621306273.342 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:13.733Z,1621306273.733 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:14.132Z,1621306274.132 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:14.538Z,1621306274.538 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:14.933Z,1621306274.933 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:15.338Z,1621306275.338 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:15.749Z,1621306275.749 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:16.156Z,1621306276.156 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:16.573Z,1621306276.573 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:16.961Z,1621306276.961 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:16.962Z,1621306276.962 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:16.962Z,1621306276.962 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:17.353Z,1621306277.353 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:17.765Z,1621306277.765 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:18.178Z,1621306278.178 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:18.566Z,1621306278.566 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:18.989Z,1621306278.989 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:19.394Z,1621306279.394 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:19.797Z,1621306279.797 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:20.181Z,1621306280.181 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:20.593Z,1621306280.593 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:20.994Z,1621306280.994 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:21.406Z,1621306281.406 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:21.822Z,1621306281.822 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:22.215Z,1621306282.215 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:22.216Z,1621306282.216 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:22.216Z,1621306282.216 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:22.625Z,1621306282.625 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:23.022Z,1621306283.022 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:23.413Z,1621306283.413 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:23.833Z,1621306283.833 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:24.242Z,1621306284.242 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:24.646Z,1621306284.646 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:25.029Z,1621306285.029 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:25.431Z,1621306285.431 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:25.862Z,1621306285.862 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:26.265Z,1621306286.265 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:26.673Z,1621306286.673 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:27.043Z,1621306287.043 [DAT](INFO): ****** received valid address query ****** 2021-05-18T02:51:27.043Z,1621306287.043 [DAT](INFO): ****** received valid ping request ****** 2021-05-18T02:51:27.043Z,1621306287.043 [DAT](INFO): Querying Benthos address 50 with 5 pings in terminal homing one-way mode. 2021-05-18T02:51:27.045Z,1621306287.045 [DAT](INFO): ****** ping requested ****** 2021-05-18T02:51:27.062Z,1621306287.062 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:27.446Z,1621306287.446 [DAT](INFO): DAT read: user:45> 2021-05-18T02:51:27.448Z,1621306287.448 [DAT](INFO): DAT read: Tx time:02:51:01.8393 2021-05-18T02:51:27.448Z,1621306287.448 [DAT](INFO): Ping request sent. 2021-05-18T02:51:27.448Z,1621306287.448 [DAT](INFO): transmitted an acoustic signal 2021-05-18T02:51:27.448Z,1621306287.448 [DAT](INFO): publishing transmit ping time 2021-05-18T02:51:27.461Z,1621306287.461 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:27.462Z,1621306287.462 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:27.462Z,1621306287.462 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:27.883Z,1621306287.883 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:28.290Z,1621306288.290 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:28.681Z,1621306288.681 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:29.079Z,1621306289.079 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:29.489Z,1621306289.489 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:29.879Z,1621306289.879 [DAT](INFO): DAT read: Rx Time:02:51:03.9690 2021-05-18T02:51:29.880Z,1621306289.880 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:29.881Z,1621306289.881 [DAT](INFO): DAT read: Bearing 69.7, -7.3 (Local) 2021-05-18T02:51:29.881Z,1621306289.881 [DAT](INFO): Local bearing/azimuth received: Bearing 69.7, -7.3 (Local) 2021-05-18T02:51:29.884Z,1621306289.884 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:51:29.885Z,1621306289.885 [DAT](ERROR): Read range message, but no direction. 2021-05-18T02:51:29.885Z,1621306289.885 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:29.925Z,1621306289.925 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:29.926Z,1621306289.926 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.353266 forward, 0.925113 starboard, -0.139173 keelward ] 2021-05-18T02:51:29.927Z,1621306289.927 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:29.964Z,1621306289.964 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999337,-0.036299,-0.002709;0.036355,0.999031,0.024821;0.001805,-0.024903,0.999688 ] 2021-05-18T02:51:29.964Z,1621306289.964 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:51:29.965Z,1621306289.965 [lab_range_test:A.](INFO): direction in world frame: [ 0.386413 north, 0.914859 east, -0.117124 down ] 2021-05-18T02:51:29.965Z,1621306289.965 [lab_range_test:A.](INFO): relPosInFSK: [ 0.105980 forward, 0.277534 starboard, -0.041752 keelward ] 2021-05-18T02:51:29.966Z,1621306289.966 [lab_range_test:A.](INFO): relPosInNED: [ 0.115924 north, 0.274458 east, -0.035137 down ] 2021-05-18T02:51:29.966Z,1621306289.966 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:29.967Z,1621306289.967 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:30.296Z,1621306290.296 [DAT](INFO): DAT read: 02:51:03.9690 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 208,-0.20, 0.944, 0.623, 0.904, 0.876, PHS= 0.065,-0.209, 0.013, RAW= 139.7, 10.5, CAL= 140.3, 7.3, ROT= 69.7, -7.3 2021-05-18T02:51:30.298Z,1621306290.298 [DAT](INFO): got valid direction response: 02:51:03.9690 LVL= 32752, 32753, 32754, 32755, AGC= 69, IDX= 208,-0.20, 0.944, 0.623, 0.904, 0.876, PHS= 0.065,-0.209, 0.013, RAW= 139.7, 10.5, CAL= 140.3, 7.3, ROT= 69.7, -7.3 2021-05-18T02:51:30.299Z,1621306290.299 [DAT](INFO): DAT read: Rx Time:02:51:04.4689 2021-05-18T02:51:30.299Z,1621306290.299 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:30.301Z,1621306290.301 [DAT](INFO): DAT read: Bearing 68.7, -8.7 (Local) 2021-05-18T02:51:30.301Z,1621306290.301 [DAT](INFO): Local bearing/azimuth received: Bearing 68.7, -8.7 (Local) 2021-05-18T02:51:30.303Z,1621306290.303 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:51:30.304Z,1621306290.304 [DAT](INFO): Read range and messages. 2021-05-18T02:51:30.305Z,1621306290.305 [DAT](INFO): direction in vehicle frame: [ 0.344124 forward, 0.930287 starboard, -0.127065 keelward ] 2021-05-18T02:51:30.305Z,1621306290.305 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:30.306Z,1621306290.306 [DAT](INFO): publishing direction and range info 2021-05-18T02:51:30.317Z,1621306290.317 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:30.319Z,1621306290.319 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.344124 forward, 0.930287 starboard, -0.127065 keelward ] 2021-05-18T02:51:30.319Z,1621306290.319 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:30.322Z,1621306290.322 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999377,-0.035207,-0.002614;0.035261,0.999066,0.024983;0.001732,-0.025060,0.999684 ] 2021-05-18T02:51:30.322Z,1621306290.322 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:51:30.323Z,1621306290.323 [lab_range_test:A.](INFO): direction in world frame: [ 0.376492 north, 0.920486 east, -0.104682 down ] 2021-05-18T02:51:30.324Z,1621306290.324 [lab_range_test:A.](INFO): relPosInFSK: [ 0.068825 forward, 0.186057 starboard, -0.025413 keelward ] 2021-05-18T02:51:30.325Z,1621306290.325 [lab_range_test:A.](INFO): relPosInNED: [ 0.075298 north, 0.184097 east, -0.020936 down ] 2021-05-18T02:51:30.325Z,1621306290.325 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:30.325Z,1621306290.325 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:30.690Z,1621306290.690 [DAT](INFO): DAT read: 02:51:04.4689 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 479,-0.04,-0.382,-0.686,-0.415,-0.439, PHS= 0.053,-0.203, 0.009, RAW= 140.7, 11.9, CAL= 141.3, 8.7, ROT= 68.7, -8.7 2021-05-18T02:51:30.691Z,1621306290.691 [DAT](INFO): got valid direction response: 02:51:04.4689 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 479,-0.04,-0.382,-0.686,-0.415,-0.439, PHS= 0.053,-0.203, 0.009, RAW= 140.7, 11.9, CAL= 141.3, 8.7, ROT= 68.7, -8.7 2021-05-18T02:51:30.692Z,1621306290.692 [DAT](INFO): DAT read: Rx Time:02:51:04.9690 2021-05-18T02:51:30.693Z,1621306290.693 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:30.693Z,1621306290.693 [DAT](INFO): DAT read: Bearing 72.3, -7.7 (Local) 2021-05-18T02:51:30.694Z,1621306290.694 [DAT](INFO): Local bearing/azimuth received: Bearing 72.3, -7.7 (Local) 2021-05-18T02:51:30.694Z,1621306290.694 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:51:30.696Z,1621306290.696 [DAT](INFO): direction in vehicle frame: [ 0.359072 forward, 0.920971 starboard, -0.151261 keelward ] 2021-05-18T02:51:30.696Z,1621306290.696 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:30.716Z,1621306290.716 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:31.098Z,1621306291.098 [DAT](INFO): DAT read: Range 7 to 50 : 0.3 m (trip time 0.2 ms) speed 0.0 2021-05-18T02:51:31.103Z,1621306291.103 [DAT](INFO): DAT read: 02:51:04.9690 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.63, 2.119, 1.577, 2.013, 1.991, PHS= 0.124,-0.370, 0.007, RAW= 136.9, 10.7, CAL= 137.7, 7.7, ROT= 72.3, -7.7 2021-05-18T02:51:31.104Z,1621306291.104 [DAT](INFO): got valid direction response: 02:51:04.9690 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.63, 2.119, 1.577, 2.013, 1.991, PHS= 0.124,-0.370, 0.007, RAW= 136.9, 10.7, CAL= 137.7, 7.7, ROT= 72.3, -7.7 2021-05-18T02:51:31.104Z,1621306291.104 [DAT](INFO): Read range and messages. 2021-05-18T02:51:31.105Z,1621306291.105 [DAT](INFO): direction in vehicle frame: [ 0.301292 forward, 0.944072 starboard, -0.133986 keelward ] 2021-05-18T02:51:31.106Z,1621306291.106 [DAT](INFO): publishing direction and range info 2021-05-18T02:51:31.118Z,1621306291.118 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:31.119Z,1621306291.119 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.301292 forward, 0.944072 starboard, -0.133986 keelward ] 2021-05-18T02:51:31.119Z,1621306291.119 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:31.122Z,1621306291.122 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999303,-0.037244,-0.002533;0.037295,0.998996,0.024818;0.001606,-0.024895,0.999689 ] 2021-05-18T02:51:31.122Z,1621306291.122 [lab_range_test:A.](INFO): rangeToContact_ = 0.300000 m 2021-05-18T02:51:31.123Z,1621306291.123 [lab_range_test:A.](INFO): direction in world frame: [ 0.336076 north, 0.935238 east, -0.111277 down ] 2021-05-18T02:51:31.124Z,1621306291.124 [lab_range_test:A.](INFO): relPosInFSK: [ 0.090387 forward, 0.283221 starboard, -0.040196 keelward ] 2021-05-18T02:51:31.125Z,1621306291.125 [lab_range_test:A.](INFO): relPosInNED: [ 0.100823 north, 0.280571 east, -0.033383 down ] 2021-05-18T02:51:31.125Z,1621306291.125 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:31.126Z,1621306291.126 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:31.506Z,1621306291.506 [DAT](INFO): DAT read: Rx Time:02:51:05.4688 2021-05-18T02:51:31.506Z,1621306291.506 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:31.508Z,1621306291.508 [DAT](INFO): DAT read: Bearing 71.4, -6.5 (Local) 2021-05-18T02:51:31.508Z,1621306291.508 [DAT](INFO): Local bearing/azimuth received: Bearing 71.4, -6.5 (Local) 2021-05-18T02:51:31.510Z,1621306291.510 [DAT](INFO): DAT read: Range 7 to 50 : 0.0 m (trip time 0.0 ms) speed 0.0 2021-05-18T02:51:31.510Z,1621306291.510 [DAT](INFO): unknown deviceResponse_: Range 7 to 50 : 0.0 m (trip time 0.0 ms) speed 0.0 2021-05-18T02:51:31.515Z,1621306291.515 [DAT](INFO): DAT read: 02:51:05.4688 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 479, 0.22, 1.428, 1.163, 1.391, 1.367, PHS= 0.057,-0.160, 0.009, RAW= 137.9, 9.6, CAL= 138.6, 6.5, ROT= 71.4, -6.5 2021-05-18T02:51:31.516Z,1621306291.516 [DAT](INFO): got valid direction response: 02:51:05.4688 LVL= 32752, 32753, 32754, 32755, AGC= 67, IDX= 479, 0.22, 1.428, 1.163, 1.391, 1.367, PHS= 0.057,-0.160, 0.009, RAW= 137.9, 9.6, CAL= 138.6, 6.5, ROT= 71.4, -6.5 2021-05-18T02:51:31.517Z,1621306291.517 [DAT](INFO): Read direction message, but no range. 2021-05-18T02:51:31.518Z,1621306291.518 [DAT](INFO): direction in vehicle frame: [ 0.316909 forward, 0.941676 starboard, -0.113203 keelward ] 2021-05-18T02:51:31.518Z,1621306291.518 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:31.570Z,1621306291.570 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:31.906Z,1621306291.906 [DAT](INFO): DAT read: Rx Time:02:51:05.9689 2021-05-18T02:51:31.906Z,1621306291.906 [DAT](INFO): received an acoustic signal 2021-05-18T02:51:31.908Z,1621306291.908 [DAT](INFO): DAT read: Bearing 69.0, -8.0 (Local) 2021-05-18T02:51:31.908Z,1621306291.908 [DAT](INFO): Local bearing/azimuth received: Bearing 69.0, -8.0 (Local) 2021-05-18T02:51:31.911Z,1621306291.911 [DAT](INFO): DAT read: Range 7 to 50 : 0.2 m (trip time 0.1 ms) speed 0.0 2021-05-18T02:51:31.928Z,1621306291.928 [DAT](INFO): DAT read: 02:51:05.9689 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.51, 1.088, 0.793, 1.055, 1.030, PHS= 0.054,-0.193, 0.011, RAW= 140.5, 11.2, CAL= 141.0, 8.0, ROT= 69.0, -8.0 2021-05-18T02:51:31.929Z,1621306291.929 [DAT](INFO): got valid direction response: 02:51:05.9689 LVL= 32752, 32753, 32754, 32755, AGC= 70, IDX= 0, 0.51, 1.088, 0.793, 1.055, 1.030, PHS= 0.054,-0.193, 0.011, RAW= 140.5, 11.2, CAL= 141.0, 8.0, ROT= 69.0, -8.0 2021-05-18T02:51:31.929Z,1621306291.929 [DAT](INFO): Read range and messages. 2021-05-18T02:51:31.930Z,1621306291.930 [DAT](INFO): direction in vehicle frame: [ 0.354880 forward, 0.924495 starboard, -0.139173 keelward ] 2021-05-18T02:51:31.930Z,1621306291.930 [DAT](INFO): not publishing receive ping time as it could be a packet for anyone 2021-05-18T02:51:31.930Z,1621306291.930 [DAT](INFO): publishing direction and range info 2021-05-18T02:51:31.993Z,1621306291.993 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:31.994Z,1621306291.994 [lab_range_test:A.](INFO): direction in vehicle frame: [ 0.354880 forward, 0.924495 starboard, -0.139173 keelward ] 2021-05-18T02:51:31.994Z,1621306291.994 [lab_range_test:A.](DEBUG): processing response from DAT 2021-05-18T02:51:32.013Z,1621306292.013 [lab_range_test:A.](INFO): rotationFromVehicleToNavigationFrame_ = [ 0.999358,-0.035723,-0.002646;0.035778,0.999049,0.024931;0.001753,-0.025009,0.999686 ] 2021-05-18T02:51:32.014Z,1621306292.014 [lab_range_test:A.](INFO): rangeToContact_ = 0.200000 m 2021-05-18T02:51:32.014Z,1621306292.014 [lab_range_test:A.](INFO): direction in world frame: [ 0.387486 north, 0.914418 east, -0.117020 down ] 2021-05-18T02:51:32.024Z,1621306292.024 [lab_range_test:A.](INFO): relPosInFSK: [ 0.070976 forward, 0.184899 starboard, -0.027835 keelward ] 2021-05-18T02:51:32.024Z,1621306292.024 [lab_range_test:A.](INFO): relPosInNED: [ 0.077497 north, 0.182884 east, -0.023404 down ] 2021-05-18T02:51:32.025Z,1621306292.025 [lab_range_test:A.](DEBUG): Combining 5 samples. 2021-05-18T02:51:32.025Z,1621306292.025 [lab_range_test:A.](DEBUG): Could not read vehicle position; cannot calculate contact position. 2021-05-18T02:51:32.316Z,1621306292.316 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:32.719Z,1621306292.719 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:33.110Z,1621306293.110 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:33.513Z,1621306293.513 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:33.933Z,1621306293.933 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:34.336Z,1621306294.336 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:34.749Z,1621306294.749 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:35.129Z,1621306295.129 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:35.541Z,1621306295.541 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:35.950Z,1621306295.950 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:36.342Z,1621306296.342 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:36.746Z,1621306296.746 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:37.169Z,1621306297.169 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:37.170Z,1621306297.170 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:37.170Z,1621306297.170 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:37.573Z,1621306297.573 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:37.981Z,1621306297.981 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:38.361Z,1621306298.361 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:38.773Z,1621306298.773 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:39.166Z,1621306299.166 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:39.573Z,1621306299.573 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:39.993Z,1621306299.993 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:40.404Z,1621306300.404 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:40.806Z,1621306300.806 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:41.189Z,1621306301.189 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:41.593Z,1621306301.593 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:42.005Z,1621306302.005 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:42.415Z,1621306302.415 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:42.416Z,1621306302.416 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:42.416Z,1621306302.416 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:42.871Z,1621306302.871 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:43.237Z,1621306303.237 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:43.636Z,1621306303.636 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:44.028Z,1621306304.028 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:44.433Z,1621306304.433 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:44.849Z,1621306304.849 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:45.264Z,1621306305.264 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:45.665Z,1621306305.665 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:46.045Z,1621306306.045 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:46.448Z,1621306306.448 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:46.873Z,1621306306.873 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:47.277Z,1621306307.277 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:47.664Z,1621306307.664 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:47.664Z,1621306307.664 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:47.665Z,1621306307.665 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:48.061Z,1621306308.061 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:48.473Z,1621306308.473 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:48.865Z,1621306308.865 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:49.269Z,1621306309.269 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:49.681Z,1621306309.681 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:50.091Z,1621306310.091 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:50.513Z,1621306310.513 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:50.902Z,1621306310.902 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:51.297Z,1621306311.297 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:51.706Z,1621306311.706 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:52.098Z,1621306312.098 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:52.501Z,1621306312.501 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:52.929Z,1621306312.929 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:52.929Z,1621306312.929 [lab_range_test:A.](INFO): update period (5.000000 s) has elapsed, querying... 2021-05-18T02:51:52.929Z,1621306312.929 [lab_range_test:A.](INFO): *** querying DAT *** 2021-05-18T02:51:53.329Z,1621306313.329 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:53.732Z,1621306313.732 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:54.117Z,1621306314.117 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:54.522Z,1621306314.522 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:54.933Z,1621306314.933 [lab_range_test:A.](DEBUG): Tracking... 2021-05-18T02:51:55.330Z,1621306315.330 [lab_range_test](INFO): Timed out from 2021-05-18T02:49:54.9Z 2021-05-18T02:51:55.330Z,1621306315.330 [MissionManager](INFO): lab_range_test is completed. 2021-05-18T02:51:55.330Z,1621306315.330 [MissionManager](INFO): Uninitializing Mission lab_range_test 2021-05-18T02:51:55.330Z,1621306315.330 [lab_range_test] Stopped 2021-05-18T02:51:55.330Z,1621306315.330 [lab_range_test](DEBUG): Aggregate::uninitialize lab_range_test 2021-05-18T02:51:55.330Z,1621306315.330 [lab_range_test:A.] Stopped 2021-05-18T02:51:55.330Z,1621306315.330 [lab_range_test:A.](DEBUG): Uninitializing Tracking. 2021-05-18T02:51:55.331Z,1621306315.331 [lab_range_test:B.Wait] Stopped 2021-05-18T02:51:55.331Z,1621306315.331 [lab_range_test:B.Wait](DEBUG): Uninitialize Wait Component. 2021-05-18T02:51:55.737Z,1621306315.737 [MissionManager](IMPORTANT): Started mission Default 2021-05-18T02:51:55.737Z,1621306315.737 [Default] Running Loop=1 2021-05-18T02:51:55.738Z,1621306315.738 [Default](DEBUG): Aggregate::initialize Default 2021-05-18T02:51:55.738Z,1621306315.738 [Default:B.GoToSurface] Running Loop=1 2021-05-18T02:51:55.738Z,1621306315.738 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-05-18T02:51:55.738Z,1621306315.738 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-05-18T02:51:55.738Z,1621306315.738 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-05-18T02:51:55.739Z,1621306315.739 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-05-18T02:51:55.739Z,1621306315.739 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-05-18T02:51:55.739Z,1621306315.739 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-05-18T02:51:55.740Z,1621306315.740 [Default:A.Wait] Running Loop=1 2021-05-18T02:51:55.740Z,1621306315.740 [Default:A.Wait](DEBUG): Initialize Wait Component.