2018-11-08T17:27:05.048Z,1541698025.048 [CommandLine](IMPORTANT): got command restart logs 2018-11-08T17:27:05.786Z,1541698025.786 [DataOverHttps](INFO): Moved sent file to Logs/20181106T220818/Express0191.lzma.bak 2018-11-08T17:27:05.787Z,1541698025.787 [DataOverHttps](INFO): SBD MOMSN=8818035 2018-11-08T17:27:20.097Z,1541698040.097 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181106T220818/Courier0193.lzma 2018-11-08T17:27:20.882Z,1541698040.882 [DataOverHttps](INFO): Moved sent file to Logs/20181106T220818/Courier0193.lzma.bak 2018-11-08T17:27:20.883Z,1541698040.883 [DataOverHttps](INFO): SBD MOMSN=8818039 2018-11-08T17:27:31.470Z,1541698051.470 [NAL9602](INFO): Powering down 2018-11-08T17:27:31.587Z,1541698051.587 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Courier0000.lzma 2018-11-08T17:27:32.382Z,1541698052.382 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0000.lzma.bak 2018-11-08T17:27:32.382Z,1541698052.382 [DataOverHttps](INFO): SBD MOMSN=8818041 2018-11-08T17:27:42.606Z,1541698062.606 [DataOverHttps](INFO): Sending 96 bytes from file Logs/20181106T220818/Express0194.lzma 2018-11-08T17:27:43.403Z,1541698063.403 [DataOverHttps](INFO): Moved sent file to Logs/20181106T220818/Express0194.lzma.bak 2018-11-08T17:27:43.403Z,1541698063.403 [DataOverHttps](INFO): SBD MOMSN=8818044 2018-11-08T17:27:58.063Z,1541698078.063 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Express0001.lzma 2018-11-08T17:27:58.862Z,1541698078.862 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0001.lzma.bak 2018-11-08T17:27:58.862Z,1541698078.862 [DataOverHttps](INFO): SBD MOMSN=8818050 2018-11-08T17:27:59.371Z,1541698079.371 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T17:27:59.376Z,1541698079.376 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T17:27:59.376Z,1541698079.376 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T17:33:00.050Z,1541698380.050 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T17:33:00.050Z,1541698380.050 [Default:CheckIn:C.Wait] Stopped 2018-11-08T17:33:00.050Z,1541698380.050 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T17:33:00.051Z,1541698380.051 [Default:CheckIn:D] Running Loop=1 2018-11-08T17:33:00.503Z,1541698380.503 [Default:CheckIn:D] Stopped 2018-11-08T17:33:00.503Z,1541698380.503 [Default:CheckIn:E] Running Loop=1 2018-11-08T17:33:03.791Z,1541698383.791 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 23.238464 min 2018-11-08T17:33:03.791Z,1541698383.791 [Default:CheckIn:E] Stopped 2018-11-08T17:33:03.791Z,1541698383.791 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T17:33:03.791Z,1541698383.791 [Default:CheckIn] Stopped 2018-11-08T17:33:03.791Z,1541698383.791 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T17:33:03.792Z,1541698383.792 [Default:CheckIn](INFO): Running loop #4 2018-11-08T17:33:03.792Z,1541698383.792 [Default:CheckIn] Running Loop=4 2018-11-08T17:33:03.792Z,1541698383.792 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T17:33:03.792Z,1541698383.792 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T17:33:04.217Z,1541698384.217 [NAL9602](INFO): Powering up 2018-11-08T17:33:15.417Z,1541698395.417 [NAL9602](INFO): NAL9602 initialized 2018-11-08T17:33:30.618Z,1541698410.618 [NAL9602](INFO): SBD MO Status=0, MOMSN=10736, MT Status=0, MTMSN=0 2018-11-08T17:33:30.618Z,1541698410.618 [NAL9602](INFO): No messages in MT queue 2018-11-08T17:34:26.913Z,1541698466.913 [NAL9602](INFO): GPS fix at 20181108T173353: (36.762582, -121.868865) 2018-11-08T17:34:26.950Z,1541698466.950 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T17:34:26.950Z,1541698466.950 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T17:34:35.204Z,1541698475.204 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20181108T172705/Courier0003.lzma 2018-11-08T17:34:35.998Z,1541698475.998 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0003.lzma.bak 2018-11-08T17:34:35.998Z,1541698475.998 [DataOverHttps](INFO): SBD MOMSN=8818121 2018-11-08T17:34:45.993Z,1541698485.993 [DataOverHttps](INFO): Sending 336 bytes from file Logs/20181108T172705/Express0004.lzma 2018-11-08T17:34:46.792Z,1541698486.792 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0004.lzma.bak 2018-11-08T17:34:46.793Z,1541698486.793 [DataOverHttps](INFO): SBD MOMSN=8818124 2018-11-08T17:34:47.287Z,1541698487.287 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T17:34:47.287Z,1541698487.287 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T17:34:47.287Z,1541698487.287 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T17:34:59.357Z,1541698499.357 [NAL9602](INFO): Powering down 2018-11-08T17:39:47.714Z,1541698787.714 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T17:39:47.714Z,1541698787.714 [Default:CheckIn:C.Wait] Stopped 2018-11-08T17:39:47.714Z,1541698787.714 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T17:39:47.715Z,1541698787.715 [Default:CheckIn:D] Running Loop=1 2018-11-08T17:39:48.122Z,1541698788.122 [Default:CheckIn:D] Stopped 2018-11-08T17:39:48.122Z,1541698788.122 [Default:CheckIn:E] Running Loop=1 2018-11-08T17:39:48.592Z,1541698788.592 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.032125 min 2018-11-08T17:39:48.592Z,1541698788.592 [Default:CheckIn:E] Stopped 2018-11-08T17:39:48.592Z,1541698788.592 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T17:39:48.592Z,1541698788.592 [Default:CheckIn] Stopped 2018-11-08T17:39:48.593Z,1541698788.593 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T17:39:48.593Z,1541698788.593 [Default:CheckIn](INFO): Running loop #5 2018-11-08T17:39:48.593Z,1541698788.593 [Default:CheckIn] Running Loop=5 2018-11-08T17:39:48.593Z,1541698788.593 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T17:39:48.593Z,1541698788.593 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T17:39:49.253Z,1541698789.253 [NAL9602](INFO): Powering up 2018-11-08T17:40:00.053Z,1541698800.053 [NAL9602](INFO): NAL9602 initialized 2018-11-08T17:40:14.481Z,1541698814.481 [NAL9602](INFO): SBD MO Status=0, MOMSN=10737, MT Status=0, MTMSN=0 2018-11-08T17:40:14.481Z,1541698814.481 [NAL9602](INFO): No messages in MT queue 2018-11-08T17:40:18.456Z,1541698818.456 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:41:18.451Z,1541698878.451 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:41:30.065Z,1541698890.065 [NAL9602](INFO): GPS fix at 20181108T174056: (36.744459, -121.879455) 2018-11-08T17:41:30.138Z,1541698890.138 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T17:41:30.138Z,1541698890.138 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T17:41:54.506Z,1541698914.506 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.055176 2018-11-08T17:42:03.794Z,1541698923.794 [NAL9602](INFO): SBD MO Status=1, MOMSN=10738, MT Status=0, MTMSN=0 2018-11-08T17:42:03.852Z,1541698923.852 [NAL9602](INFO): Sent 61 bytes from file Logs/20181108T172705/Courier0006.lzma 2018-11-08T17:42:03.852Z,1541698923.852 [NAL9602](INFO): Packets left to send: 0 2018-11-08T17:42:03.853Z,1541698923.853 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181108T172705/Courier0006.lzma.parts/0000.sbd 2018-11-08T17:42:03.854Z,1541698923.854 [NAL9602](DEBUG): Completed sending Logs/20181108T172705/Courier0006.lzma 2018-11-08T17:42:14.687Z,1541698934.687 [NAL9602](INFO): SBD MO Status=1, MOMSN=10739, MT Status=0, MTMSN=0 2018-11-08T17:42:14.736Z,1541698934.736 [NAL9602](INFO): Sent 135 bytes from file Logs/20181108T172705/Express0007.lzma 2018-11-08T17:42:14.736Z,1541698934.736 [NAL9602](INFO): Packets left to send: 0 2018-11-08T17:42:14.738Z,1541698934.738 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181108T172705/Express0007.lzma.parts/0000.sbd 2018-11-08T17:42:14.738Z,1541698934.738 [NAL9602](DEBUG): Completed sending Logs/20181108T172705/Express0007.lzma 2018-11-08T17:42:25.077Z,1541698945.077 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:42:25.082Z,1541698945.082 [NAL9602](INFO): SBD MO Status=0, MOMSN=10740, MT Status=0, MTMSN=0 2018-11-08T17:42:25.188Z,1541698945.188 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T17:42:25.188Z,1541698945.188 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T17:42:25.188Z,1541698945.188 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T17:42:55.881Z,1541698975.881 [NAL9602](INFO): Powering down 2018-11-08T17:43:25.477Z,1541699005.477 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:44:25.477Z,1541699065.477 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:45:25.477Z,1541699125.477 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:46:25.877Z,1541699185.877 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:47:25.546Z,1541699245.546 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T17:47:25.546Z,1541699245.546 [Default:CheckIn:C.Wait] Stopped 2018-11-08T17:47:25.546Z,1541699245.546 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T17:47:25.547Z,1541699245.547 [Default:CheckIn:D] Running Loop=1 2018-11-08T17:47:25.877Z,1541699245.877 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:47:25.929Z,1541699245.929 [Default:CheckIn:D] Stopped 2018-11-08T17:47:25.929Z,1541699245.929 [Default:CheckIn:E] Running Loop=1 2018-11-08T17:47:26.350Z,1541699246.350 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 37.662236 min 2018-11-08T17:47:26.350Z,1541699246.350 [Default:CheckIn:E] Stopped 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn] Stopped 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn](INFO): Running loop #6 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn] Running Loop=6 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T17:47:26.351Z,1541699246.351 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T17:47:27.092Z,1541699247.092 [NAL9602](INFO): Powering up 2018-11-08T17:47:38.285Z,1541699258.285 [NAL9602](INFO): NAL9602 initialized 2018-11-08T17:47:57.882Z,1541699277.882 [NAL9602](INFO): SBD MO Status=2, MOMSN=10741, MT Status=2, MTMSN=0 2018-11-08T17:47:57.883Z,1541699277.883 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-11-08T17:48:08.286Z,1541699288.286 [NAL9602](INFO): SBD MO Status=0, MOMSN=10741, MT Status=0, MTMSN=0 2018-11-08T17:48:08.286Z,1541699288.286 [NAL9602](INFO): No messages in MT queue 2018-11-08T17:48:26.277Z,1541699306.277 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:48:53.885Z,1541699333.885 [NAL9602](INFO): GPS fix at 20181108T174820: (36.744603, -121.879386) 2018-11-08T17:48:53.951Z,1541699333.951 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T17:48:53.952Z,1541699333.952 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T17:49:13.254Z,1541699353.254 [NAL9602](INFO): SBD MO Status=1, MOMSN=10742, MT Status=0, MTMSN=0 2018-11-08T17:49:13.304Z,1541699353.304 [NAL9602](INFO): Sent 61 bytes from file Logs/20181108T172705/Courier0009.lzma 2018-11-08T17:49:13.304Z,1541699353.304 [NAL9602](INFO): Packets left to send: 0 2018-11-08T17:49:13.305Z,1541699353.305 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181108T172705/Courier0009.lzma.parts/0000.sbd 2018-11-08T17:49:13.306Z,1541699353.306 [NAL9602](DEBUG): Completed sending Logs/20181108T172705/Courier0009.lzma 2018-11-08T17:49:22.954Z,1541699362.954 [NAL9602](INFO): SBD MO Status=1, MOMSN=10743, MT Status=0, MTMSN=0 2018-11-08T17:49:23.004Z,1541699363.004 [NAL9602](INFO): Sent 121 bytes from file Logs/20181108T172705/Express0010.lzma 2018-11-08T17:49:23.004Z,1541699363.004 [NAL9602](INFO): Packets left to send: 0 2018-11-08T17:49:23.006Z,1541699363.006 [NAL9602](DEBUG): Stored copy of sent data in Logs/20181108T172705/Express0010.lzma.parts/0000.sbd 2018-11-08T17:49:23.006Z,1541699363.006 [NAL9602](DEBUG): Completed sending Logs/20181108T172705/Express0010.lzma 2018-11-08T17:49:26.149Z,1541699366.149 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-11-08T17:49:36.154Z,1541699376.154 [NAL9602](INFO): SBD MO Status=0, MOMSN=10744, MT Status=0, MTMSN=0 2018-11-08T17:49:36.298Z,1541699376.298 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T17:49:36.298Z,1541699376.298 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T17:49:36.298Z,1541699376.298 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T17:50:00.951Z,1541699400.951 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003101 2018-11-08T17:50:06.567Z,1541699406.567 [NAL9602](INFO): Powering down 2018-11-08T17:54:36.715Z,1541699676.715 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T17:54:36.715Z,1541699676.715 [Default:CheckIn:C.Wait] Stopped 2018-11-08T17:54:36.715Z,1541699676.715 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T17:54:36.720Z,1541699676.720 [Default:CheckIn:D] Running Loop=1 2018-11-08T17:54:37.065Z,1541699677.065 [Default:CheckIn:D] Stopped 2018-11-08T17:54:37.065Z,1541699677.065 [Default:CheckIn:E] Running Loop=1 2018-11-08T17:54:37.459Z,1541699677.459 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.847835 min 2018-11-08T17:54:37.460Z,1541699677.460 [Default:CheckIn:E] Stopped 2018-11-08T17:54:37.460Z,1541699677.460 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T17:54:37.460Z,1541699677.460 [Default:CheckIn] Stopped 2018-11-08T17:54:37.460Z,1541699677.460 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T17:54:37.460Z,1541699677.460 [Default:CheckIn](INFO): Running loop #7 2018-11-08T17:54:37.461Z,1541699677.461 [Default:CheckIn] Running Loop=7 2018-11-08T17:54:37.461Z,1541699677.461 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T17:54:37.461Z,1541699677.461 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T17:54:38.193Z,1541699678.193 [NAL9602](INFO): Powering up 2018-11-08T17:54:48.993Z,1541699688.993 [NAL9602](INFO): NAL9602 initialized 2018-11-08T17:55:08.586Z,1541699708.586 [NAL9602](INFO): SBD MO Status=0, MOMSN=10745, MT Status=0, MTMSN=0 2018-11-08T17:55:08.586Z,1541699708.586 [NAL9602](INFO): No messages in MT queue 2018-11-08T17:56:22.033Z,1541699782.033 [NAL9602](INFO): GPS fix at 20181108T175548: (36.744474, -121.879507) 2018-11-08T17:56:22.096Z,1541699782.096 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T17:56:22.097Z,1541699782.097 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T17:56:26.851Z,1541699786.851 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181108T172705/Courier0012.lzma 2018-11-08T17:56:27.653Z,1541699787.653 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0012.lzma.bak 2018-11-08T17:56:27.653Z,1541699787.653 [DataOverHttps](INFO): SBD MOMSN=8818292 2018-11-08T17:56:37.064Z,1541699797.064 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181108T172705/Express0013.lzma 2018-11-08T17:56:37.862Z,1541699797.862 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0013.lzma.bak 2018-11-08T17:56:37.862Z,1541699797.862 [DataOverHttps](INFO): SBD MOMSN=8818295 2018-11-08T17:56:38.414Z,1541699798.414 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T17:56:38.414Z,1541699798.414 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T17:56:38.414Z,1541699798.414 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T17:56:56.997Z,1541699816.997 [NAL9602](INFO): Powering down 2018-11-08T18:01:38.889Z,1541700098.889 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:01:38.889Z,1541700098.889 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:01:38.889Z,1541700098.889 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:01:38.889Z,1541700098.889 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:01:39.287Z,1541700099.287 [Default:CheckIn:D] Stopped 2018-11-08T18:01:39.288Z,1541700099.288 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:01:39.667Z,1541700099.667 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 51.884611 min 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn:E] Stopped 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn] Stopped 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn](INFO): Running loop #8 2018-11-08T18:01:39.668Z,1541700099.668 [Default:CheckIn] Running Loop=8 2018-11-08T18:01:39.669Z,1541700099.669 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:01:39.669Z,1541700099.669 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:01:43.728Z,1541700103.728 [NAL9602](INFO): Powering up 2018-11-08T18:01:54.625Z,1541700114.625 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:02:09.027Z,1541700129.027 [NAL9602](INFO): SBD MO Status=0, MOMSN=10746, MT Status=0, MTMSN=0 2018-11-08T18:02:09.027Z,1541700129.027 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:02:58.029Z,1541700178.029 [NAL9602](INFO): GPS fix at 20181108T180224: (36.744531, -121.879706) 2018-11-08T18:02:58.097Z,1541700178.097 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:02:58.098Z,1541700178.098 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:03:02.751Z,1541700182.751 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181108T172705/Courier0015.lzma 2018-11-08T18:03:03.538Z,1541700183.538 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0015.lzma.bak 2018-11-08T18:03:03.538Z,1541700183.538 [DataOverHttps](INFO): SBD MOMSN=8818347 2018-11-08T18:03:13.116Z,1541700193.116 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181108T172705/Express0016.lzma 2018-11-08T18:03:13.914Z,1541700193.914 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0016.lzma.bak 2018-11-08T18:03:13.914Z,1541700193.914 [DataOverHttps](INFO): SBD MOMSN=8818350 2018-11-08T18:03:14.404Z,1541700194.404 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:03:14.404Z,1541700194.404 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:03:14.404Z,1541700194.404 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:03:33.037Z,1541700213.037 [NAL9602](INFO): Powering down 2018-11-08T18:08:15.038Z,1541700495.038 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:08:15.038Z,1541700495.038 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:08:15.038Z,1541700495.038 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:08:15.039Z,1541700495.039 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:08:15.442Z,1541700495.442 [Default:CheckIn:D] Stopped 2018-11-08T18:08:15.442Z,1541700495.442 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:08:15.850Z,1541700495.850 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 58.487455 min 2018-11-08T18:08:15.850Z,1541700495.850 [Default:CheckIn:E] Stopped 2018-11-08T18:08:15.851Z,1541700495.851 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:08:15.851Z,1541700495.851 [Default:CheckIn] Stopped 2018-11-08T18:08:15.851Z,1541700495.851 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:08:15.851Z,1541700495.851 [Default:CheckIn](INFO): Running loop #9 2018-11-08T18:08:15.855Z,1541700495.855 [Default:CheckIn] Running Loop=9 2018-11-08T18:08:15.856Z,1541700495.856 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:08:15.856Z,1541700495.856 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:08:19.675Z,1541700499.675 [NAL9602](INFO): Powering up 2018-11-08T18:08:30.573Z,1541700510.573 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:08:39.774Z,1541700519.774 [NAL9602](INFO): SBD MO Status=0, MOMSN=10747, MT Status=0, MTMSN=0 2018-11-08T18:08:39.775Z,1541700519.775 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:09:06.990Z,1541700546.990 [NAL9602](INFO): GPS fix at 20181108T180833: (36.744684, -121.879757) 2018-11-08T18:09:07.218Z,1541700547.218 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:09:07.218Z,1541700547.218 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:09:11.823Z,1541700551.823 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181108T172705/Courier0018.lzma 2018-11-08T18:09:12.602Z,1541700552.602 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0018.lzma.bak 2018-11-08T18:09:12.602Z,1541700552.602 [DataOverHttps](INFO): SBD MOMSN=8818378 2018-11-08T18:09:22.028Z,1541700562.028 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181108T172705/Express0019.lzma 2018-11-08T18:09:22.778Z,1541700562.778 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0019.lzma.bak 2018-11-08T18:09:22.778Z,1541700562.778 [DataOverHttps](INFO): SBD MOMSN=8818381 2018-11-08T18:09:23.315Z,1541700563.315 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:09:23.315Z,1541700563.315 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:09:23.315Z,1541700563.315 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:09:42.121Z,1541700582.121 [NAL9602](INFO): Powering down 2018-11-08T18:14:23.708Z,1541700863.708 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:14:23.708Z,1541700863.708 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:14:23.708Z,1541700863.708 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:14:23.709Z,1541700863.709 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:14:24.111Z,1541700864.111 [Default:CheckIn:D] Stopped 2018-11-08T18:14:24.111Z,1541700864.111 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:14:24.600Z,1541700864.600 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.631942 min 2018-11-08T18:14:24.601Z,1541700864.601 [Default:CheckIn:E] Stopped 2018-11-08T18:14:24.601Z,1541700864.601 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:14:24.602Z,1541700864.602 [Default:CheckIn] Stopped 2018-11-08T18:14:24.602Z,1541700864.602 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:14:24.603Z,1541700864.603 [Default:CheckIn](INFO): Running loop #10 2018-11-08T18:14:24.603Z,1541700864.603 [Default:CheckIn] Running Loop=10 2018-11-08T18:14:24.604Z,1541700864.604 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:14:24.604Z,1541700864.604 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:14:27.889Z,1541700867.889 [NAL9602](INFO): Powering up 2018-11-08T18:14:39.037Z,1541700879.037 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:15:04.654Z,1541700904.654 [NAL9602](INFO): SBD MO Status=0, MOMSN=10748, MT Status=0, MTMSN=0 2018-11-08T18:15:04.655Z,1541700904.655 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:15:34.949Z,1541700934.949 [NAL9602](INFO): GPS fix at 20181108T181501: (36.774276, -121.838351) 2018-11-08T18:15:35.023Z,1541700935.023 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:15:35.023Z,1541700935.023 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:15:39.792Z,1541700939.792 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181108T172705/Courier0021.lzma 2018-11-08T18:15:40.578Z,1541700940.578 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0021.lzma.bak 2018-11-08T18:15:40.578Z,1541700940.578 [DataOverHttps](INFO): SBD MOMSN=8818426 2018-11-08T18:15:49.982Z,1541700949.982 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20181108T172705/Express0022.lzma 2018-11-08T18:15:50.746Z,1541700950.746 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0022.lzma.bak 2018-11-08T18:15:50.746Z,1541700950.746 [DataOverHttps](INFO): SBD MOMSN=8818433 2018-11-08T18:15:51.263Z,1541700951.263 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:15:51.263Z,1541700951.263 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:15:51.264Z,1541700951.264 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:16:10.101Z,1541700970.101 [NAL9602](INFO): Powering down 2018-11-08T18:20:51.951Z,1541701251.951 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:20:51.951Z,1541701251.951 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:20:51.951Z,1541701251.951 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:20:51.952Z,1541701251.952 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:20:52.421Z,1541701252.421 [Default:CheckIn:D] Stopped 2018-11-08T18:20:52.422Z,1541701252.422 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:20:52.755Z,1541701252.755 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 71.103784 min 2018-11-08T18:20:52.755Z,1541701252.755 [Default:CheckIn:E] Stopped 2018-11-08T18:20:52.755Z,1541701252.755 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:20:52.759Z,1541701252.759 [Default:CheckIn] Stopped 2018-11-08T18:20:52.759Z,1541701252.759 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:20:52.760Z,1541701252.760 [Default:CheckIn](INFO): Running loop #11 2018-11-08T18:20:52.760Z,1541701252.760 [Default:CheckIn] Running Loop=11 2018-11-08T18:20:52.760Z,1541701252.760 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:20:52.760Z,1541701252.760 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:20:56.466Z,1541701256.466 [NAL9602](INFO): Powering up 2018-11-08T18:21:07.445Z,1541701267.445 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:21:21.858Z,1541701281.858 [NAL9602](INFO): SBD MO Status=0, MOMSN=10749, MT Status=0, MTMSN=0 2018-11-08T18:21:21.858Z,1541701281.858 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:21:57.393Z,1541701317.393 [NAL9602](INFO): GPS fix at 20181108T182123: (36.806042, -121.790999) 2018-11-08T18:21:57.467Z,1541701317.467 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:21:57.467Z,1541701317.467 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:22:02.588Z,1541701322.588 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181108T172705/Courier0024.lzma 2018-11-08T18:22:03.386Z,1541701323.386 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0024.lzma.bak 2018-11-08T18:22:03.386Z,1541701323.386 [DataOverHttps](INFO): SBD MOMSN=8818461 2018-11-08T18:22:13.003Z,1541701333.003 [DataOverHttps](INFO): Sending 136 bytes from file Logs/20181108T172705/Express0025.lzma 2018-11-08T18:22:13.794Z,1541701333.794 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0025.lzma.bak 2018-11-08T18:22:13.794Z,1541701333.794 [DataOverHttps](INFO): SBD MOMSN=8818464 2018-11-08T18:22:14.346Z,1541701334.346 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:22:14.347Z,1541701334.347 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:22:14.347Z,1541701334.347 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:22:32.453Z,1541701352.453 [NAL9602](INFO): Powering down 2018-11-08T18:27:14.661Z,1541701634.661 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:27:14.661Z,1541701634.661 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:27:14.661Z,1541701634.661 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:27:14.662Z,1541701634.662 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:27:15.020Z,1541701635.020 [Default:CheckIn:D] Stopped 2018-11-08T18:27:15.020Z,1541701635.020 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:27:15.426Z,1541701635.426 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.480428 min 2018-11-08T18:27:15.426Z,1541701635.426 [Default:CheckIn:E] Stopped 2018-11-08T18:27:15.426Z,1541701635.426 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:27:15.426Z,1541701635.426 [Default:CheckIn] Stopped 2018-11-08T18:27:15.427Z,1541701635.427 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:27:15.427Z,1541701635.427 [Default:CheckIn](INFO): Running loop #12 2018-11-08T18:27:15.427Z,1541701635.427 [Default:CheckIn] Running Loop=12 2018-11-08T18:27:15.427Z,1541701635.427 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:27:15.428Z,1541701635.428 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:27:18.852Z,1541701638.852 [NAL9602](INFO): Powering up 2018-11-08T18:27:30.005Z,1541701650.005 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:27:40.802Z,1541701660.802 [NAL9602](INFO): SBD MO Status=0, MOMSN=10750, MT Status=0, MTMSN=0 2018-11-08T18:27:40.802Z,1541701660.802 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:28:00.019Z,1541701680.019 [NAL9602](INFO): GPS fix at 20181108T182726: (36.803497, -121.786088) 2018-11-08T18:28:00.082Z,1541701680.082 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:28:00.082Z,1541701680.082 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:28:04.796Z,1541701684.796 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181108T172705/Courier0027.lzma 2018-11-08T18:28:05.574Z,1541701685.574 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0027.lzma.bak 2018-11-08T18:28:05.575Z,1541701685.575 [DataOverHttps](INFO): SBD MOMSN=8818546 2018-11-08T18:28:14.840Z,1541701694.841 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20181108T172705/Express0028.lzma 2018-11-08T18:28:15.630Z,1541701695.630 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0028.lzma.bak 2018-11-08T18:28:15.630Z,1541701695.630 [DataOverHttps](INFO): SBD MOMSN=8818549 2018-11-08T18:28:16.137Z,1541701696.137 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:28:16.137Z,1541701696.137 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:28:16.137Z,1541701696.137 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:28:35.017Z,1541701715.017 [NAL9602](INFO): Powering down 2018-11-08T18:33:16.537Z,1541701996.537 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:33:16.537Z,1541701996.537 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:33:16.537Z,1541701996.537 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:33:16.538Z,1541701996.538 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:33:16.864Z,1541701996.864 [Default:CheckIn:D] Stopped 2018-11-08T18:33:16.864Z,1541701996.864 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:33:17.242Z,1541701997.242 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 83.511165 min 2018-11-08T18:33:17.243Z,1541701997.243 [Default:CheckIn:E] Stopped 2018-11-08T18:33:17.243Z,1541701997.243 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:33:17.243Z,1541701997.243 [Default:CheckIn] Stopped 2018-11-08T18:33:17.243Z,1541701997.243 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:33:17.244Z,1541701997.244 [Default:CheckIn](INFO): Running loop #13 2018-11-08T18:33:17.244Z,1541701997.244 [Default:CheckIn] Running Loop=13 2018-11-08T18:33:17.244Z,1541701997.244 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:33:17.244Z,1541701997.244 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:33:20.723Z,1541702000.723 [NAL9602](INFO): Powering up 2018-11-08T18:33:31.897Z,1541702011.897 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:34:02.290Z,1541702042.290 [NAL9602](INFO): SBD MO Status=2, MOMSN=10751, MT Status=2, MTMSN=0 2018-11-08T18:34:02.290Z,1541702042.290 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-11-08T18:34:20.811Z,1541702060.811 [NAL9602](INFO): SBD MO Status=2, MOMSN=10751, MT Status=2, MTMSN=0 2018-11-08T18:34:20.812Z,1541702060.812 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-11-08T18:34:27.714Z,1541702067.714 [NAL9602](INFO): SBD MO Status=0, MOMSN=10751, MT Status=0, MTMSN=0 2018-11-08T18:34:27.715Z,1541702067.715 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:34:28.917Z,1541702068.917 [NAL9602](INFO): GPS fix at 20181108T183355: (36.802724, -121.786946) 2018-11-08T18:34:29.013Z,1541702069.013 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:34:29.013Z,1541702069.013 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:34:34.136Z,1541702074.136 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181108T172705/Courier0030.lzma 2018-11-08T18:34:34.936Z,1541702074.936 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0030.lzma.bak 2018-11-08T18:34:34.936Z,1541702074.936 [DataOverHttps](INFO): SBD MOMSN=8818586 2018-11-08T18:34:44.687Z,1541702084.687 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20181108T172705/Express0031.lzma 2018-11-08T18:34:45.482Z,1541702085.482 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0031.lzma.bak 2018-11-08T18:34:45.482Z,1541702085.482 [DataOverHttps](INFO): SBD MOMSN=8818589 2018-11-08T18:34:45.990Z,1541702085.990 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:34:45.990Z,1541702085.990 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:34:45.990Z,1541702085.990 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:35:03.933Z,1541702103.933 [NAL9602](INFO): Powering down 2018-11-08T18:39:46.584Z,1541702386.584 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:39:46.585Z,1541702386.585 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:39:46.585Z,1541702386.585 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:39:46.585Z,1541702386.585 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:39:46.942Z,1541702386.942 [Default:CheckIn:D] Stopped 2018-11-08T18:39:46.942Z,1541702386.942 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:39:47.342Z,1541702387.342 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 90.012459 min 2018-11-08T18:39:47.342Z,1541702387.342 [Default:CheckIn:E] Stopped 2018-11-08T18:39:47.342Z,1541702387.342 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:39:47.342Z,1541702387.342 [Default:CheckIn] Stopped 2018-11-08T18:39:47.343Z,1541702387.343 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:39:47.343Z,1541702387.343 [Default:CheckIn](INFO): Running loop #14 2018-11-08T18:39:47.343Z,1541702387.343 [Default:CheckIn] Running Loop=14 2018-11-08T18:39:47.343Z,1541702387.343 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:39:47.343Z,1541702387.343 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:39:51.172Z,1541702391.172 [NAL9602](INFO): Powering up 2018-11-08T18:40:02.065Z,1541702402.065 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:40:14.066Z,1541702414.066 [NAL9602](INFO): SBD MO Status=0, MOMSN=10752, MT Status=0, MTMSN=0 2018-11-08T18:40:14.066Z,1541702414.066 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:41:06.865Z,1541702466.865 [NAL9602](INFO): GPS fix at 20181108T184033: (36.802809, -121.787961) 2018-11-08T18:41:06.971Z,1541702466.971 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:41:06.972Z,1541702466.972 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:41:12.323Z,1541702472.323 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181108T172705/Courier0033.lzma 2018-11-08T18:41:13.118Z,1541702473.118 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0033.lzma.bak 2018-11-08T18:41:13.118Z,1541702473.118 [DataOverHttps](INFO): SBD MOMSN=8818624 2018-11-08T18:41:23.052Z,1541702483.052 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20181108T172705/Express0034.lzma 2018-11-08T18:41:23.850Z,1541702483.850 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0034.lzma.bak 2018-11-08T18:41:23.850Z,1541702483.850 [DataOverHttps](INFO): SBD MOMSN=8818627 2018-11-08T18:41:24.551Z,1541702484.551 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:41:24.551Z,1541702484.551 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:41:24.563Z,1541702484.563 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:41:42.089Z,1541702502.089 [NAL9602](INFO): Powering down 2018-11-08T18:46:24.772Z,1541702784.772 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:46:24.772Z,1541702784.772 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:46:24.772Z,1541702784.772 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:46:24.773Z,1541702784.773 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:46:25.109Z,1541702785.109 [Default:CheckIn:D] Stopped 2018-11-08T18:46:25.109Z,1541702785.109 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:46:25.546Z,1541702785.546 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 96.648568 min 2018-11-08T18:46:25.546Z,1541702785.546 [Default:CheckIn:E] Stopped 2018-11-08T18:46:25.546Z,1541702785.546 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:46:25.546Z,1541702785.546 [Default:CheckIn] Stopped 2018-11-08T18:46:25.546Z,1541702785.546 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:46:25.547Z,1541702785.547 [Default:CheckIn](INFO): Running loop #15 2018-11-08T18:46:25.547Z,1541702785.547 [Default:CheckIn] Running Loop=15 2018-11-08T18:46:25.547Z,1541702785.547 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:46:25.547Z,1541702785.547 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:46:26.245Z,1541702786.245 [NAL9602](INFO): Powering up 2018-11-08T18:46:37.121Z,1541702797.121 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:46:51.522Z,1541702811.522 [NAL9602](INFO): SBD MO Status=0, MOMSN=10753, MT Status=0, MTMSN=0 2018-11-08T18:46:51.522Z,1541702811.522 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:47:05.133Z,1541702825.133 [NAL9602](INFO): GPS fix at 20181108T184631: (36.802936, -121.787998) 2018-11-08T18:47:05.185Z,1541702825.185 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:47:05.186Z,1541702825.186 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:47:10.204Z,1541702830.204 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20181108T172705/Courier0036.lzma 2018-11-08T18:47:11.006Z,1541702831.006 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0036.lzma.bak 2018-11-08T18:47:11.006Z,1541702831.006 [DataOverHttps](INFO): SBD MOMSN=8818705 2018-11-08T18:47:20.982Z,1541702840.982 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20181108T172705/Express0037.lzma 2018-11-08T18:47:21.774Z,1541702841.774 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0037.lzma.bak 2018-11-08T18:47:21.774Z,1541702841.774 [DataOverHttps](INFO): SBD MOMSN=8818708 2018-11-08T18:47:22.282Z,1541702842.282 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:47:22.283Z,1541702842.283 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:47:22.283Z,1541702842.283 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:47:40.161Z,1541702860.161 [NAL9602](INFO): Powering down 2018-11-08T18:52:23.015Z,1541703143.015 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:52:23.015Z,1541703143.015 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:52:23.015Z,1541703143.015 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:52:23.016Z,1541703143.016 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:52:23.424Z,1541703143.424 [Default:CheckIn:D] Stopped 2018-11-08T18:52:23.424Z,1541703143.424 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:52:23.830Z,1541703143.830 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.620483 min 2018-11-08T18:52:23.831Z,1541703143.831 [Default:CheckIn:E] Stopped 2018-11-08T18:52:23.831Z,1541703143.831 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:52:23.831Z,1541703143.831 [Default:CheckIn] Stopped 2018-11-08T18:52:23.831Z,1541703143.831 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:52:23.832Z,1541703143.832 [Default:CheckIn](INFO): Running loop #16 2018-11-08T18:52:23.832Z,1541703143.832 [Default:CheckIn] Running Loop=16 2018-11-08T18:52:23.832Z,1541703143.832 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:52:23.832Z,1541703143.832 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:52:27.365Z,1541703147.365 [NAL9602](INFO): Powering up 2018-11-08T18:52:38.549Z,1541703158.549 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:53:30.531Z,1541703210.531 [NAL9602](INFO): SBD MO Status=0, MOMSN=10754, MT Status=0, MTMSN=0 2018-11-08T18:53:30.532Z,1541703210.532 [NAL9602](INFO): No messages in MT queue 2018-11-08T18:53:31.713Z,1541703211.713 [NAL9602](INFO): GPS fix at 20181108T185257: (36.802907, -121.788021) 2018-11-08T18:53:31.788Z,1541703211.788 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T18:53:31.788Z,1541703211.788 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T18:53:36.657Z,1541703216.657 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20181108T172705/Courier0039.lzma 2018-11-08T18:53:37.446Z,1541703217.446 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0039.lzma.bak 2018-11-08T18:53:37.446Z,1541703217.446 [DataOverHttps](INFO): SBD MOMSN=8818712 2018-11-08T18:53:46.966Z,1541703226.966 [DataOverHttps](INFO): Sending 240 bytes from file Logs/20181108T172705/Express0040.lzma 2018-11-08T18:53:47.734Z,1541703227.734 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0040.lzma.bak 2018-11-08T18:53:47.734Z,1541703227.734 [DataOverHttps](INFO): SBD MOMSN=8818715 2018-11-08T18:53:48.240Z,1541703228.240 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T18:53:48.240Z,1541703228.240 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T18:53:48.240Z,1541703228.240 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T18:54:03.317Z,1541703243.317 [NAL9602](INFO): Powering down 2018-11-08T18:58:48.752Z,1541703528.752 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T18:58:48.752Z,1541703528.752 [Default:CheckIn:C.Wait] Stopped 2018-11-08T18:58:48.752Z,1541703528.752 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T18:58:48.753Z,1541703528.753 [Default:CheckIn:D] Running Loop=1 2018-11-08T18:58:49.188Z,1541703529.188 [Default:CheckIn:D] Stopped 2018-11-08T18:58:49.188Z,1541703529.188 [Default:CheckIn:E] Running Loop=1 2018-11-08T18:58:49.541Z,1541703529.541 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 109.049894 min 2018-11-08T18:58:49.541Z,1541703529.541 [Default:CheckIn:E] Stopped 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn] Stopped 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn](INFO): Running loop #17 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn] Running Loop=17 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T18:58:49.542Z,1541703529.542 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T18:58:53.093Z,1541703533.093 [NAL9602](INFO): Powering up 2018-11-08T18:59:04.261Z,1541703544.261 [NAL9602](INFO): NAL9602 initialized 2018-11-08T18:59:15.467Z,1541703555.467 [NAL9602](INFO): SBD MO Status=0, MOMSN=10755, MT Status=0, MTMSN=0 2018-11-08T18:59:15.467Z,1541703555.467 [NAL9602](INFO): No messages in MT queue 2018-11-08T19:00:34.797Z,1541703634.797 [NAL9602](INFO): GPS fix at 20181108T190000: (36.802891, -121.787994) 2018-11-08T19:00:34.943Z,1541703634.943 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:00:34.944Z,1541703634.944 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T19:00:39.575Z,1541703639.575 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20181108T172705/Courier0042.lzma 2018-11-08T19:00:40.374Z,1541703640.374 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0042.lzma.bak 2018-11-08T19:00:40.374Z,1541703640.374 [DataOverHttps](INFO): SBD MOMSN=8818783 2018-11-08T19:00:50.576Z,1541703650.576 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181108T172705/Express0043.lzma 2018-11-08T19:00:51.370Z,1541703651.370 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0043.lzma.bak 2018-11-08T19:00:51.370Z,1541703651.370 [DataOverHttps](INFO): SBD MOMSN=8818787 2018-11-08T19:00:51.875Z,1541703651.875 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T19:00:51.875Z,1541703651.875 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T19:00:51.875Z,1541703651.875 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T19:01:09.901Z,1541703669.901 [NAL9602](INFO): Powering down 2018-11-08T19:05:52.552Z,1541703952.552 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T19:05:52.552Z,1541703952.552 [Default:CheckIn:C.Wait] Stopped 2018-11-08T19:05:52.552Z,1541703952.552 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T19:05:52.552Z,1541703952.552 [Default:CheckIn:D] Running Loop=1 2018-11-08T19:05:52.965Z,1541703952.965 [Default:CheckIn:D] Stopped 2018-11-08T19:05:52.965Z,1541703952.965 [Default:CheckIn:E] Running Loop=1 2018-11-08T19:05:53.362Z,1541703953.362 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 116.112834 min 2018-11-08T19:05:53.363Z,1541703953.363 [Default:CheckIn:E] Stopped 2018-11-08T19:05:53.363Z,1541703953.363 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T19:05:53.363Z,1541703953.363 [Default:CheckIn] Stopped 2018-11-08T19:05:53.363Z,1541703953.363 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:05:53.367Z,1541703953.367 [Default:CheckIn](INFO): Running loop #18 2018-11-08T19:05:53.367Z,1541703953.367 [Default:CheckIn] Running Loop=18 2018-11-08T19:05:53.368Z,1541703953.368 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T19:05:53.368Z,1541703953.368 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T19:05:56.887Z,1541703956.887 [NAL9602](INFO): Powering up 2018-11-08T19:06:08.077Z,1541703968.077 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:10:53.461Z,1541704253.461 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-08T19:05:53.4Z 2018-11-08T19:10:53.461Z,1541704253.461 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:10:53.461Z,1541704253.461 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T19:10:58.203Z,1541704258.203 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Courier0045.lzma 2018-11-08T19:10:58.973Z,1541704258.973 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0045.lzma.bak 2018-11-08T19:10:58.973Z,1541704258.973 [DataOverHttps](INFO): SBD MOMSN=8818864 2018-11-08T19:11:11.229Z,1541704271.229 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-11-08T19:11:39.190Z,1541704299.190 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20181108T172705/Express0046.lzma 2018-11-08T19:11:39.982Z,1541704299.982 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0046.lzma.bak 2018-11-08T19:11:39.982Z,1541704299.982 [DataOverHttps](INFO): SBD MOMSN=8818866 2018-11-08T19:11:40.486Z,1541704300.486 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T19:11:40.487Z,1541704300.487 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T19:11:40.487Z,1541704300.487 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T19:11:44.329Z,1541704304.329 [NAL9602](INFO): Powering down 2018-11-08T19:16:40.891Z,1541704600.891 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T19:16:40.891Z,1541704600.891 [Default:CheckIn:C.Wait] Stopped 2018-11-08T19:16:40.891Z,1541704600.891 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T19:16:40.904Z,1541704600.904 [Default:CheckIn:D] Running Loop=1 2018-11-08T19:16:41.335Z,1541704601.335 [Default:CheckIn:D] Stopped 2018-11-08T19:16:41.335Z,1541704601.335 [Default:CheckIn:E] Running Loop=1 2018-11-08T19:16:41.753Z,1541704601.753 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 126.919010 min 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn:E] Stopped 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn] Stopped 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn](INFO): Running loop #19 2018-11-08T19:16:41.754Z,1541704601.754 [Default:CheckIn] Running Loop=19 2018-11-08T19:16:41.755Z,1541704601.755 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T19:16:41.755Z,1541704601.755 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T19:16:49.581Z,1541704609.581 [NAL9602](INFO): Powering up 2018-11-08T19:17:00.749Z,1541704620.749 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:17:01.549Z,1541704621.549 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-11-08T19:17:01.549Z,1541704621.549 [NAL9602] Data Fault, FailCount= 1 2018-11-08T19:17:01.549Z,1541704621.549 [NAL9602](ERROR): Data Fault 2018-11-08T19:17:01.692Z,1541704621.692 [CBIT](ERROR): Data Fault in component: NAL9602 2018-11-08T19:17:01.949Z,1541704621.949 [NAL9602](INFO): Powering down 2018-11-08T19:17:02.854Z,1541704622.854 [CBIT](INFO): Clearing failed state for component NAL9602 2018-11-08T19:17:02.854Z,1541704622.854 [NAL9602] No Fault, FailCount= 1 2018-11-08T19:17:32.354Z,1541704652.354 [NAL9602](INFO): Powering up NAL9602 2018-11-08T19:17:49.989Z,1541704669.989 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:21:41.810Z,1541704901.810 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-08T19:16:41.8Z 2018-11-08T19:21:41.810Z,1541704901.810 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:21:41.811Z,1541704901.811 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T19:21:50.426Z,1541704910.426 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Courier0048.lzma 2018-11-08T19:21:51.178Z,1541704911.178 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0048.lzma.bak 2018-11-08T19:21:51.178Z,1541704911.178 [DataOverHttps](INFO): SBD MOMSN=8818936 2018-11-08T19:22:08.782Z,1541704928.782 [DataOverHttps](INFO): Sending 238 bytes from file Logs/20181108T172705/Express0049.lzma 2018-11-08T19:22:09.582Z,1541704929.582 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0049.lzma.bak 2018-11-08T19:22:09.582Z,1541704929.582 [DataOverHttps](INFO): SBD MOMSN=8818938 2018-11-08T19:22:10.187Z,1541704930.187 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T19:22:10.207Z,1541704930.207 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T19:22:10.207Z,1541704930.207 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T19:22:53.425Z,1541704973.425 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-11-08T19:23:24.157Z,1541705004.157 [NAL9602](INFO): Powering down 2018-11-08T19:27:10.623Z,1541705230.623 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T19:27:10.632Z,1541705230.632 [Default:CheckIn:C.Wait] Stopped 2018-11-08T19:27:10.632Z,1541705230.632 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T19:27:10.633Z,1541705230.633 [Default:CheckIn:D] Running Loop=1 2018-11-08T19:27:11.025Z,1541705231.025 [Default:CheckIn:D] Stopped 2018-11-08T19:27:11.025Z,1541705231.025 [Default:CheckIn:E] Running Loop=1 2018-11-08T19:27:11.418Z,1541705231.418 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.413835 min 2018-11-08T19:27:11.418Z,1541705231.418 [Default:CheckIn:E] Stopped 2018-11-08T19:27:11.418Z,1541705231.418 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T19:27:11.418Z,1541705231.418 [Default:CheckIn] Stopped 2018-11-08T19:27:11.418Z,1541705231.418 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:27:11.419Z,1541705231.419 [Default:CheckIn](INFO): Running loop #20 2018-11-08T19:27:11.419Z,1541705231.419 [Default:CheckIn] Running Loop=20 2018-11-08T19:27:11.419Z,1541705231.419 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T19:27:11.419Z,1541705231.419 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T19:27:18.734Z,1541705238.734 [NAL9602](INFO): Powering up 2018-11-08T19:27:29.917Z,1541705249.917 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:28:01.905Z,1541705281.905 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-11-08T19:28:01.980Z,1541705281.980 [NAL9602](FAULT): received: +CSQ:0 OK755, 0, 0, 0, 0 OK 2018-11-08T19:28:01.980Z,1541705281.980 [NAL9602] Data Fault, FailCount= 2 2018-11-08T19:28:01.980Z,1541705281.980 [NAL9602](ERROR): Data Fault 2018-11-08T19:28:02.083Z,1541705282.083 [CBIT](ERROR): Data Fault in component: NAL9602 2018-11-08T19:28:02.305Z,1541705282.305 [NAL9602](INFO): Powering down 2018-11-08T19:28:03.259Z,1541705283.259 [CBIT](INFO): Clearing failed state for component NAL9602 2018-11-08T19:28:03.259Z,1541705283.259 [NAL9602] No Fault, FailCount= 2 2018-11-08T19:28:32.349Z,1541705312.349 [NAL9602](INFO): Powering up NAL9602 2018-11-08T19:28:43.145Z,1541705323.145 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:28:43.945Z,1541705323.945 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-11-08T19:28:43.945Z,1541705323.945 [NAL9602] Data Fault, FailCount= 3 2018-11-08T19:28:43.945Z,1541705323.945 [NAL9602](ERROR): Data Fault 2018-11-08T19:28:44.086Z,1541705324.086 [CBIT](ERROR): Data Fault in component: NAL9602 2018-11-08T19:28:44.350Z,1541705324.350 [NAL9602](INFO): Powering down 2018-11-08T19:28:45.285Z,1541705325.285 [CBIT](INFO): Clearing failed state for component NAL9602 2018-11-08T19:28:45.285Z,1541705325.285 [NAL9602] No Fault, FailCount= 3 2018-11-08T19:29:19.102Z,1541705359.102 [NAL9602](INFO): Powering up NAL9602 2018-11-08T19:29:30.061Z,1541705370.061 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:32:11.725Z,1541705531.725 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-08T19:27:11.4Z 2018-11-08T19:32:11.725Z,1541705531.725 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:32:11.725Z,1541705531.725 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T19:32:16.993Z,1541705536.993 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Courier0051.lzma 2018-11-08T19:32:17.786Z,1541705537.786 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0051.lzma.bak 2018-11-08T19:32:17.786Z,1541705537.786 [DataOverHttps](INFO): SBD MOMSN=8818979 2018-11-08T19:32:27.272Z,1541705547.272 [DataOverHttps](INFO): Sending 253 bytes from file Logs/20181108T172705/Express0052.lzma 2018-11-08T19:32:28.038Z,1541705548.038 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0052.lzma.bak 2018-11-08T19:32:28.038Z,1541705548.038 [DataOverHttps](INFO): SBD MOMSN=8818981 2018-11-08T19:32:28.566Z,1541705548.566 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T19:32:28.566Z,1541705548.566 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T19:32:28.567Z,1541705548.567 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T19:32:32.813Z,1541705552.813 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-11-08T19:33:03.618Z,1541705583.618 [NAL9602](INFO): Powering down 2018-11-08T19:37:29.158Z,1541705849.158 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T19:37:29.159Z,1541705849.159 [Default:CheckIn:C.Wait] Stopped 2018-11-08T19:37:29.159Z,1541705849.159 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T19:37:29.159Z,1541705849.159 [Default:CheckIn:D] Running Loop=1 2018-11-08T19:37:29.578Z,1541705849.578 [Default:CheckIn:D] Stopped 2018-11-08T19:37:29.578Z,1541705849.578 [Default:CheckIn:E] Running Loop=1 2018-11-08T19:37:29.982Z,1541705849.982 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.723063 min 2018-11-08T19:37:29.983Z,1541705849.983 [Default:CheckIn:E] Stopped 2018-11-08T19:37:29.983Z,1541705849.983 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T19:37:29.983Z,1541705849.983 [Default:CheckIn] Stopped 2018-11-08T19:37:29.983Z,1541705849.983 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:37:30.007Z,1541705850.007 [Default:CheckIn](INFO): Running loop #21 2018-11-08T19:37:30.007Z,1541705850.007 [Default:CheckIn] Running Loop=21 2018-11-08T19:37:30.008Z,1541705850.008 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T19:37:30.008Z,1541705850.008 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T19:37:33.750Z,1541705853.750 [NAL9602](INFO): Powering up 2018-11-08T19:37:44.673Z,1541705864.673 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:38:16.665Z,1541705896.665 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-11-08T19:38:16.747Z,1541705896.747 [NAL9602](FAULT): received: +CSQ:0 OK755, 0, 0, 0, 0 OK 2018-11-08T19:38:16.747Z,1541705896.747 [NAL9602] Data Fault, FailCount= 4 2018-11-08T19:38:16.748Z,1541705896.748 [NAL9602](ERROR): Data Fault 2018-11-08T19:38:16.859Z,1541705896.859 [CBIT](ERROR): Data Fault in component: NAL9602 2018-11-08T19:38:17.074Z,1541705897.074 [NAL9602](INFO): Powering down 2018-11-08T19:38:17.933Z,1541705897.933 [CBIT](INFO): Clearing failed state for component NAL9602 2018-11-08T19:38:17.933Z,1541705897.933 [NAL9602] No Fault, FailCount= 4 2018-11-08T19:38:47.293Z,1541705927.293 [NAL9602](INFO): Powering up NAL9602 2018-11-08T19:38:58.493Z,1541705938.493 [NAL9602](INFO): NAL9602 initialized 2018-11-08T19:42:30.017Z,1541706150.017 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-11-08T19:37:30.0Z 2018-11-08T19:42:30.018Z,1541706150.018 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:42:30.018Z,1541706150.018 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-11-08T19:42:34.711Z,1541706154.711 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20181108T172705/Courier0054.lzma 2018-11-08T19:42:35.494Z,1541706155.494 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Courier0054.lzma.bak 2018-11-08T19:42:35.494Z,1541706155.494 [DataOverHttps](INFO): SBD MOMSN=8819026 2018-11-08T19:42:45.126Z,1541706165.126 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20181108T172705/Express0055.lzma 2018-11-08T19:42:45.926Z,1541706165.926 [DataOverHttps](INFO): Moved sent file to Logs/20181108T172705/Express0055.lzma.bak 2018-11-08T19:42:45.927Z,1541706165.927 [DataOverHttps](INFO): SBD MOMSN=8819028 2018-11-08T19:42:46.529Z,1541706166.529 [Default:CheckIn:Read_Iridium] Stopped 2018-11-08T19:42:46.529Z,1541706166.529 [Default:CheckIn:C.Wait] Running Loop=1 2018-11-08T19:42:46.529Z,1541706166.529 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-11-08T19:42:50.037Z,1541706170.037 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-11-08T19:43:20.557Z,1541706200.557 [NAL9602](INFO): Powering down 2018-11-08T19:47:46.822Z,1541706466.822 [CommandLine](IMPORTANT): got command quit 2018-11-08T19:47:46.849Z,1541706466.849 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-11-08T19:47:46.849Z,1541706466.849 [Default:CheckIn:C.Wait] Stopped 2018-11-08T19:47:46.849Z,1541706466.849 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-11-08T19:47:46.850Z,1541706466.850 [Default:CheckIn:D] Running Loop=1 2018-11-08T19:47:47.230Z,1541706467.230 [Default:CheckIn:D] Stopped 2018-11-08T19:47:47.231Z,1541706467.231 [Default:CheckIn:E] Running Loop=1 2018-11-08T19:47:47.646Z,1541706467.646 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 158.017269 min 2018-11-08T19:47:47.646Z,1541706467.646 [Default:CheckIn:E] Stopped 2018-11-08T19:47:47.646Z,1541706467.646 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-11-08T19:47:47.646Z,1541706467.646 [Default:CheckIn] Stopped 2018-11-08T19:47:47.646Z,1541706467.646 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:47:47.647Z,1541706467.647 [Default:CheckIn](INFO): Running loop #22 2018-11-08T19:47:47.647Z,1541706467.647 [Default:CheckIn] Running Loop=22 2018-11-08T19:47:47.647Z,1541706467.647 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-11-08T19:47:47.647Z,1541706467.647 [Default:CheckIn:Read_GPS] Running Loop=1 2018-11-08T19:47:47.832Z,1541706467.832 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:47.832Z,1541706467.832 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:47.855Z,1541706467.855 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-11-08T19:47:47.855Z,1541706467.855 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:47.856Z,1541706467.856 [CommandLine](INFO): Join timeout helper Thread ID is 4773 2018-11-08T19:47:47.857Z,1541706467.857 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-11-08T19:47:47.857Z,1541706467.857 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:47.857Z,1541706467.857 [NavChartDb](INFO): Join timeout helper Thread ID is 4774 2018-11-08T19:47:48.156Z,1541706468.156 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.156Z,1541706468.156 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.171Z,1541706468.171 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-11-08T19:47:48.172Z,1541706468.172 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.172Z,1541706468.172 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 4775 2018-11-08T19:47:48.292Z,1541706468.292 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.292Z,1541706468.292 [WetLabsBB2FL](INFO): Powering down 2018-11-08T19:47:48.293Z,1541706468.293 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.312Z,1541706468.312 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2018-11-08T19:47:48.312Z,1541706468.312 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.312Z,1541706468.312 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 4776 2018-11-08T19:47:48.313Z,1541706468.313 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.313Z,1541706468.313 [CTD_NeilBrown](INFO): Powering down 2018-11-08T19:47:48.313Z,1541706468.313 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.314Z,1541706468.314 [ComponentRegistry](INFO): Shutting down Rowe_600LCM ThreadHandler 2018-11-08T19:47:48.314Z,1541706468.314 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.314Z,1541706468.314 [Rowe_600LCM](INFO): Join timeout helper Thread ID is 4777 2018-11-08T19:47:48.612Z,1541706468.612 [Rowe_600LCM ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.612Z,1541706468.612 [Rowe_600LCM](INFO): Stopping potential previous instance(s) of roweadcp LCM interface 2018-11-08T19:47:48.845Z,1541706468.845 [Rowe_600LCM](INFO): Powering down 2018-11-08T19:47:48.846Z,1541706468.846 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.864Z,1541706468.864 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-11-08T19:47:48.865Z,1541706468.865 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.865Z,1541706468.865 [Radio_Surface](INFO): Join timeout helper Thread ID is 4779 2018-11-08T19:47:48.952Z,1541706468.952 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.952Z,1541706468.952 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.968Z,1541706468.968 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-11-08T19:47:48.968Z,1541706468.968 [logger ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.969Z,1541706468.969 [logger](INFO): Join timeout helper Thread ID is 4780 2018-11-08T19:47:48.969Z,1541706468.969 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:48.970Z,1541706468.970 [logger ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.971Z,1541706468.971 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-11-08T19:47:48.971Z,1541706468.971 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.971Z,1541706468.971 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-11-08T19:47:48.971Z,1541706468.971 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:48.972Z,1541706468.972 [controlThread](INFO): Join timeout helper Thread ID is 4781 2018-11-08T19:47:51.148Z,1541706471.148 [NAL9602](INFO): Powering up 2018-11-08T19:47:51.206Z,1541706471.206 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-11-08T19:47:51.206Z,1541706471.206 [controlThread](DEBUG): Uninitializing ControlThread 2018-11-08T19:47:51.211Z,1541706471.211 [NAL9602](INFO): Powering down 2018-11-08T19:47:51.212Z,1541706471.212 [PNI_TCM](INFO): Powering down 2018-11-08T19:47:51.300Z,1541706471.300 [Aanderaa_O2](INFO): Powering down 2018-11-08T19:47:51.301Z,1541706471.301 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-11-08T19:47:51.302Z,1541706471.302 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-11-08T19:47:51.303Z,1541706471.303 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-11-08T19:47:51.304Z,1541706471.304 [MissionManager](INFO): Uninitializing Mission Default 2018-11-08T19:47:51.304Z,1541706471.304 [Default] Stopped 2018-11-08T19:47:51.304Z,1541706471.304 [Default](DEBUG): Aggregate::uninitialize Default 2018-11-08T19:47:51.304Z,1541706471.304 [Default:B.GoToSurface] Stopped 2018-11-08T19:47:51.304Z,1541706471.304 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-11-08T19:47:51.304Z,1541706471.304 [Default:CheckIn] Stopped 2018-11-08T19:47:51.305Z,1541706471.305 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-11-08T19:47:51.305Z,1541706471.305 [Default:CheckIn:Read_GPS] Stopped 2018-11-08T19:47:51.309Z,1541706471.309 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-11-08T19:47:51.309Z,1541706471.309 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-11-08T19:47:51.309Z,1541706471.309 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-11-08T19:47:51.310Z,1541706471.310 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-11-08T19:47:51.310Z,1541706471.310 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-11-08T19:47:51.310Z,1541706471.310 [BuoyancyServo](INFO): Powering down 2018-11-08T19:47:51.324Z,1541706471.324 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-11-08T19:47:51.324Z,1541706471.324 [ElevatorServo](INFO): Powering down 2018-11-08T19:47:51.325Z,1541706471.325 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-11-08T19:47:51.325Z,1541706471.325 [MassServo](INFO): Powering down 2018-11-08T19:47:51.326Z,1541706471.326 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-11-08T19:47:51.326Z,1541706471.326 [RudderServo](INFO): Powering down 2018-11-08T19:47:51.327Z,1541706471.327 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-11-08T19:47:51.327Z,1541706471.327 [ThrusterServo](INFO): Powering down 2018-11-08T19:47:51.328Z,1541706471.328 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-11-08T19:47:51.329Z,1541706471.329 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-11-08T19:47:51.329Z,1541706471.329 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-11-08T19:47:51.330Z,1541706471.330 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.398Z,1541706471.398 [Rowe_600LCM ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.405Z,1541706471.405 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.443Z,1541706471.443 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.447Z,1541706471.447 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.474Z,1541706471.474 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-11-08T19:47:51.589Z,1541706471.589 [logger ThreadHandler](INFO): Thread cancelled.