2022-06-07T02:44:47.554Z,1654569887.554 [CommandExec](IMPORTANT): got command failComponent hardware DAT 2022-06-07T02:44:47.554Z,1654569887.554 [DAT] Hardware Fault, FailCount= 1 2022-06-07T02:44:47.555Z,1654569887.555 [DAT](ERROR): Hardware Fault 2022-06-07T02:44:47.555Z,1654569887.555 [CommandExec](IMPORTANT): DAT failureMode is Hardware Fault 2022-06-07T02:44:47.556Z,1654569887.556 [CommandExec](IMPORTANT): got command restart logs 2022-06-07T02:44:47.585Z,1654569887.585 [CBIT](ERROR): Hardware Fault in component: DAT 2022-06-07T02:44:47.592Z,1654569887.592 [DAT](INFO): Powering down 2022-06-07T02:44:48.653Z,1654569888.653 [CBIT](INFO): Clearing failed state for component DAT 2022-06-07T02:44:48.654Z,1654569888.654 [DAT] No Fault, FailCount= 1 2022-06-07T02:44:50.640Z,1654569890.640 [DAT](INFO): Powering up 2022-06-07T02:44:50.640Z,1654569890.640 [DAT](DEBUG): Initializing DAT. 2022-06-07T02:44:55.424Z,1654569895.424 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:45:02.744Z,1654569902.744 [DAT](INFO): DAT read: 2022-06-07T02:45:02.745Z,1654569902.745 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series 2022-06-07T02:45:04.509Z,1654569904.509 [DAT](INFO): DAT read: MF Frequency Band 2022-06-07T02:45:04.510Z,1654569904.510 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0 2022-06-07T02:45:04.510Z,1654569904.510 [DAT](INFO): DAT read: Jun 7 2022 02:44:58 2022-06-07T02:45:05.516Z,1654569905.516 [DAT](INFO): DAT read: Features enabled [Bearing] 2022-06-07T02:45:05.518Z,1654569905.518 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP 2022-06-07T02:45:05.518Z,1654569905.518 [DAT](INFO): commRate: 800 2022-06-07T02:45:07.583Z,1654569907.583 [DAT](INFO): entering command mode 2022-06-07T02:45:07.784Z,1654569907.784 [DAT](INFO): DAT read: 2022-06-07T02:45:07.785Z,1654569907.785 [DAT](INFO): DAT read: user:1> 2022-06-07T02:45:07.785Z,1654569907.785 [DAT](INFO): setting verbose to 3 2022-06-07T02:45:08.036Z,1654569908.036 [DAT](INFO): DAT read: user:1> 2022-06-07T02:45:08.037Z,1654569908.037 [DAT](INFO): DAT read: Verbose | 3 2022-06-07T02:45:08.037Z,1654569908.037 [DAT](INFO): set verbose to 3 2022-06-07T02:45:08.037Z,1654569908.037 [DAT](INFO): setting DatVerbose to 27440 2022-06-07T02:45:08.288Z,1654569908.288 [DAT](INFO): DAT read: user:2> 2022-06-07T02:45:08.289Z,1654569908.289 [DAT](INFO): DAT read: DatVerbose | 27440 2022-06-07T02:45:08.289Z,1654569908.289 [DAT](INFO): set DatVerbose to 27440 2022-06-07T02:45:08.290Z,1654569908.290 [DAT](INFO): setting transmit power to 8 2022-06-07T02:45:08.542Z,1654569908.542 [DAT](INFO): DAT read: user:3> 2022-06-07T02:45:08.543Z,1654569908.543 [DAT](INFO): DAT read: TxPower | 8 (Max) 2022-06-07T02:45:08.543Z,1654569908.543 [DAT](INFO): set transmit power to 8 2022-06-07T02:45:08.544Z,1654569908.544 [DAT](INFO): setting local address to 6 2022-06-07T02:45:08.792Z,1654569908.792 [DAT](INFO): DAT read: user:4> 2022-06-07T02:45:08.793Z,1654569908.793 [DAT](INFO): DAT read: LocalAddr | 6 2022-06-07T02:45:08.793Z,1654569908.793 [DAT](INFO): set local address to 6 2022-06-07T02:45:08.794Z,1654569908.794 [DAT](INFO): Setting time to: 2:45:8 And date to:6/7/2022 2022-06-07T02:45:08.943Z,1654569908.943 [NAL9602](IMPORTANT): SBD MO Status=1, MOMSN=17421, MT Status=1, MTMSN=730 2022-06-07T02:45:08.988Z,1654569908.988 [NAL9602](INFO): Sent 39 bytes from file Logs/20220607T012355/Courier0015.lzma 2022-06-07T02:45:08.988Z,1654569908.988 [NAL9602](INFO): Packets left to send: 0 2022-06-07T02:45:09.045Z,1654569909.045 [DAT](INFO): DAT read: user:5> 2022-06-07T02:45:09.048Z,1654569909.048 [DAT](INFO): DAT read: Tue Jun 7, 2022 02:45:08 2022-06-07T02:45:09.049Z,1654569909.049 [DAT](INFO): Local DAT time set to Tue Jun 7, 2022 02:45:08 2022-06-07T02:45:09.660Z,1654569909.660 [NAL9602](INFO): Received command: load Transport/transit.xml;set transit.MissionTimeout 45 min;set transit.NeedCommsTime 45 min;set transit.Latitude 36.772886 degree;set transit.Longitude -121.86307 degree;set transit.Northings 700 m;set transit.Eastings -700 m;run 2022-06-07T02:45:09.748Z,1654569909.748 [CommandExec](IMPORTANT): got command load ./Missions/Transport/transit.xml 2022-06-07T02:45:09.748Z,1654569909.748 [MissionManager](INFO): Loading Mission from file: ./Missions/Transport/transit.xml 2022-06-07T02:45:09.910Z,1654569909.910 [MissionManager](INFO): DefineArg transit.MissionTimeout = 60.000000 min 2022-06-07T02:45:09.913Z,1654569909.913 [MissionManager](INFO): DefineArg transit.NeedCommsTime = 30.000000 min 2022-06-07T02:45:09.916Z,1654569909.916 [MissionManager](INFO): DefineArg transit.Latitude = nan arcdeg 2022-06-07T02:45:09.927Z,1654569909.927 [MissionManager](INFO): DefineArg transit.Longitude = nan arcdeg 2022-06-07T02:45:09.930Z,1654569909.930 [MissionManager](INFO): DefineArg transit.Northings = 0.000000 m 2022-06-07T02:45:09.934Z,1654569909.934 [MissionManager](INFO): DefineArg transit.Eastings = 0.000000 m 2022-06-07T02:45:09.944Z,1654569909.944 [MissionManager](INFO): DefineArg transit.Depth = 10.000000 m 2022-06-07T02:45:09.947Z,1654569909.947 [MissionManager](INFO): DefineArg transit.Speed = 1.000000 m/s 2022-06-07T02:45:09.950Z,1654569909.950 [MissionManager](INFO): DefineArg transit.MaxDepth = 20.000000 m 2022-06-07T02:45:09.953Z,1654569909.953 [MissionManager](INFO): DefineArg transit.MinOffshore = 1.000000 km 2022-06-07T02:45:09.965Z,1654569909.965 [MissionManager](INFO): DefineArg transit.MinAltitude = 7.000000 m 2022-06-07T02:45:09.972Z,1654569909.972 [MissionManager](INFO): DefineArg transit.MassHold = 1 bool 2022-06-07T02:45:09.974Z,1654569909.974 [MissionManager](INFO): DefineArg transit.BuoyancyHold = 1 bool 2022-06-07T02:45:09.975Z,1654569909.975 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/NeedComms.xml 2022-06-07T02:45:10.079Z,1654569910.079 [MissionManager](INFO): DefineArg transit:NeedComms.DiveInterval = 3.000000 h 2022-06-07T02:45:10.087Z,1654569910.087 [MissionManager](INFO): DefineArg transit:NeedComms.WaitForPitchUp = 10.000000 min 2022-06-07T02:45:10.094Z,1654569910.094 [MissionManager](INFO): DefineArg transit:NeedComms.SurfacePitch = 20.000000 arcdeg 2022-06-07T02:45:10.098Z,1654569910.098 [MissionManager](INFO): DefineArg transit:NeedComms.SurfaceDepthRate = nan m/s 2022-06-07T02:45:10.110Z,1654569910.110 [MissionManager](INFO): DefineArg transit:NeedComms.SurfaceSpeed = 1.000000 m/s 2022-06-07T02:45:10.113Z,1654569910.113 [MissionManager](INFO): DefineArg transit:NeedComms.GPSTimeout = 7.000000 min 2022-06-07T02:45:10.124Z,1654569910.124 [MissionManager](INFO): DefineArg transit:NeedComms.CommsTimeout = 30.000000 min 2022-06-07T02:45:10.149Z,1654569910.149 [transit:NeedComms:B.GoToSurface](DEBUG): Construct GoToSurface. 2022-06-07T02:45:10.234Z,1654569910.234 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/StandardEnvelopes.xml 2022-06-07T02:45:10.279Z,1654569910.279 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MinAltitude = 5.000000 m 2022-06-07T02:45:10.286Z,1654569910.286 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MaxDepth = 200.000000 m 2022-06-07T02:45:10.295Z,1654569910.295 [MissionManager](INFO): DefineArg transit:StandardEnvelopes.MinOffshore = 2000.000000 m 2022-06-07T02:45:10.302Z,1654569910.302 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Construct AltitudeEnvelope. 2022-06-07T02:45:10.326Z,1654569910.326 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Construct DepthEnvelope. 2022-06-07T02:45:10.348Z,1654569910.348 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Construct OffshoreEnvelope. 2022-06-07T02:45:10.373Z,1654569910.373 [transit:BuoyancyHold.Buoyancy](DEBUG): Construct Buoyancy. 2022-06-07T02:45:10.381Z,1654569910.381 [transit:MassHold.Pitch](DEBUG): Construct. 2022-06-07T02:45:10.398Z,1654569910.398 [transit:Transit:A.Pitch](DEBUG): Construct. 2022-06-07T02:45:10.436Z,1654569910.436 [transit:Transit:B.SetSpeed](DEBUG): Construct. 2022-06-07T02:45:10.448Z,1654569910.448 [transit:Transit:Wpt1.Waypoint](DEBUG): Construct Waypoint. 2022-06-07T02:45:10.498Z,1654569910.498 [MissionManager](DEBUG): Vehicle transits to desired waypoint and can be commanded to use/hold mass or buoyancy. Maximum duration of mission 60 How often to surface for commumications 30 Latitude of waypoint to seek. If set to NaN, uses latitude at mission initialization. NaN Longitude of waypoint to seek. If set to NaN, uses longitude at mission initialization. NaN Northward distance of the waypoint to seek. If combined with Latitude and/or Longitude, this is an offset from the specified Latitude and/or Longitude. 0 Eastward distance of the waypoint to seek. If combined with Latitude and/or Longitude, this is an offset from the specified Latitude and/or Longitude. 0 Depth of flat and level flight during the mission. 10 Speed of vehicle (relative to water) during the mission. 1 Maximum depth for the entire mission. 20 Minimum distance offshore for the entire mission. 1 Minimum height above the sea floor for the entire mission. 7 Set to True in order to hold mass at default position, False to allow mass to run on its own. Set to True in order to hold buoyancy at neutral position, False to allow buoyancy to run on its own. 1 2022-06-07T02:45:10.499Z,1654569910.499 [CommandExec](IMPORTANT): Loaded ./Missions/Transport/transit.xml 2022-06-07T02:45:22.427Z,1654569922.427 [CommandExec](IMPORTANT): got command set transit.MissionTimeout 45 minute 2022-06-07T02:45:22.428Z,1654569922.428 [CommandExec](IMPORTANT): got command set transit.NeedCommsTime 45 minute 2022-06-07T02:45:22.429Z,1654569922.429 [CommandExec](IMPORTANT): got command set transit.Latitude 36.772886 degree 2022-06-07T02:45:22.429Z,1654569922.429 [CommandExec](IMPORTANT): got command set transit.Longitude -121.86307 degree 2022-06-07T02:45:22.430Z,1654569922.430 [CommandExec](IMPORTANT): got command set transit.Northings 700 meter 2022-06-07T02:45:22.431Z,1654569922.431 [CommandExec](IMPORTANT): got command set transit.Eastings -700 meter 2022-06-07T02:45:22.435Z,1654569922.435 [CommandExec](IMPORTANT): got command run 2022-06-07T02:45:22.437Z,1654569922.437 [CommandExec](IMPORTANT): Running 2022-06-07T02:45:22.832Z,1654569922.832 [DefaultWithUndock] Stopped 2022-06-07T02:45:22.832Z,1654569922.832 [DefaultWithUndock](DEBUG): Aggregate::uninitialize DefaultWithUndock 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault] Stopped 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Stopped 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T02:45:22.833Z,1654569922.833 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T02:45:22.833Z,1654569922.833 [MissionManager](IMPORTANT): Started mission transit 2022-06-07T02:45:22.833Z,1654569922.833 [transit] Running Loop=1 2022-06-07T02:45:22.834Z,1654569922.834 [transit](DEBUG): Aggregate::initialize transit 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes] Running Loop=1 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes](DEBUG): Aggregate::initialize transit:StandardEnvelopes 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Initialize AltitudeEnvelopeComponent. 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Initialize DepthEnvelopeComponent. 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1 2022-06-07T02:45:22.834Z,1654569922.834 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Initialize OffshoreEnvelopeComponent. 2022-06-07T02:45:22.835Z,1654569922.835 [transit:BuoyancyHold.Buoyancy] Running Loop=1 2022-06-07T02:45:22.835Z,1654569922.835 [transit:BuoyancyHold.Buoyancy](DEBUG): Initialize Buoyancy Component. 2022-06-07T02:45:22.835Z,1654569922.835 [transit:MassHold.Pitch] Running Loop=1 2022-06-07T02:45:22.835Z,1654569922.835 [transit:MassHold.Pitch](DEBUG): Initialize. 2022-06-07T02:45:22.835Z,1654569922.835 [transit:B] Running Loop=1 2022-06-07T02:45:22.836Z,1654569922.836 [transit:MassHold.Pitch] Running Loop=1 2022-06-07T02:45:22.836Z,1654569922.836 [transit:BuoyancyHold.Buoyancy] Running Loop=1 2022-06-07T02:45:22.836Z,1654569922.836 [transit:StandardEnvelopes] Running Loop=1 2022-06-07T02:45:22.836Z,1654569922.836 [transit:StandardEnvelopes:C.OffshoreEnvelope] Running Loop=1 2022-06-07T02:45:22.837Z,1654569922.837 [transit:StandardEnvelopes:B.DepthEnvelope] Running Loop=1 2022-06-07T02:45:22.837Z,1654569922.837 [transit:StandardEnvelopes:A.AltitudeEnvelope] Running Loop=1 2022-06-07T02:45:22.838Z,1654569922.838 [transit:B] Stopped 2022-06-07T02:45:22.838Z,1654569922.838 [transit:C] Running Loop=1 2022-06-07T02:45:23.524Z,1654569923.524 [transit:C] Stopped 2022-06-07T02:45:23.524Z,1654569923.524 [transit:E] Running Loop=1 2022-06-07T02:45:23.617Z,1654569923.617 [transit:E] Stopped 2022-06-07T02:45:23.617Z,1654569923.617 [transit:F] Running Loop=1 2022-06-07T02:45:24.024Z,1654569924.024 [transit:F] Stopped 2022-06-07T02:45:24.024Z,1654569924.024 [transit:G] Running Loop=1 2022-06-07T02:45:24.442Z,1654569924.442 [transit:G] Stopped 2022-06-07T02:45:24.442Z,1654569924.442 [transit:Transit] Running Loop=1 2022-06-07T02:45:24.442Z,1654569924.442 [transit:Transit](DEBUG): Aggregate::initialize transit:Transit 2022-06-07T02:45:24.442Z,1654569924.442 [transit:Transit:A.Pitch] Running Loop=1 2022-06-07T02:45:24.443Z,1654569924.443 [transit:Transit:A.Pitch](DEBUG): Initialize. 2022-06-07T02:45:24.443Z,1654569924.443 [transit:Transit:B.SetSpeed] Running Loop=1 2022-06-07T02:45:24.443Z,1654569924.443 [transit:Transit:B.SetSpeed](DEBUG): Initialize. 2022-06-07T02:45:24.443Z,1654569924.443 [transit:Transit:Wpt1.Waypoint] Running Loop=1 2022-06-07T02:45:24.443Z,1654569924.443 [transit:Transit:Wpt1.Waypoint](DEBUG): Initialize WaypointComponent. 2022-06-07T02:45:24.826Z,1654569924.826 [transit:Transit:B.SetSpeed] Running Loop=1 2022-06-07T02:45:24.827Z,1654569924.827 [transit:Transit:A.Pitch] Running Loop=1 2022-06-07T02:45:26.565Z,1654569926.565 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:45:53.903Z,1654569953.903 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T02:45:57.688Z,1654569957.688 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:46:28.815Z,1654569988.815 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:46:59.948Z,1654570019.948 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:47:09.192Z,1654570029.192 [Radio_Surface](INFO): Powering down 2022-06-07T02:47:31.073Z,1654570051.073 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T02:47:32.076Z,1654570052.076 [DataOverHttps](INFO): Radio surface powered OFF, will not connect. 2022-06-07T02:52:25.421Z,1654570345.421 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2022-06-07T02:52:58.128Z,1654570378.128 [BPC1](INFO): Calculating totals. Valid battery stick count: 50. Valid reserve battery stick count: 6. 2022-06-07T02:52:58.130Z,1654570378.130 [BPC1](INFO): Received data from all battery sticks. 2022-06-07T03:05:18.268Z,1654571118.268 [transit:Transit:Wpt1.Waypoint](IMPORTANT): Reached Waypoint: 36.779180,-121.870927 2022-06-07T03:05:18.268Z,1654571118.268 [transit:Transit:Wpt1.Waypoint] Stopped 2022-06-07T03:05:18.268Z,1654571118.268 [transit:Transit:Wpt1.Waypoint](DEBUG): Uninitialize WaypointComponent. 2022-06-07T03:05:18.268Z,1654571118.268 [transit:Transit:PhoneHome] Running Loop=1 2022-06-07T03:05:18.268Z,1654571118.268 [transit:Transit:PhoneHome](DEBUG): Aggregate::initialize transit:Transit:PhoneHome 2022-06-07T03:05:18.685Z,1654571118.685 [transit:NeedComms] Running Loop=1 2022-06-07T03:05:18.686Z,1654571118.686 [transit:NeedComms](DEBUG): Aggregate::initialize transit:NeedComms 2022-06-07T03:05:18.686Z,1654571118.686 [transit:NeedComms:B.GoToSurface] Running Loop=1 2022-06-07T03:05:18.686Z,1654571118.686 [transit:NeedComms:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-06-07T03:05:18.686Z,1654571118.686 [transit:NeedComms:B.GoToSurface](INFO): Received depth rate setting nan m/s. 2022-06-07T03:05:18.687Z,1654571118.687 [transit:NeedComms:B.GoToSurface](INFO): Received pitch setting 19.999999 degrees. 2022-06-07T03:05:18.687Z,1654571118.687 [transit:NeedComms:B.GoToSurface](INFO): Received speed setting 1.000000 m/s. 2022-06-07T03:05:18.687Z,1654571118.687 [transit:NeedComms:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-06-07T03:05:18.688Z,1654571118.688 [transit:NeedComms:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-06-07T03:05:18.688Z,1654571118.688 [transit:NeedComms:A] Running Loop=1 2022-06-07T03:05:18.689Z,1654571118.689 [transit:NeedComms:A](INFO): last time_fix was: 1654569713.000000 second since 1970/01/01T00:00:00Z 2022-06-07T03:05:18.690Z,1654571118.690 [transit:NeedComms:A] Stopped 2022-06-07T03:05:57.046Z,1654571157.046 [transit:NeedComms:C] Running Loop=1 2022-06-07T03:05:57.482Z,1654571157.482 [transit:NeedComms:C](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-06-07T03:05:57.588Z,1654571157.588 [Radio_Surface](INFO): Powering up 2022-06-07T03:06:03.688Z,1654571163.688 [DataOverHttps](INFO): Radio surface powered ON. 2022-06-07T03:06:21.315Z,1654571181.315 [NAL9602](INFO): SBD MO Status=2, MOMSN=17422, MT Status=2, MTMSN=0 2022-06-07T03:06:21.320Z,1654571181.320 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:06:33.820Z,1654571193.820 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:06:43.910Z,1654571203.910 [NAL9602](INFO): SBD MO Status=2, MOMSN=17422, MT Status=2, MTMSN=0 2022-06-07T03:06:43.910Z,1654571203.910 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:07:04.944Z,1654571224.944 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:07:26.326Z,1654571246.326 [NAL9602](INFO): SBD MO Status=2, MOMSN=17422, MT Status=2, MTMSN=0 2022-06-07T03:07:26.327Z,1654571246.327 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:07:36.076Z,1654571256.076 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:07:44.498Z,1654571264.498 [NAL9602](INFO): SBD MO Status=2, MOMSN=17422, MT Status=2, MTMSN=0 2022-06-07T03:07:44.498Z,1654571264.498 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:07:54.602Z,1654571274.602 [NAL9602](INFO): SBD MO Status=0, MOMSN=17422, MT Status=0, MTMSN=0 2022-06-07T03:07:54.603Z,1654571274.603 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:07:55.815Z,1654571275.815 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,030754.00,A,3646.77403,N,12152.28195,W,0.991,224.00,070622,,,A*7F 2022-06-07T03:07:55.817Z,1654571275.817 [NAL9602](INFO): GPS fix at 20220607T030754: (36.779567, -121.871366) 2022-06-07T03:07:55.830Z,1654571275.830 [UniversalFixResidualReporter](INFO): Fix residual: 1.9 %DT, over the last 1245.3 m. Residual distance 24.3 m at bearing 126.2 degrees. Fix at (36.7796, -121.8714) with 1052.8 m made good. 2022-06-07T03:07:55.833Z,1654571275.833 [transit:NeedComms:C] Stopped 2022-06-07T03:07:55.833Z,1654571275.833 [transit:NeedComms:D] Running Loop=1 2022-06-07T03:07:56.247Z,1654571276.247 [transit:NeedComms:D](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-06-07T03:08:07.220Z,1654571287.220 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:08:09.630Z,1654571289.630 [NAL9602](INFO): SBD MO Status=1, MOMSN=17423, MT Status=0, MTMSN=0 2022-06-07T03:08:09.680Z,1654571289.680 [NAL9602](INFO): Sent 332 bytes from file Logs/20220607T024447/Courier0000.lzma 2022-06-07T03:08:09.680Z,1654571289.680 [NAL9602](INFO): Packets left to send: 1 2022-06-07T03:08:31.525Z,1654571311.525 [NAL9602](INFO): SBD MO Status=2, MOMSN=17424, MT Status=2, MTMSN=0 2022-06-07T03:08:31.525Z,1654571311.525 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:08:38.360Z,1654571318.360 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:08:54.613Z,1654571334.613 [NAL9602](INFO): SBD MO Status=1, MOMSN=17424, MT Status=0, MTMSN=0 2022-06-07T03:08:54.664Z,1654571334.664 [NAL9602](INFO): Sent 36 bytes from file Logs/20220607T024447/Courier0000.lzma 2022-06-07T03:08:54.664Z,1654571334.664 [NAL9602](INFO): Packets left to send: 0 2022-06-07T03:09:06.454Z,1654571346.454 [NAL9602](INFO): SBD MO Status=1, MOMSN=17425, MT Status=0, MTMSN=0 2022-06-07T03:09:06.512Z,1654571346.512 [NAL9602](INFO): Sent 231 bytes from file Logs/20220607T012355/Express0013.lzma 2022-06-07T03:09:06.512Z,1654571346.512 [NAL9602](INFO): Packets left to send: 0 2022-06-07T03:09:09.492Z,1654571349.492 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-06-07T03:09:27.396Z,1654571367.396 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002869 2022-06-07T03:09:29.154Z,1654571369.154 [NAL9602](INFO): SBD MO Status=1, MOMSN=17426, MT Status=0, MTMSN=0 2022-06-07T03:09:29.212Z,1654571369.212 [NAL9602](INFO): Sent 145 bytes from file Logs/20220607T012355/Express0016.lzma 2022-06-07T03:09:29.212Z,1654571369.212 [NAL9602](INFO): Packets left to send: 0 2022-06-07T03:09:35.104Z,1654571375.104 [DataOverHttps](INFO): Sending 878 bytes from file Logs/20220607T024447/Express0001.lzma 2022-06-07T03:09:36.105Z,1654571376.105 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0001.lzma.bak 2022-06-07T03:09:36.105Z,1654571376.105 [DataOverHttps](INFO): SBD MOMSN=16863507 2022-06-07T03:09:37.690Z,1654571377.690 [transit:NeedComms:D] Stopped 2022-06-07T03:09:37.690Z,1654571377.690 [transit:NeedComms:E] Running Loop=1 2022-06-07T03:09:38.058Z,1654571378.058 [transit:NeedComms:E](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-06-07T03:09:39.662Z,1654571379.662 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,030938.00,A,3646.76626,N,12152.28354,W,0.214,113.08,070622,,,A*79 2022-06-07T03:09:39.665Z,1654571379.665 [NAL9602](INFO): GPS fix at 20220607T030938: (36.779438, -121.871392) 2022-06-07T03:09:39.771Z,1654571379.771 [transit:NeedComms:E] Stopped 2022-06-07T03:09:39.772Z,1654571379.772 [transit:NeedComms](INFO): Completed transit:NeedComms 2022-06-07T03:09:39.772Z,1654571379.772 [transit:NeedComms] Stopped 2022-06-07T03:09:39.772Z,1654571379.772 [transit:NeedComms](DEBUG): Aggregate::uninitialize transit:NeedComms 2022-06-07T03:09:39.772Z,1654571379.772 [transit:NeedComms:B.GoToSurface] Stopped 2022-06-07T03:09:39.773Z,1654571379.773 [transit:NeedComms:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-06-07T03:09:40.109Z,1654571380.109 [transit:Transit:PhoneHome](INFO): Completed transit:Transit:PhoneHome 2022-06-07T03:09:40.109Z,1654571380.109 [transit:Transit:PhoneHome] Stopped 2022-06-07T03:09:40.110Z,1654571380.110 [transit:Transit:PhoneHome](DEBUG): Aggregate::uninitialize transit:Transit:PhoneHome 2022-06-07T03:09:40.110Z,1654571380.110 [transit:Transit](INFO): Completed transit:Transit 2022-06-07T03:09:40.110Z,1654571380.110 [transit:Transit] Stopped 2022-06-07T03:09:40.111Z,1654571380.111 [transit:Transit](DEBUG): Aggregate::uninitialize transit:Transit 2022-06-07T03:09:40.111Z,1654571380.111 [transit:Transit:A.Pitch] Stopped 2022-06-07T03:09:40.111Z,1654571380.111 [transit:Transit:B.SetSpeed] Stopped 2022-06-07T03:09:40.111Z,1654571380.111 [transit:Transit:B.SetSpeed](DEBUG): Uninitialize. 2022-06-07T03:09:40.137Z,1654571380.137 [transit](INFO): Completed transit 2022-06-07T03:09:40.137Z,1654571380.137 [MissionManager](INFO): transit is completed. 2022-06-07T03:09:40.137Z,1654571380.137 [MissionManager](INFO): Uninitializing Mission transit 2022-06-07T03:09:40.137Z,1654571380.137 [transit] Stopped 2022-06-07T03:09:40.137Z,1654571380.137 [transit](DEBUG): Aggregate::uninitialize transit 2022-06-07T03:09:40.137Z,1654571380.137 [transit:StandardEnvelopes] Stopped 2022-06-07T03:09:40.137Z,1654571380.137 [transit:StandardEnvelopes](DEBUG): Aggregate::uninitialize transit:StandardEnvelopes 2022-06-07T03:09:40.137Z,1654571380.137 [transit:StandardEnvelopes:A.AltitudeEnvelope] Stopped 2022-06-07T03:09:40.137Z,1654571380.137 [transit:StandardEnvelopes:A.AltitudeEnvelope](DEBUG): Uninitialize AltitudeEnvelopeComponent. 2022-06-07T03:09:40.137Z,1654571380.137 [transit:StandardEnvelopes:B.DepthEnvelope] Stopped 2022-06-07T03:09:40.138Z,1654571380.138 [transit:StandardEnvelopes:B.DepthEnvelope](DEBUG): Uninitialize. 2022-06-07T03:09:40.138Z,1654571380.138 [transit:StandardEnvelopes:C.OffshoreEnvelope] Stopped 2022-06-07T03:09:40.138Z,1654571380.138 [transit:StandardEnvelopes:C.OffshoreEnvelope](DEBUG): Uninitialize OffshoreEnvelopeComponent. 2022-06-07T03:09:40.138Z,1654571380.138 [transit:BuoyancyHold.Buoyancy] Stopped 2022-06-07T03:09:40.138Z,1654571380.138 [transit:BuoyancyHold.Buoyancy](DEBUG): Uninitialize Buoyancy Component. 2022-06-07T03:09:40.138Z,1654571380.138 [transit:MassHold.Pitch] Stopped 2022-06-07T03:09:40.472Z,1654571380.472 [ElevatorOffsetCalculator](INFO): Removing expired estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -32.00 mm. 2022-06-07T03:09:40.473Z,1654571380.473 [ElevatorOffsetCalculator](INFO): Removing expired estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -26.71 mm. 2022-06-07T03:09:40.508Z,1654571380.508 [MissionManager](IMPORTANT): Started mission DefaultWithUndock 2022-06-07T03:09:40.508Z,1654571380.508 [DefaultWithUndock] Running Loop=1 2022-06-07T03:09:40.508Z,1654571380.508 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock 2022-06-07T03:09:40.508Z,1654571380.508 [DefaultWithUndock:A.Wait] Running Loop=1 2022-06-07T03:09:40.508Z,1654571380.508 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:A.Wait](INFO): Done Waiting. 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:A.Wait] Stopped 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component. 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:LeaveDock] Running Loop=1 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock 2022-06-07T03:10:10.821Z,1654571410.821 [DefaultWithUndock:LeaveDock:A.] Running Loop=1 2022-06-07T03:10:10.822Z,1654571410.822 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact. 2022-06-07T03:10:10.822Z,1654571410.822 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1 2022-06-07T03:10:10.822Z,1654571410.822 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize. 2022-06-07T03:10:10.822Z,1654571410.822 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values. 2022-06-07T03:10:11.209Z,1654571411.209 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module hardware isn't loaded, so simply satisfying DockingState request. 2022-06-07T03:10:11.589Z,1654571411.589 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:10:11.591Z,1654571411.591 [PowerOnly](INFO): Powering up loadControl 2022-06-07T03:10:11.760Z,1654571411.760 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module hardware isn't loaded, so simply satisfying DockingState request. 2022-06-07T03:10:12.044Z,1654571412.044 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module hardware isn't loaded, so simply satisfying DockingState request. 2022-06-07T03:10:12.488Z,1654571412.488 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module hardware isn't loaded, so simply satisfying DockingState request. 2022-06-07T03:10:12.488Z,1654571412.488 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detaching from dock. 2022-06-07T03:10:12.850Z,1654571412.850 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer. 2022-06-07T03:10:13.798Z,1654571413.798 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:13.820Z,1654571413.820 [DAT](INFO): ****** received valid address query ****** 2022-06-07T03:10:13.820Z,1654571413.820 [DAT](INFO): ****** received valid ping request ****** 2022-06-07T03:10:13.820Z,1654571413.820 [DAT](INFO): setting remote address to 0 2022-06-07T03:10:14.072Z,1654571414.072 [DAT](INFO): DAT read: user:6> 2022-06-07T03:10:14.073Z,1654571414.073 [DAT](INFO): DAT read: RemoteAddr | 0 2022-06-07T03:10:14.073Z,1654571414.073 [DAT](INFO): set remote address to 0 2022-06-07T03:10:14.074Z,1654571414.074 [DAT](INFO): ****** received valid address query ****** 2022-06-07T03:10:14.074Z,1654571414.074 [DAT](INFO): ****** received valid ping request ****** 2022-06-07T03:10:14.074Z,1654571414.074 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2022-06-07T03:10:14.324Z,1654571414.324 [DAT](INFO): DAT read: user:7> 2022-06-07T03:10:14.325Z,1654571414.325 [DAT](INFO): DAT read: Tx time:03:10:13.4214 2022-06-07T03:10:14.325Z,1654571414.325 [DAT](INFO): Ping request sent. 2022-06-07T03:10:14.325Z,1654571414.325 [DAT](INFO): transmitted an acoustic signal 2022-06-07T03:10:14.325Z,1654571414.325 [DAT](INFO): publishing transmit ping time 2022-06-07T03:10:14.326Z,1654571414.326 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000753 2022-06-07T03:10:14.576Z,1654571414.576 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.251074 2022-06-07T03:10:14.828Z,1654571414.828 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502929 2022-06-07T03:10:15.080Z,1654571415.080 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.754937 2022-06-07T03:10:15.334Z,1654571415.334 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.008391 2022-06-07T03:10:15.584Z,1654571415.584 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.258926 2022-06-07T03:10:15.836Z,1654571415.836 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.511051 2022-06-07T03:10:16.088Z,1654571416.088 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.763066 2022-06-07T03:10:16.340Z,1654571416.340 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.014916 2022-06-07T03:10:16.550Z,1654571416.550 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:16.592Z,1654571416.592 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.266956 2022-06-07T03:10:16.844Z,1654571416.844 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.519008 2022-06-07T03:10:17.096Z,1654571417.096 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.770923 2022-06-07T03:10:17.348Z,1654571417.348 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.022947 2022-06-07T03:10:17.600Z,1654571417.600 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.275060 2022-06-07T03:10:17.852Z,1654571417.852 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.526921 2022-06-07T03:10:18.104Z,1654571418.104 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.778950 2022-06-07T03:10:18.356Z,1654571418.356 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.031010 2022-06-07T03:10:18.608Z,1654571418.608 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.282963 2022-06-07T03:10:18.861Z,1654571418.861 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.535284 2022-06-07T03:10:19.113Z,1654571419.113 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.787225 2022-06-07T03:10:19.364Z,1654571419.364 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.038996 2022-06-07T03:10:19.437Z,1654571419.437 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:19.616Z,1654571419.616 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.291129 2022-06-07T03:10:19.869Z,1654571419.869 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.543194 2022-06-07T03:10:20.121Z,1654571420.121 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.795351 2022-06-07T03:10:20.373Z,1654571420.373 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.047394 2022-06-07T03:10:20.625Z,1654571420.625 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.299198 2022-06-07T03:10:20.876Z,1654571420.876 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.551123 2022-06-07T03:10:21.128Z,1654571421.128 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.803137 2022-06-07T03:10:21.384Z,1654571421.384 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.058989 2022-06-07T03:10:21.637Z,1654571421.637 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.311514 2022-06-07T03:10:21.888Z,1654571421.888 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.563137 2022-06-07T03:10:22.140Z,1654571422.140 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.815142 2022-06-07T03:10:22.154Z,1654571422.154 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:22.392Z,1654571422.392 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.067114 2022-06-07T03:10:22.644Z,1654571422.644 [DAT](INFO): DAT read: Response Not Received 2022-06-07T03:10:22.645Z,1654571422.645 [DAT](INFO): response not received 2022-06-07T03:10:22.645Z,1654571422.645 [DAT](ERROR): No response from remote modem. 2022-06-07T03:10:22.645Z,1654571422.645 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.320093 2022-06-07T03:10:22.897Z,1654571422.897 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.571217 2022-06-07T03:10:23.160Z,1654571423.160 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.834920 2022-06-07T03:10:23.412Z,1654571423.412 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.086953 2022-06-07T03:10:23.664Z,1654571423.664 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.339101 2022-06-07T03:10:23.916Z,1654571423.916 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.591142 2022-06-07T03:10:24.168Z,1654571424.168 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.843038 2022-06-07T03:10:24.422Z,1654571424.422 [DAT](INFO): ****** received valid address query ****** 2022-06-07T03:10:24.422Z,1654571424.422 [DAT](INFO): ****** received valid ping request ****** 2022-06-07T03:10:24.422Z,1654571424.422 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2022-06-07T03:10:24.672Z,1654571424.672 [DAT](INFO): DAT read: user:8> 2022-06-07T03:10:24.673Z,1654571424.673 [DAT](INFO): DAT read: Tx time:03:10:23.7715 2022-06-07T03:10:24.673Z,1654571424.673 [DAT](INFO): Ping request sent. 2022-06-07T03:10:24.673Z,1654571424.673 [DAT](INFO): transmitted an acoustic signal 2022-06-07T03:10:24.673Z,1654571424.673 [DAT](INFO): publishing transmit ping time 2022-06-07T03:10:24.674Z,1654571424.674 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000734 2022-06-07T03:10:24.925Z,1654571424.925 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.251528 2022-06-07T03:10:24.995Z,1654571424.995 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:25.176Z,1654571425.176 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.502994 2022-06-07T03:10:25.429Z,1654571425.429 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.755349 2022-06-07T03:10:25.680Z,1654571425.680 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.006988 2022-06-07T03:10:25.932Z,1654571425.932 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.259037 2022-06-07T03:10:26.184Z,1654571426.184 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.511092 2022-06-07T03:10:26.436Z,1654571426.436 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.763271 2022-06-07T03:10:26.688Z,1654571426.688 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.015080 2022-06-07T03:10:26.940Z,1654571426.940 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.266991 2022-06-07T03:10:27.192Z,1654571427.192 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.519250 2022-06-07T03:10:27.444Z,1654571427.444 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.771149 2022-06-07T03:10:27.698Z,1654571427.698 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.024611 2022-06-07T03:10:27.800Z,1654571427.800 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:27.948Z,1654571427.948 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.275255 2022-06-07T03:10:28.200Z,1654571428.200 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.527142 2022-06-07T03:10:28.452Z,1654571428.452 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.778919 2022-06-07T03:10:28.705Z,1654571428.705 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.031279 2022-06-07T03:10:28.956Z,1654571428.956 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.283055 2022-06-07T03:10:29.208Z,1654571429.208 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.534956 2022-06-07T03:10:29.461Z,1654571429.461 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.787745 2022-06-07T03:10:29.712Z,1654571429.712 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.039042 2022-06-07T03:10:29.964Z,1654571429.964 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.290975 2022-06-07T03:10:30.217Z,1654571430.217 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.543377 2022-06-07T03:10:30.468Z,1654571430.468 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.795009 2022-06-07T03:10:30.627Z,1654571430.627 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:30.720Z,1654571430.720 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.047033 2022-06-07T03:10:30.972Z,1654571430.972 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.299001 2022-06-07T03:10:31.224Z,1654571431.224 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.551015 2022-06-07T03:10:31.476Z,1654571431.476 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.803101 2022-06-07T03:10:31.728Z,1654571431.728 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.054998 2022-06-07T03:10:31.980Z,1654571431.980 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.307052 2022-06-07T03:10:32.232Z,1654571432.232 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.559080 2022-06-07T03:10:32.485Z,1654571432.485 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.811293 2022-06-07T03:10:32.736Z,1654571432.736 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.063116 2022-06-07T03:10:32.988Z,1654571432.988 [DAT](INFO): DAT read: Response Not Received 2022-06-07T03:10:32.989Z,1654571432.989 [DAT](INFO): response not received 2022-06-07T03:10:32.989Z,1654571432.989 [DAT](ERROR): No response from remote modem. 2022-06-07T03:10:32.989Z,1654571432.989 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.315917 2022-06-07T03:10:33.072Z,1654571433.072 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: 131.40 m. Transitioning docking module to standby. 2022-06-07T03:10:33.240Z,1654571433.240 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.567134 2022-06-07T03:10:33.475Z,1654571433.475 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module hardware isn't loaded, so simply satisfying DockingState request. 2022-06-07T03:10:33.475Z,1654571433.475 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Docking module at standby. 2022-06-07T03:10:33.476Z,1654571433.476 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact *** 2022-06-07T03:10:33.492Z,1654571433.492 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.818971 2022-06-07T03:10:33.745Z,1654571433.745 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.071388 2022-06-07T03:10:33.866Z,1654571433.866 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete. 2022-06-07T03:10:33.867Z,1654571433.867 [DefaultWithUndock:LeaveDock:B.Undock] Stopped 2022-06-07T03:10:33.867Z,1654571433.867 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock 2022-06-07T03:10:33.867Z,1654571433.867 [DefaultWithUndock:LeaveDock] Stopped 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:LeaveDock:A.] Stopped 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:LeaveDock:A.](DEBUG): Uninitializing TrackAcousticContact. 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:SurfaceDefault] Running Loop=1 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:SurfaceDefault:A.GoToSurface] Running Loop=1 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-06-07T03:10:33.868Z,1654571433.868 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-06-07T03:10:33.869Z,1654571433.869 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-06-07T03:10:33.869Z,1654571433.869 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-06-07T03:10:33.869Z,1654571433.869 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-06-07T03:10:33.870Z,1654571433.870 [DefaultWithUndock:SurfaceDefault:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-06-07T03:10:33.996Z,1654571433.996 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.323017 2022-06-07T03:10:34.250Z,1654571434.250 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.577238 2022-06-07T03:10:34.288Z,1654571434.288 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1 2022-06-07T03:10:34.289Z,1654571434.289 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:10:34.289Z,1654571434.289 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2022-06-07T03:10:34.506Z,1654571434.506 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.833080 2022-06-07T03:10:34.756Z,1654571434.756 [DAT](INFO): ****** received valid address query ****** 2022-06-07T03:10:34.757Z,1654571434.757 [DAT](INFO): ****** received valid ping request ****** 2022-06-07T03:10:34.757Z,1654571434.757 [DAT](INFO): Querying Benthos address 50 with one ping in standard two-way mode. 2022-06-07T03:10:35.008Z,1654571435.008 [DAT](INFO): DAT read: user:9> 2022-06-07T03:10:35.009Z,1654571435.009 [DAT](INFO): DAT read: Tx time:03:10:34.1216 2022-06-07T03:10:35.009Z,1654571435.009 [DAT](INFO): Ping request sent. 2022-06-07T03:10:35.009Z,1654571435.009 [DAT](INFO): transmitted an acoustic signal 2022-06-07T03:10:35.009Z,1654571435.009 [DAT](INFO): publishing transmit ping time 2022-06-07T03:10:35.010Z,1654571435.010 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.000819 2022-06-07T03:10:35.262Z,1654571435.262 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.252496 2022-06-07T03:10:35.302Z,1654571435.302 [CBIT](IMPORTANT): Beginning ground fault scan 2022-06-07T03:10:35.514Z,1654571435.514 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.504712 2022-06-07T03:10:35.764Z,1654571435.764 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=0.755159 2022-06-07T03:10:36.016Z,1654571436.016 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.007049 2022-06-07T03:10:36.268Z,1654571436.268 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.259246 2022-06-07T03:10:36.278Z,1654571436.278 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,031035.00,A,3646.76120,N,12152.28392,W,1.011,216.58,070622,,,A*72 2022-06-07T03:10:36.281Z,1654571436.281 [NAL9602](INFO): GPS fix at 20220607T031035: (36.779353, -121.871399) 2022-06-07T03:10:36.293Z,1654571436.293 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2022-06-07T03:10:36.293Z,1654571436.293 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2022-06-07T03:10:36.520Z,1654571436.520 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.511043 2022-06-07T03:10:36.772Z,1654571436.772 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=1.762959 2022-06-07T03:10:37.025Z,1654571437.025 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.015277 2022-06-07T03:10:37.278Z,1654571437.278 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.268685 2022-06-07T03:10:37.528Z,1654571437.528 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.519086 2022-06-07T03:10:37.780Z,1654571437.780 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=2.771003 2022-06-07T03:10:38.032Z,1654571438.032 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.022905 2022-06-07T03:10:38.284Z,1654571438.284 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.275096 2022-06-07T03:10:38.536Z,1654571438.536 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.527205 2022-06-07T03:10:38.788Z,1654571438.788 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=3.779058 2022-06-07T03:10:39.041Z,1654571439.041 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.031273 2022-06-07T03:10:39.294Z,1654571439.294 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.284099 2022-06-07T03:10:39.544Z,1654571439.544 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.535158 2022-06-07T03:10:39.796Z,1654571439.796 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=4.787073 2022-06-07T03:10:40.048Z,1654571440.048 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.039055 2022-06-07T03:10:40.300Z,1654571440.300 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.291203 2022-06-07T03:10:40.552Z,1654571440.552 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.543039 2022-06-07T03:10:40.805Z,1654571440.805 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=5.795284 2022-06-07T03:10:41.056Z,1654571441.056 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.047119 2022-06-07T03:10:41.311Z,1654571441.311 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.300752 2022-06-07T03:10:41.561Z,1654571441.561 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.551345 2022-06-07T03:10:41.812Z,1654571441.812 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=6.803057 2022-06-07T03:10:42.064Z,1654571442.064 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.054862 2022-06-07T03:10:42.317Z,1654571442.317 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.307342 2022-06-07T03:10:42.568Z,1654571442.568 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.559114 2022-06-07T03:10:42.820Z,1654571442.820 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=7.811075 2022-06-07T03:10:43.073Z,1654571443.073 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.063306 2022-06-07T03:10:43.326Z,1654571443.326 [DAT](INFO): DAT read: Response Not Received 2022-06-07T03:10:43.327Z,1654571443.327 [DAT](INFO): response not received 2022-06-07T03:10:43.328Z,1654571443.328 [DAT](ERROR): No response from remote modem. 2022-06-07T03:10:43.329Z,1654571443.329 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.319340 2022-06-07T03:10:43.576Z,1654571443.576 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.567145 2022-06-07T03:10:43.828Z,1654571443.828 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=8.819014 2022-06-07T03:10:44.080Z,1654571444.080 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.071215 2022-06-07T03:10:44.279Z,1654571444.279 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220607T024447/Courier0003.lzma 2022-06-07T03:10:44.332Z,1654571444.332 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.322925 2022-06-07T03:10:44.585Z,1654571444.585 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.575284 2022-06-07T03:10:44.836Z,1654571444.836 [DAT](INFO): checking for new query: numPingsReceived=0, elapsed TxPingTime=9.827049 2022-06-07T03:10:45.287Z,1654571445.287 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Courier0003.lzma.bak 2022-06-07T03:10:45.288Z,1654571445.288 [DataOverHttps](INFO): SBD MOMSN=16863529 2022-06-07T03:10:46.050Z,1654571446.050 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.004613 CHAN A1 (24V): -0.026467 CHAN A2 (12V): -0.004442 CHAN A3 (5V): -0.002599 CHAN B0 (3.3V): -0.001349 CHAN B1 (3.15aV): -0.001008 CHAN B2 (3.15bV): -0.001323 CHAN B3 (GND): -0.000598 OPEN: 0.006480 Full Scale: +/- 1 mA 2022-06-07T03:10:58.498Z,1654571458.498 [NAL9602](INFO): SBD MO Status=0, MOMSN=17427, MT Status=0, MTMSN=0 2022-06-07T03:10:58.498Z,1654571458.498 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:11:01.784Z,1654571461.784 [DataOverHttps](INFO): Sending 223 bytes from file Logs/20220607T024447/Express0004.lzma 2022-06-07T03:11:02.785Z,1654571462.785 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0004.lzma.bak 2022-06-07T03:11:02.785Z,1654571462.785 [DataOverHttps](INFO): SBD MOMSN=16863531 2022-06-07T03:11:04.179Z,1654571464.179 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T03:11:04.179Z,1654571464.179 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2022-06-07T03:11:04.179Z,1654571464.179 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:11:29.195Z,1654571489.195 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:12:12.909Z,1654571532.909 [PowerOnly](INFO): Powering down loadControl 2022-06-07T03:16:04.882Z,1654571764.882 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2022-06-07T03:16:04.882Z,1654571764.882 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2022-06-07T03:16:04.882Z,1654571764.882 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-06-07T03:16:04.882Z,1654571764.882 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2022-06-07T03:16:05.351Z,1654571765.351 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2022-06-07T03:16:05.351Z,1654571765.351 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 6.414044 min 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2 2022-06-07T03:16:05.737Z,1654571765.737 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2 2022-06-07T03:16:05.738Z,1654571765.738 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:16:05.738Z,1654571765.738 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2022-06-07T03:16:07.698Z,1654571767.698 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,031606.00,A,3646.73450,N,12152.28381,W,1.302,233.07,070622,,,A*7D 2022-06-07T03:16:07.701Z,1654571767.701 [NAL9602](INFO): GPS fix at 20220607T031606: (36.778908, -121.871397) 2022-06-07T03:16:07.782Z,1654571767.782 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2022-06-07T03:16:07.782Z,1654571767.782 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2022-06-07T03:16:20.239Z,1654571780.239 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220607T024447/Courier0006.lzma 2022-06-07T03:16:21.241Z,1654571781.241 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Courier0006.lzma.bak 2022-06-07T03:16:21.242Z,1654571781.242 [DataOverHttps](INFO): SBD MOMSN=16863547 2022-06-07T03:16:38.676Z,1654571798.676 [DataOverHttps](INFO): Sending 355 bytes from file Logs/20220607T024447/Express0007.lzma 2022-06-07T03:16:39.677Z,1654571799.677 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0007.lzma.bak 2022-06-07T03:16:39.677Z,1654571799.677 [DataOverHttps](INFO): SBD MOMSN=16863550 2022-06-07T03:16:41.357Z,1654571801.357 [NAL9602](INFO): SBD MO Status=0, MOMSN=17428, MT Status=0, MTMSN=0 2022-06-07T03:16:41.357Z,1654571801.357 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:16:41.410Z,1654571801.410 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T03:16:41.410Z,1654571801.410 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2022-06-07T03:16:41.410Z,1654571801.410 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:17:11.988Z,1654571831.988 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:21:41.975Z,1654572101.975 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2022-06-07T03:21:41.975Z,1654572101.975 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2022-06-07T03:21:41.991Z,1654572101.991 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-06-07T03:21:41.992Z,1654572101.992 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2022-06-07T03:21:42.374Z,1654572102.374 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2022-06-07T03:21:42.374Z,1654572102.374 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2022-06-07T03:21:42.781Z,1654572102.781 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 12.031102 min 2022-06-07T03:21:42.781Z,1654572102.781 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2022-06-07T03:21:42.781Z,1654572102.781 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #3 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=3 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:21:42.782Z,1654572102.782 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2022-06-07T03:21:44.789Z,1654572104.789 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,032143.00,A,3646.70941,N,12152.28653,W,0.758,253.69,070622,,,A*78 2022-06-07T03:21:44.801Z,1654572104.801 [NAL9602](INFO): GPS fix at 20220607T032143: (36.778490, -121.871442) 2022-06-07T03:21:44.825Z,1654572104.825 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2022-06-07T03:21:44.825Z,1654572104.825 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2022-06-07T03:21:52.535Z,1654572112.535 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220607T024447/Courier0009.lzma 2022-06-07T03:21:53.537Z,1654572113.537 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Courier0009.lzma.bak 2022-06-07T03:21:53.537Z,1654572113.537 [DataOverHttps](INFO): SBD MOMSN=16863576 2022-06-07T03:22:13.318Z,1654572133.318 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20220607T024447/Express0010.lzma 2022-06-07T03:22:14.313Z,1654572134.313 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0010.lzma.bak 2022-06-07T03:22:14.314Z,1654572134.314 [DataOverHttps](INFO): SBD MOMSN=16863579 2022-06-07T03:22:15.996Z,1654572135.996 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T03:22:15.997Z,1654572135.997 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2022-06-07T03:22:15.997Z,1654572135.997 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:22:17.623Z,1654572137.623 [NAL9602](INFO): SBD MO Status=0, MOMSN=17429, MT Status=0, MTMSN=0 2022-06-07T03:22:17.623Z,1654572137.623 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:22:48.372Z,1654572168.372 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:27:16.647Z,1654572436.647 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2022-06-07T03:27:16.647Z,1654572436.647 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2022-06-07T03:27:16.647Z,1654572436.647 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-06-07T03:27:16.651Z,1654572436.651 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2022-06-07T03:27:17.039Z,1654572437.039 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2022-06-07T03:27:17.039Z,1654572437.039 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2022-06-07T03:27:17.462Z,1654572437.462 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 17.608842 min 2022-06-07T03:27:17.462Z,1654572437.462 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2022-06-07T03:27:17.462Z,1654572437.462 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:27:17.462Z,1654572437.462 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2022-06-07T03:27:17.462Z,1654572437.462 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:27:17.463Z,1654572437.463 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #4 2022-06-07T03:27:17.463Z,1654572437.463 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=4 2022-06-07T03:27:17.463Z,1654572437.463 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:27:17.463Z,1654572437.463 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2022-06-07T03:27:19.462Z,1654572439.462 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,032718.00,A,3646.68439,N,12152.29516,W,0.661,224.07,070622,,,A*7B 2022-06-07T03:27:19.465Z,1654572439.465 [NAL9602](INFO): GPS fix at 20220607T032718: (36.778073, -121.871586) 2022-06-07T03:27:19.516Z,1654572439.516 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2022-06-07T03:27:19.516Z,1654572439.516 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2022-06-07T03:27:27.483Z,1654572447.483 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220607T024447/Courier0012.lzma 2022-06-07T03:27:28.486Z,1654572448.486 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Courier0012.lzma.bak 2022-06-07T03:27:28.486Z,1654572448.486 [DataOverHttps](INFO): SBD MOMSN=16863613 2022-06-07T03:27:37.234Z,1654572457.234 [NAL9602](INFO): SBD MO Status=0, MOMSN=17430, MT Status=0, MTMSN=0 2022-06-07T03:27:37.234Z,1654572457.234 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:27:44.891Z,1654572464.891 [DataOverHttps](INFO): Sending 127 bytes from file Logs/20220607T024447/Express0013.lzma 2022-06-07T03:27:45.893Z,1654572465.893 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0013.lzma.bak 2022-06-07T03:27:45.893Z,1654572465.893 [DataOverHttps](INFO): SBD MOMSN=16863616 2022-06-07T03:27:47.380Z,1654572467.380 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T03:27:47.380Z,1654572467.380 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2022-06-07T03:27:47.380Z,1654572467.380 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:28:07.940Z,1654572487.940 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:31:12.508Z,1654572672.508 [DAT](INFO): DAT read: user:10>Rx Time:03:31:11.2293 2022-06-07T03:31:13.279Z,1654572673.279 [DAT](INFO): DAT read: 03:31:11.2293 LVL= 3632, 2721, 3234, 3123, AGC= 71, IDX= 280, 0.40, 0.121, 1.164, 0.254,-0.114, PHS= 0.323, 1.326, 0.365, RAW= 327.9, -35.9, CAL= 328.3, -35.4, ROT= 211.7, 35.4 2022-06-07T03:31:13.282Z,1654572673.282 [DAT](INFO): got valid direction response: 03:31:11.2293 LVL= 3632, 2721, 3234, 3123, AGC= 71, IDX= 280, 0.40, 0.121, 1.164, 0.254,-0.114, PHS= 0.323, 1.326, 0.365, RAW= 327.9, -35.9, CAL= 328.3, -35.4, ROT= 211.7, 35.4 2022-06-07T03:31:13.304Z,1654572673.304 [DAT](INFO): DAT read: $Error in header 2022-06-07T03:31:13.305Z,1654572673.305 [DAT](INFO): Received a bad header 2022-06-07T03:31:13.317Z,1654572673.317 [DAT](INFO): #Rx 1: Read direction message, but no range. 2022-06-07T03:31:13.320Z,1654572673.320 [DAT](INFO): direction in vehicle frame: [ -0.693520 forward, -0.428326 starboard, -0.579281 keelward ] 2022-06-07T03:31:44.272Z,1654572704.272 [DAT](INFO): DAT read: Rx Time:03:31:43.0221 2022-06-07T03:31:44.274Z,1654572704.274 [DAT](INFO): Rx dataTimestamp_ set to:1654572703.022099 2022-06-07T03:31:44.274Z,1654572704.274 [DAT](INFO): received an acoustic signal 2022-06-07T03:31:44.274Z,1654572704.274 [DAT](INFO): DAT read: 2022-06-07T03:31:44.275Z,1654572704.275 [DAT](INFO): DAT read: $Packet for address 0 2022-06-07T03:31:44.275Z,1654572704.275 [DAT](INFO): received a packet notification 2022-06-07T03:32:47.944Z,1654572767.944 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting. 2022-06-07T03:32:47.944Z,1654572767.944 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped 2022-06-07T03:32:47.944Z,1654572767.944 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-06-07T03:32:47.944Z,1654572767.944 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1 2022-06-07T03:32:48.358Z,1654572768.358 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped 2022-06-07T03:32:48.359Z,1654572768.359 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1 2022-06-07T03:32:48.742Z,1654572768.742 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 23.130839 min 2022-06-07T03:32:48.742Z,1654572768.742 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped 2022-06-07T03:32:48.742Z,1654572768.742 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:32:48.742Z,1654572768.742 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped 2022-06-07T03:32:48.743Z,1654572768.743 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:32:48.743Z,1654572768.743 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #5 2022-06-07T03:32:48.743Z,1654572768.743 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=5 2022-06-07T03:32:48.743Z,1654572768.743 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn 2022-06-07T03:32:48.743Z,1654572768.743 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1 2022-06-07T03:32:50.758Z,1654572770.758 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,033249.00,A,3646.66018,N,12152.30236,W,1.166,200.51,070622,,,A*7B 2022-06-07T03:32:50.761Z,1654572770.761 [NAL9602](INFO): GPS fix at 20220607T033249: (36.777670, -121.871706) 2022-06-07T03:32:50.791Z,1654572770.791 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped 2022-06-07T03:32:50.791Z,1654572770.791 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1 2022-06-07T03:32:58.987Z,1654572778.987 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220607T024447/Courier0015.lzma 2022-06-07T03:32:59.989Z,1654572779.989 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Courier0015.lzma.bak 2022-06-07T03:32:59.989Z,1654572779.989 [DataOverHttps](INFO): SBD MOMSN=16863648 2022-06-07T03:33:16.367Z,1654572796.367 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220607T024447/Express0016.lzma 2022-06-07T03:33:17.369Z,1654572797.369 [DataOverHttps](INFO): Moved sent file to Logs/20220607T024447/Express0016.lzma.bak 2022-06-07T03:33:17.369Z,1654572797.369 [DataOverHttps](INFO): SBD MOMSN=16863651 2022-06-07T03:33:18.658Z,1654572798.658 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped 2022-06-07T03:33:18.658Z,1654572798.658 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1 2022-06-07T03:33:18.658Z,1654572798.658 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-06-07T03:33:20.658Z,1654572800.658 [NAL9602](INFO): SBD MO Status=2, MOMSN=17431, MT Status=2, MTMSN=0 2022-06-07T03:33:20.658Z,1654572800.658 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-06-07T03:33:33.181Z,1654572813.181 [NAL9602](INFO): SBD MO Status=0, MOMSN=17431, MT Status=0, MTMSN=0 2022-06-07T03:33:33.181Z,1654572813.181 [NAL9602](INFO): No messages in MT queue 2022-06-07T03:34:03.903Z,1654572843.903 [NAL9602](INFO): Not Powering down - fast GPS 2022-06-07T03:34:27.549Z,1654572867.549 [DataOverHttps](IMPORTANT): SBD MTMSN=20220607T033426 2022-06-07T03:34:35.318Z,1654572875.318 [DataOverHttps](INFO): Received command: restart logs 2022-06-07T03:34:35.325Z,1654572875.325 [CommandExec](IMPORTANT): got command restart logs