2019-05-28T23:37:53.128Z,1559086673.128 [Supervisor](DEBUG): Initializing supervisor.
2019-05-28T23:37:53.130Z,1559086673.130 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-28T23:37:53.131Z,1559086673.131 [SyncHandler](INFO): Protected caller Thread ID is 807
2019-05-28T23:37:53.131Z,1559086673.131 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-28T23:37:53.132Z,1559086673.132 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-28T23:37:53.133Z,1559086673.133 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 808
2019-05-28T23:37:53.135Z,1559086673.135 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-28T23:37:53.147Z,1559086673.147 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-28T23:37:53.148Z,1559086673.148 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-28T23:37:53.148Z,1559086673.148 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 809
2019-05-28T23:37:53.149Z,1559086673.149 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-28T23:37:53.150Z,1559086673.150 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-28T23:37:53.150Z,1559086673.150 [logger ThreadHandler](INFO): Protected caller Thread ID is 810
2019-05-28T23:37:53.152Z,1559086673.152 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-28T23:37:53.153Z,1559086673.153 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-28T23:37:53.157Z,1559086673.157 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-28T23:37:53.588Z,1559086673.588 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-28T23:37:53.590Z,1559086673.590 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-28T23:37:53.689Z,1559086673.689 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-28T23:37:53.690Z,1559086673.690 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-28T23:37:54.022Z,1559086674.022 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-28T23:37:54.024Z,1559086674.024 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-28T23:37:54.167Z,1559086674.167 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-28T23:37:54.168Z,1559086674.168 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-28T23:37:54.363Z,1559086674.363 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-28T23:37:54.365Z,1559086674.365 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-28T23:37:54.830Z,1559086674.830 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-28T23:37:54.832Z,1559086674.832 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-28T23:37:55.044Z,1559086675.044 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-28T23:37:55.046Z,1559086675.046 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-28T23:37:55.194Z,1559086675.194 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-28T23:37:55.195Z,1559086675.195 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-28T23:37:55.391Z,1559086675.391 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-28T23:37:55.392Z,1559086675.392 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-28T23:37:55.489Z,1559086675.489 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-28T23:37:55.491Z,1559086675.491 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-28T23:37:55.818Z,1559086675.818 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-28T23:37:55.819Z,1559086675.819 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-28T23:37:55.901Z,1559086675.901 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-28T23:37:56.005Z,1559086676.005 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-28T23:37:56.007Z,1559086676.007 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-28T23:37:56.599Z,1559086676.599 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-28T23:37:56.601Z,1559086676.601 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-28T23:37:57.547Z,1559086677.547 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-28T23:37:57.550Z,1559086677.550 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-28T23:37:57.555Z,1559086677.555 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-28T23:37:57.767Z,1559086677.767 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-28T23:37:57.867Z,1559086677.867 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-28T23:37:57.966Z,1559086677.966 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-28T23:37:58.195Z,1559086678.195 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-28T23:37:58.196Z,1559086678.196 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-28T23:37:58.281Z,1559086678.281 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-28T23:37:58.376Z,1559086678.376 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-28T23:37:58.474Z,1559086678.474 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-28T23:37:58.557Z,1559086678.557 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-28T23:37:58.671Z,1559086678.671 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-28T23:37:58.850Z,1559086678.850 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-28T23:37:59.073Z,1559086679.073 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2019-05-28T23:37:59.078Z,1559086679.078 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-28T23:37:59.797Z,1559086679.797 [AHRS_M2] Loaded
2019-05-28T23:37:59.797Z,1559086679.797 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-28T23:37:59.938Z,1559086679.938 [DataOverHttps] Loaded
2019-05-28T23:37:59.939Z,1559086679.939 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-28T23:37:59.940Z,1559086679.940 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4075A4E0
2019-05-28T23:37:59.940Z,1559086679.940 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 890
2019-05-28T23:37:59.954Z,1559086679.954 [Depth_Keller] Loaded
2019-05-28T23:37:59.954Z,1559086679.954 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-28T23:37:59.959Z,1559086679.959 [DropWeight] Loaded
2019-05-28T23:37:59.959Z,1559086679.959 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-28T23:38:00.016Z,1559086680.016 [DUSBL_Hydroid] Loaded
2019-05-28T23:38:00.017Z,1559086680.017 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-28T23:38:00.058Z,1559086680.058 [Micromodem] Loaded
2019-05-28T23:38:00.058Z,1559086680.058 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-28T23:38:00.159Z,1559086680.159 [NAL9602] Loaded
2019-05-28T23:38:00.160Z,1559086680.160 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-28T23:38:00.176Z,1559086680.176 [Onboard] Loaded
2019-05-28T23:38:00.176Z,1559086680.176 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-28T23:38:00.182Z,1559086680.182 [PowerOnly] Loaded
2019-05-28T23:38:00.182Z,1559086680.182 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-28T23:38:00.189Z,1559086680.189 [Radio_Surface] Loaded
2019-05-28T23:38:00.189Z,1559086680.189 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-28T23:38:00.190Z,1559086680.190 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4078A4E0
2019-05-28T23:38:00.191Z,1559086680.191 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 891
2019-05-28T23:38:00.235Z,1559086680.235 [RDI_Pathfinder] Loaded
2019-05-28T23:38:00.236Z,1559086680.236 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-28T23:38:01.766Z,1559086681.766 [BPC1] Loaded
2019-05-28T23:38:01.767Z,1559086681.767 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-28T23:38:01.767Z,1559086681.767 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-28T23:38:01.768Z,1559086681.768 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-28T23:38:01.819Z,1559086681.819 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-28T23:38:01.820Z,1559086681.820 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-28T23:38:02.397Z,1559086682.397 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-28T23:38:02.397Z,1559086682.397 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-28T23:38:02.422Z,1559086682.422 [NavChart] Loaded
2019-05-28T23:38:02.423Z,1559086682.423 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-28T23:38:02.427Z,1559086682.427 [UniversalFixResidualReporter] Loaded
2019-05-28T23:38:02.427Z,1559086682.427 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-28T23:38:02.427Z,1559086682.427 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-28T23:38:02.428Z,1559086682.428 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-28T23:38:02.562Z,1559086682.562 [BuoyancyServo] Loaded
2019-05-28T23:38:02.562Z,1559086682.562 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-28T23:38:02.578Z,1559086682.578 [ElevatorServo] Loaded
2019-05-28T23:38:02.578Z,1559086682.578 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-28T23:38:02.593Z,1559086682.593 [MassServo] Loaded
2019-05-28T23:38:02.593Z,1559086682.593 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-28T23:38:02.609Z,1559086682.609 [RudderServo] Loaded
2019-05-28T23:38:02.609Z,1559086682.609 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-28T23:38:02.624Z,1559086682.624 [ThrusterServo] Loaded
2019-05-28T23:38:02.624Z,1559086682.624 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-28T23:38:02.624Z,1559086682.624 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-28T23:38:02.625Z,1559086682.625 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-28T23:38:02.953Z,1559086682.953 [CTD_NeilBrown] Loaded
2019-05-28T23:38:02.954Z,1559086682.954 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-28T23:38:02.955Z,1559086682.955 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408CC4E0
2019-05-28T23:38:02.955Z,1559086682.955 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 893
2019-05-28T23:38:03.000Z,1559086683.000 [WetLabsSeaOWL_UV_A] Loaded
2019-05-28T23:38:03.001Z,1559086683.001 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-28T23:38:03.002Z,1559086683.002 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 408FC4E0
2019-05-28T23:38:03.002Z,1559086683.002 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 894
2019-05-28T23:38:03.003Z,1559086683.003 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-28T23:38:03.003Z,1559086683.003 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-28T23:38:03.354Z,1559086683.354 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-28T23:38:03.355Z,1559086683.355 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-28T23:38:03.411Z,1559086683.411 [DepthRateCalculator] Loaded
2019-05-28T23:38:03.411Z,1559086683.411 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-28T23:38:03.417Z,1559086683.417 [PitchRateCalculator] Loaded
2019-05-28T23:38:03.417Z,1559086683.417 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-28T23:38:03.429Z,1559086683.429 [SpeedCalculator] Loaded
2019-05-28T23:38:03.430Z,1559086683.430 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-28T23:38:03.451Z,1559086683.451 [TempGradientCalculator] Loaded
2019-05-28T23:38:03.451Z,1559086683.451 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-28T23:38:03.457Z,1559086683.457 [YawRateCalculator] Loaded
2019-05-28T23:38:03.457Z,1559086683.457 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-28T23:38:03.498Z,1559086683.498 [ElevatorOffsetCalculator] Loaded
2019-05-28T23:38:03.499Z,1559086683.499 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-28T23:38:03.499Z,1559086683.499 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-28T23:38:03.500Z,1559086683.500 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-28T23:38:03.664Z,1559086683.664 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-28T23:38:03.686Z,1559086683.686 [SBIT] Loaded
2019-05-28T23:38:03.686Z,1559086683.686 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-28T23:38:03.687Z,1559086683.687 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-28T23:38:03.699Z,1559086683.699 [IBIT] Loaded
2019-05-28T23:38:03.699Z,1559086683.699 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-28T23:38:03.702Z,1559086683.702 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-28T23:38:03.843Z,1559086683.843 [CBIT] Loaded
2019-05-28T23:38:03.843Z,1559086683.843 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-28T23:38:03.843Z,1559086683.843 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-28T23:38:03.844Z,1559086683.844 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-28T23:38:03.967Z,1559086683.967 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-28T23:38:03.968Z,1559086683.968 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-28T23:38:04.094Z,1559086684.094 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-28T23:38:04.095Z,1559086684.095 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-28T23:38:04.184Z,1559086684.184 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-28T23:38:04.269Z,1559086684.269 [VerticalControl] Loaded
2019-05-28T23:38:04.270Z,1559086684.270 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-28T23:38:04.270Z,1559086684.270 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-28T23:38:04.329Z,1559086684.329 [HorizontalControl] Loaded
2019-05-28T23:38:04.330Z,1559086684.330 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-28T23:38:04.330Z,1559086684.330 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-28T23:38:04.332Z,1559086684.332 [SpeedControl] Loaded
2019-05-28T23:38:04.332Z,1559086684.332 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-28T23:38:04.333Z,1559086684.333 [LoopControl](DEBUG): Construct LoopControl.
2019-05-28T23:38:04.334Z,1559086684.334 [LoopControl] Loaded
2019-05-28T23:38:04.334Z,1559086684.334 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-28T23:38:04.334Z,1559086684.334 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-28T23:38:04.335Z,1559086684.335 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-28T23:38:04.377Z,1559086684.377 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-28T23:38:04.381Z,1559086684.381 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-28T23:38:04.382Z,1559086684.382 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-28T23:38:04.389Z,1559086684.389 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-28T23:38:04.390Z,1559086684.390 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AD54E0
2019-05-28T23:38:04.390Z,1559086684.390 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 895
2019-05-28T23:38:04.395Z,1559086684.395 [Supervisor](INFO): Main Thread ID is 803
2019-05-28T23:38:04.395Z,1559086684.395 [Supervisor](DEBUG): Running supervisor.
2019-05-28T23:38:04.395Z,1559086684.395 [CommandLine ThreadHandler](INFO): Handler Thread ID is 896
2019-05-28T23:38:04.398Z,1559086684.398 [controlThread ThreadHandler](INFO): Handler Thread ID is 897
2019-05-28T23:38:04.398Z,1559086684.398 [controlThread](DEBUG): Initializing ControlThread
2019-05-28T23:38:04.404Z,1559086684.404 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-28T23:38:04.404Z,1559086684.404 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-28T23:38:04.406Z,1559086684.406 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-28T23:38:04.406Z,1559086684.406 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-28T23:38:04.407Z,1559086684.407 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-28T23:38:04.407Z,1559086684.407 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-28T23:38:04.407Z,1559086684.408 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-28T23:38:04.408Z,1559086684.408 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-28T23:38:04.408Z,1559086684.408 [SBIT](INFO): Initialize SBIT Component.
2019-05-28T23:38:04.409Z,1559086684.409 [SBIT](IMPORTANT): git: 2019-05-22
2019-05-28T23:38:04.409Z,1559086684.409 [SBIT](INFO): git hash: b146eb58452ebd2f190c0e5bc4ac3eb35807c4ac
2019-05-28T23:38:04.410Z,1559086684.410 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-28T23:38:04.411Z,1559086684.411 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-28T23:38:04.412Z,1559086684.412 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-05-28T23:38:04.412Z,1559086684.412 [IBIT](INFO): Initialize IBIT Component.
2019-05-28T23:38:04.413Z,1559086684.413 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-28T23:38:04.414Z,1559086684.414 [logger ThreadHandler](INFO): Handler Thread ID is 898
2019-05-28T23:38:04.425Z,1559086684.425 [CBIT](DEBUG): Initialized mux pins.
2019-05-28T23:38:04.425Z,1559086684.425 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2019-05-28T23:38:04.425Z,1559086684.425 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-28T23:38:04.433Z,1559086684.433 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 899
2019-05-28T23:38:04.434Z,1559086684.434 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-28T23:38:04.445Z,1559086684.445 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 900
2019-05-28T23:38:04.449Z,1559086684.449 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2019-05-28T23:38:04.449Z,1559086684.449 [CBIT](DEBUG): Initializing heartbeat.
2019-05-28T23:38:04.465Z,1559086684.465 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 901
2019-05-28T23:38:04.466Z,1559086684.466 [CTD_NeilBrown](INFO): Powering down
2019-05-28T23:38:04.485Z,1559086684.485 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 902
2019-05-28T23:38:04.486Z,1559086684.486 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-28T23:38:04.521Z,1559086684.521 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-28T23:38:04.521Z,1559086684.521 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-28T23:38:04.522Z,1559086684.522 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 903
2019-05-28T23:38:04.530Z,1559086684.530 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-28T23:38:04.530Z,1559086684.530 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-28T23:38:04.531Z,1559086684.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-28T23:38:04.531Z,1559086684.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-28T23:38:04.531Z,1559086684.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-28T23:38:04.531Z,1559086684.531 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-28T23:38:04.531Z,1559086684.531 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-28T23:38:04.532Z,1559086684.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-28T23:38:04.532Z,1559086684.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-28T23:38:04.532Z,1559086684.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-28T23:38:04.532Z,1559086684.532 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-28T23:38:04.532Z,1559086684.532 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-28T23:38:04.533Z,1559086684.533 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-28T23:38:04.533Z,1559086684.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-28T23:38:04.533Z,1559086684.533 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-28T23:38:04.533Z,1559086684.533 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-28T23:38:04.557Z,1559086684.557 [CBIT](DEBUG): Backplane powered.
2019-05-28T23:38:04.557Z,1559086684.557 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-28T23:38:04.559Z,1559086684.559 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-28T23:38:04.560Z,1559086684.560 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-28T23:38:04.560Z,1559086684.560 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-28T23:38:04.561Z,1559086684.561 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-28T23:38:04.583Z,1559086684.583 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T23:38:04.602Z,1559086684.602 [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>


2019-05-28T23:38:04.602Z,1559086684.602 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-28T23:38:04.664Z,1559086684.664 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-28T23:38:04.685Z,1559086684.685 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-28T23:38:04.687Z,1559086684.687 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-28T23:38:04.713Z,1559086684.713 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-28T23:38:04.716Z,1559086684.716 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-28T23:38:04.741Z,1559086684.741 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-28T23:38:04.753Z,1559086684.753 [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="P2H">
                <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>


2019-05-28T23:38:04.778Z,1559086684.778 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-28T23:38:04.799Z,1559086684.799 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-28T23:38:04.849Z,1559086684.849 [Radio_Surface](INFO): Powering up
2019-05-28T23:38:04.922Z,1559086684.922 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-28T23:38:04.922Z,1559086684.922 [DUSBL_Hydroid](INFO): Powering up
2019-05-28T23:38:04.923Z,1559086684.923 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-28T23:38:05.001Z,1559086685.001 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-28T23:38:05.042Z,1559086685.042 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:05.053Z,1559086685.053 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-28T23:38:05.054Z,1559086685.054 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:05.061Z,1559086685.061 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-28T23:38:05.062Z,1559086685.062 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:05.069Z,1559086685.069 [MassServo](DEBUG): Initializing MassServo.
2019-05-28T23:38:05.070Z,1559086685.070 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:05.078Z,1559086685.078 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-28T23:38:05.078Z,1559086685.078 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:05.085Z,1559086685.085 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-28T23:38:05.087Z,1559086685.087 [CommandLine](FAULT): Scheduling is paused
2019-05-28T23:38:05.087Z,1559086685.087 [CBIT](INFO): Critical error at 20190528T233804
2019-05-28T23:38:05.088Z,1559086685.088 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2019-05-28T23:38:05.223Z,1559086685.223 [Micromodem](INFO): Powering up
2019-05-28T23:38:05.223Z,1559086685.223 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-28T23:38:05.261Z,1559086685.261 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-28T23:38:05.925Z,1559086685.925 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-28T23:38:05.925Z,1559086685.925 [RudderServo](FAULT): Rudder failed to initialize
2019-05-28T23:38:05.925Z,1559086685.925 [RudderServo] Communications Fault, FailCount= 1
2019-05-28T23:38:05.925Z,1559086685.925 [RudderServo](ERROR): Communications Fault
2019-05-28T23:38:06.085Z,1559086686.085 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-28T23:38:06.258Z,1559086686.258 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-28T23:38:06.258Z,1559086686.258 [RudderServo](INFO): Powering down
2019-05-28T23:38:06.933Z,1559086686.933 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-28T23:38:07.054Z,1559086687.054 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-28T23:38:07.058Z,1559086687.058 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-28T23:38:07.058Z,1559086687.058 [RudderServo] No Fault, FailCount= 1
2019-05-28T23:38:18.255Z,1559086698.255 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-28T23:38:21.462Z,1559086701.462 [Micromodem](ERROR): Nmea resend: $CCCFG,ALL,0*33

2019-05-28T23:38:23.075Z,1559086703.075 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-28T23:38:30.348Z,1559086710.348 [NAL9602](INFO): Powering up NAL9602
2019-05-28T23:38:32.803Z,1559086712.803 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-28T23:38:32.832Z,1559086712.832 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-28T23:38:41.344Z,1559086721.344 [NAL9602](INFO): NAL9602 initialized
2019-05-28T23:38:42.153Z,1559086722.153 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:38:43.830Z,1559086723.830 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.011077
CHAN A1 (24V): -0.025697
CHAN A2 (12V): -0.006084
CHAN A3 (5V): -0.001884
CHAN B0 (3.3V): 0.000237
CHAN B1 (3.15aV): 0.000007
CHAN B2 (3.15bV): 0.000352
CHAN B3 (GND): 0.001768
OPEN: 0.009049
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-28T23:39:26.507Z,1559086766.507 [SBIT](IMPORTANT): SBIT PASSED
2019-05-28T23:39:26.554Z,1559086766.554 [CommandLine](IMPORTANT): got command configSet list
2019-05-28T23:39:26.555Z,1559086766.555 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-28T23:39:26.586Z,1559086766.586 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour;

2019-05-28T23:39:26.586Z,1559086766.586 [CommandLine](IMPORTANT): BPC1.loadAtStartup=1 bool;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): DUSBL_Hydroid.detectionThreshold=35 count;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.range 2.000000 meter;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation DUSBL_Hydroid.xAngle 2.000000 angular_degree;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.BottomVelocityFlag 0.000000 count;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation RDI_Pathfinder.height_above_sea_floor 2.000000 meter;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_latitude;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express none TrackAcousticContact.contact_longitude;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation acoustic_contact_range 1.000000 meter;

2019-05-28T23:39:26.587Z,1559086766.587 [CommandLine](IMPORTANT): Express linearApproximation mass_concentration_of_chlorophyll_in_sea_water 5.000000 microgram_per_liter;

2019-05-28T23:39:26.588Z,1559086766.588 [CommandLine](IMPORTANT): Express none mass_concentration_of_oxygen_in_sea_water;

2019-05-28T23:39:26.588Z,1559086766.588 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool;

2019-05-28T23:39:26.588Z,1559086766.588 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=190 cubic_centimeter;

2019-05-28T23:39:26.588Z,1559086766.588 [CommandLine](IMPORTANT): VerticalControl.massDefault=5 millimeter;

2019-05-28T23:39:26.896Z,1559086766.896 [MissionManager](IMPORTANT): Started mission Startup
2019-05-28T23:39:26.896Z,1559086766.896 [Startup] Running Loop=1
2019-05-28T23:39:26.897Z,1559086766.897 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-28T23:39:26.897Z,1559086766.897 [Startup:A.GoToSurface] Running Loop=1
2019-05-28T23:39:26.897Z,1559086766.897 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:39:26.898Z,1559086766.898 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:39:26.898Z,1559086766.898 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:39:26.898Z,1559086766.898 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:39:26.899Z,1559086766.899 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:39:26.899Z,1559086766.899 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:39:26.900Z,1559086766.900 [Startup:StartupSatComms] Running Loop=1
2019-05-28T23:39:26.900Z,1559086766.900 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-28T23:39:26.901Z,1559086766.901 [Startup:StartupSatComms:A] Running Loop=1
2019-05-28T23:39:27.314Z,1559086767.314 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-28T23:40:27.070Z,1559086827.070 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-28T23:39:26.9Z
2019-05-28T23:40:27.070Z,1559086827.070 [Startup:StartupSatComms:A] Stopped
2019-05-28T23:40:27.070Z,1559086827.070 [Startup:StartupSatComms:B] Running Loop=1
2019-05-28T23:40:27.486Z,1559086827.486 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T23:40:27.756Z,1559086827.756 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005003
2019-05-28T23:40:32.984Z,1559086832.984 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190528T230903/Courier0019.lzma
2019-05-28T23:40:33.790Z,1559086833.790 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Courier0019.lzma.bak
2019-05-28T23:40:33.791Z,1559086833.791 [DataOverHttps](INFO): SBD MOMSN=11208618
2019-05-28T23:40:44.872Z,1559086844.872 [DataOverHttps](INFO): Sending 99 bytes from file Logs/20190528T233753/Courier0000.lzma
2019-05-28T23:40:45.678Z,1559086845.678 [DataOverHttps](INFO): Moved sent file to Logs/20190528T233753/Courier0000.lzma.bak
2019-05-28T23:40:45.678Z,1559086845.678 [DataOverHttps](INFO): SBD MOMSN=11208620
2019-05-28T23:40:57.472Z,1559086857.472 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190528T230903/Express0020.lzma
2019-05-28T23:40:58.278Z,1559086858.278 [DataOverHttps](INFO): Moved sent file to Logs/20190528T230903/Express0020.lzma.bak
2019-05-28T23:40:58.279Z,1559086858.279 [DataOverHttps](INFO): SBD MOMSN=11208624
2019-05-28T23:41:04.668Z,1559086864.668 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-28T23:41:04.668Z,1559086864.668 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-28T23:41:04.678Z,1559086864.678 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-28T23:41:05.050Z,1559086865.050 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-28T23:41:05.050Z,1559086865.050 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-28T23:41:09.870Z,1559086869.870 [Micromodem](ERROR): Response from modem failed NMEA checksum: 0*21

2019-05-28T23:41:14.499Z,1559086874.499 [DataOverHttps](INFO): Sending 1055 bytes from file Logs/20190528T233753/Express0001.lzma
2019-05-28T23:41:15.314Z,1559086875.314 [DataOverHttps](INFO): Moved sent file to Logs/20190528T233753/Express0001.lzma.bak
2019-05-28T23:41:15.314Z,1559086875.314 [DataOverHttps](INFO): SBD MOMSN=11208626
2019-05-28T23:41:16.383Z,1559086876.383 [Startup:StartupSatComms:B] Stopped
2019-05-28T23:41:16.384Z,1559086876.384 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-28T23:41:16.384Z,1559086876.384 [Startup:StartupSatComms] Stopped
2019-05-28T23:41:16.384Z,1559086876.384 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-28T23:41:16.384Z,1559086876.384 [Startup](INFO): Completed Startup
2019-05-28T23:41:16.389Z,1559086876.389 [MissionManager](INFO): Startup is completed.
2019-05-28T23:41:16.389Z,1559086876.389 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-28T23:41:16.389Z,1559086876.389 [Startup] Stopped
2019-05-28T23:41:16.389Z,1559086876.389 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-28T23:41:16.389Z,1559086876.389 [Startup:A.GoToSurface] Stopped
2019-05-28T23:41:16.389Z,1559086876.389 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:41:16.771Z,1559086876.771 [MissionManager](IMPORTANT): Started mission Default
2019-05-28T23:41:16.771Z,1559086876.771 [Default] Running Loop=1
2019-05-28T23:41:16.771Z,1559086876.771 [Default](DEBUG): Aggregate::initialize Default
2019-05-28T23:41:16.771Z,1559086876.771 [Default:B.GoToSurface] Running Loop=1
2019-05-28T23:41:16.771Z,1559086876.771 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-28T23:41:16.771Z,1559086876.771 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-28T23:41:16.772Z,1559086876.772 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-28T23:41:16.772Z,1559086876.772 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-28T23:41:16.772Z,1559086876.772 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-28T23:41:16.773Z,1559086876.773 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-28T23:41:16.773Z,1559086876.773 [Default:A.Wait] Running Loop=1
2019-05-28T23:41:16.773Z,1559086876.773 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:41:18.360Z,1559086878.360 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CACST,6,1,20190528234109.5330$CADQF,200,1*52

2019-05-28T23:41:30.090Z,1559086890.090 [Default:A.Wait](INFO): Done Waiting.
2019-05-28T23:41:30.090Z,1559086890.090 [Default:A.Wait] Stopped
2019-05-28T23:41:30.090Z,1559086890.090 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:41:30.510Z,1559086890.510 [Default:CheckIn] Running Loop=1
2019-05-28T23:41:30.510Z,1559086890.510 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:41:30.511Z,1559086890.511 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:41:30.910Z,1559086890.910 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-28T23:43:40.192Z,1559087020.192 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CA9C,0.10.0.46*40

2019-05-28T23:43:40.194Z,1559087020.194 [Micromodem](ERROR): Response from modem failed NMEA checksum: .15,-999,9760,4000*77

2019-05-28T23:43:44.599Z,1559087024.599 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-05-28T23:43:45.425Z,1559087025.425 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:43:49.461Z,1559087029.461 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:43:49.853Z,1559087029.853 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234259.00,A,3648.16637,N,12147.28275,W,0.039,25.73,280519,,,A*4E
2019-05-28T23:43:49.856Z,1559087029.856 [NAL9602](INFO): GPS fix at 20190528T234259: (36.802773, -121.788046)
2019-05-28T23:43:49.884Z,1559087029.884 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:43:49.884Z,1559087029.884 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-05-28T23:43:50.318Z,1559087030.318 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-28T23:43:59.241Z,1559087039.241 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190528T233753/Courier0004.lzma
2019-05-28T23:44:00.046Z,1559087040.046 [DataOverHttps](INFO): Moved sent file to Logs/20190528T233753/Courier0004.lzma.bak
2019-05-28T23:44:00.046Z,1559087040.046 [DataOverHttps](INFO): SBD MOMSN=11208686
2019-05-28T23:44:14.033Z,1559087054.033 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20190528T233753/Express0005.lzma
2019-05-28T23:44:14.838Z,1559087054.838 [DataOverHttps](INFO): Moved sent file to Logs/20190528T233753/Express0005.lzma.bak
2019-05-28T23:44:14.839Z,1559087054.839 [DataOverHttps](INFO): SBD MOMSN=11208689
2019-05-28T23:44:14.950Z,1559087054.950 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-05-28T23:44:14.957Z,1559087054.957 [BPC1](INFO): Received data from all battery sticks.
2019-05-28T23:44:15.970Z,1559087055.970 [Default:CheckIn:Read_Iridium] Stopped
2019-05-28T23:44:15.970Z,1559087055.970 [Default:CheckIn:C.Wait] Running Loop=1
2019-05-28T23:44:15.970Z,1559087055.970 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-05-28T23:44:21.991Z,1559087061.991 [NAL9602](INFO): Powering down
2019-05-28T23:44:58.760Z,1559087098.760 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CA,-9.99,207,0.10,-999,9760,4000*5A

2019-05-28T23:45:39.210Z,1559087139.210 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-05-28T23:45:39.210Z,1559087139.210 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  98.58,  93.93,  92.60
2019-05-28T23:46:15.550Z,1559087175.550 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-28T23:46:15.550Z,1559087175.550 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19052816545467,35.0, -0.1,   .9,  0
2019-05-28T23:47:16.550Z,1559087236.550 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,  97.92,  94.42,  92.93,   0.00
2019-05-28T23:48:54.368Z,1559087334.368 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,23442625,06,376,13,0098,0150,246,00,00,02,02,0,-01,-01,,2.0.27690*V0,00,,1,-999,-99.9,-9.99,-999,-9.99,198,-0.15,-999,9760V,234747,COPROC,0.10.0.46*41

2019-05-28T23:49:16.557Z,1559087356.557 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-05-28T23:49:16.557Z,1559087356.557 [Default:CheckIn:C.Wait] Stopped
2019-05-28T23:49:16.557Z,1559087356.557 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-28T23:49:16.557Z,1559087356.557 [Default:CheckIn:D] Running Loop=1
2019-05-28T23:49:16.956Z,1559087356.956 [Default:CheckIn:D] Stopped
2019-05-28T23:49:16.957Z,1559087356.957 [Default:CheckIn:E] Running Loop=1
2019-05-28T23:49:17.379Z,1559087357.379 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.003094 min 
2019-05-28T23:49:17.379Z,1559087357.379 [Default:CheckIn:E] Stopped
2019-05-28T23:49:17.379Z,1559087357.379 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-05-28T23:49:17.379Z,1559087357.379 [Default:CheckIn] Stopped
2019-05-28T23:49:17.379Z,1559087357.379 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:49:17.380Z,1559087357.380 [Default:CheckIn](INFO): Running loop #2
2019-05-28T23:49:17.380Z,1559087357.380 [Default:CheckIn] Running Loop=2
2019-05-28T23:49:17.380Z,1559087357.380 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-28T23:49:17.380Z,1559087357.380 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-28T23:49:18.144Z,1559087358.144 [NAL9602](INFO): Powering up
2019-05-28T23:49:29.055Z,1559087369.055 [NAL9602](INFO): NAL9602 initialized
2019-05-28T23:49:29.873Z,1559087369.873 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:50:00.967Z,1559087400.967 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-05-28T23:50:01.045Z,1559087401.045 [NAL9602](FAULT): received: 
+CSQ:0

OK
2019-05-28T23:50:01.045Z,1559087401.045 [NAL9602] Data Fault, FailCount= 1
2019-05-28T23:50:01.045Z,1559087401.045 [NAL9602](ERROR): Data Fault
2019-05-28T23:50:01.081Z,1559087401.081 [CBIT](ERROR): Data Fault in component: NAL9602
2019-05-28T23:50:01.371Z,1559087401.371 [NAL9602](INFO): Powering down
2019-05-28T23:50:02.241Z,1559087402.241 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-28T23:50:02.241Z,1559087402.241 [NAL9602] No Fault, FailCount= 1
2019-05-28T23:50:31.671Z,1559087431.671 [NAL9602](INFO): Powering up NAL9602
2019-05-28T23:50:42.589Z,1559087442.589 [NAL9602](INFO): NAL9602 initialized
2019-05-28T23:50:43.405Z,1559087443.405 [NAL9602](DEBUG): Fix Requested
2019-05-28T23:53:36.111Z,1559087616.111 [CommandLine](IMPORTANT): got command restart system
2019-05-28T23:53:38.598Z,1559087618.598 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:38.598Z,1559087618.598 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:38.757Z,1559087618.757 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-28T23:53:38.757Z,1559087618.757 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:38.758Z,1559087618.758 [CommandLine](INFO): Join timeout helper Thread ID is 958
2019-05-28T23:53:38.770Z,1559087618.770 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-28T23:53:38.770Z,1559087618.770 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:38.770Z,1559087618.770 [NavChartDb](INFO): Join timeout helper Thread ID is 959
2019-05-28T23:53:38.985Z,1559087618.985 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:38.985Z,1559087618.985 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:38.989Z,1559087618.989 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-28T23:53:38.989Z,1559087618.989 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:38.989Z,1559087618.989 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 960
2019-05-28T23:53:39.053Z,1559087619.053 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.053Z,1559087619.053 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-28T23:53:39.054Z,1559087619.054 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.069Z,1559087619.069 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-28T23:53:39.069Z,1559087619.069 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.070Z,1559087619.070 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 961
2019-05-28T23:53:39.141Z,1559087619.141 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.141Z,1559087619.141 [CTD_NeilBrown](INFO): Powering down
2019-05-28T23:53:39.154Z,1559087619.154 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.174Z,1559087619.174 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-28T23:53:39.174Z,1559087619.174 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.176Z,1559087619.176 [Radio_Surface](INFO): Join timeout helper Thread ID is 962
2019-05-28T23:53:39.409Z,1559087619.409 [Radio_Surface](INFO): Powering down
2019-05-28T23:53:39.410Z,1559087619.410 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.410Z,1559087619.410 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.418Z,1559087619.418 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-28T23:53:39.418Z,1559087619.418 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.418Z,1559087619.418 [DataOverHttps](INFO): Join timeout helper Thread ID is 963
2019-05-28T23:53:39.473Z,1559087619.473 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.473Z,1559087619.473 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.478Z,1559087619.478 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-28T23:53:39.478Z,1559087619.478 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.478Z,1559087619.478 [logger](INFO): Join timeout helper Thread ID is 964
2019-05-28T23:53:39.517Z,1559087619.517 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.517Z,1559087619.517 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.538Z,1559087619.538 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-28T23:53:39.538Z,1559087619.538 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.538Z,1559087619.538 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-28T23:53:39.538Z,1559087619.538 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:39.539Z,1559087619.539 [controlThread](INFO): Join timeout helper Thread ID is 965
2019-05-28T23:53:39.574Z,1559087619.574 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-28T23:53:39.574Z,1559087619.574 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-28T23:53:39.574Z,1559087619.574 [AHRS_M2](INFO): Powering down
2019-05-28T23:53:39.646Z,1559087619.646 [DUSBL_Hydroid](INFO): Powering down
2019-05-28T23:53:39.737Z,1559087619.737 [Micromodem](INFO): Powering down
2019-05-28T23:53:39.833Z,1559087619.833 [NAL9602](INFO): Powering down
2019-05-28T23:53:39.905Z,1559087619.905 [RDI_Pathfinder](INFO): Powering down
2019-05-28T23:53:39.906Z,1559087619.906 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-28T23:53:39.907Z,1559087619.907 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-28T23:53:39.908Z,1559087619.908 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-28T23:53:39.908Z,1559087619.908 [MissionManager](INFO): Uninitializing Mission Default
2019-05-28T23:53:39.908Z,1559087619.908 [Default] Stopped
2019-05-28T23:53:39.908Z,1559087619.908 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-28T23:53:39.908Z,1559087619.908 [Default:B.GoToSurface] Stopped
2019-05-28T23:53:39.909Z,1559087619.909 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-28T23:53:39.909Z,1559087619.909 [Default:CheckIn] Stopped
2019-05-28T23:53:39.909Z,1559087619.909 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-28T23:53:39.909Z,1559087619.909 [Default:CheckIn:Read_GPS] Stopped
2019-05-28T23:53:39.911Z,1559087619.911 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-28T23:53:39.912Z,1559087619.912 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-28T23:53:39.912Z,1559087619.912 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-28T23:53:39.912Z,1559087619.912 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-28T23:53:39.913Z,1559087619.913 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-28T23:53:39.913Z,1559087619.913 [BuoyancyServo](INFO): Powering down
2019-05-28T23:53:39.925Z,1559087619.925 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-28T23:53:39.925Z,1559087619.925 [ElevatorServo](INFO): Powering down
2019-05-28T23:53:39.926Z,1559087619.926 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-28T23:53:39.926Z,1559087619.926 [MassServo](INFO): Powering down
2019-05-28T23:53:39.927Z,1559087619.927 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-28T23:53:39.927Z,1559087619.927 [RudderServo](INFO): Powering down
2019-05-28T23:53:39.928Z,1559087619.928 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-28T23:53:39.928Z,1559087619.928 [ThrusterServo](INFO): Powering down
2019-05-28T23:53:39.929Z,1559087619.929 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-28T23:53:39.929Z,1559087619.929 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-28T23:53:39.929Z,1559087619.929 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-28T23:53:39.929Z,1559087619.929 [CBIT](DEBUG): Powering off loads.
2019-05-28T23:53:39.941Z,1559087619.941 [CBIT](DEBUG): Disabling WDT.
2019-05-28T23:53:39.953Z,1559087619.953 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-28T23:53:39.954Z,1559087619.954 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.001Z,1559087620.001 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.010Z,1559087620.010 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.052Z,1559087620.052 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.055Z,1559087620.055 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.114Z,1559087620.114 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-28T23:53:40.185Z,1559087620.185 [logger ThreadHandler](INFO): Thread cancelled.