2021-06-08T16:25:36.695Z,1623169536.695 [CommandLine](IMPORTANT): got command restart logs 2021-06-08T16:26:15.236Z,1623169575.236 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:26:15.236Z,1623169575.236 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:26:15.236Z,1623169575.236 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:26:15.236Z,1623169575.236 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:26:15.550Z,1623169575.550 [Default:CheckIn:D] Stopped 2021-06-08T16:26:15.550Z,1623169575.550 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:26:15.950Z,1623169575.950 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 18.586399 min 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn:E] Stopped 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn] Stopped 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn](INFO): Running loop #4 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn] Running Loop=4 2021-06-08T16:26:15.951Z,1623169575.951 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:26:15.952Z,1623169575.952 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:26:17.962Z,1623169577.962 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,162617.00,A,3648.80017,N,12149.36969,W,1.263,57.37,080621,,,A*4F 2021-06-08T16:26:17.972Z,1623169577.972 [NAL9602](INFO): GPS fix at 20210608T162617: (36.813336, -121.822828) 2021-06-08T16:26:17.983Z,1623169577.983 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:26:17.983Z,1623169577.983 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:26:25.998Z,1623169585.998 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210607T214921/Courier0238.lzma 2021-06-08T16:26:27.001Z,1623169587.001 [DataOverHttps](INFO): Moved sent file to Logs/20210607T214921/Courier0238.lzma.bak 2021-06-08T16:26:27.001Z,1623169587.001 [DataOverHttps](INFO): SBD MOMSN=15703451 2021-06-08T16:26:39.016Z,1623169599.016 [NAL9602](INFO): SBD MO Status=2, MOMSN=4858, MT Status=2, MTMSN=0 2021-06-08T16:26:39.016Z,1623169599.016 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:26:53.189Z,1623169613.189 [NAL9602](INFO): SBD MO Status=2, MOMSN=4858, MT Status=2, MTMSN=0 2021-06-08T16:26:53.189Z,1623169613.189 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:27:19.019Z,1623169639.019 [BPC1](INFO): Calculating totals. Valid battery stick count: 49. Valid reserve battery stick count: 5. 2021-06-08T16:27:19.022Z,1623169639.022 [BPC1](INFO): Received data from all battery sticks. 2021-06-08T16:27:19.026Z,1623169639.026 [NAL9602](INFO): SBD MO Status=2, MOMSN=4858, MT Status=2, MTMSN=0 2021-06-08T16:27:19.026Z,1623169639.026 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:27:34.769Z,1623169654.769 [NAL9602](INFO): SBD MO Status=2, MOMSN=4858, MT Status=2, MTMSN=0 2021-06-08T16:27:34.769Z,1623169654.769 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:27:56.575Z,1623169676.575 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.607346 2021-06-08T16:28:27.723Z,1623169707.723 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2021-06-08T16:28:29.719Z,1623169709.719 [NAL9602](INFO): SBD MO Status=0, MOMSN=4858, MT Status=0, MTMSN=0 2021-06-08T16:28:29.719Z,1623169709.719 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:28:55.241Z,1623169735.241 [NAL9602](INFO): SBD MO Status=2, MOMSN=4859, MT Status=2, MTMSN=0 2021-06-08T16:28:55.241Z,1623169735.241 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:29:02.875Z,1623169742.875 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2021-06-08T16:29:14.726Z,1623169754.726 [NAL9602](INFO): SBD MO Status=1, MOMSN=4859, MT Status=0, MTMSN=0 2021-06-08T16:29:14.779Z,1623169754.779 [NAL9602](INFO): Sent 268 bytes from file Logs/20210608T162536/Courier0000.lzma 2021-06-08T16:29:14.779Z,1623169754.779 [NAL9602](INFO): Packets left to send: 0 2021-06-08T16:29:30.077Z,1623169770.077 [NAL9602](INFO): SBD MO Status=2, MOMSN=4860, MT Status=2, MTMSN=0 2021-06-08T16:29:30.078Z,1623169770.078 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:29:35.823Z,1623169775.823 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003231 2021-06-08T16:29:43.125Z,1623169783.125 [DataOverHttps](INFO): Sending 1691 bytes from file Logs/20210607T214921/Express0239.lzma 2021-06-08T16:29:44.125Z,1623169784.125 [DataOverHttps](INFO): Moved sent file to Logs/20210607T214921/Express0239.lzma.bak 2021-06-08T16:29:44.125Z,1623169784.125 [DataOverHttps](INFO): SBD MOMSN=15703455 2021-06-08T16:29:57.113Z,1623169797.113 [NAL9602](INFO): SBD MO Status=2, MOMSN=4860, MT Status=2, MTMSN=0 2021-06-08T16:29:57.113Z,1623169797.113 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:30:27.817Z,1623169827.817 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T16:30:34.151Z,1623169834.151 [DataOverHttps](INFO): Sending 589 bytes from file Logs/20210608T162536/Express0001.lzma 2021-06-08T16:30:35.156Z,1623169835.156 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0001.lzma.bak 2021-06-08T16:30:35.157Z,1623169835.157 [DataOverHttps](INFO): SBD MOMSN=15703458 2021-06-08T16:30:55.182Z,1623169855.182 [DataOverHttps](INFO): Sending 70 bytes from file Logs/20210608T162536/Express0004.lzma 2021-06-08T16:30:56.184Z,1623169856.184 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0004.lzma.bak 2021-06-08T16:30:56.185Z,1623169856.185 [DataOverHttps](INFO): SBD MOMSN=15703464 2021-06-08T16:30:58.240Z,1623169858.240 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:30:58.240Z,1623169858.240 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:30:58.240Z,1623169858.240 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:35:58.766Z,1623170158.766 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:35:58.766Z,1623170158.766 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:35:58.766Z,1623170158.766 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:35:58.766Z,1623170158.766 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:35:59.178Z,1623170159.178 [Default:CheckIn:D] Stopped 2021-06-08T16:35:59.178Z,1623170159.178 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 28.313536 min 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn:E] Stopped 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn] Stopped 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:35:59.587Z,1623170159.587 [Default:CheckIn](INFO): Running loop #5 2021-06-08T16:35:59.588Z,1623170159.588 [Default:CheckIn] Running Loop=5 2021-06-08T16:35:59.588Z,1623170159.588 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:35:59.588Z,1623170159.588 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:36:01.589Z,1623170161.589 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163600.00,A,3648.33434,N,12147.11837,W,2.352,177.11,080621,,,A*73 2021-06-08T16:36:01.592Z,1623170161.592 [NAL9602](INFO): GPS fix at 20210608T163600: (36.805572, -121.785306) 2021-06-08T16:36:01.619Z,1623170161.619 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:36:01.619Z,1623170161.619 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:36:09.234Z,1623170169.234 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20210608T162536/Courier0006.lzma 2021-06-08T16:36:10.237Z,1623170170.237 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0006.lzma.bak 2021-06-08T16:36:10.237Z,1623170170.237 [DataOverHttps](INFO): SBD MOMSN=15703475 2021-06-08T16:36:26.217Z,1623170186.217 [DataOverHttps](INFO): Sending 595 bytes from file Logs/20210608T162536/Express0007.lzma 2021-06-08T16:36:26.247Z,1623170186.247 [NAL9602](INFO): SBD MO Status=1, MOMSN=4860, MT Status=0, MTMSN=0 2021-06-08T16:36:26.247Z,1623170186.247 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:36:27.212Z,1623170187.212 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0007.lzma.bak 2021-06-08T16:36:27.213Z,1623170187.213 [DataOverHttps](INFO): SBD MOMSN=15703478 2021-06-08T16:36:29.069Z,1623170189.069 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:36:29.069Z,1623170189.069 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:36:29.069Z,1623170189.069 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:36:56.960Z,1623170216.960 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T16:41:29.667Z,1623170489.667 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:41:29.667Z,1623170489.667 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:41:29.667Z,1623170489.667 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:41:29.667Z,1623170489.667 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:41:30.079Z,1623170490.079 [Default:CheckIn:D] Stopped 2021-06-08T16:41:30.079Z,1623170490.079 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:41:30.491Z,1623170490.491 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 33.828546 min 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn:E] Stopped 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn] Stopped 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn](INFO): Running loop #6 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn] Running Loop=6 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:41:30.492Z,1623170490.492 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:41:32.493Z,1623170492.493 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164131.00,A,3648.16591,N,12147.21383,W,0.544,215.07,080621,,,A*7C 2021-06-08T16:41:32.496Z,1623170492.496 [NAL9602](INFO): GPS fix at 20210608T164131: (36.802765, -121.786897) 2021-06-08T16:41:32.527Z,1623170492.527 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:41:32.527Z,1623170492.527 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:41:40.238Z,1623170500.238 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0009.lzma 2021-06-08T16:41:41.241Z,1623170501.241 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0009.lzma.bak 2021-06-08T16:41:41.241Z,1623170501.241 [DataOverHttps](INFO): SBD MOMSN=15703493 2021-06-08T16:41:41.379Z,1623170501.379 [NAL9602](INFO): SBD MO Status=1, MOMSN=4861, MT Status=0, MTMSN=0 2021-06-08T16:41:41.379Z,1623170501.379 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:41:57.567Z,1623170517.567 [DataOverHttps](INFO): Sending 180 bytes from file Logs/20210608T162536/Express0010.lzma 2021-06-08T16:41:58.568Z,1623170518.568 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0010.lzma.bak 2021-06-08T16:41:58.569Z,1623170518.569 [DataOverHttps](INFO): SBD MOMSN=15703496 2021-06-08T16:42:00.384Z,1623170520.384 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:42:00.384Z,1623170520.384 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:42:00.384Z,1623170520.384 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:42:12.083Z,1623170532.083 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T16:44:46.427Z,1623170686.427 [BPC1](INFO): Calculating totals. Valid battery stick count: 50. Valid reserve battery stick count: 5. 2021-06-08T16:44:46.430Z,1623170686.430 [BPC1](INFO): Received data from all battery sticks. 2021-06-08T16:47:00.977Z,1623170820.977 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:47:00.978Z,1623170820.978 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:47:00.978Z,1623170820.978 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:47:00.978Z,1623170820.978 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:47:01.392Z,1623170821.392 [Default:CheckIn:D] Stopped 2021-06-08T16:47:01.392Z,1623170821.392 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:47:01.785Z,1623170821.785 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 39.350435 min 2021-06-08T16:47:01.785Z,1623170821.785 [Default:CheckIn:E] Stopped 2021-06-08T16:47:01.785Z,1623170821.785 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:47:01.785Z,1623170821.785 [Default:CheckIn] Stopped 2021-06-08T16:47:01.785Z,1623170821.785 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:47:01.786Z,1623170821.786 [Default:CheckIn](INFO): Running loop #7 2021-06-08T16:47:01.786Z,1623170821.786 [Default:CheckIn] Running Loop=7 2021-06-08T16:47:01.786Z,1623170821.786 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:47:01.786Z,1623170821.786 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:47:03.798Z,1623170823.798 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164703.00,A,3648.16581,N,12147.21816,W,0.175,269.27,080621,,,D*77 2021-06-08T16:47:03.801Z,1623170823.801 [NAL9602](INFO): GPS fix at 20210608T164703: (36.802763, -121.786969) 2021-06-08T16:47:03.811Z,1623170823.811 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:47:03.811Z,1623170823.811 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:47:10.758Z,1623170830.758 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20210608T162536/Courier0012.lzma 2021-06-08T16:47:11.756Z,1623170831.756 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0012.lzma.bak 2021-06-08T16:47:11.757Z,1623170831.757 [DataOverHttps](INFO): SBD MOMSN=15703517 2021-06-08T16:47:27.595Z,1623170847.595 [DataOverHttps](INFO): Sending 242 bytes from file Logs/20210608T162536/Express0013.lzma 2021-06-08T16:47:28.596Z,1623170848.596 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0013.lzma.bak 2021-06-08T16:47:28.597Z,1623170848.597 [DataOverHttps](INFO): SBD MOMSN=15703520 2021-06-08T16:47:30.519Z,1623170850.519 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:47:30.519Z,1623170850.519 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:47:30.519Z,1623170850.519 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:47:37.367Z,1623170857.367 [NAL9602](INFO): SBD MO Status=2, MOMSN=4862, MT Status=2, MTMSN=0 2021-06-08T16:47:37.367Z,1623170857.367 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:47:57.165Z,1623170877.165 [NAL9602](INFO): SBD MO Status=2, MOMSN=4862, MT Status=2, MTMSN=0 2021-06-08T16:47:57.165Z,1623170877.165 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:48:12.917Z,1623170892.917 [NAL9602](INFO): SBD MO Status=2, MOMSN=4862, MT Status=2, MTMSN=0 2021-06-08T16:48:12.917Z,1623170892.917 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T16:48:32.713Z,1623170912.713 [NAL9602](INFO): SBD MO Status=1, MOMSN=4862, MT Status=0, MTMSN=0 2021-06-08T16:48:32.713Z,1623170912.713 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:49:03.419Z,1623170943.419 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T16:52:31.101Z,1623171151.101 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:52:31.101Z,1623171151.101 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:52:31.101Z,1623171151.101 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:52:31.102Z,1623171151.102 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:52:31.501Z,1623171151.501 [Default:CheckIn:D] Stopped 2021-06-08T16:52:31.501Z,1623171151.501 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:52:31.908Z,1623171151.908 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 44.852258 min 2021-06-08T16:52:31.908Z,1623171151.908 [Default:CheckIn:E] Stopped 2021-06-08T16:52:31.908Z,1623171151.908 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn] Stopped 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn](INFO): Running loop #8 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn] Running Loop=8 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:52:31.909Z,1623171151.909 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:52:33.923Z,1623171153.923 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165233.00,A,3648.15886,N,12147.22052,W,1.536,217.77,080621,,,D*7C 2021-06-08T16:52:33.925Z,1623171153.925 [NAL9602](INFO): GPS fix at 20210608T165233: (36.802648, -121.787009) 2021-06-08T16:52:33.941Z,1623171153.941 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:52:33.941Z,1623171153.941 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:52:45.006Z,1623171165.006 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0015.lzma 2021-06-08T16:52:46.008Z,1623171166.008 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0015.lzma.bak 2021-06-08T16:52:46.009Z,1623171166.009 [DataOverHttps](INFO): SBD MOMSN=15703532 2021-06-08T16:53:01.751Z,1623171181.751 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20210608T162536/Express0016.lzma 2021-06-08T16:53:02.753Z,1623171182.753 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0016.lzma.bak 2021-06-08T16:53:02.753Z,1623171182.753 [DataOverHttps](INFO): SBD MOMSN=15703535 2021-06-08T16:53:04.676Z,1623171184.676 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:53:04.676Z,1623171184.676 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:53:04.676Z,1623171184.676 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:53:05.462Z,1623171185.462 [NAL9602](INFO): SBD MO Status=1, MOMSN=4863, MT Status=0, MTMSN=0 2021-06-08T16:53:05.462Z,1623171185.462 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:53:36.163Z,1623171216.163 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T16:58:05.245Z,1623171485.245 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T16:58:05.245Z,1623171485.245 [Default:CheckIn:C.Wait] Stopped 2021-06-08T16:58:05.245Z,1623171485.245 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T16:58:05.245Z,1623171485.245 [Default:CheckIn:D] Running Loop=1 2021-06-08T16:58:05.654Z,1623171485.654 [Default:CheckIn:D] Stopped 2021-06-08T16:58:05.654Z,1623171485.654 [Default:CheckIn:E] Running Loop=1 2021-06-08T16:58:06.050Z,1623171486.050 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 50.421476 min 2021-06-08T16:58:06.050Z,1623171486.050 [Default:CheckIn:E] Stopped 2021-06-08T16:58:06.050Z,1623171486.050 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T16:58:06.050Z,1623171486.050 [Default:CheckIn] Stopped 2021-06-08T16:58:06.050Z,1623171486.050 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T16:58:06.051Z,1623171486.051 [Default:CheckIn](INFO): Running loop #9 2021-06-08T16:58:06.051Z,1623171486.051 [Default:CheckIn] Running Loop=9 2021-06-08T16:58:06.051Z,1623171486.051 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T16:58:06.051Z,1623171486.051 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T16:58:08.070Z,1623171488.070 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165807.00,A,3648.16921,N,12147.27123,W,0.369,301.28,080621,,,A*78 2021-06-08T16:58:08.073Z,1623171488.073 [NAL9602](INFO): GPS fix at 20210608T165807: (36.802820, -121.787854) 2021-06-08T16:58:08.083Z,1623171488.083 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T16:58:08.084Z,1623171488.084 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T16:58:15.145Z,1623171495.145 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0018.lzma 2021-06-08T16:58:15.944Z,1623171495.944 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0018.lzma.bak 2021-06-08T16:58:15.945Z,1623171495.945 [DataOverHttps](INFO): SBD MOMSN=15703546 2021-06-08T16:58:22.673Z,1623171502.673 [NAL9602](INFO): SBD MO Status=1, MOMSN=4864, MT Status=0, MTMSN=0 2021-06-08T16:58:22.673Z,1623171502.673 [NAL9602](INFO): No messages in MT queue 2021-06-08T16:58:31.679Z,1623171511.679 [DataOverHttps](INFO): Sending 293 bytes from file Logs/20210608T162536/Express0019.lzma 2021-06-08T16:58:32.681Z,1623171512.681 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0019.lzma.bak 2021-06-08T16:58:32.681Z,1623171512.681 [DataOverHttps](INFO): SBD MOMSN=15703549 2021-06-08T16:58:35.280Z,1623171515.280 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T16:58:35.281Z,1623171515.281 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T16:58:35.281Z,1623171515.281 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T16:58:53.439Z,1623171533.439 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T17:02:09.833Z,1623171729.833 [BPC1](INFO): Calculating totals. Valid battery stick count: 50. Valid reserve battery stick count: 5. 2021-06-08T17:02:09.836Z,1623171729.836 [BPC1](INFO): Received data from all battery sticks. 2021-06-08T17:03:35.893Z,1623171815.893 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:03:35.893Z,1623171815.893 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:03:35.893Z,1623171815.893 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:03:35.893Z,1623171815.893 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:03:36.300Z,1623171816.300 [Default:CheckIn:D] Stopped 2021-06-08T17:03:36.300Z,1623171816.300 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:03:36.711Z,1623171816.711 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 55.932235 min 2021-06-08T17:03:36.711Z,1623171816.711 [Default:CheckIn:E] Stopped 2021-06-08T17:03:36.711Z,1623171816.711 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:03:36.711Z,1623171816.711 [Default:CheckIn] Stopped 2021-06-08T17:03:36.712Z,1623171816.712 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:03:36.712Z,1623171816.712 [Default:CheckIn](INFO): Running loop #10 2021-06-08T17:03:36.712Z,1623171816.712 [Default:CheckIn] Running Loop=10 2021-06-08T17:03:36.712Z,1623171816.712 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:03:36.712Z,1623171816.712 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:03:38.717Z,1623171818.717 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170337.00,A,3648.16570,N,12147.28233,W,0.233,301.28,080621,,,A*7F 2021-06-08T17:03:38.720Z,1623171818.720 [NAL9602](INFO): GPS fix at 20210608T170337: (36.802762, -121.788039) 2021-06-08T17:03:38.751Z,1623171818.751 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:03:38.752Z,1623171818.752 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:03:46.302Z,1623171826.302 [DataOverHttps](INFO): Sending 85 bytes from file Logs/20210608T162536/Courier0021.lzma 2021-06-08T17:03:47.304Z,1623171827.304 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0021.lzma.bak 2021-06-08T17:03:47.305Z,1623171827.305 [DataOverHttps](INFO): SBD MOMSN=15703561 2021-06-08T17:04:03.019Z,1623171843.019 [DataOverHttps](INFO): Sending 427 bytes from file Logs/20210608T162536/Express0022.lzma 2021-06-08T17:04:04.021Z,1623171844.021 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0022.lzma.bak 2021-06-08T17:04:04.021Z,1623171844.021 [DataOverHttps](INFO): SBD MOMSN=15703564 2021-06-08T17:04:05.792Z,1623171845.792 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:04:05.792Z,1623171845.792 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:04:05.792Z,1623171845.792 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:07:10.437Z,1623172030.437 [NAL9602](INFO): SBD MO Status=2, MOMSN=4865, MT Status=2, MTMSN=0 2021-06-08T17:07:10.437Z,1623172030.437 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T17:07:32.250Z,1623172052.250 [NAL9602](INFO): SBD MO Status=2, MOMSN=4865, MT Status=2, MTMSN=0 2021-06-08T17:07:32.250Z,1623172052.250 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T17:07:49.621Z,1623172069.621 [NAL9602](INFO): SBD MO Status=2, MOMSN=4865, MT Status=2, MTMSN=0 2021-06-08T17:07:49.621Z,1623172069.621 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-06-08T17:08:41.332Z,1623172121.332 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-06-08T17:09:06.397Z,1623172146.397 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:09:06.397Z,1623172146.397 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:09:06.397Z,1623172146.397 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:09:06.398Z,1623172146.398 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:09:06.805Z,1623172146.805 [Default:CheckIn:D] Stopped 2021-06-08T17:09:06.805Z,1623172146.805 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:09:07.198Z,1623172147.198 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 61.440653 min 2021-06-08T17:09:07.198Z,1623172147.198 [Default:CheckIn:E] Stopped 2021-06-08T17:09:07.198Z,1623172147.198 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:09:07.198Z,1623172147.198 [Default:CheckIn] Stopped 2021-06-08T17:09:07.198Z,1623172147.198 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:09:07.199Z,1623172147.199 [Default:CheckIn](INFO): Running loop #11 2021-06-08T17:09:07.199Z,1623172147.199 [Default:CheckIn] Running Loop=11 2021-06-08T17:09:07.199Z,1623172147.199 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:09:07.199Z,1623172147.199 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:09:09.213Z,1623172149.213 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170908.00,A,3648.16454,N,12147.27891,W,0.700,301.28,080621,,,A*76 2021-06-08T17:09:09.216Z,1623172149.216 [NAL9602](INFO): GPS fix at 20210608T170908: (36.802742, -121.787982) 2021-06-08T17:09:09.226Z,1623172149.226 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:09:09.226Z,1623172149.226 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:09:16.418Z,1623172156.418 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210608T162536/Courier0024.lzma 2021-06-08T17:09:17.421Z,1623172157.421 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0024.lzma.bak 2021-06-08T17:09:17.421Z,1623172157.421 [DataOverHttps](INFO): SBD MOMSN=15703575 2021-06-08T17:09:33.095Z,1623172173.095 [DataOverHttps](INFO): Sending 260 bytes from file Logs/20210608T162536/Express0025.lzma 2021-06-08T17:09:34.096Z,1623172174.096 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0025.lzma.bak 2021-06-08T17:09:34.097Z,1623172174.097 [DataOverHttps](INFO): SBD MOMSN=15703579 2021-06-08T17:09:35.891Z,1623172175.891 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:09:35.892Z,1623172175.892 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:09:35.892Z,1623172175.892 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:09:41.532Z,1623172181.532 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T17:14:36.542Z,1623172476.542 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:14:36.542Z,1623172476.542 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:14:36.542Z,1623172476.542 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:14:36.542Z,1623172476.542 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:14:36.959Z,1623172476.959 [Default:CheckIn:D] Stopped 2021-06-08T17:14:36.959Z,1623172476.959 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:14:37.345Z,1623172477.345 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 66.943229 min 2021-06-08T17:14:37.345Z,1623172477.345 [Default:CheckIn:E] Stopped 2021-06-08T17:14:37.345Z,1623172477.345 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:14:37.345Z,1623172477.345 [Default:CheckIn] Stopped 2021-06-08T17:14:37.345Z,1623172477.345 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:14:37.346Z,1623172477.346 [Default:CheckIn](INFO): Running loop #12 2021-06-08T17:14:37.346Z,1623172477.346 [Default:CheckIn] Running Loop=12 2021-06-08T17:14:37.346Z,1623172477.346 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:14:37.346Z,1623172477.346 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:14:39.458Z,1623172479.458 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171438.00,A,3648.16492,N,12147.28445,W,0.680,0.00,080621,,,A*78 2021-06-08T17:14:39.461Z,1623172479.461 [NAL9602](INFO): GPS fix at 20210608T171438: (36.802749, -121.788074) 2021-06-08T17:14:39.480Z,1623172479.480 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:14:39.480Z,1623172479.480 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:14:46.926Z,1623172486.926 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0027.lzma 2021-06-08T17:14:47.928Z,1623172487.928 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0027.lzma.bak 2021-06-08T17:14:47.929Z,1623172487.929 [DataOverHttps](INFO): SBD MOMSN=15703590 2021-06-08T17:15:03.815Z,1623172503.815 [DataOverHttps](INFO): Sending 477 bytes from file Logs/20210608T162536/Express0028.lzma 2021-06-08T17:15:04.817Z,1623172504.817 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0028.lzma.bak 2021-06-08T17:15:04.817Z,1623172504.817 [DataOverHttps](INFO): SBD MOMSN=15703593 2021-06-08T17:15:06.628Z,1623172506.628 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:15:06.628Z,1623172506.628 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:15:06.628Z,1623172506.628 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:15:09.852Z,1623172509.852 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-06-08T17:15:09.935Z,1623172509.935 [NAL9602](ERROR): received: +CSQ:0 OK65, 2, 0, 0, 0 OK 2021-06-08T17:19:36.904Z,1623172776.904 [BPC1](INFO): Calculating totals. Valid battery stick count: 50. Valid reserve battery stick count: 5. 2021-06-08T17:19:36.919Z,1623172776.919 [BPC1](INFO): Received data from all battery sticks. 2021-06-08T17:19:41.329Z,1623172781.329 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-06-08T17:20:07.208Z,1623172807.208 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:20:07.209Z,1623172807.209 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:20:07.209Z,1623172807.209 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:20:07.209Z,1623172807.209 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:20:07.601Z,1623172807.601 [Default:CheckIn:D] Stopped 2021-06-08T17:20:07.602Z,1623172807.602 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:20:08.006Z,1623172808.006 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 72.453931 min 2021-06-08T17:20:08.006Z,1623172808.006 [Default:CheckIn:E] Stopped 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn] Stopped 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn](INFO): Running loop #13 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn] Running Loop=13 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:20:08.007Z,1623172808.007 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:20:10.022Z,1623172810.022 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172009.00,A,3648.18526,N,12147.28201,W,1.963,4.63,080621,,,A*79 2021-06-08T17:20:10.024Z,1623172810.024 [NAL9602](INFO): GPS fix at 20210608T172009: (36.803088, -121.788033) 2021-06-08T17:20:10.035Z,1623172810.035 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:20:10.035Z,1623172810.035 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:20:16.900Z,1623172816.900 [DataOverHttps](INFO): Sending 83 bytes from file Logs/20210608T162536/Courier0030.lzma 2021-06-08T17:20:17.900Z,1623172817.900 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0030.lzma.bak 2021-06-08T17:20:17.901Z,1623172817.901 [DataOverHttps](INFO): SBD MOMSN=15703603 2021-06-08T17:20:33.579Z,1623172833.579 [DataOverHttps](INFO): Sending 237 bytes from file Logs/20210608T162536/Express0031.lzma 2021-06-08T17:20:34.581Z,1623172834.581 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0031.lzma.bak 2021-06-08T17:20:34.581Z,1623172834.581 [DataOverHttps](INFO): SBD MOMSN=15703606 2021-06-08T17:20:36.701Z,1623172836.701 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:20:36.701Z,1623172836.701 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:20:36.701Z,1623172836.701 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:20:42.335Z,1623172842.335 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T17:25:37.316Z,1623173137.316 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:25:37.316Z,1623173137.316 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:25:37.317Z,1623173137.317 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:25:37.317Z,1623173137.317 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:25:37.729Z,1623173137.729 [Default:CheckIn:D] Stopped 2021-06-08T17:25:37.729Z,1623173137.729 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 77.956055 min 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn:E] Stopped 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn] Stopped 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:25:38.110Z,1623173138.110 [Default:CheckIn](INFO): Running loop #14 2021-06-08T17:25:38.135Z,1623173138.135 [Default:CheckIn] Running Loop=14 2021-06-08T17:25:38.135Z,1623173138.135 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:25:38.135Z,1623173138.135 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:25:40.122Z,1623173140.122 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172539.00,A,3648.17871,N,12147.27993,W,1.944,68.31,080621,,,A*48 2021-06-08T17:25:40.129Z,1623173140.129 [NAL9602](INFO): GPS fix at 20210608T172539: (36.802979, -121.787999) 2021-06-08T17:25:40.176Z,1623173140.176 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:25:40.176Z,1623173140.176 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:25:52.755Z,1623173152.755 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0033.lzma 2021-06-08T17:25:53.757Z,1623173153.757 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0033.lzma.bak 2021-06-08T17:25:53.757Z,1623173153.757 [DataOverHttps](INFO): SBD MOMSN=15703617 2021-06-08T17:26:10.624Z,1623173170.624 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-06-08T17:26:10.707Z,1623173170.707 [NAL9602](ERROR): received: +CSQ:0 OK65, 2, 0, 0, 0 OK 2021-06-08T17:26:20.254Z,1623173180.254 [DataOverHttps](INFO): Sending 140 bytes from file Logs/20210608T162536/Express0034.lzma 2021-06-08T17:26:21.257Z,1623173181.257 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0034.lzma.bak 2021-06-08T17:26:21.257Z,1623173181.257 [DataOverHttps](INFO): SBD MOMSN=15703620 2021-06-08T17:26:23.983Z,1623173183.983 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:26:23.984Z,1623173183.984 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:26:23.984Z,1623173183.984 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:30:42.518Z,1623173442.518 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-06-08T17:31:13.239Z,1623173473.239 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T17:31:24.558Z,1623173484.558 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:31:24.558Z,1623173484.558 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:31:24.558Z,1623173484.558 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:31:24.563Z,1623173484.563 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:31:25.123Z,1623173485.123 [Default:CheckIn:D] Stopped 2021-06-08T17:31:25.123Z,1623173485.123 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 83.745955 min 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn:E] Stopped 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn] Stopped 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn](INFO): Running loop #15 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn] Running Loop=15 2021-06-08T17:31:25.413Z,1623173485.413 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:31:25.414Z,1623173485.414 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:31:27.377Z,1623173487.377 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173126.00,A,3648.17207,N,12147.28873,W,0.797,24.14,080621,,,A*46 2021-06-08T17:31:27.380Z,1623173487.380 [NAL9602](INFO): GPS fix at 20210608T173126: (36.802868, -121.788145) 2021-06-08T17:31:27.456Z,1623173487.456 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:31:27.456Z,1623173487.456 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:31:28.906Z,1623173488.906 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0036.lzma 2021-06-08T17:31:29.445Z,1623173489.445 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0036.lzma.bak 2021-06-08T17:31:29.445Z,1623173489.445 [DataOverHttps](INFO): SBD MOMSN=15703630 2021-06-08T17:31:45.162Z,1623173505.162 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20210608T162536/Express0037.lzma 2021-06-08T17:31:46.165Z,1623173506.165 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0037.lzma.bak 2021-06-08T17:31:46.165Z,1623173506.165 [DataOverHttps](INFO): SBD MOMSN=15703633 2021-06-08T17:31:48.055Z,1623173508.055 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:31:48.055Z,1623173508.055 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:31:48.055Z,1623173508.055 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:31:58.121Z,1623173518.121 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-06-08T17:31:58.195Z,1623173518.195 [NAL9602](ERROR): received: +CSQ:0 OK65, 2, 0, 0, 0 OK 2021-06-08T17:36:29.208Z,1623173789.208 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-06-08T17:36:48.619Z,1623173808.619 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-06-08T17:36:48.619Z,1623173808.619 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:36:48.619Z,1623173808.619 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:36:48.619Z,1623173808.619 [Default:CheckIn:D] Running Loop=1 2021-06-08T17:36:49.018Z,1623173809.018 [Default:CheckIn:D] Stopped 2021-06-08T17:36:49.018Z,1623173809.018 [Default:CheckIn:E] Running Loop=1 2021-06-08T17:36:49.414Z,1623173809.414 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 89.144206 min 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn:E] Stopped 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn] Stopped 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn](INFO): Running loop #16 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn] Running Loop=16 2021-06-08T17:36:49.415Z,1623173809.415 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-06-08T17:36:49.416Z,1623173809.416 [Default:CheckIn:Read_GPS] Running Loop=1 2021-06-08T17:36:51.430Z,1623173811.430 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173650.00,A,3648.16766,N,12147.28738,W,0.350,24.14,080621,,,A*4C 2021-06-08T17:36:51.441Z,1623173811.441 [NAL9602](INFO): GPS fix at 20210608T173650: (36.802794, -121.788123) 2021-06-08T17:36:51.452Z,1623173811.452 [Default:CheckIn:Read_GPS] Stopped 2021-06-08T17:36:51.452Z,1623173811.452 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-06-08T17:36:58.706Z,1623173818.706 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210608T162536/Courier0039.lzma 2021-06-08T17:37:00.275Z,1623173820.275 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Courier0039.lzma.bak 2021-06-08T17:37:00.275Z,1623173820.275 [DataOverHttps](INFO): SBD MOMSN=15703645 2021-06-08T17:37:03.160Z,1623173823.160 [BPC1](INFO): Calculating totals. Valid battery stick count: 49. Valid reserve battery stick count: 5. 2021-06-08T17:37:03.183Z,1623173823.183 [BPC1](INFO): Received data from all battery sticks. 2021-06-08T17:37:15.658Z,1623173835.658 [DataOverHttps](INFO): Sending 216 bytes from file Logs/20210608T162536/Express0040.lzma 2021-06-08T17:37:16.660Z,1623173836.660 [DataOverHttps](INFO): Moved sent file to Logs/20210608T162536/Express0040.lzma.bak 2021-06-08T17:37:16.661Z,1623173836.661 [DataOverHttps](INFO): SBD MOMSN=15703648 2021-06-08T17:37:18.516Z,1623173838.516 [Default:CheckIn:Read_Iridium] Stopped 2021-06-08T17:37:18.516Z,1623173838.516 [Default:CheckIn:C.Wait] Running Loop=1 2021-06-08T17:37:18.516Z,1623173838.516 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-06-08T17:37:23.343Z,1623173843.343 [NAL9602](INFO): Not Powering down - fast GPS 2021-06-08T17:39:04.071Z,1623173944.071 [CommandLine](IMPORTANT): got command quit 2021-06-08T17:39:05.091Z,1623173945.091 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:05.091Z,1623173945.091 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.123Z,1623173945.123 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2021-06-08T17:39:05.123Z,1623173945.123 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.123Z,1623173945.123 [CommandLine](INFO): Join timeout helper Thread ID is 816 2021-06-08T17:39:05.124Z,1623173945.124 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2021-06-08T17:39:05.124Z,1623173945.124 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.124Z,1623173945.124 [NavChartDb](INFO): Join timeout helper Thread ID is 817 2021-06-08T17:39:05.295Z,1623173945.295 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:05.295Z,1623173945.295 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.303Z,1623173945.303 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2021-06-08T17:39:05.303Z,1623173945.303 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.303Z,1623173945.303 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 818 2021-06-08T17:39:05.535Z,1623173945.535 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:05.535Z,1623173945.535 [WetLabsBB2FL](INFO): Powering down 2021-06-08T17:39:05.536Z,1623173945.536 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.543Z,1623173945.543 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2021-06-08T17:39:05.543Z,1623173945.543 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:05.543Z,1623173945.543 [CTD_Seabird](INFO): Join timeout helper Thread ID is 819 2021-06-08T17:39:06.351Z,1623173946.351 [CTD_Seabird](INFO): Powering down 2021-06-08T17:39:06.363Z,1623173946.363 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:06.363Z,1623173946.363 [CTD_Seabird](INFO): Powering down 2021-06-08T17:39:06.375Z,1623173946.375 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:06.379Z,1623173946.379 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2021-06-08T17:39:06.379Z,1623173946.379 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:06.379Z,1623173946.379 [Radio_Surface](INFO): Join timeout helper Thread ID is 820 2021-06-08T17:39:06.655Z,1623173946.655 [Radio_Surface](INFO): Powering down 2021-06-08T17:39:06.656Z,1623173946.656 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:06.656Z,1623173946.656 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:06.675Z,1623173946.675 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2021-06-08T17:39:06.676Z,1623173946.676 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:06.676Z,1623173946.676 [Onboard](INFO): Join timeout helper Thread ID is 822 2021-06-08T17:39:07.099Z,1623173947.099 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:07.099Z,1623173947.099 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.103Z,1623173947.103 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2021-06-08T17:39:07.103Z,1623173947.103 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.104Z,1623173947.104 [DataOverHttps](INFO): Join timeout helper Thread ID is 823 2021-06-08T17:39:07.223Z,1623173947.223 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:07.224Z,1623173947.224 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.227Z,1623173947.227 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler 2021-06-08T17:39:07.228Z,1623173947.228 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.228Z,1623173947.228 [BackseatComponent](INFO): Join timeout helper Thread ID is 824 2021-06-08T17:39:07.427Z,1623173947.427 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:07.427Z,1623173947.427 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.435Z,1623173947.435 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2021-06-08T17:39:07.435Z,1623173947.435 [logger ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.436Z,1623173947.436 [logger](INFO): Join timeout helper Thread ID is 825 2021-06-08T17:39:07.459Z,1623173947.459 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:07.459Z,1623173947.459 [logger ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.475Z,1623173947.475 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2021-06-08T17:39:07.475Z,1623173947.475 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.476Z,1623173947.476 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2021-06-08T17:39:07.476Z,1623173947.476 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.476Z,1623173947.476 [controlThread](INFO): Join timeout helper Thread ID is 826 2021-06-08T17:39:07.555Z,1623173947.555 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2021-06-08T17:39:07.555Z,1623173947.555 [controlThread](DEBUG): Uninitializing ControlThread 2021-06-08T17:39:07.556Z,1623173947.556 [AHRS_M2](INFO): Powering down 2021-06-08T17:39:07.627Z,1623173947.627 [NAL9602](INFO): Powering down 2021-06-08T17:39:07.629Z,1623173947.629 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2021-06-08T17:39:07.630Z,1623173947.630 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2021-06-08T17:39:07.631Z,1623173947.631 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2021-06-08T17:39:07.631Z,1623173947.631 [MissionManager](INFO): Uninitializing Mission Default 2021-06-08T17:39:07.632Z,1623173947.632 [Default] Stopped 2021-06-08T17:39:07.632Z,1623173947.632 [Default](DEBUG): Aggregate::uninitialize Default 2021-06-08T17:39:07.632Z,1623173947.632 [Default:B.GoToSurface] Stopped 2021-06-08T17:39:07.632Z,1623173947.632 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-06-08T17:39:07.632Z,1623173947.632 [Default:CheckIn] Stopped 2021-06-08T17:39:07.632Z,1623173947.632 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-06-08T17:39:07.632Z,1623173947.632 [Default:CheckIn:C.Wait] Stopped 2021-06-08T17:39:07.632Z,1623173947.632 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-06-08T17:39:07.636Z,1623173947.636 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2021-06-08T17:39:07.636Z,1623173947.636 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2021-06-08T17:39:07.636Z,1623173947.636 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2021-06-08T17:39:07.637Z,1623173947.637 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2021-06-08T17:39:07.637Z,1623173947.637 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2021-06-08T17:39:07.637Z,1623173947.637 [BuoyancyServo](INFO): Powering down 2021-06-08T17:39:07.651Z,1623173947.651 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2021-06-08T17:39:07.651Z,1623173947.651 [ElevatorServo](INFO): Powering down 2021-06-08T17:39:07.652Z,1623173947.652 [MassServo](DEBUG): Uninitialize Mass Servo. 2021-06-08T17:39:07.652Z,1623173947.652 [MassServo](INFO): Powering down 2021-06-08T17:39:07.653Z,1623173947.653 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-06-08T17:39:07.653Z,1623173947.653 [RudderServo](INFO): Powering down 2021-06-08T17:39:07.654Z,1623173947.654 [ThrusterHE](DEBUG): Uninitialize Thruster Servo. 2021-06-08T17:39:07.654Z,1623173947.654 [ThrusterHE](INFO): Powering down 2021-06-08T17:39:07.655Z,1623173947.655 [SBIT](DEBUG): Uninitialize SBIT Component. 2021-06-08T17:39:07.655Z,1623173947.655 [IBIT](DEBUG): Uninitialize IBIT Component. 2021-06-08T17:39:07.656Z,1623173947.656 [CBIT](DEBUG): Uninitialize CBIT Component. 2021-06-08T17:39:07.656Z,1623173947.656 [CBIT](DEBUG): Powering off loads. 2021-06-08T17:39:07.666Z,1623173947.666 [CBIT](DEBUG): Disabling WDT. 2021-06-08T17:39:07.678Z,1623173947.678 [CBIT](DEBUG): Opening all GF detection circuits. 2021-06-08T17:39:07.680Z,1623173947.680 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.743Z,1623173947.743 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.746Z,1623173947.746 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.753Z,1623173947.753 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.803Z,1623173947.803 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.841Z,1623173947.841 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.845Z,1623173947.845 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.878Z,1623173947.878 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-06-08T17:39:07.966Z,1623173947.966 [logger ThreadHandler](INFO): Thread cancelled.