2019-05-19T17:55:10.954Z,1558288510.954 [Supervisor](DEBUG): Initializing supervisor. 2019-05-19T17:55:10.957Z,1558288510.957 [SyncHandler](DEBUG): Created PCaller Thread at 404514E0 2019-05-19T17:55:10.958Z,1558288510.958 [SyncHandler](INFO): Protected caller Thread ID is 2568 2019-05-19T17:55:10.958Z,1558288510.958 [ComponentRegistry](DEBUG): Component "controlThread" handled in its own thread. 2019-05-19T17:55:10.959Z,1558288510.959 [controlThread ThreadHandler](DEBUG): Created PCaller Thread at 404814E0 2019-05-19T17:55:10.960Z,1558288510.960 [controlThread ThreadHandler](INFO): Protected caller Thread ID is 2569 2019-05-19T17:55:10.963Z,1558288510.963 [ComponentRegistry](DEBUG): SyncComponent "CycleStarter" handled in the control thread. 2019-05-19T17:55:10.975Z,1558288510.975 [ComponentRegistry](DEBUG): Component "CommandLine" handled in its own thread. 2019-05-19T17:55:10.976Z,1558288510.976 [CommandLine ThreadHandler](DEBUG): Created PCaller Thread at 404B14E0 2019-05-19T17:55:10.976Z,1558288510.976 [CommandLine ThreadHandler](INFO): Protected caller Thread ID is 2570 2019-05-19T17:55:10.977Z,1558288510.977 [ComponentRegistry](DEBUG): Component "logger" handled in its own thread. 2019-05-19T17:55:10.978Z,1558288510.978 [logger ThreadHandler](DEBUG): Created PCaller Thread at 404E14E0 2019-05-19T17:55:10.979Z,1558288510.979 [logger ThreadHandler](INFO): Protected caller Thread ID is 2571 2019-05-19T17:55:10.980Z,1558288510.980 [ComponentRegistry](DEBUG): SyncComponent "LogSplitter" handled in the control thread. 2019-05-19T17:55:10.981Z,1558288510.981 [Supervisor](INFO): Looking for Config files in directory: Config/ 2019-05-19T17:55:10.983Z,1558288510.983 [Supervisor](INFO): Opening Config file at: Config/Navigation.cfg 2019-05-19T17:55:11.155Z,1558288511.155 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Navigation.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:11.180Z,1558288511.180 [Supervisor](INFO): Closing pipe. Elapsed 0.024127 2019-05-19T17:55:11.181Z,1558288511.181 [Supervisor](INFO): Pipe closed. Elapsed 0.024968 2019-05-19T17:55:11.181Z,1558288511.181 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Navigation 2019-05-19T17:55:11.182Z,1558288511.182 [Supervisor](INFO): Opening Config file at: Config/Guidance.cfg 2019-05-19T17:55:11.211Z,1558288511.211 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Guidance.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:11.263Z,1558288511.263 [Supervisor](INFO): Closing pipe. Elapsed 0.051579 2019-05-19T17:55:11.263Z,1558288511.263 [Supervisor](INFO): Pipe closed. Elapsed 0.052255 2019-05-19T17:55:11.264Z,1558288511.264 [Supervisor](INFO): Opening Config file at: Config/Simulator.cfg 2019-05-19T17:55:11.659Z,1558288511.659 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Simulator.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:11.683Z,1558288511.683 [Supervisor](INFO): Closing pipe. Elapsed 0.024185 2019-05-19T17:55:11.684Z,1558288511.684 [Supervisor](INFO): Pipe closed. Elapsed 0.024878 2019-05-19T17:55:11.684Z,1558288511.684 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Simulator 2019-05-19T17:55:11.685Z,1558288511.685 [Supervisor](INFO): Opening Config file at: Config/Control.cfg 2019-05-19T17:55:11.979Z,1558288511.979 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Control.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:12.004Z,1558288512.004 [Supervisor](INFO): Closing pipe. Elapsed 0.024177 2019-05-19T17:55:12.005Z,1558288512.005 [Supervisor](INFO): Pipe closed. Elapsed 0.024864 2019-05-19T17:55:12.005Z,1558288512.005 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Control 2019-05-19T17:55:12.006Z,1558288512.006 [Supervisor](INFO): Opening Config file at: Config/secure.cfg 2019-05-19T17:55:12.043Z,1558288512.043 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/secure.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:12.102Z,1558288512.102 [Supervisor](INFO): Closing pipe. Elapsed 0.059324 2019-05-19T17:55:12.103Z,1558288512.103 [Supervisor](INFO): Pipe closed. Elapsed 0.060000 2019-05-19T17:55:12.104Z,1558288512.104 [ComponentRegistry](DEBUG): Loaded Config Component "Config/secure 2019-05-19T17:55:12.104Z,1558288512.104 [Supervisor](INFO): Opening Config file at: Config/Servo.cfg 2019-05-19T17:55:12.369Z,1558288512.369 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Servo.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:12.394Z,1558288512.394 [Supervisor](INFO): Closing pipe. Elapsed 0.023944 2019-05-19T17:55:12.394Z,1558288512.394 [Supervisor](INFO): Pipe closed. Elapsed 0.024758 2019-05-19T17:55:12.395Z,1558288512.395 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Servo 2019-05-19T17:55:12.395Z,1558288512.395 [Supervisor](INFO): Opening Config file at: Config/BIT.cfg 2019-05-19T17:55:12.563Z,1558288512.563 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/BIT.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:12.636Z,1558288512.636 [Supervisor](INFO): Closing pipe. Elapsed 0.072948 2019-05-19T17:55:12.637Z,1558288512.637 [Supervisor](INFO): Pipe closed. Elapsed 0.073638 2019-05-19T17:55:12.637Z,1558288512.637 [ComponentRegistry](DEBUG): Loaded Config Component "Config/BIT 2019-05-19T17:55:12.638Z,1558288512.638 [Supervisor](INFO): Opening Config file at: Config/vehicle.cfg 2019-05-19T17:55:13.184Z,1558288513.184 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/vehicle.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:13.208Z,1558288513.208 [Supervisor](INFO): Closing pipe. Elapsed 0.024250 2019-05-19T17:55:13.209Z,1558288513.209 [Supervisor](INFO): Pipe closed. Elapsed 0.024931 2019-05-19T17:55:13.210Z,1558288513.210 [ComponentRegistry](DEBUG): Loaded Config Component "Config/vehicle 2019-05-19T17:55:13.210Z,1558288513.210 [Supervisor](INFO): Opening Config file at: Config/workSite.cfg 2019-05-19T17:55:13.255Z,1558288513.255 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/workSite.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:13.315Z,1558288513.315 [Supervisor](INFO): Closing pipe. Elapsed 0.060258 2019-05-19T17:55:13.316Z,1558288513.316 [Supervisor](INFO): Pipe closed. Elapsed 0.060946 2019-05-19T17:55:13.317Z,1558288513.317 [ComponentRegistry](DEBUG): Loaded Config Component "Config/workSite 2019-05-19T17:55:13.317Z,1558288513.317 [Supervisor](INFO): Opening Config file at: Config/Sample.cfg 2019-05-19T17:55:13.359Z,1558288513.359 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Sample.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:13.419Z,1558288513.419 [Supervisor](INFO): Closing pipe. Elapsed 0.060385 2019-05-19T17:55:13.420Z,1558288513.420 [Supervisor](INFO): Pipe closed. Elapsed 0.061063 2019-05-19T17:55:13.420Z,1558288513.420 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sample 2019-05-19T17:55:13.421Z,1558288513.421 [Supervisor](INFO): Opening Config file at: Config/Sensor.cfg 2019-05-19T17:55:13.966Z,1558288513.966 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Sensor.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.007Z,1558288514.007 [Supervisor](INFO): Closing pipe. Elapsed 0.041305 2019-05-19T17:55:14.008Z,1558288514.008 [Supervisor](INFO): Pipe closed. Elapsed 0.041993 2019-05-19T17:55:14.009Z,1558288514.009 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Sensor 2019-05-19T17:55:14.009Z,1558288514.009 [Supervisor](INFO): Opening Config file at: Config/Science.cfg 2019-05-19T17:55:14.363Z,1558288514.363 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Science.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.387Z,1558288514.387 [Supervisor](INFO): Closing pipe. Elapsed 0.023877 2019-05-19T17:55:14.387Z,1558288514.387 [Supervisor](INFO): Pipe closed. Elapsed 0.024562 2019-05-19T17:55:14.388Z,1558288514.388 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Science 2019-05-19T17:55:14.389Z,1558288514.389 [Supervisor](INFO): Opening Config file at: Config/logger.cfg 2019-05-19T17:55:14.551Z,1558288514.551 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/logger.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.578Z,1558288514.578 [Supervisor](INFO): Closing pipe. Elapsed 0.027007 2019-05-19T17:55:14.579Z,1558288514.579 [Supervisor](INFO): Pipe closed. Elapsed 0.027695 2019-05-19T17:55:14.579Z,1558288514.579 [ComponentRegistry](DEBUG): Loaded Config Component "Config/logger 2019-05-19T17:55:14.580Z,1558288514.580 [Supervisor](INFO): Opening Config file at: Config/Estimation.cfg 2019-05-19T17:55:14.679Z,1558288514.679 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Estimation.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.725Z,1558288514.725 [Supervisor](INFO): Closing pipe. Elapsed 0.045882 2019-05-19T17:55:14.726Z,1558288514.726 [Supervisor](INFO): Pipe closed. Elapsed 0.046577 2019-05-19T17:55:14.726Z,1558288514.726 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Estimation 2019-05-19T17:55:14.727Z,1558288514.727 [Supervisor](INFO): Opening Config file at: Config/Derivation.cfg 2019-05-19T17:55:14.827Z,1558288514.827 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/;cp -r Config/Derivation.cfg Logs/20190519T175510/Config/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.875Z,1558288514.875 [Supervisor](INFO): Closing pipe. Elapsed 0.047746 2019-05-19T17:55:14.875Z,1558288514.875 [Supervisor](INFO): Pipe closed. Elapsed 0.048429 2019-05-19T17:55:14.876Z,1558288514.876 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Derivation 2019-05-19T17:55:14.878Z,1558288514.878 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/ 2019-05-19T17:55:14.879Z,1558288514.879 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Navigation.cfg 2019-05-19T17:55:14.911Z,1558288514.911 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Navigation.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:14.971Z,1558288514.971 [Supervisor](INFO): Closing pipe. Elapsed 0.059825 2019-05-19T17:55:14.972Z,1558288514.972 [Supervisor](INFO): Pipe closed. Elapsed 0.060517 2019-05-19T17:55:14.972Z,1558288514.972 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Simulator.cfg 2019-05-19T17:55:15.007Z,1558288515.007 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Simulator.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.059Z,1558288515.059 [Supervisor](INFO): Closing pipe. Elapsed 0.051975 2019-05-19T17:55:15.060Z,1558288515.060 [Supervisor](INFO): Pipe closed. Elapsed 0.052663 2019-05-19T17:55:15.060Z,1558288515.060 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Control.cfg 2019-05-19T17:55:15.103Z,1558288515.103 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Control.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.164Z,1558288515.164 [Supervisor](INFO): Closing pipe. Elapsed 0.060542 2019-05-19T17:55:15.164Z,1558288515.164 [Supervisor](INFO): Pipe closed. Elapsed 0.061294 2019-05-19T17:55:15.165Z,1558288515.165 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/secure.cfg 2019-05-19T17:55:15.199Z,1558288515.199 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/secure.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.250Z,1558288515.250 [Supervisor](INFO): Closing pipe. Elapsed 0.050725 2019-05-19T17:55:15.250Z,1558288515.250 [Supervisor](INFO): Pipe closed. Elapsed 0.051413 2019-05-19T17:55:15.251Z,1558288515.251 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Servo.cfg 2019-05-19T17:55:15.287Z,1558288515.287 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Servo.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.348Z,1558288515.348 [Supervisor](INFO): Closing pipe. Elapsed 0.060852 2019-05-19T17:55:15.349Z,1558288515.349 [Supervisor](INFO): Pipe closed. Elapsed 0.061542 2019-05-19T17:55:15.349Z,1558288515.349 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/BIT.cfg 2019-05-19T17:55:15.391Z,1558288515.391 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/BIT.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.451Z,1558288515.451 [Supervisor](INFO): Closing pipe. Elapsed 0.059614 2019-05-19T17:55:15.451Z,1558288515.451 [Supervisor](INFO): Pipe closed. Elapsed 0.060313 2019-05-19T17:55:15.452Z,1558288515.452 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/vehicle.cfg 2019-05-19T17:55:15.631Z,1558288515.631 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/vehicle.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.659Z,1558288515.659 [Supervisor](INFO): Closing pipe. Elapsed 0.027629 2019-05-19T17:55:15.659Z,1558288515.659 [Supervisor](INFO): Pipe closed. Elapsed 0.028387 2019-05-19T17:55:15.660Z,1558288515.660 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/workSite.cfg 2019-05-19T17:55:15.687Z,1558288515.687 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/workSite.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.739Z,1558288515.739 [Supervisor](INFO): Closing pipe. Elapsed 0.051601 2019-05-19T17:55:15.739Z,1558288515.739 [Supervisor](INFO): Pipe closed. Elapsed 0.052300 2019-05-19T17:55:15.740Z,1558288515.740 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Sensor.cfg 2019-05-19T17:55:15.855Z,1558288515.855 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Sensor.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:15.902Z,1558288515.902 [Supervisor](INFO): Closing pipe. Elapsed 0.047138 2019-05-19T17:55:15.903Z,1558288515.903 [Supervisor](INFO): Pipe closed. Elapsed 0.047825 2019-05-19T17:55:15.904Z,1558288515.904 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Science.cfg 2019-05-19T17:55:15.975Z,1558288515.975 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Science.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:16.035Z,1558288516.035 [Supervisor](INFO): Closing pipe. Elapsed 0.059894 2019-05-19T17:55:16.036Z,1558288516.036 [Supervisor](INFO): Pipe closed. Elapsed 0.060579 2019-05-19T17:55:16.036Z,1558288516.036 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/logger.cfg 2019-05-19T17:55:16.091Z,1558288516.091 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/logger.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:16.153Z,1558288516.153 [Supervisor](INFO): Closing pipe. Elapsed 0.061528 2019-05-19T17:55:16.153Z,1558288516.153 [Supervisor](INFO): Pipe closed. Elapsed 0.062209 2019-05-19T17:55:16.154Z,1558288516.154 [Supervisor](INFO): Opening Config file at: Config/lrauv-daphne/Battery.cfg 2019-05-19T17:55:16.355Z,1558288516.355 [Supervisor](INFO): Executing 'mkdir -p Logs/20190519T175510/Config/lrauv-daphne/;cp -r Config/lrauv-daphne/Battery.cfg Logs/20190519T175510/Config/lrauv-daphne/' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:16.380Z,1558288516.380 [Supervisor](INFO): Closing pipe. Elapsed 0.024685 2019-05-19T17:55:16.380Z,1558288516.380 [Supervisor](INFO): Pipe closed. Elapsed 0.025378 2019-05-19T17:55:16.381Z,1558288516.381 [ComponentRegistry](DEBUG): Loaded Config Component "Config/Battery 2019-05-19T17:55:16.383Z,1558288516.383 [Supervisor](INFO): Looking for Config files in directory: Config/lrauv-daphne/root/ 2019-05-19T17:55:16.383Z,1558288516.383 [Supervisor](IMPORTANT): Reading configuration overrides from Data/persisted.cfg 2019-05-19T17:55:16.398Z,1558288516.398 [Module Loader](DEBUG): Loading Module at Modules/Control.so 2019-05-19T17:55:16.483Z,1558288516.483 [VerticalControl](DEBUG): Construct VerticalControl. 2019-05-19T17:55:16.593Z,1558288516.593 [VerticalControl] Loaded 2019-05-19T17:55:16.593Z,1558288516.593 [ComponentRegistry](DEBUG): SyncComponent "VerticalControl" handled in the control thread. 2019-05-19T17:55:16.594Z,1558288516.594 [HorizontalControl](DEBUG): Construct HorizontalControl. 2019-05-19T17:55:16.663Z,1558288516.663 [HorizontalControl] Loaded 2019-05-19T17:55:16.663Z,1558288516.663 [ComponentRegistry](DEBUG): SyncComponent "HorizontalControl" handled in the control thread. 2019-05-19T17:55:16.664Z,1558288516.664 [SpeedControl](DEBUG): Construct SpeedControl. 2019-05-19T17:55:16.669Z,1558288516.669 [SpeedControl] Loaded 2019-05-19T17:55:16.670Z,1558288516.670 [ComponentRegistry](DEBUG): SyncComponent "SpeedControl" handled in the control thread. 2019-05-19T17:55:16.671Z,1558288516.671 [LoopControl](DEBUG): Construct LoopControl. 2019-05-19T17:55:16.671Z,1558288516.671 [LoopControl] Loaded 2019-05-19T17:55:16.671Z,1558288516.671 [ComponentRegistry](DEBUG): SyncComponent "LoopControl" handled in the control thread. 2019-05-19T17:55:16.672Z,1558288516.672 [Module Loader](DEBUG): Loaded Module: Control (Contains the Control components, such as Depth, Heading, and Speed Control) 2019-05-19T17:55:16.672Z,1558288516.672 [Module Loader](DEBUG): Loading Module at Modules/Sample.so 2019-05-19T17:55:16.695Z,1558288516.695 [Module Loader](DEBUG): Loaded Module: Sample (This is a Sample Module of Sample Components) 2019-05-19T17:55:16.696Z,1558288516.696 [Module Loader](DEBUG): Loading Module at Modules/Simulator.so 2019-05-19T17:55:16.793Z,1558288516.793 [Module Loader](DEBUG): Loaded Module: Simulator (This is the module containing the Simulator) 2019-05-19T17:55:16.794Z,1558288516.794 [Module Loader](DEBUG): Loading Module at Modules/Servo.so 2019-05-19T17:55:16.939Z,1558288516.939 [BuoyancyServo] Loaded 2019-05-19T17:55:16.940Z,1558288516.940 [ComponentRegistry](DEBUG): SyncComponent "BuoyancyServo" handled in the control thread. 2019-05-19T17:55:16.951Z,1558288516.951 [ElevatorServo] Loaded 2019-05-19T17:55:16.951Z,1558288516.951 [ComponentRegistry](DEBUG): SyncComponent "ElevatorServo" handled in the control thread. 2019-05-19T17:55:16.962Z,1558288516.962 [MassServo] Loaded 2019-05-19T17:55:16.962Z,1558288516.962 [ComponentRegistry](DEBUG): SyncComponent "MassServo" handled in the control thread. 2019-05-19T17:55:16.973Z,1558288516.973 [RudderServo] Loaded 2019-05-19T17:55:16.974Z,1558288516.974 [ComponentRegistry](DEBUG): SyncComponent "RudderServo" handled in the control thread. 2019-05-19T17:55:16.984Z,1558288516.984 [ThrusterServo] Loaded 2019-05-19T17:55:16.985Z,1558288516.985 [ComponentRegistry](DEBUG): SyncComponent "ThrusterServo" handled in the control thread. 2019-05-19T17:55:16.985Z,1558288516.985 [Module Loader](DEBUG): Loaded Module: Servo (This is the module containing motor controllers) 2019-05-19T17:55:16.986Z,1558288516.986 [Module Loader](DEBUG): Loading Module at Modules/Navigation.so 2019-05-19T17:55:17.109Z,1558288517.109 [DeadReckonUsingMultipleVelocitySources] Loaded 2019-05-19T17:55:17.109Z,1558288517.109 [ComponentRegistry](DEBUG): SyncComponent "DeadReckonUsingMultipleVelocitySources" handled in the control thread. 2019-05-19T17:55:17.129Z,1558288517.129 [NavChart] Loaded 2019-05-19T17:55:17.129Z,1558288517.129 [ComponentRegistry](DEBUG): SyncComponent "NavChart" handled in the control thread. 2019-05-19T17:55:17.133Z,1558288517.133 [UniversalFixResidualReporter] Loaded 2019-05-19T17:55:17.133Z,1558288517.133 [ComponentRegistry](DEBUG): SyncComponent "UniversalFixResidualReporter" handled in the control thread. 2019-05-19T17:55:17.134Z,1558288517.134 [Module Loader](DEBUG): Loaded Module: Navigation (Contains the base navigation components) 2019-05-19T17:55:17.134Z,1558288517.135 [Module Loader](DEBUG): Loading Module at Modules/Estimation.so 2019-05-19T17:55:17.243Z,1558288517.243 [Module Loader](DEBUG): Loaded Module: Estimation (Contains the base estimation components) 2019-05-19T17:55:17.244Z,1558288517.244 [Module Loader](DEBUG): Loading Module at Modules/Sensor.so 2019-05-19T17:55:17.654Z,1558288517.654 [DataOverHttps] Loaded 2019-05-19T17:55:17.655Z,1558288517.655 [ComponentRegistry](DEBUG): Component "DataOverHttps" handled in its own thread. 2019-05-19T17:55:17.656Z,1558288517.656 [DataOverHttps ThreadHandler](DEBUG): Created PCaller Thread at 4087B4E0 2019-05-19T17:55:17.656Z,1558288517.656 [DataOverHttps ThreadHandler](INFO): Protected caller Thread ID is 2653 2019-05-19T17:55:17.669Z,1558288517.669 [Depth_Keller] Loaded 2019-05-19T17:55:17.670Z,1558288517.670 [ComponentRegistry](DEBUG): SyncComponent "Depth_Keller" handled in the control thread. 2019-05-19T17:55:17.805Z,1558288517.805 [NAL9602] Loaded 2019-05-19T17:55:17.805Z,1558288517.805 [ComponentRegistry](DEBUG): SyncComponent "NAL9602" handled in the control thread. 2019-05-19T17:55:17.821Z,1558288517.821 [Onboard] Loaded 2019-05-19T17:55:17.821Z,1558288517.821 [ComponentRegistry](DEBUG): SyncComponent "Onboard" handled in the control thread. 2019-05-19T17:55:17.824Z,1558288517.824 [Radio_Surface] Loaded 2019-05-19T17:55:17.825Z,1558288517.825 [ComponentRegistry](DEBUG): Component "Radio_Surface" handled in its own thread. 2019-05-19T17:55:17.826Z,1558288517.826 [Radio_Surface ThreadHandler](DEBUG): Created PCaller Thread at 408AB4E0 2019-05-19T17:55:17.826Z,1558288517.826 [Radio_Surface ThreadHandler](INFO): Protected caller Thread ID is 2654 2019-05-19T17:55:17.956Z,1558288517.956 [DAT] Loaded 2019-05-19T17:55:17.956Z,1558288517.956 [ComponentRegistry](DEBUG): SyncComponent "DAT" handled in the control thread. 2019-05-19T17:55:17.957Z,1558288517.957 [Module Loader](DEBUG): Loaded Module: Sensor (Contains the sensor components) 2019-05-19T17:55:17.957Z,1558288517.957 [Module Loader](DEBUG): Loading Module at Modules/Derivation.so 2019-05-19T17:55:18.791Z,1558288518.791 [DepthRateCalculator] Loaded 2019-05-19T17:55:18.792Z,1558288518.792 [ComponentRegistry](DEBUG): SyncComponent "DepthRateCalculator" handled in the control thread. 2019-05-19T17:55:18.797Z,1558288518.797 [PitchRateCalculator] Loaded 2019-05-19T17:55:18.797Z,1558288518.797 [ComponentRegistry](DEBUG): SyncComponent "PitchRateCalculator" handled in the control thread. 2019-05-19T17:55:18.809Z,1558288518.809 [SpeedCalculator] Loaded 2019-05-19T17:55:18.809Z,1558288518.809 [ComponentRegistry](DEBUG): SyncComponent "SpeedCalculator" handled in the control thread. 2019-05-19T17:55:18.830Z,1558288518.830 [TempGradientCalculator] Loaded 2019-05-19T17:55:18.831Z,1558288518.831 [ComponentRegistry](DEBUG): SyncComponent "TempGradientCalculator" handled in the control thread. 2019-05-19T17:55:18.836Z,1558288518.836 [YawRateCalculator] Loaded 2019-05-19T17:55:18.836Z,1558288518.836 [ComponentRegistry](DEBUG): SyncComponent "YawRateCalculator" handled in the control thread. 2019-05-19T17:55:18.866Z,1558288518.866 [ElevatorOffsetCalculator] Loaded 2019-05-19T17:55:18.866Z,1558288518.866 [ComponentRegistry](DEBUG): SyncComponent "ElevatorOffsetCalculator" handled in the control thread. 2019-05-19T17:55:18.867Z,1558288518.867 [Module Loader](DEBUG): Loaded Module: Derivation (Contains the base derivation components) 2019-05-19T17:55:18.867Z,1558288518.867 [Module Loader](DEBUG): Loading Module at Modules/Science.so 2019-05-19T17:55:19.184Z,1558288519.184 [CTD_NeilBrown] Loaded 2019-05-19T17:55:19.184Z,1558288519.184 [ComponentRegistry](DEBUG): Component "CTD_NeilBrown" handled in its own thread. 2019-05-19T17:55:19.185Z,1558288519.185 [CTD_NeilBrown ThreadHandler](DEBUG): Created PCaller Thread at 409AD4E0 2019-05-19T17:55:19.186Z,1558288519.186 [CTD_NeilBrown ThreadHandler](INFO): Protected caller Thread ID is 2655 2019-05-19T17:55:19.215Z,1558288519.215 [ESPComponent] Loaded 2019-05-19T17:55:19.215Z,1558288519.215 [ComponentRegistry](DEBUG): SyncComponent "ESPComponent" handled in the control thread. 2019-05-19T17:55:19.230Z,1558288519.230 [PAR_Licor] Loaded 2019-05-19T17:55:19.230Z,1558288519.230 [ComponentRegistry](DEBUG): SyncComponent "PAR_Licor" handled in the control thread. 2019-05-19T17:55:19.278Z,1558288519.278 [WetLabsBB2FL] Loaded 2019-05-19T17:55:19.278Z,1558288519.278 [ComponentRegistry](DEBUG): Component "WetLabsBB2FL" handled in its own thread. 2019-05-19T17:55:19.279Z,1558288519.279 [WetLabsBB2FL ThreadHandler](DEBUG): Created PCaller Thread at 409DD4E0 2019-05-19T17:55:19.279Z,1558288519.279 [WetLabsBB2FL ThreadHandler](INFO): Protected caller Thread ID is 2656 2019-05-19T17:55:19.280Z,1558288519.280 [Module Loader](DEBUG): Loaded Module: Science (Contains the science components) 2019-05-19T17:55:19.281Z,1558288519.281 [Module Loader](DEBUG): Loading Module at Modules/Trigger.so 2019-05-19T17:55:19.321Z,1558288519.321 [Module Loader](DEBUG): Loaded Module: Trigger (Contains triggers for use in missions) 2019-05-19T17:55:19.321Z,1558288519.321 [Module Loader](DEBUG): Loading Module at Modules/Guidance.so 2019-05-19T17:55:19.650Z,1558288519.650 [Module Loader](DEBUG): Loaded Module: Guidance (Contains behaviors and commands) 2019-05-19T17:55:19.650Z,1558288519.650 [Module Loader](DEBUG): Loading Module at Modules/BIT.so 2019-05-19T17:55:19.803Z,1558288519.803 [SBIT](DEBUG): Construct Startup Built In Test. 2019-05-19T17:55:19.814Z,1558288519.814 [SBIT] Loaded 2019-05-19T17:55:19.814Z,1558288519.814 [ComponentRegistry](DEBUG): SyncComponent "SBIT" handled in the control thread. 2019-05-19T17:55:19.815Z,1558288519.815 [IBIT](DEBUG): Construct Initiated Built In Test. 2019-05-19T17:55:19.827Z,1558288519.827 [IBIT] Loaded 2019-05-19T17:55:19.827Z,1558288519.827 [ComponentRegistry](DEBUG): SyncComponent "IBIT" handled in the control thread. 2019-05-19T17:55:19.831Z,1558288519.831 [CBIT](DEBUG): Construct Continuous Built In Test. 2019-05-19T17:55:20.219Z,1558288520.219 [CBIT] Loaded 2019-05-19T17:55:20.219Z,1558288520.219 [ComponentRegistry](DEBUG): SyncComponent "CBIT" handled in the control thread. 2019-05-19T17:55:20.219Z,1558288520.219 [Module Loader](DEBUG): Loaded Module: BIT (Contains the BuiltInTest components, such as C Built In Test) 2019-05-19T17:55:20.223Z,1558288520.223 [ComponentRegistry](DEBUG): SyncComponent "MissionManager" handled in the control thread. 2019-05-19T17:55:20.224Z,1558288520.224 [ComponentRegistry](DEBUG): SyncComponent "Reporter" handled in the control thread. 2019-05-19T17:55:20.231Z,1558288520.231 [ComponentRegistry](DEBUG): Component "NavChartDb" handled in its own thread. 2019-05-19T17:55:20.232Z,1558288520.232 [NavChartDb ThreadHandler](DEBUG): Created PCaller Thread at 40ADB4E0 2019-05-19T17:55:20.233Z,1558288520.233 [NavChartDb ThreadHandler](INFO): Protected caller Thread ID is 2657 2019-05-19T17:55:20.238Z,1558288520.238 [Supervisor](INFO): Main Thread ID is 2408 2019-05-19T17:55:20.238Z,1558288520.238 [Supervisor](DEBUG): Running supervisor. 2019-05-19T17:55:20.238Z,1558288520.238 [CommandLine ThreadHandler](INFO): Handler Thread ID is 2658 2019-05-19T17:55:20.241Z,1558288520.241 [controlThread ThreadHandler](INFO): Handler Thread ID is 2659 2019-05-19T17:55:20.241Z,1558288520.241 [controlThread](DEBUG): Initializing ControlThread 2019-05-19T17:55:20.242Z,1558288520.242 [VerticalControl](DEBUG): Initialize VerticalControlComponent. 2019-05-19T17:55:20.243Z,1558288520.243 [HorizontalControl](DEBUG): Initialize HorizontalControlComponent. 2019-05-19T17:55:20.244Z,1558288520.244 [SpeedControl](DEBUG): Initialize SpeedControlComponent. 2019-05-19T17:55:20.245Z,1558288520.245 [LoopControl](DEBUG): Initialize LoopControlComponent. 2019-05-19T17:55:20.246Z,1558288520.246 [NavChart](DEBUG): Initialize NavChart Navigation. 2019-05-19T17:55:20.247Z,1558288520.247 [UniversalFixResidualReporter](DEBUG): Initializing UniversalFixResidualReporter component. 2019-05-19T17:55:20.251Z,1558288520.251 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2019-05-19T17:55:20.251Z,1558288520.251 [PitchRateCalculator](DEBUG): Initializing PitchRateCalculator. 2019-05-19T17:55:20.251Z,1558288520.251 [SpeedCalculator](DEBUG): Initializing SpeedCalculator. 2019-05-19T17:55:20.252Z,1558288520.252 [TempGradientCalculator](DEBUG): Initializing TempGradientCalculator. 2019-05-19T17:55:20.252Z,1558288520.252 [YawRateCalculator](DEBUG): Initializing YawRateCalculator. 2019-05-19T17:55:20.252Z,1558288520.252 [ElevatorOffsetCalculator](DEBUG): Initializing ElevatorOffsetCalculator. 2019-05-19T17:55:20.258Z,1558288520.258 [SBIT](INFO): Initialize SBIT Component. 2019-05-19T17:55:20.258Z,1558288520.258 [SBIT](IMPORTANT): git: 2019-05-01-10-gcab12ce 2019-05-19T17:55:20.259Z,1558288520.259 [SBIT](INFO): git hash: cab12ce958be6da2bb158d8a74bde728d70637cd 2019-05-19T17:55:20.259Z,1558288520.259 [SBIT](IMPORTANT): Kernel Release: 2.6.27.8 2019-05-19T17:55:20.260Z,1558288520.260 [SBIT](INFO): Kernel Reporting Different Version From Configuration. Kernel Expected: #2 PREEMPT Thu Jan 11 20:13:48 PST 2018 Kernel Reported: #1 PREEMPT Tue Dec 18 21:19:28 PST 2018 2019-05-19T17:55:20.261Z,1558288520.261 [SBIT](INFO): Beginning SBIT in 59.000000 seconds. 2019-05-19T17:55:20.262Z,1558288520.262 [IBIT](INFO): Initialize IBIT Component. 2019-05-19T17:55:20.263Z,1558288520.263 [CBIT](DEBUG): Initialize CBIT Component. 2019-05-19T17:55:20.264Z,1558288520.264 [logger ThreadHandler](INFO): Handler Thread ID is 2660 2019-05-19T17:55:20.274Z,1558288520.274 [CBIT](DEBUG): Initialized mux pins. 2019-05-19T17:55:20.274Z,1558288520.274 [CBIT](DEBUG): Initializing the watchdog timer. 2019-05-19T17:55:20.282Z,1558288520.282 [DataOverHttps ThreadHandler](INFO): Handler Thread ID is 2661 2019-05-19T17:55:20.283Z,1558288520.283 [DataOverHttps](DEBUG): dashIP=134.89.2.23 starts with a digit so assuming it is a numeric IP 2019-05-19T17:55:20.294Z,1558288520.294 [Radio_Surface ThreadHandler](INFO): Handler Thread ID is 2662 2019-05-19T17:55:20.298Z,1558288520.298 [CBIT](INFO): Last reboot was NOT due to watchdog timer. 2019-05-19T17:55:20.298Z,1558288520.298 [CBIT](DEBUG): Initializing heartbeat. 2019-05-19T17:55:20.306Z,1558288520.306 [CTD_NeilBrown ThreadHandler](INFO): Handler Thread ID is 2663 2019-05-19T17:55:20.307Z,1558288520.307 [CTD_NeilBrown](INFO): Powering down 2019-05-19T17:55:20.326Z,1558288520.326 [WetLabsBB2FL ThreadHandler](INFO): Handler Thread ID is 2664 2019-05-19T17:55:20.327Z,1558288520.327 [WetLabsBB2FL](INFO): Powering down 2019-05-19T17:55:20.359Z,1558288520.359 [NavChartDb ThreadHandler](INFO): Handler Thread ID is 2665 2019-05-19T17:55:20.362Z,1558288520.362 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US1WC07M.000 2019-05-19T17:55:20.362Z,1558288520.362 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US1WC07M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US2WC11M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US2WC11M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US3CA52M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US3CA52M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US4CA60M.000 2019-05-19T17:55:20.363Z,1558288520.363 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US4CA60M.000 2019-05-19T17:55:20.364Z,1558288520.364 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA50M.000 2019-05-19T17:55:20.364Z,1558288520.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA50M.000 2019-05-19T17:55:20.364Z,1558288520.364 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA61M.000 2019-05-19T17:55:20.364Z,1558288520.364 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA61M.000 2019-05-19T17:55:20.364Z,1558288520.364 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA62M.000 2019-05-19T17:55:20.365Z,1558288520.365 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA62M.000 2019-05-19T17:55:20.365Z,1558288520.365 [NavChartDb](INFO): Looking for Electronic Nav Chart file at: Resources/ElectronicNavigationCharts/US5CA83M.000 2019-05-19T17:55:20.365Z,1558288520.365 [NavChartDb](INFO): Already Loaded Electronic Nav Chart data from US5CA83M.000 2019-05-19T17:55:20.370Z,1558288520.370 [CBIT](DEBUG): Deactivating GF circuits. 2019-05-19T17:55:20.370Z,1558288520.370 [CBIT](DEBUG): Deactivating emergency mode. 2019-05-19T17:55:20.406Z,1558288520.406 [CBIT](DEBUG): Backplane powered. 2019-05-19T17:55:20.407Z,1558288520.407 [MissionManager](INFO): Loading Mission: Missions/Startup.xml 2019-05-19T17:55:20.417Z,1558288520.417 [Startup:A.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-19T17:55:20.428Z,1558288520.428 [MissionManager](DEBUG): 2019-05-19T17:55:20.429Z,1558288520.429 [MissionManager](INFO): Loading Mission: Missions/Default.xml 2019-05-19T17:55:20.500Z,1558288520.500 [MissionManager](INFO): DefineArg Default.ElapsedSinceDefaultStarted = 0.000000 min 2019-05-19T17:55:20.501Z,1558288520.501 [Default:A.Wait](DEBUG): Construct Wait. 2019-05-19T17:55:20.519Z,1558288520.519 [Default:B.GoToSurface](DEBUG): Construct GoToSurface. 2019-05-19T17:55:20.541Z,1558288520.541 [Default:CheckIn:Read_Iridium:A_Timeout:A.Execute](DEBUG): Construct Execute. 2019-05-19T17:55:20.544Z,1558288520.544 [Default:CheckIn:C.Wait](DEBUG): Construct Wait. 2019-05-19T17:55:20.573Z,1558288520.573 [Default:E.Execute](DEBUG): Construct Execute. 2019-05-19T17:55:20.576Z,1558288520.576 [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 2019-05-19T17:55:20.585Z,1558288520.585 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2019-05-19T17:55:20.698Z,1558288520.698 [Radio_Surface](INFO): Powering up 2019-05-19T17:55:20.717Z,1558288520.717 [DAT](INFO): Powered 24V power converter LCB with command: ! echo 1 > /dev/loadB2 2019-05-19T17:55:20.717Z,1558288520.717 [DAT](INFO): Powering up 2019-05-19T17:55:20.717Z,1558288520.717 [DAT](DEBUG): Initializing DAT. 2019-05-19T17:55:20.733Z,1558288520.733 [ESPComponent](INFO): powering down ESP 2019-05-19T17:55:20.742Z,1558288520.742 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadB2 2019-05-19T17:55:20.799Z,1558288520.799 [CommandLine](INFO): Executing 'echo 1 > /dev/loadB2' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:55:20.882Z,1558288520.882 [CommandLine](INFO): Closing pipe. Elapsed 0.048421 2019-05-19T17:55:20.883Z,1558288520.883 [CommandLine](INFO): Pipe closed. Elapsed 0.083488 2019-05-19T17:55:21.232Z,1558288521.232 [BuoyancyServo](DEBUG): Initializing EZServoServo. 2019-05-19T17:55:21.238Z,1558288521.238 [BuoyancyServo](DEBUG): Initializing BuoyancyServo. 2019-05-19T17:55:21.239Z,1558288521.239 [ElevatorServo](DEBUG): Initializing EZServoServo. 2019-05-19T17:55:21.246Z,1558288521.246 [ElevatorServo](DEBUG): Initializing ElevatorServo. 2019-05-19T17:55:21.247Z,1558288521.247 [MassServo](DEBUG): Initializing EZServoServo. 2019-05-19T17:55:21.254Z,1558288521.254 [MassServo](DEBUG): Initializing MassServo. 2019-05-19T17:55:21.255Z,1558288521.255 [RudderServo](DEBUG): Initializing EZServoServo. 2019-05-19T17:55:21.262Z,1558288521.262 [RudderServo](DEBUG): Initializing RudderServo. 2019-05-19T17:55:21.263Z,1558288521.263 [ThrusterServo](DEBUG): Initializing EZServoServo. 2019-05-19T17:55:21.274Z,1558288521.274 [ThrusterServo](DEBUG): Initializing ThrusterServo. 2019-05-19T17:55:33.837Z,1558288533.837 [DAT](INFO): setting local address to 2 2019-05-19T17:55:34.234Z,1558288534.234 [DAT](INFO): set local address to 2 2019-05-19T17:55:47.955Z,1558288547.955 [NAL9602](INFO): Powering up NAL9602 2019-05-19T17:55:58.860Z,1558288558.860 [NAL9602](INFO): NAL9602 initialized 2019-05-19T17:55:59.682Z,1558288559.682 [NAL9602](DEBUG): Fix Requested 2019-05-19T17:56:08.246Z,1558288568.246 [CommandLine](IMPORTANT): got command ! sleep 10 2019-05-19T17:56:08.271Z,1558288568.271 [CommandLine](INFO): Executing 'sleep 10' with timout: 5.000000 should timeout at :1558288512.000000 2019-05-19T17:56:08.370Z,1558288568.370 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.098863 2019-05-19T17:56:08.470Z,1558288568.470 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.198847 2019-05-19T17:56:08.570Z,1558288568.570 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.299332 2019-05-19T17:56:08.670Z,1558288568.670 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.398959 2019-05-19T17:56:08.770Z,1558288568.770 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.498854 2019-05-19T17:56:08.870Z,1558288568.870 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.598927 2019-05-19T17:56:08.970Z,1558288568.970 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.699097 2019-05-19T17:56:09.077Z,1558288569.077 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.806065 2019-05-19T17:56:09.174Z,1558288569.174 [CommandLine](INFO): Executing 'sleep 10' elapsed 0.902877 2019-05-19T17:56:09.274Z,1558288569.274 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.002859 2019-05-19T17:56:09.374Z,1558288569.374 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.103493 2019-05-19T17:56:09.474Z,1558288569.474 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.202867 2019-05-19T17:56:09.574Z,1558288569.574 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.302873 2019-05-19T17:56:09.674Z,1558288569.674 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.402858 2019-05-19T17:56:09.775Z,1558288569.775 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.503895 2019-05-19T17:56:09.874Z,1558288569.874 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.602856 2019-05-19T17:56:09.974Z,1558288569.974 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.702987 2019-05-19T17:56:10.074Z,1558288570.074 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.802856 2019-05-19T17:56:10.174Z,1558288570.174 [CommandLine](INFO): Executing 'sleep 10' elapsed 1.902892 2019-05-19T17:56:10.274Z,1558288570.274 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.002844 2019-05-19T17:56:10.374Z,1558288570.374 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.102849 2019-05-19T17:56:10.474Z,1558288570.474 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.202857 2019-05-19T17:56:10.574Z,1558288570.574 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.303241 2019-05-19T17:56:10.674Z,1558288570.674 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.402854 2019-05-19T17:56:10.774Z,1558288570.774 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.502848 2019-05-19T17:56:10.874Z,1558288570.874 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.602856 2019-05-19T17:56:10.974Z,1558288570.974 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.702982 2019-05-19T17:56:11.074Z,1558288571.074 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.802860 2019-05-19T17:56:11.174Z,1558288571.174 [CommandLine](INFO): Executing 'sleep 10' elapsed 2.902907 2019-05-19T17:56:11.274Z,1558288571.274 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.002859 2019-05-19T17:56:11.374Z,1558288571.374 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.102859 2019-05-19T17:56:11.474Z,1558288571.474 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.202904 2019-05-19T17:56:11.574Z,1558288571.574 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.302894 2019-05-19T17:56:11.674Z,1558288571.674 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.402919 2019-05-19T17:56:11.774Z,1558288571.774 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.502985 2019-05-19T17:56:11.874Z,1558288571.874 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.602871 2019-05-19T17:56:11.974Z,1558288571.974 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.702918 2019-05-19T17:56:12.074Z,1558288572.074 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.802840 2019-05-19T17:56:12.174Z,1558288572.174 [CommandLine](INFO): Executing 'sleep 10' elapsed 3.902886 2019-05-19T17:56:12.274Z,1558288572.274 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.002847 2019-05-19T17:56:12.374Z,1558288572.374 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.102970 2019-05-19T17:56:12.474Z,1558288572.474 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.202855 2019-05-19T17:56:12.574Z,1558288572.574 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.302921 2019-05-19T17:56:12.674Z,1558288572.674 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.402847 2019-05-19T17:56:12.774Z,1558288572.774 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.503290 2019-05-19T17:56:12.874Z,1558288572.874 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.602846 2019-05-19T17:56:12.974Z,1558288572.974 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.702852 2019-05-19T17:56:13.074Z,1558288573.074 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.802860 2019-05-19T17:56:13.174Z,1558288573.174 [CommandLine](INFO): Executing 'sleep 10' elapsed 4.902887 2019-05-19T17:56:13.274Z,1558288573.274 [CommandLine](INFO): Executing 'sleep 10' elapsed 5.002836 2019-05-19T17:56:13.274Z,1558288573.274 [CommandLine](INFO): Closing pipe. Elapsed 5.003134 2019-05-19T17:56:18.324Z,1558288578.324 [CommandLine](INFO): Pipe closed. Elapsed 10.053258 2019-05-19T17:56:18.325Z,1558288578.325 [CommandLine](FAULT): The command 'sleep 10' timed out after 10.05 seconds 2019-05-19T17:56:19.909Z,1558288579.909 [SBIT](IMPORTANT): Beginning Startup BIT 2019-05-19T17:56:19.912Z,1558288579.912 [CBIT](IMPORTANT): Beginning ground fault scan 2019-05-19T17:56:30.576Z,1558288590.576 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): -0.015947 CHAN A1 (24V): -0.016581 CHAN A2 (12V): -0.002004 CHAN A3 (5V): -0.001590 CHAN B0 (3.3V): -0.000086 CHAN B1 (3.15aV): 4.767929 CHAN B2 (3.15bV): -0.000002 CHAN B3 (GND): 4.792929 OPEN: 0.005218 Full Scale Calc: 4.765 mA, -1.589 mA 2019-05-19T17:57:13.237Z,1558288633.237 [SBIT](IMPORTANT): SBIT PASSED 2019-05-19T17:57:13.310Z,1558288633.310 [CommandLine](IMPORTANT): got command configSet list 2019-05-19T17:57:13.311Z,1558288633.311 [CommandLine](IMPORTANT): Listing configuration overrides from Data/persisted.cfg 2019-05-19T17:57:13.311Z,1558288633.311 [CommandLine](IMPORTANT): AHRS_M2.loadAtStartup=0 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): Aanderaa_O2.loadAtStartup=0 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): BPC1.batteryMissingStickThreshold=8 count; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): BPC1.batterySamplingInterval=3 hour; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): BPC1.loadAtStartup=0 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): CBIT.gf24Offset=172 microampere; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): CBIT.vehicleOpen=1 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): CTD_Seabird.loadAtStartup=0 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): DVL_micro.loadAtStartup=0 bool; 2019-05-19T17:57:13.312Z,1558288633.312 [CommandLine](IMPORTANT): DropWeight.loadAtStartup=0 bool; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): ESPComponent.loadAtStartup=1 bool; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): Express none DVL_micro.height_above_sea_floor; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): NAL9602.fastGPSFix=1 bool; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): VerticalControl.buoyancyNeutral=90 cubic_centimeter; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): VerticalControl.massDefault=-1 centimeter; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitAft=-33 millimeter; 2019-05-19T17:57:13.313Z,1558288633.313 [CommandLine](IMPORTANT): VerticalControl.massPositionLimitFwd=27 millimeter; 2019-05-19T17:57:13.631Z,1558288633.631 [MissionManager](IMPORTANT): Started mission Startup 2019-05-19T17:57:13.632Z,1558288633.632 [Startup] Running Loop=1 2019-05-19T17:57:13.632Z,1558288633.632 [Startup](DEBUG): Aggregate::initialize Startup 2019-05-19T17:57:13.632Z,1558288633.632 [Startup:A.GoToSurface] Running Loop=1 2019-05-19T17:57:13.632Z,1558288633.632 [Startup:A.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-19T17:57:13.633Z,1558288633.633 [Startup:A.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-19T17:57:13.633Z,1558288633.633 [Startup:A.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-19T17:57:13.634Z,1558288633.634 [Startup:A.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-19T17:57:13.634Z,1558288633.634 [Startup:A.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-19T17:57:13.634Z,1558288633.634 [Startup:A.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-19T17:57:13.636Z,1558288633.636 [Startup:StartupSatComms] Running Loop=1 2019-05-19T17:57:13.636Z,1558288633.636 [Startup:StartupSatComms](DEBUG): Aggregate::initialize Startup:StartupSatComms 2019-05-19T17:57:13.636Z,1558288633.636 [Startup:StartupSatComms:A] Running Loop=1 2019-05-19T17:57:14.047Z,1558288634.047 [Startup:StartupSatComms:A](DEBUG): Initialize ReadDataComponent to sense latitude_fix 2019-05-19T17:57:20.513Z,1558288640.513 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds. 2019-05-19T17:57:20.514Z,1558288640.514 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 1 2019-05-19T17:57:20.514Z,1558288640.514 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-19T17:57:20.524Z,1558288640.524 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-19T17:57:20.935Z,1558288640.935 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-19T17:57:20.935Z,1558288640.935 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 1 2019-05-19T17:57:58.960Z,1558288678.960 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.005265 2019-05-19T17:58:13.843Z,1558288693.843 [Startup:StartupSatComms:A](INFO): Timed out from 2019-05-19T17:57:13.6Z 2019-05-19T17:58:13.843Z,1558288693.843 [Startup:StartupSatComms:A] Stopped 2019-05-19T17:58:13.843Z,1558288693.843 [Startup:StartupSatComms:B] Running Loop=1 2019-05-19T17:58:14.248Z,1558288694.248 [Startup:StartupSatComms:B](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-05-19T17:58:19.969Z,1558288699.969 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190519T173405/Courier0010.lzma 2019-05-19T17:58:20.775Z,1558288700.775 [DataOverHttps](INFO): Moved sent file to Logs/20190519T173405/Courier0010.lzma.bak 2019-05-19T17:58:20.775Z,1558288700.775 [DataOverHttps](INFO): SBD MOMSN=11113934 2019-05-19T17:58:33.294Z,1558288713.294 [DataOverHttps](INFO): Sending 155 bytes from file Logs/20190519T173405/Express0011.lzma 2019-05-19T17:58:34.099Z,1558288714.099 [DataOverHttps](INFO): Moved sent file to Logs/20190519T173405/Express0011.lzma.bak 2019-05-19T17:58:34.099Z,1558288714.099 [DataOverHttps](INFO): SBD MOMSN=11113936 2019-05-19T17:58:46.651Z,1558288726.651 [DataOverHttps](INFO): Sending 1072 bytes from file Logs/20190519T175510/Express0001.lzma 2019-05-19T17:58:47.455Z,1558288727.455 [DataOverHttps](INFO): Moved sent file to Logs/20190519T175510/Express0001.lzma.bak 2019-05-19T17:58:47.455Z,1558288727.455 [DataOverHttps](INFO): SBD MOMSN=11113941 2019-05-19T17:58:50.210Z,1558288730.210 [Startup:StartupSatComms:B] Stopped 2019-05-19T17:58:50.211Z,1558288730.211 [Startup:StartupSatComms](INFO): Completed Startup:StartupSatComms 2019-05-19T17:58:50.211Z,1558288730.211 [Startup:StartupSatComms] Stopped 2019-05-19T17:58:50.211Z,1558288730.211 [Startup:StartupSatComms](DEBUG): Aggregate::uninitialize Startup:StartupSatComms 2019-05-19T17:58:50.212Z,1558288730.212 [Startup](INFO): Completed Startup 2019-05-19T17:58:50.212Z,1558288730.212 [MissionManager](INFO): Startup is completed. 2019-05-19T17:58:50.212Z,1558288730.212 [MissionManager](INFO): Uninitializing Mission Startup 2019-05-19T17:58:50.212Z,1558288730.212 [Startup] Stopped 2019-05-19T17:58:50.212Z,1558288730.212 [Startup](DEBUG): Aggregate::uninitialize Startup 2019-05-19T17:58:50.212Z,1558288730.212 [Startup:A.GoToSurface] Stopped 2019-05-19T17:58:50.212Z,1558288730.212 [Startup:A.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-05-19T17:58:50.618Z,1558288730.618 [MissionManager](IMPORTANT): Started mission Default 2019-05-19T17:58:50.619Z,1558288730.619 [Default] Running Loop=1 2019-05-19T17:58:50.619Z,1558288730.619 [Default](DEBUG): Aggregate::initialize Default 2019-05-19T17:58:50.619Z,1558288730.619 [Default:B.GoToSurface] Running Loop=1 2019-05-19T17:58:50.619Z,1558288730.619 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2019-05-19T17:58:50.619Z,1558288730.619 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2019-05-19T17:58:50.619Z,1558288730.619 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2019-05-19T17:58:50.620Z,1558288730.620 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2019-05-19T17:58:50.620Z,1558288730.620 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2019-05-19T17:58:50.620Z,1558288730.620 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2019-05-19T17:58:50.621Z,1558288730.621 [Default:A.Wait] Running Loop=1 2019-05-19T17:58:50.621Z,1558288730.621 [Default:A.Wait](DEBUG): Initialize Wait Component. 2019-05-19T17:59:03.933Z,1558288743.933 [Default:A.Wait](INFO): Done Waiting. 2019-05-19T17:59:03.933Z,1558288743.933 [Default:A.Wait] Stopped 2019-05-19T17:59:03.933Z,1558288743.933 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2019-05-19T17:59:04.340Z,1558288744.340 [Default:CheckIn] Running Loop=1 2019-05-19T17:59:04.340Z,1558288744.340 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-05-19T17:59:04.340Z,1558288744.340 [Default:CheckIn:Read_GPS] Running Loop=1 2019-05-19T17:59:04.736Z,1558288744.736 [Default:CheckIn:Read_GPS](DEBUG): Initialize ReadDataComponent to sense time_fix 2019-05-19T17:59:21.720Z,1558288761.720 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds. 2019-05-19T17:59:21.720Z,1558288761.720 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2 2019-05-19T17:59:21.720Z,1558288761.720 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-19T17:59:21.731Z,1558288761.731 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-19T17:59:22.140Z,1558288762.140 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-19T17:59:22.141Z,1558288762.141 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2 2019-05-19T18:01:02.275Z,1558288862.275 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-05-19T18:01:03.098Z,1558288863.098 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:05.926Z,1558288865.926 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:08.750Z,1558288868.750 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:11.986Z,1558288871.986 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:14.814Z,1558288874.814 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:18.042Z,1558288878.042 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:20.870Z,1558288880.870 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:22.906Z,1558288882.906 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds. 2019-05-19T18:01:22.906Z,1558288882.906 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3 2019-05-19T18:01:22.906Z,1558288882.906 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault 2019-05-19T18:01:22.916Z,1558288882.916 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources 2019-05-19T18:01:23.323Z,1558288883.323 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources 2019-05-19T18:01:23.323Z,1558288883.323 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3 2019-05-19T18:01:24.106Z,1558288884.106 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:26.933Z,1558288886.933 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:29.762Z,1558288889.762 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:32.990Z,1558288892.990 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:35.822Z,1558288895.822 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:39.054Z,1558288899.054 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:41.882Z,1558288901.882 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:45.110Z,1558288905.110 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:47.942Z,1558288907.942 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:50.766Z,1558288910.766 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:52.790Z,1558288912.790 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:54.814Z,1558288914.814 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:01:58.058Z,1558288918.058 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:00.882Z,1558288920.882 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:04.118Z,1558288924.118 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:06.942Z,1558288926.942 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:09.770Z,1558288929.770 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:11.790Z,1558288931.790 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:13.810Z,1558288933.810 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:15.830Z,1558288935.830 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:19.074Z,1558288939.074 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:21.890Z,1558288941.890 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:25.122Z,1558288945.122 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:27.950Z,1558288947.950 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:31.182Z,1558288951.182 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:34.010Z,1558288954.010 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:36.846Z,1558288956.846 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:38.858Z,1558288958.858 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:40.878Z,1558288960.878 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:44.110Z,1558288964.110 [NAL9602](DEBUG): Fix Requested 2019-05-19T18:02:46.938Z,1558288966.938 [NAL9602](DE