2022-05-11T00:13:29.106Z,1652228009.106 [Supervisor](DEBUG): Initializing supervisor. 2022-05-11T00:13:29.111Z,1652228009.111 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2022-05-11T00:13:29.111Z,1652228009.111 [SyncHandler](INFO): Protected caller Thread ID is 6268 2022-05-11T00:13:29.111Z,1652228009.111 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2022-05-11T00:13:29.112Z,1652228009.112 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2022-05-11T00:13:29.113Z,1652228009.113 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 6269 2022-05-11T00:13:29.117Z,1652228009.117 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2022-05-11T00:13:29.135Z,1652228009.135 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread. 2022-05-11T00:13:29.136Z,1652228009.136 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2022-05-11T00:13:29.136Z,1652228009.136 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 6270 2022-05-11T00:13:29.140Z,1652228009.140 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2022-05-11T00:13:29.141Z,1652228009.141 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2022-05-11T00:13:29.142Z,1652228009.142 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 6271 2022-05-11T00:13:29.144Z,1652228009.144 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2022-05-11T00:13:29.145Z,1652228009.145 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0 2022-05-11T00:13:29.145Z,1652228009.145 [logger ThreadHandler](INFO): Protected caller Thread ID is 6272 2022-05-11T00:13:29.149Z,1652228009.149 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2022-05-11T00:13:29.149Z,1652228009.149 [Supervisor](INFO): Looking for Config files in directory: Config/ 2022-05-11T00:13:29.151Z,1652228009.151 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2022-05-11T00:13:29.461Z,1652228009.461 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2022-05-11T00:13:29.462Z,1652228009.462 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2022-05-11T00:13:30.098Z,1652228010.098 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2022-05-11T00:13:30.098Z,1652228010.098 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2022-05-11T00:13:30.203Z,1652228010.203 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2022-05-11T00:13:30.204Z,1652228010.204 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2022-05-11T00:13:30.748Z,1652228010.748 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2022-05-11T00:13:30.748Z,1652228010.748 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2022-05-11T00:13:30.842Z,1652228010.842 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2022-05-11T00:13:30.843Z,1652228010.843 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2022-05-11T00:13:30.925Z,1652228010.925 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2022-05-11T00:13:31.288Z,1652228011.288 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2022-05-11T00:13:31.289Z,1652228011.289 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2022-05-11T00:13:31.505Z,1652228011.505 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2022-05-11T00:13:31.505Z,1652228011.505 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2022-05-11T00:13:31.629Z,1652228011.629 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2022-05-11T00:13:31.630Z,1652228011.630 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg 2022-05-11T00:13:31.871Z,1652228011.871 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock 2022-05-11T00:13:31.872Z,1652228011.872 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2022-05-11T00:13:32.342Z,1652228012.342 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2022-05-11T00:13:32.342Z,1652228012.342 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2022-05-11T00:13:32.700Z,1652228012.700 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2022-05-11T00:13:32.700Z,1652228012.700 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2022-05-11T00:13:32.778Z,1652228012.778 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2022-05-11T00:13:33.038Z,1652228013.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2022-05-11T00:13:33.039Z,1652228013.039 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2022-05-11T00:13:33.257Z,1652228013.257 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2022-05-11T00:13:33.258Z,1652228013.258 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2022-05-11T00:13:33.544Z,1652228013.544 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2022-05-11T00:13:33.546Z,1652228013.546 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/ 2022-05-11T00:13:33.547Z,1652228013.547 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Control.cfg 2022-05-11T00:13:33.653Z,1652228013.653 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Sensor.cfg 2022-05-11T00:13:33.807Z,1652228013.807 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Simulator.cfg 2022-05-11T00:13:34.078Z,1652228014.078 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/secure.cfg 2022-05-11T00:13:34.384Z,1652228014.384 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Servo.cfg 2022-05-11T00:13:34.587Z,1652228014.587 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/vehicle.cfg 2022-05-11T00:13:34.803Z,1652228014.803 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Battery.cfg 2022-05-11T00:13:35.062Z,1652228015.062 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2022-05-11T00:13:35.062Z,1652228015.062 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Science.cfg 2022-05-11T00:13:35.191Z,1652228015.191 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/logger.cfg 2022-05-11T00:13:35.282Z,1652228015.282 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/BIT.cfg 2022-05-11T00:13:35.384Z,1652228015.384 [Supervisor](INFO): Opening Config file at: Config/lrauv-brizo/Navigation.cfg 2022-05-11T00:13:35.485Z,1652228015.485 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-brizo/root/ 2022-05-11T00:13:35.486Z,1652228015.486 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2022-05-11T00:13:35.494Z,1652228015.494 [Module Loader](DEBUG): Loading Module at Modules/Dock.so 2022-05-11T00:13:35.592Z,1652228015.592 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking) 2022-05-11T00:13:35.593Z,1652228015.593 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2022-05-11T00:13:35.603Z,1652228015.603 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2022-05-11T00:13:35.604Z,1652228015.604 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2022-05-11T00:13:35.658Z,1652228015.658 [DepthRateCalculator] Loaded 2022-05-11T00:13:35.658Z,1652228015.658 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2022-05-11T00:13:35.663Z,1652228015.663 [PitchRateCalculator] Loaded 2022-05-11T00:13:35.664Z,1652228015.664 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2022-05-11T00:13:35.674Z,1652228015.674 [SpeedCalculator] Loaded 2022-05-11T00:13:35.674Z,1652228015.674 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2022-05-11T00:13:35.679Z,1652228015.679 [YawRateCalculator] Loaded 2022-05-11T00:13:35.679Z,1652228015.679 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2022-05-11T00:13:35.699Z,1652228015.699 [ElevatorOffsetCalculator] Loaded 2022-05-11T00:13:35.700Z,1652228015.700 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2022-05-11T00:13:35.700Z,1652228015.700 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2022-05-11T00:13:35.701Z,1652228015.701 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2022-05-11T00:13:35.752Z,1652228015.752 [VerticalControl](DEBUG): Construct VerticalControl. 2022-05-11T00:13:35.812Z,1652228015.812 [VerticalControl] Loaded 2022-05-11T00:13:35.812Z,1652228015.812 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2022-05-11T00:13:35.814Z,1652228015.814 [HorizontalControl](DEBUG): Construct HorizontalControl. 2022-05-11T00:13:35.853Z,1652228015.853 [HorizontalControl] Loaded 2022-05-11T00:13:35.853Z,1652228015.853 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2022-05-11T00:13:35.855Z,1652228015.855 [SpeedControl](DEBUG): Construct SpeedControl. 2022-05-11T00:13:35.858Z,1652228015.858 [SpeedControl] Loaded 2022-05-11T00:13:35.858Z,1652228015.858 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2022-05-11T00:13:35.861Z,1652228015.861 [LoopControl](DEBUG): Construct LoopControl. 2022-05-11T00:13:35.861Z,1652228015.861 [LoopControl] Loaded 2022-05-11T00:13:35.861Z,1652228015.861 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2022-05-11T00:13:35.862Z,1652228015.862 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2022-05-11T00:13:35.862Z,1652228015.862 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2022-05-11T00:13:35.970Z,1652228015.970 [DeadReckonUsingMultipleVelocitySources] Loaded 2022-05-11T00:13:35.971Z,1652228015.971 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2022-05-11T00:13:35.984Z,1652228015.984 [NavChart] Loaded 2022-05-11T00:13:35.984Z,1652228015.984 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2022-05-11T00:13:35.990Z,1652228015.990 [UniversalFixResidualReporter] Loaded 2022-05-11T00:13:35.990Z,1652228015.990 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2022-05-11T00:13:35.991Z,1652228015.991 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2022-05-11T00:13:35.991Z,1652228015.991 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2022-05-11T00:13:36.097Z,1652228016.097 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2022-05-11T00:13:36.097Z,1652228016.097 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2022-05-11T00:13:36.487Z,1652228016.487 [AHRS_M2] Loaded 2022-05-11T00:13:36.488Z,1652228016.488 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2022-05-11T00:13:36.522Z,1652228016.522 [BackseatComponent] Loaded 2022-05-11T00:13:36.522Z,1652228016.522 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread. 2022-05-11T00:13:36.523Z,1652228016.523 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408DD4E0 2022-05-11T00:13:36.524Z,1652228016.524 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 6355 2022-05-11T00:13:36.526Z,1652228016.526 [LcmUniversalReporter] Loaded 2022-05-11T00:13:36.526Z,1652228016.526 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread. 2022-05-11T00:13:36.599Z,1652228016.599 [DataOverHttps] Loaded 2022-05-11T00:13:36.599Z,1652228016.599 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2022-05-11T00:13:36.600Z,1652228016.600 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4090D4E0 2022-05-11T00:13:36.600Z,1652228016.600 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 6356 2022-05-11T00:13:36.620Z,1652228016.620 [Depth_Keller] Loaded 2022-05-11T00:13:36.620Z,1652228016.620 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2022-05-11T00:13:36.625Z,1652228016.625 [DropWeight] Loaded 2022-05-11T00:13:36.625Z,1652228016.625 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2022-05-11T00:13:36.661Z,1652228016.661 [DVL_micro] Loaded 2022-05-11T00:13:36.661Z,1652228016.661 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2022-05-11T00:13:36.719Z,1652228016.719 [NAL9602] Loaded 2022-05-11T00:13:36.719Z,1652228016.719 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2022-05-11T00:13:36.747Z,1652228016.747 [Onboard] Loaded 2022-05-11T00:13:36.748Z,1652228016.748 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread. 2022-05-11T00:13:36.749Z,1652228016.749 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 4093D4E0 2022-05-11T00:13:36.749Z,1652228016.749 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 6357 2022-05-11T00:13:36.761Z,1652228016.761 [Power24vConverter] Loaded 2022-05-11T00:13:36.761Z,1652228016.761 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread. 2022-05-11T00:13:36.773Z,1652228016.773 [Radio_Surface] Loaded 2022-05-11T00:13:36.774Z,1652228016.774 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2022-05-11T00:13:36.774Z,1652228016.774 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4096D4E0 2022-05-11T00:13:36.775Z,1652228016.775 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 6358 2022-05-11T00:13:36.859Z,1652228016.859 [DAT] Loaded 2022-05-11T00:13:36.860Z,1652228016.860 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread. 2022-05-11T00:13:36.861Z,1652228016.861 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 4099D4E0 2022-05-11T00:13:36.861Z,1652228016.861 [DAT ThreadHandler](INFO): Protected caller Thread ID is 6359 2022-05-11T00:13:36.862Z,1652228016.862 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2022-05-11T00:13:36.862Z,1652228016.862 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2022-05-11T00:13:36.984Z,1652228016.984 [BuoyancyServo] Loaded 2022-05-11T00:13:36.985Z,1652228016.985 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2022-05-11T00:13:37.004Z,1652228017.004 [ElevatorServo] Loaded 2022-05-11T00:13:37.004Z,1652228017.004 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2022-05-11T00:13:37.023Z,1652228017.023 [MassServo] Loaded 2022-05-11T00:13:37.023Z,1652228017.023 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2022-05-11T00:13:37.041Z,1652228017.041 [RudderServo] Loaded 2022-05-11T00:13:37.041Z,1652228017.041 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2022-05-11T00:13:37.056Z,1652228017.056 [ThrusterHE] Loaded 2022-05-11T00:13:37.056Z,1652228017.056 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread. 2022-05-11T00:13:37.057Z,1652228017.057 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2022-05-11T00:13:37.057Z,1652228017.057 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2022-05-11T00:13:37.114Z,1652228017.114 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2022-05-11T00:13:37.115Z,1652228017.115 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2022-05-11T00:13:37.141Z,1652228017.141 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2022-05-11T00:13:37.142Z,1652228017.142 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2022-05-11T00:13:37.449Z,1652228017.449 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2022-05-11T00:13:37.450Z,1652228017.450 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2022-05-11T00:13:37.617Z,1652228017.617 [CTD_Seabird] Loaded 2022-05-11T00:13:37.617Z,1652228017.617 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2022-05-11T00:13:37.619Z,1652228017.619 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40B394E0 2022-05-11T00:13:37.619Z,1652228017.619 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 6360 2022-05-11T00:13:37.650Z,1652228017.650 [ESPComponent] Loaded 2022-05-11T00:13:37.651Z,1652228017.651 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2022-05-11T00:13:37.670Z,1652228017.670 [PAR_Licor] Loaded 2022-05-11T00:13:37.670Z,1652228017.670 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2022-05-11T00:13:37.701Z,1652228017.701 [WetLabsBB2FL] Loaded 2022-05-11T00:13:37.701Z,1652228017.701 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2022-05-11T00:13:37.702Z,1652228017.702 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40B694E0 2022-05-11T00:13:37.702Z,1652228017.702 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 6361 2022-05-11T00:13:37.703Z,1652228017.703 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2022-05-11T00:13:37.704Z,1652228017.704 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2022-05-11T00:13:37.843Z,1652228017.843 [SBIT](DEBUG): Construct Startup Built In Test. 2022-05-11T00:13:37.852Z,1652228017.852 [SBIT] Loaded 2022-05-11T00:13:37.852Z,1652228017.852 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2022-05-11T00:13:37.855Z,1652228017.855 [IBIT](DEBUG): Construct Initiated Built In Test. 2022-05-11T00:13:37.869Z,1652228017.869 [IBIT] Loaded 2022-05-11T00:13:37.869Z,1652228017.869 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2022-05-11T00:13:37.874Z,1652228017.874 [CBIT](DEBUG): Construct Continuous Built In Test. 2022-05-11T00:13:38.099Z,1652228018.099 [CBIT] Loaded 2022-05-11T00:13:38.100Z,1652228018.100 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2022-05-11T00:13:38.100Z,1652228018.100 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2022-05-11T00:13:38.106Z,1652228018.106 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2022-05-11T00:13:38.109Z,1652228018.109 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2022-05-11T00:13:38.119Z,1652228018.119 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2022-05-11T00:13:38.120Z,1652228018.120 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BD74E0 2022-05-11T00:13:38.121Z,1652228018.121 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 6362 2022-05-11T00:13:38.125Z,1652228018.125 [Supervisor](INFO): Main Thread ID is 6267 2022-05-11T00:13:38.125Z,1652228018.125 [Supervisor](DEBUG): Running supervisor. 2022-05-11T00:13:38.126Z,1652228018.126 [CommandExec ThreadHandler](INFO): Handler Thread ID is 6363 2022-05-11T00:13:38.126Z,1652228018.126 [CommandExec](INFO): Initializing the command executive. 2022-05-11T00:13:38.128Z,1652228018.128 [CommandLine ThreadHandler](INFO): Handler Thread ID is 6364 2022-05-11T00:13:38.134Z,1652228018.134 [controlThread ThreadHandler](INFO): Handler Thread ID is 6365 2022-05-11T00:13:38.135Z,1652228018.135 [controlThread](DEBUG): Initializing ControlThread 2022-05-11T00:13:38.136Z,1652228018.136 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2022-05-11T00:13:38.136Z,1652228018.136 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2022-05-11T00:13:38.136Z,1652228018.136 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2022-05-11T00:13:38.137Z,1652228018.137 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2022-05-11T00:13:38.137Z,1652228018.137 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2022-05-11T00:13:38.138Z,1652228018.138 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2022-05-11T00:13:38.139Z,1652228018.139 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2022-05-11T00:13:38.140Z,1652228018.140 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2022-05-11T00:13:38.141Z,1652228018.141 [LoopControl](DEBUG): Initialize LoopControlComponent. 2022-05-11T00:13:38.141Z,1652228018.141 [NavChart](DEBUG): Initialize NavChart Navigation. 2022-05-11T00:13:38.142Z,1652228018.142 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2022-05-11T00:13:38.148Z,1652228018.148 [SBIT](INFO): Initialize SBIT Component. 2022-05-11T00:13:38.149Z,1652228018.149 [SBIT](IMPORTANT): git: 2022-04-25-37-g2a944135f 2022-05-11T00:13:38.149Z,1652228018.149 [SBIT](INFO): git hash: 2a944135f4713de004d013a6b17eee164aec7a5a 2022-05-11T00:13:38.149Z,1652228018.149 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2022-05-11T00:13:38.150Z,1652228018.150 [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 2022-05-11T00:13:38.151Z,1652228018.151 [SBIT](INFO): Beginning SBIT in 26.000000 seconds. 2022-05-11T00:13:38.152Z,1652228018.152 [IBIT](INFO): Initialize IBIT Component. 2022-05-11T00:13:38.153Z,1652228018.153 [CBIT](DEBUG): Initialize CBIT Component. 2022-05-11T00:13:38.154Z,1652228018.154 [logger ThreadHandler](INFO): Handler Thread ID is 6366 2022-05-11T00:13:38.164Z,1652228018.164 [CBIT](DEBUG): Initialized mux pins. 2022-05-11T00:13:38.164Z,1652228018.164 [CBIT](DEBUG): Initializing the watchdog timer. 2022-05-11T00:13:38.172Z,1652228018.172 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 6367 2022-05-11T00:13:38.184Z,1652228018.184 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 6368 2022-05-11T00:13:38.185Z,1652228018.185 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2022-05-11T00:13:38.188Z,1652228018.188 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2022-05-11T00:13:38.189Z,1652228018.189 [CBIT](DEBUG): Initializing heartbeat. 2022-05-11T00:13:38.197Z,1652228018.197 [Onboard ThreadHandler](INFO): Handler Thread ID is 6369 2022-05-11T00:13:38.220Z,1652228018.220 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 6370 2022-05-11T00:13:38.232Z,1652228018.232 [DAT ThreadHandler](INFO): Handler Thread ID is 6371 2022-05-11T00:13:38.233Z,1652228018.233 [DAT](INFO): Powering up 2022-05-11T00:13:38.233Z,1652228018.233 [DAT](DEBUG): Initializing DAT. 2022-05-11T00:13:38.237Z,1652228018.237 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 6373 2022-05-11T00:13:38.238Z,1652228018.238 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2022-05-11T00:13:38.241Z,1652228018.241 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 6375 2022-05-11T00:13:38.244Z,1652228018.244 [WetLabsBB2FL](INFO): Powering up 2022-05-11T00:13:38.245Z,1652228018.245 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 6377 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2022-05-11T00:13:38.249Z,1652228018.249 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2022-05-11T00:13:38.250Z,1652228018.250 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2022-05-11T00:13:38.250Z,1652228018.250 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2022-05-11T00:13:38.250Z,1652228018.250 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000 2022-05-11T00:13:38.250Z,1652228018.250 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000 2022-05-11T00:13:38.260Z,1652228018.260 [CBIT](DEBUG): Deactivating GF circuits. 2022-05-11T00:13:38.260Z,1652228018.260 [CBIT](DEBUG): Deactivating emergency mode. 2022-05-11T00:13:38.296Z,1652228018.296 [CBIT](DEBUG): Backplane powered. 2022-05-11T00:13:38.297Z,1652228018.297 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml 2022-05-11T00:13:38.310Z,1652228018.310 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2022-05-11T00:13:38.329Z,1652228018.329 [MissionManager](DEBUG): 2022-05-11T00:13:38.330Z,1652228018.330 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml 2022-05-11T00:13:38.402Z,1652228018.402 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2022-05-11T00:13:38.403Z,1652228018.403 [Default:A.Wait](DEBUG): Construct Wait. 2022-05-11T00:13:38.405Z,1652228018.405 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2022-05-11T00:13:38.448Z,1652228018.448 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2022-05-11T00:13:38.451Z,1652228018.451 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2022-05-11T00:13:38.489Z,1652228018.489 [Default:E.Execute](DEBUG): Construct Execute. 2022-05-11T00:13:38.509Z,1652228018.509 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2022-05-11T00:13:38.513Z,1652228018.513 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Power24vConverter,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter, 2022-05-11T00:13:38.518Z,1652228018.518 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2022-05-11T00:13:38.573Z,1652228018.573 [Power24vConverter](INFO): Powering up. 2022-05-11T00:13:38.622Z,1652228018.622 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2022-05-11T00:13:38.624Z,1652228018.624 [Radio_Surface](INFO): Powering up 2022-05-11T00:13:38.628Z,1652228018.628 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2022-05-11T00:13:38.630Z,1652228018.630 [ElevatorServo](DEBUG): Initializing EZServoServo. 2022-05-11T00:13:38.636Z,1652228018.636 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2022-05-11T00:13:38.637Z,1652228018.637 [MassServo](DEBUG): Initializing EZServoServo. 2022-05-11T00:13:38.652Z,1652228018.652 [MassServo](DEBUG): Initializing MassServo. 2022-05-11T00:13:38.653Z,1652228018.653 [RudderServo](DEBUG): Initializing EZServoServo. 2022-05-11T00:13:38.664Z,1652228018.664 [RudderServo](DEBUG): Initializing RudderServo. 2022-05-11T00:13:38.665Z,1652228018.665 [ThrusterHE](DEBUG): Initializing EZServoServo. 2022-05-11T00:13:38.672Z,1652228018.672 [ThrusterHE](DEBUG): Initializing ThrusterHE. 2022-05-11T00:13:38.961Z,1652228018.961 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2022-05-11T00:13:38.961Z,1652228018.961 [DropWeight] Hardware Fault, FailCount= 1 2022-05-11T00:13:38.961Z,1652228018.961 [DropWeight](ERROR): Hardware Fault 2022-05-11T00:13:39.052Z,1652228019.052 [CommandExec](FAULT): Scheduling is paused 2022-05-11T00:13:39.052Z,1652228019.052 [CBIT](INFO): Critical error at 20220511T001338 2022-05-11T00:13:39.052Z,1652228019.052 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2022-05-11T00:13:39.055Z,1652228019.055 [CBIT](ERROR): Hardware Fault in component: DropWeight 2022-05-11T00:13:39.055Z,1652228019.055 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2022-05-11T00:13:39.393Z,1652228019.393 [CBIT](INFO): Critical error at 20220511T001339 2022-05-11T00:13:40.856Z,1652228020.856 [WetLabsBB2FL](INFO): Powering down 2022-05-11T00:13:44.285Z,1652228024.285 [ThrusterHE](ERROR): Zero Speed Commanded. 2022-05-11T00:13:45.268Z,1652228025.268 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit. 2022-05-11T00:13:51.091Z,1652228031.091 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004702 2022-05-11T00:13:52.598Z,1652228032.598 [DAT](INFO): commRate: 800 2022-05-11T00:13:54.664Z,1652228034.664 [DAT](INFO): entering command mode 2022-05-11T00:13:54.865Z,1652228034.865 [DAT](INFO): setting verbose to 3 2022-05-11T00:13:55.119Z,1652228035.119 [DAT](INFO): set verbose to 3 2022-05-11T00:13:55.119Z,1652228035.119 [DAT](INFO): setting DatVerbose to 27440 2022-05-11T00:13:55.369Z,1652228035.369 [DAT](INFO): set DatVerbose to 27440 2022-05-11T00:13:55.370Z,1652228035.370 [DAT](INFO): setting transmit power to 8 2022-05-11T00:13:55.621Z,1652228035.621 [DAT](INFO): set transmit power to 8 2022-05-11T00:13:55.622Z,1652228035.622 [DAT](INFO): setting local address to 8 2022-05-11T00:13:55.873Z,1652228035.873 [DAT](INFO): set local address to 8 2022-05-11T00:13:55.874Z,1652228035.874 [DAT](INFO): Setting time to: 0:13:55 And date to:5/11/2022 2022-05-11T00:13:56.125Z,1652228036.125 [DAT](INFO): Local DAT time set to Wed May 11, 2022 00:13:55 2022-05-11T00:14:04.914Z,1652228044.914 [SBIT](IMPORTANT): Beginning Startup BIT 2022-05-11T00:14:04.919Z,1652228044.919 [CBIT](IMPORTANT): Beginning ground fault scan 2022-05-11T00:14:06.810Z,1652228046.810 [NAL9602](INFO): Powering up NAL9602 2022-05-11T00:14:08.550Z,1652228048.550 [CommandExec](IMPORTANT): got command ! /etc/rc.d/init.d/settime restart 2022-05-11T00:14:09.505Z,1652228049.505 [CommandExec](IMPORTANT): settime stop or restart Setting hardware clock from system clock Wed May 11 00:14:10 2022 0.000000 seconds settime start or restart Setting clock frequency and tick values from nonvolatile memory. mode: 16386 -o offset: 0 -f frequency: 880700 maxerror: 16000000 esterror: 16000000 status: 64 (UNSYNC) -p timeconstant: 2 precision: 1 tolerance: 32768000 -t tick: 10000 time.tv_sec: 1652228049 time.tv_usec: 284706 return value: 5 (clock not synchronized) ping returned from NTP server: 216.239.35.4 44690 00850.664 43152.0 0.0 -2409832.7 122.1 880700 Time set from NTP server: 216.239.35.4 Setting hardware clock from system clock Wed May 11 00:14:09 2022 0.000000 seconds 2022-05-11T00:14:15.753Z,1652228055.753 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.024351 CHAN A1 (24V): 0.034750 CHAN A2 (12V): 0.000923 CHAN A3 (5V): -0.011847 CHAN B0 (3.3V): -0.003725 CHAN B1 (3.15aV): -0.003864 CHAN B2 (3.15bV): -0.003931 CHAN B3 (GND): -0.008167 OPEN: 0.005067 Full Scale: +/- 1 mA 2022-05-11T00:14:17.706Z,1652228057.706 [NAL9602](INFO): NAL9602 initialized 2022-05-11T00:14:55.114Z,1652228095.114 [CommandExec](IMPORTANT): got command ! /etc/rc.d/init.d/settime restart 2022-05-11T00:14:57.785Z,1652228097.785 [CommandExec](IMPORTANT): settime stop or restart Setting hardware clock from system clock Wed May 11 00:14:55 2022 0.000000 seconds settime start or restart Setting clock frequency and tick values from nonvolatile memory. mode: 16386 -o offset: 0 -f frequency: 880700 maxerror: 16000000 esterror: 16000000 status: 64 (UNSYNC) -p timeconstant: 2 precision: 1 tolerance: 32768000 -t tick: 10000 time.tv_sec: 1652228095 time.tv_usec: 429402 return value: 5 (clock not synchronized) ping returned from NTP server: 216.239.35.4 44690 00896.670 43231.0 0.0 21670.6 91.6 880700 Time set from NTP server: 216.239.35.4 Setting hardware clock from system clock Wed May 11 00:14:57 2022 0.000000 seconds 2022-05-11T00:14:58.197Z,1652228098.197 [SBIT](FAULT): Mass: EXPECTED:-0.001543 ACTUAL:-0.003024 2022-05-11T00:14:58.197Z,1652228098.197 [SBIT](FAULT): Control surface position failure. 2022-05-11T00:14:58.561Z,1652228098.561 [SBIT](CRITICAL): SBIT FAILED 2022-05-11T00:14:58.561Z,1652228098.561 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2022-05-11T00:14:58.562Z,1652228098.562 [SBIT](IMPORTANT): BuoyancyServo.limitLo=1750 count; 2022-05-11T00:14:58.562Z,1652228098.562 [SBIT](IMPORTANT): Express linearApproximation CBIT.ampHoursUsed 1.000000 ampere_hour; 2022-05-11T00:14:58.563Z,1652228098.563 [SBIT](IMPORTANT): Express linearApproximation CTD_Seabird.bin_median_sea_water_salinity 0.010000 practical_salinity_unit; 2022-05-11T00:14:58.563Z,1652228098.563 [SBIT](IMPORTANT): Express none WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water; 2022-05-11T00:14:58.563Z,1652228098.563 [SBIT](IMPORTANT): Express linearApproximation WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water 0.200000 microgram_per_liter; 2022-05-11T00:14:58.563Z,1652228098.563 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=275.139201 cubic_centimeter; 2022-05-11T00:14:58.563Z,1652228098.563 [SBIT](IMPORTANT): VerticalControl.massDefault=-1.542962 millimeter; 2022-05-11T00:14:58.565Z,1652228098.565 [CBIT](INFO): Critical error at 20220511T001458 2022-05-11T00:14:58.942Z,1652228098.942 [MissionManager](IMPORTANT): Started mission Startup 2022-05-11T00:14:58.942Z,1652228098.942 [Startup] Running Loop=1 2022-05-11T00:14:58.942Z,1652228098.942 [Startup](DEBUG): Aggregate::initialize Startup 2022-05-11T00:14:58.942Z,1652228098.942 [Startup:A.GoToSurface] Running Loop=1 2022-05-11T00:14:58.942Z,1652228098.942 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-05-11T00:14:58.943Z,1652228098.943 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-05-11T00:14:58.943Z,1652228098.943 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-05-11T00:14:58.944Z,1652228098.944 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-05-11T00:14:58.944Z,1652228098.944 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-05-11T00:14:58.945Z,1652228098.945 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-05-11T00:14:58.946Z,1652228098.946 [Startup:StartupSatComms] Running Loop=1 2022-05-11T00:14:58.946Z,1652228098.946 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2022-05-11T00:14:58.946Z,1652228098.946 [Startup:StartupSatComms:A] Running Loop=1 2022-05-11T00:14:59.339Z,1652228099.339 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2022-05-11T00:15:02.891Z,1652228102.891 [CommandExec](IMPORTANT): got command ! /etc/rc.d/init.d/settime restart 2022-05-11T00:15:05.641Z,1652228105.641 [CommandExec](IMPORTANT): settime stop or restart Setting hardware clock from system clock Wed May 11 00:15:03 2022 0.000000 seconds settime start or restart Setting clock frequency and tick values from nonvolatile memory. mode: 16386 -o offset: 0 -f frequency: 880700 maxerror: 16000000 esterror: 16000000 status: 64 (UNSYNC) -p timeconstant: 2 precision: 1 tolerance: 32768000 -t tick: 10000 time.tv_sec: 1652228103 time.tv_usec: 202663 return value: 5 (clock not synchronized) ping returned from NTP server: 216.239.35.4 44690 00904.380 43084.0 0.0 21727.6 122.1 880700 Time set from NTP server: 216.239.35.4 Setting hardware clock from system clock Wed May 11 00:15:05 2022 0.000000 seconds 2022-05-11T00:15:59.171Z,1652228159.171 [Startup:StartupSatComms:A](INFO): Timed out from 2022-05-11T00:14:58.9Z 2022-05-11T00:15:59.171Z,1652228159.171 [Startup:StartupSatComms:A] Stopped 2022-05-11T00:15:59.171Z,1652228159.171 [Startup:StartupSatComms:B] Running Loop=1 2022-05-11T00:15:59.567Z,1652228159.567 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-05-11T00:16:01.731Z,1652228161.731 [Startup:StartupSatComms:B] Stopped 2022-05-11T00:16:01.731Z,1652228161.731 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2022-05-11T00:16:01.731Z,1652228161.731 [Startup:StartupSatComms] Stopped 2022-05-11T00:16:01.731Z,1652228161.731 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2022-05-11T00:16:01.732Z,1652228161.732 [Startup](INFO): Completed Startup 2022-05-11T00:16:01.732Z,1652228161.732 [MissionManager](INFO): Startup is completed. 2022-05-11T00:16:01.739Z,1652228161.739 [MissionManager](INFO): Uninitializing Mission Startup 2022-05-11T00:16:01.740Z,1652228161.740 [Startup] Stopped 2022-05-11T00:16:01.785Z,1652228161.785 [Startup](DEBUG): Aggregate::uninitialize Startup 2022-05-11T00:16:01.785Z,1652228161.785 [Startup:A.GoToSurface] Stopped 2022-05-11T00:16:01.785Z,1652228161.785 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-05-11T00:16:02.092Z,1652228162.092 [MissionManager](IMPORTANT): Started mission Default 2022-05-11T00:16:02.093Z,1652228162.093 [Default] Running Loop=1 2022-05-11T00:16:02.093Z,1652228162.093 [Default](DEBUG): Aggregate::initialize Default 2022-05-11T00:16:02.093Z,1652228162.093 [Default:B.GoToSurface] Running Loop=1 2022-05-11T00:16:02.093Z,1652228162.093 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2022-05-11T00:16:02.093Z,1652228162.093 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2022-05-11T00:16:02.094Z,1652228162.094 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2022-05-11T00:16:02.094Z,1652228162.094 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2022-05-11T00:16:02.094Z,1652228162.094 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2022-05-11T00:16:02.094Z,1652228162.094 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2022-05-11T00:16:02.095Z,1652228162.095 [Default:A.Wait] Running Loop=1 2022-05-11T00:16:02.095Z,1652228162.095 [Default:A.Wait](DEBUG): Initialize Wait Component. 2022-05-11T00:16:11.393Z,1652228171.393 [DataOverHttps](INFO): Sending 266 bytes from file Logs/20220511T001329/Courier0000.lzma 2022-05-11T00:16:12.395Z,1652228172.395 [DataOverHttps](INFO): Moved sent file to Logs/20220511T001329/Courier0000.lzma.bak 2022-05-11T00:16:12.395Z,1652228172.395 [DataOverHttps](INFO): SBD MOMSN=16735349 2022-05-11T00:16:15.370Z,1652228175.370 [Default:A.Wait](INFO): Done Waiting. 2022-05-11T00:16:15.370Z,1652228175.370 [Default:A.Wait] Stopped 2022-05-11T00:16:15.371Z,1652228175.371 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2022-05-11T00:16:15.778Z,1652228175.778 [Default:CheckIn] Running Loop=1 2022-05-11T00:16:15.778Z,1652228175.778 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-11T00:16:15.778Z,1652228175.778 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-11T00:16:16.194Z,1652228176.194 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2022-05-11T00:16:38.418Z,1652228198.418 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2022-05-11T00:16:38.418Z,1652228198.418 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-05-11T00:16:38.428Z,1652228198.428 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-05-11T00:16:38.834Z,1652228198.834 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-05-11T00:16:38.834Z,1652228198.834 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2022-05-11T00:16:43.810Z,1652228203.810 [CommandExec](IMPORTANT): got command burn on 2022-05-11T00:16:43.810Z,1652228203.810 [CommandExec](IMPORTANT): Activating dropweight wire 2022-05-11T00:16:50.786Z,1652228210.786 [CommandExec](IMPORTANT): got command burn off 2022-05-11T00:16:50.786Z,1652228210.786 [CommandExec](IMPORTANT): Deactivating dropweight wire 2022-05-11T00:19:20.798Z,1652228360.798 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-11T00:19:39.406Z,1652228379.406 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2022-05-11T00:19:39.406Z,1652228379.406 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-05-11T00:19:39.416Z,1652228379.416 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-05-11T00:19:39.830Z,1652228379.830 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-05-11T00:19:39.830Z,1652228379.830 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2022-05-11T00:20:14.902Z,1652228414.902 [DAT](INFO): unknown deviceResponse_: Acoustic Wakeup 2022-05-11T00:20:14.903Z,1652228414.903 [DAT](INFO): commRate: 800 2022-05-11T00:20:15.658Z,1652228415.658 [DAT](INFO): unknown deviceResponse_: Lowpower 2022-05-11T00:21:15.983Z,1652228475.983 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-05-11T00:16:15.8Z 2022-05-11T00:21:15.983Z,1652228475.983 [Default:CheckIn:Read_GPS] Stopped 2022-05-11T00:21:15.983Z,1652228475.983 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-11T00:21:16.374Z,1652228476.374 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2022-05-11T00:21:26.048Z,1652228486.048 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20220511T001329/Courier0004.lzma 2022-05-11T00:21:27.051Z,1652228487.051 [DataOverHttps](INFO): Moved sent file to Logs/20220511T001329/Courier0004.lzma.bak 2022-05-11T00:21:27.051Z,1652228487.051 [DataOverHttps](INFO): SBD MOMSN=16735356 2022-05-11T00:21:49.201Z,1652228509.201 [DVL_micro](ERROR): Failed to parse: :WI,+00449,-00519,+00777,+00000,A 2022-05-11T00:21:54.452Z,1652228514.452 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2022-05-11T00:21:57.015Z,1652228517.015 [DataOverHttps](INFO): Sending 1432 bytes from file Logs/20220511T001329/Express0001.lzma 2022-05-11T00:21:58.015Z,1652228518.015 [DataOverHttps](INFO): Moved sent file to Logs/20220511T001329/Express0001.lzma.bak 2022-05-11T00:21:58.015Z,1652228518.015 [DataOverHttps](INFO): SBD MOMSN=16735360 2022-05-11T00:22:14.037Z,1652228534.037 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20220511T001329/Express0005.lzma 2022-05-11T00:22:15.038Z,1652228535.038 [DataOverHttps](INFO): Moved sent file to Logs/20220511T001329/Express0005.lzma.bak 2022-05-11T00:22:15.039Z,1652228535.039 [DataOverHttps](INFO): SBD MOMSN=16735386 2022-05-11T00:22:16.294Z,1652228536.294 [Default:CheckIn:Read_Iridium] Stopped 2022-05-11T00:22:16.294Z,1652228536.294 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-11T00:22:16.294Z,1652228536.294 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-11T00:22:40.535Z,1652228560.535 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2022-05-11T00:22:40.536Z,1652228560.536 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2022-05-11T00:22:40.554Z,1652228560.554 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2022-05-11T00:22:40.922Z,1652228560.922 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2022-05-11T00:22:40.922Z,1652228560.922 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2022-05-11T00:24:19.478Z,1652228659.478 [NAL9602](FAULT): GPS failed to acquire within timeout. 2022-05-11T00:24:19.479Z,1652228659.479 [NAL9602] Data Fault, FailCount= 1 2022-05-11T00:24:19.479Z,1652228659.479 [NAL9602](ERROR): Data Fault 2022-05-11T00:24:19.495Z,1652228659.495 [CBIT](ERROR): Data Fault in component: NAL9602 2022-05-11T00:24:19.892Z,1652228659.892 [NAL9602](INFO): Powering down 2022-05-11T00:24:20.714Z,1652228660.714 [CBIT](INFO): Clearing failed state for component NAL9602 2022-05-11T00:24:20.714Z,1652228660.714 [NAL9602] No Fault, FailCount= 1 2022-05-11T00:24:50.183Z,