2018-12-18T17:50:45.911Z,1545155445.911 [Supervisor](DEBUG): Initializing supervisor.
2018-12-18T17:50:45.914Z,1545155445.914 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-12-18T17:50:45.914Z,1545155445.914 [SyncHandler](INFO): Protected caller Thread ID is 1006
2018-12-18T17:50:45.915Z,1545155445.915 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-12-18T17:50:45.915Z,1545155445.915 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-12-18T17:50:45.916Z,1545155445.916 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 1007
2018-12-18T17:50:45.919Z,1545155445.919 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-12-18T17:50:45.930Z,1545155445.930 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-12-18T17:50:45.931Z,1545155445.931 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-12-18T17:50:45.932Z,1545155445.932 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 1008
2018-12-18T17:50:45.932Z,1545155445.932 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-12-18T17:50:45.933Z,1545155445.933 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-12-18T17:50:45.934Z,1545155445.934 [logger ThreadHandler](INFO): Protected caller Thread ID is 1009
2018-12-18T17:50:45.936Z,1545155445.936 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-12-18T17:50:45.936Z,1545155445.936 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-12-18T17:50:45.938Z,1545155445.938 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-12-18T17:50:46.248Z,1545155446.248 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-12-18T17:50:46.248Z,1545155446.248 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-12-18T17:50:46.436Z,1545155446.436 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-12-18T17:50:46.437Z,1545155446.437 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-12-18T17:50:46.728Z,1545155446.728 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-12-18T17:50:46.729Z,1545155446.729 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-12-18T17:50:46.870Z,1545155446.870 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-12-18T17:50:46.871Z,1545155446.871 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-12-18T17:50:46.968Z,1545155446.968 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-12-18T17:50:46.969Z,1545155446.969 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-12-18T17:50:47.426Z,1545155447.426 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-12-18T17:50:47.427Z,1545155447.427 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-12-18T17:50:47.872Z,1545155447.872 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-12-18T17:50:47.872Z,1545155447.872 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-12-18T17:50:48.323Z,1545155448.323 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-12-18T17:50:48.324Z,1545155448.324 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-12-18T17:50:48.426Z,1545155448.426 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-12-18T17:50:48.426Z,1545155448.426 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-12-18T17:50:48.521Z,1545155448.521 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-12-18T17:50:48.522Z,1545155448.522 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-12-18T17:50:48.733Z,1545155448.733 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-12-18T17:50:48.733Z,1545155448.733 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-12-18T17:50:48.931Z,1545155448.931 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-12-18T17:50:48.932Z,1545155448.932 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-12-18T17:50:49.319Z,1545155449.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-12-18T17:50:49.319Z,1545155449.319 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-12-18T17:50:49.462Z,1545155449.462 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-12-18T17:50:49.462Z,1545155449.462 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-12-18T17:50:49.545Z,1545155449.545 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-12-18T17:50:49.546Z,1545155449.546 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-12-18T17:50:49.647Z,1545155449.647 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-12-18T17:50:49.766Z,1545155449.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-12-18T17:50:49.861Z,1545155449.861 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-12-18T17:50:49.946Z,1545155449.946 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-12-18T17:50:50.108Z,1545155450.108 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-12-18T17:50:50.291Z,1545155450.291 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-12-18T17:50:50.366Z,1545155450.366 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-12-18T17:50:50.763Z,1545155450.763 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-12-18T17:50:50.764Z,1545155450.764 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-12-18T17:50:50.869Z,1545155450.869 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-12-18T17:50:51.001Z,1545155451.001 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-12-18T17:50:51.228Z,1545155451.228 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-12-18T17:50:51.353Z,1545155451.353 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-12-18T17:50:51.366Z,1545155451.366 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-12-18T17:50:51.600Z,1545155451.600 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-12-18T17:50:51.600Z,1545155451.600 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-12-18T17:50:51.642Z,1545155451.642 [DepthRateCalculator] Loaded
2018-12-18T17:50:51.643Z,1545155451.643 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-12-18T17:50:51.648Z,1545155451.648 [PitchRateCalculator] Loaded
2018-12-18T17:50:51.649Z,1545155451.649 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-12-18T17:50:51.664Z,1545155451.664 [SpeedCalculator] Loaded
2018-12-18T17:50:51.664Z,1545155451.664 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-12-18T17:50:51.685Z,1545155451.685 [TempGradientCalculator] Loaded
2018-12-18T17:50:51.686Z,1545155451.686 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-12-18T17:50:51.691Z,1545155451.691 [YawRateCalculator] Loaded
2018-12-18T17:50:51.691Z,1545155451.691 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-12-18T17:50:51.731Z,1545155451.731 [ElevatorOffsetCalculator] Loaded
2018-12-18T17:50:51.731Z,1545155451.731 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-12-18T17:50:51.732Z,1545155451.732 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-12-18T17:50:51.732Z,1545155451.732 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-12-18T17:50:51.795Z,1545155451.795 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-12-18T17:50:51.795Z,1545155451.795 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-12-18T17:50:51.919Z,1545155451.919 [BuoyancyServo] Loaded
2018-12-18T17:50:51.919Z,1545155451.919 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-12-18T17:50:51.934Z,1545155451.934 [ElevatorServo] Loaded
2018-12-18T17:50:51.934Z,1545155451.934 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2018-12-18T17:50:51.948Z,1545155451.948 [MassServo] Loaded
2018-12-18T17:50:51.949Z,1545155451.949 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2018-12-18T17:50:51.964Z,1545155451.964 [RudderServo] Loaded
2018-12-18T17:50:51.964Z,1545155451.964 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2018-12-18T17:50:51.978Z,1545155451.978 [ThrusterServo] Loaded
2018-12-18T17:50:51.978Z,1545155451.978 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2018-12-18T17:50:51.979Z,1545155451.979 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-12-18T17:50:51.979Z,1545155451.979 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-12-18T17:50:51.992Z,1545155451.992 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-12-18T17:50:51.993Z,1545155451.993 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-12-18T17:50:52.090Z,1545155452.090 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-12-18T17:50:52.091Z,1545155452.091 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-12-18T17:50:52.378Z,1545155452.378 [DataOverHttps] Loaded
2018-12-18T17:50:52.379Z,1545155452.379 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-12-18T17:50:52.392Z,1545155452.392 [Depth_Keller] Loaded
2018-12-18T17:50:52.392Z,1545155452.392 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-12-18T17:50:52.397Z,1545155452.397 [DropWeight] Loaded
2018-12-18T17:50:52.397Z,1545155452.397 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-12-18T17:50:52.495Z,1545155452.495 [NAL9602] Loaded
2018-12-18T17:50:52.495Z,1545155452.495 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-12-18T17:50:52.510Z,1545155452.510 [Onboard] Loaded
2018-12-18T17:50:52.511Z,1545155452.511 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-12-18T17:50:52.521Z,1545155452.521 [Radio_Surface] Loaded
2018-12-18T17:50:52.521Z,1545155452.521 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-12-18T17:50:52.522Z,1545155452.522 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-12-18T17:50:52.522Z,1545155452.522 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 1091
2018-12-18T17:50:52.568Z,1545155452.568 [PNI_TCM] Loaded
2018-12-18T17:50:52.568Z,1545155452.568 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-12-18T17:50:52.569Z,1545155452.569 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-12-18T17:50:52.570Z,1545155452.570 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-12-18T17:50:52.702Z,1545155452.702 [SBIT](DEBUG): Construct Startup Built In Test.
2018-12-18T17:50:52.723Z,1545155452.723 [SBIT] Loaded
2018-12-18T17:50:52.723Z,1545155452.723 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-12-18T17:50:52.724Z,1545155452.724 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-12-18T17:50:52.737Z,1545155452.737 [IBIT] Loaded
2018-12-18T17:50:52.737Z,1545155452.737 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-12-18T17:50:52.740Z,1545155452.740 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-12-18T17:50:53.116Z,1545155453.116 [CBIT] Loaded
2018-12-18T17:50:53.116Z,1545155453.116 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-12-18T17:50:53.116Z,1545155453.116 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-12-18T17:50:53.117Z,1545155453.117 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-12-18T17:50:53.354Z,1545155453.354 [CTD_NeilBrown] Loaded
2018-12-18T17:50:53.355Z,1545155453.355 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-12-18T17:50:53.356Z,1545155453.356 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 4096F4E0
2018-12-18T17:50:53.356Z,1545155453.356 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 1092
2018-12-18T17:50:53.436Z,1545155453.436 [CTD_Seabird] Loaded
2018-12-18T17:50:53.437Z,1545155453.437 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-12-18T17:50:53.438Z,1545155453.438 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 4099F4E0
2018-12-18T17:50:53.438Z,1545155453.438 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 1093
2018-12-18T17:50:53.452Z,1545155453.452 [PAR_Licor] Loaded
2018-12-18T17:50:53.452Z,1545155453.452 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-12-18T17:50:53.502Z,1545155453.502 [WetLabsBB2FL] Loaded
2018-12-18T17:50:53.502Z,1545155453.502 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-12-18T17:50:53.503Z,1545155453.503 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409CF4E0
2018-12-18T17:50:53.503Z,1545155453.503 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 1094
2018-12-18T17:50:53.504Z,1545155453.504 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-12-18T17:50:53.504Z,1545155453.504 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-12-18T17:50:53.570Z,1545155453.570 [VerticalControl](DEBUG): Construct VerticalControl.
2018-12-18T17:50:53.652Z,1545155453.652 [VerticalControl] Loaded
2018-12-18T17:50:53.652Z,1545155453.652 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-12-18T17:50:53.653Z,1545155453.653 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-12-18T17:50:53.708Z,1545155453.708 [HorizontalControl] Loaded
2018-12-18T17:50:53.709Z,1545155453.709 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-12-18T17:50:53.710Z,1545155453.710 [SpeedControl](DEBUG): Construct SpeedControl.
2018-12-18T17:50:53.711Z,1545155453.711 [SpeedControl] Loaded
2018-12-18T17:50:53.711Z,1545155453.711 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-12-18T17:50:53.712Z,1545155453.712 [LoopControl](DEBUG): Construct LoopControl.
2018-12-18T17:50:53.713Z,1545155453.713 [LoopControl] Loaded
2018-12-18T17:50:53.713Z,1545155453.713 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-12-18T17:50:53.713Z,1545155453.713 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-12-18T17:50:53.714Z,1545155453.714 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-12-18T17:50:53.740Z,1545155453.740 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-12-18T17:50:53.740Z,1545155453.740 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-12-18T17:50:53.836Z,1545155453.836 [DeadReckonUsingSpeedCalculator] Loaded
2018-12-18T17:50:53.836Z,1545155453.836 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-12-18T17:50:53.853Z,1545155453.853 [NavChart] Loaded
2018-12-18T17:50:53.853Z,1545155453.853 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-12-18T17:50:53.857Z,1545155453.857 [UniversalFixResidualReporter] Loaded
2018-12-18T17:50:53.857Z,1545155453.857 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-12-18T17:50:53.858Z,1545155453.858 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-12-18T17:50:53.861Z,1545155453.861 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-12-18T17:50:53.862Z,1545155453.862 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-12-18T17:50:53.869Z,1545155453.869 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-12-18T17:50:53.870Z,1545155453.870 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A684E0
2018-12-18T17:50:53.870Z,1545155453.870 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 1095
2018-12-18T17:50:53.874Z,1545155453.874 [Supervisor](INFO): Main Thread ID is 797
2018-12-18T17:50:53.875Z,1545155453.875 [Supervisor](DEBUG): Running supervisor.
2018-12-18T17:50:53.875Z,1545155453.875 [CommandLine ThreadHandler](INFO): Handler Thread ID is 1096
2018-12-18T17:50:53.878Z,1545155453.878 [controlThread ThreadHandler](INFO): Handler Thread ID is 1097
2018-12-18T17:50:53.878Z,1545155453.878 [controlThread](DEBUG): Initializing ControlThread
2018-12-18T17:50:53.879Z,1545155453.879 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-12-18T17:50:53.879Z,1545155453.879 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-12-18T17:50:53.880Z,1545155453.880 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-12-18T17:50:53.880Z,1545155453.880 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-12-18T17:50:53.880Z,1545155453.880 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-12-18T17:50:53.881Z,1545155453.881 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-12-18T17:50:53.887Z,1545155453.887 [SBIT](INFO): Initialize SBIT Component.
2018-12-18T17:50:53.887Z,1545155453.887 [SBIT](IMPORTANT): git: 2018-12-13
2018-12-18T17:50:53.888Z,1545155453.888 [SBIT](INFO): git hash: 8200dc43e6ef01082c531ff0fab84136a371dc2d
2018-12-18T17:50:53.888Z,1545155453.888 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-12-18T17:50:53.888Z,1545155453.888 [SBIT](IMPORTANT): Kernel Version:#2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-12-18T17:50:53.889Z,1545155453.889 [SBIT](INFO): Beginning SBIT in 36.000000 seconds.
2018-12-18T17:50:53.890Z,1545155453.890 [IBIT](INFO): Initialize IBIT Component.
2018-12-18T17:50:53.891Z,1545155453.891 [CBIT](DEBUG): Initialize CBIT Component.
2018-12-18T17:50:53.892Z,1545155453.892 [logger ThreadHandler](INFO): Handler Thread ID is 1098
2018-12-18T17:50:53.905Z,1545155453.905 [CBIT](DEBUG): Initialized mux pins.
2018-12-18T17:50:53.905Z,1545155453.905 [CBIT](DEBUG): Initializing the watchdog timer.
2018-12-18T17:50:53.909Z,1545155453.909 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 1099
2018-12-18T17:50:53.915Z,1545155453.915 [Radio_Surface](INFO): Powering up
2018-12-18T17:50:53.925Z,1545155453.925 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 1100
2018-12-18T17:50:53.926Z,1545155453.926 [CTD_NeilBrown](INFO): Powering down
2018-12-18T17:50:53.933Z,1545155453.933 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2018-12-18T17:50:53.933Z,1545155453.933 [CBIT](DEBUG): Initializing heartbeat.
2018-12-18T17:50:53.953Z,1545155453.953 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 1101
2018-12-18T17:50:53.954Z,1545155453.954 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2018-12-18T17:50:53.958Z,1545155453.958 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 1103
2018-12-18T17:50:53.960Z,1545155453.960 [WetLabsBB2FL](INFO): Powering down
2018-12-18T17:50:53.978Z,1545155453.978 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2018-12-18T17:50:53.986Z,1545155453.986 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 1104
2018-12-18T17:50:53.994Z,1545155453.994 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-12-18T17:50:53.994Z,1545155453.994 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-12-18T17:50:53.995Z,1545155453.995 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-12-18T17:50:53.996Z,1545155453.996 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-12-18T17:50:53.996Z,1545155453.996 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-12-18T17:50:53.996Z,1545155453.996 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-12-18T17:50:53.996Z,1545155453.996 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-12-18T17:50:53.996Z,1545155453.996 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-12-18T17:50:54.005Z,1545155454.005 [CBIT](DEBUG): Deactivating GF circuits.
2018-12-18T17:50:54.005Z,1545155454.005 [CBIT](DEBUG): Deactivating emergency mode.
2018-12-18T17:50:54.005Z,1545155454.005 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-12-18T17:50:54.005Z,1545155454.005 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-12-18T17:50:54.006Z,1545155454.006 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-12-18T17:50:54.045Z,1545155454.045 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-12-18T17:50:54.047Z,1545155454.047 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-12-18T17:50:54.048Z,1545155454.048 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-12-18T17:50:54.048Z,1545155454.048 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-12-18T17:50:54.048Z,1545155454.048 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-12-18T17:50:54.049Z,1545155454.049 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-12-18T17:50:54.050Z,1545155454.050 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-12-18T17:50:54.050Z,1545155454.050 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-12-18T17:50:54.051Z,1545155454.051 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-12-18T17:50:54.052Z,1545155454.052 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-12-18T17:50:54.078Z,1545155454.078 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-12-18T17:50:54.130Z,1545155454.130 [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>


2018-12-18T17:50:54.130Z,1545155454.130 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-12-18T17:50:54.232Z,1545155454.232 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-12-18T17:50:54.233Z,1545155454.233 [Default:A.Wait](DEBUG): Construct Wait.
2018-12-18T17:50:54.235Z,1545155454.235 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-12-18T17:50:54.301Z,1545155454.301 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-12-18T17:50:54.304Z,1545155454.304 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-12-18T17:50:54.338Z,1545155454.338 [Default:E.Execute](DEBUG): Construct Execute.
2018-12-18T17:50:54.341Z,1545155454.341 [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>


2018-12-18T17:50:54.361Z,1545155454.361 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-12-18T17:50:54.402Z,1545155454.402 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-12-18T17:50:55.045Z,1545155455.045 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-12-18T17:50:55.057Z,1545155455.057 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-12-18T17:50:55.075Z,1545155455.075 [ElevatorServo](DEBUG): Initializing EZServoServo.
2018-12-18T17:50:55.097Z,1545155455.097 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2018-12-18T17:50:55.119Z,1545155455.119 [MassServo](DEBUG): Initializing EZServoServo.
2018-12-18T17:50:55.126Z,1545155455.126 [MassServo](DEBUG): Initializing MassServo.
2018-12-18T17:50:55.155Z,1545155455.155 [RudderServo](DEBUG): Initializing EZServoServo.
2018-12-18T17:50:55.169Z,1545155455.169 [RudderServo](DEBUG): Initializing RudderServo.
2018-12-18T17:50:55.174Z,1545155455.174 [ThrusterServo](DEBUG): Initializing EZServoServo.
2018-12-18T17:50:55.185Z,1545155455.185 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2018-12-18T17:51:22.711Z,1545155482.711 [NAL9602](INFO): Powering up NAL9602
2018-12-18T17:51:30.412Z,1545155490.412 [SBIT](IMPORTANT): Beginning Startup BIT
2018-12-18T17:51:30.420Z,1545155490.420 [CBIT](IMPORTANT): Beginning ground fault scan
2018-12-18T17:51:33.630Z,1545155493.630 [NAL9602](INFO): NAL9602 initialized
2018-12-18T17:51:41.343Z,1545155501.343 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 4.657929
CHAN A1 (24V): -0.015206
CHAN A2 (12V): 4.697929
CHAN A3 (5V): -0.001524
CHAN B0 (3.3V): -0.000216
CHAN B1 (3.15aV): 0.000152
CHAN B2 (3.15bV): -0.000299
CHAN B3 (GND): 0.000265
OPEN: -0.000415
Full Scale Calc: 4.765 mA, -1.589 mA
2018-12-18T17:51:54.632Z,1545155514.632 [NAL9602](INFO): SBD MO Status=0, MOMSN=10794, MT Status=0, MTMSN=0
2018-12-18T17:51:54.632Z,1545155514.632 [NAL9602](INFO): No messages in MT queue
2018-12-18T17:52:02.240Z,1545155522.240 [NAL9602](INFO): GPS fix at 20181218T175200: (36.802737, -121.786909)
2018-12-18T17:52:24.407Z,1545155544.407 [SBIT](IMPORTANT): SBIT PASSED
2018-12-18T17:52:24.473Z,1545155544.473 [CommandLine](IMPORTANT): got command configSet list
2018-12-18T17:52:24.473Z,1545155544.473 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-12-18T17:52:24.475Z,1545155544.475 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool;

2018-12-18T17:52:24.475Z,1545155544.475 [CommandLine](IMPORTANT): BPC1.batteryMuxCycleTime=10 minute;

2018-12-18T17:52:24.475Z,1545155544.475 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=1 bool;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_salinity;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_temperature 0.150000 kelvin;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express linearApproximation CTD_NeilBrown.bin_median_sea_water_salinity 0.020000 practical_salinity_unit;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express linearApproximation CTD_NeilBrown.bin_median_sea_water_temperature 0.150000 kelvin;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;

2018-12-18T17:52:24.476Z,1545155544.476 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;

2018-12-18T17:52:24.477Z,1545155544.477 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=213 cubic_centimeter;

2018-12-18T17:52:24.478Z,1545155544.478 [CommandLine](IMPORTANT): VerticalControl.massDefault=4 millimeter;

2018-12-18T17:52:24.821Z,1545155544.821 [MissionManager](IMPORTANT): Started mission Startup
2018-12-18T17:52:24.821Z,1545155544.821 [Startup] Running Loop=1
2018-12-18T17:52:24.822Z,1545155544.822 [Startup](DEBUG): Aggregate::initialize Startup
2018-12-18T17:52:24.822Z,1545155544.822 [Startup:A.GoToSurface] Running Loop=1
2018-12-18T17:52:24.822Z,1545155544.822 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-12-18T17:52:24.822Z,1545155544.822 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-12-18T17:52:24.823Z,1545155544.823 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-12-18T17:52:24.823Z,1545155544.823 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-12-18T17:52:24.824Z,1545155544.824 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-12-18T17:52:24.824Z,1545155544.824 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-12-18T17:52:24.829Z,1545155544.829 [Startup:StartupSatComms] Running Loop=1
2018-12-18T17:52:24.829Z,1545155544.829 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-12-18T17:52:24.830Z,1545155544.830 [Startup:StartupSatComms:A] Running Loop=1
2018-12-18T17:52:25.194Z,1545155545.194 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-12-18T17:52:26.770Z,1545155546.770 [NAL9602](INFO): GPS fix at 20181218T175224: (36.802729, -121.786916)
2018-12-18T17:52:26.826Z,1545155546.826 [Startup:StartupSatComms:A] Stopped
2018-12-18T17:52:26.827Z,1545155546.827 [Startup:StartupSatComms:B] Running Loop=1
2018-12-18T17:52:27.214Z,1545155547.214 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-12-18T17:52:53.676Z,1545155573.676 [NAL9602](INFO): SBD MO Status=2, MOMSN=10795, MT Status=2, MTMSN=0
2018-12-18T17:52:53.676Z,1545155573.676 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-12-18T17:53:14.979Z,1545155594.979 [NAL9602](INFO): SBD MO Status=2, MOMSN=10795, MT Status=2, MTMSN=0
2018-12-18T17:53:14.980Z,1545155594.980 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2018-12-18T17:53:27.128Z,1545155607.128 [Startup:StartupSatComms:B](INFO): Timed out from 2018-12-18T17:52:26.8Z
2018-12-18T17:53:27.128Z,1545155607.128 [Startup:StartupSatComms:B] Stopped
2018-12-18T17:53:27.128Z,1545155607.128 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-12-18T17:53:27.130Z,1545155607.130 [Startup:StartupSatComms] Stopped
2018-12-18T17:53:27.130Z,1545155607.130 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-12-18T17:53:27.131Z,1545155607.131 [Startup](INFO): Completed Startup
2018-12-18T17:53:27.131Z,1545155607.131 [MissionManager](INFO): Startup is completed.
2018-12-18T17:53:27.131Z,1545155607.131 [MissionManager](INFO): Uninitializing Mission Startup
2018-12-18T17:53:27.131Z,1545155607.131 [Startup] Stopped
2018-12-18T17:53:27.131Z,1545155607.131 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-12-18T17:53:27.131Z,1545155607.131 [Startup:A.GoToSurface] Stopped
2018-12-18T17:53:27.131Z,1545155607.131 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-12-18T17:53:27.529Z,1545155607.529 [MissionManager](IMPORTANT): Started mission Default
2018-12-18T17:53:27.530Z,1545155607.530 [Default] Running Loop=1
2018-12-18T17:53:27.530Z,1545155607.530 [Default](DEBUG): Aggregate::initialize Default
2018-12-18T17:53:27.530Z,1545155607.530 [Default:B.GoToSurface] Running Loop=1
2018-12-18T17:53:27.530Z,1545155607.530 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-12-18T17:53:27.530Z,1545155607.530 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-12-18T17:53:27.530Z,1545155607.530 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-12-18T17:53:27.531Z,1545155607.531 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-12-18T17:53:27.531Z,1545155607.531 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-12-18T17:53:27.531Z,1545155607.531 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-12-18T17:53:27.532Z,1545155607.532 [Default:A.Wait] Running Loop=1
2018-12-18T17:53:27.532Z,1545155607.532 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-12-18T17:53:33.479Z,1545155613.479 [NAL9602](INFO): SBD MO Status=1, MOMSN=10795, MT Status=0, MTMSN=0
2018-12-18T17:53:33.529Z,1545155613.529 [NAL9602](INFO): Sent 25 bytes from file Logs/20181218T171601/Courier0016.lzma
2018-12-18T17:53:33.529Z,1545155613.529 [NAL9602](INFO): Packets left to send: 0
2018-12-18T17:53:33.531Z,1545155613.531 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T171601/Courier0016.lzma.parts/0000.sbd
2018-12-18T17:53:33.531Z,1545155613.531 [NAL9602](DEBUG): Completed sending Logs/20181218T171601/Courier0016.lzma
2018-12-18T17:53:40.724Z,1545155620.724 [Default:A.Wait](INFO): Done Waiting.
2018-12-18T17:53:40.724Z,1545155620.724 [Default:A.Wait] Stopped
2018-12-18T17:53:40.724Z,1545155620.724 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-12-18T17:53:41.130Z,1545155621.130 [Default:CheckIn] Running Loop=1
2018-12-18T17:53:41.130Z,1545155621.130 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-12-18T17:53:41.130Z,1545155621.130 [Default:CheckIn:Read_GPS] Running Loop=1
2018-12-18T17:53:41.531Z,1545155621.531 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-12-18T17:53:43.082Z,1545155623.082 [NAL9602](INFO): GPS fix at 20181218T175341: (36.802731, -121.786929)
2018-12-18T17:53:43.144Z,1545155623.144 [Default:CheckIn:Read_GPS] Stopped
2018-12-18T17:53:43.145Z,1545155623.145 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-12-18T17:53:43.565Z,1545155623.565 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-12-18T17:54:06.783Z,1545155646.783 [NAL9602](INFO): SBD MO Status=1, MOMSN=10796, MT Status=0, MTMSN=0
2018-12-18T17:54:06.833Z,1545155646.833 [NAL9602](INFO): Sent 210 bytes from file Logs/20181218T175045/Courier0000.lzma
2018-12-18T17:54:06.833Z,1545155646.833 [NAL9602](INFO): Packets left to send: 0
2018-12-18T17:54:06.835Z,1545155646.835 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Courier0000.lzma.parts/0000.sbd
2018-12-18T17:54:06.835Z,1545155646.835 [NAL9602](DEBUG): Completed sending Logs/20181218T175045/Courier0000.lzma
2018-12-18T17:54:14.084Z,1545155654.084 [NAL9602](INFO): SBD MO Status=1, MOMSN=10797, MT Status=0, MTMSN=0
2018-12-18T17:54:14.133Z,1545155654.133 [NAL9602](INFO): Sent 62 bytes from file Logs/20181218T175045/Courier0004.lzma
2018-12-18T17:54:14.133Z,1545155654.133 [NAL9602](INFO): Packets left to send: 0
2018-12-18T17:54:14.135Z,1545155654.135 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Courier0004.lzma.parts/0000.sbd
2018-12-18T17:54:14.135Z,1545155654.135 [NAL9602](DEBUG): Completed sending Logs/20181218T175045/Courier0004.lzma
2018-12-18T17:54:23.367Z,1545155663.367 [NAL9602](INFO): SBD MO Status=1, MOMSN=10798, MT Status=0, MTMSN=0
2018-12-18T17:54:23.421Z,1545155663.421 [NAL9602](INFO): Sent 196 bytes from file Logs/20181218T171601/Express0017.lzma
2018-12-18T17:54:23.421Z,1545155663.421 [NAL9602](INFO): Packets left to send: 0
2018-12-18T17:54:23.439Z,1545155663.439 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T171601/Express0017.lzma.parts/0000.sbd
2018-12-18T17:54:23.440Z,1545155663.440 [NAL9602](DEBUG): Completed sending Logs/20181218T171601/Express0017.lzma
2018-12-18T17:54:34.300Z,1545155674.300 [NAL9602](INFO): SBD MO Status=1, MOMSN=10799, MT Status=0, MTMSN=0
2018-12-18T17:54:34.349Z,1545155674.349 [NAL9602](INFO): Sent 332 bytes from file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:54:34.349Z,1545155674.349 [NAL9602](INFO): Packets left to send: 3
2018-12-18T17:54:34.354Z,1545155674.354 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Express0001.lzma.parts/0003.sbd
2018-12-18T17:54:46.439Z,1545155686.439 [NAL9602](INFO): SBD MO Status=1, MOMSN=10800, MT Status=0, MTMSN=0
2018-12-18T17:54:46.489Z,1545155686.489 [NAL9602](INFO): Sent 332 bytes from file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:54:46.489Z,1545155686.489 [NAL9602](INFO): Packets left to send: 2
2018-12-18T17:54:46.490Z,1545155686.490 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Express0001.lzma.parts/0002.sbd
2018-12-18T17:54:59.280Z,1545155699.280 [NAL9602](INFO): SBD MO Status=1, MOMSN=10801, MT Status=0, MTMSN=0
2018-12-18T17:54:59.329Z,1545155699.329 [NAL9602](INFO): Sent 332 bytes from file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:54:59.329Z,1545155699.329 [NAL9602](INFO): Packets left to send: 1
2018-12-18T17:54:59.330Z,1545155699.330 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Express0001.lzma.parts/0001.sbd
2018-12-18T17:55:01.988Z,1545155701.988 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004138
2018-12-18T17:55:07.924Z,1545155707.924 [NAL9602](INFO): SBD MO Status=1, MOMSN=10802, MT Status=0, MTMSN=0
2018-12-18T17:55:07.977Z,1545155707.977 [NAL9602](INFO): Sent 30 bytes from file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:07.978Z,1545155707.978 [NAL9602](INFO): Packets left to send: 0
2018-12-18T17:55:07.979Z,1545155707.979 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181218T175045/Express0001.lzma.parts/0000.sbd
2018-12-18T17:55:07.979Z,1545155707.979 [NAL9602](DEBUG): Completed sending Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:08.090Z,1545155708.090 [Default:CheckIn:Read_Iridium] Stopped
2018-12-18T17:55:08.090Z,1545155708.090 [Default:CheckIn:C.Wait] Running Loop=1
2018-12-18T17:55:08.090Z,1545155708.090 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-12-18T17:55:08.171Z,1545155708.171 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:08.171Z,1545155708.171 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:08.312Z,1545155708.312 [CommandLine](FAULT): Scheduling is paused
2018-12-18T17:55:08.337Z,1545155708.337 [CBIT](INFO): Critical error at 20181218T175508
2018-12-18T17:55:08.337Z,1545155708.337 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-12-18T17:55:13.086Z,1545155713.086 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:13.086Z,1545155713.086 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:55:13.223Z,1545155713.223 [CBIT](INFO): Critical error at 20181218T175513
2018-12-18T17:55:22.768Z,1545155722.768 [CommandLine](IMPORTANT): got command failComponent
2018-12-18T17:55:22.769Z,1545155722.769 [CommandLine](IMPORTANT): Failed components:
2018-12-18T17:55:22.769Z,1545155722.769 [CommandLine](IMPORTANT): No failed Components.
2018-12-18T17:55:25.958Z,1545155725.958 [CommandLine](IMPORTANT): got command ibit
2018-12-18T17:55:25.987Z,1545155725.987 [IBIT](IMPORTANT): Beginning Initiated BIT
2018-12-18T17:55:25.987Z,1545155725.987 [IBIT](IMPORTANT): Beginning control surface checks.
2018-12-18T17:55:25.990Z,1545155725.990 [CBIT](IMPORTANT): Beginning ground fault scan
2018-12-18T17:55:27.507Z,1545155727.507 [NAL9602](INFO): GPS fix at 20181218T175525: (36.802728, -121.786911)
2018-12-18T17:55:29.898Z,1545155729.898 [NAL9602](INFO): GPS fix at 20181218T175528: (36.802731, -121.786911)
2018-12-18T17:55:33.092Z,1545155733.092 [NAL9602](INFO): GPS fix at 20181218T175531: (36.802733, -121.786910)
2018-12-18T17:55:35.895Z,1545155735.895 [NAL9602](INFO): GPS fix at 20181218T175534: (36.802733, -121.786909)
2018-12-18T17:55:36.768Z,1545155736.768 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.012076
CHAN A1 (24V): -0.015200
CHAN A2 (12V): -0.002316
CHAN A3 (5V): 4.753929
CHAN B0 (3.3V): 0.001570
CHAN B1 (3.15aV): -0.000045
CHAN B2 (3.15bV): 0.000142
CHAN B3 (GND): 0.000385
OPEN: -0.000465
Full Scale Calc: 4.765 mA, -1.589 mA
2018-12-18T17:55:39.094Z,1545155739.094 [NAL9602](INFO): GPS fix at 20181218T175537: (36.802733, -121.786908)
2018-12-18T17:55:41.894Z,1545155741.894 [NAL9602](INFO): GPS fix at 20181218T175540: (36.802733, -121.786908)
2018-12-18T17:55:45.098Z,1545155745.098 [NAL9602](INFO): GPS fix at 20181218T175543: (36.802733, -121.786907)
2018-12-18T17:55:47.894Z,1545155747.894 [NAL9602](INFO): GPS fix at 20181218T175546: (36.802733, -121.786909)
2018-12-18T17:55:49.213Z,1545155749.213 [CommandLine](IMPORTANT): got command get NAL9602.sigQuality
2018-12-18T17:55:49.214Z,1545155749.214 [CommandLine](IMPORTANT): NAL9602.sigQuality 4 count
2018-12-18T17:55:51.094Z,1545155751.094 [NAL9602](INFO): GPS fix at 20181218T175549: (36.802733, -121.786913)
2018-12-18T17:55:53.902Z,1545155753.902 [NAL9602](INFO): GPS fix at 20181218T175552: (36.802729, -121.786918)
2018-12-18T17:55:57.094Z,1545155757.094 [NAL9602](INFO): GPS fix at 20181218T175555: (36.802729, -121.786920)
2018-12-18T17:55:59.894Z,1545155759.894 [NAL9602](INFO): GPS fix at 20181218T175558: (36.802730, -121.786922)
2018-12-18T17:56:03.094Z,1545155763.094 [NAL9602](INFO): GPS fix at 20181218T175601: (36.802730, -121.786923)
2018-12-18T17:56:05.894Z,1545155765.894 [NAL9602](INFO): GPS fix at 20181218T175604: (36.802733, -121.786924)
2018-12-18T17:56:09.094Z,1545155769.094 [NAL9602](INFO): GPS fix at 20181218T175607: (36.802733, -121.786924)
2018-12-18T17:56:13.277Z,1545155773.277 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:56:13.277Z,1545155773.277 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:56:13.382Z,1545155773.382 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 36.802734 Longitude: -121.786926
2018-12-18T17:56:13.383Z,1545155773.383 [CBIT](INFO): Critical error at 20181218T175613
2018-12-18T17:56:13.740Z,1545155773.740 [IBIT](FAULT): Warning: Battery Data not active. Expected only when running primaries. Threshold checking not active.
2018-12-18T17:56:14.082Z,1545155774.082 [NAL9602](INFO): GPS fix at 20181218T175612: (36.802730, -121.786925)
2018-12-18T17:56:14.146Z,1545155774.146 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2018-12-18T17:56:14.146Z,1545155774.146 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2018-12-18T17:56:14.146Z,1545155774.146 [IBIT](IMPORTANT): Pressure:9.971053 PSI
2018-12-18T17:56:14.147Z,1545155774.147 [IBIT](IMPORTANT): Humidity:15.901598 %
2018-12-18T17:56:14.534Z,1545155774.534 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2018-12-18T17:56:14.535Z,1545155774.535 [IBIT](IMPORTANT): buoyancyNeutral: 213.000000 cc
2018-12-18T17:56:14.535Z,1545155774.535 [IBIT](IMPORTANT): massDefault: 0.400000 cm
2018-12-18T17:56:14.535Z,1545155774.535 [IBIT](IMPORTANT): stopDepth: 205.000000 m
2018-12-18T17:56:14.535Z,1545155774.535 [IBIT](IMPORTANT): abortDepth: 250.000000 m
2018-12-18T17:56:14.536Z,1545155774.536 [IBIT](IMPORTANT): IBIT PASSED
2018-12-18T17:56:46.478Z,1545155806.478 [NAL9602](INFO): Powering down
2018-12-18T17:57:13.281Z,1545155833.281 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:57:13.282Z,1545155833.282 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:57:13.399Z,1545155833.399 [CBIT](INFO): Critical error at 20181218T175713
2018-12-18T17:57:59.556Z,1545155879.556 [CommandLine](IMPORTANT): got command failComponent
2018-12-18T17:57:59.556Z,1545155879.556 [CommandLine](IMPORTANT): Failed components:
2018-12-18T17:57:59.557Z,1545155879.557 [CommandLine](IMPORTANT): No failed Components.
2018-12-18T17:58:13.735Z,1545155893.735 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:58:13.735Z,1545155893.735 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:58:13.863Z,1545155893.863 [CBIT](INFO): Critical error at 20181218T175813
2018-12-18T17:59:13.930Z,1545155953.930 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:59:13.930Z,1545155953.930 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T17:59:14.031Z,1545155954.031 [CBIT](INFO): Critical error at 20181218T175913
2018-12-18T18:00:08.375Z,1545156008.375 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2018-12-18T18:00:08.375Z,1545156008.375 [Default:CheckIn:C.Wait] Stopped
2018-12-18T18:00:08.375Z,1545156008.375 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-12-18T18:00:08.376Z,1545156008.376 [Default:CheckIn:D] Running Loop=1
2018-12-18T18:00:08.783Z,1545156008.783 [Default:CheckIn:D] Stopped
2018-12-18T18:00:08.783Z,1545156008.783 [Default:CheckIn:E] Running Loop=1
2018-12-18T18:00:09.158Z,1545156009.158 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.687535 min 
2018-12-18T18:00:09.160Z,1545156009.160 [Default:CheckIn:E] Stopped
2018-12-18T18:00:09.160Z,1545156009.160 [Default:CheckIn](INFO): Completed Default:CheckIn
2018-12-18T18:00:09.160Z,1545156009.160 [Default:CheckIn] Stopped
2018-12-18T18:00:09.177Z,1545156009.177 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-12-18T18:00:09.177Z,1545156009.177 [Default:CheckIn](INFO): Running loop #2
2018-12-18T18:00:09.177Z,1545156009.177 [Default:CheckIn] Running Loop=2
2018-12-18T18:00:09.177Z,1545156009.177 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-12-18T18:00:09.177Z,1545156009.177 [Default:CheckIn:Read_GPS] Running Loop=1
2018-12-18T18:00:09.924Z,1545156009.924 [NAL9602](INFO): Powering up
2018-12-18T18:00:13.932Z,1545156013.932 [DataOverHttps](IMPORTANT): Could not stat file Logs/20181218T175045/Express0001.lzma
2018-12-18T18:00:13.932Z,1545156013.932 [DataOverHttps](CRITICAL): Could not open file Logs/20181218T175045/Express0001.lzma
2018-12-18T18:00:14.047Z,1545156014.047 [CBIT](INFO): Critical error at 20181218T180013
2018-12-18T18:00:20.734Z,1545156020.734 [NAL9602](INFO): NAL9602 initialized