2023-05-08T21:57:33.909Z,1683583053.909 [Supervisor](DEBUG): Initializing supervisor.
2023-05-08T21:57:33.915Z,1683583053.915 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2023-05-08T21:57:33.915Z,1683583053.915 [SyncHandler](INFO): Protected caller Thread ID is 7531
2023-05-08T21:57:33.916Z,1683583053.916 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2023-05-08T21:57:33.917Z,1683583053.917 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2023-05-08T21:57:33.917Z,1683583053.917 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 7532
2023-05-08T21:57:33.922Z,1683583053.922 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2023-05-08T21:57:33.939Z,1683583053.939 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2023-05-08T21:57:33.940Z,1683583053.940 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2023-05-08T21:57:33.941Z,1683583053.941 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 7533
2023-05-08T21:57:33.945Z,1683583053.945 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2023-05-08T21:57:33.946Z,1683583053.946 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2023-05-08T21:57:33.946Z,1683583053.946 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 7534
2023-05-08T21:57:33.948Z,1683583053.948 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2023-05-08T21:57:33.949Z,1683583053.949 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2023-05-08T21:57:33.950Z,1683583053.950 [logger ThreadHandler](INFO): Protected caller Thread ID is 7535
2023-05-08T21:57:33.953Z,1683583053.953 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2023-05-08T21:57:33.954Z,1683583053.954 [Supervisor](INFO): Looking for Config files in directory: Config/
2023-05-08T21:57:33.955Z,1683583053.955 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2023-05-08T21:57:34.312Z,1683583054.312 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2023-05-08T21:57:34.313Z,1683583054.313 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2023-05-08T21:57:34.985Z,1683583054.985 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2023-05-08T21:57:34.986Z,1683583054.986 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2023-05-08T21:57:35.098Z,1683583055.098 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2023-05-08T21:57:35.099Z,1683583055.099 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2023-05-08T21:57:35.602Z,1683583055.602 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2023-05-08T21:57:35.603Z,1683583055.603 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2023-05-08T21:57:35.704Z,1683583055.704 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2023-05-08T21:57:35.705Z,1683583055.705 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2023-05-08T21:57:35.789Z,1683583055.789 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2023-05-08T21:57:36.198Z,1683583056.198 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2023-05-08T21:57:36.198Z,1683583056.198 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2023-05-08T21:57:36.423Z,1683583056.423 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2023-05-08T21:57:36.424Z,1683583056.424 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2023-05-08T21:57:36.565Z,1683583056.565 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2023-05-08T21:57:36.566Z,1683583056.566 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2023-05-08T21:57:36.805Z,1683583056.805 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2023-05-08T21:57:36.806Z,1683583056.806 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2023-05-08T21:57:37.737Z,1683583057.737 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2023-05-08T21:57:37.737Z,1683583057.737 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2023-05-08T21:57:38.114Z,1683583058.114 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2023-05-08T21:57:38.114Z,1683583058.114 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2023-05-08T21:57:38.197Z,1683583058.197 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2023-05-08T21:57:38.391Z,1683583058.391 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2023-05-08T21:57:38.392Z,1683583058.392 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2023-05-08T21:57:38.616Z,1683583058.616 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2023-05-08T21:57:38.617Z,1683583058.617 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2023-05-08T21:57:38.918Z,1683583058.918 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2023-05-08T21:57:38.920Z,1683583058.920 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/
2023-05-08T21:57:38.921Z,1683583058.921 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg
2023-05-08T21:57:39.033Z,1683583059.033 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg
2023-05-08T21:57:39.182Z,1683583059.182 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg
2023-05-08T21:57:39.271Z,1683583059.271 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg
2023-05-08T21:57:39.356Z,1683583059.356 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg
2023-05-08T21:57:39.468Z,1683583059.468 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg
2023-05-08T21:57:39.646Z,1683583059.646 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg
2023-05-08T21:57:39.914Z,1683583059.914 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2023-05-08T21:57:39.915Z,1683583059.915 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg
2023-05-08T21:57:40.050Z,1683583060.050 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg
2023-05-08T21:57:40.145Z,1683583060.145 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg
2023-05-08T21:57:40.252Z,1683583060.252 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg
2023-05-08T21:57:40.358Z,1683583060.358 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/root/
2023-05-08T21:57:40.358Z,1683583060.358 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2023-05-08T21:57:40.380Z,1683583060.380 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2023-05-08T21:57:40.481Z,1683583060.481 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2023-05-08T21:57:40.482Z,1683583060.482 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2023-05-08T21:57:40.492Z,1683583060.492 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2023-05-08T21:57:40.492Z,1683583060.492 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2023-05-08T21:57:40.544Z,1683583060.544 [DepthRateCalculator] Loaded
2023-05-08T21:57:40.545Z,1683583060.545 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2023-05-08T21:57:40.550Z,1683583060.550 [PitchRateCalculator] Loaded
2023-05-08T21:57:40.551Z,1683583060.551 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2023-05-08T21:57:40.561Z,1683583060.561 [SpeedCalculator] Loaded
2023-05-08T21:57:40.561Z,1683583060.561 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2023-05-08T21:57:40.576Z,1683583060.576 [VerticalHomogeneityIndexCalculator] Loaded
2023-05-08T21:57:40.577Z,1683583060.577 [ComponentRegistry](DEBUG): SyncComponent "VerticalHomogeneityIndexCalculator" handled in the control thread.
2023-05-08T21:57:40.581Z,1683583060.581 [YawRateCalculator] Loaded
2023-05-08T21:57:40.582Z,1683583060.582 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2023-05-08T21:57:40.603Z,1683583060.603 [ElevatorOffsetCalculator] Loaded
2023-05-08T21:57:40.603Z,1683583060.603 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2023-05-08T21:57:40.603Z,1683583060.603 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2023-05-08T21:57:40.604Z,1683583060.604 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2023-05-08T21:57:40.656Z,1683583060.656 [VerticalControl](DEBUG): Construct VerticalControl.
2023-05-08T21:57:40.711Z,1683583060.711 [VerticalControl] Loaded
2023-05-08T21:57:40.711Z,1683583060.711 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2023-05-08T21:57:40.714Z,1683583060.714 [HorizontalControl](DEBUG): Construct HorizontalControl.
2023-05-08T21:57:40.754Z,1683583060.754 [HorizontalControl] Loaded
2023-05-08T21:57:40.755Z,1683583060.755 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2023-05-08T21:57:40.757Z,1683583060.757 [SpeedControl](DEBUG): Construct SpeedControl.
2023-05-08T21:57:40.760Z,1683583060.760 [SpeedControl] Loaded
2023-05-08T21:57:40.760Z,1683583060.760 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2023-05-08T21:57:40.763Z,1683583060.763 [LoopControl](DEBUG): Construct LoopControl.
2023-05-08T21:57:40.763Z,1683583060.763 [LoopControl] Loaded
2023-05-08T21:57:40.764Z,1683583060.764 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2023-05-08T21:57:40.764Z,1683583060.764 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2023-05-08T21:57:40.765Z,1683583060.765 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2023-05-08T21:57:40.878Z,1683583060.878 [DeadReckonUsingMultipleVelocitySources] Loaded
2023-05-08T21:57:40.878Z,1683583060.878 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2023-05-08T21:57:40.892Z,1683583060.892 [NavChart] Loaded
2023-05-08T21:57:40.892Z,1683583060.892 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2023-05-08T21:57:40.898Z,1683583060.898 [UniversalFixResidualReporter] Loaded
2023-05-08T21:57:40.898Z,1683583060.898 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2023-05-08T21:57:40.898Z,1683583060.898 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2023-05-08T21:57:40.899Z,1683583060.899 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2023-05-08T21:57:41.050Z,1683583061.050 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2023-05-08T21:57:41.051Z,1683583061.051 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2023-05-08T21:57:41.487Z,1683583061.487 [BackseatComponent] Loaded
2023-05-08T21:57:41.487Z,1683583061.487 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2023-05-08T21:57:41.488Z,1683583061.488 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408F64E0
2023-05-08T21:57:41.488Z,1683583061.488 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 7617
2023-05-08T21:57:41.491Z,1683583061.491 [LcmUniversalReporter] Loaded
2023-05-08T21:57:41.492Z,1683583061.492 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2023-05-08T21:57:42.327Z,1683583062.327 [BPC1] Loaded
2023-05-08T21:57:42.327Z,1683583062.327 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2023-05-08T21:57:42.399Z,1683583062.399 [DataOverHttps] Loaded
2023-05-08T21:57:42.399Z,1683583062.399 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2023-05-08T21:57:42.400Z,1683583062.400 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 409264E0
2023-05-08T21:57:42.401Z,1683583062.401 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 7618
2023-05-08T21:57:42.422Z,1683583062.422 [Depth_Keller] Loaded
2023-05-08T21:57:42.422Z,1683583062.422 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2023-05-08T21:57:42.427Z,1683583062.427 [DropWeight] Loaded
2023-05-08T21:57:42.428Z,1683583062.428 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2023-05-08T21:57:42.491Z,1683583062.491 [NAL9602] Loaded
2023-05-08T21:57:42.491Z,1683583062.491 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2023-05-08T21:57:42.521Z,1683583062.521 [Onboard] Loaded
2023-05-08T21:57:42.522Z,1683583062.522 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2023-05-08T21:57:42.523Z,1683583062.523 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409564E0
2023-05-08T21:57:42.523Z,1683583062.523 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 7619
2023-05-08T21:57:42.535Z,1683583062.535 [Power24vConverter] Loaded
2023-05-08T21:57:42.536Z,1683583062.536 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2023-05-08T21:57:42.549Z,1683583062.549 [Radio_Surface] Loaded
2023-05-08T21:57:42.549Z,1683583062.549 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2023-05-08T21:57:42.550Z,1683583062.550 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409864E0
2023-05-08T21:57:42.551Z,1683583062.551 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 7620
2023-05-08T21:57:42.644Z,1683583062.644 [DAT] Loaded
2023-05-08T21:57:42.644Z,1683583062.644 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2023-05-08T21:57:42.645Z,1683583062.645 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 409B64E0
2023-05-08T21:57:42.646Z,1683583062.646 [DAT ThreadHandler](INFO): Protected caller Thread ID is 7621
2023-05-08T21:57:42.646Z,1683583062.646 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2023-05-08T21:57:42.647Z,1683583062.647 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2023-05-08T21:57:42.998Z,1683583062.998 [BuoyancyServo] Loaded
2023-05-08T21:57:42.998Z,1683583062.998 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2023-05-08T21:57:43.131Z,1683583063.131 [ElevatorServo] Loaded
2023-05-08T21:57:43.131Z,1683583063.131 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2023-05-08T21:57:43.190Z,1683583063.190 [MassServo] Loaded
2023-05-08T21:57:43.190Z,1683583063.190 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2023-05-08T21:57:43.240Z,1683583063.240 [RudderServo] Loaded
2023-05-08T21:57:43.241Z,1683583063.241 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2023-05-08T21:57:43.306Z,1683583063.306 [ThrusterHE] Loaded
2023-05-08T21:57:43.307Z,1683583063.307 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2023-05-08T21:57:43.307Z,1683583063.307 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2023-05-08T21:57:43.308Z,1683583063.308 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2023-05-08T21:57:43.425Z,1683583063.425 [StratificationFrontDetector](IMPORTANT): thresholdVTHI set to: 0.100000 degC
2023-05-08T21:57:43.425Z,1683583063.425 [StratificationFrontDetector](INFO): (re)initializing
2023-05-08T21:57:43.425Z,1683583063.425 [StratificationFrontDetector] Loaded
2023-05-08T21:57:43.426Z,1683583063.426 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2023-05-08T21:57:43.426Z,1683583063.426 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2023-05-08T21:57:43.427Z,1683583063.427 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2023-05-08T21:57:43.454Z,1683583063.454 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2023-05-08T21:57:43.455Z,1683583063.455 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2023-05-08T21:57:43.771Z,1683583063.771 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2023-05-08T21:57:43.772Z,1683583063.772 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2023-05-08T21:57:43.917Z,1683583063.917 [ESPComponent] Loaded
2023-05-08T21:57:43.917Z,1683583063.917 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2023-05-08T21:57:43.937Z,1683583063.937 [PAR_Licor] Loaded
2023-05-08T21:57:43.937Z,1683583063.937 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2023-05-08T21:57:43.938Z,1683583063.938 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2023-05-08T21:57:43.939Z,1683583063.939 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2023-05-08T21:57:44.084Z,1683583064.084 [SBIT](DEBUG): Construct Startup Built In Test.
2023-05-08T21:57:44.093Z,1683583064.093 [SBIT] Loaded
2023-05-08T21:57:44.094Z,1683583064.094 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2023-05-08T21:57:44.097Z,1683583064.097 [IBIT](DEBUG): Construct Initiated Built In Test.
2023-05-08T21:57:44.110Z,1683583064.110 [IBIT] Loaded
2023-05-08T21:57:44.110Z,1683583064.110 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2023-05-08T21:57:44.116Z,1683583064.116 [CBIT](DEBUG): Construct Continuous Built In Test.
2023-05-08T21:57:44.221Z,1683583064.221 [CBIT] Loaded
2023-05-08T21:57:44.221Z,1683583064.221 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2023-05-08T21:57:44.221Z,1683583064.221 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2023-05-08T21:57:44.228Z,1683583064.228 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2023-05-08T21:57:44.230Z,1683583064.230 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2023-05-08T21:57:44.242Z,1683583064.242 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2023-05-08T21:57:44.243Z,1683583064.243 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B874E0
2023-05-08T21:57:44.243Z,1683583064.243 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 7622
2023-05-08T21:57:44.248Z,1683583064.248 [Supervisor](INFO): Main Thread ID is 6516
2023-05-08T21:57:44.248Z,1683583064.248 [Supervisor](DEBUG): Running supervisor.
2023-05-08T21:57:44.249Z,1683583064.249 [CommandExec ThreadHandler](INFO): Handler Thread ID is 7623
2023-05-08T21:57:44.249Z,1683583064.249 [CommandExec](INFO): Initializing the command executive.
2023-05-08T21:57:44.250Z,1683583064.250 [CommandLine ThreadHandler](INFO): Handler Thread ID is 7624
2023-05-08T21:57:44.253Z,1683583064.253 [controlThread ThreadHandler](INFO): Handler Thread ID is 7625
2023-05-08T21:57:44.253Z,1683583064.253 [controlThread](DEBUG): Initializing ControlThread
2023-05-08T21:57:44.254Z,1683583064.254 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2023-05-08T21:57:44.254Z,1683583064.254 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2023-05-08T21:57:44.255Z,1683583064.255 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2023-05-08T21:57:44.255Z,1683583064.255 [VerticalHomogeneityIndexCalculator](DEBUG): (re)initializing
2023-05-08T21:57:44.256Z,1683583064.256 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2023-05-08T21:57:44.257Z,1683583064.257 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2023-05-08T21:57:44.257Z,1683583064.257 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2023-05-08T21:57:44.259Z,1683583064.259 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2023-05-08T21:57:44.260Z,1683583064.260 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2023-05-08T21:57:44.260Z,1683583064.260 [LoopControl](DEBUG): Initialize LoopControlComponent.
2023-05-08T21:57:44.261Z,1683583064.261 [NavChart](DEBUG): Initialize NavChart Navigation.
2023-05-08T21:57:44.261Z,1683583064.261 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2023-05-08T21:57:44.268Z,1683583064.268 [SBIT](INFO): Initialize SBIT Component.
2023-05-08T21:57:44.268Z,1683583064.268 [SBIT](IMPORTANT): git: 2023-04-26-7-g7f279a801
2023-05-08T21:57:44.268Z,1683583064.268 [SBIT](INFO): git hash: 7f279a80182f0d21b6971cb50dd91b68e1024218
2023-05-08T21:57:44.269Z,1683583064.269 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2023-05-08T21:57:44.270Z,1683583064.270 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #1 PREEMPT Tue Sep 24 11:12:27 PDT 2019
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2023-05-08T21:57:44.271Z,1683583064.271 [SBIT](INFO): Beginning SBIT in 134.000000 seconds.
2023-05-08T21:57:44.271Z,1683583064.271 [IBIT](INFO): Initialize IBIT Component.
2023-05-08T21:57:44.272Z,1683583064.272 [CBIT](DEBUG): Initialize CBIT Component.
2023-05-08T21:57:44.273Z,1683583064.273 [logger ThreadHandler](INFO): Handler Thread ID is 7626
2023-05-08T21:57:44.283Z,1683583064.283 [CBIT](DEBUG): Initialized mux pins.
2023-05-08T21:57:44.283Z,1683583064.283 [CBIT](DEBUG): Initializing the watchdog timer.
2023-05-08T21:57:44.292Z,1683583064.292 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 7627
2023-05-08T21:57:44.304Z,1683583064.304 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 7628
2023-05-08T21:57:44.305Z,1683583064.305 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2023-05-08T21:57:44.307Z,1683583064.307 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2023-05-08T21:57:44.308Z,1683583064.308 [CBIT](DEBUG): Initializing heartbeat.
2023-05-08T21:57:44.316Z,1683583064.316 [Onboard ThreadHandler](INFO): Handler Thread ID is 7629
2023-05-08T21:57:44.333Z,1683583064.333 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 7630
2023-05-08T21:57:44.352Z,1683583064.352 [DAT ThreadHandler](INFO): Handler Thread ID is 7631
2023-05-08T21:57:44.353Z,1683583064.353 [DAT](INFO): Powering up
2023-05-08T21:57:44.353Z,1683583064.353 [DAT](DEBUG): Initializing DAT.
2023-05-08T21:57:44.357Z,1683583064.357 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 7633
2023-05-08T21:57:44.361Z,1683583064.361 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2023-05-08T21:57:44.361Z,1683583064.361 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2023-05-08T21:57:44.361Z,1683583064.361 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2023-05-08T21:57:44.361Z,1683583064.361 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2023-05-08T21:57:44.361Z,1683583064.361 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2023-05-08T21:57:44.362Z,1683583064.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2023-05-08T21:57:44.362Z,1683583064.362 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2023-05-08T21:57:44.362Z,1683583064.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2023-05-08T21:57:44.379Z,1683583064.379 [CBIT](DEBUG): Deactivating GF circuits.
2023-05-08T21:57:44.379Z,1683583064.379 [CBIT](DEBUG): Deactivating emergency mode.
2023-05-08T21:57:44.419Z,1683583064.419 [CBIT](DEBUG): Backplane powered.
2023-05-08T21:57:44.420Z,1683583064.420 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2023-05-08T21:57:44.434Z,1683583064.434 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-08T21:57:44.469Z,1683583064.469 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2023-05-08T21:57:44.470Z,1683583064.470 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2023-05-08T21:57:44.532Z,1683583064.532 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2023-05-08T21:57:44.533Z,1683583064.533 [Default:A.Wait](DEBUG): Construct Wait.
2023-05-08T21:57:44.544Z,1683583064.544 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2023-05-08T21:57:44.579Z,1683583064.579 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2023-05-08T21:57:44.582Z,1683583064.582 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2023-05-08T21:57:44.627Z,1683583064.627 [Default:E.Execute](DEBUG): Construct Execute.
2023-05-08T21:57:44.631Z,1683583064.631 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

    <DefineArg Name="ElapsedSinceDefaultStarted"><Units:minute/><Value>0</Value></DefineArg>

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P4H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2023-05-08T21:57:44.651Z,1683583064.651 [controlThread](DEBUG): Component order: CycleStarter,BPC1,Depth_Keller,DropWeight,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,VerticalHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2023-05-08T21:57:44.703Z,1683583064.703 [Power24vConverter](INFO): Powering up.
2023-05-08T21:57:44.739Z,1683583064.739 [Radio_Surface](INFO): Powering up
2023-05-08T21:57:44.754Z,1683583064.754 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2023-05-08T21:57:44.760Z,1683583064.760 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2023-05-08T21:57:44.761Z,1683583064.761 [ElevatorServo](DEBUG): Initializing EZServoServo.
2023-05-08T21:57:44.768Z,1683583064.768 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2023-05-08T21:57:44.769Z,1683583064.769 [MassServo](DEBUG): Initializing EZServoServo.
2023-05-08T21:57:44.779Z,1683583064.779 [MassServo](DEBUG): Initializing MassServo.
2023-05-08T21:57:44.780Z,1683583064.780 [RudderServo](DEBUG): Initializing EZServoServo.
2023-05-08T21:57:44.788Z,1683583064.788 [RudderServo](DEBUG): Initializing RudderServo.
2023-05-08T21:57:44.788Z,1683583064.788 [ThrusterHE](DEBUG): Initializing EZServoServo.
2023-05-08T21:57:44.800Z,1683583064.800 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2023-05-08T21:57:45.109Z,1683583065.109 [DropWeight](CRITICAL): DROP WEIGHT MISSING.

2023-05-08T21:57:45.109Z,1683583065.109 [DropWeight] Hardware Fault, FailCount= 1
2023-05-08T21:57:45.110Z,1683583065.110 [DropWeight](ERROR): Hardware Fault
2023-05-08T21:57:45.139Z,1683583065.139 [CommandExec](FAULT): Scheduling is paused
2023-05-08T21:57:45.147Z,1683583065.147 [CBIT](INFO): Critical error at 20230508T215745
2023-05-08T21:57:45.148Z,1683583065.148 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2023-05-08T21:57:45.150Z,1683583065.150 [CBIT](ERROR): Hardware Fault in component: DropWeight
2023-05-08T21:57:45.150Z,1683583065.150 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2023-05-08T21:57:45.489Z,1683583065.489 [CBIT](INFO): Critical error at 20230508T215745
2023-05-08T21:57:50.372Z,1683583070.372 [ThrusterHE](ERROR): Zero Speed Commanded.
2023-05-08T21:58:06.218Z,1683583086.218 [CommandExec](IMPORTANT): got command failComponent none DropWeight
2023-05-08T21:58:06.219Z,1683583086.219 [DropWeight] No Fault, FailCount= 1
2023-05-08T21:58:06.219Z,1683583086.219 [CommandExec](IMPORTANT): DropWeight failureMode is No Fault
2023-05-08T21:58:12.542Z,1683583092.542 [NAL9602](INFO): Powering up NAL9602
2023-05-08T21:58:23.449Z,1683583103.449 [NAL9602](INFO): NAL9602 initialized
2023-05-08T21:58:44.604Z,1683583124.604 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T21:58:44.604Z,1683583124.604 [DAT] Communications Fault, FailCount= 1
2023-05-08T21:58:44.604Z,1683583124.604 [DAT](ERROR): Communications Fault
2023-05-08T21:58:44.910Z,1683583124.910 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T21:58:45.007Z,1683583125.007 [DAT](INFO): Powering down
2023-05-08T21:58:46.139Z,1683583126.139 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T21:58:46.139Z,1683583126.139 [DAT] No Fault, FailCount= 1
2023-05-08T21:58:48.056Z,1683583128.056 [DAT](INFO): Powering up
2023-05-08T21:58:48.056Z,1683583128.056 [DAT](DEBUG): Initializing DAT.
2023-05-08T21:58:50.515Z,1683583130.515 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T21:59:05.456Z,1683583145.456 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T21:59:20.808Z,1683583160.808 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T21:59:35.757Z,1683583175.757 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T21:59:44.659Z,1683583184.659 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T21:59:44.659Z,1683583184.659 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2023-05-08T21:59:44.659Z,1683583184.659 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T21:59:44.693Z,1683583184.693 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T21:59:45.092Z,1683583185.092 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T21:59:45.092Z,1683583185.092 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2023-05-08T21:59:48.296Z,1683583188.296 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T21:59:48.296Z,1683583188.296 [DAT] Communications Fault, FailCount= 2
2023-05-08T21:59:48.296Z,1683583188.296 [DAT](ERROR): Communications Fault
2023-05-08T21:59:48.305Z,1683583188.305 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T21:59:48.700Z,1683583188.700 [DAT](INFO): Powering down
2023-05-08T21:59:49.920Z,1683583189.920 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T21:59:49.920Z,1683583189.920 [DAT] No Fault, FailCount= 2
2023-05-08T21:59:50.706Z,1683583190.706 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T21:59:51.743Z,1683583191.743 [DAT](INFO): Powering up
2023-05-08T21:59:51.744Z,1683583191.744 [DAT](DEBUG): Initializing DAT.
2023-05-08T21:59:58.805Z,1683583198.805 [SBIT](IMPORTANT): Beginning Startup BIT
2023-05-08T21:59:58.810Z,1683583198.810 [CBIT](IMPORTANT): Beginning ground fault scan
2023-05-08T22:00:05.653Z,1683583205.653 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T22:00:09.807Z,1683583209.807 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.001004
CHAN A1 (24V): -0.002242
CHAN A2 (12V): 0.000007
CHAN A3 (5V): -0.000019
CHAN B0 (3.3V): 0.000037
CHAN B1 (3.15aV): 0.000415
CHAN B2 (3.15bV): 0.000846
CHAN B3 (GND): 0.000340
OPEN: 0.005179
Full Scale: +/- 1 mA
2023-05-08T22:00:12.366Z,1683583212.366 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004938
2023-05-08T22:00:20.601Z,1683583220.601 [BPC1](ERROR): BPC1B got IPBS message with 6 sticks (min is 7).
2023-05-08T22:00:51.756Z,1683583251.756 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:00:51.756Z,1683583251.756 [DAT] Communications Fault, FailCount= 3
2023-05-08T22:00:51.756Z,1683583251.756 [DAT](ERROR): Communications Fault
2023-05-08T22:00:52.144Z,1683583252.144 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:00:52.159Z,1683583252.159 [DAT](INFO): Powering down
2023-05-08T22:00:52.942Z,1683583252.942 [SBIT](IMPORTANT): SBIT PASSED
2023-05-08T22:00:52.942Z,1683583252.942 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): BPC1.batteryMissingStickThreshold=12 count;

2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): DVL_micro.loadAtStartup=0 bool;

2023-05-08T22:00:52.943Z,1683583252.943 [SBIT](IMPORTANT): Depth_Keller.offset=3.6 decibar;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): Express none CBIT.ampHoursUsed;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_salinity_homogeneity_index 0.050000 practical_salinity_unit;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): Express linearApproximation VerticalHomogeneityIndexCalculator.vertical_temperature_homogeneity_index 0.050000 celsius;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): Express none height_above_sea_floor;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): StratificationFrontDetector.loadAtStartup=1 bool;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): StratificationFrontDetector.threshold_VTHI=0.1 celsius;

2023-05-08T22:00:52.944Z,1683583252.944 [SBIT](IMPORTANT): StratificationFrontDetector.verbosity=1 count;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=208.617815 cubic_centimeter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalControl.massDefault=28.688721 millimeter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-28 millimeter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalControl.massPositionLimitFwd=32 millimeter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalControl.surfaceThreshold=1.5 meter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth1=3 meter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth2=5 meter;

2023-05-08T22:00:52.945Z,1683583252.945 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth3=10 meter;

2023-05-08T22:00:52.946Z,1683583252.946 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.depth4=15 meter;

2023-05-08T22:00:52.946Z,1683583252.946 [SBIT](IMPORTANT): VerticalHomogeneityIndexCalculator.loadAtStartup=1 bool;

2023-05-08T22:00:52.946Z,1683583252.946 [SBIT](IMPORTANT): WetLabsBB2FL.loadAtStartup=0 bool;

2023-05-08T22:00:53.357Z,1683583253.357 [MissionManager](IMPORTANT): Started mission Startup
2023-05-08T22:00:53.358Z,1683583253.358 [Startup] Running Loop=1
2023-05-08T22:00:53.358Z,1683583253.358 [Startup](DEBUG): Aggregate::initialize Startup
2023-05-08T22:00:53.358Z,1683583253.358 [Startup:A.GoToSurface] Running Loop=1
2023-05-08T22:00:53.358Z,1683583253.358 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-08T22:00:53.358Z,1683583253.358 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-08T22:00:53.359Z,1683583253.359 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-08T22:00:53.359Z,1683583253.359 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-08T22:00:53.360Z,1683583253.360 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-08T22:00:53.360Z,1683583253.360 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-08T22:00:53.361Z,1683583253.361 [Startup:StartupSatComms] Running Loop=1
2023-05-08T22:00:53.362Z,1683583253.362 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2023-05-08T22:00:53.362Z,1683583253.362 [Startup:StartupSatComms:A] Running Loop=1
2023-05-08T22:00:53.371Z,1683583253.371 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:00:53.371Z,1683583253.371 [DAT] No Fault, FailCount= 3
2023-05-08T22:00:53.766Z,1683583253.766 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2023-05-08T22:00:55.203Z,1683583255.203 [DAT](INFO): Powering up
2023-05-08T22:00:55.204Z,1683583255.204 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:01:45.883Z,1683583305.883 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:01:45.883Z,1683583305.883 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2023-05-08T22:01:45.883Z,1683583305.883 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:01:45.894Z,1683583305.894 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:01:46.289Z,1683583306.289 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:01:46.289Z,1683583306.289 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2023-05-08T22:01:53.553Z,1683583313.553 [Startup:StartupSatComms:A](INFO): Timed out from 2023-05-08T22:00:53.4Z
2023-05-08T22:01:53.553Z,1683583313.553 [Startup:StartupSatComms:A] Stopped
2023-05-08T22:01:53.554Z,1683583313.554 [Startup:StartupSatComms:B] Running Loop=1
2023-05-08T22:01:53.949Z,1683583313.949 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-08T22:01:55.444Z,1683583315.444 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:01:55.444Z,1683583315.444 [DAT] Communications Fault, FailCount= 4
2023-05-08T22:01:55.444Z,1683583315.444 [DAT](ERROR): Communications Fault
2023-05-08T22:01:55.678Z,1683583315.678 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:01:55.847Z,1683583315.847 [DAT](INFO): Powering down
2023-05-08T22:01:56.818Z,1683583316.818 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20230508T193459/Courier0040.lzma
2023-05-08T22:01:56.888Z,1683583316.888 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:01:56.888Z,1683583316.888 [DAT] No Fault, FailCount= 4
2023-05-08T22:01:57.557Z,1683583317.557 [DataOverHttps](INFO): Moved sent file to Logs/20230508T193459/Courier0040.lzma.bak
2023-05-08T22:01:57.557Z,1683583317.557 [DataOverHttps](INFO): SBD MOMSN=18282992
2023-05-08T22:01:58.895Z,1683583318.895 [DAT](INFO): Powering up
2023-05-08T22:01:58.896Z,1683583318.896 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:02:01.363Z,1683583321.363 [CommandExec](IMPORTANT): got command run ./Missions/Maintenance/sample_lab.xml
2023-05-08T22:02:01.363Z,1683583321.363 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.xml
2023-05-08T22:02:01.437Z,1683583321.437 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2023-05-08T22:02:01.460Z,1683583321.460 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2023-05-08T22:02:01.463Z,1683583321.463 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2023-05-08T22:02:01.472Z,1683583321.472 [sample_lab:A.AbortSample](DEBUG): Construct.
2023-05-08T22:02:01.480Z,1683583321.480 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct.
2023-05-08T22:02:01.490Z,1683583321.490 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Science="Tethys/Science"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sample http://okeanids.mbari.org/tethys/Xml/Sample.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="sample_lab">

    <Description>
        This mission is designed to run in the lab only and triggers an ESP
        sample with specified type.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4)
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Sample:AbortSample>
        <Parallel/>
    </Sample:AbortSample>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Syslog Severity="Important">Sampling ESP cartridge type <Arg Name="CartridgeType"/><Units:count/></Syslog>

        <Science:ESPCartridgeSelect>
            <Sequence/>
            <Timeout Duration="P1M"/>
            <Setting><Science:ESPCartridgeSelect.cartridgeType/><Arg Name="CartridgeType"/></Setting>
        </Science:ESPCartridgeSelect>

        <ReadDatum Id="TriggerESP">
            <Science:ESPComponent.sampling/>
        </ReadDatum>

        <ReadDatum Id="WaitForESP">
            <Science:ESPComponent.sample_number/>
        </ReadDatum>

    </Aggregate>

</Mission>


2023-05-08T22:02:01.516Z,1683583321.516 [CommandExec](IMPORTANT): Running ./Missions/Maintenance/sample_lab.xml
2023-05-08T22:02:12.924Z,1683583332.924 [DataOverHttps](INFO): Sending 245 bytes from file Logs/20230508T215733/Courier0000.lzma
2023-05-08T22:02:13.925Z,1683583333.925 [DataOverHttps](INFO): Moved sent file to Logs/20230508T215733/Courier0000.lzma.bak
2023-05-08T22:02:13.925Z,1683583333.925 [DataOverHttps](INFO): SBD MOMSN=18282994
2023-05-08T22:02:29.099Z,1683583349.099 [DataOverHttps](INFO): Sending 165 bytes from file Logs/20230508T193459/Express0041.lzma
2023-05-08T22:02:30.101Z,1683583350.101 [DataOverHttps](INFO): Moved sent file to Logs/20230508T193459/Express0041.lzma.bak
2023-05-08T22:02:30.101Z,1683583350.101 [DataOverHttps](INFO): SBD MOMSN=18282999
2023-05-08T22:02:45.354Z,1683583365.354 [DataOverHttps](INFO): Sending 1427 bytes from file Logs/20230508T215733/Express0001.lzma
2023-05-08T22:02:46.353Z,1683583366.353 [DataOverHttps](INFO): Moved sent file to Logs/20230508T215733/Express0001.lzma.bak
2023-05-08T22:02:46.353Z,1683583366.353 [DataOverHttps](INFO): SBD MOMSN=18283003
2023-05-08T22:02:48.261Z,1683583368.261 [Startup:StartupSatComms:B] Stopped
2023-05-08T22:02:48.261Z,1683583368.261 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2023-05-08T22:02:48.261Z,1683583368.261 [Startup:StartupSatComms] Stopped
2023-05-08T22:02:48.261Z,1683583368.261 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2023-05-08T22:02:48.262Z,1683583368.262 [Startup](INFO): Completed Startup
2023-05-08T22:02:48.262Z,1683583368.262 [MissionManager](INFO): Startup is completed.
2023-05-08T22:02:48.263Z,1683583368.263 [MissionManager](INFO): Uninitializing Mission Startup
2023-05-08T22:02:48.263Z,1683583368.263 [Startup] Stopped
2023-05-08T22:02:48.263Z,1683583368.263 [Startup](DEBUG): Aggregate::uninitialize Startup
2023-05-08T22:02:48.263Z,1683583368.263 [Startup:A.GoToSurface] Stopped
2023-05-08T22:02:48.263Z,1683583368.263 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-08T22:02:48.614Z,1683583368.614 [MissionManager](IMPORTANT): Started mission sample_lab
2023-05-08T22:02:48.614Z,1683583368.614 [sample_lab] Running Loop=1
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab](DEBUG): Aggregate::initialize sample_lab
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab:A.AbortSample] Running Loop=1
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab:SampleRepeater] Running Loop=1
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2023-05-08T22:02:48.615Z,1683583368.615 [sample_lab:SampleRepeater:A] Running Loop=1
2023-05-08T22:02:48.616Z,1683583368.616 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -4.000000 count 
2023-05-08T22:02:48.616Z,1683583368.616 [sample_lab:SampleRepeater:A] Stopped
2023-05-08T22:02:48.616Z,1683583368.616 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2023-05-08T22:02:48.616Z,1683583368.616 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2023-05-08T22:02:48.616Z,1683583368.616 [sample_lab:A.AbortSample] Running Loop=1
2023-05-08T22:02:49.029Z,1683583369.029 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -4.
2023-05-08T22:02:49.030Z,1683583369.030 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2023-05-08T22:02:49.030Z,1683583369.030 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2023-05-08T22:02:49.030Z,1683583369.030 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2023-05-08T22:02:49.426Z,1683583369.426 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2023-05-08T22:02:50.202Z,1683583370.202 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:'
2023-05-08T22:02:50.205Z,1683583370.205 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:"
2023-05-08T22:02:50.206Z,1683583370.206 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2023-05-08T22:02:59.148Z,1683583379.148 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:02:59.148Z,1683583379.148 [DAT] Communications Fault, FailCount= 5
2023-05-08T22:02:59.148Z,1683583379.148 [DAT](ERROR): Communications Fault
2023-05-08T22:02:59.197Z,1683583379.197 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:02:59.551Z,1683583379.551 [DAT](INFO): Powering down
2023-05-08T22:03:00.307Z,1683583380.307 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2023-05-08T22:03:00.309Z,1683583380.309 [ESPComponent](INFO): powering up ESP
2023-05-08T22:03:00.327Z,1683583380.327 [ESPComponent](INFO): powering up ESP secondary power supply
2023-05-08T22:03:00.344Z,1683583380.344 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.11.2:10.89.11.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2023-05-08T22:03:00.468Z,1683583380.468 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2023-05-08T22:03:00.534Z,1683583380.534 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:03:00.534Z,1683583380.534 [DAT] No Fault, FailCount= 5
2023-05-08T22:03:01.518Z,1683583381.518 [ESPComponent](INFO): console:

2023-05-08T22:03:01.924Z,1683583381.924 [ESPComponent](INFO): console:NAND:  256 MiB
2023-05-08T22:03:02.323Z,1683583382.323 [ESPComponent](INFO): console:
BOOTMODE: SPI
2023-05-08T22:03:02.599Z,1683583382.599 [DAT](INFO): Powering up
2023-05-08T22:03:02.600Z,1683583382.600 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:03:02.726Z,1683583382.726 [ESPComponent](INFO): console:
reading SPI NOR..Done
2023-05-08T22:03:03.134Z,1683583383.134 [ESPComponent](INFO): console:

2023-05-08T22:03:03.536Z,1683583383.536 [ESPComponent](INFO): console:

2023-05-08T22:03:03.953Z,1683583383.953 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51)
2023-05-08T22:03:04.352Z,1683583384.352 [ESPComponent](INFO): console:

2023-05-08T22:03:04.765Z,1683583384.765 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2023-05-08T22:03:05.169Z,1683583385.169 [ESPComponent](INFO): console:
flash params are already written into flash
2023-05-08T22:03:05.558Z,1683583385.558 [ESPComponent](INFO): console:
DRAM:  64 MB
2023-05-08T22:03:05.963Z,1683583385.963 [ESPComponent](INFO): console:
In:    serial
2023-05-08T22:03:06.366Z,1683583386.366 [ESPComponent](INFO): console:
Out:   serial
2023-05-08T22:03:06.766Z,1683583386.766 [ESPComponent](INFO): console:
Err:   serial
2023-05-08T22:03:07.171Z,1683583387.171 [ESPComponent](INFO): console:
Net:   ks8851_mll
2023-05-08T22:03:07.575Z,1683583387.575 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2023-05-08T22:03:07.983Z,1683583387.983 [ESPComponent](INFO): console:
4096 KiB S25FL032P at 0:0 is now current device
2023-05-08T22:03:08.384Z,1683583388.384 [ESPComponent](INFO): console:
Loading kernel from SPI flash...done
2023-05-08T22:03:08.937Z,1683583388.937 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2023-05-08T22:03:09.213Z,1683583389.213 [ESPComponent](INFO): console:
   Image Name:   Linux-3.18.140-lpc31-mbari4
2023-05-08T22:03:09.630Z,1683583389.630 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2023-05-08T22:03:10.029Z,1683583390.029 [ESPComponent](INFO): console:
   Data Size:    2336368 Bytes =  2.2 MB
2023-05-08T22:03:10.402Z,1683583390.402 [ESPComponent](INFO): console:
   Load Address: 30008000
2023-05-08T22:03:10.811Z,1683583390.811 [ESPComponent](INFO): console:
   Entry Point:  30008000
2023-05-08T22:03:11.212Z,1683583391.212 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2023-05-08T22:03:11.618Z,1683583391.618 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2023-05-08T22:03:12.022Z,1683583392.022 [ESPComponent](INFO): console:
OK
2023-05-08T22:03:12.426Z,1683583392.426 [ESPComponent](INFO): console:

2023-05-08T22:03:12.827Z,1683583392.827 [ESPComponent](INFO): console:
Starting kernel ...
2023-05-08T22:03:13.230Z,1683583393.230 [ESPComponent](INFO): console:

2023-05-08T22:03:13.692Z,1683583393.692 [ESPComponent](INFO): console:
Uncompressing Linux... Booting kernel...
2023-05-08T22:03:14.056Z,1683583394.056 [ESPComponent](INFO): console:
[    0.06] MBARI ESP 3G
2023-05-08T22:03:14.543Z,1683583394.543 [ESPComponent](INFO): console:

2023-05-08T22:03:14.883Z,1683583394.883 [ESPComponent](INFO): console:
INIT: version 2.85 booting
2023-05-08T22:03:15.270Z,1683583395.270 [ESPComponent](INFO): console:

2023-05-08T22:03:15.660Z,1683583395.660 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2023-05-08T22:03:16.058Z,1683583396.058 [ESPComponent](INFO): console:
ESPlrauvSIM
2023-05-08T22:03:16.462Z,1683583396.462 [ESPComponent](INFO): console:

2023-05-08T22:03:16.871Z,1683583396.871 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2023-05-08T22:03:17.274Z,1683583397.274 [ESPComponent](INFO): console:

2023-05-08T22:03:17.674Z,1683583397.674 [ESPComponent](INFO): console:Loading kernel modules
2023-05-08T22:03:18.081Z,1683583398.081 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2023-05-08T22:03:18.485Z,1683583398.485 [ESPComponent](INFO): console:
[    6.35] EXT4-fs: Warning: mounting with data=journal disables delayed allocation and O_DIRECT support!
2023-05-08T22:03:18.891Z,1683583398.891 [ESPComponent](INFO): console:
Starting device events handler
2023-05-08T22:03:19.379Z,1683583399.379 [ESPComponent](INFO): console:

2023-05-08T22:03:24.577Z,1683583404.577 [ESPComponent](INFO): console:Set system clock to:  Mon May  8 15:03:24 PDT 2023
2023-05-08T22:03:24.964Z,1683583404.964 [ESPComponent](INFO): console:
Starting syogd...
2023-05-08T22:03:25.369Z,1683583405.369 [ESPComponent](INFO): console:
stopped syslogd (pid 679)
2023-05-08T22:03:25.765Z,1683583405.765 [ESPComponent](INFO): console:
Bringing up lo ...
2023-05-08T22:03:26.158Z,1683583406.158 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2023-05-08T22:03:26.571Z,1683583406.571 [ESPComponent](INFO): console:
Packet forwarding enabled
2023-05-08T22:03:26.967Z,1683583406.967 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2023-05-08T22:03:26.970Z,1683583406.970 [ESPComponent](INFO): console:
Bringing up platform ...
2023-05-08T22:03:27.370Z,1683583407.370 [ESPComponent](INFO): console:
Bringing up wired ...
2023-05-08T22:03:27.914Z,1683583407.914 [ESPComponent](INFO): console:
Determining IP configuration for wired ...udhcpc (v1.11.2) started
2023-05-08T22:03:28.263Z,1683583408.263 [ESPComponent](INFO): console:

2023-05-08T22:03:29.003Z,1683583409.003 [ESPComponent](INFO): console:Sending discover...
2023-05-08T22:03:29.455Z,1683583409.455 [ESPComponent](INFO): console:

2023-05-08T22:03:31.815Z,1683583411.815 [ESPComponent](INFO): console:Sending select for 10.89.11.71...
2023-05-08T22:03:32.233Z,1683583412.233 [ESPComponent](INFO): console:
Lease of 10.89.11.71 obtained, lease time 3600
2023-05-08T22:03:32.711Z,1683583412.711 [ESPComponent](INFO): console:

2023-05-08T22:03:33.839Z,1683583413.839 [ESPComponent](INFO): console:Bringing up direct ...
2023-05-08T22:03:34.244Z,1683583414.244 [ESPComponent](INFO): console:
direct IP=10.10.10.10
2023-05-08T22:03:34.707Z,1683583414.707 [ESPComponent](INFO): console:

2023-05-08T22:03:38.298Z,1683583418.298 [ESPComponent](INFO): console:[#] ip link add wg2shore type wireguard
2023-05-08T22:03:38.763Z,1683583418.763 [ESPComponent](INFO): console:

2023-05-08T22:03:41.529Z,1683583421.529 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63
2023-05-08T22:03:41.933Z,1683583421.933 [ESPComponent](INFO): console:
[#] ip -4 address add 192.168.5.39 dev wg2shore
2023-05-08T22:03:42.378Z,1683583422.378 [ESPComponent](INFO): console:
[#] ip link set mtu 1376 up dev wg2shore
2023-05-08T22:03:42.735Z,1683583422.735 [ESPComponent](INFO): console:
[#] ip -4 route add 192.168.4.0/23 dev wg2shore
2023-05-08T22:03:43.142Z,1683583423.142 [ESPComponent](INFO): console:
Bringing up wg2shore ...
2023-05-08T22:03:43.548Z,1683583423.548 [ESPComponent](INFO): console:
Starting netplugd...
2023-05-08T22:03:43.934Z,1683583423.934 [ESPComponent](INFO): console:
Starting portmap...
2023-05-08T22:03:44.352Z,1683583424.352 [ESPComponent](INFO): console:
Mounting nfs filesystems ...
2023-05-08T22:03:44.762Z,1683583424.762 [ESPComponent](INFO): console:
NTP sycn'd with ESPshore at Mon May  8 15:03:44 PDT 2023
2023-05-08T22:03:45.227Z,1683583425.227 [ESPComponent](INFO): console:

2023-05-08T22:03:46.767Z,1683583426.767 [ESPComponent](INFO): console:Starting chronyd...
2023-05-08T22:03:46.773Z,1683583426.773 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:03:46.773Z,1683583426.773 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2023-05-08T22:03:46.773Z,1683583426.773 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:03:46.784Z,1683583426.784 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:03:47.247Z,1683583427.247 [ESPComponent](INFO): console:

2023-05-08T22:03:47.269Z,1683583427.269 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:03:47.269Z,1683583427.269 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2023-05-08T22:03:47.992Z,1683583427.992 [ESPComponent](INFO): console:Starting darkhttpd...
2023-05-08T22:03:48.385Z,1683583428.385 [ESPComponent](INFO): console:
darkhttpd/1.14, copyright (c) 2003-2022 Emil Mikulic.
2023-05-08T22:03:48.783Z,1683583428.783 [ESPComponent](INFO): console:
listening on: http://0.0.0.0:80/
2023-05-08T22:03:49.190Z,1683583429.190 [ESPComponent](INFO): console:
set gid to 1
2023-05-08T22:03:49.591Z,1683583429.591 [ESPComponent](INFO): console:
set uid to 65534
2023-05-08T22:03:50.000Z,1683583430.000 [ESPComponent](INFO): console:
Starting dnsmasq...
2023-05-08T22:03:50.475Z,1683583430.475 [ESPComponent](INFO): console:

2023-05-08T22:03:53.648Z,1683583433.648 [ESPComponent](INFO): console:

2023-05-08T22:03:54.053Z,1683583434.053 [ESPComponent](INFO): console:
MBARI ESP Embedded Linux 2.81 -- 2/11/23 brent@mbari.org
2023-05-08T22:03:54.443Z,1683583434.443 [ESPComponent](INFO): console:

2023-05-08T22:03:54.907Z,1683583434.907 [ESPComponent](INFO): console:ESPlrauvSIM login: 
2023-05-08T22:03:55.246Z,1683583435.246 [ESPComponent](IMPORTANT): ESP has connected as client
2023-05-08T22:03:56.078Z,1683583436.078 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -4
2023-05-08T22:03:56.078Z,1683583436.078 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2023-05-08T22:03:56.079Z,1683583436.079 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2023-05-08T22:03:56.087Z,1683583436.087 [sample_lab:SampleRepeater:TriggerESP] Stopped
2023-05-08T22:03:56.087Z,1683583436.087 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1
2023-05-08T22:03:56.542Z,1683583436.542 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2023-05-08T22:03:57.283Z,1683583437.283 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2023-05-08T22:03:57.686Z,1683583437.686 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2023-05-08T22:03:59.291Z,1683583439.291 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2023-05-08T22:04:00.923Z,1683583440.923 [ESPComponent](ERROR): In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<<Cartridge::None in LRAUV -- No dry archiveHiBiomass_bac cartridges remain
>>. Elapsed time since command issued: 2.0244
2023-05-08T22:04:01.306Z,1683583441.306 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING
2023-05-08T22:04:02.616Z,1683583442.616 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:04:02.616Z,1683583442.616 [DAT] Communications Fault, FailCount= 6
2023-05-08T22:04:02.616Z,1683583442.616 [DAT](ERROR): Communications Fault
2023-05-08T22:04:02.961Z,1683583442.961 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:04:03.019Z,1683583443.019 [DAT](INFO): Powering down
2023-05-08T22:04:04.189Z,1683583444.189 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:04:04.189Z,1683583444.189 [DAT] No Fault, FailCount= 6
2023-05-08T22:04:06.068Z,1683583446.068 [DAT](INFO): Powering up
2023-05-08T22:04:06.068Z,1683583446.068 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:04:30.818Z,1683583470.818 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq -e 'ssh -o StrictHostKeyChecking=no' --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs &
2023-05-08T22:04:30.832Z,1683583470.832 [ESPComponent](INFO): closing pipe.
2023-05-08T22:04:31.217Z,1683583471.217 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2023-05-08T22:05:06.092Z,1683583506.092 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:05:06.092Z,1683583506.092 [DAT] Communications Fault, FailCount= 7
2023-05-08T22:05:06.092Z,1683583506.092 [DAT](ERROR): Communications Fault
2023-05-08T22:05:06.370Z,1683583506.370 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:05:06.495Z,1683583506.495 [DAT](INFO): Powering down
2023-05-08T22:05:07.605Z,1683583507.605 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:05:07.605Z,1683583507.605 [DAT] No Fault, FailCount= 7
2023-05-08T22:05:09.547Z,1683583509.547 [DAT](INFO): Powering up
2023-05-08T22:05:09.548Z,1683583509.548 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:05:37.461Z,1683583537.461 [BPC1](INFO): Calculating totals. Valid battery stick count: 48. Valid reserve battery stick count: 5.
2023-05-08T22:05:37.464Z,1683583537.464 [BPC1](INFO): Received data from all battery sticks.
2023-05-08T22:05:47.987Z,1683583547.987 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:05:47.988Z,1683583547.987 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2023-05-08T22:05:47.988Z,1683583547.988 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:05:48.030Z,1683583548.030 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:05:48.409Z,1683583548.409 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:05:48.409Z,1683583548.409 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2023-05-08T22:06:09.576Z,1683583569.576 [DAT](FAULT): failed to initialize, no bytes available on serial interface
2023-05-08T22:06:09.576Z,1683583569.576 [DAT] Communications Fault, FailCount= 8
2023-05-08T22:06:09.576Z,1683583569.576 [DAT](ERROR): Communications Fault
2023-05-08T22:06:09.804Z,1683583569.804 [CBIT](ERROR): Communications Fault in component: DAT
2023-05-08T22:06:09.804Z,1683583569.804 [CBIT](FAULT): Communications Fault in component: DAT
2023-05-08T22:06:09.979Z,1683583569.979 [DAT](INFO): Powering down
2023-05-08T22:07:49.192Z,1683583669.192 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:07:49.192Z,1683583669.192 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2023-05-08T22:07:49.192Z,1683583669.192 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:07:49.228Z,1683583669.228 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:07:49.605Z,1683583669.605 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:07:49.605Z,1683583669.605 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2023-05-08T22:08:26.333Z,1683583706.333 [NAL9602](FAULT): GPS failed to acquire within timeout.
2023-05-08T22:08:26.333Z,1683583706.333 [NAL9602] Data Fault, FailCount= 1
2023-05-08T22:08:26.333Z,1683583706.333 [NAL9602](ERROR): Data Fault
2023-05-08T22:08:26.373Z,1683583706.373 [CBIT](ERROR): Data Fault in component: NAL9602
2023-05-08T22:08:26.737Z,1683583706.737 [NAL9602](INFO): Powering down
2023-05-08T22:08:27.562Z,1683583707.562 [CBIT](INFO): Clearing failed state for component NAL9602
2023-05-08T22:08:27.562Z,1683583707.562 [NAL9602] No Fault, FailCount= 1
2023-05-08T22:08:45.721Z,1683583725.721 [Power24vConverter](INFO): Powering down.
2023-05-08T22:08:57.037Z,1683583737.037 [NAL9602](INFO): Powering up NAL9602
2023-05-08T22:09:07.945Z,1683583747.945 [NAL9602](INFO): NAL9602 initialized
2023-05-08T22:09:30.988Z,1683583770.988 [ESPComponent](CRITICAL): [sample #1] ESP sampling sequence terminated with error: In state S_LOADING_CARTRIDGE got exception while awaiting result for cmd='Cmd.loadCartridge -4' exception=<<Cartridge::None in LRAUV -- No dry archiveHiBiomass_bac cartridges remain
>>. Elapsed time since command issued: 2.0244
2023-05-08T22:09:30.988Z,1683583770.988 [ESPComponent] Communications Fault, FailCount= 1
2023-05-08T22:09:30.988Z,1683583770.988 [ESPComponent](ERROR): Communications Fault
2023-05-08T22:09:31.007Z,1683583771.007 [CBIT](INFO): Critical error at 20230508T220930
2023-05-08T22:09:31.007Z,1683583771.007 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2023-05-08T22:09:31.010Z,1683583771.010 [CBIT](ERROR): Communications Fault in component: ESPComponent
2023-05-08T22:09:31.390Z,1683583771.390 [ESPComponent](IMPORTANT): [sample #1] No ESP summary messages.
2023-05-08T22:09:31.391Z,1683583771.391 [ESPComponent](INFO): powering down ESP
2023-05-08T22:09:31.392Z,1683583771.392 [ESPComponent](INFO): powering down ESP secondary power supply
2023-05-08T22:09:31.530Z,1683583771.530 [MissionManager](INFO): MissionManager is completed.
2023-05-08T22:09:31.530Z,1683583771.530 [MissionManager](INFO): Uninitializing Mission sample_lab
2023-05-08T22:09:31.530Z,1683583771.530 [sample_lab] Stopped
2023-05-08T22:09:31.531Z,1683583771.531 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab
2023-05-08T22:09:31.531Z,1683583771.531 [sample_lab:A.AbortSample] Stopped
2023-05-08T22:09:31.531Z,1683583771.531 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample.
2023-05-08T22:09:31.531Z,1683583771.531 [sample_lab:SampleRepeater] Stopped
2023-05-08T22:09:31.531Z,1683583771.531 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater
2023-05-08T22:09:31.532Z,1683583771.532 [sample_lab:SampleRepeater:WaitForESP] Stopped
2023-05-08T22:09:31.789Z,1683583771.789 [MissionManager](IMPORTANT): Started mission Default
2023-05-08T22:09:31.790Z,1683583771.790 [Default] Running Loop=1
2023-05-08T22:09:31.790Z,1683583771.790 [Default](DEBUG): Aggregate::initialize Default
2023-05-08T22:09:31.790Z,1683583771.790 [Default:B.GoToSurface] Running Loop=1
2023-05-08T22:09:31.790Z,1683583771.790 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2023-05-08T22:09:31.790Z,1683583771.790 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2023-05-08T22:09:31.791Z,1683583771.791 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2023-05-08T22:09:31.791Z,1683583771.791 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2023-05-08T22:09:31.792Z,1683583771.792 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2023-05-08T22:09:31.792Z,1683583771.792 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2023-05-08T22:09:31.793Z,1683583771.793 [Default:A.Wait] Running Loop=1
2023-05-08T22:09:31.793Z,1683583771.793 [Default:A.Wait](DEBUG): Initialize Wait Component.
2023-05-08T22:09:32.204Z,1683583772.204 [CBIT](INFO): Clearing failed state for component ESPComponent
2023-05-08T22:09:32.204Z,1683583772.204 [ESPComponent] No Fault, FailCount= 1
2023-05-08T22:09:33.008Z,1683583773.008 [ESPComponent](INFO): powering down ESP
2023-05-08T22:09:33.009Z,1683583773.009 [ESPComponent](INFO): powering down ESP secondary power supply
2023-05-08T22:09:45.116Z,1683583785.116 [Default:A.Wait](INFO): Done Waiting.
2023-05-08T22:09:45.116Z,1683583785.116 [Default:A.Wait] Stopped
2023-05-08T22:09:45.117Z,1683583785.117 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2023-05-08T22:09:45.518Z,1683583785.518 [Default:CheckIn] Running Loop=1
2023-05-08T22:09:45.518Z,1683583785.518 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2023-05-08T22:09:45.518Z,1683583785.518 [Default:CheckIn:Read_GPS] Running Loop=1
2023-05-08T22:09:45.930Z,1683583785.930 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2023-05-08T22:09:50.377Z,1683583790.377 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:09:50.377Z,1683583790.377 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 6
2023-05-08T22:09:50.377Z,1683583790.377 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:09:50.414Z,1683583790.414 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:09:50.786Z,1683583790.786 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:09:50.786Z,1683583790.786 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 6
2023-05-08T22:11:09.589Z,1683583869.589 [CBIT](INFO): Clearing failed state for component DAT
2023-05-08T22:11:09.589Z,1683583869.589 [DAT] No Fault, FailCount= 8
2023-05-08T22:11:09.819Z,1683583869.819 [DAT](INFO): Powering up
2023-05-08T22:11:09.820Z,1683583869.820 [DAT](DEBUG): Initializing DAT.
2023-05-08T22:11:09.963Z,1683583869.963 [Power24vConverter](INFO): Powering up.
2023-05-08T22:11:21.680Z,1683583881.680 [DAT](INFO): DAT read: 

2023-05-08T22:11:21.681Z,1683583881.681 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2023-05-08T22:11:23.444Z,1683583883.444 [DAT](INFO): DAT read: MF Frequency Band

2023-05-08T22:11:23.445Z,1683583883.445 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2023-05-08T22:11:23.446Z,1683583883.446 [DAT](INFO): DAT read: May  8 2023 22:11:18 

2023-05-08T22:11:24.452Z,1683583884.452 [DAT](INFO): DAT read: Features enabled [Bearing]

2023-05-08T22:11:24.454Z,1683583884.454 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2023-05-08T22:11:24.454Z,1683583884.454 [DAT](INFO): commRate: 800
2023-05-08T22:11:26.519Z,1683583886.519 [DAT](INFO): entering command mode
2023-05-08T22:11:26.720Z,1683583886.720 [DAT](INFO): DAT read: 

2023-05-08T22:11:26.720Z,1683583886.720 [DAT](INFO): DAT read: user:1>

2023-05-08T22:11:26.721Z,1683583886.721 [DAT](INFO): setting verbose to 3
2023-05-08T22:11:26.972Z,1683583886.972 [DAT](INFO): DAT read: user:1>

2023-05-08T22:11:26.973Z,1683583886.973 [DAT](INFO): DAT read: Verbose         | 3           

2023-05-08T22:11:26.973Z,1683583886.973 [DAT](INFO): set verbose to 3
2023-05-08T22:11:26.974Z,1683583886.974 [DAT](INFO): setting DatVerbose to 27440
2023-05-08T22:11:27.224Z,1683583887.224 [DAT](INFO): DAT read: user:2>

2023-05-08T22:11:27.225Z,1683583887.225 [DAT](INFO): DAT read: DatVerbose      | 27440       

2023-05-08T22:11:27.225Z,1683583887.225 [DAT](INFO): set DatVerbose to 27440
2023-05-08T22:11:27.225Z,1683583887.225 [DAT](INFO): setting transmit power to 8
2023-05-08T22:11:27.476Z,1683583887.476 [DAT](INFO): DAT read: user:3>

2023-05-08T22:11:27.477Z,1683583887.477 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2023-05-08T22:11:27.477Z,1683583887.477 [DAT](INFO): set transmit power to 8
2023-05-08T22:11:27.477Z,1683583887.477 [DAT](INFO): setting local address to 8
2023-05-08T22:11:27.728Z,1683583887.728 [DAT](INFO): DAT read: user:4>

2023-05-08T22:11:27.729Z,1683583887.729 [DAT](INFO): DAT read: LocalAddr       | 8           

2023-05-08T22:11:27.729Z,1683583887.729 [DAT](INFO): set local address to 8
2023-05-08T22:11:27.730Z,1683583887.730 [DAT](INFO): Setting time to: 22:11:27 And date to:5/8/2023
2023-05-08T22:11:27.980Z,1683583887.980 [DAT](INFO): DAT read: user:5>

2023-05-08T22:11:27.981Z,1683583887.981 [DAT](INFO): DAT read: Mon May 8, 2023  22:11:27  

2023-05-08T22:11:27.981Z,1683583887.981 [DAT](INFO): Local DAT time set to Mon May 8, 2023  22:11:27  

2023-05-08T22:11:51.588Z,1683583911.588 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:11:51.588Z,1683583911.588 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 7
2023-05-08T22:11:51.588Z,1683583911.588 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:11:51.599Z,1683583911.599 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:11:52.010Z,1683583912.010 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:11:52.010Z,1683583912.010 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 7
2023-05-08T22:13:52.775Z,1683584032.775 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:13:52.775Z,1683584032.775 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 8
2023-05-08T22:13:52.776Z,1683584032.776 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:13:52.791Z,1683584032.791 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:13:53.196Z,1683584033.196 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:13:53.196Z,1683584033.196 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 8
2023-05-08T22:14:27.808Z,1683584067.808 [DAT](INFO): DAT read: user:6>Lowpower

2023-05-08T22:14:27.809Z,1683584067.809 [DAT](DEBUG): Re-entering command mode due to deviceResponse_: user:6>Lowpower

2023-05-08T22:14:45.697Z,1683584085.697 [Default:CheckIn:Read_GPS](INFO): Timed out from 2023-05-08T22:09:45.5Z
2023-05-08T22:14:45.697Z,1683584085.697 [Default:CheckIn:Read_GPS] Stopped
2023-05-08T22:14:45.697Z,1683584085.697 [Default:CheckIn:Read_Iridium] Running Loop=1
2023-05-08T22:14:46.103Z,1683584086.103 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2023-05-08T22:14:52.668Z,1683584092.668 [DataOverHttps](INFO): Sending 439 bytes from file Logs/20230508T215733/Courier0004.lzma
2023-05-08T22:14:53.669Z,1683584093.669 [DataOverHttps](INFO): Moved sent file to Logs/20230508T215733/Courier0004.lzma.bak
2023-05-08T22:14:53.669Z,1683584093.669 [DataOverHttps](INFO): SBD MOMSN=18283048
2023-05-08T22:15:08.809Z,1683584108.809 [DataOverHttps](INFO): Sending 1113 bytes from file Logs/20230508T215733/Express0005.lzma
2023-05-08T22:15:09.809Z,1683584109.809 [DataOverHttps](INFO): Moved sent file to Logs/20230508T215733/Express0005.lzma.bak
2023-05-08T22:15:09.809Z,1683584109.809 [DataOverHttps](INFO): SBD MOMSN=18283052
2023-05-08T22:15:11.565Z,1683584111.565 [Default:CheckIn:Read_Iridium] Stopped
2023-05-08T22:15:11.565Z,1683584111.565 [Default:CheckIn:C.Wait] Running Loop=1
2023-05-08T22:15:11.565Z,1683584111.565 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2023-05-08T22:15:53.654Z,1683584153.654 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:15:53.654Z,1683584153.654 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 9
2023-05-08T22:15:53.654Z,1683584153.654 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:15:53.744Z,1683584153.744 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:15:54.081Z,1683584154.081 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:15:54.081Z,1683584154.081 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 9
2023-05-08T22:17:54.824Z,1683584274.824 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2023-05-08T22:17:54.824Z,1683584274.824 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 10
2023-05-08T22:17:54.824Z,1683584274.824 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2023-05-08T22:17:54.843Z,1683584274.843 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2023-05-08T22:17:55.243Z,1683584275.243 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2023-05-08T22:17:55.243Z,1683584275.243 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 10
2023-05-08T22:18:08.938Z,1683584288.938 [CommandExec](IMPORTANT): got command restart system
2023-05-08T22:18:11.040Z,1683584291.040 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:11.040Z,1683584291.040 [CommandExec](INFO): Uninitializing the command executive.
2023-05-08T22:18:11.040Z,1683584291.040 [CommandExec](INFO): Uninitializing the command scheduler.
2023-05-08T22:18:11.040Z,1683584291.040 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.232Z,1683584291.232 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2023-05-08T22:18:11.232Z,1683584291.232 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2023-05-08T22:18:11.232Z,1683584291.232 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.233Z,1683584291.233 [NavChartDb](INFO): Join timeout helper Thread ID is 7698
2023-05-08T22:18:11.619Z,1683584291.619 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:11.620Z,1683584291.620 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.623Z,1683584291.623 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler
2023-05-08T22:18:11.623Z,1683584291.623 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.624Z,1683584291.624 [DAT](INFO): Join timeout helper Thread ID is 7699
2023-05-08T22:18:11.707Z,1683584291.707 [DAT](INFO): Powering down
2023-05-08T22:18:11.781Z,1683584291.781 [DAT ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:11.781Z,1683584291.781 [DAT](INFO): Powering down
2023-05-08T22:18:11.782Z,1683584291.782 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.787Z,1683584291.787 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2023-05-08T22:18:11.787Z,1683584291.787 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.788Z,1683584291.788 [Radio_Surface](INFO): Join timeout helper Thread ID is 7700
2023-05-08T22:18:11.915Z,1683584291.915 [Radio_Surface](INFO): Powering down
2023-05-08T22:18:11.916Z,1683584291.916 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:11.917Z,1683584291.917 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.931Z,1683584291.931 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler
2023-05-08T22:18:11.931Z,1683584291.931 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:11.932Z,1683584291.932 [Onboard](INFO): Join timeout helper Thread ID is 7701
2023-05-08T22:18:15.335Z,1683584295.335 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:15.336Z,1683584295.336 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.343Z,1683584295.343 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2023-05-08T22:18:15.343Z,1683584295.343 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.344Z,1683584295.344 [DataOverHttps](INFO): Join timeout helper Thread ID is 7702
2023-05-08T22:18:15.739Z,1683584295.739 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:15.744Z,1683584295.744 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.752Z,1683584295.752 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler
2023-05-08T22:18:15.752Z,1683584295.752 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.753Z,1683584295.753 [BackseatComponent](INFO): Join timeout helper Thread ID is 7703
2023-05-08T22:18:15.755Z,1683584295.755 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:15.756Z,1683584295.756 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.772Z,1683584295.772 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2023-05-08T22:18:15.772Z,1683584295.772 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.772Z,1683584295.772 [logger](INFO): Join timeout helper Thread ID is 7704
2023-05-08T22:18:15.787Z,1683584295.787 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:15.787Z,1683584295.787 [logger ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.804Z,1683584295.804 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2023-05-08T22:18:15.804Z,1683584295.804 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.804Z,1683584295.804 [CommandLine](INFO): Join timeout helper Thread ID is 7705
2023-05-08T22:18:15.879Z,1683584295.879 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:15.880Z,1683584295.880 [CommandLine ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.884Z,1683584295.884 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler
2023-05-08T22:18:15.885Z,1683584295.885 [CommandExec ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.885Z,1683584295.885 [CommandExec](INFO): Join timeout helper Thread ID is 7706
2023-05-08T22:18:15.886Z,1683584295.886 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2023-05-08T22:18:15.886Z,1683584295.886 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:15.887Z,1683584295.887 [controlThread](INFO): Join timeout helper Thread ID is 7707
2023-05-08T22:18:16.219Z,1683584296.219 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2023-05-08T22:18:16.220Z,1683584296.220 [controlThread](DEBUG): Uninitializing ControlThread
2023-05-08T22:18:16.220Z,1683584296.220 [NAL9602](INFO): Powering down
2023-05-08T22:18:16.224Z,1683584296.224 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2023-05-08T22:18:16.224Z,1683584296.224 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2023-05-08T22:18:16.225Z,1683584296.225 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2023-05-08T22:18:16.225Z,1683584296.225 [MissionManager](INFO): Uninitializing Mission Default
2023-05-08T22:18:16.225Z,1683584296.225 [Default] Stopped
2023-05-08T22:18:16.225Z,1683584296.225 [Default](DEBUG): Aggregate::uninitialize Default
2023-05-08T22:18:16.225Z,1683584296.225 [Default:B.GoToSurface] Stopped
2023-05-08T22:18:16.225Z,1683584296.225 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2023-05-08T22:18:16.225Z,1683584296.225 [Default:CheckIn] Stopped
2023-05-08T22:18:16.226Z,1683584296.226 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2023-05-08T22:18:16.226Z,1683584296.226 [Default:CheckIn:C.Wait] Stopped
2023-05-08T22:18:16.226Z,1683584296.226 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2023-05-08T22:18:16.228Z,1683584296.228 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2023-05-08T22:18:16.229Z,1683584296.229 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2023-05-08T22:18:16.229Z,1683584296.229 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2023-05-08T22:18:16.229Z,1683584296.229 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2023-05-08T22:18:16.229Z,1683584296.229 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2023-05-08T22:18:16.230Z,1683584296.230 [BuoyancyServo](INFO): Powering down
2023-05-08T22:18:16.243Z,1683584296.243 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2023-05-08T22:18:16.244Z,1683584296.244 [ElevatorServo](INFO): Powering down
2023-05-08T22:18:16.245Z,1683584296.245 [MassServo](DEBUG): Uninitialize Mass Servo.
2023-05-08T22:18:16.245Z,1683584296.245 [MassServo](INFO): Powering down
2023-05-08T22:18:16.246Z,1683584296.246 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2023-05-08T22:18:16.246Z,1683584296.246 [RudderServo](INFO): Powering down
2023-05-08T22:18:16.247Z,1683584296.247 [ThrusterHE](DEBUG): Uninitialize Thruster Servo.
2023-05-08T22:18:16.247Z,1683584296.247 [ThrusterHE](INFO): Powering down
2023-05-08T22:18:16.248Z,1683584296.248 [SBIT](DEBUG): Uninitialize SBIT Component.
2023-05-08T22:18:16.248Z,1683584296.248 [IBIT](DEBUG): Uninitialize IBIT Component.
2023-05-08T22:18:16.248Z,1683584296.248 [CBIT](DEBUG): Uninitialize CBIT Component.
2023-05-08T22:18:16.249Z,1683584296.249 [CBIT](DEBUG): Powering off loads.
2023-05-08T22:18:16.259Z,1683584296.259 [CBIT](DEBUG): Disabling WDT.
2023-05-08T22:18:16.271Z,1683584296.271 [CBIT](DEBUG): Opening all GF detection circuits.
2023-05-08T22:18:16.272Z,1683584296.272 [controlThread ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.347Z,1683584296.347 [DAT ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.352Z,1683584296.352 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.354Z,1683584296.354 [Onboard ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.361Z,1683584296.361 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.405Z,1683584296.405 [BackseatComponent ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.578Z,1683584296.578 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2023-05-08T22:18:16.628Z,1683584296.628 [logger ThreadHandler](INFO): Thread cancelled.