2025-05-12T18:59:05.881Z,1747076345.881 [Supervisor](DEBUG): Initializing supervisor.
2025-05-12T18:59:05.885Z,1747076345.885 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2025-05-12T18:59:05.886Z,1747076345.886 [SyncHandler](INFO): Protected caller Thread ID is 840
2025-05-12T18:59:05.886Z,1747076345.886 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2025-05-12T18:59:05.887Z,1747076345.887 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2025-05-12T18:59:05.888Z,1747076345.888 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 841
2025-05-12T18:59:05.892Z,1747076345.892 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2025-05-12T18:59:05.912Z,1747076345.912 [ComponentRegistry](DEBUG): Component "CommandExec" handled in its own thread.
2025-05-12T18:59:05.913Z,1747076345.913 [CommandExec ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2025-05-12T18:59:05.914Z,1747076345.914 [CommandExec ThreadHandler](INFO): Protected caller Thread ID is 842
2025-05-12T18:59:05.918Z,1747076345.918 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2025-05-12T18:59:05.919Z,1747076345.919 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2025-05-12T18:59:05.920Z,1747076345.920 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 843
2025-05-12T18:59:05.922Z,1747076345.922 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2025-05-12T18:59:05.923Z,1747076345.923 [logger ThreadHandler](DEBUG): Created PCaller Thread at 405114E0
2025-05-12T18:59:05.923Z,1747076345.923 [logger ThreadHandler](INFO): Protected caller Thread ID is 844
2025-05-12T18:59:05.927Z,1747076345.927 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2025-05-12T18:59:05.928Z,1747076345.928 [Supervisor](INFO): Looking for Config files in directory: Config/
2025-05-12T18:59:05.931Z,1747076345.931 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2025-05-12T18:59:06.160Z,1747076346.160 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2025-05-12T18:59:06.161Z,1747076346.161 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2025-05-12T18:59:06.292Z,1747076346.292 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2025-05-12T18:59:06.294Z,1747076346.294 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2025-05-12T18:59:06.401Z,1747076346.401 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2025-05-12T18:59:06.403Z,1747076346.403 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2025-05-12T18:59:06.928Z,1747076346.928 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2025-05-12T18:59:06.930Z,1747076346.930 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2025-05-12T18:59:07.319Z,1747076347.319 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2025-05-12T18:59:07.319Z,1747076347.319 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2025-05-12T18:59:07.690Z,1747076347.690 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2025-05-12T18:59:07.691Z,1747076347.691 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2025-05-12T18:59:07.895Z,1747076347.895 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2025-05-12T18:59:07.896Z,1747076347.896 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2025-05-12T18:59:07.987Z,1747076347.987 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2025-05-12T18:59:08.080Z,1747076348.080 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2025-05-12T18:59:08.522Z,1747076348.522 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2025-05-12T18:59:08.523Z,1747076348.523 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2025-05-12T18:59:08.826Z,1747076348.826 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2025-05-12T18:59:08.827Z,1747076348.827 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2025-05-12T18:59:09.694Z,1747076349.694 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2025-05-12T18:59:09.695Z,1747076349.695 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2025-05-12T18:59:10.173Z,1747076350.173 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2025-05-12T18:59:10.175Z,1747076350.175 [Supervisor](INFO): Opening Config file at: Config/Dock.cfg
2025-05-12T18:59:10.445Z,1747076350.445 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Dock
2025-05-12T18:59:10.446Z,1747076350.446 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2025-05-12T18:59:10.601Z,1747076350.601 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2025-05-12T18:59:10.603Z,1747076350.603 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2025-05-12T18:59:11.554Z,1747076351.554 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2025-05-12T18:59:11.556Z,1747076351.556 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-galene/
2025-05-12T18:59:11.559Z,1747076351.559 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/secure.cfg
2025-05-12T18:59:11.655Z,1747076351.655 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/vehicle.cfg
2025-05-12T18:59:11.800Z,1747076351.800 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Battery.cfg
2025-05-12T18:59:12.082Z,1747076352.082 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2025-05-12T18:59:12.084Z,1747076352.084 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Science.cfg
2025-05-12T18:59:12.226Z,1747076352.226 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Control.cfg
2025-05-12T18:59:12.339Z,1747076352.339 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/logger.cfg
2025-05-12T18:59:12.446Z,1747076352.446 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Servo.cfg
2025-05-12T18:59:12.569Z,1747076352.569 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Navigation.cfg
2025-05-12T18:59:12.667Z,1747076352.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Simulator.cfg
2025-05-12T18:59:12.766Z,1747076352.766 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/BIT.cfg
2025-05-12T18:59:12.872Z,1747076352.872 [Supervisor](INFO): Opening Config file at: Config/lrauv-galene/Sensor.cfg
2025-05-12T18:59:13.062Z,1747076353.062 [Supervisor](IMPORTANT): Reloading configuration overrides from Data/persisted.cfg
2025-05-12T18:59:13.077Z,1747076353.077 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2025-05-12T18:59:13.150Z,1747076353.150 [DepthRateCalculator] Loaded
2025-05-12T18:59:13.151Z,1747076353.151 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2025-05-12T18:59:13.156Z,1747076353.156 [PitchRateCalculator] Loaded
2025-05-12T18:59:13.157Z,1747076353.157 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2025-05-12T18:59:13.168Z,1747076353.168 [SpeedCalculator] Loaded
2025-05-12T18:59:13.168Z,1747076353.168 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2025-05-12T18:59:13.173Z,1747076353.173 [YawRateCalculator] Loaded
2025-05-12T18:59:13.173Z,1747076353.173 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2025-05-12T18:59:13.196Z,1747076353.196 [ElevatorOffsetCalculator] Loaded
2025-05-12T18:59:13.196Z,1747076353.196 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2025-05-12T18:59:13.197Z,1747076353.197 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2025-05-12T18:59:13.197Z,1747076353.197 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2025-05-12T18:59:13.246Z,1747076353.246 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2025-05-12T18:59:13.246Z,1747076353.246 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2025-05-12T18:59:13.262Z,1747076353.262 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2025-05-12T18:59:13.263Z,1747076353.263 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2025-05-12T18:59:14.157Z,1747076354.157 [AHRS_M2] Loaded
2025-05-12T18:59:14.157Z,1747076354.157 [ComponentRegistry](DEBUG): SyncComponent "AHRS_M2" handled in the control thread.
2025-05-12T18:59:14.418Z,1747076354.418 [BackseatComponent] Loaded
2025-05-12T18:59:14.419Z,1747076354.419 [ComponentRegistry](DEBUG): Component "BackseatComponent" handled in its own thread.
2025-05-12T18:59:14.420Z,1747076354.420 [BackseatComponent ThreadHandler](DEBUG): Created PCaller Thread at 408754E0
2025-05-12T18:59:14.420Z,1747076354.420 [BackseatComponent ThreadHandler](INFO): Protected caller Thread ID is 927
2025-05-12T18:59:14.423Z,1747076354.423 [LcmUniversalReporter] Loaded
2025-05-12T18:59:14.423Z,1747076354.423 [ComponentRegistry](DEBUG): SyncComponent "LcmUniversalReporter" handled in the control thread.
2025-05-12T18:59:15.678Z,1747076355.678 [BPC1] Loaded
2025-05-12T18:59:15.678Z,1747076355.678 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2025-05-12T18:59:15.779Z,1747076355.779 [DAT] Loaded
2025-05-12T18:59:15.779Z,1747076355.779 [ComponentRegistry](DEBUG): Component "DAT" handled in its own thread.
2025-05-12T18:59:15.780Z,1747076355.780 [DAT ThreadHandler](DEBUG): Created PCaller Thread at 408A54E0
2025-05-12T18:59:15.781Z,1747076355.781 [DAT ThreadHandler](INFO): Protected caller Thread ID is 928
2025-05-12T18:59:15.929Z,1747076355.929 [DataOverHttps] Loaded
2025-05-12T18:59:15.929Z,1747076355.929 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread.
2025-05-12T18:59:15.930Z,1747076355.930 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 408D54E0
2025-05-12T18:59:15.930Z,1747076355.930 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 929
2025-05-12T18:59:15.953Z,1747076355.953 [Depth_Keller] Loaded
2025-05-12T18:59:15.953Z,1747076355.953 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2025-05-12T18:59:15.958Z,1747076355.958 [DropWeight] Loaded
2025-05-12T18:59:15.959Z,1747076355.959 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2025-05-12T18:59:15.980Z,1747076355.980 [MultiRay](INFO): Found secondary power supply at: /dev/loadC7
2025-05-12T18:59:15.980Z,1747076355.980 [MultiRay] Loaded
2025-05-12T18:59:15.980Z,1747076355.980 [ComponentRegistry](DEBUG): SyncComponent "MultiRay" handled in the control thread.
2025-05-12T18:59:16.045Z,1747076356.045 [NAL9602] Loaded
2025-05-12T18:59:16.046Z,1747076356.046 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2025-05-12T18:59:16.076Z,1747076356.076 [Onboard] Loaded
2025-05-12T18:59:16.076Z,1747076356.076 [ComponentRegistry](DEBUG): Component "Onboard" handled in its own thread.
2025-05-12T18:59:16.077Z,1747076356.077 [Onboard ThreadHandler](DEBUG): Created PCaller Thread at 409054E0
2025-05-12T18:59:16.077Z,1747076356.077 [Onboard ThreadHandler](INFO): Protected caller Thread ID is 930
2025-05-12T18:59:16.084Z,1747076356.084 [PowerOnly](INFO): Adding load control power supply at /dev/loadC3
2025-05-12T18:59:16.097Z,1747076356.097 [PowerOnly] Loaded
2025-05-12T18:59:16.097Z,1747076356.097 [ComponentRegistry](DEBUG): SyncComponent "PowerOnly" handled in the control thread.
2025-05-12T18:59:16.111Z,1747076356.111 [Power24vConverter] Loaded
2025-05-12T18:59:16.112Z,1747076356.112 [ComponentRegistry](DEBUG): SyncComponent "Power24vConverter" handled in the control thread.
2025-05-12T18:59:16.129Z,1747076356.129 [Radio_Surface] Loaded
2025-05-12T18:59:16.129Z,1747076356.129 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2025-05-12T18:59:16.130Z,1747076356.130 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 409354E0
2025-05-12T18:59:16.130Z,1747076356.130 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 931
2025-05-12T18:59:16.131Z,1747076356.131 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2025-05-12T18:59:16.132Z,1747076356.132 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2025-05-12T18:59:16.272Z,1747076356.272 [DeadReckonUsingMultipleVelocitySources] Loaded
2025-05-12T18:59:16.273Z,1747076356.273 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread.
2025-05-12T18:59:16.287Z,1747076356.287 [NavChart] Loaded
2025-05-12T18:59:16.287Z,1747076356.287 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2025-05-12T18:59:16.293Z,1747076356.293 [UniversalFixResidualReporter] Loaded
2025-05-12T18:59:16.293Z,1747076356.293 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2025-05-12T18:59:16.294Z,1747076356.294 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2025-05-12T18:59:16.294Z,1747076356.294 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2025-05-12T18:59:16.494Z,1747076356.494 [SBIT](DEBUG): Construct Startup Built In Test.
2025-05-12T18:59:16.509Z,1747076356.509 [SBIT] Loaded
2025-05-12T18:59:16.509Z,1747076356.509 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2025-05-12T18:59:16.512Z,1747076356.512 [IBIT](DEBUG): Construct Initiated Built In Test.
2025-05-12T18:59:16.525Z,1747076356.525 [IBIT] Loaded
2025-05-12T18:59:16.526Z,1747076356.526 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2025-05-12T18:59:16.531Z,1747076356.531 [CBIT](DEBUG): Construct Continuous Built In Test.
2025-05-12T18:59:16.612Z,1747076356.612 [CBIT] Loaded
2025-05-12T18:59:16.613Z,1747076356.613 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2025-05-12T18:59:16.644Z,1747076356.644 [GFScanner] Loaded
2025-05-12T18:59:16.645Z,1747076356.645 [ComponentRegistry](DEBUG): SyncComponent "GFScanner" handled in the control thread.
2025-05-12T18:59:16.645Z,1747076356.645 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2025-05-12T18:59:16.646Z,1747076356.646 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2025-05-12T18:59:16.866Z,1747076356.866 [CTD_Seabird] Loaded
2025-05-12T18:59:16.867Z,1747076356.867 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2025-05-12T18:59:16.868Z,1747076356.868 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 40A474E0
2025-05-12T18:59:16.868Z,1747076356.868 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 932
2025-05-12T18:59:16.889Z,1747076356.889 [PAR_Licor] Loaded
2025-05-12T18:59:16.889Z,1747076356.889 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2025-05-12T18:59:16.935Z,1747076356.935 [WetLabsBB2FL] Loaded
2025-05-12T18:59:16.936Z,1747076356.936 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2025-05-12T18:59:16.936Z,1747076356.936 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 40A774E0
2025-05-12T18:59:16.937Z,1747076356.937 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 933
2025-05-12T18:59:16.938Z,1747076356.938 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2025-05-12T18:59:16.938Z,1747076356.938 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2025-05-12T18:59:17.110Z,1747076357.110 [BuoyancyServo] Loaded
2025-05-12T18:59:17.110Z,1747076357.110 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2025-05-12T18:59:17.135Z,1747076357.135 [ElevatorServo] Loaded
2025-05-12T18:59:17.135Z,1747076357.135 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread.
2025-05-12T18:59:17.159Z,1747076357.159 [MassServo] Loaded
2025-05-12T18:59:17.159Z,1747076357.159 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread.
2025-05-12T18:59:17.182Z,1747076357.182 [RudderServo] Loaded
2025-05-12T18:59:17.182Z,1747076357.182 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread.
2025-05-12T18:59:17.201Z,1747076357.201 [ThrusterHE] Loaded
2025-05-12T18:59:17.201Z,1747076357.201 [ComponentRegistry](DEBUG): SyncComponent "ThrusterHE" handled in the control thread.
2025-05-12T18:59:17.201Z,1747076357.201 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2025-05-12T18:59:17.202Z,1747076357.202 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2025-05-12T18:59:17.275Z,1747076357.275 [VerticalControl](DEBUG): Construct VerticalControl.
2025-05-12T18:59:17.329Z,1747076357.329 [VerticalControl] Loaded
2025-05-12T18:59:17.329Z,1747076357.329 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2025-05-12T18:59:17.332Z,1747076357.332 [HorizontalControl](DEBUG): Construct HorizontalControl.
2025-05-12T18:59:17.377Z,1747076357.377 [HorizontalControl] Loaded
2025-05-12T18:59:17.378Z,1747076357.378 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2025-05-12T18:59:17.380Z,1747076357.380 [SpeedControl](DEBUG): Construct SpeedControl.
2025-05-12T18:59:17.382Z,1747076357.382 [SpeedControl] Loaded
2025-05-12T18:59:17.382Z,1747076357.382 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2025-05-12T18:59:17.385Z,1747076357.385 [LoopControl](DEBUG): Construct LoopControl.
2025-05-12T18:59:17.385Z,1747076357.385 [LoopControl] Loaded
2025-05-12T18:59:17.386Z,1747076357.386 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2025-05-12T18:59:17.386Z,1747076357.386 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2025-05-12T18:59:17.387Z,1747076357.387 [Module Loader](DEBUG): Loading Module at Modules/Dock.so
2025-05-12T18:59:17.553Z,1747076357.553 [Module Loader](DEBUG): Loaded Module: Dock (Contains behaviors and commands for docking)
2025-05-12T18:59:17.554Z,1747076357.554 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2025-05-12T18:59:17.774Z,1747076357.774 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2025-05-12T18:59:17.775Z,1747076357.775 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2025-05-12T18:59:18.193Z,1747076358.193 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2025-05-12T18:59:18.194Z,1747076358.194 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2025-05-12T18:59:18.282Z,1747076358.282 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2025-05-12T18:59:18.289Z,1747076358.289 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2025-05-12T18:59:18.291Z,1747076358.291 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2025-05-12T18:59:18.303Z,1747076358.303 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2025-05-12T18:59:18.304Z,1747076358.304 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40C654E0
2025-05-12T18:59:18.304Z,1747076358.304 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 934
2025-05-12T18:59:18.309Z,1747076358.309 [Supervisor](INFO): Main Thread ID is 832
2025-05-12T18:59:18.309Z,1747076358.309 [Supervisor](DEBUG): Running supervisor.
2025-05-12T18:59:18.310Z,1747076358.310 [CommandExec ThreadHandler](INFO): Handler Thread ID is 935
2025-05-12T18:59:18.310Z,1747076358.310 [CommandExec](INFO): Initializing the command executive.
2025-05-12T18:59:18.312Z,1747076358.312 [CommandLine ThreadHandler](INFO): Handler Thread ID is 936
2025-05-12T18:59:18.314Z,1747076358.314 [controlThread ThreadHandler](INFO): Handler Thread ID is 937
2025-05-12T18:59:18.314Z,1747076358.314 [controlThread](DEBUG): Initializing ControlThread
2025-05-12T18:59:18.315Z,1747076358.315 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2025-05-12T18:59:18.316Z,1747076358.316 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2025-05-12T18:59:18.316Z,1747076358.316 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2025-05-12T18:59:18.316Z,1747076358.316 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2025-05-12T18:59:18.317Z,1747076358.317 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2025-05-12T18:59:18.321Z,1747076358.321 [NavChart](DEBUG): Initialize NavChart Navigation.
2025-05-12T18:59:18.321Z,1747076358.321 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2025-05-12T18:59:18.322Z,1747076358.322 [SBIT](INFO): Initialize SBIT Component.
2025-05-12T18:59:18.322Z,1747076358.322 [SBIT](IMPORTANT): git: 2025-05-12_B
2025-05-12T18:59:18.322Z,1747076358.322 [SBIT](INFO): git hash: 7c5b1c07405cfe7ca09821eb029d166d25d65d57
2025-05-12T18:59:18.323Z,1747076358.323 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2025-05-12T18:59:18.324Z,1747076358.324 [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
2025-05-12T18:59:18.325Z,1747076358.325 [SBIT](INFO): Beginning SBIT in 121.000000 seconds.
2025-05-12T18:59:18.325Z,1747076358.325 [IBIT](INFO): Initialize IBIT Component.
2025-05-12T18:59:18.326Z,1747076358.326 [CBIT](DEBUG): Initialize CBIT Component.
2025-05-12T18:59:18.327Z,1747076358.327 [logger ThreadHandler](INFO): Handler Thread ID is 938
2025-05-12T18:59:18.338Z,1747076358.338 [CBIT](DEBUG): Initialized mux pins.
2025-05-12T18:59:18.338Z,1747076358.338 [CBIT](DEBUG): Initializing the watchdog timer.
2025-05-12T18:59:18.346Z,1747076358.346 [BackseatComponent ThreadHandler](INFO): Handler Thread ID is 939
2025-05-12T18:59:18.362Z,1747076358.362 [CBIT](INFO): Last reboot was NOT due to watchdog timer.
2025-05-12T18:59:18.362Z,1747076358.362 [CBIT](DEBUG): Initializing heartbeat.
2025-05-12T18:59:18.363Z,1747076358.363 [DAT ThreadHandler](INFO): Handler Thread ID is 940
2025-05-12T18:59:18.364Z,1747076358.364 [DAT](INFO): Powering up
2025-05-12T18:59:18.364Z,1747076358.364 [DAT](DEBUG): Initializing DAT.
2025-05-12T18:59:18.367Z,1747076358.367 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 942
2025-05-12T18:59:18.369Z,1747076358.369 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2025-05-12T18:59:18.390Z,1747076358.390 [Onboard ThreadHandler](INFO): Handler Thread ID is 943
2025-05-12T18:59:18.407Z,1747076358.407 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 944
2025-05-12T18:59:18.426Z,1747076358.426 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 945
2025-05-12T18:59:18.427Z,1747076358.427 [CTD_Seabird](DEBUG): Initializing CTD_Seabird.
2025-05-12T18:59:18.431Z,1747076358.431 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 947
2025-05-12T18:59:18.434Z,1747076358.434 [CBIT](DEBUG): Deactivating emergency mode.
2025-05-12T18:59:18.435Z,1747076358.435 [WetLabsBB2FL](INFO): Powering up
2025-05-12T18:59:18.436Z,1747076358.436 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 949
2025-05-12T18:59:18.443Z,1747076358.443 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2025-05-12T18:59:18.443Z,1747076358.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2025-05-12T18:59:18.443Z,1747076358.443 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2025-05-12T18:59:18.443Z,1747076358.443 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2025-05-12T18:59:18.443Z,1747076358.443 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2025-05-12T18:59:18.444Z,1747076358.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2025-05-12T18:59:18.444Z,1747076358.444 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2025-05-12T18:59:18.444Z,1747076358.444 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2025-05-12T18:59:18.474Z,1747076358.474 [CBIT](DEBUG): Backplane powered.
2025-05-12T18:59:18.474Z,1747076358.474 [GFScanner](DEBUG): Initializing GFScanner
2025-05-12T18:59:18.474Z,1747076358.474 [GFScanner](DEBUG): Deactivating GF circuits.
2025-05-12T18:59:18.483Z,1747076358.483 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2025-05-12T18:59:18.485Z,1747076358.485 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2025-05-12T18:59:18.486Z,1747076358.486 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2025-05-12T18:59:18.486Z,1747076358.486 [LoopControl](DEBUG): Initialize LoopControlComponent.
2025-05-12T18:59:18.487Z,1747076358.487 [MissionManager](IMPORTANT): Using TethysL tl-to-tx parser
2025-05-12T18:59:18.488Z,1747076358.488 [MissionManager](INFO): Loading Mission from file: Missions/Startup.tl
2025-05-12T18:59:18.488Z,1747076358.488 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Startup.tl
2025-05-12T18:59:18.494Z,1747076358.494 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Startup.tl
2025-05-12T18:59:18.538Z,1747076358.538 [MissionManager](DEBUG): TethyslAPI: Missions/Startup.tl translated into:
<?xml version="1.0" encoding="UTF-8" ?>
<!--generated by tl2xml-->
<Mission 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>

2025-05-12T18:59:18.551Z,1747076358.551 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2025-05-12T18:59:18.575Z,1747076358.575 [MissionManager](DEBUG): 
#   Copyright (c) 2024 MBARI
#   MBARI Proprietary Information. Confidential. All Rights Reserved
#   Unauthorized copying or distribution of this file via any medium is strictly
#   prohibited.
#
#   WARNING - This file contains information whose export is restricted by the
#   Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as
#   amended. Violations of these export laws are subject to severe civil and/or
#   criminal penalties.

mission Startup {
  behavior Guidance:GoToSurface {
    run in progression
  }

  aggregate StartupSatComms {
    run in sequence

    readDatum {
      timeout duration=P1M

      Universal:latitude_fix
    }

    readDatum {
      timeout duration=P1M

      Universal:platform_communications
    }
  }
}


2025-05-12T18:59:18.576Z,1747076358.576 [MissionManager](INFO): Loading Mission from file: Missions/Default.tl
2025-05-12T18:59:18.576Z,1747076358.576 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Default.tl
2025-05-12T18:59:18.579Z,1747076358.579 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Default.tl
2025-05-12T18:59:18.786Z,1747076358.786 [MissionManager](DEBUG): TethyslAPI: Missions/Default.tl translated into:
<?xml version="1.0" encoding="UTF-8" ?>
<!--generated by tl2xml-->
<Mission Id="Default">
    <DefineArg Name="ElapsedSinceDefaultStarted">
        <Units:minute />
        <Value>0</Value>
    </DefineArg>
    <Guidance:Wait>
        <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>

2025-05-12T18:59:18.791Z,1747076358.791 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2025-05-12T18:59:18.793Z,1747076358.793 [Default:A.Wait](DEBUG): Construct Wait.
2025-05-12T18:59:18.811Z,1747076358.811 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2025-05-12T18:59:18.814Z,1747076358.814 [Radio_Surface](INFO): Powering up
2025-05-12T18:59:18.834Z,1747076358.834 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2025-05-12T18:59:18.836Z,1747076358.836 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2025-05-12T18:59:18.858Z,1747076358.858 [Default:E.Execute](DEBUG): Construct Execute.
2025-05-12T18:59:18.862Z,1747076358.862 [MissionManager](DEBUG): 
#   Copyright (c) 2024 MBARI
#   MBARI Proprietary Information. Confidential. All Rights Reserved
#   Unauthorized copying or distribution of this file via any medium is strictly
#   prohibited.
#
#   WARNING - This file contains information whose export is restricted by the
#   Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as
#   amended. Violations of these export laws are subject to severe civil and/or
#   criminal penalties.

mission Default {
  arguments {
    ElapsedSinceDefaultStarted = 0 minute
  }

  behavior Guidance:Wait {
    """
    Wait a moment to see if the scheduler starts a new mission before
    starting to actually run Default.
    """

    run in sequence

    set duration = 13 second
  }

  behavior Guidance:GoToSurface {
    run in progression
  }

  aggregate CheckIn {
    run in sequence repeat=288

    readDatum id="Read_GPS" {
      timeout duration=P5M

      Universal:time_fix
    }

    readDatum id="Read_Iridium" {
      timeout duration=P4H {
        behavior Guidance:Execute {
          run in sequence

          set command = "Burn on"
        }

        syslog critical "Dropped weight due to communications timeout."
      }

      Universal:platform_communications
    }

    behavior Guidance:Wait {
      run in sequence

      set duration = 5 minute
    }

    assign in sequence ElapsedSinceDefaultStarted = elapsed ( Universal:mission_started )

    syslog important "Default mission has been running for " + ElapsedSinceDefaultStarted~minute
  }

  syslog important "Restarting logs and Default mission."

  behavior Guidance:Execute {
    run in sequence

    set command = "restart logs"
  }
}


2025-05-12T18:59:18.867Z,1747076358.867 [controlThread](DEBUG): Component order: CycleStarter,AHRS_M2,BPC1,Depth_Keller,DropWeight,MultiRay,NAL9602,PowerOnly,Power24vConverter,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterHE,SBIT,IBIT,CBIT,GFScanner,LcmUniversalReporter,Reporter,LogSplitter,
2025-05-12T18:59:18.886Z,1747076358.886 [AHRS_M2](DEBUG): Initializing AHRS_M2.
2025-05-12T18:59:19.014Z,1747076359.014 [Depth_Keller](INFO): Initializing.
2025-05-12T18:59:19.015Z,1747076359.015 [MultiRay](INFO): Powering up MultiRay Lights
2025-05-12T18:59:19.016Z,1747076359.016 [MultiRay](INFO): Powering up secondary power supply.
2025-05-12T18:59:19.055Z,1747076359.055 [Power24vConverter](INFO): Powering up.
2025-05-12T18:59:19.063Z,1747076359.063 [DepthRateCalculator](ERROR): Depth measurement is not active
2025-05-12T18:59:19.081Z,1747076359.081 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2025-05-12T18:59:19.082Z,1747076359.082 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2025-05-12T18:59:19.083Z,1747076359.083 [ElevatorServo](DEBUG): Initializing EZServoServo.
2025-05-12T18:59:19.090Z,1747076359.090 [ElevatorServo](DEBUG): Initializing ElevatorServo.
2025-05-12T18:59:19.091Z,1747076359.091 [MassServo](DEBUG): Initializing EZServoServo.
2025-05-12T18:59:19.098Z,1747076359.098 [MassServo](DEBUG): Initializing MassServo.
2025-05-12T18:59:19.099Z,1747076359.099 [RudderServo](DEBUG): Initializing EZServoServo.
2025-05-12T18:59:19.106Z,1747076359.106 [RudderServo](DEBUG): Initializing RudderServo.
2025-05-12T18:59:19.107Z,1747076359.107 [ThrusterHE](DEBUG): Initializing EZServoServo.
2025-05-12T18:59:19.114Z,1747076359.114 [ThrusterHE](DEBUG): Initializing ThrusterHE.
2025-05-12T18:59:20.087Z,1747076360.087 [MultiRay](INFO): Powering down
2025-05-12T18:59:20.206Z,1747076360.206 [MultiRay](INFO): Powering down LCB2
2025-05-12T18:59:21.078Z,1747076361.078 [WetLabsBB2FL](INFO): Powering down
2025-05-12T18:59:24.818Z,1747076364.818 [ThrusterHE](ERROR): Zero Speed Commanded.
2025-05-12T18:59:25.458Z,1747076365.458 [CTD_Seabird](ERROR): Device message queue exceeded the allowed limit.
2025-05-12T18:59:30.719Z,1747076370.719 [DAT](INFO): DAT read: 

2025-05-12T18:59:30.720Z,1747076370.720 [DAT](INFO): DAT read: Teledyne Benthos DAT-900 Series

2025-05-12T18:59:32.231Z,1747076372.231 [DAT](INFO): DAT read: MF Frequency Band

2025-05-12T18:59:32.232Z,1747076372.232 [DAT](INFO): DAT read: Directional Acoustic Transponder version 8.15.0

2025-05-12T18:59:32.232Z,1747076372.232 [DAT](INFO): DAT read: May 12 2025 18:59:27 

2025-05-12T18:59:33.239Z,1747076373.239 [DAT](INFO): DAT read: Features enabled [Bearing]

2025-05-12T18:59:33.240Z,1747076373.240 [DAT](INFO): DAT read: CONNECT 00800 bits/sec 1 of 4, Rate 1/2 CC 12.50ms MGP

2025-05-12T18:59:33.241Z,1747076373.241 [DAT](INFO): commRate: 800
2025-05-12T18:59:35.306Z,1747076375.306 [DAT](INFO): entering command mode
2025-05-12T18:59:35.507Z,1747076375.507 [DAT](INFO): DAT read: 

2025-05-12T18:59:35.507Z,1747076375.507 [DAT](INFO): DAT read: user:1>

2025-05-12T18:59:35.507Z,1747076375.507 [DAT](INFO): setting verbose to 3
2025-05-12T18:59:35.759Z,1747076375.759 [DAT](INFO): DAT read: user:1>

2025-05-12T18:59:35.760Z,1747076375.760 [DAT](INFO): DAT read: Verbose         | 3           

2025-05-12T18:59:35.760Z,1747076375.760 [DAT](INFO): set verbose to 3
2025-05-12T18:59:35.760Z,1747076375.760 [DAT](INFO): setting DatVerbose to 27440
2025-05-12T18:59:36.011Z,1747076376.011 [DAT](INFO): DAT read: user:2>

2025-05-12T18:59:36.012Z,1747076376.012 [DAT](INFO): DAT read: DatVerbose      | 27440       

2025-05-12T18:59:36.012Z,1747076376.012 [DAT](INFO): set DatVerbose to 27440
2025-05-12T18:59:36.012Z,1747076376.012 [DAT](INFO): setting transmit power to 8
2025-05-12T18:59:36.263Z,1747076376.263 [DAT](INFO): DAT read: user:3>

2025-05-12T18:59:36.264Z,1747076376.264 [DAT](INFO): DAT read: TxPower         | 8 (Max)     

2025-05-12T18:59:36.265Z,1747076376.265 [DAT](INFO): set transmit power to 8
2025-05-12T18:59:36.265Z,1747076376.265 [DAT](INFO): setting local address to 9
2025-05-12T18:59:36.515Z,1747076376.515 [DAT](INFO): DAT read: user:4>

2025-05-12T18:59:36.516Z,1747076376.516 [DAT](INFO): DAT read: LocalAddr       | 9           

2025-05-12T18:59:36.516Z,1747076376.516 [DAT](INFO): set local address to 9
2025-05-12T18:59:36.517Z,1747076376.517 [DAT](INFO): Setting time to: 18:59:36 And date to:5/12/2025
2025-05-12T18:59:36.767Z,1747076376.767 [DAT](INFO): DAT read: user:5>

2025-05-12T18:59:36.768Z,1747076376.768 [DAT](INFO): DAT read: Mon May 12, 2025  18:59:36  

2025-05-12T18:59:36.768Z,1747076376.768 [DAT](INFO): Local DAT time set to Mon May 12, 2025  18:59:36  

2025-05-12T18:59:46.420Z,1747076386.420 [NAL9602](INFO): Powering up NAL9602
2025-05-12T18:59:57.332Z,1747076397.332 [NAL9602](INFO): NAL9602 initialized
2025-05-12T19:00:16.322Z,1747076416.322 [NAL9602](INFO): SBD MO Status=0, MOMSN=19441, MT Status=0, MTMSN=0
2025-05-12T19:00:16.322Z,1747076416.322 [NAL9602](INFO): No messages in MT queue
2025-05-12T19:01:02.782Z,1747076462.782 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190101.00,A,3648.28276,N,12147.12279,W,4.704,0.00,120525,,,A*7C
2025-05-12T19:01:02.785Z,1747076462.785 [NAL9602](INFO): GPS fix at 20250512T190101: (36.804713, -121.785380)
2025-05-12T19:01:19.844Z,1747076479.844 [SBIT](IMPORTANT): Beginning Startup BIT
2025-05-12T19:01:19.848Z,1747076479.848 [GFScanner](IMPORTANT): Beginning ground fault scan
2025-05-12T19:01:24.287Z,1747076484.287 [GFScanner](IMPORTANT): No ground fault detected
mA:
CHAN A0 (Batt): -0.006490
CHAN A1 (24V): -0.000160
CHAN A2 (12V): -0.004854
CHAN A3 (5V): -0.002873
CHAN B0 (3.3V): -0.001226
CHAN B1 (3.15aV): -0.001159
CHAN B2 (3.15bV): -0.001243
CHAN B3 (GND): -0.000978
OPEN: 0.004487
Full Scale: +/- 1 mA
2025-05-12T19:01:35.122Z,1747076495.122 [NAL9602](INFO): Powering down
2025-05-12T19:02:13.661Z,1747076533.661 [SBIT](IMPORTANT): SBIT PASSED
2025-05-12T19:02:13.661Z,1747076533.661 [SBIT](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2025-05-12T19:02:13.662Z,1747076533.662 [SBIT](IMPORTANT): Express linearApproximation DATMMP.acoustic_contact_range 15.000000 meter;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): Express linearApproximation TrackAcousticContact.range_to_contact 15.000000 meter;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): GFScanner.loadAtStartup=1 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): GFScanner.simulateHardware=0 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): MultiRay.brightnessWhite=88 none;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): MultiRay.loadAtStartup=1 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): NAL9602.fastGPSFix=0 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): PowerOnly.loadAtStartup=1 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): Sonardyne_Nano.loadAtStartup=0 bool;

2025-05-12T19:02:13.663Z,1747076533.663 [SBIT](IMPORTANT): VerticalControl.buoyancyNeutral=213.529736 cubic_centimeter;

2025-05-12T19:02:13.664Z,1747076533.664 [SBIT](IMPORTANT): VerticalControl.massDefault=25.437902 millimeter;

2025-05-12T19:02:13.982Z,1747076533.982 [MissionManager](IMPORTANT): Started mission Startup
2025-05-12T19:02:13.982Z,1747076533.982 [Startup] Running Loop=1
2025-05-12T19:02:13.982Z,1747076533.982 [Startup](DEBUG): Aggregate::initialize Startup
2025-05-12T19:02:13.982Z,1747076533.982 [Startup:A.GoToSurface] Running Loop=1
2025-05-12T19:02:13.982Z,1747076533.982 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2025-05-12T19:02:13.983Z,1747076533.983 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2025-05-12T19:02:13.983Z,1747076533.983 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2025-05-12T19:02:13.984Z,1747076533.984 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2025-05-12T19:02:13.984Z,1747076533.984 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2025-05-12T19:02:13.984Z,1747076533.984 [Startup:A.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds.
2025-05-12T19:02:13.985Z,1747076533.985 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2025-05-12T19:02:13.991Z,1747076533.991 [Startup:StartupSatComms] Running Loop=1
2025-05-12T19:02:13.992Z,1747076533.992 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2025-05-12T19:02:13.992Z,1747076533.992 [Startup:StartupSatComms:A] Running Loop=1
2025-05-12T19:02:14.373Z,1747076534.373 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2025-05-12T19:02:14.747Z,1747076534.747 [NAL9602](INFO): Powering up
2025-05-12T19:02:25.636Z,1747076545.636 [NAL9602](INFO): NAL9602 initialized
2025-05-12T19:02:41.021Z,1747076561.021 [NAL9602](INFO): SBD MO Status=0, MOMSN=19442, MT Status=0, MTMSN=0
2025-05-12T19:02:41.021Z,1747076561.021 [NAL9602](INFO): No messages in MT queue
2025-05-12T19:02:51.745Z,1747076571.745 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005149
2025-05-12T19:03:14.158Z,1747076594.158 [Startup:StartupSatComms:A](INFO): Timed out from 2025-05-12T19:02:13.0Z
2025-05-12T19:03:14.158Z,1747076594.158 [Startup:StartupSatComms:A] Stopped
2025-05-12T19:03:14.158Z,1747076594.158 [Startup:StartupSatComms:B] Running Loop=1
2025-05-12T19:03:14.559Z,1747076594.559 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2025-05-12T19:03:21.385Z,1747076601.385 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20250512T172749/Courier0040.lzma
2025-05-12T19:03:22.388Z,1747076602.388 [DataOverHttps](INFO): Moved sent file to Logs/20250512T172749/Courier0040.lzma.bak
2025-05-12T19:03:22.388Z,1747076602.388 [DataOverHttps](INFO): SBD MOMSN=24855267
2025-05-12T19:03:41.510Z,1747076621.510 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20250512T185905/Courier0000.lzma
2025-05-12T19:03:42.513Z,1747076622.513 [DataOverHttps](INFO): Moved sent file to Logs/20250512T185905/Courier0000.lzma.bak
2025-05-12T19:03:42.513Z,1747076622.513 [DataOverHttps](IMPORTANT): SBD MOMSN=24855271, MTMSN=20250512T190341
2025-05-12T19:03:47.413Z,1747076627.413 [NAL9602](INFO): Powering down
2025-05-12T19:03:50.196Z,1747076630.196 [DataOverHttps](INFO): Received command: run Engineering/lab_test_optim.tl
2025-05-12T19:03:50.248Z,1747076630.248 [CommandExec](IMPORTANT): got command run ./Missions/Engineering/lab_test_optim.tl
2025-05-12T19:03:50.248Z,1747076630.248 [MissionManager](INFO): Loading Mission from file: ./Missions/Engineering/lab_test_optim.tl
2025-05-12T19:03:50.249Z,1747076630.249 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Engineering/lab_test_optim.tl
2025-05-12T19:03:50.252Z,1747076630.252 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Engineering/lab_test_optim.tl
2025-05-12T19:03:50.495Z,1747076630.495 [MissionManager](DEBUG): TethyslAPI: ./Missions/Engineering/lab_test_optim.tl translated into:
<?xml version="1.0" encoding="UTF-8" ?>
<!--generated by tl2xml-->
<Mission Id="lab_test_optim">
    <DefineArg Name="MissionTimeout">
        <Units:minute />
        <Value>15</Value>
    </DefineArg>
    <DefineArg Name="RecordTime">
        <Units:minute />
        <Value>1</Value>
    </DefineArg>
    <DefineArg Name="BackseatWait">
        <Units:second />
        <Value>30</Value>
    </DefineArg>
    <DefineArg Name="LightMode">
        <Units:count />
        <Value>2</Value>
    </DefineArg>
    <DefineArg Name="BrightnessWhite">
        <Units:none_int />
        <Value>100</Value>
    </DefineArg>
    <DefineArg Name="BrightnessRed">
        <Units:none_int />
        <Value>100</Value>
    </DefineArg>
    <DefineOutput Name="RecordingEnabled">
        <False />
    </DefineOutput>
    <DefineOutput Name="LightsEnabled">
        <False />
    </DefineOutput>
    <Timeout Duration="MissionTimeout" />
    <Insert Filename="Insert/BackseatDriver.tl" />
    <Assign>
        <Parallel />
        <Arg Name="BackseatDriver:EnableBackseat" />
        <True />
    </Assign>
    <ReadData Strategy="MinError">
        <While>
            <Arg Name="RecordingEnabled" />
        </While>
        <Sensor:PowerOnly.sampleLoad1 />
    </ReadData>
    <ReadData Strategy="MinError">
        <While>
            <Arg Name="LightsEnabled" />
        </While>
        <Sensor:MultiRay.lightModeLog />
    </ReadData>
    <Aggregate Id="Startup">
        <Sequence />
        <Syslog Severity="Important">
            Waiting 
            <Arg Name="BackseatWait" />
            <Units:second />
             for backseat to start up...
        </Syslog>
        <Guidance:Wait>
            <Sequence />
            <Setting>
                <Guidance:Wait.duration />
                <Arg Name="BackseatWait" />
            </Setting>
        </Guidance:Wait>
    </Aggregate>
    <Aggregate Id="Run">
        <Sequence />
        <Syslog Severity="Important">Trying to run Optim and Multiray forreal</Syslog>
        <Assign>
            <Sequence />
            <Arg Name="RecordingEnabled" />
            <True />
        </Assign>
        <Assign>
            <Sequence />
            <Arg Name="LightsEnabled" />
            <True />
        </Assign>
        <Assign>
            <Sequence />
            <Sensor:MultiRay.lightModeCommand />
            <Arg Name="LightMode" />
        </Assign>
        <Aggregate Id="setRed">
            <Sequence />
            <Break>
                <Arg Name="LightMode" />
                <Ne>
                    <Units:count />
                    <Value>1</Value>
                </Ne>
            </Break>
            <Assign>
                <Sequence />
                <Sensor:MultiRay.brightnessRed />
                <Arg Name="BrightnessRed" />
            </Assign>
            <Syslog Severity="Info">
                Setting multiray red brightness to
                <Arg Name="BrightnessRed" />
                <Units:count />
            </Syslog>
        </Aggregate>
        <Aggregate Id="setWhite">
            <Sequence />
            <Break>
                <Arg Name="LightMode" />
                <Ne>
                    <Units:count />
                    <Value>2</Value>
                </Ne>
            </Break>
            <Assign>
                <Sequence />
                <Sensor:MultiRay.brightnessWhite />
                <Arg Name="BrightnessWhite" />
            </Assign>
            <Syslog Severity="Info">
                Setting muliray white brightness to
                <Arg Name="BrightnessWhite" />
                <Units:count />
            </Syslog>
        </Aggregate>
        <Syslog Severity="Important">
            Recording for 
            <Arg Name="RecordTime" />
            <Units:minute />
        </Syslog>
        <Guidance:Wait>
            <Sequence />
            <Setting>
                <Guidance:Wait.duration />
                <Arg Name="RecordTime" />
            </Setting>
        </Guidance:Wait>
    </Aggregate>
    <Guidance:Wait>
        <Sequence />
        <Setting>
            <Guidance:Wait.duration />
            <Arg Name="MissionTimeout" />
        </Setting>
    </Guidance:Wait>
</Mission>

2025-05-12T19:03:50.501Z,1747076630.501 [MissionManager](INFO): DefineArg lab_test_optim.MissionTimeout = 15.000000 min
2025-05-12T19:03:50.544Z,1747076630.544 [MissionManager](INFO): DefineArg lab_test_optim.RecordTime = 1.000000 min
2025-05-12T19:03:50.551Z,1747076630.551 [MissionManager](INFO): DefineArg lab_test_optim.BackseatWait = 30.000000 s
2025-05-12T19:03:50.579Z,1747076630.579 [MissionManager](INFO): DefineArg lab_test_optim.LightMode = 2.000000 count
2025-05-12T19:03:50.594Z,1747076630.594 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessWhite = 100.000000 n/a int32
2025-05-12T19:03:50.597Z,1747076630.597 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessRed = 100.000000 n/a int32
2025-05-12T19:03:50.608Z,1747076630.608 [MissionManager](INFO): DefineOutput lab_test_optim.RecordingEnabled = 0 bool
2025-05-12T19:03:50.619Z,1747076630.619 [MissionManager](INFO): DefineOutput lab_test_optim.LightsEnabled = 0 bool
2025-05-12T19:03:50.620Z,1747076630.620 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/BackseatDriver.tl
2025-05-12T19:03:50.620Z,1747076630.620 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Insert/BackseatDriver.tl
2025-05-12T19:03:50.621Z,1747076630.621 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Insert/BackseatDriver.tl
2025-05-12T19:03:50.660Z,1747076630.660 [MissionManager](DEBUG): TethyslAPI: Missions/Insert/BackseatDriver.tl translated into:
<?xml version="1.0" encoding="UTF-8" ?>
<!--generated by tl2xml-->
<Aggregate Id="BackseatDriver">
    <DefineArg Name="EnableBackseat">
        <False />
    </DefineArg>
    <Parallel />
    <Guidance:BackseatDriver>
        <Sequence />
        <Setting>
            <Guidance:BackseatDriver.powerBackseat />
            <Arg Name="EnableBackseat" />
        </Setting>
    </Guidance:BackseatDriver>
</Aggregate>

2025-05-12T19:03:50.668Z,1747076630.668 [MissionManager](INFO): DefineArg lab_test_optim:BackseatDriver.EnableBackseat = 0 bool
2025-05-12T19:03:50.675Z,1747076630.675 [lab_test_optim:BackseatDriver:A.BackseatDriver](DEBUG): Construct BackseatDriver.
2025-05-12T19:03:50.695Z,1747076630.695 [lab_test_optim:Startup:B.Wait](DEBUG): Construct Wait.
2025-05-12T19:03:50.736Z,1747076630.736 [lab_test_optim:Run:H.Wait](DEBUG): Construct Wait.
2025-05-12T19:03:50.746Z,1747076630.746 [lab_test_optim:G.Wait](DEBUG): Construct Wait.
2025-05-12T19:03:50.752Z,1747076630.752 [MissionManager](DEBUG): 
#   Copyright (c) 2024 MBARI
#   MBARI Proprietary Information. Confidential. All Rights Reserved
#   Unauthorized copying or distribution of this file via any medium is strictly
#   prohibited.
#
#   WARNING - This file contains information whose export is restricted by the
#   Export Administration Act of 1979 (Title 50, U.S.C., App. 2401 et seq.), as
#   amended. Violations of these export laws are subject to severe civil and/or
#   criminal penalties.

mission lab_test_optim {
  arguments {
    MissionTimeout = 15 minute
      """
      Backseat will stay on for this duration, independent of Optim state
      """

    RecordTime = 1 minute
      """
      How long to record after startup sequence (hopefully) turns on Optim camera
      """

    BackseatWait = 30 second
      """
      How long to wait for the backseat to power up before attempting to power the Optim
      """

    LightMode = 2 count
      """
      Mode for Multiray lights. 0 is off, 1 is red, 2 is white
      """

    BrightnessWhite = 100 none_int
      """
      White Multiray LED brightness, 0-100
      """

    BrightnessRed = 100 none_int
      """
      Red Multiray LED brightness, 0-100
      """
  }

  output {
    RecordingEnabled = false

    LightsEnabled = false
  }

  timeout duration=MissionTimeout

  insert Insert/BackseatDriver.tl
  assign in parallel BackseatDriver:EnableBackseat = true

  readData strategy="MinError" {
    while ( RecordingEnabled )

    Sensor:PowerOnly.sampleLoad1
  }

  readData strategy="MinError" {
    while ( LightsEnabled )

    Sensor:MultiRay.lightModeLog
  }

  aggregate Startup {
    run in sequence

    syslog important "Waiting " + BackseatWait~s + " for backseat to start up..."

    behavior Guidance:Wait {
      run in sequence

      set duration = BackseatWait
    }
  }

  aggregate Run {
    run in sequence

    syslog important "Trying to run Optim and Multiray forreal"

    assign in sequence RecordingEnabled = true
    assign in sequence LightsEnabled = true
    assign in sequence Sensor:MultiRay.lightModeCommand = LightMode

    aggregate setRed {
      run in sequence

      break if ( LightMode != 1 count )

      assign in sequence Sensor:MultiRay.brightnessRed = BrightnessRed
      syslog info "Setting multiray red brightness to" + BrightnessRed~count
    }

    aggregate setWhite {
      run in sequence

      break if ( LightMode != 2 count )

      assign in sequence Sensor:MultiRay.brightnessWhite = BrightnessWhite
      syslog info "Setting muliray white brightness to" + BrightnessWhite~count
    }

    syslog important "Recording for " + RecordTime~min

    behavior Guidance:Wait {
      run in sequence

      set duration = RecordTime
    }
  }

  behavior Guidance:Wait {
    run in sequence

    set duration = MissionTimeout
  }
}


2025-05-12T19:03:50.759Z,1747076630.759 [CommandExec](IMPORTANT): Running ./Missions/Engineering/lab_test_optim.tl
2025-05-12T19:03:58.901Z,1747076638.901 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20250512T172749/Express0041.lzma
2025-05-12T19:03:59.904Z,1747076639.904 [DataOverHttps](INFO): Moved sent file to Logs/20250512T172749/Express0041.lzma.bak
2025-05-12T19:03:59.904Z,1747076639.904 [DataOverHttps](INFO): SBD MOMSN=24855279
2025-05-12T19:04:14.413Z,1747076654.413 [Startup:StartupSatComms:B](INFO): Timed out from 2025-05-12T19:03:14.2Z
2025-05-12T19:04:14.413Z,1747076654.413 [Startup:StartupSatComms:B] Stopped
2025-05-12T19:04:14.413Z,1747076654.413 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2025-05-12T19:04:14.413Z,1747076654.413 [Startup:StartupSatComms] Stopped
2025-05-12T19:04:14.413Z,1747076654.413 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2025-05-12T19:04:14.418Z,1747076654.418 [Startup](INFO): Completed Startup
2025-05-12T19:04:14.418Z,1747076654.418 [MissionManager](INFO): Startup is completed.
2025-05-12T19:04:14.419Z,1747076654.419 [MissionManager](INFO): Uninitializing Mission Startup
2025-05-12T19:04:14.419Z,1747076654.419 [Startup] Stopped
2025-05-12T19:04:14.419Z,1747076654.419 [Startup](DEBUG): Aggregate::uninitialize Startup
2025-05-12T19:04:14.419Z,1747076654.419 [Startup:A.GoToSurface] Stopped
2025-05-12T19:04:14.419Z,1747076654.419 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2025-05-12T19:04:14.941Z,1747076654.941 [MissionManager](IMPORTANT): Started mission lab_test_optim
2025-05-12T19:04:14.941Z,1747076654.941 [lab_test_optim] Running Loop=1
2025-05-12T19:04:14.941Z,1747076654.941 [lab_test_optim](DEBUG): Aggregate::initialize lab_test_optim
2025-05-12T19:04:14.941Z,1747076654.941 [lab_test_optim:BackseatDriver] Running Loop=1
2025-05-12T19:04:14.941Z,1747076654.941 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::initialize lab_test_optim:BackseatDriver
2025-05-12T19:04:14.942Z,1747076654.942 [lab_test_optim:BackseatDriver:A.BackseatDriver] Running Loop=1
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:B] Running Loop=1
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:C] Running Loop=1
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:D] Running Loop=1
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:Startup] Running Loop=1
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:Startup](DEBUG): Aggregate::initialize lab_test_optim:Startup
2025-05-12T19:04:14.946Z,1747076654.946 [lab_test_optim:Startup:A] Running Loop=1
2025-05-12T19:04:14.947Z,1747076654.947 [lab_test_optim:Startup:A](IMPORTANT): Waiting  30.000000 s  for backseat to start up...
2025-05-12T19:04:14.947Z,1747076654.947 [lab_test_optim:Startup:A] Stopped
2025-05-12T19:04:14.947Z,1747076654.947 [lab_test_optim:Startup:B.Wait] Running Loop=1
2025-05-12T19:04:14.947Z,1747076654.947 [lab_test_optim:Startup:B.Wait](DEBUG): Initialize Wait Component.
2025-05-12T19:04:14.947Z,1747076654.947 [lab_test_optim:D] Stopped
2025-05-12T19:04:14.948Z,1747076654.948 [lab_test_optim:C] Stopped
2025-05-12T19:04:14.948Z,1747076654.948 [lab_test_optim:B] Running Loop=1
2025-05-12T19:04:14.948Z,1747076654.948 [lab_test_optim:BackseatDriver] Running Loop=1
2025-05-12T19:04:14.948Z,1747076654.948 [lab_test_optim:BackseatDriver:A.BackseatDriver](INFO): Initializing backseat
2025-05-12T19:04:15.118Z,1747076655.118 [BackseatComponent](INFO): Powering up
2025-05-12T19:04:15.119Z,1747076655.119 [BackseatComponent](INFO): Subscribing to LCM channels.
2025-05-12T19:04:16.269Z,1747076656.269 [DataOverHttps](INFO): Sending 38 bytes from file Logs/20250512T185905/Courier0004.lzma
2025-05-12T19:04:17.272Z,1747076657.272 [DataOverHttps](INFO): Moved sent file to Logs/20250512T185905/Courier0004.lzma.bak
2025-05-12T19:04:17.272Z,1747076657.272 [DataOverHttps](INFO): SBD MOMSN=24855284
2025-05-12T19:04:45.497Z,1747076685.497 [lab_test_optim:Startup:B.Wait](INFO): Done Waiting.
2025-05-12T19:04:45.497Z,1747076685.497 [lab_test_optim:Startup:B.Wait] Stopped
2025-05-12T19:04:45.497Z,1747076685.497 [lab_test_optim:Startup:B.Wait](DEBUG): Uninitialize Wait Component.
2025-05-12T19:04:45.498Z,1747076685.498 [lab_test_optim:Startup](INFO): Completed lab_test_optim:Startup
2025-05-12T19:04:45.498Z,1747076685.498 [lab_test_optim:Startup] Stopped
2025-05-12T19:04:45.498Z,1747076685.498 [lab_test_optim:Startup](DEBUG): Aggregate::uninitialize lab_test_optim:Startup
2025-05-12T19:04:45.500Z,1747076685.500 [lab_test_optim:Run] Running Loop=1
2025-05-12T19:04:45.500Z,1747076685.500 [lab_test_optim:Run](DEBUG): Aggregate::initialize lab_test_optim:Run
2025-05-12T19:04:45.500Z,1747076685.500 [lab_test_optim:Run:A] Running Loop=1
2025-05-12T19:04:45.896Z,1747076685.896 [lab_test_optim:Run:A](IMPORTANT): Trying to run Optim and Multiray forreal
2025-05-12T19:04:45.897Z,1747076685.897 [lab_test_optim:Run:A] Stopped
2025-05-12T19:04:45.897Z,1747076685.897 [lab_test_optim:Run:B] Running Loop=1
2025-05-12T19:04:46.293Z,1747076686.293 [lab_test_optim:Run:B] Stopped
2025-05-12T19:04:46.294Z,1747076686.294 [lab_test_optim:Run:C] Running Loop=1
2025-05-12T19:04:46.703Z,1747076686.703 [lab_test_optim:Run:C] Stopped
2025-05-12T19:04:46.703Z,1747076686.703 [lab_test_optim:Run:D] Running Loop=1
2025-05-12T19:04:46.703Z,1747076686.703 [lab_test_optim:C] Running Loop=1
2025-05-12T19:04:46.703Z,1747076686.703 [lab_test_optim:C] Running Loop=1
2025-05-12T19:04:46.704Z,1747076686.704 [lab_test_optim:C](DEBUG): Initialize ReadDataComponent to sense PowerOnly.sampleLoad1
2025-05-12T19:04:47.100Z,1747076687.100 [PowerOnly](INFO): Powering up loadControl
2025-05-12T19:04:47.127Z,1747076687.127 [lab_test_optim:Run:D] Stopped
2025-05-12T19:04:47.128Z,1747076687.128 [lab_test_optim:Run:setRed] Running Loop=1
2025-05-12T19:04:47.128Z,1747076687.128 [lab_test_optim:Run:setRed](DEBUG): Aggregate::initialize lab_test_optim:Run:setRed
2025-05-12T19:04:47.128Z,1747076687.128 [lab_test_optim:Run:setRed:A] Running Loop=1
2025-05-12T19:04:47.128Z,1747076687.128 [lab_test_optim:D] Running Loop=1
2025-05-12T19:04:47.128Z,1747076687.128 [lab_test_optim:D] Running Loop=1
2025-05-12T19:04:47.129Z,1747076687.129 [lab_test_optim:D](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setRed] Stopped
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setRed](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setRed
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setRed:A] Stopped
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setWhite] Running Loop=1
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::initialize lab_test_optim:Run:setWhite
2025-05-12T19:04:47.509Z,1747076687.509 [lab_test_optim:Run:setWhite:A] Running Loop=1
2025-05-12T19:04:47.961Z,1747076687.961 [lab_test_optim:Run:setWhite:A] Stopped
2025-05-12T19:04:47.961Z,1747076687.961 [lab_test_optim:Run:setWhite:B] Running Loop=1
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:setWhite:B](INFO): Setting muliray white brightness to 100.000000 count 
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:setWhite:B] Stopped
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:setWhite](INFO): Completed lab_test_optim:Run:setWhite
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:setWhite] Stopped
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setWhite
2025-05-12T19:04:48.367Z,1747076688.367 [lab_test_optim:Run:G] Running Loop=1
2025-05-12T19:04:48.738Z,1747076688.738 [lab_test_optim:Run:G](IMPORTANT): Recording for  1.000000 min 
2025-05-12T19:04:48.738Z,1747076688.738 [lab_test_optim:Run:G] Stopped
2025-05-12T19:04:48.739Z,1747076688.739 [lab_test_optim:Run:H.Wait] Running Loop=1
2025-05-12T19:04:48.739Z,1747076688.739 [lab_test_optim:Run:H.Wait](DEBUG): Initialize Wait Component.
2025-05-12T19:04:49.517Z,1747076689.517 [MultiRay](IMPORTANT): MultiRay white lights ON
2025-05-12T19:05:14.679Z,1747076714.679 [BackseatComponent](IMPORTANT): ikshana: running backseat application.
2025-05-12T19:05:17.384Z,1747076717.384 [BackseatComponent](INFO): Created universal data reader for depth with code: 6
2025-05-12T19:05:17.384Z,1747076717.384 [BackseatComponent](INFO): Requesting data from depth (6). Requested size is: 1
2025-05-12T19:05:49.391Z,1747076749.391 [lab_test_optim:Run:H.Wait](INFO): Done Waiting.
2025-05-12T19:05:49.391Z,1747076749.391 [lab_test_optim:Run:H.Wait] Stopped
2025-05-12T19:05:49.391Z,1747076749.391 [lab_test_optim:Run:H.Wait](DEBUG): Uninitialize Wait Component.
2025-05-12T19:05:49.391Z,1747076749.391 [lab_test_optim:Run](INFO): Completed lab_test_optim:Run
2025-05-12T19:05:49.391Z,1747076749.391 [lab_test_optim:Run] Stopped
2025-05-12T19:05:49.392Z,1747076749.392 [lab_test_optim:Run](DEBUG): Aggregate::uninitialize lab_test_optim:Run
2025-05-12T19:05:49.392Z,1747076749.392 [lab_test_optim:G.Wait] Running Loop=1
2025-05-12T19:05:49.392Z,1747076749.392 [lab_test_optim:G.Wait](DEBUG): Initialize Wait Component.
2025-05-12T19:07:36.057Z,1747076856.057 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 5.
2025-05-12T19:07:36.060Z,1747076856.060 [BPC1](INFO): Received data from all battery sticks.
2025-05-12T19:10:43.390Z,1747077043.390 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2025-05-12T19:10:49.415Z,1747077049.415 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.251404
2025-05-12T19:11:32.612Z,1747077092.612 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003332
2025-05-12T19:13:06.398Z,1747077186.398 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239262
2025-05-12T19:13:17.870Z,1747077197.870 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003311
2025-05-12T19:14:50.642Z,1747077290.642 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2025-05-12T19:14:53.655Z,1747077293.655 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.271427
2025-05-12T19:15:15.057Z,1747077315.057 [lab_test_optim:BackseatDriver:A.BackseatDriver](INFO): Created data writer for _.data_dir_logging_rate with code: 1967
2025-05-12T19:15:25.782Z,1747077325.782 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.
2025-05-12T19:15:56.746Z,1747077356.746 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003320
2025-05-12T19:18:36.435Z,1747077516.435 [DataOverHttps](IMPORTANT): SBD MTMSN=20250512T191835
2025-05-12T19:18:43.894Z,1747077523.894 [DataOverHttps](INFO): Received command: stop
2025-05-12T19:18:43.975Z,1747077523.975 [CommandExec](IMPORTANT): got command stop
2025-05-12T19:18:43.975Z,1747077523.975 [CommandExec](IMPORTANT): Scheduling is paused
2025-05-12T19:18:43.975Z,1747077523.975 [Supervisor](INFO): Stop Mission called by CommandExec::commandStop
2025-05-12T19:18:44.354Z,1747077524.354 [MissionManager](INFO): MissionManager is completed.
2025-05-12T19:18:44.355Z,1747077524.355 [MissionManager](INFO): Uninitializing Mission lab_test_optim
2025-05-12T19:18:44.356Z,1747077524.356 [lab_test_optim] Stopped
2025-05-12T19:18:44.356Z,1747077524.356 [lab_test_optim](DEBUG): Aggregate::uninitialize lab_test_optim
2025-05-12T19:18:44.357Z,1747077524.357 [lab_test_optim:BackseatDriver] Stopped
2025-05-12T19:18:44.363Z,1747077524.363 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::uninitialize lab_test_optim:BackseatDriver
2025-05-12T19:18:44.363Z,1747077524.363 [lab_test_optim:BackseatDriver:A.BackseatDriver] Stopped
2025-05-12T19:18:44.365Z,1747077524.365 [lab_test_optim:B] Stopped
2025-05-12T19:18:44.365Z,1747077524.365 [lab_test_optim:C] Stopped
2025-05-12T19:18:44.370Z,1747077524.370 [lab_test_optim:D] Stopped
2025-05-12T19:18:44.371Z,1747077524.371 [lab_test_optim:G.Wait] Stopped
2025-05-12T19:18:44.372Z,1747077524.372 [lab_test_optim:G.Wait](DEBUG): Uninitialize Wait Component.
2025-05-12T19:18:44.730Z,1747077524.730 [MissionManager](IMPORTANT): Started mission Default
2025-05-12T19:18:44.730Z,1747077524.730 [Default] Running Loop=1
2025-05-12T19:18:44.730Z,1747077524.730 [Default](DEBUG): Aggregate::initialize Default
2025-05-12T19:18:44.730Z,1747077524.730 [Default:B.GoToSurface] Running Loop=1
2025-05-12T19:18:44.730Z,1747077524.730 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2025-05-12T19:18:44.731Z,1747077524.731 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2025-05-12T19:18:44.731Z,1747077524.731 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2025-05-12T19:18:44.731Z,1747077524.731 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2025-05-12T19:18:44.731Z,1747077524.731 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2025-05-12T19:18:44.732Z,1747077524.732 [Default:B.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds.
2025-05-12T19:18:44.732Z,1747077524.732 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2025-05-12T19:18:44.732Z,1747077524.732 [Default:A.Wait] Running Loop=1
2025-05-12T19:18:44.733Z,1747077524.733 [Default:A.Wait](DEBUG): Initialize Wait Component.
2025-05-12T19:18:45.131Z,1747077525.131 [MultiRay](INFO): Powering down
2025-05-12T19:18:45.250Z,1747077525.250 [MultiRay](INFO): Powering down LCB2
2025-05-12T19:18:45.757Z,1747077525.757 [BackseatComponent](INFO): Sent LCM shutdown request.
2025-05-12T19:18:45.758Z,1747077525.758 [BackseatComponent](INFO): Shutdown requested. Waiting (18.00 sec to power down.).
2025-05-12T19:18:58.073Z,1747077538.073 [Default:A.Wait](INFO): Done Waiting.
2025-05-12T19:18:58.073Z,1747077538.073 [Default:A.Wait] Stopped
2025-05-12T19:18:58.073Z,1747077538.073 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2025-05-12T19:18:58.486Z,1747077538.486 [Default:CheckIn] Running Loop=1
2025-05-12T19:18:58.486Z,1747077538.486 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2025-05-12T19:18:58.486Z,1747077538.486 [Default:CheckIn:Read_GPS] Running Loop=1
2025-05-12T19:18:58.873Z,1747077538.873 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2025-05-12T19:18:59.264Z,1747077539.264 [NAL9602](INFO): Powering up
2025-05-12T19:19:03.934Z,1747077543.934 [BackseatComponent](INFO): Powering down and starting shutdown timer (18.00 sec).
2025-05-12T19:19:03.935Z,1747077543.935 [BackseatComponent](INFO): Unsubscribing from LCM channels.
2025-05-12T19:19:03.935Z,1747077543.935 [LcmUniversalReporter](INFO): Deactivating messaging.
2025-05-12T19:19:10.174Z,1747077550.174 [NAL9602](INFO): NAL9602 initialized
2025-05-12T19:19:10.987Z,1747077550.987 [NAL9602](FAULT): GPS failed to acquire within timeout.
2025-05-12T19:19:10.987Z,1747077550.987 [NAL9602] Data Fault, FailCount= 1
2025-05-12T19:19:10.987Z,1747077550.987 [NAL9602](ERROR): Data Fault
2025-05-12T19:19:11.006Z,1747077551.006 [CBIT](ERROR): Data Fault in component: NAL9602
2025-05-12T19:19:11.387Z,1747077551.387 [NAL9602](INFO): Powering down
2025-05-12T19:19:12.218Z,1747077552.218 [CBIT](INFO): Clearing failed state for component NAL9602
2025-05-12T19:19:12.218Z,1747077552.218 [NAL9602] No Fault, FailCount= 1
2025-05-12T19:19:41.684Z,1747077581.684 [NAL9602](INFO): Powering up NAL9602
2025-05-12T19:19:52.600Z,1747077592.600 [NAL9602](INFO): NAL9602 initialized
2025-05-12T19:20:14.816Z,1747077614.816 [PowerOnly](INFO): Powering down loadControl
2025-05-12T19:20:19.261Z,1747077619.261 [NAL9602](INFO): SBD MO Status=0, MOMSN=19446, MT Status=0, MTMSN=0
2025-05-12T19:20:19.261Z,1747077619.261 [NAL9602](INFO): No messages in MT queue
2025-05-12T19:21:07.183Z,1747077667.183 [DataOverHttps](IMPORTANT): SBD MTMSN=20250512T192106
2025-05-12T19:21:14.618Z,1747077674.618 [DataOverHttps](INFO): Received command: restart logs