2019-11-11T18:05:43.131Z,1573495543.131 [Supervisor](DEBUG): Initializing supervisor.
2019-11-11T18:05:43.134Z,1573495543.134 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-11-11T18:05:43.134Z,1573495543.134 [SyncHandler](INFO): Protected caller Thread ID is 806
2019-11-11T18:05:43.134Z,1573495543.134 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-11-11T18:05:43.135Z,1573495543.135 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-11-11T18:05:43.136Z,1573495543.136 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 807
2019-11-11T18:05:43.138Z,1573495543.138 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-11-11T18:05:43.149Z,1573495543.149 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-11-11T18:05:43.150Z,1573495543.150 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-11-11T18:05:43.150Z,1573495543.150 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 808
2019-11-11T18:05:43.151Z,1573495543.151 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-11-11T18:05:43.152Z,1573495543.152 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-11-11T18:05:43.152Z,1573495543.152 [logger ThreadHandler](INFO): Protected caller Thread ID is 809
2019-11-11T18:05:43.154Z,1573495543.154 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-11-11T18:05:43.155Z,1573495543.155 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-11-11T18:05:43.159Z,1573495543.159 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-11-11T18:05:43.254Z,1573495543.254 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-11-11T18:05:43.256Z,1573495543.256 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-11-11T18:05:43.841Z,1573495543.841 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-11-11T18:05:43.843Z,1573495543.843 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-11-11T18:05:43.942Z,1573495543.942 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-11-11T18:05:43.944Z,1573495543.944 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-11-11T18:05:44.046Z,1573495544.046 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-11-11T18:05:44.048Z,1573495544.048 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-11-11T18:05:44.128Z,1573495544.128 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-11-11T18:05:44.265Z,1573495544.265 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-11-11T18:05:44.266Z,1573495544.266 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-11-11T18:05:44.563Z,1573495544.563 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-11-11T18:05:44.563Z,1573495544.563 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-11-11T18:05:45.011Z,1573495545.011 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-11-11T18:05:45.012Z,1573495545.012 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-11-11T18:05:45.239Z,1573495545.239 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-11-11T18:05:45.240Z,1573495545.240 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-11-11T18:05:45.432Z,1573495545.432 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-11-11T18:05:45.433Z,1573495545.433 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-11-11T18:05:45.889Z,1573495545.889 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-11-11T18:05:45.891Z,1573495545.891 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-11-11T18:05:46.100Z,1573495546.100 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-11-11T18:05:46.102Z,1573495546.102 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-11-11T18:05:46.299Z,1573495546.299 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-11-11T18:05:46.301Z,1573495546.301 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-11-11T18:05:46.702Z,1573495546.702 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-11-11T18:05:46.842Z,1573495546.842 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-11-11T18:05:47.448Z,1573495547.448 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-11-11T18:05:47.451Z,1573495547.451 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/
2019-11-11T18:05:47.453Z,1573495547.453 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/secure.cfg
2019-11-11T18:05:47.575Z,1573495547.575 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Sensor.cfg
2019-11-11T18:05:47.729Z,1573495547.729 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Servo.cfg
2019-11-11T18:05:47.837Z,1573495547.837 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Simulator.cfg
2019-11-11T18:05:47.922Z,1573495547.922 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/logger.cfg
2019-11-11T18:05:48.016Z,1573495548.016 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/vehicle.cfg
2019-11-11T18:05:48.209Z,1573495548.209 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Battery.cfg
2019-11-11T18:05:48.433Z,1573495548.433 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-11-11T18:05:48.433Z,1573495548.433 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Navigation.cfg
2019-11-11T18:05:48.526Z,1573495548.526 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/BIT.cfg
2019-11-11T18:05:48.624Z,1573495548.624 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Science.cfg
2019-11-11T18:05:48.762Z,1573495548.762 [Supervisor](INFO): Opening Config file at: Config/lrauv-pontus/Control.cfg
2019-11-11T18:05:48.860Z,1573495548.860 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-pontus/root/
2019-11-11T18:05:48.861Z,1573495548.861 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-11-11T18:05:48.864Z,1573495548.864 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-11-11T18:05:48.929Z,1573495548.929 [VerticalControl](DEBUG): Construct VerticalControl.
2019-11-11T18:05:49.041Z,1573495549.041 [VerticalControl] Loaded
2019-11-11T18:05:49.041Z,1573495549.041 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-11-11T18:05:49.042Z,1573495549.042 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-11-11T18:05:49.110Z,1573495549.110 [HorizontalControl] Loaded
2019-11-11T18:05:49.110Z,1573495549.110 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-11-11T18:05:49.111Z,1573495549.111 [SpeedControl](DEBUG): Construct SpeedControl.
2019-11-11T18:05:49.116Z,1573495549.116 [SpeedControl] Loaded
2019-11-11T18:05:49.116Z,1573495549.116 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-11-11T18:05:49.117Z,1573495549.117 [LoopControl](DEBUG): Construct LoopControl.
2019-11-11T18:05:49.117Z,1573495549.117 [LoopControl] Loaded
2019-11-11T18:05:49.118Z,1573495549.118 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-11-11T18:05:49.118Z,1573495549.118 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-11-11T18:05:49.120Z,1573495549.120 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-11-11T18:05:49.175Z,1573495549.175 [DepthRateCalculator] Loaded
2019-11-11T18:05:49.175Z,1573495549.175 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-11-11T18:05:49.180Z,1573495549.180 [PitchRateCalculator] Loaded
2019-11-11T18:05:49.181Z,1573495549.181 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-11-11T18:05:49.196Z,1573495549.196 [SpeedCalculator] Loaded
2019-11-11T18:05:49.196Z,1573495549.196 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-11-11T18:05:49.217Z,1573495549.217 [TempGradientCalculator] Loaded
2019-11-11T18:05:49.217Z,1573495549.217 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-11-11T18:05:49.222Z,1573495549.222 [YawRateCalculator] Loaded
2019-11-11T18:05:49.222Z,1573495549.222 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-11-11T18:05:49.251Z,1573495549.251 [ElevatorOffsetCalculator] Loaded
2019-11-11T18:05:49.251Z,1573495549.251 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-11-11T18:05:49.252Z,1573495549.252 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-11-11T18:05:49.254Z,1573495549.254 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-11-11T18:05:49.302Z,1573495549.302 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-11-11T18:05:49.303Z,1573495549.303 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-11-11T18:05:49.415Z,1573495549.415 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-11-11T18:05:49.415Z,1573495549.415 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-11-11T18:05:49.748Z,1573495549.748 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-11-11T18:05:49.749Z,1573495549.749 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-11-11T18:05:49.873Z,1573495549.873 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-11-11T18:05:49.874Z,1573495549.874 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-11-11T18:05:50.351Z,1573495550.351 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_orientation
2019-11-11T18:05:50.356Z,1573495550.356 [AHRS_M2](INFO): created writer for : platform_orientation
2019-11-11T18:05:50.358Z,1573495550.358 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_magnetic_orientation
2019-11-11T18:05:50.363Z,1573495550.363 [AHRS_M2](INFO): created writer for : platform_magnetic_orientation
2019-11-11T18:05:50.363Z,1573495550.363 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_pitch_angle
2019-11-11T18:05:50.368Z,1573495550.368 [AHRS_M2](INFO): created writer for : platform_pitch_angle
2019-11-11T18:05:50.369Z,1573495550.369 [AHRS_M2](DEBUG): LcmSlateWriter::add(): platform_roll_angle
2019-11-11T18:05:50.374Z,1573495550.374 [AHRS_M2](INFO): created writer for : platform_roll_angle
2019-11-11T18:05:50.551Z,1573495550.551 [AHRS_M2] Loaded
2019-11-11T18:05:50.551Z,1573495550.551 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-11-11T18:05:50.695Z,1573495550.695 [DataOverHttps] Loaded
2019-11-11T18:05:50.695Z,1573495550.695 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-11-11T18:05:50.696Z,1573495550.696 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408B14E0
2019-11-11T18:05:50.697Z,1573495550.697 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 889
2019-11-11T18:05:50.710Z,1573495550.710 [Depth_Keller] Loaded
2019-11-11T18:05:50.710Z,1573495550.710 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-11-11T18:05:50.715Z,1573495550.715 [DropWeight] Loaded
2019-11-11T18:05:50.715Z,1573495550.715 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-11-11T18:05:50.812Z,1573495550.812 [NAL9602] Loaded
2019-11-11T18:05:50.812Z,1573495550.812 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-11-11T18:05:50.828Z,1573495550.828 [Onboard] Loaded
2019-11-11T18:05:50.828Z,1573495550.828 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-11-11T18:05:50.831Z,1573495550.831 [Radio_Surface] Loaded
2019-11-11T18:05:50.832Z,1573495550.832 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-11-11T18:05:50.833Z,1573495550.833 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408E14E0
2019-11-11T18:05:50.833Z,1573495550.833 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 890
2019-11-11T18:05:50.876Z,1573495550.876 [RDI_Pathfinder] Loaded
2019-11-11T18:05:50.876Z,1573495550.876 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-11-11T18:05:50.000Z,1573495551.000 [DAT] Loaded
2019-11-11T18:05:51.000Z,1573495551.000 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread.
2019-11-11T18:05:52.921Z,1573495552.921 [BPC1] Loaded
2019-11-11T18:05:52.921Z,1573495552.921 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-11-11T18:05:52.922Z,1573495552.922 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-11-11T18:05:52.922Z,1573495552.922 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-11-11T18:05:53.039Z,1573495553.039 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-11-11T18:05:53.040Z,1573495553.040 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-11-11T18:05:53.060Z,1573495553.060 [NavChart] Loaded
2019-11-11T18:05:53.060Z,1573495553.060 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-11-11T18:05:53.064Z,1573495553.064 [UniversalFixResidualReporter] Loaded
2019-11-11T18:05:53.064Z,1573495553.064 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-11-11T18:05:53.065Z,1573495553.065 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-11-11T18:05:53.067Z,1573495553.067 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-11-11T18:05:53.226Z,1573495553.226 [SBIT](DEBUG): Construct Startup Built In Test.
2019-11-11T18:05:53.237Z,1573495553.237 [SBIT] Loaded
2019-11-11T18:05:53.238Z,1573495553.238 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-11-11T18:05:53.238Z,1573495553.238 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-11-11T18:05:53.251Z,1573495553.251 [IBIT] Loaded
2019-11-11T18:05:53.251Z,1573495553.251 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-11-11T18:05:53.254Z,1573495553.254 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-11-11T18:05:53.390Z,1573495553.390 [CBIT] Loaded
2019-11-11T18:05:53.391Z,1573495553.391 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-11-11T18:05:53.391Z,1573495553.391 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-11-11T18:05:53.392Z,1573495553.392 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-11-11T18:05:53.519Z,1573495553.519 [BuoyancyServo] Loaded
2019-11-11T18:05:53.519Z,1573495553.519 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-11-11T18:05:53.531Z,1573495553.531 [ElevatorServo] Loaded
2019-11-11T18:05:53.531Z,1573495553.531 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-11-11T18:05:53.542Z,1573495553.542 [MassServo] Loaded
2019-11-11T18:05:53.542Z,1573495553.542 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-11-11T18:05:53.553Z,1573495553.553 [RudderServo] Loaded
2019-11-11T18:05:53.554Z,1573495553.554 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-11-11T18:05:53.564Z,1573495553.564 [ThrusterServo] Loaded
2019-11-11T18:05:53.564Z,1573495553.564 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-11-11T18:05:53.565Z,1573495553.565 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-11-11T18:05:53.566Z,1573495553.566 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-11-11T18:05:53.589Z,1573495553.589 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-11-11T18:05:53.590Z,1573495553.590 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-11-11T18:05:53.874Z,1573495553.874 [BackSeatDriver] Loaded
2019-11-11T18:05:53.874Z,1573495553.874 [ComponentRegistry](DEBUG): Component "BackSeatDriver" handled in its own thread.
2019-11-11T18:05:53.875Z,1573495553.875 [BackSeatDriver ThreadHandler](DEBUG): Created PCaller Thread at 40A654E0
2019-11-11T18:05:53.875Z,1573495553.875 [BackSeatDriver ThreadHandler](INFO): Protected caller Thread ID is 891
2019-11-11T18:05:53.885Z,1573495553.885 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_density
2019-11-11T18:05:53.890Z,1573495553.890 [CTD_Seabird](INFO): created writer for : sea_water_density
2019-11-11T18:05:53.890Z,1573495553.890 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): depth
2019-11-11T18:05:53.895Z,1573495553.895 [CTD_Seabird](INFO): created writer for : depth
2019-11-11T18:05:53.896Z,1573495553.896 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_pressure
2019-11-11T18:05:53.901Z,1573495553.901 [CTD_Seabird](INFO): created writer for : sea_water_pressure
2019-11-11T18:05:53.902Z,1573495553.902 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_salinity
2019-11-11T18:05:53.907Z,1573495553.907 [CTD_Seabird](INFO): created writer for : sea_water_salinity
2019-11-11T18:05:53.907Z,1573495553.907 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_temperature
2019-11-11T18:05:53.912Z,1573495553.912 [CTD_Seabird](INFO): created writer for : sea_water_temperature
2019-11-11T18:05:53.913Z,1573495553.913 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): sea_water_electrical_conductivity
2019-11-11T18:05:53.918Z,1573495553.918 [CTD_Seabird](INFO): created writer for : sea_water_electrical_conductivity
2019-11-11T18:05:53.919Z,1573495553.919 [CTD_Seabird](DEBUG): LcmSlateWriter::add(): speed_of_sound_in_sea_water
2019-11-11T18:05:53.924Z,1573495553.924 [CTD_Seabird](INFO): created writer for : speed_of_sound_in_sea_water
2019-11-11T18:05:53.950Z,1573495553.950 [CTD_Seabird] Loaded
2019-11-11T18:05:53.951Z,1573495553.951 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2019-11-11T18:05:53.952Z,1573495553.952 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A954E0
2019-11-11T18:05:53.952Z,1573495553.952 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 892
2019-11-11T18:05:53.959Z,1573495553.959 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output470
2019-11-11T18:05:53.959Z,1573495553.959 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output470
2019-11-11T18:05:53.963Z,1573495553.963 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.Output650
2019-11-11T18:05:53.963Z,1573495553.963 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: Output650
2019-11-11T18:05:53.968Z,1573495553.968 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.OutputChl
2019-11-11T18:05:53.968Z,1573495553.968 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: OutputChl
2019-11-11T18:05:53.972Z,1573495553.972 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg470nm
2019-11-11T18:05:53.972Z,1573495553.972 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg470nm
2019-11-11T18:05:53.976Z,1573495553.976 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.VolumeScatCoeff117deg650nm
2019-11-11T18:05:53.976Z,1573495553.976 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: VolumeScatCoeff117deg650nm
2019-11-11T18:05:53.981Z,1573495553.981 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff470nm
2019-11-11T18:05:53.981Z,1573495553.981 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff470nm
2019-11-11T18:05:53.985Z,1573495553.985 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.BackscatteringCoeff650nm
2019-11-11T18:05:53.985Z,1573495553.985 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: BackscatteringCoeff650nm
2019-11-11T18:05:53.989Z,1573495553.989 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:53.994Z,1573495553.994 [WetLabsBB2FL](INFO): created writer for : mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:53.994Z,1573495553.994 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:53.995Z,1573495553.995 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_median_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:53.999Z,1573495553.999 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:53.999Z,1573495553.999 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_mean_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:54.003Z,1573495554.003 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsBB2FL.bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:54.004Z,1573495554.004 [WetLabsBB2FL](DEBUG): LcmSlateWriter::add(): dataName: bin_variance_mass_concentration_of_chlorophyll_in_sea_water
2019-11-11T18:05:54.008Z,1573495554.008 [WetLabsBB2FL] Loaded
2019-11-11T18:05:54.008Z,1573495554.008 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2019-11-11T18:05:54.009Z,1573495554.009 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40AC54E0
2019-11-11T18:05:54.010Z,1573495554.010 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 893
2019-11-11T18:05:54.245Z,1573495554.245 [WetLabsUBAT..SerialDriver](INFO): Created logger
2019-11-11T18:05:54.246Z,1573495554.246 [WetLabsUBAT..SerialDriver](INFO): publishing on LCM channel WetLabsUBAT
2019-11-11T18:05:54.246Z,1573495554.246 [WetLabsUBAT..StreamSerialDriver](INFO): Created logger
2019-11-11T18:05:54.251Z,1573495554.251 [WetLabsUBAT](INFO): readConfig(): serialNo_: UBAT0051, uartName_: /dev/ttyC1, optionalArgs_: -ldir /mnt/mmc/LRAUV/Logs/latest
2019-11-11T18:05:54.252Z,1573495554.252 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.biolum_potential
2019-11-11T18:05:54.252Z,1573495554.252 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: biolum_potential
2019-11-11T18:05:54.256Z,1573495554.256 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(DAtaURI): WetLabsUBAT.flow_rate
2019-11-11T18:05:54.256Z,1573495554.256 [WetLabsUBAT](DEBUG): LcmSlateWriter::add(): dataName: flow_rate
2019-11-11T18:05:54.260Z,1573495554.260 [WetLabsUBAT] Loaded
2019-11-11T18:05:54.261Z,1573495554.261 [ComponentRegistry](DEBUG): Component "WetLabsUBAT" handled in its own thread.
2019-11-11T18:05:54.262Z,1573495554.262 [WetLabsUBAT ThreadHandler](DEBUG): Created PCaller Thread at 40AF54E0
2019-11-11T18:05:54.262Z,1573495554.262 [WetLabsUBAT ThreadHandler](INFO): Protected caller Thread ID is 894
2019-11-11T18:05:54.263Z,1573495554.263 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-11-11T18:05:54.266Z,1573495554.266 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-11-11T18:05:54.267Z,1573495554.267 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-11-11T18:05:54.274Z,1573495554.274 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-11-11T18:05:54.275Z,1573495554.275 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40B254E0
2019-11-11T18:05:54.275Z,1573495554.275 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 895
2019-11-11T18:05:54.279Z,1573495554.279 [Supervisor](INFO): Main Thread ID is 802
2019-11-11T18:05:54.280Z,1573495554.280 [Supervisor](DEBUG): Running supervisor.
2019-11-11T18:05:54.280Z,1573495554.280 [CommandLine ThreadHandler](INFO): Handler Thread ID is 896
2019-11-11T18:05:54.283Z,1573495554.283 [controlThread ThreadHandler](INFO): Handler Thread ID is 897
2019-11-11T18:05:54.284Z,1573495554.284 [controlThread](DEBUG): Initializing ControlThread
2019-11-11T18:05:54.285Z,1573495554.285 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-11-11T18:05:54.287Z,1573495554.287 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-11-11T18:05:54.287Z,1573495554.287 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-11-11T18:05:54.288Z,1573495554.288 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-11-11T18:05:54.288Z,1573495554.288 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-11-11T18:05:54.288Z,1573495554.288 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-11-11T18:05:54.289Z,1573495554.289 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-11-11T18:05:54.289Z,1573495554.289 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-11-11T18:05:54.290Z,1573495554.290 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-11-11T18:05:54.290Z,1573495554.290 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-11-11T18:05:54.296Z,1573495554.296 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-11-11T18:05:54.296Z,1573495554.296 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-11-11T18:05:54.296Z,1573495554.296 [SBIT](INFO): Initialize SBIT Component.
2019-11-11T18:05:54.297Z,1573495554.297 [SBIT](IMPORTANT): git: 2019-11-11
2019-11-11T18:05:54.297Z,1573495554.297 [SBIT](INFO): git hash: d323e2e841967a23cb7fd5209d5be46b38c2f2ac
2019-11-11T18:05:54.297Z,1573495554.297 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-11-11T18:05:54.298Z,1573495554.298 [SBIT](IMPORTANT): Kernel Version:#1 PREEMPT Thu Feb 21 11:17:40 PST 2019
2019-11-11T18:05:54.299Z,1573495554.299 [SBIT](INFO): Beginning SBIT in 44.000000 seconds.
2019-11-11T18:05:54.299Z,1573495554.299 [IBIT](INFO): Initialize IBIT Component.
2019-11-11T18:05:54.300Z,1573495554.300 [CBIT](DEBUG): Initialize CBIT Component.
2019-11-11T18:05:54.301Z,1573495554.301 [logger ThreadHandler](INFO): Handler Thread ID is 898
2019-11-11T18:05:54.313Z,1573495554.313 [CBIT](DEBUG): Initialized mux pins.
2019-11-11T18:05:54.313Z,1573495554.313 [CBIT](DEBUG): Initializing the watchdog timer.
2019-11-11T18:05:54.321Z,1573495554.321 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 899
2019-11-11T18:05:54.323Z,1573495554.323 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-11-11T18:05:54.333Z,1573495554.333 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 900
2019-11-11T18:05:54.337Z,1573495554.337 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-11-11T18:05:54.337Z,1573495554.337 [CBIT](DEBUG): Initializing heartbeat.
2019-11-11T18:05:54.345Z,1573495554.345 [BackSeatDriver ThreadHandler](INFO): Handler Thread ID is 901
2019-11-11T18:05:54.365Z,1573495554.365 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 902
2019-11-11T18:05:54.366Z,1573495554.366 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2019-11-11T18:05:54.369Z,1573495554.369 [CTD_Seabird](INFO): Opening uart, block timeout 10ths=20
2019-11-11T18:05:54.371Z,1573495554.371 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 904
2019-11-11T18:05:54.372Z,1573495554.372 [WetLabsBB2FL](INFO): Powering down
2019-11-11T18:05:54.401Z,1573495554.401 [WetLabsUBAT ThreadHandler](INFO): Handler Thread ID is 905
2019-11-11T18:05:54.409Z,1573495554.409 [CBIT](DEBUG): Deactivating GF circuits.
2019-11-11T18:05:54.409Z,1573495554.409 [CBIT](DEBUG): Deactivating emergency mode.
2019-11-11T18:05:54.410Z,1573495554.410 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 906
2019-11-11T18:05:54.419Z,1573495554.419 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-11-11T18:05:54.419Z,1573495554.419 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-11-11T18:05:54.419Z,1573495554.419 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-11-11T18:05:54.420Z,1573495554.420 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-11-11T18:05:54.420Z,1573495554.420 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-11-11T18:05:54.420Z,1573495554.420 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-11-11T18:05:54.420Z,1573495554.420 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-11-11T18:05:54.420Z,1573495554.420 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-11-11T18:05:54.421Z,1573495554.421 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-11-11T18:05:54.421Z,1573495554.421 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-11-11T18:05:54.421Z,1573495554.421 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-11-11T18:05:54.421Z,1573495554.421 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-11-11T18:05:54.422Z,1573495554.422 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-11-11T18:05:54.422Z,1573495554.422 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-11-11T18:05:54.422Z,1573495554.422 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-11-11T18:05:54.422Z,1573495554.422 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-11-11T18:05:54.445Z,1573495554.445 [CBIT](DEBUG): Backplane powered.
2019-11-11T18:05:54.447Z,1573495554.447 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-11-11T18:05:54.474Z,1573495554.474 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-11T18:05:54.484Z,1573495554.484 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="StartupSatComms">

        <Sequence/>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:latitude_fix/>
        </ReadDatum>

        <ReadDatum>
            <Timeout Duration="P1M" />
            <Universal:platform_communications/>
        </ReadDatum>

    </Aggregate>

</Mission>


2019-11-11T18:05:54.485Z,1573495554.485 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-11-11T18:05:54.530Z,1573495554.530 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-11-11T18:05:54.531Z,1573495554.531 [Default:A.Wait](DEBUG): Construct Wait.
2019-11-11T18:05:54.549Z,1573495554.549 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-11-11T18:05:54.592Z,1573495554.592 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-11-11T18:05:54.594Z,1573495554.594 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-11-11T18:05:54.620Z,1573495554.620 [Default:E.Execute](DEBUG): Construct Execute.
2019-11-11T18:05:54.623Z,1573495554.623 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

    <Guidance:Wait>
        <Description>
            Wait a moment to see if the scheduler starts a new mission before
            starting to actually run Default.
        </Description>
        <Sequence/>
        <Setting><Guidance:Wait.duration/><Units:second/><Value>13</Value></Setting>
    </Guidance:Wait>

    <Guidance:GoToSurface>
        <Progression/>
    </Guidance:GoToSurface>

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

        <ReadDatum Id="Read_GPS">
            <Timeout Duration="P5M"/>
            <Universal:time_fix/>
        </ReadDatum>

        <ReadDatum Id="Read_Iridium">
            <Timeout Duration="P2H">
                <Guidance:Execute>
                    <Sequence/>
                    <Setting><Guidance:Execute.command/><String>Burn on</String></Setting>
                </Guidance:Execute>
                <Syslog Severity="Critical">Dropped weight due to communications timeout.</Syslog>
            </Timeout>
            <Universal:platform_communications/>
        </ReadDatum>

        <Guidance:Wait>
            <Sequence/>
            <Setting><Guidance:Wait.duration/><Units:minute/><Value>5</Value></Setting>
        </Guidance:Wait>

        <Assign><Sequence/><Arg Name="ElapsedSinceDefaultStarted"/><Elapsed><Universal:mission_started/></Elapsed></Assign>

        <Syslog Severity="Important">Default mission has been running for <Arg Name="ElapsedSinceDefaultStarted"/><Units:minute/></Syslog>

    </Aggregate>

    <Syslog Severity="Important">Restarting logs and Default mission.</Syslog>

    <Guidance:Execute>
        <Sequence/>
        <Setting><Guidance:Execute.command/><String>restart logs</String></Setting>
    </Guidance:Execute>

</Mission>


2019-11-11T18:05:54.641Z,1573495554.641 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,NAL9602,Onboard,RDI_Pathfinder,DAT,BPC1,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-11-11T18:05:54.646Z,1573495554.646 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-11-11T18:05:54.737Z,1573495554.737 [Radio_Surface](INFO): Powering up
2019-11-11T18:05:54.802Z,1573495554.802 [Depth_Keller](ERROR): Pressure reading out of range: 1650.297119 decibar
2019-11-11T18:05:54.832Z,1573495554.832 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-11-11T18:05:54.832Z,1573495554.832 [DAT](INFO): Powering up
2019-11-11T18:05:54.832Z,1573495554.832 [DAT](DEBUG): Initializing DAT.
2019-11-11T18:05:54.881Z,1573495554.881 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-11-11T18:05:54.901Z,1573495554.901 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-11-11T18:05:54.983Z,1573495554.983 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-11-11T18:05:54.993Z,1573495554.993 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-11-11T18:05:54.995Z,1573495554.995 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-11-11T18:05:55.008Z,1573495555.008 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-11-11T18:05:55.009Z,1573495555.009 [MassServo](DEBUG): Initializing EZServoServo.
2019-11-11T18:05:55.017Z,1573495555.017 [MassServo](DEBUG): Initializing MassServo.
2019-11-11T18:05:55.018Z,1573495555.018 [RudderServo](DEBUG): Initializing EZServoServo.
2019-11-11T18:05:55.025Z,1573495555.025 [RudderServo](DEBUG): Initializing RudderServo.
2019-11-11T18:05:55.026Z,1573495555.026 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-11-11T18:05:55.033Z,1573495555.033 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-11-11T18:05:55.117Z,1573495555.117 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-11-11T18:06:01.433Z,1573495561.433 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2019-11-11T18:06:08.494Z,1573495568.494 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-11-11T18:06:09.367Z,1573495569.367 [RDI_Pathfinder](ERROR): Failed to parse:
:8,-32768,-32768,V
2019-11-11T18:06:09.368Z,1573495569.368 [DAT](INFO): setting local address to 4
2019-11-11T18:06:09.706Z,1573495569.706 [DAT](INFO): set local address to 4
2019-11-11T18:06:21.007Z,1573495581.007 [NAL9602](INFO): Powering up NAL9602
2019-11-11T18:06:31.907Z,1573495591.907 [NAL9602](INFO): NAL9602 initialized
2019-11-11T18:06:38.811Z,1573495598.811 [SBIT](IMPORTANT): Beginning Startup BIT
2019-11-11T18:06:38.819Z,1573495598.819 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-11T18:06:49.877Z,1573495609.877 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.010646
CHAN A1 (24V): 0.037419
CHAN A2 (12V): -0.007523
CHAN A3 (5V): -0.002854
CHAN B0 (3.3V): 0.000001
CHAN B1 (3.15aV): -0.000363
CHAN B2 (3.15bV): -0.000567
CHAN B3 (GND): 0.001523
OPEN: -0.003184
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-11T18:07:08.476Z,1573495628.476 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:07:08.476Z,1573495628.476 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:07:32.495Z,1573495652.495 [SBIT](IMPORTANT): SBIT PASSED
2019-11-11T18:07:32.528Z,1573495652.528 [CommandLine](IMPORTANT): got command configSet list
2019-11-11T18:07:32.528Z,1573495652.528 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2019-11-11T18:07:32.529Z,1573495652.529 [CommandLine](IMPORTANT): No configSet variables persisted
2019-11-11T18:07:32.846Z,1573495652.846 [MissionManager](IMPORTANT): Started mission Startup
2019-11-11T18:07:32.846Z,1573495652.846 [Startup] Running Loop=1
2019-11-11T18:07:32.846Z,1573495652.846 [Startup](DEBUG): Aggregate::initialize Startup
2019-11-11T18:07:32.846Z,1573495652.846 [Startup:A.GoToSurface] Running Loop=1
2019-11-11T18:07:32.846Z,1573495652.846 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-11T18:07:32.847Z,1573495652.847 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-11T18:07:32.847Z,1573495652.847 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-11T18:07:32.848Z,1573495652.848 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-11T18:07:32.848Z,1573495652.848 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-11T18:07:32.849Z,1573495652.849 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-11T18:07:32.850Z,1573495652.850 [Startup:StartupSatComms] Running Loop=1
2019-11-11T18:07:32.850Z,1573495652.850 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2019-11-11T18:07:32.850Z,1573495652.850 [Startup:StartupSatComms:A] Running Loop=1
2019-11-11T18:07:33.262Z,1573495653.262 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2019-11-11T18:08:26.699Z,1573495706.699 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005108
2019-11-11T18:08:33.062Z,1573495713.062 [Startup:StartupSatComms:A](INFO): Timed out from 2019-11-11T18:07:32.9Z
2019-11-11T18:08:33.062Z,1573495713.062 [Startup:StartupSatComms:A] Stopped
2019-11-11T18:08:33.062Z,1573495713.062 [Startup:StartupSatComms:B] Running Loop=1
2019-11-11T18:08:33.470Z,1573495713.470 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-11T18:08:37.051Z,1573495717.051 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:08:37.052Z,1573495717.052 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:08:40.466Z,1573495720.466 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180120/Courier0004.lzma
2019-11-11T18:08:42.470Z,1573495722.470 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180120/Courier0004.lzma.bak
2019-11-11T18:08:42.471Z,1573495722.471 [DataOverHttps](INFO): SBD MOMSN=11972412
2019-11-11T18:08:54.464Z,1573495734.464 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2019-11-11T18:08:54.464Z,1573495734.464 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-11-11T18:08:54.482Z,1573495734.482 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-11-11T18:08:54.864Z,1573495734.864 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-11-11T18:08:54.864Z,1573495734.864 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2019-11-11T18:08:59.672Z,1573495739.672 [DataOverHttps](INFO): Sending 1257 bytes from file Logs/20191108T003045/Express0008.lzma
2019-11-11T18:09:01.308Z,1573495741.308 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:09:01.308Z,1573495741.308 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:09:01.666Z,1573495741.666 [DataOverHttps](INFO): Moved sent file to Logs/20191108T003045/Express0008.lzma.bak
2019-11-11T18:09:01.667Z,1573495741.667 [DataOverHttps](INFO): SBD MOMSN=11972417
2019-11-11T18:09:18.668Z,1573495758.668 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:09:18.668Z,1573495758.668 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:09:18.773Z,1573495758.773 [DataOverHttps](INFO): Sending 868 bytes from file Logs/20191108T004255/Express0001.lzma
2019-11-11T18:09:20.774Z,1573495760.774 [DataOverHttps](INFO): Moved sent file to Logs/20191108T004255/Express0001.lzma.bak
2019-11-11T18:09:20.775Z,1573495760.775 [DataOverHttps](INFO): SBD MOMSN=11972456
2019-11-11T18:09:33.257Z,1573495773.257 [Startup:StartupSatComms:B](INFO): Timed out from 2019-11-11T18:08:33.1Z
2019-11-11T18:09:33.257Z,1573495773.257 [Startup:StartupSatComms:B] Stopped
2019-11-11T18:09:33.257Z,1573495773.257 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2019-11-11T18:09:33.257Z,1573495773.257 [Startup:StartupSatComms] Stopped
2019-11-11T18:09:33.258Z,1573495773.258 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2019-11-11T18:09:33.258Z,1573495773.258 [Startup](INFO): Completed Startup
2019-11-11T18:09:33.258Z,1573495773.258 [MissionManager](INFO): Startup is completed.
2019-11-11T18:09:33.259Z,1573495773.259 [MissionManager](INFO): Uninitializing Mission Startup
2019-11-11T18:09:33.259Z,1573495773.259 [Startup] Stopped
2019-11-11T18:09:33.259Z,1573495773.259 [Startup](DEBUG): Aggregate::uninitialize Startup
2019-11-11T18:09:33.259Z,1573495773.259 [Startup:A.GoToSurface] Stopped
2019-11-11T18:09:33.259Z,1573495773.259 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-11-11T18:09:33.698Z,1573495773.698 [MissionManager](IMPORTANT): Started mission Default
2019-11-11T18:09:33.698Z,1573495773.698 [Default] Running Loop=1
2019-11-11T18:09:33.698Z,1573495773.698 [Default](DEBUG): Aggregate::initialize Default
2019-11-11T18:09:33.698Z,1573495773.698 [Default:B.GoToSurface] Running Loop=1
2019-11-11T18:09:33.698Z,1573495773.698 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-11-11T18:09:33.699Z,1573495773.699 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-11-11T18:09:33.699Z,1573495773.699 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-11-11T18:09:33.699Z,1573495773.699 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-11-11T18:09:33.699Z,1573495773.699 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-11-11T18:09:33.700Z,1573495773.700 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-11-11T18:09:33.700Z,1573495773.700 [Default:A.Wait] Running Loop=1
2019-11-11T18:09:33.700Z,1573495773.700 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:09:36.444Z,1573495776.444 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:09:36.444Z,1573495776.444 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:09:37.800Z,1573495777.800 [DataOverHttps](INFO): Sending 695 bytes from file Logs/20191111T180120/Express0001.lzma
2019-11-11T18:09:39.802Z,1573495779.802 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180120/Express0001.lzma.bak
2019-11-11T18:09:39.802Z,1573495779.802 [DataOverHttps](INFO): SBD MOMSN=11972502
2019-11-11T18:09:46.983Z,1573495786.983 [Default:A.Wait](INFO): Done Waiting.
2019-11-11T18:09:46.983Z,1573495786.983 [Default:A.Wait] Stopped
2019-11-11T18:09:46.983Z,1573495786.983 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:09:47.379Z,1573495787.379 [Default:CheckIn] Running Loop=1
2019-11-11T18:09:47.379Z,1573495787.379 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:09:47.379Z,1573495787.379 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:09:47.814Z,1573495787.814 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2019-11-11T18:10:16.432Z,1573495816.432 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:10:16.432Z,1573495816.432 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:10:42.701Z,1573495842.701 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:10:42.702Z,1573495842.702 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:11:35.214Z,1573495895.214 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-11-11T18:11:36.440Z,1573495896.440 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181134.00,A,3648.16513,N,12147.28061,W,0.156,299.60,111119,,,A*79
2019-11-11T18:11:36.444Z,1573495896.444 [NAL9602](INFO): GPS fix at 20191111T181134: (36.802752, -121.788010)
2019-11-11T18:11:36.550Z,1573495896.550 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:11:36.550Z,1573495896.550 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:11:36.914Z,1573495896.914 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2019-11-11T18:11:45.885Z,1573495905.885 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20191111T180543/Courier0004.lzma
2019-11-11T18:11:47.890Z,1573495907.890 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0004.lzma.bak
2019-11-11T18:11:47.890Z,1573495907.890 [DataOverHttps](INFO): SBD MOMSN=11972519
2019-11-11T18:12:06.220Z,1573495926.220 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20191111T180120/Express0005.lzma
2019-11-11T18:12:08.226Z,1573495928.226 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180120/Express0005.lzma.bak
2019-11-11T18:12:08.226Z,1573495928.226 [DataOverHttps](INFO): SBD MOMSN=11972523
2019-11-11T18:12:08.347Z,1573495928.347 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:12:26.086Z,1573495946.086 [DataOverHttps](INFO): Sending 662 bytes from file Logs/20191111T180543/Express0001.lzma
2019-11-11T18:12:28.090Z,1573495948.090 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0001.lzma.bak
2019-11-11T18:12:28.091Z,1573495948.091 [DataOverHttps](INFO): SBD MOMSN=11972526
2019-11-11T18:12:45.617Z,1573495965.617 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20191111T180543/Express0005.lzma
2019-11-11T18:12:47.622Z,1573495967.622 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0005.lzma.bak
2019-11-11T18:12:47.623Z,1573495967.623 [DataOverHttps](INFO): SBD MOMSN=11972541
2019-11-11T18:12:48.780Z,1573495968.780 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:12:48.780Z,1573495968.780 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:12:48.780Z,1573495968.780 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:13:46.541Z,1573496026.541 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-11-11T18:13:46.544Z,1573496026.544 [BPC1](INFO): Received data from all battery sticks.
2019-11-11T18:15:38.060Z,1573496138.060 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2019-11-11T18:15:38.060Z,1573496138.060 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00
2019-11-11T18:16:41.474Z,1573496201.474 [DAT](FAULT): unknown deviceResponse_: :01.0 MPD:03.5 SPD:+00.0

2019-11-11T18:16:41.474Z,1573496201.474 [DAT] Communications Fault, FailCount= 1
2019-11-11T18:16:41.474Z,1573496201.474 [DAT](ERROR): Communications Fault
2019-11-11T18:16:41.475Z,1573496201.475 [DAT](FAULT): unknown deviceResponse_: Header stats CRC:Fail PSNR:02.4 CCERR:002 Mod:MFSK

2019-11-11T18:16:41.520Z,1573496201.520 [CBIT](ERROR): Communications Fault in component: DAT
2019-11-11T18:16:41.873Z,1573496201.873 [DAT](INFO): Powering down
2019-11-11T18:16:42.710Z,1573496202.710 [CBIT](INFO): Clearing failed state for component DAT
2019-11-11T18:16:42.711Z,1573496202.711 [DAT] No Fault, FailCount= 1
2019-11-11T18:16:45.103Z,1573496205.103 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2
2019-11-11T18:16:45.103Z,1573496205.103 [DAT](INFO): Powering up
2019-11-11T18:16:45.103Z,1573496205.103 [DAT](DEBUG): Initializing DAT.
2019-11-11T18:16:45.178Z,1573496205.178 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2
2019-11-11T18:16:59.337Z,1573496219.337 [DAT](INFO): setting local address to 4
2019-11-11T18:16:59.655Z,1573496219.655 [DAT](INFO): set local address to 4
2019-11-11T18:17:49.377Z,1573496269.377 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:17:49.378Z,1573496269.378 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:17:49.378Z,1573496269.378 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:17:49.378Z,1573496269.378 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:17:49.764Z,1573496269.764 [Default:CheckIn:D] Stopped
2019-11-11T18:17:49.764Z,1573496269.764 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:17:50.176Z,1573496270.176 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 8.267764 min 
2019-11-11T18:17:50.176Z,1573496270.176 [Default:CheckIn:E] Stopped
2019-11-11T18:17:50.176Z,1573496270.176 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:17:50.176Z,1573496270.176 [Default:CheckIn] Stopped
2019-11-11T18:17:50.176Z,1573496270.176 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:17:50.177Z,1573496270.177 [Default:CheckIn](INFO): Running loop #2
2019-11-11T18:17:50.177Z,1573496270.177 [Default:CheckIn] Running Loop=2
2019-11-11T18:17:50.177Z,1573496270.177 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:17:50.177Z,1573496270.177 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:17:52.158Z,1573496272.158 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181751.00,A,3648.16781,N,12147.28399,W,0.622,299.60,111119,,,A*75
2019-11-11T18:17:52.160Z,1573496272.160 [NAL9602](INFO): GPS fix at 20191111T181751: (36.802797, -121.788066)
2019-11-11T18:17:52.205Z,1573496272.205 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:17:52.205Z,1573496272.205 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:17:59.854Z,1573496279.854 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20191111T180543/Courier0007.lzma
2019-11-11T18:18:01.858Z,1573496281.858 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0007.lzma.bak
2019-11-11T18:18:01.858Z,1573496281.858 [DataOverHttps](INFO): SBD MOMSN=11972555
2019-11-11T18:18:19.269Z,1573496299.269 [DataOverHttps](INFO): Sending 300 bytes from file Logs/20191111T180543/Express0008.lzma
2019-11-11T18:18:21.277Z,1573496301.277 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0008.lzma.bak
2019-11-11T18:18:21.278Z,1573496301.278 [DataOverHttps](INFO): SBD MOMSN=11972558
2019-11-11T18:18:22.496Z,1573496302.496 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:18:22.496Z,1573496302.496 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:18:22.496Z,1573496302.496 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:18:31.761Z,1573496311.761 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:18:31.761Z,1573496311.761 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:18:48.731Z,1573496328.731 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:18:48.732Z,1573496328.732 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:19:22.699Z,1573496362.699 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-11-11T18:19:22.699Z,1573496362.699 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00
2019-11-11T18:19:29.531Z,1573496369.531 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:19:29.532Z,1573496369.532 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:22:54.384Z,1573496574.384 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-11-11T18:23:23.080Z,1573496603.080 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:23:23.080Z,1573496603.080 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:23:23.080Z,1573496603.080 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:23:23.080Z,1573496603.080 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:23:23.502Z,1573496603.502 [Default:CheckIn:D] Stopped
2019-11-11T18:23:23.502Z,1573496603.502 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:23:23.896Z,1573496603.896 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 13.830068 min 
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn:E] Stopped
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn] Stopped
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn](INFO): Running loop #3
2019-11-11T18:23:23.897Z,1573496603.897 [Default:CheckIn] Running Loop=3
2019-11-11T18:23:23.898Z,1573496603.898 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:23:23.898Z,1573496603.898 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:23:25.885Z,1573496605.885 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182325.00,A,3648.16454,N,12147.29539,W,0.661,59.04,111119,,,A*4C
2019-11-11T18:23:25.887Z,1573496605.887 [NAL9602](INFO): GPS fix at 20191111T182325: (36.802742, -121.788257)
2019-11-11T18:23:25.916Z,1573496605.916 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:23:25.916Z,1573496605.916 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:23:33.992Z,1573496613.992 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191111T180543/Courier0010.lzma
2019-11-11T18:23:35.998Z,1573496615.998 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0010.lzma.bak
2019-11-11T18:23:35.999Z,1573496615.999 [DataOverHttps](INFO): SBD MOMSN=11972566
2019-11-11T18:23:53.385Z,1573496633.385 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20191111T180543/Express0011.lzma
2019-11-11T18:23:55.390Z,1573496635.390 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0011.lzma.bak
2019-11-11T18:23:55.391Z,1573496635.391 [DataOverHttps](INFO): SBD MOMSN=11972569
2019-11-11T18:23:56.616Z,1573496636.616 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:23:56.616Z,1573496636.616 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:23:56.616Z,1573496636.616 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:23:58.602Z,1573496638.602 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:28:57.206Z,1573496937.206 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:28:57.206Z,1573496937.206 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:28:57.206Z,1573496937.206 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:28:57.206Z,1573496937.206 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:28:57.634Z,1573496937.634 [Default:CheckIn:D] Stopped
2019-11-11T18:28:57.635Z,1573496937.635 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:28:58.035Z,1573496938.035 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 19.398932 min 
2019-11-11T18:28:58.035Z,1573496938.035 [Default:CheckIn:E] Stopped
2019-11-11T18:28:58.035Z,1573496938.035 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:28:58.035Z,1573496938.035 [Default:CheckIn] Stopped
2019-11-11T18:28:58.035Z,1573496938.035 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:28:58.036Z,1573496938.036 [Default:CheckIn](INFO): Running loop #4
2019-11-11T18:28:58.036Z,1573496938.036 [Default:CheckIn] Running Loop=4
2019-11-11T18:28:58.036Z,1573496938.036 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:28:58.036Z,1573496938.036 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:29:00.018Z,1573496940.018 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182859.00,A,3648.16855,N,12147.28380,W,0.078,2.31,111119,,,A*72
2019-11-11T18:29:00.020Z,1573496940.020 [NAL9602](INFO): GPS fix at 20191111T182859: (36.802809, -121.788063)
2019-11-11T18:29:00.061Z,1573496940.061 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:29:00.061Z,1573496940.061 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:29:08.080Z,1573496948.080 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191111T180543/Courier0013.lzma
2019-11-11T18:29:10.086Z,1573496950.086 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0013.lzma.bak
2019-11-11T18:29:10.087Z,1573496950.087 [DataOverHttps](INFO): SBD MOMSN=11972585
2019-11-11T18:29:27.476Z,1573496967.476 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191111T180543/Express0014.lzma
2019-11-11T18:29:29.482Z,1573496969.482 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0014.lzma.bak
2019-11-11T18:29:29.483Z,1573496969.483 [DataOverHttps](INFO): SBD MOMSN=11972588
2019-11-11T18:29:30.762Z,1573496970.762 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check.
2019-11-11T18:29:30.837Z,1573496970.837 [NAL9602](FAULT): received: 
+CSQ:0

OK44, 2, 0, 0, 0

OK
2019-11-11T18:29:30.837Z,1573496970.837 [NAL9602] Data Fault, FailCount= 1
2019-11-11T18:29:30.837Z,1573496970.837 [NAL9602](ERROR): Data Fault
2019-11-11T18:29:30.868Z,1573496970.868 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:29:30.868Z,1573496970.868 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:29:30.868Z,1573496970.868 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:29:30.878Z,1573496970.878 [CBIT](ERROR): Data Fault in component: NAL9602
2019-11-11T18:29:31.166Z,1573496971.166 [NAL9602](INFO): Powering down
2019-11-11T18:29:32.020Z,1573496972.020 [CBIT](INFO): Clearing failed state for component NAL9602
2019-11-11T18:29:32.020Z,1573496972.020 [NAL9602] No Fault, FailCount= 1
2019-11-11T18:29:41.320Z,1573496981.320 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-11T18:30:01.468Z,1573497001.468 [NAL9602](INFO): Powering up NAL9602
2019-11-11T18:30:01.492Z,1573497001.492 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2019-11-11T18:30:01.492Z,1573497001.492 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-3

2019-11-11T18:30:12.382Z,1573497012.382 [NAL9602](INFO): NAL9602 initialized
2019-11-11T18:30:43.496Z,1573497043.496 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:31:26.202Z,1573497086.202 [DataOverHttps](IMPORTANT): SBD MTMSN=20191111T183124
2019-11-11T18:31:34.053Z,1573497094.053 [DataOverHttps](INFO): Received command:ibit
2019-11-11T18:31:34.141Z,1573497094.141 [CommandLine](IMPORTANT): got command ibit
2019-11-11T18:31:34.442Z,1573497094.442 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-11-11T18:31:34.442Z,1573497094.442 [IBIT](IMPORTANT): Beginning control surface checks.
2019-11-11T18:31:34.445Z,1573497094.445 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-11T18:31:36.012Z,1573497096.012 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183134.00,A,3648.17510,N,12147.28123,W,0.097,0.00,111119,,,A*76
2019-11-11T18:31:36.014Z,1573497096.014 [NAL9602](INFO): GPS fix at 20191111T183134: (36.802918, -121.788021)
2019-11-11T18:31:45.408Z,1573497105.408 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.004875
CHAN A1 (24V): 0.049582
CHAN A2 (12V): -0.001174
CHAN A3 (5V): -0.001228
CHAN B0 (3.3V): 0.000873
CHAN B1 (3.15aV): 0.001032
CHAN B2 (3.15bV): 0.001272
CHAN B3 (GND): 0.001825
OPEN: 0.004980
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-11T18:32:03.078Z,1573497123.078 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:32:03.078Z,1573497123.078 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:32:04.823Z,1573497124.823 [IBIT](FAULT): Rudder: EXPECTED:-15.000000 ACTUAL:-14.764685
2019-11-11T18:32:04.823Z,1573497124.823 [IBIT](FAULT): Control surface position failure.
2019-11-11T18:32:20.491Z,1573497140.491 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 4
Latitude: 36.802917 Longitude: -121.788017
2019-11-11T18:32:20.890Z,1573497140.890 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 0.000000
2019-11-11T18:32:20.890Z,1573497140.890 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2019-11-11T18:32:20.890Z,1573497140.890 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2019-11-11T18:32:21.339Z,1573497141.339 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-11-11T18:32:21.340Z,1573497141.340 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-11-11T18:32:21.340Z,1573497141.340 [IBIT](IMPORTANT): Pressure:7.415627 PSI
2019-11-11T18:32:21.341Z,1573497141.341 [IBIT](IMPORTANT): Humidity:12.263460 %
2019-11-11T18:32:21.713Z,1573497141.713 [IBIT](IMPORTANT): Vehicle Pitch:-0.025241 degrees
2019-11-11T18:32:21.713Z,1573497141.713 [IBIT](IMPORTANT): Vehicle  Roll:-3.283141 degrees
2019-11-11T18:32:21.714Z,1573497141.714 [IBIT](IMPORTANT): Vehicle  Heading:95.871788 degrees
2019-11-11T18:32:22.099Z,1573497142.099 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-11-11T18:32:22.099Z,1573497142.099 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2019-11-11T18:32:22.099Z,1573497142.099 [IBIT](IMPORTANT): massDefault: 0.600000 cm
2019-11-11T18:32:22.099Z,1573497142.099 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2019-11-11T18:32:22.100Z,1573497142.100 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2019-11-11T18:32:22.100Z,1573497142.100 [IBIT](IMPORTANT): IBIT FAILED
2019-11-11T18:32:23.688Z,1573497143.688 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:32:23.688Z,1573497143.688 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:32:35.842Z,1573497155.842 [RDI_Pathfinder](ERROR): Failed to parse:
:RA,  0.00,   0.00,   0.00,   0.00,   0.00
2019-11-11T18:34:02.281Z,1573497242.281 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2019-11-11T18:34:31.403Z,1573497271.403 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:34:31.403Z,1573497271.403 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:34:31.403Z,1573497271.403 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:34:31.403Z,1573497271.403 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:34:31.780Z,1573497271.780 [Default:CheckIn:D] Stopped
2019-11-11T18:34:31.780Z,1573497271.780 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:34:32.184Z,1573497272.184 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 24.968034 min 
2019-11-11T18:34:32.184Z,1573497272.184 [Default:CheckIn:E] Stopped
2019-11-11T18:34:32.185Z,1573497272.185 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn] Stopped
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn](INFO): Running loop #5
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn] Running Loop=5
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:34:32.189Z,1573497272.189 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:34:34.184Z,1573497274.184 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183432.00,A,3648.17451,N,12147.28175,W,0.097,0.00,111119,,,D*77
2019-11-11T18:34:34.196Z,1573497274.196 [NAL9602](INFO): GPS fix at 20191111T183432: (36.802909, -121.788029)
2019-11-11T18:34:34.224Z,1573497274.224 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:34:34.224Z,1573497274.224 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:34:54.724Z,1573497294.724 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191111T180543/Courier0016.lzma
2019-11-11T18:34:56.730Z,1573497296.730 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0016.lzma.bak
2019-11-11T18:34:56.730Z,1573497296.730 [DataOverHttps](INFO): SBD MOMSN=11972600
2019-11-11T18:35:06.498Z,1573497306.498 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:35:14.088Z,1573497314.088 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180543/Courier0020.lzma
2019-11-11T18:35:16.094Z,1573497316.094 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0020.lzma.bak
2019-11-11T18:35:16.095Z,1573497316.095 [DataOverHttps](INFO): SBD MOMSN=11972607
2019-11-11T18:35:33.567Z,1573497333.567 [DataOverHttps](INFO): Sending 960 bytes from file Logs/20191111T180543/Express0017.lzma
2019-11-11T18:35:35.570Z,1573497335.570 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0017.lzma.bak
2019-11-11T18:35:35.571Z,1573497335.571 [DataOverHttps](INFO): SBD MOMSN=11972609
2019-11-11T18:35:52.912Z,1573497352.912 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180543/Express0022.lzma
2019-11-11T18:35:54.918Z,1573497354.918 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0022.lzma.bak
2019-11-11T18:35:54.918Z,1573497354.918 [DataOverHttps](INFO): SBD MOMSN=11972639
2019-11-11T18:35:56.228Z,1573497356.228 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:35:56.228Z,1573497356.228 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:35:56.228Z,1573497356.228 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:40:56.846Z,1573497656.846 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:40:56.846Z,1573497656.846 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:40:56.846Z,1573497656.846 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:40:56.846Z,1573497656.846 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:40:57.248Z,1573497657.248 [Default:CheckIn:D] Stopped
2019-11-11T18:40:57.248Z,1573497657.248 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:40:57.676Z,1573497657.676 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 31.392499 min 
2019-11-11T18:40:57.676Z,1573497657.676 [Default:CheckIn:E] Stopped
2019-11-11T18:40:57.676Z,1573497657.676 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:40:57.676Z,1573497657.676 [Default:CheckIn] Stopped
2019-11-11T18:40:57.676Z,1573497657.676 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:40:57.677Z,1573497657.677 [Default:CheckIn](INFO): Running loop #6
2019-11-11T18:40:57.677Z,1573497657.677 [Default:CheckIn] Running Loop=6
2019-11-11T18:40:57.677Z,1573497657.677 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:40:57.677Z,1573497657.677 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:40:59.626Z,1573497659.626 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184058.00,A,3648.13778,N,12147.23325,W,0.039,16.79,111119,,,D*45
2019-11-11T18:40:59.628Z,1573497659.628 [NAL9602](INFO): GPS fix at 20191111T184058: (36.802296, -121.787221)
2019-11-11T18:40:59.695Z,1573497659.695 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:40:59.695Z,1573497659.695 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:41:07.733Z,1573497667.733 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191111T180543/Courier0019.lzma
2019-11-11T18:41:09.738Z,1573497669.738 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0019.lzma.bak
2019-11-11T18:41:09.739Z,1573497669.739 [DataOverHttps](INFO): SBD MOMSN=11972643
2019-11-11T18:41:25.951Z,1573497685.951 [NAL9602](INFO): SBD MO Status=2, MOMSN=4844, MT Status=2, MTMSN=0
2019-11-11T18:41:25.952Z,1573497685.952 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T18:41:28.373Z,1573497688.373 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20191111T180543/Express0021.lzma
2019-11-11T18:41:30.378Z,1573497690.378 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0021.lzma.bak
2019-11-11T18:41:30.379Z,1573497690.379 [DataOverHttps](INFO): SBD MOMSN=11972646
2019-11-11T18:41:31.656Z,1573497691.656 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:41:31.656Z,1573497691.656 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:41:31.656Z,1573497691.656 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:41:39.696Z,1573497699.696 [NAL9602](INFO): SBD MO Status=0, MOMSN=4844, MT Status=0, MTMSN=0
2019-11-11T18:41:39.696Z,1573497699.696 [NAL9602](INFO): No messages in MT queue
2019-11-11T18:42:10.394Z,1573497730.394 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:45:13.838Z,1573497913.838 [DataOverHttps](IMPORTANT): SBD MTMSN=20191111T184511
2019-11-11T18:45:21.500Z,1573497921.500 [DataOverHttps](INFO): Received command:ibit
2019-11-11T18:45:21.510Z,1573497921.510 [CommandLine](IMPORTANT): got command ibit
2019-11-11T18:45:21.607Z,1573497921.607 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-11-11T18:45:21.607Z,1573497921.607 [IBIT](IMPORTANT): Beginning control surface checks.
2019-11-11T18:45:21.614Z,1573497921.614 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-11T18:45:23.160Z,1573497923.160 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184522.00,A,3648.13993,N,12147.23429,W,0.039,16.79,111119,,,D*4D
2019-11-11T18:45:23.162Z,1573497923.162 [NAL9602](INFO): GPS fix at 20191111T184522: (36.802332, -121.787238)
2019-11-11T18:45:31.637Z,1573497931.637 [NAL9602](INFO): SBD MO Status=0, MOMSN=4845, MT Status=0, MTMSN=0
2019-11-11T18:45:31.638Z,1573497931.638 [NAL9602](INFO): No messages in MT queue
2019-11-11T18:45:32.510Z,1573497932.510 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.006486
CHAN A1 (24V): 0.046545
CHAN A2 (12V): -0.002727
CHAN A3 (5V): -0.000400
CHAN B0 (3.3V): 0.000503
CHAN B1 (3.15aV): 0.000767
CHAN B2 (3.15bV): 0.001347
CHAN B3 (GND): 0.002086
OPEN: 0.005477
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-11T18:45:32.856Z,1573497932.856 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184532.00,A,3648.14040,N,12147.23451,W,0.019,16.79,111119,,,D*41
2019-11-11T18:45:32.858Z,1573497932.858 [NAL9602](INFO): GPS fix at 20191111T184532: (36.802340, -121.787242)
2019-11-11T18:45:36.089Z,1573497936.089 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184535.00,A,3648.14052,N,12147.23445,W,0.039,16.79,111119,,,D*42
2019-11-11T18:45:36.091Z,1573497936.091 [NAL9602](INFO): GPS fix at 20191111T184535: (36.802342, -121.787241)
2019-11-11T18:45:39.316Z,1573497939.316 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184538.00,A,3648.14059,N,12147.23446,W,0.078,16.79,111119,,,D*42
2019-11-11T18:45:39.328Z,1573497939.328 [NAL9602](INFO): GPS fix at 20191111T184538: (36.802343, -121.787241)
2019-11-11T18:45:42.142Z,1573497942.142 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184541.00,A,3648.14037,N,12147.23424,W,0.019,16.79,111119,,,D*47
2019-11-11T18:45:42.144Z,1573497942.144 [NAL9602](INFO): GPS fix at 20191111T184541: (36.802340, -121.787237)
2019-11-11T18:45:44.970Z,1573497944.970 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184544.00,A,3648.14034,N,12147.23388,W,0.078,16.79,111119,,,D*47
2019-11-11T18:45:44.972Z,1573497944.972 [NAL9602](INFO): GPS fix at 20191111T184544: (36.802339, -121.787231)
2019-11-11T18:45:48.202Z,1573497948.202 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184547.00,A,3648.14046,N,12147.23358,W,0.058,16.79,111119,,,D*4E
2019-11-11T18:45:48.204Z,1573497948.204 [NAL9602](INFO): GPS fix at 20191111T184547: (36.802341, -121.787226)
2019-11-11T18:45:51.038Z,1573497951.038 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184550.00,A,3648.14040,N,12147.23328,W,0.000,16.79,111119,,,D*44
2019-11-11T18:45:51.040Z,1573497951.040 [NAL9602](INFO): GPS fix at 20191111T184550: (36.802340, -121.787221)
2019-11-11T18:45:51.955Z,1573497951.955 [IBIT](FAULT): Rudder: EXPECTED:-15.000000 ACTUAL:-14.764685
2019-11-11T18:45:51.955Z,1573497951.955 [IBIT](FAULT): Control surface position failure.
2019-11-11T18:45:54.264Z,1573497954.264 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184553.00,A,3648.14052,N,12147.23334,W,0.000,16.79,111119,,,D*49
2019-11-11T18:45:54.270Z,1573497954.270 [NAL9602](INFO): GPS fix at 20191111T184553: (36.802342, -121.787222)
2019-11-11T18:45:57.092Z,1573497957.092 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184556.00,A,3648.14075,N,12147.23341,W,0.039,16.79,111119,,,D*41
2019-11-11T18:45:57.094Z,1573497957.094 [NAL9602](INFO): GPS fix at 20191111T184556: (36.802346, -121.787223)
2019-11-11T18:46:00.328Z,1573497960.328 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184559.00,A,3648.14101,N,12147.23344,W,0.019,16.79,111119,,,D*4B
2019-11-11T18:46:00.330Z,1573497960.330 [NAL9602](INFO): GPS fix at 20191111T184559: (36.802350, -121.787224)
2019-11-11T18:46:03.156Z,1573497963.156 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184602.00,A,3648.14132,N,12147.23363,W,0.039,16.79,111119,,,D*41
2019-11-11T18:46:03.158Z,1573497963.158 [NAL9602](INFO): GPS fix at 20191111T184602: (36.802355, -121.787227)
2019-11-11T18:46:05.982Z,1573497965.982 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184605.00,A,3648.14152,N,12147.23372,W,0.039,16.79,111119,,,D*40
2019-11-11T18:46:05.984Z,1573497965.984 [NAL9602](INFO): GPS fix at 20191111T184605: (36.802359, -121.787229)
2019-11-11T18:46:07.668Z,1573497967.668 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 5
Latitude: 36.802361 Longitude: -121.787231
2019-11-11T18:46:08.063Z,1573497968.063 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 0.000000
2019-11-11T18:46:08.063Z,1573497968.063 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2019-11-11T18:46:08.064Z,1573497968.064 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2019-11-11T18:46:08.470Z,1573497968.470 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-11-11T18:46:08.471Z,1573497968.471 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-11-11T18:46:08.471Z,1573497968.471 [IBIT](IMPORTANT): Pressure:7.412316 PSI
2019-11-11T18:46:08.471Z,1573497968.471 [IBIT](IMPORTANT): Humidity:11.946038 %
2019-11-11T18:46:08.834Z,1573497968.834 [IBIT](IMPORTANT): Vehicle Pitch:-1.169629 degrees
2019-11-11T18:46:08.834Z,1573497968.834 [IBIT](IMPORTANT): Vehicle  Roll:-4.306999 degrees
2019-11-11T18:46:08.834Z,1573497968.834 [IBIT](IMPORTANT): Vehicle  Heading:297.528015 degrees
2019-11-11T18:46:09.254Z,1573497969.254 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-11-11T18:46:09.254Z,1573497969.254 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2019-11-11T18:46:09.254Z,1573497969.254 [IBIT](IMPORTANT): massDefault: 0.600000 cm
2019-11-11T18:46:09.255Z,1573497969.255 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2019-11-11T18:46:09.255Z,1573497969.255 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2019-11-11T18:46:09.255Z,1573497969.255 [IBIT](IMPORTANT): IBIT FAILED
2019-11-11T18:46:32.297Z,1573497992.297 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:46:32.298Z,1573497992.298 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:46:32.298Z,1573497992.298 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:46:32.298Z,1573497992.298 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:46:32.686Z,1573497992.686 [Default:CheckIn:D] Stopped
2019-11-11T18:46:32.686Z,1573497992.686 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:46:33.080Z,1573497993.080 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.983138 min 
2019-11-11T18:46:33.080Z,1573497993.080 [Default:CheckIn:E] Stopped
2019-11-11T18:46:33.080Z,1573497993.080 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:46:33.080Z,1573497993.080 [Default:CheckIn] Stopped
2019-11-11T18:46:33.080Z,1573497993.080 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:46:33.081Z,1573497993.081 [Default:CheckIn](INFO): Running loop #7
2019-11-11T18:46:33.081Z,1573497993.081 [Default:CheckIn] Running Loop=7
2019-11-11T18:46:33.081Z,1573497993.081 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:46:33.081Z,1573497993.081 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:46:35.068Z,1573497995.068 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184634.00,A,3648.14089,N,12147.23471,W,0.039,16.79,111119,,,D*41
2019-11-11T18:46:35.070Z,1573497995.070 [NAL9602](INFO): GPS fix at 20191111T184634: (36.802348, -121.787245)
2019-11-11T18:46:35.124Z,1573497995.124 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:46:35.124Z,1573497995.124 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:46:42.468Z,1573498002.468 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191111T180543/Courier0025.lzma
2019-11-11T18:46:44.474Z,1573498004.474 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0025.lzma.bak
2019-11-11T18:46:44.475Z,1573498004.475 [DataOverHttps](INFO): SBD MOMSN=11972695
2019-11-11T18:47:03.100Z,1573498023.100 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180543/Courier0028.lzma
2019-11-11T18:47:05.108Z,1573498025.108 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0028.lzma.bak
2019-11-11T18:47:05.108Z,1573498025.108 [DataOverHttps](INFO): SBD MOMSN=11972698
2019-11-11T18:47:07.810Z,1573498027.810 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:47:22.830Z,1573498042.830 [DataOverHttps](INFO): Sending 823 bytes from file Logs/20191111T180543/Express0026.lzma
2019-11-11T18:47:24.834Z,1573498044.834 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0026.lzma.bak
2019-11-11T18:47:24.835Z,1573498044.835 [DataOverHttps](INFO): SBD MOMSN=11972700
2019-11-11T18:47:42.309Z,1573498062.309 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20191111T180543/Express0027.lzma
2019-11-11T18:47:44.314Z,1573498064.314 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0027.lzma.bak
2019-11-11T18:47:44.315Z,1573498064.315 [DataOverHttps](INFO): SBD MOMSN=11972728
2019-11-11T18:48:01.984Z,1573498081.984 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180543/Express0029.lzma
2019-11-11T18:48:03.994Z,1573498083.994 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0029.lzma.bak
2019-11-11T18:48:03.994Z,1573498083.994 [DataOverHttps](INFO): SBD MOMSN=11972730
2019-11-11T18:48:05.240Z,1573498085.240 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:48:05.240Z,1573498085.240 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:48:05.240Z,1573498085.240 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:53:05.796Z,1573498385.796 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:53:05.796Z,1573498385.796 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:53:05.796Z,1573498385.796 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:53:05.796Z,1573498385.796 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:53:06.193Z,1573498386.193 [Default:CheckIn:D] Stopped
2019-11-11T18:53:06.193Z,1573498386.193 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:53:06.588Z,1573498386.588 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.541577 min 
2019-11-11T18:53:06.588Z,1573498386.588 [Default:CheckIn:E] Stopped
2019-11-11T18:53:06.588Z,1573498386.588 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:53:06.605Z,1573498386.605 [Default:CheckIn] Stopped
2019-11-11T18:53:06.606Z,1573498386.606 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:53:06.606Z,1573498386.606 [Default:CheckIn](INFO): Running loop #8
2019-11-11T18:53:06.606Z,1573498386.606 [Default:CheckIn] Running Loop=8
2019-11-11T18:53:06.607Z,1573498386.607 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:53:06.607Z,1573498386.607 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:53:08.592Z,1573498388.592 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185307.00,A,3648.11869,N,12147.23363,W,0.019,74.25,111119,,,D*4D
2019-11-11T18:53:08.594Z,1573498388.594 [NAL9602](INFO): GPS fix at 20191111T185307: (36.801978, -121.787227)
2019-11-11T18:53:08.646Z,1573498388.646 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:53:08.646Z,1573498388.646 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:53:18.816Z,1573498398.816 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191111T180543/Courier0030.lzma
2019-11-11T18:53:20.822Z,1573498400.822 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0030.lzma.bak
2019-11-11T18:53:20.823Z,1573498400.823 [DataOverHttps](INFO): SBD MOMSN=11972772
2019-11-11T18:53:38.433Z,1573498418.433 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191111T180543/Express0032.lzma
2019-11-11T18:53:40.438Z,1573498420.438 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0032.lzma.bak
2019-11-11T18:53:40.439Z,1573498420.439 [DataOverHttps](INFO): SBD MOMSN=11972775
2019-11-11T18:53:41.744Z,1573498421.744 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:53:41.744Z,1573498421.744 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:53:41.744Z,1573498421.744 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T18:54:52.415Z,1573498492.415 [NAL9602](INFO): SBD MO Status=0, MOMSN=4846, MT Status=0, MTMSN=0
2019-11-11T18:54:52.416Z,1573498492.416 [NAL9602](INFO): No messages in MT queue
2019-11-11T18:55:02.046Z,1573498502.046 [DataOverHttps](IMPORTANT): SBD MTMSN=20191111T185500
2019-11-11T18:55:09.909Z,1573498509.909 [DataOverHttps](INFO): Received command:ibit
2019-11-11T18:55:09.930Z,1573498509.930 [CommandLine](IMPORTANT): got command ibit
2019-11-11T18:55:10.247Z,1573498510.247 [IBIT](IMPORTANT): Beginning Initiated BIT
2019-11-11T18:55:10.247Z,1573498510.247 [IBIT](IMPORTANT): Beginning control surface checks.
2019-11-11T18:55:10.253Z,1573498510.253 [CBIT](IMPORTANT): Beginning ground fault scan
2019-11-11T18:55:11.810Z,1573498511.810 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185510.00,A,3648.11870,N,12147.23332,W,0.019,74.25,111119,,,D*41
2019-11-11T18:55:11.812Z,1573498511.812 [NAL9602](INFO): GPS fix at 20191111T185510: (36.801978, -121.787222)
2019-11-11T18:55:15.035Z,1573498515.035 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185514.00,A,3648.11863,N,12147.23310,W,0.058,74.25,111119,,,D*42
2019-11-11T18:55:15.048Z,1573498515.048 [NAL9602](INFO): GPS fix at 20191111T185514: (36.801977, -121.787218)
2019-11-11T18:55:18.277Z,1573498518.277 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185517.00,A,3648.11845,N,12147.23261,W,0.039,74.25,111119,,,D*45
2019-11-11T18:55:18.303Z,1573498518.303 [NAL9602](INFO): GPS fix at 20191111T185517: (36.801974, -121.787210)
2019-11-11T18:55:21.096Z,1573498521.096 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185520.00,A,3648.11848,N,12147.23243,W,0.039,74.25,111119,,,D*4C
2019-11-11T18:55:21.098Z,1573498521.098 [NAL9602](INFO): GPS fix at 20191111T185520: (36.801975, -121.787207)
2019-11-11T18:55:21.212Z,1573498521.212 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): -0.007875
CHAN A1 (24V): 0.045211
CHAN A2 (12V): -0.003395
CHAN A3 (5V): -0.001082
CHAN B0 (3.3V): 0.000599
CHAN B1 (3.15aV): 0.000878
CHAN B2 (3.15bV): 0.000479
CHAN B3 (GND): 0.001950
OPEN: 0.005305
Full Scale Calc: 4.765 mA, -1.589 mA
2019-11-11T18:55:24.350Z,1573498524.350 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185523.00,A,3648.11855,N,12147.23243,W,0.019,74.25,111119,,,D*41
2019-11-11T18:55:24.355Z,1573498524.355 [NAL9602](INFO): GPS fix at 20191111T185523: (36.801976, -121.787207)
2019-11-11T18:55:27.163Z,1573498527.163 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185526.00,A,3648.11861,N,12147.23244,W,0.097,74.25,111119,,,D*42
2019-11-11T18:55:27.165Z,1573498527.165 [NAL9602](INFO): GPS fix at 20191111T185526: (36.801977, -121.787207)
2019-11-11T18:55:29.984Z,1573498529.984 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185529.00,A,3648.11856,N,12147.23221,W,0.039,74.25,111119,,,D*4E
2019-11-11T18:55:29.987Z,1573498529.987 [NAL9602](INFO): GPS fix at 20191111T185529: (36.801976, -121.787204)
2019-11-11T18:55:33.214Z,1573498533.214 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185532.00,A,3648.11855,N,12147.23214,W,0.039,74.25,111119,,,D*41
2019-11-11T18:55:33.216Z,1573498533.216 [NAL9602](INFO): GPS fix at 20191111T185532: (36.801976, -121.787202)
2019-11-11T18:55:36.062Z,1573498536.062 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185535.00,A,3648.11851,N,12147.23209,W,0.117,74.25,111119,,,D*43
2019-11-11T18:55:36.064Z,1573498536.064 [NAL9602](INFO): GPS fix at 20191111T185535: (36.801975, -121.787201)
2019-11-11T18:55:39.295Z,1573498539.295 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185538.00,A,3648.11840,N,12147.23218,W,0.019,74.25,111119,,,D*41
2019-11-11T18:55:39.298Z,1573498539.298 [NAL9602](INFO): GPS fix at 20191111T185538: (36.801973, -121.787203)
2019-11-11T18:55:42.104Z,1573498542.104 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185541.00,A,3648.11840,N,12147.23237,W,0.058,74.25,111119,,,D*47
2019-11-11T18:55:42.110Z,1573498542.110 [NAL9602](INFO): GPS fix at 20191111T185541: (36.801973, -121.787206)
2019-11-11T18:55:45.336Z,1573498545.336 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185544.00,A,3648.11852,N,12147.23244,W,0.019,74.25,111119,,,D*40
2019-11-11T18:55:45.338Z,1573498545.338 [NAL9602](INFO): GPS fix at 20191111T185544: (36.801975, -121.787207)
2019-11-11T18:55:48.170Z,1573498548.170 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185547.00,A,3648.11847,N,12147.23217,W,1.011,93.22,111119,,,D*46
2019-11-11T18:55:48.172Z,1573498548.172 [NAL9602](INFO): GPS fix at 20191111T185547: (36.801975, -121.787203)
2019-11-11T18:55:50.996Z,1573498550.996 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185550.00,A,3648.11822,N,12147.23153,W,0.564,110.18,111119,,,D*75
2019-11-11T18:55:50.999Z,1573498550.999 [NAL9602](INFO): GPS fix at 20191111T185550: (36.801970, -121.787192)
2019-11-11T18:55:54.228Z,1573498554.228 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185553.00,A,3648.11836,N,12147.23160,W,0.156,110.18,111119,,,D*76
2019-11-11T18:55:54.230Z,1573498554.230 [NAL9602](INFO): GPS fix at 20191111T185553: (36.801973, -121.787193)
2019-11-11T18:55:56.722Z,1573498556.722 [IBIT](IMPORTANT): Communications Status:
Fix Status: 1
Iridium Signal Strength: 2
Latitude: 36.801971 Longitude: -121.787193
2019-11-11T18:55:57.056Z,1573498557.056 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185556.00,A,3648.11846,N,12147.23162,W,0.058,110.18,111119,,,D*79
2019-11-11T18:55:57.058Z,1573498557.058 [NAL9602](INFO): GPS fix at 20191111T185556: (36.801974, -121.787194)
2019-11-11T18:55:57.115Z,1573498557.115 [IBIT](IMPORTANT): Battery Status:
Battery Charge (AH): 0.000000
Voltage: 0.000000
2019-11-11T18:55:57.115Z,1573498557.115 [IBIT](IMPORTANT): batteryCapacityThreshold: 50.000000 Ah
2019-11-11T18:55:57.115Z,1573498557.115 [IBIT](IMPORTANT): batteryVoltageThreshold: 13.700000 V
2019-11-11T18:55:57.508Z,1573498557.508 [IBIT](IMPORTANT): bitHumidityThreshold: 55.000000 %
2019-11-11T18:55:57.508Z,1573498557.508 [IBIT](IMPORTANT): bitPressureThreshold: 0.750000 psi
2019-11-11T18:55:57.509Z,1573498557.509 [IBIT](IMPORTANT): Pressure:7.439108 PSI
2019-11-11T18:55:57.509Z,1573498557.509 [IBIT](IMPORTANT): Humidity:11.848371 %
2019-11-11T18:55:57.902Z,1573498557.902 [IBIT](IMPORTANT): Vehicle Pitch:-1.392616 degrees
2019-11-11T18:55:57.902Z,1573498557.902 [IBIT](IMPORTANT): Vehicle  Roll:-4.101001 degrees
2019-11-11T18:55:57.903Z,1573498557.903 [IBIT](IMPORTANT): Vehicle  Heading:110.462555 degrees
2019-11-11T18:55:58.367Z,1573498558.367 [IBIT](IMPORTANT): surfaceThreshold: 1.000000 m
2019-11-11T18:55:58.368Z,1573498558.368 [IBIT](IMPORTANT): buoyancyNeutral: 300.000000 cc
2019-11-11T18:55:58.368Z,1573498558.368 [IBIT](IMPORTANT): massDefault: 0.600000 cm
2019-11-11T18:55:58.368Z,1573498558.368 [IBIT](IMPORTANT): stopDepth: 215.000000 m
2019-11-11T18:55:58.369Z,1573498558.369 [IBIT](IMPORTANT): abortDepth: 255.000000 m
2019-11-11T18:55:58.373Z,1573498558.373 [IBIT](IMPORTANT): IBIT PASSED
2019-11-11T18:56:29.778Z,1573498589.778 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:58:42.382Z,1573498722.382 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T18:58:42.382Z,1573498722.382 [Default:CheckIn:C.Wait] Stopped
2019-11-11T18:58:42.383Z,1573498722.383 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T18:58:42.383Z,1573498722.383 [Default:CheckIn:D] Running Loop=1
2019-11-11T18:58:42.736Z,1573498722.736 [Default:CheckIn:D] Stopped
2019-11-11T18:58:42.736Z,1573498722.736 [Default:CheckIn:E] Running Loop=1
2019-11-11T18:58:43.148Z,1573498723.148 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.150635 min 
2019-11-11T18:58:43.148Z,1573498723.148 [Default:CheckIn:E] Stopped
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn] Stopped
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn](INFO): Running loop #9
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn] Running Loop=9
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T18:58:43.153Z,1573498723.153 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T18:58:45.136Z,1573498725.136 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185844.00,A,3648.12039,N,12147.23105,W,0.039,54.38,111119,,,D*41
2019-11-11T18:58:45.146Z,1573498725.146 [NAL9602](INFO): GPS fix at 20191111T185844: (36.802006, -121.787184)
2019-11-11T18:58:45.216Z,1573498725.216 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T18:58:45.216Z,1573498725.216 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T18:58:54.680Z,1573498734.680 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191111T180543/Courier0034.lzma
2019-11-11T18:58:56.687Z,1573498736.687 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0034.lzma.bak
2019-11-11T18:58:56.687Z,1573498736.687 [DataOverHttps](INFO): SBD MOMSN=11972821
2019-11-11T18:59:01.480Z,1573498741.480 [NAL9602](INFO): SBD MO Status=0, MOMSN=4847, MT Status=0, MTMSN=0
2019-11-11T18:59:01.480Z,1573498741.480 [NAL9602](INFO): No messages in MT queue
2019-11-11T18:59:14.024Z,1573498754.024 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20191111T180543/Courier0037.lzma
2019-11-11T18:59:16.031Z,1573498756.031 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0037.lzma.bak
2019-11-11T18:59:16.031Z,1573498756.031 [DataOverHttps](INFO): SBD MOMSN=11972824
2019-11-11T18:59:32.186Z,1573498772.186 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T18:59:33.634Z,1573498773.634 [DataOverHttps](INFO): Sending 768 bytes from file Logs/20191111T180543/Express0035.lzma
2019-11-11T18:59:35.638Z,1573498775.638 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0035.lzma.bak
2019-11-11T18:59:35.639Z,1573498775.639 [DataOverHttps](INFO): SBD MOMSN=11972826
2019-11-11T18:59:53.148Z,1573498793.148 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191111T180543/Express0038.lzma
2019-11-11T18:59:55.154Z,1573498795.154 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0038.lzma.bak
2019-11-11T18:59:55.155Z,1573498795.155 [DataOverHttps](INFO): SBD MOMSN=11972852
2019-11-11T18:59:56.445Z,1573498796.445 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T18:59:56.445Z,1573498796.445 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T18:59:56.445Z,1573498796.445 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T19:04:43.323Z,1573499083.323 [RDI_Pathfinder](ERROR): Failed to parse:
:BE,-32768,-32768,-32768,V
2019-11-11T19:04:57.029Z,1573499097.029 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T19:04:57.029Z,1573499097.029 [Default:CheckIn:C.Wait] Stopped
2019-11-11T19:04:57.029Z,1573499097.029 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T19:04:57.029Z,1573499097.029 [Default:CheckIn:D] Running Loop=1
2019-11-11T19:04:57.433Z,1573499097.433 [Default:CheckIn:D] Stopped
2019-11-11T19:04:57.433Z,1573499097.433 [Default:CheckIn:E] Running Loop=1
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.395585 min 
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn:E] Stopped
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn] Stopped
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn](INFO): Running loop #10
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn] Running Loop=10
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T19:04:57.856Z,1573499097.856 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T19:04:59.840Z,1573499099.840 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190459.00,A,3648.12094,N,12147.23098,W,0.039,54.38,111119,,,D*47
2019-11-11T19:04:59.842Z,1573499099.842 [NAL9602](INFO): GPS fix at 20191111T190459: (36.802016, -121.787183)
2019-11-11T19:04:59.892Z,1573499099.892 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T19:04:59.892Z,1573499099.892 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T19:05:08.041Z,1573499108.041 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191111T180543/Courier0040.lzma
2019-11-11T19:05:10.046Z,1573499110.046 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0040.lzma.bak
2019-11-11T19:05:10.047Z,1573499110.047 [DataOverHttps](INFO): SBD MOMSN=11972863
2019-11-11T19:05:26.908Z,1573499126.908 [NAL9602](INFO): SBD MO Status=0, MOMSN=4848, MT Status=0, MTMSN=0
2019-11-11T19:05:26.908Z,1573499126.908 [NAL9602](INFO): No messages in MT queue
2019-11-11T19:05:27.333Z,1573499127.333 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20191111T180543/Express0041.lzma
2019-11-11T19:05:29.339Z,1573499129.339 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0041.lzma.bak
2019-11-11T19:05:29.339Z,1573499129.339 [DataOverHttps](INFO): SBD MOMSN=11972866
2019-11-11T19:05:30.584Z,1573499130.584 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T19:05:30.584Z,1573499130.584 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T19:05:30.585Z,1573499130.585 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T19:05:57.630Z,1573499157.630 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T19:10:31.176Z,1573499431.176 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T19:10:31.176Z,1573499431.176 [Default:CheckIn:C.Wait] Stopped
2019-11-11T19:10:31.176Z,1573499431.176 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T19:10:31.176Z,1573499431.176 [Default:CheckIn:D] Running Loop=1
2019-11-11T19:10:31.587Z,1573499431.587 [Default:CheckIn:D] Stopped
2019-11-11T19:10:31.587Z,1573499431.587 [Default:CheckIn:E] Running Loop=1
2019-11-11T19:10:31.987Z,1573499431.987 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 60.964819 min 
2019-11-11T19:10:31.987Z,1573499431.987 [Default:CheckIn:E] Stopped
2019-11-11T19:10:31.987Z,1573499431.987 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T19:10:31.987Z,1573499431.987 [Default:CheckIn] Stopped
2019-11-11T19:10:31.988Z,1573499431.988 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T19:10:31.988Z,1573499431.988 [Default:CheckIn](INFO): Running loop #11
2019-11-11T19:10:31.988Z,1573499431.988 [Default:CheckIn] Running Loop=11
2019-11-11T19:10:31.988Z,1573499431.988 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T19:10:31.988Z,1573499431.988 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T19:10:33.972Z,1573499433.972 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191033.00,A,3648.36796,N,12147.11277,W,4.976,352.16,111119,,,D*70
2019-11-11T19:10:33.974Z,1573499433.974 [NAL9602](INFO): GPS fix at 20191111T191033: (36.806133, -121.785213)
2019-11-11T19:10:33.000Z,1573499434.000 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T19:10:33.000Z,1573499434.000 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T19:10:41.665Z,1573499441.665 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20191111T180543/Courier0043.lzma
2019-11-11T19:10:43.671Z,1573499443.671 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0043.lzma.bak
2019-11-11T19:10:43.671Z,1573499443.671 [DataOverHttps](INFO): SBD MOMSN=11972880
2019-11-11T19:11:03.597Z,1573499463.597 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20191111T180543/Express0044.lzma
2019-11-11T19:11:05.603Z,1573499465.603 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0044.lzma.bak
2019-11-11T19:11:05.603Z,1573499465.603 [DataOverHttps](INFO): SBD MOMSN=11972883
2019-11-11T19:11:06.756Z,1573499466.756 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T19:11:06.756Z,1573499466.756 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T19:11:06.756Z,1573499466.756 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T19:11:13.987Z,1573499473.987 [NAL9602](INFO): SBD MO Status=2, MOMSN=4849, MT Status=2, MTMSN=0
2019-11-11T19:11:13.987Z,1573499473.987 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T19:11:33.780Z,1573499493.780 [NAL9602](INFO): SBD MO Status=2, MOMSN=4849, MT Status=2, MTMSN=0
2019-11-11T19:11:33.780Z,1573499493.780 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T19:11:57.638Z,1573499517.638 [NAL9602](INFO): SBD MO Status=2, MOMSN=4849, MT Status=2, MTMSN=0
2019-11-11T19:11:57.638Z,1573499517.638 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2019-11-11T19:12:06.498Z,1573499526.498 [NAL9602](INFO): SBD MO Status=0, MOMSN=4849, MT Status=0, MTMSN=0
2019-11-11T19:12:06.498Z,1573499526.498 [NAL9602](INFO): No messages in MT queue
2019-11-11T19:12:37.206Z,1573499557.206 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T19:13:40.282Z,1573499620.282 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2019-11-11T19:13:40.282Z,1573499620.282 [RDI_Pathfinder](ERROR): Failed to parse:
:BS,-32768,-32768,
2019-11-11T19:16:07.338Z,1573499767.338 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2019-11-11T19:16:07.338Z,1573499767.338 [Default:CheckIn:C.Wait] Stopped
2019-11-11T19:16:07.338Z,1573499767.338 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-11-11T19:16:07.338Z,1573499767.338 [Default:CheckIn:D] Running Loop=1
2019-11-11T19:16:07.764Z,1573499767.764 [Default:CheckIn:D] Stopped
2019-11-11T19:16:07.764Z,1573499767.764 [Default:CheckIn:E] Running Loop=1
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.567769 min 
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn:E] Stopped
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn](INFO): Completed Default:CheckIn
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn] Stopped
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn](INFO): Running loop #12
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn] Running Loop=12
2019-11-11T19:16:08.159Z,1573499768.159 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-11-11T19:16:08.160Z,1573499768.160 [Default:CheckIn:Read_GPS] Running Loop=1
2019-11-11T19:16:10.148Z,1573499770.148 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191609.00,A,3648.30194,N,12147.97470,W,20.974,261.05,111119,,,D*45
2019-11-11T19:16:10.150Z,1573499770.150 [NAL9602](INFO): GPS fix at 20191111T191609: (36.805032, -121.799578)
2019-11-11T19:16:10.194Z,1573499770.194 [Default:CheckIn:Read_GPS] Stopped
2019-11-11T19:16:10.194Z,1573499770.194 [Default:CheckIn:Read_Iridium] Running Loop=1
2019-11-11T19:16:18.584Z,1573499778.584 [DataOverHttps](INFO): Sending 65 bytes from file Logs/20191111T180543/Courier0046.lzma
2019-11-11T19:16:20.590Z,1573499780.590 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Courier0046.lzma.bak
2019-11-11T19:16:20.591Z,1573499780.591 [DataOverHttps](INFO): SBD MOMSN=11972895
2019-11-11T19:16:23.889Z,1573499783.889 [NAL9602](INFO): SBD MO Status=0, MOMSN=4850, MT Status=0, MTMSN=0
2019-11-11T19:16:23.889Z,1573499783.889 [NAL9602](INFO): No messages in MT queue
2019-11-11T19:16:37.949Z,1573499797.949 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20191111T180543/Express0047.lzma
2019-11-11T19:16:39.954Z,1573499799.954 [DataOverHttps](INFO): Moved sent file to Logs/20191111T180543/Express0047.lzma.bak
2019-11-11T19:16:39.955Z,1573499799.955 [DataOverHttps](INFO): SBD MOMSN=11972902
2019-11-11T19:16:41.320Z,1573499801.320 [Default:CheckIn:Read_Iridium] Stopped
2019-11-11T19:16:41.320Z,1573499801.320 [Default:CheckIn:C.Wait] Running Loop=1
2019-11-11T19:16:41.320Z,1573499801.320 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2019-11-11T19:16:54.610Z,1573499814.610 [NAL9602](INFO): Not Powering down - fast GPS
2019-11-11T19:21:15.631Z,1573500075.631 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2019-11-11T19:21:15.633Z,1573500075.633 [BPC1](INFO): Received data from all battery sticks.
2019-11-11T19:21:32.966Z,1573500092.966 [DataOverHttps](IMPORTANT): SBD MTMSN=20191111T192130
2019-11-11T19:21:40.816Z,1573500100.816 [DataOverHttps](INFO): Received command:restart logs