2019-05-21T14:47:45.908Z,1558450065.908 [Supervisor](DEBUG): Initializing supervisor.
2019-05-21T14:47:45.911Z,1558450065.911 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2019-05-21T14:47:45.912Z,1558450065.912 [SyncHandler](INFO): Protected caller Thread ID is 393
2019-05-21T14:47:45.912Z,1558450065.912 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2019-05-21T14:47:45.913Z,1558450065.913 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2019-05-21T14:47:45.913Z,1558450065.913 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 394
2019-05-21T14:47:45.916Z,1558450065.916 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2019-05-21T14:47:45.938Z,1558450065.938 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2019-05-21T14:47:45.939Z,1558450065.939 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2019-05-21T14:47:45.940Z,1558450065.940 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 395
2019-05-21T14:47:45.941Z,1558450065.941 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2019-05-21T14:47:45.942Z,1558450065.942 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2019-05-21T14:47:45.942Z,1558450065.942 [logger ThreadHandler](INFO): Protected caller Thread ID is 396
2019-05-21T14:47:45.944Z,1558450065.944 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2019-05-21T14:47:45.944Z,1558450065.944 [Supervisor](INFO): Looking for Config files in directory: Config/
2019-05-21T14:47:45.946Z,1558450065.946 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2019-05-21T14:47:46.367Z,1558450066.367 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2019-05-21T14:47:46.368Z,1558450066.368 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2019-05-21T14:47:46.468Z,1558450066.468 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2019-05-21T14:47:46.469Z,1558450066.469 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2019-05-21T14:47:46.794Z,1558450066.794 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2019-05-21T14:47:46.795Z,1558450066.795 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2019-05-21T14:47:46.938Z,1558450066.938 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2019-05-21T14:47:46.938Z,1558450066.938 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2019-05-21T14:47:47.131Z,1558450067.131 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2019-05-21T14:47:47.132Z,1558450067.132 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2019-05-21T14:47:47.586Z,1558450067.586 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2019-05-21T14:47:47.587Z,1558450067.587 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2019-05-21T14:47:47.798Z,1558450067.798 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2019-05-21T14:47:47.798Z,1558450067.798 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2019-05-21T14:47:47.945Z,1558450067.945 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2019-05-21T14:47:47.946Z,1558450067.946 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2019-05-21T14:47:48.141Z,1558450068.141 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2019-05-21T14:47:48.141Z,1558450068.141 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2019-05-21T14:47:48.239Z,1558450068.239 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2019-05-21T14:47:48.239Z,1558450068.239 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2019-05-21T14:47:48.559Z,1558450068.559 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2019-05-21T14:47:48.560Z,1558450068.560 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2019-05-21T14:47:48.642Z,1558450068.642 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2019-05-21T14:47:48.747Z,1558450068.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2019-05-21T14:47:48.748Z,1558450068.748 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2019-05-21T14:47:49.337Z,1558450069.337 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2019-05-21T14:47:49.338Z,1558450069.338 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2019-05-21T14:47:49.726Z,1558450069.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2019-05-21T14:47:49.729Z,1558450069.729 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/
2019-05-21T14:47:49.730Z,1558450069.730 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/vehicle.cfg
2019-05-21T14:47:49.939Z,1558450069.939 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Control.cfg
2019-05-21T14:47:50.041Z,1558450070.041 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/BIT.cfg
2019-05-21T14:47:50.141Z,1558450070.141 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Battery.cfg
2019-05-21T14:47:50.369Z,1558450070.369 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2019-05-21T14:47:50.370Z,1558450070.370 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Simulator.cfg
2019-05-21T14:47:50.458Z,1558450070.458 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Navigation.cfg
2019-05-21T14:47:50.554Z,1558450070.554 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/logger.cfg
2019-05-21T14:47:50.655Z,1558450070.655 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/secure.cfg
2019-05-21T14:47:50.741Z,1558450070.741 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Servo.cfg
2019-05-21T14:47:50.850Z,1558450070.850 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Sensor.cfg
2019-05-21T14:47:51.079Z,1558450071.079 [Supervisor](INFO): Opening Config file at: Config/lrauv-whoidhs/Science.cfg
2019-05-21T14:47:51.377Z,1558450071.377 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-whoidhs/LOGIN/
2019-05-21T14:47:51.378Z,1558450071.378 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2019-05-21T14:47:51.392Z,1558450071.392 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2019-05-21T14:47:52.004Z,1558450072.004 [AHRS_M2] Loaded
2019-05-21T14:47:52.004Z,1558450072.004 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2019-05-21T14:47:52.078Z,1558450072.078 [DataOverHttps] Loaded
2019-05-21T14:47:52.078Z,1558450072.078 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2019-05-21T14:47:52.080Z,1558450072.080 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 407614E0
2019-05-21T14:47:52.080Z,1558450072.080 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 476
2019-05-21T14:47:52.093Z,1558450072.093 [Depth_Keller] Loaded
2019-05-21T14:47:52.094Z,1558450072.094 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2019-05-21T14:47:52.098Z,1558450072.098 [DropWeight] Loaded
2019-05-21T14:47:52.099Z,1558450072.099 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2019-05-21T14:47:52.155Z,1558450072.155 [DUSBL_Hydroid] Loaded
2019-05-21T14:47:52.156Z,1558450072.156 [ComponentRegistry](DEBUG): SyncComponent "DUSBL_Hydroid" handled in the control thread.
2019-05-21T14:47:52.203Z,1558450072.203 [Micromodem] Loaded
2019-05-21T14:47:52.203Z,1558450072.203 [ComponentRegistry](DEBUG): SyncComponent "Micromodem" handled in the control thread.
2019-05-21T14:47:52.301Z,1558450072.301 [NAL9602] Loaded
2019-05-21T14:47:52.301Z,1558450072.301 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2019-05-21T14:47:52.317Z,1558450072.317 [Onboard] Loaded
2019-05-21T14:47:52.317Z,1558450072.317 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2019-05-21T14:47:52.323Z,1558450072.323 [PowerOnly] Loaded
2019-05-21T14:47:52.323Z,1558450072.323 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2019-05-21T14:47:52.330Z,1558450072.330 [Radio_Surface] Loaded
2019-05-21T14:47:52.330Z,1558450072.330 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2019-05-21T14:47:52.331Z,1558450072.331 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 407914E0
2019-05-21T14:47:52.332Z,1558450072.332 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 477
2019-05-21T14:47:52.376Z,1558450072.376 [RDI_Pathfinder] Loaded
2019-05-21T14:47:52.377Z,1558450072.377 [ComponentRegistry](DEBUG): SyncComponent "RDI_Pathfinder" handled in the control thread.
2019-05-21T14:47:53.898Z,1558450073.898 [BPC1] Loaded
2019-05-21T14:47:53.898Z,1558450073.898 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2019-05-21T14:47:53.899Z,1558450073.899 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2019-05-21T14:47:53.899Z,1558450073.899 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2019-05-21T14:47:53.912Z,1558450073.912 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2019-05-21T14:47:53.913Z,1558450073.913 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2019-05-21T14:47:54.018Z,1558450074.018 [DeadReckonUsingMultipleVelocitySources] Loaded
2019-05-21T14:47:54.019Z,1558450074.019 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2019-05-21T14:47:54.040Z,1558450074.040 [NavChart] Loaded
2019-05-21T14:47:54.040Z,1558450074.040 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2019-05-21T14:47:54.044Z,1558450074.044 [UniversalFixResidualReporter] Loaded
2019-05-21T14:47:54.044Z,1558450074.044 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2019-05-21T14:47:54.045Z,1558450074.045 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2019-05-21T14:47:54.045Z,1558450074.045 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2019-05-21T14:47:54.153Z,1558450074.153 [BuoyancyServo] Loaded
2019-05-21T14:47:54.153Z,1558450074.153 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2019-05-21T14:47:54.169Z,1558450074.169 [ElevatorServo] Loaded
2019-05-21T14:47:54.169Z,1558450074.169 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2019-05-21T14:47:54.184Z,1558450074.184 [MassServo] Loaded
2019-05-21T14:47:54.184Z,1558450074.184 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2019-05-21T14:47:54.200Z,1558450074.200 [RudderServo] Loaded
2019-05-21T14:47:54.200Z,1558450074.200 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2019-05-21T14:47:54.215Z,1558450074.215 [ThrusterServo] Loaded
2019-05-21T14:47:54.215Z,1558450074.215 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread.
2019-05-21T14:47:54.216Z,1558450074.216 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2019-05-21T14:47:54.216Z,1558450074.216 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2019-05-21T14:47:54.467Z,1558450074.467 [CTD_NeilBrown] Loaded
2019-05-21T14:47:54.468Z,1558450074.468 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2019-05-21T14:47:54.469Z,1558450074.469 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 408D34E0
2019-05-21T14:47:54.469Z,1558450074.469 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 478
2019-05-21T14:47:54.514Z,1558450074.514 [WetLabsSeaOWL_UV_A] Loaded
2019-05-21T14:47:54.515Z,1558450074.515 [ComponentRegistry](DEBUG): Component "WetLabsSeaOWL_UV_A" handled in its own thread.
2019-05-21T14:47:54.516Z,1558450074.516 [WetLabsSeaOWL_UV_A ThreadHandler](DEBUG): Created PCaller Thread at 409034E0
2019-05-21T14:47:54.516Z,1558450074.516 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Protected caller Thread ID is 479
2019-05-21T14:47:54.517Z,1558450074.517 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2019-05-21T14:47:54.517Z,1558450074.517 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2019-05-21T14:47:54.814Z,1558450074.814 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2019-05-21T14:47:54.815Z,1558450074.815 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2019-05-21T14:47:54.856Z,1558450074.856 [DepthRateCalculator] Loaded
2019-05-21T14:47:54.857Z,1558450074.857 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2019-05-21T14:47:54.862Z,1558450074.862 [PitchRateCalculator] Loaded
2019-05-21T14:47:54.863Z,1558450074.863 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2019-05-21T14:47:54.875Z,1558450074.875 [SpeedCalculator] Loaded
2019-05-21T14:47:54.875Z,1558450074.875 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2019-05-21T14:47:54.897Z,1558450074.897 [TempGradientCalculator] Loaded
2019-05-21T14:47:54.897Z,1558450074.897 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2019-05-21T14:47:54.903Z,1558450074.903 [YawRateCalculator] Loaded
2019-05-21T14:47:54.903Z,1558450074.903 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2019-05-21T14:47:54.944Z,1558450074.944 [ElevatorOffsetCalculator] Loaded
2019-05-21T14:47:54.944Z,1558450074.944 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2019-05-21T14:47:54.945Z,1558450074.945 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2019-05-21T14:47:54.945Z,1558450074.945 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2019-05-21T14:47:55.080Z,1558450075.080 [SBIT](DEBUG): Construct Startup Built In Test.
2019-05-21T14:47:55.102Z,1558450075.102 [SBIT] Loaded
2019-05-21T14:47:55.102Z,1558450075.102 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2019-05-21T14:47:55.103Z,1558450075.103 [IBIT](DEBUG): Construct Initiated Built In Test.
2019-05-21T14:47:55.115Z,1558450075.115 [IBIT] Loaded
2019-05-21T14:47:55.115Z,1558450075.115 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2019-05-21T14:47:55.118Z,1558450075.118 [CBIT](DEBUG): Construct Continuous Built In Test.
2019-05-21T14:47:55.257Z,1558450075.257 [CBIT] Loaded
2019-05-21T14:47:55.258Z,1558450075.258 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2019-05-21T14:47:55.258Z,1558450075.258 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2019-05-21T14:47:55.259Z,1558450075.259 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2019-05-21T14:47:55.329Z,1558450075.329 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2019-05-21T14:47:55.330Z,1558450075.330 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2019-05-21T14:47:55.429Z,1558450075.429 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2019-05-21T14:47:55.430Z,1558450075.430 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2019-05-21T14:47:55.498Z,1558450075.498 [VerticalControl](DEBUG): Construct VerticalControl.
2019-05-21T14:47:55.583Z,1558450075.583 [VerticalControl] Loaded
2019-05-21T14:47:55.583Z,1558450075.583 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2019-05-21T14:47:55.584Z,1558450075.584 [HorizontalControl](DEBUG): Construct HorizontalControl.
2019-05-21T14:47:55.641Z,1558450075.641 [HorizontalControl] Loaded
2019-05-21T14:47:55.642Z,1558450075.642 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2019-05-21T14:47:55.642Z,1558450075.642 [SpeedControl](DEBUG): Construct SpeedControl.
2019-05-21T14:47:55.644Z,1558450075.644 [SpeedControl] Loaded
2019-05-21T14:47:55.644Z,1558450075.644 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2019-05-21T14:47:55.645Z,1558450075.645 [LoopControl](DEBUG): Construct LoopControl.
2019-05-21T14:47:55.645Z,1558450075.645 [LoopControl] Loaded
2019-05-21T14:47:55.646Z,1558450075.646 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2019-05-21T14:47:55.646Z,1558450075.646 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2019-05-21T14:47:55.647Z,1558450075.647 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2019-05-21T14:47:55.673Z,1558450075.673 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2019-05-21T14:47:55.677Z,1558450075.677 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2019-05-21T14:47:55.678Z,1558450075.678 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2019-05-21T14:47:55.684Z,1558450075.684 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2019-05-21T14:47:55.685Z,1558450075.685 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADA4E0
2019-05-21T14:47:55.686Z,1558450075.686 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 480
2019-05-21T14:47:55.690Z,1558450075.690 [Supervisor](INFO): Main Thread ID is 392
2019-05-21T14:47:55.690Z,1558450075.690 [Supervisor](DEBUG): Running supervisor.
2019-05-21T14:47:55.691Z,1558450075.691 [CommandLine ThreadHandler](INFO): Handler Thread ID is 481
2019-05-21T14:47:55.693Z,1558450075.693 [controlThread ThreadHandler](INFO): Handler Thread ID is 482
2019-05-21T14:47:55.693Z,1558450075.693 [controlThread](DEBUG): Initializing ControlThread
2019-05-21T14:47:55.700Z,1558450075.700 [NavChart](DEBUG): Initialize NavChart Navigation.
2019-05-21T14:47:55.700Z,1558450075.700 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2019-05-21T14:47:55.702Z,1558450075.702 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2019-05-21T14:47:55.702Z,1558450075.702 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2019-05-21T14:47:55.702Z,1558450075.702 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2019-05-21T14:47:55.702Z,1558450075.702 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2019-05-21T14:47:55.703Z,1558450075.703 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2019-05-21T14:47:55.703Z,1558450075.703 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2019-05-21T14:47:55.704Z,1558450075.704 [SBIT](INFO): Initialize SBIT Component.
2019-05-21T14:47:55.704Z,1558450075.704 [SBIT](IMPORTANT): git: 2019-05-01-9-g5be6d91
2019-05-21T14:47:55.704Z,1558450075.704 [SBIT](INFO): git hash: 5be6d91bfd1d3ef858080230e47d423d1f938b96
2019-05-21T14:47:55.705Z,1558450075.705 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2019-05-21T14:47:55.706Z,1558450075.706 [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 Feb 21 11:17:40 PST 2019
2019-05-21T14:47:55.707Z,1558450075.707 [SBIT](INFO): Beginning SBIT in 52.000000 seconds.
2019-05-21T14:47:55.708Z,1558450075.708 [IBIT](INFO): Initialize IBIT Component.
2019-05-21T14:47:55.708Z,1558450075.708 [CBIT](DEBUG): Initialize CBIT Component.
2019-05-21T14:47:55.710Z,1558450075.710 [logger ThreadHandler](INFO): Handler Thread ID is 483
2019-05-21T14:47:55.721Z,1558450075.721 [CBIT](DEBUG): Initialized mux pins.
2019-05-21T14:47:55.721Z,1558450075.721 [CBIT](DEBUG): Initializing the watchdog timer.
2019-05-21T14:47:55.729Z,1558450075.729 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 484
2019-05-21T14:47:55.730Z,1558450075.730 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2019-05-21T14:47:55.741Z,1558450075.741 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 485
2019-05-21T14:47:55.745Z,1558450075.745 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2019-05-21T14:47:55.745Z,1558450075.745 [CBIT](DEBUG): Initializing heartbeat.
2019-05-21T14:47:55.753Z,1558450075.753 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 486
2019-05-21T14:47:55.754Z,1558450075.754 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:47:55.773Z,1558450075.773 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Handler Thread ID is 487
2019-05-21T14:47:55.774Z,1558450075.774 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:47:55.812Z,1558450075.812 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 488
2019-05-21T14:47:55.815Z,1558450075.815 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2019-05-21T14:47:55.815Z,1558450075.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2019-05-21T14:47:55.815Z,1558450075.815 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2019-05-21T14:47:55.815Z,1558450075.815 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2019-05-21T14:47:55.816Z,1558450075.816 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2019-05-21T14:47:55.816Z,1558450075.816 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2019-05-21T14:47:55.816Z,1558450075.816 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2019-05-21T14:47:55.816Z,1558450075.816 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2019-05-21T14:47:55.816Z,1558450075.816 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2019-05-21T14:47:55.817Z,1558450075.817 [CBIT](DEBUG): Deactivating GF circuits.
2019-05-21T14:47:55.817Z,1558450075.817 [CBIT](DEBUG): Deactivating emergency mode.
2019-05-21T14:47:55.817Z,1558450075.817 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2019-05-21T14:47:55.817Z,1558450075.817 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2019-05-21T14:47:55.818Z,1558450075.818 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2019-05-21T14:47:55.818Z,1558450075.818 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2019-05-21T14:47:55.818Z,1558450075.818 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2019-05-21T14:47:55.818Z,1558450075.818 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2019-05-21T14:47:55.818Z,1558450075.818 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2019-05-21T14:47:55.853Z,1558450075.853 [CBIT](DEBUG): Backplane powered.
2019-05-21T14:47:55.853Z,1558450075.853 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2019-05-21T14:47:55.855Z,1558450075.855 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2019-05-21T14:47:55.855Z,1558450075.855 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2019-05-21T14:47:55.856Z,1558450075.856 [LoopControl](DEBUG): Initialize LoopControlComponent.
2019-05-21T14:47:55.857Z,1558450075.857 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2019-05-21T14:47:55.866Z,1558450075.866 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:47:55.889Z,1558450075.889 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns="Tethys"
       xmlns:Control="Tethys/Control"
       xmlns:Guidance="Tethys/Guidance" 
       xmlns:Units="Tethys/Units"
       xmlns:Universal="Tethys/Universal"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                           Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd
                           Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                           Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                           Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
       Id="Startup">

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

    <Aggregate Id="StartupSatComms">

        <Sequence/>

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

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

    </Aggregate>

</Mission>


2019-05-21T14:47:55.890Z,1558450075.890 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2019-05-21T14:47:55.966Z,1558450075.966 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2019-05-21T14:47:55.967Z,1558450075.967 [Default:A.Wait](DEBUG): Construct Wait.
2019-05-21T14:47:55.969Z,1558450075.969 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2019-05-21T14:47:56.003Z,1558450076.003 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2019-05-21T14:47:56.022Z,1558450076.022 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2019-05-21T14:47:56.027Z,1558450076.027 [Default:E.Execute](DEBUG): Construct Execute.
2019-05-21T14:47:56.047Z,1558450076.047 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Universal="Tethys/Universal"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Universal http://okeanids.mbari.org/tethys/Xml/Universal.xsd"
         Id="Default">

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

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

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

    <Aggregate Id="CheckIn">

        <Sequence Repeat="288"/>

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

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

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

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

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

    </Aggregate>

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

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

</Mission>


2019-05-21T14:47:56.051Z,1558450076.051 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,Depth_Keller,DropWeight,DUSBL_Hydroid,Micromodem,NAL9602,Onboard,PowerOnly,RDI_Pathfinder,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-05-21T14:47:56.073Z,1558450076.073 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2019-05-21T14:47:56.103Z,1558450076.103 [Depth_Keller](ERROR): Pressure reading out of range: 1913.424561 decibar
2019-05-21T14:47:56.104Z,1558450076.104 [DUSBL_Hydroid](INFO): Powering up
2019-05-21T14:47:56.105Z,1558450076.105 [DUSBL_Hydroid](DEBUG): Initializing DUSBL_Hydroid.
2019-05-21T14:47:56.125Z,1558450076.125 [Micromodem](INFO): Start
2019-05-21T14:47:56.145Z,1558450076.145 [Radio_Surface](INFO): Powering up
2019-05-21T14:47:56.194Z,1558450076.194 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:47:56.261Z,1558450076.261 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:56.281Z,1558450076.281 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2019-05-21T14:47:56.282Z,1558450076.282 [ElevatorServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:56.293Z,1558450076.293 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2019-05-21T14:47:56.294Z,1558450076.294 [MassServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:56.305Z,1558450076.305 [MassServo](DEBUG): Initializing MassServo.
2019-05-21T14:47:56.306Z,1558450076.306 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:56.313Z,1558450076.313 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-21T14:47:56.314Z,1558450076.314 [ThrusterServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:56.321Z,1558450076.321 [ThrusterServo](DEBUG): Initializing ThrusterServo.
2019-05-21T14:47:56.474Z,1558450076.474 [Micromodem](INFO): Starting
2019-05-21T14:47:56.475Z,1558450076.475 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:56.475Z,1558450076.475 [Micromodem](INFO): Powering up
2019-05-21T14:47:56.476Z,1558450076.476 [Micromodem](DEBUG): Initializing Micromodem.
2019-05-21T14:47:56.509Z,1558450076.509 [DepthRateCalculator](ERROR): Depth measurement is not active
2019-05-21T14:47:56.871Z,1558450076.871 [Micromodem](INFO): Starting
2019-05-21T14:47:56.872Z,1558450076.872 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:57.233Z,1558450077.233 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2019-05-21T14:47:57.233Z,1558450077.233 [RudderServo](FAULT): Rudder failed to initialize
2019-05-21T14:47:57.233Z,1558450077.233 [RudderServo] Communications Fault, FailCount= 1
2019-05-21T14:47:57.233Z,1558450077.233 [RudderServo](ERROR): Communications Fault
2019-05-21T14:47:57.344Z,1558450077.344 [CBIT](ERROR): Communications Fault in component: RudderServo
2019-05-21T14:47:57.354Z,1558450077.354 [Micromodem](INFO): Starting
2019-05-21T14:47:57.355Z,1558450077.355 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:57.530Z,1558450077.530 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-21T14:47:57.530Z,1558450077.530 [RudderServo](INFO): Powering down
2019-05-21T14:47:57.758Z,1558450077.758 [Micromodem](INFO): Starting
2019-05-21T14:47:57.759Z,1558450077.759 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:58.162Z,1558450078.162 [Micromodem](INFO): Starting
2019-05-21T14:47:58.163Z,1558450078.163 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:58.189Z,1558450078.189 [RudderServo](DEBUG): Initializing EZServoServo.
2019-05-21T14:47:58.310Z,1558450078.310 [RudderServo](DEBUG): Initializing RudderServo.
2019-05-21T14:47:58.314Z,1558450078.314 [CBIT](INFO): Clearing failed state for component RudderServo
2019-05-21T14:47:58.314Z,1558450078.314 [RudderServo] No Fault, FailCount= 1
2019-05-21T14:47:58.578Z,1558450078.578 [Micromodem](INFO): Starting
2019-05-21T14:47:58.579Z,1558450078.579 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:58.970Z,1558450078.970 [Micromodem](INFO): Starting
2019-05-21T14:47:58.971Z,1558450078.971 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:59.439Z,1558450079.439 [Micromodem](INFO): Starting
2019-05-21T14:47:59.439Z,1558450079.439 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:47:59.802Z,1558450079.802 [Micromodem](INFO): Starting
2019-05-21T14:47:59.803Z,1558450079.803 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:00.218Z,1558450080.218 [Micromodem](INFO): Starting
2019-05-21T14:48:00.219Z,1558450080.219 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:00.674Z,1558450080.674 [Micromodem](INFO): Starting
2019-05-21T14:48:00.676Z,1558450080.676 [Micromodem](INFO): Nmea in: $CAREV,144759,INIT,2.0.27690*47

2019-05-21T14:48:00.676Z,1558450080.676 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:01.026Z,1558450081.026 [Micromodem](INFO): Starting
2019-05-21T14:48:01.028Z,1558450081.028 [Micromodem](INFO): Nmea in: $CAREV,144759,SLOT1,2.0.27690*68

2019-05-21T14:48:01.028Z,1558450081.028 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:01.430Z,1558450081.430 [Micromodem](INFO): Starting
2019-05-21T14:48:01.431Z,1558450081.431 [Micromodem](INFO): Nmea in: $CAREV,144759,AUV,2.0.27690*1F

2019-05-21T14:48:01.432Z,1558450081.432 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:01.432Z,1558450081.432 [Micromodem](INFO): Starting
2019-05-21T14:48:01.433Z,1558450081.433 [Micromodem](INFO): Nmea in: $CAREV,144759,COPROC,0.10.0.46*4A

2019-05-21T14:48:01.433Z,1558450081.433 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:01.434Z,1558450081.434 [Micromodem](DEBUG): Nmea buf: $CCCFG,ALL,0*33

2019-05-21T14:48:01.434Z,1558450081.434 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:01.434Z,1558450081.434 [Micromodem](INFO): Nmea out: $CCCFG,ALL,0*33

2019-05-21T14:48:01.435Z,1558450081.435 [Micromodem](DEBUG): Nmea buf: $CCCFG,SRC,1*31

2019-05-21T14:48:01.435Z,1558450081.435 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.000438
2019-05-21T14:48:01.435Z,1558450081.435 [Micromodem](DEBUG): Nmea buf: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-21T14:48:01.436Z,1558450081.436 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.001133
2019-05-21T14:48:01.436Z,1558450081.436 [Micromodem](DEBUG): Nmea buf: $CCCFG,BND,1*3B

2019-05-21T14:48:01.436Z,1558450081.436 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.001754
2019-05-21T14:48:01.834Z,1558450081.834 [Micromodem](INFO): Starting
2019-05-21T14:48:01.836Z,1558450081.836 [Micromodem](INFO): Nmea in: $CATMG,2019-05-21T14:47:59Z,RTC,RTC*78

2019-05-21T14:48:01.836Z,1558450081.836 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.401480
2019-05-21T14:48:02.238Z,1558450082.238 [Micromodem](INFO): Starting
2019-05-21T14:48:02.239Z,1558450082.239 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.804328
2019-05-21T14:48:02.642Z,1558450082.642 [Micromodem](INFO): Starting
2019-05-21T14:48:02.643Z,1558450082.643 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.208416
2019-05-21T14:48:03.046Z,1558450083.046 [Micromodem](INFO): Starting
2019-05-21T14:48:03.047Z,1558450083.047 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.612432
2019-05-21T14:48:03.450Z,1558450083.450 [Micromodem](INFO): Starting
2019-05-21T14:48:03.451Z,1558450083.451 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.016323
2019-05-21T14:48:03.862Z,1558450083.862 [Micromodem](INFO): Starting
2019-05-21T14:48:03.863Z,1558450083.863 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.428316
2019-05-21T14:48:04.246Z,1558450084.246 [Micromodem](INFO): Starting
2019-05-21T14:48:04.247Z,1558450084.247 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.812416
2019-05-21T14:48:04.654Z,1558450084.654 [Micromodem](INFO): Starting
2019-05-21T14:48:04.655Z,1558450084.655 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.220431
2019-05-21T14:48:05.042Z,1558450085.042 [Micromodem](INFO): Starting
2019-05-21T14:48:05.043Z,1558450085.043 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.608399
2019-05-21T14:48:05.455Z,1558450085.455 [Micromodem](INFO): Starting
2019-05-21T14:48:05.456Z,1558450085.456 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.021453
2019-05-21T14:48:05.858Z,1558450085.858 [Micromodem](INFO): Starting
2019-05-21T14:48:05.859Z,1558450085.859 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.424410
2019-05-21T14:48:06.250Z,1558450086.250 [Micromodem](INFO): Starting
2019-05-21T14:48:06.251Z,1558450086.251 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.816436
2019-05-21T14:48:06.659Z,1558450086.659 [Micromodem](INFO): Starting
2019-05-21T14:48:06.660Z,1558450086.660 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.225132
2019-05-21T14:48:07.050Z,1558450087.050 [Micromodem](INFO): Starting
2019-05-21T14:48:07.051Z,1558450087.051 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.616281
2019-05-21T14:48:07.454Z,1558450087.454 [Micromodem](INFO): Starting
2019-05-21T14:48:07.455Z,1558450087.455 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.020322
2019-05-21T14:48:07.626Z,1558450087.626 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004418
2019-05-21T14:48:07.863Z,1558450087.863 [Micromodem](INFO): Starting
2019-05-21T14:48:07.863Z,1558450087.863 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.428683
2019-05-21T14:48:08.262Z,1558450088.262 [Micromodem](INFO): Starting
2019-05-21T14:48:08.263Z,1558450088.263 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.828223
2019-05-21T14:48:08.666Z,1558450088.666 [Micromodem](INFO): Starting
2019-05-21T14:48:08.667Z,1558450088.667 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.232193
2019-05-21T14:48:09.070Z,1558450089.070 [Micromodem](INFO): Starting
2019-05-21T14:48:09.071Z,1558450089.071 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.636316
2019-05-21T14:48:09.474Z,1558450089.474 [Micromodem](INFO): Starting
2019-05-21T14:48:09.475Z,1558450089.475 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.040441
2019-05-21T14:48:09.501Z,1558450089.501 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder
2019-05-21T14:48:09.878Z,1558450089.878 [Micromodem](INFO): Starting
2019-05-21T14:48:09.879Z,1558450089.879 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.444341
2019-05-21T14:48:10.302Z,1558450090.302 [Micromodem](INFO): Starting
2019-05-21T14:48:10.303Z,1558450090.303 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.868265
2019-05-21T14:48:10.686Z,1558450090.686 [Micromodem](INFO): Starting
2019-05-21T14:48:10.687Z,1558450090.687 [Micromodem](INFO): Nmea in: $CACFG,ALL,0*31

2019-05-21T14:48:10.688Z,1558450090.688 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:10.688Z,1558450090.688 [Micromodem](INFO): Nmea out: $CCCFG,SRC,1*31

2019-05-21T14:48:11.090Z,1558450091.090 [Micromodem](INFO): Starting
2019-05-21T14:48:11.091Z,1558450091.091 [Micromodem](INFO): Nmea in: $CAREV,144809,AUV,2.0.27690*15

2019-05-21T14:48:11.092Z,1558450091.092 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.403712
2019-05-21T14:48:11.494Z,1558450091.494 [Micromodem](INFO): Starting
2019-05-21T14:48:11.495Z,1558450091.495 [Micromodem](INFO): Nmea in: $CAREV,144809,COPROC,0.10.0.46*40

2019-05-21T14:48:11.496Z,1558450091.496 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.807651
2019-05-21T14:48:11.899Z,1558450091.899 [Micromodem](INFO): Starting
2019-05-21T14:48:11.899Z,1558450091.899 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.210925
2019-05-21T14:48:12.302Z,1558450092.302 [Micromodem](INFO): Starting
2019-05-21T14:48:12.303Z,1558450092.303 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.614798
2019-05-21T14:48:12.706Z,1558450092.706 [Micromodem](INFO): Starting
2019-05-21T14:48:12.707Z,1558450092.707 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.018785
2019-05-21T14:48:13.110Z,1558450093.110 [Micromodem](INFO): Starting
2019-05-21T14:48:13.111Z,1558450093.111 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.422893
2019-05-21T14:48:13.516Z,1558450093.516 [Micromodem](INFO): Starting
2019-05-21T14:48:13.516Z,1558450093.516 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.828079
2019-05-21T14:48:13.923Z,1558450093.923 [Micromodem](INFO): Starting
2019-05-21T14:48:13.923Z,1558450093.923 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.235308
2019-05-21T14:48:14.327Z,1558450094.327 [DUSBL_Hydroid](INFO): DUSBL Version:O
2019-05-21T14:48:14.342Z,1558450094.342 [Micromodem](INFO): Starting
2019-05-21T14:48:14.342Z,1558450094.342 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.654008
2019-05-21T14:48:14.727Z,1558450094.727 [Micromodem](INFO): Starting
2019-05-21T14:48:14.727Z,1558450094.727 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.039164
2019-05-21T14:48:15.135Z,1558450095.135 [Micromodem](INFO): Starting
2019-05-21T14:48:15.135Z,1558450095.135 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.447273
2019-05-21T14:48:15.534Z,1558450095.534 [Micromodem](INFO): Starting
2019-05-21T14:48:15.535Z,1558450095.535 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.846664
2019-05-21T14:48:15.938Z,1558450095.938 [Micromodem](INFO): Starting
2019-05-21T14:48:15.939Z,1558450095.939 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.250555
2019-05-21T14:48:16.347Z,1558450096.347 [Micromodem](INFO): Starting
2019-05-21T14:48:16.347Z,1558450096.347 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.658997
2019-05-21T14:48:16.746Z,1558450096.746 [Micromodem](INFO): Starting
2019-05-21T14:48:16.747Z,1558450096.747 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.058754
2019-05-21T14:48:17.150Z,1558450097.150 [Micromodem](INFO): Starting
2019-05-21T14:48:17.151Z,1558450097.151 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.462546
2019-05-21T14:48:17.558Z,1558450097.558 [Micromodem](INFO): Starting
2019-05-21T14:48:17.559Z,1558450097.559 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.870912
2019-05-21T14:48:17.958Z,1558450097.958 [Micromodem](INFO): Starting
2019-05-21T14:48:17.959Z,1558450097.959 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.270470
2019-05-21T14:48:18.362Z,1558450098.362 [Micromodem](INFO): Starting
2019-05-21T14:48:18.363Z,1558450098.363 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.674440
2019-05-21T14:48:18.778Z,1558450098.778 [Micromodem](INFO): Starting
2019-05-21T14:48:18.779Z,1558450098.779 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.090614
2019-05-21T14:48:19.170Z,1558450099.170 [Micromodem](INFO): Starting
2019-05-21T14:48:19.171Z,1558450099.171 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.482689
2019-05-21T14:48:19.574Z,1558450099.574 [Micromodem](INFO): Starting
2019-05-21T14:48:19.575Z,1558450099.575 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.886546
2019-05-21T14:48:19.982Z,1558450099.982 [Micromodem](INFO): Starting
2019-05-21T14:48:19.983Z,1558450099.983 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.294906
2019-05-21T14:48:20.391Z,1558450100.391 [Micromodem](INFO): Starting
2019-05-21T14:48:20.392Z,1558450100.392 [Micromodem](INFO): Nmea in: $CACFG,SRC,1*33

2019-05-21T14:48:20.393Z,1558450100.393 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:20.394Z,1558450100.394 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-21T14:48:20.786Z,1558450100.786 [Micromodem](INFO): Starting
2019-05-21T14:48:20.787Z,1558450100.787 [Micromodem](INFO): Nmea in: $CAREV,144819,AUV,2.0.27690*14

2019-05-21T14:48:20.788Z,1558450100.788 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.393185
2019-05-21T14:48:21.190Z,1558450101.190 [Micromodem](INFO): Starting
2019-05-21T14:48:21.191Z,1558450101.191 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.796362
2019-05-21T14:48:21.594Z,1558450101.594 [Micromodem](INFO): Starting
2019-05-21T14:48:21.595Z,1558450101.595 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.200470
2019-05-21T14:48:21.998Z,1558450101.998 [Micromodem](INFO): Starting
2019-05-21T14:48:21.999Z,1558450101.999 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.604368
2019-05-21T14:48:22.402Z,1558450102.402 [Micromodem](INFO): Starting
2019-05-21T14:48:22.403Z,1558450102.403 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.008359
2019-05-21T14:48:22.404Z,1558450102.404 [NAL9602](INFO): Powering up NAL9602
2019-05-21T14:48:22.806Z,1558450102.806 [Micromodem](INFO): Starting
2019-05-21T14:48:22.807Z,1558450102.807 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.412481
2019-05-21T14:48:23.210Z,1558450103.210 [Micromodem](INFO): Starting
2019-05-21T14:48:23.211Z,1558450103.211 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.816155
2019-05-21T14:48:23.614Z,1558450103.614 [Micromodem](INFO): Starting
2019-05-21T14:48:23.615Z,1558450103.615 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.220361
2019-05-21T14:48:24.018Z,1558450104.018 [Micromodem](INFO): Starting
2019-05-21T14:48:24.019Z,1558450104.019 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.624468
2019-05-21T14:48:24.434Z,1558450104.434 [Micromodem](INFO): Starting
2019-05-21T14:48:24.435Z,1558450104.435 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.040359
2019-05-21T14:48:24.831Z,1558450104.831 [Micromodem](INFO): Starting
2019-05-21T14:48:24.831Z,1558450104.831 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.436895
2019-05-21T14:48:25.230Z,1558450105.230 [Micromodem](INFO): Starting
2019-05-21T14:48:25.231Z,1558450105.231 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.836499
2019-05-21T14:48:25.639Z,1558450105.639 [Micromodem](INFO): Starting
2019-05-21T14:48:25.639Z,1558450105.639 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.245115
2019-05-21T14:48:26.038Z,1558450106.038 [Micromodem](INFO): Starting
2019-05-21T14:48:26.039Z,1558450106.039 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.644241
2019-05-21T14:48:26.473Z,1558450106.473 [Micromodem](INFO): Starting
2019-05-21T14:48:26.473Z,1558450106.473 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.079108
2019-05-21T14:48:26.846Z,1558450106.846 [Micromodem](INFO): Starting
2019-05-21T14:48:26.847Z,1558450106.847 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.452169
2019-05-21T14:48:27.250Z,1558450107.250 [Micromodem](INFO): Starting
2019-05-21T14:48:27.251Z,1558450107.251 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.856363
2019-05-21T14:48:27.659Z,1558450107.659 [Micromodem](INFO): Starting
2019-05-21T14:48:27.659Z,1558450107.659 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.264895
2019-05-21T14:48:28.058Z,1558450108.058 [Micromodem](INFO): Starting
2019-05-21T14:48:28.059Z,1558450108.059 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.664371
2019-05-21T14:48:28.462Z,1558450108.462 [Micromodem](INFO): Starting
2019-05-21T14:48:28.463Z,1558450108.463 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.068372
2019-05-21T14:48:28.866Z,1558450108.866 [Micromodem](INFO): Starting
2019-05-21T14:48:28.867Z,1558450108.867 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.472477
2019-05-21T14:48:29.292Z,1558450109.292 [Micromodem](INFO): Starting
2019-05-21T14:48:29.294Z,1558450109.294 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.899261
2019-05-21T14:48:29.674Z,1558450109.674 [Micromodem](INFO): Starting
2019-05-21T14:48:29.675Z,1558450109.675 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.280378
2019-05-21T14:48:30.078Z,1558450110.078 [Micromodem](INFO): Starting
2019-05-21T14:48:30.079Z,1558450110.079 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.684469
2019-05-21T14:48:30.482Z,1558450110.482 [Micromodem](INFO): Starting
2019-05-21T14:48:30.484Z,1558450110.484 [Micromodem](INFO): Nmea in: $CAREV,144819,COPROC,0.10.0.4641
$CACFG,nav.dt.txtrig_gpio4,1*66

2019-05-21T14:48:30.484Z,1558450110.484 [Micromodem](ERROR): Response from modem failed NMEA checksum: $CAREV,144819,COPROC,0.10.0.4641
$CACFG,nav.dt.txtrig_gpio4,1*66

2019-05-21T14:48:30.490Z,1558450110.490 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:30.490Z,1558450110.490 [Micromodem](INFO): Nmea out: $CCCFG,nav.dt.txtrig_gpio4,1*64

2019-05-21T14:48:30.886Z,1558450110.886 [Micromodem](INFO): Starting
2019-05-21T14:48:30.887Z,1558450110.887 [Micromodem](INFO): Nmea in: $CAREV,144829,AUV,2.0.27690*17

2019-05-21T14:48:30.888Z,1558450110.888 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.396587
2019-05-21T14:48:31.299Z,1558450111.299 [Micromodem](INFO): Starting
2019-05-21T14:48:31.300Z,1558450111.300 [Micromodem](INFO): Nmea in: $CAREV,144829,COPROC,0.10.0.46*42

2019-05-21T14:48:31.300Z,1558450111.300 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.809110
2019-05-21T14:48:31.694Z,1558450111.694 [Micromodem](INFO): Starting
2019-05-21T14:48:31.695Z,1558450111.695 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.203619
2019-05-21T14:48:32.098Z,1558450112.098 [Micromodem](INFO): Starting
2019-05-21T14:48:32.099Z,1558450112.099 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.607615
2019-05-21T14:48:32.502Z,1558450112.502 [Micromodem](INFO): Starting
2019-05-21T14:48:32.503Z,1558450112.503 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.011530
2019-05-21T14:48:32.913Z,1558450112.913 [Micromodem](INFO): Starting
2019-05-21T14:48:32.914Z,1558450112.914 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.422843
2019-05-21T14:48:33.310Z,1558450113.310 [Micromodem](INFO): Starting
2019-05-21T14:48:33.311Z,1558450113.311 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.819603
2019-05-21T14:48:33.312Z,1558450113.312 [NAL9602](INFO): NAL9602 initialized
2019-05-21T14:48:33.714Z,1558450113.714 [Micromodem](INFO): Starting
2019-05-21T14:48:33.715Z,1558450113.715 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.223707
2019-05-21T14:48:34.118Z,1558450114.118 [Micromodem](INFO): Starting
2019-05-21T14:48:34.119Z,1558450114.119 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.627645
2019-05-21T14:48:34.133Z,1558450114.133 [NAL9602](DEBUG): Fix Requested
2019-05-21T14:48:34.526Z,1558450114.526 [Micromodem](INFO): Starting
2019-05-21T14:48:34.527Z,1558450114.527 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.035604
2019-05-21T14:48:34.930Z,1558450114.930 [Micromodem](INFO): Starting
2019-05-21T14:48:34.931Z,1558450114.931 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.439480
2019-05-21T14:48:35.348Z,1558450115.348 [Micromodem](INFO): Starting
2019-05-21T14:48:35.350Z,1558450115.350 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.858795
2019-05-21T14:48:35.746Z,1558450115.746 [Micromodem](INFO): Starting
2019-05-21T14:48:35.747Z,1558450115.747 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.255720
2019-05-21T14:48:36.142Z,1558450116.142 [Micromodem](INFO): Starting
2019-05-21T14:48:36.143Z,1558450116.143 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.651526
2019-05-21T14:48:36.542Z,1558450116.542 [Micromodem](INFO): Starting
2019-05-21T14:48:36.543Z,1558450116.543 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.051415
2019-05-21T14:48:36.946Z,1558450116.946 [Micromodem](INFO): Starting
2019-05-21T14:48:36.947Z,1558450116.947 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.455628
2019-05-21T14:48:37.350Z,1558450117.350 [Micromodem](INFO): Starting
2019-05-21T14:48:37.351Z,1558450117.351 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.859721
2019-05-21T14:48:37.754Z,1558450117.754 [Micromodem](INFO): Starting
2019-05-21T14:48:37.755Z,1558450117.755 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.263622
2019-05-21T14:48:38.158Z,1558450118.158 [Micromodem](INFO): Starting
2019-05-21T14:48:38.159Z,1558450118.159 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.667434
2019-05-21T14:48:38.562Z,1558450118.562 [Micromodem](INFO): Starting
2019-05-21T14:48:38.563Z,1558450118.563 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.071515
2019-05-21T14:48:38.966Z,1558450118.966 [Micromodem](INFO): Starting
2019-05-21T14:48:38.967Z,1558450118.967 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.475628
2019-05-21T14:48:39.374Z,1558450119.374 [Micromodem](INFO): Starting
2019-05-21T14:48:39.375Z,1558450119.375 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.883410
2019-05-21T14:48:39.793Z,1558450119.793 [Micromodem](INFO): Starting
2019-05-21T14:48:39.794Z,1558450119.794 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.302850
2019-05-21T14:48:40.178Z,1558450120.178 [Micromodem](INFO): Starting
2019-05-21T14:48:40.179Z,1558450120.179 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.687621
2019-05-21T14:48:40.595Z,1558450120.595 [Micromodem](INFO): Starting
2019-05-21T14:48:40.596Z,1558450120.596 [Micromodem](INFO): Nmea in: $CACFG,nav.dt.txtrig_gpio4,1*66

2019-05-21T14:48:40.596Z,1558450120.596 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:40.596Z,1558450120.596 [Micromodem](INFO): Nmea out: $CCCFG,BND,1*3B

2019-05-21T14:48:40.991Z,1558450120.991 [Micromodem](INFO): Starting
2019-05-21T14:48:40.992Z,1558450120.992 [Micromodem](INFO): Nmea in: $CAREV,144839,AUV,2.0.27690*16

2019-05-21T14:48:40.992Z,1558450120.992 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.395124
2019-05-21T14:48:41.398Z,1558450121.398 [Micromodem](INFO): Starting
2019-05-21T14:48:41.399Z,1558450121.399 [Micromodem](INFO): Nmea in: $CAREV,144839,COPROC,0.10.0.46*43

2019-05-21T14:48:41.400Z,1558450121.400 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 0.802388
2019-05-21T14:48:41.798Z,1558450121.798 [Micromodem](INFO): Starting
2019-05-21T14:48:41.799Z,1558450121.799 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.201482
2019-05-21T14:48:42.202Z,1558450122.202 [Micromodem](INFO): Starting
2019-05-21T14:48:42.203Z,1558450122.203 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 1.605665
2019-05-21T14:48:42.602Z,1558450122.602 [Micromodem](INFO): Starting
2019-05-21T14:48:42.603Z,1558450122.603 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.005578
2019-05-21T14:48:43.006Z,1558450123.006 [Micromodem](INFO): Starting
2019-05-21T14:48:43.007Z,1558450123.007 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.409581
2019-05-21T14:48:43.410Z,1558450123.410 [Micromodem](INFO): Starting
2019-05-21T14:48:43.411Z,1558450123.411 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 2.813658
2019-05-21T14:48:43.814Z,1558450123.814 [Micromodem](INFO): Starting
2019-05-21T14:48:43.815Z,1558450123.815 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.217562
2019-05-21T14:48:44.218Z,1558450124.218 [Micromodem](INFO): Starting
2019-05-21T14:48:44.219Z,1558450124.219 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 3.621387
2019-05-21T14:48:44.622Z,1558450124.622 [Micromodem](INFO): Starting
2019-05-21T14:48:44.623Z,1558450124.623 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.025664
2019-05-21T14:48:45.026Z,1558450125.026 [Micromodem](INFO): Starting
2019-05-21T14:48:45.027Z,1558450125.027 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.429562
2019-05-21T14:48:45.430Z,1558450125.430 [Micromodem](INFO): Starting
2019-05-21T14:48:45.431Z,1558450125.431 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 4.833358
2019-05-21T14:48:45.842Z,1558450125.842 [Micromodem](INFO): Starting
2019-05-21T14:48:45.843Z,1558450125.843 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.245658
2019-05-21T14:48:46.238Z,1558450126.238 [Micromodem](INFO): Starting
2019-05-21T14:48:46.239Z,1558450126.239 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 5.641558
2019-05-21T14:48:46.646Z,1558450126.646 [Micromodem](INFO): Starting
2019-05-21T14:48:46.646Z,1558450126.647 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.049358
2019-05-21T14:48:47.046Z,1558450127.046 [Micromodem](INFO): Starting
2019-05-21T14:48:47.047Z,1558450127.047 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.449472
2019-05-21T14:48:47.450Z,1558450127.450 [Micromodem](INFO): Starting
2019-05-21T14:48:47.451Z,1558450127.451 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 6.853558
2019-05-21T14:48:47.854Z,1558450127.854 [Micromodem](INFO): Starting
2019-05-21T14:48:47.855Z,1558450127.855 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.257577
2019-05-21T14:48:48.258Z,1558450128.258 [Micromodem](INFO): Starting
2019-05-21T14:48:48.259Z,1558450128.259 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 7.661667
2019-05-21T14:48:48.287Z,1558450128.287 [SBIT](IMPORTANT): Beginning Startup BIT
2019-05-21T14:48:48.295Z,1558450128.295 [CBIT](IMPORTANT): Beginning ground fault scan
2019-05-21T14:48:48.662Z,1558450128.662 [Micromodem](INFO): Starting
2019-05-21T14:48:48.663Z,1558450128.663 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.065382
2019-05-21T14:48:49.079Z,1558450129.079 [Micromodem](INFO): Starting
2019-05-21T14:48:49.079Z,1558450129.079 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.482188
2019-05-21T14:48:49.470Z,1558450129.470 [Micromodem](INFO): Starting
2019-05-21T14:48:49.471Z,1558450129.471 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 8.873466
2019-05-21T14:48:49.874Z,1558450129.874 [Micromodem](INFO): Starting
2019-05-21T14:48:49.875Z,1558450129.875 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.277547
2019-05-21T14:48:50.299Z,1558450130.299 [Micromodem](INFO): Starting
2019-05-21T14:48:50.300Z,1558450130.300 [Micromodem](INFO): outbuffer_.isEmpty() = 0, cmdSentTime_.elapsed() = 9.702826
2019-05-21T14:48:50.682Z,1558450130.682 [Micromodem](INFO): Starting
2019-05-21T14:48:50.683Z,1558450130.683 [Micromodem](INFO): Nmea in: $CACFG,BND,1*39

2019-05-21T14:48:50.683Z,1558450130.683 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:51.285Z,1558450131.285 [Micromodem](INFO): Starting
2019-05-21T14:48:51.288Z,1558450131.288 [Micromodem](INFO): Nmea in: $CAREV,144849,AUV,2.0.27690*11

2019-05-21T14:48:51.289Z,1558450131.289 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:51.630Z,1558450131.630 [Micromodem](INFO): Starting
2019-05-21T14:48:51.630Z,1558450131.630 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:52.042Z,1558450132.042 [Micromodem](INFO): Starting
2019-05-21T14:48:52.043Z,1558450132.043 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:52.438Z,1558450132.438 [Micromodem](INFO): Starting
2019-05-21T14:48:52.438Z,1558450132.438 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:52.842Z,1558450132.842 [Micromodem](INFO): Starting
2019-05-21T14:48:52.842Z,1558450132.842 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:53.261Z,1558450133.261 [Micromodem](INFO): Starting
2019-05-21T14:48:53.262Z,1558450133.262 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:53.656Z,1558450133.656 [Micromodem](INFO): Starting
2019-05-21T14:48:53.656Z,1558450133.656 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:54.054Z,1558450134.054 [Micromodem](INFO): Starting
2019-05-21T14:48:54.054Z,1558450134.054 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:54.458Z,1558450134.458 [Micromodem](INFO): Starting
2019-05-21T14:48:54.458Z,1558450134.458 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:54.862Z,1558450134.862 [Micromodem](INFO): Starting
2019-05-21T14:48:54.863Z,1558450134.863 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:55.266Z,1558450135.266 [Micromodem](INFO): Starting
2019-05-21T14:48:55.266Z,1558450135.266 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:55.670Z,1558450135.670 [Micromodem](INFO): Starting
2019-05-21T14:48:55.670Z,1558450135.670 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:56.074Z,1558450136.074 [Micromodem](INFO): Starting
2019-05-21T14:48:56.074Z,1558450136.074 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:56.486Z,1558450136.486 [Micromodem](INFO): Starting
2019-05-21T14:48:56.487Z,1558450136.487 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:56.886Z,1558450136.886 [Micromodem](INFO): Starting
2019-05-21T14:48:56.887Z,1558450136.887 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:57.294Z,1558450137.294 [Micromodem](INFO): Starting
2019-05-21T14:48:57.295Z,1558450137.295 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:57.694Z,1558450137.694 [Micromodem](INFO): Starting
2019-05-21T14:48:57.695Z,1558450137.695 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:58.098Z,1558450138.098 [Micromodem](INFO): Starting
2019-05-21T14:48:58.099Z,1558450138.099 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:58.498Z,1558450138.498 [Micromodem](INFO): Starting
2019-05-21T14:48:58.499Z,1558450138.499 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:58.906Z,1558450138.906 [Micromodem](INFO): Starting
2019-05-21T14:48:58.907Z,1558450138.907 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:59.315Z,1558450139.315 [Micromodem](INFO): Starting
2019-05-21T14:48:59.315Z,1558450139.315 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:48:59.401Z,1558450139.401 [CBIT](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.010091
CHAN A1 (24V): -0.028675
CHAN A2 (12V): -0.007276
CHAN A3 (5V): -0.002224
CHAN B0 (3.3V): 0.000340
CHAN B1 (3.15aV): 0.000160
CHAN B2 (3.15bV): 0.000049
CHAN B3 (GND): 0.001706
OPEN: 0.005364
Full Scale Calc: 4.765 mA, -1.589 mA
2019-05-21T14:48:59.714Z,1558450139.714 [Micromodem](INFO): Starting
2019-05-21T14:48:59.715Z,1558450139.715 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:00.118Z,1558450140.118 [Micromodem](INFO): Starting
2019-05-21T14:49:00.119Z,1558450140.119 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:00.526Z,1558450140.526 [Micromodem](INFO): Starting
2019-05-21T14:49:00.527Z,1558450140.527 [Micromodem](INFO): Nmea in: $CAREV,144849,COPROC,0.10.0.46*44

2019-05-21T14:49:00.528Z,1558450140.528 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:00.922Z,1558450140.922 [Micromodem](INFO): Starting
2019-05-21T14:49:00.923Z,1558450140.923 [Micromodem](INFO): Nmea in: $CAREV,144859,AUV,2.0.27690*10

2019-05-21T14:49:00.923Z,1558450140.923 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:01.326Z,1558450141.326 [Micromodem](INFO): Starting
2019-05-21T14:49:01.327Z,1558450141.327 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:01.730Z,1558450141.730 [Micromodem](INFO): Starting
2019-05-21T14:49:01.731Z,1558450141.731 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:02.134Z,1558450142.134 [Micromodem](INFO): Starting
2019-05-21T14:49:02.135Z,1558450142.135 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:02.538Z,1558450142.538 [Micromodem](INFO): Starting
2019-05-21T14:49:02.539Z,1558450142.539 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:02.946Z,1558450142.946 [Micromodem](INFO): Starting
2019-05-21T14:49:02.947Z,1558450142.947 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:03.362Z,1558450143.362 [Micromodem](INFO): Starting
2019-05-21T14:49:03.363Z,1558450143.363 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:03.978Z,1558450143.978 [Micromodem](INFO): Starting
2019-05-21T14:49:03.979Z,1558450143.979 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:04.374Z,1558450144.374 [Micromodem](INFO): Starting
2019-05-21T14:49:04.375Z,1558450144.375 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:04.786Z,1558450144.786 [Micromodem](INFO): Starting
2019-05-21T14:49:04.787Z,1558450144.787 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:05.186Z,1558450145.186 [Micromodem](INFO): Starting
2019-05-21T14:49:05.187Z,1558450145.187 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:05.590Z,1558450145.590 [Micromodem](INFO): Starting
2019-05-21T14:49:05.591Z,1558450145.591 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:05.994Z,1558450145.994 [Micromodem](INFO): Starting
2019-05-21T14:49:05.995Z,1558450145.995 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:06.398Z,1558450146.398 [Micromodem](INFO): Starting
2019-05-21T14:49:06.399Z,1558450146.399 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:06.798Z,1558450146.798 [Micromodem](INFO): Starting
2019-05-21T14:49:06.799Z,1558450146.799 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:07.202Z,1558450147.202 [Micromodem](INFO): Starting
2019-05-21T14:49:07.203Z,1558450147.203 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:07.607Z,1558450147.607 [Micromodem](INFO): Starting
2019-05-21T14:49:07.608Z,1558450147.608 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:07.647Z,1558450147.647 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error
2019-05-21T14:49:07.647Z,1558450147.647 [RDI_Pathfinder](ERROR): Failed to parse:
:TS,19052107582968,35.0, -0.1,   0.,  0
2019-05-21T14:49:08.010Z,1558450148.010 [Micromodem](INFO): Starting
2019-05-21T14:49:08.011Z,1558450148.011 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:08.422Z,1558450148.422 [Micromodem](INFO): Starting
2019-05-21T14:49:08.423Z,1558450148.423 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:08.823Z,1558450148.823 [Micromodem](INFO): Starting
2019-05-21T14:49:08.823Z,1558450148.823 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:08.852Z,1558450148.852 [RDI_Pathfinder](ERROR): Failed to parse:
:SA,   +0.00,   +0.00,  0.00
2019-05-21T14:49:09.226Z,1558450149.226 [Micromodem](INFO): Starting
2019-05-21T14:49:09.227Z,1558450149.227 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:09.630Z,1558450149.630 [Micromodem](INFO): Starting
2019-05-21T14:49:09.631Z,1558450149.631 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:10.034Z,1558450150.034 [Micromodem](INFO): Starting
2019-05-21T14:49:10.035Z,1558450150.035 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:10.434Z,1558450150.434 [Micromodem](INFO): Starting
2019-05-21T14:49:10.435Z,1558450150.435 [Micromodem](INFO): Nmea in: $CAREV,144859,COPROC,0.10.0.46*45

2019-05-21T14:49:10.435Z,1558450150.435 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:10.842Z,1558450150.842 [Micromodem](INFO): Starting
2019-05-21T14:49:10.843Z,1558450150.843 [Micromodem](INFO): Nmea in: $CAREV,144909,AUV,2.0.27690*14

2019-05-21T14:49:10.843Z,1558450150.843 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:11.246Z,1558450151.246 [Micromodem](INFO): Starting
2019-05-21T14:49:11.247Z,1558450151.247 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:11.646Z,1558450151.646 [Micromodem](INFO): Starting
2019-05-21T14:49:11.646Z,1558450151.646 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:12.062Z,1558450152.062 [Micromodem](INFO): Starting
2019-05-21T14:49:12.062Z,1558450152.062 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:12.454Z,1558450152.454 [Micromodem](INFO): Starting
2019-05-21T14:49:12.455Z,1558450152.455 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:12.858Z,1558450152.858 [Micromodem](INFO): Starting
2019-05-21T14:49:12.859Z,1558450152.859 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:13.281Z,1558450153.281 [Micromodem](INFO): Starting
2019-05-21T14:49:13.283Z,1558450153.283 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:13.666Z,1558450153.666 [Micromodem](INFO): Starting
2019-05-21T14:49:13.667Z,1558450153.667 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:14.070Z,1558450154.070 [Micromodem](INFO): Starting
2019-05-21T14:49:14.071Z,1558450154.071 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:14.474Z,1558450154.474 [Micromodem](INFO): Starting
2019-05-21T14:49:14.475Z,1558450154.475 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:14.878Z,1558450154.878 [Micromodem](INFO): Starting
2019-05-21T14:49:14.879Z,1558450154.879 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:15.289Z,1558450155.289 [Micromodem](INFO): Starting
2019-05-21T14:49:15.289Z,1558450155.289 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:15.710Z,1558450155.710 [Micromodem](INFO): Starting
2019-05-21T14:49:15.710Z,1558450155.710 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:16.094Z,1558450156.094 [Micromodem](INFO): Starting
2019-05-21T14:49:16.095Z,1558450156.095 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:16.494Z,1558450156.494 [Micromodem](INFO): Starting
2019-05-21T14:49:16.495Z,1558450156.495 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:16.902Z,1558450156.902 [Micromodem](INFO): Starting
2019-05-21T14:49:16.903Z,1558450156.903 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:17.302Z,1558450157.302 [Micromodem](INFO): Starting
2019-05-21T14:49:17.303Z,1558450157.303 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:17.710Z,1558450157.710 [Micromodem](INFO): Starting
2019-05-21T14:49:17.711Z,1558450157.711 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:18.110Z,1558450158.110 [Micromodem](INFO): Starting
2019-05-21T14:49:18.111Z,1558450158.111 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:18.522Z,1558450158.522 [Micromodem](INFO): Starting
2019-05-21T14:49:18.523Z,1558450158.523 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:18.918Z,1558450158.918 [Micromodem](INFO): Starting
2019-05-21T14:49:18.919Z,1558450158.919 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:19.322Z,1558450159.322 [Micromodem](INFO): Starting
2019-05-21T14:49:19.323Z,1558450159.323 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:19.742Z,1558450159.742 [Micromodem](INFO): Starting
2019-05-21T14:49:19.743Z,1558450159.743 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:19.921Z,1558450159.921 [CommandLine](IMPORTANT): got command quit
2019-05-21T14:49:20.138Z,1558450160.138 [Micromodem](INFO): Starting
2019-05-21T14:49:20.139Z,1558450160.139 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:20.539Z,1558450160.539 [Micromodem](INFO): Starting
2019-05-21T14:49:20.540Z,1558450160.540 [Micromodem](INFO): Nmea in: $CAREV,144909,COPROC,0.10.0.46*41

2019-05-21T14:49:20.540Z,1558450160.540 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:20.925Z,1558450160.925 [Supervisor](INFO): Stop Mission called by Supervisor::terminate
2019-05-21T14:49:20.925Z,1558450160.925 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:20.926Z,1558450160.926 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:20.950Z,1558450160.950 [Micromodem](INFO): Starting
2019-05-21T14:49:20.951Z,1558450160.951 [Micromodem](INFO): Nmea in: $CAREV,144919,AUV,2.0.27690*15

2019-05-21T14:49:20.951Z,1558450160.951 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:20.977Z,1558450160.977 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-21T14:49:20.977Z,1558450160.977 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:20.978Z,1558450160.978 [CommandLine](INFO): Join timeout helper Thread ID is 504
2019-05-21T14:49:20.978Z,1558450160.978 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-21T14:49:20.978Z,1558450160.978 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:20.979Z,1558450160.979 [NavChartDb](INFO): Join timeout helper Thread ID is 505
2019-05-21T14:49:21.346Z,1558450161.346 [Micromodem](INFO): Starting
2019-05-21T14:49:21.347Z,1558450161.347 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:21.365Z,1558450161.365 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.365Z,1558450161.365 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.373Z,1558450161.373 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler
2019-05-21T14:49:21.373Z,1558450161.373 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.373Z,1558450161.373 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 506
2019-05-21T14:49:21.473Z,1558450161.473 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.473Z,1558450161.473 [WetLabsSeaOWL_UV_A](INFO): Powering down
2019-05-21T14:49:21.474Z,1558450161.474 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.481Z,1558450161.481 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-21T14:49:21.481Z,1558450161.481 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.481Z,1558450161.481 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 507
2019-05-21T14:49:21.493Z,1558450161.493 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.493Z,1558450161.493 [CTD_NeilBrown](INFO): Powering down
2019-05-21T14:49:21.505Z,1558450161.505 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.509Z,1558450161.509 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-21T14:49:21.509Z,1558450161.509 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.509Z,1558450161.509 [Radio_Surface](INFO): Join timeout helper Thread ID is 508
2019-05-21T14:49:21.746Z,1558450161.746 [Micromodem](INFO): Starting
2019-05-21T14:49:21.746Z,1558450161.746 [Micromodem](INFO): outbuffer_.isEmpty() = 1, cmdSentTime_.elapsed() = N/A
2019-05-21T14:49:21.801Z,1558450161.801 [Radio_Surface](INFO): Powering down
2019-05-21T14:49:21.802Z,1558450161.802 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.802Z,1558450161.802 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.810Z,1558450161.810 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-21T14:49:21.810Z,1558450161.810 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.810Z,1558450161.810 [DataOverHttps](INFO): Join timeout helper Thread ID is 509
2019-05-21T14:49:21.833Z,1558450161.833 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.833Z,1558450161.833 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.841Z,1558450161.841 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-21T14:49:21.842Z,1558450161.842 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.842Z,1558450161.842 [logger](INFO): Join timeout helper Thread ID is 510
2019-05-21T14:49:21.849Z,1558450161.849 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:21.849Z,1558450161.849 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.861Z,1558450161.861 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-21T14:49:21.862Z,1558450161.862 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.862Z,1558450161.862 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-21T14:49:21.862Z,1558450161.862 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:21.862Z,1558450161.862 [controlThread](INFO): Join timeout helper Thread ID is 511
2019-05-21T14:49:22.141Z,1558450162.141 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-21T14:49:22.141Z,1558450162.141 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-21T14:49:22.142Z,1558450162.142 [AHRS_M2](INFO): Powering down
2019-05-21T14:49:22.213Z,1558450162.213 [DUSBL_Hydroid](INFO): Powering down
2019-05-21T14:49:22.309Z,1558450162.309 [Micromodem](INFO): uninitialize
2019-05-21T14:49:22.309Z,1558450162.309 [Micromodem](INFO): Powering down
2019-05-21T14:49:22.425Z,1558450162.425 [NAL9602](INFO): Powering down
2019-05-21T14:49:22.497Z,1558450162.497 [RDI_Pathfinder](INFO): Powering down
2019-05-21T14:49:22.499Z,1558450162.499 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-21T14:49:22.499Z,1558450162.499 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-21T14:49:22.500Z,1558450162.500 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-21T14:49:22.500Z,1558450162.500 [MissionManager](INFO): Uninitializing Mission Default
2019-05-21T14:49:22.503Z,1558450162.503 [MissionManager](INFO): Uninitializing Mission Startup
2019-05-21T14:49:22.504Z,1558450162.504 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-21T14:49:22.504Z,1558450162.504 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-21T14:49:22.505Z,1558450162.505 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-21T14:49:22.505Z,1558450162.505 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-21T14:49:22.505Z,1558450162.505 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-21T14:49:22.505Z,1558450162.505 [BuoyancyServo](INFO): Powering down
2019-05-21T14:49:22.517Z,1558450162.517 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-21T14:49:22.517Z,1558450162.517 [ElevatorServo](INFO): Powering down
2019-05-21T14:49:22.518Z,1558450162.518 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-21T14:49:22.518Z,1558450162.518 [MassServo](INFO): Powering down
2019-05-21T14:49:22.519Z,1558450162.519 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-21T14:49:22.519Z,1558450162.519 [RudderServo](INFO): Powering down
2019-05-21T14:49:22.520Z,1558450162.520 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-21T14:49:22.520Z,1558450162.520 [ThrusterServo](INFO): Powering down
2019-05-21T14:49:22.521Z,1558450162.521 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-21T14:49:22.521Z,1558450162.521 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-21T14:49:22.521Z,1558450162.521 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-21T14:49:22.521Z,1558450162.521 [CBIT](DEBUG): Powering off loads.
2019-05-21T14:49:22.533Z,1558450162.533 [CBIT](DEBUG): Disabling WDT.
2019-05-21T14:49:22.545Z,1558450162.545 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-21T14:49:22.546Z,1558450162.546 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.598Z,1558450162.598 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.607Z,1558450162.607 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.646Z,1558450162.646 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.649Z,1558450162.649 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.704Z,1558450162.704 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-21T14:49:22.761Z,1558450162.761 [logger ThreadHandler](INFO): Thread cancelled.