2019-05-27T12:41:11.443Z,1558960871.443 [Supervisor](DEBUG): Initializing supervisor.
2019-05-27T12:41:11.446Z,1558960871.446 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-27T12:41:11.447Z,1558960871.447 [SyncHandler](INFO): Protected caller Thread ID is 3340
2019-05-27T12:41:11.447Z,1558960871.447 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-27T12:41:11.448Z,1558960871.448 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-27T12:41:11.448Z,1558960871.448 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 3341
2019-05-27T12:41:11.451Z,1558960871.451 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-27T12:41:11.474Z,1558960871.474 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-27T12:41:11.475Z,1558960871.475 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-27T12:41:11.475Z,1558960871.475 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 3342
2019-05-27T12:41:11.476Z,1558960871.476 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-27T12:41:11.477Z,1558960871.477 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-27T12:41:11.477Z,1558960871.477 [logger ThreadHandler](INFO): Protected caller Thread ID is 3343
2019-05-27T12:41:11.479Z,1558960871.479 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-27T12:41:11.479Z,1558960871.479 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-27T12:41:11.481Z,1558960871.481 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-27T12:41:11.579Z,1558960871.579 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-27T12:41:11.580Z,1558960871.580 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-27T12:41:12.125Z,1558960872.125 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-27T12:41:12.126Z,1558960872.126 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-27T12:41:12.227Z,1558960872.227 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-27T12:41:12.228Z,1558960872.228 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-27T12:41:12.333Z,1558960872.333 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-27T12:41:12.334Z,1558960872.334 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-27T12:41:12.418Z,1558960872.418 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-27T12:41:12.559Z,1558960872.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-27T12:41:12.559Z,1558960872.559 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-27T12:41:12.856Z,1558960872.856 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-27T12:41:12.857Z,1558960872.857 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-27T12:41:13.313Z,1558960873.313 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-27T12:41:13.314Z,1558960873.314 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-27T12:41:13.462Z,1558960873.462 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-27T12:41:13.463Z,1558960873.463 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-27T12:41:13.664Z,1558960873.664 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-27T12:41:13.665Z,1558960873.665 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-27T12:41:14.119Z,1558960874.119 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-27T12:41:14.119Z,1558960874.119 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-27T12:41:14.339Z,1558960874.339 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-27T12:41:14.340Z,1558960874.340 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-27T12:41:14.543Z,1558960874.543 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-27T12:41:14.544Z,1558960874.544 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-27T12:41:14.930Z,1558960874.930 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-27T12:41:14.930Z,1558960874.930 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-27T12:41:15.266Z,1558960875.266 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-27T12:41:15.268Z,1558960875.268 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-05-27T12:41:15.269Z,1558960875.269 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-05-27T12:41:15.355Z,1558960875.355 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-05-27T12:41:15.512Z,1558960875.512 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-05-27T12:41:15.624Z,1558960875.624 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-05-27T12:41:15.713Z,1558960875.713 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-05-27T12:41:15.811Z,1558960875.811 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-05-27T12:41:16.007Z,1558960876.007 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-05-27T12:41:16.276Z,1558960876.276 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-27T12:41:16.277Z,1558960876.277 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-05-27T12:41:16.382Z,1558960876.382 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-05-27T12:41:16.491Z,1558960876.491 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-05-27T12:41:16.689Z,1558960876.689 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-05-27T12:41:16.933Z,1558960876.933 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/LOGIN/
2019-05-27T12:41:16.933Z,1558960876.933 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-27T12:41:16.941Z,1558960876.941 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-27T12:41:17.052Z,1558960877.052 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-27T12:41:17.364Z,1558960877.364 [VerticalControl] Loaded
2019-05-27T12:41:17.364Z,1558960877.364 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-27T12:41:17.365Z,1558960877.365 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-27T12:41:17.631Z,1558960877.631 [HorizontalControl] Loaded
2019-05-27T12:41:17.631Z,1558960877.631 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-27T12:41:17.632Z,1558960877.632 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-27T12:41:17.637Z,1558960877.637 [SpeedControl] Loaded
2019-05-27T12:41:17.637Z,1558960877.637 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-27T12:41:17.638Z,1558960877.638 [LoopControl](DEBUG): Construct LoopControl.
2019-05-27T12:41:17.638Z,1558960877.638 [LoopControl] Loaded
2019-05-27T12:41:17.639Z,1558960877.639 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-27T12:41:17.639Z,1558960877.639 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-27T12:41:17.640Z,1558960877.640 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-27T12:41:17.679Z,1558960877.679 [DepthRateCalculator] Loaded
2019-05-27T12:41:17.679Z,1558960877.679 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-27T12:41:17.684Z,1558960877.684 [PitchRateCalculator] Loaded
2019-05-27T12:41:17.685Z,1558960877.685 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-27T12:41:17.699Z,1558960877.699 [SpeedCalculator] Loaded
2019-05-27T12:41:17.700Z,1558960877.700 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-27T12:41:17.720Z,1558960877.720 [TempGradientCalculator] Loaded
2019-05-27T12:41:17.720Z,1558960877.720 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-27T12:41:17.725Z,1558960877.725 [YawRateCalculator] Loaded
2019-05-27T12:41:17.725Z,1558960877.725 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-27T12:41:17.753Z,1558960877.753 [ElevatorOffsetCalculator] Loaded
2019-05-27T12:41:17.753Z,1558960877.753 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-27T12:41:17.754Z,1558960877.754 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-27T12:41:17.754Z,1558960877.754 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-27T12:41:17.780Z,1558960877.780 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-27T12:41:17.781Z,1558960877.781 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-27T12:41:17.846Z,1558960877.846 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-27T12:41:17.847Z,1558960877.847 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-27T12:41:18.123Z,1558960878.123 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-27T12:41:18.124Z,1558960878.124 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-27T12:41:18.215Z,1558960878.215 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-27T12:41:18.216Z,1558960878.216 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-27T12:41:18.502Z,1558960878.502 [Depth_Keller] Loaded
2019-05-27T12:41:18.502Z,1558960878.502 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-27T12:41:18.553Z,1558960878.553 [Micromodem] Loaded
2019-05-27T12:41:18.553Z,1558960878.553 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-27T12:41:18.648Z,1558960878.648 [NAL9602] Loaded
2019-05-27T12:41:18.648Z,1558960878.648 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-27T12:41:18.664Z,1558960878.664 [Onboard] Loaded
2019-05-27T12:41:18.664Z,1558960878.664 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-27T12:41:18.671Z,1558960878.671 [Radio_Surface] Loaded
2019-05-27T12:41:18.671Z,1558960878.671 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-27T12:41:18.672Z,1558960878.672 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408D04E0
2019-05-27T12:41:18.672Z,1558960878.672 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 3422
2019-05-27T12:41:20.125Z,1558960880.125 [BPC1] Loaded
2019-05-27T12:41:20.125Z,1558960880.125 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-27T12:41:20.126Z,1558960880.126 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-27T12:41:20.126Z,1558960880.126 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-27T12:41:20.227Z,1558960880.227 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-27T12:41:20.227Z,1558960880.227 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-27T12:41:20.247Z,1558960880.247 [NavChart] Loaded
2019-05-27T12:41:20.247Z,1558960880.247 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-27T12:41:20.251Z,1558960880.251 [UniversalFixResidualReporter] Loaded
2019-05-27T12:41:20.251Z,1558960880.251 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-27T12:41:20.252Z,1558960880.252 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-27T12:41:20.252Z,1558960880.252 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-27T12:41:20.382Z,1558960880.382 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-27T12:41:20.393Z,1558960880.393 [SBIT] Loaded
2019-05-27T12:41:20.393Z,1558960880.393 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-27T12:41:20.394Z,1558960880.394 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-27T12:41:20.405Z,1558960880.405 [IBIT] Loaded
2019-05-27T12:41:20.405Z,1558960880.405 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-27T12:41:20.409Z,1558960880.409 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-27T12:41:20.542Z,1558960880.542 [CBIT] Loaded
2019-05-27T12:41:20.543Z,1558960880.543 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-27T12:41:20.543Z,1558960880.543 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-27T12:41:20.544Z,1558960880.544 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-27T12:41:20.642Z,1558960880.642 [BuoyancyServo] Loaded
2019-05-27T12:41:20.643Z,1558960880.643 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-27T12:41:20.654Z,1558960880.654 [ElevatorServo] Loaded
2019-05-27T12:41:20.654Z,1558960880.654 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-27T12:41:20.665Z,1558960880.665 [MassServo] Loaded
2019-05-27T12:41:20.665Z,1558960880.665 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-27T12:41:20.676Z,1558960880.676 [RudderServo] Loaded
2019-05-27T12:41:20.676Z,1558960880.676 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-27T12:41:20.687Z,1558960880.687 [ThrusterServo] Loaded
2019-05-27T12:41:20.687Z,1558960880.687 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-27T12:41:20.687Z,1558960880.687 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-27T12:41:20.688Z,1558960880.688 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-27T12:41:20.701Z,1558960880.701 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-27T12:41:20.701Z,1558960880.701 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-27T12:41:20.940Z,1558960880.940 [CTD_NeilBrown] Loaded
2019-05-27T12:41:20.941Z,1558960880.941 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-27T12:41:20.942Z,1558960880.942 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 40A4C4E0
2019-05-27T12:41:20.942Z,1558960880.942 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 3423
2019-05-27T12:41:20.956Z,1558960880.956 [PAR_Licor] Loaded
2019-05-27T12:41:20.957Z,1558960880.957 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2019-05-27T12:41:21.003Z,1558960881.003 [WetLabsBB2FL] Loaded
2019-05-27T12:41:21.003Z,1558960881.003 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-05-27T12:41:21.004Z,1558960881.004 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A7C4E0
2019-05-27T12:41:21.005Z,1558960881.005 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 3424
2019-05-27T12:41:21.005Z,1558960881.005 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-27T12:41:21.009Z,1558960881.009 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-27T12:41:21.010Z,1558960881.010 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-27T12:41:21.017Z,1558960881.017 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-27T12:41:21.018Z,1558960881.018 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AAC4E0
2019-05-27T12:41:21.018Z,1558960881.018 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 3425
2019-05-27T12:41:21.023Z,1558960881.023 [Supervisor](INFO): Main Thread ID is 3339
2019-05-27T12:41:21.023Z,1558960881.023 [Supervisor](DEBUG): Running supervisor.
2019-05-27T12:41:21.023Z,1558960881.023 [CommandLine ThreadHandler](INFO): Handler Thread ID is 3426
2019-05-27T12:41:21.025Z,1558960881.025 [controlThread ThreadHandler](INFO): Handler Thread ID is 3427
2019-05-27T12:41:21.026Z,1558960881.026 [controlThread](DEBUG): Initializing ControlThread
2019-05-27T12:41:21.026Z,1558960881.026 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-27T12:41:21.028Z,1558960881.028 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-27T12:41:21.029Z,1558960881.029 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-27T12:41:21.029Z,1558960881.029 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-27T12:41:21.030Z,1558960881.030 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-27T12:41:21.030Z,1558960881.030 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-27T12:41:21.030Z,1558960881.030 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-27T12:41:21.031Z,1558960881.031 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-27T12:41:21.031Z,1558960881.031 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-27T12:41:21.032Z,1558960881.032 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-27T12:41:21.034Z,1558960881.034 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-27T12:41:21.035Z,1558960881.035 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-27T12:41:21.035Z,1558960881.035 [SBIT](INFO): Initialize SBIT Component.
2019-05-27T12:41:21.035Z,1558960881.035 [SBIT](IMPORTANT): git: 2019-05-01-19-g6ef4ecc
2019-05-27T12:41:21.036Z,1558960881.036 [SBIT](INFO): git hash: 6ef4ecc926d3cc84e5878e2d73d98fd38ff7dcf7
2019-05-27T12:41:21.036Z,1558960881.036 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-27T12:41:21.036Z,1558960881.036 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-05-27T12:41:21.037Z,1558960881.037 [SBIT](INFO): Beginning SBIT in 28.000000 seconds.
2019-05-27T12:41:21.038Z,1558960881.038 [IBIT](INFO): Initialize IBIT Component.
2019-05-27T12:41:21.039Z,1558960881.039 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-27T12:41:21.040Z,1558960881.040 [logger ThreadHandler](INFO): Handler Thread ID is 3428
2019-05-27T12:41:21.053Z,1558960881.053 [CBIT](DEBUG): Initialized mux pins.
2019-05-27T12:41:21.053Z,1558960881.053 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-27T12:41:21.057Z,1558960881.057 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 3429
2019-05-27T12:41:21.065Z,1558960881.065 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 3430
2019-05-27T12:41:21.073Z,1558960881.073 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 3431
2019-05-27T12:41:21.074Z,1558960881.074 [WetLabsBB2FL](INFO): Powering down
2019-05-27T12:41:21.077Z,1558960881.077 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-27T12:41:21.077Z,1558960881.077 [CBIT](DEBUG): Initializing heartbeat.
2019-05-27T12:41:21.105Z,1558960881.105 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 3432
2019-05-27T12:41:21.108Z,1558960881.108 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-27T12:41:21.108Z,1558960881.108 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-27T12:41:21.109Z,1558960881.109 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-27T12:41:21.109Z,1558960881.109 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-27T12:41:21.109Z,1558960881.109 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-27T12:41:21.109Z,1558960881.109 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-27T12:41:21.110Z,1558960881.110 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-27T12:41:21.111Z,1558960881.111 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-27T12:41:21.111Z,1558960881.111 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-27T12:41:21.111Z,1558960881.111 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-27T12:41:21.111Z,1558960881.111 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-27T12:41:21.149Z,1558960881.149 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-27T12:41:21.149Z,1558960881.149 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-27T12:41:21.185Z,1558960881.185 [CBIT](DEBUG): Backplane powered.
2019-05-27T12:41:21.190Z,1558960881.190 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-27T12:41:21.204Z,1558960881.204 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-27T12:41:21.239Z,1558960881.239 [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-27T12:41:21.240Z,1558960881.240 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-27T12:41:21.311Z,1558960881.311 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-27T12:41:21.312Z,1558960881.312 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-27T12:41:21.314Z,1558960881.314 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-27T12:41:21.359Z,1558960881.359 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-27T12:41:21.370Z,1558960881.370 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-27T12:41:21.376Z,1558960881.376 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-27T12:41:21.395Z,1558960881.395 [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-27T12:41:21.399Z,1558960881.399 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,Micromodem,NAL9602,Onboard,BPC1,PAR_Licor,Depth_Keller,PAR_Licor,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-27T12:41:21.434Z,1558960881.434 [Depth_Keller](ERROR): Pressure reading out of range: 1925.893799 decibar
2019-05-27T12:41:21.461Z,1558960881.461 [Radio_Surface](INFO): Powering up
2019-05-27T12:41:21.498Z,1558960881.498 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-27T12:41:21.586Z,1558960881.586 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:21.625Z,1558960881.625 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-27T12:41:21.646Z,1558960881.646 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:21.649Z,1558960881.649 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-27T12:41:21.650Z,1558960881.650 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:21.653Z,1558960881.653 [MassServo](DEBUG): Initializing MassServo.
2019-05-27T12:41:21.654Z,1558960881.654 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:21.665Z,1558960881.665 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-27T12:41:21.666Z,1558960881.666 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:21.704Z,1558960881.704 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-27T12:41:21.823Z,1558960881.823 [Micromodem](INFO): Powering up
2019-05-27T12:41:21.823Z,1558960881.823 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-27T12:41:22.577Z,1558960882.577 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-27T12:41:22.577Z,1558960882.577 [RudderServo](FAULT): Rudder failed to initialize
2019-05-27T12:41:22.577Z,1558960882.577 [RudderServo] Communications Fault, FailCount= 1
2019-05-27T12:41:22.577Z,1558960882.577 [RudderServo](ERROR): Communications Fault
2019-05-27T12:41:22.688Z,1558960882.688 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-27T12:41:22.918Z,1558960882.918 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-27T12:41:22.918Z,1558960882.918 [RudderServo](INFO): Powering down
2019-05-27T12:41:23.572Z,1558960883.572 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-27T12:41:23.702Z,1558960883.702 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-27T12:41:23.706Z,1558960883.706 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-27T12:41:23.706Z,1558960883.706 [RudderServo] No Fault, FailCount= 1
2019-05-27T12:41:26.738Z,1558960886.738 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-05-27T12:41:28.423Z,1558960888.423 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-05-27T12:41:28.424Z,1558960888.424 [Micromodem](INFO): Nmea out: $CCCFG,SRC,7*37

2019-05-27T12:41:39.734Z,1558960899.734 [Micromodem](ERROR): Nmea resend: $CCCFG,SRC,7*37

2019-05-27T12:41:49.026Z,1558960909.026 [Micromodem](INFO): Nmea in: $CACFG,SRC,7*35

2019-05-27T12:41:49.027Z,1558960909.027 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-05-27T12:41:49.027Z,1558960909.027 [NAL9602](INFO): Powering up NAL9602
2019-05-27T12:41:49.494Z,1558960909.494 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-27T12:41:49.498Z,1558960909.498 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-27T12:41:49.834Z,1558960909.834 [Micromodem](INFO): Nmea in: $CACFG,BND,1*39

2019-05-27T12:41:49.835Z,1558960909.835 [Micromodem](INFO): Nmea out: $CCCLK,2019,9-,5-,7T,2:,1:*22

2019-05-27T12:42:00.431Z,1558960920.431 [Micromodem](INFO): Nmea in: $CACLK,2019,09,05,07,02,01*44

2019-05-27T12:42:00.549Z,1558960920.549 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): 0.001399
CHAN A1 (24V): 0.003143
CHAN A2 (12V): -0.006603
CHAN A3 (5V): -0.002334
CHAN B0 (3.3V): 0.000249
CHAN B1 (3.15aV): 0.000231
CHAN B2 (3.15bV): -0.000679
CHAN B3 (GND): 0.002013
OPEN: -0.000185
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-27T12:42:09.879Z,1558960929.879 [NAL9602](ERROR): NAL9602 initialization error.
2019-05-27T12:42:09.879Z,1558960929.879 [NAL9602] Communications Fault, FailCount= 1
2019-05-27T12:42:09.879Z,1558960929.879 [NAL9602](ERROR): Communications Fault
2019-05-27T12:42:10.121Z,1558960930.121 [CBIT](ERROR): Communications Fault in component: NAL9602
2019-05-27T12:42:10.283Z,1558960930.283 [NAL9602](INFO): Powering down
2019-05-27T12:42:11.157Z,1558960931.157 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-27T12:42:11.158Z,1558960931.158 [NAL9602] No Fault, FailCount= 1
2019-05-27T12:42:40.659Z,1558960960.659 [NAL9602](INFO): Powering up NAL9602
2019-05-27T12:42:42.739Z,1558960962.739 [SBIT](IMPORTANT): SBIT PASSED
2019-05-27T12:42:42.797Z,1558960962.797 [CommandLine](IMPORTANT): got command configSet list
2019-05-27T12:42:42.797Z,1558960962.797 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-05-27T12:42:42.798Z,1558960962.798 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool;

2019-05-27T12:42:42.798Z,1558960962.798 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=0 count;

2019-05-27T12:42:42.798Z,1558960962.798 [CommandLine](IMPORTANT): CBIT.vehicleOpen=1 bool;

2019-05-27T12:42:42.798Z,1558960962.798 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool;

2019-05-27T12:42:42.799Z,1558960962.799 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2019-05-27T12:42:42.799Z,1558960962.799 [CommandLine](IMPORTANT): PAR_Licor.loadAtStartup=1 bool;

2019-05-27T12:42:42.799Z,1558960962.799 [CommandLine](IMPORTANT): VerticalControl.surfaceThreshold=1 meter;

2019-05-27T12:42:43.134Z,1558960963.134 [MissionManager](IMPORTANT): Started mission Startup
2019-05-27T12:42:43.134Z,1558960963.134 [Startup] Running Loop=1
2019-05-27T12:42:43.135Z,1558960963.135 [Startup](DEBUG): Aggregate::initialize Startup
2019-05-27T12:42:43.135Z,1558960963.135 [Startup:A.GoToSurface] Running Loop=1
2019-05-27T12:42:43.135Z,1558960963.135 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-27T12:42:43.135Z,1558960963.135 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-27T12:42:43.136Z,1558960963.136 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-27T12:42:43.136Z,1558960963.136 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-27T12:42:43.137Z,1558960963.137 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-27T12:42:43.137Z,1558960963.137 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-27T12:42:43.138Z,1558960963.138 [Startup:StartupSatComms] Running Loop=1
2019-05-27T12:42:43.139Z,1558960963.139 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-05-27T12:42:43.139Z,1558960963.139 [Startup:StartupSatComms:A] Running Loop=1
2019-05-27T12:42:43.515Z,1558960963.515 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-05-27T12:43:01.264Z,1558960981.264 [NAL9602](ERROR): NAL9602 initialization error.
2019-05-27T12:43:01.264Z,1558960981.264 [NAL9602] Communications Fault, FailCount= 2
2019-05-27T12:43:01.264Z,1558960981.264 [NAL9602](ERROR): Communications Fault
2019-05-27T12:43:01.296Z,1558960981.296 [CBIT](ERROR): Communications Fault in component: NAL9602
2019-05-27T12:43:01.666Z,1558960981.666 [NAL9602](INFO): Powering down
2019-05-27T12:43:02.525Z,1558960982.525 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-27T12:43:02.525Z,1558960982.525 [NAL9602] No Fault, FailCount= 2
2019-05-27T12:43:19.737Z,1558960999.737 [CommandLine](IMPORTANT): got command show stack
2019-05-27T12:43:19.737Z,1558960999.737 [CommandLine](IMPORTANT): Behavior Stack:

2019-05-27T12:43:19.738Z,1558960999.738 [Startup](IMPORTANT): Priority 0: Startup:A.GoToSurface
2019-05-27T12:43:19.738Z,1558960999.738 [Startup:StartupSatComms](IMPORTANT): Priority 1: Startup:StartupSatComms:A
2019-05-27T12:43:21.080Z,1558961001.080 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-27T12:43:21.080Z,1558961001.080 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-05-27T12:43:21.080Z,1558961001.080 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-27T12:43:21.091Z,1558961001.091 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-27T12:43:21.555Z,1558961001.555 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-27T12:43:21.555Z,1558961001.555 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-05-27T12:43:31.971Z,1558961011.971 [NAL9602](INFO): Powering up NAL9602
2019-05-27T12:43:40.452Z,1558961020.452 [Micromodem](INFO): Nmea in: $CADQF,190,2*5B

2019-05-27T12:43:40.855Z,1558961020.855 [Micromodem](INFO): Nmea in: $CAMSG,BAD_CRC,2*23

2019-05-27T12:43:43.300Z,1558961023.300 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-27T12:42:43.1Z
2019-05-27T12:43:43.300Z,1558961023.300 [Startup:StartupSatComms:A] Stopped
2019-05-27T12:43:43.301Z,1558961023.301 [Startup:StartupSatComms:B] Running Loop=1
2019-05-27T12:43:43.711Z,1558961023.711 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-05-27T12:43:44.093Z,1558961024.093 [Micromodem](INFO): Nmea in: $CACST,1,070350.0000,1,361,-4,0109,0112,250,03,03,05,05,-1,-1,-1,0,2,1,1,-1,-1,-1,-1,00,190,0.1,-1*40

2019-05-27T12:43:44.595Z,1558961024.595 [Micromodem](INFO): Using rate 1 for 108 bytes.
2019-05-27T12:43:44.596Z,1558961024.596 [Micromodem](INFO): Outgoing frame #1: EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934
2019-05-27T12:43:44.596Z,1558961024.596 [Micromodem](INFO): Outgoing frame #2: 54031CA985EBBD68A09A4FE7838F5A7847A26DAB203B5B5FE57D57233D16A1EDDA3F30E935A5D332C7FC03030000000000000000000000000000000000000000
2019-05-27T12:43:44.596Z,1558961024.596 [Micromodem](INFO): Outgoing frame #3: 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
2019-05-27T12:43:44.597Z,1558961024.597 [Micromodem](INFO): Nmea out: $CCCYC,0,7,9,1,0,3*55

2019-05-27T12:43:45.054Z,1558961025.054 [Micromodem](INFO): Nmea in: $CACYC,0,7,9,1,0,3*57

2019-05-27T12:43:46.675Z,1558961026.675 [Micromodem](INFO): Nmea in: $CADRQ,070355,7,9,0,62,1*4A

2019-05-27T12:43:46.676Z,1558961026.676 [Micromodem](INFO): Nmea out: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:43:50.716Z,1558961030.716 [Micromodem](INFO): Nmea in: $CAERR,070357,DATA_IMEOUT,,*6

2019-05-27T12:43:50.716Z,1558961030.716 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAERR,070357,DATA_IMEOUT,,*6
 expected 1
2019-05-27T12:43:50.717Z,1558961030.717 [Micromodem](INFO): Nmea out: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:43:51.119Z,1558961031.119 [Micromodem](INFO): Nmea in: $CATXD,7,9,1,64*77

2019-05-27T12:43:51.119Z,1558961031.119 [Micromodem](ERROR): TXD response from modem unexpected: $CATXD,7,9,1,64*77

2019-05-27T12:43:52.735Z,1558961032.735 [NAL9602](ERROR): NAL9602 initialization error.
2019-05-27T12:43:52.735Z,1558961032.735 [NAL9602] Communications Fault, FailCount= 3
2019-05-27T12:43:52.735Z,1558961032.735 [NAL9602](ERROR): Communications Fault
2019-05-27T12:43:52.765Z,1558961032.765 [CBIT](ERROR): Communications Fault in component: NAL9602
2019-05-27T12:43:53.131Z,1558961033.131 [NAL9602](INFO): Powering down
2019-05-27T12:43:53.976Z,1558961033.976 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-27T12:43:53.976Z,1558961033.976 [NAL9602] No Fault, FailCount= 3
2019-05-27T12:44:00.816Z,1558961040.816 [Micromodem](INFO): Nmea in: $CAERR,070401,fifo,0,Data FIFO full; last TXD frame ignored*2E

2019-05-27T12:44:00.816Z,1558961040.816 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070401,fifo,0,Data FIFO full; last TXD frame ignored*2E

2019-05-27T12:44:02.022Z,1558961042.022 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:44:10.915Z,1558961050.915 [Micromodem](INFO): Nmea in: $CAERR,070413,fifo,0,Data FIFO full; last TXD frame ignored*2D

2019-05-27T12:44:10.916Z,1558961050.916 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070413,fifo,0,Data FIFO full; last TXD frame ignored*2D

2019-05-27T12:44:13.338Z,1558961053.338 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:44:21.015Z,1558961061.015 [Micromodem](INFO): Nmea in: $CAERR,070424,fifo,0,Data FIFO full; last TXD frame ignored*29

2019-05-27T12:44:21.016Z,1558961061.016 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070424,fifo,0,Data FIFO full; last TXD frame ignored*29

2019-05-27T12:44:23.439Z,1558961063.439 [NAL9602](INFO): Powering up NAL9602
2019-05-27T12:44:24.650Z,1558961064.650 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:44:30.711Z,1558961070.711 [Micromodem](INFO): Nmea in: $CAERR,070435,fifo,0,Data FIFO full; last TXD frame ignored*29

2019-05-27T12:44:30.712Z,1558961070.712 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070435,fifo,0,Data FIFO full; last TXD frame ignored*29

2019-05-27T12:44:35.955Z,1558961075.955 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:44:40.811Z,1558961080.811 [Micromodem](INFO): Nmea in: $CAERR,070447,fifo,0,Data FIFO full; last TXD frame ignored*2C

2019-05-27T12:44:40.812Z,1558961080.812 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070447,fifo,0,Data FIFO full; last TXD frame ignored*2C

2019-05-27T12:44:43.724Z,1558961083.724 [Startup:StartupSatComms:B](INFO): Timed out from 2019-05-27T12:43:43.3Z
2019-05-27T12:44:43.724Z,1558961083.724 [Startup:StartupSatComms:B] Stopped
2019-05-27T12:44:43.724Z,1558961083.724 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-05-27T12:44:43.724Z,1558961083.724 [Startup:StartupSatComms] Stopped
2019-05-27T12:44:43.724Z,1558961083.724 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-05-27T12:44:43.725Z,1558961083.725 [Startup](INFO): Completed Startup
2019-05-27T12:44:43.725Z,1558961083.725 [MissionManager](INFO): Startup is completed.
2019-05-27T12:44:43.725Z,1558961083.725 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-27T12:44:43.725Z,1558961083.725 [Startup] Stopped
2019-05-27T12:44:43.725Z,1558961083.725 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-05-27T12:44:43.726Z,1558961083.726 [Startup:A.GoToSurface] Stopped
2019-05-27T12:44:43.726Z,1558961083.726 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-27T12:44:44.039Z,1558961084.039 [NAL9602](ERROR): NAL9602 initialization error.
2019-05-27T12:44:44.039Z,1558961084.039 [NAL9602] Communications Fault, FailCount= 4
2019-05-27T12:44:44.039Z,1558961084.039 [NAL9602](ERROR): Communications Fault
2019-05-27T12:44:44.074Z,1558961084.074 [MissionManager](IMPORTANT): Started mission Default
2019-05-27T12:44:44.074Z,1558961084.074 [Default] Running Loop=1
2019-05-27T12:44:44.074Z,1558961084.074 [Default](DEBUG): Aggregate::initialize Default
2019-05-27T12:44:44.074Z,1558961084.074 [Default:B.GoToSurface] Running Loop=1
2019-05-27T12:44:44.074Z,1558961084.074 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-27T12:44:44.074Z,1558961084.074 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-27T12:44:44.075Z,1558961084.075 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-27T12:44:44.075Z,1558961084.075 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-27T12:44:44.075Z,1558961084.075 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-27T12:44:44.076Z,1558961084.076 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-27T12:44:44.076Z,1558961084.076 [Default:A.Wait] Running Loop=1
2019-05-27T12:44:44.076Z,1558961084.076 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-27T12:44:44.085Z,1558961084.085 [CBIT](ERROR): Communications Fault in component: NAL9602
2019-05-27T12:44:44.442Z,1558961084.442 [NAL9602](INFO): Powering down
2019-05-27T12:44:45.284Z,1558961085.284 [CBIT](INFO): Clearing failed state for component NAL9602
2019-05-27T12:44:45.284Z,1558961085.284 [NAL9602] No Fault, FailCount= 4
2019-05-27T12:44:47.274Z,1558961087.274 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:44:50.911Z,1558961090.911 [Micromodem](INFO): Nmea in: $CAERR,070458,fifo,0,Data FIFO full; last TXD frame ignored*22

2019-05-27T12:44:50.912Z,1558961090.912 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070458,fifo,0,Data FIFO full; last TXD frame ignored*22

2019-05-27T12:44:57.402Z,1558961097.402 [Default:A.Wait](INFO): Done Waiting.
2019-05-27T12:44:57.402Z,1558961097.402 [Default:A.Wait] Stopped
2019-05-27T12:44:57.403Z,1558961097.403 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-27T12:44:57.814Z,1558961097.814 [Default:CheckIn] Running Loop=1
2019-05-27T12:44:57.815Z,1558961097.815 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-27T12:44:57.815Z,1558961097.815 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-27T12:44:58.218Z,1558961098.218 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-05-27T12:44:58.586Z,1558961098.586 [Micromodem](ERROR): Nmea resend: $CCTXD,7,9,1,EDD7EB5C040000005D00000400550000000000000000151D80030C5669BF31555EAE1409A708CE248A48082F971AAFC35C3BD5C718E92D00A46491AEDBFE5934*74

2019-05-27T12:45:00.489Z,1558961100.489 [CommandLine](IMPORTANT): got command quit
2019-05-27T12:45:01.011Z,1558961101.011 [Micromodem](INFO): Nmea in: $CAERR,070509,fifo,0,Data FIFO full; last TXD frame ignored*27

2019-05-27T12:45:01.012Z,1558961101.012 [Micromodem](ERROR): TXD response from modem unexpected: $CAERR,070509,fifo,0,Data FIFO full; last TXD frame ignored*27

2019-05-27T12:45:01.493Z,1558961101.493 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-27T12:45:01.493Z,1558961101.493 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:01.493Z,1558961101.493 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.529Z,1558961101.529 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-27T12:45:01.529Z,1558961101.529 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.529Z,1558961101.529 [CommandLine](INFO): Join timeout helper Thread ID is 3448
2019-05-27T12:45:01.530Z,1558961101.530 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-27T12:45:01.530Z,1558961101.530 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.531Z,1558961101.531 [NavChartDb](INFO): Join timeout helper Thread ID is 3449
2019-05-27T12:45:01.885Z,1558961101.885 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:01.885Z,1558961101.885 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.897Z,1558961101.897 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-27T12:45:01.897Z,1558961101.897 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.897Z,1558961101.897 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3450
2019-05-27T12:45:01.922Z,1558961101.922 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:01.923Z,1558961101.923 [WetLabsBB2FL](INFO): Powering down
2019-05-27T12:45:01.923Z,1558961101.923 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.941Z,1558961101.941 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-27T12:45:01.941Z,1558961101.941 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.941Z,1558961101.941 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 3451
2019-05-27T12:45:01.953Z,1558961101.953 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:01.953Z,1558961101.953 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.961Z,1558961101.961 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-27T12:45:01.961Z,1558961101.961 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:01.961Z,1558961101.961 [Radio_Surface](INFO): Join timeout helper Thread ID is 3452
2019-05-27T12:45:02.061Z,1558961102.061 [Radio_Surface](INFO): Powering down
2019-05-27T12:45:02.062Z,1558961102.062 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:02.062Z,1558961102.062 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.082Z,1558961102.082 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-27T12:45:02.082Z,1558961102.082 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.082Z,1558961102.082 [logger](INFO): Join timeout helper Thread ID is 3453
2019-05-27T12:45:02.109Z,1558961102.109 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:02.109Z,1558961102.109 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.121Z,1558961102.121 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-27T12:45:02.122Z,1558961102.122 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.122Z,1558961102.122 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-27T12:45:02.122Z,1558961102.122 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.122Z,1558961102.122 [controlThread](INFO): Join timeout helper Thread ID is 3454
2019-05-27T12:45:02.209Z,1558961102.209 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-27T12:45:02.209Z,1558961102.209 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-27T12:45:02.210Z,1558961102.210 [Micromodem](INFO): Powering down
2019-05-27T12:45:02.305Z,1558961102.305 [NAL9602](INFO): Powering down
2019-05-27T12:45:02.307Z,1558961102.307 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-27T12:45:02.308Z,1558961102.308 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-27T12:45:02.309Z,1558961102.309 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-27T12:45:02.309Z,1558961102.309 [MissionManager](INFO): Uninitializing Mission Default
2019-05-27T12:45:02.309Z,1558961102.309 [Default] Stopped
2019-05-27T12:45:02.310Z,1558961102.310 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-27T12:45:02.310Z,1558961102.310 [Default:B.GoToSurface] Stopped
2019-05-27T12:45:02.310Z,1558961102.310 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-27T12:45:02.310Z,1558961102.310 [Default:CheckIn] Stopped
2019-05-27T12:45:02.310Z,1558961102.310 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-27T12:45:02.310Z,1558961102.310 [Default:CheckIn:Read_GPS] Stopped
2019-05-27T12:45:02.312Z,1558961102.312 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-27T12:45:02.312Z,1558961102.312 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-27T12:45:02.313Z,1558961102.313 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-27T12:45:02.313Z,1558961102.313 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-27T12:45:02.313Z,1558961102.313 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-27T12:45:02.314Z,1558961102.314 [BuoyancyServo](INFO): Powering down
2019-05-27T12:45:02.325Z,1558961102.325 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-27T12:45:02.325Z,1558961102.325 [ElevatorServo](INFO): Powering down
2019-05-27T12:45:02.326Z,1558961102.326 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-27T12:45:02.326Z,1558961102.326 [MassServo](INFO): Powering down
2019-05-27T12:45:02.327Z,1558961102.327 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-27T12:45:02.327Z,1558961102.327 [RudderServo](INFO): Powering down
2019-05-27T12:45:02.327Z,1558961102.327 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-27T12:45:02.328Z,1558961102.328 [ThrusterServo](INFO): Powering down
2019-05-27T12:45:02.328Z,1558961102.328 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-27T12:45:02.329Z,1558961102.329 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-27T12:45:02.329Z,1558961102.329 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-27T12:45:02.329Z,1558961102.329 [CBIT](DEBUG): Powering off loads.
2019-05-27T12:45:02.341Z,1558961102.341 [CBIT](DEBUG): Disabling WDT.
2019-05-27T12:45:02.353Z,1558961102.353 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-27T12:45:02.353Z,1558961102.353 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.429Z,1558961102.429 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.478Z,1558961102.478 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.481Z,1558961102.481 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.489Z,1558961102.489 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-27T12:45:02.543Z,1558961102.543 [logger ThreadHandler](INFO): Thread cancelled.