2017-09-19T21:39:30.499Z,1505857170.499 [Supervisor](DEBUG): Initializing supervisor.
2017-09-19T21:39:30.502Z,1505857170.502 [SyncHandler](DEBUG): Created PCaller Thread at 4051A4E0
2017-09-19T21:39:30.503Z,1505857170.503 [SyncHandler](INFO): Protected caller Thread ID is 769
2017-09-19T21:39:30.503Z,1505857170.503 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2017-09-19T21:39:30.504Z,1505857170.504 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 4054A4E0
2017-09-19T21:39:30.505Z,1505857170.505 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 770
2017-09-19T21:39:30.508Z,1505857170.508 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2017-09-19T21:39:30.523Z,1505857170.523 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2017-09-19T21:39:30.524Z,1505857170.524 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 4057A4E0
2017-09-19T21:39:30.524Z,1505857170.524 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 771
2017-09-19T21:39:30.525Z,1505857170.525 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2017-09-19T21:39:30.526Z,1505857170.526 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405AA4E0
2017-09-19T21:39:30.527Z,1505857170.527 [logger ThreadHandler](INFO): Protected caller Thread ID is 772
2017-09-19T21:39:30.529Z,1505857170.529 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2017-09-19T21:39:30.530Z,1505857170.530 [Supervisor](INFO): Looking for Config files in directory: Config/
2017-09-19T21:39:30.533Z,1505857170.533 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2017-09-19T21:39:30.737Z,1505857170.737 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2017-09-19T21:39:30.738Z,1505857170.738 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2017-09-19T21:39:30.961Z,1505857170.961 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2017-09-19T21:39:30.962Z,1505857170.962 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2017-09-19T21:39:31.345Z,1505857171.345 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2017-09-19T21:39:31.345Z,1505857171.345 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2017-09-19T21:39:31.498Z,1505857171.498 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2017-09-19T21:39:31.499Z,1505857171.499 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2017-09-19T21:39:31.586Z,1505857171.586 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2017-09-19T21:39:31.809Z,1505857171.809 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2017-09-19T21:39:31.811Z,1505857171.811 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2017-09-19T21:39:31.919Z,1505857171.919 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2017-09-19T21:39:31.920Z,1505857171.920 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2017-09-19T21:39:32.253Z,1505857172.253 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2017-09-19T21:39:32.254Z,1505857172.254 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2017-09-19T21:39:32.676Z,1505857172.676 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2017-09-19T21:39:32.677Z,1505857172.677 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2017-09-19T21:39:33.024Z,1505857173.024 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2017-09-19T21:39:33.025Z,1505857173.025 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2017-09-19T21:39:33.671Z,1505857173.671 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2017-09-19T21:39:35.927Z,1505857175.927 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2017-09-19T21:39:36.193Z,1505857176.193 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2017-09-19T21:39:36.194Z,1505857176.194 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2017-09-19T21:39:36.302Z,1505857176.302 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2017-09-19T21:39:36.303Z,1505857176.303 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2017-09-19T21:39:36.851Z,1505857176.851 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2017-09-19T21:39:36.852Z,1505857176.852 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2017-09-19T21:39:36.969Z,1505857176.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2017-09-19T21:39:36.971Z,1505857176.971 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2017-09-19T21:39:36.974Z,1505857176.974 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2017-09-19T21:39:37.272Z,1505857177.272 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2017-09-19T21:39:37.273Z,1505857177.273 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2017-09-19T21:39:37.381Z,1505857177.381 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2017-09-19T21:39:37.478Z,1505857177.478 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2017-09-19T21:39:37.589Z,1505857177.589 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2017-09-19T21:39:37.681Z,1505857177.681 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2017-09-19T21:39:37.821Z,1505857177.821 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2017-09-19T21:39:37.992Z,1505857177.992 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2017-09-19T21:39:38.095Z,1505857178.095 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2017-09-19T21:39:38.194Z,1505857178.194 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2017-09-19T21:39:38.285Z,1505857178.285 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2017-09-19T21:39:38.484Z,1505857178.484 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2017-09-19T21:39:38.566Z,1505857178.566 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2017-09-19T21:39:38.569Z,1505857178.569 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2017-09-19T21:39:38.739Z,1505857178.739 [SBIT](DEBUG): Construct Startup Built In Test.
2017-09-19T21:39:38.776Z,1505857178.776 [SBIT] Loaded
2017-09-19T21:39:38.776Z,1505857178.776 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2017-09-19T21:39:38.777Z,1505857178.777 [IBIT](DEBUG): Construct Initiated Built In Test.
2017-09-19T21:39:38.812Z,1505857178.812 [IBIT] Loaded
2017-09-19T21:39:38.812Z,1505857178.812 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2017-09-19T21:39:38.817Z,1505857178.817 [CBIT](DEBUG): Construct Continuous Built In Test.
2017-09-19T21:39:39.027Z,1505857179.027 [CBIT] Loaded
2017-09-19T21:39:39.027Z,1505857179.027 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2017-09-19T21:39:39.028Z,1505857179.028 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2017-09-19T21:39:39.028Z,1505857179.028 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2017-09-19T21:39:41.554Z,1505857181.554 [VerticalControl](DEBUG): Construct VerticalControl.
2017-09-19T21:39:41.675Z,1505857181.675 [VerticalControl] Loaded
2017-09-19T21:39:41.675Z,1505857181.675 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2017-09-19T21:39:41.676Z,1505857181.676 [HorizontalControl](DEBUG): Construct HorizontalControl.
2017-09-19T21:39:41.754Z,1505857181.754 [HorizontalControl] Loaded
2017-09-19T21:39:41.754Z,1505857181.754 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2017-09-19T21:39:41.755Z,1505857181.755 [SpeedControl](DEBUG): Construct SpeedControl.
2017-09-19T21:39:41.762Z,1505857181.762 [SpeedControl] Loaded
2017-09-19T21:39:41.762Z,1505857181.762 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2017-09-19T21:39:41.763Z,1505857181.763 [LoopControl](DEBUG): Construct LoopControl.
2017-09-19T21:39:41.764Z,1505857181.764 [LoopControl] Loaded
2017-09-19T21:39:41.764Z,1505857181.764 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2017-09-19T21:39:41.765Z,1505857181.765 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2017-09-19T21:39:41.766Z,1505857181.766 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2017-09-19T21:39:41.808Z,1505857181.808 [DepthRateCalculator] Loaded
2017-09-19T21:39:41.808Z,1505857181.808 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2017-09-19T21:39:41.815Z,1505857181.815 [PitchRateCalculator] Loaded
2017-09-19T21:39:41.815Z,1505857181.815 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2017-09-19T21:39:41.834Z,1505857181.834 [SpeedCalculator] Loaded
2017-09-19T21:39:41.834Z,1505857181.834 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2017-09-19T21:39:41.861Z,1505857181.861 [TempGradientCalculator] Loaded
2017-09-19T21:39:41.861Z,1505857181.861 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2017-09-19T21:39:41.880Z,1505857181.880 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2017-09-19T21:39:41.881Z,1505857181.881 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2017-09-19T21:39:41.887Z,1505857181.887 [YawRateCalculator] Loaded
2017-09-19T21:39:41.887Z,1505857181.887 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2017-09-19T21:39:41.888Z,1505857181.888 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2017-09-19T21:39:41.888Z,1505857181.888 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2017-09-19T21:39:42.027Z,1505857182.027 [StratificationFrontDetector](INFO): threshold set to: 0.399988 degC
2017-09-19T21:39:42.027Z,1505857182.027 [StratificationFrontDetector](DEBUG): (re)initializing
2017-09-19T21:39:42.027Z,1505857182.027 [StratificationFrontDetector] Loaded
2017-09-19T21:39:42.027Z,1505857182.027 [ComponentRegistry](DEBUG): SyncComponent "StratificationFrontDetector" handled in the control thread.
2017-09-19T21:39:42.028Z,1505857182.028 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2017-09-19T21:39:42.029Z,1505857182.029 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2017-09-19T21:39:42.317Z,1505857182.317 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2017-09-19T21:39:42.318Z,1505857182.318 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2017-09-19T21:39:42.455Z,1505857182.455 [DeadReckonUsingMultipleVelocitySources] Loaded
2017-09-19T21:39:42.455Z,1505857182.455 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2017-09-19T21:39:42.523Z,1505857182.523 [DeadReckonUsingSpeedCalculator] Loaded
2017-09-19T21:39:42.523Z,1505857182.523 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2017-09-19T21:39:42.544Z,1505857182.544 [NavChart] Loaded
2017-09-19T21:39:42.544Z,1505857182.544 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2017-09-19T21:39:42.550Z,1505857182.550 [UniversalFixResidualReporter] Loaded
2017-09-19T21:39:42.550Z,1505857182.550 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2017-09-19T21:39:42.550Z,1505857182.550 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2017-09-19T21:39:42.551Z,1505857182.551 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2017-09-19T21:39:42.588Z,1505857182.588 [lcmLoadTest](CRITICAL): No configuration setting for: lcmLoadTest.lcmApplication
2017-09-19T21:39:42.590Z,1505857182.590 [lcmLoadTest] Loaded
2017-09-19T21:39:42.590Z,1505857182.590 [ComponentRegistry](DEBUG): Component "lcmLoadTest" handled in its own thread.
2017-09-19T21:39:42.591Z,1505857182.591 [lcmLoadTest ThreadHandler](DEBUG): Created PCaller Thread at 407944E0
2017-09-19T21:39:42.592Z,1505857182.592 [lcmLoadTest ThreadHandler](INFO): Protected caller Thread ID is 855
2017-09-19T21:39:42.592Z,1505857182.592 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2017-09-19T21:39:42.593Z,1505857182.593 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2017-09-19T21:39:42.812Z,1505857182.812 [Aanderaa_O2] Loaded
2017-09-19T21:39:42.812Z,1505857182.812 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2017-09-19T21:39:42.918Z,1505857182.918 [CTD_NeilBrown] Loaded
2017-09-19T21:39:42.918Z,1505857182.918 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2017-09-19T21:39:42.919Z,1505857182.919 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408474E0
2017-09-19T21:39:42.920Z,1505857182.920 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 856
2017-09-19T21:39:42.963Z,1505857182.963 [CTD_Seabird] Loaded
2017-09-19T21:39:42.963Z,1505857182.963 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2017-09-19T21:39:42.965Z,1505857182.965 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 408774E0
2017-09-19T21:39:42.965Z,1505857182.965 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 857
2017-09-19T21:39:42.983Z,1505857182.983 [PAR_Licor] Loaded
2017-09-19T21:39:42.984Z,1505857182.984 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2017-09-19T21:39:43.042Z,1505857183.042 [WetLabsBB2FL] Loaded
2017-09-19T21:39:43.043Z,1505857183.043 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2017-09-19T21:39:43.044Z,1505857183.044 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 408A74E0
2017-09-19T21:39:43.044Z,1505857183.044 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 858
2017-09-19T21:39:43.045Z,1505857183.045 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2017-09-19T21:39:43.046Z,1505857183.046 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2017-09-19T21:39:43.693Z,1505857183.693 [DataOverHttps] Loaded
2017-09-19T21:39:43.693Z,1505857183.693 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2017-09-19T21:39:43.710Z,1505857183.710 [Depth_Keller] Loaded
2017-09-19T21:39:43.710Z,1505857183.710 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2017-09-19T21:39:43.716Z,1505857183.716 [DropWeight] Loaded
2017-09-19T21:39:43.717Z,1505857183.717 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2017-09-19T21:39:43.830Z,1505857183.830 [NAL9602] Loaded
2017-09-19T21:39:43.830Z,1505857183.830 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2017-09-19T21:39:43.842Z,1505857183.842 [Onboard] Loaded
2017-09-19T21:39:43.842Z,1505857183.842 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2017-09-19T21:39:43.851Z,1505857183.851 [Radio_Surface] Loaded
2017-09-19T21:39:43.851Z,1505857183.851 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2017-09-19T21:39:43.852Z,1505857183.852 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40B2B4E0
2017-09-19T21:39:43.853Z,1505857183.853 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 859
2017-09-19T21:39:44.010Z,1505857184.010 [DAT] Loaded
2017-09-19T21:39:44.010Z,1505857184.010 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2017-09-19T21:39:44.213Z,1505857184.213 [PNI_TCM] Loaded
2017-09-19T21:39:44.213Z,1505857184.213 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2017-09-19T21:39:44.288Z,1505857184.288 [Rowe_600LCM] Loaded
2017-09-19T21:39:44.288Z,1505857184.288 [ComponentRegistry](DEBUG): Component "Rowe_600LCM" handled in its own thread.
2017-09-19T21:39:44.289Z,1505857184.289 [Rowe_600LCM ThreadHandler](DEBUG): Created PCaller Thread at 40B5B4E0
2017-09-19T21:39:44.290Z,1505857184.290 [Rowe_600LCM ThreadHandler](INFO): Protected caller Thread ID is 860
2017-09-19T21:39:46.724Z,1505857186.724 [BPC1] Loaded
2017-09-19T21:39:46.724Z,1505857186.724 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2017-09-19T21:39:46.725Z,1505857186.725 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2017-09-19T21:39:46.725Z,1505857186.725 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2017-09-19T21:39:46.881Z,1505857186.881 [BuoyancyServo] Loaded
2017-09-19T21:39:46.881Z,1505857186.881 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2017-09-19T21:39:46.897Z,1505857186.897 [ElevatorServo] Loaded
2017-09-19T21:39:46.897Z,1505857186.897 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2017-09-19T21:39:46.912Z,1505857186.912 [MassServo] Loaded
2017-09-19T21:39:46.913Z,1505857186.913 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2017-09-19T21:39:46.927Z,1505857186.927 [RudderServo] Loaded
2017-09-19T21:39:46.928Z,1505857186.928 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2017-09-19T21:39:46.942Z,1505857186.942 [ThrusterServo] Loaded
2017-09-19T21:39:46.942Z,1505857186.942 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2017-09-19T21:39:46.943Z,1505857186.943 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2017-09-19T21:39:46.944Z,1505857186.944 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2017-09-19T21:39:47.084Z,1505857187.084 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2017-09-19T21:39:47.085Z,1505857187.085 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2017-09-19T21:39:47.130Z,1505857187.130 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2017-09-19T21:39:47.136Z,1505857187.136 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2017-09-19T21:39:47.137Z,1505857187.137 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2017-09-19T21:39:47.147Z,1505857187.147 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2017-09-19T21:39:47.149Z,1505857187.149 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C2F4E0
2017-09-19T21:39:47.149Z,1505857187.149 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 861
2017-09-19T21:39:47.156Z,1505857187.156 [Supervisor](INFO): Main Thread ID is 765
2017-09-19T21:39:47.156Z,1505857187.156 [Supervisor](DEBUG): Running supervisor.
2017-09-19T21:39:47.157Z,1505857187.157 [CommandLine ThreadHandler](INFO): Handler Thread ID is 862
2017-09-19T21:39:47.160Z,1505857187.160 [controlThread ThreadHandler](INFO): Handler Thread ID is 863
2017-09-19T21:39:47.160Z,1505857187.160 [controlThread](DEBUG): Initializing ControlThread
2017-09-19T21:39:47.161Z,1505857187.161 [SBIT](INFO): Initialize SBIT Component.
2017-09-19T21:39:47.162Z,1505857187.162 [SBIT](IMPORTANT): git: 2017-08-02-127-gbf090d4
2017-09-19T21:39:47.162Z,1505857187.162 [SBIT](INFO): git hash: bf090d438624f3eab8dcd53a95a0b085cf9a0ee9
2017-09-19T21:39:47.164Z,1505857187.164 [SBIT](INFO): Kernel Reporting Different Release From Configuration.
Kernel Expected: 2.6.27.8
Kernel Reported: 2.6.27.8-00011-g2bc81df-dirty
2017-09-19T21:39:47.165Z,1505857187.165 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
Kernel Reported: #646 PREEMPT Thu Feb 11 17:01:12 PST 2016
2017-09-19T21:39:47.166Z,1505857187.166 [SBIT](INFO): Beginning SBIT in 23.000000 seconds.
2017-09-19T21:39:47.166Z,1505857187.166 [IBIT](INFO): Initialize IBIT Component.
2017-09-19T21:39:47.167Z,1505857187.167 [CBIT](DEBUG): Initialize CBIT Component.
2017-09-19T21:39:47.168Z,1505857187.168 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2017-09-19T21:39:47.168Z,1505857187.168 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2017-09-19T21:39:47.169Z,1505857187.169 [logger ThreadHandler](INFO): Handler Thread ID is 864
2017-09-19T21:39:47.195Z,1505857187.195 [lcmLoadTest ThreadHandler](INFO): Handler Thread ID is 865
2017-09-19T21:39:47.215Z,1505857187.215 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 866
2017-09-19T21:39:47.216Z,1505857187.216 [CTD_NeilBrown](INFO): Powering down
2017-09-19T21:39:47.251Z,1505857187.251 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2017-09-19T21:39:47.253Z,1505857187.253 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2017-09-19T21:39:47.254Z,1505857187.254 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2017-09-19T21:39:47.259Z,1505857187.259 [LoopControl](DEBUG): Initialize LoopControlComponent.
2017-09-19T21:39:47.259Z,1505857187.259 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2017-09-19T21:39:47.260Z,1505857187.260 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2017-09-19T21:39:47.260Z,1505857187.260 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2017-09-19T21:39:47.261Z,1505857187.261 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2017-09-19T21:39:47.261Z,1505857187.261 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2017-09-19T21:39:47.262Z,1505857187.262 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2017-09-19T21:39:47.263Z,1505857187.263 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:39:47.264Z,1505857187.264 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:39:47.264Z,1505857187.264 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:39:47.265Z,1505857187.265 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2017-09-19T21:39:47.265Z,1505857187.265 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:39:47.266Z,1505857187.266 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:39:47.266Z,1505857187.266 [NavChart](DEBUG): Initialize NavChart Navigation.
2017-09-19T21:39:47.271Z,1505857187.271 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2017-09-19T21:39:47.291Z,1505857187.291 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2017-09-19T21:39:47.349Z,1505857187.349 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 867
2017-09-19T21:39:47.351Z,1505857187.351 [CTD_Seabird](INFO): Initializing
2017-09-19T21:39:47.523Z,1505857187.523 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 869
2017-09-19T21:39:47.525Z,1505857187.525 [WetLabsBB2FL](INFO): Powering down
2017-09-19T21:39:47.549Z,1505857187.549 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2017-09-19T21:39:47.560Z,1505857187.560 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 870
2017-09-19T21:39:47.566Z,1505857187.566 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2017-09-19T21:39:47.567Z,1505857187.567 [CTD_Seabird](INFO): Powering down
2017-09-19T21:39:47.686Z,1505857187.686 [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>


2017-09-19T21:39:47.686Z,1505857187.686 [Rowe_600LCM ThreadHandler](INFO): Handler Thread ID is 871
2017-09-19T21:39:47.687Z,1505857187.687 [Rowe_600LCM](INFO): Initializing
2017-09-19T21:39:47.688Z,1505857187.688 [Rowe_600LCM](INFO): Checking LCM
2017-09-19T21:39:47.689Z,1505857187.689 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2017-09-19T21:39:47.708Z,1505857187.708 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 872
2017-09-19T21:39:47.724Z,1505857187.724 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2017-09-19T21:39:47.724Z,1505857187.724 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2017-09-19T21:39:47.724Z,1505857187.724 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2017-09-19T21:39:47.725Z,1505857187.725 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2017-09-19T21:39:47.725Z,1505857187.725 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2017-09-19T21:39:47.725Z,1505857187.725 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2017-09-19T21:39:47.725Z,1505857187.725 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2017-09-19T21:39:47.725Z,1505857187.725 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2017-09-19T21:39:47.726Z,1505857187.726 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2017-09-19T21:39:47.726Z,1505857187.726 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2017-09-19T21:39:47.726Z,1505857187.726 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2017-09-19T21:39:47.726Z,1505857187.726 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2017-09-19T21:39:47.727Z,1505857187.727 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2017-09-19T21:39:47.727Z,1505857187.727 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2017-09-19T21:39:47.727Z,1505857187.727 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2017-09-19T21:39:47.727Z,1505857187.727 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2017-09-19T21:39:47.750Z,1505857187.750 [Radio_Surface](INFO): Powering up
2017-09-19T21:39:47.893Z,1505857187.893 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2017-09-19T21:39:47.895Z,1505857187.895 [Default:A.Wait](DEBUG): Construct Wait.
2017-09-19T21:39:47.909Z,1505857187.909 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2017-09-19T21:39:47.962Z,1505857187.962 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2017-09-19T21:39:47.966Z,1505857187.966 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2017-09-19T21:39:47.998Z,1505857187.998 [Default:E.Execute](DEBUG): Construct Execute.
2017-09-19T21:39:48.060Z,1505857188.060 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
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/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="Default">

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

    <Guidance:Wait>
        <Sequence/>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <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">
            <Sequence/>
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Sequence/>
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn 300</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>


2017-09-19T21:39:48.081Z,1505857188.081 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2017-09-19T21:39:48.094Z,1505857188.094 [Rowe_600LCM](INFO): LCM OK
2017-09-19T21:39:48.094Z,1505857188.094 [Rowe_600LCM](INFO): Powering up
2017-09-19T21:39:48.268Z,1505857188.268 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2017-09-19T21:39:48.504Z,1505857188.504 [DAT](INFO): Powering up
2017-09-19T21:39:48.504Z,1505857188.504 [DAT](DEBUG): Initializing DAT.
2017-09-19T21:39:48.894Z,1505857188.894 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:49.086Z,1505857189.086 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:49.237Z,1505857189.237 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:49.267Z,1505857189.267 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2017-09-19T21:39:49.302Z,1505857189.302 [ElevatorServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:49.311Z,1505857189.311 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2017-09-19T21:39:49.319Z,1505857189.319 [MassServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:49.330Z,1505857189.330 [MassServo](DEBUG): Initializing MassServo.
2017-09-19T21:39:49.337Z,1505857189.337 [RudderServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:49.350Z,1505857189.350 [RudderServo](DEBUG): Initializing RudderServo.
2017-09-19T21:39:49.357Z,1505857189.357 [ThrusterServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:49.374Z,1505857189.374 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2017-09-19T21:39:49.452Z,1505857189.452 [CommandLine](FAULT): Scheduling is paused
2017-09-19T21:39:49.453Z,1505857189.453 [CBIT](INFO): Critical error at 20170919T213942
2017-09-19T21:39:49.453Z,1505857189.453 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2017-09-19T21:39:49.758Z,1505857189.758 [NAL9602](INFO): Powering up NAL9602
2017-09-19T21:39:49.851Z,1505857189.851 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:49.852Z,1505857189.852 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:50.195Z,1505857190.195 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2017-09-19T21:39:50.196Z,1505857190.196 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2017-09-19T21:39:50.196Z,1505857190.196 [BuoyancyServo] Communications Fault, FailCount= 1
2017-09-19T21:39:50.196Z,1505857190.196 [BuoyancyServo](ERROR): Communications Fault
2017-09-19T21:39:50.405Z,1505857190.405 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2017-09-19T21:39:50.473Z,1505857190.473 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:50.474Z,1505857190.474 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:50.498Z,1505857190.498 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2017-09-19T21:39:50.499Z,1505857190.499 [BuoyancyServo](INFO): Powering down
2017-09-19T21:39:50.866Z,1505857190.866 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:50.867Z,1505857190.867 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:51.333Z,1505857191.333 [Aanderaa_O2](INFO): Powering down
2017-09-19T21:39:51.515Z,1505857191.515 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:51.516Z,1505857191.516 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:51.694Z,1505857191.694 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:51.695Z,1505857191.695 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:52.073Z,1505857192.073 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:52.095Z,1505857192.095 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:52.201Z,1505857192.201 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of Rowe LCM interface
2017-09-19T21:39:52.306Z,1505857192.306 [Rowe_600LCM](INFO): Started Rowe LCM interface with command:nohup ./lrauv-framework/onboard/bin/roweadcp -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyB4 -b 38400 >& /dev/null &
2017-09-19T21:39:52.314Z,1505857192.314 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.bottom_track
2017-09-19T21:39:52.316Z,1505857192.316 [Rowe_600LCM](INFO): LCM subscribed to channel:Rowe_600LCM.adcp_dvl.vehicle_water_velocity
2017-09-19T21:39:52.317Z,1505857192.317 [Rowe_600LCM](INFO): LCM subscribed to channel:rowe_dvl.rowe
2017-09-19T21:39:52.484Z,1505857192.484 [DeadReckonUsingMultipleVelocitySources](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:52.486Z,1505857192.486 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2017-09-19T21:39:53.397Z,1505857193.397 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2017-09-19T21:39:53.397Z,1505857193.397 [BuoyancyServo] No Fault, FailCount= 1
2017-09-19T21:39:53.620Z,1505857193.620 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2017-09-19T21:39:53.620Z,1505857193.620 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2017-09-19T21:40:00.643Z,1505857200.643 [NAL9602](INFO): NAL9602 initialized
2017-09-19T21:40:01.145Z,1505857201.145 [DAT](DEBUG): 
Teledyne Benthos DAT-900 Series
MF Frequency Band
Directional Acoustic Transponder version 8.12.5
Sep 19 2017 21:39:44 
WARNING: battery low
Features enabled [Bearing]
CONNECT
2017-09-19T21:40:01.145Z,1505857201.145 [DAT](INFO): Got CONNECT
2017-09-19T21:40:01.157Z,1505857201.157 [DAT](INFO): entering command mode
2017-09-19T21:40:01.459Z,1505857201.459 [DAT](DEBUG): checking for command mode acknowledgment
2017-09-19T21:40:01.460Z,1505857201.460 [DAT](DEBUG): read user prompt 1: user:1>
2017-09-19T21:40:01.460Z,1505857201.460 [DAT](INFO): command mode acknowledged
2017-09-19T21:40:01.860Z,1505857201.860 [DAT](INFO): setting local address to 2
2017-09-19T21:40:02.288Z,1505857202.288 [DAT](DEBUG): checking for local address setting acknowledgment
2017-09-19T21:40:02.289Z,1505857202.289 [DAT](INFO): set local address to 2
2017-09-19T21:40:02.647Z,1505857202.647 [DAT](DEBUG): read user prompt 2: user:2>
2017-09-19T21:40:10.739Z,1505857210.739 [SBIT](IMPORTANT): Beginning Startup BIT
2017-09-19T21:40:10.751Z,1505857210.751 [CBIT](IMPORTANT): Beginning ground fault scan
2017-09-19T21:40:16.542Z,1505857216.542 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2017-09-19T21:40:17.336Z,1505857217.336 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2017-09-19T21:40:21.313Z,1505857221.313 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.004903
CHAN A1 (24V): 0.126517
CHAN A2 (12V): -0.002029
CHAN A3 (5V): 0.000274
CHAN B0 (3.3V): -0.000049
CHAN B1 (3.15aV): -0.000004
CHAN B2 (3.15bV): -0.000349
CHAN B3 (GND): -0.000047
OPEN: -0.000523
Full Scale Calc: 4.765 mA, -1.589 mA
2017-09-19T21:40:29.905Z,1505857229.905 [BPC1](ERROR): Failed to parse bank A battery data
2017-09-19T21:40:29.905Z,1505857229.905 [BPC1] Data Fault, FailCount= 1
2017-09-19T21:40:29.905Z,1505857229.905 [BPC1](ERROR): Data Fault
2017-09-19T21:40:30.092Z,1505857230.092 [CBIT](ERROR): Data Fault in component: BPC1
2017-09-19T21:40:31.307Z,1505857231.307 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:40:31.307Z,1505857231.307 [BPC1] No Fault, FailCount= 1
2017-09-19T21:41:04.966Z,1505857264.966 [SBIT](IMPORTANT): SBIT PASSED
2017-09-19T21:41:05.352Z,1505857265.352 [MissionManager](IMPORTANT): Started mission Startup
2017-09-19T21:41:05.352Z,1505857265.352 [Startup] Running Loop=1
2017-09-19T21:41:05.352Z,1505857265.352 [Startup](DEBUG): Aggregate::initialize Startup
2017-09-19T21:41:05.352Z,1505857265.352 [Startup:A.GoToSurface] Running Loop=1
2017-09-19T21:41:05.353Z,1505857265.353 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2017-09-19T21:41:05.353Z,1505857265.353 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2017-09-19T21:41:05.354Z,1505857265.354 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2017-09-19T21:41:05.354Z,1505857265.354 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2017-09-19T21:41:05.355Z,1505857265.355 [Startup:A.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds.
2017-09-19T21:41:05.355Z,1505857265.355 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2017-09-19T21:41:05.382Z,1505857265.382 [Startup:StartupSatComms] Running Loop=1
2017-09-19T21:41:05.383Z,1505857265.383 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2017-09-19T21:41:05.383Z,1505857265.383 [Startup:StartupSatComms:A] Running Loop=1
2017-09-19T21:41:05.772Z,1505857265.772 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2017-09-19T21:41:55.309Z,1505857315.309 [BPC1](ERROR): Failed to parse bank B battery data
2017-09-19T21:41:55.309Z,1505857315.309 [BPC1] Data Fault, FailCount= 1
2017-09-19T21:41:55.310Z,1505857315.310 [BPC1](ERROR): Data Fault
2017-09-19T21:41:55.380Z,1505857315.380 [CBIT](ERROR): Data Fault in component: BPC1
2017-09-19T21:41:56.586Z,1505857316.586 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:41:56.586Z,1505857316.586 [BPC1] No Fault, FailCount= 1
2017-09-19T21:42:05.807Z,1505857325.807 [Startup:StartupSatComms:A](INFO): Timed out from 2017-09-19T21:41:05.4Z
2017-09-19T21:42:05.807Z,1505857325.807 [Startup:StartupSatComms:A] Stopped
2017-09-19T21:42:05.807Z,1505857325.807 [Startup:StartupSatComms:B] Running Loop=1
2017-09-19T21:42:06.164Z,1505857326.164 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2017-09-19T21:42:08.148Z,1505857328.148 [PNI_TCM](ERROR): CRC does not match. Expected:0x31358 got:0x19115
2017-09-19T21:42:13.341Z,1505857333.341 [BPC1](ERROR): Failed to receive battery data
2017-09-19T21:42:13.341Z,1505857333.341 [BPC1] Communications Fault, FailCount= 2
2017-09-19T21:42:13.341Z,1505857333.341 [BPC1](ERROR): Communications Fault
2017-09-19T21:42:13.392Z,1505857333.392 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-19T21:42:14.584Z,1505857334.584 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:42:14.584Z,1505857334.584 [BPC1] No Fault, FailCount= 2
2017-09-19T21:42:17.743Z,1505857337.743 [PNI_TCM](ERROR): CRC does not match. Expected:0x63433 got:0x10781
2017-09-19T21:42:32.140Z,1505857352.140 [PNI_TCM](ERROR): CRC does not match. Expected:0x61037 got:0x44902
2017-09-19T21:42:47.377Z,1505857367.377 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:42:47.378Z,1505857367.378 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2017-09-19T21:42:47.378Z,1505857367.378 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-19T21:42:47.380Z,1505857367.380 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:42:47.380Z,1505857367.380 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2017-09-19T21:42:47.380Z,1505857367.380 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2017-09-19T21:42:47.396Z,1505857367.396 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-19T21:42:47.396Z,1505857367.396 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2017-09-19T21:42:47.862Z,1505857367.862 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-19T21:42:47.863Z,1505857367.863 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2017-09-19T21:42:47.863Z,1505857367.863 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2017-09-19T21:42:47.863Z,1505857367.863 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2017-09-19T21:42:48.172Z,1505857368.172 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:42:48.173Z,1505857368.173 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:42:48.173Z,1505857368.173 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:42:48.174Z,1505857368.174 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2017-09-19T21:42:48.174Z,1505857368.174 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:42:48.175Z,1505857368.175 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:42:54.558Z,1505857374.558 [PNI_TCM](ERROR): CRC does not match. Expected:0x64111 got:0x57883
2017-09-19T21:43:04.158Z,1505857384.158 [PNI_TCM](ERROR): CRC does not match. Expected:0x25900 got:0x1347
2017-09-19T21:43:06.173Z,1505857386.173 [PNI_TCM](ERROR): CRC does not match. Expected:0x28605 got:0x5926
2017-09-19T21:43:06.204Z,1505857386.204 [Startup:StartupSatComms:B](INFO): Timed out from 2017-09-19T21:42:05.8Z
2017-09-19T21:43:06.204Z,1505857386.204 [Startup:StartupSatComms:B] Stopped
2017-09-19T21:43:06.204Z,1505857386.204 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2017-09-19T21:43:06.204Z,1505857386.204 [Startup:StartupSatComms] Stopped
2017-09-19T21:43:06.205Z,1505857386.205 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2017-09-19T21:43:06.206Z,1505857386.206 [Startup](INFO): Completed Startup
2017-09-19T21:43:06.206Z,1505857386.206 [MissionManager](INFO): Startup is completed.
2017-09-19T21:43:06.206Z,1505857386.206 [MissionManager](INFO): Uninitializing Mission Startup
2017-09-19T21:43:06.206Z,1505857386.206 [Startup] Stopped
2017-09-19T21:43:06.206Z,1505857386.206 [Startup](DEBUG): Aggregate::uninitialize Startup
2017-09-19T21:43:06.207Z,1505857386.207 [Startup:A.GoToSurface] Stopped
2017-09-19T21:43:06.207Z,1505857386.207 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2017-09-19T21:43:06.584Z,1505857386.584 [MissionManager](IMPORTANT): Started mission Default
2017-09-19T21:43:06.584Z,1505857386.584 [Default] Running Loop=1
2017-09-19T21:43:06.584Z,1505857386.584 [Default](DEBUG): Aggregate::initialize Default
2017-09-19T21:43:06.584Z,1505857386.584 [Default:B.GoToSurface] Running Loop=1
2017-09-19T21:43:06.584Z,1505857386.584 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2017-09-19T21:43:06.585Z,1505857386.585 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2017-09-19T21:43:06.585Z,1505857386.585 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2017-09-19T21:43:06.585Z,1505857386.585 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2017-09-19T21:43:06.586Z,1505857386.586 [Default:B.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 20.000000 seconds.
2017-09-19T21:43:06.586Z,1505857386.586 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2017-09-19T21:43:06.587Z,1505857386.587 [Default:A.Wait] Running Loop=1
2017-09-19T21:43:06.587Z,1505857386.587 [Default:A.Wait](DEBUG): Initialize Wait Component.
2017-09-19T21:43:08.943Z,1505857388.943 [PNI_TCM](ERROR): CRC does not match. Expected:0x22151 got:0x16997
2017-09-19T21:43:15.780Z,1505857395.780 [PNI_TCM](ERROR): CRC does not match. Expected:0x12758 got:0x5149
2017-09-19T21:43:19.776Z,1505857399.776 [Default:A.Wait](INFO): Done Waiting.
2017-09-19T21:43:19.776Z,1505857399.776 [Default:A.Wait] Stopped
2017-09-19T21:43:19.776Z,1505857399.776 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2017-09-19T21:43:20.198Z,1505857400.198 [Default:CheckIn] Running Loop=1
2017-09-19T21:43:20.198Z,1505857400.198 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2017-09-19T21:43:20.198Z,1505857400.198 [Default:CheckIn:Read_GPS] Running Loop=1
2017-09-19T21:43:20.571Z,1505857400.571 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2017-09-19T21:43:21.742Z,1505857401.742 [PNI_TCM](ERROR): CRC does not match. Expected:0x2858 got:0x36453
2017-09-19T21:43:23.345Z,1505857403.345 [PNI_TCM](ERROR): CRC does not match. Expected:0x33792 got:0x6593
2017-09-19T21:43:26.548Z,1505857406.548 [PNI_TCM](ERROR): CRC does not match. Expected:0x23536 got:0x18353
2017-09-19T21:43:32.955Z,1505857412.955 [PNI_TCM](ERROR): CRC does not match. Expected:0x46020 got:0x7232
2017-09-19T21:43:34.543Z,1505857414.543 [PNI_TCM](ERROR): CRC does not match. Expected:0x51104 got:0x17223
2017-09-19T21:43:39.350Z,1505857419.350 [PNI_TCM](ERROR): CRC does not match. Expected:0x16295 got:0x18340
2017-09-19T21:43:45.770Z,1505857425.770 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003707
2017-09-19T21:44:45.796Z,1505857485.796 [BPC1](ERROR): Failed to receive battery data
2017-09-19T21:44:45.796Z,1505857485.796 [BPC1] Communications Fault, FailCount= 1
2017-09-19T21:44:45.796Z,1505857485.796 [BPC1](ERROR): Communications Fault
2017-09-19T21:44:45.847Z,1505857485.847 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-19T21:44:47.020Z,1505857487.020 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:44:47.021Z,1505857487.021 [BPC1] No Fault, FailCount= 1
2017-09-19T21:45:03.741Z,1505857503.741 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2017-09-19T21:45:07.799Z,1505857507.799 [NAL9602](INFO): GPS fix at 20170919T214507: (36.802766, -121.788044)
2017-09-19T21:45:07.890Z,1505857507.890 [Default:CheckIn:Read_GPS] Stopped
2017-09-19T21:45:07.890Z,1505857507.890 [Default:CheckIn:Read_Iridium] Running Loop=1
2017-09-19T21:45:08.225Z,1505857508.225 [DeadReckonUsingMultipleVelocitySources](ERROR): Caught NaN! Will not write estimated position: latitude_ = nan, longitude_ = nan, depth_ = nan, horizontalPathLengthSinceLastFix_ = nan, latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:45:08.225Z,1505857508.225 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2017-09-19T21:45:08.225Z,1505857508.225 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-19T21:45:08.240Z,1505857508.240 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2017-09-19T21:45:08.272Z,1505857508.272 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-19T21:45:08.843Z,1505857508.843 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-19T21:45:08.843Z,1505857508.843 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2017-09-19T21:45:09.099Z,1505857509.099 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:45:09.104Z,1505857509.104 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:45:09.105Z,1505857509.105 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:45:15.223Z,1505857515.223 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T212528/Courier0004.lzma
2017-09-19T21:45:16.021Z,1505857516.021 [DataOverHttps](INFO): Moved sent file to Logs/20170919T212528/Courier0004.lzma.bak
2017-09-19T21:45:16.021Z,1505857516.021 [DataOverHttps](INFO): SBD MOMSN=5096527
2017-09-19T21:45:21.627Z,1505857521.627 [NAL9602](INFO): Powering down
2017-09-19T21:45:28.303Z,1505857528.303 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T212954/Courier0000.lzma
2017-09-19T21:45:29.071Z,1505857529.071 [DataOverHttps](INFO): Moved sent file to Logs/20170919T212954/Courier0000.lzma.bak
2017-09-19T21:45:29.071Z,1505857529.071 [DataOverHttps](INFO): SBD MOMSN=5096529
2017-09-19T21:45:42.614Z,1505857542.614 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T213349/Courier0000.lzma
2017-09-19T21:45:43.388Z,1505857543.388 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213349/Courier0000.lzma.bak
2017-09-19T21:45:43.389Z,1505857543.389 [DataOverHttps](INFO): SBD MOMSN=5096532
2017-09-19T21:45:54.575Z,1505857554.575 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T213716/Courier0000.lzma
2017-09-19T21:45:55.383Z,1505857555.383 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213716/Courier0000.lzma.bak
2017-09-19T21:45:55.384Z,1505857555.384 [DataOverHttps](INFO): SBD MOMSN=5096535
2017-09-19T21:46:05.650Z,1505857565.650 [DataOverHttps](INFO): Sending 109 bytes from file Logs/20170919T213930/Courier0000.lzma
2017-09-19T21:46:06.421Z,1505857566.421 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213930/Courier0000.lzma.bak
2017-09-19T21:46:06.421Z,1505857566.421 [DataOverHttps](INFO): SBD MOMSN=5096538
2017-09-19T21:46:17.113Z,1505857577.113 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20170919T213930/Courier0004.lzma
2017-09-19T21:46:17.883Z,1505857577.883 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213930/Courier0004.lzma.bak
2017-09-19T21:46:17.883Z,1505857577.883 [DataOverHttps](INFO): SBD MOMSN=5096542
2017-09-19T21:46:23.888Z,1505857583.888 [CommandLine](IMPORTANT): got command burn 5.000000
2017-09-19T21:46:28.918Z,1505857588.918 [CommandLine](IMPORTANT): Deactivating dropweight wire
2017-09-19T21:46:29.860Z,1505857589.860 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T212528/Express0005.lzma
2017-09-19T21:46:30.635Z,1505857590.635 [DataOverHttps](INFO): Moved sent file to Logs/20170919T212528/Express0005.lzma.bak
2017-09-19T21:46:30.635Z,1505857590.635 [DataOverHttps](INFO): SBD MOMSN=5096545
2017-09-19T21:46:45.100Z,1505857605.100 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T212954/Express0001.lzma
2017-09-19T21:46:45.887Z,1505857605.887 [DataOverHttps](INFO): Moved sent file to Logs/20170919T212954/Express0001.lzma.bak
2017-09-19T21:46:45.888Z,1505857605.888 [DataOverHttps](INFO): SBD MOMSN=5096547
2017-09-19T21:46:58.964Z,1505857618.964 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T213349/Express0001.lzma
2017-09-19T21:46:59.773Z,1505857619.773 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213349/Express0001.lzma.bak
2017-09-19T21:46:59.774Z,1505857619.774 [DataOverHttps](INFO): SBD MOMSN=5096549
2017-09-19T21:47:10.672Z,1505857630.672 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20170919T213716/Express0001.lzma
2017-09-19T21:47:11.464Z,1505857631.464 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213716/Express0001.lzma.bak
2017-09-19T21:47:11.464Z,1505857631.464 [DataOverHttps](INFO): SBD MOMSN=5096551
2017-09-19T21:47:22.276Z,1505857642.276 [DataOverHttps](INFO): Sending 628 bytes from file Logs/20170919T213930/Express0001.lzma
2017-09-19T21:47:23.010Z,1505857643.010 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213930/Express0001.lzma.bak
2017-09-19T21:47:23.010Z,1505857643.010 [DataOverHttps](INFO): SBD MOMSN=5096553
2017-09-19T21:47:33.778Z,1505857653.778 [DataOverHttps](INFO): Sending 299 bytes from file Logs/20170919T213930/Express0005.lzma
2017-09-19T21:47:34.569Z,1505857654.569 [DataOverHttps](INFO): Moved sent file to Logs/20170919T213930/Express0005.lzma.bak
2017-09-19T21:47:34.569Z,1505857654.569 [DataOverHttps](INFO): SBD MOMSN=5096565
2017-09-19T21:47:35.036Z,1505857655.036 [Default:CheckIn:Read_Iridium] Stopped
2017-09-19T21:47:35.036Z,1505857655.036 [Default:CheckIn:C.Wait] Running Loop=1
2017-09-19T21:47:35.036Z,1505857655.036 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2017-09-19T21:48:09.313Z,1505857689.313 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:48:09.313Z,1505857689.313 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2017-09-19T21:48:09.313Z,1505857689.313 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-19T21:48:09.336Z,1505857689.336 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-19T21:48:09.804Z,1505857689.804 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-19T21:48:09.804Z,1505857689.804 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2017-09-19T21:48:10.121Z,1505857690.121 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:48:10.121Z,1505857690.121 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:48:10.142Z,1505857690.142 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:48:26.577Z,1505857706.577 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2017-09-19T21:48:27.370Z,1505857707.370 [Rowe_600LCM](DEBUG): LCB error: Software Overcurrent.
2017-09-19T21:49:47.466Z,1505857787.466 [CBIT](DEBUG): EFC running - data check-sum false
2017-09-19T21:51:10.300Z,1505857870.300 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:51:10.300Z,1505857870.300 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2017-09-19T21:51:10.300Z,1505857870.300 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-19T21:51:10.332Z,1505857870.332 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-19T21:51:10.737Z,1505857870.737 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-19T21:51:10.737Z,1505857870.737 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2017-09-19T21:51:11.091Z,1505857871.091 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:51:11.092Z,1505857871.092 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:51:11.092Z,1505857871.092 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:51:57.464Z,1505857917.464 [BPC1](ERROR): Failed to receive battery data
2017-09-19T21:51:57.464Z,1505857917.464 [BPC1] Communications Fault, FailCount= 1
2017-09-19T21:51:57.464Z,1505857917.464 [BPC1](ERROR): Communications Fault
2017-09-19T21:51:57.535Z,1505857917.535 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-19T21:51:58.702Z,1505857918.702 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:51:58.703Z,1505857918.703 [BPC1] No Fault, FailCount= 1
2017-09-19T21:52:35.507Z,1505857955.507 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2017-09-19T21:52:35.508Z,1505857955.508 [Default:CheckIn:C.Wait] Stopped
2017-09-19T21:52:35.508Z,1505857955.508 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2017-09-19T21:52:35.508Z,1505857955.508 [Default:CheckIn:D] Running Loop=1
2017-09-19T21:52:35.898Z,1505857955.898 [Default:CheckIn:D] Stopped
2017-09-19T21:52:35.898Z,1505857955.898 [Default:CheckIn:E] Running Loop=1
2017-09-19T21:52:36.300Z,1505857956.300 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.488516 min 
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn:E] Stopped
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn](INFO): Completed Default:CheckIn
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn] Stopped
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn](INFO): Running loop #2
2017-09-19T21:52:36.306Z,1505857956.306 [Default:CheckIn] Running Loop=2
2017-09-19T21:52:36.307Z,1505857956.307 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2017-09-19T21:52:36.307Z,1505857956.307 [Default:CheckIn:Read_GPS] Running Loop=1
2017-09-19T21:52:40.388Z,1505857960.388 [NAL9602](INFO): Powering up
2017-09-19T21:52:51.580Z,1505857971.580 [NAL9602](INFO): NAL9602 initialized
2017-09-19T21:53:23.584Z,1505858003.584 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2017-09-19T21:53:23.662Z,1505858003.662 [NAL9602](FAULT): received: 
+CSQ:0

OK
2017-09-19T21:53:23.662Z,1505858003.662 [NAL9602] Data Fault, FailCount= 1
2017-09-19T21:53:23.662Z,1505858003.662 [NAL9602](ERROR): Data Fault
2017-09-19T21:53:23.770Z,1505858003.770 [CBIT](ERROR): Data Fault in component: NAL9602
2017-09-19T21:53:23.988Z,1505858003.988 [NAL9602](INFO): Powering down
2017-09-19T21:53:24.935Z,1505858004.935 [CBIT](INFO): Clearing failed state for component NAL9602
2017-09-19T21:53:24.935Z,1505858004.935 [NAL9602] No Fault, FailCount= 1
2017-09-19T21:53:29.172Z,1505858009.172 [NAL9602](INFO): Powering up NAL9602
2017-09-19T21:53:43.213Z,1505858023.213 [BPC1](ERROR): Failed to receive battery data
2017-09-19T21:53:43.213Z,1505858023.213 [BPC1] Communications Fault, FailCount= 1
2017-09-19T21:53:43.213Z,1505858023.213 [BPC1](ERROR): Communications Fault
2017-09-19T21:53:43.280Z,1505858023.280 [CBIT](ERROR): Communications Fault in component: BPC1
2017-09-19T21:53:43.707Z,1505858023.707 [NAL9602](INFO): NAL9602 initialized
2017-09-19T21:53:44.251Z,1505858024.251 [CBIT](INFO): Clearing failed state for component BPC1
2017-09-19T21:53:44.251Z,1505858024.251 [BPC1] No Fault, FailCount= 1
2017-09-19T21:53:46.552Z,1505858026.552 [PNI_TCM](ERROR): CRC does not match. Expected:0x13489 got:0x1305
2017-09-19T21:54:11.372Z,1505858051.372 [DeadReckonUsingMultipleVelocitySources](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2017-09-19T21:54:11.372Z,1505858051.372 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2017-09-19T21:54:11.372Z,1505858051.372 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2017-09-19T21:54:11.417Z,1505858051.417 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2017-09-19T21:54:11.849Z,1505858051.849 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2017-09-19T21:54:11.849Z,1505858051.849 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2017-09-19T21:54:12.185Z,1505858052.185 [DeadReckonUsingMultipleVelocitySources](DEBUG): Initializing DeadReckonUsingMultipleVelocitySources component.
2017-09-19T21:54:12.185Z,1505858052.185 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider orientation measurement stale after 120s.
2017-09-19T21:54:12.185Z,1505858052.185 [DeadReckonUsingMultipleVelocitySources](INFO): Will consider velocity measurement stale after 20s.
2017-09-19T21:54:24.168Z,1505858064.168 [PNI_TCM](ERROR): CRC does not match. Expected:0x41380 got:0x54533
2017-09-19T21:54:30.571Z,1505858070.571 [PNI_TCM](ERROR): CRC does not match. Expected:0x53594 got:0x36892
2017-09-19T21:54:41.539Z,1505858081.539 [DataOverHttps](IMPORTANT): SBD MTMSN=20170919T215441
2017-09-19T21:54:46.482Z,1505858086.482 [DataOverHttps](INFO): Received command:restart app
2017-09-19T21:54:46.529Z,1505858086.529 [CommandLine](IMPORTANT): got command restart application
2017-09-19T21:54:47.541Z,1505858087.541 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:47.541Z,1505858087.541 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:47.691Z,1505858087.691 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2017-09-19T21:54:47.691Z,1505858087.691 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:47.692Z,1505858087.692 [CommandLine](INFO): Join timeout helper Thread ID is 942
2017-09-19T21:54:47.701Z,1505858087.701 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2017-09-19T21:54:47.701Z,1505858087.701 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:47.702Z,1505858087.702 [NavChartDb](INFO): Join timeout helper Thread ID is 943
2017-09-19T21:54:48.099Z,1505858088.099 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:48.100Z,1505858088.100 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:48.107Z,1505858088.107 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler
2017-09-19T21:54:48.107Z,1505858088.107 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:48.108Z,1505858088.108 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 944
2017-09-19T21:54:48.556Z,1505858088.556 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:48.557Z,1505858088.557 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface
2017-09-19T21:54:48.749Z,1505858088.749 [Rowe_600LCM](INFO): Powering down
2017-09-19T21:54:48.751Z,1505858088.751 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:48.756Z,1505858088.756 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2017-09-19T21:54:48.756Z,1505858088.756 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:48.757Z,1505858088.757 [Radio_Surface](INFO): Join timeout helper Thread ID is 946
2017-09-19T21:54:49.065Z,1505858089.065 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:49.065Z,1505858089.065 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.081Z,1505858089.081 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2017-09-19T21:54:49.081Z,1505858089.081 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.081Z,1505858089.081 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 947
2017-09-19T21:54:49.402Z,1505858089.402 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:49.402Z,1505858089.402 [WetLabsBB2FL](INFO): Powering down
2017-09-19T21:54:49.403Z,1505858089.403 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.410Z,1505858089.410 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2017-09-19T21:54:49.411Z,1505858089.411 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.411Z,1505858089.411 [CTD_Seabird](INFO): Join timeout helper Thread ID is 948
2017-09-19T21:54:49.651Z,1505858089.651 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:49.907Z,1505858089.907 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2017-09-19T21:54:49.907Z,1505858089.907 [CTD_Seabird](INFO): Powering down
2017-09-19T21:54:49.908Z,1505858089.908 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.915Z,1505858089.915 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2017-09-19T21:54:49.915Z,1505858089.915 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:49.916Z,1505858089.916 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 950
2017-09-19T21:54:50.071Z,1505858090.071 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:50.071Z,1505858090.071 [CTD_NeilBrown](INFO): Powering down
2017-09-19T21:54:50.072Z,1505858090.072 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.079Z,1505858090.079 [ComponentRegistry](INFO): Shutting down lcmLoadTest ThreadHandler
2017-09-19T21:54:50.079Z,1505858090.079 [lcmLoadTest ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.080Z,1505858090.080 [lcmLoadTest](INFO): Join timeout helper Thread ID is 951
2017-09-19T21:54:50.127Z,1505858090.127 [lcmLoadTest ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:50.127Z,1505858090.127 [lcmLoadTest ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.129Z,1505858090.129 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2017-09-19T21:54:50.129Z,1505858090.129 [logger ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.129Z,1505858090.129 [logger](INFO): Join timeout helper Thread ID is 952
2017-09-19T21:54:50.152Z,1505858090.152 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:50.152Z,1505858090.152 [logger ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.163Z,1505858090.163 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2017-09-19T21:54:50.163Z,1505858090.163 [CommandLine ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.164Z,1505858090.164 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2017-09-19T21:54:50.164Z,1505858090.164 [controlThread ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.164Z,1505858090.164 [controlThread](INFO): Join timeout helper Thread ID is 953
2017-09-19T21:54:50.427Z,1505858090.427 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2017-09-19T21:54:50.427Z,1505858090.427 [controlThread](DEBUG): Uninitializing ControlThread
2017-09-19T21:54:50.428Z,1505858090.428 [Aanderaa_O2](INFO): Powering down
2017-09-19T21:54:50.430Z,1505858090.430 [NAL9602](INFO): Powering down
2017-09-19T21:54:50.431Z,1505858090.431 [DAT](INFO): Powering down
2017-09-19T21:54:50.551Z,1505858090.551 [PNI_TCM](INFO): Powering down
2017-09-19T21:54:50.640Z,1505858090.640 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2017-09-19T21:54:50.642Z,1505858090.642 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2017-09-19T21:54:50.643Z,1505858090.643 [MissionManager](INFO): Uninitializing Mission Default
2017-09-19T21:54:50.643Z,1505858090.643 [Default] Stopped
2017-09-19T21:54:50.643Z,1505858090.643 [Default](DEBUG): Aggregate::uninitialize Default
2017-09-19T21:54:50.643Z,1505858090.643 [Default:B.GoToSurface] Stopped
2017-09-19T21:54:50.643Z,1505858090.643 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2017-09-19T21:54:50.643Z,1505858090.643 [Default:CheckIn] Stopped
2017-09-19T21:54:50.643Z,1505858090.643 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2017-09-19T21:54:50.643Z,1505858090.643 [Default:CheckIn:Read_GPS] Stopped
2017-09-19T21:54:50.648Z,1505858090.648 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2017-09-19T21:54:50.648Z,1505858090.648 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2017-09-19T21:54:50.648Z,1505858090.648 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2017-09-19T21:54:50.649Z,1505858090.649 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2017-09-19T21:54:50.649Z,1505858090.649 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2017-09-19T21:54:50.649Z,1505858090.649 [BuoyancyServo](INFO): Powering down
2017-09-19T21:54:50.663Z,1505858090.663 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2017-09-19T21:54:50.663Z,1505858090.663 [ElevatorServo](INFO): Powering down
2017-09-19T21:54:50.665Z,1505858090.665 [MassServo](DEBUG): Uninitialize Mass Servo.
2017-09-19T21:54:50.665Z,1505858090.665 [MassServo](INFO): Powering down
2017-09-19T21:54:50.666Z,1505858090.666 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2017-09-19T21:54:50.666Z,1505858090.666 [RudderServo](INFO): Powering down
2017-09-19T21:54:50.667Z,1505858090.667 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2017-09-19T21:54:50.667Z,1505858090.667 [ThrusterServo](INFO): Powering down
2017-09-19T21:54:50.668Z,1505858090.668 [SBIT](DEBUG): Uninitialize SBIT Component.
2017-09-19T21:54:50.669Z,1505858090.669 [IBIT](DEBUG): Uninitialize IBIT Component.
2017-09-19T21:54:50.669Z,1505858090.669 [CBIT](DEBUG): Uninitialize CBIT Component.
2017-09-19T21:54:50.670Z,1505858090.670 [controlThread ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:50.766Z,1505858090.766 [lcmLoadTest ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:59.764Z,1505858099.764 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:59.769Z,1505858099.769 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:54:59.772Z,1505858099.772 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:55:00.257Z,1505858100.257 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:55:00.267Z,1505858100.267 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:55:00.318Z,1505858100.318 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2017-09-19T21:55:00.412Z,1505858100.412 [logger ThreadHandler](INFO): Thread cancelled.