2018-09-19T21:01:49.272Z,1537390909.272 [Supervisor](DEBUG): Initializing supervisor.
2018-09-19T21:01:49.275Z,1537390909.275 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0
2018-09-19T21:01:49.275Z,1537390909.275 [SyncHandler](INFO): Protected caller Thread ID is 2477
2018-09-19T21:01:49.276Z,1537390909.276 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread.
2018-09-19T21:01:49.277Z,1537390909.277 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0
2018-09-19T21:01:49.277Z,1537390909.277 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2478
2018-09-19T21:01:49.280Z,1537390909.280 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread.
2018-09-19T21:01:49.294Z,1537390909.294 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread.
2018-09-19T21:01:49.295Z,1537390909.295 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0
2018-09-19T21:01:49.295Z,1537390909.295 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2479
2018-09-19T21:01:49.296Z,1537390909.296 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread.
2018-09-19T21:01:49.297Z,1537390909.297 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0
2018-09-19T21:01:49.298Z,1537390909.298 [logger ThreadHandler](INFO): Protected caller Thread ID is 2480
2018-09-19T21:01:49.300Z,1537390909.300 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread.
2018-09-19T21:01:49.301Z,1537390909.301 [Supervisor](INFO): Looking for Config files in directory: Config/
2018-09-19T21:01:49.303Z,1537390909.303 [Supervisor](INFO): Opening Config file at: Config/Control.cfg
2018-09-19T21:01:49.709Z,1537390909.709 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control
2018-09-19T21:01:49.709Z,1537390909.709 [Supervisor](INFO): Opening Config file at: Config/logger.cfg
2018-09-19T21:01:49.916Z,1537390909.916 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger
2018-09-19T21:01:49.917Z,1537390909.917 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg
2018-09-19T21:01:50.222Z,1537390910.222 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo
2018-09-19T21:01:50.222Z,1537390910.222 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg
2018-09-19T21:01:50.365Z,1537390910.365 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation
2018-09-19T21:01:50.365Z,1537390910.365 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg
2018-09-19T21:01:50.464Z,1537390910.464 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample
2018-09-19T21:01:50.465Z,1537390910.465 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg
2018-09-19T21:01:50.943Z,1537390910.943 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator
2018-09-19T21:01:50.944Z,1537390910.944 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg
2018-09-19T21:01:51.396Z,1537390911.396 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor
2018-09-19T21:01:51.397Z,1537390911.397 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg
2018-09-19T21:01:51.885Z,1537390911.885 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle
2018-09-19T21:01:51.886Z,1537390911.886 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg
2018-09-19T21:01:51.992Z,1537390911.992 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite
2018-09-19T21:01:51.993Z,1537390911.993 [Supervisor](INFO): Opening Config file at: Config/secure.cfg
2018-09-19T21:01:52.092Z,1537390912.092 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure
2018-09-19T21:01:52.092Z,1537390912.092 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg
2018-09-19T21:01:52.303Z,1537390912.303 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation
2018-09-19T21:01:52.303Z,1537390912.303 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg
2018-09-19T21:01:52.509Z,1537390912.509 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT
2018-09-19T21:01:52.510Z,1537390912.510 [Supervisor](INFO): Opening Config file at: Config/Science.cfg
2018-09-19T21:01:52.865Z,1537390912.865 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science
2018-09-19T21:01:52.865Z,1537390912.865 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg
2018-09-19T21:01:53.010Z,1537390913.010 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation
2018-09-19T21:01:53.011Z,1537390913.011 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg
2018-09-19T21:01:53.342Z,1537390913.342 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/
2018-09-19T21:01:53.343Z,1537390913.343 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg
2018-09-19T21:01:53.450Z,1537390913.450 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg
2018-09-19T21:01:53.571Z,1537390913.571 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg
2018-09-19T21:01:53.667Z,1537390913.667 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg
2018-09-19T21:01:53.754Z,1537390913.754 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg
2018-09-19T21:01:53.915Z,1537390913.915 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg
2018-09-19T21:01:54.096Z,1537390914.096 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg
2018-09-19T21:01:54.173Z,1537390914.173 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg
2018-09-19T21:01:54.405Z,1537390914.405 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery
2018-09-19T21:01:54.406Z,1537390914.406 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg
2018-09-19T21:01:54.491Z,1537390914.491 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg
2018-09-19T21:01:54.583Z,1537390914.583 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg
2018-09-19T21:01:54.686Z,1537390914.686 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg
2018-09-19T21:01:54.818Z,1537390914.818 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/
2018-09-19T21:01:54.818Z,1537390914.818 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg
2018-09-19T21:01:54.835Z,1537390914.835 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so
2018-09-19T21:01:55.114Z,1537390915.114 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands)
2018-09-19T21:01:55.114Z,1537390915.114 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so
2018-09-19T21:01:55.171Z,1537390915.171 [DepthRateCalculator] Loaded
2018-09-19T21:01:55.171Z,1537390915.171 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread.
2018-09-19T21:01:55.177Z,1537390915.177 [PitchRateCalculator] Loaded
2018-09-19T21:01:55.177Z,1537390915.177 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread.
2018-09-19T21:01:55.194Z,1537390915.194 [SpeedCalculator] Loaded
2018-09-19T21:01:55.194Z,1537390915.194 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread.
2018-09-19T21:01:55.215Z,1537390915.215 [TempGradientCalculator] Loaded
2018-09-19T21:01:55.215Z,1537390915.215 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread.
2018-09-19T21:01:55.231Z,1537390915.231 [VerticalTemperatureHomogeneityIndexCalculator] Loaded
2018-09-19T21:01:55.231Z,1537390915.231 [ComponentRegistry](DEBUG): SyncComponent "VerticalTemperatureHomogeneityIndexCalculator" handled in the control thread.
2018-09-19T21:01:55.237Z,1537390915.237 [YawRateCalculator] Loaded
2018-09-19T21:01:55.237Z,1537390915.237 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread.
2018-09-19T21:01:55.277Z,1537390915.277 [ElevatorOffsetCalculator] Loaded
2018-09-19T21:01:55.277Z,1537390915.277 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread.
2018-09-19T21:01:55.278Z,1537390915.278 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components)
2018-09-19T21:01:55.278Z,1537390915.278 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so
2018-09-19T21:01:55.381Z,1537390915.381 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components)
2018-09-19T21:01:55.381Z,1537390915.381 [Module Loader](DEBUG): Loading Module at Modules/Servo.so
2018-09-19T21:01:55.514Z,1537390915.514 [BuoyancyServo] Loaded
2018-09-19T21:01:55.514Z,1537390915.514 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread.
2018-09-19T21:01:55.515Z,1537390915.515 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers)
2018-09-19T21:01:55.516Z,1537390915.516 [Module Loader](DEBUG): Loading Module at Modules/Sample.so
2018-09-19T21:01:55.539Z,1537390915.539 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components)
2018-09-19T21:01:55.539Z,1537390915.539 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so
2018-09-19T21:01:55.665Z,1537390915.665 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator)
2018-09-19T21:01:55.666Z,1537390915.666 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so
2018-09-19T21:01:56.033Z,1537390916.033 [DataOverHttps] Loaded
2018-09-19T21:01:56.034Z,1537390916.034 [ComponentRegistry](DEBUG): SyncComponent "DataOverHttps" handled in the control thread.
2018-09-19T21:01:56.048Z,1537390916.048 [Depth_Keller] Loaded
2018-09-19T21:01:56.048Z,1537390916.048 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread.
2018-09-19T21:01:56.053Z,1537390916.053 [DropWeight] Loaded
2018-09-19T21:01:56.053Z,1537390916.053 [ComponentRegistry](DEBUG): SyncComponent "DropWeight" handled in the control thread.
2018-09-19T21:01:56.151Z,1537390916.151 [NAL9602] Loaded
2018-09-19T21:01:56.151Z,1537390916.151 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread.
2018-09-19T21:01:56.168Z,1537390916.168 [Onboard] Loaded
2018-09-19T21:01:56.168Z,1537390916.168 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread.
2018-09-19T21:01:56.178Z,1537390916.178 [Radio_Surface] Loaded
2018-09-19T21:01:56.178Z,1537390916.178 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread.
2018-09-19T21:01:56.179Z,1537390916.179 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 4088F4E0
2018-09-19T21:01:56.180Z,1537390916.180 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2562
2018-09-19T21:01:56.227Z,1537390916.227 [PNI_TCM] Loaded
2018-09-19T21:01:56.228Z,1537390916.228 [ComponentRegistry](DEBUG): SyncComponent "PNI_TCM" handled in the control thread.
2018-09-19T21:01:56.251Z,1537390916.251 [BPC1](INFO): BPC1A: got serial number for stick 1: 0138
2018-09-19T21:01:56.252Z,1537390916.252 [BPC1](INFO): BPC1A: got serial number for stick 2: 0125
2018-09-19T21:01:56.253Z,1537390916.253 [BPC1](INFO): BPC1A: got serial number for stick 3: 00EF
2018-09-19T21:01:56.254Z,1537390916.254 [BPC1](INFO): BPC1A: got serial number for stick 4: 0158
2018-09-19T21:01:56.255Z,1537390916.255 [BPC1](INFO): BPC1A: got serial number for stick 5: 0088
2018-09-19T21:01:56.255Z,1537390916.255 [BPC1](INFO): BPC1A: got serial number for stick 6: 00A3
2018-09-19T21:01:56.256Z,1537390916.256 [BPC1](INFO): BPC1A: got serial number for stick 7: 012D
2018-09-19T21:01:56.257Z,1537390916.257 [BPC1](INFO): BPC1A: got serial number for stick 8: 00E7
2018-09-19T21:01:56.258Z,1537390916.258 [BPC1](INFO): BPC1A: got serial number for stick 9: 0100
2018-09-19T21:01:56.259Z,1537390916.259 [BPC1](INFO): BPC1A: got serial number for stick 10: 00B9
2018-09-19T21:01:56.259Z,1537390916.259 [BPC1](INFO): BPC1A: got serial number for stick 11: 008C
2018-09-19T21:01:56.260Z,1537390916.260 [BPC1](INFO): BPC1A: got serial number for stick 12: 0117
2018-09-19T21:01:56.261Z,1537390916.261 [BPC1](INFO): BPC1A: got serial number for stick 13: 00E4
2018-09-19T21:01:56.261Z,1537390916.261 [BPC1](INFO): BPC1A: got serial number for stick 14: 011D
2018-09-19T21:01:56.262Z,1537390916.262 [BPC1](INFO): BPC1A: got serial number for stick 15: 014E
2018-09-19T21:01:56.263Z,1537390916.263 [BPC1](INFO): BPC1A: got serial number for stick 16: 00EC
2018-09-19T21:01:56.264Z,1537390916.264 [BPC1](INFO): BPC1A: got serial number for stick 17: 008A
2018-09-19T21:01:56.264Z,1537390916.264 [BPC1](INFO): BPC1A: got serial number for stick 18: 0140
2018-09-19T21:01:56.265Z,1537390916.265 [BPC1](INFO): BPC1A: got serial number for stick 19: 00E5
2018-09-19T21:01:56.266Z,1537390916.266 [BPC1](INFO): BPC1A: got serial number for stick 20: 00E0
2018-09-19T21:01:56.267Z,1537390916.267 [BPC1](INFO): BPC1A: got serial number for stick 21: 00CD
2018-09-19T21:01:56.267Z,1537390916.267 [BPC1](INFO): BPC1A: got serial number for stick 22: 009F
2018-09-19T21:01:56.268Z,1537390916.268 [BPC1](INFO): BPC1A: got serial number for stick 23: 009C
2018-09-19T21:01:56.269Z,1537390916.269 [BPC1](INFO): BPC1A: got serial number for stick 24: 00A6
2018-09-19T21:01:56.270Z,1537390916.270 [BPC1](INFO): BPC1A: got serial number for stick 25: 00E8
2018-09-19T21:01:56.270Z,1537390916.270 [BPC1](INFO): BPC1A: got serial number for stick 26: 00D1
2018-09-19T21:01:56.271Z,1537390916.271 [BPC1](INFO): BPC1A: got serial number for stick 27: 00F3
2018-09-19T21:01:56.272Z,1537390916.272 [BPC1](INFO): BPC1A: got serial number for stick 28: 0092
2018-09-19T21:01:56.272Z,1537390916.272 [BPC1](INFO): BPC1A: got serial number for stick 29: 00AD
2018-09-19T21:01:56.273Z,1537390916.273 [BPC1](INFO): BPC1A: got serial number for stick 30: 00E9
2018-09-19T21:01:56.274Z,1537390916.274 [BPC1](INFO): BPC1A: got serial number for stick 31: 0126
2018-09-19T21:01:56.275Z,1537390916.275 [BPC1](INFO): BPC1B: got serial number for stick 32: 0157
2018-09-19T21:01:56.276Z,1537390916.276 [BPC1](INFO): BPC1B: got serial number for stick 33: 00F1
2018-09-19T21:01:56.277Z,1537390916.277 [BPC1](INFO): BPC1B: got serial number for stick 34: 00BF
2018-09-19T21:01:56.278Z,1537390916.278 [BPC1](INFO): BPC1B: got serial number for stick 35: 0089
2018-09-19T21:01:56.278Z,1537390916.278 [BPC1](INFO): BPC1B: got serial number for stick 36: 00C2
2018-09-19T21:01:56.279Z,1537390916.279 [BPC1](INFO): BPC1B: got serial number for stick 37: 00CA
2018-09-19T21:01:56.280Z,1537390916.280 [BPC1](INFO): BPC1B: got serial number for stick 38: 011A
2018-09-19T21:01:56.281Z,1537390916.281 [BPC1](INFO): BPC1B: got serial number for stick 39: 00FD
2018-09-19T21:01:56.281Z,1537390916.281 [BPC1](INFO): BPC1B: got serial number for stick 40: 0095
2018-09-19T21:01:56.282Z,1537390916.282 [BPC1](INFO): BPC1B: got serial number for stick 41: 00BE
2018-09-19T21:01:56.283Z,1537390916.283 [BPC1](INFO): BPC1B: got serial number for stick 42: 0086
2018-09-19T21:01:56.284Z,1537390916.284 [BPC1](INFO): BPC1B: got serial number for stick 43: 00AE
2018-09-19T21:01:56.284Z,1537390916.284 [BPC1](INFO): BPC1B: got serial number for stick 44: 00CB
2018-09-19T21:01:56.285Z,1537390916.285 [BPC1](INFO): BPC1B: got serial number for stick 45: 00F7
2018-09-19T21:01:56.286Z,1537390916.286 [BPC1](INFO): BPC1B: got serial number for stick 46: 00A1
2018-09-19T21:01:56.287Z,1537390916.287 [BPC1](INFO): BPC1B: got serial number for stick 47: 00F0
2018-09-19T21:01:56.287Z,1537390916.287 [BPC1](INFO): BPC1B: got serial number for stick 48: 00C9
2018-09-19T21:01:56.288Z,1537390916.288 [BPC1](INFO): BPC1B: got serial number for stick 49: 0103
2018-09-19T21:01:56.289Z,1537390916.289 [BPC1](INFO): BPC1B: got serial number for stick 50: 0152
2018-09-19T21:01:56.290Z,1537390916.290 [BPC1](INFO): BPC1B: got serial number for stick 51: 014A
2018-09-19T21:01:56.290Z,1537390916.290 [BPC1](INFO): BPC1B: got serial number for stick 52: 0114
2018-09-19T21:01:56.291Z,1537390916.291 [BPC1](INFO): BPC1B: got serial number for stick 53: 015E
2018-09-19T21:01:56.292Z,1537390916.292 [BPC1](INFO): BPC1B: got serial number for stick 54: 008E
2018-09-19T21:01:56.293Z,1537390916.293 [BPC1](INFO): BPC1B: got serial number for stick 55: 00AC
2018-09-19T21:01:56.293Z,1537390916.293 [BPC1](INFO): BPC1B: got serial number for stick 56: 0091
2018-09-19T21:01:56.294Z,1537390916.294 [BPC1](INFO): BPC1B: got serial number for stick 57: 0153
2018-09-19T21:01:56.295Z,1537390916.295 [BPC1](INFO): BPC1B: got serial number for stick 58: 00AF
2018-09-19T21:01:56.295Z,1537390916.295 [BPC1](INFO): BPC1B: got serial number for stick 59: 0151
2018-09-19T21:01:56.296Z,1537390916.296 [BPC1](INFO): BPC1B: got serial number for stick 60: 00DC
2018-09-19T21:01:56.297Z,1537390916.297 [BPC1](INFO): BPC1B: got serial number for stick 61: 00BA
2018-09-19T21:01:56.298Z,1537390916.298 [BPC1](INFO): BPC1B: got serial number for stick 62: 00DA
2018-09-19T21:01:58.022Z,1537390918.022 [BPC1] Loaded
2018-09-19T21:01:58.023Z,1537390918.023 [ComponentRegistry](DEBUG): SyncComponent "BPC1" handled in the control thread.
2018-09-19T21:01:58.023Z,1537390918.023 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components)
2018-09-19T21:01:58.024Z,1537390918.024 [Module Loader](DEBUG): Loading Module at Modules/BIT.so
2018-09-19T21:01:58.177Z,1537390918.177 [SBIT](DEBUG): Construct Startup Built In Test.
2018-09-19T21:01:58.200Z,1537390918.200 [SBIT] Loaded
2018-09-19T21:01:58.200Z,1537390918.200 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread.
2018-09-19T21:01:58.201Z,1537390918.201 [IBIT](DEBUG): Construct Initiated Built In Test.
2018-09-19T21:01:58.213Z,1537390918.213 [IBIT] Loaded
2018-09-19T21:01:58.213Z,1537390918.213 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread.
2018-09-19T21:01:58.216Z,1537390918.216 [CBIT](DEBUG): Construct Continuous Built In Test.
2018-09-19T21:01:58.365Z,1537390918.365 [CBIT] Loaded
2018-09-19T21:01:58.366Z,1537390918.366 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread.
2018-09-19T21:01:58.366Z,1537390918.366 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test)
2018-09-19T21:01:58.367Z,1537390918.367 [Module Loader](DEBUG): Loading Module at Modules/Science.so
2018-09-19T21:01:58.845Z,1537390918.845 [Aanderaa_O2] Loaded
2018-09-19T21:01:58.845Z,1537390918.845 [ComponentRegistry](DEBUG): SyncComponent "Aanderaa_O2" handled in the control thread.
2018-09-19T21:01:58.923Z,1537390918.923 [CTD_NeilBrown] Loaded
2018-09-19T21:01:58.923Z,1537390918.923 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread.
2018-09-19T21:01:58.924Z,1537390918.924 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409534E0
2018-09-19T21:01:58.925Z,1537390918.925 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2563
2018-09-19T21:01:58.976Z,1537390918.976 [CTD_Seabird] Loaded
2018-09-19T21:01:58.976Z,1537390918.976 [ComponentRegistry](DEBUG): Component "CTD_Seabird" handled in its own thread.
2018-09-19T21:01:58.977Z,1537390918.977 [CTD_Seabird ThreadHandler](DEBUG): Created PCaller Thread at 409834E0
2018-09-19T21:01:58.977Z,1537390918.977 [CTD_Seabird ThreadHandler](INFO): Protected caller Thread ID is 2564
2018-09-19T21:01:58.995Z,1537390918.995 [ESPComponent] Loaded
2018-09-19T21:01:58.995Z,1537390918.995 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread.
2018-09-19T21:01:59.009Z,1537390919.009 [PAR_Licor] Loaded
2018-09-19T21:01:59.009Z,1537390919.009 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread.
2018-09-19T21:01:59.059Z,1537390919.059 [WetLabsBB2FL] Loaded
2018-09-19T21:01:59.059Z,1537390919.059 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread.
2018-09-19T21:01:59.060Z,1537390919.060 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409B34E0
2018-09-19T21:01:59.061Z,1537390919.061 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2565
2018-09-19T21:01:59.061Z,1537390919.061 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components)
2018-09-19T21:01:59.062Z,1537390919.062 [Module Loader](DEBUG): Loading Module at Modules/Control.so
2018-09-19T21:01:59.149Z,1537390919.149 [VerticalControl](DEBUG): Construct VerticalControl.
2018-09-19T21:01:59.241Z,1537390919.241 [VerticalControl] Loaded
2018-09-19T21:01:59.241Z,1537390919.241 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread.
2018-09-19T21:01:59.242Z,1537390919.242 [HorizontalControl](DEBUG): Construct HorizontalControl.
2018-09-19T21:01:59.303Z,1537390919.303 [HorizontalControl] Loaded
2018-09-19T21:01:59.303Z,1537390919.303 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread.
2018-09-19T21:01:59.304Z,1537390919.304 [SpeedControl](DEBUG): Construct SpeedControl.
2018-09-19T21:01:59.309Z,1537390919.309 [SpeedControl] Loaded
2018-09-19T21:01:59.309Z,1537390919.309 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread.
2018-09-19T21:01:59.310Z,1537390919.310 [LoopControl](DEBUG): Construct LoopControl.
2018-09-19T21:01:59.310Z,1537390919.310 [LoopControl] Loaded
2018-09-19T21:01:59.311Z,1537390919.311 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread.
2018-09-19T21:01:59.311Z,1537390919.311 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control)
2018-09-19T21:01:59.312Z,1537390919.312 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so
2018-09-19T21:01:59.348Z,1537390919.348 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions)
2018-09-19T21:01:59.348Z,1537390919.348 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so
2018-09-19T21:01:59.455Z,1537390919.455 [DeadReckonUsingSpeedCalculator] Loaded
2018-09-19T21:01:59.455Z,1537390919.455 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingSpeedCalculator" handled in the control thread.
2018-09-19T21:01:59.472Z,1537390919.472 [NavChart] Loaded
2018-09-19T21:01:59.472Z,1537390919.472 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread.
2018-09-19T21:01:59.476Z,1537390919.476 [UniversalFixResidualReporter] Loaded
2018-09-19T21:01:59.476Z,1537390919.476 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread.
2018-09-19T21:01:59.477Z,1537390919.477 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components)
2018-09-19T21:01:59.480Z,1537390919.480 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread.
2018-09-19T21:01:59.481Z,1537390919.481 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread.
2018-09-19T21:01:59.488Z,1537390919.488 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread.
2018-09-19T21:01:59.489Z,1537390919.489 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40A3F4E0
2018-09-19T21:01:59.490Z,1537390919.490 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2566
2018-09-19T21:01:59.494Z,1537390919.494 [Supervisor](INFO): Main Thread ID is 9268
2018-09-19T21:01:59.494Z,1537390919.494 [Supervisor](DEBUG): Running supervisor.
2018-09-19T21:01:59.495Z,1537390919.495 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2567
2018-09-19T21:01:59.498Z,1537390919.498 [controlThread ThreadHandler](INFO): Handler Thread ID is 2568
2018-09-19T21:01:59.498Z,1537390919.498 [controlThread](DEBUG): Initializing ControlThread
2018-09-19T21:01:59.499Z,1537390919.499 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-09-19T21:01:59.499Z,1537390919.499 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator.
2018-09-19T21:01:59.500Z,1537390919.500 [SpeedCalculator](DEBUG): Initializing SpeedCalculator.
2018-09-19T21:01:59.500Z,1537390919.500 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator.
2018-09-19T21:01:59.501Z,1537390919.501 [VerticalTemperatureHomogeneityIndexCalculator](DEBUG): (re)initializing
2018-09-19T21:01:59.501Z,1537390919.501 [YawRateCalculator](DEBUG): Initializing YawRateCalculator.
2018-09-19T21:01:59.502Z,1537390919.502 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator.
2018-09-19T21:01:59.507Z,1537390919.507 [SBIT](INFO): Initialize SBIT Component.
2018-09-19T21:01:59.507Z,1537390919.507 [SBIT](IMPORTANT): git: 2018-09-04-21-gd54d9fc
2018-09-19T21:01:59.508Z,1537390919.508 [SBIT](INFO): git hash: d54d9fc12f891c3a6b7eed365ed7708e78930892
2018-09-19T21:01:59.508Z,1537390919.508 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8
2018-09-19T21:01:59.509Z,1537390919.509 [SBIT](INFO): Kernel Reporting Different Version From Configuration.
Kernel Expected: #639 PREEMPT Wed Mar 12 12:53:33 PDT 2014
Kernel Reported: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018
2018-09-19T21:01:59.510Z,1537390919.510 [SBIT](INFO): Beginning SBIT in 160.000000 seconds.
2018-09-19T21:01:59.511Z,1537390919.511 [IBIT](INFO): Initialize IBIT Component.
2018-09-19T21:01:59.512Z,1537390919.512 [CBIT](DEBUG): Initialize CBIT Component.
2018-09-19T21:01:59.512Z,1537390919.512 [CBIT](CRITICAL): LAST REBOOT DUE TO WATCHDOG TIMER RESET.
2018-09-19T21:01:59.513Z,1537390919.513 [logger ThreadHandler](INFO): Handler Thread ID is 2569
2018-09-19T21:01:59.533Z,1537390919.533 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2570
2018-09-19T21:01:59.539Z,1537390919.539 [Radio_Surface](INFO): Powering up
2018-09-19T21:01:59.545Z,1537390919.545 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2571
2018-09-19T21:01:59.546Z,1537390919.546 [CTD_NeilBrown](INFO): Powering down
2018-09-19T21:01:59.577Z,1537390919.577 [CTD_Seabird ThreadHandler](INFO): Handler Thread ID is 2572
2018-09-19T21:01:59.577Z,1537390919.577 [CTD_Seabird](INFO): Initializing
2018-09-19T21:01:59.578Z,1537390919.578 [CTD_Seabird](INFO): Checking LCM
2018-09-19T21:01:59.587Z,1537390919.587 [CTD_Seabird](INFO): LCM OK
2018-09-19T21:01:59.587Z,1537390919.587 [CTD_Seabird](INFO): Powering up
2018-09-19T21:01:59.597Z,1537390919.597 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2573
2018-09-19T21:01:59.598Z,1537390919.598 [WetLabsBB2FL](INFO): Powering down
2018-09-19T21:01:59.629Z,1537390919.629 [VerticalControl](DEBUG): Initialize VerticalControlComponent.
2018-09-19T21:01:59.631Z,1537390919.631 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent.
2018-09-19T21:01:59.631Z,1537390919.631 [SpeedControl](DEBUG): Initialize SpeedControlComponent.
2018-09-19T21:01:59.632Z,1537390919.632 [LoopControl](DEBUG): Initialize LoopControlComponent.
2018-09-19T21:01:59.632Z,1537390919.632 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:01:59.633Z,1537390919.633 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:01:59.633Z,1537390919.633 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:01:59.634Z,1537390919.634 [NavChart](DEBUG): Initialize NavChart Navigation.
2018-09-19T21:01:59.634Z,1537390919.634 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component.
2018-09-19T21:01:59.635Z,1537390919.635 [MissionManager](INFO): Loading Mission: Missions/Startup.xml
2018-09-19T21:01:59.641Z,1537390919.641 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2574
2018-09-19T21:01:59.651Z,1537390919.651 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000
2018-09-19T21:01:59.651Z,1537390919.651 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000
2018-09-19T21:01:59.651Z,1537390919.651 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000
2018-09-19T21:01:59.651Z,1537390919.651 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000
2018-09-19T21:01:59.652Z,1537390919.652 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000
2018-09-19T21:01:59.652Z,1537390919.652 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000
2018-09-19T21:01:59.652Z,1537390919.652 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000
2018-09-19T21:01:59.652Z,1537390919.652 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000
2018-09-19T21:01:59.653Z,1537390919.653 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000
2018-09-19T21:01:59.653Z,1537390919.653 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000
2018-09-19T21:01:59.653Z,1537390919.653 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000
2018-09-19T21:01:59.653Z,1537390919.653 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000
2018-09-19T21:01:59.653Z,1537390919.653 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000
2018-09-19T21:01:59.654Z,1537390919.654 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000
2018-09-19T21:01:59.654Z,1537390919.654 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000
2018-09-19T21:01:59.654Z,1537390919.654 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000
2018-09-19T21:01:59.690Z,1537390919.690 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface.
2018-09-19T21:01:59.710Z,1537390919.710 [MissionManager](DEBUG):
2018-09-19T21:01:59.710Z,1537390919.710 [MissionManager](INFO): Loading Mission: Missions/Default.xml
2018-09-19T21:01:59.808Z,1537390919.808 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min
2018-09-19T21:01:59.809Z,1537390919.809 [Default:A.Wait](DEBUG): Construct Wait.
2018-09-19T21:01:59.811Z,1537390919.811 [Default:B.GoToSurface](DEBUG): Construct GoToSurface.
2018-09-19T21:01:59.858Z,1537390919.858 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute.
2018-09-19T21:01:59.861Z,1537390919.861 [Default:CheckIn:C.Wait](DEBUG): Construct Wait.
2018-09-19T21:01:59.881Z,1537390919.881 [Default:E.Execute](DEBUG): Construct Execute.
2018-09-19T21:01:59.905Z,1537390919.905 [MissionManager](DEBUG):
0
Wait a moment to see if the scheduler starts a new mission before
starting to actually run Default.
13
Burn on
Dropped weight due to communications timeout.
5
Default mission has been running for
Restarting logs and Default mission.
restart logs
2018-09-19T21:01:59.910Z,1537390919.910 [controlThread](DEBUG): Component order: CycleStarter,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2018-09-19T21:01:59.938Z,1537390919.938 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP
2018-09-19T21:01:59.972Z,1537390919.972 [Depth_Keller](ERROR): Pressure reading out of range: 1831.023193 decibar
2018-09-19T21:02:00.306Z,1537390920.306 [DepthRateCalculator](ERROR): Depth measurement is not active
2018-09-19T21:02:00.389Z,1537390920.389 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:00.511Z,1537390920.511 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-09-19T21:02:00.517Z,1537390920.517 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-09-19T21:02:00.561Z,1537390920.561 [CommandLine](FAULT): Scheduling is paused
2018-09-19T21:02:00.562Z,1537390920.562 [CBIT](INFO): Critical error at 20180919T210159
2018-09-19T21:02:00.562Z,1537390920.562 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals
2018-09-19T21:02:00.783Z,1537390920.783 [DropWeight](CRITICAL): DROP WEIGHT MISSING.
2018-09-19T21:02:00.783Z,1537390920.783 [DropWeight] Hardware Fault, FailCount= 1
2018-09-19T21:02:00.783Z,1537390920.783 [DropWeight](ERROR): Hardware Fault
2018-09-19T21:02:00.857Z,1537390920.857 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:00.865Z,1537390920.865 [CBIT](INFO): Critical error at 20180919T210200
2018-09-19T21:02:00.868Z,1537390920.868 [CBIT](ERROR): Hardware Fault in component: DropWeight
2018-09-19T21:02:00.868Z,1537390920.868 [CBIT](CRITICAL): Hardware Fault in component: DropWeight
2018-09-19T21:02:01.058Z,1537390921.058 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:01.397Z,1537390921.397 [BuoyancyServo](ERROR): Buoyancy initialization uart error serial timeout
2018-09-19T21:02:01.397Z,1537390921.397 [BuoyancyServo](FAULT): Buoyancy failed to initialize
2018-09-19T21:02:01.397Z,1537390921.397 [BuoyancyServo] Communications Fault, FailCount= 1
2018-09-19T21:02:01.397Z,1537390921.397 [BuoyancyServo](ERROR): Communications Fault
2018-09-19T21:02:01.400Z,1537390921.400 [CBIT](INFO): Critical error at 20180919T210200
2018-09-19T21:02:01.402Z,1537390921.402 [CBIT](ERROR): Communications Fault in component: BuoyancyServo
2018-09-19T21:02:01.462Z,1537390921.462 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:01.485Z,1537390921.485 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-09-19T21:02:01.485Z,1537390921.485 [BuoyancyServo](INFO): Powering down
2018-09-19T21:02:01.860Z,1537390921.860 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:02.261Z,1537390922.261 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:02.705Z,1537390922.705 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:03.061Z,1537390923.061 [DeadReckonUsingSpeedCalculator](DEBUG): Starting up and don't have orientation data yet.
2018-09-19T21:02:03.565Z,1537390923.565 [Aanderaa_O2](INFO): Powering down
2018-09-19T21:02:03.889Z,1537390923.889 [CBIT](INFO): Clearing failed state for component BuoyancyServo
2018-09-19T21:02:03.890Z,1537390923.890 [BuoyancyServo] No Fault, FailCount= 1
2018-09-19T21:02:04.395Z,1537390924.395 [BuoyancyServo](DEBUG): Initializing EZServoServo.
2018-09-19T21:02:04.513Z,1537390924.513 [BuoyancyServo](DEBUG): Initializing BuoyancyServo.
2018-09-19T21:02:05.084Z,1537390925.084 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-19T21:02:05.371Z,1537390925.371 [CTD_Seabird](INFO): Started Seabird LCM interface with command:nohup ./lrauv-framework/onboard/bin/gpctd -ldir /mnt/mmc/LRAUV/Logs/latest/ -dev /dev/ttyC6 -b 9600 >& /dev/null &
2018-09-19T21:02:05.391Z,1537390925.391 [CTD_Seabird](INFO): LCM subscribed to channel:seabird_gpctd_t.seabird-gpctd
2018-09-19T21:02:05.756Z,1537390925.756 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-19T21:02:05.756Z,1537390925.756 [CTD_Seabird](INFO): Powering down
2018-09-19T21:02:26.218Z,1537390946.218 [NAL9602](INFO): Powering up NAL9602
2018-09-19T21:02:37.018Z,1537390957.018 [NAL9602](INFO): NAL9602 initialized
2018-09-19T21:03:01.073Z,1537390981.073 [BPC1](INFO): BPC1A: initialized.
2018-09-19T21:03:01.085Z,1537390981.085 [BPC1](INFO): BPC1B: initialized.
2018-09-19T21:03:02.253Z,1537390982.253 [BPC1](INFO): BPC1B: sending IBPS break.
2018-09-19T21:03:02.647Z,1537390982.647 [BPC1](INFO): BPC1A: sending IBPS break.
2018-09-19T21:03:06.671Z,1537390986.671 [BPC1](INFO): BPC1B: validating data format.
2018-09-19T21:03:06.710Z,1537390986.710 [BPC1](INFO): BPC1B: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:07.059Z,1537390987.059 [BPC1](INFO): BPC1A: validating data format.
2018-09-19T21:03:07.099Z,1537390987.099 [BPC1](INFO): BPC1A: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:07.100Z,1537390987.100 [BPC1](INFO): BPC1B valid message: 1824 bytes.
2018-09-19T21:03:07.129Z,1537390987.129 [BPC1](INFO): BPC1B: data parsed.
2018-09-19T21:03:07.448Z,1537390987.448 [BPC1](INFO): BPC1A valid message: 1824 bytes.
2018-09-19T21:03:07.456Z,1537390987.456 [BPC1](INFO): BPC1A: data parsed.
2018-09-19T21:03:07.872Z,1537390987.872 [BPC1](INFO): BPC1B: initialized.
2018-09-19T21:03:08.264Z,1537390988.264 [BPC1](INFO): BPC1A: initialized.
2018-09-19T21:03:15.450Z,1537390995.450 [BPC1](INFO): BPC1B: sending IBPS break.
2018-09-19T21:03:15.853Z,1537390995.853 [BPC1](INFO): BPC1A: sending IBPS break.
2018-09-19T21:03:19.852Z,1537390999.852 [BPC1](INFO): BPC1B: validating data format.
2018-09-19T21:03:19.937Z,1537390999.937 [BPC1](INFO): BPC1B: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:20.251Z,1537391000.251 [BPC1](INFO): BPC1B valid message: 1824 bytes.
2018-09-19T21:03:20.259Z,1537391000.259 [BPC1](INFO): BPC1B: data parsed.
2018-09-19T21:03:20.651Z,1537391000.651 [BPC1](INFO): BPC1A: validating data format.
2018-09-19T21:03:20.733Z,1537391000.733 [BPC1](INFO): BPC1A: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:21.047Z,1537391001.047 [BPC1](INFO): BPC1A valid message: 1824 bytes.
2018-09-19T21:03:21.056Z,1537391001.056 [BPC1](INFO): BPC1A: data parsed.
2018-09-19T21:03:21.069Z,1537391001.069 [BPC1](INFO): BPC1B: initialized.
2018-09-19T21:03:21.868Z,1537391001.868 [BPC1](INFO): BPC1A: initialized.
2018-09-19T21:03:28.255Z,1537391008.255 [BPC1](INFO): BPC1B: sending IBPS break.
2018-09-19T21:03:29.454Z,1537391009.454 [BPC1](INFO): BPC1A: sending IBPS break.
2018-09-19T21:03:33.065Z,1537391013.065 [BPC1](INFO): BPC1B: validating data format.
2018-09-19T21:03:33.147Z,1537391013.147 [BPC1](INFO): BPC1B: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:33.451Z,1537391013.451 [BPC1](INFO): BPC1B valid message: 1824 bytes.
2018-09-19T21:03:33.468Z,1537391013.468 [BPC1](INFO): BPC1B: data parsed.
2018-09-19T21:03:34.243Z,1537391014.243 [BPC1](INFO): BPC1A: validating data format.
2018-09-19T21:03:34.331Z,1537391014.331 [BPC1](INFO): BPC1A: got 8 stick msg (1824 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:34.345Z,1537391014.345 [BPC1](INFO): BPC1B: initialized.
2018-09-19T21:03:34.643Z,1537391014.643 [BPC1](INFO): BPC1A valid message: 1824 bytes.
2018-09-19T21:03:34.651Z,1537391014.651 [BPC1](INFO): BPC1A: data parsed.
2018-09-19T21:03:35.473Z,1537391015.473 [BPC1](INFO): BPC1A: initialized.
2018-09-19T21:03:41.853Z,1537391021.853 [BPC1](INFO): BPC1B: sending IBPS break.
2018-09-19T21:03:42.666Z,1537391022.666 [BPC1](INFO): BPC1A: sending IBPS break.
2018-09-19T21:03:45.844Z,1537391025.844 [BPC1](INFO): BPC1B: validating data format.
2018-09-19T21:03:45.929Z,1537391025.929 [BPC1](INFO): BPC1B: got 7 stick msg (1596 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:46.244Z,1537391026.244 [BPC1](INFO): BPC1B valid message: 1596 bytes.
2018-09-19T21:03:46.252Z,1537391026.252 [BPC1](INFO): BPC1B: data parsed.
2018-09-19T21:03:47.051Z,1537391027.051 [BPC1](INFO): BPC1A: validating data format.
2018-09-19T21:03:47.134Z,1537391027.134 [BPC1](INFO): BPC1A: got 7 stick msg (1596 bytes) with SHORT_IBPS_MENU.
2018-09-19T21:03:47.144Z,1537391027.144 [BPC1](INFO): BPC1B: initialized.
2018-09-19T21:03:47.471Z,1537391027.471 [BPC1](INFO): BPC1A valid message: 1596 bytes.
2018-09-19T21:03:47.479Z,1537391027.479 [BPC1](INFO): BPC1A: data parsed.
2018-09-19T21:03:47.481Z,1537391027.481 [BPC1](FAULT): Battery stick #2 (s/n: 0125) reported . Status code: 0x00C0.
2018-09-19T21:03:47.481Z,1537391027.481 [BPC1](FAULT): Battery stick #3 (s/n: 00EF) reported . Status code: 0x00C0.
2018-09-19T21:03:47.482Z,1537391027.482 [BPC1](FAULT): Battery stick #4 (s/n: 0158) reported . Status code: 0x00C0.
2018-09-19T21:03:47.483Z,1537391027.483 [BPC1](FAULT): Battery stick #5 (s/n: 0088) reported . Status code: 0x00C0.
2018-09-19T21:03:47.484Z,1537391027.484 [BPC1](FAULT): Battery stick #6 (s/n: 00A3) reported . Status code: 0x00C0.
2018-09-19T21:03:47.485Z,1537391027.485 [BPC1](FAULT): Battery stick #7 (s/n: 012D) reported . Status code: 0x00C0.
2018-09-19T21:03:47.486Z,1537391027.486 [BPC1](FAULT): Battery stick #9 (s/n: 0100) reported . Status code: 0x00C0.
2018-09-19T21:03:47.487Z,1537391027.487 [BPC1](FAULT): Battery stick #10 (s/n: 00B9) reported . Status code: 0x00C0.
2018-09-19T21:03:47.487Z,1537391027.487 [BPC1](FAULT): Battery stick #11 (s/n: 008C) reported . Status code: 0x00C0.
2018-09-19T21:03:47.488Z,1537391027.488 [BPC1](FAULT): Battery stick #12 (s/n: 0117) reported . Status code: 0x00C0.
2018-09-19T21:03:47.489Z,1537391027.489 [BPC1](FAULT): Battery stick #13 (s/n: 00E4) reported . Status code: 0x00C0.
2018-09-19T21:03:47.490Z,1537391027.490 [BPC1](FAULT): Battery stick #16 (s/n: 00EC) reported . Status code: 0x00C0.
2018-09-19T21:03:47.491Z,1537391027.491 [BPC1](FAULT): Battery stick #17 (s/n: 008A) reported . Status code: 0x00C0.
2018-09-19T21:03:47.491Z,1537391027.491 [BPC1](FAULT): Battery stick #19 (s/n: 00E5) reported . Status code: 0x00C0.
2018-09-19T21:03:47.492Z,1537391027.492 [BPC1](FAULT): Battery stick #20 (s/n: 00E0) reported . Status code: 0x00C0.
2018-09-19T21:03:47.493Z,1537391027.493 [BPC1](FAULT): Battery stick #23 (s/n: 009C) reported . Status code: 0x00C0.
2018-09-19T21:03:47.494Z,1537391027.494 [BPC1](FAULT): Battery stick #24 (s/n: 00A6) reported . Status code: 0x00C0.
2018-09-19T21:03:47.495Z,1537391027.495 [BPC1](FAULT): Battery stick #25 (s/n: 00E8) reported . Status code: 0x00C0.
2018-09-19T21:03:47.496Z,1537391027.496 [BPC1](FAULT): Battery stick #27 (s/n: 00F3) reported . Status code: 0x00C0.
2018-09-19T21:03:47.497Z,1537391027.497 [BPC1](FAULT): Battery stick #29 (s/n: 00AD) reported . Status code: 0x00C0.
2018-09-19T21:03:47.498Z,1537391027.498 [BPC1](FAULT): Battery stick #31 (s/n: 0126) reported . Status code: 0x00C0.
2018-09-19T21:03:47.499Z,1537391027.499 [BPC1](FAULT): Battery stick #33 (s/n: 00F1) reported . Status code: 0x00C0.
2018-09-19T21:03:47.500Z,1537391027.500 [BPC1](FAULT): Battery stick #34 (s/n: 00BF) reported . Status code: 0x00C0.
2018-09-19T21:03:47.501Z,1537391027.501 [BPC1](FAULT): Battery stick #35 (s/n: 0089) reported . Status code: 0x00C0.
2018-09-19T21:03:47.502Z,1537391027.502 [BPC1](FAULT): Battery stick #36 (s/n: 00C2) reported . Status code: 0x00C0.
2018-09-19T21:03:47.503Z,1537391027.503 [BPC1](FAULT): Battery stick #37 (s/n: 00CA) reported . Status code: 0x00C0.
2018-09-19T21:03:47.504Z,1537391027.504 [BPC1](FAULT): Battery stick #38 (s/n: 011A) reported . Status code: 0x00C0.
2018-09-19T21:03:47.505Z,1537391027.505 [BPC1](FAULT): Battery stick #40 (s/n: 0095) reported . Status code: 0x00C0.
2018-09-19T21:03:47.506Z,1537391027.506 [BPC1](FAULT): Battery stick #41 (s/n: 00BE) reported . Status code: 0x00C0.
2018-09-19T21:03:47.507Z,1537391027.507 [BPC1](FAULT): Battery stick #42 (s/n: 0086) reported . Status code: 0x00C0.
2018-09-19T21:03:47.509Z,1537391027.509 [BPC1](FAULT): Battery stick #47 (s/n: 00F0) reported . Status code: 0x00C0.
2018-09-19T21:03:47.510Z,1537391027.510 [BPC1](FAULT): Battery stick #48 (s/n: 00C9) reported . Status code: 0x00C0.
2018-09-19T21:03:47.511Z,1537391027.511 [BPC1](FAULT): Battery stick #49 (s/n: 0103) reported . Status code: 0x00C0.
2018-09-19T21:03:47.512Z,1537391027.512 [BPC1](FAULT): Battery stick #52 (s/n: 0114) reported . Status code: 0x00C0.
2018-09-19T21:03:47.533Z,1537391027.533 [BPC1](FAULT): Battery stick #54 (s/n: 008E) reported . Status code: 0x00C0.
2018-09-19T21:03:47.534Z,1537391027.534 [BPC1](FAULT): Battery stick #55 (s/n: 00AC) reported . Status code: 0x00C0.
2018-09-19T21:03:47.535Z,1537391027.535 [BPC1](FAULT): Battery stick #58 (s/n: 00AF) reported . Status code: 0x00C0.
2018-09-19T21:03:47.535Z,1537391027.535 [BPC1](FAULT): Battery stick #59 (s/n: 0151) reported . Status code: 0x00C0.
2018-09-19T21:03:47.536Z,1537391027.536 [BPC1](FAULT): Battery stick #60 (s/n: 00DC) reported . Status code: 0x00C0.
2018-09-19T21:03:47.537Z,1537391027.537 [BPC1](FAULT): Battery stick #61 (s/n: 00BA) reported . Status code: 0x00C0.
2018-09-19T21:03:47.538Z,1537391027.538 [BPC1](INFO): Calculating totals. Valid battery stick count: 36. Valid reserve battery stick count: 4.
2018-09-19T21:04:40.280Z,1537391080.280 [SBIT](IMPORTANT): Beginning Startup BIT
2018-09-19T21:04:40.289Z,1537391080.289 [CBIT](IMPORTANT): Beginning ground fault scan
2018-09-19T21:04:51.111Z,1537391091.111 [CBIT](IMPORTANT): Ground fault detected
mA:
CHAN A0 (Batt): 0.133062
CHAN A1 (24V): -0.004427
CHAN A2 (12V): -0.002595
CHAN A3 (5V): -0.002252
CHAN B0 (3.3V): -0.000224
CHAN B1 (3.15aV): -0.000313
CHAN B2 (3.15bV): -0.000145
CHAN B3 (GND): 0.000094
OPEN: -0.000704
Full Scale Calc: 4.765 mA, -1.589 mA
2018-09-19T21:04:53.469Z,1537391093.469 [SBIT](ERROR): Could not read elevatorAngleReader_.
2018-09-19T21:04:53.469Z,1537391093.469 [SBIT](ERROR): Could not read rudderAngleReader_.
2018-09-19T21:04:53.469Z,1537391093.469 [SBIT](ERROR): Could not read massPosReader_.
2018-09-19T21:04:59.864Z,1537391099.864 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-09-19T21:04:59.864Z,1537391099.864 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 1
2018-09-19T21:04:59.864Z,1537391099.864 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-09-19T21:04:59.884Z,1537391099.884 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-09-19T21:05:00.313Z,1537391100.313 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-09-19T21:05:00.313Z,1537391100.313 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 1
2018-09-19T21:05:00.666Z,1537391100.666 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:05:00.667Z,1537391100.667 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:05:00.667Z,1537391100.667 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:05:06.319Z,1537391106.319 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004286
2018-09-19T21:05:19.968Z,1537391119.968 [SBIT](ERROR): Could not read elevatorAngleReader_.
2018-09-19T21:05:19.968Z,1537391119.968 [SBIT](ERROR): Could not read rudderAngleReader_.
2018-09-19T21:05:19.969Z,1537391119.969 [SBIT](ERROR): Could not read massPosReader_.
2018-09-19T21:05:19.969Z,1537391119.969 [SBIT](FAULT): Control surface position failure.
2018-09-19T21:05:33.576Z,1537391133.576 [SBIT](ERROR): Could not read elevatorAngleReader_.
2018-09-19T21:05:33.576Z,1537391133.576 [SBIT](ERROR): Could not read rudderAngleReader_.
2018-09-19T21:05:33.576Z,1537391133.576 [SBIT](ERROR): Could not read massPosReader_.
2018-09-19T21:05:33.576Z,1537391133.576 [SBIT](FAULT): Control surface position failure.
2018-09-19T21:05:33.977Z,1537391133.977 [SBIT](CRITICAL): SBIT FAILED
2018-09-19T21:05:34.039Z,1537391134.039 [CommandLine](IMPORTANT): got command configSet list
2018-09-19T21:05:34.039Z,1537391134.039 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg
2018-09-19T21:05:34.040Z,1537391134.040 [CommandLine](IMPORTANT): DAT.loadAtStartup=0 bool;
2018-09-19T21:05:34.040Z,1537391134.040 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool;
2018-09-19T21:05:34.040Z,1537391134.040 [CommandLine](IMPORTANT): ESPComponent.sampleTimeout=10 minute;
2018-09-19T21:05:34.040Z,1537391134.040 [CommandLine](IMPORTANT): ESPComponent.simulateHardware=1 bool;
2018-09-19T21:05:34.040Z,1537391134.040 [CommandLine](IMPORTANT): ElevatorServo.loadAtStartup=0 bool;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_salinity;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_mean_sea_water_temperature;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none CTD_NeilBrown.bin_median_sea_water_temperature;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none CTD_Seabird.bin_median_sea_water_salinity;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none Rowe_600LCM.height_above_sea_floor;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express none VerticalTemperatureHomogeneityIndexCalculator.vertical_temperature_homogeneity_index;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): Express linearApproximation height_above_sea_floor 5.000000 meter;
2018-09-19T21:05:34.041Z,1537391134.041 [CommandLine](IMPORTANT): MassServo.loadAtStartup=0 bool;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): Rowe_600LCM.loadAtStartup=0 bool;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): RudderServo.loadAtStartup=0 bool;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): StratificationFrontDetector.loadAtStartup=0 bool;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): ThrusterServo.loadAtStartup=0 bool;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=497.852 cubic_centimeter;
2018-09-19T21:05:34.042Z,1537391134.042 [CommandLine](IMPORTANT): VerticalControl.massDefault=-35 millimeter;
2018-09-19T21:05:34.054Z,1537391134.054 [CBIT](INFO): Critical error at 20180919T210533
2018-09-19T21:05:34.383Z,1537391134.383 [MissionManager](IMPORTANT): Started mission Startup
2018-09-19T21:05:34.383Z,1537391134.383 [Startup] Running Loop=1
2018-09-19T21:05:34.383Z,1537391134.383 [Startup](DEBUG): Aggregate::initialize Startup
2018-09-19T21:05:34.383Z,1537391134.383 [Startup:A.GoToSurface] Running Loop=1
2018-09-19T21:05:34.383Z,1537391134.383 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-09-19T21:05:34.384Z,1537391134.384 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-09-19T21:05:34.401Z,1537391134.401 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-09-19T21:05:34.401Z,1537391134.401 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-09-19T21:05:34.402Z,1537391134.402 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-09-19T21:05:34.402Z,1537391134.402 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-09-19T21:05:34.421Z,1537391134.421 [Startup:StartupSatComms] Running Loop=1
2018-09-19T21:05:34.422Z,1537391134.422 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms
2018-09-19T21:05:34.422Z,1537391134.422 [Startup:StartupSatComms:A] Running Loop=1
2018-09-19T21:05:34.770Z,1537391134.770 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix
2018-09-19T21:06:34.793Z,1537391194.793 [Startup:StartupSatComms:A](INFO): Timed out from 2018-09-19T21:05:34.4Z
2018-09-19T21:06:34.793Z,1537391194.793 [Startup:StartupSatComms:A] Stopped
2018-09-19T21:06:34.793Z,1537391194.793 [Startup:StartupSatComms:B] Running Loop=1
2018-09-19T21:06:35.191Z,1537391195.191 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-09-19T21:06:39.171Z,1537391199.171 [DataOverHttps](INFO): Sending 345 bytes from file Logs/20180919T205628/Courier0000.lzma
2018-09-19T21:06:39.936Z,1537391199.936 [DataOverHttps](INFO): Moved sent file to Logs/20180919T205628/Courier0000.lzma.bak
2018-09-19T21:06:39.936Z,1537391199.936 [DataOverHttps](INFO): SBD MOMSN=8540051
2018-09-19T21:06:49.234Z,1537391209.234 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180919T205628/Courier0004.lzma
2018-09-19T21:06:50.036Z,1537391210.036 [DataOverHttps](INFO): Moved sent file to Logs/20180919T205628/Courier0004.lzma.bak
2018-09-19T21:06:50.036Z,1537391210.036 [DataOverHttps](INFO): SBD MOMSN=8540058
2018-09-19T21:06:58.866Z,1537391218.866 [DataOverHttps](INFO): Sending 346 bytes from file Logs/20180919T210149/Courier0000.lzma
2018-09-19T21:06:59.651Z,1537391219.651 [DataOverHttps](INFO): Moved sent file to Logs/20180919T210149/Courier0000.lzma.bak
2018-09-19T21:06:59.652Z,1537391219.652 [DataOverHttps](INFO): SBD MOMSN=8540060
2018-09-19T21:07:08.529Z,1537391228.529 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20180918T224323/Express0392.lzma
2018-09-19T21:07:09.328Z,1537391229.328 [DataOverHttps](INFO): Moved sent file to Logs/20180918T224323/Express0392.lzma.bak
2018-09-19T21:07:09.328Z,1537391229.328 [DataOverHttps](INFO): SBD MOMSN=8540067
2018-09-19T21:07:18.221Z,1537391238.221 [DataOverHttps](INFO): Sending 1416 bytes from file Logs/20180919T205628/Express0001.lzma
2018-09-19T21:07:18.999Z,1537391238.999 [DataOverHttps](INFO): Moved sent file to Logs/20180919T205628/Express0001.lzma.bak
2018-09-19T21:07:18.000Z,1537391239.000 [DataOverHttps](INFO): SBD MOMSN=8540070
2018-09-19T21:07:28.008Z,1537391248.008 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20180919T205628/Express0005.lzma
2018-09-19T21:07:28.808Z,1537391248.808 [DataOverHttps](INFO): Moved sent file to Logs/20180919T205628/Express0005.lzma.bak
2018-09-19T21:07:28.808Z,1537391248.808 [DataOverHttps](INFO): SBD MOMSN=8540145
2018-09-19T21:07:37.650Z,1537391257.650 [Startup:StartupSatComms:B](INFO): Timed out from 2018-09-19T21:06:34.8Z
2018-09-19T21:07:37.650Z,1537391257.650 [Startup:StartupSatComms:B] Stopped
2018-09-19T21:07:37.650Z,1537391257.650 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms
2018-09-19T21:07:37.650Z,1537391257.650 [Startup:StartupSatComms] Stopped
2018-09-19T21:07:37.650Z,1537391257.650 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms
2018-09-19T21:07:37.651Z,1537391257.651 [Startup](INFO): Completed Startup
2018-09-19T21:07:37.651Z,1537391257.651 [MissionManager](INFO): Startup is completed.
2018-09-19T21:07:37.652Z,1537391257.652 [MissionManager](INFO): Uninitializing Mission Startup
2018-09-19T21:07:37.652Z,1537391257.652 [Startup] Stopped
2018-09-19T21:07:37.652Z,1537391257.652 [Startup](DEBUG): Aggregate::uninitialize Startup
2018-09-19T21:07:37.652Z,1537391257.652 [Startup:A.GoToSurface] Stopped
2018-09-19T21:07:37.652Z,1537391257.652 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-09-19T21:07:37.727Z,1537391257.727 [DataOverHttps](INFO): Sending 1376 bytes from file Logs/20180919T210149/Express0001.lzma
2018-09-19T21:07:37.851Z,1537391257.851 [MissionManager](IMPORTANT): Started mission Default
2018-09-19T21:07:37.852Z,1537391257.852 [Default] Running Loop=1
2018-09-19T21:07:37.852Z,1537391257.852 [Default](DEBUG): Aggregate::initialize Default
2018-09-19T21:07:37.852Z,1537391257.852 [Default:B.GoToSurface] Running Loop=1
2018-09-19T21:07:37.852Z,1537391257.852 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2018-09-19T21:07:37.852Z,1537391257.852 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2018-09-19T21:07:37.853Z,1537391257.853 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2018-09-19T21:07:37.853Z,1537391257.853 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2018-09-19T21:07:37.854Z,1537391257.854 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2018-09-19T21:07:37.854Z,1537391257.854 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2018-09-19T21:07:37.854Z,1537391257.854 [Default:A.Wait] Running Loop=1
2018-09-19T21:07:37.854Z,1537391257.854 [Default:A.Wait](DEBUG): Initialize Wait Component.
2018-09-19T21:07:38.471Z,1537391258.471 [DataOverHttps](INFO): Moved sent file to Logs/20180919T210149/Express0001.lzma.bak
2018-09-19T21:07:38.472Z,1537391258.472 [DataOverHttps](INFO): SBD MOMSN=8540148
2018-09-19T21:07:42.382Z,1537391262.382 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session.
2018-09-19T21:07:50.938Z,1537391270.938 [Default:A.Wait](INFO): Done Waiting.
2018-09-19T21:07:50.939Z,1537391270.939 [Default:A.Wait] Stopped
2018-09-19T21:07:50.939Z,1537391270.939 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2018-09-19T21:07:51.337Z,1537391271.337 [Default:CheckIn] Running Loop=1
2018-09-19T21:07:51.337Z,1537391271.337 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2018-09-19T21:07:51.337Z,1537391271.337 [Default:CheckIn:Read_GPS] Running Loop=1
2018-09-19T21:07:51.743Z,1537391271.743 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix
2018-09-19T21:08:00.951Z,1537391280.951 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-09-19T21:08:00.951Z,1537391280.951 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 2
2018-09-19T21:08:00.951Z,1537391280.951 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-09-19T21:08:00.971Z,1537391280.971 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-09-19T21:08:01.352Z,1537391281.352 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-09-19T21:08:01.352Z,1537391281.352 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 2
2018-09-19T21:08:01.733Z,1537391281.733 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:08:01.733Z,1537391281.733 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:08:01.733Z,1537391281.733 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:11:02.076Z,1537391462.076 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-09-19T21:11:02.076Z,1537391462.076 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 3
2018-09-19T21:11:02.076Z,1537391462.076 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-09-19T21:11:02.094Z,1537391462.094 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-09-19T21:11:02.501Z,1537391462.501 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-09-19T21:11:02.501Z,1537391462.501 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 3
2018-09-19T21:11:02.908Z,1537391462.908 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:11:02.909Z,1537391462.909 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:11:02.909Z,1537391462.909 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:12:39.618Z,1537391559.618 [NAL9602](FAULT): GPS failed to acquire within timeout.
2018-09-19T21:12:39.618Z,1537391559.618 [NAL9602] Data Fault, FailCount= 1
2018-09-19T21:12:39.618Z,1537391559.618 [NAL9602](ERROR): Data Fault
2018-09-19T21:12:39.702Z,1537391559.702 [CBIT](ERROR): Data Fault in component: NAL9602
2018-09-19T21:12:40.018Z,1537391560.018 [NAL9602](INFO): Powering down
2018-09-19T21:12:40.875Z,1537391560.875 [CBIT](INFO): Clearing failed state for component NAL9602
2018-09-19T21:12:40.875Z,1537391560.875 [NAL9602] No Fault, FailCount= 1
2018-09-19T21:12:51.637Z,1537391571.637 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-09-19T21:07:51.3Z
2018-09-19T21:12:51.637Z,1537391571.637 [Default:CheckIn:Read_GPS] Stopped
2018-09-19T21:12:51.637Z,1537391571.637 [Default:CheckIn:Read_Iridium] Running Loop=1
2018-09-19T21:12:52.035Z,1537391572.035 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications
2018-09-19T21:12:56.008Z,1537391576.008 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180919T210149/Courier0004.lzma
2018-09-19T21:12:56.807Z,1537391576.807 [DataOverHttps](INFO): Moved sent file to Logs/20180919T210149/Courier0004.lzma.bak
2018-09-19T21:12:56.808Z,1537391576.808 [DataOverHttps](INFO): SBD MOMSN=8540257
2018-09-19T21:13:05.786Z,1537391585.786 [DataOverHttps](INFO): Sending 192 bytes from file Logs/20180919T210149/Express0005.lzma
2018-09-19T21:13:06.583Z,1537391586.583 [DataOverHttps](INFO): Moved sent file to Logs/20180919T210149/Express0005.lzma.bak
2018-09-19T21:13:06.584Z,1537391586.584 [DataOverHttps](INFO): SBD MOMSN=8540259
2018-09-19T21:13:07.427Z,1537391587.427 [Default:CheckIn:Read_Iridium] Stopped
2018-09-19T21:13:07.427Z,1537391587.427 [Default:CheckIn:C.Wait] Running Loop=1
2018-09-19T21:13:07.428Z,1537391587.428 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component.
2018-09-19T21:13:10.554Z,1537391590.554 [NAL9602](INFO): Powering up NAL9602
2018-09-19T21:13:21.462Z,1537391601.462 [NAL9602](INFO): NAL9602 initialized
2018-09-19T21:13:58.709Z,1537391638.709 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.373732 seconds old.
2018-09-19T21:13:59.104Z,1537391639.104 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.768988 seconds old.
2018-09-19T21:13:59.512Z,1537391639.512 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.176753 seconds old.
2018-09-19T21:13:59.918Z,1537391639.918 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.583069 seconds old.
2018-09-19T21:14:03.119Z,1537391643.119 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-09-19T21:14:03.119Z,1537391643.119 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 4
2018-09-19T21:14:03.120Z,1537391643.120 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-09-19T21:14:03.148Z,1537391643.148 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-09-19T21:14:03.515Z,1537391643.515 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-09-19T21:14:03.515Z,1537391643.515 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 4
2018-09-19T21:14:03.916Z,1537391643.916 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:14:03.916Z,1537391643.916 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:14:03.916Z,1537391643.916 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:17:01.173Z,1537391821.173 [CBIT](INFO): Clearing failed state for component DropWeight
2018-09-19T21:17:01.174Z,1537391821.174 [DropWeight] No Fault, FailCount= 1
2018-09-19T21:17:03.961Z,1537391823.961 [DeadReckonUsingSpeedCalculator](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan
2018-09-19T21:17:03.961Z,1537391823.961 [DeadReckonUsingSpeedCalculator] Software Fault, FailCount= 5
2018-09-19T21:17:03.961Z,1537391823.961 [DeadReckonUsingSpeedCalculator](ERROR): Software Fault
2018-09-19T21:17:03.972Z,1537391823.972 [CBIT](ERROR): Software Fault in component: DeadReckonUsingSpeedCalculator
2018-09-19T21:17:04.378Z,1537391824.378 [CBIT](INFO): Clearing failed state for component DeadReckonUsingSpeedCalculator
2018-09-19T21:17:04.378Z,1537391824.378 [DeadReckonUsingSpeedCalculator] No Fault, FailCount= 5
2018-09-19T21:17:04.766Z,1537391824.766 [DeadReckonUsingSpeedCalculator](DEBUG): Initializing DeadReckonUsingSpeedCalculator component.
2018-09-19T21:17:04.767Z,1537391824.767 [DeadReckonUsingSpeedCalculator](INFO): Will consider orientation measurement stale after 120s.
2018-09-19T21:17:04.767Z,1537391824.767 [DeadReckonUsingSpeedCalculator](INFO): Will consider velocity measurement stale after 20s.
2018-09-19T21:17:44.634Z,1537391864.634 [CommandLine](IMPORTANT): got command restart application
2018-09-19T21:17:45.643Z,1537391865.643 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:45.644Z,1537391865.644 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.724Z,1537391865.724 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye!
2018-09-19T21:17:45.725Z,1537391865.725 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.725Z,1537391865.725 [CommandLine](INFO): Join timeout helper Thread ID is 2608
2018-09-19T21:17:45.726Z,1537391865.726 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2018-09-19T21:17:45.726Z,1537391865.726 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.726Z,1537391865.726 [NavChartDb](INFO): Join timeout helper Thread ID is 2609
2018-09-19T21:17:45.809Z,1537391865.809 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:45.809Z,1537391865.809 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.824Z,1537391865.824 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2018-09-19T21:17:45.825Z,1537391865.825 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.825Z,1537391865.825 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2610
2018-09-19T21:17:45.849Z,1537391865.849 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:45.849Z,1537391865.849 [WetLabsBB2FL](INFO): Powering down
2018-09-19T21:17:45.850Z,1537391865.850 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.868Z,1537391865.868 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler
2018-09-19T21:17:45.869Z,1537391865.869 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:45.869Z,1537391865.869 [CTD_Seabird](INFO): Join timeout helper Thread ID is 2611
2018-09-19T21:17:46.245Z,1537391866.245 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:46.449Z,1537391866.449 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface
2018-09-19T21:17:46.449Z,1537391866.449 [CTD_Seabird](INFO): Powering down
2018-09-19T21:17:46.450Z,1537391866.450 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.461Z,1537391866.461 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2018-09-19T21:17:46.461Z,1537391866.461 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.461Z,1537391866.461 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2613
2018-09-19T21:17:46.497Z,1537391866.497 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:46.497Z,1537391866.497 [CTD_NeilBrown](INFO): Powering down
2018-09-19T21:17:46.498Z,1537391866.498 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.502Z,1537391866.502 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2018-09-19T21:17:46.502Z,1537391866.502 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.502Z,1537391866.502 [Radio_Surface](INFO): Join timeout helper Thread ID is 2614
2018-09-19T21:17:46.901Z,1537391866.901 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:46.901Z,1537391866.901 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.905Z,1537391866.905 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2018-09-19T21:17:46.905Z,1537391866.905 [logger ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.906Z,1537391866.906 [logger](INFO): Join timeout helper Thread ID is 2615
2018-09-19T21:17:46.921Z,1537391866.921 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:46.921Z,1537391866.921 [logger ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.925Z,1537391866.925 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2018-09-19T21:17:46.925Z,1537391866.925 [CommandLine ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.926Z,1537391866.926 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2018-09-19T21:17:46.926Z,1537391866.926 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:46.926Z,1537391866.926 [controlThread](INFO): Join timeout helper Thread ID is 2616
2018-09-19T21:17:47.085Z,1537391867.085 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2018-09-19T21:17:47.085Z,1537391867.085 [controlThread](DEBUG): Uninitializing ControlThread
2018-09-19T21:17:47.086Z,1537391867.086 [NAL9602](INFO): Powering down
2018-09-19T21:17:47.087Z,1537391867.087 [PNI_TCM](INFO): Powering down
2018-09-19T21:17:47.173Z,1537391867.173 [Aanderaa_O2](INFO): Powering down
2018-09-19T21:17:47.175Z,1537391867.175 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator.
2018-09-19T21:17:47.176Z,1537391867.176 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2018-09-19T21:17:47.177Z,1537391867.177 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2018-09-19T21:17:47.177Z,1537391867.177 [MissionManager](INFO): Uninitializing Mission Default
2018-09-19T21:17:47.177Z,1537391867.177 [Default] Stopped
2018-09-19T21:17:47.177Z,1537391867.177 [Default](DEBUG): Aggregate::uninitialize Default
2018-09-19T21:17:47.178Z,1537391867.178 [Default:B.GoToSurface] Stopped
2018-09-19T21:17:47.178Z,1537391867.178 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2018-09-19T21:17:47.178Z,1537391867.178 [Default:CheckIn] Stopped
2018-09-19T21:17:47.178Z,1537391867.178 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2018-09-19T21:17:47.178Z,1537391867.178 [Default:CheckIn:C.Wait] Stopped
2018-09-19T21:17:47.178Z,1537391867.178 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2018-09-19T21:17:47.182Z,1537391867.182 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2018-09-19T21:17:47.182Z,1537391867.182 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2018-09-19T21:17:47.182Z,1537391867.182 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2018-09-19T21:17:47.183Z,1537391867.183 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2018-09-19T21:17:47.183Z,1537391867.183 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2018-09-19T21:17:47.183Z,1537391867.183 [BuoyancyServo](INFO): Powering down
2018-09-19T21:17:47.197Z,1537391867.197 [SBIT](DEBUG): Uninitialize SBIT Component.
2018-09-19T21:17:47.197Z,1537391867.197 [IBIT](DEBUG): Uninitialize IBIT Component.
2018-09-19T21:17:47.197Z,1537391867.197 [CBIT](DEBUG): Uninitialize CBIT Component.
2018-09-19T21:17:47.198Z,1537391867.198 [controlThread ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.305Z,1537391867.305 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.346Z,1537391867.346 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.350Z,1537391867.350 [CTD_Seabird ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.353Z,1537391867.353 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.382Z,1537391867.382 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2018-09-19T21:17:47.442Z,1537391867.442 [logger ThreadHandler](INFO): Thread cancelled.