2025-04-28T21:12:17.575Z,1745874737.575 [DataOverHttps](INFO): Received command: restart logs 2025-04-28T21:12:17.596Z,1745874737.596 [CommandExec](IMPORTANT): got command restart logs 2025-04-28T21:12:34.968Z,1745874754.968 [NAL9602](INFO): Not Powering down - fast GPS 2025-04-28T21:12:37.464Z,1745874757.464 [DataOverHttps](INFO): Sending 894 bytes from file Logs/20250428T202201/Express0005.lzma 2025-04-28T21:12:38.465Z,1745874758.465 [DataOverHttps](INFO): Moved sent file to Logs/20250428T202201/Express0005.lzma.bak 2025-04-28T21:12:38.465Z,1745874758.465 [DataOverHttps](INFO): SBD MOMSN=24740869 2025-04-28T21:12:47.512Z,1745874767.512 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2025-04-28T21:12:47.515Z,1745874767.515 [BPC1](INFO): Received data from all battery sticks. 2025-04-28T21:13:06.762Z,1745874786.762 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T202201/Courier0009.lzma 2025-04-28T21:13:07.765Z,1745874787.765 [DataOverHttps](INFO): Moved sent file to Logs/20250428T202201/Courier0009.lzma.bak 2025-04-28T21:13:07.765Z,1745874787.765 [DataOverHttps](INFO): SBD MOMSN=24740886 2025-04-28T21:13:48.611Z,1745874828.611 [DataOverHttps](INFO): Sending 218 bytes from file Logs/20250428T202201/Express0010.lzma 2025-04-28T21:13:49.609Z,1745874829.609 [DataOverHttps](INFO): Moved sent file to Logs/20250428T202201/Express0010.lzma.bak 2025-04-28T21:13:49.609Z,1745874829.609 [DataOverHttps](INFO): SBD MOMSN=24740888 2025-04-28T21:13:51.038Z,1745874831.038 [Default:CheckIn:Read_Iridium] Stopped 2025-04-28T21:13:51.055Z,1745874831.055 [Default:CheckIn:C.Wait] Running Loop=1 2025-04-28T21:13:51.056Z,1745874831.056 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:17:31.424Z,1745875051.424 [DataOverHttps](IMPORTANT): SBD MTMSN=20250428T211730 2025-04-28T21:17:38.847Z,1745875058.847 [DataOverHttps](INFO): Received command: ! date 2025-04-28T21:17:38.908Z,1745875058.908 [CommandExec](IMPORTANT): got command ! date 2025-04-28T21:17:39.029Z,1745875059.029 [CommandExec](IMPORTANT): Mon Apr 28 21:17:39 UTC 2025 2025-04-28T21:18:51.625Z,1745875131.625 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2025-04-28T21:18:51.625Z,1745875131.625 [Default:CheckIn:C.Wait] Stopped 2025-04-28T21:18:51.625Z,1745875131.625 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:18:51.625Z,1745875131.625 [Default:CheckIn:D] Running Loop=1 2025-04-28T21:18:52.018Z,1745875132.018 [Default:CheckIn:D] Stopped 2025-04-28T21:18:52.018Z,1745875132.018 [Default:CheckIn:E] Running Loop=1 2025-04-28T21:18:52.426Z,1745875132.426 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 17.330223 min 2025-04-28T21:18:52.426Z,1745875132.426 [Default:CheckIn:E] Stopped 2025-04-28T21:18:52.426Z,1745875132.426 [Default:CheckIn](INFO): Completed Default:CheckIn 2025-04-28T21:18:52.426Z,1745875132.426 [Default:CheckIn] Stopped 2025-04-28T21:18:52.427Z,1745875132.427 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2025-04-28T21:18:52.427Z,1745875132.427 [Default:CheckIn](INFO): Running loop #2 2025-04-28T21:18:52.427Z,1745875132.427 [Default:CheckIn] Running Loop=2 2025-04-28T21:18:52.427Z,1745875132.427 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2025-04-28T21:18:52.427Z,1745875132.427 [Default:CheckIn:Read_GPS] Running Loop=1 2025-04-28T21:18:54.029Z,1745875134.029 [NAL9602](FAULT): GPS failed to acquire within timeout. 2025-04-28T21:18:54.029Z,1745875134.029 [NAL9602] Data Fault, FailCount= 1 2025-04-28T21:18:54.029Z,1745875134.029 [NAL9602](ERROR): Data Fault 2025-04-28T21:18:54.049Z,1745875134.049 [CBIT](ERROR): Data Fault in component: NAL9602 2025-04-28T21:18:54.440Z,1745875134.440 [NAL9602](INFO): Powering down 2025-04-28T21:18:55.290Z,1745875135.290 [CBIT](INFO): Clearing failed state for component NAL9602 2025-04-28T21:18:55.291Z,1745875135.291 [NAL9602] No Fault, FailCount= 1 2025-04-28T21:19:24.732Z,1745875164.732 [NAL9602](INFO): Powering up NAL9602 2025-04-28T21:19:35.641Z,1745875175.641 [NAL9602](INFO): NAL9602 initialized 2025-04-28T21:20:51.201Z,1745875251.201 [NAL9602](INFO): SBD MO Status=2, MOMSN=19054, MT Status=2, MTMSN=0 2025-04-28T21:20:51.201Z,1745875251.201 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2025-04-28T21:23:35.529Z,1745875415.529 [DataOverHttps](IMPORTANT): SBD MTMSN=20250428T212334 2025-04-28T21:23:43.107Z,1745875423.107 [DataOverHttps](INFO): Received command: load Engineering/lab_test_optim.tl;set lab_test_optim.MissionTimeout 5 min;set lab_test_optim.BackseatWait 0 s;run 2025-04-28T21:23:43.198Z,1745875423.198 [CommandExec](IMPORTANT): got command load ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:23:43.199Z,1745875423.199 [MissionManager](INFO): Loading Mission from file: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:23:43.199Z,1745875423.199 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:23:43.201Z,1745875423.201 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:23:43.547Z,1745875423.547 [MissionManager](DEBUG): TethyslAPI: ./Missions/Engineering/lab_test_optim.tl translated into: 15 1 30 2 100 100 Waiting for backseat to start up... Trying to run Optim and Multiray forreal 1 Setting multiray red brightness to 2 Setting muliray white brightness to Recording for 2025-04-28T21:23:43.553Z,1745875423.553 [MissionManager](INFO): DefineArg lab_test_optim.MissionTimeout = 15.000000 min 2025-04-28T21:23:43.556Z,1745875423.556 [MissionManager](INFO): DefineArg lab_test_optim.RecordTime = 1.000000 min 2025-04-28T21:23:43.560Z,1745875423.560 [MissionManager](INFO): DefineArg lab_test_optim.BackseatWait = 30.000000 s 2025-04-28T21:23:43.563Z,1745875423.563 [MissionManager](INFO): DefineArg lab_test_optim.LightMode = 2.000000 count 2025-04-28T21:23:43.567Z,1745875423.567 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessWhite = 100.000000 n/a int32 2025-04-28T21:23:43.570Z,1745875423.570 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessRed = 100.000000 n/a int32 2025-04-28T21:23:43.573Z,1745875423.573 [MissionManager](INFO): DefineOutput lab_test_optim.RecordingEnabled = 0 bool 2025-04-28T21:23:43.596Z,1745875423.596 [MissionManager](INFO): DefineOutput lab_test_optim.LightsEnabled = 0 bool 2025-04-28T21:23:43.597Z,1745875423.597 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/BackseatDriver.tl 2025-04-28T21:23:43.597Z,1745875423.597 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Insert/BackseatDriver.tl 2025-04-28T21:23:43.598Z,1745875423.598 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Insert/BackseatDriver.tl 2025-04-28T21:23:43.652Z,1745875423.652 [MissionManager](DEBUG): TethyslAPI: Missions/Insert/BackseatDriver.tl translated into: 2025-04-28T21:23:43.661Z,1745875423.661 [MissionManager](INFO): DefineArg lab_test_optim:BackseatDriver.EnableBackseat = 0 bool 2025-04-28T21:23:43.668Z,1745875423.668 [lab_test_optim:BackseatDriver:A.BackseatDriver](DEBUG): Construct BackseatDriver. 2025-04-28T21:23:43.692Z,1745875423.692 [lab_test_optim:Startup:B.Wait](DEBUG): Construct Wait. 2025-04-28T21:23:43.740Z,1745875423.740 [lab_test_optim:Run:H.Wait](DEBUG): Construct Wait. 2025-04-28T21:23:43.742Z,1745875423.742 [lab_test_optim:G.Wait](DEBUG): Construct Wait. 2025-04-28T21:23:43.788Z,1745875423.788 [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-04-28T21:23:43.789Z,1745875423.789 [CommandExec](IMPORTANT): Loaded ./Missions/Engineering/lab_test_optim.tl id=lab_test_optim 2025-04-28T21:23:52.810Z,1745875432.810 [Default:CheckIn:Read_GPS](INFO): Timed out from 2025-04-28T21:18:52.4Z 2025-04-28T21:23:52.810Z,1745875432.810 [Default:CheckIn:Read_GPS] Stopped 2025-04-28T21:23:52.810Z,1745875432.810 [Default:CheckIn:Read_Iridium] Running Loop=1 2025-04-28T21:24:06.215Z,1745875446.215 [CommandExec](IMPORTANT): got command set lab_test_optim.MissionTimeout 5 minute 2025-04-28T21:24:06.216Z,1745875446.216 [CommandExec](IMPORTANT): got command set lab_test_optim.BackseatWait 0 second 2025-04-28T21:24:06.216Z,1745875446.216 [CommandExec](IMPORTANT): got command run 2025-04-28T21:24:06.223Z,1745875446.223 [CommandExec](IMPORTANT): Running 2025-04-28T21:24:06.550Z,1745875446.550 [Default] Stopped 2025-04-28T21:24:06.566Z,1745875446.566 [Default](DEBUG): Aggregate::uninitialize Default 2025-04-28T21:24:06.567Z,1745875446.567 [Default:B.GoToSurface] Stopped 2025-04-28T21:24:06.567Z,1745875446.567 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-04-28T21:24:06.567Z,1745875446.567 [Default:CheckIn] Stopped 2025-04-28T21:24:06.567Z,1745875446.567 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2025-04-28T21:24:06.567Z,1745875446.567 [Default:CheckIn:Read_Iridium] Stopped 2025-04-28T21:24:06.567Z,1745875446.567 [MissionManager](IMPORTANT): Started mission lab_test_optim 2025-04-28T21:24:06.567Z,1745875446.567 [lab_test_optim] Running Loop=1 2025-04-28T21:24:06.567Z,1745875446.567 [lab_test_optim](DEBUG): Aggregate::initialize lab_test_optim 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:BackseatDriver] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::initialize lab_test_optim:BackseatDriver 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:BackseatDriver:A.BackseatDriver] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:B] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:C] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:D] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:Startup] Running Loop=1 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:Startup](DEBUG): Aggregate::initialize lab_test_optim:Startup 2025-04-28T21:24:06.568Z,1745875446.568 [lab_test_optim:Startup:A] Running Loop=1 2025-04-28T21:24:06.569Z,1745875446.569 [lab_test_optim:Startup:A](IMPORTANT): Waiting 0.000000 s for backseat to start up... 2025-04-28T21:24:06.569Z,1745875446.569 [lab_test_optim:Startup:A] Stopped 2025-04-28T21:24:06.569Z,1745875446.569 [lab_test_optim:Startup:B.Wait] Running Loop=1 2025-04-28T21:24:06.569Z,1745875446.569 [lab_test_optim:Startup:B.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:24:06.570Z,1745875446.570 [lab_test_optim:D] Stopped 2025-04-28T21:24:06.570Z,1745875446.570 [lab_test_optim:C] Stopped 2025-04-28T21:24:06.570Z,1745875446.570 [lab_test_optim:B] Running Loop=1 2025-04-28T21:24:06.570Z,1745875446.570 [lab_test_optim:BackseatDriver] Running Loop=1 2025-04-28T21:24:06.570Z,1745875446.570 [lab_test_optim:BackseatDriver:A.BackseatDriver](INFO): Initializing backseat 2025-04-28T21:24:06.603Z,1745875446.603 [BackseatComponent](INFO): Powering up 2025-04-28T21:24:06.604Z,1745875446.604 [BackseatComponent](INFO): Subscribing to LCM channels. 2025-04-28T21:24:06.704Z,1745875446.704 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20250428T211217/Courier0003.lzma 2025-04-28T21:24:06.954Z,1745875446.954 [lab_test_optim:Startup:B.Wait](INFO): Done Waiting. 2025-04-28T21:24:06.954Z,1745875446.954 [lab_test_optim:Startup:B.Wait] Stopped 2025-04-28T21:24:06.954Z,1745875446.954 [lab_test_optim:Startup:B.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Startup](INFO): Completed lab_test_optim:Startup 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Startup] Stopped 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Startup](DEBUG): Aggregate::uninitialize lab_test_optim:Startup 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Run] Running Loop=1 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Run](DEBUG): Aggregate::initialize lab_test_optim:Run 2025-04-28T21:24:06.955Z,1745875446.955 [lab_test_optim:Run:A] Running Loop=1 2025-04-28T21:24:07.384Z,1745875447.384 [lab_test_optim:Run:A](IMPORTANT): Trying to run Optim and Multiray forreal 2025-04-28T21:24:07.384Z,1745875447.384 [lab_test_optim:Run:A] Stopped 2025-04-28T21:24:07.384Z,1745875447.384 [lab_test_optim:Run:B] Running Loop=1 2025-04-28T21:24:07.705Z,1745875447.705 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0003.lzma.bak 2025-04-28T21:24:07.705Z,1745875447.705 [DataOverHttps](INFO): SBD MOMSN=24740915 2025-04-28T21:24:07.787Z,1745875447.787 [lab_test_optim:Run:B] Stopped 2025-04-28T21:24:07.787Z,1745875447.787 [lab_test_optim:Run:C] Running Loop=1 2025-04-28T21:24:08.162Z,1745875448.162 [lab_test_optim:Run:C] Stopped 2025-04-28T21:24:08.162Z,1745875448.162 [lab_test_optim:Run:D] Running Loop=1 2025-04-28T21:24:08.162Z,1745875448.162 [lab_test_optim:C] Running Loop=1 2025-04-28T21:24:08.162Z,1745875448.162 [lab_test_optim:C] Running Loop=1 2025-04-28T21:24:08.163Z,1745875448.163 [lab_test_optim:C](DEBUG): Initialize ReadDataComponent to sense PowerOnly.sampleLoad1 2025-04-28T21:24:08.558Z,1745875448.558 [PowerOnly](INFO): Powering up loadControl 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:Run:D] Stopped 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:Run:setRed] Running Loop=1 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:Run:setRed](DEBUG): Aggregate::initialize lab_test_optim:Run:setRed 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:Run:setRed:A] Running Loop=1 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:D] Running Loop=1 2025-04-28T21:24:08.607Z,1745875448.607 [lab_test_optim:D] Running Loop=1 2025-04-28T21:24:08.608Z,1745875448.608 [lab_test_optim:D](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog 2025-04-28T21:24:08.971Z,1745875448.971 [lab_test_optim:Run:setRed] Stopped 2025-04-28T21:24:08.972Z,1745875448.972 [lab_test_optim:Run:setRed](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setRed 2025-04-28T21:24:08.972Z,1745875448.972 [lab_test_optim:Run:setRed:A] Stopped 2025-04-28T21:24:08.972Z,1745875448.972 [lab_test_optim:Run:setWhite] Running Loop=1 2025-04-28T21:24:08.972Z,1745875448.972 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::initialize lab_test_optim:Run:setWhite 2025-04-28T21:24:08.972Z,1745875448.972 [lab_test_optim:Run:setWhite:A] Running Loop=1 2025-04-28T21:24:09.410Z,1745875449.410 [lab_test_optim:Run:setWhite:A] Stopped 2025-04-28T21:24:09.410Z,1745875449.410 [lab_test_optim:Run:setWhite:B] Running Loop=1 2025-04-28T21:24:09.835Z,1745875449.835 [lab_test_optim:Run:setWhite:B](INFO): Setting muliray white brightness to 100.000000 count 2025-04-28T21:24:09.836Z,1745875449.836 [lab_test_optim:Run:setWhite:B] Stopped 2025-04-28T21:24:09.836Z,1745875449.836 [lab_test_optim:Run:setWhite](INFO): Completed lab_test_optim:Run:setWhite 2025-04-28T21:24:09.836Z,1745875449.836 [lab_test_optim:Run:setWhite] Stopped 2025-04-28T21:24:09.836Z,1745875449.836 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setWhite 2025-04-28T21:24:09.836Z,1745875449.836 [lab_test_optim:Run:G] Running Loop=1 2025-04-28T21:24:10.184Z,1745875450.184 [lab_test_optim:Run:G](IMPORTANT): Recording for 1.000000 min 2025-04-28T21:24:10.184Z,1745875450.184 [lab_test_optim:Run:G] Stopped 2025-04-28T21:24:10.184Z,1745875450.184 [lab_test_optim:Run:H.Wait] Running Loop=1 2025-04-28T21:24:10.184Z,1745875450.184 [lab_test_optim:Run:H.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:24:10.984Z,1745875450.984 [MultiRay](IMPORTANT): MultiRay white lights ON 2025-04-28T21:24:25.549Z,1745875465.549 [lab_test_optim:BackseatDriver:A.BackseatDriver](INFO): Created data writer for _.data_dir_logging_rate with code: 2352 2025-04-28T21:24:25.812Z,1745875465.812 [BackseatComponent](CRITICAL): ikshana: Data dir size (16.52 GB) did not increase within 10 minutes 2025-04-28T21:24:25.812Z,1745875465.812 [BackseatComponent] Data Fault, FailCount= 1 2025-04-28T21:24:25.812Z,1745875465.812 [BackseatComponent](ERROR): Data Fault 2025-04-28T21:24:25.969Z,1745875465.969 [CommandExec](FAULT): Scheduling is paused 2025-04-28T21:24:25.969Z,1745875465.969 [CBIT](INFO): Critical error at 20250428T212425 2025-04-28T21:24:25.969Z,1745875465.969 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2025-04-28T21:24:25.976Z,1745875465.976 [CBIT](ERROR): Data Fault in component: BackseatComponent 2025-04-28T21:24:26.216Z,1745875466.216 [BackseatComponent](INFO): Sent LCM shutdown request. 2025-04-28T21:24:26.216Z,1745875466.216 [BackseatComponent](INFO): Shutdown requested. Waiting (18.00 sec to power down.). 2025-04-28T21:24:26.359Z,1745875466.359 [MissionManager](INFO): MissionManager is completed. 2025-04-28T21:24:26.359Z,1745875466.359 [MissionManager](INFO): Uninitializing Mission lab_test_optim 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim] Stopped 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim](DEBUG): Aggregate::uninitialize lab_test_optim 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:BackseatDriver] Stopped 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::uninitialize lab_test_optim:BackseatDriver 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:BackseatDriver:A.BackseatDriver] Stopped 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:B] Stopped 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:C] Stopped 2025-04-28T21:24:26.359Z,1745875466.359 [lab_test_optim:D] Stopped 2025-04-28T21:24:26.360Z,1745875466.360 [lab_test_optim:Run] Stopped 2025-04-28T21:24:26.360Z,1745875466.360 [lab_test_optim:Run](DEBUG): Aggregate::uninitialize lab_test_optim:Run 2025-04-28T21:24:26.360Z,1745875466.360 [lab_test_optim:Run:H.Wait] Stopped 2025-04-28T21:24:26.360Z,1745875466.360 [lab_test_optim:Run:H.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:24:26.758Z,1745875466.758 [MissionManager](IMPORTANT): Started mission Default 2025-04-28T21:24:26.759Z,1745875466.759 [Default] Running Loop=1 2025-04-28T21:24:26.759Z,1745875466.759 [Default](DEBUG): Aggregate::initialize Default 2025-04-28T21:24:26.759Z,1745875466.759 [Default:B.GoToSurface] Running Loop=1 2025-04-28T21:24:26.759Z,1745875466.759 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-04-28T21:24:26.759Z,1745875466.759 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-04-28T21:24:26.760Z,1745875466.760 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-04-28T21:24:26.760Z,1745875466.760 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-04-28T21:24:26.760Z,1745875466.760 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-04-28T21:24:26.762Z,1745875466.762 [Default:B.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-04-28T21:24:26.762Z,1745875466.762 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-04-28T21:24:26.763Z,1745875466.763 [Default:A.Wait] Running Loop=1 2025-04-28T21:24:26.763Z,1745875466.763 [Default:A.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:24:27.140Z,1745875467.140 [MultiRay](INFO): Powering down 2025-04-28T21:24:27.255Z,1745875467.255 [MultiRay](INFO): Powering down LCB2 2025-04-28T21:24:38.856Z,1745875478.856 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2025-04-28T21:24:40.079Z,1745875480.079 [Default:A.Wait](INFO): Done Waiting. 2025-04-28T21:24:40.079Z,1745875480.079 [Default:A.Wait] Stopped 2025-04-28T21:24:40.079Z,1745875480.079 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:24:40.486Z,1745875480.486 [Default:CheckIn] Running Loop=1 2025-04-28T21:24:40.487Z,1745875480.487 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2025-04-28T21:24:40.487Z,1745875480.487 [Default:CheckIn:Read_GPS] Running Loop=1 2025-04-28T21:24:42.496Z,1745875482.496 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212441.00,A,3647.70116,N,12151.28260,W,0.136,159.97,280425,,,A*7D 2025-04-28T21:24:42.498Z,1745875482.498 [NAL9602](INFO): GPS fix at 20250428T212441: (36.795019, -121.854710) 2025-04-28T21:24:42.510Z,1745875482.510 [UniversalFixResidualReporter](INFO): Fix residual: 24.9 %DT, over the last 1990.0 m. Residual distance 496.4 m at bearing -71.6 degrees. Fix at (36.7950, -121.8547) with 298.2 m made good. 2025-04-28T21:24:42.511Z,1745875482.511 [Default:CheckIn:Read_GPS] Stopped 2025-04-28T21:24:42.511Z,1745875482.511 [Default:CheckIn:Read_Iridium] Running Loop=1 2025-04-28T21:24:44.395Z,1745875484.395 [BackseatComponent](INFO): Powering down and starting shutdown timer (18.00 sec). 2025-04-28T21:24:44.396Z,1745875484.396 [BackseatComponent](INFO): Unsubscribing from LCM channels. 2025-04-28T21:24:44.396Z,1745875484.396 [LcmUniversalReporter](INFO): Deactivating messaging. 2025-04-28T21:24:50.198Z,1745875490.198 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0006.lzma 2025-04-28T21:24:52.205Z,1745875492.205 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0006.lzma.bak 2025-04-28T21:24:52.205Z,1745875492.205 [DataOverHttps](INFO): SBD MOMSN=24740918 2025-04-28T21:25:03.132Z,1745875503.132 [CBIT](INFO): Clearing failed state for component BackseatComponent 2025-04-28T21:25:03.132Z,1745875503.132 [BackseatComponent] No Fault, FailCount= 0 2025-04-28T21:25:03.383Z,1745875503.383 [BackseatComponent](INFO): Powering up 2025-04-28T21:25:03.383Z,1745875503.383 [BackseatComponent](INFO): Subscribing to LCM channels. 2025-04-28T21:25:08.043Z,1745875508.043 [DataOverHttps](INFO): Sending 374 bytes from file Logs/20250428T211217/Courier0009.lzma 2025-04-28T21:25:09.045Z,1745875509.045 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0009.lzma.bak 2025-04-28T21:25:09.045Z,1745875509.045 [DataOverHttps](INFO): SBD MOMSN=24740920 2025-04-28T21:25:14.416Z,1745875514.416 [NAL9602](INFO): Not Powering down - fast GPS 2025-04-28T21:25:24.096Z,1745875524.096 [BackseatComponent](INFO): Sent LCM shutdown request. 2025-04-28T21:25:24.096Z,1745875524.096 [BackseatComponent](INFO): Shutdown requested. Waiting (18.00 sec to power down.). 2025-04-28T21:25:26.132Z,1745875526.132 [DataOverHttps](INFO): Sending 609 bytes from file Logs/20250428T211217/Express0004.lzma 2025-04-28T21:25:27.132Z,1745875527.132 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0004.lzma.bak 2025-04-28T21:25:27.133Z,1745875527.133 [DataOverHttps](INFO): SBD MOMSN=24740924 2025-04-28T21:25:42.107Z,1745875542.107 [BackseatComponent](INFO): Powering down and starting shutdown timer (18.00 sec). 2025-04-28T21:25:42.108Z,1745875542.108 [BackseatComponent](INFO): Unsubscribing from LCM channels. 2025-04-28T21:25:42.108Z,1745875542.108 [LcmUniversalReporter](INFO): Deactivating messaging. 2025-04-28T21:25:44.102Z,1745875544.102 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20250428T211217/Express0007.lzma 2025-04-28T21:25:45.104Z,1745875545.104 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0007.lzma.bak 2025-04-28T21:25:45.105Z,1745875545.105 [DataOverHttps](INFO): SBD MOMSN=24740935 2025-04-28T21:25:56.881Z,1745875556.881 [PowerOnly](INFO): Powering down loadControl 2025-04-28T21:26:03.821Z,1745875563.821 [DataOverHttps](INFO): Sending 646 bytes from file Logs/20250428T211217/Express0010.lzma 2025-04-28T21:26:04.749Z,1745875564.749 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0010.lzma.bak 2025-04-28T21:26:04.749Z,1745875564.749 [DataOverHttps](IMPORTANT): SBD MOMSN=24740938, MTMSN=20250428T212603 2025-04-28T21:26:05.807Z,1745875565.807 [Default:CheckIn:Read_Iridium] Stopped 2025-04-28T21:26:05.807Z,1745875565.807 [Default:CheckIn:C.Wait] Running Loop=1 2025-04-28T21:26:05.807Z,1745875565.807 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:26:12.223Z,1745875572.223 [DataOverHttps](INFO): Received command: load Engineering/lab_test_optim.tl;set lab_test_optim.MissionTimeout 5 min;set lab_test_optim.BackseatWait 0 s;run 2025-04-28T21:26:12.320Z,1745875572.320 [CommandExec](IMPORTANT): got command load ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:26:12.320Z,1745875572.320 [MissionManager](INFO): Loading Mission from file: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:26:12.320Z,1745875572.320 [MissionManager](DEBUG): TethyslAPI: loading: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:26:12.322Z,1745875572.322 [MissionManager](DEBUG): TethyslAPI: mission file loaded: ./Missions/Engineering/lab_test_optim.tl 2025-04-28T21:26:12.575Z,1745875572.575 [MissionManager](DEBUG): TethyslAPI: ./Missions/Engineering/lab_test_optim.tl translated into: 15 1 30 2 100 100 Waiting for backseat to start up... Trying to run Optim and Multiray forreal 1 Setting multiray red brightness to 2 Setting muliray white brightness to Recording for 2025-04-28T21:26:12.580Z,1745875572.580 [MissionManager](INFO): DefineArg lab_test_optim.MissionTimeout = 15.000000 min 2025-04-28T21:26:12.582Z,1745875572.582 [MissionManager](INFO): DefineArg lab_test_optim.RecordTime = 1.000000 min 2025-04-28T21:26:12.585Z,1745875572.585 [MissionManager](INFO): DefineArg lab_test_optim.BackseatWait = 30.000000 s 2025-04-28T21:26:12.587Z,1745875572.587 [MissionManager](INFO): DefineArg lab_test_optim.LightMode = 2.000000 count 2025-04-28T21:26:12.589Z,1745875572.589 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessWhite = 100.000000 n/a int32 2025-04-28T21:26:12.591Z,1745875572.591 [MissionManager](INFO): DefineArg lab_test_optim.BrightnessRed = 100.000000 n/a int32 2025-04-28T21:26:12.594Z,1745875572.594 [MissionManager](INFO): DefineOutput lab_test_optim.RecordingEnabled = 0 bool 2025-04-28T21:26:12.596Z,1745875572.596 [MissionManager](INFO): DefineOutput lab_test_optim.LightsEnabled = 0 bool 2025-04-28T21:26:12.596Z,1745875572.596 [MissionManager](INFO): Inserting Stack from file: Missions/Insert/BackseatDriver.tl 2025-04-28T21:26:12.597Z,1745875572.597 [MissionManager](DEBUG): TethyslAPI: loading: Missions/Insert/BackseatDriver.tl 2025-04-28T21:26:12.597Z,1745875572.597 [MissionManager](DEBUG): TethyslAPI: mission file loaded: Missions/Insert/BackseatDriver.tl 2025-04-28T21:26:12.694Z,1745875572.694 [MissionManager](DEBUG): TethyslAPI: Missions/Insert/BackseatDriver.tl translated into: 2025-04-28T21:26:12.713Z,1745875572.713 [MissionManager](INFO): DefineArg lab_test_optim:BackseatDriver.EnableBackseat = 0 bool 2025-04-28T21:26:12.716Z,1745875572.716 [lab_test_optim:BackseatDriver:A.BackseatDriver](DEBUG): Construct BackseatDriver. 2025-04-28T21:26:12.745Z,1745875572.745 [lab_test_optim:Startup:B.Wait](DEBUG): Construct Wait. 2025-04-28T21:26:12.790Z,1745875572.790 [lab_test_optim:Run:H.Wait](DEBUG): Construct Wait. 2025-04-28T21:26:12.800Z,1745875572.800 [lab_test_optim:G.Wait](DEBUG): Construct Wait. 2025-04-28T21:26:12.810Z,1745875572.810 [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-04-28T21:26:12.814Z,1745875572.814 [CommandExec](IMPORTANT): Loaded ./Missions/Engineering/lab_test_optim.tl id=lab_test_optim 2025-04-28T21:26:23.253Z,1745875583.253 [CommandExec](IMPORTANT): got command set lab_test_optim.MissionTimeout 5 minute 2025-04-28T21:26:23.254Z,1745875583.254 [CommandExec](IMPORTANT): got command set lab_test_optim.BackseatWait 0 second 2025-04-28T21:26:23.267Z,1745875583.267 [CommandExec](IMPORTANT): got command run 2025-04-28T21:26:23.269Z,1745875583.269 [CommandExec](IMPORTANT): Running 2025-04-28T21:26:23.557Z,1745875583.557 [Default] Stopped 2025-04-28T21:26:23.558Z,1745875583.558 [Default](DEBUG): Aggregate::uninitialize Default 2025-04-28T21:26:23.558Z,1745875583.558 [Default:B.GoToSurface] Stopped 2025-04-28T21:26:23.558Z,1745875583.558 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2025-04-28T21:26:23.558Z,1745875583.558 [Default:CheckIn] Stopped 2025-04-28T21:26:23.558Z,1745875583.558 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2025-04-28T21:26:23.558Z,1745875583.558 [Default:CheckIn:C.Wait] Stopped 2025-04-28T21:26:23.558Z,1745875583.558 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:26:23.558Z,1745875583.558 [MissionManager](IMPORTANT): Started mission lab_test_optim 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim](DEBUG): Aggregate::initialize lab_test_optim 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:BackseatDriver] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::initialize lab_test_optim:BackseatDriver 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:BackseatDriver:A.BackseatDriver] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:B] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:C] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:D] Running Loop=1 2025-04-28T21:26:23.559Z,1745875583.559 [lab_test_optim:Startup] Running Loop=1 2025-04-28T21:26:23.560Z,1745875583.560 [lab_test_optim:Startup](DEBUG): Aggregate::initialize lab_test_optim:Startup 2025-04-28T21:26:23.560Z,1745875583.560 [lab_test_optim:Startup:A] Running Loop=1 2025-04-28T21:26:23.560Z,1745875583.560 [lab_test_optim:Startup:A](IMPORTANT): Waiting 0.000000 s for backseat to start up... 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:Startup:A] Stopped 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:Startup:B.Wait] Running Loop=1 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:Startup:B.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:D] Stopped 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:C] Stopped 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:B] Running Loop=1 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:BackseatDriver] Running Loop=1 2025-04-28T21:26:23.561Z,1745875583.561 [lab_test_optim:BackseatDriver:A.BackseatDriver](INFO): Initializing backseat 2025-04-28T21:26:23.615Z,1745875583.615 [BackseatComponent](INFO): Powering up 2025-04-28T21:26:23.615Z,1745875583.615 [BackseatComponent](INFO): Subscribing to LCM channels. 2025-04-28T21:26:23.958Z,1745875583.958 [lab_test_optim:Startup:B.Wait](INFO): Done Waiting. 2025-04-28T21:26:23.958Z,1745875583.958 [lab_test_optim:Startup:B.Wait] Stopped 2025-04-28T21:26:23.958Z,1745875583.958 [lab_test_optim:Startup:B.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:26:23.958Z,1745875583.958 [lab_test_optim:Startup](INFO): Completed lab_test_optim:Startup 2025-04-28T21:26:23.958Z,1745875583.958 [lab_test_optim:Startup] Stopped 2025-04-28T21:26:23.959Z,1745875583.959 [lab_test_optim:Startup](DEBUG): Aggregate::uninitialize lab_test_optim:Startup 2025-04-28T21:26:23.959Z,1745875583.959 [lab_test_optim:Run] Running Loop=1 2025-04-28T21:26:23.959Z,1745875583.959 [lab_test_optim:Run](DEBUG): Aggregate::initialize lab_test_optim:Run 2025-04-28T21:26:23.959Z,1745875583.959 [lab_test_optim:Run:A] Running Loop=1 2025-04-28T21:26:24.371Z,1745875584.371 [lab_test_optim:Run:A](IMPORTANT): Trying to run Optim and Multiray forreal 2025-04-28T21:26:24.371Z,1745875584.371 [lab_test_optim:Run:A] Stopped 2025-04-28T21:26:24.371Z,1745875584.371 [lab_test_optim:Run:B] Running Loop=1 2025-04-28T21:26:24.762Z,1745875584.762 [lab_test_optim:Run:B] Stopped 2025-04-28T21:26:24.762Z,1745875584.762 [lab_test_optim:Run:C] Running Loop=1 2025-04-28T21:26:25.164Z,1745875585.164 [lab_test_optim:Run:C] Stopped 2025-04-28T21:26:25.164Z,1745875585.164 [lab_test_optim:Run:D] Running Loop=1 2025-04-28T21:26:25.164Z,1745875585.164 [lab_test_optim:C] Running Loop=1 2025-04-28T21:26:25.164Z,1745875585.164 [lab_test_optim:C] Running Loop=1 2025-04-28T21:26:25.165Z,1745875585.165 [lab_test_optim:C](DEBUG): Initialize ReadDataComponent to sense PowerOnly.sampleLoad1 2025-04-28T21:26:25.564Z,1745875585.564 [PowerOnly](INFO): Powering up loadControl 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:Run:D] Stopped 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:Run:setRed] Running Loop=1 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:Run:setRed](DEBUG): Aggregate::initialize lab_test_optim:Run:setRed 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:Run:setRed:A] Running Loop=1 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:D] Running Loop=1 2025-04-28T21:26:25.599Z,1745875585.599 [lab_test_optim:D] Running Loop=1 2025-04-28T21:26:25.600Z,1745875585.600 [lab_test_optim:D](DEBUG): Initialize ReadDataComponent to sense MultiRay.lightModeLog 2025-04-28T21:26:25.981Z,1745875585.981 [lab_test_optim:Run:setRed] Stopped 2025-04-28T21:26:25.981Z,1745875585.981 [lab_test_optim:Run:setRed](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setRed 2025-04-28T21:26:25.981Z,1745875585.981 [lab_test_optim:Run:setRed:A] Stopped 2025-04-28T21:26:25.981Z,1745875585.981 [lab_test_optim:Run:setWhite] Running Loop=1 2025-04-28T21:26:25.981Z,1745875585.981 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::initialize lab_test_optim:Run:setWhite 2025-04-28T21:26:25.982Z,1745875585.982 [lab_test_optim:Run:setWhite:A] Running Loop=1 2025-04-28T21:26:26.404Z,1745875586.404 [lab_test_optim:Run:setWhite:A] Stopped 2025-04-28T21:26:26.405Z,1745875586.405 [lab_test_optim:Run:setWhite:B] Running Loop=1 2025-04-28T21:26:26.827Z,1745875586.827 [lab_test_optim:Run:setWhite:B](INFO): Setting muliray white brightness to 100.000000 count 2025-04-28T21:26:26.827Z,1745875586.827 [lab_test_optim:Run:setWhite:B] Stopped 2025-04-28T21:26:26.828Z,1745875586.828 [lab_test_optim:Run:setWhite](INFO): Completed lab_test_optim:Run:setWhite 2025-04-28T21:26:26.828Z,1745875586.828 [lab_test_optim:Run:setWhite] Stopped 2025-04-28T21:26:26.828Z,1745875586.828 [lab_test_optim:Run:setWhite](DEBUG): Aggregate::uninitialize lab_test_optim:Run:setWhite 2025-04-28T21:26:26.828Z,1745875586.828 [lab_test_optim:Run:G] Running Loop=1 2025-04-28T21:26:27.184Z,1745875587.184 [lab_test_optim:Run:G](IMPORTANT): Recording for 1.000000 min 2025-04-28T21:26:27.184Z,1745875587.184 [lab_test_optim:Run:G] Stopped 2025-04-28T21:26:27.184Z,1745875587.184 [lab_test_optim:Run:H.Wait] Running Loop=1 2025-04-28T21:26:27.184Z,1745875587.184 [lab_test_optim:Run:H.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:26:27.980Z,1745875587.980 [MultiRay](IMPORTANT): MultiRay white lights ON 2025-04-28T21:27:21.560Z,1745875641.560 [BackseatComponent](IMPORTANT): ikshana: running backseat application. 2025-04-28T21:27:24.266Z,1745875644.266 [BackseatComponent](INFO): Created universal data reader for depth with code: 6 2025-04-28T21:27:24.266Z,1745875644.266 [BackseatComponent](INFO): Requesting data from depth (6). Requested size is: 1 2025-04-28T21:27:27.782Z,1745875647.782 [lab_test_optim:Run:H.Wait](INFO): Done Waiting. 2025-04-28T21:27:27.782Z,1745875647.782 [lab_test_optim:Run:H.Wait] Stopped 2025-04-28T21:27:27.782Z,1745875647.782 [lab_test_optim:Run:H.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:27:27.783Z,1745875647.783 [lab_test_optim:Run](INFO): Completed lab_test_optim:Run 2025-04-28T21:27:27.783Z,1745875647.783 [lab_test_optim:Run] Stopped 2025-04-28T21:27:27.783Z,1745875647.783 [lab_test_optim:Run](DEBUG): Aggregate::uninitialize lab_test_optim:Run 2025-04-28T21:27:27.783Z,1745875647.783 [lab_test_optim:G.Wait] Running Loop=1 2025-04-28T21:27:27.783Z,1745875647.783 [lab_test_optim:G.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim](INFO): Timed out from 2025-04-28T21:26:23.6Z 2025-04-28T21:31:23.727Z,1745875883.727 [MissionManager](INFO): lab_test_optim is completed. 2025-04-28T21:31:23.727Z,1745875883.727 [MissionManager](INFO): Uninitializing Mission lab_test_optim 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim] Stopped 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim](DEBUG): Aggregate::uninitialize lab_test_optim 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim:BackseatDriver] Stopped 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim:BackseatDriver](DEBUG): Aggregate::uninitialize lab_test_optim:BackseatDriver 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim:BackseatDriver:A.BackseatDriver] Stopped 2025-04-28T21:31:23.727Z,1745875883.727 [lab_test_optim:B] Stopped 2025-04-28T21:31:23.728Z,1745875883.728 [lab_test_optim:C] Stopped 2025-04-28T21:31:23.728Z,1745875883.728 [lab_test_optim:D] Stopped 2025-04-28T21:31:23.728Z,1745875883.728 [lab_test_optim:G.Wait] Stopped 2025-04-28T21:31:23.728Z,1745875883.728 [lab_test_optim:G.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:31:24.129Z,1745875884.129 [MissionManager](IMPORTANT): Started mission Default 2025-04-28T21:31:24.129Z,1745875884.129 [Default] Running Loop=1 2025-04-28T21:31:24.130Z,1745875884.130 [Default](DEBUG): Aggregate::initialize Default 2025-04-28T21:31:24.130Z,1745875884.130 [Default:B.GoToSurface] Running Loop=1 2025-04-28T21:31:24.130Z,1745875884.130 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2025-04-28T21:31:24.130Z,1745875884.130 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2025-04-28T21:31:24.130Z,1745875884.130 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2025-04-28T21:31:24.131Z,1745875884.131 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2025-04-28T21:31:24.131Z,1745875884.131 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2025-04-28T21:31:24.131Z,1745875884.131 [Default:B.GoToSurface](DEBUG): No altitude timeout specified. Using default value of 600.000000 seconds. 2025-04-28T21:31:24.132Z,1745875884.132 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2025-04-28T21:31:24.132Z,1745875884.132 [Default:A.Wait] Running Loop=1 2025-04-28T21:31:24.132Z,1745875884.132 [Default:A.Wait](DEBUG): Initialize Wait Component. 2025-04-28T21:31:24.525Z,1745875884.525 [MultiRay](INFO): Powering down 2025-04-28T21:31:24.639Z,1745875884.639 [MultiRay](INFO): Powering down LCB2 2025-04-28T21:31:25.116Z,1745875885.116 [BackseatComponent](INFO): Sent LCM shutdown request. 2025-04-28T21:31:25.116Z,1745875885.116 [BackseatComponent](INFO): Shutdown requested. Waiting (18.00 sec to power down.). 2025-04-28T21:31:37.460Z,1745875897.460 [Default:A.Wait](INFO): Done Waiting. 2025-04-28T21:31:37.460Z,1745875897.460 [Default:A.Wait] Stopped 2025-04-28T21:31:37.460Z,1745875897.460 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2025-04-28T21:31:37.873Z,1745875897.873 [Default:CheckIn] Running Loop=1 2025-04-28T21:31:37.873Z,1745875897.873 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2025-04-28T21:31:37.873Z,1745875897.873 [Default:CheckIn:Read_GPS] Running Loop=1 2025-04-28T21:31:39.878Z,1745875899.878 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,213139.00,A,3647.66347,N,12151.24364,W,0.622,104.90,280425,,,A*73 2025-04-28T21:31:39.880Z,1745875899.880 [NAL9602](INFO): GPS fix at 20250428T213139: (36.794391, -121.854061) 2025-04-28T21:31:39.912Z,1745875899.912 [Default:CheckIn:Read_GPS] Stopped 2025-04-28T21:31:39.912Z,1745875899.912 [Default:CheckIn:Read_Iridium] Running Loop=1 2025-04-28T21:31:43.305Z,1745875903.305 [BackseatComponent](INFO): Powering down and starting shutdown timer (18.00 sec). 2025-04-28T21:31:43.306Z,1745875903.306 [BackseatComponent](INFO): Unsubscribing from LCM channels. 2025-04-28T21:31:43.306Z,1745875903.306 [LcmUniversalReporter](INFO): Deactivating messaging. 2025-04-28T21:31:50.399Z,1745875910.399 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20250428T211217/Courier0012.lzma 2025-04-28T21:31:51.398Z,1745875911.398 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0012.lzma.bak 2025-04-28T21:31:51.398Z,1745875911.398 [DataOverHttps](IMPORTANT): SBD MOMSN=24740963, MTMSN=20250428T213150 2025-04-28T21:31:59.203Z,1745875919.203 [DataOverHttps](INFO): Received command: sched "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s" crt0 1 2 2025-04-28T21:31:59.234Z,1745875919.234 [CommandExec](IMPORTANT): got command schedule "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s" crt0 1 2.000000 2025-04-28T21:31:59.235Z,1745875919.235 [CommandExec](IMPORTANT): Scheduling command #1 of 2 with id=crt0 2025-04-28T21:31:59.236Z,1745875919.236 [CommandExec](IMPORTANT): Scheduled #5 (#1 of 2 with id='crt0'): "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s", AFTER MISSION 2025-04-28T21:31:59.236Z,1745875919.236 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:32:00.395Z,1745875920.395 [DataOverHttps](IMPORTANT): SBD MTMSN=20250428T213159 2025-04-28T21:32:07.844Z,1745875927.844 [DataOverHttps](INFO): Sending 540 bytes from file Logs/20250428T211217/Express0013.lzma 2025-04-28T21:32:07.848Z,1745875927.848 [DataOverHttps](INFO): Received command: sched "set sci2_noyo_optim.EnableRecording 0 bool;run" crt0 2 2 2025-04-28T21:32:07.880Z,1745875927.880 [CommandExec](IMPORTANT): got command schedule "set sci2_noyo_optim.EnableRecording 0 bool;run" crt0 2 2.000000 2025-04-28T21:32:07.880Z,1745875927.880 [CommandExec](IMPORTANT): Scheduling command #2 of 2 with id=crt0 2025-04-28T21:32:07.881Z,1745875927.881 [CommandExec](IMPORTANT): Scheduled #6 (#2 of 2 with id='crt0'): "set sci2_noyo_optim.EnableRecording 0 bool;run", AFTER MISSION 2025-04-28T21:32:07.881Z,1745875927.881 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:32:09.120Z,1745875929.120 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0013.lzma.bak 2025-04-28T21:32:09.120Z,1745875929.120 [DataOverHttps](INFO): SBD MOMSN=24740968 2025-04-28T21:32:10.644Z,1745875930.644 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2025-04-28T21:32:10.727Z,1745875930.727 [NAL9602](ERROR): received: +CSQ:0 OK054, 2, 0, 0, 0 OK 2025-04-28T21:32:24.830Z,1745875944.830 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0018.lzma 2025-04-28T21:32:25.833Z,1745875945.833 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0018.lzma.bak 2025-04-28T21:32:25.833Z,1745875945.833 [DataOverHttps](INFO): SBD MOMSN=24740993 2025-04-28T21:32:41.870Z,1745875961.870 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0021.lzma 2025-04-28T21:32:42.873Z,1745875962.873 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0021.lzma.bak 2025-04-28T21:32:42.873Z,1745875962.873 [DataOverHttps](INFO): SBD MOMSN=24740995 2025-04-28T21:32:54.270Z,1745875974.270 [PowerOnly](INFO): Powering down loadControl 2025-04-28T21:32:59.774Z,1745875979.774 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20250428T211217/Express0016.lzma 2025-04-28T21:33:00.777Z,1745875980.777 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0016.lzma.bak 2025-04-28T21:33:00.777Z,1745875980.777 [DataOverHttps](IMPORTANT): SBD MOMSN=24740998, MTMSN=20250428T213259 2025-04-28T21:33:08.283Z,1745875988.283 [DataOverHttps](INFO): Received command: sched 20250428T2150 "set sci2_noyo_optim.enablerecording 1 bool;" 2025-04-28T21:33:08.310Z,1745875988.310 [CommandExec](IMPORTANT): got command schedule 20250428T215000 "set sci2_noyo_optim.enablerecording 1 bool;" 2025-04-28T21:33:08.311Z,1745875988.311 [CommandExec](IMPORTANT): Scheduled #7: "set sci2_noyo_optim.enablerecording 1 bool;", AT TIME: 2025-04-28T21:50:00Z 2025-04-28T21:33:08.311Z,1745875988.311 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:33:16.847Z,1745875996.847 [DataOverHttps](INFO): Sending 373 bytes from file Logs/20250428T211217/Express0019.lzma 2025-04-28T21:33:17.849Z,1745875997.849 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0019.lzma.bak 2025-04-28T21:33:17.849Z,1745875997.849 [DataOverHttps](IMPORTANT): SBD MOMSN=24741002, MTMSN=20250428T213317 2025-04-28T21:33:25.339Z,1745876005.339 [DataOverHttps](INFO): Received command: schedule clear 2025-04-28T21:33:25.401Z,1745876005.401 [CommandExec](IMPORTANT): got command schedule clear 2025-04-28T21:33:25.401Z,1745876005.401 [CommandExec](IMPORTANT): Cleared 3 scheduled commands. 2025-04-28T21:33:33.814Z,1745876013.814 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0024.lzma 2025-04-28T21:33:34.816Z,1745876014.816 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0024.lzma.bak 2025-04-28T21:33:34.817Z,1745876014.817 [DataOverHttps](INFO): SBD MOMSN=24741016 2025-04-28T21:33:53.554Z,1745876033.554 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0027.lzma 2025-04-28T21:33:54.582Z,1745876034.582 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0027.lzma.bak 2025-04-28T21:33:54.582Z,1745876034.582 [DataOverHttps](IMPORTANT): SBD MOMSN=24741019, MTMSN=20250428T213353 2025-04-28T21:34:02.103Z,1745876042.103 [DataOverHttps](INFO): Received command: sched "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.Lat2 36.797 degree" crw6 1 2 2025-04-28T21:34:02.135Z,1745876042.135 [CommandExec](IMPORTANT): got command schedule "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.Lat2 36.797 degree" crw6 1 2.000000 2025-04-28T21:34:02.135Z,1745876042.135 [CommandExec](IMPORTANT): Scheduling command #1 of 2 with id=crw6 2025-04-28T21:34:02.136Z,1745876042.136 [CommandExec](IMPORTANT): Scheduled #8 (#1 of 2 with id='crw6'): "load Science/sci2_noyo_optim.tl;set sci2_noyo_optim.MissionTimeout 45 min;set sci2_noyo_optim.Depth1 20 m;set sci2_noyo_optim.Lat1 36.79562 degree;set sci2_noyo_optim.Lon1 -121.8624 degree;set sci2_noyo_optim.Lat2 36.797 degree", AFTER MISSION 2025-04-28T21:34:02.137Z,1745876042.137 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:34:03.292Z,1745876043.292 [DataOverHttps](IMPORTANT): SBD MTMSN=20250428T213402 2025-04-28T21:34:10.711Z,1745876050.711 [DataOverHttps](INFO): Sending 286 bytes from file Logs/20250428T211217/Express0022.lzma 2025-04-28T21:34:10.714Z,1745876050.714 [DataOverHttps](INFO): Received command: sched "set sci2_noyo_optim.Lon2 -121.847 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s;set sci2_noyo_optim.EnableRecording 0 bool;run" crw6 2 2 2025-04-28T21:34:10.817Z,1745876050.817 [CommandExec](IMPORTANT): got command schedule "set sci2_noyo_optim.Lon2 -121.847 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s;set sci2_noyo_optim.EnableRecording 0 bool;run" crw6 2 2.000000 2025-04-28T21:34:10.817Z,1745876050.817 [CommandExec](IMPORTANT): Scheduling command #2 of 2 with id=crw6 2025-04-28T21:34:10.818Z,1745876050.818 [CommandExec](IMPORTANT): Scheduled #9 (#2 of 2 with id='crw6'): "set sci2_noyo_optim.Lon2 -121.847 degree;set sci2_noyo_optim.SlowSpeed 0.75 m/s;set sci2_noyo_optim.EnableRecording 0 bool;run", AFTER MISSION 2025-04-28T21:34:10.819Z,1745876050.819 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:34:12.717Z,1745876052.717 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0022.lzma.bak 2025-04-28T21:34:12.717Z,1745876052.717 [DataOverHttps](IMPORTANT): SBD MOMSN=24741023, MTMSN=20250428T213411 2025-04-28T21:34:20.407Z,1745876060.407 [DataOverHttps](INFO): Received command: sched 20250428T2150 "set sci2_noyo_optim.enablerecording 1 bool;" 2025-04-28T21:34:20.502Z,1745876060.502 [CommandExec](IMPORTANT): got command schedule 20250428T215000 "set sci2_noyo_optim.enablerecording 1 bool;" 2025-04-28T21:34:20.503Z,1745876060.503 [CommandExec](IMPORTANT): Scheduled #10: "set sci2_noyo_optim.enablerecording 1 bool;", AT TIME: 2025-04-28T21:50:00Z 2025-04-28T21:34:20.503Z,1745876060.503 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:34:28.870Z,1745876068.870 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0030.lzma 2025-04-28T21:34:29.873Z,1745876069.873 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0030.lzma.bak 2025-04-28T21:34:29.873Z,1745876069.873 [DataOverHttps](INFO): SBD MOMSN=24741032 2025-04-28T21:34:46.790Z,1745876086.790 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0033.lzma 2025-04-28T21:34:47.793Z,1745876087.793 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0033.lzma.bak 2025-04-28T21:34:47.793Z,1745876087.793 [DataOverHttps](INFO): SBD MOMSN=24741034 2025-04-28T21:35:03.926Z,1745876103.926 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0036.lzma 2025-04-28T21:35:04.929Z,1745876104.929 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0036.lzma.bak 2025-04-28T21:35:04.929Z,1745876104.929 [DataOverHttps](INFO): SBD MOMSN=24741036 2025-04-28T21:35:13.424Z,1745876113.424 [DataOverHttps](IMPORTANT): SBD MTMSN=20250428T213512 2025-04-28T21:35:21.847Z,1745876121.847 [DataOverHttps](INFO): Sending 265 bytes from file Logs/20250428T211217/Express0025.lzma 2025-04-28T21:35:21.850Z,1745876121.850 [DataOverHttps](INFO): Received command: sched 20250428T2215 "set sci2_noyo_optim.enablerecording 0 bool;" 2025-04-28T21:35:21.879Z,1745876121.879 [CommandExec](IMPORTANT): got command schedule 20250428T221500 "set sci2_noyo_optim.enablerecording 0 bool;" 2025-04-28T21:35:21.879Z,1745876121.879 [CommandExec](IMPORTANT): Scheduled #11: "set sci2_noyo_optim.enablerecording 0 bool;", AT TIME: 2025-04-28T22:15:00Z 2025-04-28T21:35:21.880Z,1745876121.880 [CommandExec](FAULT): Scheduling was paused by an error at 2025-04-28T21:24:25Z 2025-04-28T21:35:23.105Z,1745876123.105 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Express0025.lzma.bak 2025-04-28T21:35:23.105Z,1745876123.105 [DataOverHttps](INFO): SBD MOMSN=24741039 2025-04-28T21:35:38.806Z,1745876138.806 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20250428T211217/Courier0039.lzma 2025-04-28T21:35:39.809Z,1745876139.809 [DataOverHttps](INFO): Moved sent file to Logs/20250428T211217/Courier0039.lzma.bak 2025-04-28T21:35:39.809Z,1745876139.809 [DataOverHttps](IMPORTANT): SBD MOMSN=24741047, MTMSN=20250428T213539