2020-12-10T21:43:11.460Z,1607636591.460 [Supervisor](DEBUG): Initializing supervisor.
2020-12-10T21:43:11.464Z,1607636591.464 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2020-12-10T21:43:11.465Z,1607636591.465 [SyncHandler](INFO): Protected caller Thread ID is 826
2020-12-10T21:43:11.465Z,1607636591.465 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2020-12-10T21:43:11.466Z,1607636591.466 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2020-12-10T21:43:11.467Z,1607636591.467 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 827
2020-12-10T21:43:11.471Z,1607636591.471 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2020-12-10T21:43:11.490Z,1607636591.490 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2020-12-10T21:43:11.491Z,1607636591.491 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2020-12-10T21:43:11.491Z,1607636591.491 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 828
2020-12-10T21:43:11.493Z,1607636591.493 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2020-12-10T21:43:11.494Z,1607636591.494 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2020-12-10T21:43:11.495Z,1607636591.495 [logger ThreadHandler](INFO): Protected caller Thread ID is 829
2020-12-10T21:43:11.499Z,1607636591.499 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2020-12-10T21:43:11.499Z,1607636591.499 [Supervisor](INFO): Looking for Config files in directory: Config/
2020-12-10T21:43:11.503Z,1607636591.503 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2020-12-10T21:43:11.910Z,1607636591.910 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2020-12-10T21:43:11.911Z,1607636591.911 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2020-12-10T21:43:11.992Z,1607636591.992 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2020-12-10T21:43:12.331Z,1607636592.331 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2020-12-10T21:43:12.332Z,1607636592.332 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2020-12-10T21:43:12.433Z,1607636592.433 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2020-12-10T21:43:12.435Z,1607636592.435 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2020-12-10T21:43:12.632Z,1607636592.632 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2020-12-10T21:43:12.634Z,1607636592.634 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2020-12-10T21:43:13.159Z,1607636593.159 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2020-12-10T21:43:13.159Z,1607636593.159 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2020-12-10T21:43:13.400Z,1607636593.400 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2020-12-10T21:43:13.402Z,1607636593.402 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2020-12-10T21:43:13.551Z,1607636593.551 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2020-12-10T21:43:13.552Z,1607636593.552 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2020-12-10T21:43:13.751Z,1607636593.751 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2020-12-10T21:43:13.753Z,1607636593.753 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2020-12-10T21:43:13.851Z,1607636593.851 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2020-12-10T21:43:13.852Z,1607636593.852 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2020-12-10T21:43:14.075Z,1607636594.075 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2020-12-10T21:43:14.076Z,1607636594.076 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2020-12-10T21:43:14.401Z,1607636594.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2020-12-10T21:43:14.402Z,1607636594.402 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2020-12-10T21:43:14.484Z,1607636594.484 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2020-12-10T21:43:14.612Z,1607636594.612 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2020-12-10T21:43:14.614Z,1607636594.614 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2020-12-10T21:43:15.919Z,1607636595.919 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2020-12-10T21:43:15.921Z,1607636595.921 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2020-12-10T21:43:16.297Z,1607636596.297 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2020-12-10T21:43:16.299Z,1607636596.299 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2020-12-10T21:43:16.301Z,1607636596.301 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2020-12-10T21:43:16.506Z,1607636596.506 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2020-12-10T21:43:16.608Z,1607636596.608 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2020-12-10T21:43:16.709Z,1607636596.709 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2020-12-10T21:43:16.969Z,1607636596.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2020-12-10T21:43:16.970Z,1607636596.970 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2020-12-10T21:43:17.058Z,1607636597.058 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2020-12-10T21:43:17.156Z,1607636597.156 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2020-12-10T21:43:17.271Z,1607636597.271 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2020-12-10T21:43:17.357Z,1607636597.357 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Dock.cfg
2020-12-10T21:43:17.445Z,1607636597.445 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2020-12-10T21:43:17.556Z,1607636597.556 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/workSite.cfg
2020-12-10T21:43:17.656Z,1607636597.656 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2020-12-10T21:43:17.852Z,1607636597.852 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2020-12-10T21:43:17.993Z,1607636597.993 [Supervisor](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2020-12-10T21:43:17.998Z,1607636597.998 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2020-12-10T21:43:18.718Z,1607636598.718 [AHRS_M2] Loaded
2020-12-10T21:43:18.718Z,1607636598.718 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2020-12-10T21:43:19.452Z,1607636599.452 [BPC1] Loaded
2020-12-10T21:43:19.452Z,1607636599.452 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2020-12-10T21:43:19.590Z,1607636599.590 [DataOverHttps] Loaded
2020-12-10T21:43:19.591Z,1607636599.591 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2020-12-10T21:43:19.592Z,1607636599.592 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407974E0
2020-12-10T21:43:19.592Z,1607636599.592 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 917
2020-12-10T21:43:19.613Z,1607636599.613 [DDM] Loaded
2020-12-10T21:43:19.613Z,1607636599.613 [ComponentRegistry](DEBUG): SyncComponent "DDM" handled in the control thread.
2020-12-10T21:43:19.631Z,1607636599.631 [Depth_Keller] Loaded
2020-12-10T21:43:19.632Z,1607636599.632 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2020-12-10T21:43:19.636Z,1607636599.636 [DropWeight] Loaded
2020-12-10T21:43:19.636Z,1607636599.636 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2020-12-10T21:43:19.678Z,1607636599.678 [DUSBL_Hydroid] Loaded
2020-12-10T21:43:19.678Z,1607636599.678 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2020-12-10T21:43:19.722Z,1607636599.722 [Micromodem] Loaded
2020-12-10T21:43:19.723Z,1607636599.723 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2020-12-10T21:43:19.779Z,1607636599.779 [NAL9602] Loaded
2020-12-10T21:43:19.779Z,1607636599.779 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2020-12-10T21:43:19.806Z,1607636599.806 [Onboard] Loaded
2020-12-10T21:43:19.806Z,1607636599.806 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2020-12-10T21:43:19.807Z,1607636599.807 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 407C74E0
2020-12-10T21:43:19.808Z,1607636599.808 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 918
2020-12-10T21:43:19.813Z,1607636599.813 [PowerOnly](INFO): Adding load control power supply at /dev/loadC1
2020-12-10T21:43:19.824Z,1607636599.824 [PowerOnly] Loaded
2020-12-10T21:43:19.824Z,1607636599.824 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2020-12-10T21:43:19.837Z,1607636599.837 [Radio_Surface] Loaded
2020-12-10T21:43:19.837Z,1607636599.837 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2020-12-10T21:43:19.838Z,1607636599.838 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407F74E0
2020-12-10T21:43:19.839Z,1607636599.839 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 919
2020-12-10T21:43:19.868Z,1607636599.868 [RDI_Pathfinder] Loaded
2020-12-10T21:43:19.868Z,1607636599.868 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2020-12-10T21:43:19.892Z,1607636599.892 [RDI_PathfinderUp] Loaded
2020-12-10T21:43:19.893Z,1607636599.893 [ComponentRegistry](DEBUG): SyncComponent "RDI_PathfinderUp" handled in the control thread.
2020-12-10T21:43:19.893Z,1607636599.893 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2020-12-10T21:43:19.894Z,1607636599.894 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2020-12-10T21:43:19.910Z,1607636599.910 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2020-12-10T21:43:19.912Z,1607636599.912 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2020-12-10T21:43:20.040Z,1607636600.040 [DeadReckonUsingMultipleVelocitySources] Loaded
2020-12-10T21:43:20.040Z,1607636600.040 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2020-12-10T21:43:20.053Z,1607636600.053 [NavChart] Loaded
2020-12-10T21:43:20.053Z,1607636600.053 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2020-12-10T21:43:20.059Z,1607636600.059 [UniversalFixResidualReporter] Loaded
2020-12-10T21:43:20.059Z,1607636600.059 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2020-12-10T21:43:20.069Z,1607636600.069 [WorkSite] Loaded
2020-12-10T21:43:20.069Z,1607636600.069 [ComponentRegistry](DEBUG): SyncComponent "WorkSite" handled in the control thread.
2020-12-10T21:43:20.070Z,1607636600.070 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2020-12-10T21:43:20.070Z,1607636600.070 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2020-12-10T21:43:20.179Z,1607636600.179 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2020-12-10T21:43:20.180Z,1607636600.180 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2020-12-10T21:43:20.319Z,1607636600.319 [BuoyancyServo] Loaded
2020-12-10T21:43:20.319Z,1607636600.319 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2020-12-10T21:43:20.340Z,1607636600.340 [ElevatorServo] Loaded
2020-12-10T21:43:20.340Z,1607636600.340 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2020-12-10T21:43:20.360Z,1607636600.360 [MassServo] Loaded
2020-12-10T21:43:20.360Z,1607636600.360 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2020-12-10T21:43:20.379Z,1607636600.379 [RudderServo] Loaded
2020-12-10T21:43:20.380Z,1607636600.380 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2020-12-10T21:43:20.398Z,1607636600.398 [ThrusterServo] Loaded
2020-12-10T21:43:20.398Z,1607636600.398 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2020-12-10T21:43:20.399Z,1607636600.399 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2020-12-10T21:43:20.399Z,1607636600.399 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2020-12-10T21:43:21.387Z,1607636601.387 [CTD_Seabird] Loaded
2020-12-10T21:43:21.388Z,1607636601.388 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2020-12-10T21:43:21.389Z,1607636601.389 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409274E0
2020-12-10T21:43:21.389Z,1607636601.389 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 920
2020-12-10T21:43:21.408Z,1607636601.408 [PAR_Licor] Loaded
2020-12-10T21:43:21.409Z,1607636601.409 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2020-12-10T21:43:21.441Z,1607636601.441 [WetLabsSeaOWL_UV_A] Loaded
2020-12-10T21:43:21.441Z,1607636601.441 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2020-12-10T21:43:21.442Z,1607636601.442 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409574E0
2020-12-10T21:43:21.442Z,1607636601.442 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 921
2020-12-10T21:43:21.443Z,1607636601.443 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2020-12-10T21:43:21.444Z,1607636601.444 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2020-12-10T21:43:21.821Z,1607636601.821 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2020-12-10T21:43:21.821Z,1607636601.821 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2020-12-10T21:43:21.878Z,1607636601.878 [DepthRateCalculator] Loaded
2020-12-10T21:43:21.878Z,1607636601.878 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2020-12-10T21:43:21.883Z,1607636601.883 [PitchRateCalculator] Loaded
2020-12-10T21:43:21.884Z,1607636601.884 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2020-12-10T21:43:21.893Z,1607636601.893 [SpeedCalculator] Loaded
2020-12-10T21:43:21.893Z,1607636601.893 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2020-12-10T21:43:21.907Z,1607636601.907 [TempGradientCalculator] Loaded
2020-12-10T21:43:21.907Z,1607636601.907 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2020-12-10T21:43:21.912Z,1607636601.912 [YawRateCalculator] Loaded
2020-12-10T21:43:21.912Z,1607636601.912 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2020-12-10T21:43:21.933Z,1607636601.933 [ElevatorOffsetCalculator] Loaded
2020-12-10T21:43:21.933Z,1607636601.933 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2020-12-10T21:43:21.934Z,1607636601.934 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2020-12-10T21:43:21.934Z,1607636601.934 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2020-12-10T21:43:22.096Z,1607636602.096 [SBIT](DEBUG): Construct Startup Built In Test.
2020-12-10T21:43:22.108Z,1607636602.108 [SBIT] Loaded
2020-12-10T21:43:22.109Z,1607636602.109 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2020-12-10T21:43:22.111Z,1607636602.111 [IBIT](DEBUG): Construct Initiated Built In Test.
2020-12-10T21:43:22.125Z,1607636602.125 [IBIT] Loaded
2020-12-10T21:43:22.125Z,1607636602.125 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2020-12-10T21:43:22.131Z,1607636602.131 [CBIT](DEBUG): Construct Continuous Built In Test.
2020-12-10T21:43:22.231Z,1607636602.231 [CBIT] Loaded
2020-12-10T21:43:22.232Z,1607636602.232 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2020-12-10T21:43:22.232Z,1607636602.232 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2020-12-10T21:43:22.233Z,1607636602.233 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2020-12-10T21:43:22.310Z,1607636602.310 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2020-12-10T21:43:22.310Z,1607636602.310 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2020-12-10T21:43:22.435Z,1607636602.435 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2020-12-10T21:43:22.436Z,1607636602.436 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2020-12-10T21:43:22.503Z,1607636602.503 [VerticalControl](DEBUG): Construct VerticalControl.
2020-12-10T21:43:22.556Z,1607636602.556 [VerticalControl] Loaded
2020-12-10T21:43:22.557Z,1607636602.557 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2020-12-10T21:43:22.559Z,1607636602.559 [HorizontalControl](DEBUG): Construct HorizontalControl.
2020-12-10T21:43:22.595Z,1607636602.595 [HorizontalControl] Loaded
2020-12-10T21:43:22.595Z,1607636602.595 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2020-12-10T21:43:22.598Z,1607636602.598 [SpeedControl](DEBUG): Construct SpeedControl.
2020-12-10T21:43:22.599Z,1607636602.599 [SpeedControl] Loaded
2020-12-10T21:43:22.599Z,1607636602.599 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2020-12-10T21:43:22.602Z,1607636602.602 [LoopControl](DEBUG): Construct LoopControl.
2020-12-10T21:43:22.603Z,1607636602.603 [LoopControl] Loaded
2020-12-10T21:43:22.603Z,1607636602.603 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2020-12-10T21:43:22.603Z,1607636602.603 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2020-12-10T21:43:22.604Z,1607636602.604 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2020-12-10T21:43:22.646Z,1607636602.646 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2020-12-10T21:43:22.652Z,1607636602.652 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2020-12-10T21:43:22.654Z,1607636602.654 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2020-12-10T21:43:22.665Z,1607636602.665 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2020-12-10T21:43:22.666Z,1607636602.666 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40AFF4E0
2020-12-10T21:43:22.666Z,1607636602.666 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 922
2020-12-10T21:43:22.671Z,1607636602.671 [Supervisor](INFO): Main Thread ID is 822
2020-12-10T21:43:22.671Z,1607636602.671 [Supervisor](DEBUG): Running supervisor.
2020-12-10T21:43:22.672Z,1607636602.672 [CommandLine ThreadHandler](INFO): Handler Thread ID is 923
2020-12-10T21:43:22.674Z,1607636602.674 [controlThread ThreadHandler](INFO): Handler Thread ID is 924
2020-12-10T21:43:22.675Z,1607636602.675 [controlThread](DEBUG): Initializing ControlThread
2020-12-10T21:43:22.683Z,1607636602.683 [NavChart](DEBUG): Initialize NavChart Navigation.
2020-12-10T21:43:22.684Z,1607636602.684 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2020-12-10T21:43:22.684Z,1607636602.684 [WorkSite](DEBUG): Initializing WorkSite component.
2020-12-10T21:43:22.688Z,1607636602.688 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2020-12-10T21:43:22.688Z,1607636602.688 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2020-12-10T21:43:22.689Z,1607636602.689 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2020-12-10T21:43:22.689Z,1607636602.689 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2020-12-10T21:43:22.690Z,1607636602.690 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2020-12-10T21:43:22.690Z,1607636602.690 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2020-12-10T21:43:22.691Z,1607636602.691 [SBIT](INFO): Initialize SBIT Component.
2020-12-10T21:43:22.691Z,1607636602.691 [SBIT](IMPORTANT): git: 2020-12-09_polaris
2020-12-10T21:43:22.691Z,1607636602.691 [SBIT](INFO): git hash: af9a0cd533cadbfdab8ca7c32aa0f39f5c9a4f8c
2020-12-10T21:43:22.692Z,1607636602.692 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2020-12-10T21:43:22.693Z,1607636602.693 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Thu Aug 6 12:04:53 PDT 2020
2020-12-10T21:43:22.694Z,1607636602.694 [SBIT](INFO): Beginning SBIT in 21.000000 seconds.
2020-12-10T21:43:22.695Z,1607636602.695 [IBIT](INFO): Initialize IBIT Component.
2020-12-10T21:43:22.695Z,1607636602.695 [CBIT](DEBUG): Initialize CBIT Component.
2020-12-10T21:43:22.696Z,1607636602.696 [logger ThreadHandler](INFO): Handler Thread ID is 925
2020-12-10T21:43:22.708Z,1607636602.708 [CBIT](DEBUG): Initialized mux pins.
2020-12-10T21:43:22.708Z,1607636602.708 [CBIT](FAULT): LAST RESTART WAS UNINTENTIONAL.
2020-12-10T21:43:22.708Z,1607636602.708 [CBIT](DEBUG): Initializing the watchdog timer.
2020-12-10T21:43:22.716Z,1607636602.716 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 926
2020-12-10T21:43:22.717Z,1607636602.717 [DataOverHttps](DEBUG): dashIP=128.128.181.155 starts with a digit so assuming it is a numeric IP
2020-12-10T21:43:22.728Z,1607636602.728 [Onboard ThreadHandler](INFO): Handler Thread ID is 927
2020-12-10T21:43:22.732Z,1607636602.732 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2020-12-10T21:43:22.733Z,1607636602.733 [CBIT](DEBUG): Initializing heartbeat.
2020-12-10T21:43:22.748Z,1607636602.748 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 928
2020-12-10T21:43:22.764Z,1607636602.764 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 929
2020-12-10T21:43:22.765Z,1607636602.765 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2020-12-10T21:43:22.769Z,1607636602.769 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 931
2020-12-10T21:43:22.770Z,1607636602.770 [WetLabsSeaOWL_UV_A](INFO): Powering down
2020-12-10T21:43:22.781Z,1607636602.781 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 932
2020-12-10T21:43:22.789Z,1607636602.789 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2020-12-10T21:43:22.789Z,1607636602.789 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2020-12-10T21:43:22.789Z,1607636602.789 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2020-12-10T21:43:22.790Z,1607636602.790 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2020-12-10T21:43:22.791Z,1607636602.791 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2020-12-10T21:43:22.791Z,1607636602.791 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2020-12-10T21:43:22.791Z,1607636602.791 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2020-12-10T21:43:22.791Z,1607636602.791 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2020-12-10T21:43:22.791Z,1607636602.791 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2020-12-10T21:43:22.792Z,1607636602.792 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2020-12-10T21:43:22.804Z,1607636602.804 [CBIT](DEBUG): Deactivating GF circuits.
2020-12-10T21:43:22.804Z,1607636602.804 [CBIT](DEBUG): Deactivating emergency mode.
2020-12-10T21:43:22.840Z,1607636602.840 [CBIT](DEBUG): Backplane powered.
2020-12-10T21:43:22.840Z,1607636602.840 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2020-12-10T21:43:22.842Z,1607636602.842 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2020-12-10T21:43:22.843Z,1607636602.843 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2020-12-10T21:43:22.843Z,1607636602.843 [LoopControl](DEBUG): Initialize LoopControlComponent.
2020-12-10T21:43:22.844Z,1607636602.844 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2020-12-10T21:43:22.883Z,1607636602.883 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T21:43:22.902Z,1607636602.902 [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>


2020-12-10T21:43:22.903Z,1607636602.903 [MissionManager](INFO): Loading Mission: Missions/underIce/DefaultWithUndock.xml
2020-12-10T21:43:23.066Z,1607636603.066 [MissionManager](INFO): DefineArg DefaultWithUndock.ElapsedSinceDefaultStarted = 0.000000 min
2020-12-10T21:43:23.098Z,1607636603.098 [MissionManager](INFO): DefineArg DefaultWithUndock.DetachTimeout = 30.000000 min
2020-12-10T21:43:23.102Z,1607636603.102 [MissionManager](INFO): DefineArg DefaultWithUndock.TransponderCode = 2 count
2020-12-10T21:43:23.121Z,1607636603.121 [MissionManager](INFO): DefineArg DefaultWithUndock.TrackingUpdatePeriod = 2.500000 s
2020-12-10T21:43:23.125Z,1607636603.125 [MissionManager](INFO): DefineArg DefaultWithUndock.NumberOfPings = 1.000000 count
2020-12-10T21:43:23.152Z,1607636603.152 [Radio_Surface](INFO): Powering up
2020-12-10T21:43:23.153Z,1607636603.153 [MissionManager](INFO): DefineArg DefaultWithUndock.DetachModeDDM = 2.000000 count
2020-12-10T21:43:23.154Z,1607636603.154 [DefaultWithUndock:A.Wait](DEBUG): Construct Wait.
2020-12-10T21:43:23.278Z,1607636603.278 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Construct.
2020-12-10T21:43:23.278Z,1607636603.278 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-10T21:43:23.330Z,1607636603.330 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Construct GoToSurface.
2020-12-10T21:43:23.381Z,1607636603.381 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2020-12-10T21:43:23.384Z,1607636603.384 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Construct Wait.
2020-12-10T21:43:23.406Z,1607636603.406 [DefaultWithUndock:E.Execute](DEBUG): Construct Execute.
2020-12-10T21:43:23.422Z,1607636603.422 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Dock="Tethys/Dock"
         xmlns:Estimation="Tethys/Estimation"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Sensor="Tethys/Sensor"
         xmlns:Units="Tethys/Units"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Dock http://okeanids.mbari.org/tethys/Xml/Dock.xsd
                             Tethys/Estimation http://okeanids.mbari.org/tethys/Xml/Estimation.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Sensor http://okeanids.mbari.org/tethys/Xml/Sensor.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="DefaultWithUndock">

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

    <DefineArg Name="DetachTimeout"><Description>
        Maximum time duration for the vehicle to detach form the dock.
    </Description><Units:minute/><Value>30</Value></DefineArg>

    <DefineArg Name="TransponderCode"><Description>
        Dock transponder address.
    </Description><Dock:Dock.transponderCode/></DefineArg>

    <DefineArg Name="TrackingUpdatePeriod"><Description>
        Time duration between acoustic range queries while the
        mission is detaching from the dock.
    </Description><Units:second/><Value>2.5</Value></DefineArg>

    <DefineArg Name="NumberOfPings"><Description>
        Number of pings requested each time.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="DetachModeDDM"><Description>
        DDM DETACH mode enumeration (whiskers retracted, latch open).
    </Description><Units:count/><Value>2</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>30</Value></Setting>
    </Guidance:Wait>

    <Aggregate Id="LeaveDock">
        <Sequence/>

        <Timeout Duration="DetachTimeout">
            <Syslog Severity="Important">Timed out while trying to detach from dock at current depth of <Universal:depth/><Units:meter/>.</Syslog>
        </Timeout>

        <!-- Acoustic tracking directives -->
        <Estimation:TrackAcousticContact>
            <Parallel/>
            <Setting><Estimation:TrackAcousticContact.contactLabelSetting/><Arg Name="TransponderCode"/></Setting>
            <Setting><Estimation:TrackAcousticContact.numberOfSamplesSetting/><Arg Name="NumberOfPings"/></Setting>
            <Setting><Estimation:TrackAcousticContact.updatePeriodSetting/><Arg Name="TrackingUpdatePeriod"/></Setting>
        </Estimation:TrackAcousticContact>

        <!-- Leave the dock -->
        <Dock:Undock>
            <Sequence/>
        </Dock:Undock>

    </Aggregate>


    <Aggregate Id="SurfaceDefault">

        <Sequence/>

        <Aggregate Id="HoldLatchOpen">

            <While>
                <Universal:depth/>
                <Gt><Control:VerticalControl.surfaceThreshold/></Gt>
            </While>

            <!-- Power the DDM -->
            <ReadData>
                <Sensor:DDM.DDMMode/>
            </ReadData>

            <!-- Hold the DDM in DETACH mode (whiskers retracted, latch open) -->
            <Assign><Parallel/><Sensor:DDM.DDMModeCmd/><Arg Name="DetachModeDDM"/></Assign>

        </Aggregate>

        <!-- This mission assumes open water so from here on it's the same old default that's always used -->
        <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>

    </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>


2020-12-10T21:43:23.440Z,1607636603.440 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,DDM,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,PowerOnly,RDI_Pathfinder,RDI_PathfinderUp,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,WorkSite,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2020-12-10T21:43:23.452Z,1607636603.452 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2020-12-10T21:43:23.560Z,1607636603.560 [DDM](INFO): Powering up
2020-12-10T21:43:23.561Z,1607636603.561 [DDM](DEBUG): Initializing DDM.
2020-12-10T21:43:23.585Z,1607636603.585 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2020-12-10T21:43:23.586Z,1607636603.586 [DUSBL_Hydroid](INFO): Powering up
2020-12-10T21:43:23.586Z,1607636603.586 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2020-12-10T21:43:23.629Z,1607636603.629 [DepthRateCalculator](ERROR): Depth measurement is not active
2020-12-10T21:43:23.697Z,1607636603.697 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:23.704Z,1607636603.704 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2020-12-10T21:43:23.705Z,1607636603.705 [ElevatorServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:23.712Z,1607636603.712 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2020-12-10T21:43:23.713Z,1607636603.713 [MassServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:23.721Z,1607636603.721 [MassServo](DEBUG): Initializing MassServo.
2020-12-10T21:43:23.722Z,1607636603.722 [RudderServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:23.728Z,1607636603.728 [RudderServo](DEBUG): Initializing RudderServo.
2020-12-10T21:43:23.729Z,1607636603.729 [ThrusterServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:23.736Z,1607636603.736 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2020-12-10T21:43:23.738Z,1607636603.738 [CommandLine](FAULT): Scheduling is paused
2020-12-10T21:43:23.738Z,1607636603.738 [CBIT](INFO): Critical error at 20201210T214322
2020-12-10T21:43:23.739Z,1607636603.739 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2020-12-10T21:43:23.868Z,1607636603.868 [Micromodem](INFO): Powering up
2020-12-10T21:43:23.868Z,1607636603.868 [Micromodem](DEBUG): Initializing Micromodem.
2020-12-10T21:43:24.588Z,1607636604.588 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2020-12-10T21:43:24.588Z,1607636604.588 [RudderServo](FAULT): Rudder failed to initialize
2020-12-10T21:43:24.588Z,1607636604.588 [RudderServo] Communications Fault, FailCount= 1
2020-12-10T21:43:24.588Z,1607636604.588 [RudderServo](ERROR): Communications Fault
2020-12-10T21:43:24.688Z,1607636604.688 [CBIT](ERROR): Communications Fault in component: RudderServo
2020-12-10T21:43:24.873Z,1607636604.873 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2020-12-10T21:43:24.873Z,1607636604.873 [RudderServo](INFO): Powering down
2020-12-10T21:43:25.519Z,1607636605.519 [RudderServo](DEBUG): Initializing EZServoServo.
2020-12-10T21:43:25.641Z,1607636605.641 [RudderServo](DEBUG): Initializing RudderServo.
2020-12-10T21:43:25.645Z,1607636605.645 [CBIT](INFO): Clearing failed state for component RudderServo
2020-12-10T21:43:25.645Z,1607636605.645 [RudderServo] No Fault, FailCount= 1
2020-12-10T21:43:29.183Z,1607636609.183 [Micromodem](ERROR): CFG response from modem unexpected: $CATMG,2020-12-10T21:43:29.661499Z,RTC,RTC*58

2020-12-10T21:43:29.212Z,1607636609.212 [Radio_Surface](INFO): Powering down
2020-12-10T21:43:29.796Z,1607636609.796 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2020-12-10T21:43:39.240Z,1607636619.240 [DDM](INFO): Dynamic Docking Module:
2020-12-10T21:43:41.666Z,1607636621.666 [DUSBL_Hydroid](INFO): DUSBL Version:O
2020-12-10T21:43:44.175Z,1607636624.175 [SBIT](IMPORTANT): Beginning Startup BIT
2020-12-10T21:43:44.179Z,1607636624.179 [CBIT](IMPORTANT): Beginning ground fault scan
2020-12-10T21:43:50.150Z,1607636630.150 [NAL9602](INFO): Powering up NAL9602
2020-12-10T21:43:55.145Z,1607636635.145 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.062619
CHAN A1 (24V): 0.082685
CHAN A2 (12V): 0.039342
CHAN A3 (5V): 0.008463
CHAN B0 (3.3V): 0.003633
CHAN B1 (3.15aV): 0.002833
CHAN B2 (3.15bV): 0.003064
CHAN B3 (GND): -0.010959
OPEN: 0.007796
Full Scale Calc: 4.765 mA, -1.589 mA
2020-12-10T21:44:01.066Z,1607636641.066 [NAL9602](INFO): NAL9602 initialized
2020-12-10T21:44:18.060Z,1607636658.060 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T21:44:28.174Z,1607636668.174 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T21:44:32.999Z,1607636672.999 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T21:44:38.294Z,1607636678.294 [SBIT](IMPORTANT): SBIT PASSED
2020-12-10T21:44:38.294Z,1607636678.294 [SBIT](FAULT): Ignoring configuration overrides from Data/persisted.cfg
2020-12-10T21:44:38.643Z,1607636678.643 [WorkSite](IMPORTANT): Reading workSite position from Data/workSite.cfg
2020-12-10T21:44:38.667Z,1607636678.667 [WorkSite](IMPORTANT): WorkSite fix at 20201210T214028: (41.551953, -70.720599)
2020-12-10T21:44:38.669Z,1607636678.669 [MissionManager](IMPORTANT): Started mission Startup
2020-12-10T21:44:38.669Z,1607636678.669 [Startup] Running Loop=1
2020-12-10T21:44:38.669Z,1607636678.669 [Startup](DEBUG): Aggregate::initialize Startup
2020-12-10T21:44:38.669Z,1607636678.669 [Startup:A.GoToSurface] Running Loop=1
2020-12-10T21:44:38.669Z,1607636678.669 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T21:44:38.670Z,1607636678.670 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-10T21:44:38.670Z,1607636678.670 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-10T21:44:38.671Z,1607636678.671 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-10T21:44:38.671Z,1607636678.671 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T21:44:38.671Z,1607636678.671 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T21:44:39.089Z,1607636679.089 [ElevatorOffsetCalculator](INFO): New estimator for commanded vars: speed 1.00 m/s, pitch 30.00 deg, mass-position -24.00 mm (1 active estimators).
2020-12-10T21:44:39.144Z,1607636679.144 [Radio_Surface](INFO): Powering up
2020-12-10T21:44:58.102Z,1607636698.102 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for altitude
2020-12-10T21:45:08.959Z,1607636708.959 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:45:17.927Z,1607636717.927 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:45:17.942Z,1607636717.942 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T21:45:42.961Z,1607636742.961 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:45:48.148Z,1607636748.148 [RDI_Pathfinder](ERROR): only read 1 of 4 data items
2020-12-10T21:45:52.991Z,1607636752.991 [RDI_Pathfinder](ERROR): only read 3 of 4 data items
2020-12-10T21:45:52.999Z,1607636752.999 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T21:46:03.082Z,1607636763.082 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T21:46:07.951Z,1607636767.951 [RDI_Pathfinder](ERROR): only read 2 of 4 data items
2020-12-10T21:46:11.161Z,1607636771.161 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude
2020-12-10T21:46:13.197Z,1607636773.197 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:46:18.048Z,1607636778.048 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T21:46:22.967Z,1607636782.967 [RDI_PathfinderUp](ERROR): DVL BIT error. See manual. Result code: 294
2020-12-10T21:46:27.022Z,1607636787.022 [Startup:A.GoToSurface](ERROR): Pitch down timeout. Pitch: -1.50
2020-12-10T21:46:28.154Z,1607636788.154 [RDI_PathfinderUp](ERROR): only read 2 of 4 data items
2020-12-10T21:46:33.084Z,1607636793.084 [RDI_PathfinderUp](ERROR): DVL uart error: serial timeout
2020-12-10T21:46:33.084Z,1607636793.084 [RDI_PathfinderUp] Communications Fault, FailCount= 1
2020-12-10T21:46:33.084Z,1607636793.084 [RDI_PathfinderUp](ERROR): Communications Fault
2020-12-10T21:46:33.204Z,1607636793.204 [CBIT](ERROR): Communications Fault in component: RDI_PathfinderUp
2020-12-10T21:46:33.460Z,1607636793.460 [RDI_PathfinderUp](INFO): Powering down
2020-12-10T21:46:34.276Z,1607636794.276 [CBIT](INFO): Clearing failed state for component RDI_PathfinderUp
2020-12-10T21:46:34.276Z,1607636794.276 [RDI_PathfinderUp] No Fault, FailCount= 1
2020-12-10T21:46:47.524Z,1607636807.524 [Startup:StartupSatComms] Running Loop=1
2020-12-10T21:46:47.524Z,1607636807.524 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2020-12-10T21:46:47.524Z,1607636807.524 [Startup:StartupSatComms:A] Running Loop=1
2020-12-10T21:46:47.979Z,1607636807.979 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2020-12-10T21:47:00.072Z,1607636820.072 [NAL9602](INFO): SBD MO Status=0, MOMSN=12259, MT Status=0, MTMSN=0
2020-12-10T21:47:00.072Z,1607636820.072 [NAL9602](INFO): No messages in MT queue
2020-12-10T21:47:36.459Z,1607636856.459 [RDI_PathfinderUp](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:47:47.742Z,1607636867.742 [Startup:StartupSatComms:A](INFO): Timed out from 2020-12-10T21:46:47.5Z
2020-12-10T21:47:47.742Z,1607636867.742 [Startup:StartupSatComms:A] Stopped
2020-12-10T21:47:47.742Z,1607636867.742 [Startup:StartupSatComms:B] Running Loop=1
2020-12-10T21:47:48.151Z,1607636868.151 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T21:48:07.902Z,1607636887.902 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.013325
2020-12-10T21:48:11.910Z,1607636891.910 [DataOverHttps](INFO): Sending 2982 bytes from file Logs/20201210T212904/Courier0009.lzma
2020-12-10T21:48:12.906Z,1607636892.906 [DataOverHttps](INFO): Moved sent file to Logs/20201210T212904/Courier0009.lzma.bak
2020-12-10T21:48:12.906Z,1607636892.906 [DataOverHttps](INFO): SBD MOMSN=61160
2020-12-10T21:48:20.489Z,1607636900.489 [NAL9602](INFO): SBD MO Status=2, MOMSN=12260, MT Status=2, MTMSN=0
2020-12-10T21:48:20.489Z,1607636900.489 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2
2020-12-10T21:48:21.944Z,1607636901.944 [DataOverHttps](INFO): Sending 326 bytes from file Logs/20201210T214311/Courier0000.lzma
2020-12-10T21:48:22.946Z,1607636902.946 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Courier0000.lzma.bak
2020-12-10T21:48:22.946Z,1607636902.946 [DataOverHttps](INFO): SBD MOMSN=61992
2020-12-10T21:48:31.992Z,1607636911.992 [DataOverHttps](INFO): Sending 367 bytes from file Logs/20201210T212904/Express0011.lzma
2020-12-10T21:48:32.994Z,1607636912.994 [DataOverHttps](INFO): Moved sent file to Logs/20201210T212904/Express0011.lzma.bak
2020-12-10T21:48:32.994Z,1607636912.994 [DataOverHttps](INFO): SBD MOMSN=61997
2020-12-10T21:48:42.033Z,1607636922.033 [DataOverHttps](INFO): Sending 832 bytes from file Logs/20201210T214311/Express0001.lzma
2020-12-10T21:48:43.034Z,1607636923.034 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Express0001.lzma.bak
2020-12-10T21:48:43.034Z,1607636923.034 [DataOverHttps](INFO): SBD MOMSN=62016
2020-12-10T21:48:44.316Z,1607636924.316 [Startup:StartupSatComms:B] Stopped
2020-12-10T21:48:44.316Z,1607636924.316 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2020-12-10T21:48:44.316Z,1607636924.316 [Startup:StartupSatComms] Stopped
2020-12-10T21:48:44.317Z,1607636924.317 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2020-12-10T21:48:44.317Z,1607636924.317 [Startup](INFO): Completed Startup
2020-12-10T21:48:44.317Z,1607636924.317 [MissionManager](INFO): Startup is completed.
2020-12-10T21:48:44.318Z,1607636924.318 [MissionManager](INFO): Uninitializing Mission Startup
2020-12-10T21:48:44.318Z,1607636924.318 [Startup] Stopped
2020-12-10T21:48:44.318Z,1607636924.318 [Startup](DEBUG): Aggregate::uninitialize Startup
2020-12-10T21:48:44.318Z,1607636924.318 [Startup:A.GoToSurface] Stopped
2020-12-10T21:48:44.318Z,1607636924.318 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2020-12-10T21:48:44.732Z,1607636924.732 [MissionManager](IMPORTANT): Started mission DefaultWithUndock
2020-12-10T21:48:44.732Z,1607636924.732 [DefaultWithUndock] Running Loop=1
2020-12-10T21:48:44.732Z,1607636924.732 [DefaultWithUndock](DEBUG): Aggregate::initialize DefaultWithUndock
2020-12-10T21:48:44.732Z,1607636924.732 [DefaultWithUndock:A.Wait] Running Loop=1
2020-12-10T21:48:44.732Z,1607636924.732 [DefaultWithUndock:A.Wait](DEBUG): Initialize Wait Component.
2020-12-10T21:48:51.177Z,1607636931.177 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T21:49:15.050Z,1607636955.050 [DefaultWithUndock:A.Wait](INFO): Done Waiting.
2020-12-10T21:49:15.050Z,1607636955.050 [DefaultWithUndock:A.Wait] Stopped
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:A.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock] Running Loop=1
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::initialize DefaultWithUndock:LeaveDock
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock:A.](INFO): Initializing TrackAcousticContact.
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock:B.Undock] Running Loop=1
2020-12-10T21:49:15.051Z,1607636955.051 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initialize.
2020-12-10T21:49:15.052Z,1607636955.052 [DefaultWithUndock:LeaveDock:B.Undock](DEBUG): Initializing internal variables to default values.
2020-12-10T21:49:15.468Z,1607636955.468 [DefaultWithUndock:LeaveDock:A.] Running Loop=1
2020-12-10T21:49:15.825Z,1607636955.825 [PowerOnly](INFO): Powering up loadControl
2020-12-10T21:49:17.938Z,1607636957.938 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:19.551Z,1607636959.551 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detaching from dock.
2020-12-10T21:49:19.954Z,1607636959.954 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detected possible detachment. Starting timer.
2020-12-10T21:49:20.694Z,1607636960.694 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,AFD,000,04799,189
2020-12-10T21:49:20.742Z,1607636960.742 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:23.558Z,1607636963.558 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:26.373Z,1607636966.373 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:29.177Z,1607636969.177 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,F1E,000,0479F,187,8
2020-12-10T21:49:29.225Z,1607636969.225 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:32.164Z,1607636972.164 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:34.922Z,1607636974.922 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:37.682Z,1607636977.682 [DUSBL_Hydroid](ERROR): unknown deviceResponse_: !U1,R,F52,000,047AA,186,80,80,
2020-12-10T21:49:37.750Z,1607636977.750 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:40.167Z,1607636980.167 [DefaultWithUndock:LeaveDock:B.Undock](INFO): Detached at range: nan m. Transitioning DDM to standby.
2020-12-10T21:49:40.670Z,1607636980.670 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:43.383Z,1607636983.383 [DefaultWithUndock:LeaveDock:B.Undock](INFO): DDM at standby.
2020-12-10T21:49:43.383Z,1607636983.383 [DefaultWithUndock:LeaveDock:A.](INFO): *** querying acoustic contact ***
2020-12-10T21:49:43.787Z,1607636983.787 [DefaultWithUndock:LeaveDock:B.Undock](IMPORTANT): Undocking sequence complete.
2020-12-10T21:49:43.787Z,1607636983.787 [DefaultWithUndock:LeaveDock:B.Undock] Stopped
2020-12-10T21:49:43.787Z,1607636983.787 [DefaultWithUndock:LeaveDock](INFO): Completed DefaultWithUndock:LeaveDock
2020-12-10T21:49:43.787Z,1607636983.787 [DefaultWithUndock:LeaveDock] Stopped
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:LeaveDock](DEBUG): Aggregate::uninitialize DefaultWithUndock:LeaveDock
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:LeaveDock:A.] Stopped
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:SurfaceDefault] Running Loop=1
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:SurfaceDefault](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Running Loop=1
2020-12-10T21:49:43.804Z,1607636983.804 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Running Loop=1
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Running Loop=1
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:B.GoToSurface] Running Loop=1
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2020-12-10T21:49:43.805Z,1607636983.805 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2020-12-10T21:49:43.806Z,1607636983.806 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2020-12-10T21:49:43.806Z,1607636983.806 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2020-12-10T21:49:43.806Z,1607636983.806 [DefaultWithUndock:SurfaceDefault:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=1
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen] Stopped
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:HoldLatchOpen
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:A] Stopped
2020-12-10T21:49:44.154Z,1607636984.154 [DefaultWithUndock:SurfaceDefault:HoldLatchOpen:B] Stopped
2020-12-10T21:49:44.578Z,1607636984.578 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2020-12-10T21:49:46.136Z,1607636986.136 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,214945.00,A,4133.07723,N,07043.25995,W,0.058,109.05,101220,,,A*75
2020-12-10T21:49:46.139Z,1607636986.139 [NAL9602](INFO): GPS fix at 20201210T214945: (41.551287, -70.720999)
2020-12-10T21:49:46.206Z,1607636986.206 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-10T21:49:46.206Z,1607636986.206 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-10T21:49:46.618Z,1607636986.618 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2020-12-10T21:49:50.311Z,1607636990.311 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20201210T214311/Courier0004.lzma
2020-12-10T21:49:51.322Z,1607636991.322 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Courier0004.lzma.bak
2020-12-10T21:49:51.322Z,1607636991.322 [DataOverHttps](INFO): SBD MOMSN=62032
2020-12-10T21:50:00.360Z,1607637000.360 [DataOverHttps](INFO): Sending 167 bytes from file Logs/20201210T214311/Express0005.lzma
2020-12-10T21:50:01.362Z,1607637001.362 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Express0005.lzma.bak
2020-12-10T21:50:01.362Z,1607637001.362 [DataOverHttps](INFO): SBD MOMSN=62035
2020-12-10T21:50:02.847Z,1607637002.847 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-10T21:50:02.847Z,1607637002.847 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-10T21:50:02.847Z,1607637002.847 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-10T21:50:05.228Z,1607637005.228 [NAL9602](INFO): SBD MO Status=1, MOMSN=12260, MT Status=0, MTMSN=0
2020-12-10T21:50:05.228Z,1607637005.228 [NAL9602](INFO): No messages in MT queue
2020-12-10T21:50:35.948Z,1607637035.948 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T21:50:47.244Z,1607637047.244 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6.
2020-12-10T21:50:47.246Z,1607637047.246 [BPC1](INFO): Received data from all battery sticks.
2020-12-10T21:50:47.266Z,1607637047.266 [PowerOnly](INFO): Powering down loadControl
2020-12-10T21:55:03.425Z,1607637303.425 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](INFO): Done Waiting.
2020-12-10T21:55:03.425Z,1607637303.425 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Stopped
2020-12-10T21:55:03.425Z,1607637303.425 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2020-12-10T21:55:03.425Z,1607637303.425 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Running Loop=1
2020-12-10T21:55:03.822Z,1607637303.822 [DefaultWithUndock:SurfaceDefault:CheckIn:D] Stopped
2020-12-10T21:55:03.822Z,1607637303.822 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Running Loop=1
2020-12-10T21:55:04.229Z,1607637304.229 [DefaultWithUndock:SurfaceDefault:CheckIn:E](IMPORTANT): Default mission has been running for 6.318163 min 
2020-12-10T21:55:04.229Z,1607637304.229 [DefaultWithUndock:SurfaceDefault:CheckIn:E] Stopped
2020-12-10T21:55:04.229Z,1607637304.229 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Completed DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T21:55:04.229Z,1607637304.229 [DefaultWithUndock:SurfaceDefault:CheckIn] Stopped
2020-12-10T21:55:04.229Z,1607637304.229 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::uninitialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T21:55:04.230Z,1607637304.230 [DefaultWithUndock:SurfaceDefault:CheckIn](INFO): Running loop #2
2020-12-10T21:55:04.230Z,1607637304.230 [DefaultWithUndock:SurfaceDefault:CheckIn] Running Loop=2
2020-12-10T21:55:04.230Z,1607637304.230 [DefaultWithUndock:SurfaceDefault:CheckIn](DEBUG): Aggregate::initialize DefaultWithUndock:SurfaceDefault:CheckIn
2020-12-10T21:55:04.230Z,1607637304.230 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Running Loop=1
2020-12-10T21:55:06.234Z,1607637306.234 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,215506.00,A,4133.06162,N,07043.26728,W,0.233,126.38,101220,,,A*7A
2020-12-10T21:55:06.236Z,1607637306.236 [NAL9602](INFO): GPS fix at 20201210T215506: (41.551027, -70.721121)
2020-12-10T21:55:06.257Z,1607637306.257 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_GPS] Stopped
2020-12-10T21:55:06.257Z,1607637306.257 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Running Loop=1
2020-12-10T21:55:10.675Z,1607637310.675 [DataOverHttps](INFO): Sending 200 bytes from file Logs/20201210T214311/Courier0007.lzma
2020-12-10T21:55:11.678Z,1607637311.678 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Courier0007.lzma.bak
2020-12-10T21:55:11.678Z,1607637311.678 [DataOverHttps](INFO): SBD MOMSN=62040
2020-12-10T21:55:20.716Z,1607637320.716 [DataOverHttps](INFO): Sending 168 bytes from file Logs/20201210T214311/Express0008.lzma
2020-12-10T21:55:21.718Z,1607637321.718 [DataOverHttps](INFO): Moved sent file to Logs/20201210T214311/Express0008.lzma.bak
2020-12-10T21:55:21.718Z,1607637321.718 [DataOverHttps](INFO): SBD MOMSN=62043
2020-12-10T21:55:22.918Z,1607637322.918 [DefaultWithUndock:SurfaceDefault:CheckIn:Read_Iridium] Stopped
2020-12-10T21:55:22.918Z,1607637322.918 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait] Running Loop=1
2020-12-10T21:55:22.918Z,1607637322.918 [DefaultWithUndock:SurfaceDefault:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2020-12-10T21:56:11.296Z,1607637371.296 [NAL9602](INFO): SBD MO Status=1, MOMSN=12261, MT Status=0, MTMSN=0
2020-12-10T21:56:11.296Z,1607637371.296 [NAL9602](INFO): No messages in MT queue
2020-12-10T21:56:41.993Z,1607637401.993 [NAL9602](INFO): Not Powering down - fast GPS
2020-12-10T21:57:09.067Z,1607637429.067 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2020-12-10T21:57:38.563Z,1607637458.563 [RDI_PathfinderUp](ERROR): only read 3 of 4 data items
2020-12-10T21:57:48.321Z,1607637468.321 [DataOverHttps](IMPORTANT): SBD MTMSN=20201210T215748
2020-12-10T21:57:52.344Z,1607637472.344 [DataOverHttps](INFO): Received command:restart sys
2020-12-10T21:57:52.392Z,1607637472.392 [CommandLine](IMPORTANT): got command restart system
2020-12-10T21:57:54.560Z,1607637474.560 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2020-12-10T21:57:54.561Z,1607637474.561 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-12-10T21:57:54.592Z,1607637474.592 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2020-12-10T21:57:54.592Z,1607637474.592 [CommandLine ThreadHandler](INFO): Thread cancelled.
2020-12-10T21:57:54.593Z,1607637474.593 [CommandLine](INFO): Join timeout helper Thread ID is 1029
2020-12-10T21:57:54.593Z,1607637474.593 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2020-12-10T21:57:54.594Z,1607637474.5