2019-09-12T19:36:18.595Z,1568316978.595 [Supervisor](DEBUG): Initializing supervisor. 2019-09-12T19:36:18.597Z,1568316978.597 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-09-12T19:36:18.598Z,1568316978.598 [SyncHandler](INFO): Protected caller Thread ID is 5701 2019-09-12T19:36:18.598Z,1568316978.598 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-09-12T19:36:18.599Z,1568316978.599 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-09-12T19:36:18.600Z,1568316978.600 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 5702 2019-09-12T19:36:18.602Z,1568316978.602 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-09-12T19:36:18.613Z,1568316978.613 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-09-12T19:36:18.614Z,1568316978.614 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-09-12T19:36:18.614Z,1568316978.614 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 5703 2019-09-12T19:36:18.615Z,1568316978.615 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-09-12T19:36:18.616Z,1568316978.616 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-09-12T19:36:18.616Z,1568316978.616 [logger ThreadHandler](INFO): Protected caller Thread ID is 5704 2019-09-12T19:36:18.618Z,1568316978.618 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-09-12T19:36:18.618Z,1568316978.618 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-09-12T19:36:18.620Z,1568316978.620 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-09-12T19:36:19.027Z,1568316979.027 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-09-12T19:36:19.027Z,1568316979.027 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-09-12T19:36:19.174Z,1568316979.174 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-09-12T19:36:19.174Z,1568316979.174 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-09-12T19:36:19.261Z,1568316979.261 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-09-12T19:36:19.360Z,1568316979.360 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-09-12T19:36:19.360Z,1568316979.360 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-09-12T19:36:19.456Z,1568316979.456 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-09-12T19:36:19.456Z,1568316979.456 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-09-12T19:36:19.879Z,1568316979.879 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-09-12T19:36:19.880Z,1568316979.880 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-09-12T19:36:19.982Z,1568316979.982 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-09-12T19:36:19.983Z,1568316979.983 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-09-12T19:36:20.429Z,1568316980.429 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-09-12T19:36:20.430Z,1568316980.430 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-09-12T19:36:20.624Z,1568316980.624 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-09-12T19:36:20.625Z,1568316980.625 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-09-12T19:36:20.920Z,1568316980.920 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-09-12T19:36:20.921Z,1568316980.921 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-09-12T19:36:21.129Z,1568316981.129 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-09-12T19:36:21.130Z,1568316981.130 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-09-12T19:36:21.270Z,1568316981.270 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-09-12T19:36:21.271Z,1568316981.271 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-09-12T19:36:21.870Z,1568316981.870 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-09-12T19:36:21.870Z,1568316981.870 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-09-12T19:36:22.210Z,1568316982.210 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-09-12T19:36:22.210Z,1568316982.210 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-09-12T19:36:22.413Z,1568316982.413 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-09-12T19:36:22.415Z,1568316982.415 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-triton/ 2019-09-12T19:36:22.416Z,1568316982.416 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/vehicle.cfg 2019-09-12T19:36:22.604Z,1568316982.604 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/secure.cfg 2019-09-12T19:36:22.689Z,1568316982.689 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Science.cfg 2019-09-12T19:36:22.821Z,1568316982.821 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Simulator.cfg 2019-09-12T19:36:22.908Z,1568316982.908 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Battery.cfg 2019-09-12T19:36:23.136Z,1568316983.136 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-09-12T19:36:23.137Z,1568316983.137 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/logger.cfg 2019-09-12T19:36:23.231Z,1568316983.231 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Servo.cfg 2019-09-12T19:36:23.339Z,1568316983.339 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Navigation.cfg 2019-09-12T19:36:23.434Z,1568316983.434 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Sensor.cfg 2019-09-12T19:36:23.578Z,1568316983.578 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/Control.cfg 2019-09-12T19:36:23.678Z,1568316983.678 [Supervisor](INFO): Opening Config file at: Config/lrauv-triton/BIT.cfg 2019-09-12T19:36:23.776Z,1568316983.776 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg 2019-09-12T19:36:23.778Z,1568316983.778 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-09-12T19:36:23.791Z,1568316983.791 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-09-12T19:36:23.792Z,1568316983.792 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-09-12T19:36:23.854Z,1568316983.854 [VerticalControl](DEBUG): Construct VerticalControl. 2019-09-12T19:36:23.962Z,1568316983.962 [VerticalControl] Loaded 2019-09-12T19:36:23.963Z,1568316983.963 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-09-12T19:36:23.963Z,1568316983.963 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-09-12T19:36:24.028Z,1568316984.028 [HorizontalControl] Loaded 2019-09-12T19:36:24.029Z,1568316984.029 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-09-12T19:36:24.029Z,1568316984.029 [SpeedControl](DEBUG): Construct SpeedControl. 2019-09-12T19:36:24.035Z,1568316984.035 [SpeedControl] Loaded 2019-09-12T19:36:24.035Z,1568316984.035 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-09-12T19:36:24.036Z,1568316984.036 [LoopControl](DEBUG): Construct LoopControl. 2019-09-12T19:36:24.036Z,1568316984.036 [LoopControl] Loaded 2019-09-12T19:36:24.037Z,1568316984.037 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-09-12T19:36:24.037Z,1568316984.037 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-09-12T19:36:24.037Z,1568316984.037 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-09-12T19:36:24.136Z,1568316984.136 [BuoyancyServo] Loaded 2019-09-12T19:36:24.136Z,1568316984.136 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-09-12T19:36:24.147Z,1568316984.147 [ElevatorServo] Loaded 2019-09-12T19:36:24.147Z,1568316984.147 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-09-12T19:36:24.157Z,1568316984.157 [MassServo] Loaded 2019-09-12T19:36:24.158Z,1568316984.158 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-09-12T19:36:24.168Z,1568316984.168 [RudderServo] Loaded 2019-09-12T19:36:24.168Z,1568316984.168 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-09-12T19:36:24.179Z,1568316984.179 [ThrusterServo] Loaded 2019-09-12T19:36:24.179Z,1568316984.179 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-09-12T19:36:24.179Z,1568316984.179 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-09-12T19:36:24.180Z,1568316984.180 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-09-12T19:36:24.218Z,1568316984.218 [DepthRateCalculator] Loaded 2019-09-12T19:36:24.218Z,1568316984.218 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-09-12T19:36:24.223Z,1568316984.223 [PitchRateCalculator] Loaded 2019-09-12T19:36:24.223Z,1568316984.223 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-09-12T19:36:24.238Z,1568316984.238 [SpeedCalculator] Loaded 2019-09-12T19:36:24.238Z,1568316984.238 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-09-12T19:36:24.258Z,1568316984.258 [TempGradientCalculator] Loaded 2019-09-12T19:36:24.259Z,1568316984.259 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-09-12T19:36:24.264Z,1568316984.264 [YawRateCalculator] Loaded 2019-09-12T19:36:24.264Z,1568316984.264 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-09-12T19:36:24.292Z,1568316984.292 [ElevatorOffsetCalculator] Loaded 2019-09-12T19:36:24.292Z,1568316984.292 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-09-12T19:36:24.293Z,1568316984.293 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-09-12T19:36:24.293Z,1568316984.293 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-09-12T19:36:24.392Z,1568316984.392 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-09-12T19:36:24.392Z,1568316984.392 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-09-12T19:36:24.412Z,1568316984.412 [NavChart] Loaded 2019-09-12T19:36:24.412Z,1568316984.412 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-09-12T19:36:24.416Z,1568316984.416 [UniversalFixResidualReporter] Loaded 2019-09-12T19:36:24.416Z,1568316984.416 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-09-12T19:36:24.416Z,1568316984.416 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-09-12T19:36:24.417Z,1568316984.417 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-09-12T19:36:24.643Z,1568316984.643 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation 2019-09-12T19:36:24.648Z,1568316984.648 [AHRS_M2](INFO): created writer for : platform_orientation 2019-09-12T19:36:24.650Z,1568316984.650 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation 2019-09-12T19:36:24.655Z,1568316984.655 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation 2019-09-12T19:36:24.655Z,1568316984.655 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle 2019-09-12T19:36:24.660Z,1568316984.660 [AHRS_M2](INFO): created writer for : platform_pitch_angle 2019-09-12T19:36:24.661Z,1568316984.661 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle 2019-09-12T19:36:24.666Z,1568316984.666 [AHRS_M2](INFO): created writer for : platform_roll_angle 2019-09-12T19:36:24.734Z,1568316984.734 [AHRS_M2] Loaded 2019-09-12T19:36:24.734Z,1568316984.734 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread. 2019-09-12T19:36:24.810Z,1568316984.810 [DataOverHttps] Loaded 2019-09-12T19:36:24.810Z,1568316984.810 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-09-12T19:36:24.811Z,1568316984.811 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407F84E0 2019-09-12T19:36:24.811Z,1568316984.811 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 5783 2019-09-12T19:36:24.824Z,1568316984.824 [Depth_Keller] Loaded 2019-09-12T19:36:24.824Z,1568316984.824 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-09-12T19:36:24.829Z,1568316984.829 [DropWeight] Loaded 2019-09-12T19:36:24.829Z,1568316984.829 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread. 2019-09-12T19:36:24.873Z,1568316984.873 [DVL_micro] Loaded 2019-09-12T19:36:24.873Z,1568316984.873 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread. 2019-09-12T19:36:24.965Z,1568316984.965 [NAL9602] Loaded 2019-09-12T19:36:24.966Z,1568316984.966 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-09-12T19:36:24.981Z,1568316984.981 [Onboard] Loaded 2019-09-12T19:36:24.981Z,1568316984.981 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-09-12T19:36:24.984Z,1568316984.984 [Radio_Surface] Loaded 2019-09-12T19:36:24.984Z,1568316984.984 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-09-12T19:36:24.985Z,1568316984.985 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408284E0 2019-09-12T19:36:24.986Z,1568316984.986 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 5784 2019-09-12T19:36:25.107Z,1568316985.107 [DAT] Loaded 2019-09-12T19:36:25.108Z,1568316985.108 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2019-09-12T19:36:26.559Z,1568316986.559 [BPC1] Loaded 2019-09-12T19:36:26.559Z,1568316986.559 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread. 2019-09-12T19:36:26.559Z,1568316986.559 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-09-12T19:36:26.560Z,1568316986.560 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-09-12T19:36:26.795Z,1568316986.795 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-09-12T19:36:26.795Z,1568316986.795 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-09-12T19:36:27.105Z,1568316987.105 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-09-12T19:36:27.105Z,1568316987.105 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-09-12T19:36:27.517Z,1568316987.517 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-09-12T19:36:27.517Z,1568316987.517 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-09-12T19:36:27.680Z,1568316987.680 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density 2019-09-12T19:36:27.685Z,1568316987.685 [CTD_Seabird](INFO): created writer for : sea_water_density 2019-09-12T19:36:27.686Z,1568316987.686 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth 2019-09-12T19:36:27.690Z,1568316987.690 [CTD_Seabird](INFO): created writer for : depth 2019-09-12T19:36:27.691Z,1568316987.691 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure 2019-09-12T19:36:27.696Z,1568316987.696 [CTD_Seabird](INFO): created writer for : sea_water_pressure 2019-09-12T19:36:27.697Z,1568316987.697 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity 2019-09-12T19:36:27.702Z,1568316987.702 [CTD_Seabird](INFO): created writer for : sea_water_salinity 2019-09-12T19:36:27.702Z,1568316987.702 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature 2019-09-12T19:36:27.707Z,1568316987.707 [CTD_Seabird](INFO): created writer for : sea_water_temperature 2019-09-12T19:36:27.708Z,1568316987.708 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity 2019-09-12T19:36:27.713Z,1568316987.713 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity 2019-09-12T19:36:27.713Z,1568316987.713 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water 2019-09-12T19:36:27.718Z,1568316987.718 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water 2019-09-12T19:36:27.719Z,1568316987.719 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): mass_concentration_of_oxygen_in_sea_water 2019-09-12T19:36:27.724Z,1568316987.724 [CTD_Seabird](INFO): created writer for : mass_concentration_of_oxygen_in_sea_water 2019-09-12T19:36:27.725Z,1568316987.725 [CTD_Seabird](DEBUG): LcmSlateWriter::add(DAtaURI): CTD_Seabird.sea_water_dissolved_oxygen_freq 2019-09-12T19:36:27.725Z,1568316987.725 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): dataName: sea_water_dissolved_oxygen_freq 2019-09-12T19:36:27.757Z,1568316987.757 [CTD_Seabird] Loaded 2019-09-12T19:36:27.757Z,1568316987.757 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread. 2019-09-12T19:36:27.758Z,1568316987.758 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409BF4E0 2019-09-12T19:36:27.759Z,1568316987.759 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 5785 2019-09-12T19:36:27.773Z,1568316987.773 [PAR_Licor] Loaded 2019-09-12T19:36:27.773Z,1568316987.773 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-09-12T19:36:27.818Z,1568316987.818 [WetLabsBB2FL] Loaded 2019-09-12T19:36:27.819Z,1568316987.819 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-09-12T19:36:27.820Z,1568316987.820 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409EF4E0 2019-09-12T19:36:27.820Z,1568316987.820 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 5786 2019-09-12T19:36:27.821Z,1568316987.821 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-09-12T19:36:27.821Z,1568316987.821 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-09-12T19:36:28.102Z,1568316988.102 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-09-12T19:36:28.102Z,1568316988.102 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-09-12T19:36:28.227Z,1568316988.227 [SBIT](DEBUG): Construct Startup Built In Test. 2019-09-12T19:36:28.237Z,1568316988.237 [SBIT] Loaded 2019-09-12T19:36:28.237Z,1568316988.237 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-09-12T19:36:28.238Z,1568316988.238 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-09-12T19:36:28.249Z,1568316988.249 [IBIT] Loaded 2019-09-12T19:36:28.250Z,1568316988.250 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-09-12T19:36:28.252Z,1568316988.252 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-09-12T19:36:28.387Z,1568316988.387 [CBIT] Loaded 2019-09-12T19:36:28.387Z,1568316988.387 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-09-12T19:36:28.388Z,1568316988.388 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-09-12T19:36:28.391Z,1568316988.391 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-09-12T19:36:28.392Z,1568316988.392 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-09-12T19:36:28.398Z,1568316988.398 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-09-12T19:36:28.399Z,1568316988.399 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ACE4E0 2019-09-12T19:36:28.400Z,1568316988.400 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 5787 2019-09-12T19:36:28.404Z,1568316988.404 [Supervisor](INFO): Main Thread ID is 5700 2019-09-12T19:36:28.404Z,1568316988.404 [Supervisor](DEBUG): Running supervisor. 2019-09-12T19:36:28.405Z,1568316988.405 [CommandLine ThreadHandler](INFO): Handler Thread ID is 5788 2019-09-12T19:36:28.407Z,1568316988.407 [controlThread ThreadHandler](INFO): Handler Thread ID is 5789 2019-09-12T19:36:28.408Z,1568316988.408 [controlThread](DEBUG): Initializing ControlThread 2019-09-12T19:36:28.408Z,1568316988.408 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-09-12T19:36:28.410Z,1568316988.410 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-09-12T19:36:28.411Z,1568316988.411 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-09-12T19:36:28.411Z,1568316988.411 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-09-12T19:36:28.413Z,1568316988.413 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-09-12T19:36:28.413Z,1568316988.413 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-09-12T19:36:28.413Z,1568316988.413 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-09-12T19:36:28.413Z,1568316988.413 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-09-12T19:36:28.414Z,1568316988.414 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-09-12T19:36:28.414Z,1568316988.414 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-09-12T19:36:28.415Z,1568316988.415 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-09-12T19:36:28.416Z,1568316988.416 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-09-12T19:36:28.421Z,1568316988.421 [SBIT](INFO): Initialize SBIT Component. 2019-09-12T19:36:28.422Z,1568316988.422 [SBIT](IMPORTANT): git: 2019-09-12-A 2019-09-12T19:36:28.422Z,1568316988.422 [SBIT](INFO): git hash: eb701a7227645e802542eb6676257ee77fc4e0fc 2019-09-12T19:36:28.422Z,1568316988.422 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-09-12T19:36:28.423Z,1568316988.423 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018 Kernel Reported: #1 PREEMPT Thu Feb 21 11:17:40 PST 2019 2019-09-12T19:36:28.424Z,1568316988.424 [SBIT](INFO): Beginning SBIT in 30.000000 seconds. 2019-09-12T19:36:28.425Z,1568316988.425 [IBIT](INFO): Initialize IBIT Component. 2019-09-12T19:36:28.426Z,1568316988.426 [CBIT](DEBUG): Initialize CBIT Component. 2019-09-12T19:36:28.427Z,1568316988.427 [logger ThreadHandler](INFO): Handler Thread ID is 5790 2019-09-12T19:36:28.437Z,1568316988.437 [CBIT](DEBUG): Initialized mux pins. 2019-09-12T19:36:28.437Z,1568316988.437 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL. 2019-09-12T19:36:28.437Z,1568316988.437 [CBIT](DEBUG): Initializing the watchdog timer. 2019-09-12T19:36:28.445Z,1568316988.445 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 5791 2019-09-12T19:36:28.446Z,1568316988.446 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-09-12T19:36:28.457Z,1568316988.457 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 5792 2019-09-12T19:36:28.461Z,1568316988.461 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-09-12T19:36:28.461Z,1568316988.461 [CBIT](DEBUG): Initializing heartbeat. 2019-09-12T19:36:28.469Z,1568316988.469 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 5793 2019-09-12T19:36:28.470Z,1568316988.470 [CTD_Seabird](DEBUG): Initializing CTD_Seabird. 2019-09-12T19:36:28.473Z,1568316988.473 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20 2019-09-12T19:36:28.474Z,1568316988.474 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 5795 2019-09-12T19:36:28.476Z,1568316988.476 [WetLabsBB2FL](INFO): Powering down 2019-09-12T19:36:28.502Z,1568316988.502 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 5796 2019-09-12T19:36:28.505Z,1568316988.505 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-09-12T19:36:28.506Z,1568316988.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-09-12T19:36:28.506Z,1568316988.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-09-12T19:36:28.506Z,1568316988.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-09-12T19:36:28.506Z,1568316988.506 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-09-12T19:36:28.506Z,1568316988.506 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-09-12T19:36:28.507Z,1568316988.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-09-12T19:36:28.507Z,1568316988.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-09-12T19:36:28.507Z,1568316988.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-09-12T19:36:28.507Z,1568316988.507 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-09-12T19:36:28.507Z,1568316988.507 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-09-12T19:36:28.508Z,1568316988.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-09-12T19:36:28.508Z,1568316988.508 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-09-12T19:36:28.508Z,1568316988.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-09-12T19:36:28.508Z,1568316988.508 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-09-12T19:36:28.508Z,1568316988.508 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-09-12T19:36:28.533Z,1568316988.533 [CBIT](DEBUG): Deactivating GF circuits. 2019-09-12T19:36:28.533Z,1568316988.533 [CBIT](DEBUG): Deactivating emergency mode. 2019-09-12T19:36:28.569Z,1568316988.569 [CBIT](DEBUG): Backplane powered. 2019-09-12T19:36:28.570Z,1568316988.570 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-09-12T19:36:28.579Z,1568316988.579 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-09-12T19:36:28.589Z,1568316988.589 [MissionManager](DEBUG): 2019-09-12T19:36:28.590Z,1568316988.590 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-09-12T19:36:28.656Z,1568316988.656 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-09-12T19:36:28.657Z,1568316988.657 [Default:A.Wait](DEBUG): Construct Wait. 2019-09-12T19:36:28.658Z,1568316988.658 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-09-12T19:36:28.705Z,1568316988.705 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-09-12T19:36:28.708Z,1568316988.708 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-09-12T19:36:28.729Z,1568316988.729 [Default:E.Execute](DEBUG): Construct Execute. 2019-09-12T19:36:28.732Z,1568316988.732 [MissionManager](DEBUG): 0 Wait a moment to see if the scheduler starts a new mission before starting to actually run Default. 13 Burn on Dropped weight due to communications timeout. 5 Default mission has been running for Restarting logs and Default mission. restart logs 2019-09-12T19:36:28.745Z,1568316988.745 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DVL_micro,NAL9602,Onboard,DAT,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-09-12T19:36:28.757Z,1568316988.757 [AHRS_M2](DEBUG): Initializing AHRS_M2. 2019-09-12T19:36:28.820Z,1568316988.820 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2019-09-12T19:36:28.820Z,1568316988.820 [DAT](INFO): Powering up 2019-09-12T19:36:28.821Z,1568316988.821 [DAT](DEBUG): Initializing DAT. 2019-09-12T19:36:28.861Z,1568316988.861 [Radio_Surface](INFO): Powering up 2019-09-12T19:36:28.905Z,1568316988.905 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2019-09-12T19:36:28.959Z,1568316988.959 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:28.969Z,1568316988.969 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-09-12T19:36:28.970Z,1568316988.970 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:28.981Z,1568316988.981 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-09-12T19:36:28.982Z,1568316988.982 [MassServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:28.993Z,1568316988.993 [MassServo](DEBUG): Initializing MassServo. 2019-09-12T19:36:28.994Z,1568316988.994 [RudderServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:29.005Z,1568316989.005 [RudderServo](DEBUG): Initializing RudderServo. 2019-09-12T19:36:29.006Z,1568316989.006 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:29.013Z,1568316989.013 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-09-12T19:36:29.945Z,1568316989.945 [RudderServo](ERROR): Rudder initialization uart error serial timeout 2019-09-12T19:36:29.945Z,1568316989.945 [RudderServo](FAULT): Rudder failed to initialize 2019-09-12T19:36:29.945Z,1568316989.945 [RudderServo] Communications Fault, FailCount= 1 2019-09-12T19:36:29.945Z,1568316989.945 [RudderServo](ERROR): Communications Fault 2019-09-12T19:36:30.056Z,1568316990.056 [CBIT](ERROR): Communications Fault in component: RudderServo 2019-09-12T19:36:30.262Z,1568316990.262 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-09-12T19:36:30.262Z,1568316990.262 [RudderServo](INFO): Powering down 2019-09-12T19:36:30.925Z,1568316990.925 [RudderServo](DEBUG): Initializing EZServoServo. 2019-09-12T19:36:31.046Z,1568316991.046 [RudderServo](DEBUG): Initializing RudderServo. 2019-09-12T19:36:31.050Z,1568316991.050 [CBIT](INFO): Clearing failed state for component RudderServo 2019-09-12T19:36:31.050Z,1568316991.050 [RudderServo] No Fault, FailCount= 1 2019-09-12T19:36:42.234Z,1568317002.234 [DAT](INFO): setting local address to 5 2019-09-12T19:36:42.651Z,1568317002.651 [DAT](INFO): set local address to 5 2019-09-12T19:36:44.010Z,1568317004.010 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004646 2019-09-12T19:36:55.131Z,1568317015.131 [NAL9602](INFO): Powering up NAL9602 2019-09-12T19:36:59.251Z,1568317019.251 [SBIT](IMPORTANT): Beginning Startup BIT 2019-09-12T19:36:59.259Z,1568317019.259 [CBIT](IMPORTANT): Beginning ground fault scan 2019-09-12T19:37:06.183Z,1568317026.183 [NAL9602](INFO): NAL9602 initialized 2019-09-12T19:37:06.955Z,1568317026.955 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:10.274Z,1568317030.274 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.853497 CHAN A1 (24V): 0.986843 CHAN A2 (12V): 0.895543 CHAN A3 (5V): 0.474594 CHAN B0 (3.3V): 0.244590 CHAN B1 (3.15aV): 0.340377 CHAN B2 (3.15bV): 0.350946 CHAN B3 (GND): -0.017671 OPEN: 0.022529 Full Scale Calc: 4.765 mA, -1.589 mA 2019-09-12T19:37:12.593Z,1568317032.593 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:37:12.593Z,1568317032.593 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.51489.0,000 2019-09-12T19:37:24.020Z,1568317044.020 [NAL9602](INFO): SBD MO Status=0, MOMSN=1276, MT Status=0, MTMSN=0 2019-09-12T19:37:24.020Z,1568317044.020 [NAL9602](INFO): No messages in MT queue 2019-09-12T19:37:24.845Z,1568317044.845 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:27.265Z,1568317047.265 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:30.117Z,1568317050.117 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:33.329Z,1568317053.329 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:36.165Z,1568317056.165 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:39.389Z,1568317059.389 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:42.349Z,1568317062.349 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:45.181Z,1568317065.181 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:48.405Z,1568317068.405 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:51.240Z,1568317071.240 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:52.888Z,1568317072.888 [SBIT](IMPORTANT): SBIT PASSED 2019-09-12T19:37:52.926Z,1568317072.926 [CommandLine](IMPORTANT): got command configSet list 2019-09-12T19:37:52.926Z,1568317072.926 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-09-12T19:37:52.927Z,1568317072.927 [CommandLine](IMPORTANT): Express linearApproximation Tracking.range_to_contact 10.000000 meter; 2019-09-12T19:37:52.927Z,1568317072.927 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=270 cubic_centimeter; 2019-09-12T19:37:52.927Z,1568317072.927 [CommandLine](IMPORTANT): VerticalControl.massDefault=-4.25 millimeter; 2019-09-12T19:37:53.237Z,1568317073.237 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:37:53.237Z,1568317073.237 [DVL_micro](ERROR): Failed to parse: :TS,000000000.0,+21.5,0000.0,1489.0,000 2019-09-12T19:37:53.260Z,1568317073.260 [MissionManager](IMPORTANT): Started mission Startup 2019-09-12T19:37:53.260Z,1568317073.260 [Startup] Running Loop=1 2019-09-12T19:37:53.278Z,1568317073.278 [Startup](DEBUG): Aggregate::initialize Startup 2019-09-12T19:37:53.278Z,1568317073.278 [Startup:A.GoToSurface] Running Loop=1 2019-09-12T19:37:53.278Z,1568317073.278 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-09-12T19:37:53.279Z,1568317073.279 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-09-12T19:37:53.279Z,1568317073.279 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-09-12T19:37:53.280Z,1568317073.280 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-09-12T19:37:53.280Z,1568317073.280 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-09-12T19:37:53.301Z,1568317073.301 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-09-12T19:37:53.303Z,1568317073.303 [Startup:StartupSatComms] Running Loop=1 2019-09-12T19:37:53.303Z,1568317073.303 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-09-12T19:37:53.303Z,1568317073.303 [Startup:StartupSatComms:A] Running Loop=1 2019-09-12T19:37:53.670Z,1568317073.670 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-09-12T19:37:54.461Z,1568317074.461 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:37:57.293Z,1568317077.293 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:00.529Z,1568317080.529 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:03.357Z,1568317083.357 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:06.173Z,1568317086.173 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:09.409Z,1568317089.409 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:12.237Z,1568317092.237 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:15.065Z,1568317095.065 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:18.301Z,1568317098.301 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:21.137Z,1568317101.137 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:24.353Z,1568317104.353 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:27.183Z,1568317107.183 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:28.786Z,1568317108.786 [DVL_micro](ERROR): DVL BIT error. See manual. Result code: 128 2019-09-12T19:38:28.849Z,1568317108.849 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-09-12T19:38:28.849Z,1568317108.849 [DVL_micro] Communications Fault, FailCount= 1 2019-09-12T19:38:28.849Z,1568317108.849 [DVL_micro](ERROR): Communications Fault 2019-09-12T19:38:28.849Z,1568317108.849 [DVL_micro](ERROR): Failed to parse: 2019-09-12T19:38:28.967Z,1568317108.967 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-09-12T19:38:29.261Z,1568317109.261 [DVL_micro](INFO): Powering down 2019-09-12T19:38:30.013Z,1568317110.013 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:30.068Z,1568317110.068 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-09-12T19:38:30.068Z,1568317110.068 [DVL_micro] No Fault, FailCount= 1 2019-09-12T19:38:33.241Z,1568317113.241 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:36.061Z,1568317116.061 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:38:36.061Z,1568317116.061 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.5,009.0,000 2019-09-12T19:38:36.073Z,1568317116.073 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:38:36.469Z,1568317116.469 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193836.00,A,3648.35589,N,12147.86499,W,18.622,275.81,120919,,,A*4E 2019-09-12T19:38:36.472Z,1568317116.472 [NAL9602](INFO): GPS fix at 20190912T193836: (36.805931, -121.797750) 2019-09-12T19:38:36.537Z,1568317116.537 [Startup:StartupSatComms:A] Stopped 2019-09-12T19:38:36.538Z,1568317116.538 [Startup:StartupSatComms:B] Running Loop=1 2019-09-12T19:38:36.917Z,1568317116.917 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-09-12T19:38:46.220Z,1568317126.220 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:38:46.220Z,1568317126.220 [DVL_micro](ERROR): Failed to parse: :TS,000000035.0,+21.,1489.0,000 2019-09-12T19:38:48.416Z,1568317128.416 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190912T185414/Courier0022.lzma 2019-09-12T19:38:50.423Z,1568317130.423 [DataOverHttps](INFO): Moved sent file to Logs/20190912T185414/Courier0022.lzma.bak 2019-09-12T19:38:50.423Z,1568317130.423 [DataOverHttps](INFO): SBD MOMSN=11776826 2019-09-12T19:39:04.069Z,1568317144.069 [DVL_micro](ERROR): DVL uart error: serial timeout 2019-09-12T19:39:04.069Z,1568317144.069 [DVL_micro] Communications Fault, FailCount= 1 2019-09-12T19:39:04.069Z,1568317144.069 [DVL_micro](ERROR): Communications Fault 2019-09-12T19:39:04.069Z,1568317144.069 [DVL_micro](ERROR): Failed to parse: 2019-09-12T19:39:04.148Z,1568317144.148 [CBIT](ERROR): Communications Fault in component: DVL_micro 2019-09-12T19:39:04.481Z,1568317144.481 [DVL_micro](INFO): Powering down 2019-09-12T19:39:05.268Z,1568317145.268 [CBIT](INFO): Clearing failed state for component DVL_micro 2019-09-12T19:39:05.268Z,1568317145.268 [DVL_micro] No Fault, FailCount= 1 2019-09-12T19:39:09.246Z,1568317149.246 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T19:39:09.945Z,1568317149.945 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190912T193618/Courier0000.lzma 2019-09-12T19:39:11.950Z,1568317151.950 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0000.lzma.bak 2019-09-12T19:39:11.950Z,1568317151.950 [DataOverHttps](INFO): SBD MOMSN=11776828 2019-09-12T19:39:31.520Z,1568317171.520 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190912T185414/Express0023.lzma 2019-09-12T19:39:33.526Z,1568317173.526 [DataOverHttps](INFO): Moved sent file to Logs/20190912T185414/Express0023.lzma.bak 2019-09-12T19:39:33.527Z,1568317173.527 [DataOverHttps](INFO): SBD MOMSN=11776832 2019-09-12T19:39:36.785Z,1568317176.785 [Startup:StartupSatComms:B](INFO): Timed out from 2019-09-12T19:38:36.5Z 2019-09-12T19:39:36.785Z,1568317176.785 [Startup:StartupSatComms:B] Stopped 2019-09-12T19:39:36.785Z,1568317176.785 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-09-12T19:39:36.785Z,1568317176.785 [Startup:StartupSatComms] Stopped 2019-09-12T19:39:36.785Z,1568317176.785 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-09-12T19:39:36.786Z,1568317176.786 [Startup](INFO): Completed Startup 2019-09-12T19:39:36.786Z,1568317176.786 [MissionManager](INFO): Startup is completed. 2019-09-12T19:39:36.786Z,1568317176.786 [MissionManager](INFO): Uninitializing Mission Startup 2019-09-12T19:39:36.786Z,1568317176.786 [Startup] Stopped 2019-09-12T19:39:36.787Z,1568317176.787 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-09-12T19:39:36.787Z,1568317176.787 [Startup:A.GoToSurface] Stopped 2019-09-12T19:39:36.787Z,1568317176.787 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-09-12T19:39:37.177Z,1568317177.177 [MissionManager](IMPORTANT): Started mission Default 2019-09-12T19:39:37.177Z,1568317177.177 [Default] Running Loop=1 2019-09-12T19:39:37.177Z,1568317177.177 [Default](DEBUG): Aggregate::initialize Default 2019-09-12T19:39:37.177Z,1568317177.177 [Default:B.GoToSurface] Running Loop=1 2019-09-12T19:39:37.177Z,1568317177.177 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-09-12T19:39:37.178Z,1568317177.178 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-09-12T19:39:37.178Z,1568317177.178 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-09-12T19:39:37.178Z,1568317177.178 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-09-12T19:39:37.178Z,1568317177.178 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-09-12T19:39:37.179Z,1568317177.179 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-09-12T19:39:37.179Z,1568317177.179 [Default:A.Wait] Running Loop=1 2019-09-12T19:39:37.179Z,1568317177.179 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-09-12T19:39:46.823Z,1568317186.823 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T19:39:50.522Z,1568317190.522 [Default:A.Wait](INFO): Done Waiting. 2019-09-12T19:39:50.522Z,1568317190.522 [Default:A.Wait] Stopped 2019-09-12T19:39:50.522Z,1568317190.522 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T19:39:50.913Z,1568317190.913 [Default:CheckIn] Running Loop=1 2019-09-12T19:39:50.913Z,1568317190.913 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T19:39:50.913Z,1568317190.913 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T19:39:51.298Z,1568317191.298 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-09-12T19:39:52.497Z,1568317192.497 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:39:52.642Z,1568317192.642 [DataOverHttps](INFO): Sending 861 bytes from file Logs/20190912T193618/Express0001.lzma 2019-09-12T19:39:52.884Z,1568317192.884 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193952.00,A,3648.36581,N,12148.32614,W,18.019,253.28,120919,,,A*48 2019-09-12T19:39:52.886Z,1568317192.886 [NAL9602](INFO): GPS fix at 20190912T193952: (36.806097, -121.805436) 2019-09-12T19:39:52.939Z,1568317192.939 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T19:39:52.939Z,1568317192.939 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T19:39:53.328Z,1568317193.328 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-09-12T19:39:54.646Z,1568317194.646 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0001.lzma.bak 2019-09-12T19:39:54.646Z,1568317194.646 [DataOverHttps](INFO): SBD MOMSN=11776834 2019-09-12T19:40:07.828Z,1568317207.828 [NAL9602](INFO): SBD MO Status=0, MOMSN=1277, MT Status=0, MTMSN=0 2019-09-12T19:40:07.828Z,1568317207.828 [NAL9602](INFO): No messages in MT queue 2019-09-12T19:40:12.896Z,1568317212.896 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T193618/Courier0004.lzma 2019-09-12T19:40:14.902Z,1568317214.902 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0004.lzma.bak 2019-09-12T19:40:14.902Z,1568317214.902 [DataOverHttps](INFO): SBD MOMSN=11776852 2019-09-12T19:40:34.048Z,1568317234.048 [DataOverHttps](INFO): Sending 106 bytes from file Logs/20190912T193618/Express0005.lzma 2019-09-12T19:40:36.054Z,1568317236.054 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0005.lzma.bak 2019-09-12T19:40:36.054Z,1568317236.054 [DataOverHttps](INFO): SBD MOMSN=11776855 2019-09-12T19:40:38.538Z,1568317238.538 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T19:40:38.977Z,1568317238.977 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T19:40:38.977Z,1568317238.977 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T19:40:38.978Z,1568317238.978 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T19:41:33.482Z,1568317293.482 [DVL_micro](ERROR): Failed to parse: :WI,-01516,+02104,-00117,+00000,A 2019-09-12T19:41:51.266Z,1568317311.266 [DVL_micro](ERROR): Failed to parse: :BI,-01661+00241,+0:BD,+00000000.00,+000,+00000000.00,9999.99,000.00 2019-09-12T19:42:09.044Z,1568317329.044 [DVL_micro](ERROR): Failed to parse: :WI,-00371,+00222,-00029,+00000,A 2019-09-12T19:42:26.821Z,1568317346.821 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:42:26.821Z,1568317346.821 [DVL_micro](ERROR): Failed to parse: :TS0000000,35,0000.0,1489.0,000 2019-09-12T19:43:20.143Z,1568317400.143 [DVL_micro](ERROR): Failed to parse: :WI,-03108,+00296,+00668,+00000,A 2019-09-12T19:44:13.470Z,1568317453.470 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:44:13.470Z,1568317453.470 [DVL_micro](ERROR): Failed to parse: :TS,000000,35.0,00.0,1489.0,000 2019-09-12T19:44:25.214Z,1568317465.214 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:44:33.790Z,1568317473.790 [DataOverHttps](IMPORTANT): SBD MTMSN=20190912T194433 2019-09-12T19:44:38.565Z,1568317478.565 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:44:41.569Z,1568317481.569 [DataOverHttps](INFO): Received command:gfscan 2019-09-12T19:44:41.642Z,1568317481.642 [CommandLine](IMPORTANT): got command gfscan 2019-09-12T19:44:41.793Z,1568317481.793 [CBIT](IMPORTANT): Beginning ground fault scan 2019-09-12T19:44:51.479Z,1568317491.479 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:44:52.736Z,1568317492.736 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.852382 CHAN A1 (24V): 0.984810 CHAN A2 (12V): 0.892045 CHAN A3 (5V): 0.463929 CHAN B0 (3.3V): 0.230203 CHAN B1 (3.15aV): 0.330407 CHAN B2 (3.15bV): 0.343125 CHAN B3 (GND): -0.018498 OPEN: 0.020708 Full Scale Calc: 4.765 mA, -1.589 mA 2019-09-12T19:45:04.401Z,1568317504.401 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:45:16.941Z,1568317516.941 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:45:24.586Z,1568317524.586 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:45:24.586Z,1568317524.586 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+21.3,0000.0000 2019-09-12T19:45:29.447Z,1568317529.447 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:45:39.565Z,1568317539.565 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T19:45:39.565Z,1568317539.565 [Default:CheckIn:C.Wait] Stopped 2019-09-12T19:45:39.565Z,1568317539.565 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T19:45:39.565Z,1568317539.565 [Default:CheckIn:D] Running Loop=1 2019-09-12T19:45:39.965Z,1568317539.965 [Default:CheckIn:D] Stopped 2019-09-12T19:45:39.965Z,1568317539.965 [Default:CheckIn:E] Running Loop=1 2019-09-12T19:45:40.375Z,1568317540.375 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 6.046467 min 2019-09-12T19:45:40.375Z,1568317540.375 [Default:CheckIn:E] Stopped 2019-09-12T19:45:40.375Z,1568317540.375 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T19:45:40.375Z,1568317540.375 [Default:CheckIn] Stopped 2019-09-12T19:45:40.375Z,1568317540.375 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T19:45:40.376Z,1568317540.376 [Default:CheckIn](INFO): Running loop #2 2019-09-12T19:45:40.376Z,1568317540.376 [Default:CheckIn] Running Loop=2 2019-09-12T19:45:40.376Z,1568317540.376 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T19:45:40.376Z,1568317540.376 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T19:45:41.961Z,1568317541.961 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:45:42.355Z,1568317542.355 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T19:45:42.355Z,1568317542.355 [DVL_micro](ERROR): Failed to parse: :BI,-0009,-00035,+00000,I 2019-09-12T19:45:42.357Z,1568317542.357 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194541.00,A,3647.67533,N,12150.05439,W,1.575,237.24,120919,,,A*7A 2019-09-12T19:45:42.359Z,1568317542.359 [NAL9602](INFO): GPS fix at 20190912T194541: (36.794589, -121.834240) 2019-09-12T19:45:42.375Z,1568317542.375 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:45:42.389Z,1568317542.389 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T19:45:42.389Z,1568317542.389 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T19:45:51.984Z,1568317551.984 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T193618/Courier0007.lzma 2019-09-12T19:45:53.990Z,1568317553.990 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0007.lzma.bak 2019-09-12T19:45:53.990Z,1568317553.990 [DataOverHttps](INFO): SBD MOMSN=11776877 2019-09-12T19:45:55.303Z,1568317555.303 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:46:00.527Z,1568317560.527 [NAL9602](INFO): SBD MO Status=0, MOMSN=1278, MT Status=0, MTMSN=0 2019-09-12T19:46:00.528Z,1568317560.528 [NAL9602](INFO): No messages in MT queue 2019-09-12T19:46:02.549Z,1568317562.549 [DVL_micro](ERROR): Failed to parse: :WI,-01325,+00224,+0010,A 2019-09-12T19:46:07.841Z,1568317567.841 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:46:13.212Z,1568317573.212 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T193618/Courier0010.lzma 2019-09-12T19:46:15.219Z,1568317575.219 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0010.lzma.bak 2019-09-12T19:46:15.219Z,1568317575.219 [DataOverHttps](INFO): SBD MOMSN=11776880 2019-09-12T19:46:20.361Z,1568317580.361 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:46:31.242Z,1568317591.242 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T19:46:32.902Z,1568317592.902 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:46:34.933Z,1568317594.933 [DataOverHttps](INFO): Sending 426 bytes from file Logs/20190912T193618/Express0008.lzma 2019-09-12T19:46:36.938Z,1568317596.938 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0008.lzma.bak 2019-09-12T19:46:36.938Z,1568317596.938 [DataOverHttps](INFO): SBD MOMSN=11776882 2019-09-12T19:47:05.588Z,1568317625.588 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T193618/Express0011.lzma 2019-09-12T19:47:07.594Z,1568317627.594 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0011.lzma.bak 2019-09-12T19:47:07.594Z,1568317627.594 [DataOverHttps](INFO): SBD MOMSN=11776893 2019-09-12T19:47:10.473Z,1568317630.473 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T19:47:10.473Z,1568317630.473 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T19:47:10.473Z,1568317630.473 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T19:47:49.228Z,1568317669.228 [DVL_micro](ERROR): Failed to parse: 9.99,+9999..99,+9999.99 2019-09-12T19:48:04.572Z,1568317684.572 [DVL_micro](ERROR): Failed to parse: :BI,-01693,-00172+00000,I 2019-09-12T19:48:24.771Z,1568317704.771 [DVL_micro](ERROR): Failed to parse: :WI,-02271+00289,+000I,-02271,-00117,+00289,+00000,I 2019-09-12T19:48:57.899Z,1568317737.899 [DVL_micro](ERROR): only read 3 of 4 data items 2019-09-12T19:48:57.899Z,1568317737.899 [DVL_micro](ERROR): Failed to parse: :BI,-01640,-00194,00000,I 2019-09-12T19:50:19.104Z,1568317819.104 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:50:19.104Z,1568317819.104 [DVL_micro](ERROR): Failed to parse: :TS,000000,35,0000.0,1489.0,000 2019-09-12T19:50:36.877Z,1568317836.877 [DVL_micro](ERROR): only read 0 of 4 data items 2019-09-12T19:50:36.877Z,1568317836.877 [DVL_micro](ERROR): Failed to parse: :RD,++9999.99,++9999.99 2019-09-12T19:50:54.656Z,1568317854.656 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:50:54.656Z,1568317854.656 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,00.0,1489.0,000 2019-09-12T19:52:11.049Z,1568317931.049 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T19:52:11.049Z,1568317931.049 [Default:CheckIn:C.Wait] Stopped 2019-09-12T19:52:11.049Z,1568317931.049 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T19:52:11.050Z,1568317931.050 [Default:CheckIn:D] Running Loop=1 2019-09-12T19:52:11.489Z,1568317931.489 [Default:CheckIn:D] Stopped 2019-09-12T19:52:11.489Z,1568317931.489 [Default:CheckIn:E] Running Loop=1 2019-09-12T19:52:12.069Z,1568317932.069 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.571871 min 2019-09-12T19:52:12.069Z,1568317932.069 [Default:CheckIn:E] Stopped 2019-09-12T19:52:12.069Z,1568317932.069 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn] Stopped 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn](INFO): Running loop #3 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn] Running Loop=3 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T19:52:12.070Z,1568317932.070 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T19:52:13.454Z,1568317933.454 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:52:13.848Z,1568317933.848 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195214.00,A,3647.68315,N,12150.64857,W,9.952,50.06,120919,,,A*40 2019-09-12T19:52:13.850Z,1568317933.850 [NAL9602](INFO): GPS fix at 20190912T195214: (36.794719, -121.844143) 2019-09-12T19:52:13.878Z,1568317933.878 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T19:52:13.878Z,1568317933.878 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T19:52:18.291Z,1568317938.291 [DVL_micro](ERROR): Failed to parse: :WI,-01369,+01993,-00130,+00000,A 2019-09-12T19:52:23.588Z,1568317943.588 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T193618/Courier0013.lzma 2019-09-12T19:52:25.595Z,1568317945.595 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0013.lzma.bak 2019-09-12T19:52:25.595Z,1568317945.595 [DataOverHttps](INFO): SBD MOMSN=11776908 2019-09-12T19:52:30.008Z,1568317950.008 [NAL9602](INFO): SBD MO Status=0, MOMSN=1279, MT Status=0, MTMSN=0 2019-09-12T19:52:30.008Z,1568317950.008 [NAL9602](INFO): No messages in MT queue 2019-09-12T19:52:44.708Z,1568317964.708 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190912T193618/Express0014.lzma 2019-09-12T19:52:46.714Z,1568317966.714 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0014.lzma.bak 2019-09-12T19:52:46.714Z,1568317966.714 [DataOverHttps](INFO): SBD MOMSN=11776911 2019-09-12T19:52:49.953Z,1568317969.953 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T19:52:49.953Z,1568317969.953 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T19:52:49.953Z,1568317969.953 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T19:53:00.715Z,1568317980.715 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T19:54:00.511Z,1568318040.511 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:54:11.841Z,1568318051.841 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:54:23.550Z,1568318063.550 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:54:34.864Z,1568318074.864 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:54:46.580Z,1568318086.580 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:54:55.862Z,1568318095.862 [DVL_micro](ERROR): Failed to parse: :BD,+00000000.00,+00000000.00,+00000000.00,9999.99,000.00 2019-09-12T19:54:57.878Z,1568318097.878 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:55:09.200Z,1568318109.200 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:55:20.509Z,1568318120.509 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:55:31.829Z,1568318131.829 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:55:43.537Z,1568318143.537 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:55:54.843Z,1568318154.843 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:56:06.566Z,1568318166.566 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:56:17.909Z,1568318177.909 [BPC1](ERROR): BPC1A got IPBS message with 5 sticks (min is 7). 2019-09-12T19:57:50.430Z,1568318270.430 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T19:57:50.430Z,1568318270.430 [Default:CheckIn:C.Wait] Stopped 2019-09-12T19:57:50.430Z,1568318270.430 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T19:57:50.430Z,1568318270.430 [Default:CheckIn:D] Running Loop=1 2019-09-12T19:57:50.841Z,1568318270.841 [Default:CheckIn:D] Stopped 2019-09-12T19:57:50.841Z,1568318270.841 [Default:CheckIn:E] Running Loop=1 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.227732 min 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn:E] Stopped 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn] Stopped 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn](INFO): Running loop #4 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn] Running Loop=4 2019-09-12T19:57:51.277Z,1568318271.277 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T19:57:51.278Z,1568318271.278 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T19:57:52.837Z,1568318272.837 [NAL9602](DEBUG): Fix Requested 2019-09-12T19:57:53.236Z,1568318273.236 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195753.00,A,3647.86645,N,12150.08700,W,1.419,133.17,120919,,,A*7F 2019-09-12T19:57:53.238Z,1568318273.238 [NAL9602](INFO): GPS fix at 20190912T195753: (36.797774, -121.834783) 2019-09-12T19:57:53.269Z,1568318273.269 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T19:57:53.269Z,1568318273.269 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T19:57:58.532Z,1568318278.532 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -32.00 mm (1 active estimators). 2019-09-12T19:58:04.252Z,1568318284.252 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T193618/Courier0016.lzma 2019-09-12T19:58:06.258Z,1568318286.258 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Courier0016.lzma.bak 2019-09-12T19:58:06.258Z,1568318286.258 [DataOverHttps](INFO): SBD MOMSN=11776935 2019-09-12T19:58:12.908Z,1568318292.908 [NAL9602](INFO): SBD MO Status=0, MOMSN=1280, MT Status=0, MTMSN=0 2019-09-12T19:58:12.908Z,1568318292.908 [NAL9602](INFO): No messages in MT queue 2019-09-12T19:58:18.576Z,1568318298.576 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2019-09-12T19:58:18.576Z,1568318298.576 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+20.0,0000.0,148 2019-09-12T19:58:27.828Z,1568318307.828 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20190912T193618/Express0017.lzma 2019-09-12T19:58:29.834Z,1568318309.834 [DataOverHttps](INFO): Moved sent file to Logs/20190912T193618/Express0017.lzma.bak 2019-09-12T19:58:29.834Z,1568318309.834 [DataOverHttps](INFO): SBD MOMSN=11776938 2019-09-12T19:58:32.772Z,1568318312.772 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T19:58:32.772Z,1568318312.772 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T19:58:32.772Z,1568318312.772 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T19:58:42.206Z,1568318322.206 [DataOverHttps](IMPORTANT): SBD MTMSN=20190912T195841 2019-09-12T19:58:43.627Z,1568318323.627 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T19:58:49.896Z,1568318329.896 [DataOverHttps](INFO): Received command:restart logs