2025-01-09T06:56:18.609Z,1736405778.609 [undock:I.Execute] Stopped 2025-01-09T06:56:18.609Z,1736405778.609 [undock:Detach] Running Loop=1 2025-01-09T06:56:18.609Z,1736405778.609 [undock:Detach](DEBUG): Aggregate::initialize undock:Detach 2025-01-09T06:56:18.610Z,1736405778.610 [undock:Detach:A.] Running Loop=1 2025-01-09T06:56:18.610Z,1736405778.610 [undock:Detach:A.](INFO): Initializing TrackAcousticContact. 2025-01-09T06:56:18.610Z,1736405778.610 [undock:Detach:B] Running Loop=1 2025-01-09T06:56:18.633Z,1736405778.633 [CommandExec](IMPORTANT): got command restart logs 2025-01-09T06:56:18.975Z,1736405778.975 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:18.984Z,1736405778.984 [undock:Detach:B](IMPORTANT): Undocking at range 21.200001 m and depth 66.620392 m . 2025-01-09T06:56:18.984Z,1736405778.984 [undock:Detach:B] Stopped 2025-01-09T06:56:18.984Z,1736405778.984 [undock:Detach:C] Running Loop=1 2025-01-09T06:56:18.984Z,1736405778.984 [undock:Detach:A.] Running Loop=1 2025-01-09T06:56:18.985Z,1736405778.985 [undock:Detach:A.](ERROR): Failed to read sound speed 2025-01-09T06:56:19.413Z,1736405779.413 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:19.421Z,1736405779.421 [undock:Detach:C] Stopped 2025-01-09T06:56:19.422Z,1736405779.422 [undock:Detach:D.Undock] Running Loop=1 2025-01-09T06:56:19.422Z,1736405779.422 [undock:Detach:D.Undock](DEBUG): Initialize. 2025-01-09T06:56:19.422Z,1736405779.422 [undock:Detach:D.Undock](DEBUG): Initializing internal variables to default values. 2025-01-09T06:56:19.747Z,1736405779.747 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2025-01-09T06:56:19.787Z,1736405779.787 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:19.795Z,1736405779.795 [undock:Detach:D.Undock](DEBUG): Initialize. 2025-01-09T06:56:19.795Z,1736405779.795 [undock:Detach:D.Undock](DEBUG): Initializing internal variables to default values. 2025-01-09T06:56:19.796Z,1736405779.796 [undock:Detach:D.Undock](INFO): Detached from dock at depth 66.670792 m. 2025-01-09T06:56:19.944Z,1736405779.944 [DockingStepper](INFO): Resume 2025-01-09T06:56:20.187Z,1736405780.187 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:20.214Z,1736405780.214 [DockingStepper](INFO): Resuming 2025-01-09T06:56:20.312Z,1736405780.312 [DAT](INFO): DAT read: Rx Time:06:56:19.1893 2025-01-09T06:56:20.312Z,1736405780.312 [DAT](INFO): Rx dataTimestamp_ set to:1736405780.311905 2025-01-09T06:56:20.633Z,1736405780.633 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:20.659Z,1736405780.659 [DockingStepper](INFO): Start 2025-01-09T06:56:20.659Z,1736405780.659 [DockingStepper](DEBUG): Initializing EZServoServo. 2025-01-09T06:56:20.751Z,1736405780.751 [DataOverHttps](DEBUG): Managing dock network, ignoring radio surface power off 2025-01-09T06:56:20.780Z,1736405780.780 [DockingStepper](DEBUG): Initializing DockingStepper. 2025-01-09T06:56:20.999Z,1736405780.999 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:21.014Z,1736405781.014 [DockingStepper](INFO): Starting 2025-01-09T06:56:21.072Z,1736405781.072 [DAT](INFO): DAT read: 06:56:19.1893 LVL= 28464, 26833, 17458, 32755, AGC= 57, IDX= 435,-0.37,-2.592, 2.809,-1.155,-2.262, PHS=-0.242,-1.165, 1.104, RAW= 186.1, 3.1, CAL= 186.2, -5.2, ROT= 323.8, 5.2 2025-01-09T06:56:21.073Z,1736405781.073 [DAT](INFO): got valid direction response: 06:56:19.1893 LVL= 28464, 26833, 17458, 32755, AGC= 57, IDX= 435,-0.37,-2.592, 2.809,-1.155,-2.262, PHS=-0.242,-1.165, 1.104, RAW= 186.1, 3.1, CAL= 186.2, -5.2, ROT= 323.8, 5.2 2025-01-09T06:56:21.073Z,1736405781.073 [DAT](INFO): DAT read: OK 2025-01-09T06:56:21.073Z,1736405781.073 [DAT](INFO): unknown deviceResponse_: OK 2025-01-09T06:56:21.074Z,1736405781.074 [DAT](INFO): DAT read: user:263> 2025-01-09T06:56:21.075Z,1736405781.075 [DAT](INFO): DAT read: Tx time:06:56:20.2804 2025-01-09T06:56:21.076Z,1736405781.076 [DAT](INFO): Ping request sent. 2025-01-09T06:56:21.076Z,1736405781.076 [DAT](INFO): transmitted an acoustic signal 2025-01-09T06:56:21.076Z,1736405781.076 [DAT](INFO): #Rx 3: Read direction message, but no range. 2025-01-09T06:56:21.077Z,1736405781.077 [DAT](INFO): direction in FSK: [0.803639,-0.588175,-0.090633] 2025-01-09T06:56:21.077Z,1736405781.077 [DAT](INFO): publishing transmit ping time 2025-01-09T06:56:21.080Z,1736405781.080 [DAT](INFO): publishing transmit ping time 2025-01-09T06:56:21.408Z,1736405781.408 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:21.427Z,1736405781.427 [DockingStepper](INFO): Starting 2025-01-09T06:56:21.807Z,1736405781.807 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:21.847Z,1736405781.847 [DockingStepper](INFO): Starting 2025-01-09T06:56:21.895Z,1736405781.895 [DockingStepper](INFO): Init string: /1z16321aE13561N3m50 2025-01-09T06:56:22.211Z,1736405782.211 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:22.241Z,1736405782.241 [DockingStepper](INFO): Starting 2025-01-09T06:56:22.552Z,1736405782.552 [CTD_Seabird](ERROR): Failed to parse device response: 2025-01-09T06:56:22.605Z,1736405782.605 [RDI_Pathfinder](ERROR): only read 2 of 4 data items for water velocity. Device response is::WS,-32768,-32768, 2025-01-09T06:56:22.616Z,1736405782.616 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 0.4 s old, using for 20.0 s. 2025-01-09T06:56:22.616Z,1736405782.616 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:22.642Z,1736405782.642 [DockingStepper](INFO): Starting 2025-01-09T06:56:23.018Z,1736405783.018 [DeadReckonUsingMultipleVelocitySources](DEBUG): Bottom track data is 0.8 s old, using for 20.0 s. 2025-01-09T06:56:23.018Z,1736405783.018 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:23.042Z,1736405783.042 [DockingStepper](INFO): Starting 2025-01-09T06:56:23.338Z,1736405783.338 [DAT](INFO): DAT read: Rx Time:06:56:22.1893 2025-01-09T06:56:23.340Z,1736405783.340 [DAT](INFO): Rx dataTimestamp_ set to:1736405783.339208 2025-01-09T06:56:23.450Z,1736405783.450 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:23.474Z,1736405783.474 [DockingStepper](INFO): Starting 2025-01-09T06:56:23.499Z,1736405783.499 [DockingStepper](INFO): Sent speed cmd:/1V10000 Response:ÿ/0@ 2025-01-09T06:56:23.860Z,1736405783.860 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:23.884Z,1736405783.884 [DockingStepper](INFO): Starting 2025-01-09T06:56:24.096Z,1736405784.096 [DAT](INFO): DAT read: 06:56:22.1893 LVL= 25136, 21601, 14354, 30963, AGC= 54, IDX= 435,-0.47,-0.398,-1.254, 0.975,-0.041, PHS=-0.269,-1.167, 1.012, RAW= 185.8, 4.5, CAL= 185.8, -4.1, ROT= 324.2, 4.1 2025-01-09T06:56:24.097Z,1736405784.097 [DAT](INFO): got valid direction response: 06:56:22.1893 LVL= 25136, 21601, 14354, 30963, AGC= 54, IDX= 435,-0.47,-0.398,-1.254, 0.975,-0.041, PHS=-0.269,-1.167, 1.012, RAW= 185.8, 4.5, CAL= 185.8, -4.1, ROT= 324.2, 4.1 2025-01-09T06:56:24.097Z,1736405784.097 [DAT](INFO): DAT read: OK 2025-01-09T06:56:24.097Z,1736405784.097 [DAT](INFO): unknown deviceResponse_: OK 2025-01-09T06:56:24.098Z,1736405784.098 [DAT](INFO): #Rx 4: Read direction message, but no range. 2025-01-09T06:56:24.099Z,1736405784.099 [DAT](INFO): direction in FSK: [0.808988,-0.583460,-0.071497] 2025-01-09T06:56:24.231Z,1736405784.231 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:24.246Z,1736405784.246 [DockingStepper](INFO): Changing to mode: 3 2025-01-09T06:56:24.246Z,1736405784.246 [DockingStepper](INFO): Detach mode. 2025-01-09T06:56:24.311Z,1736405784.311 [DockingStepper](INFO): Commanding negative:54297 2025-01-09T06:56:24.658Z,1736405784.658 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:25.039Z,1736405785.039 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:25.461Z,1736405785.461 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:25.847Z,1736405785.847 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:26.251Z,1736405786.251 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:26.694Z,1736405786.694 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:27.064Z,1736405787.064 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:27.481Z,1736405787.481 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:27.867Z,1736405787.867 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:28.272Z,1736405788.272 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:28.710Z,1736405788.710 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:28.724Z,1736405788.724 [undock:Detach:A.](INFO): *** querying acoustic contact *** 2025-01-09T06:56:28.880Z,1736405788.880 [DAT](DEBUG): Acoustic response timeout 2025-01-09T06:56:28.880Z,1736405788.880 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2025-01-09T06:56:29.083Z,1736405789.083 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:29.132Z,1736405789.132 [DAT](INFO): DAT read: user:264> 2025-01-09T06:56:29.133Z,1736405789.133 [DAT](INFO): DAT read: Tx time:06:56:28.3815 2025-01-09T06:56:29.134Z,1736405789.134 [DAT](INFO): Ping request sent. 2025-01-09T06:56:29.134Z,1736405789.134 [DAT](INFO): transmitted an acoustic signal 2025-01-09T06:56:29.134Z,1736405789.134 [DAT](INFO): publishing transmit ping time 2025-01-09T06:56:29.135Z,1736405789.135 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.001510 2025-01-09T06:56:29.387Z,1736405789.387 [DAT](INFO): DAT read: TxSync time:06:56:28.3807 2025-01-09T06:56:29.389Z,1736405789.389 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.255159 2025-01-09T06:56:29.497Z,1736405789.497 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:29.636Z,1736405789.636 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502637 2025-01-09T06:56:29.888Z,1736405789.888 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754074 2025-01-09T06:56:29.892Z,1736405789.892 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:30.140Z,1736405790.140 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.005929 2025-01-09T06:56:30.287Z,1736405790.287 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:30.291Z,1736405790.291 [undock:Detach:D.Undock](INFO): Detected possible detachment. Starting timer. 2025-01-09T06:56:30.394Z,1736405790.394 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.260100 2025-01-09T06:56:30.645Z,1736405790.645 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.510528 2025-01-09T06:56:30.734Z,1736405790.734 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:30.896Z,1736405790.896 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.761952 2025-01-09T06:56:31.127Z,1736405791.127 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:31.148Z,1736405791.148 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.014252 2025-01-09T06:56:31.400Z,1736405791.400 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.265912 2025-01-09T06:56:31.541Z,1736405791.541 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:31.652Z,1736405791.652 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.518611 2025-01-09T06:56:31.904Z,1736405791.904 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.770209 2025-01-09T06:56:31.908Z,1736405791.908 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:32.156Z,1736405792.156 [DAT](INFO): DAT read: Rx Time:06:56:30.8218 2025-01-09T06:56:32.156Z,1736405792.156 [DAT](INFO): Rx dataTimestamp_ set to:1736405792.156051 2025-01-09T06:56:32.157Z,1736405792.157 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.023171 2025-01-09T06:56:32.343Z,1736405792.343 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:32.408Z,1736405792.408 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.274433 2025-01-09T06:56:32.668Z,1736405792.668 [DAT](INFO): DAT read: 06:56:30.8218 LVL= 21040, 19905, 9906, 25955, AGC= 51, IDX= 239,-0.19, 0.627,-0.137, 2.040, 1.074, PHS=-0.359,-1.164, 0.963, RAW= 188.0, 6.1, CAL= 188.0, -2.7, ROT= 322.0, 2.7 2025-01-09T06:56:32.669Z,1736405792.669 [DAT](INFO): got valid direction response: 06:56:30.8218 LVL= 21040, 19905, 9906, 25955, AGC= 51, IDX= 239,-0.19, 0.627,-0.137, 2.040, 1.074, PHS=-0.359,-1.164, 0.963, RAW= 188.0, 6.1, CAL= 188.0, -2.7, ROT= 322.0, 2.7 2025-01-09T06:56:32.670Z,1736405792.670 [DAT](INFO): DAT read: Bearing 322.0, 2.7 (Local) 2025-01-09T06:56:32.670Z,1736405792.670 [DAT](INFO): Local bearing/azimuth received: Bearing 322.0, 2.7 (Local) 2025-01-09T06:56:32.671Z,1736405792.671 [DAT](INFO): DAT read: Range 10 to 50 : 27.1 m (Round-trip 36.2 ms) speed -0.1 m/s 2025-01-09T06:56:32.672Z,1736405792.672 [DAT](INFO): #Rx 1: Read range and direction messages. 2025-01-09T06:56:32.673Z,1736405792.673 [DAT](INFO): direction in FSK: [0.787136,-0.614978,-0.047106] 2025-01-09T06:56:32.673Z,1736405792.673 [DAT](INFO): publishing direction and range info 2025-01-09T06:56:32.746Z,1736405792.746 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:33.112Z,1736405793.112 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:33.687Z,1736405793.687 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:33.913Z,1736405793.913 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:34.327Z,1736405794.327 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:34.745Z,1736405794.745 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:35.142Z,1736405795.142 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:35.577Z,1736405795.577 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:35.938Z,1736405795.938 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:36.347Z,1736405796.347 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:36.766Z,1736405796.766 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:37.150Z,1736405797.150 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:37.605Z,1736405797.605 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:37.960Z,1736405797.960 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:38.374Z,1736405798.374 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:38.801Z,1736405798.801 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:38.811Z,1736405798.811 [undock:Detach:A.](INFO): *** querying acoustic contact *** 2025-01-09T06:56:38.975Z,1736405798.975 [DAT](INFO): ****** received valid address query ****** 2025-01-09T06:56:38.975Z,1736405798.975 [DAT](INFO): ****** received valid ping request ****** 2025-01-09T06:56:38.976Z,1736405798.976 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2025-01-09T06:56:39.172Z,1736405799.172 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:39.228Z,1736405799.228 [DAT](INFO): DAT read: user:265> 2025-01-09T06:56:39.228Z,1736405799.228 [DAT](INFO): DAT read: Tx time:06:56:38.4815 2025-01-09T06:56:39.229Z,1736405799.229 [DAT](INFO): Ping request sent. 2025-01-09T06:56:39.229Z,1736405799.229 [DAT](INFO): transmitted an acoustic signal 2025-01-09T06:56:39.229Z,1736405799.229 [DAT](INFO): publishing transmit ping time 2025-01-09T06:56:39.230Z,1736405799.230 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000719 2025-01-09T06:56:39.480Z,1736405799.480 [DAT](INFO): DAT read: TxSync time:06:56:38.4808 2025-01-09T06:56:39.480Z,1736405799.480 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.251620 2025-01-09T06:56:39.660Z,1736405799.660 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:39.732Z,1736405799.732 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.503345 2025-01-09T06:56:39.983Z,1736405799.983 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754641 2025-01-09T06:56:40.003Z,1736405800.003 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:40.236Z,1736405800.236 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.006736 2025-01-09T06:56:40.380Z,1736405800.380 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:40.488Z,1736405800.488 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258784 2025-01-09T06:56:40.740Z,1736405800.740 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.510721 2025-01-09T06:56:40.813Z,1736405800.813 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:40.992Z,1736405800.992 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.763022 2025-01-09T06:56:41.202Z,1736405801.202 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:41.249Z,1736405801.249 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.019566 2025-01-09T06:56:41.500Z,1736405801.500 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.270688 2025-01-09T06:56:41.681Z,1736405801.681 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:41.752Z,1736405801.752 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.523113 2025-01-09T06:56:41.998Z,1736405801.998 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:42.004Z,1736405802.004 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.774894 2025-01-09T06:56:42.256Z,1736405802.256 [DAT](INFO): DAT read: Rx Time:06:56:40.9228 2025-01-09T06:56:42.256Z,1736405802.256 [DAT](INFO): Rx dataTimestamp_ set to:1736405802.255785 2025-01-09T06:56:42.257Z,1736405802.257 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.027767 2025-01-09T06:56:42.407Z,1736405802.407 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:42.508Z,1736405802.508 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.279012 2025-01-09T06:56:42.765Z,1736405802.765 [DAT](INFO): DAT read: 06:56:40.9228 LVL= 25168, 21329, 12098, 30515, AGC= 48, IDX= 440,-0.11,-0.436,-1.066, 1.094, 0.129, PHS=-0.477,-1.148, 0.963, RAW= 191.9, 7.1, CAL= 192.2, -1.6, ROT= 317.8, 1.6 2025-01-09T06:56:42.766Z,1736405802.766 [DAT](INFO): got valid direction response: 06:56:40.9228 LVL= 25168, 21329, 12098, 30515, AGC= 48, IDX= 440,-0.11,-0.436,-1.066, 1.094, 0.129, PHS=-0.477,-1.148, 0.963, RAW= 191.9, 7.1, CAL= 192.2, -1.6, ROT= 317.8, 1.6 2025-01-09T06:56:42.767Z,1736405802.767 [DAT](INFO): DAT read: Bearing 317.8, 1.6 (Local) 2025-01-09T06:56:42.767Z,1736405802.767 [DAT](INFO): Local bearing/azimuth received: Bearing 317.8, 1.6 (Local) 2025-01-09T06:56:42.768Z,1736405802.768 [DAT](INFO): DAT read: Range 10 to 50 : 27.8 m (Round-trip 37.1 ms) speed -0.2 m/s 2025-01-09T06:56:42.769Z,1736405802.769 [DAT](INFO): #Rx 1: Read range and direction messages. 2025-01-09T06:56:42.770Z,1736405802.770 [DAT](INFO): direction in FSK: [0.740516,-0.671459,-0.027922] 2025-01-09T06:56:42.770Z,1736405802.770 [DAT](INFO): publishing direction and range info 2025-01-09T06:56:42.882Z,1736405802.882 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:43.205Z,1736405803.205 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:43.693Z,1736405803.693 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:44.024Z,1736405804.024 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:44.418Z,1736405804.418 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:44.860Z,1736405804.860 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:45.231Z,1736405805.231 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:45.693Z,1736405805.693 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:46.066Z,1736405806.066 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:46.443Z,1736405806.443 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:46.877Z,1736405806.877 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:47.252Z,1736405807.252 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:47.721Z,1736405807.721 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:48.074Z,1736405808.074 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:48.468Z,1736405808.468 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:48.891Z,1736405808.891 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:48.897Z,1736405808.897 [undock:Detach:A.](INFO): *** querying acoustic contact *** 2025-01-09T06:56:49.059Z,1736405809.059 [DAT](INFO): ****** received valid address query ****** 2025-01-09T06:56:49.059Z,1736405809.059 [DAT](INFO): ****** received valid ping request ****** 2025-01-09T06:56:49.060Z,1736405809.060 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2025-01-09T06:56:49.272Z,1736405809.272 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:49.312Z,1736405809.312 [DAT](INFO): DAT read: user:266> 2025-01-09T06:56:49.313Z,1736405809.313 [DAT](INFO): DAT read: Tx time:06:56:48.5317 2025-01-09T06:56:49.313Z,1736405809.313 [DAT](INFO): Ping request sent. 2025-01-09T06:56:49.313Z,1736405809.313 [DAT](INFO): transmitted an acoustic signal 2025-01-09T06:56:49.314Z,1736405809.314 [DAT](INFO): DAT read: TxSync time:06:56:48.5309 2025-01-09T06:56:49.315Z,1736405809.315 [DAT](INFO): publishing transmit ping time 2025-01-09T06:56:49.316Z,1736405809.316 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.001908 2025-01-09T06:56:49.564Z,1736405809.564 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.250224 2025-01-09T06:56:49.732Z,1736405809.732 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:49.817Z,1736405809.817 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.503310 2025-01-09T06:56:50.068Z,1736405810.068 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754606 2025-01-09T06:56:50.097Z,1736405810.097 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:50.320Z,1736405810.320 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.006288 2025-01-09T06:56:50.489Z,1736405810.489 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:50.494Z,1736405810.494 [undock:Detach:D.Undock](INFO): Detached at range: 27.80 m. Transitioning docking module to standby. 2025-01-09T06:56:50.572Z,1736405810.572 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258271 2025-01-09T06:56:50.824Z,1736405810.824 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.510509 2025-01-09T06:56:50.875Z,1736405810.875 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2025-01-09T06:56:50.913Z,1736405810.913 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:50.925Z,1736405810.925 [DockingStepper](INFO): Changing to mode: 1 2025-01-09T06:56:50.925Z,1736405810.925 [DockingStepper](INFO): Standby mode. 2025-01-09T06:56:50.983Z,1736405810.983 [DockingStepper](INFO): Commanding positive:54309 2025-01-09T06:56:51.076Z,1736405811.076 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.762302 2025-01-09T06:56:51.291Z,1736405811.291 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:51.328Z,1736405811.328 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.014794 2025-01-09T06:56:51.580Z,1736405811.580 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.266244 2025-01-09T06:56:51.700Z,1736405811.700 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:51.833Z,1736405811.833 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.519863 2025-01-09T06:56:51.879Z,1736405811.879 [DataOverHttps](DEBUG): Managing dock network, ignoring radio surface power off 2025-01-09T06:56:52.085Z,1736405812.085 [DAT](INFO): DAT read: Rx Time:06:56:50.9753 2025-01-09T06:56:52.086Z,1736405812.086 [DAT](INFO): Rx dataTimestamp_ set to:1736405812.085340 2025-01-09T06:56:52.086Z,1736405812.086 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.772816 2025-01-09T06:56:52.136Z,1736405812.136 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:52.336Z,1736405812.336 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.022269 2025-01-09T06:56:52.503Z,1736405812.503 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:52.589Z,1736405812.589 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.275398 2025-01-09T06:56:52.845Z,1736405812.845 [DAT](INFO): DAT read: 06:56:50.9753 LVL= 23024, 25969, 13410, 29107, AGC= 48, IDX= 449, 0.02, 1.132, 0.692, 2.716, 1.744, PHS=-0.525,-1.005, 0.968, RAW= 196.5, 6.4, CAL= 197.0, -2.0, ROT= 313.0, 2.0 2025-01-09T06:56:52.846Z,1736405812.846 [DAT](INFO): got valid direction response: 06:56:50.9753 LVL= 23024, 25969, 13410, 29107, AGC= 48, IDX= 449, 0.02, 1.132, 0.692, 2.716, 1.744, PHS=-0.525,-1.005, 0.968, RAW= 196.5, 6.4, CAL= 197.0, -2.0, ROT= 313.0, 2.0 2025-01-09T06:56:52.847Z,1736405812.847 [DAT](INFO): DAT read: Bearing 313.0, 2.0 (Local) 2025-01-09T06:56:52.847Z,1736405812.847 [DAT](INFO): Local bearing/azimuth received: Bearing 313.0, 2.0 (Local) 2025-01-09T06:56:52.849Z,1736405812.849 [DAT](INFO): DAT read: Range 10 to 50 : 29.6 m (Round-trip 39.5 ms) speed 0.0 m/s 2025-01-09T06:56:52.849Z,1736405812.849 [DAT](INFO): #Rx 1: Read range and direction messages. 2025-01-09T06:56:52.850Z,1736405812.850 [DAT](INFO): direction in FSK: [0.681583,-0.730908,-0.034899] 2025-01-09T06:56:52.850Z,1736405812.850 [DAT](INFO): publishing direction and range info 2025-01-09T06:56:52.965Z,1736405812.965 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:53.323Z,1736405813.323 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:53.709Z,1736405813.709 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:54.147Z,1736405814.147 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:54.523Z,1736405814.523 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:54.941Z,1736405814.941 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:55.337Z,1736405815.337 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:55.735Z,1736405815.735 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:56.157Z,1736405816.157 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:56.543Z,1736405816.543 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:56.972Z,1736405816.972 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:56.976Z,1736405816.976 [undock:Detach:D.Undock](INFO): Docking module at standby. 2025-01-09T06:56:57.346Z,1736405817.346 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:57.351Z,1736405817.351 [undock:Detach:D.Undock](IMPORTANT): Undocking sequence complete. 2025-01-09T06:56:57.351Z,1736405817.351 [undock:Detach:D.Undock] Stopped 2025-01-09T06:56:57.352Z,1736405817.352 [undock:Detach](INFO): Completed undock:Detach 2025-01-09T06:56:57.352Z,1736405817.352 [undock:Detach] Stopped 2025-01-09T06:56:57.353Z,1736405817.353 [undock:Detach](DEBUG): Aggregate::uninitialize undock:Detach 2025-01-09T06:56:57.353Z,1736405817.353 [undock:Detach:A.] Stopped 2025-01-09T06:56:57.353Z,1736405817.353 [undock:Detach:A.](DEBUG): Uninitializing TrackAcousticContact. 2025-01-09T06:56:57.354Z,1736405817.354 [undock:Transit] Running Loop=1 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit](DEBUG): Aggregate::initialize undock:Transit 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:BuoyancyHold.Buoyancy] Running Loop=1 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component. 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:MassHold.Pitch] Running Loop=1 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:MassHold.Pitch](DEBUG): Initialize. 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:C.Pitch] Running Loop=1 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:C.Pitch](DEBUG): Initialize. 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:D.SetSpeed] Running Loop=1 2025-01-09T06:56:57.371Z,1736405817.371 [undock:Transit:D.SetSpeed](DEBUG): Initialize. 2025-01-09T06:56:57.372Z,1736405817.372 [undock:Transit:Wpt1.Waypoint] Running Loop=1 2025-01-09T06:56:57.372Z,1736405817.372 [undock:Transit:Wpt1.Waypoint](DEBUG): Initialize WaypointComponent. 2025-01-09T06:56:57.760Z,1736405817.760 [DeadReckonUsingMultipleVelocitySources](DEBUG): using accuracyPremultiplier from config 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit] Stopped 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit](DEBUG): Aggregate::uninitialize undock:Transit 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit:BuoyancyHold.Buoyancy] Stopped 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit:MassHold.Pitch] Stopped 2025-01-09T06:56:57.764Z,1736405817.764 [undock:Transit:C.Pitch] Stopped