2018-08-06T18:14:22.694Z,1533579262.694 [CommandLine](IMPORTANT): got command restart logs 2018-08-06T18:18:13.701Z,1533579493.701 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T18:18:13.701Z,1533579493.701 [Default:CheckIn:C.Wait] Stopped 2018-08-06T18:18:13.702Z,1533579493.702 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T18:18:13.702Z,1533579493.702 [Default:CheckIn:D] Running Loop=1 2018-08-06T18:18:14.121Z,1533579494.121 [Default:CheckIn:D] Stopped 2018-08-06T18:18:14.121Z,1533579494.121 [Default:CheckIn:E] Running Loop=1 2018-08-06T18:18:14.508Z,1533579494.508 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 43.802157 min 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn:E] Stopped 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn] Stopped 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn](INFO): Running loop #6 2018-08-06T18:18:14.509Z,1533579494.509 [Default:CheckIn] Running Loop=6 2018-08-06T18:18:14.510Z,1533579494.510 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T18:18:14.510Z,1533579494.510 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T18:18:15.255Z,1533579495.255 [NAL9602](INFO): Powering up 2018-08-06T18:18:26.379Z,1533579506.379 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:18:38.781Z,1533579518.781 [NAL9602](INFO): SBD MO Status=2, MOMSN=23337, MT Status=2, MTMSN=0 2018-08-06T18:18:38.781Z,1533579518.781 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:18:57.985Z,1533579537.985 [NAL9602](INFO): SBD MO Status=0, MOMSN=23337, MT Status=0, MTMSN=0 2018-08-06T18:18:57.985Z,1533579537.985 [NAL9602](INFO): No messages in MT queue 2018-08-06T18:20:40.497Z,1533579640.497 [NAL9602](INFO): GPS fix at 20180806T181551: (36.821084, -121.843966) 2018-08-06T18:20:40.556Z,1533579640.556 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T18:20:40.557Z,1533579640.557 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T18:20:50.179Z,1533579650.179 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-06T18:21:12.594Z,1533579672.594 [NAL9602](INFO): Powering down 2018-08-06T18:21:20.582Z,1533579680.582 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-06T18:21:45.129Z,1533579705.129 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20180806T004129/Courier0133.lzma 2018-08-06T18:21:45.922Z,1533579705.922 [DataOverHttps](INFO): Moved sent file to Logs/20180806T004129/Courier0133.lzma.bak 2018-08-06T18:21:45.922Z,1533579705.922 [DataOverHttps](INFO): SBD MOMSN=8403411 2018-08-06T18:21:57.831Z,1533579717.831 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20180806T181422/Courier0000.lzma 2018-08-06T18:21:58.617Z,1533579718.617 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0000.lzma.bak 2018-08-06T18:21:58.617Z,1533579718.617 [DataOverHttps](INFO): SBD MOMSN=8403413 2018-08-06T18:22:11.140Z,1533579731.140 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0003.lzma 2018-08-06T18:22:11.937Z,1533579731.937 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0003.lzma.bak 2018-08-06T18:22:11.937Z,1533579731.937 [DataOverHttps](INFO): SBD MOMSN=8403417 2018-08-06T18:22:21.847Z,1533579741.847 [DataOverHttps](INFO): Sending 93 bytes from file Logs/20180806T004129/Express0134.lzma 2018-08-06T18:22:22.621Z,1533579742.621 [DataOverHttps](INFO): Moved sent file to Logs/20180806T004129/Express0134.lzma.bak 2018-08-06T18:22:22.622Z,1533579742.622 [DataOverHttps](INFO): SBD MOMSN=8403419 2018-08-06T18:22:33.636Z,1533579753.636 [DataOverHttps](INFO): Sending 344 bytes from file Logs/20180806T181422/Express0001.lzma 2018-08-06T18:22:34.409Z,1533579754.409 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0001.lzma.bak 2018-08-06T18:22:34.409Z,1533579754.409 [DataOverHttps](INFO): SBD MOMSN=8403422 2018-08-06T18:22:44.688Z,1533579764.688 [DataOverHttps](INFO): Sending 52 bytes from file Logs/20180806T181422/Express0004.lzma 2018-08-06T18:22:45.885Z,1533579765.885 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0004.lzma.bak 2018-08-06T18:22:45.885Z,1533579765.885 [DataOverHttps](INFO): SBD MOMSN=8403426 2018-08-06T18:22:47.267Z,1533579767.267 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T18:22:47.267Z,1533579767.267 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T18:22:47.267Z,1533579767.267 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T18:27:18.192Z,1533580038.192 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2018-08-06T18:27:47.458Z,1533580067.458 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T18:27:47.458Z,1533580067.458 [Default:CheckIn:C.Wait] Stopped 2018-08-06T18:27:47.458Z,1533580067.458 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T18:27:47.459Z,1533580067.459 [Default:CheckIn:D] Running Loop=1 2018-08-06T18:27:47.847Z,1533580067.847 [Default:CheckIn:D] Stopped 2018-08-06T18:27:47.847Z,1533580067.847 [Default:CheckIn:E] Running Loop=1 2018-08-06T18:27:48.252Z,1533580068.252 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.364250 min 2018-08-06T18:27:48.252Z,1533580068.252 [Default:CheckIn:E] Stopped 2018-08-06T18:27:48.252Z,1533580068.252 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T18:27:48.252Z,1533580068.252 [Default:CheckIn] Stopped 2018-08-06T18:27:48.252Z,1533580068.252 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T18:27:48.253Z,1533580068.253 [Default:CheckIn](INFO): Running loop #7 2018-08-06T18:27:48.253Z,1533580068.253 [Default:CheckIn] Running Loop=7 2018-08-06T18:27:48.253Z,1533580068.253 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T18:27:48.253Z,1533580068.253 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T18:27:48.995Z,1533580068.995 [NAL9602](INFO): Powering up 2018-08-06T18:27:59.799Z,1533580079.799 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:28:22.325Z,1533580102.325 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:28:22.325Z,1533580102.325 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:28:37.129Z,1533580117.129 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:28:37.129Z,1533580117.129 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:30:03.974Z,1533580203.974 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:30:03.974Z,1533580203.974 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:31:18.705Z,1533580278.705 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:31:18.705Z,1533580278.705 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:32:46.853Z,1533580366.853 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:32:46.853Z,1533580366.853 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:32:48.515Z,1533580368.515 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T18:27:48.3Z 2018-08-06T18:32:48.515Z,1533580368.515 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T18:32:48.515Z,1533580368.515 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T18:32:56.067Z,1533580376.067 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0006.lzma 2018-08-06T18:32:58.065Z,1533580378.065 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0006.lzma.bak 2018-08-06T18:32:58.065Z,1533580378.065 [DataOverHttps](INFO): SBD MOMSN=8403433 2018-08-06T18:33:16.617Z,1533580396.617 [NAL9602](INFO): SBD MO Status=2, MOMSN=23338, MT Status=2, MTMSN=0 2018-08-06T18:33:16.617Z,1533580396.617 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:33:17.011Z,1533580397.011 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T18:33:36.956Z,1533580416.956 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20180806T181422/Express0007.lzma 2018-08-06T18:33:38.552Z,1533580418.552 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2018-08-06T18:33:47.755Z,1533580427.755 [NAL9602](INFO): Powering down 2018-08-06T18:35:00.279Z,1533580500.279 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20180806T181422/Express0007.lzma 2018-08-06T18:35:01.877Z,1533580501.877 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0007.lzma.bak 2018-08-06T18:35:01.877Z,1533580501.877 [DataOverHttps](INFO): SBD MOMSN=8403435 2018-08-06T18:35:03.302Z,1533580503.302 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T18:35:03.303Z,1533580503.303 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T18:35:03.303Z,1533580503.303 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T18:40:03.658Z,1533580803.658 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T18:40:03.658Z,1533580803.658 [Default:CheckIn:C.Wait] Stopped 2018-08-06T18:40:03.658Z,1533580803.658 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T18:40:03.658Z,1533580803.658 [Default:CheckIn:D] Running Loop=1 2018-08-06T18:40:04.059Z,1533580804.059 [Default:CheckIn:D] Stopped 2018-08-06T18:40:04.059Z,1533580804.059 [Default:CheckIn:E] Running Loop=1 2018-08-06T18:40:04.459Z,1533580804.459 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.634452 min 2018-08-06T18:40:04.459Z,1533580804.459 [Default:CheckIn:E] Stopped 2018-08-06T18:40:04.459Z,1533580804.459 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn] Stopped 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn](INFO): Running loop #8 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn] Running Loop=8 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T18:40:04.460Z,1533580804.460 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T18:40:05.212Z,1533580805.212 [NAL9602](INFO): Powering up 2018-08-06T18:40:15.205Z,1533580815.205 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=180.400635 2018-08-06T18:40:16.407Z,1533580816.407 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:40:17.211Z,1533580817.211 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T18:40:17.211Z,1533580817.211 [NAL9602] Data Fault, FailCount= 1 2018-08-06T18:40:17.212Z,1533580817.212 [NAL9602](ERROR): Data Fault 2018-08-06T18:40:17.290Z,1533580817.290 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T18:40:17.611Z,1533580817.611 [NAL9602](INFO): Powering down 2018-08-06T18:40:18.483Z,1533580818.483 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T18:40:18.483Z,1533580818.483 [NAL9602] No Fault, FailCount= 1 2018-08-06T18:40:48.007Z,1533580848.007 [NAL9602](INFO): Powering up NAL9602 2018-08-06T18:40:59.211Z,1533580859.211 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:41:18.009Z,1533580878.009 [NAL9602](INFO): SBD MO Status=0, MOMSN=23338, MT Status=0, MTMSN=0 2018-08-06T18:41:18.009Z,1533580878.009 [NAL9602](INFO): No messages in MT queue 2018-08-06T18:41:42.411Z,1533580902.411 [NAL9602](INFO): GPS fix at 20180806T183651: (36.803510, -121.786252) 2018-08-06T18:41:42.477Z,1533580902.477 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T18:41:42.482Z,1533580902.482 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T18:41:55.982Z,1533580915.982 [NAL9602](INFO): SBD MO Status=1, MOMSN=23339, MT Status=0, MTMSN=0 2018-08-06T18:41:56.034Z,1533580916.034 [NAL9602](INFO): Sent 62 bytes from file Logs/20180806T181422/Courier0009.lzma 2018-08-06T18:41:56.034Z,1533580916.034 [NAL9602](INFO): Packets left to send: 0 2018-08-06T18:41:56.036Z,1533580916.036 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180806T181422/Courier0009.lzma.parts/0000.sbd 2018-08-06T18:41:56.036Z,1533580916.036 [NAL9602](DEBUG): Completed sending Logs/20180806T181422/Courier0009.lzma 2018-08-06T18:42:09.566Z,1533580929.566 [NAL9602](INFO): SBD MO Status=2, MOMSN=23340, MT Status=2, MTMSN=0 2018-08-06T18:42:09.566Z,1533580929.566 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:42:19.119Z,1533580939.119 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003053 2018-08-06T18:42:25.118Z,1533580945.118 [NAL9602](INFO): SBD MO Status=1, MOMSN=23340, MT Status=0, MTMSN=0 2018-08-06T18:42:25.166Z,1533580945.166 [NAL9602](INFO): Sent 255 bytes from file Logs/20180806T181422/Express0010.lzma 2018-08-06T18:42:25.166Z,1533580945.166 [NAL9602](INFO): Packets left to send: 0 2018-08-06T18:42:25.215Z,1533580945.215 [NAL9602](DEBUG): Stored copy of sent data in Logs/20180806T181422/Express0010.lzma.parts/0000.sbd 2018-08-06T18:42:25.216Z,1533580945.216 [NAL9602](DEBUG): Completed sending Logs/20180806T181422/Express0010.lzma 2018-08-06T18:42:26.311Z,1533580946.311 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T18:42:26.311Z,1533580946.311 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T18:42:26.312Z,1533580946.312 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T18:42:56.288Z,1533580976.288 [NAL9602](INFO): Powering down 2018-08-06T18:43:01.960Z,1533580981.960 [CBIT](IMPORTANT): Beginning ground fault scan 2018-08-06T18:43:12.773Z,1533580992.773 [CBIT](IMPORTANT): Ground fault detected mA: CHAN A0 (Batt): 0.191691 CHAN A1 (24V): 0.027881 CHAN A2 (12V): 0.043706 CHAN A3 (5V): -0.012350 CHAN B0 (3.3V): -0.010542 CHAN B1 (3.15aV): -0.004398 CHAN B2 (3.15bV): -0.000978 CHAN B3 (GND): -0.025637 OPEN: 0.008711 Full Scale Calc: 4.765 mA, -1.589 mA 2018-08-06T18:47:26.735Z,1533581246.735 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T18:47:26.735Z,1533581246.735 [Default:CheckIn:C.Wait] Stopped 2018-08-06T18:47:26.735Z,1533581246.735 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T18:47:26.736Z,1533581246.736 [Default:CheckIn:D] Running Loop=1 2018-08-06T18:47:27.137Z,1533581247.137 [Default:CheckIn:D] Stopped 2018-08-06T18:47:27.137Z,1533581247.137 [Default:CheckIn:E] Running Loop=1 2018-08-06T18:47:27.539Z,1533581247.539 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 73.019084 min 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn:E] Stopped 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn] Stopped 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn](INFO): Running loop #9 2018-08-06T18:47:27.540Z,1533581247.540 [Default:CheckIn] Running Loop=9 2018-08-06T18:47:27.541Z,1533581247.541 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T18:47:27.541Z,1533581247.541 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T18:47:28.287Z,1533581248.287 [NAL9602](INFO): Powering up 2018-08-06T18:47:39.199Z,1533581259.199 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:48:05.205Z,1533581285.205 [NAL9602](INFO): SBD MO Status=2, MOMSN=23341, MT Status=2, MTMSN=0 2018-08-06T18:48:05.205Z,1533581285.205 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T18:48:53.468Z,1533581333.468 [NAL9602](INFO): SBD MO Status=0, MOMSN=23341, MT Status=0, MTMSN=0 2018-08-06T18:48:53.468Z,1533581333.468 [NAL9602](INFO): No messages in MT queue 2018-08-06T18:48:54.669Z,1533581334.669 [NAL9602](INFO): GPS fix at 20180806T184402: (36.802772, -121.786974) 2018-08-06T18:48:54.731Z,1533581334.731 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T18:48:54.732Z,1533581334.732 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T18:48:59.634Z,1533581339.634 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0012.lzma 2018-08-06T18:49:00.421Z,1533581340.421 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0012.lzma.bak 2018-08-06T18:49:00.421Z,1533581340.421 [DataOverHttps](INFO): SBD MOMSN=8403460 2018-08-06T18:49:10.164Z,1533581350.164 [DataOverHttps](INFO): Sending 349 bytes from file Logs/20180806T181422/Express0013.lzma 2018-08-06T18:49:10.949Z,1533581350.949 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0013.lzma.bak 2018-08-06T18:49:10.949Z,1533581350.949 [DataOverHttps](INFO): SBD MOMSN=8403463 2018-08-06T18:49:13.691Z,1533581353.691 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T18:49:13.691Z,1533581353.691 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T18:49:13.691Z,1533581353.691 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T18:49:26.331Z,1533581366.331 [NAL9602](INFO): Powering down 2018-08-06T18:54:13.954Z,1533581653.954 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T18:54:13.954Z,1533581653.954 [Default:CheckIn:C.Wait] Stopped 2018-08-06T18:54:13.954Z,1533581653.954 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T18:54:13.955Z,1533581653.955 [Default:CheckIn:D] Running Loop=1 2018-08-06T18:54:14.359Z,1533581654.359 [Default:CheckIn:D] Stopped 2018-08-06T18:54:14.359Z,1533581654.359 [Default:CheckIn:E] Running Loop=1 2018-08-06T18:54:14.773Z,1533581654.773 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 79.806128 min 2018-08-06T18:54:14.773Z,1533581654.773 [Default:CheckIn:E] Stopped 2018-08-06T18:54:14.773Z,1533581654.773 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn] Stopped 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn](INFO): Running loop #10 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn] Running Loop=10 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T18:54:14.790Z,1533581654.790 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T18:54:18.342Z,1533581658.342 [NAL9602](INFO): Powering up 2018-08-06T18:54:29.231Z,1533581669.231 [NAL9602](INFO): NAL9602 initialized 2018-08-06T18:55:47.797Z,1533581747.797 [NAL9602](INFO): SBD MO Status=0, MOMSN=23342, MT Status=0, MTMSN=0 2018-08-06T18:55:47.797Z,1533581747.797 [NAL9602](INFO): No messages in MT queue 2018-08-06T18:55:54.592Z,1533581754.592 [NAL9602](INFO): GPS fix at 20180806T185102: (36.802387, -121.787209) 2018-08-06T18:55:54.656Z,1533581754.656 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T18:55:54.656Z,1533581754.656 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T18:55:59.546Z,1533581759.546 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0015.lzma 2018-08-06T18:56:00.333Z,1533581760.333 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0015.lzma.bak 2018-08-06T18:56:00.333Z,1533581760.333 [DataOverHttps](INFO): SBD MOMSN=8403470 2018-08-06T18:56:10.478Z,1533581770.478 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20180806T181422/Express0016.lzma 2018-08-06T18:56:11.265Z,1533581771.265 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0016.lzma.bak 2018-08-06T18:56:11.265Z,1533581771.265 [DataOverHttps](INFO): SBD MOMSN=8403473 2018-08-06T18:56:12.838Z,1533581772.838 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T18:56:12.838Z,1533581772.838 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T18:56:12.838Z,1533581772.838 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T18:56:29.911Z,1533581789.911 [NAL9602](INFO): Powering down 2018-08-06T19:01:13.122Z,1533582073.122 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:01:13.122Z,1533582073.122 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:01:13.123Z,1533582073.123 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:01:13.123Z,1533582073.123 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:01:13.526Z,1533582073.526 [Default:CheckIn:D] Stopped 2018-08-06T19:01:13.526Z,1533582073.526 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:01:13.911Z,1533582073.911 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.792244 min 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn:E] Stopped 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn] Stopped 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn](INFO): Running loop #11 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn] Running Loop=11 2018-08-06T19:01:13.912Z,1533582073.912 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:01:13.913Z,1533582073.913 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:01:17.505Z,1533582077.505 [NAL9602](INFO): Powering up 2018-08-06T19:01:28.383Z,1533582088.383 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:02:25.709Z,1533582145.709 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:02:25.709Z,1533582145.709 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:06:14.155Z,1533582374.155 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T19:01:13.9Z 2018-08-06T19:06:14.156Z,1533582374.156 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:06:14.156Z,1533582374.156 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:06:18.843Z,1533582378.843 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0018.lzma 2018-08-06T19:06:19.641Z,1533582379.641 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0018.lzma.bak 2018-08-06T19:06:19.641Z,1533582379.641 [DataOverHttps](INFO): SBD MOMSN=8403483 2018-08-06T19:06:29.786Z,1533582389.786 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20180806T181422/Express0019.lzma 2018-08-06T19:06:30.529Z,1533582390.529 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0019.lzma.bak 2018-08-06T19:06:30.529Z,1533582390.529 [DataOverHttps](INFO): SBD MOMSN=8403485 2018-08-06T19:06:31.976Z,1533582391.976 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:06:31.976Z,1533582391.976 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:06:31.977Z,1533582391.977 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:06:32.059Z,1533582392.059 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T19:07:05.355Z,1533582425.355 [NAL9602](INFO): Powering down 2018-08-06T19:11:32.515Z,1533582692.515 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:11:32.516Z,1533582692.516 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:11:32.516Z,1533582692.516 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:11:32.516Z,1533582692.516 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:11:32.911Z,1533582692.911 [Default:CheckIn:D] Stopped 2018-08-06T19:11:32.911Z,1533582692.911 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:11:33.315Z,1533582693.315 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.115324 min 2018-08-06T19:11:33.315Z,1533582693.315 [Default:CheckIn:E] Stopped 2018-08-06T19:11:33.315Z,1533582693.315 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:11:33.315Z,1533582693.315 [Default:CheckIn] Stopped 2018-08-06T19:11:33.315Z,1533582693.315 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:11:33.316Z,1533582693.316 [Default:CheckIn](INFO): Running loop #12 2018-08-06T19:11:33.316Z,1533582693.316 [Default:CheckIn] Running Loop=12 2018-08-06T19:11:33.316Z,1533582693.316 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:11:33.316Z,1533582693.316 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:11:38.158Z,1533582698.158 [NAL9602](INFO): Powering up 2018-08-06T19:11:49.324Z,1533582709.324 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:11:50.127Z,1533582710.127 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T19:11:50.128Z,1533582710.128 [NAL9602] Data Fault, FailCount= 1 2018-08-06T19:11:50.128Z,1533582710.128 [NAL9602](ERROR): Data Fault 2018-08-06T19:11:50.224Z,1533582710.224 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T19:11:50.527Z,1533582710.527 [NAL9602](INFO): Powering down 2018-08-06T19:11:51.412Z,1533582711.412 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T19:11:51.412Z,1533582711.412 [NAL9602] No Fault, FailCount= 1 2018-08-06T19:12:20.923Z,1533582740.923 [NAL9602](INFO): Powering up NAL9602 2018-08-06T19:12:31.727Z,1533582751.727 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:16:33.489Z,1533582993.489 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T19:11:33.3Z 2018-08-06T19:16:33.489Z,1533582993.489 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:16:33.501Z,1533582993.501 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:16:38.619Z,1533582998.619 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0021.lzma 2018-08-06T19:16:39.419Z,1533582999.419 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0021.lzma.bak 2018-08-06T19:16:39.419Z,1533582999.419 [DataOverHttps](INFO): SBD MOMSN=8403494 2018-08-06T19:16:49.716Z,1533583009.716 [DataOverHttps](INFO): Sending 213 bytes from file Logs/20180806T181422/Express0022.lzma 2018-08-06T19:16:50.505Z,1533583010.505 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0022.lzma.bak 2018-08-06T19:16:50.505Z,1533583010.505 [DataOverHttps](INFO): SBD MOMSN=8403496 2018-08-06T19:16:51.904Z,1533583011.904 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:16:51.904Z,1533583011.904 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:16:51.904Z,1533583011.904 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:17:16.589Z,1533583036.589 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:17:16.589Z,1533583036.589 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:17:40.186Z,1533583060.186 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:17:40.186Z,1533583060.186 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:17:40.587Z,1533583060.587 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T19:18:11.323Z,1533583091.323 [NAL9602](INFO): Powering down 2018-08-06T19:19:38.278Z,1533583178.278 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-06T19:19:38.278Z,1533583178.278 [BPC1] Communications Fault, FailCount= 1 2018-08-06T19:19:38.278Z,1533583178.278 [BPC1](ERROR): Communications Fault 2018-08-06T19:19:38.340Z,1533583178.340 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-06T19:19:39.534Z,1533583179.534 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-06T19:19:39.534Z,1533583179.534 [BPC1] No Fault, FailCount= 1 2018-08-06T19:21:52.224Z,1533583312.224 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:21:52.224Z,1533583312.224 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:21:52.224Z,1533583312.224 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:21:52.224Z,1533583312.224 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:21:52.624Z,1533583312.624 [Default:CheckIn:D] Stopped 2018-08-06T19:21:52.624Z,1533583312.624 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:21:53.027Z,1533583313.027 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 107.443864 min 2018-08-06T19:21:53.027Z,1533583313.027 [Default:CheckIn:E] Stopped 2018-08-06T19:21:53.027Z,1533583313.027 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:21:53.027Z,1533583313.027 [Default:CheckIn] Stopped 2018-08-06T19:21:53.027Z,1533583313.027 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:21:53.028Z,1533583313.028 [Default:CheckIn](INFO): Running loop #13 2018-08-06T19:21:53.028Z,1533583313.028 [Default:CheckIn] Running Loop=13 2018-08-06T19:21:53.028Z,1533583313.028 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:21:53.028Z,1533583313.028 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:21:56.835Z,1533583316.835 [NAL9602](INFO): Powering up 2018-08-06T19:22:07.755Z,1533583327.755 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:25:38.673Z,1533583538.673 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:25:38.673Z,1533583538.673 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:25:57.723Z,1533583557.723 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:25:57.724Z,1533583557.724 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:26:30.225Z,1533583590.225 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:26:30.225Z,1533583590.225 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:26:47.829Z,1533583607.829 [NAL9602](INFO): SBD MO Status=2, MOMSN=23343, MT Status=2, MTMSN=0 2018-08-06T19:26:47.829Z,1533583607.829 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:26:53.079Z,1533583613.079 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T19:21:53.0Z 2018-08-06T19:26:53.079Z,1533583613.079 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:26:53.080Z,1533583613.080 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:26:57.727Z,1533583617.727 [DataOverHttps](INFO): Sending 195 bytes from file Logs/20180806T181422/Courier0024.lzma 2018-08-06T19:26:58.513Z,1533583618.513 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0024.lzma.bak 2018-08-06T19:26:58.513Z,1533583618.513 [DataOverHttps](INFO): SBD MOMSN=8403510 2018-08-06T19:27:08.884Z,1533583628.884 [DataOverHttps](INFO): Sending 197 bytes from file Logs/20180806T181422/Express0025.lzma 2018-08-06T19:27:09.682Z,1533583629.682 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0025.lzma.bak 2018-08-06T19:27:09.682Z,1533583629.682 [DataOverHttps](INFO): SBD MOMSN=8403512 2018-08-06T19:27:11.085Z,1533583631.085 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:27:11.086Z,1533583631.086 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:27:11.086Z,1533583631.086 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:27:14.376Z,1533583634.376 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T19:27:44.867Z,1533583664.867 [NAL9602](INFO): Powering down 2018-08-06T19:32:11.348Z,1533583931.348 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:32:11.348Z,1533583931.348 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:32:11.348Z,1533583931.348 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:32:11.348Z,1533583931.348 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:32:11.748Z,1533583931.748 [Default:CheckIn:D] Stopped 2018-08-06T19:32:11.749Z,1533583931.749 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:32:12.139Z,1533583932.139 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 117.762614 min 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn:E] Stopped 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn] Stopped 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn](INFO): Running loop #14 2018-08-06T19:32:12.140Z,1533583932.140 [Default:CheckIn] Running Loop=14 2018-08-06T19:32:12.141Z,1533583932.141 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:32:12.141Z,1533583932.141 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:32:15.800Z,1533583935.800 [NAL9602](INFO): Powering up 2018-08-06T19:32:26.703Z,1533583946.703 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:32:27.500Z,1533583947.500 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T19:32:27.500Z,1533583947.500 [NAL9602] Data Fault, FailCount= 2 2018-08-06T19:32:27.501Z,1533583947.501 [NAL9602](ERROR): Data Fault 2018-08-06T19:32:27.593Z,1533583947.593 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T19:32:27.907Z,1533583947.907 [NAL9602](INFO): Powering down 2018-08-06T19:32:28.763Z,1533583948.763 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T19:32:28.763Z,1533583948.763 [NAL9602] No Fault, FailCount= 2 2018-08-06T19:32:58.311Z,1533583978.311 [NAL9602](INFO): Powering up NAL9602 2018-08-06T19:33:09.499Z,1533583989.499 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:37:12.262Z,1533584232.262 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T19:32:12.1Z 2018-08-06T19:37:12.262Z,1533584232.262 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:37:12.263Z,1533584232.263 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:37:16.977Z,1533584236.977 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0027.lzma 2018-08-06T19:37:17.745Z,1533584237.745 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0027.lzma.bak 2018-08-06T19:37:17.745Z,1533584237.745 [DataOverHttps](INFO): SBD MOMSN=8403522 2018-08-06T19:37:27.510Z,1533584247.510 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20180806T181422/Express0028.lzma 2018-08-06T19:37:28.285Z,1533584248.285 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0028.lzma.bak 2018-08-06T19:37:28.285Z,1533584248.285 [DataOverHttps](INFO): SBD MOMSN=8403524 2018-08-06T19:37:29.655Z,1533584249.655 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:37:29.656Z,1533584249.656 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:37:29.656Z,1533584249.656 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:38:12.839Z,1533584292.839 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T19:38:43.363Z,1533584323.363 [NAL9602](INFO): Powering down 2018-08-06T19:42:30.140Z,1533584550.140 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:42:30.140Z,1533584550.140 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:42:30.140Z,1533584550.140 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:42:30.141Z,1533584550.141 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:42:30.543Z,1533584550.543 [Default:CheckIn:D] Stopped 2018-08-06T19:42:30.543Z,1533584550.543 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:42:30.946Z,1533584550.946 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 128.075854 min 2018-08-06T19:42:30.946Z,1533584550.946 [Default:CheckIn:E] Stopped 2018-08-06T19:42:30.946Z,1533584550.946 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:42:30.946Z,1533584550.946 [Default:CheckIn] Stopped 2018-08-06T19:42:30.946Z,1533584550.946 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:42:30.947Z,1533584550.947 [Default:CheckIn](INFO): Running loop #15 2018-08-06T19:42:30.947Z,1533584550.947 [Default:CheckIn] Running Loop=15 2018-08-06T19:42:30.947Z,1533584550.947 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:42:30.947Z,1533584550.947 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:42:34.252Z,1533584554.252 [NAL9602](INFO): Powering up 2018-08-06T19:42:45.411Z,1533584565.411 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:43:17.411Z,1533584597.411 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-08-06T19:43:17.490Z,1533584597.490 [NAL9602](FAULT): received: +CSQ:0 OK343, 2, 0, 0, 0 OK 2018-08-06T19:43:17.490Z,1533584597.490 [NAL9602] Data Fault, FailCount= 3 2018-08-06T19:43:17.490Z,1533584597.490 [NAL9602](ERROR): Data Fault 2018-08-06T19:43:17.581Z,1533584597.581 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T19:43:17.811Z,1533584597.811 [NAL9602](INFO): Powering down 2018-08-06T19:43:18.695Z,1533584598.695 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T19:43:18.695Z,1533584598.695 [NAL9602] No Fault, FailCount= 3 2018-08-06T19:43:48.004Z,1533584628.004 [NAL9602](INFO): Powering up NAL9602 2018-08-06T19:43:58.803Z,1533584638.803 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:43:59.603Z,1533584639.603 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T19:43:59.604Z,1533584639.604 [NAL9602] Data Fault, FailCount= 4 2018-08-06T19:43:59.604Z,1533584639.604 [NAL9602](ERROR): Data Fault 2018-08-06T19:43:59.731Z,1533584639.731 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T19:44:00.003Z,1533584640.003 [NAL9602](INFO): Powering down 2018-08-06T19:44:00.879Z,1533584640.879 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T19:44:00.879Z,1533584640.879 [NAL9602] No Fault, FailCount= 4 2018-08-06T19:44:30.007Z,1533584670.007 [NAL9602](INFO): Powering up NAL9602 2018-08-06T19:44:41.144Z,1533584681.144 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:46:27.273Z,1533584787.273 [NAL9602](INFO): SBD MO Status=0, MOMSN=23343, MT Status=0, MTMSN=0 2018-08-06T19:46:27.273Z,1533584787.273 [NAL9602](INFO): No messages in MT queue 2018-08-06T19:46:50.273Z,1533584810.273 [NAL9602](INFO): GPS fix at 20180806T194153: (36.802885, -121.788061) 2018-08-06T19:46:50.347Z,1533584810.347 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:46:50.347Z,1533584810.347 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:46:55.627Z,1533584815.627 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0030.lzma 2018-08-06T19:46:56.417Z,1533584816.417 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0030.lzma.bak 2018-08-06T19:46:56.417Z,1533584816.417 [DataOverHttps](INFO): SBD MOMSN=8403535 2018-08-06T19:47:06.504Z,1533584826.504 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20180806T181422/Express0031.lzma 2018-08-06T19:47:07.301Z,1533584827.301 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0031.lzma.bak 2018-08-06T19:47:07.302Z,1533584827.302 [DataOverHttps](INFO): SBD MOMSN=8403538 2018-08-06T19:47:08.849Z,1533584828.849 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:47:08.849Z,1533584828.849 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:47:08.849Z,1533584828.849 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:47:25.479Z,1533584845.479 [NAL9602](INFO): Powering down 2018-08-06T19:52:09.065Z,1533585129.065 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T19:52:09.066Z,1533585129.066 [Default:CheckIn:C.Wait] Stopped 2018-08-06T19:52:09.066Z,1533585129.066 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T19:52:09.066Z,1533585129.066 [Default:CheckIn:D] Running Loop=1 2018-08-06T19:52:09.473Z,1533585129.473 [Default:CheckIn:D] Stopped 2018-08-06T19:52:09.473Z,1533585129.473 [Default:CheckIn:E] Running Loop=1 2018-08-06T19:52:09.883Z,1533585129.883 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 137.724691 min 2018-08-06T19:52:09.883Z,1533585129.883 [Default:CheckIn:E] Stopped 2018-08-06T19:52:09.883Z,1533585129.883 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn] Stopped 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn](INFO): Running loop #16 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn] Running Loop=16 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T19:52:09.884Z,1533585129.884 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T19:52:13.459Z,1533585133.459 [NAL9602](INFO): Powering up 2018-08-06T19:52:24.347Z,1533585144.347 [NAL9602](INFO): NAL9602 initialized 2018-08-06T19:52:49.549Z,1533585169.549 [NAL9602](INFO): SBD MO Status=2, MOMSN=23344, MT Status=2, MTMSN=0 2018-08-06T19:52:49.549Z,1533585169.549 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T19:53:09.949Z,1533585189.949 [NAL9602](INFO): SBD MO Status=0, MOMSN=23344, MT Status=0, MTMSN=0 2018-08-06T19:53:09.949Z,1533585189.949 [NAL9602](INFO): No messages in MT queue 2018-08-06T19:55:56.275Z,1533585356.275 [NAL9602](INFO): GPS fix at 20180806T195058: (36.802829, -121.787976) 2018-08-06T19:55:56.342Z,1533585356.342 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T19:55:56.342Z,1533585356.342 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T19:56:01.301Z,1533585361.301 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0033.lzma 2018-08-06T19:56:02.081Z,1533585362.081 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0033.lzma.bak 2018-08-06T19:56:02.081Z,1533585362.081 [DataOverHttps](INFO): SBD MOMSN=8403553 2018-08-06T19:56:12.236Z,1533585372.236 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20180806T181422/Express0034.lzma 2018-08-06T19:56:13.025Z,1533585373.025 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0034.lzma.bak 2018-08-06T19:56:13.025Z,1533585373.025 [DataOverHttps](INFO): SBD MOMSN=8403556 2018-08-06T19:56:14.577Z,1533585374.577 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T19:56:14.577Z,1533585374.577 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T19:56:14.594Z,1533585374.594 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T19:56:31.623Z,1533585391.623 [NAL9602](INFO): Powering down 2018-08-06T20:01:14.816Z,1533585674.816 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:01:14.817Z,1533585674.817 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:01:14.817Z,1533585674.817 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:01:14.817Z,1533585674.817 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:01:15.216Z,1533585675.216 [Default:CheckIn:D] Stopped 2018-08-06T20:01:15.216Z,1533585675.216 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:01:15.610Z,1533585675.610 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 146.820410 min 2018-08-06T20:01:15.610Z,1533585675.610 [Default:CheckIn:E] Stopped 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn] Stopped 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn](INFO): Running loop #17 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn] Running Loop=17 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:01:15.611Z,1533585675.611 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:01:19.203Z,1533585679.203 [NAL9602](INFO): Powering up 2018-08-06T20:01:30.111Z,1533585690.111 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:01:48.913Z,1533585708.913 [NAL9602](INFO): SBD MO Status=0, MOMSN=23345, MT Status=0, MTMSN=0 2018-08-06T20:01:48.913Z,1533585708.913 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:03:40.859Z,1533585820.859 [NAL9602](INFO): GPS fix at 20180806T195842: (36.803051, -121.787946) 2018-08-06T20:03:40.917Z,1533585820.917 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:03:40.917Z,1533585820.917 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:03:45.704Z,1533585825.704 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0036.lzma 2018-08-06T20:03:46.501Z,1533585826.501 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0036.lzma.bak 2018-08-06T20:03:46.501Z,1533585826.501 [DataOverHttps](INFO): SBD MOMSN=8403567 2018-08-06T20:03:58.046Z,1533585838.046 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20180806T181422/Express0037.lzma 2018-08-06T20:03:58.825Z,1533585838.825 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0037.lzma.bak 2018-08-06T20:03:58.826Z,1533585838.826 [DataOverHttps](INFO): SBD MOMSN=8403570 2018-08-06T20:04:00.261Z,1533585840.261 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:04:00.262Z,1533585840.262 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:04:00.262Z,1533585840.262 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:04:16.113Z,1533585856.113 [NAL9602](INFO): Powering down 2018-08-06T20:09:00.494Z,1533586140.494 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:09:00.494Z,1533586140.494 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:09:00.494Z,1533586140.494 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:09:00.494Z,1533586140.494 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:09:00.894Z,1533586140.894 [Default:CheckIn:D] Stopped 2018-08-06T20:09:00.894Z,1533586140.894 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:09:01.300Z,1533586141.300 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 154.581706 min 2018-08-06T20:09:01.300Z,1533586141.300 [Default:CheckIn:E] Stopped 2018-08-06T20:09:01.300Z,1533586141.300 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:09:01.300Z,1533586141.300 [Default:CheckIn] Stopped 2018-08-06T20:09:01.300Z,1533586141.300 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:09:01.301Z,1533586141.301 [Default:CheckIn](INFO): Running loop #18 2018-08-06T20:09:01.301Z,1533586141.301 [Default:CheckIn] Running Loop=18 2018-08-06T20:09:01.301Z,1533586141.301 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:09:01.301Z,1533586141.301 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:09:04.877Z,1533586144.877 [NAL9602](INFO): Powering up 2018-08-06T20:09:15.767Z,1533586155.767 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:09:28.973Z,1533586168.973 [NAL9602](INFO): SBD MO Status=0, MOMSN=23346, MT Status=0, MTMSN=0 2018-08-06T20:09:28.973Z,1533586168.973 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:14:01.337Z,1533586441.337 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T20:09:01.3Z 2018-08-06T20:14:01.337Z,1533586441.337 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:14:01.342Z,1533586441.342 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:14:06.105Z,1533586446.105 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0039.lzma 2018-08-06T20:14:06.897Z,1533586446.897 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0039.lzma.bak 2018-08-06T20:14:06.897Z,1533586446.897 [DataOverHttps](INFO): SBD MOMSN=8403581 2018-08-06T20:14:17.176Z,1533586457.176 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20180806T181422/Express0040.lzma 2018-08-06T20:14:17.961Z,1533586457.961 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0040.lzma.bak 2018-08-06T20:14:17.961Z,1533586457.961 [DataOverHttps](INFO): SBD MOMSN=8403583 2018-08-06T20:14:19.374Z,1533586459.374 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:14:19.374Z,1533586459.374 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:14:19.374Z,1533586459.374 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:14:36.435Z,1533586476.435 [NAL9602](INFO): Powering down 2018-08-06T20:19:19.610Z,1533586759.610 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:19:19.610Z,1533586759.610 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:19:19.610Z,1533586759.610 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:19:19.611Z,1533586759.611 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:19:20.018Z,1533586760.018 [Default:CheckIn:D] Stopped 2018-08-06T20:19:20.018Z,1533586760.018 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:19:20.410Z,1533586760.410 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 164.900439 min 2018-08-06T20:19:20.410Z,1533586760.410 [Default:CheckIn:E] Stopped 2018-08-06T20:19:20.410Z,1533586760.410 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:19:20.410Z,1533586760.410 [Default:CheckIn] Stopped 2018-08-06T20:19:20.411Z,1533586760.411 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:19:20.411Z,1533586760.411 [Default:CheckIn](INFO): Running loop #19 2018-08-06T20:19:20.411Z,1533586760.411 [Default:CheckIn] Running Loop=19 2018-08-06T20:19:20.411Z,1533586760.411 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:19:20.411Z,1533586760.411 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:19:24.200Z,1533586764.200 [NAL9602](INFO): Powering up 2018-08-06T20:19:35.095Z,1533586775.095 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:19:35.895Z,1533586775.895 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T20:19:35.896Z,1533586775.896 [NAL9602] Data Fault, FailCount= 1 2018-08-06T20:19:35.896Z,1533586775.896 [NAL9602](ERROR): Data Fault 2018-08-06T20:19:36.018Z,1533586776.018 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T20:19:36.304Z,1533586776.304 [NAL9602](INFO): Powering down 2018-08-06T20:19:37.166Z,1533586777.166 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T20:19:37.167Z,1533586777.167 [NAL9602] No Fault, FailCount= 1 2018-08-06T20:20:06.702Z,1533586806.702 [NAL9602](INFO): Powering up NAL9602 2018-08-06T20:20:17.895Z,1533586817.895 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:20:29.261Z,1533586829.261 [NAL9602](INFO): SBD MO Status=0, MOMSN=23347, MT Status=0, MTMSN=0 2018-08-06T20:20:29.261Z,1533586829.261 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:24:20.576Z,1533587060.576 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T20:19:20.4Z 2018-08-06T20:24:20.576Z,1533587060.576 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:24:20.576Z,1533587060.576 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:24:25.264Z,1533587065.264 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20180806T181422/Courier0042.lzma 2018-08-06T20:24:26.057Z,1533587066.057 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0042.lzma.bak 2018-08-06T20:24:26.057Z,1533587066.057 [DataOverHttps](INFO): SBD MOMSN=8403601 2018-08-06T20:24:36.011Z,1533587076.011 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20180806T181422/Express0043.lzma 2018-08-06T20:24:36.793Z,1533587076.793 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0043.lzma.bak 2018-08-06T20:24:36.793Z,1533587076.793 [DataOverHttps](INFO): SBD MOMSN=8403603 2018-08-06T20:24:38.190Z,1533587078.190 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:24:38.190Z,1533587078.190 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:24:38.190Z,1533587078.190 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:24:51.179Z,1533587091.179 [NAL9602](INFO): Powering down 2018-08-06T20:29:38.605Z,1533587378.605 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:29:38.606Z,1533587378.606 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:29:38.606Z,1533587378.606 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:29:38.606Z,1533587378.606 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:29:39.006Z,1533587379.006 [Default:CheckIn:D] Stopped 2018-08-06T20:29:39.006Z,1533587379.006 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:29:39.409Z,1533587379.409 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 175.216911 min 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn:E] Stopped 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn] Stopped 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn](INFO): Running loop #20 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn] Running Loop=20 2018-08-06T20:29:39.410Z,1533587379.410 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:29:39.411Z,1533587379.411 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:29:44.655Z,1533587384.655 [NAL9602](INFO): Powering up 2018-08-06T20:29:55.539Z,1533587395.539 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:30:08.345Z,1533587408.345 [NAL9602](INFO): SBD MO Status=0, MOMSN=23348, MT Status=0, MTMSN=0 2018-08-06T20:30:08.345Z,1533587408.345 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:30:19.143Z,1533587419.143 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T20:30:19.143Z,1533587419.143 [NAL9602] Data Fault, FailCount= 1 2018-08-06T20:30:19.144Z,1533587419.144 [NAL9602](ERROR): Data Fault 2018-08-06T20:30:19.224Z,1533587419.224 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T20:30:19.539Z,1533587419.539 [NAL9602](INFO): Powering down 2018-08-06T20:30:20.407Z,1533587420.407 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T20:30:20.407Z,1533587420.407 [NAL9602] No Fault, FailCount= 1 2018-08-06T20:30:49.891Z,1533587449.891 [NAL9602](INFO): Powering up NAL9602 2018-08-06T20:31:01.087Z,1533587461.087 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:34:39.631Z,1533587679.631 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T20:29:39.4Z 2018-08-06T20:34:39.631Z,1533587679.631 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:34:39.631Z,1533587679.631 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:34:44.306Z,1533587684.306 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0045.lzma 2018-08-06T20:34:45.082Z,1533587685.082 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0045.lzma.bak 2018-08-06T20:34:45.082Z,1533587685.082 [DataOverHttps](INFO): SBD MOMSN=8403614 2018-08-06T20:34:54.945Z,1533587694.945 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20180806T181422/Express0046.lzma 2018-08-06T20:34:55.737Z,1533587695.737 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0046.lzma.bak 2018-08-06T20:34:55.737Z,1533587695.737 [DataOverHttps](INFO): SBD MOMSN=8403616 2018-08-06T20:34:57.145Z,1533587697.145 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:34:57.145Z,1533587697.145 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:34:57.145Z,1533587697.145 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:35:11.300Z,1533587711.300 [NAL9602](INFO): Powering down 2018-08-06T20:39:57.638Z,1533587997.638 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:39:57.639Z,1533587997.639 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:39:57.639Z,1533587997.639 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:39:57.639Z,1533587997.639 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:39:58.045Z,1533587998.045 [Default:CheckIn:D] Stopped 2018-08-06T20:39:58.046Z,1533587998.046 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:39:58.446Z,1533587998.446 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 185.534229 min 2018-08-06T20:39:58.446Z,1533587998.446 [Default:CheckIn:E] Stopped 2018-08-06T20:39:58.446Z,1533587998.446 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:39:58.446Z,1533587998.446 [Default:CheckIn] Stopped 2018-08-06T20:39:58.446Z,1533587998.446 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:39:58.447Z,1533587998.447 [Default:CheckIn](INFO): Running loop #21 2018-08-06T20:39:58.447Z,1533587998.447 [Default:CheckIn] Running Loop=21 2018-08-06T20:39:58.447Z,1533587998.447 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:39:58.447Z,1533587998.447 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:40:01.772Z,1533588001.772 [NAL9602](INFO): Powering up 2018-08-06T20:40:12.919Z,1533588012.919 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:40:28.529Z,1533588028.529 [NAL9602](INFO): SBD MO Status=0, MOMSN=23349, MT Status=0, MTMSN=0 2018-08-06T20:40:28.529Z,1533588028.529 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:41:01.975Z,1533588061.975 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T20:41:01.975Z,1533588061.975 [NAL9602] Data Fault, FailCount= 1 2018-08-06T20:41:01.976Z,1533588061.976 [NAL9602](ERROR): Data Fault 2018-08-06T20:41:02.078Z,1533588062.078 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T20:41:02.347Z,1533588062.347 [NAL9602](INFO): Powering down 2018-08-06T20:41:03.220Z,1533588063.220 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T20:41:03.220Z,1533588063.220 [NAL9602] No Fault, FailCount= 1 2018-08-06T20:41:32.752Z,1533588092.752 [NAL9602](INFO): Powering up NAL9602 2018-08-06T20:41:43.547Z,1533588103.547 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:44:58.697Z,1533588298.697 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T20:39:58.4Z 2018-08-06T20:44:58.697Z,1533588298.697 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:44:58.702Z,1533588298.702 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:45:02.932Z,1533588302.932 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0048.lzma 2018-08-06T20:45:03.709Z,1533588303.709 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0048.lzma.bak 2018-08-06T20:45:03.709Z,1533588303.709 [DataOverHttps](INFO): SBD MOMSN=8403627 2018-08-06T20:45:13.772Z,1533588313.772 [DataOverHttps](INFO): Sending 164 bytes from file Logs/20180806T181422/Express0049.lzma 2018-08-06T20:45:14.545Z,1533588314.545 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0049.lzma.bak 2018-08-06T20:45:14.545Z,1533588314.545 [DataOverHttps](INFO): SBD MOMSN=8403629 2018-08-06T20:45:15.936Z,1533588315.936 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:45:15.936Z,1533588315.936 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:45:15.936Z,1533588315.936 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:45:29.379Z,1533588329.379 [NAL9602](INFO): Powering down 2018-08-06T20:50:16.210Z,1533588616.210 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T20:50:16.210Z,1533588616.210 [Default:CheckIn:C.Wait] Stopped 2018-08-06T20:50:16.210Z,1533588616.210 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T20:50:16.211Z,1533588616.211 [Default:CheckIn:D] Running Loop=1 2018-08-06T20:50:16.603Z,1533588616.603 [Default:CheckIn:D] Stopped 2018-08-06T20:50:16.603Z,1533588616.603 [Default:CheckIn:E] Running Loop=1 2018-08-06T20:50:16.000Z,1533588617.000 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 195.843522 min 2018-08-06T20:50:16.000Z,1533588617.000 [Default:CheckIn:E] Stopped 2018-08-06T20:50:17.000Z,1533588617.000 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T20:50:17.000Z,1533588617.000 [Default:CheckIn] Stopped 2018-08-06T20:50:17.000Z,1533588617.000 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T20:50:17.001Z,1533588617.001 [Default:CheckIn](INFO): Running loop #22 2018-08-06T20:50:17.001Z,1533588617.001 [Default:CheckIn] Running Loop=22 2018-08-06T20:50:17.001Z,1533588617.001 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T20:50:17.001Z,1533588617.001 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T20:50:20.595Z,1533588620.595 [NAL9602](INFO): Powering up 2018-08-06T20:50:31.495Z,1533588631.495 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:50:57.889Z,1533588657.889 [NAL9602](INFO): SBD MO Status=2, MOMSN=23350, MT Status=2, MTMSN=0 2018-08-06T20:50:57.889Z,1533588657.889 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T20:53:35.893Z,1533588815.893 [NAL9602](INFO): SBD MO Status=2, MOMSN=23350, MT Status=2, MTMSN=0 2018-08-06T20:53:35.893Z,1533588815.893 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T20:53:55.097Z,1533588835.097 [NAL9602](INFO): SBD MO Status=0, MOMSN=23350, MT Status=0, MTMSN=0 2018-08-06T20:53:55.097Z,1533588835.097 [NAL9602](INFO): No messages in MT queue 2018-08-06T20:53:55.895Z,1533588835.895 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T20:53:55.895Z,1533588835.895 [NAL9602] Data Fault, FailCount= 1 2018-08-06T20:53:55.895Z,1533588835.895 [NAL9602](ERROR): Data Fault 2018-08-06T20:53:55.984Z,1533588835.984 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T20:53:56.291Z,1533588836.291 [NAL9602](INFO): Powering down 2018-08-06T20:53:57.160Z,1533588837.160 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T20:53:57.160Z,1533588837.160 [NAL9602] No Fault, FailCount= 1 2018-08-06T20:54:26.419Z,1533588866.419 [NAL9602](INFO): Powering up NAL9602 2018-08-06T20:54:37.623Z,1533588877.623 [NAL9602](INFO): NAL9602 initialized 2018-08-06T20:55:17.275Z,1533588917.275 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T20:50:17.0Z 2018-08-06T20:55:17.275Z,1533588917.275 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T20:55:17.275Z,1533588917.275 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T20:55:22.113Z,1533588922.113 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0051.lzma 2018-08-06T20:55:22.905Z,1533588922.905 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0051.lzma.bak 2018-08-06T20:55:22.905Z,1533588922.905 [DataOverHttps](INFO): SBD MOMSN=8403639 2018-08-06T20:55:33.262Z,1533588933.262 [DataOverHttps](INFO): Sending 164 bytes from file Logs/20180806T181422/Express0052.lzma 2018-08-06T20:55:34.053Z,1533588934.053 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0052.lzma.bak 2018-08-06T20:55:34.053Z,1533588934.053 [DataOverHttps](INFO): SBD MOMSN=8403641 2018-08-06T20:55:35.450Z,1533588935.450 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T20:55:35.450Z,1533588935.450 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T20:55:35.450Z,1533588935.450 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T20:55:48.523Z,1533588948.523 [NAL9602](INFO): Powering down 2018-08-06T21:00:36.008Z,1533589236.008 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:00:36.008Z,1533589236.008 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:00:36.008Z,1533589236.008 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:00:36.009Z,1533589236.009 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:00:36.409Z,1533589236.409 [Default:CheckIn:D] Stopped 2018-08-06T21:00:36.409Z,1533589236.409 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:00:36.810Z,1533589236.810 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 206.173617 min 2018-08-06T21:00:36.810Z,1533589236.810 [Default:CheckIn:E] Stopped 2018-08-06T21:00:36.810Z,1533589236.810 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:00:36.810Z,1533589236.810 [Default:CheckIn] Stopped 2018-08-06T21:00:36.810Z,1533589236.810 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:00:36.811Z,1533589236.811 [Default:CheckIn](INFO): Running loop #23 2018-08-06T21:00:36.811Z,1533589236.811 [Default:CheckIn] Running Loop=23 2018-08-06T21:00:36.811Z,1533589236.811 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:00:36.811Z,1533589236.811 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:00:40.332Z,1533589240.332 [NAL9602](INFO): Powering up 2018-08-06T21:00:51.487Z,1533589251.487 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:02:33.604Z,1533589353.604 [NAL9602](INFO): SBD MO Status=2, MOMSN=23351, MT Status=2, MTMSN=0 2018-08-06T21:02:33.605Z,1533589353.605 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:03:28.642Z,1533589408.642 [NAL9602](INFO): SBD MO Status=2, MOMSN=23351, MT Status=2, MTMSN=0 2018-08-06T21:03:28.642Z,1533589408.642 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:03:45.757Z,1533589425.757 [NAL9602](INFO): SBD MO Status=2, MOMSN=23351, MT Status=2, MTMSN=0 2018-08-06T21:03:45.757Z,1533589425.757 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:04:14.161Z,1533589454.161 [NAL9602](INFO): SBD MO Status=0, MOMSN=23351, MT Status=0, MTMSN=0 2018-08-06T21:04:14.161Z,1533589454.161 [NAL9602](INFO): No messages in MT queue 2018-08-06T21:04:41.503Z,1533589481.503 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T21:04:41.503Z,1533589481.503 [NAL9602] Data Fault, FailCount= 1 2018-08-06T21:04:41.503Z,1533589481.503 [NAL9602](ERROR): Data Fault 2018-08-06T21:04:41.592Z,1533589481.592 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:04:41.904Z,1533589481.904 [NAL9602](INFO): Powering down 2018-08-06T21:04:42.846Z,1533589482.846 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T21:04:42.846Z,1533589482.846 [NAL9602] No Fault, FailCount= 1 2018-08-06T21:05:12.306Z,1533589512.306 [NAL9602](INFO): Powering up NAL9602 2018-08-06T21:05:23.103Z,1533589523.103 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:05:37.199Z,1533589537.199 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:00:36.8Z 2018-08-06T21:05:37.199Z,1533589537.199 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:05:37.199Z,1533589537.199 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:05:41.429Z,1533589541.429 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0054.lzma 2018-08-06T21:05:42.229Z,1533589542.229 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0054.lzma.bak 2018-08-06T21:05:42.229Z,1533589542.229 [DataOverHttps](INFO): SBD MOMSN=8403655 2018-08-06T21:05:53.393Z,1533589553.393 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20180806T181422/Express0055.lzma 2018-08-06T21:05:54.185Z,1533589554.185 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0055.lzma.bak 2018-08-06T21:05:54.185Z,1533589554.185 [DataOverHttps](INFO): SBD MOMSN=8403658 2018-08-06T21:05:55.579Z,1533589555.579 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:05:55.579Z,1533589555.579 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:05:55.579Z,1533589555.579 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:06:08.559Z,1533589568.559 [NAL9602](INFO): Powering down 2018-08-06T21:10:55.911Z,1533589855.911 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:10:55.911Z,1533589855.911 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:10:55.911Z,1533589855.911 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:10:55.911Z,1533589855.911 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:10:56.315Z,1533589856.315 [Default:CheckIn:D] Stopped 2018-08-06T21:10:56.315Z,1533589856.315 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:10:56.709Z,1533589856.709 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 216.505387 min 2018-08-06T21:10:56.709Z,1533589856.709 [Default:CheckIn:E] Stopped 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn] Stopped 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn](INFO): Running loop #24 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn] Running Loop=24 2018-08-06T21:10:56.710Z,1533589856.710 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:10:56.711Z,1533589856.711 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:11:00.494Z,1533589860.494 [NAL9602](INFO): Powering up 2018-08-06T21:11:11.371Z,1533589871.371 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:11:51.773Z,1533589911.773 [NAL9602](INFO): SBD MO Status=2, MOMSN=23352, MT Status=2, MTMSN=0 2018-08-06T21:11:51.773Z,1533589911.773 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:12:05.913Z,1533589925.913 [NAL9602](INFO): SBD MO Status=0, MOMSN=23352, MT Status=0, MTMSN=0 2018-08-06T21:12:05.913Z,1533589925.913 [NAL9602](INFO): No messages in MT queue 2018-08-06T21:12:37.115Z,1533589957.115 [NAL9602](INFO): GPS fix at 20180806T210731: (36.802797, -121.787969) 2018-08-06T21:12:37.173Z,1533589957.173 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:12:37.173Z,1533589957.173 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:12:42.471Z,1533589962.471 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0057.lzma 2018-08-06T21:12:43.269Z,1533589963.269 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0057.lzma.bak 2018-08-06T21:12:43.270Z,1533589963.270 [DataOverHttps](INFO): SBD MOMSN=8403662 2018-08-06T21:12:53.343Z,1533589973.343 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20180806T181422/Express0058.lzma 2018-08-06T21:12:54.141Z,1533589974.141 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0058.lzma.bak 2018-08-06T21:12:54.142Z,1533589974.142 [DataOverHttps](INFO): SBD MOMSN=8403666 2018-08-06T21:12:55.586Z,1533589975.586 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:12:55.586Z,1533589975.586 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:12:55.587Z,1533589975.587 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:13:12.231Z,1533589992.231 [NAL9602](INFO): Powering down 2018-08-06T21:17:55.936Z,1533590275.936 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:17:55.936Z,1533590275.936 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:17:55.936Z,1533590275.936 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:17:55.937Z,1533590275.937 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:17:56.343Z,1533590276.343 [Default:CheckIn:D] Stopped 2018-08-06T21:17:56.344Z,1533590276.344 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:17:56.739Z,1533590276.739 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 223.505859 min 2018-08-06T21:17:56.739Z,1533590276.739 [Default:CheckIn:E] Stopped 2018-08-06T21:17:56.739Z,1533590276.739 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn] Stopped 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn](INFO): Running loop #25 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn] Running Loop=25 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:17:56.740Z,1533590276.740 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:18:00.331Z,1533590280.331 [NAL9602](INFO): Powering up 2018-08-06T21:18:11.211Z,1533590291.211 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:18:46.417Z,1533590326.417 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:18:46.417Z,1533590326.417 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:20:08.021Z,1533590408.021 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:20:08.021Z,1533590408.021 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:21:27.177Z,1533590487.177 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:21:27.177Z,1533590487.177 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:21:40.378Z,1533590500.378 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:21:40.378Z,1533590500.378 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:22:10.501Z,1533590530.501 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:22:10.501Z,1533590530.501 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:22:56.963Z,1533590576.963 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:17:56.7Z 2018-08-06T21:22:56.963Z,1533590576.963 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:22:56.964Z,1533590576.964 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:23:01.720Z,1533590581.720 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0060.lzma 2018-08-06T21:23:02.505Z,1533590582.505 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0060.lzma.bak 2018-08-06T21:23:02.505Z,1533590582.505 [DataOverHttps](INFO): SBD MOMSN=8403675 2018-08-06T21:23:12.503Z,1533590592.503 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20180806T181422/Express0061.lzma 2018-08-06T21:23:13.293Z,1533590593.293 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0061.lzma.bak 2018-08-06T21:23:13.293Z,1533590593.293 [DataOverHttps](INFO): SBD MOMSN=8403677 2018-08-06T21:23:14.764Z,1533590594.764 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:23:14.764Z,1533590594.764 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:23:14.764Z,1533590594.764 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:23:14.843Z,1533590594.843 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T21:23:48.216Z,1533590628.216 [NAL9602](INFO): Powering down 2018-08-06T21:28:15.118Z,1533590895.118 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:28:15.118Z,1533590895.118 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:28:15.118Z,1533590895.118 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:28:15.119Z,1533590895.119 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:28:15.531Z,1533590895.531 [Default:CheckIn:D] Stopped 2018-08-06T21:28:15.531Z,1533590895.531 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:28:15.932Z,1533590895.932 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 233.825651 min 2018-08-06T21:28:15.932Z,1533590895.932 [Default:CheckIn:E] Stopped 2018-08-06T21:28:15.932Z,1533590895.932 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:28:15.932Z,1533590895.932 [Default:CheckIn] Stopped 2018-08-06T21:28:15.933Z,1533590895.933 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:28:15.933Z,1533590895.933 [Default:CheckIn](INFO): Running loop #26 2018-08-06T21:28:15.933Z,1533590895.933 [Default:CheckIn] Running Loop=26 2018-08-06T21:28:15.933Z,1533590895.933 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:28:15.933Z,1533590895.933 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:28:19.224Z,1533590899.224 [NAL9602](INFO): Powering up 2018-08-06T21:28:30.423Z,1533590910.423 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:28:31.223Z,1533590911.223 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T21:28:31.223Z,1533590911.223 [NAL9602] Data Fault, FailCount= 1 2018-08-06T21:28:31.223Z,1533590911.223 [NAL9602](ERROR): Data Fault 2018-08-06T21:28:31.302Z,1533590911.302 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:28:31.624Z,1533590911.624 [NAL9602](INFO): Powering down 2018-08-06T21:28:32.493Z,1533590912.493 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T21:28:32.493Z,1533590912.493 [NAL9602] No Fault, FailCount= 1 2018-08-06T21:29:02.011Z,1533590942.011 [NAL9602](INFO): Powering up NAL9602 2018-08-06T21:29:12.822Z,1533590952.822 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:29:43.852Z,1533590983.852 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-06T21:29:43.852Z,1533590983.852 [BPC1] Communications Fault, FailCount= 1 2018-08-06T21:29:43.852Z,1533590983.852 [BPC1](ERROR): Communications Fault 2018-08-06T21:29:43.879Z,1533590983.879 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-06T21:29:45.095Z,1533590985.095 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-06T21:29:45.095Z,1533590985.095 [BPC1] No Fault, FailCount= 1 2018-08-06T21:30:15.021Z,1533591015.021 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:30:15.021Z,1533591015.021 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:31:00.038Z,1533591060.038 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:31:00.038Z,1533591060.038 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:33:16.334Z,1533591196.334 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:28:15.9Z 2018-08-06T21:33:16.334Z,1533591196.334 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:33:16.334Z,1533591196.334 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:33:21.907Z,1533591201.907 [DataOverHttps](INFO): Sending 45 bytes from file Logs/20180806T181422/Courier0063.lzma 2018-08-06T21:33:22.705Z,1533591202.705 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0063.lzma.bak 2018-08-06T21:33:22.706Z,1533591202.706 [DataOverHttps](INFO): SBD MOMSN=8403686 2018-08-06T21:33:33.848Z,1533591213.848 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20180806T181422/Express0064.lzma 2018-08-06T21:33:34.646Z,1533591214.646 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0064.lzma.bak 2018-08-06T21:33:34.646Z,1533591214.646 [DataOverHttps](INFO): SBD MOMSN=8403688 2018-08-06T21:33:36.096Z,1533591216.096 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:33:36.096Z,1533591216.096 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:33:36.096Z,1533591216.096 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:33:53.869Z,1533591233.869 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:33:53.869Z,1533591233.869 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:34:15.871Z,1533591255.871 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T21:34:46.463Z,1533591286.463 [NAL9602](INFO): Powering down 2018-08-06T21:38:36.541Z,1533591516.541 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:38:36.541Z,1533591516.541 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:38:36.546Z,1533591516.546 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:38:36.546Z,1533591516.546 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:38:36.923Z,1533591516.923 [Default:CheckIn:D] Stopped 2018-08-06T21:38:36.923Z,1533591516.923 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:38:37.330Z,1533591517.330 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 244.182194 min 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn:E] Stopped 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn] Stopped 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn](INFO): Running loop #27 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn] Running Loop=27 2018-08-06T21:38:37.331Z,1533591517.331 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:38:37.332Z,1533591517.332 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:38:40.855Z,1533591520.855 [NAL9602](INFO): Powering up 2018-08-06T21:38:51.999Z,1533591531.999 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:39:23.000Z,1533591564.000 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-08-06T21:39:24.078Z,1533591564.078 [NAL9602](FAULT): received: +CSQ:0 OK353, 2, 0, 0, 0 OK 2018-08-06T21:39:24.078Z,1533591564.078 [NAL9602] Data Fault, FailCount= 2 2018-08-06T21:39:24.078Z,1533591564.078 [NAL9602](ERROR): Data Fault 2018-08-06T21:39:24.174Z,1533591564.174 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:39:24.403Z,1533591564.403 [NAL9602](INFO): Powering down 2018-08-06T21:39:25.271Z,1533591565.271 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T21:39:25.271Z,1533591565.271 [NAL9602] No Fault, FailCount= 2 2018-08-06T21:39:54.520Z,1533591594.520 [NAL9602](INFO): Powering up NAL9602 2018-08-06T21:40:05.323Z,1533591605.323 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:40:06.123Z,1533591606.123 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T21:40:06.123Z,1533591606.123 [NAL9602] Data Fault, FailCount= 3 2018-08-06T21:40:06.123Z,1533591606.123 [NAL9602](ERROR): Data Fault 2018-08-06T21:40:06.216Z,1533591606.216 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:40:06.524Z,1533591606.524 [NAL9602](INFO): Powering down 2018-08-06T21:40:07.401Z,1533591607.401 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T21:40:07.406Z,1533591607.406 [NAL9602] No Fault, FailCount= 3 2018-08-06T21:40:36.924Z,1533591636.924 [NAL9602](INFO): Powering up NAL9602 2018-08-06T21:40:47.868Z,1533591647.868 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:42:29.740Z,1533591749.740 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:42:29.741Z,1533591749.741 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:43:01.199Z,1533591781.199 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.398671 seconds old. 2018-08-06T21:43:01.613Z,1533591781.613 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 0.812734 seconds old. 2018-08-06T21:43:02.008Z,1533591782.008 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.208467 seconds old. 2018-08-06T21:43:02.404Z,1533591782.404 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.604385 seconds old. 2018-08-06T21:43:02.798Z,1533591782.798 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 1.998233 seconds old. 2018-08-06T21:43:03.202Z,1533591783.202 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.402158 seconds old. 2018-08-06T21:43:03.606Z,1533591783.606 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 2.806576 seconds old. 2018-08-06T21:43:04.008Z,1533591784.008 [DeadReckonUsingSpeedCalculator](DEBUG): Most recent orientation data is 3.207871 seconds old. 2018-08-06T21:43:37.586Z,1533591817.586 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:38:37.3Z 2018-08-06T21:43:37.586Z,1533591817.586 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:43:37.586Z,1533591817.586 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:43:41.891Z,1533591821.891 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0066.lzma 2018-08-06T21:43:42.685Z,1533591822.685 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0066.lzma.bak 2018-08-06T21:43:42.686Z,1533591822.686 [DataOverHttps](INFO): SBD MOMSN=8403699 2018-08-06T21:43:53.426Z,1533591833.426 [DataOverHttps](INFO): Sending 254 bytes from file Logs/20180806T181422/Express0067.lzma 2018-08-06T21:43:54.223Z,1533591834.223 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0067.lzma.bak 2018-08-06T21:43:54.223Z,1533591834.223 [DataOverHttps](INFO): SBD MOMSN=8403701 2018-08-06T21:43:55.540Z,1533591835.540 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T21:43:55.578Z,1533591835.578 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:43:55.579Z,1533591835.579 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:43:55.579Z,1533591835.579 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:44:25.775Z,1533591865.775 [NAL9602](INFO): Powering down 2018-08-06T21:48:55.817Z,1533592135.817 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:48:55.818Z,1533592135.818 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:48:55.818Z,1533592135.818 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:48:55.818Z,1533592135.818 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:48:56.226Z,1533592136.226 [Default:CheckIn:D] Stopped 2018-08-06T21:48:56.226Z,1533592136.226 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:48:56.629Z,1533592136.629 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 254.503906 min 2018-08-06T21:48:56.629Z,1533592136.629 [Default:CheckIn:E] Stopped 2018-08-06T21:48:56.629Z,1533592136.629 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:48:56.629Z,1533592136.629 [Default:CheckIn] Stopped 2018-08-06T21:48:56.630Z,1533592136.630 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:48:56.630Z,1533592136.630 [Default:CheckIn](INFO): Running loop #28 2018-08-06T21:48:56.630Z,1533592136.630 [Default:CheckIn] Running Loop=28 2018-08-06T21:48:56.630Z,1533592136.630 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:48:56.630Z,1533592136.630 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:49:00.341Z,1533592140.341 [NAL9602](INFO): Powering up 2018-08-06T21:49:11.231Z,1533592151.231 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:49:43.231Z,1533592183.231 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2018-08-06T21:49:43.306Z,1533592183.306 [NAL9602](FAULT): received: +CSQ:0 OK353, 2, 0, 0, 0 OK 2018-08-06T21:49:43.307Z,1533592183.307 [NAL9602] Data Fault, FailCount= 4 2018-08-06T21:49:43.307Z,1533592183.307 [NAL9602](ERROR): Data Fault 2018-08-06T21:49:43.396Z,1533592183.396 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:49:43.627Z,1533592183.627 [NAL9602](INFO): Powering down 2018-08-06T21:49:44.504Z,1533592184.504 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T21:49:44.504Z,1533592184.504 [NAL9602] No Fault, FailCount= 4 2018-08-06T21:50:13.947Z,1533592213.947 [NAL9602](INFO): Powering up NAL9602 2018-08-06T21:50:25.143Z,1533592225.143 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:53:56.844Z,1533592436.844 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:48:56.6Z 2018-08-06T21:53:56.844Z,1533592436.844 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T21:53:56.844Z,1533592436.844 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T21:54:01.874Z,1533592441.874 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0069.lzma 2018-08-06T21:54:02.669Z,1533592442.669 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0069.lzma.bak 2018-08-06T21:54:02.670Z,1533592442.670 [DataOverHttps](INFO): SBD MOMSN=8403713 2018-08-06T21:54:12.391Z,1533592452.391 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T21:54:12.391Z,1533592452.391 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T21:54:12.504Z,1533592452.504 [DataOverHttps](INFO): Sending 238 bytes from file Logs/20180806T181422/Express0070.lzma 2018-08-06T21:54:13.298Z,1533592453.298 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0070.lzma.bak 2018-08-06T21:54:13.298Z,1533592453.298 [DataOverHttps](INFO): SBD MOMSN=8403715 2018-08-06T21:54:14.695Z,1533592454.695 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T21:54:14.695Z,1533592454.695 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T21:54:14.696Z,1533592454.696 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T21:54:17.975Z,1533592457.975 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T21:54:48.463Z,1533592488.463 [NAL9602](INFO): Powering down 2018-08-06T21:59:14.999Z,1533592754.999 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T21:59:14.999Z,1533592754.999 [Default:CheckIn:C.Wait] Stopped 2018-08-06T21:59:14.999Z,1533592754.999 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T21:59:14.999Z,1533592754.999 [Default:CheckIn:D] Running Loop=1 2018-08-06T21:59:15.393Z,1533592755.393 [Default:CheckIn:D] Stopped 2018-08-06T21:59:15.393Z,1533592755.393 [Default:CheckIn:E] Running Loop=1 2018-08-06T21:59:15.797Z,1533592755.797 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 264.823356 min 2018-08-06T21:59:15.797Z,1533592755.797 [Default:CheckIn:E] Stopped 2018-08-06T21:59:15.797Z,1533592755.797 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T21:59:15.797Z,1533592755.797 [Default:CheckIn] Stopped 2018-08-06T21:59:15.802Z,1533592755.802 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T21:59:15.802Z,1533592755.802 [Default:CheckIn](INFO): Running loop #29 2018-08-06T21:59:15.802Z,1533592755.802 [Default:CheckIn] Running Loop=29 2018-08-06T21:59:15.802Z,1533592755.802 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T21:59:15.802Z,1533592755.802 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T21:59:16.547Z,1533592756.547 [NAL9602](INFO): Powering up 2018-08-06T21:59:27.471Z,1533592767.471 [NAL9602](INFO): NAL9602 initialized 2018-08-06T21:59:28.267Z,1533592768.267 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T21:59:28.268Z,1533592768.268 [NAL9602] Data Fault, FailCount= 5 2018-08-06T21:59:28.268Z,1533592768.268 [NAL9602](ERROR): Data Fault 2018-08-06T21:59:28.372Z,1533592768.372 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T21:59:28.372Z,1533592768.372 [CBIT](CRITICAL): Data Fault in component: NAL9602 2018-08-06T21:59:28.667Z,1533592768.667 [NAL9602](INFO): Powering down 2018-08-06T21:59:28.743Z,1533592768.743 [CommandLine](FAULT): Scheduling is paused 2018-08-06T21:59:28.743Z,1533592768.743 [CBIT](INFO): Critical error at 20180806T215928 2018-08-06T22:01:28.408Z,1533592888.408 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T22:01:28.408Z,1533592888.408 [NAL9602] No Fault, FailCount= 5 2018-08-06T22:01:28.759Z,1533592888.759 [NAL9602](INFO): Powering up NAL9602 2018-08-06T22:01:39.959Z,1533592899.959 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:02:21.661Z,1533592941.661 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:02:21.661Z,1533592941.661 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:03:24.585Z,1533593004.585 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:03:24.585Z,1533593004.585 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:03:59.782Z,1533593039.782 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:03:59.782Z,1533593039.782 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:04:15.785Z,1533593055.785 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:04:15.785Z,1533593055.785 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:04:15.862Z,1533593055.862 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T21:59:15.8Z 2018-08-06T22:04:15.862Z,1533593055.862 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:04:15.863Z,1533593055.863 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:04:20.743Z,1533593060.743 [DataOverHttps](INFO): Sending 92 bytes from file Logs/20180806T181422/Courier0072.lzma 2018-08-06T22:04:21.548Z,1533593061.548 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0072.lzma.bak 2018-08-06T22:04:21.548Z,1533593061.548 [DataOverHttps](INFO): SBD MOMSN=8403726 2018-08-06T22:04:26.189Z,1533593066.189 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:04:26.189Z,1533593066.189 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:04:31.233Z,1533593071.233 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20180806T181422/Express0073.lzma 2018-08-06T22:04:32.025Z,1533593072.025 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0073.lzma.bak 2018-08-06T22:04:32.025Z,1533593072.025 [DataOverHttps](INFO): SBD MOMSN=8403729 2018-08-06T22:04:33.633Z,1533593073.633 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:04:33.633Z,1533593073.633 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:04:33.633Z,1533593073.633 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:04:42.293Z,1533593082.293 [NAL9602](INFO): SBD MO Status=2, MOMSN=23353, MT Status=2, MTMSN=0 2018-08-06T22:04:42.293Z,1533593082.293 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:04:53.477Z,1533593093.477 [NAL9602](INFO): SBD MO Status=0, MOMSN=23353, MT Status=0, MTMSN=0 2018-08-06T22:04:53.477Z,1533593093.477 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:04:53.477Z,1533593093.477 [NAL9602](INFO): Failure count cleared after critical for NAL9602 2018-08-06T22:05:24.268Z,1533593124.268 [NAL9602](INFO): Powering down 2018-08-06T22:09:33.969Z,1533593373.969 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:09:33.969Z,1533593373.969 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:09:33.969Z,1533593373.969 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:09:33.969Z,1533593373.969 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:09:34.372Z,1533593374.372 [Default:CheckIn:D] Stopped 2018-08-06T22:09:34.372Z,1533593374.372 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:09:34.776Z,1533593374.776 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 275.139681 min 2018-08-06T22:09:34.776Z,1533593374.776 [Default:CheckIn:E] Stopped 2018-08-06T22:09:34.777Z,1533593374.777 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:09:34.777Z,1533593374.777 [Default:CheckIn] Stopped 2018-08-06T22:09:34.777Z,1533593374.777 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:09:34.777Z,1533593374.777 [Default:CheckIn](INFO): Running loop #30 2018-08-06T22:09:34.777Z,1533593374.777 [Default:CheckIn] Running Loop=30 2018-08-06T22:09:34.778Z,1533593374.778 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:09:34.779Z,1533593374.779 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:09:38.375Z,1533593378.375 [NAL9602](INFO): Powering up 2018-08-06T22:09:49.259Z,1533593389.259 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:12:45.573Z,1533593565.573 [NAL9602](INFO): SBD MO Status=2, MOMSN=23354, MT Status=2, MTMSN=0 2018-08-06T22:12:45.573Z,1533593565.573 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:13:10.783Z,1533593590.783 [NAL9602](INFO): SBD MO Status=2, MOMSN=23354, MT Status=2, MTMSN=0 2018-08-06T22:13:10.783Z,1533593590.783 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:13:19.579Z,1533593599.579 [NAL9602](INFO): SBD MO Status=2, MOMSN=23354, MT Status=2, MTMSN=0 2018-08-06T22:13:19.579Z,1533593599.579 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:13:28.382Z,1533593608.382 [NAL9602](INFO): SBD MO Status=0, MOMSN=23354, MT Status=0, MTMSN=0 2018-08-06T22:13:28.382Z,1533593608.382 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:13:29.176Z,1533593609.176 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T22:13:29.176Z,1533593609.176 [NAL9602] Data Fault, FailCount= 1 2018-08-06T22:13:29.176Z,1533593609.177 [NAL9602](ERROR): Data Fault 2018-08-06T22:13:29.261Z,1533593609.261 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T22:13:29.575Z,1533593609.575 [NAL9602](INFO): Powering down 2018-08-06T22:13:30.465Z,1533593610.465 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T22:13:30.465Z,1533593610.465 [NAL9602] No Fault, FailCount= 1 2018-08-06T22:13:59.687Z,1533593639.687 [NAL9602](INFO): Powering up NAL9602 2018-08-06T22:14:10.491Z,1533593650.491 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:14:34.962Z,1533593674.962 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T22:09:34.8Z 2018-08-06T22:14:34.962Z,1533593674.962 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:14:34.962Z,1533593674.962 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:14:39.688Z,1533593679.688 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0075.lzma 2018-08-06T22:14:40.469Z,1533593680.469 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0075.lzma.bak 2018-08-06T22:14:40.469Z,1533593680.469 [DataOverHttps](INFO): SBD MOMSN=8403743 2018-08-06T22:14:51.154Z,1533593691.154 [DataOverHttps](INFO): Sending 162 bytes from file Logs/20180806T181422/Express0076.lzma 2018-08-06T22:14:51.941Z,1533593691.941 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0076.lzma.bak 2018-08-06T22:14:51.941Z,1533593691.941 [DataOverHttps](INFO): SBD MOMSN=8403745 2018-08-06T22:14:53.366Z,1533593693.366 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:14:53.366Z,1533593693.366 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:14:53.366Z,1533593693.366 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:15:09.931Z,1533593709.931 [NAL9602](INFO): Powering down 2018-08-06T22:19:53.518Z,1533593993.518 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:19:53.518Z,1533593993.518 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:19:53.518Z,1533593993.518 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:19:53.519Z,1533593993.519 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:19:53.939Z,1533593993.939 [Default:CheckIn:D] Stopped 2018-08-06T22:19:53.939Z,1533593993.939 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:19:54.333Z,1533593994.333 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 285.465788 min 2018-08-06T22:19:54.338Z,1533593994.338 [Default:CheckIn:E] Stopped 2018-08-06T22:19:54.338Z,1533593994.338 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:19:54.338Z,1533593994.338 [Default:CheckIn] Stopped 2018-08-06T22:19:54.338Z,1533593994.338 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:19:54.339Z,1533593994.339 [Default:CheckIn](INFO): Running loop #31 2018-08-06T22:19:54.339Z,1533593994.339 [Default:CheckIn] Running Loop=31 2018-08-06T22:19:54.339Z,1533593994.339 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:19:54.339Z,1533593994.339 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:19:58.106Z,1533593998.106 [NAL9602](INFO): Powering up 2018-08-06T22:20:09.003Z,1533594009.003 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:21:51.973Z,1533594111.973 [NAL9602](INFO): SBD MO Status=2, MOMSN=23355, MT Status=2, MTMSN=0 2018-08-06T22:21:51.973Z,1533594111.973 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:22:09.033Z,1533594129.033 [NAL9602](INFO): SBD MO Status=2, MOMSN=23355, MT Status=2, MTMSN=0 2018-08-06T22:22:09.033Z,1533594129.033 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:22:26.637Z,1533594146.637 [NAL9602](INFO): SBD MO Status=2, MOMSN=23355, MT Status=2, MTMSN=0 2018-08-06T22:22:26.637Z,1533594146.637 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:22:36.638Z,1533594156.638 [NAL9602](INFO): SBD MO Status=0, MOMSN=23355, MT Status=0, MTMSN=0 2018-08-06T22:22:36.638Z,1533594156.638 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:24:13.503Z,1533594253.503 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T22:24:13.503Z,1533594253.503 [NAL9602] Data Fault, FailCount= 1 2018-08-06T22:24:13.503Z,1533594253.503 [NAL9602](ERROR): Data Fault 2018-08-06T22:24:13.585Z,1533594253.585 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T22:24:13.904Z,1533594253.904 [NAL9602](INFO): Powering down 2018-08-06T22:24:14.783Z,1533594254.783 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T22:24:14.783Z,1533594254.783 [NAL9602] No Fault, FailCount= 1 2018-08-06T22:24:44.299Z,1533594284.299 [NAL9602](INFO): Powering up NAL9602 2018-08-06T22:24:54.370Z,1533594294.370 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T22:19:54.3Z 2018-08-06T22:24:54.370Z,1533594294.370 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:24:54.371Z,1533594294.371 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:24:56.124Z,1533594296.124 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:24:59.955Z,1533594299.955 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0078.lzma 2018-08-06T22:25:01.549Z,1533594301.549 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0078.lzma.bak 2018-08-06T22:25:01.552Z,1533594301.552 [DataOverHttps](INFO): SBD MOMSN=8403757 2018-08-06T22:25:12.732Z,1533594312.732 [DataOverHttps](INFO): Sending 163 bytes from file Logs/20180806T181422/Express0079.lzma 2018-08-06T22:25:13.529Z,1533594313.529 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0079.lzma.bak 2018-08-06T22:25:13.529Z,1533594313.529 [DataOverHttps](INFO): SBD MOMSN=8403759 2018-08-06T22:25:14.891Z,1533594314.891 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:25:14.891Z,1533594314.891 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:25:14.891Z,1533594314.891 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:25:29.903Z,1533594329.903 [NAL9602](INFO): Powering down 2018-08-06T22:30:15.139Z,1533594615.139 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:30:15.139Z,1533594615.139 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:30:15.139Z,1533594615.139 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:30:15.140Z,1533594615.140 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:30:15.565Z,1533594615.565 [Default:CheckIn:D] Stopped 2018-08-06T22:30:15.566Z,1533594615.566 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:30:15.935Z,1533594615.935 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 295.826237 min 2018-08-06T22:30:15.935Z,1533594615.935 [Default:CheckIn:E] Stopped 2018-08-06T22:30:15.935Z,1533594615.935 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:30:15.936Z,1533594615.936 [Default:CheckIn] Stopped 2018-08-06T22:30:15.936Z,1533594615.936 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:30:15.936Z,1533594615.936 [Default:CheckIn](INFO): Running loop #32 2018-08-06T22:30:15.936Z,1533594615.936 [Default:CheckIn] Running Loop=32 2018-08-06T22:30:15.937Z,1533594615.937 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:30:15.937Z,1533594615.937 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:30:19.660Z,1533594619.660 [NAL9602](INFO): Powering up 2018-08-06T22:30:30.551Z,1533594630.551 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:31:27.633Z,1533594687.633 [NAL9602](INFO): SBD MO Status=0, MOMSN=23356, MT Status=0, MTMSN=0 2018-08-06T22:31:27.633Z,1533594687.633 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:33:43.635Z,1533594823.635 [NAL9602](INFO): GPS fix at 20180806T222830: (36.802779, -121.788074) 2018-08-06T22:33:43.698Z,1533594823.698 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:33:43.698Z,1533594823.698 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:33:48.651Z,1533594828.651 [DataOverHttps](INFO): Sending 78 bytes from file Logs/20180806T181422/Courier0081.lzma 2018-08-06T22:33:49.441Z,1533594829.441 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0081.lzma.bak 2018-08-06T22:33:49.441Z,1533594829.441 [DataOverHttps](INFO): SBD MOMSN=8403770 2018-08-06T22:34:00.841Z,1533594840.841 [DataOverHttps](INFO): Sending 123 bytes from file Logs/20180806T181422/Express0082.lzma 2018-08-06T22:34:01.633Z,1533594841.633 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0082.lzma.bak 2018-08-06T22:34:01.634Z,1533594841.634 [DataOverHttps](INFO): SBD MOMSN=8403773 2018-08-06T22:34:03.023Z,1533594843.023 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:34:03.023Z,1533594843.023 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:34:03.023Z,1533594843.023 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:34:18.935Z,1533594858.935 [NAL9602](INFO): Powering down 2018-08-06T22:39:03.164Z,1533595143.164 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:39:03.164Z,1533595143.164 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:39:03.164Z,1533595143.164 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:39:03.164Z,1533595143.164 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:39:03.564Z,1533595143.564 [Default:CheckIn:D] Stopped 2018-08-06T22:39:03.564Z,1533595143.564 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:39:03.963Z,1533595143.963 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 304.626204 min 2018-08-06T22:39:03.963Z,1533595143.963 [Default:CheckIn:E] Stopped 2018-08-06T22:39:03.963Z,1533595143.963 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn] Stopped 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn](INFO): Running loop #33 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn] Running Loop=33 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:39:03.964Z,1533595143.964 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:39:04.719Z,1533595144.719 [NAL9602](INFO): Powering up 2018-08-06T22:39:15.643Z,1533595155.643 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:39:35.245Z,1533595175.245 [NAL9602](INFO): SBD MO Status=0, MOMSN=23357, MT Status=0, MTMSN=0 2018-08-06T22:39:35.245Z,1533595175.245 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:40:14.211Z,1533595214.211 [NAL9602](INFO): GPS fix at 20180806T223500: (36.802819, -121.787986) 2018-08-06T22:40:14.277Z,1533595214.277 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:40:14.277Z,1533595214.277 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:40:19.540Z,1533595219.540 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20180806T181422/Courier0084.lzma 2018-08-06T22:40:20.337Z,1533595220.337 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0084.lzma.bak 2018-08-06T22:40:20.337Z,1533595220.337 [DataOverHttps](INFO): SBD MOMSN=8403782 2018-08-06T22:40:31.596Z,1533595231.596 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20180806T181422/Express0085.lzma 2018-08-06T22:40:32.385Z,1533595232.385 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0085.lzma.bak 2018-08-06T22:40:32.385Z,1533595232.385 [DataOverHttps](INFO): SBD MOMSN=8403785 2018-08-06T22:40:33.768Z,1533595233.768 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:40:33.768Z,1533595233.768 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:40:33.768Z,1533595233.768 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:40:49.251Z,1533595249.251 [NAL9602](INFO): Powering down 2018-08-06T22:45:34.160Z,1533595534.160 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:45:34.160Z,1533595534.160 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:45:34.160Z,1533595534.160 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:45:34.161Z,1533595534.161 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:45:34.566Z,1533595534.566 [Default:CheckIn:D] Stopped 2018-08-06T22:45:34.566Z,1533595534.566 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:45:34.978Z,1533595534.978 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 311.142904 min 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn:E] Stopped 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn] Stopped 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn](INFO): Running loop #34 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn] Running Loop=34 2018-08-06T22:45:34.979Z,1533595534.979 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:45:34.980Z,1533595534.980 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:45:38.552Z,1533595538.552 [NAL9602](INFO): Powering up 2018-08-06T22:45:49.467Z,1533595549.467 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:46:17.065Z,1533595577.065 [NAL9602](INFO): SBD MO Status=0, MOMSN=23358, MT Status=0, MTMSN=0 2018-08-06T22:46:17.065Z,1533595577.065 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:47:14.008Z,1533595634.008 [NAL9602](INFO): GPS fix at 20180806T224200: (36.802950, -121.788006) 2018-08-06T22:47:14.066Z,1533595634.066 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:47:14.067Z,1533595634.067 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:47:18.966Z,1533595638.966 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20180806T181422/Courier0087.lzma 2018-08-06T22:47:19.799Z,1533595639.799 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0087.lzma.bak 2018-08-06T22:47:19.800Z,1533595639.800 [DataOverHttps](INFO): SBD MOMSN=8403795 2018-08-06T22:47:30.271Z,1533595650.271 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20180806T181422/Express0088.lzma 2018-08-06T22:47:31.071Z,1533595651.071 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0088.lzma.bak 2018-08-06T22:47:31.071Z,1533595651.071 [DataOverHttps](INFO): SBD MOMSN=8403798 2018-08-06T22:47:32.514Z,1533595652.514 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:47:32.514Z,1533595652.514 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:47:32.515Z,1533595652.515 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:47:49.147Z,1533595669.147 [NAL9602](INFO): Powering down 2018-08-06T22:50:27.416Z,1533595827.416 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 100.000000 cubic_centimeter 2018-08-06T22:50:27.418Z,1533595827.418 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.buoyancyAction" handled in the control thread. 2018-08-06T22:50:27.695Z,1533595827.695 [controlThread](DEBUG): Component order: CycleStarter,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-08-06T22:51:11.327Z,1533595871.327 [CommandLine](IMPORTANT): got command report mod platform_buoyancy_position 2018-08-06T22:51:11.447Z,1533595871.447 [Reporter](INFO): platform_buoyancy_position 458.221533 cc 2018-08-06T22:51:11.810Z,1533595871.810 [Reporter](INFO): platform_buoyancy_position 453.789631 cc 2018-08-06T22:51:12.209Z,1533595872.209 [Reporter](INFO): platform_buoyancy_position 449.357758 cc 2018-08-06T22:51:12.610Z,1533595872.610 [Reporter](INFO): platform_buoyancy_position 443.045632 cc 2018-08-06T22:51:13.013Z,1533595873.013 [Reporter](INFO): platform_buoyancy_position 438.748015 cc 2018-08-06T22:51:13.397Z,1533595873.397 [Reporter](INFO): platform_buoyancy_position 434.047513 cc 2018-08-06T22:51:13.793Z,1533595873.793 [Reporter](INFO): platform_buoyancy_position 428.004045 cc 2018-08-06T22:51:14.217Z,1533595874.217 [Reporter](INFO): platform_buoyancy_position 421.557634 cc 2018-08-06T22:51:14.597Z,1533595874.597 [Reporter](INFO): platform_buoyancy_position 417.260046 cc 2018-08-06T22:51:15.002Z,1533595875.002 [Reporter](INFO): platform_buoyancy_position 410.813635 cc 2018-08-06T22:51:15.405Z,1533595875.405 [Reporter](INFO): platform_buoyancy_position 406.381732 cc 2018-08-06T22:51:15.809Z,1533595875.809 [Reporter](INFO): platform_buoyancy_position 400.069635 cc 2018-08-06T22:51:16.213Z,1533595876.213 [Reporter](INFO): platform_buoyancy_position 395.637733 cc 2018-08-06T22:51:16.598Z,1533595876.598 [Reporter](INFO): platform_buoyancy_position 391.340145 cc 2018-08-06T22:51:17.011Z,1533595877.011 [Reporter](INFO): platform_buoyancy_position 384.490850 cc 2018-08-06T22:51:17.409Z,1533595877.409 [Reporter](INFO): platform_buoyancy_position 379.521720 cc 2018-08-06T22:51:17.818Z,1533595877.818 [Reporter](INFO): platform_buoyancy_position 374.149764 cc 2018-08-06T22:51:18.222Z,1533595878.222 [Reporter](INFO): platform_buoyancy_position 369.852147 cc 2018-08-06T22:51:18.586Z,1533595878.586 [Reporter](INFO): platform_buoyancy_position 365.017331 cc 2018-08-06T22:51:18.994Z,1533595878.994 [Reporter](INFO): platform_buoyancy_position 359.511061 cc 2018-08-06T22:51:19.397Z,1533595879.397 [Reporter](INFO): platform_buoyancy_position 353.601848 cc 2018-08-06T22:51:19.805Z,1533595879.805 [Reporter](INFO): platform_buoyancy_position 348.498434 cc 2018-08-06T22:51:20.201Z,1533595880.201 [Reporter](INFO): platform_buoyancy_position 342.052022 cc 2018-08-06T22:51:20.609Z,1533595880.609 [Reporter](INFO): platform_buoyancy_position 338.023034 cc 2018-08-06T22:51:21.001Z,1533595881.001 [Reporter](INFO): platform_buoyancy_position 333.322532 cc 2018-08-06T22:51:21.417Z,1533595881.417 [Reporter](INFO): platform_buoyancy_position 327.144749 cc 2018-08-06T22:51:21.813Z,1533595881.813 [Reporter](INFO): platform_buoyancy_position 322.712818 cc 2018-08-06T22:51:22.189Z,1533595882.189 [Reporter](INFO): platform_buoyancy_position 318.415230 cc 2018-08-06T22:51:22.593Z,1533595882.593 [Reporter](INFO): platform_buoyancy_position 313.983328 cc 2018-08-06T22:51:22.997Z,1533595882.997 [Reporter](INFO): platform_buoyancy_position 307.671231 cc 2018-08-06T22:51:23.390Z,1533595883.390 [Reporter](INFO): platform_buoyancy_position 301.224820 cc 2018-08-06T22:51:23.801Z,1533595883.801 [Reporter](INFO): platform_buoyancy_position 297.061517 cc 2018-08-06T22:51:24.215Z,1533595884.215 [Reporter](INFO): platform_buoyancy_position 291.689532 cc 2018-08-06T22:51:24.609Z,1533595884.609 [Reporter](INFO): platform_buoyancy_position 286.183233 cc 2018-08-06T22:51:25.017Z,1533595885.017 [Reporter](INFO): platform_buoyancy_position 281.751330 cc 2018-08-06T22:51:25.409Z,1533595885.409 [Reporter](INFO): platform_buoyancy_position 275.573519 cc 2018-08-06T22:51:25.813Z,1533595885.813 [Reporter](INFO): platform_buoyancy_position 270.738732 cc 2018-08-06T22:51:26.229Z,1533595886.229 [Reporter](INFO): platform_buoyancy_position 264.829519 cc 2018-08-06T22:51:26.605Z,1533595886.605 [Reporter](INFO): platform_buoyancy_position 260.263332 cc 2018-08-06T22:51:27.005Z,1533595887.005 [Reporter](INFO): platform_buoyancy_position 253.951235 cc 2018-08-06T22:51:27.413Z,1533595887.413 [Reporter](INFO): platform_buoyancy_position 249.519304 cc 2018-08-06T22:51:27.829Z,1533595887.829 [Reporter](INFO): platform_buoyancy_position 243.744420 cc 2018-08-06T22:51:28.205Z,1533595888.205 [Reporter](INFO): platform_buoyancy_position 238.909633 cc 2018-08-06T22:51:28.590Z,1533595888.590 [Reporter](INFO): platform_buoyancy_position 234.209132 cc 2018-08-06T22:51:28.993Z,1533595888.993 [Reporter](INFO): platform_buoyancy_position 228.165620 cc 2018-08-06T22:51:29.413Z,1533595889.413 [Reporter](INFO): platform_buoyancy_position 223.733732 cc 2018-08-06T22:51:29.809Z,1533595889.809 [Reporter](INFO): platform_buoyancy_position 217.421635 cc 2018-08-06T22:51:30.225Z,1533595890.225 [Reporter](INFO): platform_buoyancy_position 212.989718 cc 2018-08-06T22:51:30.597Z,1533595890.597 [Reporter](INFO): platform_buoyancy_position 208.826415 cc 2018-08-06T22:51:31.013Z,1533595891.013 [Reporter](INFO): platform_buoyancy_position 202.245734 cc 2018-08-06T22:51:31.386Z,1533595891.386 [Reporter](INFO): platform_buoyancy_position 198.216730 cc 2018-08-06T22:51:31.809Z,1533595891.809 [Reporter](INFO): platform_buoyancy_position 191.501735 cc 2018-08-06T22:51:32.186Z,1533595892.186 [Reporter](INFO): platform_buoyancy_position 186.935518 cc 2018-08-06T22:51:32.617Z,1533595892.617 [Reporter](INFO): platform_buoyancy_position 180.757721 cc 2018-08-06T22:51:32.989Z,1533595892.989 [Reporter](INFO): platform_buoyancy_position 176.594418 cc 2018-08-06T22:51:33.405Z,1533595893.405 [Reporter](INFO): platform_buoyancy_position 170.148007 cc 2018-08-06T22:51:33.815Z,1533595893.815 [Reporter](INFO): platform_buoyancy_position 165.716119 cc 2018-08-06T22:51:37.114Z,1533595897.114 [Reporter](INFO): platform_buoyancy_position 122.874408 cc 2018-08-06T22:51:37.245Z,1533595897.245 [Reporter](INFO): platform_buoyancy_position 120.591314 cc 2018-08-06T22:51:37.633Z,1533595897.633 [Reporter](INFO): platform_buoyancy_position 116.159419 cc 2018-08-06T22:51:38.070Z,1533595898.070 [Reporter](INFO): platform_buoyancy_position 109.981607 cc 2018-08-06T22:52:32.781Z,1533595952.781 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T22:52:32.782Z,1533595952.782 [Default:CheckIn:C.Wait] Stopped 2018-08-06T22:52:32.782Z,1533595952.782 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T22:52:32.782Z,1533595952.782 [Default:CheckIn:D] Running Loop=1 2018-08-06T22:52:33.196Z,1533595953.196 [Default:CheckIn:D] Stopped 2018-08-06T22:52:33.196Z,1533595953.196 [Default:CheckIn:E] Running Loop=1 2018-08-06T22:52:33.583Z,1533595953.583 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 318.120085 min 2018-08-06T22:52:33.583Z,1533595953.583 [Default:CheckIn:E] Stopped 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn] Stopped 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn](INFO): Running loop #35 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn] Running Loop=35 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T22:52:33.584Z,1533595953.584 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T22:52:37.170Z,1533595957.170 [NAL9602](INFO): Powering up 2018-08-06T22:52:48.088Z,1533595968.088 [NAL9602](INFO): NAL9602 initialized 2018-08-06T22:53:26.490Z,1533596006.490 [NAL9602](INFO): SBD MO Status=2, MOMSN=23359, MT Status=2, MTMSN=0 2018-08-06T22:53:26.490Z,1533596006.490 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:54:09.509Z,1533596049.509 [NAL9602](INFO): SBD MO Status=2, MOMSN=23359, MT Status=2, MTMSN=0 2018-08-06T22:54:09.509Z,1533596049.509 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T22:55:15.643Z,1533596115.643 [CommandLine](IMPORTANT): got command report 2018-08-06T22:55:15.643Z,1533596115.643 [Reporter](INFO): platform_buoyancy_position reporting changes 2018-08-06T22:55:39.479Z,1533596139.479 [NAL9602](INFO): SBD MO Status=0, MOMSN=23359, MT Status=0, MTMSN=0 2018-08-06T22:55:39.480Z,1533596139.480 [NAL9602](INFO): No messages in MT queue 2018-08-06T22:55:40.462Z,1533596140.462 [NAL9602](INFO): GPS fix at 20180806T225026: (36.802961, -121.788009) 2018-08-06T22:55:40.535Z,1533596140.535 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T22:55:40.535Z,1533596140.535 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T22:55:48.934Z,1533596148.934 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0090.lzma 2018-08-06T22:55:49.709Z,1533596149.709 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0090.lzma.bak 2018-08-06T22:55:49.709Z,1533596149.709 [DataOverHttps](INFO): SBD MOMSN=8403803 2018-08-06T22:56:07.902Z,1533596167.902 [DataOverHttps](INFO): Sending 235 bytes from file Logs/20180806T181422/Express0091.lzma 2018-08-06T22:56:08.701Z,1533596168.701 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0091.lzma.bak 2018-08-06T22:56:08.702Z,1533596168.702 [DataOverHttps](INFO): SBD MOMSN=8403806 2018-08-06T22:56:11.021Z,1533596171.021 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T22:56:11.021Z,1533596171.021 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T22:56:11.021Z,1533596171.021 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T22:56:17.453Z,1533596177.453 [NAL9602](INFO): Powering down 2018-08-06T22:59:43.333Z,1533596383.333 [CommandLine](IMPORTANT): got command maintain control VerticalControl.massPositionAction 1.000000 centimeter 2018-08-06T22:59:43.334Z,1533596383.334 [ComponentRegistry](DEBUG): SyncComponent "Maintain_VerticalControl.massPositionAction" handled in the control thread. 2018-08-06T22:59:43.473Z,1533596383.473 [controlThread](DEBUG): Component order: CycleStarter,AcousticModem_Benthos_ATM900,DataOverHttps,Depth_Keller,DropWeight,NAL9602,Onboard,PNI_TCM,BPC1,Aanderaa_O2,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,VerticalTemperatureHomogeneityIndexCalculator,YawRateCalculator,ElevatorOffsetCalculator,StratificationFrontDetector,DeadReckonUsingSpeedCalculator,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,Maintain_VerticalControl.buoyancyAction,Maintain_VerticalControl.massPositionAction,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter, 2018-08-06T23:00:49.520Z,1533596449.520 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 500.000000 cubic_centimeter 2018-08-06T23:00:50.929Z,1533596450.929 [Reporter](INFO): platform_buoyancy_position 105.415413 cc 2018-08-06T23:00:51.321Z,1533596451.321 [Reporter](INFO): platform_buoyancy_position 105.684012 cc 2018-08-06T23:00:52.109Z,1533596452.109 [Reporter](INFO): platform_buoyancy_position 105.549705 cc 2018-08-06T23:00:52.513Z,1533596452.513 [Reporter](INFO): platform_buoyancy_position 109.713008 cc 2018-08-06T23:00:52.893Z,1533596452.893 [Reporter](INFO): platform_buoyancy_position 114.144903 cc 2018-08-06T23:00:53.285Z,1533596453.285 [Reporter](INFO): platform_buoyancy_position 118.576805 cc 2018-08-06T23:00:53.685Z,1533596453.685 [Reporter](INFO): platform_buoyancy_position 124.888902 cc 2018-08-06T23:00:54.109Z,1533596454.109 [Reporter](INFO): platform_buoyancy_position 131.335328 cc 2018-08-06T23:00:54.509Z,1533596454.509 [Reporter](INFO): platform_buoyancy_position 135.632901 cc 2018-08-06T23:00:54.894Z,1533596454.894 [Reporter](INFO): platform_buoyancy_position 141.004915 cc 2018-08-06T23:00:55.295Z,1533596455.295 [Reporter](INFO): platform_buoyancy_position 146.376929 cc 2018-08-06T23:00:55.701Z,1533596455.701 [Reporter](INFO): platform_buoyancy_position 151.077416 cc 2018-08-06T23:00:56.101Z,1533596456.101 [Reporter](INFO): platform_buoyancy_position 157.120914 cc 2018-08-06T23:00:56.513Z,1533596456.513 [Reporter](INFO): platform_buoyancy_position 163.164426 cc 2018-08-06T23:00:56.893Z,1533596456.893 [Reporter](INFO): platform_buoyancy_position 167.864928 cc 2018-08-06T23:00:57.309Z,1533596457.309 [Reporter](INFO): platform_buoyancy_position 174.177039 cc 2018-08-06T23:00:57.707Z,1533596457.707 [Reporter](INFO): platform_buoyancy_position 178.743227 cc 2018-08-06T23:00:58.097Z,1533596458.097 [Reporter](INFO): platform_buoyancy_position 183.040829 cc 2018-08-06T23:00:58.485Z,1533596458.485 [Reporter](INFO): platform_buoyancy_position 189.352941 cc 2018-08-06T23:00:58.893Z,1533596458.893 [Reporter](INFO): platform_buoyancy_position 193.784814 cc 2018-08-06T23:00:59.286Z,1533596459.286 [Reporter](INFO): platform_buoyancy_position 200.231225 cc 2018-08-06T23:00:59.694Z,1533596459.694 [Reporter](INFO): platform_buoyancy_position 204.394528 cc 2018-08-06T23:01:00.097Z,1533596460.097 [Reporter](INFO): platform_buoyancy_position 208.960730 cc 2018-08-06T23:01:00.490Z,1533596460.490 [Reporter](INFO): platform_buoyancy_position 215.138512 cc 2018-08-06T23:01:00.913Z,1533596460.913 [Reporter](INFO): platform_buoyancy_position 221.584924 cc 2018-08-06T23:01:01.317Z,1533596461.317 [Reporter](INFO): platform_buoyancy_position 225.882541 cc 2018-08-06T23:01:01.709Z,1533596461.709 [Reporter](INFO): platform_buoyancy_position 230.314428 cc 2018-08-06T23:01:02.113Z,1533596462.113 [Reporter](INFO): platform_buoyancy_position 236.760839 cc 2018-08-06T23:01:02.497Z,1533596462.497 [Reporter](INFO): platform_buoyancy_position 241.058442 cc 2018-08-06T23:01:02.885Z,1533596462.885 [Reporter](INFO): platform_buoyancy_position 247.236225 cc 2018-08-06T23:01:03.293Z,1533596463.293 [Reporter](INFO): platform_buoyancy_position 251.668127 cc 2018-08-06T23:01:03.713Z,1533596463.713 [Reporter](INFO): platform_buoyancy_position 257.845910 cc 2018-08-06T23:01:04.089Z,1533596464.089 [Reporter](INFO): platform_buoyancy_position 262.546411 cc 2018-08-06T23:01:04.493Z,1533596464.493 [Reporter](INFO): platform_buoyancy_position 268.724252 cc 2018-08-06T23:01:04.894Z,1533596464.894 [Reporter](INFO): platform_buoyancy_position 273.156125 cc 2018-08-06T23:01:05.309Z,1533596465.309 [Reporter](INFO): platform_buoyancy_position 277.588057 cc 2018-08-06T23:01:05.709Z,1533596465.709 [Reporter](INFO): platform_buoyancy_position 283.900154 cc 2018-08-06T23:01:06.109Z,1533596466.109 [Reporter](INFO): platform_buoyancy_position 290.346536 cc 2018-08-06T23:01:06.505Z,1533596466.505 [Reporter](INFO): platform_buoyancy_position 294.644124 cc 2018-08-06T23:01:06.907Z,1533596466.907 [Reporter](INFO): platform_buoyancy_position 299.076026 cc 2018-08-06T23:01:07.358Z,1533596467.358 [Reporter](INFO): platform_buoyancy_position 305.388123 cc 2018-08-06T23:01:07.693Z,1533596467.693 [Reporter](INFO): platform_buoyancy_position 309.820025 cc 2018-08-06T23:01:08.109Z,1533596468.109 [Reporter](INFO): platform_buoyancy_position 314.117642 cc 2018-08-06T23:01:08.493Z,1533596468.493 [Reporter](INFO): platform_buoyancy_position 318.549544 cc 2018-08-06T23:01:08.890Z,1533596468.890 [Reporter](INFO): platform_buoyancy_position 324.727327 cc 2018-08-06T23:01:09.297Z,1533596469.297 [Reporter](INFO): platform_buoyancy_position 331.173738 cc 2018-08-06T23:01:09.709Z,1533596469.709 [Reporter](INFO): platform_buoyancy_position 335.605611 cc 2018-08-06T23:01:10.098Z,1533596470.098 [Reporter](INFO): platform_buoyancy_position 339.768943 cc 2018-08-06T23:01:10.509Z,1533596470.509 [Reporter](INFO): platform_buoyancy_position 346.215325 cc 2018-08-06T23:01:10.917Z,1533596470.917 [Reporter](INFO): platform_buoyancy_position 352.124538 cc 2018-08-06T23:01:11.263Z,1533596471.263 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T23:01:11.263Z,1533596471.263 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:01:11.263Z,1533596471.263 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:01:11.264Z,1533596471.264 [Default:CheckIn:D] Running Loop=1 2018-08-06T23:01:11.313Z,1533596471.313 [Reporter](INFO): platform_buoyancy_position 356.825039 cc 2018-08-06T23:01:11.658Z,1533596471.658 [Default:CheckIn:D] Stopped 2018-08-06T23:01:11.658Z,1533596471.658 [Default:CheckIn:E] Running Loop=1 2018-08-06T23:01:11.706Z,1533596471.706 [Reporter](INFO): platform_buoyancy_position 361.391227 cc 2018-08-06T23:01:12.054Z,1533596472.054 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 326.761035 min 2018-08-06T23:01:12.054Z,1533596472.054 [Default:CheckIn:E] Stopped 2018-08-06T23:01:12.054Z,1533596472.054 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T23:01:12.054Z,1533596472.054 [Default:CheckIn] Stopped 2018-08-06T23:01:12.055Z,1533596472.055 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:01:12.055Z,1533596472.055 [Default:CheckIn](INFO): Running loop #36 2018-08-06T23:01:12.055Z,1533596472.055 [Default:CheckIn] Running Loop=36 2018-08-06T23:01:12.055Z,1533596472.055 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T23:01:12.055Z,1533596472.055 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T23:01:12.113Z,1533596472.113 [Reporter](INFO): platform_buoyancy_position 367.703353 cc 2018-08-06T23:01:12.509Z,1533596472.509 [Reporter](INFO): platform_buoyancy_position 373.746821 cc 2018-08-06T23:01:15.656Z,1533596475.656 [NAL9602](INFO): Powering up 2018-08-06T23:01:15.765Z,1533596475.765 [Reporter](INFO): platform_buoyancy_position 415.111223 cc 2018-08-06T23:01:15.905Z,1533596475.905 [Reporter](INFO): platform_buoyancy_position 417.260046 cc 2018-08-06T23:01:16.281Z,1533596476.281 [Reporter](INFO): platform_buoyancy_position 421.691919 cc 2018-08-06T23:01:16.681Z,1533596476.681 [Reporter](INFO): platform_buoyancy_position 429.078471 cc 2018-08-06T23:01:17.093Z,1533596477.093 [Reporter](INFO): platform_buoyancy_position 434.316142 cc 2018-08-06T23:01:17.493Z,1533596477.493 [Reporter](INFO): platform_buoyancy_position 438.613730 cc 2018-08-06T23:01:17.881Z,1533596477.881 [Reporter](INFO): platform_buoyancy_position 442.911347 cc 2018-08-06T23:01:18.281Z,1533596478.281 [Reporter](INFO): platform_buoyancy_position 447.208964 cc 2018-08-06T23:01:18.698Z,1533596478.698 [Reporter](INFO): platform_buoyancy_position 453.655375 cc 2018-08-06T23:01:19.077Z,1533596479.077 [Reporter](INFO): platform_buoyancy_position 458.087248 cc 2018-08-06T23:01:19.477Z,1533596479.477 [Reporter](INFO): platform_buoyancy_position 464.399316 cc 2018-08-06T23:01:19.881Z,1533596479.881 [Reporter](INFO): platform_buoyancy_position 470.845727 cc 2018-08-06T23:01:20.281Z,1533596480.281 [Reporter](INFO): platform_buoyancy_position 477.426423 cc 2018-08-06T23:01:20.690Z,1533596480.690 [Reporter](INFO): platform_buoyancy_position 479.575217 cc 2018-08-06T23:01:24.309Z,1533596484.309 [Reporter](INFO): platform_buoyancy_position 496.765657 cc 2018-08-06T23:01:26.579Z,1533596486.579 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:01:42.581Z,1533596502.581 [NAL9602](INFO): SBD MO Status=0, MOMSN=23360, MT Status=0, MTMSN=0 2018-08-06T23:01:42.581Z,1533596502.581 [NAL9602](INFO): No messages in MT queue 2018-08-06T23:01:51.490Z,1533596511.490 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 90.000000 cubic_centimeter 2018-08-06T23:01:56.400Z,1533596516.400 [Reporter](INFO): platform_buoyancy_position 499.183079 cc 2018-08-06T23:01:56.730Z,1533596516.730 [Reporter](INFO): platform_buoyancy_position 500.928902 cc 2018-08-06T23:01:57.151Z,1533596517.151 [Reporter](INFO): platform_buoyancy_position 498.914451 cc 2018-08-06T23:01:57.538Z,1533596517.538 [Reporter](INFO): platform_buoyancy_position 493.005209 cc 2018-08-06T23:01:57.929Z,1533596517.929 [Reporter](INFO): platform_buoyancy_position 490.319217 cc 2018-08-06T23:01:58.333Z,1533596518.333 [Reporter](INFO): platform_buoyancy_position 486.021629 cc 2018-08-06T23:01:58.742Z,1533596518.742 [Reporter](INFO): platform_buoyancy_position 481.724041 cc 2018-08-06T23:01:59.105Z,1533596519.105 [Reporter](INFO): platform_buoyancy_position 477.426423 cc 2018-08-06T23:01:59.505Z,1533596519.505 [Reporter](INFO): platform_buoyancy_position 473.800319 cc 2018-08-06T23:01:59.875Z,1533596519.875 [Reporter](INFO): platform_buoyancy_position 468.831277 cc 2018-08-06T23:02:00.301Z,1533596520.301 [Reporter](INFO): platform_buoyancy_position 464.533659 cc 2018-08-06T23:02:00.705Z,1533596520.705 [Reporter](INFO): platform_buoyancy_position 460.101728 cc 2018-08-06T23:02:01.130Z,1533596521.130 [Reporter](INFO): platform_buoyancy_position 453.655375 cc 2018-08-06T23:02:01.510Z,1533596521.510 [Reporter](INFO): platform_buoyancy_position 449.492043 cc 2018-08-06T23:02:01.894Z,1533596521.894 [Reporter](INFO): platform_buoyancy_position 444.791542 cc 2018-08-06T23:02:02.281Z,1533596522.281 [Reporter](INFO): platform_buoyancy_position 438.613730 cc 2018-08-06T23:02:02.677Z,1533596522.677 [Reporter](INFO): platform_buoyancy_position 433.913228 cc 2018-08-06T23:02:03.078Z,1533596523.078 [Reporter](INFO): platform_buoyancy_position 428.004045 cc 2018-08-06T23:02:03.501Z,1533596523.501 [Reporter](INFO): platform_buoyancy_position 423.034944 cc 2018-08-06T23:02:03.881Z,1533596523.881 [Reporter](INFO): platform_buoyancy_position 417.260046 cc 2018-08-06T23:02:04.305Z,1533596524.305 [Reporter](INFO): platform_buoyancy_position 410.947949 cc 2018-08-06T23:02:04.701Z,1533596524.701 [Reporter](INFO): platform_buoyancy_position 406.381732 cc 2018-08-06T23:02:05.097Z,1533596525.097 [Reporter](INFO): platform_buoyancy_position 399.935321 cc 2018-08-06T23:02:05.482Z,1533596525.482 [Reporter](INFO): platform_buoyancy_position 395.637733 cc 2018-08-06T23:02:05.889Z,1533596525.889 [Reporter](INFO): platform_buoyancy_position 389.325665 cc 2018-08-06T23:02:06.282Z,1533596526.282 [Reporter](INFO): platform_buoyancy_position 385.028048 cc 2018-08-06T23:02:06.678Z,1533596526.678 [Reporter](INFO): platform_buoyancy_position 378.447323 cc 2018-08-06T23:02:07.097Z,1533596527.097 [Reporter](INFO): platform_buoyancy_position 374.149764 cc 2018-08-06T23:02:07.497Z,1533596527.497 [Reporter](INFO): platform_buoyancy_position 368.106237 cc 2018-08-06T23:02:07.897Z,1533596527.897 [Reporter](INFO): platform_buoyancy_position 363.540050 cc 2018-08-06T23:02:08.273Z,1533596528.273 [Reporter](INFO): platform_buoyancy_position 359.242433 cc 2018-08-06T23:02:08.685Z,1533596528.685 [Reporter](INFO): platform_buoyancy_position 354.810560 cc 2018-08-06T23:02:09.097Z,1533596529.097 [Reporter](INFO): platform_buoyancy_position 348.498434 cc 2018-08-06T23:02:09.485Z,1533596529.485 [Reporter](INFO): platform_buoyancy_position 344.066531 cc 2018-08-06T23:02:09.877Z,1533596529.877 [Reporter](INFO): platform_buoyancy_position 338.157348 cc 2018-08-06T23:02:10.310Z,1533596530.310 [Reporter](INFO): platform_buoyancy_position 333.188218 cc 2018-08-06T23:02:10.591Z,1533596530.591 [NAL9602](INFO): GPS fix at 20180806T225655: (36.802932, -121.788053) 2018-08-06T23:02:10.672Z,1533596530.672 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T23:02:10.672Z,1533596530.672 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T23:02:10.719Z,1533596530.719 [Reporter](INFO): platform_buoyancy_position 326.876121 cc 2018-08-06T23:02:11.110Z,1533596531.110 [Reporter](INFO): platform_buoyancy_position 322.309934 cc 2018-08-06T23:02:12.013Z,1533596532.013 [Reporter](INFO): platform_buoyancy_position 311.834534 cc 2018-08-06T23:02:12.189Z,1533596532.189 [Reporter](INFO): platform_buoyancy_position 309.685740 cc 2018-08-06T23:02:12.529Z,1533596532.529 [Reporter](INFO): platform_buoyancy_position 303.910841 cc 2018-08-06T23:02:15.970Z,1533596535.970 [Reporter](INFO): platform_buoyancy_position 258.114538 cc 2018-08-06T23:02:16.099Z,1533596536.099 [Reporter](INFO): platform_buoyancy_position 256.100029 cc 2018-08-06T23:02:16.383Z,1533596536.383 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0093.lzma 2018-08-06T23:02:16.505Z,1533596536.505 [Reporter](INFO): platform_buoyancy_position 251.668127 cc 2018-08-06T23:02:16.877Z,1533596536.877 [Reporter](INFO): platform_buoyancy_position 247.370539 cc 2018-08-06T23:02:17.274Z,1533596537.274 [Reporter](INFO): platform_buoyancy_position 241.058442 cc 2018-08-06T23:02:17.581Z,1533596537.581 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0093.lzma.bak 2018-08-06T23:02:17.581Z,1533596537.581 [DataOverHttps](INFO): SBD MOMSN=8403822 2018-08-06T23:02:17.713Z,1533596537.713 [Reporter](INFO): platform_buoyancy_position 235.283544 cc 2018-08-06T23:02:19.033Z,1533596539.033 [Reporter](INFO): platform_buoyancy_position 217.958834 cc 2018-08-06T23:02:19.181Z,1533596539.181 [Reporter](INFO): platform_buoyancy_position 217.555935 cc 2018-08-06T23:02:19.549Z,1533596539.549 [Reporter](INFO): platform_buoyancy_position 210.840910 cc 2018-08-06T23:02:19.949Z,1533596539.949 [Reporter](INFO): platform_buoyancy_position 206.677607 cc 2018-08-06T23:02:20.341Z,1533596540.341 [Reporter](INFO): platform_buoyancy_position 202.245734 cc 2018-08-06T23:02:20.753Z,1533596540.753 [Reporter](INFO): platform_buoyancy_position 193.919128 cc 2018-08-06T23:02:21.169Z,1533596541.169 [Reporter](INFO): platform_buoyancy_position 189.487211 cc 2018-08-06T23:02:21.547Z,1533596541.547 [Reporter](INFO): platform_buoyancy_position 185.189638 cc 2018-08-06T23:02:21.937Z,1533596541.937 [Reporter](INFO): platform_buoyancy_position 178.743227 cc 2018-08-06T23:02:22.337Z,1533596542.337 [Reporter](INFO): platform_buoyancy_position 174.445624 cc 2018-08-06T23:02:22.745Z,1533596542.745 [Reporter](INFO): platform_buoyancy_position 170.013736 cc 2018-08-06T23:02:23.149Z,1533596543.149 [Reporter](INFO): platform_buoyancy_position 163.567325 cc 2018-08-06T23:02:23.557Z,1533596543.557 [Reporter](INFO): platform_buoyancy_position 157.120914 cc 2018-08-06T23:02:23.973Z,1533596543.973 [Reporter](INFO): platform_buoyancy_position 153.091925 cc 2018-08-06T23:02:24.353Z,1533596544.353 [Reporter](INFO): platform_buoyancy_position 146.511200 cc 2018-08-06T23:02:24.757Z,1533596544.757 [Reporter](INFO): platform_buoyancy_position 142.213627 cc 2018-08-06T23:02:25.149Z,1533596545.149 [Reporter](INFO): platform_buoyancy_position 137.781710 cc 2018-08-06T23:02:25.553Z,1533596545.553 [Reporter](INFO): platform_buoyancy_position 131.469598 cc 2018-08-06T23:02:25.978Z,1533596545.978 [Reporter](INFO): platform_buoyancy_position 127.037711 cc 2018-08-06T23:02:26.354Z,1533596546.354 [Reporter](INFO): platform_buoyancy_position 120.725606 cc 2018-08-06T23:02:26.759Z,1533596546.759 [Reporter](INFO): platform_buoyancy_position 116.562311 cc 2018-08-06T23:02:27.145Z,1533596547.145 [Reporter](INFO): platform_buoyancy_position 111.727517 cc 2018-08-06T23:02:27.553Z,1533596547.553 [Reporter](INFO): platform_buoyancy_position 105.684012 cc 2018-08-06T23:02:34.173Z,1533596554.173 [Reporter](INFO): platform_buoyancy_position 92.791204 cc 2018-08-06T23:02:39.912Z,1533596559.912 [DataOverHttps](INFO): Sending 230 bytes from file Logs/20180806T181422/Express0094.lzma 2018-08-06T23:02:40.709Z,1533596560.709 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0094.lzma.bak 2018-08-06T23:02:40.710Z,1533596560.710 [DataOverHttps](INFO): SBD MOMSN=8403825 2018-08-06T23:02:42.100Z,1533596562.100 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T23:02:42.100Z,1533596562.100 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T23:02:42.100Z,1533596562.100 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T23:02:42.556Z,1533596562.556 [NAL9602](INFO): Powering down 2018-08-06T23:03:06.068Z,1533596586.068 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 500.000000 cubic_centimeter 2018-08-06T23:03:10.589Z,1533596590.589 [Reporter](INFO): platform_buoyancy_position 92.656912 cc 2018-08-06T23:03:10.964Z,1533596590.964 [Reporter](INFO): platform_buoyancy_position 92.791204 cc 2018-08-06T23:03:11.769Z,1533596591.769 [Reporter](INFO): platform_buoyancy_position 93.059803 cc 2018-08-06T23:03:12.188Z,1533596592.188 [Reporter](INFO): platform_buoyancy_position 97.088814 cc 2018-08-06T23:03:12.579Z,1533596592.579 [Reporter](INFO): platform_buoyancy_position 101.252110 cc 2018-08-06T23:03:12.966Z,1533596592.966 [Reporter](INFO): platform_buoyancy_position 105.818304 cc 2018-08-06T23:03:13.353Z,1533596593.353 [Reporter](INFO): platform_buoyancy_position 111.996116 cc 2018-08-06T23:03:13.770Z,1533596593.770 [Reporter](INFO): platform_buoyancy_position 116.428018 cc 2018-08-06T23:03:14.157Z,1533596594.157 [Reporter](INFO): platform_buoyancy_position 122.874408 cc 2018-08-06T23:03:14.557Z,1533596594.557 [Reporter](INFO): platform_buoyancy_position 127.306310 cc 2018-08-06T23:03:14.977Z,1533596594.977 [Reporter](INFO): platform_buoyancy_position 133.752721 cc 2018-08-06T23:03:15.357Z,1533596595.357 [Reporter](INFO): platform_buoyancy_position 138.587522 cc 2018-08-06T23:03:15.772Z,1533596595.772 [Reporter](INFO): platform_buoyancy_position 144.362421 cc 2018-08-06T23:03:16.170Z,1533596596.170 [Reporter](INFO): platform_buoyancy_position 148.794308 cc 2018-08-06T23:03:16.569Z,1533596596.569 [Reporter](INFO): platform_buoyancy_position 155.106420 cc 2018-08-06T23:03:16.978Z,1533596596.978 [Reporter](INFO): platform_buoyancy_position 160.747004 cc 2018-08-06T23:03:17.369Z,1533596597.369 [Reporter](INFO): platform_buoyancy_position 165.716119 cc 2018-08-06T23:03:17.761Z,1533596597.761 [Reporter](INFO): platform_buoyancy_position 172.162530 cc 2018-08-06T23:03:18.181Z,1533596598.181 [Reporter](INFO): platform_buoyancy_position 176.460118 cc 2018-08-06T23:03:18.561Z,1533596598.561 [Reporter](INFO): platform_buoyancy_position 180.892035 cc 2018-08-06T23:03:18.983Z,1533596598.983 [Reporter](INFO): platform_buoyancy_position 187.204132 cc 2018-08-06T23:03:19.373Z,1533596599.373 [Reporter](INFO): platform_buoyancy_position 191.636020 cc 2018-08-06T23:03:19.765Z,1533596599.765 [Reporter](INFO): platform_buoyancy_position 197.813817 cc 2018-08-06T23:03:20.149Z,1533596600.149 [Reporter](INFO): platform_buoyancy_position 202.380033 cc 2018-08-06T23:03:20.549Z,1533596600.549 [Reporter](INFO): platform_buoyancy_position 206.677607 cc 2018-08-06T23:03:20.965Z,1533596600.965 [Reporter](INFO): platform_buoyancy_position 212.989718 cc 2018-08-06T23:03:21.357Z,1533596601.357 [Reporter](INFO): platform_buoyancy_position 218.093133 cc 2018-08-06T23:03:21.761Z,1533596601.761 [Reporter](INFO): platform_buoyancy_position 223.733732 cc 2018-08-06T23:03:22.162Z,1533596602.162 [Reporter](INFO): platform_buoyancy_position 228.031335 cc 2018-08-06T23:03:22.577Z,1533596602.577 [Reporter](INFO): platform_buoyancy_position 234.612031 cc 2018-08-06T23:03:22.962Z,1533596602.962 [Reporter](INFO): platform_buoyancy_position 238.775334 cc 2018-08-06T23:03:23.373Z,1533596603.373 [Reporter](INFO): platform_buoyancy_position 245.356030 cc 2018-08-06T23:03:23.765Z,1533596603.765 [Reporter](INFO): platform_buoyancy_position 249.653618 cc 2018-08-06T23:03:24.161Z,1533596604.161 [Reporter](INFO): platform_buoyancy_position 254.085549 cc 2018-08-06T23:03:24.573Z,1533596604.573 [Reporter](INFO): platform_buoyancy_position 260.397646 cc 2018-08-06T23:03:24.977Z,1533596604.977 [Reporter](INFO): platform_buoyancy_position 264.695234 cc 2018-08-06T23:03:25.373Z,1533596605.373 [Reporter](INFO): platform_buoyancy_position 271.141645 cc 2018-08-06T23:03:25.761Z,1533596605.761 [Reporter](INFO): platform_buoyancy_position 275.439234 cc 2018-08-06T23:03:26.163Z,1533596606.163 [Reporter](INFO): platform_buoyancy_position 281.751330 cc 2018-08-06T23:03:26.565Z,1533596606.565 [Reporter](INFO): platform_buoyancy_position 286.183233 cc 2018-08-06T23:03:26.987Z,1533596606.987 [Reporter](INFO): platform_buoyancy_position 292.495330 cc 2018-08-06T23:03:27.369Z,1533596607.369 [Reporter](INFO): platform_buoyancy_position 296.792947 cc 2018-08-06T23:03:27.781Z,1533596607.781 [Reporter](INFO): platform_buoyancy_position 301.359134 cc 2018-08-06T23:03:28.173Z,1533596608.173 [Reporter](INFO): platform_buoyancy_position 307.536917 cc 2018-08-06T23:03:28.577Z,1533596608.577 [Reporter](INFO): platform_buoyancy_position 312.103162 cc 2018-08-06T23:03:28.969Z,1533596608.969 [Reporter](INFO): platform_buoyancy_position 316.132151 cc 2018-08-06T23:03:29.377Z,1533596609.377 [Reporter](INFO): platform_buoyancy_position 322.712818 cc 2018-08-06T23:03:29.775Z,1533596609.775 [Reporter](INFO): platform_buoyancy_position 328.890630 cc 2018-08-06T23:03:30.177Z,1533596610.177 [Reporter](INFO): platform_buoyancy_position 333.456846 cc 2018-08-06T23:03:30.553Z,1533596610.553 [Reporter](INFO): platform_buoyancy_position 337.754434 cc 2018-08-06T23:03:30.953Z,1533596610.953 [Reporter](INFO): platform_buoyancy_position 344.066531 cc 2018-08-06T23:03:31.357Z,1533596611.357 [Reporter](INFO): platform_buoyancy_position 348.498434 cc 2018-08-06T23:03:31.781Z,1533596611.781 [Reporter](INFO): platform_buoyancy_position 354.810560 cc 2018-08-06T23:03:32.161Z,1533596612.161 [Reporter](INFO): platform_buoyancy_position 359.242433 cc 2018-08-06T23:03:32.557Z,1533596612.557 [Reporter](INFO): platform_buoyancy_position 365.688844 cc 2018-08-06T23:03:32.961Z,1533596612.961 [Reporter](INFO): platform_buoyancy_position 369.986461 cc 2018-08-06T23:03:33.377Z,1533596613.377 [Reporter](INFO): platform_buoyancy_position 376.567128 cc 2018-08-06T23:03:33.793Z,1533596613.793 [Reporter](INFO): platform_buoyancy_position 382.744940 cc 2018-08-06T23:03:34.169Z,1533596614.169 [Reporter](INFO): platform_buoyancy_position 385.565247 cc 2018-08-06T23:03:34.550Z,1533596614.550 [Reporter](INFO): platform_buoyancy_position 389.594235 cc 2018-08-06T23:03:34.949Z,1533596614.949 [Reporter](INFO): platform_buoyancy_position 395.772047 cc 2018-08-06T23:03:35.353Z,1533596615.353 [Reporter](INFO): platform_buoyancy_position 402.352744 cc 2018-08-06T23:03:35.757Z,1533596615.757 [Reporter](INFO): platform_buoyancy_position 406.516046 cc 2018-08-06T23:03:36.161Z,1533596616.161 [Reporter](INFO): platform_buoyancy_position 412.828143 cc 2018-08-06T23:03:36.561Z,1533596616.561 [Reporter](INFO): platform_buoyancy_position 417.260046 cc 2018-08-06T23:03:36.978Z,1533596616.978 [Reporter](INFO): platform_buoyancy_position 423.572114 cc 2018-08-06T23:03:37.381Z,1533596617.381 [Reporter](INFO): platform_buoyancy_position 430.018525 cc 2018-08-06T23:03:37.781Z,1533596617.781 [Reporter](INFO): platform_buoyancy_position 434.316142 cc 2018-08-06T23:03:38.173Z,1533596618.173 [Reporter](INFO): platform_buoyancy_position 438.613730 cc 2018-08-06T23:03:38.557Z,1533596618.557 [Reporter](INFO): platform_buoyancy_position 442.911347 cc 2018-08-06T23:03:38.973Z,1533596618.973 [Reporter](INFO): platform_buoyancy_position 449.223415 cc 2018-08-06T23:03:39.365Z,1533596619.365 [Reporter](INFO): platform_buoyancy_position 453.655375 cc 2018-08-06T23:03:39.765Z,1533596619.765 [Reporter](INFO): platform_buoyancy_position 458.624418 cc 2018-08-06T23:03:40.185Z,1533596620.185 [Reporter](INFO): platform_buoyancy_position 466.548139 cc 2018-08-06T23:03:40.573Z,1533596620.573 [Reporter](INFO): platform_buoyancy_position 470.980071 cc 2018-08-06T23:03:40.985Z,1533596620.985 [Reporter](INFO): platform_buoyancy_position 477.292138 cc 2018-08-06T23:03:41.377Z,1533596621.377 [Reporter](INFO): platform_buoyancy_position 481.589756 cc 2018-08-06T23:03:46.753Z,1533596626.753 [Reporter](INFO): platform_buoyancy_position 498.780108 cc 2018-08-06T23:07:03.073Z,1533596823.073 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 300.000000 cubic_centimeter 2018-08-06T23:07:07.689Z,1533596827.689 [Reporter](INFO): platform_buoyancy_position 500.928902 cc 2018-08-06T23:07:08.869Z,1533596828.869 [Reporter](INFO): platform_buoyancy_position 494.482578 cc 2018-08-06T23:07:09.273Z,1533596829.273 [Reporter](INFO): platform_buoyancy_position 491.259387 cc 2018-08-06T23:07:09.659Z,1533596829.659 [Reporter](INFO): platform_buoyancy_position 488.170452 cc 2018-08-06T23:07:10.057Z,1533596830.057 [Reporter](INFO): platform_buoyancy_position 483.872835 cc 2018-08-06T23:07:10.441Z,1533596830.441 [Reporter](INFO): platform_buoyancy_position 479.440961 cc 2018-08-06T23:07:10.845Z,1533596830.845 [Reporter](INFO): platform_buoyancy_position 475.277629 cc 2018-08-06T23:07:11.245Z,1533596831.245 [Reporter](INFO): platform_buoyancy_position 470.308558 cc 2018-08-06T23:07:11.645Z,1533596831.645 [Reporter](INFO): platform_buoyancy_position 465.876627 cc 2018-08-06T23:07:12.061Z,1533596832.061 [Reporter](INFO): platform_buoyancy_position 460.236042 cc 2018-08-06T23:07:12.445Z,1533596832.445 [Reporter](INFO): platform_buoyancy_position 455.804169 cc 2018-08-06T23:07:12.849Z,1533596832.849 [Reporter](INFO): platform_buoyancy_position 451.237953 cc 2018-08-06T23:07:13.257Z,1533596833.257 [Reporter](INFO): platform_buoyancy_position 445.060141 cc 2018-08-06T23:07:13.653Z,1533596833.653 [Reporter](INFO): platform_buoyancy_position 438.882358 cc 2018-08-06T23:07:14.053Z,1533596834.053 [Reporter](INFO): platform_buoyancy_position 434.181857 cc 2018-08-06T23:07:14.441Z,1533596834.441 [Reporter](INFO): platform_buoyancy_position 428.809843 cc 2018-08-06T23:07:14.841Z,1533596834.841 [Reporter](INFO): platform_buoyancy_position 423.572114 cc 2018-08-06T23:07:15.245Z,1533596835.245 [Reporter](INFO): platform_buoyancy_position 417.394331 cc 2018-08-06T23:07:15.649Z,1533596835.649 [Reporter](INFO): platform_buoyancy_position 412.828143 cc 2018-08-06T23:07:16.045Z,1533596836.045 [Reporter](INFO): platform_buoyancy_position 406.381732 cc 2018-08-06T23:07:16.445Z,1533596836.445 [Reporter](INFO): platform_buoyancy_position 402.084144 cc 2018-08-06T23:07:16.873Z,1533596836.873 [Reporter](INFO): platform_buoyancy_position 396.040647 cc 2018-08-06T23:07:17.265Z,1533596837.265 [Reporter](INFO): platform_buoyancy_position 391.340145 cc 2018-08-06T23:07:17.665Z,1533596837.665 [Reporter](INFO): platform_buoyancy_position 385.028048 cc 2018-08-06T23:07:18.057Z,1533596838.057 [Reporter](INFO): platform_buoyancy_position 378.581637 cc 2018-08-06T23:07:18.446Z,1533596838.446 [Reporter](INFO): platform_buoyancy_position 374.284020 cc 2018-08-06T23:07:18.845Z,1533596838.845 [Reporter](INFO): platform_buoyancy_position 369.852147 cc 2018-08-06T23:07:19.241Z,1533596839.241 [Reporter](INFO): platform_buoyancy_position 365.688844 cc 2018-08-06T23:07:19.645Z,1533596839.645 [Reporter](INFO): platform_buoyancy_position 360.988342 cc 2018-08-06T23:07:20.063Z,1533596840.063 [Reporter](INFO): platform_buoyancy_position 354.944816 cc 2018-08-06T23:07:20.453Z,1533596840.453 [Reporter](INFO): platform_buoyancy_position 349.438546 cc 2018-08-06T23:07:20.889Z,1533596840.889 [Reporter](INFO): platform_buoyancy_position 344.200846 cc 2018-08-06T23:07:21.265Z,1533596841.265 [Reporter](INFO): platform_buoyancy_position 339.903228 cc 2018-08-06T23:07:21.657Z,1533596841.657 [Reporter](INFO): platform_buoyancy_position 333.591131 cc 2018-08-06T23:07:22.057Z,1533596842.057 [Reporter](INFO): platform_buoyancy_position 329.159229 cc 2018-08-06T23:07:22.461Z,1533596842.461 [Reporter](INFO): platform_buoyancy_position 323.115732 cc 2018-08-06T23:07:22.845Z,1533596842.845 [Reporter](INFO): platform_buoyancy_position 318.280945 cc 2018-08-06T23:07:26.494Z,1533596846.494 [Reporter](INFO): platform_buoyancy_position 303.239329 cc 2018-08-06T23:07:42.398Z,1533596862.398 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T23:07:42.398Z,1533596862.398 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:07:42.398Z,1533596862.398 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:07:42.398Z,1533596862.398 [Default:CheckIn:D] Running Loop=1 2018-08-06T23:07:42.807Z,1533596862.807 [Default:CheckIn:D] Stopped 2018-08-06T23:07:42.807Z,1533596862.807 [Default:CheckIn:E] Running Loop=1 2018-08-06T23:07:43.205Z,1533596863.205 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 333.280273 min 2018-08-06T23:07:43.205Z,1533596863.205 [Default:CheckIn:E] Stopped 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn] Stopped 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn](INFO): Running loop #37 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn] Running Loop=37 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T23:07:43.206Z,1533596863.206 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T23:07:46.538Z,1533596866.538 [NAL9602](INFO): Powering up 2018-08-06T23:07:57.696Z,1533596877.696 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:08:40.975Z,1533596920.975 [CommandLine](IMPORTANT): got command maintain control VerticalControl.buoyancyAction 945.000000 cubic_centimeter 2018-08-06T23:08:48.858Z,1533596928.858 [Reporter](INFO): platform_buoyancy_position 303.373614 cc 2018-08-06T23:08:49.253Z,1533596929.253 [Reporter](INFO): platform_buoyancy_position 305.522437 cc 2018-08-06T23:08:49.656Z,1533596929.656 [Reporter](INFO): platform_buoyancy_position 309.685740 cc 2018-08-06T23:08:50.053Z,1533596930.053 [Reporter](INFO): platform_buoyancy_position 313.983328 cc 2018-08-06T23:08:50.461Z,1533596930.461 [Reporter](INFO): platform_buoyancy_position 320.429739 cc 2018-08-06T23:08:50.874Z,1533596930.874 [Reporter](INFO): platform_buoyancy_position 324.861641 cc 2018-08-06T23:08:51.261Z,1533596931.261 [Reporter](INFO): platform_buoyancy_position 331.173738 cc 2018-08-06T23:08:51.682Z,1533596931.682 [Reporter](INFO): platform_buoyancy_position 337.485835 cc 2018-08-06T23:08:52.069Z,1533596932.069 [Reporter](INFO): platform_buoyancy_position 341.917737 cc 2018-08-06T23:08:52.453Z,1533596932.453 [Reporter](INFO): platform_buoyancy_position 348.632748 cc 2018-08-06T23:08:52.889Z,1533596932.889 [Reporter](INFO): platform_buoyancy_position 354.810560 cc 2018-08-06T23:08:53.245Z,1533596933.245 [Reporter](INFO): platform_buoyancy_position 359.108119 cc 2018-08-06T23:08:53.653Z,1533596933.653 [Reporter](INFO): platform_buoyancy_position 364.211533 cc 2018-08-06T23:08:54.053Z,1533596934.053 [Reporter](INFO): platform_buoyancy_position 369.852147 cc 2018-08-06T23:08:54.453Z,1533596934.453 [Reporter](INFO): platform_buoyancy_position 376.432843 cc 2018-08-06T23:08:54.850Z,1533596934.850 [Reporter](INFO): platform_buoyancy_position 382.476341 cc 2018-08-06T23:08:55.261Z,1533596935.261 [Reporter](INFO): platform_buoyancy_position 387.176842 cc 2018-08-06T23:08:55.665Z,1533596935.665 [Reporter](INFO): platform_buoyancy_position 391.340145 cc 2018-08-06T23:08:56.065Z,1533596936.065 [Reporter](INFO): platform_buoyancy_position 397.786527 cc 2018-08-06T23:08:56.457Z,1533596936.457 [Reporter](INFO): platform_buoyancy_position 402.084144 cc 2018-08-06T23:08:56.850Z,1533596936.850 [Reporter](INFO): platform_buoyancy_position 406.516046 cc 2018-08-06T23:08:57.293Z,1533596937.293 [Reporter](INFO): platform_buoyancy_position 412.828143 cc 2018-08-06T23:08:57.653Z,1533596937.653 [Reporter](INFO): platform_buoyancy_position 417.260046 cc 2018-08-06T23:08:58.057Z,1533596938.057 [Reporter](INFO): platform_buoyancy_position 423.572114 cc 2018-08-06T23:08:58.453Z,1533596938.453 [Reporter](INFO): platform_buoyancy_position 430.152868 cc 2018-08-06T23:08:58.849Z,1533596938.849 [Reporter](INFO): platform_buoyancy_position 434.450456 cc 2018-08-06T23:08:59.259Z,1533596939.259 [Reporter](INFO): platform_buoyancy_position 438.479474 cc 2018-08-06T23:08:59.665Z,1533596939.665 [Reporter](INFO): platform_buoyancy_position 442.911347 cc 2018-08-06T23:09:00.069Z,1533596940.069 [Reporter](INFO): platform_buoyancy_position 449.357758 cc 2018-08-06T23:09:00.469Z,1533596940.469 [Reporter](INFO): platform_buoyancy_position 453.655375 cc 2018-08-06T23:09:00.873Z,1533596940.873 [Reporter](INFO): platform_buoyancy_position 460.101728 cc 2018-08-06T23:09:01.261Z,1533596941.261 [Reporter](INFO): platform_buoyancy_position 464.399316 cc 2018-08-06T23:09:01.645Z,1533596941.645 [Reporter](INFO): platform_buoyancy_position 470.980071 cc 2018-08-06T23:09:02.079Z,1533596942.079 [Reporter](INFO): platform_buoyancy_position 477.292138 cc 2018-08-06T23:09:02.445Z,1533596942.445 [Reporter](INFO): platform_buoyancy_position 481.589756 cc 2018-08-06T23:09:02.869Z,1533596942.869 [Reporter](INFO): platform_buoyancy_position 486.021629 cc 2018-08-06T23:09:03.270Z,1533596943.270 [Reporter](INFO): platform_buoyancy_position 492.333784 cc 2018-08-06T23:09:03.661Z,1533596943.661 [Reporter](INFO): platform_buoyancy_position 496.631372 cc 2018-08-06T23:09:04.061Z,1533596944.061 [Reporter](INFO): platform_buoyancy_position 502.003299 cc 2018-08-06T23:09:04.446Z,1533596944.446 [Reporter](INFO): platform_buoyancy_position 507.375342 cc 2018-08-06T23:09:04.882Z,1533596944.882 [Reporter](INFO): platform_buoyancy_position 511.807215 cc 2018-08-06T23:09:05.251Z,1533596945.251 [Reporter](INFO): platform_buoyancy_position 518.119312 cc 2018-08-06T23:09:05.561Z,1533596945.561 [NAL9602](INFO): SBD MO Status=0, MOMSN=23361, MT Status=0, MTMSN=0 2018-08-06T23:09:05.561Z,1533596945.561 [NAL9602](INFO): No messages in MT queue 2018-08-06T23:09:05.701Z,1533596945.701 [Reporter](INFO): platform_buoyancy_position 522.685528 cc 2018-08-06T23:09:06.062Z,1533596946.062 [Reporter](INFO): platform_buoyancy_position 528.997625 cc 2018-08-06T23:09:06.481Z,1533596946.481 [Reporter](INFO): platform_buoyancy_position 533.295213 cc 2018-08-06T23:09:06.881Z,1533596946.881 [Reporter](INFO): platform_buoyancy_position 539.607310 cc 2018-08-06T23:09:07.273Z,1533596947.273 [Reporter](INFO): platform_buoyancy_position 544.039242 cc 2018-08-06T23:09:07.657Z,1533596947.657 [Reporter](INFO): platform_buoyancy_position 548.336771 cc 2018-08-06T23:09:08.057Z,1533596948.057 [Reporter](INFO): platform_buoyancy_position 554.648926 cc 2018-08-06T23:09:08.465Z,1533596948.465 [Reporter](INFO): platform_buoyancy_position 559.080800 cc 2018-08-06T23:09:08.874Z,1533596948.874 [Reporter](INFO): platform_buoyancy_position 565.392955 cc 2018-08-06T23:09:09.281Z,1533596949.281 [Reporter](INFO): platform_buoyancy_position 569.690543 cc 2018-08-06T23:09:09.683Z,1533596949.683 [Reporter](INFO): platform_buoyancy_position 576.002640 cc 2018-08-06T23:09:10.082Z,1533596950.082 [Reporter](INFO): platform_buoyancy_position 580.568856 cc 2018-08-06T23:09:10.481Z,1533596950.481 [Reporter](INFO): platform_buoyancy_position 584.732101 cc 2018-08-06T23:09:10.865Z,1533596950.865 [Reporter](INFO): platform_buoyancy_position 591.178541 cc 2018-08-06T23:09:11.270Z,1533596951.270 [Reporter](INFO): platform_buoyancy_position 595.476129 cc 2018-08-06T23:09:11.685Z,1533596951.685 [Reporter](INFO): platform_buoyancy_position 601.788226 cc 2018-08-06T23:09:12.081Z,1533596952.081 [Reporter](INFO): platform_buoyancy_position 606.220157 cc 2018-08-06T23:09:12.465Z,1533596952.465 [Reporter](INFO): platform_buoyancy_position 610.652030 cc 2018-08-06T23:09:12.866Z,1533596952.866 [Reporter](INFO): platform_buoyancy_position 616.964127 cc 2018-08-06T23:09:13.293Z,1533596953.293 [Reporter](INFO): platform_buoyancy_position 621.396000 cc 2018-08-06T23:09:13.669Z,1533596953.669 [Reporter](INFO): platform_buoyancy_position 627.708156 cc 2018-08-06T23:09:14.073Z,1533596954.073 [Reporter](INFO): platform_buoyancy_position 632.005744 cc 2018-08-06T23:09:14.457Z,1533596954.457 [Reporter](INFO): platform_buoyancy_position 636.571902 cc 2018-08-06T23:09:14.889Z,1533596954.889 [Reporter](INFO): platform_buoyancy_position 642.884057 cc 2018-08-06T23:09:15.289Z,1533596955.289 [Reporter](INFO): platform_buoyancy_position 649.061811 cc 2018-08-06T23:09:15.697Z,1533596955.697 [Reporter](INFO): platform_buoyancy_position 653.628027 cc 2018-08-06T23:09:16.081Z,1533596956.081 [Reporter](INFO): platform_buoyancy_position 657.925673 cc 2018-08-06T23:09:16.473Z,1533596956.473 [Reporter](INFO): platform_buoyancy_position 662.626175 cc 2018-08-06T23:09:16.866Z,1533596956.866 [Reporter](INFO): platform_buoyancy_position 668.535358 cc 2018-08-06T23:09:17.259Z,1533596957.259 [Reporter](INFO): platform_buoyancy_position 672.967231 cc 2018-08-06T23:09:17.669Z,1533596957.669 [Reporter](INFO): platform_buoyancy_position 679.279387 cc 2018-08-06T23:09:17.963Z,1533596957.963 [NAL9602](INFO): GPS fix at 20180806T230402: (36.803001, -121.787952) 2018-08-06T23:09:18.034Z,1533596958.034 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T23:09:18.035Z,1533596958.035 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T23:09:18.085Z,1533596958.085 [Reporter](INFO): platform_buoyancy_position 683.711260 cc 2018-08-06T23:09:18.474Z,1533596958.474 [Reporter](INFO): platform_buoyancy_position 688.948901 cc 2018-08-06T23:09:19.514Z,1533596959.514 [Reporter](INFO): platform_buoyancy_position 702.916121 cc 2018-08-06T23:09:19.662Z,1533596959.662 [Reporter](INFO): platform_buoyancy_position 705.199200 cc 2018-08-06T23:09:22.971Z,1533596962.971 [Reporter](INFO): platform_buoyancy_position 748.040969 cc 2018-08-06T23:09:22.986Z,1533596962.986 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0096.lzma 2018-08-06T23:09:23.113Z,1533596963.113 [Reporter](INFO): platform_buoyancy_position 750.189763 cc 2018-08-06T23:09:23.498Z,1533596963.498 [Reporter](INFO): platform_buoyancy_position 754.487352 cc 2018-08-06T23:09:23.781Z,1533596963.781 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0096.lzma.bak 2018-08-06T23:09:23.787Z,1533596963.787 [DataOverHttps](INFO): SBD MOMSN=8403838 2018-08-06T23:09:23.960Z,1533596963.960 [Reporter](INFO): platform_buoyancy_position 760.933734 cc 2018-08-06T23:09:25.263Z,1533596965.263 [Reporter](INFO): platform_buoyancy_position 778.124144 cc 2018-08-06T23:09:25.405Z,1533596965.405 [Reporter](INFO): platform_buoyancy_position 780.272938 cc 2018-08-06T23:09:28.635Z,1533596968.635 [Reporter](INFO): platform_buoyancy_position 821.637339 cc 2018-08-06T23:09:28.770Z,1533596968.770 [Reporter](INFO): platform_buoyancy_position 823.517505 cc 2018-08-06T23:09:29.147Z,1533596969.147 [Reporter](INFO): platform_buoyancy_position 829.561031 cc 2018-08-06T23:09:29.575Z,1533596969.575 [Reporter](INFO): platform_buoyancy_position 833.992905 cc 2018-08-06T23:09:29.949Z,1533596969.949 [Reporter](INFO): platform_buoyancy_position 840.036431 cc 2018-08-06T23:09:30.353Z,1533596970.353 [Reporter](INFO): platform_buoyancy_position 844.736933 cc 2018-08-06T23:09:33.609Z,1533596973.609 [Reporter](INFO): platform_buoyancy_position 887.578703 cc 2018-08-06T23:09:33.625Z,1533596973.625 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20180806T181422/Express0097.lzma 2018-08-06T23:09:33.753Z,1533596973.753 [Reporter](INFO): platform_buoyancy_position 889.861782 cc 2018-08-06T23:09:34.125Z,1533596974.125 [Reporter](INFO): platform_buoyancy_position 894.159370 cc 2018-08-06T23:09:34.422Z,1533596974.422 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0097.lzma.bak 2018-08-06T23:09:34.422Z,1533596974.422 [DataOverHttps](INFO): SBD MOMSN=8403841 2018-08-06T23:09:34.526Z,1533596974.526 [Reporter](INFO): platform_buoyancy_position 899.262785 cc 2018-08-06T23:09:36.004Z,1533596976.004 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T23:09:36.004Z,1533596976.004 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T23:09:36.004Z,1533596976.004 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T23:09:36.049Z,1533596976.049 [Reporter](INFO): platform_buoyancy_position 919.944956 cc 2018-08-06T23:09:36.198Z,1533596976.198 [Reporter](INFO): platform_buoyancy_position 922.093750 cc 2018-08-06T23:09:39.548Z,1533596979.548 [Reporter](INFO): platform_buoyancy_position 941.567239 cc 2018-08-06T23:09:53.163Z,1533596993.163 [NAL9602](INFO): Powering down 2018-08-06T23:14:36.459Z,1533597276.459 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T23:14:36.460Z,1533597276.460 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:14:36.460Z,1533597276.460 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:14:36.460Z,1533597276.460 [Default:CheckIn:D] Running Loop=1 2018-08-06T23:14:36.845Z,1533597276.845 [Default:CheckIn:D] Stopped 2018-08-06T23:14:36.845Z,1533597276.845 [Default:CheckIn:E] Running Loop=1 2018-08-06T23:14:37.279Z,1533597277.279 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 340.180892 min 2018-08-06T23:14:37.279Z,1533597277.279 [Default:CheckIn:E] Stopped 2018-08-06T23:14:37.279Z,1533597277.279 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T23:14:37.279Z,1533597277.279 [Default:CheckIn] Stopped 2018-08-06T23:14:37.279Z,1533597277.279 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:14:37.280Z,1533597277.280 [Default:CheckIn](INFO): Running loop #38 2018-08-06T23:14:37.280Z,1533597277.280 [Default:CheckIn] Running Loop=38 2018-08-06T23:14:37.280Z,1533597277.280 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T23:14:37.280Z,1533597277.280 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T23:14:40.575Z,1533597280.575 [NAL9602](INFO): Powering up 2018-08-06T23:14:51.723Z,1533597291.723 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:15:39.725Z,1533597339.725 [NAL9602](INFO): SBD MO Status=0, MOMSN=23362, MT Status=0, MTMSN=0 2018-08-06T23:15:39.725Z,1533597339.725 [NAL9602](INFO): No messages in MT queue 2018-08-06T23:16:47.739Z,1533597407.739 [NAL9602](INFO): GPS fix at 20180806T231131: (36.802828, -121.788041) 2018-08-06T23:16:47.808Z,1533597407.808 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T23:16:47.808Z,1533597407.808 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T23:16:53.111Z,1533597413.111 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20180806T181422/Courier0099.lzma 2018-08-06T23:16:53.918Z,1533597413.918 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0099.lzma.bak 2018-08-06T23:16:53.918Z,1533597413.918 [DataOverHttps](INFO): SBD MOMSN=8403848 2018-08-06T23:17:04.916Z,1533597424.916 [DataOverHttps](INFO): Sending 123 bytes from file Logs/20180806T181422/Express0100.lzma 2018-08-06T23:17:05.709Z,1533597425.709 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0100.lzma.bak 2018-08-06T23:17:05.710Z,1533597425.710 [DataOverHttps](INFO): SBD MOMSN=8403851 2018-08-06T23:17:08.490Z,1533597428.490 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T23:17:08.490Z,1533597428.490 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T23:17:08.490Z,1533597428.490 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T23:17:22.823Z,1533597442.823 [NAL9602](INFO): Powering down 2018-08-06T23:22:08.914Z,1533597728.914 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T23:22:08.915Z,1533597728.915 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:22:08.915Z,1533597728.915 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:22:08.915Z,1533597728.915 [Default:CheckIn:D] Running Loop=1 2018-08-06T23:22:09.313Z,1533597729.313 [Default:CheckIn:D] Stopped 2018-08-06T23:22:09.313Z,1533597729.313 [Default:CheckIn:E] Running Loop=1 2018-08-06T23:22:09.714Z,1533597729.714 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 347.722038 min 2018-08-06T23:22:09.714Z,1533597729.714 [Default:CheckIn:E] Stopped 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn] Stopped 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn](INFO): Running loop #39 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn] Running Loop=39 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T23:22:09.715Z,1533597729.715 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T23:22:13.359Z,1533597733.359 [NAL9602](INFO): Powering up 2018-08-06T23:22:24.263Z,1533597744.263 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:24:24.117Z,1533597864.117 [NAL9602](INFO): SBD MO Status=2, MOMSN=23363, MT Status=2, MTMSN=0 2018-08-06T23:24:24.117Z,1533597864.117 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T23:27:09.857Z,1533598029.857 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T23:22:09.7Z 2018-08-06T23:27:09.857Z,1533598029.857 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T23:27:09.857Z,1533598029.857 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T23:27:15.491Z,1533598035.491 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0102.lzma 2018-08-06T23:27:16.289Z,1533598036.289 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0102.lzma.bak 2018-08-06T23:27:16.289Z,1533598036.289 [DataOverHttps](INFO): SBD MOMSN=8403861 2018-08-06T23:27:26.979Z,1533598046.979 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20180806T181422/Express0103.lzma 2018-08-06T23:27:27.773Z,1533598047.773 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0103.lzma.bak 2018-08-06T23:27:27.774Z,1533598047.774 [DataOverHttps](INFO): SBD MOMSN=8403863 2018-08-06T23:27:29.247Z,1533598049.247 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T23:27:29.247Z,1533598049.247 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T23:27:29.247Z,1533598049.247 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T23:27:43.045Z,1533598063.045 [NAL9602](INFO): SBD MO Status=2, MOMSN=23363, MT Status=2, MTMSN=0 2018-08-06T23:27:43.045Z,1533598063.045 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2018-08-06T23:27:43.431Z,1533598063.431 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T23:28:14.235Z,1533598094.235 [NAL9602](INFO): Powering down 2018-08-06T23:32:29.474Z,1533598349.474 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2018-08-06T23:32:29.474Z,1533598349.474 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:32:29.475Z,1533598349.475 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:32:29.475Z,1533598349.475 [Default:CheckIn:D] Running Loop=1 2018-08-06T23:32:29.867Z,1533598349.867 [Default:CheckIn:D] Stopped 2018-08-06T23:32:29.867Z,1533598349.867 [Default:CheckIn:E] Running Loop=1 2018-08-06T23:32:30.252Z,1533598350.252 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 358.064583 min 2018-08-06T23:32:30.253Z,1533598350.253 [Default:CheckIn:E] Stopped 2018-08-06T23:32:30.253Z,1533598350.253 [Default:CheckIn](INFO): Completed Default:CheckIn 2018-08-06T23:32:30.253Z,1533598350.253 [Default:CheckIn] Stopped 2018-08-06T23:32:30.253Z,1533598350.253 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:32:30.253Z,1533598350.253 [Default:CheckIn](INFO): Running loop #40 2018-08-06T23:32:30.254Z,1533598350.254 [Default:CheckIn] Running Loop=40 2018-08-06T23:32:30.254Z,1533598350.254 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2018-08-06T23:32:30.254Z,1533598350.254 [Default:CheckIn:Read_GPS] Running Loop=1 2018-08-06T23:32:33.999Z,1533598353.999 [NAL9602](INFO): Powering up 2018-08-06T23:32:44.895Z,1533598364.895 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:32:45.699Z,1533598365.699 [NAL9602](FAULT): GPS failed to acquire within timeout. 2018-08-06T23:32:45.699Z,1533598365.699 [NAL9602] Data Fault, FailCount= 1 2018-08-06T23:32:45.699Z,1533598365.699 [NAL9602](ERROR): Data Fault 2018-08-06T23:32:45.797Z,1533598365.797 [CBIT](ERROR): Data Fault in component: NAL9602 2018-08-06T23:32:46.099Z,1533598366.099 [NAL9602](INFO): Powering down 2018-08-06T23:32:46.969Z,1533598366.969 [CBIT](INFO): Clearing failed state for component NAL9602 2018-08-06T23:32:46.970Z,1533598366.970 [NAL9602] No Fault, FailCount= 1 2018-08-06T23:33:16.499Z,1533598396.499 [NAL9602](INFO): Powering up NAL9602 2018-08-06T23:33:27.700Z,1533598407.700 [NAL9602](INFO): NAL9602 initialized 2018-08-06T23:37:30.314Z,1533598650.314 [Default:CheckIn:Read_GPS](INFO): Timed out from 2018-08-06T23:32:30.3Z 2018-08-06T23:37:30.315Z,1533598650.315 [Default:CheckIn:Read_GPS] Stopped 2018-08-06T23:37:30.315Z,1533598650.315 [Default:CheckIn:Read_Iridium] Running Loop=1 2018-08-06T23:37:37.035Z,1533598657.035 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20180806T181422/Courier0105.lzma 2018-08-06T23:37:37.833Z,1533598657.833 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Courier0105.lzma.bak 2018-08-06T23:37:37.833Z,1533598657.833 [DataOverHttps](INFO): SBD MOMSN=8403872 2018-08-06T23:37:49.325Z,1533598669.325 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20180806T181422/Express0106.lzma 2018-08-06T23:37:50.513Z,1533598670.513 [DataOverHttps](INFO): Moved sent file to Logs/20180806T181422/Express0106.lzma.bak 2018-08-06T23:37:50.514Z,1533598670.514 [DataOverHttps](INFO): SBD MOMSN=8403874 2018-08-06T23:37:51.916Z,1533598671.916 [Default:CheckIn:Read_Iridium] Stopped 2018-08-06T23:37:51.916Z,1533598671.916 [Default:CheckIn:C.Wait] Running Loop=1 2018-08-06T23:37:51.916Z,1533598671.916 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2018-08-06T23:38:31.140Z,1533598711.140 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2018-08-06T23:39:01.655Z,1533598741.655 [NAL9602](INFO): Powering down 2018-08-06T23:39:47.287Z,1533598787.287 [BPC1](ERROR): Failed to receive data from both battery packs 2018-08-06T23:39:47.287Z,1533598787.287 [BPC1] Communications Fault, FailCount= 1 2018-08-06T23:39:47.287Z,1533598787.287 [BPC1](ERROR): Communications Fault 2018-08-06T23:39:47.335Z,1533598787.335 [CBIT](ERROR): Communications Fault in component: BPC1 2018-08-06T23:39:48.529Z,1533598788.529 [CBIT](INFO): Clearing failed state for component BPC1 2018-08-06T23:39:48.529Z,1533598788.529 [BPC1] No Fault, FailCount= 1 2018-08-06T23:41:39.467Z,1533598899.467 [BPC1](ERROR): Failed to parse message. 2018-08-06T23:41:39.468Z,1533598899.468 [BPC1](ERROR): Failed to parse Bank A battery data 2018-08-06T23:41:43.674Z,1533598903.674 [CommandLine](IMPORTANT): got command quit 2018-08-06T23:41:44.693Z,1533598904.693 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:44.693Z,1533598904.693 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.726Z,1533598904.726 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2018-08-06T23:41:44.726Z,1533598904.726 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.727Z,1533598904.727 [CommandLine](INFO): Join timeout helper Thread ID is 729 2018-08-06T23:41:44.746Z,1533598904.746 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2018-08-06T23:41:44.746Z,1533598904.746 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.747Z,1533598904.747 [NavChartDb](INFO): Join timeout helper Thread ID is 730 2018-08-06T23:41:44.806Z,1533598904.806 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:44.806Z,1533598904.806 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.822Z,1533598904.822 [ComponentRegistry](INFO): Shutting down WetLabsSeaOWL_UV_A ThreadHandler 2018-08-06T23:41:44.822Z,1533598904.822 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.822Z,1533598904.822 [WetLabsSeaOWL_UV_A](INFO): Join timeout helper Thread ID is 731 2018-08-06T23:41:44.894Z,1533598904.894 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:44.894Z,1533598904.894 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.898Z,1533598904.898 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2018-08-06T23:41:44.898Z,1533598904.898 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:44.898Z,1533598904.898 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 732 2018-08-06T23:41:45.102Z,1533598905.102 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:45.102Z,1533598905.102 [WetLabsBB2FL](INFO): Powering down 2018-08-06T23:41:45.103Z,1533598905.103 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.114Z,1533598905.114 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2018-08-06T23:41:45.114Z,1533598905.114 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.114Z,1533598905.114 [CTD_Seabird](INFO): Join timeout helper Thread ID is 733 2018-08-06T23:41:45.502Z,1533598905.502 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:45.777Z,1533598905.777 [CTD_Seabird](INFO): Stopping potential previous instance(s) of CTD_Seabird LCM interface 2018-08-06T23:41:45.777Z,1533598905.777 [CTD_Seabird](INFO): Powering down 2018-08-06T23:41:45.778Z,1533598905.778 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.801Z,1533598905.801 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2018-08-06T23:41:45.802Z,1533598905.802 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.802Z,1533598905.802 [Radio_Surface](INFO): Join timeout helper Thread ID is 735 2018-08-06T23:41:45.945Z,1533598905.945 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:45.945Z,1533598905.945 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.947Z,1533598905.947 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2018-08-06T23:41:45.947Z,1533598905.947 [logger ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.947Z,1533598905.947 [logger](INFO): Join timeout helper Thread ID is 737 2018-08-06T23:41:45.949Z,1533598905.949 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:45.950Z,1533598905.950 [logger ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.962Z,1533598905.962 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2018-08-06T23:41:45.962Z,1533598905.962 [CommandLine ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.962Z,1533598905.962 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2018-08-06T23:41:45.962Z,1533598905.962 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:45.963Z,1533598905.963 [controlThread](INFO): Join timeout helper Thread ID is 738 2018-08-06T23:41:45.971Z,1533598905.971 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2018-08-06T23:41:45.972Z,1533598905.972 [controlThread](DEBUG): Uninitializing ControlThread 2018-08-06T23:41:45.972Z,1533598905.972 [AcousticModem_Benthos_ATM900](INFO): Powering down 2018-08-06T23:41:46.091Z,1533598906.091 [NAL9602](INFO): Powering down 2018-08-06T23:41:46.092Z,1533598906.092 [PNI_TCM](INFO): Powering down 2018-08-06T23:41:46.179Z,1533598906.179 [Aanderaa_O2](INFO): Powering down 2018-08-06T23:41:46.182Z,1533598906.182 [DepthRateCalculator](DEBUG): Initializing DepthRateCalculator. 2018-08-06T23:41:46.183Z,1533598906.183 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2018-08-06T23:41:46.184Z,1533598906.184 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2018-08-06T23:41:46.184Z,1533598906.184 [MissionManager](INFO): Uninitializing Mission Default 2018-08-06T23:41:46.185Z,1533598906.185 [Default] Stopped 2018-08-06T23:41:46.185Z,1533598906.185 [Default](DEBUG): Aggregate::uninitialize Default 2018-08-06T23:41:46.185Z,1533598906.185 [Default:B.GoToSurface] Stopped 2018-08-06T23:41:46.185Z,1533598906.185 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2018-08-06T23:41:46.185Z,1533598906.185 [Default:CheckIn] Stopped 2018-08-06T23:41:46.185Z,1533598906.185 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2018-08-06T23:41:46.185Z,1533598906.185 [Default:CheckIn:C.Wait] Stopped 2018-08-06T23:41:46.186Z,1533598906.186 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2018-08-06T23:41:46.190Z,1533598906.190 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2018-08-06T23:41:46.190Z,1533598906.190 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2018-08-06T23:41:46.190Z,1533598906.190 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2018-08-06T23:41:46.191Z,1533598906.191 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2018-08-06T23:41:46.191Z,1533598906.191 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2018-08-06T23:41:46.191Z,1533598906.191 [BuoyancyServo](INFO): Powering down 2018-08-06T23:41:46.206Z,1533598906.206 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2018-08-06T23:41:46.206Z,1533598906.206 [ElevatorServo](INFO): Powering down 2018-08-06T23:41:46.207Z,1533598906.207 [MassServo](DEBUG): Uninitialize Mass Servo. 2018-08-06T23:41:46.207Z,1533598906.207 [MassServo](INFO): Powering down 2018-08-06T23:41:46.208Z,1533598906.208 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2018-08-06T23:41:46.209Z,1533598906.209 [RudderServo](INFO): Powering down 2018-08-06T23:41:46.210Z,1533598906.210 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2018-08-06T23:41:46.210Z,1533598906.210 [ThrusterServo](INFO): Powering down 2018-08-06T23:41:46.211Z,1533598906.211 [SBIT](DEBUG): Uninitialize SBIT Component. 2018-08-06T23:41:46.211Z,1533598906.211 [IBIT](DEBUG): Uninitialize IBIT Component. 2018-08-06T23:41:46.212Z,1533598906.212 [CBIT](DEBUG): Uninitialize CBIT Component. 2018-08-06T23:41:46.213Z,1533598906.213 [controlThread ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.420Z,1533598906.420 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.525Z,1533598906.525 [WetLabsSeaOWL_UV_A ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.531Z,1533598906.531 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.615Z,1533598906.615 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.714Z,1533598906.714 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2018-08-06T23:41:46.946Z,1533598906.946 [logger ThreadHandler](INFO): Thread cancelled.