2018-03-07T00:26:03.214Z,1520382363.214 [CommandLine](IMPORTANT): got command restart logs 2018-03-07T00:26:18.939Z,1520382378.939 [NAL9602](INFO): SBD MO Status=2, MOMSN=5809, MT Status=2, MTMSN=0 2018-03-07T00:26:18.940Z,1520382378.940 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-03-07T00:27:38.797Z,1520382458.797 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:27:38.797Z,1520382458.797 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 14 2018-03-07T00:27:38.798Z,1520382458.798 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:27:38.810Z,1520382458.810 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:27:39.217Z,1520382459.217 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:27:39.217Z,1520382459.217 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 14 2018-03-07T00:27:39.603Z,1520382459.603 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:27:39.603Z,1520382459.603 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:27:39.603Z,1520382459.603 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:27:45.552Z,1520382465.552 [NAL9602](INFO): SBD MO Status=2, MOMSN=5809, MT Status=2, MTMSN=0 2018-03-07T00:27:45.552Z,1520382465.552 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-03-07T00:28:04.094Z,1520382484.094 [NAL9602](INFO): SBD MO Status=2, MOMSN=5809, MT Status=2, MTMSN=0 2018-03-07T00:28:04.095Z,1520382484.095 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-03-07T00:29:00.248Z,1520382540.248 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-03-07T00:23:59.9Z 2018-03-07T00:29:00.248Z,1520382540.248 [Default:CheckIn:Read_GPS] Stopped 2018-03-07T00:29:00.248Z,1520382540.248 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-03-07T00:29:04.522Z,1520382544.522 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180306T220317/Courier0084.lzma 2018-03-07T00:29:05.215Z,1520382545.215 [DataOverHttps](INFO): Moved sent file to Logs/20180306T220317/Courier0084.lzma.bak 2018-03-07T00:29:05.215Z,1520382545.215 [DataOverHttps](INFO): SBD MOMSN=7962833 2018-03-07T00:29:15.255Z,1520382555.255 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180307T002603/Courier0000.lzma 2018-03-07T00:29:16.047Z,1520382556.047 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0000.lzma.bak 2018-03-07T00:29:16.047Z,1520382556.047 [DataOverHttps](INFO): SBD MOMSN=7962835 2018-03-07T00:29:20.159Z,1520382560.159 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-03-07T00:29:25.298Z,1520382565.298 [DataOverHttps](INFO): Sending 339 bytes from file Logs/20180306T220317/Express0085.lzma 2018-03-07T00:29:26.031Z,1520382566.031 [DataOverHttps](INFO): Moved sent file to Logs/20180306T220317/Express0085.lzma.bak 2018-03-07T00:29:26.031Z,1520382566.031 [DataOverHttps](INFO): SBD MOMSN=7962838 2018-03-07T00:29:35.694Z,1520382575.694 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20180307T002603/Express0001.lzma 2018-03-07T00:29:36.424Z,1520382576.424 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Express0001.lzma.bak 2018-03-07T00:29:36.424Z,1520382576.424 [DataOverHttps](INFO): SBD MOMSN=7962853 2018-03-07T00:29:37.008Z,1520382577.008 [Default:CheckIn:Read_Iridium] Stopped 2018-03-07T00:29:37.008Z,1520382577.008 [Default:CheckIn:C.Wait] Running Loop=1 2018-03-07T00:29:37.008Z,1520382577.008 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-03-07T00:29:50.587Z,1520382590.587 [NAL9602](INFO): Powering down 2018-03-07T00:30:40.740Z,1520382640.740 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:30:40.740Z,1520382640.740 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 15 2018-03-07T00:30:40.740Z,1520382640.740 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:30:40.774Z,1520382640.774 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:30:40.953Z,1520382640.953 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:30:40.953Z,1520382640.953 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 15 2018-03-07T00:30:41.266Z,1520382641.266 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:30:41.266Z,1520382641.266 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:30:41.267Z,1520382641.267 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:33:41.347Z,1520382821.347 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:33:41.347Z,1520382821.347 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 16 2018-03-07T00:33:41.347Z,1520382821.347 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:33:41.386Z,1520382821.386 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:33:41.570Z,1520382821.570 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:33:41.571Z,1520382821.571 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 16 2018-03-07T00:33:41.895Z,1520382821.895 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:33:41.896Z,1520382821.896 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:33:41.896Z,1520382821.896 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:34:37.454Z,1520382877.454 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-03-07T00:34:37.454Z,1520382877.454 [Default:CheckIn:C.Wait] Stopped 2018-03-07T00:34:37.454Z,1520382877.454 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T00:34:37.454Z,1520382877.454 [Default:CheckIn:D] Running Loop=1 2018-03-07T00:34:37.855Z,1520382877.855 [Default:CheckIn:D] Stopped 2018-03-07T00:34:37.855Z,1520382877.855 [Default:CheckIn:E] Running Loop=1 2018-03-07T00:34:38.262Z,1520382878.262 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 172.239681 min 2018-03-07T00:34:38.262Z,1520382878.262 [Default:CheckIn:E] Stopped 2018-03-07T00:34:38.262Z,1520382878.262 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn] Stopped 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn](INFO): Running loop #25 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn] Running Loop=25 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-03-07T00:34:38.263Z,1520382878.263 [Default:CheckIn:Read_GPS] Running Loop=1 2018-03-07T00:34:41.606Z,1520382881.606 [NAL9602](INFO): Powering up 2018-03-07T00:34:48.442Z,1520382888.442 [CBIT](DEBUG): EFC running - data check-sum false 2018-03-07T00:34:52.790Z,1520382892.790 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:34:53.586Z,1520382893.586 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-03-07T00:34:53.586Z,1520382893.586 [NAL9602] Data Fault, FailCount= 4 2018-03-07T00:34:53.586Z,1520382893.586 [NAL9602](ERROR): Data Fault 2018-03-07T00:34:53.681Z,1520382893.681 [CBIT](ERROR): Data Fault in component: NAL9602 2018-03-07T00:34:53.986Z,1520382893.986 [NAL9602](INFO): Powering down 2018-03-07T00:34:54.844Z,1520382894.844 [CBIT](INFO): Clearing failed state for component NAL9602 2018-03-07T00:34:54.869Z,1520382894.869 [NAL9602] No Fault, FailCount= 4 2018-03-07T00:35:24.390Z,1520382924.390 [NAL9602](INFO): Powering up NAL9602 2018-03-07T00:35:35.590Z,1520382935.590 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:36:41.992Z,1520383001.992 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:36:41.992Z,1520383001.992 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 17 2018-03-07T00:36:41.992Z,1520383001.992 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:36:42.005Z,1520383002.005 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:36:42.186Z,1520383002.186 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:36:42.186Z,1520383002.186 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 17 2018-03-07T00:36:42.486Z,1520383002.486 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:36:42.486Z,1520383002.486 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:36:42.486Z,1520383002.486 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:37:50.599Z,1520383070.599 [NAL9602](INFO): SBD MO Status=2, MOMSN=5809, MT Status=2, MTMSN=0 2018-03-07T00:37:50.600Z,1520383070.600 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-03-07T00:39:38.446Z,1520383178.446 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-03-07T00:34:38.3Z 2018-03-07T00:39:38.446Z,1520383178.446 [Default:CheckIn:Read_GPS] Stopped 2018-03-07T00:39:38.446Z,1520383178.446 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-03-07T00:39:43.048Z,1520383183.048 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:39:43.048Z,1520383183.048 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 18 2018-03-07T00:39:43.048Z,1520383183.048 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:39:43.139Z,1520383183.139 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:39:43.167Z,1520383183.167 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180307T002603/Courier0004.lzma 2018-03-07T00:39:43.355Z,1520383183.355 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:39:43.355Z,1520383183.355 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 18 2018-03-07T00:39:43.657Z,1520383183.657 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:39:43.658Z,1520383183.658 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:39:43.658Z,1520383183.658 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:39:43.971Z,1520383183.971 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0004.lzma.bak 2018-03-07T00:39:43.971Z,1520383183.971 [DataOverHttps](INFO): SBD MOMSN=7962898 2018-03-07T00:39:54.443Z,1520383194.443 [DataOverHttps](INFO): Sending 257 bytes from file Logs/20180307T002603/Express0005.lzma 2018-03-07T00:39:55.235Z,1520383195.235 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Express0005.lzma.bak 2018-03-07T00:39:55.235Z,1520383195.235 [DataOverHttps](INFO): SBD MOMSN=7962900 2018-03-07T00:39:55.822Z,1520383195.822 [Default:CheckIn:Read_Iridium] Stopped 2018-03-07T00:39:55.822Z,1520383195.822 [Default:CheckIn:C.Wait] Running Loop=1 2018-03-07T00:39:55.822Z,1520383195.822 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-03-07T00:40:41.846Z,1520383241.846 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-03-07T00:41:12.431Z,1520383272.431 [NAL9602](INFO): Powering down 2018-03-07T00:42:43.878Z,1520383363.878 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:42:43.878Z,1520383363.878 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 19 2018-03-07T00:42:43.878Z,1520383363.878 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:42:43.890Z,1520383363.890 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:42:44.296Z,1520383364.296 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:42:44.296Z,1520383364.296 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 19 2018-03-07T00:42:44.676Z,1520383364.676 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:42:44.677Z,1520383364.677 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:42:44.677Z,1520383364.677 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:44:48.683Z,1520383488.683 [CBIT](DEBUG): EFC running - data check-sum false 2018-03-07T00:44:56.240Z,1520383496.240 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-03-07T00:44:56.240Z,1520383496.240 [Default:CheckIn:C.Wait] Stopped 2018-03-07T00:44:56.240Z,1520383496.240 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T00:44:56.241Z,1520383496.241 [Default:CheckIn:D] Running Loop=1 2018-03-07T00:44:56.644Z,1520383496.644 [Default:CheckIn:D] Stopped 2018-03-07T00:44:56.644Z,1520383496.644 [Default:CheckIn:E] Running Loop=1 2018-03-07T00:44:57.047Z,1520383497.047 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 182.552832 min 2018-03-07T00:44:57.047Z,1520383497.047 [Default:CheckIn:E] Stopped 2018-03-07T00:44:57.047Z,1520383497.047 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn] Stopped 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn](INFO): Running loop #26 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn] Running Loop=26 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-03-07T00:44:57.048Z,1520383497.048 [Default:CheckIn:Read_GPS] Running Loop=1 2018-03-07T00:45:00.418Z,1520383500.418 [NAL9602](INFO): Powering up 2018-03-07T00:45:11.582Z,1520383511.582 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:45:43.582Z,1520383543.582 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-03-07T00:45:43.665Z,1520383543.665 [NAL9602](FAULT): received: +CSQ:0 OK09, 2, 0, 0, 0 OK 2018-03-07T00:45:43.665Z,1520383543.665 [NAL9602] Data Fault, FailCount= 5 2018-03-07T00:45:43.665Z,1520383543.665 [NAL9602](ERROR): Data Fault 2018-03-07T00:45:43.796Z,1520383543.796 [CBIT](ERROR): Data Fault in component: NAL9602 2018-03-07T00:45:43.806Z,1520383543.806 [CBIT](CRITICAL): Data Fault in component: NAL9602 2018-03-07T00:45:43.994Z,1520383543.994 [NAL9602](INFO): Powering down 2018-03-07T00:45:44.086Z,1520383544.086 [CommandLine](FAULT): Scheduling is paused 2018-03-07T00:45:44.086Z,1520383544.086 [CBIT](INFO): Critical error at 20180307T004543 2018-03-07T00:45:44.828Z,1520383544.828 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:45:44.828Z,1520383544.828 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 20 2018-03-07T00:45:44.828Z,1520383544.828 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:45:44.841Z,1520383544.841 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:45:45.354Z,1520383545.354 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:45:45.354Z,1520383545.354 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 20 2018-03-07T00:45:45.707Z,1520383545.707 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:45:45.707Z,1520383545.707 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:45:45.708Z,1520383545.708 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:47:43.852Z,1520383663.852 [CBIT](INFO): Clearing failed state for component NAL9602 2018-03-07T00:47:43.852Z,1520383663.852 [NAL9602] No Fault, FailCount= 5 2018-03-07T00:47:44.150Z,1520383664.150 [NAL9602](INFO): Powering up NAL9602 2018-03-07T00:47:54.954Z,1520383674.954 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:47:55.750Z,1520383675.750 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-03-07T00:47:55.750Z,1520383675.750 [NAL9602] Data Fault, FailCount= 1 2018-03-07T00:47:55.750Z,1520383675.750 [NAL9602](ERROR): Data Fault 2018-03-07T00:47:55.840Z,1520383675.840 [CBIT](ERROR): Data Fault in component: NAL9602 2018-03-07T00:47:56.150Z,1520383676.150 [NAL9602](INFO): Powering down 2018-03-07T00:47:57.006Z,1520383677.006 [CBIT](INFO): Clearing failed state for component NAL9602 2018-03-07T00:47:57.006Z,1520383677.006 [NAL9602] No Fault, FailCount= 1 2018-03-07T00:48:26.382Z,1520383706.382 [NAL9602](INFO): Powering up NAL9602 2018-03-07T00:48:37.182Z,1520383717.182 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:48:46.108Z,1520383726.108 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:48:46.108Z,1520383726.108 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 21 2018-03-07T00:48:46.108Z,1520383726.108 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:48:46.128Z,1520383726.128 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:48:46.504Z,1520383726.504 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:48:46.504Z,1520383726.504 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 21 2018-03-07T00:48:46.859Z,1520383726.859 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:48:46.859Z,1520383726.859 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:48:46.859Z,1520383726.859 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:49:57.255Z,1520383797.255 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-03-07T00:44:57.0Z 2018-03-07T00:49:57.255Z,1520383797.255 [Default:CheckIn:Read_GPS] Stopped 2018-03-07T00:49:57.256Z,1520383797.256 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-03-07T00:50:01.773Z,1520383801.773 [DataOverHttps](INFO): Sending 92 bytes from file Logs/20180307T002603/Courier0008.lzma 2018-03-07T00:50:02.435Z,1520383802.435 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0008.lzma.bak 2018-03-07T00:50:02.435Z,1520383802.435 [DataOverHttps](INFO): SBD MOMSN=7962960 2018-03-07T00:50:12.402Z,1520383812.402 [DataOverHttps](INFO): Sending 278 bytes from file Logs/20180307T002603/Express0009.lzma 2018-03-07T00:50:13.191Z,1520383813.191 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Express0009.lzma.bak 2018-03-07T00:50:13.191Z,1520383813.191 [DataOverHttps](INFO): SBD MOMSN=7962963 2018-03-07T00:50:16.354Z,1520383816.354 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-03-07T00:50:16.407Z,1520383816.407 [Default:CheckIn:Read_Iridium] Stopped 2018-03-07T00:50:16.407Z,1520383816.407 [Default:CheckIn:C.Wait] Running Loop=1 2018-03-07T00:50:16.407Z,1520383816.407 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-03-07T00:50:46.526Z,1520383846.526 [NAL9602](INFO): Powering down 2018-03-07T00:51:47.177Z,1520383907.177 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:51:47.177Z,1520383907.177 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 22 2018-03-07T00:51:47.177Z,1520383907.177 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:51:47.202Z,1520383907.202 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:51:47.598Z,1520383907.598 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:51:47.598Z,1520383907.598 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 22 2018-03-07T00:51:47.970Z,1520383907.970 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:51:47.971Z,1520383907.971 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:51:47.971Z,1520383907.971 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:54:48.078Z,1520384088.078 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:54:48.078Z,1520384088.078 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 23 2018-03-07T00:54:48.078Z,1520384088.078 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:54:48.090Z,1520384088.090 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:54:48.509Z,1520384088.509 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:54:48.509Z,1520384088.509 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 23 2018-03-07T00:54:48.879Z,1520384088.879 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:54:48.880Z,1520384088.880 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:54:48.880Z,1520384088.880 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T00:54:48.905Z,1520384088.905 [CBIT](DEBUG): EFC running - data check-sum false 2018-03-07T00:55:16.876Z,1520384116.876 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-03-07T00:55:16.876Z,1520384116.876 [Default:CheckIn:C.Wait] Stopped 2018-03-07T00:55:16.876Z,1520384116.876 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T00:55:16.876Z,1520384116.876 [Default:CheckIn:D] Running Loop=1 2018-03-07T00:55:17.273Z,1520384117.273 [Default:CheckIn:D] Stopped 2018-03-07T00:55:17.273Z,1520384117.273 [Default:CheckIn:E] Running Loop=1 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 192.896631 min 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn:E] Stopped 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn] Stopped 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-03-07T00:55:17.682Z,1520384117.682 [Default:CheckIn](INFO): Running loop #27 2018-03-07T00:55:17.683Z,1520384117.683 [Default:CheckIn] Running Loop=27 2018-03-07T00:55:17.683Z,1520384117.683 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-03-07T00:55:17.683Z,1520384117.683 [Default:CheckIn:Read_GPS] Running Loop=1 2018-03-07T00:55:21.056Z,1520384121.056 [NAL9602](INFO): Powering up 2018-03-07T00:55:32.210Z,1520384132.210 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:56:04.206Z,1520384164.206 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-03-07T00:56:04.281Z,1520384164.281 [NAL9602](FAULT): received: +CSQ:0 OK09, 2, 0, 0, 0 OK 2018-03-07T00:56:04.281Z,1520384164.281 [NAL9602] Data Fault, FailCount= 2 2018-03-07T00:56:04.281Z,1520384164.281 [NAL9602](ERROR): Data Fault 2018-03-07T00:56:04.378Z,1520384164.378 [CBIT](ERROR): Data Fault in component: NAL9602 2018-03-07T00:56:04.615Z,1520384164.615 [NAL9602](INFO): Powering down 2018-03-07T00:56:05.493Z,1520384165.493 [CBIT](INFO): Clearing failed state for component NAL9602 2018-03-07T00:56:05.493Z,1520384165.493 [NAL9602] No Fault, FailCount= 2 2018-03-07T00:56:34.814Z,1520384194.814 [NAL9602](INFO): Powering up NAL9602 2018-03-07T00:56:46.010Z,1520384206.010 [NAL9602](INFO): NAL9602 initialized 2018-03-07T00:57:49.038Z,1520384269.038 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T00:57:49.038Z,1520384269.038 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 24 2018-03-07T00:57:49.038Z,1520384269.038 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T00:57:49.075Z,1520384269.075 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T00:57:49.460Z,1520384269.460 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T00:57:49.460Z,1520384269.460 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 24 2018-03-07T00:57:49.836Z,1520384269.836 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T00:57:49.837Z,1520384269.837 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T00:57:49.837Z,1520384269.837 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:00:17.855Z,1520384417.855 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-03-07T00:55:17.7Z 2018-03-07T01:00:17.855Z,1520384417.855 [Default:CheckIn:Read_GPS] Stopped 2018-03-07T01:00:17.855Z,1520384417.855 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-03-07T01:00:22.442Z,1520384422.442 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180307T002603/Courier0012.lzma 2018-03-07T01:00:23.227Z,1520384423.227 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0012.lzma.bak 2018-03-07T01:00:23.227Z,1520384423.227 [DataOverHttps](INFO): SBD MOMSN=7963019 2018-03-07T01:00:35.456Z,1520384435.456 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-03-07T01:00:35.842Z,1520384435.842 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20180307T002603/Express0013.lzma 2018-03-07T01:00:36.635Z,1520384436.635 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Express0013.lzma.bak 2018-03-07T01:00:36.635Z,1520384436.635 [DataOverHttps](INFO): SBD MOMSN=7963021 2018-03-07T01:00:37.234Z,1520384437.234 [Default:CheckIn:Read_Iridium] Stopped 2018-03-07T01:00:37.234Z,1520384437.234 [Default:CheckIn:C.Wait] Running Loop=1 2018-03-07T01:00:37.234Z,1520384437.234 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-03-07T01:00:50.060Z,1520384450.060 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T01:00:50.060Z,1520384450.060 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 25 2018-03-07T01:00:50.060Z,1520384450.060 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:00:50.072Z,1520384450.072 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:00:50.475Z,1520384450.475 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:00:50.475Z,1520384450.475 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 25 2018-03-07T01:00:50.861Z,1520384450.861 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:00:50.862Z,1520384450.862 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:00:50.862Z,1520384450.862 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:00:58.509Z,1520384458.509 [CommandLine](IMPORTANT): got command failComponent 2018-03-07T01:00:58.510Z,1520384458.510 [CommandLine](IMPORTANT): Failed components: 2018-03-07T01:00:58.510Z,1520384458.510 [CommandLine](IMPORTANT): No failed Components. 2018-03-07T01:01:06.022Z,1520384466.022 [NAL9602](INFO): Powering down 2018-03-07T01:01:25.948Z,1520384485.948 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1520384512.000000 second 2018-03-07T01:03:51.001Z,1520384631.001 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T01:03:51.001Z,1520384631.001 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 1 2018-03-07T01:03:51.001Z,1520384631.001 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:03:51.026Z,1520384631.026 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:03:51.411Z,1520384631.411 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:03:51.411Z,1520384631.411 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 1 2018-03-07T01:03:51.807Z,1520384631.807 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:03:51.807Z,1520384631.807 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:03:51.807Z,1520384631.807 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:04:02.434Z,1520384642.434 [CommandLine](IMPORTANT): got command get latitude 2018-03-07T01:04:02.435Z,1520384642.435 [CommandLine](IMPORTANT): latitude 21.282000 arcdeg 2018-03-07T01:04:42.911Z,1520384682.911 [DataOverHttps](IMPORTANT): SBD MTMSN=20180307T010422 2018-03-07T01:04:47.510Z,1520384687.510 [DataOverHttps](INFO): Received command:sched asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" 4zplq 1 2 2018-03-07T01:04:47.549Z,1520384687.549 [CommandLine](IMPORTANT): got command schedule asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" 4zplq 1 2.000000 2018-03-07T01:04:47.550Z,1520384687.550 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=4zplq 2018-03-07T01:04:47.551Z,1520384687.551 [CommandLine](IMPORTANT): Scheduled #5 (#1 of 2 with id='4zplq'): "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" ASAP 2018-03-07T01:04:48.299Z,1520384688.299 [DataOverHttps](IMPORTANT): SBD MTMSN=20180307T010427 2018-03-07T01:04:49.183Z,1520384689.183 [CBIT](DEBUG): EFC running - data check-sum false 2018-03-07T01:04:52.925Z,1520384692.925 [DataOverHttps](INFO): Received command:sched asap "set sample:SampleAtDepth.SettleTime 15 second;run " 4zplq 2 2 2018-03-07T01:04:52.978Z,1520384692.978 [CommandLine](IMPORTANT): got command schedule asap "set sample:SampleAtDepth.SettleTime 15 second;run " 4zplq 2 2.000000 2018-03-07T01:04:52.979Z,1520384692.979 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=4zplq 2018-03-07T01:04:52.980Z,1520384692.980 [CommandLine](IMPORTANT): Scheduled #6 (#2 of 2 with id='4zplq'): "set sample:SampleAtDepth.SettleTime 15 second;run " ASAP 2018-03-07T01:04:53.062Z,1520384693.062 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml 2018-03-07T01:04:53.063Z,1520384693.063 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml 2018-03-07T01:04:53.110Z,1520384693.110 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min 2018-03-07T01:04:53.113Z,1520384693.113 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m 2018-03-07T01:04:53.121Z,1520384693.121 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count 2018-03-07T01:04:53.128Z,1520384693.128 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min 2018-03-07T01:04:53.138Z,1520384693.138 [sample:A.Pitch](DEBUG): Construct. 2018-03-07T01:04:53.144Z,1520384693.144 [sample:B.SetSpeed](DEBUG): Construct. 2018-03-07T01:04:53.173Z,1520384693.173 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml 2018-03-07T01:04:53.276Z,1520384693.276 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m 2018-03-07T01:04:53.298Z,1520384693.298 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 30.000000 s 2018-03-07T01:04:53.305Z,1520384693.305 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h 2018-03-07T01:04:53.308Z,1520384693.308 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool 2018-03-07T01:04:53.311Z,1520384693.311 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool 2018-03-07T01:04:53.344Z,1520384693.344 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool 2018-03-07T01:04:53.381Z,1520384693.381 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min 2018-03-07T01:04:53.385Z,1520384693.385 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min 2018-03-07T01:04:53.388Z,1520384693.388 [sample:SampleAtDepth:B.Pitch](DEBUG): Construct. 2018-03-07T01:04:53.423Z,1520384693.423 [sample:SampleAtDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:04:53.427Z,1520384693.427 [sample:SampleAtDepth:D.Wait](DEBUG): Construct Wait. 2018-03-07T01:04:53.452Z,1520384693.452 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:04:53.471Z,1520384693.471 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-03-07T01:04:53.471Z,1520384693.471 [MissionManager](ERROR): Slate does not contain celsius 2018-03-07T01:04:53.475Z,1520384693.475 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:04:53.480Z,1520384693.480 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-03-07T01:04:53.480Z,1520384693.480 [MissionManager](ERROR): Slate does not contain celsius 2018-03-07T01:04:53.524Z,1520384693.524 [MissionManager](DEBUG): This mission is designed to be run in the test tank only and samples whichever sampler is installed once the vehicle reaches the target depth. How long to let the mission run. 90 Depth to sample at. 7 Number of samples to take. 1 How long to wait between samples. This starts *before* the first sample to exercise the SettleTime setting in the insert aggregate. 3 0 2018-03-07T01:04:53.525Z,1520384693.525 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml 2018-03-07T01:05:02.033Z,1520384702.033 [CommandLine](IMPORTANT): got command set sample.MissionTimeout 3.000000 hour 2018-03-07T01:05:02.034Z,1520384702.034 [CommandLine](IMPORTANT): got command set sample.Depth 3.000000 meter 2018-03-07T01:05:02.034Z,1520384702.034 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 2.000000 count 2018-03-07T01:05:02.035Z,1520384702.035 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 10.000000 second 2018-03-07T01:05:02.036Z,1520384702.036 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 3.000000 meter 2018-03-07T01:05:04.401Z,1520384704.401 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SettleTime 15.000000 second 2018-03-07T01:05:04.401Z,1520384704.401 [CommandLine](IMPORTANT): got command run 2018-03-07T01:05:04.403Z,1520384704.403 [CommandLine](IMPORTANT): Running 2018-03-07T01:05:04.567Z,1520384704.567 [Default] Stopped 2018-03-07T01:05:04.567Z,1520384704.567 [Default](DEBUG): Aggregate::uninitialize Default 2018-03-07T01:05:04.567Z,1520384704.567 [Default:B.GoToSurface] Stopped 2018-03-07T01:05:04.567Z,1520384704.567 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-03-07T01:05:04.567Z,1520384704.567 [Default:CheckIn] Stopped 2018-03-07T01:05:04.567Z,1520384704.567 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-03-07T01:05:04.567Z,1520384704.567 [Default:CheckIn:C.Wait] Stopped 2018-03-07T01:05:04.567Z,1520384704.567 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T01:05:04.568Z,1520384704.568 [MissionManager](IMPORTANT): Started mission sample 2018-03-07T01:05:04.568Z,1520384704.568 [sample] Running Loop=1 2018-03-07T01:05:04.568Z,1520384704.568 [sample](DEBUG): Aggregate::initialize sample 2018-03-07T01:05:04.568Z,1520384704.568 [sample:A.Pitch] Running Loop=1 2018-03-07T01:05:04.568Z,1520384704.568 [sample:A.Pitch](DEBUG): Initialize. 2018-03-07T01:05:04.568Z,1520384704.568 [sample:B.SetSpeed] Running Loop=1 2018-03-07T01:05:04.568Z,1520384704.568 [sample:B.SetSpeed](DEBUG): Initialize. 2018-03-07T01:05:04.568Z,1520384704.568 [sample:D] Running Loop=1 2018-03-07T01:05:04.570Z,1520384704.570 [sample:D] Stopped 2018-03-07T01:05:04.570Z,1520384704.570 [sample:E] Running Loop=1 2018-03-07T01:05:04.570Z,1520384704.570 [sample:B.SetSpeed] Running Loop=1 2018-03-07T01:05:04.587Z,1520384704.587 [sample:A.Pitch] Running Loop=1 2018-03-07T01:05:04.976Z,1520384704.976 [sample:E] Stopped 2018-03-07T01:05:04.976Z,1520384704.976 [sample:SampleRepeater] Running Loop=1 2018-03-07T01:05:04.976Z,1520384704.976 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater 2018-03-07T01:05:04.976Z,1520384704.976 [sample:SampleRepeater:Sample] Running Loop=1 2018-03-07T01:05:04.976Z,1520384704.976 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample 2018-03-07T01:05:05.369Z,1520384705.369 [sample:SampleAtDepth] Running Loop=1 2018-03-07T01:05:05.369Z,1520384705.369 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth 2018-03-07T01:05:05.370Z,1520384705.370 [sample:SampleAtDepth:B.Pitch] Running Loop=1 2018-03-07T01:05:05.370Z,1520384705.370 [sample:SampleAtDepth:B.Pitch](DEBUG): Initialize. 2018-03-07T01:05:05.370Z,1520384705.370 [sample:SampleAtDepth:A] Running Loop=1 2018-03-07T01:05:05.375Z,1520384705.375 [sample:SampleAtDepth:A](INFO): Moving to 3.000000 m 2018-03-07T01:05:05.376Z,1520384705.376 [sample:SampleAtDepth:A] Stopped 2018-03-07T01:05:09.925Z,1520384709.925 [Reporter](INFO): platform_buoyancy_position 952.311268 cc 2018-03-07T01:05:10.276Z,1520384710.276 [Reporter](INFO): platform_buoyancy_position 952.445553 cc 2018-03-07T01:05:10.660Z,1520384710.660 [Reporter](INFO): platform_buoyancy_position 952.311268 cc 2018-03-07T01:05:11.040Z,1520384711.040 [Reporter](INFO): platform_buoyancy_position 943.850318 cc 2018-03-07T01:05:11.440Z,1520384711.440 [Reporter](INFO): platform_buoyancy_position 943.447521 cc 2018-03-07T01:05:11.828Z,1520384711.828 [Reporter](INFO): platform_buoyancy_position 941.567239 cc 2018-03-07T01:05:12.263Z,1520384712.263 [Reporter](INFO): platform_buoyancy_position 937.135366 cc 2018-03-07T01:05:12.687Z,1520384712.687 [Reporter](INFO): platform_buoyancy_position 932.972063 cc 2018-03-07T01:05:13.096Z,1520384713.096 [Reporter](INFO): platform_buoyancy_position 930.688984 cc 2018-03-07T01:05:13.489Z,1520384713.489 [Reporter](INFO): platform_buoyancy_position 926.525623 cc 2018-03-07T01:05:13.848Z,1520384713.848 [Reporter](INFO): platform_buoyancy_position 924.376829 cc 2018-03-07T01:05:14.252Z,1520384714.252 [Reporter](INFO): platform_buoyancy_position 922.093750 cc 2018-03-07T01:05:14.664Z,1520384714.664 [Reporter](INFO): platform_buoyancy_position 917.796162 cc 2018-03-07T01:05:15.052Z,1520384715.052 [Reporter](INFO): platform_buoyancy_position 915.781653 cc 2018-03-07T01:05:15.464Z,1520384715.464 [Reporter](INFO): platform_buoyancy_position 911.484065 cc 2018-03-07T01:05:15.566Z,1520384715.566 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter 2018-03-07T01:05:15.567Z,1520384715.567 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread. 2018-03-07T01:05:15.828Z,1520384715.828 [Reporter](INFO): platform_buoyancy_position 909.335271 cc 2018-03-07T01:05:15.834Z,1520384715.834 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:05:16.169Z,1520384716.169 [sample:SampleAtDepth:C] Running Loop=1 2018-03-07T01:05:16.240Z,1520384716.240 [Reporter](INFO): platform_buoyancy_position 907.052134 cc 2018-03-07T01:05:16.463Z,1520384716.463 [Radio_Surface](INFO): Powering down 2018-03-07T01:05:16.586Z,1520384716.586 [sample:SampleAtDepth:C](INFO): At 3.000000 m , settling for 0.166667 min 2018-03-07T01:05:16.587Z,1520384716.587 [sample:SampleAtDepth:C] Stopped 2018-03-07T01:05:16.587Z,1520384716.587 [sample:SampleAtDepth:D.Wait] Running Loop=1 2018-03-07T01:05:16.587Z,1520384716.587 [sample:SampleAtDepth:D.Wait](DEBUG): Initialize Wait Component. 2018-03-07T01:05:16.692Z,1520384716.692 [Reporter](INFO): platform_buoyancy_position 902.754546 cc 2018-03-07T01:05:17.083Z,1520384717.083 [Reporter](INFO): platform_buoyancy_position 898.591243 cc 2018-03-07T01:05:17.230Z,1520384717.230 [CommandLine](IMPORTANT): got command get depth 2018-03-07T01:05:17.230Z,1520384717.230 [CommandLine](IMPORTANT): depth 3.000000 m 2018-03-07T01:05:17.441Z,1520384717.441 [Reporter](INFO): platform_buoyancy_position 896.308164 cc 2018-03-07T01:05:17.816Z,1520384717.816 [Reporter](INFO): platform_buoyancy_position 894.159370 cc 2018-03-07T01:05:18.247Z,1520384718.247 [Reporter](INFO): platform_buoyancy_position 889.996008 cc 2018-03-07T01:05:18.648Z,1520384718.648 [Reporter](INFO): platform_buoyancy_position 887.712929 cc 2018-03-07T01:05:19.016Z,1520384719.016 [Reporter](INFO): platform_buoyancy_position 883.415341 cc 2018-03-07T01:05:19.451Z,1520384719.451 [Reporter](INFO): platform_buoyancy_position 881.266547 cc 2018-03-07T01:05:19.852Z,1520384719.852 [Reporter](INFO): platform_buoyancy_position 876.968959 cc 2018-03-07T01:05:20.255Z,1520384720.255 [Reporter](INFO): platform_buoyancy_position 872.805656 cc 2018-03-07T01:05:20.647Z,1520384720.647 [Reporter](INFO): platform_buoyancy_position 870.522519 cc 2018-03-07T01:05:21.016Z,1520384721.016 [Reporter](INFO): platform_buoyancy_position 868.239440 cc 2018-03-07T01:05:21.456Z,1520384721.456 [Reporter](INFO): platform_buoyancy_position 864.076195 cc 2018-03-07T01:05:21.859Z,1520384721.859 [Reporter](INFO): platform_buoyancy_position 860.047119 cc 2018-03-07T01:05:22.212Z,1520384722.212 [Reporter](INFO): platform_buoyancy_position 857.629755 cc 2018-03-07T01:05:22.624Z,1520384722.624 [Reporter](INFO): platform_buoyancy_position 853.466452 cc 2018-03-07T01:05:23.071Z,1520384723.071 [Reporter](INFO): platform_buoyancy_position 849.168806 cc 2018-03-07T01:05:23.334Z,1520384723.334 [Radio_Surface](INFO): Powering up 2018-03-07T01:05:23.472Z,1520384723.472 [Reporter](INFO): platform_buoyancy_position 844.871218 cc 2018-03-07T01:05:23.782Z,1520384723.782 [CommandLine](IMPORTANT): got command report clear 2018-03-07T01:05:27.364Z,1520384727.364 [sample:SampleAtDepth:D.Wait](INFO): Done Waiting. 2018-03-07T01:05:27.364Z,1520384727.364 [sample:SampleAtDepth:D.Wait] Stopped 2018-03-07T01:05:27.364Z,1520384727.364 [sample:SampleAtDepth:D.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T01:05:27.364Z,1520384727.364 [sample:SampleAtDepth:SampleWrapper] Running Loop=1 2018-03-07T01:05:27.364Z,1520384727.364 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper 2018-03-07T01:05:27.365Z,1520384727.365 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1 2018-03-07T01:05:27.365Z,1520384727.365 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-03-07T01:05:27.365Z,1520384727.365 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1 2018-03-07T01:05:27.365Z,1520384727.365 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1 2018-03-07T01:05:27.365Z,1520384727.365 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1 2018-03-07T01:05:27.805Z,1520384727.805 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-03-07T01:05:27.806Z,1520384727.806 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1 2018-03-07T01:05:28.171Z,1520384728.171 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2018-03-07T01:05:28.998Z,1520384728.998 [Radio_Surface](INFO): Powering down 2018-03-07T01:05:31.098Z,1520384731.098 [ESPComponent](INFO): powering up ESP 2018-03-07T01:05:31.099Z,1520384731.099 [ESPComponent](INFO): manually powering up ESP 2018-03-07T01:05:31.100Z,1520384731.100 [ESPComponent](IMPORTANT): Powered ESP with command: ! echo 1 > /dev/loadA6 2018-03-07T01:05:31.101Z,1520384731.101 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.2.2:10.89.2.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 8.8.8.8 2018-03-07T01:05:31.185Z,1520384731.185 [CommandLine](IMPORTANT): got command ! echo 1 > /dev/loadA6 2018-03-07T01:05:31.333Z,1520384731.333 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2018-03-07T01:05:36.678Z,1520384736.678 [Radio_Surface](INFO): Powering up 2018-03-07T01:05:42.350Z,1520384742.350 [Radio_Surface](INFO): Powering down 2018-03-07T01:05:47.723Z,1520384747.723 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:05:47.723Z,1520384747.723 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:05:47.723Z,1520384747.723 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:05:47.723Z,1520384747.723 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:05:47.724Z,1520384747.724 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:05:47.724Z,1520384747.724 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:06:13.878Z,1520384773.878 [Radio_Surface](INFO): Powering up 2018-03-07T01:06:19.470Z,1520384779.470 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:06:19.542Z,1520384779.542 [Radio_Surface](INFO): Powering down 2018-03-07T01:06:37.459Z,1520384797.459 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:06:37.459Z,1520384797.459 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:06:37.459Z,1520384797.459 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:06:37.459Z,1520384797.459 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:06:37.460Z,1520384797.460 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:06:37.460Z,1520384797.460 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:06:51.928Z,1520384811.928 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T01:06:51.928Z,1520384811.928 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 2 2018-03-07T01:06:51.928Z,1520384811.928 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:06:51.974Z,1520384811.974 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:06:52.278Z,1520384812.278 [Radio_Surface](INFO): Powering up 2018-03-07T01:06:52.394Z,1520384812.394 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:06:52.394Z,1520384812.394 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 2 2018-03-07T01:06:52.732Z,1520384812.732 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:06:52.733Z,1520384812.733 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:06:52.734Z,1520384812.734 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:06:57.934Z,1520384817.934 [Radio_Surface](INFO): Powering down 2018-03-07T01:07:19.470Z,1520384839.470 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:07:24.102Z,1520384844.102 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:07:24.102Z,1520384844.102 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:07:24.102Z,1520384844.102 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:07:24.102Z,1520384844.102 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:07:24.103Z,1520384844.103 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:07:24.103Z,1520384844.103 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:07:31.078Z,1520384851.078 [Radio_Surface](INFO): Powering up 2018-03-07T01:07:36.734Z,1520384856.734 [Radio_Surface](INFO): Powering down 2018-03-07T01:07:53.878Z,1520384873.878 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.155472 2018-03-07T01:07:58.847Z,1520384878.847 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:07:58.847Z,1520384878.847 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:07:58.847Z,1520384878.847 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:07:58.847Z,1520384878.847 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:07:58.848Z,1520384878.848 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:07:58.848Z,1520384878.848 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:08:01.466Z,1520384881.466 [ESPComponent](CRITICAL): Timeout while waiting for ESP to connect (elapsed=150.1370) 2018-03-07T01:08:01.466Z,1520384881.466 [ESPComponent] Communications Fault, FailCount= 1 2018-03-07T01:08:01.466Z,1520384881.466 [ESPComponent](ERROR): Communications Fault 2018-03-07T01:08:01.628Z,1520384881.628 [CBIT](INFO): Critical error at 20180307T010801 2018-03-07T01:08:01.628Z,1520384881.628 [Supervisor](INFO): Stop Mission called by CBIT::checkCriticals 2018-03-07T01:08:01.631Z,1520384881.631 [CBIT](ERROR): Communications Fault in component: ESPComponent 2018-03-07T01:08:01.864Z,1520384881.864 [ESPComponent](INFO): powering down ESP 2018-03-07T01:08:02.051Z,1520384882.051 [MissionManager](INFO): MissionManager is completed. 2018-03-07T01:08:02.051Z,1520384882.051 [MissionManager](INFO): Uninitializing Mission sample 2018-03-07T01:08:02.051Z,1520384882.051 [sample] Stopped 2018-03-07T01:08:02.051Z,1520384882.051 [sample](DEBUG): Aggregate::uninitialize sample 2018-03-07T01:08:02.051Z,1520384882.051 [sample:A.Pitch] Stopped 2018-03-07T01:08:02.051Z,1520384882.051 [sample:B.SetSpeed] Stopped 2018-03-07T01:08:02.051Z,1520384882.051 [sample:B.SetSpeed](DEBUG): Uninitialize. 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth] Stopped 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:B.Pitch] Stopped 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:SampleWrapper] Stopped 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-03-07T01:08:02.052Z,1520384882.052 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped 2018-03-07T01:08:02.055Z,1520384882.055 [sample:SampleRepeater] Stopped 2018-03-07T01:08:02.055Z,1520384882.055 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater 2018-03-07T01:08:02.055Z,1520384882.055 [sample:SampleRepeater:Sample] Stopped 2018-03-07T01:08:02.055Z,1520384882.055 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample 2018-03-07T01:08:02.349Z,1520384882.349 [MissionManager](IMPORTANT): Started mission Default 2018-03-07T01:08:02.349Z,1520384882.349 [Default] Running Loop=1 2018-03-07T01:08:02.349Z,1520384882.349 [Default](DEBUG): Aggregate::initialize Default 2018-03-07T01:08:02.349Z,1520384882.349 [Default:B.GoToSurface] Running Loop=1 2018-03-07T01:08:02.349Z,1520384882.349 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-03-07T01:08:02.350Z,1520384882.350 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-03-07T01:08:02.350Z,1520384882.350 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-03-07T01:08:02.350Z,1520384882.350 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-03-07T01:08:02.351Z,1520384882.351 [Default:B.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 30.000000 seconds. 2018-03-07T01:08:02.351Z,1520384882.351 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-03-07T01:08:02.352Z,1520384882.352 [Default:A.Wait] Running Loop=1 2018-03-07T01:08:02.352Z,1520384882.352 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-03-07T01:08:02.773Z,1520384882.773 [CBIT](INFO): Clearing failed state for component ESPComponent 2018-03-07T01:08:02.773Z,1520384882.773 [ESPComponent] No Fault, FailCount= 1 2018-03-07T01:08:03.464Z,1520384883.464 [ESPComponent](INFO): powering down ESP 2018-03-07T01:08:15.705Z,1520384895.705 [Default:A.Wait](INFO): Done Waiting. 2018-03-07T01:08:15.706Z,1520384895.706 [Default:A.Wait] Stopped 2018-03-07T01:08:15.706Z,1520384895.706 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T01:08:29.667Z,1520384909.667 [Radio_Surface](INFO): Powering up 2018-03-07T01:08:32.525Z,1520384912.525 [Default:B.GoToSurface](ERROR): Pitch down timeout. Pitch: -5.42 2018-03-07T01:08:48.460Z,1520384928.460 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:08:48.460Z,1520384928.460 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:08:48.460Z,1520384928.460 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface 2018-03-07T01:09:19.650Z,1520384959.650 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:09:52.902Z,1520384992.902 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = 0.000000, longitudeAccuracy_ = 0.000000, depthAccuracy_ = nan 2018-03-07T01:09:52.902Z,1520384992.902 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 3 2018-03-07T01:09:52.902Z,1520384992.902 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:09:52.942Z,1520384992.942 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:09:53.346Z,1520384993.346 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:09:53.346Z,1520384993.346 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 3 2018-03-07T01:09:53.701Z,1520384993.701 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:09:53.701Z,1520384993.701 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:09:53.702Z,1520384993.702 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:10:03.907Z,1520385003.907 [CommandLine](IMPORTANT): got command get depth 2018-03-07T01:10:03.907Z,1520385003.907 [CommandLine](IMPORTANT): depth 3.000000 m 2018-03-07T01:10:20.050Z,1520385020.050 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:10:23.842Z,1520385023.842 [CommandLine](IMPORTANT): got command maintain clear 2018-03-07T01:10:24.161Z,1520385024.161 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:10:24.500Z,1520385024.500 [Default:CheckIn] Running Loop=1 2018-03-07T01:10:24.500Z,1520385024.500 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-03-07T01:10:24.500Z,1520385024.500 [Default:CheckIn:Read_GPS] Running Loop=1 2018-03-07T01:10:25.288Z,1520385025.288 [NAL9602](INFO): Powering up 2018-03-07T01:10:36.174Z,1520385036.174 [NAL9602](INFO): NAL9602 initialized 2018-03-07T01:10:36.974Z,1520385036.974 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-03-07T01:10:36.974Z,1520385036.974 [NAL9602] Data Fault, FailCount= 3 2018-03-07T01:10:36.974Z,1520385036.974 [NAL9602](ERROR): Data Fault 2018-03-07T01:10:37.142Z,1520385037.142 [CBIT](ERROR): Data Fault in component: NAL9602 2018-03-07T01:10:37.374Z,1520385037.374 [NAL9602](INFO): Powering down 2018-03-07T01:10:38.354Z,1520385038.354 [CBIT](INFO): Clearing failed state for component NAL9602 2018-03-07T01:10:38.354Z,1520385038.354 [NAL9602] No Fault, FailCount= 3 2018-03-07T01:10:55.196Z,1520385055.196 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.002178 2018-03-07T01:10:56.350Z,1520385056.350 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1520385024.000000 second 2018-03-07T01:10:59.603Z,1520385059.603 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:10:59.603Z,1520385059.603 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:10:59.603Z,1520385059.603 [Default](IMPORTANT): Priority 0: Default:B.GoToSurface 2018-03-07T01:10:59.603Z,1520385059.603 [Default:CheckIn](IMPORTANT): Priority 1: Default:CheckIn:Read_GPS 2018-03-07T01:11:07.598Z,1520385067.598 [NAL9602](INFO): Powering up NAL9602 2018-03-07T01:11:18.794Z,1520385078.794 [NAL9602](INFO): NAL9602 initialized 2018-03-07T01:12:54.300Z,1520385174.300 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-03-07T01:12:54.300Z,1520385174.300 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 4 2018-03-07T01:12:54.300Z,1520385174.300 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:12:54.325Z,1520385174.325 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:12:54.442Z,1520385174.442 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:12:54.442Z,1520385174.442 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 4 2018-03-07T01:12:54.799Z,1520385174.799 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:12:54.800Z,1520385174.800 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:12:54.800Z,1520385174.800 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:12:55.546Z,1520385175.546 [DataOverHttps](IMPORTANT): SBD MTMSN=20180307T011235 2018-03-07T01:12:57.054Z,1520385177.054 [CommandLine](IMPORTANT): got command set NAL9602.time_fix 1520385152.000000 second 2018-03-07T01:12:59.833Z,1520385179.833 [Default:CheckIn:Read_GPS] Stopped 2018-03-07T01:12:59.834Z,1520385179.834 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-03-07T01:12:59.912Z,1520385179.912 [DataOverHttps](INFO): Received command:sched asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" 4zpze 1 2 2018-03-07T01:12:59.966Z,1520385179.966 [CommandLine](IMPORTANT): got command schedule asap "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" 4zpze 1 2.000000 2018-03-07T01:12:59.966Z,1520385179.966 [CommandLine](IMPORTANT): Scheduling command #1 of 2 with id=4zpze 2018-03-07T01:12:59.967Z,1520385179.967 [CommandLine](IMPORTANT): Scheduled #7 (#1 of 2 with id='4zpze'): "load Maintenance/sample.xml;set sample.MissionTimeout 3 hour;set sample.Depth 3 meter;set sample.NumberOfSamples 2 count;set sample.WaitBeforeSample 10 second;set sample:SampleAtDepth.TargetDepth 3 meter" ASAP 2018-03-07T01:13:00.831Z,1520385180.831 [DataOverHttps](IMPORTANT): SBD MTMSN=20180307T011240 2018-03-07T01:13:06.782Z,1520385186.782 [DataOverHttps](INFO): Sending 225 bytes from file Logs/20180307T002603/Courier0016.lzma 2018-03-07T01:13:06.784Z,1520385186.784 [DataOverHttps](INFO): Received command:sched asap "set sample:SampleAtDepth.SettleTime 15 second;run " 4zpze 2 2 2018-03-07T01:13:06.867Z,1520385186.867 [CommandLine](IMPORTANT): got command schedule asap "set sample:SampleAtDepth.SettleTime 15 second;run " 4zpze 2 2.000000 2018-03-07T01:13:06.867Z,1520385186.867 [CommandLine](IMPORTANT): Scheduling command #2 of 2 with id=4zpze 2018-03-07T01:13:06.868Z,1520385186.868 [CommandLine](IMPORTANT): Scheduled #8 (#2 of 2 with id='4zpze'): "set sample:SampleAtDepth.SettleTime 15 second;run " ASAP 2018-03-07T01:13:06.984Z,1520385186.984 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml 2018-03-07T01:13:06.985Z,1520385186.985 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml 2018-03-07T01:13:07.022Z,1520385187.022 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min 2018-03-07T01:13:07.024Z,1520385187.024 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m 2018-03-07T01:13:07.026Z,1520385187.026 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count 2018-03-07T01:13:07.028Z,1520385187.028 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min 2018-03-07T01:13:07.029Z,1520385187.029 [sample:A.Pitch](DEBUG): Construct. 2018-03-07T01:13:07.033Z,1520385187.033 [sample:B.SetSpeed](DEBUG): Construct. 2018-03-07T01:13:07.036Z,1520385187.036 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml 2018-03-07T01:13:07.121Z,1520385187.121 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m 2018-03-07T01:13:07.123Z,1520385187.123 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 30.000000 s 2018-03-07T01:13:07.126Z,1520385187.126 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h 2018-03-07T01:13:07.128Z,1520385187.128 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool 2018-03-07T01:13:07.132Z,1520385187.132 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool 2018-03-07T01:13:07.217Z,1520385187.217 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool 2018-03-07T01:13:07.219Z,1520385187.219 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min 2018-03-07T01:13:07.222Z,1520385187.222 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min 2018-03-07T01:13:07.230Z,1520385187.230 [sample:SampleAtDepth:B.Pitch](DEBUG): Construct. 2018-03-07T01:13:07.246Z,1520385187.246 [sample:SampleAtDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:13:07.250Z,1520385187.250 [sample:SampleAtDepth:D.Wait](DEBUG): Construct Wait. 2018-03-07T01:13:07.309Z,1520385187.309 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:13:07.311Z,1520385187.311 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-03-07T01:13:07.312Z,1520385187.312 [MissionManager](ERROR): Slate does not contain celsius 2018-03-07T01:13:07.315Z,1520385187.315 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute. 2018-03-07T01:13:07.331Z,1520385187.331 [MissionManager](ERROR): Slate does not contain CTD_NeilBrown.bin_mean_sea_water_temperature 2018-03-07T01:13:07.332Z,1520385187.332 [MissionManager](ERROR): Slate does not contain celsius 2018-03-07T01:13:07.398Z,1520385187.398 [MissionManager](DEBUG): This mission is designed to be run in the test tank only and samples whichever sampler is installed once the vehicle reaches the target depth. How long to let the mission run. 90 Depth to sample at. 7 Number of samples to take. 1 How long to wait between samples. This starts *before* the first sample to exercise the SettleTime setting in the insert aggregate. 3 0 2018-03-07T01:13:07.398Z,1520385187.398 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml 2018-03-07T01:13:07.780Z,1520385187.780 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0016.lzma.bak 2018-03-07T01:13:07.780Z,1520385187.780 [DataOverHttps](INFO): SBD MOMSN=7963081 2018-03-07T01:13:18.978Z,1520385198.978 [CommandLine](IMPORTANT): got command set sample.MissionTimeout 3.000000 hour 2018-03-07T01:13:18.979Z,1520385198.979 [CommandLine](IMPORTANT): got command set sample.Depth 3.000000 meter 2018-03-07T01:13:18.979Z,1520385198.979 [CommandLine](IMPORTANT): got command set sample.NumberOfSamples 2.000000 count 2018-03-07T01:13:18.980Z,1520385198.980 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 10.000000 second 2018-03-07T01:13:18.981Z,1520385198.981 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 3.000000 meter 2018-03-07T01:13:22.539Z,1520385202.539 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.SettleTime 15.000000 second 2018-03-07T01:13:22.540Z,1520385202.540 [CommandLine](IMPORTANT): got command run 2018-03-07T01:13:22.542Z,1520385202.542 [CommandLine](IMPORTANT): Running 2018-03-07T01:13:22.670Z,1520385202.670 [Default] Stopped 2018-03-07T01:13:22.670Z,1520385202.670 [Default](DEBUG): Aggregate::uninitialize Default 2018-03-07T01:13:22.670Z,1520385202.670 [Default:B.GoToSurface] Stopped 2018-03-07T01:13:22.670Z,1520385202.670 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-03-07T01:13:22.670Z,1520385202.670 [Default:CheckIn] Stopped 2018-03-07T01:13:22.670Z,1520385202.670 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-03-07T01:13:22.670Z,1520385202.670 [Default:CheckIn:Read_Iridium] Stopped 2018-03-07T01:13:22.670Z,1520385202.670 [MissionManager](IMPORTANT): Started mission sample 2018-03-07T01:13:22.671Z,1520385202.671 [sample] Running Loop=1 2018-03-07T01:13:22.671Z,1520385202.671 [sample](DEBUG): Aggregate::initialize sample 2018-03-07T01:13:22.671Z,1520385202.671 [sample:A.Pitch] Running Loop=1 2018-03-07T01:13:22.671Z,1520385202.671 [sample:A.Pitch](DEBUG): Initialize. 2018-03-07T01:13:22.671Z,1520385202.671 [sample:B.SetSpeed] Running Loop=1 2018-03-07T01:13:22.671Z,1520385202.671 [sample:B.SetSpeed](DEBUG): Initialize. 2018-03-07T01:13:22.671Z,1520385202.671 [sample:D] Running Loop=1 2018-03-07T01:13:22.673Z,1520385202.673 [sample:D] Stopped 2018-03-07T01:13:22.673Z,1520385202.673 [sample:E] Running Loop=1 2018-03-07T01:13:22.673Z,1520385202.673 [sample:B.SetSpeed] Running Loop=1 2018-03-07T01:13:22.674Z,1520385202.674 [sample:A.Pitch] Running Loop=1 2018-03-07T01:13:22.833Z,1520385202.833 [sample:E] Stopped 2018-03-07T01:13:22.833Z,1520385202.833 [sample:SampleRepeater] Running Loop=1 2018-03-07T01:13:22.834Z,1520385202.834 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater 2018-03-07T01:13:22.834Z,1520385202.834 [sample:SampleRepeater:Sample] Running Loop=1 2018-03-07T01:13:22.834Z,1520385202.834 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample 2018-03-07T01:13:23.101Z,1520385203.101 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180307T002603/Courier0020.lzma 2018-03-07T01:13:23.178Z,1520385203.178 [sample:SampleAtDepth] Running Loop=1 2018-03-07T01:13:23.178Z,1520385203.178 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth 2018-03-07T01:13:23.178Z,1520385203.178 [sample:SampleAtDepth:B.Pitch] Running Loop=1 2018-03-07T01:13:23.178Z,1520385203.178 [sample:SampleAtDepth:B.Pitch](DEBUG): Initialize. 2018-03-07T01:13:23.178Z,1520385203.178 [sample:SampleAtDepth:A] Running Loop=1 2018-03-07T01:13:23.180Z,1520385203.180 [sample:SampleAtDepth:A](INFO): Moving to 3.000000 m 2018-03-07T01:13:23.180Z,1520385203.180 [sample:SampleAtDepth:A] Stopped 2018-03-07T01:13:23.899Z,1520385203.899 [DataOverHttps](INFO): Moved sent file to Logs/20180307T002603/Courier0020.lzma.bak 2018-03-07T01:13:23.900Z,1520385203.900 [DataOverHttps](INFO): SBD MOMSN=7963085 2018-03-07T01:13:33.739Z,1520385213.739 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 3.000000 meter 2018-03-07T01:13:33.740Z,1520385213.740 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread. 2018-03-07T01:13:33.898Z,1520385213.898 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:13:34.167Z,1520385214.167 [sample:SampleAtDepth:C] Running Loop=1 2018-03-07T01:13:34.174Z,1520385214.174 [Radio_Surface](INFO): Powering down 2018-03-07T01:13:34.578Z,1520385214.578 [sample:SampleAtDepth:C](INFO): At 3.000000 m , settling for 0.166667 min 2018-03-07T01:13:34.579Z,1520385214.579 [sample:SampleAtDepth:C] Stopped 2018-03-07T01:13:34.579Z,1520385214.579 [sample:SampleAtDepth:D.Wait] Running Loop=1 2018-03-07T01:13:34.579Z,1520385214.579 [sample:SampleAtDepth:D.Wait](DEBUG): Initialize Wait Component. 2018-03-07T01:13:44.993Z,1520385224.993 [sample:SampleAtDepth:D.Wait](INFO): Done Waiting. 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:D.Wait] Stopped 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:D.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper] Running Loop=1 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1 2018-03-07T01:13:44.994Z,1520385224.994 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1 2018-03-07T01:13:44.995Z,1520385224.995 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped 2018-03-07T01:13:45.441Z,1520385225.441 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1 2018-03-07T01:13:45.442Z,1520385225.442 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-03-07T01:13:45.442Z,1520385225.442 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1 2018-03-07T01:13:45.807Z,1520385225.807 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2018-03-07T01:13:46.913Z,1520385226.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:47.713Z,1520385227.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:48.513Z,1520385228.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:49.313Z,1520385229.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:50.113Z,1520385230.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:50.913Z,1520385230.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:51.713Z,1520385231.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:52.513Z,1520385232.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:53.313Z,1520385233.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:54.113Z,1520385234.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:54.913Z,1520385234.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:55.713Z,1520385235.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:56.513Z,1520385236.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:57.313Z,1520385237.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:58.113Z,1520385238.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:58.913Z,1520385238.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:13:59.713Z,1520385239.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:00.513Z,1520385240.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:01.313Z,1520385241.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:02.113Z,1520385242.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:02.913Z,1520385242.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:03.713Z,1520385243.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:04.513Z,1520385244.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:05.313Z,1520385245.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:06.113Z,1520385246.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:06.913Z,1520385246.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:07.330Z,1520385247.330 [Radio_Surface](INFO): Powering up 2018-03-07T01:14:07.713Z,1520385247.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:08.513Z,1520385248.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:09.313Z,1520385249.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:10.113Z,1520385250.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:10.913Z,1520385250.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:11.713Z,1520385251.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:12.513Z,1520385252.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:12.988Z,1520385252.988 [Radio_Surface](INFO): Powering down 2018-03-07T01:14:13.313Z,1520385253.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:14.113Z,1520385254.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:14.913Z,1520385254.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:15.713Z,1520385255.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:16.513Z,1520385256.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:17.313Z,1520385257.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:18.113Z,1520385258.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:18.913Z,1520385258.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:19.713Z,1520385259.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:20.513Z,1520385260.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:21.313Z,1520385261.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:22.113Z,1520385262.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:22.913Z,1520385262.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:23.713Z,1520385263.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:24.513Z,1520385264.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:25.313Z,1520385265.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:26.113Z,1520385266.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:26.913Z,1520385266.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:27.713Z,1520385267.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:28.513Z,1520385268.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:29.313Z,1520385269.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:30.113Z,1520385270.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:30.913Z,1520385270.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:31.713Z,1520385271.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:32.513Z,1520385272.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:33.313Z,1520385273.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:34.113Z,1520385274.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:34.913Z,1520385274.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:35.713Z,1520385275.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:36.513Z,1520385276.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:37.313Z,1520385277.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:38.113Z,1520385278.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:38.913Z,1520385278.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:39.713Z,1520385279.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:40.513Z,1520385280.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:41.313Z,1520385281.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:41.395Z,1520385281.395 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:14:41.395Z,1520385281.395 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:14:41.395Z,1520385281.395 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:14:41.395Z,1520385281.395 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:14:41.396Z,1520385281.396 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:14:41.396Z,1520385281.396 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:14:42.113Z,1520385282.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:42.913Z,1520385282.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:43.713Z,1520385283.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:44.513Z,1520385284.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:44.526Z,1520385284.526 [Radio_Surface](INFO): Powering up 2018-03-07T01:14:44.802Z,1520385284.802 [CommandLine](IMPORTANT): got command get depth 2018-03-07T01:14:44.802Z,1520385284.802 [CommandLine](IMPORTANT): depth 3.000000 m 2018-03-07T01:14:45.313Z,1520385285.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:46.113Z,1520385286.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:46.913Z,1520385286.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:47.713Z,1520385287.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:48.513Z,1520385288.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:49.315Z,1520385289.315 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:49.422Z,1520385289.422 [CBIT](DEBUG): EFC running - data check-sum false 2018-03-07T01:14:50.113Z,1520385290.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:50.186Z,1520385290.186 [Radio_Surface](INFO): Powering down 2018-03-07T01:14:50.913Z,1520385290.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:51.713Z,1520385291.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:52.513Z,1520385292.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:53.313Z,1520385293.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:54.113Z,1520385294.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:54.913Z,1520385294.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:54.918Z,1520385294.918 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:14:55.713Z,1520385295.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:56.513Z,1520385296.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:57.313Z,1520385297.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:58.113Z,1520385298.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:58.913Z,1520385298.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:14:59.713Z,1520385299.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:00.513Z,1520385300.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:01.313Z,1520385301.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:02.116Z,1520385302.116 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:02.913Z,1520385302.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:03.713Z,1520385303.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:04.513Z,1520385304.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:05.313Z,1520385305.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:06.113Z,1520385306.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:06.913Z,1520385306.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:07.713Z,1520385307.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:08.513Z,1520385308.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:09.313Z,1520385309.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:10.113Z,1520385310.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:10.913Z,1520385310.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:11.713Z,1520385311.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:12.513Z,1520385312.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:13.313Z,1520385313.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:14.113Z,1520385314.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:14.913Z,1520385314.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:15.713Z,1520385315.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:16.513Z,1520385316.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:17.313Z,1520385317.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:18.113Z,1520385318.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:18.913Z,1520385318.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:19.713Z,1520385319.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:20.513Z,1520385320.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:21.313Z,1520385321.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:22.113Z,1520385322.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:22.526Z,1520385322.526 [Radio_Surface](INFO): Powering up 2018-03-07T01:15:22.913Z,1520385322.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:23.713Z,1520385323.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:24.513Z,1520385324.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:25.313Z,1520385325.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:26.113Z,1520385326.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:26.913Z,1520385326.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:27.713Z,1520385327.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:28.182Z,1520385328.182 [Radio_Surface](INFO): Powering down 2018-03-07T01:15:28.513Z,1520385328.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:29.313Z,1520385329.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:30.113Z,1520385330.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:30.913Z,1520385330.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:31.713Z,1520385331.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:32.514Z,1520385332.514 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:33.313Z,1520385333.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:34.113Z,1520385334.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:34.913Z,1520385334.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:35.713Z,1520385335.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:36.513Z,1520385336.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:37.313Z,1520385337.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:38.113Z,1520385338.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:38.913Z,1520385338.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:39.713Z,1520385339.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:40.515Z,1520385340.515 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:41.314Z,1520385341.314 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:42.113Z,1520385342.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:42.913Z,1520385342.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:43.713Z,1520385343.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:44.513Z,1520385344.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:45.313Z,1520385345.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:46.113Z,1520385346.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:46.913Z,1520385346.913 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:47.713Z,1520385347.713 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:48.139Z,1520385348.139 [CommandLine](IMPORTANT): got command show stack 2018-03-07T01:15:48.140Z,1520385348.140 [CommandLine](IMPORTANT): Behavior Stack: 2018-03-07T01:15:48.140Z,1520385348.140 [sample](IMPORTANT): Priority 0: sample:A.Pitch 2018-03-07T01:15:48.140Z,1520385348.140 [sample](IMPORTANT): Priority 1: sample:B.SetSpeed 2018-03-07T01:15:48.141Z,1520385348.141 [sample:SampleAtDepth](IMPORTANT): Priority 2: sample:SampleAtDepth:B.Pitch 2018-03-07T01:15:48.141Z,1520385348.141 [sample:SampleAtDepth:SampleWrapper:SampleESP](IMPORTANT): Priority 3: sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP 2018-03-07T01:15:48.513Z,1520385348.513 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:49.313Z,1520385349.313 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:49.818Z,1520385349.818 [CommandLine](IMPORTANT): got command stop 2018-03-07T01:15:49.818Z,1520385349.818 [CommandLine](IMPORTANT): Scheduling is paused 2018-03-07T01:15:49.818Z,1520385349.818 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop 2018-03-07T01:15:50.113Z,1520385350.113 [ESPComponent](DEBUG): Error in ESPComm::open: cannot open socket port 2018-03-07T01:15:50.189Z,1520385350.189 [MissionManager](INFO): MissionManager is completed. 2018-03-07T01:15:50.189Z,1520385350.189 [MissionManager](INFO): Uninitializing Mission sample 2018-03-07T01:15:50.189Z,1520385350.189 [sample] Stopped 2018-03-07T01:15:50.189Z,1520385350.189 [sample](DEBUG): Aggregate::uninitialize sample 2018-03-07T01:15:50.189Z,1520385350.189 [sample:A.Pitch] Stopped 2018-03-07T01:15:50.189Z,1520385350.189 [sample:B.SetSpeed] Stopped 2018-03-07T01:15:50.189Z,1520385350.189 [sample:B.SetSpeed](DEBUG): Uninitialize. 2018-03-07T01:15:50.189Z,1520385350.189 [sample:SampleAtDepth] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:B.Pitch] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:SampleWrapper] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleRepeater] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleRepeater:Sample] Stopped 2018-03-07T01:15:50.190Z,1520385350.190 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample 2018-03-07T01:15:50.585Z,1520385350.585 [MissionManager](IMPORTANT): Started mission Default 2018-03-07T01:15:50.585Z,1520385350.585 [Default] Running Loop=1 2018-03-07T01:15:50.585Z,1520385350.585 [Default](DEBUG): Aggregate::initialize Default 2018-03-07T01:15:50.585Z,1520385350.585 [Default:B.GoToSurface] Running Loop=1 2018-03-07T01:15:50.586Z,1520385350.586 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2018-03-07T01:15:50.586Z,1520385350.586 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2018-03-07T01:15:50.586Z,1520385350.586 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2018-03-07T01:15:50.586Z,1520385350.586 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2018-03-07T01:15:50.587Z,1520385350.587 [Default:B.GoToSurface](DEBUG): No pitch timeout specified. Using default value of 30.000000 seconds. 2018-03-07T01:15:50.587Z,1520385350.587 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2018-03-07T01:15:50.588Z,1520385350.588 [Default:A.Wait] Running Loop=1 2018-03-07T01:15:50.588Z,1520385350.588 [Default:A.Wait](DEBUG): Initialize Wait Component. 2018-03-07T01:15:50.912Z,1520385350.912 [ESPComponent](INFO): powering down ESP 2018-03-07T01:15:54.645Z,1520385354.645 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-03-07T01:15:55.092Z,1520385355.092 [DeadReckonWithRespectToSeafloor](ERROR): Will not write estimated position: latitudeAccuracy_ = nan, longitudeAccuracy_ = nan, depthAccuracy_ = nan 2018-03-07T01:15:55.092Z,1520385355.092 [DeadReckonWithRespectToSeafloor] Software Fault, FailCount= 5 2018-03-07T01:15:55.092Z,1520385355.092 [DeadReckonWithRespectToSeafloor](ERROR): Software Fault 2018-03-07T01:15:55.193Z,1520385355.193 [CBIT](ERROR): Software Fault in component: DeadReckonWithRespectToSeafloor 2018-03-07T01:15:55.573Z,1520385355.573 [CBIT](INFO): Clearing failed state for component DeadReckonWithRespectToSeafloor 2018-03-07T01:15:55.573Z,1520385355.573 [DeadReckonWithRespectToSeafloor] No Fault, FailCount= 5 2018-03-07T01:15:55.896Z,1520385355.896 [DeadReckonWithRespectToSeafloor](DEBUG): Initializing DeadReckonWithRespectToSeafloor component. 2018-03-07T01:15:55.896Z,1520385355.896 [DeadReckonWithRespectToSeafloor](INFO): Will consider orientation measurement stale after 120s. 2018-03-07T01:15:55.897Z,1520385355.897 [DeadReckonWithRespectToSeafloor](INFO): Will consider velocity measurement stale after 20s. 2018-03-07T01:15:57.369Z,1520385357.369 [CommandLine](IMPORTANT): got command maintain clear 2018-03-07T01:15:57.625Z,1520385357.625 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:15:58.094Z,1520385358.094 [Radio_Surface](INFO): Powering up 2018-03-07T01:16:03.889Z,1520385363.889 [Default:A.Wait](INFO): Done Waiting. 2018-03-07T01:16:03.889Z,1520385363.889 [Default:A.Wait] Stopped 2018-03-07T01:16:03.889Z,1520385363.889 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2018-03-07T01:16:04.306Z,1520385364.306 [Default:CheckIn] Running Loop=1 2018-03-07T01:16:04.306Z,1520385364.306 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-03-07T01:16:04.306Z,1520385364.306 [Default:CheckIn:Read_GPS] Running Loop=1 2018-03-07T01:16:22.238Z,1520385382.238 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-03-07T01:16:29.038Z,1520385389.038 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.123749 2018-03-07T01:17:46.823Z,1520385466.823 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 21.282000 degree 2018-03-07T01:17:46.824Z,1520385466.824 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.latitude_fix" handled in the control thread. 2018-03-07T01:17:46.824Z,1520385466.824 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -157.897995 2018-03-07T01:17:46.825Z,1520385466.825 [CommandLine](FAULT): Incomplete syntax. Try: help maintain 2018-03-07T01:17:47.144Z,1520385467.144 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:17:51.407Z,1520385471.407 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.latitude_fix 21.282000 degree 2018-03-07T01:17:51.408Z,1520385471.408 [CommandLine](IMPORTANT): got command maintain sensor NAL9602.longitude_fix -157.897995 degree 2018-03-07T01:17:51.409Z,1520385471.409 [ComponentRegistry](DEBUG): SyncComponent "Maintain_NAL9602.longitude_fix" handled in the control thread. 2018-03-07T01:17:51.544Z,1520385471.544 [controlThread](DEBUG): Component order: CycleStarter,Aanderaa_O2,ESPComponent,PAR_Licor,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,DAT,PNI_TCM,BPC1,PAR_Licor,Depth_Keller,Maintain_NAL9602.latitude_fix,Maintain_NAL9602.longitude_fix,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,StratificationFrontDetector,DeadReckonUsingMultipleVelocitySources,DeadReckonUsingSpeedCalculator,DeadReckonWithRespectToSeafloor,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-03-07T01:17:54.638Z,1520385474.638 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting.