2019-11-14T23:46:19.853Z,1573775179.853 [CommandLine](IMPORTANT): got command restart logs 2019-11-14T23:46:20.904Z,1573775180.904 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,234619.00,A,3648.51866,N,12149.46960,W,0.136,162.00,141119,,,A*7C 2019-11-14T23:46:20.907Z,1573775180.907 [NAL9602](INFO): GPS fix at 20191114T234619: (36.808644, -121.824493) 2019-11-14T23:46:20.963Z,1573775180.963 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T23:46:20.963Z,1573775180.963 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T23:46:21.359Z,1573775181.359 [Default:CheckIn:Read_Iridium](DEBUG): Initialize ReadDataComponent to sense platform_communications 2019-11-14T23:46:24.626Z,1573775184.626 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T23:46:53.293Z,1573775213.293 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-14T23:48:00.325Z,1573775280.325 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004804 2019-11-14T23:48:01.624Z,1573775281.624 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-14T23:48:01.631Z,1573775281.631 [BPC1](INFO): Received data from all battery sticks. 2019-11-14T23:48:08.091Z,1573775288.091 [DataOverHttps](INFO): Sending 426 bytes from file Logs/20191114T225812/Express0019.lzma 2019-11-14T23:48:10.097Z,1573775290.097 [DataOverHttps](INFO): Moved sent file to Logs/20191114T225812/Express0019.lzma.bak 2019-11-14T23:48:10.097Z,1573775290.097 [DataOverHttps](INFO): SBD MOMSN=12065100 2019-11-14T23:48:27.792Z,1573775307.792 [DataOverHttps](INFO): Sending 1258 bytes from file Logs/20191114T234027/Express0001.lzma 2019-11-14T23:48:29.796Z,1573775309.796 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234027/Express0001.lzma.bak 2019-11-14T23:48:29.797Z,1573775309.797 [DataOverHttps](INFO): SBD MOMSN=12065104 2019-11-14T23:48:47.551Z,1573775327.551 [DataOverHttps](INFO): Sending 297 bytes from file Logs/20191114T234027/Express0005.lzma 2019-11-14T23:48:49.561Z,1573775329.561 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234027/Express0005.lzma.bak 2019-11-14T23:48:49.561Z,1573775329.561 [DataOverHttps](INFO): SBD MOMSN=12065136 2019-11-14T23:48:51.324Z,1573775331.324 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T23:48:51.324Z,1573775331.324 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T23:48:51.324Z,1573775331.324 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T23:50:39.983Z,1573775439.983 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T23:50:39.984Z,1573775439.984 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T23:51:00.604Z,1573775460.604 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T23:51:00.605Z,1573775460.605 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,-32768-32768,-32768,-32768,V 2019-11-14T23:51:04.625Z,1573775464.625 [RDI_Pathfinder](ERROR): Failed to parse: :R, 0.00, 0.00, 0.00, 0.00 2019-11-14T23:51:40.597Z,1573775500.597 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T23:51:40.597Z,1573775500.597 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T23:52:20.977Z,1573775540.977 [RDI_Pathfinder](ERROR): Failed to parse: :BI,-32768,-32768,-32768,-32768,V 2019-11-14T23:53:51.911Z,1573775631.911 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-14T23:53:51.911Z,1573775631.911 [Default:CheckIn:C.Wait] Stopped 2019-11-14T23:53:51.911Z,1573775631.911 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-14T23:53:51.911Z,1573775631.911 [Default:CheckIn:D] Running Loop=1 2019-11-14T23:53:52.325Z,1573775632.325 [Default:CheckIn:D] Stopped 2019-11-14T23:53:52.325Z,1573775632.325 [Default:CheckIn:E] Running Loop=1 2019-11-14T23:53:52.720Z,1573775632.720 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 9.758727 min 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn:E] Stopped 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn] Stopped 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn](INFO): Running loop #2 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn] Running Loop=2 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-14T23:53:52.721Z,1573775632.721 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-14T23:53:54.716Z,1573775634.716 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,235353.00,A,3648.53480,N,12149.33270,W,10.633,106.69,141119,,,D*43 2019-11-14T23:53:54.718Z,1573775634.718 [NAL9602](INFO): GPS fix at 20191114T235353: (36.808913, -121.822212) 2019-11-14T23:53:54.765Z,1573775634.765 [Default:CheckIn:Read_GPS] Stopped 2019-11-14T23:53:54.765Z,1573775634.765 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-14T23:54:03.620Z,1573775643.620 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T23:54:03.621Z,1573775643.621 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111417055820,.1, 0.0,1448.9, 0 2019-11-14T23:54:07.676Z,1573775647.676 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2019-11-14T23:54:12.696Z,1573775652.696 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.915798 2019-11-14T23:54:22.623Z,1573775662.623 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-14T23:54:22.623Z,1573775662.623 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111417061720,.1, 0.0,1448.9, 0 2019-11-14T23:55:04.319Z,1573775704.319 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-11-14T23:55:04.319Z,1573775704.319 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-11-14T23:55:04.319Z,1573775704.319 [RDI_Pathfinder](ERROR): Communications Fault 2019-11-14T23:55:04.320Z,1573775704.320 [RDI_Pathfinder](ERROR): Failed to parse: 2019-11-14T23:55:04.418Z,1573775704.418 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-11-14T23:55:04.699Z,1573775704.699 [RDI_Pathfinder](INFO): Powering down 2019-11-14T23:55:05.469Z,1573775705.469 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-11-14T23:55:05.469Z,1573775705.469 [RDI_Pathfinder] No Fault, FailCount= 1 2019-11-14T23:55:18.767Z,1573775718.767 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-11-14T23:55:28.078Z,1573775728.078 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-14T23:55:28.078Z,1573775728.078 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-2768,V 2019-11-14T23:55:36.926Z,1573775736.926 [NAL9602](INFO): SBD MO Status=2, MOMSN=9949, MT Status=2, MTMSN=0 2019-11-14T23:55:36.927Z,1573775736.927 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T23:55:37.844Z,1573775737.844 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003486 2019-11-14T23:56:14.120Z,1573775774.120 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T23:56:21.475Z,1573775781.475 [DataOverHttps](INFO): Sending 301 bytes from file Logs/20191114T234619/Courier0003.lzma 2019-11-14T23:56:23.481Z,1573775783.481 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0003.lzma.bak 2019-11-14T23:56:23.481Z,1573775783.481 [DataOverHttps](INFO): SBD MOMSN=12065150 2019-11-14T23:56:27.442Z,1573775787.442 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T23:56:31.462Z,1573775791.462 [NAL9602](INFO): SBD MO Status=2, MOMSN=9949, MT Status=2, MTMSN=0 2019-11-14T23:56:31.462Z,1573775791.462 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-14T23:56:55.619Z,1573775815.619 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2019-11-14T23:57:16.272Z,1573775836.272 [DataOverHttps](INFO): Sending 638 bytes from file Logs/20191114T234619/Express0004.lzma 2019-11-14T23:57:18.276Z,1573775838.276 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0004.lzma.bak 2019-11-14T23:57:18.277Z,1573775838.277 [DataOverHttps](INFO): SBD MOMSN=12065154 2019-11-14T23:57:19.991Z,1573775839.991 [Default:CheckIn:Read_Iridium] Stopped 2019-11-14T23:57:19.991Z,1573775839.991 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-14T23:57:19.991Z,1573775839.991 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-14T23:57:32.090Z,1573775852.090 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-14T23:57:32.090Z,1573775852.090 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-14T23:57:34.118Z,1573775854.118 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-14T23:57:40.554Z,1573775860.554 [NAL9602](INFO): SBD MO Status=0, MOMSN=9949, MT Status=0, MTMSN=0 2019-11-14T23:57:40.554Z,1573775860.554 [NAL9602](INFO): No messages in MT queue 2019-11-14T23:58:11.257Z,1573775891.257 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:02:20.563Z,1573776140.563 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:02:20.563Z,1573776140.563 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:02:20.563Z,1573776140.563 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:02:20.563Z,1573776140.563 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:02:20.987Z,1573776140.987 [Default:CheckIn:D] Stopped 2019-11-15T00:02:20.987Z,1573776140.987 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.236436 min 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn:E] Stopped 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn] Stopped 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn](INFO): Running loop #3 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn] Running Loop=3 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:02:21.392Z,1573776141.392 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:02:23.366Z,1573776143.366 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000221.00,A,3648.29434,N,12147.12981,W,3.888,178.09,151119,,,D*7B 2019-11-15T00:02:23.368Z,1573776143.368 [NAL9602](INFO): GPS fix at 20191115T000221: (36.804906, -121.785497) 2019-11-15T00:02:23.393Z,1573776143.393 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:02:23.393Z,1573776143.393 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:02:32.974Z,1573776152.974 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20191114T234619/Courier0006.lzma 2019-11-15T00:02:33.481Z,1573776153.481 [NAL9602](INFO): SBD MO Status=0, MOMSN=9950, MT Status=0, MTMSN=0 2019-11-15T00:02:33.481Z,1573776153.481 [NAL9602](INFO): No messages in MT queue 2019-11-15T00:02:34.980Z,1573776154.980 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0006.lzma.bak 2019-11-15T00:02:34.981Z,1573776154.981 [DataOverHttps](INFO): SBD MOMSN=12065161 2019-11-15T00:02:55.823Z,1573776175.823 [DataOverHttps](INFO): Sending 274 bytes from file Logs/20191114T234619/Express0007.lzma 2019-11-15T00:02:57.828Z,1573776177.828 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0007.lzma.bak 2019-11-15T00:02:57.829Z,1573776177.829 [DataOverHttps](INFO): SBD MOMSN=12065164 2019-11-15T00:02:59.774Z,1573776179.774 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:02:59.775Z,1573776179.775 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:02:59.775Z,1573776179.775 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:03:04.173Z,1573776184.173 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:08:00.367Z,1573776480.367 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:08:00.367Z,1573776480.367 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:08:00.367Z,1573776480.367 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:08:00.367Z,1573776480.367 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:08:00.761Z,1573776480.761 [Default:CheckIn:D] Stopped 2019-11-15T00:08:00.761Z,1573776480.761 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.899327 min 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn:E] Stopped 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn] Stopped 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:08:01.164Z,1573776481.164 [Default:CheckIn](INFO): Running loop #4 2019-11-15T00:08:01.165Z,1573776481.165 [Default:CheckIn] Running Loop=4 2019-11-15T00:08:01.165Z,1573776481.165 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:08:01.165Z,1573776481.165 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:08:03.151Z,1573776483.151 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,000801.00,A,3648.12125,N,12147.23015,W,0.194,294.98,151119,,,D*76 2019-11-15T00:08:03.153Z,1573776483.153 [NAL9602](INFO): GPS fix at 20191115T000801: (36.802021, -121.787169) 2019-11-15T00:08:03.194Z,1573776483.194 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:08:03.194Z,1573776483.194 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:08:14.010Z,1573776494.010 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191114T234619/Courier0009.lzma 2019-11-15T00:08:16.016Z,1573776496.016 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0009.lzma.bak 2019-11-15T00:08:16.017Z,1573776496.017 [DataOverHttps](INFO): SBD MOMSN=12065180 2019-11-15T00:08:29.417Z,1573776509.417 [NAL9602](INFO): SBD MO Status=2, MOMSN=9951, MT Status=2, MTMSN=0 2019-11-15T00:08:29.418Z,1573776509.418 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-15T00:08:35.623Z,1573776515.623 [DataOverHttps](INFO): Sending 210 bytes from file Logs/20191114T234619/Express0010.lzma 2019-11-15T00:08:37.629Z,1573776517.629 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0010.lzma.bak 2019-11-15T00:08:37.629Z,1573776517.629 [DataOverHttps](INFO): SBD MOMSN=12065183 2019-11-15T00:08:39.965Z,1573776519.965 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:08:39.965Z,1573776519.965 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:08:39.965Z,1573776519.965 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:08:54.462Z,1573776534.462 [NAL9602](INFO): SBD MO Status=0, MOMSN=9951, MT Status=0, MTMSN=0 2019-11-15T00:08:54.462Z,1573776534.462 [NAL9602](INFO): No messages in MT queue 2019-11-15T00:09:25.161Z,1573776565.161 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:13:40.527Z,1573776820.527 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:13:40.527Z,1573776820.527 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:13:40.527Z,1573776820.527 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:13:40.527Z,1573776820.527 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:13:40.941Z,1573776820.941 [Default:CheckIn:D] Stopped 2019-11-15T00:13:40.941Z,1573776820.941 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:13:41.403Z,1573776821.403 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 29.569004 min 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn:E] Stopped 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn] Stopped 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn](INFO): Running loop #5 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn] Running Loop=5 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:13:41.404Z,1573776821.404 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:13:43.323Z,1573776823.323 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001341.00,A,3648.11949,N,12147.23051,W,0.039,220.90,151119,,,D*78 2019-11-15T00:13:43.325Z,1573776823.325 [NAL9602](INFO): GPS fix at 20191115T001341: (36.801991, -121.787175) 2019-11-15T00:13:43.382Z,1573776823.382 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:13:43.382Z,1573776823.382 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:13:45.940Z,1573776825.940 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191114T234619/Courier0012.lzma 2019-11-15T00:13:47.648Z,1573776827.648 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0012.lzma.bak 2019-11-15T00:13:47.649Z,1573776827.649 [DataOverHttps](INFO): SBD MOMSN=12065188 2019-11-15T00:14:08.383Z,1573776848.383 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20191114T234619/Express0013.lzma 2019-11-15T00:14:10.389Z,1573776850.389 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0013.lzma.bak 2019-11-15T00:14:10.389Z,1573776850.389 [DataOverHttps](INFO): SBD MOMSN=12065191 2019-11-15T00:14:12.151Z,1573776852.151 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:14:12.151Z,1573776852.151 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:14:12.151Z,1573776852.151 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:14:32.727Z,1573776872.727 [NAL9602](INFO): SBD MO Status=2, MOMSN=9952, MT Status=2, MTMSN=0 2019-11-15T00:14:32.727Z,1573776872.727 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-15T00:14:50.907Z,1573776890.907 [NAL9602](INFO): SBD MO Status=2, MOMSN=9952, MT Status=2, MTMSN=0 2019-11-15T00:14:50.907Z,1573776890.907 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-11-15T00:15:00.603Z,1573776900.603 [NAL9602](INFO): SBD MO Status=0, MOMSN=9952, MT Status=0, MTMSN=0 2019-11-15T00:15:00.603Z,1573776900.603 [NAL9602](INFO): No messages in MT queue 2019-11-15T00:15:31.301Z,1573776931.301 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:15:45.889Z,1573776945.889 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:15:45.889Z,1573776945.889 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:15:49.119Z,1573776949.119 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:15:49.119Z,1573776949.119 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:15:55.177Z,1573776955.177 [RDI_Pathfinder](ERROR): Failed to parse: :BE,-32768,-32768,-32768,V 2019-11-15T00:17:49.096Z,1573777069.096 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:17:49.096Z,1573777069.096 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:19:12.782Z,1573777152.782 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:19:12.782Z,1573777152.782 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:19:12.782Z,1573777152.782 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:19:12.782Z,1573777152.782 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:19:13.151Z,1573777153.151 [Default:CheckIn:D] Stopped 2019-11-15T00:19:13.151Z,1573777153.151 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:19:13.552Z,1573777153.552 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 35.105831 min 2019-11-15T00:19:13.552Z,1573777153.552 [Default:CheckIn:E] Stopped 2019-11-15T00:19:13.552Z,1573777153.552 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:19:13.552Z,1573777153.552 [Default:CheckIn] Stopped 2019-11-15T00:19:13.553Z,1573777153.553 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:19:13.553Z,1573777153.553 [Default:CheckIn](INFO): Running loop #6 2019-11-15T00:19:13.553Z,1573777153.553 [Default:CheckIn] Running Loop=6 2019-11-15T00:19:13.553Z,1573777153.553 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:19:13.553Z,1573777153.553 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:19:14.779Z,1573777154.779 [RDI_Pathfinder](ERROR): Failed to parse: :B,-32768,-32768,V 2019-11-15T00:19:15.543Z,1573777155.543 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,001914.00,A,3648.17067,N,12147.27854,W,0.758,253.99,151119,,,A*70 2019-11-15T00:19:15.545Z,1573777155.545 [NAL9602](INFO): GPS fix at 20191115T001914: (36.802844, -121.787976) 2019-11-15T00:19:15.589Z,1573777155.589 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:19:15.589Z,1573777155.589 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:19:25.374Z,1573777165.374 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191114T234619/Courier0015.lzma 2019-11-15T00:19:27.381Z,1573777167.381 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0015.lzma.bak 2019-11-15T00:19:27.381Z,1573777167.381 [DataOverHttps](INFO): SBD MOMSN=12065206 2019-11-15T00:19:45.803Z,1573777185.803 [DataOverHttps](INFO): Sending 512 bytes from file Logs/20191114T234619/Express0016.lzma 2019-11-15T00:19:47.808Z,1573777187.809 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0016.lzma.bak 2019-11-15T00:19:47.809Z,1573777187.809 [DataOverHttps](INFO): SBD MOMSN=12065209 2019-11-15T00:19:49.507Z,1573777189.507 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:19:49.507Z,1573777189.507 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:19:49.507Z,1573777189.507 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:20:26.254Z,1573777226.254 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:20:26.255Z,1573777226.255 [RDI_Pathfinder](ERROR): Failed to parse: :TS7322068,35.0, -0.1, 0.0,1448.9, 0 2019-11-15T00:20:29.105Z,1573777229.105 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:20:29.105Z,1573777229.105 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111417322368,35.0, -0.1, 0.0,1448.9,, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:21:29.740Z,1573777289.740 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-15T00:21:29.740Z,1573777289.740 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.070.89 2019-11-15T00:21:54.781Z,1573777314.781 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-15T00:21:54.781Z,1573777314.781 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-3768,-32768,V 2019-11-15T00:24:18.140Z,1573777458.140 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-15T00:24:48.861Z,1573777488.861 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:24:50.110Z,1573777490.110 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:24:50.110Z,1573777490.110 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:24:50.110Z,1573777490.110 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:24:50.110Z,1573777490.110 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:24:50.501Z,1573777490.501 [Default:CheckIn:D] Stopped 2019-11-15T00:24:50.501Z,1573777490.501 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:24:51.021Z,1573777491.021 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 40.728333 min 2019-11-15T00:24:51.021Z,1573777491.021 [Default:CheckIn:E] Stopped 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn] Stopped 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn](INFO): Running loop #7 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn] Running Loop=7 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:24:51.022Z,1573777491.022 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:24:52.898Z,1573777492.898 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,002451.00,A,3648.16474,N,12147.29624,W,12.305,77.99,151119,,,A*74 2019-11-15T00:24:52.912Z,1573777492.912 [NAL9602](INFO): GPS fix at 20191115T002451: (36.802746, -121.788271) 2019-11-15T00:24:52.946Z,1573777492.946 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:24:52.946Z,1573777492.946 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:25:01.283Z,1573777501.283 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20191114T234619/Courier0018.lzma 2019-11-15T00:25:03.288Z,1573777503.288 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0018.lzma.bak 2019-11-15T00:25:03.289Z,1573777503.289 [DataOverHttps](INFO): SBD MOMSN=12065214 2019-11-15T00:25:22.943Z,1573777522.943 [DataOverHttps](INFO): Sending 517 bytes from file Logs/20191114T234619/Express0019.lzma 2019-11-15T00:25:23.601Z,1573777523.601 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-11-15T00:25:23.675Z,1573777523.675 [NAL9602](FAULT): received: +CSQ:0 OK52, 0, 0, 0, 0 OK 2019-11-15T00:25:23.675Z,1573777523.675 [NAL9602] Data Fault, FailCount= 1 2019-11-15T00:25:23.675Z,1573777523.675 [NAL9602](ERROR): Data Fault 2019-11-15T00:25:23.762Z,1573777523.762 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-15T00:25:24.009Z,1573777524.009 [NAL9602](INFO): Powering down 2019-11-15T00:25:24.855Z,1573777524.855 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-15T00:25:24.855Z,1573777524.855 [NAL9602] No Fault, FailCount= 1 2019-11-15T00:25:24.950Z,1573777524.950 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0019.lzma.bak 2019-11-15T00:25:24.950Z,1573777524.950 [DataOverHttps](INFO): SBD MOMSN=12065222 2019-11-15T00:25:26.867Z,1573777526.867 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:25:26.867Z,1573777526.867 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:25:26.867Z,1573777526.867 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:25:30.084Z,1573777530.084 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:25:30.084Z,1573777530.084 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:25:54.309Z,1573777554.309 [NAL9602](INFO): Powering up NAL9602 2019-11-15T00:26:05.224Z,1573777565.224 [NAL9602](INFO): NAL9602 initialized 2019-11-15T00:26:36.321Z,1573777596.321 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:30:27.069Z,1573777827.069 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-15T00:30:27.069Z,1573777827.069 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,-32768,- 2019-11-15T00:30:27.450Z,1573777827.450 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:30:27.451Z,1573777827.451 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:30:27.451Z,1573777827.451 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:30:27.451Z,1573777827.451 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:30:27.860Z,1573777827.860 [Default:CheckIn:D] Stopped 2019-11-15T00:30:27.860Z,1573777827.860 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:30:28.275Z,1573777828.275 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 46.350981 min 2019-11-15T00:30:28.275Z,1573777828.275 [Default:CheckIn:E] Stopped 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn] Stopped 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn](INFO): Running loop #8 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn] Running Loop=8 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:30:28.276Z,1573777828.276 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:30:32.275Z,1573777832.275 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-15T00:31:07.061Z,1573777867.061 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2019-11-15T00:31:07.061Z,1573777867.061 [RDI_Pathfinder](ERROR): Failed to parse: :BS,-32768,32768,V 2019-11-15T00:32:35.997Z,1573777955.997 [RDI_Pathfinder](ERROR): Failed to parse: :SA, +0.00, +0.00, 0.00 2019-11-15T00:33:51.091Z,1573778031.091 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:33:51.091Z,1573778031.091 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:33:55.122Z,1573778035.122 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:33:55.123Z,1573778035.123 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111417454968,35.0, -0.1, 0.0,14 2019-11-15T00:35:28.469Z,1573778128.469 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-15T00:30:28.3Z 2019-11-15T00:35:28.469Z,1573778128.469 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:35:28.469Z,1573778128.469 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:35:37.307Z,1573778137.307 [DataOverHttps](INFO): Sending 328 bytes from file Logs/20191114T234619/Express0022.lzma 2019-11-15T00:35:39.312Z,1573778139.312 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0022.lzma.bak 2019-11-15T00:35:39.313Z,1573778139.313 [DataOverHttps](INFO): SBD MOMSN=12065236 2019-11-15T00:35:41.074Z,1573778141.074 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:35:41.075Z,1573778141.075 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:35:41.075Z,1573778141.075 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:36:01.643Z,1573778161.643 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:36:38.470Z,1573778198.470 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:36:38.470Z,1573778198.470 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111417483268,31, 0.0,1448.9, 0 2019-11-15T00:40:18.204Z,1573778418.204 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00, 0.00 2019-11-15T00:40:41.645Z,1573778441.645 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:40:41.645Z,1573778441.645 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:40:41.645Z,1573778441.645 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:40:41.645Z,1573778441.645 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:40:42.059Z,1573778442.059 [Default:CheckIn:D] Stopped 2019-11-15T00:40:42.059Z,1573778442.059 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 56.587626 min 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn:E] Stopped 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn] Stopped 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:40:42.461Z,1573778442.461 [Default:CheckIn](INFO): Running loop #9 2019-11-15T00:40:42.462Z,1573778442.462 [Default:CheckIn] Running Loop=9 2019-11-15T00:40:42.462Z,1573778442.462 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:40:42.462Z,1573778442.462 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:40:44.041Z,1573778444.041 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-15T00:40:44.041Z,1573778444.041 [NAL9602] Data Fault, FailCount= 1 2019-11-15T00:40:44.041Z,1573778444.041 [NAL9602](ERROR): Data Fault 2019-11-15T00:40:44.130Z,1573778444.130 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-15T00:40:44.441Z,1573778444.441 [NAL9602](INFO): Powering down 2019-11-15T00:40:45.299Z,1573778445.299 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-15T00:40:45.299Z,1573778445.299 [NAL9602] No Fault, FailCount= 1 2019-11-15T00:41:14.766Z,1573778474.766 [NAL9602](INFO): Powering up NAL9602 2019-11-15T00:41:25.654Z,1573778485.654 [NAL9602](INFO): NAL9602 initialized 2019-11-15T00:43:09.926Z,1573778589.926 [RDI_Pathfinder](ERROR): Failed to parse: +0.00, +0.00, +0.00, 0.00,2869.63 2019-11-15T00:45:42.625Z,1573778742.625 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-15T00:40:42.5Z 2019-11-15T00:45:42.625Z,1573778742.625 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:45:42.625Z,1573778742.625 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:45:48.799Z,1573778748.799 [RDI_Pathfinder](ERROR): DVL uart error: serial timeout 2019-11-15T00:45:48.799Z,1573778748.799 [RDI_Pathfinder] Communications Fault, FailCount= 1 2019-11-15T00:45:48.799Z,1573778748.799 [RDI_Pathfinder](ERROR): Communications Fault 2019-11-15T00:45:48.800Z,1573778748.800 [RDI_Pathfinder](ERROR): Failed to parse: 2019-11-15T00:45:48.867Z,1573778748.867 [CBIT](ERROR): Communications Fault in component: RDI_Pathfinder 2019-11-15T00:45:49.143Z,1573778749.143 [RDI_Pathfinder](INFO): Powering down 2019-11-15T00:45:49.950Z,1573778749.950 [CBIT](INFO): Clearing failed state for component RDI_Pathfinder 2019-11-15T00:45:49.950Z,1573778749.950 [RDI_Pathfinder] No Fault, FailCount= 1 2019-11-15T00:45:52.090Z,1573778752.090 [DataOverHttps](INFO): Sending 179 bytes from file Logs/20191114T234619/Express0025.lzma 2019-11-15T00:45:54.097Z,1573778754.097 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0025.lzma.bak 2019-11-15T00:45:54.097Z,1573778754.097 [DataOverHttps](INFO): SBD MOMSN=12065247 2019-11-15T00:45:55.975Z,1573778755.975 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:45:55.975Z,1573778755.975 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:45:55.975Z,1573778755.975 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:46:03.229Z,1573778763.229 [RDI_Pathfinder](ERROR): Failed to parse:Pathfinder 2019-11-15T00:46:29.057Z,1573778789.057 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-15T00:46:59.781Z,1573778819.781 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:47:11.541Z,1573778831.541 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:47:11.541Z,1573778831.541 [RDI_Pathfinder](ERROR): Failed to parse: :TS,191114175.0, -0.1, 0.0,1448.9, 0 2019-11-15T00:48:58.212Z,1573778938.212 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for altitude 2019-11-15T00:48:58.212Z,1573778938.212 [RDI_Pathfinder](ERROR): Failed to parse: :BD, +0.0 +0.00, +0.00, 0.00,175.00 2019-11-15T00:49:36.567Z,1573778976.567 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:49:36.567Z,1573778976.567 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111418013117,35.0, -0.1,448.9, 0 2019-11-15T00:50:56.599Z,1573779056.599 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T00:50:56.599Z,1573779056.599 [Default:CheckIn:C.Wait] Stopped 2019-11-15T00:50:56.599Z,1573779056.599 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T00:50:56.599Z,1573779056.599 [Default:CheckIn:D] Running Loop=1 2019-11-15T00:50:56.971Z,1573779056.971 [Default:CheckIn:D] Stopped 2019-11-15T00:50:56.971Z,1573779056.971 [Default:CheckIn:E] Running Loop=1 2019-11-15T00:50:57.385Z,1573779057.385 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.836161 min 2019-11-15T00:50:57.385Z,1573779057.385 [Default:CheckIn:E] Stopped 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn] Stopped 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn](INFO): Running loop #10 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn] Running Loop=10 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T00:50:57.386Z,1573779057.386 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T00:51:38.585Z,1573779098.585 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:51:38.585Z,1573779098.585 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111418033317,35.0, 0.0,1448.9, 0 2019-11-15T00:53:32.539Z,1573779212.539 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2019-11-15T00:53:32.539Z,1573779212.539 [RDI_Pathfinder](ERROR): Failed to parse: :TS,19111418052717,31, 0.0,1448.9, 0 2019-11-15T00:55:29.339Z,1573779329.339 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-11-15T00:55:29.341Z,1573779329.341 [BPC1](INFO): Received data from all battery sticks. 2019-11-15T00:55:57.560Z,1573779357.560 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-15T00:50:57.4Z 2019-11-15T00:55:57.560Z,1573779357.560 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T00:55:57.560Z,1573779357.560 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T00:56:01.153Z,1573779361.153 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-15T00:56:05.878Z,1573779365.878 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20191114T234619/Courier0027.lzma 2019-11-15T00:56:07.892Z,1573779367.892 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Courier0027.lzma.bak 2019-11-15T00:56:07.893Z,1573779367.893 [DataOverHttps](INFO): SBD MOMSN=12065260 2019-11-15T00:56:31.853Z,1573779391.853 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T00:56:41.168Z,1573779401.168 [DataOverHttps](INFO): Sending 226 bytes from file Logs/20191114T234619/Express0028.lzma 2019-11-15T00:56:43.175Z,1573779403.175 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0028.lzma.bak 2019-11-15T00:56:43.176Z,1573779403.176 [DataOverHttps](INFO): SBD MOMSN=12065268 2019-11-15T00:56:44.829Z,1573779404.829 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T00:56:44.829Z,1573779404.829 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T00:56:44.829Z,1573779404.829 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T00:58:52.912Z,1573779532.912 [RDI_Pathfinder](ERROR): only read 3 of 4 data items 2019-11-15T00:58:52.913Z,1573779532.913 [RDI_Pathfinder](ERROR): Failed to parse: :RA, 0.00, 0.00, 0.00, 0.00 2019-11-15T01:01:45.451Z,1573779705.451 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T01:01:45.451Z,1573779705.451 [Default:CheckIn:C.Wait] Stopped 2019-11-15T01:01:45.451Z,1573779705.451 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T01:01:45.451Z,1573779705.451 [Default:CheckIn:D] Running Loop=1 2019-11-15T01:01:45.849Z,1573779705.849 [Default:CheckIn:D] Stopped 2019-11-15T01:01:45.850Z,1573779705.850 [Default:CheckIn:E] Running Loop=1 2019-11-15T01:01:46.267Z,1573779706.267 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.650806 min 2019-11-15T01:01:46.267Z,1573779706.267 [Default:CheckIn:E] Stopped 2019-11-15T01:01:46.267Z,1573779706.267 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn] Stopped 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn](INFO): Running loop #11 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn] Running Loop=11 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T01:01:46.268Z,1573779706.268 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T01:01:47.825Z,1573779707.825 [NAL9602](FAULT): GPS failed to acquire within timeout. 2019-11-15T01:01:47.825Z,1573779707.825 [NAL9602] Data Fault, FailCount= 2 2019-11-15T01:01:47.825Z,1573779707.825 [NAL9602](ERROR): Data Fault 2019-11-15T01:01:47.884Z,1573779707.884 [CBIT](ERROR): Data Fault in component: NAL9602 2019-11-15T01:01:48.233Z,1573779708.233 [NAL9602](INFO): Powering down 2019-11-15T01:01:49.086Z,1573779709.086 [CBIT](INFO): Clearing failed state for component NAL9602 2019-11-15T01:01:49.086Z,1573779709.086 [NAL9602] No Fault, FailCount= 2 2019-11-15T01:02:18.533Z,1573779738.533 [NAL9602](INFO): Powering up NAL9602 2019-11-15T01:02:29.445Z,1573779749.445 [NAL9602](INFO): NAL9602 initialized 2019-11-15T01:03:36.533Z,1573779816.533 [RDI_Pathfinder](ERROR): Failed to parse: :R, 0.00, 0.00, 0.00, 0.00 2019-11-15T01:06:46.424Z,1573780006.424 [Default:CheckIn:Read_GPS](INFO): Timed out from 2019-11-15T01:01:46.3Z 2019-11-15T01:06:46.424Z,1573780006.424 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T01:06:46.424Z,1573780006.424 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-11-15T01:06:54.423Z,1573780014.423 [DataOverHttps](INFO): Sending 233 bytes from file Logs/20191114T234619/Express0031.lzma 2019-11-15T01:06:56.429Z,1573780016.429 [DataOverHttps](INFO): Moved sent file to Logs/20191114T234619/Express0031.lzma.bak 2019-11-15T01:06:56.429Z,1573780016.429 [DataOverHttps](INFO): SBD MOMSN=12065280 2019-11-15T01:06:58.143Z,1573780018.143 [Default:CheckIn:Read_Iridium] Stopped 2019-11-15T01:06:58.143Z,1573780018.143 [Default:CheckIn:C.Wait] Running Loop=1 2019-11-15T01:06:58.159Z,1573780018.159 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-11-15T01:07:32.850Z,1573780052.850 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-11-15T01:08:03.553Z,1573780083.553 [NAL9602](INFO): Not Powering down - fast GPS 2019-11-15T01:11:58.747Z,1573780318.747 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-11-15T01:11:58.747Z,1573780318.747 [Default:CheckIn:C.Wait] Stopped 2019-11-15T01:11:58.747Z,1573780318.747 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-11-15T01:11:58.747Z,1573780318.747 [Default:CheckIn:D] Running Loop=1 2019-11-15T01:11:59.151Z,1573780319.151 [Default:CheckIn:D] Stopped 2019-11-15T01:11:59.151Z,1573780319.151 [Default:CheckIn:E] Running Loop=1 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 87.872493 min 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn:E] Stopped 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn] Stopped 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn](INFO): Running loop #12 2019-11-15T01:11:59.566Z,1573780319.566 [Default:CheckIn] Running Loop=12 2019-11-15T01:11:59.567Z,1573780319.567 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-11-15T01:11:59.567Z,1573780319.567 [Default:CheckIn:Read_GPS] Running Loop=1 2019-11-15T01:13:57.944Z,1573780437.944 [CommandLine](IMPORTANT): got command quit 2019-11-15T01:13:58.947Z,1573780438.947 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-11-15T01:13:58.947Z,1573780438.947 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:58.948Z,1573780438.948 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:58.995Z,1573780438.995 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-11-15T01:13:58.995Z,1573780438.995 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:58.996Z,1573780438.996 [CommandLine](INFO): Join timeout helper Thread ID is 5328 2019-11-15T01:13:58.997Z,1573780438.997 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-11-15T01:13:58.997Z,1573780438.997 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:58.998Z,1573780438.998 [NavChartDb](INFO): Join timeout helper Thread ID is 5329 2019-11-15T01:13:59.039Z,1573780439.039 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.039Z,1573780439.039 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.043Z,1573780439.043 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2019-11-15T01:13:59.043Z,1573780439.043 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.043Z,1573780439.043 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 5330 2019-11-15T01:13:59.399Z,1573780439.399 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.399Z,1573780439.399 [WetLabsSeaOWL_UV_A](INFO): Powering down 2019-11-15T01:13:59.400Z,1573780439.400 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.403Z,1573780439.403 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-11-15T01:13:59.403Z,1573780439.403 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.404Z,1573780439.404 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5331 2019-11-15T01:13:59.404Z,1573780439.404 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.404Z,1573780439.404 [CTD_NeilBrown](INFO): Powering down 2019-11-15T01:13:59.419Z,1573780439.419 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.423Z,1573780439.423 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-11-15T01:13:59.423Z,1573780439.423 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.423Z,1573780439.423 [Radio_Surface](INFO): Join timeout helper Thread ID is 5332 2019-11-15T01:13:59.727Z,1573780439.727 [Radio_Surface](INFO): Powering down 2019-11-15T01:13:59.728Z,1573780439.728 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.728Z,1573780439.728 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.732Z,1573780439.732 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-11-15T01:13:59.732Z,1573780439.732 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.732Z,1573780439.732 [DataOverHttps](INFO): Join timeout helper Thread ID is 5333 2019-11-15T01:13:59.879Z,1573780439.879 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.879Z,1573780439.879 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.892Z,1573780439.892 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-11-15T01:13:59.892Z,1573780439.892 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.892Z,1573780439.892 [logger](INFO): Join timeout helper Thread ID is 5334 2019-11-15T01:13:59.909Z,1573780439.909 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.909Z,1573780439.909 [logger ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.912Z,1573780439.912 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-11-15T01:13:59.912Z,1573780439.912 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.912Z,1573780439.912 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-11-15T01:13:59.912Z,1573780439.912 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:13:59.913Z,1573780439.913 [controlThread](INFO): Join timeout helper Thread ID is 5335 2019-11-15T01:13:59.964Z,1573780439.964 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-11-15T01:13:59.965Z,1573780439.965 [controlThread](DEBUG): Uninitializing ControlThread 2019-11-15T01:13:59.965Z,1573780439.965 [AHRS_M2](INFO): Powering down 2019-11-15T01:14:00.036Z,1573780440.036 [DDM](INFO): Powering down 2019-11-15T01:14:00.128Z,1573780440.128 [DUSBL_Hydroid](INFO): Powering down 2019-11-15T01:14:00.219Z,1573780440.219 [Micromodem](INFO): Powering down 2019-11-15T01:14:00.316Z,1573780440.316 [NAL9602](INFO): Powering down 2019-11-15T01:14:00.387Z,1573780440.387 [RDI_Pathfinder](INFO): Powering down 2019-11-15T01:14:00.389Z,1573780440.389 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-11-15T01:14:00.390Z,1573780440.390 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-11-15T01:14:00.390Z,1573780440.390 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-11-15T01:14:00.390Z,1573780440.390 [MissionManager](INFO): Uninitializing Mission Default 2019-11-15T01:14:00.391Z,1573780440.391 [Default] Stopped 2019-11-15T01:14:00.391Z,1573780440.391 [Default](DEBUG): Aggregate::uninitialize Default 2019-11-15T01:14:00.391Z,1573780440.391 [Default:B.GoToSurface] Stopped 2019-11-15T01:14:00.391Z,1573780440.391 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-11-15T01:14:00.391Z,1573780440.391 [Default:CheckIn] Stopped 2019-11-15T01:14:00.391Z,1573780440.391 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-11-15T01:14:00.391Z,1573780440.391 [Default:CheckIn:Read_GPS] Stopped 2019-11-15T01:14:00.394Z,1573780440.394 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-11-15T01:14:00.394Z,1573780440.394 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-11-15T01:14:00.394Z,1573780440.394 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-11-15T01:14:00.394Z,1573780440.394 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-11-15T01:14:00.395Z,1573780440.395 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-11-15T01:14:00.395Z,1573780440.395 [BuoyancyServo](INFO): Powering down 2019-11-15T01:14:00.407Z,1573780440.407 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-11-15T01:14:00.407Z,1573780440.407 [ElevatorServo](INFO): Powering down 2019-11-15T01:14:00.408Z,1573780440.408 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-11-15T01:14:00.408Z,1573780440.408 [MassServo](INFO): Powering down 2019-11-15T01:14:00.409Z,1573780440.409 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-11-15T01:14:00.409Z,1573780440.409 [RudderServo](INFO): Powering down 2019-11-15T01:14:00.410Z,1573780440.410 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-11-15T01:14:00.410Z,1573780440.410 [ThrusterServo](INFO): Powering down 2019-11-15T01:14:00.410Z,1573780440.410 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-11-15T01:14:00.411Z,1573780440.411 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-11-15T01:14:00.411Z,1573780440.411 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-11-15T01:14:00.411Z,1573780440.411 [CBIT](DEBUG): Powering off loads. 2019-11-15T01:14:00.423Z,1573780440.423 [CBIT](DEBUG): Disabling WDT. 2019-11-15T01:14:00.435Z,1573780440.435 [CBIT](DEBUG): Opening all GF detection circuits. 2019-11-15T01:14:00.436Z,1573780440.436 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.493Z,1573780440.493 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.504Z,1573780440.504 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.546Z,1573780440.546 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.549Z,1573780440.549 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.607Z,1573780440.607 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-11-15T01:14:00.680Z,1573780440.680 [logger ThreadHandler](INFO): Thread cancelled.