2022-10-07T00:56:13.731Z,1665104173.731 [Supervisor](DEBUG): Initializing supervisor.
2022-10-07T00:56:13.736Z,1665104173.736 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2022-10-07T00:56:13.736Z,1665104173.736 [SyncHandler](INFO): Protected caller Thread ID is 2250
2022-10-07T00:56:13.737Z,1665104173.737 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2022-10-07T00:56:13.738Z,1665104173.738 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2022-10-07T00:56:13.738Z,1665104173.738 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2251
2022-10-07T00:56:13.742Z,1665104173.742 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2022-10-07T00:56:13.760Z,1665104173.760 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2022-10-07T00:56:13.761Z,1665104173.761 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2022-10-07T00:56:13.761Z,1665104173.761 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 2252
2022-10-07T00:56:13.765Z,1665104173.765 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2022-10-07T00:56:13.766Z,1665104173.766 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2022-10-07T00:56:13.767Z,1665104173.767 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2253
2022-10-07T00:56:13.769Z,1665104173.769 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2022-10-07T00:56:13.770Z,1665104173.770 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2022-10-07T00:56:13.770Z,1665104173.770 [logger ThreadHandler](INFO): Protected caller Thread ID is 2254
2022-10-07T00:56:13.774Z,1665104173.774 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2022-10-07T00:56:13.774Z,1665104173.774 [Supervisor](INFO): Looking for Config files in directory: Config/
2022-10-07T00:56:13.780Z,1665104173.780 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2022-10-07T00:56:13.941Z,1665104173.941 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2022-10-07T00:56:13.942Z,1665104173.942 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2022-10-07T00:56:14.162Z,1665104174.162 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2022-10-07T00:56:14.162Z,1665104174.162 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2022-10-07T00:56:14.419Z,1665104174.419 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2022-10-07T00:56:14.420Z,1665104174.420 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2022-10-07T00:56:14.530Z,1665104174.530 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2022-10-07T00:56:14.531Z,1665104174.531 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2022-10-07T00:56:15.201Z,1665104175.201 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2022-10-07T00:56:15.201Z,1665104175.201 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2022-10-07T00:56:15.656Z,1665104175.656 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2022-10-07T00:56:15.657Z,1665104175.657 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2022-10-07T00:56:16.163Z,1665104176.163 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2022-10-07T00:56:16.164Z,1665104176.164 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2022-10-07T00:56:16.558Z,1665104176.558 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2022-10-07T00:56:16.940Z,1665104176.940 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2022-10-07T00:56:17.388Z,1665104177.388 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2022-10-07T00:56:17.388Z,1665104177.388 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2022-10-07T00:56:17.747Z,1665104177.747 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2022-10-07T00:56:17.748Z,1665104177.748 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2022-10-07T00:56:17.969Z,1665104177.969 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2022-10-07T00:56:17.970Z,1665104177.970 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2022-10-07T00:56:18.110Z,1665104178.110 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2022-10-07T00:56:18.111Z,1665104178.111 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2022-10-07T00:56:18.194Z,1665104178.194 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2022-10-07T00:56:18.276Z,1665104178.276 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2022-10-07T00:56:18.462Z,1665104178.462 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2022-10-07T00:56:18.464Z,1665104178.464 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2022-10-07T00:56:18.681Z,1665104178.681 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2022-10-07T00:56:18.683Z,1665104178.683 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/
2022-10-07T00:56:18.686Z,1665104178.686 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/secure.cfg
2022-10-07T00:56:18.774Z,1665104178.774 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Battery.cfg
2022-10-07T00:56:19.038Z,1665104179.038 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2022-10-07T00:56:19.039Z,1665104179.039 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Navigation.cfg
2022-10-07T00:56:19.141Z,1665104179.141 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Sensor.cfg
2022-10-07T00:56:19.305Z,1665104179.305 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/vehicle.cfg
2022-10-07T00:56:19.488Z,1665104179.488 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Simulator.cfg
2022-10-07T00:56:19.576Z,1665104179.576 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Servo.cfg
2022-10-07T00:56:19.687Z,1665104179.687 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Control.cfg
2022-10-07T00:56:19.795Z,1665104179.795 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/Science.cfg
2022-10-07T00:56:19.956Z,1665104179.956 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/logger.cfg
2022-10-07T00:56:20.061Z,1665104180.061 [Supervisor](INFO): Opening Config file at: Config/lrauv-makai/BIT.cfg
2022-10-07T00:56:20.164Z,1665104180.164 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-makai/root/
2022-10-07T00:56:20.164Z,1665104180.164 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2022-10-07T00:56:20.190Z,1665104180.190 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2022-10-07T00:56:20.366Z,1665104180.366 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2022-10-07T00:56:20.367Z,1665104180.367 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2022-10-07T00:56:20.533Z,1665104180.533 [BuoyancyServo] Loaded
2022-10-07T00:56:20.534Z,1665104180.534 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2022-10-07T00:56:20.555Z,1665104180.555 [ElevatorServo] Loaded
2022-10-07T00:56:20.555Z,1665104180.555 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2022-10-07T00:56:20.575Z,1665104180.575 [MassServo] Loaded
2022-10-07T00:56:20.575Z,1665104180.575 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2022-10-07T00:56:20.595Z,1665104180.595 [RudderServo] Loaded
2022-10-07T00:56:20.595Z,1665104180.595 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2022-10-07T00:56:20.611Z,1665104180.611 [ThrusterHE] Loaded
2022-10-07T00:56:20.611Z,1665104180.611 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2022-10-07T00:56:20.611Z,1665104180.611 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2022-10-07T00:56:20.612Z,1665104180.612 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2022-10-07T00:56:20.773Z,1665104180.773 [SBIT](DEBUG): Construct Startup Built In Test.
2022-10-07T00:56:20.788Z,1665104180.788 [SBIT] Loaded
2022-10-07T00:56:20.788Z,1665104180.788 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2022-10-07T00:56:20.791Z,1665104180.791 [IBIT](DEBUG): Construct Initiated Built In Test.
2022-10-07T00:56:20.812Z,1665104180.812 [IBIT] Loaded
2022-10-07T00:56:20.813Z,1665104180.813 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2022-10-07T00:56:20.818Z,1665104180.818 [CBIT](DEBUG): Construct Continuous Built In Test.
2022-10-07T00:56:21.032Z,1665104181.032 [CBIT] Loaded
2022-10-07T00:56:21.032Z,1665104181.032 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2022-10-07T00:56:21.033Z,1665104181.033 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2022-10-07T00:56:21.033Z,1665104181.033 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2022-10-07T00:56:21.236Z,1665104181.236 [CTD_Seabird] Loaded
2022-10-07T00:56:21.237Z,1665104181.237 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2022-10-07T00:56:21.238Z,1665104181.238 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 406664E0
2022-10-07T00:56:21.238Z,1665104181.238 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 2336
2022-10-07T00:56:21.270Z,1665104181.270 [ESPComponent] Loaded
2022-10-07T00:56:21.270Z,1665104181.270 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2022-10-07T00:56:21.289Z,1665104181.289 [PAR_Licor] Loaded
2022-10-07T00:56:21.289Z,1665104181.289 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2022-10-07T00:56:21.320Z,1665104181.320 [WetLabsBB2FL] Loaded
2022-10-07T00:56:21.320Z,1665104181.320 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2022-10-07T00:56:21.321Z,1665104181.321 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 406964E0
2022-10-07T00:56:21.321Z,1665104181.321 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2337
2022-10-07T00:56:21.322Z,1665104181.322 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2022-10-07T00:56:21.323Z,1665104181.323 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2022-10-07T00:56:21.389Z,1665104181.389 [DepthRateCalculator] Loaded
2022-10-07T00:56:21.389Z,1665104181.389 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2022-10-07T00:56:21.395Z,1665104181.395 [PitchRateCalculator] Loaded
2022-10-07T00:56:21.395Z,1665104181.395 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2022-10-07T00:56:21.405Z,1665104181.405 [SpeedCalculator] Loaded
2022-10-07T00:56:21.405Z,1665104181.405 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2022-10-07T00:56:21.410Z,1665104181.410 [YawRateCalculator] Loaded
2022-10-07T00:56:21.410Z,1665104181.410 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2022-10-07T00:56:21.430Z,1665104181.430 [ElevatorOffsetCalculator] Loaded
2022-10-07T00:56:21.430Z,1665104181.430 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2022-10-07T00:56:21.447Z,1665104181.447 [ShortestDistanceToPolygonSidesCalculator] Loaded
2022-10-07T00:56:21.447Z,1665104181.447 [ComponentRegistry](DEBUG): SyncComponent "ShortestDistanceToPolygonSidesCalculator" handled in the control thread.
2022-10-07T00:56:21.447Z,1665104181.447 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2022-10-07T00:56:21.448Z,1665104181.448 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2022-10-07T00:56:21.560Z,1665104181.560 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2022-10-07T00:56:21.560Z,1665104181.560 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2022-10-07T00:56:22.062Z,1665104182.062 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2022-10-07T00:56:22.063Z,1665104182.063 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2022-10-07T00:56:22.411Z,1665104182.411 [DeadReckonUsingMultipleVelocitySources] Loaded
2022-10-07T00:56:22.411Z,1665104182.411 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2022-10-07T00:56:22.425Z,1665104182.425 [NavChart] Loaded
2022-10-07T00:56:22.426Z,1665104182.426 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2022-10-07T00:56:22.431Z,1665104182.431 [UniversalFixResidualReporter] Loaded
2022-10-07T00:56:22.431Z,1665104182.431 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2022-10-07T00:56:22.432Z,1665104182.432 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2022-10-07T00:56:22.433Z,1665104182.433 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2022-10-07T00:56:22.948Z,1665104182.948 [AHRS_M2] Loaded
2022-10-07T00:56:22.948Z,1665104182.948 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2022-10-07T00:56:22.981Z,1665104182.981 [BackseatComponent] Loaded
2022-10-07T00:56:22.982Z,1665104182.982 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2022-10-07T00:56:22.983Z,1665104182.983 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 40A144E0
2022-10-07T00:56:22.983Z,1665104182.983 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 2338
2022-10-07T00:56:22.986Z,1665104182.986 [LcmUniversalReporter] Loaded
2022-10-07T00:56:22.986Z,1665104182.986 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2022-10-07T00:56:23.062Z,1665104183.062 [DataOverHttps] Loaded
2022-10-07T00:56:23.063Z,1665104183.063 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2022-10-07T00:56:23.064Z,1665104183.064 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 40A444E0
2022-10-07T00:56:23.064Z,1665104183.064 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2339
2022-10-07T00:56:23.084Z,1665104183.084 [Depth_Keller] Loaded
2022-10-07T00:56:23.084Z,1665104183.084 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2022-10-07T00:56:23.122Z,1665104183.122 [DVL_micro] Loaded
2022-10-07T00:56:23.123Z,1665104183.123 [ComponentRegistry](DEBUG): SyncComponent "DVL_micro" handled in the control thread.
2022-10-07T00:56:23.182Z,1665104183.182 [NAL9602] Loaded
2022-10-07T00:56:23.182Z,1665104183.182 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2022-10-07T00:56:23.208Z,1665104183.208 [Onboard] Loaded
2022-10-07T00:56:23.208Z,1665104183.208 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2022-10-07T00:56:23.209Z,1665104183.209 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 40A744E0
2022-10-07T00:56:23.209Z,1665104183.209 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 2340
2022-10-07T00:56:23.221Z,1665104183.221 [Power24vConverter] Loaded
2022-10-07T00:56:23.221Z,1665104183.221 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2022-10-07T00:56:23.235Z,1665104183.235 [Radio_Surface] Loaded
2022-10-07T00:56:23.235Z,1665104183.235 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2022-10-07T00:56:23.236Z,1665104183.236 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 40AA44E0
2022-10-07T00:56:23.236Z,1665104183.236 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2341
2022-10-07T00:56:23.332Z,1665104183.332 [DAT] Loaded
2022-10-07T00:56:23.333Z,1665104183.333 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2022-10-07T00:56:23.334Z,1665104183.334 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 40AD44E0
2022-10-07T00:56:23.334Z,1665104183.334 [DAT ThreadHandler](INFO): Protected caller Thread ID is 2342
2022-10-07T00:56:23.335Z,1665104183.335 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2022-10-07T00:56:23.335Z,1665104183.335 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2022-10-07T00:56:23.413Z,1665104183.413 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2022-10-07T00:56:23.413Z,1665104183.413 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2022-10-07T00:56:23.473Z,1665104183.473 [VerticalControl](DEBUG): Construct VerticalControl.
2022-10-07T00:56:23.524Z,1665104183.524 [VerticalControl] Loaded
2022-10-07T00:56:23.524Z,1665104183.524 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2022-10-07T00:56:23.527Z,1665104183.527 [HorizontalControl](DEBUG): Construct HorizontalControl.
2022-10-07T00:56:23.565Z,1665104183.565 [HorizontalControl] Loaded
2022-10-07T00:56:23.565Z,1665104183.565 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2022-10-07T00:56:23.567Z,1665104183.567 [SpeedControl](DEBUG): Construct SpeedControl.
2022-10-07T00:56:23.569Z,1665104183.569 [SpeedControl] Loaded
2022-10-07T00:56:23.569Z,1665104183.569 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2022-10-07T00:56:23.572Z,1665104183.572 [LoopControl](DEBUG): Construct LoopControl.
2022-10-07T00:56:23.573Z,1665104183.573 [LoopControl] Loaded
2022-10-07T00:56:23.573Z,1665104183.573 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2022-10-07T00:56:23.573Z,1665104183.573 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2022-10-07T00:56:23.574Z,1665104183.574 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2022-10-07T00:56:23.587Z,1665104183.587 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2022-10-07T00:56:23.588Z,1665104183.588 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2022-10-07T00:56:23.932Z,1665104183.932 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2022-10-07T00:56:23.938Z,1665104183.938 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2022-10-07T00:56:23.941Z,1665104183.941 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2022-10-07T00:56:23.952Z,1665104183.952 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2022-10-07T00:56:23.953Z,1665104183.953 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40BCE4E0
2022-10-07T00:56:23.953Z,1665104183.953 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2343
2022-10-07T00:56:23.958Z,1665104183.958 [Supervisor](INFO): Main Thread ID is 825
2022-10-07T00:56:23.958Z,1665104183.958 [Supervisor](DEBUG): Running supervisor.
2022-10-07T00:56:23.959Z,1665104183.959 [CommandExec ThreadHandler](INFO): Handler Thread ID is 2344
2022-10-07T00:56:23.959Z,1665104183.959 [CommandExec](INFO): Initializing the command executive.
2022-10-07T00:56:23.961Z,1665104183.961 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2345
2022-10-07T00:56:23.963Z,1665104183.963 [controlThread ThreadHandler](INFO): Handler Thread ID is 2346
2022-10-07T00:56:23.964Z,1665104183.964 [controlThread](DEBUG): Initializing ControlThread
2022-10-07T00:56:23.966Z,1665104183.966 [SBIT](INFO): Initialize SBIT Component.
2022-10-07T00:56:23.966Z,1665104183.966 [SBIT](IMPORTANT): git: 2022-09-08-11-gedf6df38b
2022-10-07T00:56:23.966Z,1665104183.966 [SBIT](INFO): git hash: edf6df38bc8d0b722d0abacdffe647c9d44a259d
2022-10-07T00:56:23.967Z,1665104183.967 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2022-10-07T00:56:23.968Z,1665104183.968 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
Kernel Reported: #1 PREEMPT Wed Mar 17 08:23:48 PDT 2021
2022-10-07T00:56:23.969Z,1665104183.969 [SBIT](INFO): Beginning SBIT in 20.000000 seconds.
2022-10-07T00:56:23.970Z,1665104183.970 [IBIT](INFO): Initialize IBIT Component.
2022-10-07T00:56:23.970Z,1665104183.970 [CBIT](DEBUG): Initialize CBIT Component.
2022-10-07T00:56:23.971Z,1665104183.971 [logger ThreadHandler](INFO): Handler Thread ID is 2347
2022-10-07T00:56:23.984Z,1665104183.984 [CBIT](DEBUG): Initialized mux pins.
2022-10-07T00:56:23.984Z,1665104183.984 [CBIT](DEBUG): Initializing the watchdog timer.
2022-10-07T00:56:23.992Z,1665104183.992 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 2348
2022-10-07T00:56:23.993Z,1665104183.993 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2022-10-07T00:56:23.997Z,1665104183.997 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2350
2022-10-07T00:56:24.001Z,1665104184.001 [WetLabsBB2FL](INFO): Powering up
2022-10-07T00:56:24.002Z,1665104184.002 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 2352
2022-10-07T00:56:24.008Z,1665104184.008 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2022-10-07T00:56:24.008Z,1665104184.008 [CBIT](DEBUG): Initializing heartbeat.
2022-10-07T00:56:24.009Z,1665104184.009 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2353
2022-10-07T00:56:24.010Z,1665104184.010 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2022-10-07T00:56:24.032Z,1665104184.032 [Onboard ThreadHandler](INFO): Handler Thread ID is 2354
2022-10-07T00:56:24.049Z,1665104184.049 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2355
2022-10-07T00:56:24.072Z,1665104184.072 [DAT ThreadHandler](INFO): Handler Thread ID is 2356
2022-10-07T00:56:24.073Z,1665104184.073 [DAT](INFO): Powering up
2022-10-07T00:56:24.073Z,1665104184.073 [DAT](DEBUG): Initializing DAT.
2022-10-07T00:56:24.077Z,1665104184.077 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2358
2022-10-07T00:56:24.080Z,1665104184.080 [CBIT](DEBUG): Deactivating GF circuits.
2022-10-07T00:56:24.080Z,1665104184.080 [CBIT](DEBUG): Deactivating emergency mode.
2022-10-07T00:56:24.085Z,1665104184.085 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2022-10-07T00:56:24.085Z,1665104184.085 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2022-10-07T00:56:24.085Z,1665104184.085 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2022-10-07T00:56:24.085Z,1665104184.085 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA69M.000
2022-10-07T00:56:24.086Z,1665104184.086 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA69M.000
2022-10-07T00:56:24.116Z,1665104184.116 [CBIT](DEBUG): Backplane powered.
2022-10-07T00:56:24.120Z,1665104184.120 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2022-10-07T00:56:24.121Z,1665104184.121 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2022-10-07T00:56:24.121Z,1665104184.121 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2022-10-07T00:56:24.121Z,1665104184.121 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2022-10-07T00:56:24.122Z,1665104184.122 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2022-10-07T00:56:24.122Z,1665104184.122 [ShortestDistanceToPolygonSidesCalculator](DEBUG): Initializing.
2022-10-07T00:56:24.124Z,1665104184.124 [NavChart](DEBUG): Initialize NavChart Navigation.
2022-10-07T00:56:24.125Z,1665104184.125 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2022-10-07T00:56:24.133Z,1665104184.133 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2022-10-07T00:56:24.135Z,1665104184.135 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2022-10-07T00:56:24.135Z,1665104184.135 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2022-10-07T00:56:24.136Z,1665104184.136 [LoopControl](DEBUG): Initialize LoopControlComponent.
2022-10-07T00:56:24.137Z,1665104184.137 [MissionManager](INFO): Loading Mission from file: Missions/Startup.xml
2022-10-07T00:56:24.181Z,1665104184.181 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2022-10-07T00:56:24.221Z,1665104184.221 [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>


2022-10-07T00:56:24.222Z,1665104184.222 [MissionManager](INFO): Loading Mission from file: Missions/Default.xml
2022-10-07T00:56:24.341Z,1665104184.341 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2022-10-07T00:56:24.342Z,1665104184.342 [Default:A.Wait](DEBUG): Construct Wait.
2022-10-07T00:56:24.345Z,1665104184.345 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2022-10-07T00:56:24.388Z,1665104184.388 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2022-10-07T00:56:24.391Z,1665104184.391 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2022-10-07T00:56:24.409Z,1665104184.409 [Default:E.Execute](DEBUG): Construct Execute.
2022-10-07T00:56:24.412Z,1665104184.412 [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="P4H">
                <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>


2022-10-07T00:56:24.428Z,1665104184.428 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,ShortestDistanceToPolygonSidesCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2022-10-07T00:56:24.456Z,1665104184.456 [Radio_Surface](INFO): Powering up
2022-10-07T00:56:24.457Z,1665104184.457 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2022-10-07T00:56:24.563Z,1665104184.563 [Power24vConverter](INFO): Powering up.
2022-10-07T00:56:24.613Z,1665104184.613 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:24.620Z,1665104184.620 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2022-10-07T00:56:24.621Z,1665104184.621 [ElevatorServo](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:24.628Z,1665104184.628 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2022-10-07T00:56:24.629Z,1665104184.629 [MassServo](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:24.640Z,1665104184.640 [MassServo](DEBUG): Initializing MassServo.
2022-10-07T00:56:24.641Z,1665104184.641 [RudderServo](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:24.648Z,1665104184.648 [RudderServo](DEBUG): Initializing RudderServo.
2022-10-07T00:56:24.649Z,1665104184.649 [ThrusterHE](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:24.656Z,1665104184.656 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2022-10-07T00:56:25.572Z,1665104185.572 [RudderServo](ERROR): Rudder initialization uart error serial timeout
2022-10-07T00:56:25.572Z,1665104185.572 [RudderServo](FAULT): Rudder failed to initialize
2022-10-07T00:56:25.572Z,1665104185.572 [RudderServo] Communications Fault, FailCount= 1
2022-10-07T00:56:25.572Z,1665104185.572 [RudderServo](ERROR): Communications Fault
2022-10-07T00:56:25.576Z,1665104185.576 [CBIT](ERROR): Communications Fault in component: RudderServo
2022-10-07T00:56:25.805Z,1665104185.805 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2022-10-07T00:56:25.805Z,1665104185.805 [RudderServo](INFO): Powering down
2022-10-07T00:56:26.108Z,1665104186.108 [WetLabsBB2FL](INFO): Powering down
2022-10-07T00:56:26.486Z,1665104186.486 [RudderServo](DEBUG): Initializing EZServoServo.
2022-10-07T00:56:26.605Z,1665104186.605 [RudderServo](DEBUG): Initializing RudderServo.
2022-10-07T00:56:26.609Z,1665104186.609 [CBIT](INFO): Clearing failed state for component RudderServo
2022-10-07T00:56:26.609Z,1665104186.609 [RudderServo] No Fault, FailCount= 1
2022-10-07T00:56:30.385Z,1665104190.385 [ThrusterHE](ERROR): Zero Speed Commanded.
2022-10-07T00:56:38.438Z,1665104198.438 [DAT](INFO): commRate: 1200
2022-10-07T00:56:40.504Z,1665104200.504 [DAT](INFO): entering command mode
2022-10-07T00:56:40.705Z,1665104200.705 [DAT](INFO): setting verbose to 3
2022-10-07T00:56:40.962Z,1665104200.962 [DAT](INFO): set verbose to 3
2022-10-07T00:56:40.962Z,1665104200.962 [DAT](INFO): setting DatVerbose to 27440
2022-10-07T00:56:41.209Z,1665104201.209 [DAT](INFO): set DatVerbose to 27440
2022-10-07T00:56:41.210Z,1665104201.210 [DAT](INFO): setting transmit power to 8
2022-10-07T00:56:41.462Z,1665104201.462 [DAT](INFO): set transmit power to 8
2022-10-07T00:56:41.462Z,1665104201.462 [DAT](INFO): setting local address to 4
2022-10-07T00:56:41.713Z,1665104201.713 [DAT](INFO): set local address to 4
2022-10-07T00:56:41.714Z,1665104201.714 [DAT](INFO): Setting time to: 0:56:41 And date to:10/7/2022
2022-10-07T00:56:41.965Z,1665104201.965 [DAT](INFO): Local DAT time set to Fri Oct 7, 2022  00:56:41  

2022-10-07T00:56:44.777Z,1665104204.777 [SBIT](IMPORTANT): Beginning Startup BIT
2022-10-07T00:56:44.831Z,1665104204.831 [CBIT](IMPORTANT): Beginning ground fault scan
2022-10-07T00:56:53.558Z,1665104213.558 [NAL9602](INFO): Powering up NAL9602
2022-10-07T00:56:55.635Z,1665104215.635 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.064952
CHAN A1 (24V): 0.060495
CHAN A2 (12V): -0.015429
CHAN A3 (5V): -0.033015
CHAN B0 (3.3V): -0.019421
CHAN B1 (3.15aV): -0.012706
CHAN B2 (3.15bV): -0.008211
CHAN B3 (GND): -0.019681
OPEN: 0.005583
Full Scale: +/- 1 mA
2022-10-07T00:57:04.442Z,1665104224.442 [NAL9602](INFO): NAL9602 initialized
2022-10-07T00:57:38.815Z,1665104258.815 [SBIT](IMPORTANT): SBIT PASSED
2022-10-07T00:57:38.815Z,1665104258.815 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2022-10-07T00:57:38.816Z,1665104258.816 [SBIT](IMPORTANT): BPC1.loadAtStartup=0 bool;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): DAT.loadAtStartup=1 bool;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): DAT.sbdAddress=-1 enum;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): Depth_Keller.offset=-0.41 decibar;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): DropWeight.loadAtStartup=0 bool;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): ElevatorServo.offsetAngle=1 degree;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): Express linearApproximation CBIT.ampHoursUsed 5.0 ampere_hour;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): Express linearApproximation NAL9602.sigQuality 1.000000 count;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff470nm;

2022-10-07T00:57:38.817Z,1665104258.817 [SBIT](IMPORTANT): Express none WetLabsBB2FL.BackscatteringCoeff650nm;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): RudderServo.offsetAngle=0 degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.latVertex1=34.45 degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.latVertex2=34.4 degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.latVertex3=34.13 degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.latVertex4=34.29 degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.latVertex5=nan degree;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.loadAtStartup=1 bool;

2022-10-07T00:57:38.818Z,1665104258.818 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.lonVertex1=-120.09 degree;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.lonVertex2=-119.28 degree;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.lonVertex3=-119.28 degree;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.lonVertex4=-120.11 degree;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): ShortestDistanceToPolygonSidesCalculator.lonVertex5=nan degree;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=90 cubic_centimeter;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): VerticalControl.massDefault=0 centimeter;

2022-10-07T00:57:38.819Z,1665104258.819 [SBIT](IMPORTANT): VerticalControl.massPositionLimitAft=-37 millimeter;

2022-10-07T00:57:39.226Z,1665104259.226 [MissionManager](IMPORTANT): Started mission Startup
2022-10-07T00:57:39.226Z,1665104259.226 [Startup] Running Loop=1
2022-10-07T00:57:39.227Z,1665104259.227 [Startup](DEBUG): Aggregate::initialize Startup
2022-10-07T00:57:39.227Z,1665104259.227 [Startup:A.GoToSurface] Running Loop=1
2022-10-07T00:57:39.227Z,1665104259.227 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-10-07T00:57:39.227Z,1665104259.227 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-10-07T00:57:39.228Z,1665104259.228 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-10-07T00:57:39.228Z,1665104259.228 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-10-07T00:57:39.229Z,1665104259.229 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-10-07T00:57:39.229Z,1665104259.229 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-10-07T00:57:39.230Z,1665104259.230 [Startup:StartupSatComms] Running Loop=1
2022-10-07T00:57:39.230Z,1665104259.230 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2022-10-07T00:57:39.231Z,1665104259.231 [Startup:StartupSatComms:A] Running Loop=1
2022-10-07T00:57:39.638Z,1665104259.638 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2022-10-07T00:58:39.389Z,1665104319.389 [Startup:StartupSatComms:A](INFO): Timed out from 2022-10-07T00:57:39.2Z
2022-10-07T00:58:39.389Z,1665104319.389 [Startup:StartupSatComms:A] Stopped
2022-10-07T00:58:39.389Z,1665104319.389 [Startup:StartupSatComms:B] Running Loop=1
2022-10-07T00:58:39.797Z,1665104319.797 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-10-07T00:58:41.404Z,1665104321.404 [CommandExec](IMPORTANT): got command schedule
2022-10-07T00:58:59.207Z,1665104339.207 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T00:58:59.207Z,1665104339.207 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.9,0000.0,1489.0,,+00272,+00128,-00487,+00000,A
2022-10-07T00:59:07.023Z,1665104347.023 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005167
2022-10-07T00:59:17.985Z,1665104357.985 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20221006T211055/Courier0070.lzma
2022-10-07T00:59:18.986Z,1665104358.986 [DataOverHttps](INFO): Moved sent file to Logs/20221006T211055/Courier0070.lzma.bak
2022-10-07T00:59:18.986Z,1665104358.986 [DataOverHttps](INFO): SBD MOMSN=17237312
2022-10-07T00:59:24.258Z,1665104364.258 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1
2022-10-07T00:59:24.258Z,1665104364.258 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-10-07T00:59:24.284Z,1665104364.284 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-10-07T00:59:24.793Z,1665104364.793 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-10-07T00:59:24.793Z,1665104364.793 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1
2022-10-07T00:59:29.899Z,1665104369.899 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T00:59:29.899Z,1665104369.899 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.9,089.0,000
2022-10-07T00:59:39.614Z,1665104379.614 [Startup:StartupSatComms:B](INFO): Timed out from 2022-10-07T00:58:39.4Z
2022-10-07T00:59:39.614Z,1665104379.614 [Startup:StartupSatComms:B] Stopped
2022-10-07T00:59:39.614Z,1665104379.614 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2022-10-07T00:59:39.614Z,1665104379.614 [Startup:StartupSatComms] Stopped
2022-10-07T00:59:39.614Z,1665104379.614 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2022-10-07T00:59:39.615Z,1665104379.615 [Startup](INFO): Completed Startup
2022-10-07T00:59:39.615Z,1665104379.615 [MissionManager](INFO): Startup is completed.
2022-10-07T00:59:39.615Z,1665104379.615 [MissionManager](INFO): Uninitializing Mission Startup
2022-10-07T00:59:39.615Z,1665104379.615 [Startup] Stopped
2022-10-07T00:59:39.615Z,1665104379.615 [Startup](DEBUG): Aggregate::uninitialize Startup
2022-10-07T00:59:39.615Z,1665104379.615 [Startup:A.GoToSurface] Stopped
2022-10-07T00:59:39.615Z,1665104379.615 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-10-07T00:59:40.038Z,1665104380.038 [MissionManager](IMPORTANT): Started mission Default
2022-10-07T00:59:40.038Z,1665104380.038 [Default] Running Loop=1
2022-10-07T00:59:40.038Z,1665104380.038 [Default](DEBUG): Aggregate::initialize Default
2022-10-07T00:59:40.038Z,1665104380.038 [Default:B.GoToSurface] Running Loop=1
2022-10-07T00:59:40.038Z,1665104380.038 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2022-10-07T00:59:40.039Z,1665104380.039 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2022-10-07T00:59:40.039Z,1665104380.039 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2022-10-07T00:59:40.039Z,1665104380.039 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2022-10-07T00:59:40.039Z,1665104380.039 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2022-10-07T00:59:40.044Z,1665104380.044 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2022-10-07T00:59:40.044Z,1665104380.044 [Default:A.Wait] Running Loop=1
2022-10-07T00:59:40.044Z,1665104380.044 [Default:A.Wait](DEBUG): Initialize Wait Component.
2022-10-07T00:59:50.247Z,1665104390.247 [DataOverHttps](INFO): Sending 151 bytes from file Logs/20221007T005613/Courier0000.lzma
2022-10-07T00:59:51.250Z,1665104391.250 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Courier0000.lzma.bak
2022-10-07T00:59:51.250Z,1665104391.250 [DataOverHttps](INFO): SBD MOMSN=17237314
2022-10-07T00:59:53.322Z,1665104393.322 [Default:A.Wait](INFO): Done Waiting.
2022-10-07T00:59:53.322Z,1665104393.322 [Default:A.Wait] Stopped
2022-10-07T00:59:53.322Z,1665104393.322 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2022-10-07T00:59:53.729Z,1665104393.729 [Default:CheckIn] Running Loop=1
2022-10-07T00:59:53.729Z,1665104393.729 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-10-07T00:59:53.729Z,1665104393.729 [Default:CheckIn:Read_GPS] Running Loop=1
2022-10-07T00:59:54.138Z,1665104394.138 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2022-10-07T01:01:06.501Z,1665104466.501 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T01:01:06.501Z,1665104466.501 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.9,089.0,000
2022-10-07T01:02:07.512Z,1665104527.512 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2022-10-07T01:02:25.295Z,1665104545.295 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2022-10-07T01:02:25.295Z,1665104545.295 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-10-07T01:02:25.321Z,1665104545.321 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-10-07T01:02:25.719Z,1665104545.719 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-10-07T01:02:25.719Z,1665104545.719 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2022-10-07T01:04:53.973Z,1665104693.973 [Default:CheckIn:Read_GPS](INFO): Timed out from 2022-10-07T00:59:53.7Z
2022-10-07T01:04:53.974Z,1665104693.974 [Default:CheckIn:Read_GPS] Stopped
2022-10-07T01:04:53.974Z,1665104693.974 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-10-07T01:04:54.382Z,1665104694.382 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2022-10-07T01:04:59.159Z,1665104699.159 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20221007T005613/Courier0004.lzma
2022-10-07T01:05:00.166Z,1665104700.166 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Courier0004.lzma.bak
2022-10-07T01:05:00.166Z,1665104700.166 [DataOverHttps](INFO): SBD MOMSN=17237317
2022-10-07T01:05:02.864Z,1665104702.864 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T01:05:02.864Z,1665104702.864 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+20.9,00000,000
2022-10-07T01:05:08.101Z,1665104708.101 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T01:05:08.101Z,1665104708.101 [DVL_micro](ERROR): Failed to parse:
:TS,000000000000000.9,0000.0,1489.0,000
2022-10-07T01:05:23.793Z,1665104723.793 [DataOverHttps](INFO): Sending 1151 bytes from file Logs/20221006T211055/Express0068.lzma
2022-10-07T01:05:24.794Z,1665104724.794 [DataOverHttps](INFO): Moved sent file to Logs/20221006T211055/Express0068.lzma.bak
2022-10-07T01:05:24.794Z,1665104724.794 [DataOverHttps](INFO): SBD MOMSN=17237319
2022-10-07T01:05:26.309Z,1665104726.309 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2022-10-07T01:05:26.309Z,1665104726.309 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-10-07T01:05:26.330Z,1665104726.330 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-10-07T01:05:26.825Z,1665104726.825 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-10-07T01:05:26.825Z,1665104726.825 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2022-10-07T01:05:31.142Z,1665104731.142 [DVL_micro](ERROR): Failed to parse:
:B,-00066,-00463,+00000,I
2022-10-07T01:05:52.659Z,1665104752.659 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20221006T211055/Express0071.lzma
2022-10-07T01:05:53.666Z,1665104753.666 [DataOverHttps](INFO): Moved sent file to Logs/20221006T211055/Express0071.lzma.bak
2022-10-07T01:05:53.666Z,1665104753.666 [DataOverHttps](INFO): SBD MOMSN=17237354
2022-10-07T01:05:59.014Z,1665104759.014 [DVL_micro](ERROR): only read 3 of 4 data items
2022-10-07T01:05:59.014Z,1665104759.014 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,+99999.99
2022-10-07T01:06:21.586Z,1665104781.586 [DataOverHttps](INFO): Sending 1103 bytes from file Logs/20221007T005613/Express0001.lzma
2022-10-07T01:06:22.582Z,1665104782.582 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Express0001.lzma.bak
2022-10-07T01:06:22.582Z,1665104782.582 [DataOverHttps](INFO): SBD MOMSN=17237357
2022-10-07T01:06:26.904Z,1665104786.904 [DVL_micro](ERROR): only read 2 of 4 data items
2022-10-07T01:06:26.904Z,1665104786.904 [DVL_micro](ERROR): Failed to parse:
:RD,+9999.99,+9999.99,++9999.99
2022-10-07T01:06:46.258Z,1665104806.258 [DataOverHttps](INFO): Sending 231 bytes from file Logs/20221007T005613/Express0005.lzma
2022-10-07T01:06:47.258Z,1665104807.258 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Express0005.lzma.bak
2022-10-07T01:06:47.258Z,1665104807.258 [DataOverHttps](INFO): SBD MOMSN=17237394
2022-10-07T01:06:57.244Z,1665104817.244 [Default:CheckIn:Read_Iridium] Stopped
2022-10-07T01:06:57.245Z,1665104817.245 [Default:CheckIn:C.Wait] Running Loop=1
2022-10-07T01:06:57.245Z,1665104817.245 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2022-10-07T01:07:05.690Z,1665104825.690 [NAL9602](FAULT): GPS failed to acquire within timeout.
2022-10-07T01:07:05.690Z,1665104825.690 [NAL9602] Data Fault, FailCount= 1
2022-10-07T01:07:05.690Z,1665104825.690 [NAL9602](ERROR): Data Fault
2022-10-07T01:07:05.771Z,1665104825.771 [CBIT](ERROR): Data Fault in component: NAL9602
2022-10-07T01:07:06.073Z,1665104826.073 [NAL9602](INFO): Powering down
2022-10-07T01:07:06.910Z,1665104826.910 [CBIT](INFO): Clearing failed state for component NAL9602
2022-10-07T01:07:06.910Z,1665104826.910 [NAL9602] No Fault, FailCount= 1
2022-10-07T01:07:36.374Z,1665104856.374 [NAL9602](INFO): Powering up NAL9602
2022-10-07T01:07:47.282Z,1665104867.282 [NAL9602](INFO): NAL9602 initialized
2022-10-07T01:08:27.283Z,1665104907.283 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2022-10-07T01:08:27.293Z,1665104907.293 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-10-07T01:08:27.316Z,1665104907.316 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-10-07T01:08:27.697Z,1665104907.697 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-10-07T01:08:27.697Z,1665104907.697 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2022-10-07T01:08:36.525Z,1665104916.525 [DataOverHttps](IMPORTANT): SBD MTMSN=20221007T010833
2022-10-07T01:08:43.868Z,1665104923.868 [DataOverHttps](INFO): Received command: failc
2022-10-07T01:08:43.932Z,1665104923.932 [CommandExec](IMPORTANT): got command failComponent
2022-10-07T01:08:43.933Z,1665104923.933 [CommandExec](IMPORTANT): Failed components:
2022-10-07T01:08:43.933Z,1665104923.933 [CommandExec](IMPORTANT): No failed Components.
2022-10-07T01:11:09.285Z,1665105069.285 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T01:11:09.285Z,1665105069.285 [DVL_micro](ERROR): Failed to parse:
:TS,00000000000000,35.0,+21.1,000.0,000
2022-10-07T01:11:16.069Z,1665105076.069 [CommandExec](IMPORTANT): got command show stack
2022-10-07T01:11:16.069Z,1665105076.069 [CommandExec](IMPORTANT): Behavior Stack:

2022-10-07T01:11:16.069Z,1665105076.069 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface
2022-10-07T01:11:16.070Z,1665105076.070 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:C.Wait
2022-10-07T01:11:28.276Z,1665105088.276 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 5
2022-10-07T01:11:28.276Z,1665105088.276 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2022-10-07T01:11:28.287Z,1665105088.287 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2022-10-07T01:11:28.699Z,1665105088.699 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2022-10-07T01:11:28.699Z,1665105088.699 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 5
2022-10-07T01:11:48.993Z,1665105108.993 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 36.8 degree
2022-10-07T01:11:48.997Z,1665105108.997 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread.
2022-10-07T01:11:48.997Z,1665105108.997 [CommandExec](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -121.9 degree
2022-10-07T01:11:49.001Z,1665105109.001 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread.
2022-10-07T01:11:49.314Z,1665105109.314 [controlThread](DEBUG): Component order: CycleStarter,ESPComponent,PAR_Licor,AHRS_M2,Depth_Keller,DVL_micro,NAL9602,Power24vConverter,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,ShortestDistanceToPolygonSidesCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,LcmUniversalReporter,Reporter,LogSplitter,
2022-10-07T01:11:57.785Z,1665105117.785 [Default:CheckIn:C.Wait](INFO): Done Waiting.
2022-10-07T01:11:57.785Z,1665105117.785 [Default:CheckIn:C.Wait] Stopped
2022-10-07T01:11:57.785Z,1665105117.785 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2022-10-07T01:11:57.785Z,1665105117.785 [Default:CheckIn:D] Running Loop=1
2022-10-07T01:11:58.189Z,1665105118.189 [Default:CheckIn:D] Stopped
2022-10-07T01:11:58.189Z,1665105118.189 [Default:CheckIn:E] Running Loop=1
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 12.302512 min 
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn:E] Stopped
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn](INFO): Completed Default:CheckIn
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn] Stopped
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-10-07T01:11:58.582Z,1665105118.582 [Default:CheckIn](INFO): Running loop #2
2022-10-07T01:11:58.583Z,1665105118.583 [Default:CheckIn] Running Loop=2
2022-10-07T01:11:58.583Z,1665105118.583 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2022-10-07T01:11:58.583Z,1665105118.583 [Default:CheckIn:Read_GPS] Running Loop=1
2022-10-07T01:12:21.488Z,1665105141.488 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1665105118 second
2022-10-07T01:12:21.625Z,1665105141.625 [Default:CheckIn:Read_GPS] Stopped
2022-10-07T01:12:21.625Z,1665105141.625 [Default:CheckIn:Read_Iridium] Running Loop=1
2022-10-07T01:12:24.289Z,1665105144.289 [CommandExec](IMPORTANT): got command get latitude
2022-10-07T01:12:24.289Z,1665105144.289 [CommandExec](IMPORTANT): latitude 36.799999 arcdeg
2022-10-07T01:12:33.284Z,1665105153.284 [DataOverHttps](INFO): Sending 156 bytes from file Logs/20221007T005613/Courier0007.lzma
2022-10-07T01:12:34.282Z,1665105154.282 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Courier0007.lzma.bak
2022-10-07T01:12:34.282Z,1665105154.282 [DataOverHttps](INFO): SBD MOMSN=17237401
2022-10-07T01:12:53.129Z,1665105173.129 [NAL9602](INFO): Not Powering down - fast GPS
2022-10-07T01:12:55.961Z,1665105175.961 [DataOverHttps](IMPORTANT): SBD MTMSN=20221007T011253
2022-10-07T01:13:02.483Z,1665105182.483 [DataOverHttps](INFO): Sending 649 bytes from file Logs/20221007T005613/Express0008.lzma
2022-10-07T01:13:02.487Z,1665105182.487 [DataOverHttps](INFO): Received command: load Maintenance/sample_lab.xml;set sample_lab.CartridgeType -6 count;run
2022-10-07T01:13:02.605Z,1665105182.605 [CommandExec](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml
2022-10-07T01:13:02.606Z,1665105182.606 [MissionManager](INFO): Loading Mission from file: ./Missions/Maintenance/sample_lab.xml
2022-10-07T01:13:02.659Z,1665105182.659 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min
2022-10-07T01:13:02.662Z,1665105182.662 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count
2022-10-07T01:13:02.665Z,1665105182.665 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count
2022-10-07T01:13:02.667Z,1665105182.667 [sample_lab:A.AbortSample](DEBUG): Construct.
2022-10-07T01:13:02.670Z,1665105182.670 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct.
2022-10-07T01:13:02.676Z,1665105182.676 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Sample="Tethys/Sample"
         xmlns:Science="Tethys/Science"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Sample http://okeanids.mbari.org/tethys/Xml/Sample.xsd
                             Tethys/Science http://okeanids.mbari.org/tethys/Xml/Science.xsd"
       Id="sample_lab">

    <Description>
        This mission is designed to run in the lab only and triggers an ESP
        sample with specified type.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="CartridgeType"><Description>
        Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4)
    </Description><Units:count/><Value>-4</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

    <Sample:AbortSample>
        <Parallel/>
    </Sample:AbortSample>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Syslog Severity="Important">Sampling ESP cartridge type <Arg Name="CartridgeType"/><Units:count/></Syslog>

        <Science:ESPCartridgeSelect>
            <Sequence/>
            <Timeout Duration="P1M"/>
            <Setting><Science:ESPCartridgeSelect.cartridgeType/><Arg Name="CartridgeType"/></Setting>
        </Science:ESPCartridgeSelect>

        <ReadDatum Id="TriggerESP">
            <Science:ESPComponent.sampling/>
        </ReadDatum>

        <ReadDatum Id="WaitForESP">
            <Science:ESPComponent.sample_number/>
        </ReadDatum>

    </Aggregate>

</Mission>


2022-10-07T01:13:02.676Z,1665105182.676 [CommandExec](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml
2022-10-07T01:13:03.910Z,1665105183.910 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Express0008.lzma.bak
2022-10-07T01:13:03.910Z,1665105183.910 [DataOverHttps](INFO): SBD MOMSN=17237404
2022-10-07T01:13:04.727Z,1665105184.727 [CommandExec](IMPORTANT): got command set sample_lab.CartridgeType -6 count
2022-10-07T01:13:04.734Z,1665105184.734 [CommandExec](IMPORTANT): got command run
2022-10-07T01:13:04.740Z,1665105184.740 [CommandExec](IMPORTANT): Running 
2022-10-07T01:13:04.854Z,1665105184.854 [Default] Stopped
2022-10-07T01:13:04.854Z,1665105184.854 [Default](DEBUG): Aggregate::uninitialize Default
2022-10-07T01:13:04.854Z,1665105184.854 [Default:B.GoToSurface] Stopped
2022-10-07T01:13:04.854Z,1665105184.854 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2022-10-07T01:13:04.854Z,1665105184.854 [Default:CheckIn] Stopped
2022-10-07T01:13:04.854Z,1665105184.854 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2022-10-07T01:13:04.854Z,1665105184.854 [Default:CheckIn:Read_Iridium] Stopped
2022-10-07T01:13:04.854Z,1665105184.854 [MissionManager](IMPORTANT): Started mission sample_lab
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab] Running Loop=1
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab](DEBUG): Aggregate::initialize sample_lab
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab:A.AbortSample] Running Loop=1
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab:A.AbortSample](INFO): Initializing AbortSample.
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab:SampleRepeater] Running Loop=1
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater
2022-10-07T01:13:04.855Z,1665105184.855 [sample_lab:SampleRepeater:A] Running Loop=1
2022-10-07T01:13:04.860Z,1665105184.860 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -6.000000 count 
2022-10-07T01:13:04.860Z,1665105184.860 [sample_lab:SampleRepeater:A] Stopped
2022-10-07T01:13:04.860Z,1665105184.860 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1
2022-10-07T01:13:04.861Z,1665105184.861 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect.
2022-10-07T01:13:04.861Z,1665105184.861 [sample_lab:A.AbortSample] Running Loop=1
2022-10-07T01:13:05.278Z,1665105185.278 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -6.
2022-10-07T01:13:05.278Z,1665105185.278 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped
2022-10-07T01:13:05.279Z,1665105185.279 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect.
2022-10-07T01:13:05.279Z,1665105185.279 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1
2022-10-07T01:13:05.681Z,1665105185.681 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2022-10-07T01:13:06.433Z,1665105186.433 [ESPComponent](IMPORTANT): Setting regex for ESP Log summary: 'Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:'
2022-10-07T01:13:06.480Z,1665105186.480 [ESPComponent](INFO): compiled regex: "Selecting Cartridge|Sampled|Error|Underpressure|Overpressure|Fail|Retry|Cmd::|Sampler::|summary:"
2022-10-07T01:13:06.481Z,1665105186.481 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence
2022-10-07T01:13:16.533Z,1665105196.533 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence
2022-10-07T01:13:16.535Z,1665105196.535 [ESPComponent](INFO): powering up ESP
2022-10-07T01:13:16.552Z,1665105196.552 [ESPComponent](INFO): powering up ESP secondary power supply
2022-10-07T01:13:16.568Z,1665105196.568 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2022-10-07T01:13:16.891Z,1665105196.891 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2022-10-07T01:13:17.817Z,1665105197.817 [ESPComponent](INFO): console:

2022-10-07T01:13:18.221Z,1665105198.221 [ESPComponent](INFO): console:NAND:  256 MiB
2022-10-07T01:13:18.629Z,1665105198.629 [ESPComponent](INFO): console:
BOOTMODE: SPI
2022-10-07T01:13:19.029Z,1665105199.029 [ESPComponent](INFO): console:
reading SPI NOR..Done
2022-10-07T01:13:19.433Z,1665105199.433 [ESPComponent](INFO): console:

2022-10-07T01:13:19.837Z,1665105199.837 [ESPComponent](INFO): console:

2022-10-07T01:13:20.242Z,1665105200.242 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariD (Jun 28 2020 - 19:44:45)
2022-10-07T01:13:20.645Z,1665105200.645 [ESPComponent](INFO): console:

2022-10-07T01:13:21.050Z,1665105201.050 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2022-10-07T01:13:21.499Z,1665105201.499 [ESPComponent](INFO): console:
flash params are already written into flash
2022-10-07T01:13:21.857Z,1665105201.857 [ESPComponent](INFO): console:
DRAM:  64 MB
2022-10-07T01:13:22.262Z,1665105202.262 [ESPComponent](INFO): console:
In:    serial
2022-10-07T01:13:22.665Z,1665105202.665 [ESPComponent](INFO): console:
Out:   serial
2022-10-07T01:13:23.069Z,1665105203.069 [ESPComponent](INFO): console:
Err:   serial
2022-10-07T01:13:23.474Z,1665105203.474 [ESPComponent](INFO): console:
Net:   ks8851_mll
2022-10-07T01:13:23.878Z,1665105203.878 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2022-10-07T01:13:24.282Z,1665105204.282 [ESPComponent](INFO): console:
4096 KiB S25FL032P at 0:0 is now current device
2022-10-07T01:13:24.687Z,1665105204.687 [ESPComponent](INFO): console:
Loading kernel from SPI flash...done
2022-10-07T01:13:25.090Z,1665105205.090 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2022-10-07T01:13:25.494Z,1665105205.494 [ESPComponent](INFO): console:
   Image Name:   Linux-3.18.140-lpc31-mbari4
2022-10-07T01:13:25.898Z,1665105205.898 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2022-10-07T01:13:26.303Z,1665105206.303 [ESPComponent](INFO): console:
   Data Size:    2336344 Bytes =  2.2 MB
2022-10-07T01:13:26.705Z,1665105206.705 [ESPComponent](INFO): console:
   Load Address: 30008000
2022-10-07T01:13:27.110Z,1665105207.110 [ESPComponent](INFO): console:
   Entry Point:  30008000
2022-10-07T01:13:27.513Z,1665105207.513 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2022-10-07T01:13:27.917Z,1665105207.917 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2022-10-07T01:13:28.321Z,1665105208.321 [ESPComponent](INFO): console:
OK
2022-10-07T01:13:28.725Z,1665105208.725 [ESPComponent](INFO): console:

2022-10-07T01:13:29.130Z,1665105209.130 [ESPComponent](INFO): console:
Starting kernel ...
2022-10-07T01:13:29.533Z,1665105209.533 [ESPComponent](INFO): console:

2022-10-07T01:13:29.938Z,1665105209.938 [ESPComponent](INFO): console:
Uncompressing Linux... Booting kernel...
2022-10-07T01:13:30.341Z,1665105210.341 [ESPComponent](INFO): console:
[    0.03] MBARI ESP 3G
2022-10-07T01:13:30.745Z,1665105210.745 [ESPComponent](INFO): console:

2022-10-07T01:13:31.150Z,1665105211.150 [ESPComponent](INFO): console:INIT: version 2.85 booting
2022-10-07T01:13:31.553Z,1665105211.553 [ESPComponent](INFO): console:

2022-10-07T01:13:31.959Z,1665105211.959 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2022-10-07T01:13:32.361Z,1665105212.361 [ESPComponent](INFO): console:
ESPmv1
2022-10-07T01:13:32.765Z,1665105212.765 [ESPComponent](INFO): console:

2022-10-07T01:13:33.171Z,1665105213.171 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2022-10-07T01:13:33.573Z,1665105213.573 [ESPComponent](INFO): console:

2022-10-07T01:13:33.977Z,1665105213.977 [ESPComponent](INFO): console:Loading kernel modules
2022-10-07T01:13:34.382Z,1665105214.382 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2022-10-07T01:13:34.786Z,1665105214.786 [ESPComponent](INFO): console:
Starting device events handler
2022-10-07T01:13:35.260Z,1665105215.260 [ESPComponent](INFO): console:

2022-10-07T01:13:38.084Z,1665105218.084 [ESPComponent](INFO): console:Set system clock to:  
2022-10-07T01:13:39.230Z,1665105219.230 [ESPComponent](INFO): console:Thu Oct  6 18:13:37 PDT 2022
2022-10-07T01:13:39.634Z,1665105219.634 [ESPComponent](INFO): console:
Starting syslogd klogd...
2022-10-07T01:13:40.043Z,1665105220.043 [ESPComponent](INFO): console:
stopped syslogd (pid 689)
2022-10-07T01:13:40.446Z,1665105220.446 [ESPComponent](INFO): console:
Bringing up lo ...
2022-10-07T01:13:40.848Z,1665105220.848 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2022-10-07T01:13:41.250Z,1665105221.250 [ESPComponent](INFO): console:
Packet forwarding enabled
2022-10-07T01:13:41.654Z,1665105221.654 [ESPComponent](INFO): console:
Bringing up wg2shore ...
2022-10-07T01:13:42.058Z,1665105222.058 [ESPComponent](INFO): console:
[#] ip link add wg2shore type wireguard
2022-10-07T01:13:42.532Z,1665105222.532 [ESPComponent](INFO): console:

2022-10-07T01:13:43.674Z,1665105223.674 [ESPComponent](INFO): console:[#] wg setconf wg2shore /dev/fd/63
2022-10-07T01:13:44.080Z,1665105224.080 [ESPComponent](INFO): console:
[#] ip -4 address add 192.168.5.31 dev wg2shore
2022-10-07T01:13:44.482Z,1665105224.482 [ESPComponent](INFO): console:
[#] ip link set mtu 1420 up dev wg2shore
2022-10-07T01:13:44.886Z,1665105224.886 [ESPComponent](INFO): console:
[#] ip -4 route add 192.168.4.0/23 dev wg2shore
2022-10-07T01:13:45.290Z,1665105225.290 [ESPComponent](INFO): console:
Bringing up platform ...
2022-10-07T01:13:45.693Z,1665105225.693 [ESPComponent](INFO): console:
Starting netplugd...
2022-10-07T01:13:46.097Z,1665105226.097 [ESPComponent](INFO): console:
Starting portmap...
2022-10-07T01:13:46.499Z,1665105226.499 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20221007T005613/Courier0013.lzma
2022-10-07T01:13:46.508Z,1665105226.508 [ESPComponent](INFO): console:
Network unavailable:  Local time is Thu Oct  6 18:13:43 PDT 2022
2022-10-07T01:13:46.910Z,1665105226.910 [ESPComponent](INFO): console:
Starting chronyd...
2022-10-07T01:13:47.313Z,1665105227.313 [ESPComponent](INFO): console:
Starting thttpd...
2022-10-07T01:13:47.502Z,1665105227.502 [DataOverHttps](INFO): Moved sent file to Logs/20221007T005613/Courier0013.lzma.bak
2022-10-07T01:13:47.502Z,1665105227.502 [DataOverHttps](INFO): SBD MOMSN=17237420
2022-10-07T01:13:47.717Z,1665105227.717 [ESPComponent](INFO): console:
Starting dnsmasq...
2022-10-07T01:13:48.192Z,1665105228.192 [ESPComponent](INFO): console:

2022-10-07T01:13:49.737Z,1665105229.737 [ESPComponent](INFO): console:Bringing up wired ...
2022-10-07T01:13:50.212Z,1665105230.212 [ESPComponent](INFO): console:

2022-10-07T01:13:50.545Z,1665105230.545 [ESPComponent](INFO): console:

2022-10-07T01:13:50.950Z,1665105230.950 [ESPComponent](INFO): console:
MBARI ESP Embedded Linux 2.75a -- 4/28/22 brent@mbari.org
2022-10-07T01:13:51.353Z,1665105231.353 [ESPComponent](INFO): console:

2022-10-07T01:13:51.758Z,1665105231.758 [ESPComponent](INFO): console:ESPmv1 login: Determining IP configuration for wired ...udhcpc (v1.11.2) started
2022-10-07T01:13:52.161Z,1665105232.161 [ESPComponent](INFO): console:
Sending discover...
2022-10-07T01:13:52.628Z,1665105232.628 [ESPComponent](INFO): console:

2022-10-07T01:13:54.182Z,1665105234.182 [ESPComponent](INFO): console:Sending discover...
2022-10-07T01:13:54.656Z,1665105234.656 [ESPComponent](INFO): console:

2022-10-07T01:13:57.031Z,1665105237.031 [ESPComponent](INFO): console:Sending discover...
2022-10-07T01:13:57.496Z,1665105237.496 [ESPComponent](INFO): console:

2022-10-07T01:14:00.241Z,1665105240.241 [ESPComponent](INFO): console:No lease, forking to background
2022-10-07T01:14:00.718Z,1665105240.718 [ESPComponent](INFO): console:

2022-10-07T01:14:01.050Z,1665105241.050 [ESPComponent](INFO): console:Bringing up direct ...
2022-10-07T01:14:01.527Z,1665105241.527 [ESPComponent](INFO): console:

2022-10-07T01:14:01.857Z,1665105241.857 [ESPComponent](INFO): console:direct IP=10.10.10.10
2022-10-07T01:14:02.334Z,1665105242.334 [ESPComponent](INFO): console:

2022-10-07T01:14:18.421Z,1665105258.421 [ESPComponent](IMPORTANT): ESP has connected as client
2022-10-07T01:14:19.323Z,1665105259.323 [ESPComponent](IMPORTANT): [sample #1] Setting cartridge argument to -6
2022-10-07T01:14:19.323Z,1665105259.323 [ESPComponent](IMPORTANT): [sample #1] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2022-10-07T01:14:19.324Z,1665105259.324 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=1
2022-10-07T01:14:19.383Z,1665105259.383 [sample_lab:SampleRepeater:TriggerESP] Stopped
2022-10-07T01:14:19.388Z,1665105259.388 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1
2022-10-07T01:14:19.668Z,1665105259.668 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2022-10-07T01:14:20.442Z,1665105260.442 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_LOG
2022-10-07T01:14:20.845Z,1665105260.845 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PREPARING_SHOW_STATUS
2022-10-07T01:14:22.461Z,1665105262.461 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_LOADING_CARTRIDGE
2022-10-07T01:14:56.802Z,1665105296.802 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PRIMING (@59,archive_bac)
2022-10-07T01:14:59.226Z,1665105299.226 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_PRIMING (@100.0)
2022-10-07T01:14:59.227Z,1665105299.227 [ESPComponent](IMPORTANT): Filtering timeoutMinutes=92.070000 issuedCmd_=Cmd.startFiltering
2022-10-07T01:14:59.629Z,1665105299.629 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_FILTERING (@100.0)
2022-10-07T01:15:12.549Z,1665105312.549 [CommandExec](IMPORTANT): got command set NAL9602.time_fix 1665105299 second
2022-10-07T01:17:18.606Z,1665105438.606 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_FILTERING (@0.0)
2022-10-07T01:17:19.009Z,1665105439.009 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_WAITING_FOR_PAUSED (@0.0)
2022-10-07T01:18:32.164Z,1665105512.164 [DVL_micro](ERROR): only read 3 of 4 data items
2022-10-07T01:18:32.164Z,1665105512.164 [DVL_micro](ERROR): Failed to parse:
:BI,-00097,-0001,+00000,I
2022-10-07T01:21:09.810Z,1665105669.810 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error
2022-10-07T01:21:09.810Z,1665105669.810 [DVL_micro](ERROR): Failed to parse:
:TS,000000035.0,+21.3,0000.0,1489.0,000
2022-10-07T01:21:12.249Z,1665105672.249 [DVL_micro](ERROR): Failed to parse:
:WI,+00064,-00014,-00409,+00000,A
2022-10-07T01:26:53.186Z,1665106013.186 [DVL_micro](ERROR): Failed to parse:
:R99,+9999.99,+9999.99,+9999.99
2022-10-07T01:31:07.795Z,1665106267.795 [DVL_micro](ERROR): Failed to parse:
:SA,-03.67,+05.62,178.4
2022-10-07T01:31:46.091Z,1665106306.091 [DVL_micro](ERROR): only read 0 of 4 data items
2022-10-07T01:31:46.091Z,1665106306.091 [DVL_micro](ERROR): Failed to parse:
:RD9,+9999.99,+9999.99,+9999.99
2022-10-07T01:31:59.812Z,1665106319.812 [ESPComponent](ERROR): In state S_WAITING_FOR_PAUSED got exception while awaiting completion of cmd='Cmd.startFiltering' exception=<<Thread::ChildDied in LRAUV -- :FILTERING
>>. Elapsed time since command issued: 1023.4125
2022-10-07T01:32:00.213Z,1665106320.213 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPING (@426.6)
2022-10-07T01:32:07.486Z,1665106327.486 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr*' /LRAUV/ESPlogs &
2022-10-07T01:32:07.508Z,1665106327.508 [ESPComponent](INFO): closing pipe.
2022-10-07T01:32:07.890Z,1665106327.890 [ESPComponent](IMPORTANT): [sample #1] ESP sampling state: S_STOPPED
2022-10-07T01:33:50.537Z,1665106430.537 [CommandLine](INFO): End of History
2022-10-07T01:34:01.562Z,1665106441.562 [CommandLine](INFO): End of History
2022-10-07T01:34:01.562Z,1665106441.562 [CommandLine](INFO): End of History
2022-10-07T01:34:01.563Z,1665106441.563 [CommandLine](INFO): End of History
2022-10-07T01:34:01.563Z,1665106441.563 [CommandLine](INFO): End of History
2022-10-07T01:34:01.576Z,1665106441.576 [CommandLine](INFO): End of History
2022-10-07T01:34:01.577Z,1665106441.577 [CommandLine](INFO): End of History
2022-10-07T01:34:01.578Z,1665106441.578 [CommandLine](INFO): End of History
2022-10-07T01:34:01.578Z,1665106441.578 [CommandLine](INFO): End of History
2022-10-07T01:34:01.579Z,1665106441.579 [CommandLine](INFO): End of History
2022-10-07T01:34:11.148Z,1665106451.148 [DVL_micro](ERROR): Failed to parse:000000.00,+00000000.00,+00000000.00,9999.99,000.00
2022-10-07T01:34:12.305Z,1665106452.305 [CommandLine](INFO): End of History
2022-10-07T01:34:12.306Z,1665106452.306 [CommandLine](INFO): End of History
2022-10-07T01:34:12.306Z,1665106452.306 [CommandLine](INFO): End of History
2022-10-07T01:34:12.307Z,1665106452.307 [CommandLine](INFO): End of History
2022-10-07T01:34:12.307Z,1665106452.307 [CommandLine](INFO): End of History
2022-10-07T01:34:12.312Z,1665106452.312 [CommandLine](INFO): End of History
2022-10-07T01:34:12.313Z,1665106452.313 [CommandLine](INFO): End of History
2022-10-07T01:34:12.314Z,1665106452.314 [CommandLine](INFO): End of History
2022-10-07T01:34:12.314Z,1665106452.314 [CommandLine](INFO): End of History
2022-10-07T01:34:12.315Z,1665106452.315 [CommandLine](INFO): End of History
2022-10-07T01:34:12.315Z,1665106452.315 [CommandLine](INFO): End of History
2022-10-07T01:34:12.368Z,1665106452.368 [CommandLine](INFO): End of History
2022-10-07T01:34:12.369Z,1665106452.369 [CommandLine](INFO): End of History
2022-10-07T01:34:12.370Z,1665106452.370 [CommandLine](INFO): End of History
2022-10-07T01:34:12.370Z,1665106452.370 [CommandLine](INFO): End of History
2022-10-07T01:34:12.371Z,1665106452.371 [CommandLine](INFO): End of History
2022-10-07T01:35:02.975Z,1665106502.975 [CommandLine](INFO): End of History
2022-10-07T01:35:02.991Z,1665106502.991 [CommandLine](INFO): End of History
2022-10-07T01:35:03.012Z,1665106503.012 [CommandLine](INFO): End of History
2022-10-07T01:35:03.020Z,1665106503.020 [CommandLine](INFO): End of History
2022-10-07T01:35:03.